Project

General

Profile

Bug #1310 ยป mds.dev14.log

Damien Churchill, 07/14/2011 01:11 AM

 
2011-07-14 09:05:57.835806 7f8f4608a700 mds2.cache.dir(2000099923f) adjust_nested_auth_pins 1/1 on [dir 2000099923f /fileserver/LonBackups/ [2,head] auth{3=1} v=106102 cv=0/0 ap=0+1+1 state=1610612738|complete f(v20 m2011-06-30 18:33:45.033189 5=0+5) n(v8684 rc2011-07-01 16:53:05.427689 b353191327744 10=5+5) hs=5+8,ss=0+0 dirty=7 | child replicated dirty 0x39f0968] by 0x395be50 count now 0 + 1
2011-07-14 09:05:57.835814 7f8f4608a700 mds2.cache.dir(2000099962c) adjust_nested_auth_pins 1/0 on [dir 2000099962c /fileserver/ [2,head] auth{0=1,3=1} v=46860 cv=0/0 dir_auth=2 ap=0+1+2 state=1610612738|complete f(v85 m2011-07-08 17:03:03.460756 1=0+1) n(v2012 rc2011-07-08 17:03:03.460756 b353191327744 11=5+6) hs=1+43,ss=0+0 dirty=1 | child subtree replicated dirty 0x39ef198] by 0x395be50 count now 0 + 2
2011-07-14 09:05:57.835823 7f8f4608a700 mds2.locker already auth_pinned [inode 20000999294 [...2,head] /fileserver/LonBackups/15-wb01-secure/ auth{3=1} v106078 ap=1 f(v5 m2011-07-01 16:53:05.427689 1=1+0) n(v0 rc2011-07-01 16:53:05.427689 b77588059136 2=1+1) (iversion lock) caps={282283=pAsLsXsFs/-@1} | request dirfrag caps replicated dirty authpin 0x395be50]
2011-07-14 09:05:57.835831 7f8f4608a700 mds2.locker already auth_pinned [inode 20000999294 [...2,head] /fileserver/LonBackups/15-wb01-secure/ auth{3=1} v106078 ap=1 f(v5 m2011-07-01 16:53:05.427689 1=1+0) n(v0 rc2011-07-01 16:53:05.427689 b77588059136 2=1+1) (iversion lock) caps={282283=pAsLsXsFs/-@1} | request dirfrag caps replicated dirty authpin 0x395be50]
2011-07-14 09:05:57.835839 7f8f4608a700 mds2.locker rdlock_start on (isnap sync r=3) on [inode 1 [...2,head] / rep@0.1 v23316 snaprealm=0x25d0900 f(v6 m2011-07-08 17:02:14.145857 4=0+4) n(v791 rc2011-07-12 15:50:54.418743 b562750828083 10885=9507+1378)/n(v0 1=0+1) (isnap sync r=3) (inest mix) (iversion lock) | lock dirfrag 0x25bf868]
2011-07-14 09:05:57.835847 7f8f4608a700 mds2.locker got rdlock on (isnap sync r=4) [inode 1 [...2,head] / rep@0.1 v23316 snaprealm=0x25d0900 f(v6 m2011-07-08 17:02:14.145857 4=0+4) n(v791 rc2011-07-12 15:50:54.418743 b562750828083 10885=9507+1378)/n(v0 1=0+1) (isnap sync r=4) (inest mix) (iversion lock) | lock dirfrag 0x25bf868]
2011-07-14 09:05:57.835856 7f8f4608a700 mds2.locker rdlock_start on (isnap sync) on [inode 2000099923f [...2,head] /fileserver/LonBackups/ auth{3=1} v46859 ap=1 f(v20 m2011-06-30 18:33:45.033189 5=0+5) n(v8684 rc2011-07-01 16:53:05.427689 b353191327744 11=5+6) (inest mix dirty) (iversion lock) caps={282283=pAsLsXs/p@1},l=282283 | dirtyscattered dirfrag caps replicated dirty authpin 0x38b23c0]
2011-07-14 09:05:57.835865 7f8f4608a700 mds2.locker got rdlock on (isnap sync r=1) [inode 2000099923f [...2,head] /fileserver/LonBackups/ auth{3=1} v46859 ap=1 f(v20 m2011-06-30 18:33:45.033189 5=0+5) n(v8684 rc2011-07-01 16:53:05.427689 b353191327744 11=5+6) (isnap sync r=1) (inest mix dirty) (iversion lock) caps={282283=pAsLsXs/p@1},l=282283 | dirtyscattered lock dirfrag caps replicated dirty authpin 0x38b23c0]
2011-07-14 09:05:57.835874 7f8f4608a700 mds2.locker rdlock_start on (isnap sync) on [inode 20000999294 [...2,head] /fileserver/LonBackups/15-wb01-secure/ auth{3=1} v106078 ap=1 f(v5 m2011-07-01 16:53:05.427689 1=1+0) n(v0 rc2011-07-01 16:53:05.427689 b77588059136 2=1+1) (iversion lock) caps={282283=pAsLsXsFs/-@1} | request dirfrag caps replicated dirty authpin 0x395be50]
2011-07-14 09:05:57.835886 7f8f4608a700 mds2.locker got rdlock on (isnap sync r=1) [inode 20000999294 [...2,head] /fileserver/LonBackups/15-wb01-secure/ auth{3=1} v106078 ap=1 f(v5 m2011-07-01 16:53:05.427689 1=1+0) n(v0 rc2011-07-01 16:53:05.427689 b77588059136 2=1+1) (isnap sync r=1) (iversion lock) caps={282283=pAsLsXsFs/-@1} | request lock dirfrag caps replicated dirty authpin 0x395be50]
2011-07-14 09:05:57.835896 7f8f4608a700 mds2.locker rdlock_start on (ifile sync) on [inode 20000999294 [...2,head] /fileserver/LonBackups/15-wb01-secure/ auth{3=1} v106078 ap=1 f(v5 m2011-07-01 16:53:05.427689 1=1+0) n(v0 rc2011-07-01 16:53:05.427689 b77588059136 2=1+1) (isnap sync r=1) (iversion lock) caps={282283=pAsLsXsFs/-@1} | request lock dirfrag caps replicated dirty authpin 0x395be50]
2011-07-14 09:05:57.835905 7f8f4608a700 mds2.locker got rdlock on (ifile sync r=1) [inode 20000999294 [...2,head] /fileserver/LonBackups/15-wb01-secure/ auth{3=1} v106078 ap=1 f(v5 m2011-07-01 16:53:05.427689 1=1+0) n(v0 rc2011-07-01 16:53:05.427689 b77588059136 2=1+1) (isnap sync r=1) (ifile sync r=1) (iversion lock) caps={282283=pAsLsXsFs/-@1} | request lock dirfrag caps replicated dirty authpin 0x395be50]
2011-07-14 09:05:57.835914 7f8f4608a700 mds2.locker rdlock_start on (idft sync) on [inode 20000999294 [...2,head] /fileserver/LonBackups/15-wb01-secure/ auth{3=1} v106078 ap=1 f(v5 m2011-07-01 16:53:05.427689 1=1+0) n(v0 rc2011-07-01 16:53:05.427689 b77588059136 2=1+1) (isnap sync r=1) (ifile sync r=1) (iversion lock) caps={282283=pAsLsXsFs/-@1} | request lock dirfrag caps replicated dirty authpin 0x395be50]
2011-07-14 09:05:57.835924 7f8f4608a700 mds2.locker got rdlock on (idft sync r=1) [inode 20000999294 [...2,head] /fileserver/LonBackups/15-wb01-secure/ auth{3=1} v106078 ap=1 f(v5 m2011-07-01 16:53:05.427689 1=1+0) n(v0 rc2011-07-01 16:53:05.427689 b77588059136 2=1+1) (idft sync r=1) (isnap sync r=1) (ifile sync r=1) (iversion lock) caps={282283=pAsLsXsFs/-@1} | request lock dirfrag caps replicated dirty authpin 0x395be50]
2011-07-14 09:05:57.835931 7f8f4608a700 mds2.locker rdlock_start on (isnap sync) on [inode 2000099962c [...2,head] /fileserver/ rep@0.1 v79512 f(v85 m2011-07-08 17:03:03.460756 1=0+1) n(v2012 rc2011-07-08 17:03:03.460756 b353191327744 11=5+6) (inest mix dirty flushed) (iversion lock) | dirtyscattered dirfrag 0x363c470]
2011-07-14 09:05:57.835939 7f8f4608a700 mds2.locker got rdlock on (isnap sync r=1) [inode 2000099962c [...2,head] /fileserver/ rep@0.1 v79512 f(v85 m2011-07-08 17:03:03.460756 1=0+1) n(v2012 rc2011-07-08 17:03:03.460756 b353191327744 11=5+6) (isnap sync r=1) (inest mix dirty flushed) (iversion lock) | dirtyscattered lock dirfrag 0x363c470]
2011-07-14 09:05:57.835943 7f8f4608a700 mds2.server frag *
2011-07-14 09:05:57.835952 7f8f4608a700 mds2.server try_open_auth_dirfrag: not auth for [dir 20000999294 /fileserver/LonBackups/15-wb01-secure/ [2,head] rep@3.9 dir_auth=3 state=0 f(v4 m2011-07-01 16:53:05.427689 1=1+0) n(v0 rc2011-07-01 16:53:05.427689 b77588059136 1=1+0) hs=0+0,ss=0+0 | subtree 0x3a00f58], fw to mds3
2011-07-14 09:05:57.835956 7f8f4608a700 mds2.cache request_forward request(client282283:3996 cr=0x3705480) to mds3 req request(client282283:3996 cr=0x3705480)
2011-07-14 09:05:57.835963 7f8f4608a700 mds2.cache request_cleanup request(client282283:3996)
2011-07-14 09:05:57.835972 7f8f4608a700 mds2.locker rdlock_finish on (isnap sync r=3) on [inode 1 [...2,head] / rep@0.1 v23316 snaprealm=0x25d0900 f(v6 m2011-07-08 17:02:14.145857 4=0+4) n(v791 rc2011-07-12 15:50:54.418743 b562750828083 10885=9507+1378)/n(v0 1=0+1) (isnap sync r=3) (inest mix) (iversion lock) | lock dirfrag 0x25bf868]
2011-07-14 09:05:57.835980 7f8f4608a700 mds2.locker rdlock_finish on (isnap sync) on [inode 2000099962c [...2,head] /fileserver/ rep@0.1 v79512 f(v85 m2011-07-08 17:03:03.460756 1=0+1) n(v2012 rc2011-07-08 17:03:03.460756 b353191327744 11=5+6) (inest mix dirty flushed) (iversion lock) | dirtyscattered dirfrag 0x363c470]
2011-07-14 09:05:57.835989 7f8f4608a700 mds2.locker rdlock_finish on (isnap sync) on [inode 2000099923f [...2,head] /fileserver/LonBackups/ auth{3=1} v46859 ap=1 f(v20 m2011-06-30 18:33:45.033189 5=0+5) n(v8684 rc2011-07-01 16:53:05.427689 b353191327744 11=5+6) (inest mix dirty) (iversion lock) caps={282283=pAsLsXs/p@1},l=282283 | dirtyscattered dirfrag caps replicated dirty authpin 0x38b23c0]
2011-07-14 09:05:57.836001 7f8f4608a700 mds2.locker simple_eval (isnap sync) on [inode 2000099923f [...2,head] /fileserver/LonBackups/ auth{3=1} v46859 ap=1 f(v20 m2011-06-30 18:33:45.033189 5=0+5) n(v8684 rc2011-07-01 16:53:05.427689 b353191327744 11=5+6) (inest mix dirty) (iversion lock) caps={282283=pAsLsXs/p@1},l=282283 | dirtyscattered dirfrag caps replicated dirty authpin 0x38b23c0]
2011-07-14 09:05:57.836011 7f8f4608a700 mds2.locker rdlock_finish on (idft sync) on [inode 20000999294 [...2,head] /fileserver/LonBackups/15-wb01-secure/ auth{3=1} v106078 ap=1 f(v5 m2011-07-01 16:53:05.427689 1=1+0) n(v0 rc2011-07-01 16:53:05.427689 b77588059136 2=1+1) (isnap sync r=1) (ifile sync r=1) (iversion lock) caps={282283=pAsLsXsFs/-@1} | request lock dirfrag caps replicated dirty authpin 0x395be50]
2011-07-14 09:05:57.836020 7f8f4608a700 mds2.locker scatter_eval (idft sync) on [inode 20000999294 [...2,head] /fileserver/LonBackups/15-wb01-secure/ auth{3=1} v106078 ap=1 f(v5 m2011-07-01 16:53:05.427689 1=1+0) n(v0 rc2011-07-01 16:53:05.427689 b77588059136 2=1+1) (isnap sync r=1) (ifile sync r=1) (iversion lock) caps={282283=pAsLsXsFs/-@1} | request lock dirfrag caps replicated dirty authpin 0x395be50]
2011-07-14 09:05:57.836030 7f8f4608a700 mds2.locker rdlock_finish on (ifile sync) on [inode 20000999294 [...2,head] /fileserver/LonBackups/15-wb01-secure/ auth{3=1} v106078 ap=1 f(v5 m2011-07-01 16:53:05.427689 1=1+0) n(v0 rc2011-07-01 16:53:05.427689 b77588059136 2=1+1) (isnap sync r=1) (iversion lock) caps={282283=pAsLsXsFs/-@1} | request lock dirfrag caps replicated dirty authpin 0x395be50]
2011-07-14 09:05:57.836039 7f8f4608a700 mds2.locker file_eval wanted= loner_wanted= other_wanted= filelock=(ifile sync) on [inode 20000999294 [...2,head] /fileserver/LonBackups/15-wb01-secure/ auth{3=1} v106078 ap=1 f(v5 m2011-07-01 16:53:05.427689 1=1+0) n(v0 rc2011-07-01 16:53:05.427689 b77588059136 2=1+1) (isnap sync r=1) (iversion lock) caps={282283=pAsLsXsFs/-@1} | request lock dirfrag caps replicated dirty authpin 0x395be50]
2011-07-14 09:05:57.836048 7f8f4608a700 mds2.locker rdlock_finish on (isnap sync) on [inode 20000999294 [...2,head] /fileserver/LonBackups/15-wb01-secure/ auth{3=1} v106078 ap=1 f(v5 m2011-07-01 16:53:05.427689 1=1+0) n(v0 rc2011-07-01 16:53:05.427689 b77588059136 2=1+1) (iversion lock) caps={282283=pAsLsXsFs/-@1} | request dirfrag caps replicated dirty authpin 0x395be50]
2011-07-14 09:05:57.836056 7f8f4608a700 mds2.locker simple_eval (isnap sync) on [inode 20000999294 [...2,head] /fileserver/LonBackups/15-wb01-secure/ auth{3=1} v106078 ap=1 f(v5 m2011-07-01 16:53:05.427689 1=1+0) n(v0 rc2011-07-01 16:53:05.427689 b77588059136 2=1+1) (iversion lock) caps={282283=pAsLsXsFs/-@1} | request dirfrag caps replicated dirty authpin 0x395be50]
2011-07-14 09:05:57.836066 7f8f4608a700 mds2.cache.ino(2000099923f) auth_unpin by 0x25b2380 on [inode 2000099923f [...2,head] /fileserver/LonBackups/ auth{3=1} v46859 f(v20 m2011-06-30 18:33:45.033189 5=0+5) n(v8684 rc2011-07-01 16:53:05.427689 b353191327744 11=5+6) (inest mix dirty) (iversion lock) caps={282283=pAsLsXs/p@1},l=282283 | dirtyscattered dirfrag caps replicated dirty 0x38b23c0] now 0+1
2011-07-14 09:05:57.836082 7f8f4608a700 mds2.cache.dir(2000099962c) adjust_nested_auth_pins -1/-1 on [dir 2000099962c /fileserver/ [2,head] auth{0=1,3=1} v=46860 cv=0/0 dir_auth=2 ap=0+0+1 state=1610612738|complete f(v85 m2011-07-08 17:03:03.460756 1=0+1) n(v2012 rc2011-07-08 17:03:03.460756 b353191327744 11=5+6) hs=1+43,ss=0+0 dirty=1 | child subtree replicated dirty 0x39ef198] by 0x38b23c0 count now 0 + 1
2011-07-14 09:05:57.836091 7f8f4608a700 mds2.cache.ino(20000999294) auth_unpin by 0x25b2380 on [inode 20000999294 [...2,head] /fileserver/LonBackups/15-wb01-secure/ auth{3=1} v106078 f(v5 m2011-07-01 16:53:05.427689 1=1+0) n(v0 rc2011-07-01 16:53:05.427689 b77588059136 2=1+1) (iversion lock) caps={282283=pAsLsXsFs/-@1} | request dirfrag caps replicated dirty 0x395be50] now 0+0
2011-07-14 09:05:57.836101 7f8f4608a700 mds2.cache.dir(2000099923f) adjust_nested_auth_pins -1/-1 on [dir 2000099923f /fileserver/LonBackups/ [2,head] auth{3=1} v=106102 cv=0/0 state=1610612738|complete f(v20 m2011-06-30 18:33:45.033189 5=0+5) n(v8684 rc2011-07-01 16:53:05.427689 b353191327744 10=5+5) hs=5+8,ss=0+0 dirty=7 | child replicated dirty 0x39f0968] by 0x395be50 count now 0 + 0
2011-07-14 09:05:57.836109 7f8f4608a700 mds2.cache.dir(2000099962c) adjust_nested_auth_pins -1/0 on [dir 2000099962c /fileserver/ [2,head] auth{0=1,3=1} v=46860 cv=0/0 dir_auth=2 state=1610612738|complete f(v85 m2011-07-08 17:03:03.460756 1=0+1) n(v2012 rc2011-07-08 17:03:03.460756 b353191327744 11=5+6) hs=1+43,ss=0+0 dirty=1 | child subtree replicated dirty 0x39ef198] by 0x395be50 count now 0 + 0
2011-07-14 09:05:57.847854 7f8f4608a700 mds2.server handle_slave_request client282283:3995 from mds7
2011-07-14 09:05:57.847878 7f8f4608a700 mds2.cache request_get client282283:3995 request(client282283:3995 cr=0x3705240)
2011-07-14 09:05:57.847885 7f8f4608a700 mds2.server handle_slave_auth_pin_ack on request(client282283:3995 cr=0x3705240) slave_request(client282283:3995 authpin_ack) v1
2011-07-14 09:05:57.847904 7f8f4608a700 mds2.server remote has pinned [inode 400009a0211 [...2,head] /filestore/ben.heley/home/.cache/ rep@7.1 v61 f(v7) n(v0 1=0+1) (ifile lock) (iversion lock) caps={282283=pAsLsXs/-@1} | request caps 0x3993960]
2011-07-14 09:05:57.847913 7f8f4608a700 mds2.server dispatch_client_request client_request(client282283:3995 getattr pAsLsXsFs #400009a0211)
2011-07-14 09:05:57.847918 7f8f4608a700 mds2.server rdlock_path_pin_ref request(client282283:3995 cr=0x3705240) #400009a0211
2011-07-14 09:05:57.847922 7f8f4608a700 mds2.cache traverse: opening base ino 400009a0211 snap head
2011-07-14 09:05:57.847925 7f8f4608a700 mds2.cache path_traverse finish on snapid head
2011-07-14 09:05:57.847933 7f8f4608a700 mds2.server ref is [inode 400009a0211 [...2,head] /filestore/ben.heley/home/.cache/ rep@7.1 v61 f(v7) n(v0 1=0+1) (ifile lock) (iversion lock) caps={282283=pAsLsXs/-@1} | request caps 0x3993960]
2011-07-14 09:05:57.847939 7f8f4608a700 mds2.locker acquire_locks request(client282283:3995 cr=0x3705240)
2011-07-14 09:05:57.847950 7f8f4608a700 mds2.locker must rdlock (isnap sync r=3) [inode 1 [...2,head] / rep@0.1 v23316 snaprealm=0x25d0900 f(v6 m2011-07-08 17:02:14.145857 4=0+4) n(v791 rc2011-07-12 15:50:54.418743 b562750828083 10885=9507+1378)/n(v0 1=0+1) (isnap sync r=3) (inest mix) (iversion lock) | lock dirfrag 0x25bf868]
2011-07-14 09:05:57.847959 7f8f4608a700 mds2.locker must rdlock (isnap sync r=3) [inode 10000000000 [...2,head] /filestore/ rep@0.1 v79518 f(v15 m2011-07-01 09:57:40.325579 5=0+5) n(v3943 rc2011-07-12 15:50:54.418743 b209559383922 10870=9500+1370) (isnap sync r=3) (inest mix dirty flushed) (iversion lock) | dirtyscattered lock dirfrag 0x25c00d0]
2011-07-14 09:05:57.847973 7f8f4608a700 mds2.locker must rdlock (isnap sync) [inode 10000000004 [...2,head] /filestore/ben.heley/ auth{7=1} v53639 ap=1 f(v29 m2011-07-01 11:27:58.697138 1=0+1) n(v5 rc2011-07-01 11:27:58.749881 5=0+5) (inest mix dirty) (iversion lock) caps={210471=pAsLsXs/-@0,211361=-/-@0,278413=pAsLsXsFs/-@3,282283=pAsLsXs/p@1,282921=pAsLsXs/-@0} | dirtyscattered dirfrag caps replicated dirty authpin 0x395f928]
2011-07-14 09:05:57.847980 7f8f4608a700 mds2.locker must rdlock (iauth sync) [inode 400009a0211 [...2,head] /filestore/ben.heley/home/.cache/ rep@7.1 v61 f(v7) n(v0 1=0+1) (ifile lock) (iversion lock) caps={282283=pAsLsXs/-@1} | request caps 0x3993960]
2011-07-14 09:05:57.847987 7f8f4608a700 mds2.locker must rdlock (ilink sync) [inode 400009a0211 [...2,head] /filestore/ben.heley/home/.cache/ rep@7.1 v61 f(v7) n(v0 1=0+1) (ifile lock) (iversion lock) caps={282283=pAsLsXs/-@1} | request caps 0x3993960]
2011-07-14 09:05:57.847994 7f8f4608a700 mds2.locker must rdlock (ifile lock) [inode 400009a0211 [...2,head] /filestore/ben.heley/home/.cache/ rep@7.1 v61 f(v7) n(v0 1=0+1) (ifile lock) (iversion lock) caps={282283=pAsLsXs/-@1} | request caps 0x3993960]
2011-07-14 09:05:57.848006 7f8f4608a700 mds2.locker will also auth_pin [inode 400009a0211 [...2,head] /filestore/ben.heley/home/.cache/ rep@7.1 v61 f(v7) n(v0 1=0+1) (ifile lock) (iversion lock) caps={282283=pAsLsXs/-@1} | request caps 0x3993960] in case we need to request a rdlock
2011-07-14 09:05:57.848013 7f8f4608a700 mds2.locker must rdlock (ixattr sync) [inode 400009a0211 [...2,head] /filestore/ben.heley/home/.cache/ rep@7.1 v61 f(v7) n(v0 1=0+1) (ifile lock) (iversion lock) caps={282283=pAsLsXs/-@1} | request caps 0x3993960]
2011-07-14 09:05:57.848020 7f8f4608a700 mds2.locker must rdlock (isnap sync) [inode 400009a0211 [...2,head] /filestore/ben.heley/home/.cache/ rep@7.1 v61 f(v7) n(v0 1=0+1) (ifile lock) (iversion lock) caps={282283=pAsLsXs/-@1} | request caps 0x3993960]
2011-07-14 09:05:57.848031 7f8f4608a700 mds2.locker must rdlock (isnap sync) [inode 400009a0210 [...2,head] /filestore/ben.heley/home/ auth{7=1} v65 ap=1 f(v4 m2011-07-01 11:27:58.749881 3=0+3) n(v5 rc2011-07-01 11:27:58.749881 4=0+4) (iversion lock) caps={278413=pAsLsXsFs/-@1,282283=pAsLsXsFs/p@1} | dirfrag caps replicated dirty authpin 0x3db9450]
2011-07-14 09:05:57.848043 7f8f4608a700 mds2.locker must authpin [inode 10000000004 [...2,head] /filestore/ben.heley/ auth{7=1} v53639 ap=1 f(v29 m2011-07-01 11:27:58.697138 1=0+1) n(v5 rc2011-07-01 11:27:58.749881 5=0+5) (inest mix dirty) (iversion lock) caps={210471=pAsLsXs/-@0,211361=-/-@0,278413=pAsLsXsFs/-@3,282283=pAsLsXs/p@1,282921=pAsLsXs/-@0} | dirtyscattered dirfrag caps replicated dirty authpin 0x395f928]
2011-07-14 09:05:57.848049 7f8f4608a700 mds2.locker must authpin [inode 400009a0211 [...2,head] /filestore/ben.heley/home/.cache/ rep@7.1 v61 f(v7) n(v0 1=0+1) (ifile lock) (iversion lock) caps={282283=pAsLsXs/-@1} | request caps 0x3993960]
2011-07-14 09:05:57.848058 7f8f4608a700 mds2.locker must authpin [inode 400009a0210 [...2,head] /filestore/ben.heley/home/ auth{7=1} v65 ap=1 f(v4 m2011-07-01 11:27:58.749881 3=0+3) n(v5 rc2011-07-01 11:27:58.749881 4=0+4) (iversion lock) caps={278413=pAsLsXsFs/-@1,282283=pAsLsXsFs/p@1} | dirfrag caps replicated dirty authpin 0x3db9450]
2011-07-14 09:05:57.848069 7f8f4608a700 mds2.locker already auth_pinned [inode 10000000004 [...2,head] /filestore/ben.heley/ auth{7=1} v53639 ap=1 f(v29 m2011-07-01 11:27:58.697138 1=0+1) n(v5 rc2011-07-01 11:27:58.749881 5=0+5) (inest mix dirty) (iversion lock) caps={210471=pAsLsXs/-@0,211361=-/-@0,278413=pAsLsXsFs/-@3,282283=pAsLsXs/p@1,282921=pAsLsXs/-@0} | dirtyscattered dirfrag caps replicated dirty authpin 0x395f928]
2011-07-14 09:05:57.848076 7f8f4608a700 mds2.locker already auth_pinned [inode 400009a0211 [...2,head] /filestore/ben.heley/home/.cache/ rep@7.1 v61 f(v7) n(v0 1=0+1) (ifile lock) (iversion lock) caps={282283=pAsLsXs/-@1} | request caps 0x3993960]
2011-07-14 09:05:57.848085 7f8f4608a700 mds2.locker already auth_pinned [inode 400009a0210 [...2,head] /filestore/ben.heley/home/ auth{7=1} v65 ap=1 f(v4 m2011-07-01 11:27:58.749881 3=0+3) n(v5 rc2011-07-01 11:27:58.749881 4=0+4) (iversion lock) caps={278413=pAsLsXsFs/-@1,282283=pAsLsXsFs/p@1} | dirfrag caps replicated dirty authpin 0x3db9450]
2011-07-14 09:05:57.848093 7f8f4608a700 mds2.locker rdlock_start on (isnap sync r=3) on [inode 1 [...2,head] / rep@0.1 v23316 snaprealm=0x25d0900 f(v6 m2011-07-08 17:02:14.145857 4=0+4) n(v791 rc2011-07-12 15:50:54.418743 b562750828083 10885=9507+1378)/n(v0 1=0+1) (isnap sync r=3) (inest mix) (iversion lock) | lock dirfrag 0x25bf868]
2011-07-14 09:05:57.848101 7f8f4608a700 mds2.locker got rdlock on (isnap sync r=4) [inode 1 [...2,head] / rep@0.1 v23316 snaprealm=0x25d0900 f(v6 m2011-07-08 17:02:14.145857 4=0+4) n(v791 rc2011-07-12 15:50:54.418743 b562750828083 10885=9507+1378)/n(v0 1=0+1) (isnap sync r=4) (inest mix) (iversion lock) | lock dirfrag 0x25bf868]
2011-07-14 09:05:57.848109 7f8f4608a700 mds2.locker rdlock_start on (isnap sync r=3) on [inode 10000000000 [...2,head] /filestore/ rep@0.1 v79518 f(v15 m2011-07-01 09:57:40.325579 5=0+5) n(v3943 rc2011-07-12 15:50:54.418743 b209559383922 10870=9500+1370) (isnap sync r=3) (inest mix dirty flushed) (iversion lock) | dirtyscattered lock dirfrag 0x25c00d0]
2011-07-14 09:05:57.848120 7f8f4608a700 mds2.locker got rdlock on (isnap sync r=4) [inode 10000000000 [...2,head] /filestore/ rep@0.1 v79518 f(v15 m2011-07-01 09:57:40.325579 5=0+5) n(v3943 rc2011-07-12 15:50:54.418743 b209559383922 10870=9500+1370) (isnap sync r=4) (inest mix dirty flushed) (iversion lock) | dirtyscattered lock dirfrag 0x25c00d0]
2011-07-14 09:05:57.848131 7f8f4608a700 mds2.locker rdlock_start on (isnap sync) on [inode 10000000004 [...2,head] /filestore/ben.heley/ auth{7=1} v53639 ap=1 f(v29 m2011-07-01 11:27:58.697138 1=0+1) n(v5 rc2011-07-01 11:27:58.749881 5=0+5) (inest mix dirty) (iversion lock) caps={210471=pAsLsXs/-@0,211361=-/-@0,278413=pAsLsXsFs/-@3,282283=pAsLsXs/p@1,282921=pAsLsXs/-@0} | dirtyscattered dirfrag caps replicated dirty authpin 0x395f928]
2011-07-14 09:05:57.848143 7f8f4608a700 mds2.locker got rdlock on (isnap sync r=1) [inode 10000000004 [...2,head] /filestore/ben.heley/ auth{7=1} v53639 ap=1 f(v29 m2011-07-01 11:27:58.697138 1=0+1) n(v5 rc2011-07-01 11:27:58.749881 5=0+5) (isnap sync r=1) (inest mix dirty) (iversion lock) caps={210471=pAsLsXs/-@0,211361=-/-@0,278413=pAsLsXsFs/-@3,282283=pAsLsXs/p@1,282921=pAsLsXs/-@0} | dirtyscattered lock dirfrag caps replicated dirty authpin 0x395f928]
2011-07-14 09:05:57.848152 7f8f4608a700 mds2.locker rdlock_start on (isnap sync) on [inode 400009a0210 [...2,head] /filestore/ben.heley/home/ auth{7=1} v65 ap=1 f(v4 m2011-07-01 11:27:58.749881 3=0+3) n(v5 rc2011-07-01 11:27:58.749881 4=0+4) (iversion lock) caps={278413=pAsLsXsFs/-@1,282283=pAsLsXsFs/p@1} | dirfrag caps replicated dirty authpin 0x3db9450]
2011-07-14 09:05:57.848162 7f8f4608a700 mds2.locker got rdlock on (isnap sync r=1) [inode 400009a0210 [...2,head] /filestore/ben.heley/home/ auth{7=1} v65 ap=1 f(v4 m2011-07-01 11:27:58.749881 3=0+3) n(v5 rc2011-07-01 11:27:58.749881 4=0+4) (isnap sync r=1) (iversion lock) caps={278413=pAsLsXsFs/-@1,282283=pAsLsXsFs/p@1} | lock dirfrag caps replicated dirty authpin 0x3db9450]
2011-07-14 09:05:57.848169 7f8f4608a700 mds2.locker rdlock_start on (isnap sync) on [inode 400009a0211 [...2,head] /filestore/ben.heley/home/.cache/ rep@7.1 v61 f(v7) n(v0 1=0+1) (ifile lock) (iversion lock) caps={282283=pAsLsXs/-@1} | request caps 0x3993960]
2011-07-14 09:05:57.848177 7f8f4608a700 mds2.locker got rdlock on (isnap sync r=1) [inode 400009a0211 [...2,head] /filestore/ben.heley/home/.cache/ rep@7.1 v61 f(v7) n(v0 1=0+1) (isnap sync r=1) (ifile lock) (iversion lock) caps={282283=pAsLsXs/-@1} | request lock caps 0x3993960]
2011-07-14 09:05:57.848184 7f8f4608a700 mds2.locker rdlock_start on (ifile lock) on [inode 400009a0211 [...2,head] /filestore/ben.heley/home/.cache/ rep@7.1 v61 f(v7) n(v0 1=0+1) (isnap sync r=1) (ifile lock) (iversion lock) caps={282283=pAsLsXs/-@1} | request lock caps 0x3993960]
2011-07-14 09:05:57.848191 7f8f4608a700 mds2.locker requesting rdlock from auth on (ifile lock) on [inode 400009a0211 [...2,head] /filestore/ben.heley/home/.cache/ rep@7.1 v61 f(v7) n(v0 1=0+1) (isnap sync r=1) (ifile lock) (iversion lock) caps={282283=pAsLsXs/-@1} | request lock caps 0x3993960]
2011-07-14 09:05:57.848204 7f8f4608a700 mds2.locker rdlock_start waiting on (ifile lock) on [inode 400009a0211 [...2,head] /filestore/ben.heley/home/.cache/ rep@7.1 v61 f(v7) n(v0 1=0+1) (isnap sync r=1) (ifile lock) (iversion lock) caps={282283=pAsLsXs/-@1} | request lock caps 0x3993960]
2011-07-14 09:05:57.848209 7f8f4608a700 mds2.cache.ino(400009a0211) add_waiter tag 40000000 0x315b6a0 !ambig 1 !frozen 1 !freezing 1
2011-07-14 09:05:57.848217 7f8f4608a700 mds2.locker nudge_log (ifile lock) on [inode 400009a0211 [...2,head] /filestore/ben.heley/home/.cache/ rep@7.1 v61 f(v7) n(v0 1=0+1) (isnap sync r=1) (ifile lock) (iversion lock) caps={282283=pAsLsXs/-@1} | request lock caps waiter 0x3993960]
2011-07-14 09:05:57.848245 7f8f4608a700 mds2.locker handle_file_lock a=lockack on (ifile sync->lock g=7) from mds7 [inode 10000000002 [...2,head] /filestore/dchurchill/ auth{0=1,1=1,3=1,4=1,5=1,6=1,7=1} v53649 ap=4 f(v49 m2011-07-12 13:58:30.614248 9=3+6) n(v8429 rc2011-07-12 13:58:30.614248 b81985828395 2054=1788+266) (isnap sync r=3) (inest mix dirty) (ifile sync->lock g=7) (iversion lock) caps={210471=pAsLsXs/-@0,211361=pAsLsXs/-@0,278413=pAsLsXs/-@0,282283=pAsLsXs/p@0,282921=pAsLsXs/-@0} | dirtyscattered request lock dirfrag caps replicated dirty waiter authpin 0x392f3c8]
2011-07-14 09:05:57.848260 7f8f4608a700 mds2.locker handle_file_lock [inode 10000000002 [...2,head] /filestore/dchurchill/ auth{0=1,1=1,3=1,4=1,5=1,6=1,7=1} v53649 ap=4 f(v49 m2011-07-12 13:58:30.614248 9=3+6) n(v8429 rc2011-07-12 13:58:30.614248 b81985828395 2054=1788+266) (isnap sync r=3) (inest mix dirty) (ifile sync->lock) (iversion lock) caps={210471=pAsLsXs/-@0,211361=pAsLsXs/-@0,278413=pAsLsXs/-@0,282283=pAsLsXs/p@0,282921=pAsLsXs/-@0} | dirtyscattered request lock dirfrag caps replicated dirty waiter authpin 0x392f3c8] from 7, last one
2011-07-14 09:05:57.848273 7f8f4608a700 mds2.locker eval_gather (ifile sync->lock) on [inode 10000000002 [...2,head] /filestore/dchurchill/ auth{0=1,1=1,3=1,4=1,5=1,6=1,7=1} v53649 ap=4 f(v49 m2011-07-12 13:58:30.614248 9=3+6) n(v8429 rc2011-07-12 13:58:30.614248 b81985828395 2054=1788+266) (isnap sync r=3) (inest mix dirty) (ifile sync->lock) (iversion lock) caps={210471=pAsLsXs/-@0,211361=pAsLsXs/-@0,278413=pAsLsXs/-@0,282283=pAsLsXs/p@0,282921=pAsLsXs/-@0} | dirtyscattered request lock dirfrag caps replicated dirty waiter authpin 0x392f3c8]
2011-07-14 09:05:57.848278 7f8f4608a700 mds2.locker next state is lock issued/allows loner /cb xlocker /cb other /cb
2011-07-14 09:05:57.848292 7f8f4608a700 mds2.locker eval_gather finished gather on (ifile sync->lock) on [inode 10000000002 [...2,head] /filestore/dchurchill/ auth{0=1,1=1,3=1,4=1,5=1,6=1,7=1} v53649 ap=4 f(v49 m2011-07-12 13:58:30.614248 9=3+6) n(v8429 rc2011-07-12 13:58:30.614248 b81985828395 2054=1788+266) (isnap sync r=3) (inest mix dirty) (ifile sync->lock) (iversion lock) caps={210471=pAsLsXs/-@0,211361=pAsLsXs/-@0,278413=pAsLsXs/-@0,282283=pAsLsXs/p@0,282921=pAsLsXs/-@0} | dirtyscattered request lock dirfrag caps replicated dirty waiter authpin 0x392f3c8]
2011-07-14 09:05:57.848306 7f8f4608a700 mds2.cache.ino(10000000002) auth_unpin by 0x392fb20 on [inode 10000000002 [...2,head] /filestore/dchurchill/ auth{0=1,1=1,3=1,4=1,5=1,6=1,7=1} v53649 ap=3 f(v49 m2011-07-12 13:58:30.614248 9=3+6) n(v8429 rc2011-07-12 13:58:30.614248 b81985828395 2054=1788+266) (isnap sync r=3) (inest mix dirty) (ifile lock) (iversion lock) caps={210471=pAsLsXs/-@0,211361=pAsLsXs/-@0,278413=pAsLsXs/-@0,282283=pAsLsXs/p@0,282921=pAsLsXs/-@0} | dirtyscattered request lock dirfrag caps replicated dirty waiter authpin 0x392f3c8] now 3+1
2011-07-14 09:05:57.848317 7f8f4608a700 mds2.cache.dir(10000000000) adjust_nested_auth_pins -1/-1 on [dir 10000000000 /filestore/ [2,head] auth{0=1,1=1,3=1,4=1,5=1,6=1,7=1} v=53650 cv=0/0 dir_auth=2 ap=0+4+6 state=1610612738|complete f(v15 m2011-07-01 09:57:40.325579 5=0+5) n(v3943 rc2011-07-12 15:50:54.418743 b209559383922 10870=9500+1370) hs=5+10,ss=0+0 dirty=5 | child subtree replicated dirty 0x38deba8] by 0x392f3c8 count now 0 + 6
2011-07-14 09:05:57.848324 7f8f4608a700 mds2.server dispatch_client_request client_request(client282921:29 mkdir #10000000002/incoming) v1
2011-07-14 09:05:57.848328 7f8f4608a700 mds2.server rdlock_path_xlock_dentry request(client282921:29 cr=0x37416c0) #10000000002/incoming
2011-07-14 09:05:57.848333 7f8f4608a700 mds2.server traverse_to_auth_dir dirpath #10000000002 dname incoming
2011-07-14 09:05:57.848336 7f8f4608a700 mds2.cache traverse: opening base ino 10000000002 snap head
2011-07-14 09:05:57.848339 7f8f4608a700 mds2.cache path_traverse finish on snapid head
2011-07-14 09:05:57.848349 7f8f4608a700 mds2.server traverse_to_auth_dir [dir 10000000002 /filestore/dchurchill/ [2,head] auth{0=1,1=1,3=1,4=1,5=1,6=1,7=1} v=87628 cv=0/0 ap=0+2+2 state=1610612738|complete f(v49 m2011-07-12 13:58:30.614248 9=3+6) n(v8429 rc2011-07-12 13:58:30.614248 b81985828395 2054=1788+266) hs=9+7,ss=0+0 dirty=8 | child replicated dirty 0x25dcb48]
2011-07-14 09:05:57.848360 7f8f4608a700 mds2.server rdlock_path_xlock_dentry dir [dir 10000000002 /filestore/dchurchill/ [2,head] auth{0=1,1=1,3=1,4=1,5=1,6=1,7=1} v=87628 cv=0/0 ap=0+2+2 state=1610612738|complete f(v49 m2011-07-12 13:58:30.614248 9=3+6) n(v8429 rc2011-07-12 13:58:30.614248 b81985828395 2054=1788+266) hs=9+7,ss=0+0 dirty=8 | child replicated dirty 0x25dcb48]
2011-07-14 09:05:57.848368 7f8f4608a700 mds2.server prepare_null_dentry incoming in [dir 10000000002 /filestore/dchurchill/ [2,head] auth{0=1,1=1,3=1,4=1,5=1,6=1,7=1} v=87628 cv=0/0 ap=0+2+2 state=1610612738|complete f(v49 m2011-07-12 13:58:30.614248 9=3+6) n(v8429 rc2011-07-12 13:58:30.614248 b81985828395 2054=1788+266) hs=9+7,ss=0+0 dirty=8 | child replicated dirty 0x25dcb48]
2011-07-14 09:05:57.848372 7f8f4608a700 mds2.cache.dir(10000000002) lookup (head, 'incoming')
2011-07-14 09:05:57.848376 7f8f4608a700 mds2.cache.dir(10000000002) hit -> (incoming,head)
2011-07-14 09:05:57.848380 7f8f4608a700 mds2.locker acquire_locks request(client282921:29 cr=0x37416c0)
2011-07-14 09:05:57.848388 7f8f4608a700 mds2.locker must xlock (dn xlock x=1 by 0x25b2040) [dentry #1/filestore/dchurchill/incoming [2,head] auth NULL (dn xlock x=1 by 0x25b2040) (dversion lock w=1 last_client=282921) pv=0 v=87623 ap=2+0 inode=0 state=new | lock authpin 0x2648d50]
2011-07-14 09:05:57.848395 7f8f4608a700 mds2.locker must wrlock (dversion lock w=1 last_client=282921) [dentry #1/filestore/dchurchill/incoming [2,head] auth NULL (dn xlock x=1 by 0x25b2040) (dversion lock w=1 last_client=282921) pv=0 v=87623 ap=2+0 inode=0 state=new | lock authpin 0x2648d50]
2011-07-14 09:05:57.848409 7f8f4608a700 mds2.locker must wrlock (ifile lock) [inode 10000000002 [...2,head] /filestore/dchurchill/ auth{0=1,1=1,3=1,4=1,5=1,6=1,7=1} v53649 ap=3 f(v49 m2011-07-12 13:58:30.614248 9=3+6) n(v8429 rc2011-07-12 13:58:30.614248 b81985828395 2054=1788+266) (isnap sync r=3) (inest mix dirty) (ifile lock) (iversion lock) caps={210471=pAsLsXs/-@0,211361=pAsLsXs/-@0,278413=pAsLsXs/-@0,282283=pAsLsXs/p@0,282921=pAsLsXs/-@0} | dirtyscattered request lock dirfrag caps replicated dirty authpin 0x392f3c8]
2011-07-14 09:05:57.848422 7f8f4608a700 mds2.locker must wrlock (inest mix dirty) [inode 10000000002 [...2,head] /filestore/dchurchill/ auth{0=1,1=1,3=1,4=1,5=1,6=1,7=1} v53649 ap=3 f(v49 m2011-07-12 13:58:30.614248 9=3+6) n(v8429 rc2011-07-12 13:58:30.614248 b81985828395 2054=1788+266) (isnap sync r=3) (inest mix dirty) (ifile lock) (iversion lock) caps={210471=pAsLsXs/-@0,211361=pAsLsXs/-@0,278413=pAsLsXs/-@0,282283=pAsLsXs/p@0,282921=pAsLsXs/-@0} | dirtyscattered request lock dirfrag caps replicated dirty authpin 0x392f3c8]
2011-07-14 09:05:57.848430 7f8f4608a700 mds2.locker must rdlock (isnap sync r=4) [inode 1 [...2,head] / rep@0.1 v23316 snaprealm=0x25d0900 f(v6 m2011-07-08 17:02:14.145857 4=0+4) n(v791 rc2011-07-12 15:50:54.418743 b562750828083 10885=9507+1378)/n(v0 1=0+1) (isnap sync r=4) (inest mix) (iversion lock) | lock dirfrag 0x25bf868]
2011-07-14 09:05:57.848438 7f8f4608a700 mds2.locker must rdlock (isnap sync r=4) [inode 10000000000 [...2,head] /filestore/ rep@0.1 v79518 f(v15 m2011-07-01 09:57:40.325579 5=0+5) n(v3943 rc2011-07-12 15:50:54.418743 b209559383922 10870=9500+1370) (isnap sync r=4) (inest mix dirty flushed) (iversion lock) | dirtyscattered lock dirfrag 0x25c00d0]
2011-07-14 09:05:57.848444 7f8f4608a700 mds2.locker must rdlock (dn xlock x=1 by 0x25b2040) [dentry #1/filestore/dchurchill/incoming [2,head] auth NULL (dn xlock x=1 by 0x25b2040) (dversion lock w=1 last_client=282921) pv=0 v=87623 ap=2+0 inode=0 state=new | lock authpin 0x2648d50]
2011-07-14 09:05:57.848457 7f8f4608a700 mds2.locker must rdlock (iauth sync) [inode 10000000002 [...2,head] /filestore/dchurchill/ auth{0=1,1=1,3=1,4=1,5=1,6=1,7=1} v53649 ap=3 f(v49 m2011-07-12 13:58:30.614248 9=3+6) n(v8429 rc2011-07-12 13:58:30.614248 b81985828395 2054=1788+266) (isnap sync r=3) (inest mix dirty) (ifile lock) (iversion lock) caps={210471=pAsLsXs/-@0,211361=pAsLsXs/-@0,278413=pAsLsXs/-@0,282283=pAsLsXs/p@0,282921=pAsLsXs/-@0} | dirtyscattered request lock dirfrag caps replicated dirty authpin 0x392f3c8]
2011-07-14 09:05:57.848473 7f8f4608a700 mds2.locker must rdlock (isnap sync r=3) [inode 10000000002 [...2,head] /filestore/dchurchill/ auth{0=1,1=1,3=1,4=1,5=1,6=1,7=1} v53649 ap=3 f(v49 m2011-07-12 13:58:30.614248 9=3+6) n(v8429 rc2011-07-12 13:58:30.614248 b81985828395 2054=1788+266) (isnap sync r=3) (inest mix dirty) (ifile lock) (iversion lock) caps={210471=pAsLsXs/-@0,211361=pAsLsXs/-@0,278413=pAsLsXs/-@0,282283=pAsLsXs/p@0,282921=pAsLsXs/-@0} | dirtyscattered request lock dirfrag caps replicated dirty authpin 0x392f3c8]
2011-07-14 09:05:57.848480 7f8f4608a700 mds2.locker must authpin [dentry #1/filestore/dchurchill/incoming [2,head] auth NULL (dn xlock x=1 by 0x25b2040) (dversion lock w=1 last_client=282921) pv=0 v=87623 ap=2+0 inode=0 state=new | lock authpin 0x2648d50]
2011-07-14 09:05:57.848485 7f8f4608a700 mds2.locker must authpin [dentry #1/filestore/dchurchill/incoming [2,head] auth NULL (dn xlock x=1 by 0x25b2040) (dversion lock w=1 last_client=282921) pv=0 v=87623 ap=2+0 inode=0 state=new | lock authpin 0x2648d50]
2011-07-14 09:05:57.848498 7f8f4608a700 mds2.locker must authpin [inode 10000000002 [...2,head] /filestore/dchurchill/ auth{0=1,1=1,3=1,4=1,5=1,6=1,7=1} v53649 ap=3 f(v49 m2011-07-12 13:58:30.614248 9=3+6) n(v8429 rc2011-07-12 13:58:30.614248 b81985828395 2054=1788+266) (isnap sync r=3) (inest mix dirty) (ifile lock) (iversion lock) caps={210471=pAsLsXs/-@0,211361=pAsLsXs/-@0,278413=pAsLsXs/-@0,282283=pAsLsXs/p@0,282921=pAsLsXs/-@0} | dirtyscattered request lock dirfrag caps replicated dirty authpin 0x392f3c8]
2011-07-14 09:05:57.848510 7f8f4608a700 mds2.locker must authpin [inode 10000000002 [...2,head] /filestore/dchurchill/ auth{0=1,1=1,3=1,4=1,5=1,6=1,7=1} v53649 ap=3 f(v49 m2011-07-12 13:58:30.614248 9=3+6) n(v8429 rc2011-07-12 13:58:30.614248 b81985828395 2054=1788+266) (isnap sync r=3) (inest mix dirty) (ifile lock) (iversion lock) caps={210471=pAsLsXs/-@0,211361=pAsLsXs/-@0,278413=pAsLsXs/-@0,282283=pAsLsXs/p@0,282921=pAsLsXs/-@0} | dirtyscattered request lock dirfrag caps replicated dirty authpin 0x392f3c8]
2011-07-14 09:05:57.848523 7f8f4608a700 mds2.locker must authpin [inode 10000000002 [...2,head] /filestore/dchurchill/ auth{0=1,1=1,3=1,4=1,5=1,6=1,7=1} v53649 ap=3 f(v49 m2011-07-12 13:58:30.614248 9=3+6) n(v8429 rc2011-07-12 13:58:30.614248 b81985828395 2054=1788+266) (isnap sync r=3) (inest mix dirty) (ifile lock) (iversion lock) caps={210471=pAsLsXs/-@0,211361=pAsLsXs/-@0,278413=pAsLsXs/-@0,282283=pAsLsXs/p@0,282921=pAsLsXs/-@0} | dirtyscattered request lock dirfrag caps replicated dirty authpin 0x392f3c8]
2011-07-14 09:05:57.848536 7f8f4608a700 mds2.locker must authpin [inode 10000000002 [...2,head] /filestore/dchurchill/ auth{0=1,1=1,3=1,4=1,5=1,6=1,7=1} v53649 ap=3 f(v49 m2011-07-12 13:58:30.614248 9=3+6) n(v8429 rc2011-07-12 13:58:30.614248 b81985828395 2054=1788+266) (isnap sync r=3) (inest mix dirty) (ifile lock) (iversion lock) caps={210471=pAsLsXs/-@0,211361=pAsLsXs/-@0,278413=pAsLsXs/-@0,282283=pAsLsXs/p@0,282921=pAsLsXs/-@0} | dirtyscattered request lock dirfrag caps replicated dirty authpin 0x392f3c8]
2011-07-14 09:05:57.848541 7f8f4608a700 mds2.locker already auth_pinned [dentry #1/filestore/dchurchill/incoming [2,head] auth NULL (dn xlock x=1 by 0x25b2040) (dversion lock w=1 last_client=282921) pv=0 v=87623 ap=2+0 inode=0 state=new | lock authpin 0x2648d50]
2011-07-14 09:05:57.848547 7f8f4608a700 mds2.locker already auth_pinned [dentry #1/filestore/dchurchill/incoming [2,head] auth NULL (dn xlock x=1 by 0x25b2040) (dversion lock w=1 last_client=282921) pv=0 v=87623 ap=2+0 inode=0 state=new | lock authpin 0x2648d50]
2011-07-14 09:05:57.848559 7f8f4608a700 mds2.locker already auth_pinned [inode 10000000002 [...2,head] /filestore/dchurchill/ auth{0=1,1=1,3=1,4=1,5=1,6=1,7=1} v53649 ap=3 f(v49 m2011-07-12 13:58:30.614248 9=3+6) n(v8429 rc2011-07-12 13:58:30.614248 b81985828395 2054=1788+266) (isnap sync r=3) (inest mix dirty) (ifile lock) (iversion lock) caps={210471=pAsLsXs/-@0,211361=pAsLsXs/-@0,278413=pAsLsXs/-@0,282283=pAsLsXs/p@0,282921=pAsLsXs/-@0} | dirtyscattered request lock dirfrag caps replicated dirty authpin 0x392f3c8]
2011-07-14 09:05:57.848574 7f8f4608a700 mds2.locker already auth_pinned [inode 10000000002 [...2,head] /filestore/dchurchill/ auth{0=1,1=1,3=1,4=1,5=1,6=1,7=1} v53649 ap=3 f(v49 m2011-07-12 13:58:30.614248 9=3+6) n(v8429 rc2011-07-12 13:58:30.614248 b81985828395 2054=1788+266) (isnap sync r=3) (inest mix dirty) (ifile lock) (iversion lock) caps={210471=pAsLsXs/-@0,211361=pAsLsXs/-@0,278413=pAsLsXs/-@0,282283=pAsLsXs/p@0,282921=pAsLsXs/-@0} | dirtyscattered request lock dirfrag caps replicated dirty authpin 0x392f3c8]
2011-07-14 09:05:57.848587 7f8f4608a700 mds2.locker already auth_pinned [inode 10000000002 [...2,head] /filestore/dchurchill/ auth{0=1,1=1,3=1,4=1,5=1,6=1,7=1} v53649 ap=3 f(v49 m2011-07-12 13:58:30.614248 9=3+6) n(v8429 rc2011-07-12 13:58:30.614248 b81985828395 2054=1788+266) (isnap sync r=3) (inest mix dirty) (ifile lock) (iversion lock) caps={210471=pAsLsXs/-@0,211361=pAsLsXs/-@0,278413=pAsLsXs/-@0,282283=pAsLsXs/p@0,282921=pAsLsXs/-@0} | dirtyscattered request lock dirfrag caps replicated dirty authpin 0x392f3c8]
2011-07-14 09:05:57.848599 7f8f4608a700 mds2.locker already auth_pinned [inode 10000000002 [...2,head] /filestore/dchurchill/ auth{0=1,1=1,3=1,4=1,5=1,6=1,7=1} v53649 ap=3 f(v49 m2011-07-12 13:58:30.614248 9=3+6) n(v8429 rc2011-07-12 13:58:30.614248 b81985828395 2054=1788+266) (isnap sync r=3) (inest mix dirty) (ifile lock) (iversion lock) caps={210471=pAsLsXs/-@0,211361=pAsLsXs/-@0,278413=pAsLsXs/-@0,282283=pAsLsXs/p@0,282921=pAsLsXs/-@0} | dirtyscattered request lock dirfrag caps replicated dirty authpin 0x392f3c8]
2011-07-14 09:05:57.848605 7f8f4608a700 mds2.locker already wrlocked (dversion lock w=1 last_client=282921) [dentry #1/filestore/dchurchill/incoming [2,head] auth NULL (dn xlock x=1 by 0x25b2040) (dversion lock w=1 last_client=282921) pv=0 v=87623 ap=2+0 inode=0 state=new | lock authpin 0x2648d50]
2011-07-14 09:05:57.848611 7f8f4608a700 mds2.locker already xlocked (dn xlock x=1 by 0x25b2040) [dentry #1/filestore/dchurchill/incoming [2,head] auth NULL (dn xlock x=1 by 0x25b2040) (dversion lock w=1 last_client=282921) pv=0 v=87623 ap=2+0 inode=0 state=new | lock authpin 0x2648d50]
2011-07-14 09:05:57.848620 7f8f4608a700 mds2.locker already rdlocked (isnap sync r=4) [inode 1 [...2,head] / rep@0.1 v23316 snaprealm=0x25d0900 f(v6 m2011-07-08 17:02:14.145857 4=0+4) n(v791 rc2011-07-12 15:50:54.418743 b562750828083 10885=9507+1378)/n(v0 1=0+1) (isnap sync r=4) (inest mix) (iversion lock) | lock dirfrag 0x25bf868]
2011-07-14 09:05:57.848627 7f8f4608a700 mds2.locker already rdlocked (isnap sync r=4) [inode 10000000000 [...2,head] /filestore/ rep@0.1 v79518 f(v15 m2011-07-01 09:57:40.325579 5=0+5) n(v3943 rc2011-07-12 15:50:54.418743 b209559383922 10870=9500+1370) (isnap sync r=4) (inest mix dirty flushed) (iversion lock) | dirtyscattered lock dirfrag 0x25c00d0]
2011-07-14 09:05:57.848640 7f8f4608a700 mds2.locker already rdlocked (isnap sync r=3) [inode 10000000002 [...2,head] /filestore/dchurchill/ auth{0=1,1=1,3=1,4=1,5=1,6=1,7=1} v53649 ap=3 f(v49 m2011-07-12 13:58:30.614248 9=3+6) n(v8429 rc2011-07-12 13:58:30.614248 b81985828395 2054=1788+266) (isnap sync r=3) (inest mix dirty) (ifile lock) (iversion lock) caps={210471=pAsLsXs/-@0,211361=pAsLsXs/-@0,278413=pAsLsXs/-@0,282283=pAsLsXs/p@0,282921=pAsLsXs/-@0} | dirtyscattered request lock dirfrag caps replicated dirty authpin 0x392f3c8]
2011-07-14 09:05:57.848654 7f8f4608a700 mds2.locker wrlock_start (ifile lock) on [inode 10000000002 [...2,head] /filestore/dchurchill/ auth{0=1,1=1,3=1,4=1,5=1,6=1,7=1} v53649 ap=3 f(v49 m2011-07-12 13:58:30.614248 9=3+6) n(v8429 rc2011-07-12 13:58:30.614248 b81985828395 2054=1788+266) (isnap sync r=3) (inest mix dirty) (ifile lock) (iversion lock) caps={210471=pAsLsXs/-@0,211361=pAsLsXs/-@0,278413=pAsLsXs/-@0,282283=pAsLsXs/p@0,282921=pAsLsXs/-@0} | dirtyscattered request lock dirfrag caps replicated dirty authpin 0x392f3c8]
2011-07-14 09:05:57.848670 7f8f4608a700 mds2.locker got wrlock on (ifile lock w=1) [inode 10000000002 [...2,head] /filestore/dchurchill/ auth{0=1,1=1,3=1,4=1,5=1,6=1,7=1} v53649 ap=3 f(v49 m2011-07-12 13:58:30.614248 9=3+6) n(v8429 rc2011-07-12 13:58:30.614248 b81985828395 2054=1788+266) (isnap sync r=3) (inest mix dirty) (ifile lock w=1) (iversion lock) caps={210471=pAsLsXs/-@0,211361=pAsLsXs/-@0,278413=pAsLsXs/-@0,282283=pAsLsXs/p@0,282921=pAsLsXs/-@0} | dirtyscattered request lock dirfrag caps replicated dirty authpin 0x392f3c8]
2011-07-14 09:05:57.848683 7f8f4608a700 mds2.locker rdlock_start on (iauth sync) on [inode 10000000002 [...2,head] /filestore/dchurchill/ auth{0=1,1=1,3=1,4=1,5=1,6=1,7=1} v53649 ap=3 f(v49 m2011-07-12 13:58:30.614248 9=3+6) n(v8429 rc2011-07-12 13:58:30.614248 b81985828395 2054=1788+266) (isnap sync r=3) (inest mix dirty) (ifile lock w=1) (iversion lock) caps={210471=pAsLsXs/-@0,211361=pAsLsXs/-@0,278413=pAsLsXs/-@0,282283=pAsLsXs/p@0,282921=pAsLsXs/-@0} | dirtyscattered request lock dirfrag caps replicated dirty authpin 0x392f3c8]
2011-07-14 09:05:57.848697 7f8f4608a700 mds2.locker got rdlock on (iauth sync r=1) [inode 10000000002 [...2,head] /filestore/dchurchill/ auth{0=1,1=1,3=1,4=1,5=1,6=1,7=1} v53649 ap=3 f(v49 m2011-07-12 13:58:30.614248 9=3+6) n(v8429 rc2011-07-12 13:58:30.614248 b81985828395 2054=1788+266) (iauth sync r=1) (isnap sync r=3) (inest mix dirty) (ifile lock w=1) (iversion lock) caps={210471=pAsLsXs/-@0,211361=pAsLsXs/-@0,278413=pAsLsXs/-@0,282283=pAsLsXs/p@0,282921=pAsLsXs/-@0} | dirtyscattered request lock dirfrag caps replicated dirty authpin 0x392f3c8]
2011-07-14 09:05:57.848710 7f8f4608a700 mds2.locker wrlock_start (inest mix dirty) on [inode 10000000002 [...2,head] /filestore/dchurchill/ auth{0=1,1=1,3=1,4=1,5=1,6=1,7=1} v53649 ap=3 f(v49 m2011-07-12 13:58:30.614248 9=3+6) n(v8429 rc2011-07-12 13:58:30.614248 b81985828395 2054=1788+266) (iauth sync r=1) (isnap sync r=3) (inest mix dirty) (ifile lock w=1) (iversion lock) caps={210471=pAsLsXs/-@0,211361=pAsLsXs/-@0,278413=pAsLsXs/-@0,282283=pAsLsXs/p@0,282921=pAsLsXs/-@0} | dirtyscattered request lock dirfrag caps replicated dirty authpin 0x392f3c8]
2011-07-14 09:05:57.848736 7f8f4608a700 mds2.locker got wrlock on (inest mix w=1 dirty) [inode 10000000002 [...2,head] /filestore/dchurchill/ auth{0=1,1=1,3=1,4=1,5=1,6=1,7=1} v53649 ap=3 f(v49 m2011-07-12 13:58:30.614248 9=3+6) n(v8429 rc2011-07-12 13:58:30.614248 b81985828395 2054=1788+266) (iauth sync r=1) (isnap sync r=3) (inest mix w=1 dirty) (ifile lock w=1) (iversion lock) caps={210471=pAsLsXs/-@0,211361=pAsLsXs/-@0,278413=pAsLsXs/-@0,282283=pAsLsXs/p@0,282921=pAsLsXs/-@0} | dirtyscattered request lock dirfrag caps replicated dirty authpin 0x392f3c8]
2011-07-14 09:05:57.848753 7f8f4608a700 mds2.inotable: project_alloc_id 0 to []/[]
./include/interval_set.h: In function 'T interval_set<T>::range_start() const [with T = inodeno_t]', in thread '0x7f8f4608a700'
./include/interval_set.h: 290: FAILED assert(!empty())
ceph version 0.31 (commit:9019c6ce64053ad515a493e912e2e63ba9b8e278)
1: /usr/bin/cmds() [0x49305e]
2: (InoTable::project_alloc_id(inodeno_t)+0x408) [0x636728]
3: (Server::prepare_new_inode(MDRequest*, CDir*, inodeno_t, unsigned int, ceph_file_layout*)+0x9cb) [0x4fba1b]
4: (Server::handle_client_mkdir(MDRequest*)+0x2be) [0x50746e]
5: (Server::dispatch_client_request(MDRequest*)+0x4eb) [0x5183cb]
6: (MDCache::dispatch_request(MDRequest*)+0x41) [0x531571]
7: (C_MDS_RetryRequest::finish(int)+0x11) [0x51d581]
8: (finish_contexts(CephContext*, std::list<Context*, std::allocator<Context*> >&, int)+0xc2) [0x4ba4e2]
9: (SimpleLock::finish_waiters(unsigned long, int)+0xad) [0x5c506d]
10: (Locker::eval_gather(SimpleLock*, bool, bool*, std::list<Context*, std::allocator<Context*> >*)+0x126f) [0x5b34ef]
11: (Locker::handle_file_lock(ScatterLock*, MLock*)+0xa02) [0x5b4232]
12: (Locker::handle_lock(MLock*)+0x1c6) [0x5b5446]
13: (MDS::handle_deferrable_message(Message*)+0x69f) [0x4a670f]
14: (MDS::_dispatch(Message*)+0x15c3) [0x4b6fa3]
15: (MDS::ms_dispatch(Message*)+0x57) [0x4b7617]
16: (SimpleMessenger::dispatch_entry()+0x7bb) [0x69f0fb]
17: (SimpleMessenger::DispatchThread::entry()+0x1c) [0x496e8c]
18: (()+0x7d60) [0x7f8f48f4cd60]
19: (clone()+0x6d) [0x7f8f47b7ae2d]
ceph version 0.31 (commit:9019c6ce64053ad515a493e912e2e63ba9b8e278)
1: /usr/bin/cmds() [0x49305e]
2: (InoTable::project_alloc_id(inodeno_t)+0x408) [0x636728]
3: (Server::prepare_new_inode(MDRequest*, CDir*, inodeno_t, unsigned int, ceph_file_layout*)+0x9cb) [0x4fba1b]
4: (Server::handle_client_mkdir(MDRequest*)+0x2be) [0x50746e]
5: (Server::dispatch_client_request(MDRequest*)+0x4eb) [0x5183cb]
6: (MDCache::dispatch_request(MDRequest*)+0x41) [0x531571]
7: (C_MDS_RetryRequest::finish(int)+0x11) [0x51d581]
8: (finish_contexts(CephContext*, std::list<Context*, std::allocator<Context*> >&, int)+0xc2) [0x4ba4e2]
9: (SimpleLock::finish_waiters(unsigned long, int)+0xad) [0x5c506d]
10: (Locker::eval_gather(SimpleLock*, bool, bool*, std::list<Context*, std::allocator<Context*> >*)+0x126f) [0x5b34ef]
11: (Locker::handle_file_lock(ScatterLock*, MLock*)+0xa02) [0x5b4232]
12: (Locker::handle_lock(MLock*)+0x1c6) [0x5b5446]
13: (MDS::handle_deferrable_message(Message*)+0x69f) [0x4a670f]
14: (MDS::_dispatch(Message*)+0x15c3) [0x4b6fa3]
15: (MDS::ms_dispatch(Message*)+0x57) [0x4b7617]
16: (SimpleMessenger::dispatch_entry()+0x7bb) [0x69f0fb]
17: (SimpleMessenger::DispatchThread::entry()+0x1c) [0x496e8c]
18: (()+0x7d60) [0x7f8f48f4cd60]
19: (clone()+0x6d) [0x7f8f47b7ae2d]
*** Caught signal (Aborted) **
in thread 0x7f8f4608a700
ceph version 0.31 (commit:9019c6ce64053ad515a493e912e2e63ba9b8e278)
1: /usr/bin/cmds() [0x73cf14]
2: (()+0xf7e0) [0x7f8f48f547e0]
3: (gsignal()+0x35) [0x7f8f47adb795]
4: (abort()+0x17b) [0x7f8f47adcc0b]
5: (__gnu_cxx::__verbose_terminate_handler()+0x11d) [0x7f8f4835ee6d]
6: (()+0xbd016) [0x7f8f4835d016]
7: (()+0xbd043) [0x7f8f4835d043]
8: (()+0xbd13e) [0x7f8f4835d13e]
9: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x175) [0x6dc055]
10: /usr/bin/cmds() [0x49305e]
11: (InoTable::project_alloc_id(inodeno_t)+0x408) [0x636728]
12: (Server::prepare_new_inode(MDRequest*, CDir*, inodeno_t, unsigned int, ceph_file_layout*)+0x9cb) [0x4fba1b]
13: (Server::handle_client_mkdir(MDRequest*)+0x2be) [0x50746e]
14: (Server::dispatch_client_request(MDRequest*)+0x4eb) [0x5183cb]
15: (MDCache::dispatch_request(MDRequest*)+0x41) [0x531571]
16: (C_MDS_RetryRequest::finish(int)+0x11) [0x51d581]
17: (finish_contexts(CephContext*, std::list<Context*, std::allocator<Context*> >&, int)+0xc2) [0x4ba4e2]
18: (SimpleLock::finish_waiters(unsigned long, int)+0xad) [0x5c506d]
19: (Locker::eval_gather(SimpleLock*, bool, bool*, std::list<Context*, std::allocator<Context*> >*)+0x126f) [0x5b34ef]
20: (Locker::handle_file_lock(ScatterLock*, MLock*)+0xa02) [0x5b4232]
21: (Locker::handle_lock(MLock*)+0x1c6) [0x5b5446]
22: (MDS::handle_deferrable_message(Message*)+0x69f) [0x4a670f]
23: (MDS::_dispatch(Message*)+0x15c3) [0x4b6fa3]
24: (MDS::ms_dispatch(Message*)+0x57) [0x4b7617]
25: (SimpleMessenger::dispatch_entry()+0x7bb) [0x69f0fb]
26: (SimpleMessenger::DispatchThread::entry()+0x1c) [0x496e8c]
27: (()+0x7d60) [0x7f8f48f4cd60]
28: (clone()+0x6d) [0x7f8f47b7ae2d]
    (1-1/1)