Project

General

Profile

Bug #2593

logmonitor: decode failure

Added by Greg Farnum almost 12 years ago. Updated over 11 years ago.

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

Duplicated by Ceph - Bug #2042: mon: crash in LogMonitor::update_from_paxos Duplicate 02/08/2012

Associated revisions

Revision fe576818 (diff)
Added by Sage Weil over 11 years ago

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 <>

Revision 14d2efc4 (diff)
Added by Sage Weil over 11 years ago

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 <>

Revision bcb1073f (diff)
Added by Sage Weil over 11 years ago

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 <>

History

#1 Updated by Sage Weil almost 12 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 almost 12 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 over 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 over 11 years ago

Do we know if the log in question actually existed on disk or not?

#5 Updated by Sage Weil over 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 over 11 years ago

  • Status changed from New to Resolved

Also available in: Atom PDF