Bug #2593
logmonitor: decode failure
Status:
Resolved
Priority:
Urgent
Assignee:
-
Category:
Monitor
Target version:
-
% Done:
0%
Source:
Development
Tags:
Backport:
Regression:
No
Severity:
3 - minor
Reviewed:
Affected Versions:
ceph-qa-suite:
Pull request ID:
Crash signature (v1):
Crash signature (v2):
Description
Saw this while trying to reproduce #2569. Sadly teuthology cleaned everything up before I could get to the data.
ceph version 0.47.2-487-g0adb33d (commit:0adb33d8670e8d81b9588593a1ba1bab11319b23) 1: /tmp/cephtest/binary/usr/local/bin/ceph-mon() [0x52cb2a] 2: (()+0xfcb0) [0x7ff03715dcb0] 3: (gsignal()+0x35) [0x7ff035852445] 4: (abort()+0x17b) [0x7ff035855bab] 5: (__gnu_cxx::__verbose_terminate_handler()+0x11d) [0x7ff0361a069d] 6: (()+0xb5846) [0x7ff03619e846] 7: (()+0xb5873) [0x7ff03619e873] 8: (()+0xb596e) [0x7ff03619e96e] 9: /tmp/cephtest/binary/usr/local/bin/ceph-mon() [0x5e43f9] 10: (LogEntry::decode(ceph::buffer::list::iterator&)+0x19b) [0x55d26b] 11: (LogMonitor::update_from_paxos()+0x536) [0x506ae6] 12: (PaxosService::_active()+0x2db) [0x4a0ecb] 13: (Context::complete(int)+0xa) [0x48869a] 14: (finish_contexts(CephContext*, std::list<Context*, std::allocator<Context*> >&, int)+0x11c) [0x48a55c] 15: (Paxos::handle_lease(MMonPaxos*)+0x3fd) [0x496a7d] 16: (Paxos::dispatch(PaxosServiceMessage*)+0x20b) [0x49d9db] 17: (Monitor::_ms_dispatch(Message*)+0x10b0) [0x487690] 18: (Monitor::ms_dispatch(Message*)+0x32) [0x494aa2] 19: (SimpleMessenger::dispatch_entry()+0x92b) [0x5c5ceb] 20: (SimpleMessenger::DispatchThread::entry()+0xd) [0x597bfd] 21: (()+0x7e9a) [0x7ff037155e9a] 22: (clone()+0x6d) [0x7ff03590e4bd] NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this
Related issues
Associated revisions
mon/MonitorStore: always O_TRUNC when writing states
It is possible for a .new file to already exist, potentially with a
larger size. This would happen if:
- we were proposing a different value
- we crashed (or were stopped) before it got renamed into place
- after restarting, a different value was proposed and accepted.This isn't so unlikely for the log state machine, where we're
aggregating random messages. O_TRUNC ensure we avoid getting the tail
end of some previous junk.
I observed #2593 and found that a logm state value had a larger size on
one mon (after slurping) than the others, pointing to put_bl_sn_map().
While we are at it, O_TRUNC put_int() too; the same type of bug is
possible there, too.
Fixes: #2593
Signed-off-by: Sage Weil <sage@inktank.com>
mon/MonitorStore: always O_TRUNC when writing states
It is possible for a .new file to already exist, potentially with a
larger size. This would happen if:
- we were proposing a different value
- we crashed (or were stopped) before it got renamed into place
- after restarting, a different value was proposed and accepted.This isn't so unlikely for the log state machine, where we're
aggregating random messages. O_TRUNC ensure we avoid getting the tail
end of some previous junk.
I observed #2593 and found that a logm state value had a larger size on
one mon (after slurping) than the others, pointing to put_bl_sn_map().
While we are at it, O_TRUNC put_int() too; the same type of bug is
possible there, too.
Fixes: #2593
Signed-off-by: Sage Weil <sage@inktank.com>
mon/MonitorStore: always O_TRUNC when writing states
It is possible for a .new file to already exist, potentially with a
larger size. This would happen if:
- we were proposing a different value
- we crashed (or were stopped) before it got renamed into place
- after restarting, a different value was proposed and accepted.This isn't so unlikely for the log state machine, where we're
aggregating random messages. O_TRUNC ensure we avoid getting the tail
end of some previous junk.
I observed #2593 and found that a logm state value had a larger size on
one mon (after slurping) than the others, pointing to put_bl_sn_map().
While we are at it, O_TRUNC put_int() too; the same type of bug is
possible there, too.
Fixes: #2593
Signed-off-by: Sage Weil <sage@inktank.com>
History
#1 Updated by Sage Weil over 11 years ago
- Priority changed from Normal to High
2012-06-20 18:34:58.511423 7ff5b63b6700 -1 *** Caught signal (Aborted) **
in thread 7ff5b63b6700
ceph version 0.47.2-568-g0062ee1 (commit:0062ee1ccdc67ce3fcdebfbab2459c20b4b79ad9)
1: /tmp/cephtest/binary/usr/local/bin/ceph-mon() [0x52cd9a]
2: (()+0xfcb0) [0x7ff5baf17cb0]
3: (gsignal()+0x35) [0x7ff5b960c445]
4: (abort()+0x17b) [0x7ff5b960fbab]
5: (__gnu_cxx::__verbose_terminate_handler()+0x11d) [0x7ff5b9f5a69d]
6: (()+0xb5846) [0x7ff5b9f58846]
7: (()+0xb5873) [0x7ff5b9f58873]
8: (()+0xb596e) [0x7ff5b9f5896e]
9: (ceph::buffer::list::iterator::copy(unsigned int, char*)+0x127) [0x5e4547]
10: (LogEntry::decode(ceph::buffer::list::iterator&)+0xea) [0x55d42a]
11: (LogMonitor::update_from_paxos()+0x536) [0x506df6]
12: (Monitor::slurp()+0x295) [0x47b685]
13: (Monitor::handle_probe_data(MMonProbe*)+0x222) [0x481e22]
14: (Monitor::handle_probe(MMonProbe*)+0x31b) [0x4866fb]
15: (Monitor::_ms_dispatch(Message*)+0x1304) [0x487a74]
16: (Monitor::ms_dispatch(Message*)+0x32) [0x493f02]
17: (SimpleMessenger::dispatch_entry()+0x92b) [0x5c5f5b]
18: (SimpleMessenger::DispatchThread::entry()+0xd) [0x597e6d]
19: (()+0x7e9a) [0x7ff5baf0fe9a]
20: (clone()+0x6d) [0x7ff5b96c84bd]
NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.
--- begin dump of recent events ---
-4> 2012-06-20 18:34:57.995975 7ff5bb335780 1 store(/tmp/cephtest/data/mon.2) mount
-3> 2012-06-20 18:34:57.996274 7ff5bb335780 0 ceph version 0.47.2-568-g0062ee1 (commit:0062ee1ccdc67ce3fcdebfbab2459c20b4b79ad9), process ceph-mon, pid 17529
-2> 2012-06-20 18:34:57.996979 7ff5bb335780 1 mon.2@-1(probing) e1 init fsid b1ce5f44-3a0d-41ef-97c9-d3dcb6a35d4a
-1> 2012-06-20 18:34:57.998406 7ff5bb335780 0 mon.2@-1(probing) e1 my rank is now 0 (was -1)
0> 2012-06-20 18:34:58.511423 7ff5b63b6700 -1 *** Caught signal (Aborted) **
in thread 7ff5b63b6700
ceph version 0.47.2-568-g0062ee1 (commit:0062ee1ccdc67ce3fcdebfbab2459c20b4b79ad9)
1: /tmp/cephtest/binary/usr/local/bin/ceph-mon() [0x52cd9a]
2: (()+0xfcb0) [0x7ff5baf17cb0]
3: (gsignal()+0x35) [0x7ff5b960c445]
4: (abort()+0x17b) [0x7ff5b960fbab]
5: (__gnu_cxx::__verbose_terminate_handler()+0x11d) [0x7ff5b9f5a69d]
6: (()+0xb5846) [0x7ff5b9f58846]
7: (()+0xb5873) [0x7ff5b9f58873]
8: (()+0xb596e) [0x7ff5b9f5896e]
9: (ceph::buffer::list::iterator::copy(unsigned int, char*)+0x127) [0x5e4547]
10: (LogEntry::decode(ceph::buffer::list::iterator&)+0xea) [0x55d42a]
11: (LogMonitor::update_from_paxos()+0x536) [0x506df6]
12: (Monitor::slurp()+0x295) [0x47b685]
13: (Monitor::handle_probe_data(MMonProbe*)+0x222) [0x481e22]
14: (Monitor::handle_probe(MMonProbe*)+0x31b) [0x4866fb]
15: (Monitor::_ms_dispatch(Message*)+0x1304) [0x487a74]
16: (Monitor::ms_dispatch(Message*)+0x32) [0x493f02]
17: (SimpleMessenger::dispatch_entry()+0x92b) [0x5c5f5b]
18: (SimpleMessenger::DispatchThread::entry()+0xd) [0x597e6d]
19: (()+0x7e9a) [0x7ff5baf0fe9a]
20: (clone()+0x6d) [0x7ff5b96c84bd]
NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.
--- end dump of recent events ---
ubuntu@teuthology:/a/sage-2012-06-20_12:46:40-regression-wip-2022-testing-basic/157
job was
- chef: null
- clock: null
- ceph: null
- mon_recovery: null
#2 Updated by Greg Farnum over 11 years ago
I wonder if this is also due to tick() colliding with slurping — the first one definitely could be (not sure about the second, that seems harder to explain).
Edit: n/m, I was confused or overeager with that idea.
#3 Updated by Sage Weil about 11 years ago
- Priority changed from High to Urgent
saw this again on next:
2012-07-02 00:35:30.993062 7f9ac2306780 1 store(/tmp/cephtest/data/mon.b) mount
2012-07-02 00:35:30.993496 7f9ac2306780 0 ceph version 0.47.3-544-g0810ab6 (commit:0810ab6de6d1d9e180bfc57a1d68a217026bcdf0), process ceph-mon, pid 16678
2012-07-02 00:35:30.994178 7f9ac2306780 1 mon.b@-1(probing) e1 init fsid 281b3ad7-d54a-41a8-b1a4-780fef0ec3aa
2012-07-02 00:35:30.995712 7f9ac2306780 0 mon.b@-1(probing) e1 my rank is now 1 (was -1)
2012-07-02 00:35:31.000539 7f9abd387700 0 log [INF] : mon.b calling new monitor election
2012-07-02 00:35:31.142824 7f9abd387700 0 log [INF] : mon.b calling new monitor election
2012-07-02 00:35:31.242692 7f9abd387700 0 log [INF] : mon.b calling new monitor election
2012-07-02 00:35:31.342634 7f9abd387700 0 log [INF] : mon.b calling new monitor election
2012-07-02 00:35:35.995861 7f9abcb86700 1 mon.b@1(electing) e1 discarding message auth(proto 0 30 bytes epoch 0) v1 and sending client elsewhere; we are not in quorum
2012-07-02 00:35:36.397982 7f9abcb86700 0 log [INF] : mon.b@1 won leader election with quorum 1,2,4,5,7,8,10,11,13,14,16,17,19,20
2012-07-02 00:35:37.763816 7f9abd387700 0 log [INF] : pgmap v21: 24 pgs: 24 active+clean; 8730 bytes data, 46178 MB used, 823 GB / 914 GB avail
2012-07-02 00:35:37.764213 7f9abd387700 0 log [INF] : mdsmap e5: 1/1/1 up {0=a=up:active}
2012-07-02 00:35:37.764643 7f9abd387700 0 log [INF] : osdmap e5: 2 osds: 2 up, 2 in
2012-07-02 00:35:37.768147 7f9abd387700 -1 *** Caught signal (Aborted) **
in thread 7f9abd387700
ceph version 0.47.3-544-g0810ab6 (commit:0810ab6de6d1d9e180bfc57a1d68a217026bcdf0)
1: /tmp/cephtest/binary/usr/local/bin/ceph-mon() [0x52e2aa]
2: (()+0xfcb0) [0x7f9ac1ee8cb0]
3: (gsignal()+0x35) [0x7f9ac05dd445]
4: (abort()+0x17b) [0x7f9ac05e0bab]
5: (__gnu_cxx::__verbose_terminate_handler()+0x11d) [0x7f9ac0f2b69d]
6: (()+0xb5846) [0x7f9ac0f29846]
7: (()+0xb5873) [0x7f9ac0f29873]
8: (()+0xb596e) [0x7f9ac0f2996e]
9: /tmp/cephtest/binary/usr/local/bin/ceph-mon() [0x5e62c9]
10: (LogEntry::decode(ceph::buffer::list::iterator&)+0x19b) [0x55e9eb]
11: (LogMonitor::update_from_paxos()+0x536) [0x507d66]
12: (PaxosService::_active()+0x2db) [0x4a19fb]
13: (Context::complete(int)+0xa) [0x488bfa]
14: (finish_contexts(CephContext*, std::list<Context*, std::allocator<Context*> >&, int)+0x11c) [0x48a6cc]
15: (Paxos::handle_last(MMonPaxos*)+0xb70) [0x49e120]
16: (Paxos::dispatch(PaxosServiceMessage*)+0x24b) [0x49e54b]
17: (Monitor::_ms_dispatch(Message*)+0x10b0) [0x487bf0]
18: (Monitor::ms_dispatch(Message*)+0x32) [0x4955d2]
19: (SimpleMessenger::dispatch_entry()+0x92b) [0x5c7b6b]
20: (SimpleMessenger::DispatchThread::entry()+0xd) [0x5993ed]
21: (()+0x7e9a) [0x7f9ac1ee0e9a]
22: (clone()+0x6d) [0x7f9ac06994bd]
NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.
ubuntu@teuthology:/var/lib/teuthworker/archive/sage-2012-07-01_21:52:14-regression-next-testing-basic/4375$ cat config.yaml
kernel: &id001
branch: testing
kdb: true
nuke-on-error: true
overrides:
ceph:
branch: next
log-whitelist:
- slow request
roles:
- - mon.a
- mon.d
- mon.g
- mon.j
- mon.m
- mon.p
- mon.s
- osd.0
- - mon.b
- mon.e
- mon.h
- mon.k
- mon.n
- mon.q
- mon.t
- mds.a
- - mon.c
- mon.f
- mon.i
- mon.l
- mon.o
- mon.r
- mon.u
- osd.1
targets:
ubuntu@plana64.front.sepia.ceph.com: ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQDk4GmsUmC8svnRI6Xd+mRX2MwKb4RHECAeLfqTm2COfqfolS2wKGw3U92eJcyvpZ+2p82X7uBrimjZh5JgRtxJ1aGUG4Pi60+JBYF0WpohM/3aYISFegVNET9rcapdDaAi6fFB5vhT06Q/cYEO0tPrdqGb/O3oiDSurtqtfOzkdwSPWSTY/hSegXgOeG6EjuEfvnU4BbgXWkLlDQRXCdgQd35F0SlKJVgMo+J1MgMCEK4qnBMFN614P1gBSzZCBsSUGQdjYBOzZfCRlI2bUdPDtB0kyjp7o5Ns9gLd07TLw8h9oxvI7wxG16XnLOAIzPBNOaH4OztTMGg3wJ/1e26t
ubuntu@plana65.front.sepia.ceph.com: ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQDTwfkF9asvpySXF/DOk10UkRDNtRwgGgLww/I/3E2r+JpsfYtW62TA1HMXjtB1g7SrcIolqCiiMd+5MIURIND94n76JiZ2o4DplLKIqUB6ys46gro7mwoeFnZNOuwdAA5bO4dfgeQ3yPtfIqpWTejkCB7ai/kG04C4ekz6EgplwtqWIfvXnij4fNaqvm3s/IxGhnO40DOGNwsAldEJo2fuJN8KHnYzsU/Dx5kJ85jQl2eQJI74VpMoh2Ge7+n9Q8rJhegfcHYPLJsX/Uyrf7Rtk1RfeTyZbIOSJIQDbQNepu278kvc9IEnFg3WfvWespfrUExVgnXq53xd1RIFcx6L
ubuntu@plana66.front.sepia.ceph.com: ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQC9QpKzRhLR+H4oCXhZtMxFDAC7E9cmtqcEPmQiW1ycxHNpk+Vy/uNNtlSh8Ljz7/R595beZe4JKgAkxZCCDmmWIEcm01bJgxVq0cbFLz+9dvyiirmr+RxbWqayu2VDC6uuiVAuxz5RdAw6+5Y/4gCrSdQKfQ8dUJZb4e/4Kz/TLr/+R5z+WqCGeutwb9QvK2anvhPJy+wa/JWHwtpTBjZVa5RFOkz9lfNDYayw3j1rylKk0d39J4VB/ch/qIBqUfxD7Hc4exu9sbG9bt5VKdomqdQvTjQXRw083+Nlj6RqJxYZfdJTWG/gYV3MXC4pwqP/ovcjoqZ9cvrsicdSezKp
tasks:
- internal.lock_machines: 3
- internal.save_config: null
- internal.check_lock: null
- internal.connect: null
- internal.check_conflict: null
- kernel: *id001
- internal.base: null
- internal.archive: null
- internal.coredump: null
- internal.syslog: null
- internal.timer: null
- chef: null
- clock: null
- ceph: null
- mon_recovery: null
#4 Updated by Greg Farnum about 11 years ago
Do we know if the log in question actually existed on disk or not?
#5 Updated by Sage Weil about 11 years ago
nope.
i wonder if we should make teuthology archive the mon data directory... that info is often useful, even for non-monitor problems (e.g., having the canonical osdmaps)...
#6 Updated by Sage Weil about 11 years ago
- Status changed from New to Resolved