Project

General

Profile

Bug #15314 » client.log

Mark Nelson, 03/30/2016 12:01 AM

 
2016-03-29 19:16:35.181203 7f756c3ca700 20 -- 10.0.10.107:0/3904314947 >> 10.0.10.107:6808/127105 pipe(0x7f755c01b8c0 sd=6 :33606 s=1 pgs=0 cs=0 l=1 c=0x7f755c023440).connect read peer addr 10.0.10.107:6808/127105 on socket 6
2016-03-29 19:16:35.181215 7f756c3ca700 20 -- 10.0.10.107:0/3904314947 >> 10.0.10.107:6808/127105 pipe(0x7f755c01b8c0 sd=6 :33606 s=1 pgs=0 cs=0 l=1 c=0x7f755c023440).connect peer addr for me is 10.0.10.107:33606/0
2016-03-29 19:16:35.181242 7f756c3ca700 10 -- 10.0.10.107:0/3904314947 >> 10.0.10.107:6808/127105 pipe(0x7f755c01b8c0 sd=6 :33606 s=1 pgs=0 cs=0 l=1 c=0x7f755c023440).connect sent my addr 10.0.10.107:0/3904314947
2016-03-29 19:16:35.181253 7f756c3ca700 10 -- 10.0.10.107:0/3904314947 >> 10.0.10.107:6808/127105 pipe(0x7f755c01b8c0 sd=6 :33606 s=1 pgs=0 cs=0 l=1 c=0x7f755c023440).connect.authorizer_len=22 protocol=1
2016-03-29 19:16:35.181258 7f756c3ca700 10 -- 10.0.10.107:0/3904314947 >> 10.0.10.107:6808/127105 pipe(0x7f755c01b8c0 sd=6 :33606 s=1 pgs=0 cs=0 l=1 c=0x7f755c023440).connect sending gseq=314 cseq=0 proto=24
2016-03-29 19:16:35.181273 7f756c3ca700 20 -- 10.0.10.107:0/3904314947 >> 10.0.10.107:6808/127105 pipe(0x7f755c01b8c0 sd=6 :33606 s=1 pgs=0 cs=0 l=1 c=0x7f755c023440).connect wrote (self +) cseq, waiting for reply
2016-03-29 19:16:35.181376 7f756c3ca700 20 -- 10.0.10.107:0/3904314947 >> 10.0.10.107:6808/127105 pipe(0x7f755c01b8c0 sd=6 :33606 s=1 pgs=0 cs=0 l=1 c=0x7f755c023440).connect got reply tag 1 connect_seq 1 global_seq 17947 proto 24 flags 1 features 576460752032874495
2016-03-29 19:16:35.181385 7f756c3ca700 10 -- 10.0.10.107:0/3904314947 >> 10.0.10.107:6808/127105 pipe(0x7f755c01b8c0 sd=6 :33606 s=2 pgs=17947 cs=1 l=1 c=0x7f755c023440).connect success 1, lossy = 1, features 576460752032874495
2016-03-29 19:16:35.181396 7f756c3ca700 20 -- 10.0.10.107:0/3904314947 >> 10.0.10.107:6808/127105 pipe(0x7f755c01b8c0 sd=6 :33606 s=2 pgs=17947 cs=1 l=1 c=0x7f755c023440).connect starting reader
2016-03-29 19:16:35.181422 7f756d6cf700 10 client.4546.objecter ms_handle_connect 0x7f755c023440
2016-03-29 19:16:35.181451 7f756c3ca700 10 -- 10.0.10.107:0/3904314947 >> 10.0.10.107:6808/127105 pipe(0x7f755c01b8c0 sd=6 :33606 s=2 pgs=17947 cs=1 l=1 c=0x7f755c023440).writer: state = open policy.server=0
2016-03-29 19:16:35.181472 7f756c3ca700 20 -- 10.0.10.107:0/3904314947 >> 10.0.10.107:6808/127105 pipe(0x7f755c01b8c0 sd=6 :33606 s=2 pgs=17947 cs=1 l=1 c=0x7f755c023440).writer encoding 1 features 576460752032874495 0x7f755c02bc80 osd_op(client.4546.0:1 2.989a68c7 cbt-librbdfio-incerta05-foo.rbd [stat] snapc 0=[] RETRY=312 ack+retry+read+known_if_redirected e121) v7
2016-03-29 19:16:35.181496 7f756c3ca700 20 -- 10.0.10.107:0/3904314947 >> 10.0.10.107:6808/127105 pipe(0x7f755c01b8c0 sd=6 :33606 s=2 pgs=17947 cs=1 l=1 c=0x7f755c023440).writer signed seq # 1): sig = 0
2016-03-29 19:16:35.181504 7f756c3ca700 20 -- 10.0.10.107:0/3904314947 >> 10.0.10.107:6808/127105 pipe(0x7f755c01b8c0 sd=6 :33606 s=2 pgs=17947 cs=1 l=1 c=0x7f755c023440).writer sending 1 0x7f755c02bc80
2016-03-29 19:16:35.181512 7f756c5cc700 20 -- 10.0.10.107:0/3904314947 >> 10.0.10.107:6808/127105 pipe(0x7f755c01b8c0 sd=6 :33606 s=2 pgs=17947 cs=1 l=1 c=0x7f755c023440).reader reading tag...
2016-03-29 19:16:35.181528 7f756c3ca700 10 -- 10.0.10.107:0/3904314947 >> 10.0.10.107:6808/127105 pipe(0x7f755c01b8c0 sd=6 :33606 s=2 pgs=17947 cs=1 l=1 c=0x7f755c023440).writer: state = open policy.server=0
2016-03-29 19:16:35.181534 7f756c3ca700 20 -- 10.0.10.107:0/3904314947 >> 10.0.10.107:6808/127105 pipe(0x7f755c01b8c0 sd=6 :33606 s=2 pgs=17947 cs=1 l=1 c=0x7f755c023440).writer sleeping
2016-03-29 19:16:35.182075 7f756c5cc700 20 -- 10.0.10.107:0/3904314947 >> 10.0.10.107:6808/127105 pipe(0x7f755c01b8c0 sd=6 :33606 s=2 pgs=17947 cs=1 l=1 c=0x7f755c023440).reader got ACK
2016-03-29 19:16:35.182093 7f756c5cc700 15 -- 10.0.10.107:0/3904314947 >> 10.0.10.107:6808/127105 pipe(0x7f755c01b8c0 sd=6 :33606 s=2 pgs=17947 cs=1 l=1 c=0x7f755c023440).reader got ack seq 1
2016-03-29 19:16:35.182101 7f756c5cc700 20 -- 10.0.10.107:0/3904314947 >> 10.0.10.107:6808/127105 pipe(0x7f755c01b8c0 sd=6 :33606 s=2 pgs=17947 cs=1 l=1 c=0x7f755c023440).reader reading tag...
2016-03-29 19:16:35.182107 7f756c5cc700 20 -- 10.0.10.107:0/3904314947 >> 10.0.10.107:6808/127105 pipe(0x7f755c01b8c0 sd=6 :33606 s=2 pgs=17947 cs=1 l=1 c=0x7f755c023440).reader got MSG
2016-03-29 19:16:35.182112 7f756c5cc700 20 -- 10.0.10.107:0/3904314947 >> 10.0.10.107:6808/127105 pipe(0x7f755c01b8c0 sd=6 :33606 s=2 pgs=17947 cs=1 l=1 c=0x7f755c023440).reader got envelope type=43 src osd.22 front=151 data=0 off 0
2016-03-29 19:16:35.182121 7f756c5cc700 10 -- 10.0.10.107:0/3904314947 >> 10.0.10.107:6808/127105 pipe(0x7f755c01b8c0 sd=6 :33606 s=2 pgs=17947 cs=1 l=1 c=0x7f755c023440).reader wants 151 from dispatch throttler 0/104857600
2016-03-29 19:16:35.182131 7f756c5cc700 20 -- 10.0.10.107:0/3904314947 >> 10.0.10.107:6808/127105 pipe(0x7f755c01b8c0 sd=6 :33606 s=2 pgs=17947 cs=1 l=1 c=0x7f755c023440).reader got front 151
2016-03-29 19:16:35.182137 7f756c5cc700 10 -- 10.0.10.107:0/3904314947 >> 10.0.10.107:6808/127105 pipe(0x7f755c01b8c0 sd=6 :33606 s=2 pgs=17947 cs=1 l=1 c=0x7f755c023440).aborted = 0
2016-03-29 19:16:35.182142 7f756c5cc700 20 -- 10.0.10.107:0/3904314947 >> 10.0.10.107:6808/127105 pipe(0x7f755c01b8c0 sd=6 :33606 s=2 pgs=17947 cs=1 l=1 c=0x7f755c023440).reader got 151 + 0 + 0 byte message
2016-03-29 19:16:35.182185 7f756c5cc700 -1 failed to decode message of type 43 v7: buffer::end_of_buffer
2016-03-29 19:16:35.182187 7f756c5cc700 1 dump:
00000000 1f 00 00 00 63 62 74 2d 6c 69 62 72 62 64 66 69 |....cbt-librbdfi|
00000010 6f 2d 69 6e 63 65 72 74 61 30 35 2d 66 6f 6f 2e |o-incerta05-foo.|
00000020 72 62 64 01 02 00 00 00 00 00 00 00 c7 68 9a 98 |rbd..........h..|
00000030 ff ff ff ff 19 00 40 00 00 00 00 00 fe ff ff ff |......@.........|
00000040 00 00 00 00 00 00 00 00 00 00 00 00 79 00 00 00 |............y...|
00000050 01 00 00 00 02 12 00 00 00 00 00 00 00 00 00 00 |................|
00000060 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................|
00000070 00 00 00 00 00 00 00 00 00 00 38 01 00 00 00 00 |..........8.....|
00000080 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................|
00000090 00 00 00 00 00 00 00 |.......|
00000097

2016-03-29 19:16:35.182247 7f756c5cc700 10 -- 10.0.10.107:0/3904314947 dispatch_throttle_release 151 to dispatch throttler 151/104857600
2016-03-29 19:16:35.182258 7f756c5cc700 2 -- 10.0.10.107:0/3904314947 >> 10.0.10.107:6808/127105 pipe(0x7f755c01b8c0 sd=6 :33606 s=2 pgs=17947 cs=1 l=1 c=0x7f755c023440).fault (0) Success
2016-03-29 19:16:35.182298 7f756c5cc700 10 -- 10.0.10.107:0/3904314947 >> 10.0.10.107:6808/127105 pipe(0x7f755c01b8c0 sd=6 :33606 s=2 pgs=17947 cs=1 l=1 c=0x7f755c023440).fault on lossy channel, failing
2016-03-29 19:16:35.182305 7f756c5cc700 10 -- 10.0.10.107:0/3904314947 >> 10.0.10.107:6808/127105 pipe(0x7f755c01b8c0 sd=6 :33606 s=2 pgs=17947 cs=1 l=1 c=0x7f755c023440).stop
2016-03-29 19:16:35.182318 7f756c5cc700 10 -- 10.0.10.107:0/3904314947 >> 10.0.10.107:6808/127105 pipe(0x7f755c01b8c0 sd=6 :33606 s=4 pgs=17947 cs=1 l=1 c=0x7f755c023440).unregister_pipe
2016-03-29 19:16:35.182325 7f756c5cc700 10 -- 10.0.10.107:0/3904314947 >> 10.0.10.107:6808/127105 pipe(0x7f755c01b8c0 sd=6 :33606 s=4 pgs=17947 cs=1 l=1 c=0x7f755c023440).discard_queue
2016-03-29 19:16:35.182340 7f756c5cc700 10 -- 10.0.10.107:0/3904314947 >> 10.0.10.107:6808/127105 pipe(0x7f755c01b8c0 sd=6 :33606 s=4 pgs=17947 cs=1 l=1 c=0x7f755c023440).reader done
2016-03-29 19:16:35.182346 7f756c3ca700 20 -- 10.0.10.107:0/3904314947 >> 10.0.10.107:6808/127105 pipe(0x7f755c01b8c0 sd=6 :33606 s=4 pgs=17947 cs=1 l=1 c=0x7f755c023440).writer finishing
2016-03-29 19:16:35.182359 7f756c3ca700 10 -- 10.0.10.107:0/3904314947 queue_reap 0x7f755c01b8c0
2016-03-29 19:16:35.182360 7f756d6cf700 1 client.4546.objecter ms_handle_reset on osd.22
2016-03-29 19:16:35.182365 7f756c3ca700 10 -- 10.0.10.107:0/3904314947 >> 10.0.10.107:6808/127105 pipe(0x7f755c01b8c0 sd=6 :33606 s=4 pgs=17947 cs=1 l=1 c=0x7f755c023440).writer done
2016-03-29 19:16:35.182366 7f756d6cf700 10 client.4546.objecter reopen_session osd.22 session, addr now osd.22 10.0.10.107:6808/127105
2016-03-29 19:16:35.182372 7f7567fff700 10 -- 10.0.10.107:0/3904314947 reaper
2016-03-29 19:16:35.182378 7f7567fff700 10 -- 10.0.10.107:0/3904314947 reaper reaping pipe 0x7f755c01b8c0 10.0.10.107:6808/127105
2016-03-29 19:16:35.182382 7f7567fff700 10 -- 10.0.10.107:0/3904314947 >> 10.0.10.107:6808/127105 pipe(0x7f755c01b8c0 sd=6 :33606 s=4 pgs=17947 cs=1 l=1 c=0x7f755c023440).discard_queue
2016-03-29 19:16:35.182389 7f7567fff700 10 -- 10.0.10.107:0/3904314947 >> 10.0.10.107:6808/127105 pipe(0x7f755c01b8c0 sd=6 :33606 s=4 pgs=17947 cs=1 l=1 c=0x7f755c023440).unregister_pipe - not registered
2016-03-29 19:16:35.182399 7f7567fff700 20 -- 10.0.10.107:0/3904314947 >> 10.0.10.107:6808/127105 pipe(0x7f755c01b8c0 sd=6 :33606 s=4 pgs=17947 cs=1 l=1 c=0x7f755c023440).join
2016-03-29 19:16:35.182405 7f756d6cf700 1 -- 10.0.10.107:0/3904314947 mark_down 0x7f755c023440 -- pipe dne
2016-03-29 19:16:35.182420 7f756d6cf700 10 -- 10.0.10.107:0/3904314947 connect_rank to 10.0.10.107:6808/127105, creating pipe and registering
2016-03-29 19:16:35.182475 7f756d6cf700 10 -- 10.0.10.107:0/3904314947 >> 10.0.10.107:6808/127105 pipe(0x7f755c00dc20 sd=-1 :0 s=1 pgs=0 cs=0 l=1 c=0x7f755c02bc80).register_pipe
2016-03-29 19:16:35.182483 7f756d6cf700 10 -- 10.0.10.107:0/3904314947 get_connection osd.22 10.0.10.107:6808/127105 new 0x7f755c00dc20
2016-03-29 19:16:35.182478 7f756c5cc700 10 -- 10.0.10.107:0/3904314947 >> 10.0.10.107:6808/127105 pipe(0x7f755c00dc20 sd=-1 :0 s=1 pgs=0 cs=0 l=1 c=0x7f755c02bc80).writer: state = connecting policy.server=0
2016-03-29 19:16:35.182507 7f756c5cc700 10 -- 10.0.10.107:0/3904314947 >> 10.0.10.107:6808/127105 pipe(0x7f755c00dc20 sd=-1 :0 s=1 pgs=0 cs=0 l=1 c=0x7f755c02bc80).connect 0
2016-03-29 19:16:35.182526 7f756d6cf700 15 client.4546.objecter _send_op 1 to osd.22
2016-03-29 19:16:35.182529 7f756d6cf700 1 -- 10.0.10.107:0/3904314947 --> 10.0.10.107:6808/127105 -- osd_op(client.4546.0:1 2.989a68c7 cbt-librbdfio-incerta05-foo.rbd [stat] snapc 0=[] RETRY=313 ack+retry+read+known_if_redirected e121) v7 -- ?+0 0x7f755c016060 con 0x7f755c02bc80
2016-03-29 19:16:35.182536 7f756c5cc700 10 -- 10.0.10.107:0/3904314947 >> 10.0.10.107:6808/127105 pipe(0x7f755c00dc20 sd=5 :0 s=1 pgs=0 cs=0 l=1 c=0x7f755c02bc80).connecting to 10.0.10.107:6808/127105
2016-03-29 19:16:35.182537 7f756d6cf700 20 -- 10.0.10.107:0/3904314947 submit_message osd_op(client.4546.0:1 2.989a68c7 cbt-librbdfio-incerta05-foo.rbd [stat] snapc 0=[] RETRY=313 ack+retry+read+known_if_redirected e121) v7 remote, 10.0.10.107:6808/127105, have pipe.
2016-03-29 19:16:35.182539 7f7567fff700 10 -- 10.0.10.107:0/3904314947 reaper reaped pipe 0x7f755c01b8c0 10.0.10.107:6808/127105
2016-03-29 19:16:35.182547 7f756d6cf700 10 client.4546.objecter _maybe_request_map subscribing (onetime) to next osd map
2016-03-29 19:16:35.182551 7f7567fff700 10 -- 10.0.10.107:0/3904314947 reaper deleted pipe 0x7f755c01b8c0
2016-03-29 19:16:35.182556 7f7567fff700 10 -- 10.0.10.107:0/3904314947 reaper done

(1-1/4)