Bug #5171
closedAfter crash monitor trying to bind to address of other monitor
0%
Description
Rebooted cluster (3 nodes, 3 monitors). After it one of monitors sync, update database, then die (assertion) and then always want to use address of other mon (IMHO).
There are log tail (monitor mon.1, on address 10.227.227.101, but trying to use 10.227.227.103 from mon.3):
-25> 2013-05-25 01:26:48.662849 7fc062a83700 1 mon.1@0(synchronizing) e1 discarding message auth(proto 0 30 bytes epoch 1) v1 and sending client elsewhere
-24> 2013-05-25 01:26:48.662852 7fc062a83700 1 -- 10.227.227.101:6789/0 mark_down 0x7fc048004900 -- pipe dne
-23> 2013-05-25 01:26:48.662858 7fc062a83700 5 mon.1@0(synchronizing) e1 waitlisting message auth(proto 0 26 bytes epoch 1) v1
-22> 2013-05-25 01:26:48.662862 7fc062a83700 1 mon.1@0(synchronizing) e1 discarding message auth(proto 0 26 bytes epoch 1) v1 and sending client elsewhere
-21> 2013-05-25 01:26:48.662865 7fc062a83700 1 -- 10.227.227.101:6789/0 mark_down 0x7fc0480056b0 -- pipe dne
-20> 2013-05-25 01:26:48.662871 7fc062a83700 5 mon.1@0(synchronizing) e1 waitlisting message auth(proto 0 26 bytes epoch 1) v1
-19> 2013-05-25 01:26:48.662874 7fc062a83700 1 mon.1@0(synchronizing) e1 discarding message auth(proto 0 30 bytes epoch 0) v1 and sending client elsewhere
-18> 2013-05-25 01:26:48.662877 7fc062a83700 1 -- 10.227.227.101:6789/0 mark_down 0x7fc048002f80 -- pipe dne
-17> 2013-05-25 01:26:48.662883 7fc062a83700 1 mon.1@0(synchronizing) e1 discarding message auth(proto 0 30 bytes epoch 1) v1 and sending client elsewhere
-16> 2013-05-25 01:26:48.662885 7fc062a83700 1 -- 10.227.227.101:6789/0 mark_down 0x7fc048001060 -- pipe dne
-15> 2013-05-25 01:26:48.662890 7fc062a83700 1 mon.1@0(synchronizing) e1 discarding message auth(proto 0 26 bytes epoch 1) v1 and sending client elsewhere
-14> 2013-05-25 01:26:48.662892 7fc062a83700 1 -- 10.227.227.101:6789/0 mark_down 0x7fc048006e90 -- pipe dne
-13> 2013-05-25 01:26:48.662898 7fc062a83700 5 mon.1@0(synchronizing) e1 waitlisting message auth(proto 0 26 bytes epoch 1) v1
-12> 2013-05-25 01:26:48.662901 7fc062a83700 5 mon.1@0(synchronizing) e1 waitlisting message auth(proto 0 30 bytes epoch 0) v1
-11> 2013-05-25 01:26:48.662948 7fc062282700 5 mon.1@0(synchronizing) e1 waitlisting message auth(proto 0 30 bytes epoch 1) v1
-10> 2013-05-25 01:26:48.662989 7fc062282700 1 -- 10.227.227.101:6789/0 <== client.26092 10.227.227.104:0/2032174 1 ==== auth(proto 0 30 bytes epoch 1) v1 ==== 60+0+0 (681331102 0 0) 0x7fbeb8006270 con 0x7fc0480008c0
-9> 2013-05-25 01:26:48.663013 7fc062282700 5 mon.1@0(synchronizing) e1 waitlisting message auth(proto 0 30 bytes epoch 1) v1
-8> 2013-05-25 01:26:48.663022 7fc062282700 1 -- 10.227.227.101:6789/0 <== client.26095 10.227.227.104:0/3032174 1 ==== auth(proto 0 30 bytes epoch 1) v1 ==== 60+0+0 (2064528846 0 0) 0x7fbf3c00a940 con 0x7fc048000a20
-7> 2013-05-25 01:26:48.663035 7fc062282700 5 mon.1@0(synchronizing) e1 waitlisting message auth(proto 0 30 bytes epoch 1) v1
-6> 2013-05-25 01:26:48.915526 7fc060f7d700 1 -- 10.227.227.101:6789/0 >> :/0 pipe(0x7fc0480035d0 sd=27 :6789 s=0 pgs=0 cs=0 l=0).accept sd=27 10.227.227.101:35927/0
-5> 2013-05-25 01:26:48.915929 7fc062282700 1 -- 10.227.227.101:6789/0 <== osd.1 10.227.227.101:6805/29217 1 ==== auth(proto 0 26 bytes epoch 1) v1 ==== 56+0+0 (1484277464 0 0) 0x7fc00000ee40 con 0x7fc0480027b0
-4> 2013-05-25 01:26:48.915974 7fc062282700 5 mon.1@0(synchronizing) e1 waitlisting message auth(proto 0 26 bytes epoch 1) v1
-3> 2013-05-25 01:26:48.981958 7fc062282700 1 -- 10.227.227.101:6789/0 <== mon.1 10.227.227.103:6789/0 16632 ==== election(2b558bc4-8db2-44d3-8fac-9d37d9ed0549 propose 2895) v4 ==== 525+0+0 (373874603 0 0) 0x7fc03c000b40 con 0x1d99790
-2> 2013-05-25 01:26:49.039211 7fc026534700 2 -- 10.227.227.101:6789/0 >> 10.227.227.101:6800/29194 pipe(0x7fc048001490 sd=24 :6789 s=2 pgs=622 cs=1 l=1).reader couldn't read tag, Success
-1> 2013-05-25 01:26:49.039255 7fc026534700 2 -- 10.227.227.101:6789/0 >> 10.227.227.101:6800/29194 pipe(0x7fc048001490 sd=24 :6789 s=2 pgs=622 cs=1 l=1).fault 0: Success
0> 2013-05-25 01:26:49.225640 7fc062a83700 -1 mon/Monitor.cc: In function 'void Monitor::sync_timeout(entity_inst_t&)' thread 7fc062a83700 time 2013-05-25 01:26:49.224458
mon/Monitor.cc: 1099: FAILED assert(sync_role == SYNC_ROLE_REQUESTER)
ceph version 0.62-350-gbb407bf (bb407bfd101d9707c63655cb3c1b51346a0de8cd)
1: (Monitor::sync_timeout(entity_inst_t&)+0x9eb) [0x4d240b]
2: (Context::complete(int)+0xa) [0x4e255a]
3: (SafeTimer::timer_thread()+0x1c2) [0x6962a2]
4: (SafeTimerThread::entry()+0xd) [0x697e3d]
5: (()+0x8216) [0x7fc0670f7216]
6: (clone()+0x6d) [0x7fc0655d204d]
NOTE: a copy of the executable, or `objdump -rdS <executable>` 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
0/ 5 osd
0/ 5 optracker
0/ 5 objclass
1/ 3 filestore
1/ 3 journal
0/ 5 ms
1/ 5 mon
0/10 monc
0/ 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 hadoop
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 /var/log/ceph/ceph-mon.1.log
--- end dump of recent events ---
2013-05-25 01:26:49.364326 7fc062a83700 -1 *** Caught signal (Aborted) **
in thread 7fc062a83700
ceph version 0.62-350-gbb407bf (bb407bfd101d9707c63655cb3c1b51346a0de8cd)
1: /usr/bin/ceph-mon() [0x5c4fbd]
2: (()+0x10630) [0x7fc0670ff630]
3: (gsignal()+0x39) [0x7fc0654ce8c9]
4: (abort()+0x160) [0x7fc0654cff80]
5: (__gnu_cxx::__verbose_terminate_handler()+0x155) [0x7fc065e324f5]
6: (()+0x63666) [0x7fc065e30666]
7: (()+0x63693) [0x7fc065e30693]
8: (()+0x638be) [0x7fc065e308be]
9: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x425) [0x6a2485]
10: (Monitor::sync_timeout(entity_inst_t&)+0x9eb) [0x4d240b]
11: (Context::complete(int)+0xa) [0x4e255a]
12: (SafeTimer::timer_thread()+0x1c2) [0x6962a2]
13: (SafeTimerThread::entry()+0xd) [0x697e3d]
14: (()+0x8216) [0x7fc0670f7216]
15: (clone()+0x6d) [0x7fc0655d204d]
NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.
--- begin dump of recent events ---
0> 2013-05-25 01:26:49.364326 7fc062a83700 -1 *** Caught signal (Aborted) **
in thread 7fc062a83700
ceph version 0.62-350-gbb407bf (bb407bfd101d9707c63655cb3c1b51346a0de8cd)
1: /usr/bin/ceph-mon() [0x5c4fbd]
2: (()+0x10630) [0x7fc0670ff630]
3: (gsignal()+0x39) [0x7fc0654ce8c9]
4: (abort()+0x160) [0x7fc0654cff80]
5: (__gnu_cxx::__verbose_terminate_handler()+0x155) [0x7fc065e324f5]
6: (()+0x63666) [0x7fc065e30666]
7: (()+0x63693) [0x7fc065e30693]
8: (()+0x638be) [0x7fc065e308be]
9: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x425) [0x6a2485]
10: (Monitor::sync_timeout(entity_inst_t&)+0x9eb) [0x4d240b]
11: (Context::complete(int)+0xa) [0x4e255a]
12: (SafeTimer::timer_thread()+0x1c2) [0x6962a2]
13: (SafeTimerThread::entry()+0xd) [0x697e3d]
14: (()+0x8216) [0x7fc0670f7216]
15: (clone()+0x6d) [0x7fc0655d204d]
NOTE: a copy of the executable, or `objdump -rdS <executable>` 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
0/ 5 osd
0/ 5 optracker
0/ 5 objclass
1/ 3 filestore
1/ 3 journal
0/ 5 ms
1/ 5 mon
0/10 monc
0/ 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 hadoop
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 /var/log/ceph/ceph-mon.1.log
--- end dump of recent events ---
2013-05-25 01:30:01.148597 7f44053d77c0 0 ceph version 0.62-350-gbb407bf (bb407bfd101d9707c63655cb3c1b51346a0de8cd), process ceph-mon, pid 14126
2013-05-25 01:30:01.688168 7f44053d77c0 -1 accepter.accepter.bind unable to bind to 10.227.227.103:6789: Cannot assign requested address
Files
Updated by Denis kaganovich almost 11 years ago
After it other 2 monitors working (answering) only after restart mon.3
Updated by Joao Eduardo Luis almost 11 years ago
- Status changed from New to Need More Info
- Assignee set to Joao Eduardo Luis
- Source changed from other to Community (user)
Do you have the full log for this monitor?
Updated by Denis kaganovich almost 11 years ago
No. First I trying to purge/recreate monitor. Now it infinite syncing and not going up. I just in panic (I have tickets to sea on this weekend and to month but in global nightmare with blackouts, ceph bugs, etc) and want to backup/recreate cluster while it just degraded (2 monitors) - ASAP. And even "compacting on trim" is evil now (->false).
I have next idea: I named monitors in old-style (mon.1, mon.3, mon.4). IMHO it conflicting with internal numeric IDs in some place, sometimes. Now I will create mon.a, mon.b, mon.c and start in leveldb paranoid mode from scratch.
All I can do - make extended log from infinite (or tooo long) syncing monitor while I do not purge all. Starting..
Updated by Denis kaganovich almost 11 years ago
- File ceph-mon.4.log.gz ceph-mon.4.log.gz added
OK, now I see: sync is tooo slow, but seems to be ready in future. Somebody can answer to this sync speed (fix or wantfix), but after few hours I will recreate cluster anymore to literal monitor names (and some tuning). So, cannot give more info now, sorry.
I can provocate misnumber, but time is critical for me. To try simulate you can install 3 nodes with numerical IDs, near default, size=3, min_size=2, kill monitor on sync on compacting and run again.
Slow sync log attached.
Updated by Denis kaganovich almost 11 years ago
PS One more issue (I will not open new by same reason): in time of 2 of 3 monitors up and repair after (or in time) third is down, after every "few" repair actions starting long "compaction on trim" process. This make repair incredible slow (db size 15M->30MB->15MB per every monitor, quorum is 99% time off, repair too slow). May be at least make it more cumulative on repair phase?
Updated by Denis kaganovich almost 11 years ago
PPS
1) fix: 15G->30G->15G;
2) In theory, can be fixed by "--inject-monmap", but repair is slow or infinite...
Updated by Joao Eduardo Luis almost 11 years ago
Okay, so you have a 15G monitor store? Is that it? If so, you might have been bit by #4895 and restarting the monitors should solve the issue with the store's size.
If you really need to get that monitor up and running, you might be able to make it sync following these steps: shut that monitor down, then restart the remaining other two monitors (and making sure their store's size decreases and they form quorum) and only then starting the monitor you want to sync. This should allow for the other monitors' stores' size to decrease to an acceptable size for the sync to finish in a reasonable amount of time. Then again, these issues are unrelated to the original bug you opened.
With regard to this bug, I will look a bit further into it, but without full logs from the initial crash I don't think I can do much about it. :-\
Updated by Sage Weil almost 11 years ago
- Status changed from Need More Info to Resolved
Denis reports that #5203 fix should resolve this one as well. Thanks!