Project

General

Profile

Actions
Copy link

Bug #8497

closed

OSDs stats getting DOWN , OUT , when i starts putting data to cluster

Added by karan singh almost 10 years ago. Updated almost 10 years ago.

Status:
Duplicate
Priority:
Immediate
Assignee:
-
Category:
OSD
Target version:
-
% Done:

0%

Source:
Development
Tags:
Firefly,OSD flapping
Backport:
Regression:
Severity:
1 - critical
Reviewed:
Affected Versions:
ceph-qa-suite:
Pull request ID:
Crash signature (v1):
Crash signature (v2):

Description

Hi
I have build a fresh Ceph cluster , stable firefly release 0.80.1, CentOS6.4

15 Node Cluster , 3 monitors , 165 OSD , capacity 0.5 PB

1. Cluster creation process was successful and state it Healthy_OK
2. After Two days of cluster , i have not not performed any operation and cluster was healthy.
3. I tried putting some data using CephFS , almost 1 TB of local data i tried to move to cluster. Just within 30 minutes cluster ODSs started getting DOWN and OUT of cluster. I tried manually making them UP but no LUCk. Then i stopped the COPY operation.
4. I set OSD NOOUT and OSD NODOWN , and after 1 hour cluster again came to healthy state. And i Unset OSD NOOUT and NODOWN. I thought the problem was due to CephFS not ready for production.
5. I integrated it with openstack and started creating volumes , again after 10-15 volume creation , cluster again went to unhealthy state, multiple ODS started getting down.
6. Now currently cluster is running with noout and nodown flags , as soon as i unset them , osds starts getting down. OR if i starts putting some data to cluster osds starts getting down.

I have identified 2 ODSs that went down and i captured logs with degug=20 , here are the failed osd logs.

====================================================== OSD.118 Logs ========================================================================

369> 2014-06-02 11:09:00.678422 7f98392d2700  5 - op tracker -- , seq: 804709, time: 2014-06-02 11:09:00.558258, event: header_read, request: pg_info(1 pgs e10842:16.d79) v4
  368> 2014-06-02 11:09:00.678426 7f98392d2700  5 - op tracker -- , seq: 804709, time: 2014-06-02 11:09:00.558259, event: throttled, request: pg_info(1 pgs e10842:16.d79) v4
  367> 2014-06-02 11:09:00.678429 7f98392d2700  5 - op tracker -- , seq: 804709, time: 2014-06-02 11:09:00.558316, event: all_read, request: pg_info(1 pgs e10842:16.d79) v4
  366> 2014-06-02 11:09:00.678432 7f98392d2700  5 - op tracker -- , seq: 804709, time: 2014-06-02 11:09:00.678417, event: dispatched, request: pg_info(1 pgs e10842:16.d79) v4
  365> 2014-06-02 11:09:00.678436 7f98392d2700  5 - op tracker -- , seq: 804709, time: 2014-06-02 11:09:00.678436, event: waiting_for_osdmap, request: pg_info(1 pgs e10842:16.d79) v4
  364> 2014-06-02 11:09:00.678439 7f98392d2700  7 osd.118 10842 handle_pg_info pg_info(1 pgs e10842:16.d79) v4 from osd.46
  -363> 2014-06-02 11:09:00.678441 7f98392d2700 15 osd.118 10842 require_same_or_newer_map 10842 (i am 10842) 0xd692f40
  -362> 2014-06-02 11:09:00.678444 7f98392d2700  5 - op tracker -- , seq: 804709, time: 2014-06-02 11:09:00.678444, event: started, request: pg_info(1 pgs e10842:16.d79) v4
  361> 2014-06-02 11:09:00.678457 7f98392d2700  5 - op tracker -- , seq: 804709, time: 2014-06-02 11:09:00.678456, event: done, request: pg_info(1 pgs e10842:16.d79) v4
  360> 2014-06-02 11:09:00.678465 7f98392d2700 10 osd.118 10842 do_waiters - start
  359> 2014-06-02 11:09:00.678469 7f98392d2700 10 osd.118 10842 do_waiters - finish
  358> 2014-06-02 11:09:00.678474 7f98392d2700  1 - 192.168.1.114:6816/90018189 <== osd.158 192.168.1.113:6809/84049479 16 ==== pg_notify(16.121(1) epoch 10842) v5 ==== 769+0+0 (1834866590 0 0) 0x9045780 con 0x11908c60
  357> 2014-06-02 11:09:00.678482 7f98392d2700 10 osd.118 10842 do_waiters - start
  356> 2014-06-02 11:09:00.678483 7f98392d2700 10 osd.118 10842 do_waiters - finish
  355> 2014-06-02 11:09:00.678484 7f98392d2700 20 osd.118 10842 _dispatch 0x9045780 pg_notify(16.121(1) epoch 10842) v5
  -354> 2014-06-02 11:09:00.678487 7f98392d2700  5 - op tracker -- , seq: 804710, time: 2014-06-02 11:09:00.664098, event: header_read, request: pg_notify(16.121(1) epoch 10842) v5
  353> 2014-06-02 11:09:00.678491 7f98392d2700  5 - op tracker -- , seq: 804710, time: 2014-06-02 11:09:00.664100, event: throttled, request: pg_notify(16.121(1) epoch 10842) v5
  352> 2014-06-02 11:09:00.678494 7f98392d2700  5 - op tracker -- , seq: 804710, time: 2014-06-02 11:09:00.664181, event: all_read, request: pg_notify(16.121(1) epoch 10842) v5
  351> 2014-06-02 11:09:00.678497 7f98392d2700  5 - op tracker -- , seq: 804710, time: 2014-06-02 11:09:00.678482, event: dispatched, request: pg_notify(16.121(1) epoch 10842) v5
  350> 2014-06-02 11:09:00.678500 7f98392d2700  5 - op tracker -- , seq: 804710, time: 2014-06-02 11:09:00.678500, event: waiting_for_osdmap, request: pg_notify(16.121(1) epoch 10842) v5
  349> 2014-06-02 11:09:00.678506 7f98392d2700  7 osd.118 10842 handle_pg_notify from osd.158
  -348> 2014-06-02 11:09:00.678508 7f98392d2700 15 osd.118 10842 require_same_or_newer_map 10842 (i am 10842) 0x9045780
  -347> 2014-06-02 11:09:00.678510 7f98392d2700  5 - op tracker -- , seq: 804710, time: 2014-06-02 11:09:00.678510, event: started, request: pg_notify(16.121(1) epoch 10842) v5
  346> 2014-06-02 11:09:00.678521 7f98392d2700  5 - op tracker -- , seq: 804710, time: 2014-06-02 11:09:00.678521, event: done, request: pg_notify(16.121(1) epoch 10842) v5
  345> 2014-06-02 11:09:00.678529 7f98392d2700 10 osd.118 10842 do_waiters - start
  344> 2014-06-02 11:09:00.678533 7f98392d2700 10 osd.118 10842 do_waiters - finish
  343> 2014-06-02 11:09:00.678539 7f98392d2700  1 - 192.168.1.114:6816/90018189 <== osd.113 192.168.1.113:6800/15058041 16 ==== pg_notify(10.19(7) epoch 10842) v5 ==== 1083+0+0 (132556027 0 0) 0xd691a40 con 0x119091e0
  342> 2014-06-02 11:09:00.678547 7f98392d2700 10 osd.118 10842 do_waiters - start
  341> 2014-06-02 11:09:00.678549 7f98392d2700 10 osd.118 10842 do_waiters - finish
  340> 2014-06-02 11:09:00.678550 7f98392d2700 20 osd.118 10842 _dispatch 0xd691a40 pg_notify(10.19(7) epoch 10842) v5
  -339> 2014-06-02 11:09:00.678553 7f98392d2700  5 - op tracker -- , seq: 804711, time: 2014-06-02 11:09:00.629463, event: header_read, request: pg_notify(10.19(7) epoch 10842) v5
  338> 2014-06-02 11:09:00.678557 7f98392d2700  5 - op tracker -- , seq: 804711, time: 2014-06-02 11:09:00.629465, event: throttled, request: pg_notify(10.19(7) epoch 10842) v5
  337> 2014-06-02 11:09:00.678560 7f98392d2700  5 - op tracker -- , seq: 804711, time: 2014-06-02 11:09:00.629533, event: all_read, request: pg_notify(10.19(7) epoch 10842) v5
  336> 2014-06-02 11:09:00.678563 7f98392d2700  5 - op tracker -- , seq: 804711, time: 2014-06-02 11:09:00.678547, event: dispatched, request: pg_notify(10.19(7) epoch 10842) v5
  335> 2014-06-02 11:09:00.678567 7f98392d2700  5 - op tracker -- , seq: 804711, time: 2014-06-02 11:09:00.678567, event: waiting_for_osdmap, request: pg_notify(10.19(7) epoch 10842) v5
  334> 2014-06-02 11:09:00.678572 7f98392d2700  7 osd.118 10842 handle_pg_notify from osd.113
  -333> 2014-06-02 11:09:00.678574 7f98392d2700 15 osd.118 10842 require_same_or_newer_map 10842 (i am 10842) 0xd691a40
  -332> 2014-06-02 11:09:00.678577 7f98392d2700  5 - op tracker -- , seq: 804711, time: 2014-06-02 11:09:00.678576, event: started, request: pg_notify(10.19(7) epoch 10842) v5
  331> 2014-06-02 11:09:00.678588 7f98392d2700  5 - op tracker -- , seq: 804711, time: 2014-06-02 11:09:00.678588, event: done, request: pg_notify(10.19(7) epoch 10842) v5
  330> 2014-06-02 11:09:00.678596 7f98392d2700 10 osd.118 10842 do_waiters - start
  329> 2014-06-02 11:09:00.678600 7f98392d2700 10 osd.118 10842 do_waiters - finish
  328> 2014-06-02 11:09:00.678607 7f98392d2700  1 - 192.168.1.114:6816/90018189 <== osd.68 192.168.1.108:6824/97011928 21 ==== pg_log(12.326 epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4 ==== 762+0+0 (1908503546 0 0) 0x85ca400 con 0x198aa100
  327> 2014-06-02 11:09:00.678616 7f98392d2700 10 osd.118 10842 do_waiters - start
  326> 2014-06-02 11:09:00.678619 7f98392d2700 10 osd.118 10842 do_waiters - finish
  325> 2014-06-02 11:09:00.678622 7f98392d2700 20 osd.118 10842 _dispatch 0x85ca400 pg_log(12.326 epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4
  -324> 2014-06-02 11:09:00.678626 7f98392d2700  5 - op tracker -- , seq: 804712, time: 2014-06-02 11:09:00.399055, event: header_read, request: pg_log(12.326 epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4
  323> 2014-06-02 11:09:00.678630 7f98392d2700  5 - op tracker -- , seq: 804712, time: 2014-06-02 11:09:00.399056, event: throttled, request: pg_log(12.326 epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4
  322> 2014-06-02 11:09:00.678635 7f98392d2700  5 - op tracker -- , seq: 804712, time: 2014-06-02 11:09:00.399231, event: all_read, request: pg_log(12.326 epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4
  321> 2014-06-02 11:09:00.678639 7f98392d2700  5 - op tracker -- , seq: 804712, time: 2014-06-02 11:09:00.678616, event: dispatched, request: pg_log(12.326 epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4
  320> 2014-06-02 11:09:00.678646 7f98392d2700  5 - op tracker -- , seq: 804712, time: 2014-06-02 11:09:00.678646, event: waiting_for_osdmap, request: pg_log(12.326 epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4
  319> 2014-06-02 11:09:00.678652 7f98392d2700  7 osd.118 10842 handle_pg_log pg_log(12.326 epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4 from osd.68
  -318> 2014-06-02 11:09:00.678658 7f98392d2700 15 osd.118 10842 require_same_or_newer_map 10842 (i am 10842) 0x85ca400
  -317> 2014-06-02 11:09:00.678660 7f98392d2700  5 - op tracker -- , seq: 804712, time: 2014-06-02 11:09:00.678660, event: started, request: pg_log(12.326 epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4
  316> 2014-06-02 11:09:00.678669 7f98392d2700  5 - op tracker -- , seq: 804712, time: 2014-06-02 11:09:00.678669, event: done, request: pg_log(12.326 epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4
  315> 2014-06-02 11:09:00.678679 7f98392d2700 10 osd.118 10842 do_waiters - start
  314> 2014-06-02 11:09:00.678682 7f98392d2700 10 osd.118 10842 do_waiters - finish
  313> 2014-06-02 11:09:00.678687 7f98392d2700  1 - 192.168.1.114:6816/90018189 <== osd.104 192.168.1.109:6808/10032986 16 ==== pg_info(1 pgs e10842:0.15a(1)) v4 ==== 765+0+0 (2198934457 0 0) 0xcfc3800 con 0x4f20160
  312> 2014-06-02 11:09:00.678695 7f98392d2700 10 osd.118 10842 do_waiters - start
  311> 2014-06-02 11:09:00.678696 7f98392d2700 10 osd.118 10842 do_waiters - finish
  310> 2014-06-02 11:09:00.678697 7f98392d2700 20 osd.118 10842 _dispatch 0xcfc3800 pg_info(1 pgs e10842:0.15a(1)) v4
  -309> 2014-06-02 11:09:00.678700 7f98392d2700  5 - op tracker -- , seq: 804713, time: 2014-06-02 11:09:00.421791, event: header_read, request: pg_info(1 pgs e10842:0.15a(1)) v4
  308> 2014-06-02 11:09:00.678704 7f98392d2700  5 - op tracker -- , seq: 804713, time: 2014-06-02 11:09:00.421794, event: throttled, request: pg_info(1 pgs e10842:0.15a(1)) v4
  307> 2014-06-02 11:09:00.678707 7f98392d2700  5 - op tracker -- , seq: 804713, time: 2014-06-02 11:09:00.421875, event: all_read, request: pg_info(1 pgs e10842:0.15a(1)) v4
  306> 2014-06-02 11:09:00.678711 7f98392d2700  5 - op tracker -- , seq: 804713, time: 2014-06-02 11:09:00.678695, event: dispatched, request: pg_info(1 pgs e10842:0.15a(1)) v4
  305> 2014-06-02 11:09:00.678717 7f98392d2700  5 - op tracker -- , seq: 804713, time: 2014-06-02 11:09:00.678717, event: waiting_for_osdmap, request: pg_info(1 pgs e10842:0.15a(1)) v4
  304> 2014-06-02 11:09:00.678723 7f98392d2700  7 osd.118 10842 handle_pg_info pg_info(1 pgs e10842:0.15a(1)) v4 from osd.104
  -303> 2014-06-02 11:09:00.678726 7f98392d2700 15 osd.118 10842 require_same_or_newer_map 10842 (i am 10842) 0xcfc3800
  -302> 2014-06-02 11:09:00.678729 7f98392d2700  5 - op tracker -- , seq: 804713, time: 2014-06-02 11:09:00.678729, event: started, request: pg_info(1 pgs e10842:0.15a(1)) v4
  301> 2014-06-02 11:09:00.678741 7f98392d2700  5 - op tracker -- , seq: 804713, time: 2014-06-02 11:09:00.678740, event: done, request: pg_info(1 pgs e10842:0.15a(1)) v4
  300> 2014-06-02 11:09:00.678749 7f98392d2700 10 osd.118 10842 do_waiters - start
  299> 2014-06-02 11:09:00.678753 7f98392d2700 10 osd.118 10842 do_waiters - finish
  298> 2014-06-02 11:09:00.678757 7f98392d2700  1 - 192.168.1.114:6816/90018189 <== osd.89 192.168.1.109:6827/80018984 13 ==== pg_info(1 pgs e10842:12.281) v4 ==== 714+0+0 (3450515911 0 0) 0x159a8c40 con 0x768d280
  297> 2014-06-02 11:09:00.678765 7f98392d2700 10 osd.118 10842 do_waiters - start
  296> 2014-06-02 11:09:00.678766 7f98392d2700 10 osd.118 10842 do_waiters - finish
  295> 2014-06-02 11:09:00.678767 7f98392d2700 20 osd.118 10842 _dispatch 0x159a8c40 pg_info(1 pgs e10842:12.281) v4
  -294> 2014-06-02 11:09:00.678770 7f98392d2700  5 - op tracker -- , seq: 804714, time: 2014-06-02 11:09:00.520280, event: header_read, request: pg_info(1 pgs e10842:12.281) v4
  293> 2014-06-02 11:09:00.678774 7f98392d2700  5 - op tracker -- , seq: 804714, time: 2014-06-02 11:09:00.520282, event: throttled, request: pg_info(1 pgs e10842:12.281) v4
  292> 2014-06-02 11:09:00.678777 7f98392d2700  5 - op tracker -- , seq: 804714, time: 2014-06-02 11:09:00.520367, event: all_read, request: pg_info(1 pgs e10842:12.281) v4
  291> 2014-06-02 11:09:00.678780 7f98392d2700  5 - op tracker -- , seq: 804714, time: 2014-06-02 11:09:00.678764, event: dispatched, request: pg_info(1 pgs e10842:12.281) v4
  290> 2014-06-02 11:09:00.678784 7f98392d2700  5 - op tracker -- , seq: 804714, time: 2014-06-02 11:09:00.678784, event: waiting_for_osdmap, request: pg_info(1 pgs e10842:12.281) v4
  289> 2014-06-02 11:09:00.678789 7f98392d2700  7 osd.118 10842 handle_pg_info pg_info(1 pgs e10842:12.281) v4 from osd.89
  -288> 2014-06-02 11:09:00.678792 7f98392d2700 15 osd.118 10842 require_same_or_newer_map 10842 (i am 10842) 0x159a8c40
  -287> 2014-06-02 11:09:00.678794 7f98392d2700  5 - op tracker -- , seq: 804714, time: 2014-06-02 11:09:00.678794, event: started, request: pg_info(1 pgs e10842:12.281) v4
  286> 2014-06-02 11:09:00.678805 7f98392d2700  5 - op tracker -- , seq: 804714, time: 2014-06-02 11:09:00.678805, event: done, request: pg_info(1 pgs e10842:12.281) v4
  285> 2014-06-02 11:09:00.678813 7f98392d2700 10 osd.118 10842 do_waiters - start
  284> 2014-06-02 11:09:00.678817 7f98392d2700 10 osd.118 10842 do_waiters - finish
  283> 2014-06-02 11:09:00.678822 7f98392d2700  1 - 192.168.1.114:6816/90018189 <== osd.72 192.168.1.107:6802/10018860 20 ==== pg_info(1 pgs e10842:0.232(1)) v4 ==== 765+0+0 (277696051 0 0) 0x52be3c0 con 0x1fc70420
  282> 2014-06-02 11:09:00.678830 7f98392d2700 10 osd.118 10842 do_waiters - start
  281> 2014-06-02 11:09:00.678833 7f98392d2700 10 osd.118 10842 do_waiters - finish
  280> 2014-06-02 11:09:00.678834 7f98392d2700 20 osd.118 10842 _dispatch 0x52be3c0 pg_info(1 pgs e10842:0.232(1)) v4
  -279> 2014-06-02 11:09:00.678837 7f98392d2700  5 - op tracker -- , seq: 804715, time: 2014-06-02 11:09:00.427880, event: header_read, request: pg_info(1 pgs e10842:0.232(1)) v4
  278> 2014-06-02 11:09:00.678840 7f98392d2700  5 - op tracker -- , seq: 804715, time: 2014-06-02 11:09:00.427882, event: throttled, request: pg_info(1 pgs e10842:0.232(1)) v4
  277> 2014-06-02 11:09:00.678844 7f98392d2700  5 - op tracker -- , seq: 804715, time: 2014-06-02 11:09:00.427938, event: all_read, request: pg_info(1 pgs e10842:0.232(1)) v4
  276> 2014-06-02 11:09:00.678847 7f98392d2700  5 - op tracker -- , seq: 804715, time: 2014-06-02 11:09:00.678830, event: dispatched, request: pg_info(1 pgs e10842:0.232(1)) v4
  275> 2014-06-02 11:09:00.678851 7f98392d2700  5 - op tracker -- , seq: 804715, time: 2014-06-02 11:09:00.678851, event: waiting_for_osdmap, request: pg_info(1 pgs e10842:0.232(1)) v4
  274> 2014-06-02 11:09:00.678856 7f98392d2700  7 osd.118 10842 handle_pg_info pg_info(1 pgs e10842:0.232(1)) v4 from osd.72
  -273> 2014-06-02 11:09:00.678859 7f98392d2700 15 osd.118 10842 require_same_or_newer_map 10842 (i am 10842) 0x52be3c0
  -272> 2014-06-02 11:09:00.678862 7f98392d2700  5 - op tracker -- , seq: 804715, time: 2014-06-02 11:09:00.678862, event: started, request: pg_info(1 pgs e10842:0.232(1)) v4
  271> 2014-06-02 11:09:00.678874 7f98392d2700  5 - op tracker -- , seq: 804715, time: 2014-06-02 11:09:00.678873, event: done, request: pg_info(1 pgs e10842:0.232(1)) v4
  270> 2014-06-02 11:09:00.678882 7f98392d2700 10 osd.118 10842 do_waiters - start
  269> 2014-06-02 11:09:00.678886 7f98392d2700 10 osd.118 10842 do_waiters - finish
  268> 2014-06-02 11:09:00.678897 7f98392d2700  1 - 192.168.1.114:6816/90018189 <== osd.65 192.168.1.109:6810/76006485 15 ==== pg_log(11.2 epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4 ==== 762+0+0 (3866491544 0 0) 0x355b000 con 0x1fc761a0
  267> 2014-06-02 11:09:00.678910 7f98392d2700 10 osd.118 10842 do_waiters - start
  266> 2014-06-02 11:09:00.678911 7f98392d2700 10 osd.118 10842 do_waiters - finish
  265> 2014-06-02 11:09:00.678912 7f98392d2700 20 osd.118 10842 _dispatch 0x355b000 pg_log(11.2 epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4
  -264> 2014-06-02 11:09:00.678916 7f98392d2700  5 - op tracker -- , seq: 804716, time: 2014-06-02 11:09:00.491874, event: header_read, request: pg_log(11.2 epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4
  263> 2014-06-02 11:09:00.678921 7f98392d2700  5 - op tracker -- , seq: 804716, time: 2014-06-02 11:09:00.491877, event: throttled, request: pg_log(11.2 epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4
  262> 2014-06-02 11:09:00.678925 7f98392d2700  5 - op tracker -- , seq: 804716, time: 2014-06-02 11:09:00.491954, event: all_read, request: pg_log(11.2 epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4
  261> 2014-06-02 11:09:00.678929 7f98392d2700  5 - op tracker -- , seq: 804716, time: 2014-06-02 11:09:00.678909, event: dispatched, request: pg_log(11.2 epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4
  260> 2014-06-02 11:09:00.678936 7f98392d2700  5 - op tracker -- , seq: 804716, time: 2014-06-02 11:09:00.678936, event: waiting_for_osdmap, request: pg_log(11.2 epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4
  259> 2014-06-02 11:09:00.678943 7f98392d2700  7 osd.118 10842 handle_pg_log pg_log(11.2 epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4 from osd.65
  -258> 2014-06-02 11:09:00.678949 7f98392d2700 15 osd.118 10842 require_same_or_newer_map 10842 (i am 10842) 0x355b000
  -257> 2014-06-02 11:09:00.678951 7f98392d2700  5 - op tracker -- , seq: 804716, time: 2014-06-02 11:09:00.678951, event: started, request: pg_log(11.2 epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4
  256> 2014-06-02 11:09:00.678961 7f98392d2700  5 - op tracker -- , seq: 804716, time: 2014-06-02 11:09:00.678961, event: done, request: pg_log(11.2 epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4
  255> 2014-06-02 11:09:00.678970 7f98392d2700 10 osd.118 10842 do_waiters - start
  254> 2014-06-02 11:09:00.678974 7f98392d2700 10 osd.118 10842 do_waiters - finish
  253> 2014-06-02 11:09:00.678978 7f98392d2700  1 - 192.168.1.114:6816/90018189 <== osd.5 192.168.1.101:6844/114018707 6 ==== osd_map(10842..10842 src has 3254..10842) v3 ==== 2256+0+0 (4211986158 0 0) 0x1fd2d340 con 0x7688160
  252> 2014-06-02 11:09:00.678986 7f98392d2700 10 osd.118 10842 do_waiters - start
  251> 2014-06-02 11:09:00.678987 7f98392d2700 10 osd.118 10842 do_waiters - finish
  250> 2014-06-02 11:09:00.678988 7f98392d2700 20 osd.118 10842 _dispatch 0x1fd2d340 osd_map(10842..10842 src has 3254..10842) v3
  -249> 2014-06-02 11:09:00.678995 7f98392d2700  3 osd.118 10842 handle_osd_map epochs [10842,10842], i have 10842, src has [3254,10842]
  -248> 2014-06-02 11:09:00.678998 7f98392d2700 10 osd.118 10842  no new maps here, dropping
  -247> 2014-06-02 11:09:00.679000 7f98392d2700 10 osd.118 10842 do_waiters - start
  246> 2014-06-02 11:09:00.679001 7f98392d2700 10 osd.118 10842 do_waiters - finish
  245> 2014-06-02 11:09:00.679004 7f98392d2700  1 - 192.168.1.114:6816/90018189 <== osd.79 192.168.1.109:6820/86064224 18 ==== pg_notify(6.164(587) epoch 10842) v5 ==== 32023+0+0 (1570566865 0 0) 0x14804980 con 0x179927e0
  244> 2014-06-02 11:09:00.679012 7f98392d2700 10 osd.118 10842 do_waiters - start
  243> 2014-06-02 11:09:00.679013 7f98392d2700 10 osd.118 10842 do_waiters - finish
  242> 2014-06-02 11:09:00.679014 7f98392d2700 20 osd.118 10842 _dispatch 0x14804980 pg_notify(6.164(587) epoch 10842) v5
  -241> 2014-06-02 11:09:00.679017 7f98392d2700  5 - op tracker -- , seq: 804717, time: 2014-06-02 11:09:00.522757, event: header_read, request: pg_notify(6.164(587) epoch 10842) v5
  240> 2014-06-02 11:09:00.679021 7f98392d2700  5 - op tracker -- , seq: 804717, time: 2014-06-02 11:09:00.522760, event: throttled, request: pg_notify(6.164(587) epoch 10842) v5
  239> 2014-06-02 11:09:00.679024 7f98392d2700  5 - op tracker -- , seq: 804717, time: 2014-06-02 11:09:00.523675, event: all_read, request: pg_notify(6.164(587) epoch 10842) v5
  238> 2014-06-02 11:09:00.679027 7f98392d2700  5 - op tracker -- , seq: 804717, time: 2014-06-02 11:09:00.679012, event: dispatched, request: pg_notify(6.164(587) epoch 10842) v5
  237> 2014-06-02 11:09:00.679031 7f98392d2700  5 - op tracker -- , seq: 804717, time: 2014-06-02 11:09:00.679031, event: waiting_for_osdmap, request: pg_notify(6.164(587) epoch 10842) v5
  236> 2014-06-02 11:09:00.679034 7f98392d2700  7 osd.118 10842 handle_pg_notify from osd.79
  -235> 2014-06-02 11:09:00.679036 7f98392d2700 15 osd.118 10842 require_same_or_newer_map 10842 (i am 10842) 0x14804980
  -234> 2014-06-02 11:09:00.679038 7f98392d2700  5 - op tracker -- , seq: 804717, time: 2014-06-02 11:09:00.679038, event: started, request: pg_notify(6.164(587) epoch 10842) v5
  233> 2014-06-02 11:09:00.679049 7f98392d2700  5 - op tracker -- , seq: 804717, time: 2014-06-02 11:09:00.679049, event: done, request: pg_notify(6.164(587) epoch 10842) v5
  232> 2014-06-02 11:09:00.679056 7f98392d2700 10 osd.118 10842 do_waiters - start
  231> 2014-06-02 11:09:00.679060 7f98392d2700 10 osd.118 10842 do_waiters - finish
  230> 2014-06-02 11:09:00.679159 7f98392d2700  1 - 192.168.1.114:6816/90018189 <== osd.122 192.168.1.111:6819/100052702 18 ==== pg_notify(7.18e(592) epoch 10842) v5 ==== 32278+0+0 (2669300493 0 0) 0x19709f80 con 0x1322eca0
  229> 2014-06-02 11:09:00.679172 7f98392d2700 10 osd.118 10842 do_waiters - start
  228> 2014-06-02 11:09:00.679174 7f98392d2700 10 osd.118 10842 do_waiters - finish
  227> 2014-06-02 11:09:00.679175 7f98392d2700 20 osd.118 10842 _dispatch 0x19709f80 pg_notify(7.18e(592) epoch 10842) v5
  -226> 2014-06-02 11:09:00.679178 7f98392d2700  5 - op tracker -- , seq: 804718, time: 2014-06-02 11:09:00.455729, event: header_read, request: pg_notify(7.18e(592) epoch 10842) v5
  225> 2014-06-02 11:09:00.679184 7f98392d2700  5 - op tracker -- , seq: 804718, time: 2014-06-02 11:09:00.455731, event: throttled, request: pg_notify(7.18e(592) epoch 10842) v5
  224> 2014-06-02 11:09:00.679188 7f98392d2700  5 - op tracker -- , seq: 804718, time: 2014-06-02 11:09:00.465984, event: all_read, request: pg_notify(7.18e(592) epoch 10842) v5
  223> 2014-06-02 11:09:00.679191 7f98392d2700  5 - op tracker -- , seq: 804718, time: 2014-06-02 11:09:00.679172, event: dispatched, request: pg_notify(7.18e(592) epoch 10842) v5
  222> 2014-06-02 11:09:00.679195 7f98392d2700  5 - op tracker -- , seq: 804718, time: 2014-06-02 11:09:00.679194, event: waiting_for_osdmap, request: pg_notify(7.18e(592) epoch 10842) v5
  221> 2014-06-02 11:09:00.679200 7f98392d2700  7 osd.118 10842 handle_pg_notify from osd.122
  -220> 2014-06-02 11:09:00.679206 7f98392d2700 15 osd.118 10842 require_same_or_newer_map 10842 (i am 10842) 0x19709f80
  -219> 2014-06-02 11:09:00.679209 7f98392d2700  5 - op tracker -- , seq: 804718, time: 2014-06-02 11:09:00.679209, event: started, request: pg_notify(7.18e(592) epoch 10842) v5
  218> 2014-06-02 11:09:00.679220 7f98392d2700  5 - op tracker -- , seq: 804718, time: 2014-06-02 11:09:00.679220, event: done, request: pg_notify(7.18e(592) epoch 10842) v5
  217> 2014-06-02 11:09:00.679230 7f98392d2700 10 osd.118 10842 do_waiters - start
  216> 2014-06-02 11:09:00.679233 7f98392d2700 10 osd.118 10842 do_waiters - finish
  215> 2014-06-02 11:09:00.679359 7f98392d2700  1 - 192.168.1.114:6816/90018189 <== osd.96 192.168.1.107:6815/12019917 16 ==== pg_notify(0.181(1) epoch 10842) v5 ==== 769+0+0 (1461860653 0 0) 0x1d3e9180 con 0x173298c0
  214> 2014-06-02 11:09:00.679372 7f98392d2700 10 osd.118 10842 do_waiters - start
  213> 2014-06-02 11:09:00.679374 7f98392d2700 10 osd.118 10842 do_waiters - finish
  212> 2014-06-02 11:09:00.679375 7f98392d2700 20 osd.118 10842 _dispatch 0x1d3e9180 pg_notify(0.181(1) epoch 10842) v5
  -211> 2014-06-02 11:09:00.679378 7f98392d2700  5 - op tracker -- , seq: 804719, time: 2014-06-02 11:09:00.508571, event: header_read, request: pg_notify(0.181(1) epoch 10842) v5
  210> 2014-06-02 11:09:00.679383 7f98392d2700  5 - op tracker -- , seq: 804719, time: 2014-06-02 11:09:00.508573, event: throttled, request: pg_notify(0.181(1) epoch 10842) v5
  209> 2014-06-02 11:09:00.679386 7f98392d2700  5 - op tracker -- , seq: 804719, time: 2014-06-02 11:09:00.508664, event: all_read, request: pg_notify(0.181(1) epoch 10842) v5
  208> 2014-06-02 11:09:00.679389 7f98392d2700  5 - op tracker -- , seq: 804719, time: 2014-06-02 11:09:00.679372, event: dispatched, request: pg_notify(0.181(1) epoch 10842) v5
  207> 2014-06-02 11:09:00.679393 7f98392d2700  5 - op tracker -- , seq: 804719, time: 2014-06-02 11:09:00.679393, event: waiting_for_osdmap, request: pg_notify(0.181(1) epoch 10842) v5
  206> 2014-06-02 11:09:00.679399 7f98392d2700  7 osd.118 10842 handle_pg_notify from osd.96
  -205> 2014-06-02 11:09:00.679401 7f98392d2700 15 osd.118 10842 require_same_or_newer_map 10842 (i am 10842) 0x1d3e9180
  -204> 2014-06-02 11:09:00.679404 7f98392d2700  5 - op tracker -- , seq: 804719, time: 2014-06-02 11:09:00.679404, event: started, request: pg_notify(0.181(1) epoch 10842) v5
  203> 2014-06-02 11:09:00.679417 7f98392d2700  5 - op tracker -- , seq: 804719, time: 2014-06-02 11:09:00.679417, event: done, request: pg_notify(0.181(1) epoch 10842) v5
  202> 2014-06-02 11:09:00.679426 7f98392d2700 10 osd.118 10842 do_waiters - start
  201> 2014-06-02 11:09:00.679430 7f98392d2700 10 osd.118 10842 do_waiters - finish
  200> 2014-06-02 11:09:00.679434 7f98392d2700  1 - 192.168.1.114:6816/90018189 <== osd.74 192.168.1.110:6835/16024166 16 ==== pg_log(9.13a epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4 ==== 762+0+0 (3942283219 0 0) 0x131af200 con 0x167891e0
  199> 2014-06-02 11:09:00.679443 7f98392d2700 10 osd.118 10842 do_waiters - start
  198> 2014-06-02 11:09:00.679444 7f98392d2700 10 osd.118 10842 do_waiters - finish
  197> 2014-06-02 11:09:00.679446 7f98392d2700 20 osd.118 10842 _dispatch 0x131af200 pg_log(9.13a epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4
  -196> 2014-06-02 11:09:00.679449 7f98392d2700  5 - op tracker -- , seq: 804720, time: 2014-06-02 11:09:00.517165, event: header_read, request: pg_log(9.13a epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4
  195> 2014-06-02 11:09:00.679454 7f98392d2700  5 - op tracker -- , seq: 804720, time: 2014-06-02 11:09:00.517167, event: throttled, request: pg_log(9.13a epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4
  194> 2014-06-02 11:09:00.679458 7f98392d2700  5 - op tracker -- , seq: 804720, time: 2014-06-02 11:09:00.517251, event: all_read, request: pg_log(9.13a epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4
  193> 2014-06-02 11:09:00.679462 7f98392d2700  5 - op tracker -- , seq: 804720, time: 2014-06-02 11:09:00.679443, event: dispatched, request: pg_log(9.13a epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4
  192> 2014-06-02 11:09:00.679470 7f98392d2700  5 - op tracker -- , seq: 804720, time: 2014-06-02 11:09:00.679470, event: waiting_for_osdmap, request: pg_log(9.13a epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4
  191> 2014-06-02 11:09:00.679476 7f98392d2700  7 osd.118 10842 handle_pg_log pg_log(9.13a epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4 from osd.74
  -190> 2014-06-02 11:09:00.679482 7f98392d2700 15 osd.118 10842 require_same_or_newer_map 10842 (i am 10842) 0x131af200
  -189> 2014-06-02 11:09:00.679486 7f98392d2700  5 - op tracker -- , seq: 804720, time: 2014-06-02 11:09:00.679486, event: started, request: pg_log(9.13a epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4
  188> 2014-06-02 11:09:00.679496 7f98392d2700  5 - op tracker -- , seq: 804720, time: 2014-06-02 11:09:00.679496, event: done, request: pg_log(9.13a epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4
  187> 2014-06-02 11:09:00.679505 7f98392d2700 10 osd.118 10842 do_waiters - start
  186> 2014-06-02 11:09:00.679509 7f98392d2700 10 osd.118 10842 do_waiters - finish
  185> 2014-06-02 11:09:00.679512 7f98392d2700  1 - 192.168.1.114:6816/90018189 <== osd.159 192.168.1.115:6815/73008493 18 ==== pg_log(16.e9a epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4 ==== 762+0+0 (1521415192 0 0) 0x672f200 con 0xcc8f640
  184> 2014-06-02 11:09:00.679520 7f98392d2700 10 osd.118 10842 do_waiters - start
  183> 2014-06-02 11:09:00.679522 7f98392d2700 10 osd.118 10842 do_waiters - finish
  182> 2014-06-02 11:09:00.679523 7f98392d2700 20 osd.118 10842 _dispatch 0x672f200 pg_log(16.e9a epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4
  -181> 2014-06-02 11:09:00.679526 7f98392d2700  5 - op tracker -- , seq: 804721, time: 2014-06-02 11:09:00.539520, event: header_read, request: pg_log(16.e9a epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4
  180> 2014-06-02 11:09:00.679531 7f98392d2700  5 - op tracker -- , seq: 804721, time: 2014-06-02 11:09:00.539523, event: throttled, request: pg_log(16.e9a epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4
  179> 2014-06-02 11:09:00.679536 7f98392d2700  5 - op tracker -- , seq: 804721, time: 2014-06-02 11:09:00.539622, event: all_read, request: pg_log(16.e9a epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4
  178> 2014-06-02 11:09:00.679541 7f98392d2700  5 - op tracker -- , seq: 804721, time: 2014-06-02 11:09:00.679520, event: dispatched, request: pg_log(16.e9a epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4
  177> 2014-06-02 11:09:00.679548 7f98392d2700  5 - op tracker -- , seq: 804721, time: 2014-06-02 11:09:00.679548, event: waiting_for_osdmap, request: pg_log(16.e9a epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4
  176> 2014-06-02 11:09:00.679555 7f98392d2700  7 osd.118 10842 handle_pg_log pg_log(16.e9a epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4 from osd.159
  -175> 2014-06-02 11:09:00.679560 7f98392d2700 15 osd.118 10842 require_same_or_newer_map 10842 (i am 10842) 0x672f200
  -174> 2014-06-02 11:09:00.679571 7f98392d2700  5 - op tracker -- , seq: 804721, time: 2014-06-02 11:09:00.679571, event: started, request: pg_log(16.e9a epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4
  173> 2014-06-02 11:09:00.679581 7f98392d2700  5 - op tracker -- , seq: 804721, time: 2014-06-02 11:09:00.679581, event: done, request: pg_log(16.e9a epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4
  172> 2014-06-02 11:09:00.679591 7f98392d2700 10 osd.118 10842 do_waiters - start
  171> 2014-06-02 11:09:00.679594 7f98392d2700 10 osd.118 10842 do_waiters - finish
  170> 2014-06-02 11:09:00.679598 7f98392d2700  1 - 192.168.1.114:6816/90018189 <== osd.82 192.168.1.107:6814/61012714 16 ==== pg_notify(16.1e9(4) epoch 10842) v5 ==== 922+0+0 (1763256932 0 0) 0x15cf1f80 con 0xcc88c60
  169> 2014-06-02 11:09:00.679606 7f98392d2700 10 osd.118 10842 do_waiters - start
  168> 2014-06-02 11:09:00.679607 7f98392d2700 10 osd.118 10842 do_waiters - finish
  167> 2014-06-02 11:09:00.679608 7f98392d2700 20 osd.118 10842 _dispatch 0x15cf1f80 pg_notify(16.1e9(4) epoch 10842) v5
  -166> 2014-06-02 11:09:00.679611 7f98392d2700  5 - op tracker -- , seq: 804722, time: 2014-06-02 11:09:00.482139, event: header_read, request: pg_notify(16.1e9(4) epoch 10842) v5
  165> 2014-06-02 11:09:00.679615 7f98392d2700  5 - op tracker -- , seq: 804722, time: 2014-06-02 11:09:00.482142, event: throttled, request: pg_notify(16.1e9(4) epoch 10842) v5
  164> 2014-06-02 11:09:00.679618 7f98392d2700  5 - op tracker -- , seq: 804722, time: 2014-06-02 11:09:00.482225, event: all_read, request: pg_notify(16.1e9(4) epoch 10842) v5
  163> 2014-06-02 11:09:00.679621 7f98392d2700  5 - op tracker -- , seq: 804722, time: 2014-06-02 11:09:00.679606, event: dispatched, request: pg_notify(16.1e9(4) epoch 10842) v5
  162> 2014-06-02 11:09:00.679625 7f98392d2700  5 - op tracker -- , seq: 804722, time: 2014-06-02 11:09:00.679625, event: waiting_for_osdmap, request: pg_notify(16.1e9(4) epoch 10842) v5
  161> 2014-06-02 11:09:00.679630 7f98392d2700  7 osd.118 10842 handle_pg_notify from osd.82
  -160> 2014-06-02 11:09:00.679633 7f98392d2700 15 osd.118 10842 require_same_or_newer_map 10842 (i am 10842) 0x15cf1f80
  -159> 2014-06-02 11:09:00.679636 7f98392d2700  5 - op tracker -- , seq: 804722, time: 2014-06-02 11:09:00.679636, event: started, request: pg_notify(16.1e9(4) epoch 10842) v5
  158> 2014-06-02 11:09:00.679647 7f98392d2700  5 - op tracker -- , seq: 804722, time: 2014-06-02 11:09:00.679647, event: done, request: pg_notify(16.1e9(4) epoch 10842) v5
  157> 2014-06-02 11:09:00.679655 7f98392d2700 10 osd.118 10842 do_waiters - start
  156> 2014-06-02 11:09:00.679659 7f98392d2700 10 osd.118 10842 do_waiters - finish
  155> 2014-06-02 11:09:00.679663 7f98392d2700  1 - 192.168.1.114:6816/90018189 <== osd.145 192.168.1.115:6813/74032359 18 ==== pg_notify(1.2e7(590),0.2f1(559) epoch 10842) v5 ==== 62223+0+0 (2789494302 0 0) 0x1d496900 con 0x5efd6a0
  154> 2014-06-02 11:09:00.679671 7f98392d2700 10 osd.118 10842 do_waiters - start
  153> 2014-06-02 11:09:00.679673 7f98392d2700 10 osd.118 10842 do_waiters - finish
  152> 2014-06-02 11:09:00.679674 7f98392d2700 20 osd.118 10842 _dispatch 0x1d496900 pg_notify(1.2e7(590),0.2f1(559) epoch 10842) v5
  -151> 2014-06-02 11:09:00.679677 7f98392d2700  5 - op tracker -- , seq: 804723, time: 2014-06-02 11:09:00.572123, event: header_read, request: pg_notify(1.2e7(590),0.2f1(559) epoch 10842) v5
  150> 2014-06-02 11:09:00.679681 7f98392d2700  5 - op tracker -- , seq: 804723, time: 2014-06-02 11:09:00.572124, event: throttled, request: pg_notify(1.2e7(590),0.2f1(559) epoch 10842) v5
  149> 2014-06-02 11:09:00.679685 7f98392d2700  5 - op tracker -- , seq: 804723, time: 2014-06-02 11:09:00.573331, event: all_read, request: pg_notify(1.2e7(590),0.2f1(559) epoch 10842) v5
  148> 2014-06-02 11:09:00.679688 7f98392d2700  5 - op tracker -- , seq: 804723, time: 2014-06-02 11:09:00.679671, event: dispatched, request: pg_notify(1.2e7(590),0.2f1(559) epoch 10842) v5
  147> 2014-06-02 11:09:00.679692 7f98392d2700  5 - op tracker -- , seq: 804723, time: 2014-06-02 11:09:00.679692, event: waiting_for_osdmap, request: pg_notify(1.2e7(590),0.2f1(559) epoch 10842) v5
  146> 2014-06-02 11:09:00.679698 7f98392d2700  7 osd.118 10842 handle_pg_notify from osd.145
  -145> 2014-06-02 11:09:00.679700 7f98392d2700 15 osd.118 10842 require_same_or_newer_map 10842 (i am 10842) 0x1d496900
  -144> 2014-06-02 11:09:00.679703 7f98392d2700  5 - op tracker -- , seq: 804723, time: 2014-06-02 11:09:00.679702, event: started, request: pg_notify(1.2e7(590),0.2f1(559) epoch 10842) v5
  143> 2014-06-02 11:09:00.679720 7f98392d2700  5 - op tracker -- , seq: 804723, time: 2014-06-02 11:09:00.679720, event: done, request: pg_notify(1.2e7(590),0.2f1(559) epoch 10842) v5
  142> 2014-06-02 11:09:00.679729 7f98392d2700 10 osd.118 10842 do_waiters - start
  141> 2014-06-02 11:09:00.679733 7f98392d2700 10 osd.118 10842 do_waiters - finish
  140> 2014-06-02 11:09:00.679903 7f98392d2700  1 - 192.168.1.114:6816/90018189 <== osd.109 192.168.1.109:6825/14032740 18 ==== pg_notify(12.16c(1) epoch 10842) v5 ==== 769+0+0 (1032297416 0 0) 0x1d48fa80 con 0x1732ad60
  139> 2014-06-02 11:09:00.679916 7f98392d2700 10 osd.118 10842 do_waiters - start
  138> 2014-06-02 11:09:00.679918 7f98392d2700 10 osd.118 10842 do_waiters - finish
  137> 2014-06-02 11:09:00.679919 7f98392d2700 20 osd.118 10842 _dispatch 0x1d48fa80 pg_notify(12.16c(1) epoch 10842) v5
  -136> 2014-06-02 11:09:00.679922 7f98392d2700  5 - op tracker -- , seq: 804724, time: 2014-06-02 11:09:00.554818, event: header_read, request: pg_notify(12.16c(1) epoch 10842) v5
  135> 2014-06-02 11:09:00.679927 7f98392d2700  5 - op tracker -- , seq: 804724, time: 2014-06-02 11:09:00.554820, event: throttled, request: pg_notify(12.16c(1) epoch 10842) v5
  134> 2014-06-02 11:09:00.679930 7f98392d2700  5 - op tracker -- , seq: 804724, time: 2014-06-02 11:09:00.554875, event: all_read, request: pg_notify(12.16c(1) epoch 10842) v5
  133> 2014-06-02 11:09:00.679933 7f98392d2700  5 - op tracker -- , seq: 804724, time: 2014-06-02 11:09:00.679916, event: dispatched, request: pg_notify(12.16c(1) epoch 10842) v5
  132> 2014-06-02 11:09:00.679937 7f98392d2700  5 - op tracker -- , seq: 804724, time: 2014-06-02 11:09:00.679937, event: waiting_for_osdmap, request: pg_notify(12.16c(1) epoch 10842) v5
  131> 2014-06-02 11:09:00.679943 7f98392d2700  7 osd.118 10842 handle_pg_notify from osd.109
  -130> 2014-06-02 11:09:00.679944 7f98392d2700 15 osd.118 10842 require_same_or_newer_map 10842 (i am 10842) 0x1d48fa80
  -129> 2014-06-02 11:09:00.679947 7f98392d2700  5 - op tracker -- , seq: 804724, time: 2014-06-02 11:09:00.679947, event: started, request: pg_notify(12.16c(1) epoch 10842) v5
  128> 2014-06-02 11:09:00.679959 7f98392d2700  5 - op tracker -- , seq: 804724, time: 2014-06-02 11:09:00.679959, event: done, request: pg_notify(12.16c(1) epoch 10842) v5
  127> 2014-06-02 11:09:00.679968 7f98392d2700 10 osd.118 10842 do_waiters - start
  126> 2014-06-02 11:09:00.679972 7f98392d2700 10 osd.118 10842 do_waiters - finish
  125> 2014-06-02 11:09:00.679976 7f98392d2700  1 - 192.168.1.114:6816/90018189 <== osd.153 192.168.1.115:6808/60063945 16 ==== pg_log(11.149 epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4 ==== 762+0+0 (166384271 0 0) 0x111c7200 con 0xf801a20
  124> 2014-06-02 11:09:00.679985 7f98392d2700 10 osd.118 10842 do_waiters - start
  123> 2014-06-02 11:09:00.679987 7f98392d2700 10 osd.118 10842 do_waiters - finish
  122> 2014-06-02 11:09:00.679988 7f98392d2700 20 osd.118 10842 _dispatch 0x111c7200 pg_log(11.149 epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4
  -121> 2014-06-02 11:09:00.679991 7f98392d2700  5 - op tracker -- , seq: 804725, time: 2014-06-02 11:09:00.602057, event: header_read, request: pg_log(11.149 epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4
  120> 2014-06-02 11:09:00.679996 7f98392d2700  5 - op tracker -- , seq: 804725, time: 2014-06-02 11:09:00.602059, event: throttled, request: pg_log(11.149 epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4
  119> 2014-06-02 11:09:00.680000 7f98392d2700  5 - op tracker -- , seq: 804725, time: 2014-06-02 11:09:00.602109, event: all_read, request: pg_log(11.149 epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4
  118> 2014-06-02 11:09:00.680004 7f98392d2700  5 - op tracker -- , seq: 804725, time: 2014-06-02 11:09:00.679985, event: dispatched, request: pg_log(11.149 epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4
  117> 2014-06-02 11:09:00.680009 7f98392d2700  5 - op tracker -- , seq: 804725, time: 2014-06-02 11:09:00.680009, event: waiting_for_osdmap, request: pg_log(11.149 epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4
  116> 2014-06-02 11:09:00.680016 7f98392d2700  7 osd.118 10842 handle_pg_log pg_log(11.149 epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4 from osd.153
  -115> 2014-06-02 11:09:00.680021 7f98392d2700 15 osd.118 10842 require_same_or_newer_map 10842 (i am 10842) 0x111c7200
  -114> 2014-06-02 11:09:00.680023 7f98392d2700  5 - op tracker -- , seq: 804725, time: 2014-06-02 11:09:00.680023, event: started, request: pg_log(11.149 epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4
  113> 2014-06-02 11:09:00.680032 7f98392d2700  5 - op tracker -- , seq: 804725, time: 2014-06-02 11:09:00.680032, event: done, request: pg_log(11.149 epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4
  112> 2014-06-02 11:09:00.680042 7f98392d2700 10 osd.118 10842 do_waiters - start
  111> 2014-06-02 11:09:00.680045 7f98392d2700 10 osd.118 10842 do_waiters - finish
  110> 2014-06-02 11:09:00.680048 7f98392d2700  1 - 192.168.1.114:6816/90018189 <== osd.49 192.168.1.103:6814/85036053 16 ==== pg_notify(16.feb(1) epoch 10842) v5 ==== 769+0+0 (45860697 0 0) 0xb379c00 con 0xcc8eca0
  109> 2014-06-02 11:09:00.680056 7f98392d2700 10 osd.118 10842 do_waiters - start
  108> 2014-06-02 11:09:00.680057 7f98392d2700 10 osd.118 10842 do_waiters - finish
  107> 2014-06-02 11:09:00.680058 7f98392d2700 20 osd.118 10842 _dispatch 0xb379c00 pg_notify(16.feb(1) epoch 10842) v5
  -106> 2014-06-02 11:09:00.680061 7f98392d2700  5 - op tracker -- , seq: 804726, time: 2014-06-02 11:09:00.457909, event: header_read, request: pg_notify(16.feb(1) epoch 10842) v5
  105> 2014-06-02 11:09:00.680065 7f98392d2700  5 - op tracker -- , seq: 804726, time: 2014-06-02 11:09:00.457911, event: throttled, request: pg_notify(16.feb(1) epoch 10842) v5
  104> 2014-06-02 11:09:00.680068 7f98392d2700  5 - op tracker -- , seq: 804726, time: 2014-06-02 11:09:00.458001, event: all_read, request: pg_notify(16.feb(1) epoch 10842) v5
  103> 2014-06-02 11:09:00.680071 7f98392d2700  5 - op tracker -- , seq: 804726, time: 2014-06-02 11:09:00.680056, event: dispatched, request: pg_notify(16.feb(1) epoch 10842) v5
  102> 2014-06-02 11:09:00.680075 7f98392d2700  5 - op tracker -- , seq: 804726, time: 2014-06-02 11:09:00.680075, event: waiting_for_osdmap, request: pg_notify(16.feb(1) epoch 10842) v5
  101> 2014-06-02 11:09:00.680081 7f98392d2700  7 osd.118 10842 handle_pg_notify from osd.49
  -100> 2014-06-02 11:09:00.680082 7f98392d2700 15 osd.118 10842 require_same_or_newer_map 10842 (i am 10842) 0xb379c00
   -99> 2014-06-02 11:09:00.680085 7f98392d2700  5 - op tracker -- , seq: 804726, time: 2014-06-02 11:09:00.680085, event: started, request: pg_notify(16.feb(1) epoch 10842) v5
   98> 2014-06-02 11:09:00.680095 7f98392d2700  5 - op tracker -- , seq: 804726, time: 2014-06-02 11:09:00.680095, event: done, request: pg_notify(16.feb(1) epoch 10842) v5
   97> 2014-06-02 11:09:00.680104 7f98392d2700 10 osd.118 10842 do_waiters - start
   96> 2014-06-02 11:09:00.680107 7f98392d2700 10 osd.118 10842 do_waiters - finish
   95> 2014-06-02 11:09:00.680111 7f98392d2700  1 - 192.168.1.114:6816/90018189 <== osd.17 192.168.1.101:6808/86030979 13 ==== pg_log(16.e38 epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4 ==== 762+0+0 (3634432978 0 0) 0x111c5a00 con 0xaf1a100
   94> 2014-06-02 11:09:00.680126 7f98392d2700 10 osd.118 10842 do_waiters - start
   93> 2014-06-02 11:09:00.680128 7f98392d2700 10 osd.118 10842 do_waiters - finish
   92> 2014-06-02 11:09:00.680129 7f98392d2700 20 osd.118 10842 _dispatch 0x111c5a00 pg_log(16.e38 epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4
   -91> 2014-06-02 11:09:00.680132 7f98392d2700  5 - op tracker -- , seq: 804727, time: 2014-06-02 11:09:00.578167, event: header_read, request: pg_log(16.e38 epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4
   90> 2014-06-02 11:09:00.680137 7f98392d2700  5 - op tracker -- , seq: 804727, time: 2014-06-02 11:09:00.578168, event: throttled, request: pg_log(16.e38 epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4
   89> 2014-06-02 11:09:00.680141 7f98392d2700  5 - op tracker -- , seq: 804727, time: 2014-06-02 11:09:00.578229, event: all_read, request: pg_log(16.e38 epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4
   88> 2014-06-02 11:09:00.680146 7f98392d2700  5 - op tracker -- , seq: 804727, time: 2014-06-02 11:09:00.680126, event: dispatched, request: pg_log(16.e38 epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4
   87> 2014-06-02 11:09:00.680153 7f98392d2700  5 - op tracker -- , seq: 804727, time: 2014-06-02 11:09:00.680152, event: waiting_for_osdmap, request: pg_log(16.e38 epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4
   86> 2014-06-02 11:09:00.680159 7f98392d2700  7 osd.118 10842 handle_pg_log pg_log(16.e38 epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4 from osd.17
   -85> 2014-06-02 11:09:00.680165 7f98392d2700 15 osd.118 10842 require_same_or_newer_map 10842 (i am 10842) 0x111c5a00
   -84> 2014-06-02 11:09:00.680167 7f98392d2700  5 - op tracker -- , seq: 804727, time: 2014-06-02 11:09:00.680167, event: started, request: pg_log(16.e38 epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4
   83> 2014-06-02 11:09:00.680176 7f98392d2700  5 - op tracker -- , seq: 804727, time: 2014-06-02 11:09:00.680176, event: done, request: pg_log(16.e38 epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4
   82> 2014-06-02 11:09:00.680186 7f98392d2700 10 osd.118 10842 do_waiters - start
   81> 2014-06-02 11:09:00.680189 7f98392d2700 10 osd.118 10842 do_waiters - finish
   80> 2014-06-02 11:09:00.680194 7f98392d2700  1 - 192.168.1.114:6816/90018189 <== osd.18 192.168.1.104:6828/94060687 17 ==== pg_log(14.27a epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4 ==== 762+0+0 (594420750 0 0) 0x56c4e00 con 0xaf1a3c0
   79> 2014-06-02 11:09:00.680202 7f98392d2700 10 osd.118 10842 do_waiters - start
   78> 2014-06-02 11:09:00.680204 7f98392d2700 10 osd.118 10842 do_waiters - finish
   77> 2014-06-02 11:09:00.680205 7f98392d2700 20 osd.118 10842 _dispatch 0x56c4e00 pg_log(14.27a epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4
   -76> 2014-06-02 11:09:00.680209 7f98392d2700  5 - op tracker -- , seq: 804728, time: 2014-06-02 11:09:00.478418, event: header_read, request: pg_log(14.27a epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4
   75> 2014-06-02 11:09:00.680214 7f98392d2700  5 - op tracker -- , seq: 804728, time: 2014-06-02 11:09:00.478420, event: throttled, request: pg_log(14.27a epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4
   74> 2014-06-02 11:09:00.680218 7f98392d2700  5 - op tracker -- , seq: 804728, time: 2014-06-02 11:09:00.478510, event: all_read, request: pg_log(14.27a epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4
   73> 2014-06-02 11:09:00.680222 7f98392d2700  5 - op tracker -- , seq: 804728, time: 2014-06-02 11:09:00.680202, event: dispatched, request: pg_log(14.27a epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4
   72> 2014-06-02 11:09:00.680229 7f98392d2700  5 - op tracker -- , seq: 804728, time: 2014-06-02 11:09:00.680229, event: waiting_for_osdmap, request: pg_log(14.27a epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4
   71> 2014-06-02 11:09:00.680236 7f98392d2700  7 osd.118 10842 handle_pg_log pg_log(14.27a epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4 from osd.18
   -70> 2014-06-02 11:09:00.680241 7f98392d2700 15 osd.118 10842 require_same_or_newer_map 10842 (i am 10842) 0x56c4e00
   -69> 2014-06-02 11:09:00.680244 7f98392d2700  5 - op tracker -- , seq: 804728, time: 2014-06-02 11:09:00.680244, event: started, request: pg_log(14.27a epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4
   68> 2014-06-02 11:09:00.680253 7f98392d2700  5 - op tracker -- , seq: 804728, time: 2014-06-02 11:09:00.680253, event: done, request: pg_log(14.27a epoch 10842 log log((0'0,0'0], crt=0'0) query_epoch 10842) v4
   67> 2014-06-02 11:09:00.680262 7f98392d2700 10 osd.118 10842 do_waiters - start
   66> 2014-06-02 11:09:00.680264 7f98392d2700 10 osd.118 10842 do_waiters - finish
   65> 2014-06-02 11:09:00.680267 7f98392d2700  1 - 192.168.1.114:6816/90018189 <== osd.33 192.168.1.103:6822/77017426 15 ==== pg_notify(6.281(1) epoch 10842) v5 ==== 769+0+0 (2443130291 0 0) 0xd697380 con 0x57a7220
   64> 2014-06-02 11:09:00.680274 7f98392d2700 10 osd.118 10842 do_waiters - start
   63> 2014-06-02 11:09:00.680275 7f98392d2700 10 osd.118 10842 do_waiters - finish
   62> 2014-06-02 11:09:00.680276 7f98392d2700 20 osd.118 10842 _dispatch 0xd697380 pg_notify(6.281(1) epoch 10842) v5
   -61> 2014-06-02 11:09:00.680279 7f98392d2700  5 - op tracker -- , seq: 804729, time: 2014-06-02 11:09:00.417625, event: header_read, request: pg_notify(6.281(1) epoch 10842) v5
   60> 2014-06-02 11:09:00.680282 7f98392d2700  5 - op tracker -- , seq: 804729, time: 2014-06-02 11:09:00.417628, event: throttled, request: pg_notify(6.281(1) epoch 10842) v5
   59> 2014-06-02 11:09:00.680286 7f98392d2700  5 - op tracker -- , seq: 804729, time: 2014-06-02 11:09:00.417716, event: all_read, request: pg_notify(6.281(1) epoch 10842) v5
   58> 2014-06-02 11:09:00.680289 7f98392d2700  5 - op tracker -- , seq: 804729, time: 2014-06-02 11:09:00.680274, event: dispatched, request: pg_notify(6.281(1) epoch 10842) v5
   57> 2014-06-02 11:09:00.680292 7f98392d2700  5 - op tracker -- , seq: 804729, time: 2014-06-02 11:09:00.680292, event: waiting_for_osdmap, request: pg_notify(6.281(1) epoch 10842) v5
   56> 2014-06-02 11:09:00.680296 7f98392d2700  7 osd.118 10842 handle_pg_notify from osd.33
   -55> 2014-06-02 11:09:00.680297 7f98392d2700 15 osd.118 10842 require_same_or_newer_map 10842 (i am 10842) 0xd697380
   -54> 2014-06-02 11:09:00.680299 7f98392d2700  5 - op tracker -- , seq: 804729, time: 2014-06-02 11:09:00.680299, event: started, request: pg_notify(6.281(1) epoch 10842) v5
   53> 2014-06-02 11:09:00.680311 7f98392d2700  5 - op tracker -- , seq: 804729, time: 2014-06-02 11:09:00.680310, event: done, request: pg_notify(6.281(1) epoch 10842) v5
   52> 2014-06-02 11:09:00.680319 7f98392d2700 10 osd.118 10842 do_waiters - start
   51> 2014-06-02 11:09:00.680323 7f98392d2700 10 osd.118 10842 do_waiters - finish
   50> 2014-06-02 11:09:00.680327 7f98392d2700  1 - 192.168.1.114:6816/90018189 <== osd.130 192.168.1.115:6809/11028428 13 ==== pg_info(1 pgs e10842:3.191(1)) v4 ==== 765+0+0 (560351203 0 0) 0x1d4939c0 con 0x3a569e0
   49> 2014-06-02 11:09:00.680336 7f98392d2700 10 osd.118 10842 do_waiters - start
   48> 2014-06-02 11:09:00.680337 7f98392d2700 10 osd.118 10842 do_waiters - finish
   47> 2014-06-02 11:09:00.680338 7f98392d2700 20 osd.118 10842 _dispatch 0x1d4939c0 pg_info(1 pgs e10842:3.191(1)) v4
   -46> 2014-06-02 11:09:00.680341 7f98392d2700  5 - op tracker -- , seq: 804730, time: 2014-06-02 11:09:00.589338, event: header_read, request: pg_info(1 pgs e10842:3.191(1)) v4
   45> 2014-06-02 11:09:00.680345 7f98392d2700  5 - op tracker -- , seq: 804730, time: 2014-06-02 11:09:00.589339, event: throttled, request: pg_info(1 pgs e10842:3.191(1)) v4
   44> 2014-06-02 11:09:00.680348 7f98392d2700  5 - op tracker -- , seq: 804730, time: 2014-06-02 11:09:00.589395, event: all_read, request: pg_info(1 pgs e10842:3.191(1)) v4
   43> 2014-06-02 11:09:00.680353 7f98392d2700  5 - op tracker -- , seq: 804730, time: 2014-06-02 11:09:00.680336, event: dispatched, request: pg_info(1 pgs e10842:3.191(1)) v4
   42> 2014-06-02 11:09:00.680359 7f98392d2700  5 - op tracker -- , seq: 804730, time: 2014-06-02 11:09:00.680359, event: waiting_for_osdmap, request: pg_info(1 pgs e10842:3.191(1)) v4
   41> 2014-06-02 11:09:00.680365 7f98392d2700  7 osd.118 10842 handle_pg_info pg_info(1 pgs e10842:3.191(1)) v4 from osd.130
   -40> 2014-06-02 11:09:00.680370 7f98392d2700 15 osd.118 10842 require_same_or_newer_map 10842 (i am 10842) 0x1d4939c0
   -39> 2014-06-02 11:09:00.680372 7f98392d2700  5 - op tracker -- , seq: 804730, time: 2014-06-02 11:09:00.680372, event: started, request: pg_info(1 pgs e10842:3.191(1)) v4
   38> 2014-06-02 11:09:00.680384 7f98392d2700  5 - op tracker -- , seq: 804730, time: 2014-06-02 11:09:00.680384, event: done, request: pg_info(1 pgs e10842:3.191(1)) v4
   37> 2014-06-02 11:09:00.680393 7f98392d2700 10 osd.118 10842 do_waiters - start
   36> 2014-06-02 11:09:00.680396 7f98392d2700 10 osd.118 10842 do_waiters - finish
   35> 2014-06-02 11:09:00.680401 7f98392d2700  1 - 192.168.1.114:6816/90018189 <== osd.41 192.168.1.101:6845/14054612 20 ==== pg_notify(16.927(463) epoch 10842) v5 ==== 24611+0+0 (3521848940 0 0) 0x14800380 con 0x57a32e0
   34> 2014-06-02 11:09:00.680409 7f98392d2700 10 osd.118 10842 do_waiters - start
   33> 2014-06-02 11:09:00.680411 7f98392d2700 10 osd.118 10842 do_waiters - finish
   32> 2014-06-02 11:09:00.680412 7f98392d2700 20 osd.118 10842 _dispatch 0x14800380 pg_notify(16.927(463) epoch 10842) v5
   -31> 2014-06-02 11:09:00.680414 7f98392d2700  5 - op tracker -- , seq: 804731, time: 2014-06-02 11:09:00.611955, event: header_read, request: pg_notify(16.927(463) epoch 10842) v5
   30> 2014-06-02 11:09:00.680418 7f98392d2700  5 - op tracker -- , seq: 804731, time: 2014-06-02 11:09:00.611957, event: throttled, request: pg_notify(16.927(463) epoch 10842) v5
   29> 2014-06-02 11:09:00.680421 7f98392d2700  5 - op tracker -- , seq: 804731, time: 2014-06-02 11:09:00.612442, event: all_read, request: pg_notify(16.927(463) epoch 10842) v5
   28> 2014-06-02 11:09:00.680424 7f98392d2700  5 - op tracker -- , seq: 804731, time: 2014-06-02 11:09:00.680409, event: dispatched, request: pg_notify(16.927(463) epoch 10842) v5
   27> 2014-06-02 11:09:00.680429 7f98392d2700  5 - op tracker -- , seq: 804731, time: 2014-06-02 11:09:00.680429, event: waiting_for_osdmap, request: pg_notify(16.927(463) epoch 10842) v5
   26> 2014-06-02 11:09:00.680435 7f98392d2700  7 osd.118 10842 handle_pg_notify from osd.41
   -25> 2014-06-02 11:09:00.680437 7f98392d2700 15 osd.118 10842 require_same_or_newer_map 10842 (i am 10842) 0x14800380
   -24> 2014-06-02 11:09:00.680439 7f98392d2700  5 - op tracker -- , seq: 804731, time: 2014-06-02 11:09:00.680439, event: started, request: pg_notify(16.927(463) epoch 10842) v5
   23> 2014-06-02 11:09:00.680450 7f98392d2700  5 - op tracker -- , seq: 804731, time: 2014-06-02 11:09:00.680450, event: done, request: pg_notify(16.927(463) epoch 10842) v5
   22> 2014-06-02 11:09:00.680537 7f98392d2700 10 osd.118 10842 do_waiters - start
   21> 2014-06-02 11:09:00.680543 7f98392d2700 10 osd.118 10842 do_waiters - finish
   20> 2014-06-02 11:09:00.680629 7f98392d2700  1 - 192.168.1.114:6816/90018189 <== osd.121 192.168.1.112:6801/12006135 16 ==== pg_notify(1.173(557) epoch 10842) v5 ==== 30445+0+0 (1497930911 0 0) 0x1c03af40 con 0x1732c360
   19> 2014-06-02 11:09:00.680642 7f98392d2700 10 osd.118 10842 do_waiters - start
   18> 2014-06-02 11:09:00.680644 7f98392d2700 10 osd.118 10842 do_waiters - finish
   17> 2014-06-02 11:09:00.680645 7f98392d2700 20 osd.118 10842 _dispatch 0x1c03af40 pg_notify(1.173(557) epoch 10842) v5
   -16> 2014-06-02 11:09:00.680648 7f98392d2700  5 - op tracker -- , seq: 804732, time: 2014-06-02 11:09:00.525959, event: header_read, request: pg_notify(1.173(557) epoch 10842) v5
   15> 2014-06-02 11:09:00.680654 7f98392d2700  5 - op tracker -- , seq: 804732, time: 2014-06-02 11:09:00.525961, event: throttled, request: pg_notify(1.173(557) epoch 10842) v5
   14> 2014-06-02 11:09:00.680657 7f98392d2700  5 - op tracker -- , seq: 804732, time: 2014-06-02 11:09:00.527460, event: all_read, request: pg_notify(1.173(557) epoch 10842) v5
   13> 2014-06-02 11:09:00.680660 7f98392d2700  5 - op tracker -- , seq: 804732, time: 2014-06-02 11:09:00.680642, event: dispatched, request: pg_notify(1.173(557) epoch 10842) v5
   12> 2014-06-02 11:09:00.680664 7f98392d2700  5 - op tracker -- , seq: 804732, time: 2014-06-02 11:09:00.680664, event: waiting_for_osdmap, request: pg_notify(1.173(557) epoch 10842) v5
   11> 2014-06-02 11:09:00.680670 7f98392d2700  7 osd.118 10842 handle_pg_notify from osd.121
   -10> 2014-06-02 11:09:00.680671 7f98392d2700 15 osd.118 10842 require_same_or_newer_map 10842 (i am 10842) 0x1c03af40
    -9> 2014-06-02 11:09:00.680674 7f98392d2700  5 - op tracker -- , seq: 804732, time: 2014-06-02 11:09:00.680674, event: started, request: pg_notify(1.173(557) epoch 10842) v5
    8> 2014-06-02 11:09:00.680686 7f98392d2700  5 - op tracker -- , seq: 804732, time: 2014-06-02 11:09:00.680686, event: done, request: pg_notify(1.173(557) epoch 10842) v5
    7> 2014-06-02 11:09:00.680695 7f98392d2700 10 osd.118 10842 do_waiters - start
    6> 2014-06-02 11:09:00.680698 7f98392d2700 10 osd.118 10842 do_waiters - finish
    5> 2014-06-02 11:09:00.680766 7f9846d1b700  5 osd.118 10842 tick
    -4> 2014-06-02 11:09:00.680780 7f98392d2700  1 - 192.168.1.114:6816/90018189 <== osd.64 192.168.1.110:6803/93028806 12 ==== pg_info(1 pgs e10842:16.21) v4 ==== 714+0+0 (3039660974 0 0) 0x78e0700 con 0xb03eb40
    3> 2014-06-02 11:09:00.706943 7f97e6884700  1 - 192.168.100.114:6844/90018189 >> :/0 pipe(0x5b7dc80 sd=722 :6844 s=0 pgs=0 cs=0 l=0 c=0x72106e0).accept sd=722 192.168.100.102:49546/0
    2> 2014-06-02 11:09:00.723892 7f97e6682700  1 - 192.168.1.114:6854/90018189 >> :/0 pipe(0xfaa2d00 sd=723 :6854 s=0 pgs=0 cs=0 l=0 c=0x1164b5a0).accept sd=723 192.168.1.102:40320/0
    1> 2014-06-02 11:09:00.734831 7f97e6480700  1 - 192.168.1.114:6854/90018189 >> :/0 pipe(0xfaa0c80 sd=724 :6854 s=0 pgs=0 cs=0 l=0 c=0x11648580).accept sd=724 192.168.1.111:38153/0
     0> 2014-06-02 11:09:00.734897 7f97f425d700 -1 msg/Pipe.cc: In function 'int Pipe::connect()' thread 7f97f425d700 time 2014-06-02 11:09:00.549538
msg/Pipe.cc: 1070: FAILED assert(m)
ceph version 0.80.1 (a38fe1169b6d2ac98b427334c12d7cf81f809b74)
 1: (Pipe::connect()+0x3d0c) [0xb2931c]
 2: (Pipe::writer()+0x9f3) [0xb2a063]
 3: (Pipe::Writer::entry()+0xd) [0xb359cd]
 4: (()+0x7851) [0x7f984d062851]
 5: (clone()+0x6d) [0x7f984bd9e94d]
 NOTE: a copy of the executable, or `objdump -rdS &lt;executable&gt;` is needed to interpret this.

--- logging levels ---
0/ 5 none
0/ 1 lockdep
0/ 1 context
1/ 1 crush
1/ 5 mds
1/ 5 mds_balancer
1/ 5 mds_locker
1/ 5 mds_log
1/ 5 mds_log_expire
1/ 5 mds_migrator
0/ 1 buffer
0/ 1 timer
0/ 1 filer
0/ 1 striper
0/ 1 objecter
0/ 5 rados
0/ 5 rbd
0/ 5 journaler
0/ 5 objectcacher
0/ 5 client
20/20 osd
0/ 5 optracker
0/ 5 objclass
1/ 3 filestore
1/ 3 keyvaluestore
1/ 3 journal
0/ 5 ms
1/ 5 mon
0/10 monc
1/ 5 paxos
0/ 5 tp
1/ 5 auth
1/ 5 crypto
1/ 1 finisher
1/ 5 heartbeatmap
1/ 5 perfcounter
1/ 5 rgw
1/ 5 javaclient
1/ 5 asok
1/ 1 throttle
2/-2 (syslog threshold)
-1/-1 (stderr threshold)
max_recent 10000
max_new 1000
log_file /ceph/storage0114/log/ceph/ceph-osd.118.log
-- end dump of recent events ---
2014-06-02 11:09:00.734907 7f97df30f700 -1 msg/Pipe.cc: In function 'int Pipe::connect()' thread 7f97df30f700 time 2014-06-02 11:09:00.549456
msg/Pipe.cc: 1070: FAILED assert(m)

ceph version 0.80.1 (a38fe1169b6d2ac98b427334c12d7cf81f809b74)
 1: (Pipe::connect()+0x3d0c) [0xb2931c]
 2: (Pipe::writer()+0x9f3) [0xb2a063]
 3: (Pipe::Writer::entry()+0xd) [0xb359cd]
 4: (()+0x7851) [0x7f984d062851]
 5: (clone()+0x6d) [0x7f984bd9e94d]
 NOTE: a copy of the executable, or `objdump -rdS &lt;executable&gt;` is needed to interpret this.

--- begin dump of recent events ---
-3> 2014-06-02 11:09:00.734907 7f97df30f700 -1 msg/Pipe.cc: In function 'int Pipe::connect()' thread 7f97df30f700 time 2014-06-02 11:09:00.549456
msg/Pipe.cc: 1070: FAILED assert(m)

ceph version 0.80.1 (a38fe1169b6d2ac98b427334c12d7cf81f809b74)
 1: (Pipe::connect()+0x3d0c) [0xb2931c]
 2: (Pipe::writer()+0x9f3) [0xb2a063]
 3: (Pipe::Writer::entry()+0xd) [0xb359cd]
 4: (()+0x7851) [0x7f984d062851]
 5: (clone()+0x6d) [0x7f984bd9e94d]
 NOTE: a copy of the executable, or `objdump -rdS &lt;executable&gt;` is needed to interpret this.
2> 2014-06-02 11:09:00.734913 7f97e637f700  1 - 192.168.100.114:6844/90018189 >> :/0 pipe(0x5b7bc00 sd=725 :6844 s=0 pgs=0 cs=0 l=0 c=0x7214ba0).accept sd=725 192.168.100.111:44273/0
    1> 2014-06-02 11:09:00.763997 7f97e607c700  1 - 192.168.1.114:6854/90018189 >> :/0 pipe(0xfaa3c00 sd=726 :6854 s=0 pgs=0 cs=0 l=0 c=0x57a3f40).accept sd=726 192.168.1.113:43814/0
     0> 2014-06-02 11:09:00.764057 7f97e5f7b700  1 -- 192.168.100.114:6844/90018189 >> :/0 pipe(0x5b78280 sd=727 :6844 s=0 pgs=0 cs=0 l=0 c=0x7215d80).accept sd=727 192.168.100.113:52859/0
--- logging levels ---
   0/ 5 none
   0/ 1 lockdep
   0/ 1 context
   1/ 1 crush
   1/ 5 mds
   1/ 5 mds_balancer
   1/ 5 mds_locker
   1/ 5 mds_log
   1/ 5 mds_log_expire
   1/ 5 mds_migrator
   0/ 1 buffer
   0/ 1 timer
   0/ 1 filer
   0/ 1 striper
   0/ 1 objecter
   0/ 5 rados
   0/ 5 rbd
   0/ 5 journaler
   0/ 5 objectcacher
   0/ 5 client
  20/20 osd
   0/ 5 optracker
   0/ 5 objclass
   1/ 3 filestore
   1/ 3 keyvaluestore
   1/ 3 journal
   0/ 5 ms
   1/ 5 mon
   0/10 monc
   1/ 5 paxos
   0/ 5 tp
   1/ 5 auth
   1/ 5 crypto
   1/ 1 finisher
   1/ 5 heartbeatmap
   1/ 5 perfcounter
   1/ 5 rgw
   1/ 5 javaclient
   1/ 5 asok
   1/ 1 throttle
  2/-2 (syslog threshold)
  -1/-1 (stderr threshold)
  max_recent     10000
  max_new         1000
  log_file /ceph/storage0114/log/ceph/ceph-osd.118.log
-- end dump of recent events ---

======================================== OSD.123 Logs =================================================================================================

[root@storage0114-ib ceph]# tail 1000 ceph-osd.123.log
-854> 2014-06-02 11:16:18.253423 7f02026f0700 10 osd.123 11123 do_waiters - start
853> 2014-06-02 11:16:18.253425 7f02026f0700 10 osd.123 11123 do_waiters - finish
852> 2014-06-02 11:16:18.253426 7f02026f0700 20 osd.123 11123 _dispatch 0x16d018c0 osd_map(11115..11115 src has 3254..11115) v3
-851> 2014-06-02 11:16:18.253430 7f02026f0700 3 osd.123 11123 handle_osd_map epochs [11115,11115], i have 11123, src has [3254,11115]
-850> 2014-06-02 11:16:18.253433 7f02026f0700 10 osd.123 11123 no new maps here, dropping
-849> 2014-06-02 11:16:18.253434 7f02026f0700 10 osd.123 11123 do_waiters - start
848> 2014-06-02 11:16:18.253435 7f02026f0700 10 osd.123 11123 do_waiters - finish
847> 2014-06-02 11:16:18.253439 7f02026f0700 1 - 192.168.1.114:6800/17052303 <== osd.155 192.168.1.111:6801/78033857 99 ==== pg_notify(9.3ff(441) epoch 11116) v5 ==== 22777+0+0 (2372128223 0 0) 0x19a04ec0 con 0x17ca5540
846> 2014-06-02 11:16:18.253447 7f02026f0700 10 osd.123 11123 do_waiters - start
845> 2014-06-02 11:16:18.253448 7f02026f0700 10 osd.123 11123 do_waiters - finish
844> 2014-06-02 11:16:18.253449 7f02026f0700 20 osd.123 11123 _dispatch 0x19a04ec0 pg_notify(9.3ff(441) epoch 11116) v5
-843> 2014-06-02 11:16:18.253464 7f02026f0700 5 - op tracker -- , seq: 150774, time: 2014-06-02 11:16:06.926042, event: header_read, request: pg_notify(9.3ff(441) epoch 11116) v5
842> 2014-06-02 11:16:18.253468 7f02026f0700 5 - op tracker -- , seq: 150774, time: 2014-06-02 11:16:06.926044, event: throttled, request: pg_notify(9.3ff(441) epoch 11116) v5
841> 2014-06-02 11:16:18.253471 7f02026f0700 5 - op tracker -- , seq: 150774, time: 2014-06-02 11:16:06.926682, event: all_read, request: pg_notify(9.3ff(441) epoch 11116) v5
840> 2014-06-02 11:16:18.253475 7f02026f0700 5 - op tracker -- , seq: 150774, time: 2014-06-02 11:16:18.253447, event: dispatched, request: pg_notify(9.3ff(441) epoch 11116) v5
839> 2014-06-02 11:16:18.253479 7f02026f0700 5 - op tracker -- , seq: 150774, time: 2014-06-02 11:16:18.253478, event: waiting_for_osdmap, request: pg_notify(9.3ff(441) epoch 11116) v5
838> 2014-06-02 11:16:18.253482 7f02026f0700 7 osd.123 11123 handle_pg_notify from osd.155
-837> 2014-06-02 11:16:18.253484 7f02026f0700 15 osd.123 11123 require_same_or_newer_map 11116 (i am 11123) 0x19a04ec0
-836> 2014-06-02 11:16:18.253486 7f02026f0700 7 osd.123 11123 still in boot state, dropping message pg_notify(9.3ff(441) epoch 11116) v5
-835> 2014-06-02 11:16:18.253489 7f02026f0700 5 - op tracker -- , seq: 150774, time: 2014-06-02 11:16:18.253489, event: done, request: pg_notify(9.3ff(441) epoch 11116) v5
834> 2014-06-02 11:16:18.253496 7f02026f0700 10 osd.123 11123 do_waiters - start
833> 2014-06-02 11:16:18.253497 7f02026f0700 10 osd.123 11123 do_waiters - finish
832> 2014-06-02 11:16:18.253582 7f02026f0700 1 - 192.168.1.114:6800/17052303 <== osd.150 192.168.1.111:6818/102010870 40 ==== osd_map(11116..11116 src has 3254..11116) v3 ==== 779+0+0 (1818745379 0 0) 0x5bb2640 con 0x1a3769e0
831> 2014-06-02 11:16:18.253605 7f02026f0700 10 osd.123 11123 do_waiters - start
830> 2014-06

Related issues 1 (0 open — 1 closed)

Is duplicate of Ceph - Bug #8232: Race condition during messenger rebindResolvedGreg Farnum04/27/2014

Actions
Actions
Copy link
 #1

Updated by karan singh almost 10 years ago

Logs in readable format

osd.123 - http://pastebin.com/QiAP5qGt
osd.118 - http://pastebin.com/GBdBAWg8

Let me know if you are able to detect problems by reading these logs.

Actions
Copy link
 #2

Updated by Greg Farnum almost 10 years ago

  • Status changed from New to Duplicate

This is a known issue and will be fixed in the next firefly release. :)

Actions
Copy link

Also available in: Atom PDF