client.log - Ceph - Ceph

Bug #518 » client.log

Greg Farnum, 10/26/2010 10:34 AM

 -10-26 17:29:42.009166 --- 16378 opened log /home/ubuntu/client.log ---
       ceph version 0.22.1 (commit:7464f9688001aa89f9673ba14e6d075d0ee33541)
 -10-26 17:29:42.009903 7fbc2982c720 -- :/16379 messenger.start
 -10-26 17:29:42.010805 7fbc2982c720 -- :/16379 --> mon0 10.135.211.78:6789/0 -- auth(proto 0 30 bytes) v1 -- ?+0 0x1c21eb0
 -10-26 17:29:42.011285 7fbc2982b710 -- 10.135.211.78:0/16379 learned my addr 10.135.211.78:0/16379
 -10-26 17:29:42.011582 7fbc274e2710 client-1 ms_handle_connect on 10.135.211.78:6789/0
 -10-26 17:29:42.012262 7fbc274e2710 -- 10.135.211.78:0/16379 <== mon0 10.135.211.78:6789/0 1 ==== auth_reply(proto 1 0 Success) v1 ==== 24+0+0 (1582388755 0 0) 0x1c21eb0
 -10-26 17:29:42.012330 7fbc274e2710 -- 10.135.211.78:0/16379 --> mon0 10.135.211.78:6789/0 -- mon_subscribe({mdsmap=0+,monmap=0+,osdmap=0}) v1 -- ?+0 0x1c226c0
 -10-26 17:29:42.012577 7fbc2982c720 client8316 mounted: have osdmap 0 and mdsmap 0
 -10-26 17:29:42.012629 7fbc2982c720 client8316 choose_target_mds 0 is_hash=0 hash=0
 -10-26 17:29:42.012644 7fbc2982c720 client8316 mds is 0
 -10-26 17:29:42.012652 7fbc2982c720 client8316 no address for mds0, waiting for new mdsmap
 -10-26 17:29:42.013258 7fbc274e2710 -- 10.135.211.78:0/16379 <== mon0 10.135.211.78:6789/0 2 ==== mdsmap(e 106) v1 ==== 693+0+0 (3328453334 0 0) 0x1c23050
 -10-26 17:29:42.013301 7fbc274e2710 client8316 handle_mds_map epoch 106
 -10-26 17:29:42.013400 7fbc274e2710 -- 10.135.211.78:0/16379 <== mon0 10.135.211.78:6789/0 3 ==== mon_map v1 ==== 328+0+0 (2707094911 0 0) 0x1c226a0
 -10-26 17:29:42.013449 7fbc274e2710 -- 10.135.211.78:0/16379 <== mon0 10.135.211.78:6789/0 4 ==== osd_map(641,641) v1 ==== 2248+0+0 (3295231082 0 0) 0x1c23d60
 -10-26 17:29:42.013583 7fbc274e2710 -- 10.135.211.78:0/16379 <== mon0 10.135.211.78:6789/0 5 ==== mon_subscribe_ack(300s) v1 ==== 20+0+0 (1205395459 0 0) 0x1c242c0
 -10-26 17:29:42.013626 7fbc2982c720 client8316 opening session to mds0
 -10-26 17:29:42.013643 7fbc2982c720 -- 10.135.211.78:0/16379 --> mds0 10.135.211.78:6800/13446 -- client_session(request_open) v1 -- ?+0 0x1c242c0
 -10-26 17:29:42.013732 7fbc2982c720 client8316 waiting for session to mds0 to open
 -10-26 17:29:42.014193 7fbc274e2710 client8316 ms_handle_connect on 10.135.211.78:6800/13446
 -10-26 17:29:42.025081 7fbc274e2710 -- 10.135.211.78:0/16379 <== mds0 10.135.211.78:6800/13446 1 ==== client_session(open) v1 ==== 28+0+0 (2719320884 0 0) 0x1c242c0
 -10-26 17:29:42.025124 7fbc274e2710 client8316 handle_client_session client_session(open) v1
 -10-26 17:29:42.025143 7fbc274e2710 client8316 renew_caps mds0
 -10-26 17:29:42.025153 7fbc274e2710 -- 10.135.211.78:0/16379 --> mds0 10.135.211.78:6800/13446 -- client_session(request_renewcaps seq 1) v1 -- ?+0 0x1c23d30
 -10-26 17:29:42.025202 7fbc2982c720 client8316 send_request rebuilding request 1 for mds0
 -10-26 17:29:42.025225 7fbc2982c720 client8316 encode_cap_releases enter (req: 0x1c26200, mds: 0)
 -10-26 17:29:42.025234 7fbc2982c720 client8316 send_request set sent_stamp to 2010-10-26 17:29:42.025233
 -10-26 17:29:42.025242 7fbc2982c720 client8316 send_request client_request(unknown0:1 getattr pAsLsXsFs #1) v1 to mds0
 -10-26 17:29:42.025265 7fbc2982c720 -- 10.135.211.78:0/16379 --> mds0 10.135.211.78:6800/13446 -- client_request(client8316:1 getattr pAsLsXsFs #1) v1 -- ?+0 0x1c254f0
 -10-26 17:29:42.025285 7fbc2982c720 client8316 awaiting reply|forward|kick on 0x7fff7019ea60
 -10-26 17:29:42.025524 7fbc274e2710 -- 10.135.211.78:0/16379 <== mds0 10.135.211.78:6800/13446 2 ==== client_session(renewcaps seq 1) v1 ==== 28+0+0 (2614397064 0 0) 0x1c242c0
 -10-26 17:29:42.025564 7fbc274e2710 client8316 handle_client_session client_session(renewcaps seq 1) v1
 -10-26 17:29:42.025744 7fbc274e2710 -- 10.135.211.78:0/16379 <== mds0 10.135.211.78:6800/13446 3 ==== client_reply(???:1 = 0 Success) v1 ==== 308+0+0 (3441981060 0 0) 0x1c23d80
 -10-26 17:29:42.025784 7fbc274e2710 client8316 handle_client_reply got a reply. Safe:1 tid 1
 -10-26 17:29:42.025802 7fbc274e2710 client8316 insert_trace from 2010-10-26 17:29:42.025233 mds0 is_target=1 is_dentry=0
 -10-26 17:29:42.025825 7fbc274e2710 client8316 update_snap_trace len 48
 -10-26 17:29:42.025839 7fbc274e2710 client8316 update_snap_trace snaprealm(1 nref=1 c=0 seq=0 parent=0 my_snaps=[] cached_snapc=0=[]) seq 1 > 0
 -10-26 17:29:42.025851 7fbc274e2710 client8316  flushing caps on snaprealm(1 nref=1 c=0 seq=0 parent=0 my_snaps=[] cached_snapc=0=[])
 -10-26 17:29:42.025861 7fbc274e2710 client8316 invalidate_snaprealm_and_children snaprealm(1 nref=1 c=0 seq=1 parent=0 my_snaps=[] cached_snapc=0=[])
 -10-26 17:29:42.025869 7fbc274e2710 client8316 update_snap_trace snaprealm(1 nref=1 c=0 seq=1 parent=0 my_snaps=[] cached_snapc=0=[]) self|parent updated
 -10-26 17:29:42.025879 7fbc274e2710 client8316   snapc 1=[]
 -10-26 17:29:42.025885 7fbc274e2710 client8316  hrm  is_target=1 is_dentry=0
 -10-26 17:29:42.025904 7fbc274e2710 client8316 setting this inode as root! 1.head( cap_refs={} open={} ref=1 caps=- mode=40000 mtime=0.000000 parent=0); ino: 1; snapidhead
 -10-26 17:29:42.025922 7fbc274e2710 client8316 add_update_inode adding 1.head( cap_refs={} open={} ref=1 caps=- mode=40000 mtime=0.000000 parent=0) caps pAsLsXsFs
 -10-26 17:29:42.025936 7fbc274e2710 client8316 add_update_cap first one, opened snaprealm 0x1c254f0
 -10-26 17:29:42.025948 7fbc274e2710 client8316 add_update_cap issued - -> pAsLsXsFs from mds0 on 1.head( cap_refs={} open={} ref=1 caps=pAsLsXsFs mode=40000 mtime=0.000000 parent=0)
 -10-26 17:29:42.025964 7fbc274e2710 client8316 update_inode_file_bits 1.head( cap_refs={} open={} ref=1 caps=pAsLsXsFs mode=40755 mtime=0.000000 parent=0) - mtime 2010-10-25 21:57:58.072562
 -10-26 17:29:42.025982 7fbc274e2710 client8316 handle_client_reply signalling caller 0x7fff7019ea60
 -10-26 17:29:42.026014 7fbc274e2710 client8316 handle_client_reply awaiting kickback on tid 1 0x7fbc274e15d0
 -10-26 17:29:42.026052 7fbc2982c720 client8316 sendrecv kickback on tid 1 0x7fbc274e15d0
 -10-26 17:29:42.026077 7fbc2982c720 client8316 lat 0.000843
 -10-26 17:29:42.026092 7fbc2982c720 client8316 root getattr result=0
 -10-26 17:29:42.026102 7fbc2982c720 client8316 _ll_get 0x1c25600 1 -> 1
 -10-26 17:29:42.026314 7fbc2982c720 client8316 unmounting
 -10-26 17:29:42.026345 7fbc2982c720 client8316 _ll_drop_pins
 -10-26 17:29:42.026354 7fbc2982c720 client8316 _ll_put 0x1c25600 1 1 -> 0
 -10-26 17:29:42.026373 7fbc2982c720 client8316 remove_cap mds0 on 1.head( cap_refs={} open={} ref=0 caps=pAsLsXsFs mode=40755 mtime=2010-10-25 21:57:58.072562 parent=0)
 -10-26 17:29:42.026394 7fbc2982c720 client8316 remove_cap last one, closing snaprealm 0x1c254f0
 -10-26 17:29:42.026410 7fbc2982c720 client8316 flush_caps
 -10-26 17:29:42.026420 7fbc2982c720 client8316 wait_sync_caps want 0 (last is 0, 0 total flushing)
 -10-26 17:29:42.026435 7fbc2982c720 client8316 sending client_session close to mds0 seq 0
 -10-26 17:29:42.026444 7fbc2982c720 -- 10.135.211.78:0/16379 --> mds0 10.135.211.78:6800/13446 -- client_session(request_close) v1 -- ?+0 0x1c23d60
 -10-26 17:29:42.026467 7fbc2982c720 client8316 waiting for 1 mds sessions to close
 -10-26 17:29:42.031732 7fbc274e2710 -- 10.135.211.78:0/16379 <== mds0 10.135.211.78:6800/13446 4 ==== client_session(close) v1 ==== 28+0+0 (3822250925 0 0) 0x1c23d30
 -10-26 17:29:42.031772 7fbc274e2710 client8316 handle_client_session client_session(close) v1
 -10-26 17:29:42.031803 7fbc274e2710 client8316 kick_requests for mds0
 -10-26 17:29:42.031817 7fbc274e2710 client8316 unmounting: trim pass, size was 0+0
 -10-26 17:29:42.031825 7fbc274e2710 client8316 unmounting: trim pass, cache now empty, waking unmount()
 -10-26 17:29:42.031869 7fbc2982c720 client8316 unmounted.
 -10-26 17:29:42.031903 7fbc2982c720 client8316 shutdown
 -10-26 17:29:42.032554 7fbc2982c720 -- 10.135.211.78:0/16379 shutdown complete.
 -10-26 17:30:38.098742 --- 16444 opened log /home/ubuntu/client.log ---
       ceph version 0.22.1 (commit:7464f9688001aa89f9673ba14e6d075d0ee33541)
 -10-26 17:30:38.099466 7fd29ba10720 -- :/16445 messenger.start
 -10-26 17:30:38.100352 7fd29ba10720 -- :/16445 --> mon1 10.106.124.118:6789/0 -- auth(proto 0 30 bytes) v1 -- ?+0 0x2484eb0
 -10-26 17:30:38.102667 7fd29ba0f710 -- 10.135.211.78:0/16445 learned my addr 10.135.211.78:0/16445
 -10-26 17:30:38.103494 7fd2996c6710 client-1 ms_handle_connect on 10.106.124.118:6789/0
 -10-26 17:30:38.104629 7fd2996c6710 -- 10.135.211.78:0/16445 <== mon1 10.106.124.118:6789/0 1 ==== auth_reply(proto 1 0 Success) v1 ==== 24+0+0 (2141111592 0 0) 0x2484eb0
 -10-26 17:30:38.104703 7fd2996c6710 -- 10.135.211.78:0/16445 --> mon1 10.106.124.118:6789/0 -- mon_subscribe({mdsmap=0+,monmap=0+,osdmap=0}) v1 -- ?+0 0x24856c0
 -10-26 17:30:38.105083 7fd29ba10720 client8333 mounted: have osdmap 0 and mdsmap 0
 -10-26 17:30:38.105139 7fd29ba10720 client8333 choose_target_mds 0 is_hash=0 hash=0
 -10-26 17:30:38.105155 7fd29ba10720 client8333 mds is 0
 -10-26 17:30:38.105163 7fd29ba10720 client8333 no address for mds0, waiting for new mdsmap
 -10-26 17:30:38.106015 7fd2996c6710 -- 10.135.211.78:0/16445 <== mon1 10.106.124.118:6789/0 2 ==== mdsmap(e 106) v1 ==== 693+0+0 (3328453334 0 0) 0x2484eb0
 -10-26 17:30:38.106059 7fd2996c6710 client8333 handle_mds_map epoch 106
 -10-26 17:30:38.106137 7fd29ba10720 client8333 opening session to mds0
 -10-26 17:30:38.106161 7fd29ba10720 -- 10.135.211.78:0/16445 --> mds0 10.135.211.78:6800/13446 -- client_session(request_open) v1 -- ?+0 0x7fd294001030
 -10-26 17:30:38.106280 7fd29ba10720 client8333 waiting for session to mds0 to open
 -10-26 17:30:38.106371 7fd2996c6710 -- 10.135.211.78:0/16445 <== mon1 10.106.124.118:6789/0 3 ==== mon_map v1 ==== 328+0+0 (2707094911 0 0) 0x2484eb0
 -10-26 17:30:38.106493 7fd2996c6710 -- 10.135.211.78:0/16445 <== mon1 10.106.124.118:6789/0 4 ==== osd_map(641,641) v1 ==== 2248+0+0 (1712609989 0 0) 0x2484eb0
 -10-26 17:30:38.106661 7fd2996c6710 client8333 ms_handle_connect on 10.135.211.78:6800/13446
 -10-26 17:30:38.106754 7fd2996c6710 -- 10.135.211.78:0/16445 <== mon1 10.106.124.118:6789/0 5 ==== mon_subscribe_ack(300s) v1 ==== 20+0+0 (1205395459 0 0) 0x2486660
 -10-26 17:30:38.113228 7fd2996c6710 -- 10.135.211.78:0/16445 <== mds0 10.135.211.78:6800/13446 1 ==== client_session(open) v1 ==== 28+0+0 (2719320884 0 0) 0x2486660
 -10-26 17:30:38.113270 7fd2996c6710 client8333 handle_client_session client_session(open) v1
 -10-26 17:30:38.113289 7fd2996c6710 client8333 renew_caps mds0
 -10-26 17:30:38.113299 7fd2996c6710 -- 10.135.211.78:0/16445 --> mds0 10.135.211.78:6800/13446 -- client_session(request_renewcaps seq 1) v1 -- ?+0 0x2486980
 -10-26 17:30:38.113369 7fd29ba10720 client8333 send_request rebuilding request 1 for mds0
 -10-26 17:30:38.113393 7fd29ba10720 client8333 encode_cap_releases enter (req: 0x7fd294000d70, mds: 0)
 -10-26 17:30:38.113403 7fd29ba10720 client8333 send_request set sent_stamp to 2010-10-26 17:30:38.113403
 -10-26 17:30:38.113412 7fd29ba10720 client8333 send_request client_request(unknown0:1 getattr pAsLsXsFs #1) v1 to mds0
 -10-26 17:30:38.113436 7fd29ba10720 -- 10.135.211.78:0/16445 --> mds0 10.135.211.78:6800/13446 -- client_request(client8333:1 getattr pAsLsXsFs #1) v1 -- ?+0 0x7fd2940017d0
 -10-26 17:30:38.113479 7fd29ba10720 client8333 awaiting reply|forward|kick on 0x7fff1fa1c730
 -10-26 17:30:38.113659 7fd2996c6710 -- 10.135.211.78:0/16445 <== mds0 10.135.211.78:6800/13446 2 ==== client_session(renewcaps seq 1) v1 ==== 28+0+0 (2614397064 0 0) 0x2486660
 -10-26 17:30:38.113697 7fd2996c6710 client8333 handle_client_session client_session(renewcaps seq 1) v1
 -10-26 17:30:38.114014 7fd2996c6710 -- 10.135.211.78:0/16445 <== mds0 10.135.211.78:6800/13446 3 ==== client_reply(???:1 = 0 Success) v1 ==== 308+0+0 (1946154150 0 0) 0x2486980
 -10-26 17:30:38.114056 7fd2996c6710 client8333 handle_client_reply got a reply. Safe:1 tid 1
 -10-26 17:30:38.114074 7fd2996c6710 client8333 insert_trace from 2010-10-26 17:30:38.113403 mds0 is_target=1 is_dentry=0
 -10-26 17:30:38.114098 7fd2996c6710 client8333 update_snap_trace len 48
 -10-26 17:30:38.114113 7fd2996c6710 client8333 update_snap_trace snaprealm(1 nref=1 c=0 seq=0 parent=0 my_snaps=[] cached_snapc=0=[]) seq 1 > 0
 -10-26 17:30:38.114132 7fd2996c6710 client8333  flushing caps on snaprealm(1 nref=1 c=0 seq=0 parent=0 my_snaps=[] cached_snapc=0=[])
 -10-26 17:30:38.114182 7fd2996c6710 client8333 invalidate_snaprealm_and_children snaprealm(1 nref=1 c=0 seq=1 parent=0 my_snaps=[] cached_snapc=0=[])
 -10-26 17:30:38.114197 7fd2996c6710 client8333 update_snap_trace snaprealm(1 nref=1 c=0 seq=1 parent=0 my_snaps=[] cached_snapc=0=[]) self|parent updated
 -10-26 17:30:38.114207 7fd2996c6710 client8333   snapc 1=[]
 -10-26 17:30:38.114215 7fd2996c6710 client8333  hrm  is_target=1 is_dentry=0
 -10-26 17:30:38.114236 7fd2996c6710 client8333 setting this inode as root! 1.head( cap_refs={} open={} ref=1 caps=- mode=40000 mtime=0.000000 parent=0); ino: 1; snapidhead
 -10-26 17:30:38.114255 7fd2996c6710 client8333 add_update_inode adding 1.head( cap_refs={} open={} ref=1 caps=- mode=40000 mtime=0.000000 parent=0) caps pAsLsXsFs
 -10-26 17:30:38.114269 7fd2996c6710 client8333 add_update_cap first one, opened snaprealm 0x2486bf0
 -10-26 17:30:38.114282 7fd2996c6710 client8333 add_update_cap issued - -> pAsLsXsFs from mds0 on 1.head( cap_refs={} open={} ref=1 caps=pAsLsXsFs mode=40000 mtime=0.000000 parent=0)
 -10-26 17:30:38.114298 7fd2996c6710 client8333 update_inode_file_bits 1.head( cap_refs={} open={} ref=1 caps=pAsLsXsFs mode=40755 mtime=0.000000 parent=0) - mtime 2010-10-25 21:57:58.072562
 -10-26 17:30:38.114316 7fd2996c6710 client8333 handle_client_reply signalling caller 0x7fff1fa1c730
 -10-26 17:30:38.114329 7fd2996c6710 client8333 handle_client_reply awaiting kickback on tid 1 0x7fd2996c55d0
 -10-26 17:30:38.114357 7fd29ba10720 client8333 sendrecv kickback on tid 1 0x7fd2996c55d0
 -10-26 17:30:38.114374 7fd29ba10720 client8333 lat 0.000971
 -10-26 17:30:38.114388 7fd29ba10720 client8333 root getattr result=0
 -10-26 17:30:38.114399 7fd29ba10720 client8333 _ll_get 0x24882f0 1 -> 1
 -10-26 17:30:39.106101 7fd2937fe710 client8333 renew_caps()
 -10-26 17:30:39.106132 7fd2937fe710 client8333 renew_caps requesting from mds0
 -10-26 17:30:39.106141 7fd2937fe710 client8333 renew_caps mds0
 -10-26 17:30:39.106149 7fd2937fe710 -- 10.135.211.78:0/16445 --> mds0 10.135.211.78:6800/13446 -- client_session(request_renewcaps seq 2) v1 -- ?+0 0x2486980
 -10-26 17:30:39.106842 7fd2996c6710 -- 10.135.211.78:0/16445 <== mds0 10.135.211.78:6800/13446 4 ==== client_session(renewcaps seq 2) v1 ==== 28+0+0 (1357429227 0 0) 0x2486980
 -10-26 17:30:39.106912 7fd2996c6710 client8333 handle_client_session client_session(renewcaps seq 2) v1
 -10-26 17:30:44.202137 7fd29ba10720 client8333 ll_getattr 1.head
 -10-26 17:30:44.202191 7fd29ba10720 client8333 _getattr mask pAsLsXsFs issued=1
 -10-26 17:30:44.202206 7fd29ba10720 client8333 fill_stat on 1 snap/dev=head mode 040755 mtime 2010-10-25 21:57:58.072562 ctime 2010-10-25 21:57:58.072562
 -10-26 17:30:44.202220 7fd29ba10720 client8333 ll_getattr 1.head = 0
 -10-26 17:30:44.863169 7fd29ba10720 client8333 ll_getattr 1.head
 -10-26 17:30:44.863204 7fd29ba10720 client8333 _getattr mask pAsLsXsFs issued=1
 -10-26 17:30:44.863214 7fd29ba10720 client8333 fill_stat on 1 snap/dev=head mode 040755 mtime 2010-10-25 21:57:58.072562 ctime 2010-10-25 21:57:58.072562
 -10-26 17:30:44.863226 7fd29ba10720 client8333 ll_getattr 1.head = 0
 -10-26 17:30:44.869200 7fd29ba10720 client8333 ll_getattr 1.head
 -10-26 17:30:44.869239 7fd29ba10720 client8333 _getattr mask pAsLsXsFs issued=1
 -10-26 17:30:44.869248 7fd29ba10720 client8333 fill_stat on 1 snap/dev=head mode 040755 mtime 2010-10-25 21:57:58.072562 ctime 2010-10-25 21:57:58.072562
 -10-26 17:30:44.869261 7fd29ba10720 client8333 ll_getattr 1.head = 0
 -10-26 17:30:45.457348 7fd29ba10720 client8333 ll_getattr 1.head
 -10-26 17:30:45.457405 7fd29ba10720 client8333 _getattr mask pAsLsXsFs issued=1
 -10-26 17:30:45.457416 7fd29ba10720 client8333 fill_stat on 1 snap/dev=head mode 040755 mtime 2010-10-25 21:57:58.072562 ctime 2010-10-25 21:57:58.072562
 -10-26 17:30:45.457428 7fd29ba10720 client8333 ll_getattr 1.head = 0
 -10-26 17:30:45.457672 7fd29ba10720 client8333 ll_getattr 1.head
 -10-26 17:30:45.457708 7fd29ba10720 client8333 _getattr mask pAsLsXsFs issued=1
 -10-26 17:30:45.457718 7fd29ba10720 client8333 fill_stat on 1 snap/dev=head mode 040755 mtime 2010-10-25 21:57:58.072562 ctime 2010-10-25 21:57:58.072562
 -10-26 17:30:45.457729 7fd29ba10720 client8333 ll_getattr 1.head = 0
 -10-26 17:30:45.457849 7fd29ba10720 client8333 ll_opendir 1.head
 -10-26 17:30:45.457878 7fd29ba10720 client8333 _opendir 1, our cache says the first dirfrag is 0/0
 -10-26 17:30:45.457891 7fd29ba10720 client8333 _opendir(1) = 0 (0x7fd2940018f0)
 -10-26 17:30:45.457899 7fd29ba10720 client8333 ll_opendir 1.head = 0 (0x7fd2940018f0)
 -10-26 17:30:45.458008 7fd29ba10720 client8333 seekdir(0x7fd2940018f0, 0)
 -10-26 17:30:45.458046 7fd29ba10720 client8333 readdir_r_cb 1.head( cap_refs={} open={} ref=3 caps=pAsLsXsFs mode=40755 mtime=2010-10-25 21:57:58.072562 parent=0) offset 0 frag 0/0 fragpos 0 at_end=0
 -10-26 17:30:45.458069 7fd29ba10720 client8333  including .
 -10-26 17:30:45.458079 7fd29ba10720 client8333 fill_dirent '.' -> 1 type 4 w/ next_off 2
 -10-26 17:30:45.458087 7fd29ba10720 client8333 fill_stat on 1 snap/dev=head mode 040755 mtime 2010-10-25 21:57:58.072562 ctime 2010-10-25 21:57:58.072562
 -10-26 17:30:45.458111 7fd29ba10720 client8333 offset 2 at_cache_name  snapid head complete 0 issued pAsLsXsFs
 -10-26 17:30:45.458121 7fd29ba10720 client8333 _readdir_get_frag 0x7fd2940018f0 on 1 fg 0/0
 -10-26 17:30:45.458140 7fd29ba10720 client8333 choose_target_mds 0x24882f0 is_hash=0 hash=0
 -10-26 17:30:45.458151 7fd29ba10720 client8333 choose_target_mds from caps
 -10-26 17:30:45.458157 7fd29ba10720 client8333 mds is 0
 -10-26 17:30:45.458164 7fd29ba10720 client8333 send_request rebuilding request 2 for mds0
 -10-26 17:30:45.458174 7fd29ba10720 client8333 encode_cap_releases enter (req: 0x7fd294000d70, mds: 0)
 -10-26 17:30:45.458182 7fd29ba10720 client8333 send_request set sent_stamp to 2010-10-26 17:30:45.458181
 -10-26 17:30:45.458190 7fd29ba10720 client8333 send_request client_request(unknown0:2 readdir #1) v1 to mds0
 -10-26 17:30:45.458201 7fd29ba10720 -- 10.135.211.78:0/16445 --> mds0 10.135.211.78:6800/13446 -- client_request(client8333:2 readdir #1) v1 -- ?+0 0x7fd294002c80
 -10-26 17:30:45.458253 7fd29ba10720 client8333 awaiting reply|forward|kick on 0x7fff1fa1c330
 -10-26 17:30:45.458749 7fd2996c6710 -- 10.135.211.78:0/16445 <== mds0 10.135.211.78:6800/13446 5 ==== client_reply(???:2 = 0 Success) v1 ==== 2085+0+0 (2621844698 0 0) 0x2486cd0
 -10-26 17:30:45.458795 7fd2996c6710 client8333 handle_client_reply got a reply. Safe:1 tid 2
 -10-26 17:30:45.458805 7fd2996c6710 client8333 insert_trace from 2010-10-26 17:30:45.458181 mds0 is_target=1 is_dentry=0
 -10-26 17:30:45.458814 7fd2996c6710 client8333 update_snap_trace len 48
 -10-26 17:30:45.458823 7fd2996c6710 client8333 update_snap_trace snaprealm(1 nref=2 c=0 seq=1 parent=0 my_snaps=[] cached_snapc=1=[]) seq 1 <= 1 and same parent, SKIPPING
 -10-26 17:30:45.458835 7fd2996c6710 client8333  hrm  is_target=1 is_dentry=0
 -10-26 17:30:45.458850 7fd2996c6710 client8333 add_update_inode had 1.head( cap_refs={} open={} ref=3 caps=pAsLsXsFs mode=40755 mtime=2010-10-25 21:57:58.072562 parent=0) caps pAsLsXsFs
 -10-26 17:30:45.458871 7fd2996c6710 client8333 add_update_cap issued pAsLsXsFs -> pAsLsXsFs from mds0 on 1.head( cap_refs={} open={} ref=3 caps=pAsLsXsFs mode=40755 mtime=2010-10-25 21:57:58.072562 parent=0)
 -10-26 17:30:45.458887 7fd2996c6710 client8333 update_inode_file_bits 1.head( cap_refs={} open={} ref=3 caps=pAsLsXsFs mode=40755 mtime=2010-10-25 21:57:58.072562 parent=0) pAsLsXsFs mtime 2010-10-25 21:57:58.072562
 -10-26 17:30:45.458950 7fd2996c6710 client8333 insert_trace 7 readdir items, end=1
 -10-26 17:30:45.458971 7fd2996c6710 client8333 add_update_inode adding 10000000000.head( cap_refs={} open={} ref=0 caps=- mode=40000 mtime=0.000000 parent=0) caps pAsLsXsFs
 -10-26 17:30:45.458983 7fd2996c6710 client8333 add_update_cap first one, opened snaprealm 0x2486bf0
 -10-26 17:30:45.458995 7fd2996c6710 client8333 add_update_cap issued - -> pAsLsXsFs from mds0 on 10000000000.head( cap_refs={} open={} ref=0 caps=pAsLsXsFs mode=40000 mtime=0.000000 parent=0)
 -10-26 17:30:45.459008 7fd2996c6710 client8333 update_inode_file_bits 10000000000.head( cap_refs={} open={} ref=0 caps=pAsLsXsFs mode=40755 mtime=0.000000 parent=0) - mtime 2010-10-16 23:04:16.042498
 -10-26 17:30:45.459025 7fd2996c6710 client8333 insert_dentry_inode lib vino 10000000000.head in dir 1
 -10-26 17:30:45.459034 7fd2996c6710 client8333  had vino 10000000000.head unlinked, linking
 -10-26 17:30:45.459049 7fd2996c6710 client8333 insert_trace  2: 'lib' -> 10000000000
 -10-26 17:30:45.459067 7fd2996c6710 client8333 add_update_inode adding 100000005f1.head( cap_refs={} open={} ref=0 caps=- mode=40000 mtime=0.000000 parent=0) caps pAsLsXsFs
 -10-26 17:30:45.459079 7fd2996c6710 client8333 add_update_cap first one, opened snaprealm 0x2486bf0
 -10-26 17:30:45.459089 7fd2996c6710 client8333 add_update_cap issued - -> pAsLsXsFs from mds0 on 100000005f1.head( cap_refs={} open={} ref=0 caps=pAsLsXsFs mode=40000 mtime=0.000000 parent=0)
 -10-26 17:30:45.459102 7fd2996c6710 client8333 update_inode_file_bits 100000005f1.head( cap_refs={} open={} ref=0 caps=pAsLsXsFs mode=40755 mtime=0.000000 parent=0) - mtime 2010-10-16 23:14:01.122594
 -10-26 17:30:45.459116 7fd2996c6710 client8333 insert_dentry_inode lib2 vino 100000005f1.head in dir 1
 -10-26 17:30:45.459124 7fd2996c6710 client8333  had vino 100000005f1.head unlinked, linking
 -10-26 17:30:45.459133 7fd2996c6710 client8333 insert_trace  3: 'lib2' -> 100000005f1
 -10-26 17:30:45.459146 7fd2996c6710 client8333 add_update_inode adding 100000009db.head( cap_refs={} open={} ref=0 caps=- mode=40000 mtime=0.000000 parent=0) caps pAsLsXsFs
 -10-26 17:30:45.459157 7fd2996c6710 client8333 add_update_cap first one, opened snaprealm 0x2486bf0
 -10-26 17:30:45.459166 7fd2996c6710 client8333 add_update_cap issued - -> pAsLsXsFs from mds0 on 100000009db.head( cap_refs={} open={} ref=0 caps=pAsLsXsFs mode=40000 mtime=0.000000 parent=0)
 -10-26 17:30:45.459179 7fd2996c6710 client8333 update_inode_file_bits 100000009db.head( cap_refs={} open={} ref=0 caps=pAsLsXsFs mode=40755 mtime=0.000000 parent=0) - mtime 2010-10-16 21:30:03.000000
 -10-26 17:30:45.459193 7fd2996c6710 client8333 insert_dentry_inode lib4 vino 100000009db.head in dir 1
 -10-26 17:30:45.459200 7fd2996c6710 client8333  had vino 100000009db.head unlinked, linking
 -10-26 17:30:45.459209 7fd2996c6710 client8333 insert_trace  4: 'lib4' -> 100000009db
 -10-26 17:30:45.459222 7fd2996c6710 client8333 add_update_inode adding 100000013a1.head( cap_refs={} open={} ref=0 caps=- mode=40000 mtime=0.000000 parent=0) caps pAsLsXsFs
 -10-26 17:30:45.459232 7fd2996c6710 client8333 add_update_cap first one, opened snaprealm 0x2486bf0
 -10-26 17:30:45.459242 7fd2996c6710 client8333 add_update_cap issued - -> pAsLsXsFs from mds0 on 100000013a1.head( cap_refs={} open={} ref=0 caps=pAsLsXsFs mode=40000 mtime=0.000000 parent=0)
 -10-26 17:30:45.459255 7fd2996c6710 client8333 update_inode_file_bits 100000013a1.head( cap_refs={} open={} ref=0 caps=pAsLsXsFs mode=40755 mtime=0.000000 parent=0) - mtime 2010-10-16 21:30:03.000000
 -10-26 17:30:45.459268 7fd2996c6710 client8333 insert_dentry_inode lib5 vino 100000013a1.head in dir 1
 -10-26 17:30:45.459276 7fd2996c6710 client8333  had vino 100000013a1.head unlinked, linking
 -10-26 17:30:45.459284 7fd2996c6710 client8333 insert_trace  5: 'lib5' -> 100000013a1
 -10-26 17:30:45.459297 7fd2996c6710 client8333 add_update_inode adding 10000002a60.head( cap_refs={} open={} ref=0 caps=- mode=100000 mtime=0.000000 parent=0) caps pAsLsXsFscr
 -10-26 17:30:45.459314 7fd2996c6710 client8333 add_update_cap first one, opened snaprealm 0x2486bf0
 -10-26 17:30:45.459325 7fd2996c6710 client8333 add_update_cap issued - -> pAsLsXsFscr from mds0 on 10000002a60.head( cap_refs={} open={} ref=0 caps=pAsLsXsFscr mode=100000 mtime=0.000000 parent=0)
 -10-26 17:30:45.459338 7fd2996c6710 client8333 update_inode_file_bits 10000002a60.head( cap_refs={} open={} ref=0 caps=pAsLsXsFscr mode=100000 mtime=0.000000 parent=0) - mtime 2010-10-25 22:00:20.502888
 -10-26 17:30:45.459352 7fd2996c6710 client8333 size 0 -> 104857600
 -10-26 17:30:45.459360 7fd2996c6710 client8333 insert_dentry_inode syn.7640.0 vino 10000002a60.head in dir 1
 -10-26 17:30:45.459367 7fd2996c6710 client8333  had vino 10000002a60.head unlinked, linking
 -10-26 17:30:45.459383 7fd2996c6710 client8333 insert_trace  6: 'syn.7640.0' -> 10000002a60
 -10-26 17:30:45.459398 7fd2996c6710 client8333 add_update_inode adding 100000013a0.head( cap_refs={} open={} ref=0 caps=- mode=100000 mtime=0.000000 parent=0) caps pAsLsXsFscr
 -10-26 17:30:45.459408 7fd2996c6710 client8333 add_update_cap first one, opened snaprealm 0x2486bf0
 -10-26 17:30:45.459419 7fd2996c6710 client8333 add_update_cap issued - -> pAsLsXsFscr from mds0 on 100000013a0.head( cap_refs={} open={} ref=0 caps=pAsLsXsFscr mode=100000 mtime=0.000000 parent=0)
 -10-26 17:30:45.459433 7fd2996c6710 client8333 update_inode_file_bits 100000013a0.head( cap_refs={} open={} ref=0 caps=pAsLsXsFscr mode=100644 mtime=0.000000 parent=0) - mtime 2010-10-16 23:34:58.682821
 -10-26 17:30:45.459462 7fd2996c6710 client8333 size 0 -> 209715200
 -10-26 17:30:45.459468 7fd2996c6710 client8333 truncate_seq 1 -> 2
 -10-26 17:30:45.459475 7fd2996c6710 client8333 truncate_size 18446744073709551615 -> 0
       osdc/Filer.cc: In function 'void Filer::file_to_extents(inodeno_t, ceph_file_layout*, uint64_t, uint64_t, std::vector<ObjectExtent, std::allocator<ObjectExtent> >&)':
       osdc/Filer.cc:305: FAILED assert(len > 0)
        ceph version 0.22.1 (commit:7464f9688001aa89f9673ba14e6d075d0ee33541)
 : (Client::update_inode_file_bits(Inode*, unsigned long, unsigned long, unsigned long, unsigned long, utime_t, utime_t, utime_t, int)+0x829) [0x46c5d9]
 : (Client::add_update_inode(InodeStat*, utime_t, int)+0xdc1) [0x471a71]
 : (Client::insert_trace(MetaRequest*, utime_t, int)+0x183d) [0x49bbdd]
 : (Client::handle_client_reply(MClientReply*)+0x4d2) [0x49d4e2]
 : (Client::ms_dispatch(Message*)+0x35b) [0x49dd9b]
 : (SimpleMessenger::dispatch_entry()+0x79b) [0x453bdb]
 : (SimpleMessenger::DispatchThread::entry()+0x1f) [0x44890f]
 : (Thread::_entry_func(void*)+0xa) [0x45a63a]
 : (()+0x69ca) [0x7fd29b3b29ca]
 : (clone()+0x6d) [0x7fd29a5d170d]
        NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.
       *** Caught signal (ABRT) ***
        ceph version 0.22.1 (commit:7464f9688001aa89f9673ba14e6d075d0ee33541)
 : (sigabrt_handler(int)+0xde) [0x54ba1e]
 : (()+0x33af0) [0x7fd29a51eaf0]
 : (gsignal()+0x35) [0x7fd29a51ea75]
 : (abort()+0x180) [0x7fd29a5225c0]
 : (__gnu_cxx::__verbose_terminate_handler()+0x115) [0x7fd29add48e5]
 : (()+0xcad16) [0x7fd29add2d16]
 : (()+0xcad43) [0x7fd29add2d43]
 : (()+0xcae3e) [0x7fd29add2e3e]
 : (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x69c) [0x538bdc]
 : (Filer::file_to_extents(inodeno_t, ceph_file_layout*, unsigned long, unsigned long, std::vector<ObjectExtent, std::allocator<ObjectExtent> >&)+0x1233) [0x4f23b3]
 : (Client::update_inode_file_bits(Inode*, unsigned long, unsigned long, unsigned long, unsigned long, utime_t, utime_t, utime_t, int)+0x829) [0x46c5d9]
 : (Client::add_update_inode(InodeStat*, utime_t, int)+0xdc1) [0x471a71]
 : (Client::insert_trace(MetaRequest*, utime_t, int)+0x183d) [0x49bbdd]
 : (Client::handle_client_reply(MClientReply*)+0x4d2) [0x49d4e2]
 : (Client::ms_dispatch(Message*)+0x35b) [0x49dd9b]
 : (SimpleMessenger::dispatch_entry()+0x79b) [0x453bdb]
 : (SimpleMessenger::DispatchThread::entry()+0x1f) [0x44890f]
 : (Thread::_entry_func(void*)+0xa) [0x45a63a]
 : (()+0x69ca) [0x7fd29b3b29ca]
 : (clone()+0x6d) [0x7fd29a5d170d]

« Previous
1
2
3
Next »

(3-3/3)

Project

General

Profile

Ceph

Bug #518 » client.log