client.log

Running main() from gtest_main.cc
[==========] Running 2 tests from 1 test case.
[----------] Global test environment set-up.
[----------] 2 tests from LibCephFS
[ RUN      ] LibCephFS.Open_empty_component
2012-09-21 08:40:10.955627 7fbb04158700 10 client.-1 ms_handle_connect on 192.168.106.221:6789/0
2012-09-21 08:40:10.956574 7fbb09889760  2 client.4107 mounted: have osdmap 0 and mdsmap 0
2012-09-21 08:40:10.956676 7fbb09889760 10 client.4107  target mds.0 not active, waiting for new mdsmap
2012-09-21 08:40:10.958020 7fbb04158700  1 client.4107 handle_mds_map epoch 10
2012-09-21 08:40:10.958317 7fbb09889760 10 client.4107 opening session to mds.0
2012-09-21 08:40:10.958486 7fbb09889760 10 client.4107 waiting for session to mds.0 to open
2012-09-21 08:40:10.958965 7fbb04158700 10 client.4107 ms_handle_connect on 192.168.106.221:6803/7026
2012-09-21 08:40:10.986170 7fbb04158700 10 client.4107 handle_client_session client_session(open) v1
2012-09-21 08:40:10.986202 7fbb04158700 10 client.4107 renew_caps mds.0
2012-09-21 08:40:10.986245 7fbb04158700 10 client.4107 connect_mds_targets for mds.0
2012-09-21 08:40:10.986317 7fbb09889760 10 client.4107 send_request rebuilding request 1 for mds.0
2012-09-21 08:40:10.986358 7fbb09889760 10 client.4107 send_request client_request(unknown.0:1 getattr pAsLsXsFs #1) v1 to mds.0
2012-09-21 08:40:10.986825 7fbb04158700 10 client.4107 handle_client_session client_session(renewcaps seq 1) v1
2012-09-21 08:40:10.987474 7fbb04158700 10 client.4107 insert_trace from 2012-09-21 08:40:10.986353 mds.0 is_target=1 is_dentry=0
2012-09-21 08:40:10.987494 7fbb04158700 10 client.4107  features 0x1fffff
2012-09-21 08:40:10.987499 7fbb04158700 10 client.4107 update_snap_trace len 48
2012-09-21 08:40:10.987540 7fbb04158700 10 client.4107 update_snap_trace snaprealm(1 nref=2 c=0 seq=0 parent=0 my_snaps=[] cached_snapc=0=[]) seq 1 > 0
2012-09-21 08:40:10.987573 7fbb04158700 10 client.4107  flushing caps on snaprealm(1 nref=2 c=0 seq=0 parent=0 my_snaps=[] cached_snapc=0=[])
2012-09-21 08:40:10.987603 7fbb04158700 10 client.4107 invalidate_snaprealm_and_children snaprealm(1 nref=2 c=0 seq=1 parent=0 my_snaps=[] cached_snapc=0=[])
2012-09-21 08:40:10.987623 7fbb04158700 10 client.4107  hrm  is_target=1 is_dentry=0
2012-09-21 08:40:10.987694 7fbb04158700 10 client.4107 update_inode_file_bits 1.head(ref=1 cap_refs={} open={} mode=40755 size=0 mtime=0.000000 caps=- 0x7fbafc0021d0) - mtime 2012-09-21 08:39:31.586845
2012-09-21 08:40:10.987764 7fbb04158700 10 client.4107 add_update_cap issued - -> pAsLsXsFs from mds.0 on 1.head(ref=1 cap_refs={} open={} mode=40755 size=0 mtime=2012-09-21 08:39:31.586845 caps=pAsLsXsFs(0=pAsLsXsFs) 0x7fbafc0021d0)
2012-09-21 08:40:10.987873 7fbb09889760 10 client.4107 root getattr result=0
2012-09-21 08:40:10.987898 7fbb09889760 10 client.4107 Client::mkdirs /open_test_7208
2012-09-21 08:40:10.987934 7fbb09889760 10 client.4107 _lookup on #1/open_test_7208
2012-09-21 08:40:10.987956 7fbb09889760 10 client.4107 choose_target_mds from caps on inode 1.head(ref=2 cap_refs={} open={} mode=40755 size=0 mtime=2012-09-21 08:39:31.586845 caps=pAsLsXsFs(0=pAsLsXsFs) 0x7fbafc0021d0)
2012-09-21 08:40:10.987987 7fbb09889760 10 client.4107 send_request rebuilding request 2 for mds.0
2012-09-21 08:40:10.988009 7fbb09889760 10 client.4107 send_request client_request(unknown.0:2 lookup #1/open_test_7208) v1 to mds.0
2012-09-21 08:40:10.988703 7fbb04158700 10 client.4107 insert_trace from 2012-09-21 08:40:10.987999 mds.0 is_target=0 is_dentry=1
2012-09-21 08:40:10.988712 7fbb04158700 10 client.4107  features 0x1fffff
2012-09-21 08:40:10.988715 7fbb04158700 10 client.4107 update_snap_trace len 48
2012-09-21 08:40:10.988723 7fbb04158700 10 client.4107 update_snap_trace snaprealm(1 nref=3 c=0 seq=1 parent=0 my_snaps=[] cached_snapc=0=[]) seq 1 <= 1 and same parent, SKIPPING
2012-09-21 08:40:10.988732 7fbb04158700 10 client.4107  hrm  is_target=0 is_dentry=1
2012-09-21 08:40:10.988768 7fbb04158700 10 client.4107 add_update_cap issued pAsLsXsFs -> pAsLsXsFs from mds.0 on 1.head(ref=2 cap_refs={} open={} mode=40755 size=0 mtime=2012-09-21 08:39:31.586845 caps=pAsLsXsFs(0=pAsLsXsFs) 0x7fbafc0021d0)
2012-09-21 08:40:10.988928 7fbb09889760 10 client.4107 _lookup res is -2
2012-09-21 08:40:10.988937 7fbb09889760 10 client.4107 _lookup 1.head(ref=2 cap_refs={} open={} mode=40755 size=0 mtime=2012-09-21 08:39:31.586845 caps=pAsLsXsFs(0=pAsLsXsFs) 0x7fbafc0021d0) open_test_7208 = -2
2012-09-21 08:40:10.988972 7fbb09889760  3 client.4107 _mkdir(1 open_test_7208, 0777, uid -1, gid -1)
2012-09-21 08:40:10.989082 7fbb09889760 10 client.4107 _mkdir: making request
2012-09-21 08:40:10.989097 7fbb09889760 10 client.4107 choose_target_mds from caps on inode 1.head(ref=3 cap_refs={} open={} mode=40755 size=0 mtime=2012-09-21 08:39:31.586845 caps=pAsLsXsFs(0=pAsLsXsFs) 0x7fbafc0021d0)
2012-09-21 08:40:10.989123 7fbb09889760 10 client.4107 send_request rebuilding request 3 for mds.0
2012-09-21 08:40:10.989162 7fbb09889760 10 client.4107 send_request client_request(unknown.0:3 mkdir #1/open_test_7208) v1 to mds.0
2012-09-21 08:40:11.028137 7fbb04158700 10 client.4107 insert_trace from 2012-09-21 08:40:10.989159 mds.0 is_target=1 is_dentry=1
2012-09-21 08:40:11.028145 7fbb04158700 10 client.4107  features 0x1fffff
2012-09-21 08:40:11.028148 7fbb04158700 10 client.4107 update_snap_trace len 48
2012-09-21 08:40:11.028156 7fbb04158700 10 client.4107 update_snap_trace snaprealm(1 nref=3 c=0 seq=1 parent=0 my_snaps=[] cached_snapc=0=[]) seq 1 <= 1 and same parent, SKIPPING
2012-09-21 08:40:11.028165 7fbb04158700 10 client.4107  hrm  is_target=1 is_dentry=1
2012-09-21 08:40:11.028201 7fbb04158700 10 client.4107 update_inode_file_bits 10000000000.head(ref=0 cap_refs={} open={} mode=40777 size=0 mtime=0.000000 caps=- 0x7fbafc0055c0) - mtime 2012-09-21 08:40:10.991530
2012-09-21 08:40:11.028226 7fbb04158700 10 client.4107 add_update_cap issued - -> pAsxLsXsxFsx from mds.0 on 10000000000.head(ref=0 cap_refs={} open={} mode=40777 size=0 mtime=2012-09-21 08:40:10.991530 caps=pAsxLsXsxFsx(0=pAsxLsXsxFsx) 0x7fbafc0055c0)
2012-09-21 08:40:11.028245 7fbb04158700 10 client.4107  marking I_COMPLETE on empty dir 10000000000.head(ref=0 cap_refs={} open={} mode=40777 size=0 mtime=2012-09-21 08:40:10.991530 caps=pAsxLsXsxFsx(0=pAsxLsXsxFsx) 0x7fbafc0055c0)
2012-09-21 08:40:11.028260 7fbb04158700 10 client.4107 update_inode_file_bits 1.head(ref=3 cap_refs={} open={} mode=40755 size=0 mtime=2012-09-21 08:39:31.586845 caps=pAsLsXs(0=pAsLsXs) 0x7fbafc0021d0) pAsLsXs mtime 2012-09-21 08:40:10.991530
2012-09-21 08:40:11.028285 7fbb04158700 10 client.4107 add_update_cap issued pAsLsXs -> pAsLsXs from mds.0 on 1.head(ref=3 cap_refs={} open={} mode=40755 size=0 mtime=2012-09-21 08:40:10.991530 caps=pAsLsXs(0=pAsLsXs) 0x7fbafc0021d0)
2012-09-21 08:40:11.028342 7fbb04158700 10 client.4107 got dentry lease on open_test_7208 dur 30000ms ttl 2012-09-21 08:40:40.989159
2012-09-21 08:40:11.028390 7fbb09889760 10 client.4107 _mkdir result is 0
2012-09-21 08:40:11.028401 7fbb09889760  3 client.4107 _mkdir(#1/open_test_7208, 0777) = 0
2012-09-21 08:40:11.028434 7fbb09889760 10 client.4107 _lookup 1.head(ref=3 cap_refs={} open={} mode=40755 size=0 mtime=2012-09-21 08:40:10.991530 caps=pAsLsXs(0=pAsLsXs) 0x7fbafc0021d0) open_test_7208 = 10000000000.head(ref=1 cap_refs={} open={} mode=40777 size=0 mtime=2012-09-21 08:40:10.991530 caps=pAsxLsXsxFsx(0=pAsxLsXsxFsx) COMPLETE parents=0x7fbafc003450 0x7fbafc0055c0)
2012-09-21 08:40:11.028487 7fbb09889760 10 client.4107 path_walk #1/open_test_7208
2012-09-21 08:40:11.028495 7fbb09889760 10 client.4107  0 1.head(ref=3 cap_refs={} open={} mode=40755 size=0 mtime=2012-09-21 08:40:10.991530 caps=pAsLsXs(0=pAsLsXs) 0x7fbafc0021d0) open_test_7208
2012-09-21 08:40:11.028516 7fbb09889760 10 client.4107 _lookup 1.head(ref=3 cap_refs={} open={} mode=40755 size=0 mtime=2012-09-21 08:40:10.991530 caps=pAsLsXs(0=pAsLsXs) 0x7fbafc0021d0) open_test_7208 = 10000000000.head(ref=1 cap_refs={} open={} mode=40777 size=0 mtime=2012-09-21 08:40:10.991530 caps=pAsxLsXsxFsx(0=pAsxLsXsxFsx) COMPLETE parents=0x7fbafc003450 0x7fbafc0055c0)
2012-09-21 08:40:11.028546 7fbb09889760 10 client.4107 _opendir 10000000000, our cache says the first dirfrag is *
2012-09-21 08:40:11.028551 7fbb09889760  3 client.4107 _opendir(10000000000) = 0 (0x7fbafc006b70)
2012-09-21 08:40:11.028562 7fbb09889760  3 client.4107 open enter(/open_test_7208//created_file_7208, 64,438) = 
2012-09-21 08:40:11.028601 7fbb09889760 10 client.4107 path_walk #1/open_test_7208//created_file_7208
2012-09-21 08:40:11.028613 7fbb09889760 10 client.4107  0 1.head(ref=3 cap_refs={} open={} mode=40755 size=0 mtime=2012-09-21 08:40:10.991530 caps=pAsLsXs(0=pAsLsXs) 0x7fbafc0021d0) open_test_7208
2012-09-21 08:40:11.028643 7fbb09889760 10 client.4107 _lookup 1.head(ref=3 cap_refs={} open={} mode=40755 size=0 mtime=2012-09-21 08:40:10.991530 caps=pAsLsXs(0=pAsLsXs) 0x7fbafc0021d0) open_test_7208 = 10000000000.head(ref=2 cap_refs={} open={} mode=40777 size=0 mtime=2012-09-21 08:40:10.991530 caps=pAsxLsXsxFsx(0=pAsxLsXsxFsx) COMPLETE parents=0x7fbafc003450 0x7fbafc0055c0)
2012-09-21 08:40:11.028674 7fbb09889760 10 client.4107  1 10000000000.head(ref=2 cap_refs={} open={} mode=40777 size=0 mtime=2012-09-21 08:40:10.991530 caps=pAsxLsXsxFsx(0=pAsxLsXsxFsx) COMPLETE parents=0x7fbafc003450 0x7fbafc0055c0) created_file_7208
2012-09-21 08:40:11.028689 7fbb09889760 10 client.4107 _lookup concluded ENOENT locally for 10000000000.head(ref=2 cap_refs={} open={} mode=40777 size=0 mtime=2012-09-21 08:40:10.991530 caps=pAsxLsXsxFsx(0=pAsxLsXsxFsx) COMPLETE parents=0x7fbafc003450 0x7fbafc0055c0) dn 'created_file_7208'
2012-09-21 08:40:11.028715 7fbb09889760 10 client.4107 path_walk #1/open_test_7208
2012-09-21 08:40:11.028718 7fbb09889760 10 client.4107  0 1.head(ref=3 cap_refs={} open={} mode=40755 size=0 mtime=2012-09-21 08:40:10.991530 caps=pAsLsXs(0=pAsLsXs) 0x7fbafc0021d0) open_test_7208
2012-09-21 08:40:11.028740 7fbb09889760 10 client.4107 _lookup 1.head(ref=3 cap_refs={} open={} mode=40755 size=0 mtime=2012-09-21 08:40:10.991530 caps=pAsLsXs(0=pAsLsXs) 0x7fbafc0021d0) open_test_7208 = 10000000000.head(ref=2 cap_refs={} open={} mode=40777 size=0 mtime=2012-09-21 08:40:10.991530 caps=pAsxLsXsxFsx(0=pAsxLsXsxFsx) COMPLETE parents=0x7fbafc003450 0x7fbafc0055c0)
2012-09-21 08:40:11.028766 7fbb09889760  3 client.4107 _create(10000000000 created_file_7208, 0666)
2012-09-21 08:40:11.028810 7fbb09889760 10 client.4107 choose_target_mds from caps on inode 10000000000.head(ref=3 cap_refs={} open={} mode=40777 size=0 mtime=2012-09-21 08:40:10.991530 caps=pAsxLsXsxFsx(0=pAsxLsXsxFsx) COMPLETE parents=0x7fbafc003450 0x7fbafc0055c0)
2012-09-21 08:40:11.028838 7fbb09889760 10 client.4107 send_request rebuilding request 4 for mds.0
2012-09-21 08:40:11.028860 7fbb09889760 10 client.4107 send_request client_request(unknown.0:4 create #10000000000/created_file_7208) v1 to mds.0
2012-09-21 08:40:11.030189 7fbb04158700 10 client.4107  mds.0 seq now 1
2012-09-21 08:40:11.030218 7fbb04158700  5 client.4107 handle_cap_grant on in 10000000000 mds.0 seq 3 caps now pAsLsXsxFsx was pAsxLsXsxFsx
2012-09-21 08:40:11.030250 7fbb04158700 10 client.4107 update_inode_file_bits 10000000000.head(ref=3 cap_refs={} open={} mode=40777 size=0 mtime=2012-09-21 08:40:10.991530 caps=pAsxLsXsxFsx(0=pAsxLsXsxFsx) COMPLETE parents=0x7fbafc003450 0x7fbafc0055c0) pAsxLsXsxFsx mtime 2012-09-21 08:40:10.991530
2012-09-21 08:40:11.030281 7fbb04158700 10 client.4107   revocation of Ax
2012-09-21 08:40:11.030289 7fbb04158700 10 client.4107 check_caps on 10000000000.head(ref=3 cap_refs={} open={} mode=40777 size=0 mtime=2012-09-21 08:40:10.991530 caps=pAsLsXsxFsx(0=pAsLsXsxFsx) COMPLETE parents=0x7fbafc003450 0x7fbafc0055c0) wanted - used - is_delayed=1
2012-09-21 08:40:11.030316 7fbb04158700 10 client.4107  cap mds.0 issued pAsLsXsxFsx implemented pAsxLsXsxFsx revoking Ax
2012-09-21 08:40:11.030324 7fbb04158700 10 client.4107 completed revocation of Ax
2012-09-21 08:40:11.030327 7fbb04158700 10 client.4107 send_cap 10000000000.head(ref=3 cap_refs={} open={} mode=40777 size=0 mtime=2012-09-21 08:40:10.991530 caps=pAsLsXsxFsx(0=pAsLsXsxFsx) COMPLETE parents=0x7fbafc003450 0x7fbafc0055c0) mds.0 seq 3 used - want - flush - retain pAsLsXsFs held pAsxLsXsxFsx revoking Ax dropping XxFx
2012-09-21 08:40:11.031422 7fbb04158700 10 client.4107 insert_trace from 2012-09-21 08:40:11.028857 mds.0 is_target=1 is_dentry=1
2012-09-21 08:40:11.031431 7fbb04158700 10 client.4107  features 0x1fffff
2012-09-21 08:40:11.031444 7fbb04158700 10 client.4107 update_snap_trace len 48
2012-09-21 08:40:11.031456 7fbb04158700 10 client.4107 update_snap_trace snaprealm(1 nref=4 c=0 seq=1 parent=0 my_snaps=[] cached_snapc=0=[]) seq 1 <= 1 and same parent, SKIPPING
2012-09-21 08:40:11.031473 7fbb04158700 10 client.4107  hrm  is_target=1 is_dentry=1
2012-09-21 08:40:11.031506 7fbb04158700 10 client.4107 update_inode_file_bits 10000000001.head(ref=0 cap_refs={} open={} mode=100666 size=0 mtime=0.000000 caps=- objectset[10000000001 ts 0/0 objects 0 dirty_or_tx 0] 0x7fbafc00a190) - mtime 2012-09-21 08:40:11.030810
2012-09-21 08:40:11.031534 7fbb04158700 10 client.4107 add_update_cap issued - -> pAsxLsXsxFscr from mds.0 on 10000000001.head(ref=0 cap_refs={} open={} mode=100666 size=0 mtime=2012-09-21 08:40:11.030810 caps=pAsxLsXsxFscr(0=pAsxLsXsxFscr) objectset[10000000001 ts 0/0 objects 0 dirty_or_tx 0] 0x7fbafc00a190)
2012-09-21 08:40:11.031558 7fbb04158700 10 client.4107 update_inode_file_bits 10000000000.head(ref=3 cap_refs={} open={} mode=40777 size=0 mtime=2012-09-21 08:40:10.991530 caps=pAsLsXsFs(0=pAsLsXsFs) COMPLETE parents=0x7fbafc003450 0x7fbafc0055c0) pAsLsXsFs mtime 2012-09-21 08:40:11.030810
2012-09-21 08:40:11.031580 7fbb04158700 10 client.4107 add_update_cap issued pAsLsXsFs -> pAsLsXsxFsx from mds.0 on 10000000000.head(ref=3 cap_refs={} open={} mode=40777 size=0 mtime=2012-09-21 08:40:11.030810 caps=pAsLsXsxFsx(0=pAsLsXsxFsx) COMPLETE parents=0x7fbafc003450 0x7fbafc0055c0)
2012-09-21 08:40:11.031712 7fbb09889760 10 client.4107 _lookup 10000000000.head(ref=3 cap_refs={} open={} mode=40777 size=0 mtime=2012-09-21 08:40:11.030810 caps=pAsLsXsxFsx(0=pAsLsXsxFsx) COMPLETE parents=0x7fbafc003450 0x7fbafc0055c0) created_file_7208 = 10000000001.head(ref=1 cap_refs={} open={} mode=100666 size=0 mtime=2012-09-21 08:40:11.030810 caps=pAsxLsXsxFscr(0=pAsxLsXsxFscr) objectset[10000000001 ts 0/0 objects 0 dirty_or_tx 0] parents=0x7fbafc002820 0x7fbafc00a190)
2012-09-21 08:40:11.031772 7fbb09889760 10 client.4107 _create_fh 10000000001 mode 1
2012-09-21 08:40:11.031777 7fbb09889760  3 client.4107 create(#10000000000/created_file_7208, 0666 layout 0 0 0 0) = 0
2012-09-21 08:40:11.031812 7fbb09889760  3 client.4107 open exit(#1/open_test_7208//created_file_7208, 64) = 10
2012-09-21 08:40:11.031826 7fbb09889760  3 client.4107 close enter(10)
2012-09-21 08:40:11.031831 7fbb09889760  5 client.4107 _release_fh 0x7fbafc00afd0 mode 1 on 10000000001.head(ref=2 cap_refs={} open={1=1} mode=100666 size=0 mtime=2012-09-21 08:40:11.030810 caps=pAsxLsXsxFscr(0=pAsxLsXsxFscr) objectset[10000000001 ts 0/0 objects 0 dirty_or_tx 0] parents=0x7fbafc002820 0x7fbafc00a190)
2012-09-21 08:40:11.031857 7fbb09889760 10 client.4107 _flush 10000000001.head(ref=2 cap_refs={} open={1=0} mode=100666 size=0 mtime=2012-09-21 08:40:11.030810 caps=pAsxLsXsxFscr(0=pAsxLsXsxFscr) objectset[10000000001 ts 0/0 objects 0 dirty_or_tx 0] parents=0x7fbafc002820 0x7fbafc00a190)
2012-09-21 08:40:11.031873 7fbb09889760 10 client.4107  nothing to flush
2012-09-21 08:40:11.031876 7fbb09889760 10 client.4107 check_caps on 10000000001.head(ref=2 cap_refs={} open={1=0} mode=100666 size=0 mtime=2012-09-21 08:40:11.030810 caps=pAsxLsXsxFscr(0=pAsxLsXsxFscr) objectset[10000000001 ts 0/0 objects 0 dirty_or_tx 0] parents=0x7fbafc002820 0x7fbafc00a190) wanted - used - is_delayed=0
2012-09-21 08:40:11.031894 7fbb09889760 10 client.4107 cap_delay_requeue on 10000000001.head(ref=2 cap_refs={} open={1=0} mode=100666 size=0 mtime=2012-09-21 08:40:11.030810 caps=pAsxLsXsxFscr(0=pAsxLsXsxFscr) objectset[10000000001 ts 0/0 objects 0 dirty_or_tx 0] parents=0x7fbafc002820 0x7fbafc00a190)
2012-09-21 08:40:11.031915 7fbb09889760 10 client.4107  cap mds.0 issued pAsxLsXsxFscr implemented pAsxLsXsxFscr revoking -
2012-09-21 08:40:11.031922 7fbb09889760 10 client.4107 delaying cap release
2012-09-21 08:40:11.031924 7fbb09889760 10 client.4107 put_inode on 10000000001.head(ref=2 cap_refs={} open={1=0} mode=100666 size=0 mtime=2012-09-21 08:40:11.030810 caps=pAsxLsXsxFscr(0=pAsxLsXsxFscr) objectset[10000000001 ts 0/0 objects 0 dirty_or_tx 0] parents=0x7fbafc002820 0x7fbafc00a190)
2012-09-21 08:40:11.031948 7fbb09889760  3 client.4107 close exit(10)
2012-09-21 08:40:11.031954 7fbb09889760  3 client.4107 closedir(0x7fbafc006b70) = 0
2012-09-21 08:40:11.031956 7fbb09889760 10 client.4107 _closedir(0x7fbafc006b70)
2012-09-21 08:40:11.031957 7fbb09889760 10 client.4107 _closedir detaching inode 0x7fbafc0055c0
2012-09-21 08:40:11.031959 7fbb09889760 10 client.4107 put_inode on 10000000000.head(ref=3 cap_refs={} open={} mode=40777 size=0 mtime=2012-09-21 08:40:11.030810 caps=pAsLsXsxFsx(0=pAsLsXsxFsx) COMPLETE parents=0x7fbafc003450 0x7fbafc0055c0)
2012-09-21 08:40:11.031975 7fbb09889760 10 client.4107 _readdir_drop_dirp_buffer 0x7fbafc006b70
2012-09-21 08:40:11.031981 7fbb09889760  2 client.4107 unmounting
2012-09-21 08:40:11.031982 7fbb09889760 10 client.4107 waiting on 1 requests
2012-09-21 08:40:11.956759 7fbb0515a700 10 client.4107 renew_caps()
2012-09-21 08:40:11.956792 7fbb0515a700 10 client.4107 renew_caps mds.0
2012-09-21 08:40:11.957634 7fbb04158700 10 client.4107 handle_client_session client_session(renewcaps seq 2) v1
2012-09-21 08:40:11.957664 7fbb04158700 10 client.4107 unmounting: trim pass, size was 2+3
2012-09-21 08:40:11.957699 7fbb04158700 10 client.4107 unmounting: trim pass, size still 2+3
2012-09-21 08:40:11.957713 7fbb04158700  1 client.4107 dump_cache
2012-09-21 08:40:11.957725 7fbb04158700  1 client.4107 dump_inode: DISCONNECTED inode 1 #1 ref 31.head(ref=3 cap_refs={} open={} mode=40755 size=0 mtime=2012-09-21 08:40:10.991530 caps=pAsLsXs(0=pAsLsXs) 0x7fbafc0021d0)
2012-09-21 08:40:11.957772 7fbb04158700  1 client.4107   dir 0x7fbafc003c20 size 1
2012-09-21 08:40:11.957788 7fbb04158700  1 client.4107    1 dn open_test_7208 0x7fbafc003450 ref 2
2012-09-21 08:40:11.957800 7fbb04158700  1 client.4107 dump_inode: inode 10000000000 #1/open_test_7208 ref 210000000000.head(ref=2 cap_refs={} open={} mode=40777 size=0 mtime=2012-09-21 08:40:11.030810 caps=pAsLsXsxFsx(0=pAsLsXsxFsx) COMPLETE parents=0x7fbafc003450 0x7fbafc0055c0)
2012-09-21 08:40:11.957826 7fbb04158700  1 client.4107   dir 0x7fbafc0042a0 size 1
2012-09-21 08:40:11.957829 7fbb04158700  1 client.4107    10000000000 dn created_file_7208 0x7fbafc002820 ref 2
2012-09-21 08:40:11.957838 7fbb04158700  1 client.4107 dump_inode: inode 10000000001 #1/open_test_7208/created_file_7208 ref 110000000001.head(ref=1 cap_refs={} open={1=0} mode=100666 size=0 mtime=2012-09-21 08:40:11.030810 caps=pAsxLsXsxFscr(0=pAsxLsXsxFscr) objectset[10000000001 ts 0/0 objects 0 dirty_or_tx 0] parents=0x7fbafc002820 0x7fbafc00a190)
2012-09-21 08:40:15.531783 7fbb04158700 10 client.4107 insert_trace from 2012-09-21 08:40:11.028857 mds.0 is_target=0 is_dentry=0
2012-09-21 08:40:15.531794 7fbb04158700 10 client.4107 insert_trace -- no trace
2012-09-21 08:40:15.531818 7fbb04158700 10 client.4107 unmounting: trim pass, size was 2+3
2012-09-21 08:40:15.531823 7fbb04158700 10 client.4107 unmounting: trim pass, size still 2+3
2012-09-21 08:40:15.531826 7fbb04158700  1 client.4107 dump_cache
2012-09-21 08:40:15.531837 7fbb04158700  1 client.4107 dump_inode: DISCONNECTED inode 1 #1 ref 31.head(ref=3 cap_refs={} open={} mode=40755 size=0 mtime=2012-09-21 08:40:10.991530 caps=pAsLsXs(0=pAsLsXs) 0x7fbafc0021d0)
2012-09-21 08:40:15.531872 7fbb04158700  1 client.4107   dir 0x7fbafc003c20 size 1
2012-09-21 08:40:15.531883 7fbb04158700  1 client.4107    1 dn open_test_7208 0x7fbafc003450 ref 2
2012-09-21 08:40:15.531893 7fbb04158700  1 client.4107 dump_inode: inode 10000000000 #1/open_test_7208 ref 210000000000.head(ref=2 cap_refs={} open={} mode=40777 size=0 mtime=2012-09-21 08:40:11.030810 caps=pAsLsXsxFsx(0=pAsLsXsxFsx) COMPLETE parents=0x7fbafc003450 0x7fbafc0055c0)
2012-09-21 08:40:15.531913 7fbb04158700  1 client.4107   dir 0x7fbafc0042a0 size 1
2012-09-21 08:40:15.531916 7fbb04158700  1 client.4107    10000000000 dn created_file_7208 0x7fbafc002820 ref 1
2012-09-21 08:40:15.531925 7fbb04158700  1 client.4107 dump_inode: inode 10000000001 #1/open_test_7208/created_file_7208 ref 110000000001.head(ref=1 cap_refs={} open={1=0} mode=100666 size=0 mtime=2012-09-21 08:40:11.030810 caps=pAsxLsXsxFscr(0=pAsxLsXsxFscr) objectset[10000000001 ts 0/0 objects 0 dirty_or_tx 0] parents=0x7fbafc002820 0x7fbafc00a190)
2012-09-21 08:40:15.532008 7fbb09889760 10 client.4107 put_inode on 1.head(ref=3 cap_refs={} open={} mode=40755 size=0 mtime=2012-09-21 08:40:10.991530 caps=pAsLsXs(0=pAsLsXs) 0x7fbafc0021d0)
2012-09-21 08:40:15.532042 7fbb09889760 10 client.4107 _ll_drop_pins
2012-09-21 08:40:15.532054 7fbb09889760 10 client.4107 put_inode on 1.head(ref=2 cap_refs={} open={} mode=40755 size=0 mtime=2012-09-21 08:40:10.991530 caps=pAsLsXs(0=pAsLsXs) 0x7fbafc0021d0)
2012-09-21 08:40:15.532099 7fbb09889760 10 client.4107 _flush 10000000000.head(ref=3 cap_refs={1024=0} open={} mode=40777 size=0 mtime=2012-09-21 08:40:11.030810 caps=pAsLsXsxFsx(0=pAsLsXsxFsx) COMPLETE parents=0x7fbafc003450 0x7fbafc0055c0)
2012-09-21 08:40:15.532128 7fbb09889760 10 client.4107  nothing to flush
2012-09-21 08:40:15.532131 7fbb09889760 10 client.4107 put_inode on 10000000000.head(ref=3 cap_refs={1024=0} open={} mode=40777 size=0 mtime=2012-09-21 08:40:11.030810 caps=pAsLsXsxFsx(0=pAsLsXsxFsx) COMPLETE parents=0x7fbafc003450 0x7fbafc0055c0)
2012-09-21 08:40:15.532162 7fbb09889760 10 client.4107 _flush 1.head(ref=2 cap_refs={1024=0} open={} mode=40755 size=0 mtime=2012-09-21 08:40:10.991530 caps=pAsLsXs(0=pAsLsXs) 0x7fbafc0021d0)
2012-09-21 08:40:15.532189 7fbb09889760 10 client.4107  nothing to flush
2012-09-21 08:40:15.532192 7fbb09889760 10 client.4107 put_inode on 1.head(ref=2 cap_refs={1024=0} open={} mode=40755 size=0 mtime=2012-09-21 08:40:10.991530 caps=pAsLsXs(0=pAsLsXs) 0x7fbafc0021d0)
2012-09-21 08:40:15.532225 7fbb09889760 10 client.4107 _flush 10000000001.head(ref=2 cap_refs={1024=0} open={1=0} mode=100666 size=0 mtime=2012-09-21 08:40:11.030810 caps=pAsxLsXsxFscr(0=pAsxLsXsxFscr) objectset[10000000001 ts 0/0 objects 0 dirty_or_tx 0] parents=0x7fbafc002820 0x7fbafc00a190)
2012-09-21 08:40:15.532261 7fbb09889760 10 client.4107  nothing to flush
2012-09-21 08:40:15.532265 7fbb09889760 10 client.4107 put_inode on 10000000001.head(ref=2 cap_refs={1024=0} open={1=0} mode=100666 size=0 mtime=2012-09-21 08:40:11.030810 caps=pAsxLsXsxFscr(0=pAsxLsXsxFscr) objectset[10000000001 ts 0/0 objects 0 dirty_or_tx 0] parents=0x7fbafc002820 0x7fbafc00a190)
2012-09-21 08:40:15.532302 7fbb09889760 10 client.4107 flush_caps
2012-09-21 08:40:15.532313 7fbb09889760 10 client.4107 check_caps on 10000000001.head(ref=1 cap_refs={1024=0} open={1=0} mode=100666 size=0 mtime=2012-09-21 08:40:11.030810 caps=pAsxLsXsxFscr(0=pAsxLsXsxFscr) objectset[10000000001 ts 0/0 objects 0 dirty_or_tx 0] parents=0x7fbafc002820 0x7fbafc00a190) wanted - used - is_delayed=1
2012-09-21 08:40:15.532351 7fbb09889760 10 client.4107  cap mds.0 issued pAsxLsXsxFscr implemented pAsxLsXsxFscr revoking -
2012-09-21 08:40:15.532363 7fbb09889760 10 client.4107 send_cap 10000000001.head(ref=1 cap_refs={1024=0} open={1=0} mode=100666 size=0 mtime=2012-09-21 08:40:11.030810 caps=pAsxLsXsxFscr(0=pAsxLsXsxFscr) objectset[10000000001 ts 0/0 objects 0 dirty_or_tx 0] parents=0x7fbafc002820 0x7fbafc00a190) mds.0 seq 1 used - want - flush - retain p held pAsxLsXsxFscr revoking - dropping AsxLsXsxFscr
2012-09-21 08:40:15.532485 7fbb09889760 10 client.4107 check_caps on 1.head(ref=1 cap_refs={1024=0} open={} mode=40755 size=0 mtime=2012-09-21 08:40:10.991530 caps=pAsLsXs(0=pAsLsXs) 0x7fbafc0021d0) wanted - used - is_delayed=1
2012-09-21 08:40:15.532507 7fbb09889760 10 client.4107  cap mds.0 issued pAsLsXs implemented pAsLsXs revoking -
2012-09-21 08:40:15.532516 7fbb09889760 10 client.4107 send_cap 1.head(ref=1 cap_refs={1024=0} open={} mode=40755 size=0 mtime=2012-09-21 08:40:10.991530 caps=pAsLsXs(0=pAsLsXs) 0x7fbafc0021d0) mds.0 seq 3 used - want - flush - retain p held pAsLsXs revoking - dropping AsLsXs
2012-09-21 08:40:15.532612 7fbb09889760 10 client.4107 check_caps on 10000000000.head(ref=2 cap_refs={1024=0} open={} mode=40777 size=0 mtime=2012-09-21 08:40:11.030810 caps=pAsLsXsxFsx(0=pAsLsXsxFsx) COMPLETE parents=0x7fbafc003450 0x7fbafc0055c0) wanted - used - is_delayed=1
2012-09-21 08:40:15.532645 7fbb09889760 10 client.4107  cap mds.0 issued pAsLsXsxFsx implemented pAsLsXsxFsx revoking -
2012-09-21 08:40:15.532657 7fbb09889760 10 client.4107 send_cap 10000000000.head(ref=2 cap_refs={1024=0} open={} mode=40777 size=0 mtime=2012-09-21 08:40:11.030810 caps=pAsLsXsxFsx(0=pAsLsXsxFsx) COMPLETE parents=0x7fbafc003450 0x7fbafc0055c0) mds.0 seq 4 used - want - flush - retain p held pAsLsXsxFsx revoking - dropping AsLsXsxFsx
2012-09-21 08:40:15.532764 7fbb09889760 10 client.4107 wait_sync_caps want 0 (last is 0, 0 total flushing)
2012-09-21 08:40:15.532777 7fbb09889760 10 client.4107  clearing I_COMPLETE on 10000000000.head(ref=2 cap_refs={1024=0} open={} mode=40777 size=0 mtime=2012-09-21 08:40:11.030810 caps=p(0=p) COMPLETE parents=0x7fbafc003450 0x7fbafc0055c0)
2012-09-21 08:40:15.532837 7fbb09889760 10 client.4107 put_inode on 10000000001.head(ref=1 cap_refs={1024=0} open={1=0} mode=100666 size=0 mtime=2012-09-21 08:40:11.030810 caps=p(0=p) objectset[10000000001 ts 0/0 objects 0 dirty_or_tx 0] 0x7fbafc00a190)
2012-09-21 08:40:15.532863 7fbb09889760 10 client.4107 remove_cap mds.0 on 10000000001.head(ref=0 cap_refs={1024=0} open={1=0} mode=100666 size=0 mtime=2012-09-21 08:40:11.030810 caps=p(0=p) objectset[10000000001 ts 0/0 objects 0 dirty_or_tx 0] 0x7fbafc00a190)
2012-09-21 08:40:15.532950 7fbb09889760 10 client.4107 put_inode deleting 10000000001.head(ref=0 cap_refs={1024=0} open={1=0} mode=100666 size=0 mtime=2012-09-21 08:40:11.030810 caps=- objectset[10000000001 ts 0/0 objects 0 dirty_or_tx 0] 0x7fbafc00a190)
2012-09-21 08:40:15.533077 7fbb09889760 10 client.4107 put_inode on 10000000000.head(ref=2 cap_refs={1024=0} open={} mode=40777 size=0 mtime=2012-09-21 08:40:11.030810 caps=p(0=p) parents=0x7fbafc003450 0x7fbafc0055c0)
2012-09-21 08:40:15.533108 7fbb09889760 10 client.4107 put_inode on 10000000000.head(ref=1 cap_refs={1024=0} open={} mode=40777 size=0 mtime=2012-09-21 08:40:11.030810 caps=p(0=p) 0x7fbafc0055c0)
2012-09-21 08:40:15.533128 7fbb09889760 10 client.4107 remove_cap mds.0 on 10000000000.head(ref=0 cap_refs={1024=0} open={} mode=40777 size=0 mtime=2012-09-21 08:40:11.030810 caps=p(0=p) 0x7fbafc0055c0)
2012-09-21 08:40:15.533158 7fbb09889760 10 client.4107 put_inode deleting 10000000000.head(ref=0 cap_refs={1024=0} open={} mode=40777 size=0 mtime=2012-09-21 08:40:11.030810 caps=- 0x7fbafc0055c0)
2012-09-21 08:40:15.533213 7fbb09889760 10 client.4107 put_inode on 1.head(ref=1 cap_refs={1024=0} open={} mode=40755 size=0 mtime=2012-09-21 08:40:10.991530 caps=p(0=p) 0x7fbafc0021d0)
2012-09-21 08:40:15.533237 7fbb09889760 10 client.4107 remove_cap mds.0 on 1.head(ref=0 cap_refs={1024=0} open={} mode=40755 size=0 mtime=2012-09-21 08:40:10.991530 caps=p(0=p) 0x7fbafc0021d0)
2012-09-21 08:40:15.533266 7fbb09889760 10 client.4107 put_inode deleting 1.head(ref=0 cap_refs={1024=0} open={} mode=40755 size=0 mtime=2012-09-21 08:40:10.991530 caps=- 0x7fbafc0021d0)
2012-09-21 08:40:15.533305 7fbb09889760  2 client.4107 sending client_session close to mds.0 seq 1
2012-09-21 08:40:15.533360 7fbb09889760  2 client.4107 waiting for 1 mds sessions to close
2012-09-21 08:40:15.573206 7fbb04158700 10 client.4107 handle_client_session client_session(close) v1
2012-09-21 08:40:15.573221 7fbb04158700 10 client.4107 kick_requests for mds.0
2012-09-21 08:40:15.573265 7fbb04158700 10 client.4107 unmounting: trim pass, size was 0+0
2012-09-21 08:40:15.573269 7fbb04158700 10 client.4107 unmounting: trim pass, cache now empty, waking unmount()
2012-09-21 08:40:15.573281 7fbb09889760  2 client.4107 unmounted.
2012-09-21 08:40:15.573291 7fbb09889760  1 client.4107 shutdown
2012-09-21 08:40:15.575826 7fbb03156700 10 client.-1 ms_handle_connect on 192.168.106.221:6789/0
2012-09-21 08:40:15.576514 7fbb09889760  2 client.4110 mounted: have osdmap 0 and mdsmap 0
2012-09-21 08:40:15.576549 7fbb09889760 10 client.4110  target mds.0 not active, waiting for new mdsmap
2012-09-21 08:40:15.577584 7fbb03156700  1 client.4110 handle_mds_map epoch 10
2012-09-21 08:40:15.577731 7fbb09889760 10 client.4110 opening session to mds.0
2012-09-21 08:40:15.577810 7fbb09889760 10 client.4110 waiting for session to mds.0 to open
2012-09-21 08:40:15.578100 7fbb03156700 10 client.4110 ms_handle_connect on 192.168.106.221:6803/7026
2012-09-21 08:40:15.614665 7fbb03156700 10 client.4110 handle_client_session client_session(open) v1
2012-09-21 08:40:15.614676 7fbb03156700 10 client.4110 renew_caps mds.0
2012-09-21 08:40:15.614707 7fbb03156700 10 client.4110 connect_mds_targets for mds.0
2012-09-21 08:40:15.614736 7fbb09889760 10 client.4110 send_request rebuilding request 1 for mds.0
2012-09-21 08:40:15.614768 7fbb09889760 10 client.4110 send_request client_request(unknown.0:1 getattr pAsLsXsFs #1) v1 to mds.0
2012-09-21 08:40:15.615093 7fbb03156700 10 client.4110 handle_client_session client_session(renewcaps seq 1) v1
2012-09-21 08:40:15.616585 7fbb03156700 10 client.4110 insert_trace from 2012-09-21 08:40:15.614764 mds.0 is_target=1 is_dentry=0
2012-09-21 08:40:15.616595 7fbb03156700 10 client.4110  features 0x1fffff
2012-09-21 08:40:15.616598 7fbb03156700 10 client.4110 update_snap_trace len 48
2012-09-21 08:40:15.616612 7fbb03156700 10 client.4110 update_snap_trace snaprealm(1 nref=2 c=0 seq=0 parent=0 my_snaps=[] cached_snapc=0=[]) seq 1 > 0
2012-09-21 08:40:15.616625 7fbb03156700 10 client.4110  flushing caps on snaprealm(1 nref=2 c=0 seq=0 parent=0 my_snaps=[] cached_snapc=0=[])
2012-09-21 08:40:15.616638 7fbb03156700 10 client.4110 invalidate_snaprealm_and_children snaprealm(1 nref=2 c=0 seq=1 parent=0 my_snaps=[] cached_snapc=0=[])
2012-09-21 08:40:15.616646 7fbb03156700 10 client.4110  hrm  is_target=1 is_dentry=0
2012-09-21 08:40:15.616675 7fbb03156700 10 client.4110 update_inode_file_bits 1.head(ref=1 cap_refs={} open={} mode=40755 size=0 mtime=0.000000 caps=- 0x7fbafc0207f0) - mtime 2012-09-21 08:40:10.991530
2012-09-21 08:40:15.616704 7fbb03156700 10 client.4110 add_update_cap issued - -> pAsLsXsFs from mds.0 on 1.head(ref=1 cap_refs={} open={} mode=40755 size=0 mtime=2012-09-21 08:40:10.991530 caps=pAsLsXsFs(0=pAsLsXsFs) 0x7fbafc0207f0)
2012-09-21 08:40:15.616749 7fbb09889760 10 client.4110 root getattr result=0
2012-09-21 08:40:15.616764 7fbb09889760  3 client.4110 open enter(/open_test_7208//created_file_7208, 0,438) = 
2012-09-21 08:40:15.616785 7fbb09889760 10 client.4110 path_walk #1/open_test_7208//created_file_7208
2012-09-21 08:40:15.616797 7fbb09889760 10 client.4110  0 1.head(ref=2 cap_refs={} open={} mode=40755 size=0 mtime=2012-09-21 08:40:10.991530 caps=pAsLsXsFs(0=pAsLsXsFs) 0x7fbafc0207f0) open_test_7208
2012-09-21 08:40:15.616831 7fbb09889760 10 client.4110 _lookup on #1/open_test_7208
2012-09-21 08:40:15.616845 7fbb09889760 10 client.4110 choose_target_mds from caps on inode 1.head(ref=2 cap_refs={} open={} mode=40755 size=0 mtime=2012-09-21 08:40:10.991530 caps=pAsLsXsFs(0=pAsLsXsFs) 0x7fbafc0207f0)
2012-09-21 08:40:15.616868 7fbb09889760 10 client.4110 send_request rebuilding request 2 for mds.0
2012-09-21 08:40:15.616885 7fbb09889760 10 client.4110 send_request client_request(unknown.0:2 lookup #1/open_test_7208) v1 to mds.0
2012-09-21 08:40:15.617617 7fbb03156700 10 client.4110 insert_trace from 2012-09-21 08:40:15.616880 mds.0 is_target=1 is_dentry=1
2012-09-21 08:40:15.617626 7fbb03156700 10 client.4110  features 0x1fffff
2012-09-21 08:40:15.617629 7fbb03156700 10 client.4110 update_snap_trace len 48
2012-09-21 08:40:15.617637 7fbb03156700 10 client.4110 update_snap_trace snaprealm(1 nref=3 c=0 seq=1 parent=0 my_snaps=[] cached_snapc=0=[]) seq 1 <= 1 and same parent, SKIPPING
2012-09-21 08:40:15.617646 7fbb03156700 10 client.4110  hrm  is_target=1 is_dentry=1
2012-09-21 08:40:15.617683 7fbb03156700 10 client.4110 update_inode_file_bits 10000000000.head(ref=0 cap_refs={} open={} mode=40777 size=0 mtime=0.000000 caps=- 0x7fbafc022120) - mtime 2012-09-21 08:40:11.030810
2012-09-21 08:40:15.617709 7fbb03156700 10 client.4110 add_update_cap issued - -> pAsLsXsFs from mds.0 on 10000000000.head(ref=0 cap_refs={} open={} mode=40777 size=0 mtime=2012-09-21 08:40:11.030810 caps=pAsLsXsFs(0=pAsLsXsFs) 0x7fbafc022120)
2012-09-21 08:40:15.617735 7fbb03156700 10 client.4110 add_update_cap issued pAsLsXsFs -> pAsLsXsFs from mds.0 on 1.head(ref=2 cap_refs={} open={} mode=40755 size=0 mtime=2012-09-21 08:40:10.991530 caps=pAsLsXsFs(0=pAsLsXsFs) 0x7fbafc0207f0)
2012-09-21 08:40:15.617858 7fbb09889760 10 client.4110 _lookup res is 0
2012-09-21 08:40:15.617868 7fbb09889760 10 client.4110 _lookup 1.head(ref=3 cap_refs={} open={} mode=40755 size=0 mtime=2012-09-21 08:40:10.991530 caps=pAsLsXsFs(0=pAsLsXsFs) 0x7fbafc0207f0) open_test_7208 = 10000000000.head(ref=1 cap_refs={} open={} mode=40777 size=0 mtime=2012-09-21 08:40:11.030810 caps=pAsLsXsFs(0=pAsLsXsFs) parents=0x7fbafc0228f0 0x7fbafc022120)
2012-09-21 08:40:15.617905 7fbb09889760 10 client.4110  1 10000000000.head(ref=1 cap_refs={} open={} mode=40777 size=0 mtime=2012-09-21 08:40:11.030810 caps=pAsLsXsFs(0=pAsLsXsFs) parents=0x7fbafc0228f0 0x7fbafc022120) 
2012-09-21 08:40:15.617937 7fbb09889760 10 client.4110 _lookup on #10000000000/
2012-09-21 08:40:15.617950 7fbb09889760 10 client.4110 choose_target_mds from caps on inode 10000000000.head(ref=1 cap_refs={} open={} mode=40777 size=0 mtime=2012-09-21 08:40:11.030810 caps=pAsLsXsFs(0=pAsLsXsFs) parents=0x7fbafc0228f0 0x7fbafc022120)
2012-09-21 08:40:15.617973 7fbb09889760 10 client.4110 send_request rebuilding request 3 for mds.0
2012-09-21 08:40:15.617999 7fbb09889760 10 client.4110 send_request client_request(unknown.0:3 lookup #10000000000/) v1 to mds.0
2012-09-21 08:40:15.632657 7fbb02854700  0 -- 192.168.106.221:0/1007208 >> 192.168.106.221:6803/7026 pipe(0x7fbafc019510 sd=4 :50658 pgs=6 cs=1 l=0).fault, initiating reconnect
2012-09-21 08:40:16.576590 7fbb04158700 10 client.4110 renew_caps()
2012-09-21 08:40:16.576612 7fbb04158700 10 client.4110 renew_caps mds.0
2012-09-21 08:40:31.004050 7fbb03156700  1 client.4110 handle_mds_map epoch 11
2012-09-21 08:40:36.578941 7fbb04158700 10 client.4110 renew_caps()
2012-09-21 08:40:36.578965 7fbb04158700 10 client.4110 renew_caps mds.0
2012-09-21 08:40:51.007692 7fbb03156700  1 client.4110 handle_mds_map epoch 12
2012-09-21 08:40:56.582453 7fbb04158700 10 client.4110 renew_caps()
2012-09-21 08:40:56.582480 7fbb04158700 10 client.4110 renew_caps mds.0