Bug #4064
osd: filestore assert on FORREMOVAL_* collection removal
0%
Description
ubuntu@teuthology:/var/lib/teuthworker/archive/sage-2013-02-08_12:11:07-rados-master-testing-basic/2870$
2013-02-08 14:48:31.384540 7f00cf167780 0 filestore(/tmp/cephtest/data/osd.3.data) mount FIEMAP ioctl is supported and appears to work 2013-02-08 14:48:31.384554 7f00cf167780 0 filestore(/tmp/cephtest/data/osd.3.data) mount FIEMAP ioctl is disabled via 'filestore fiemap' config option 2013-02-08 14:48:31.384844 7f00cf167780 0 filestore(/tmp/cephtest/data/osd.3.data) mount did NOT detect btrfs 2013-02-08 14:48:31.569382 7f00cf167780 0 filestore(/tmp/cephtest/data/osd.3.data) mount syncfs(2) syscall fully supported (by glibc and kernel) 2013-02-08 14:48:31.569522 7f00cf167780 0 filestore(/tmp/cephtest/data/osd.3.data) mount found snaps <> 2013-02-08 14:48:31.836521 7f00cf167780 0 filestore(/tmp/cephtest/data/osd.3.data) mount: enabling WRITEAHEAD journal mode: btrfs not detected 2013-02-08 14:48:31.839333 7f00cf167780 1 journal _open /tmp/cephtest/data/osd.3.journal fd 23: 104857600 bytes, block size 4096 bytes, directio = 1, aio = 1 2013-02-08 14:48:31.960639 7f00cf167780 -1 filestore(/tmp/cephtest/data/osd.3.data) error getting collection index for FORREMOVAL_215_0.13: (2) No such file or directory 2013-02-08 14:48:31.960674 7f00cf167780 -1 filestore(/tmp/cephtest/data/osd.3.data) error getting collection index for FORREMOVAL_215_0.13: (2) No such file or directory 2013-02-08 14:48:31.960694 7f00cf167780 -1 filestore(/tmp/cephtest/data/osd.3.data) error getting collection index for FORREMOVAL_215_0.13: (2) No such file or directory 2013-02-08 14:48:31.960714 7f00cf167780 -1 filestore(/tmp/cephtest/data/osd.3.data) error getting collection index for FORREMOVAL_215_0.13: (2) No such file or directory 2013-02-08 14:48:31.960733 7f00cf167780 -1 filestore(/tmp/cephtest/data/osd.3.data) error getting collection index for FORREMOVAL_215_0.13: (2) No such file or directory 2013-02-08 14:48:31.960754 7f00cf167780 -1 filestore(/tmp/cephtest/data/osd.3.data) error getting collection index for FORREMOVAL_215_0.13: (2) No such file or directory 2013-02-08 14:48:31.960773 7f00cf167780 -1 filestore(/tmp/cephtest/data/osd.3.data) error getting collection index for FORREMOVAL_215_0.13: (2) No such file or directory 2013-02-08 14:48:31.960792 7f00cf167780 -1 filestore(/tmp/cephtest/data/osd.3.data) error getting collection index for FORREMOVAL_215_0.13: (2) No such file or directory 2013-02-08 14:48:31.960812 7f00cf167780 -1 filestore(/tmp/cephtest/data/osd.3.data) error getting collection index for FORREMOVAL_215_0.13: (2) No such file or directory 2013-02-08 14:48:31.960831 7f00cf167780 -1 filestore(/tmp/cephtest/data/osd.3.data) error getting collection index for FORREMOVAL_215_0.13: (2) No such file or directory 2013-02-08 14:48:31.960850 7f00cf167780 -1 filestore(/tmp/cephtest/data/osd.3.data) error getting collection index for FORREMOVAL_215_0.13: (2) No such file or directory 2013-02-08 14:48:31.960869 7f00cf167780 -1 filestore(/tmp/cephtest/data/osd.3.data) error getting collection index for FORREMOVAL_215_0.13: (2) No such file or directory 2013-02-08 14:48:32.123259 7f00cf167780 -1 filestore(/tmp/cephtest/data/osd.3.data) error getting collection index for FORREMOVAL_217_1.10: (2) No such file or directory 2013-02-08 14:48:32.123288 7f00cf167780 -1 filestore(/tmp/cephtest/data/osd.3.data) error getting collection index for FORREMOVAL_217_1.10: (2) No such file or directory 2013-02-08 14:48:32.123308 7f00cf167780 -1 filestore(/tmp/cephtest/data/osd.3.data) error getting collection index for FORREMOVAL_217_1.10: (2) No such file or directory 2013-02-08 14:48:32.123328 7f00cf167780 -1 filestore(/tmp/cephtest/data/osd.3.data) error getting collection index for FORREMOVAL_217_1.10: (2) No such file or directory 2013-02-08 14:48:32.148526 7f00cf167780 0 filestore(/tmp/cephtest/data/osd.3.data) error (39) Directory not empty not handled on operation 21 (18509.0.1, or op 1, counting from 0) 2013-02-08 14:48:32.148545 7f00cf167780 0 filestore(/tmp/cephtest/data/osd.3.data) ENOTEMPTY suggests garbage data in osd data dir 2013-02-08 14:48:32.148547 7f00cf167780 0 filestore(/tmp/cephtest/data/osd.3.data) transaction dump: { "ops": [ { "op_num": 0, "op_name": "remove", "collection": "FORREMOVAL_219_0.a", "oid": "190173fa\/plana8923779-290\/head\/\/0"}, { "op_num": 1, "op_name": "rmcoll", "collection": "FORREMOVAL_219_0.a"}]} 2013-02-08 14:48:32.162177 7f00cf167780 -1 os/FileStore.cc: In function 'unsigned int FileStore::_do_transaction(ObjectStore::Transaction&, uint64_t, int)' thread 7f00cf167780 time 2013-02-08 14:48:32.148606 os/FileStore.cc: 2667: FAILED assert(0 == "unexpected error") ceph version 0.56-696-g2bdf753 (2bdf753d7d771062b03f47d79f6783c75d18ea38) 1: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x95) [0x11bdc11] 2: (FileStore::_do_transaction(ObjectStore::Transaction&, unsigned long, int)+0x2cf3) [0x1060ba9] 3: (FileStore::_do_transactions(std::list<ObjectStore::Transaction*, std::allocator<ObjectStore::Transaction*> >&, unsigned long, ThreadPool::TPHandle*)+0xec) [0x105c0fe] 4: (FileStore::do_transactions(std::list<ObjectStore::Transaction*, std::allocator<ObjectStore::Transaction*> >&, unsigned long)+0x2d) [0x107ae63] 5: (JournalingObjectStore::journal_replay(unsigned long)+0x8c8) [0x1088442] 6: (FileStore::mount()+0x48c9) [0x105886b] 7: (OSD::do_convertfs(ObjectStore*)+0x32) [0xea0e72] 8: (OSD::convertfs(std::string const&, std::string const&)+0x61) [0xea1dc5] 9: (main()+0x30bb) [0xdd6825] 10: (__libc_start_main()+0xed) [0x7f00ccbfb76d] 11: /tmp/cephtest/binary/usr/local/bin/ceph-osd() [0xdd32c9] NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.
ubuntu@teuthology:/var/lib/teuthworker/archive/sage-2013-02-08_12:11:07-rados-master-testing-basic/2870$ cat orig.config.yaml kernel: kdb: true sha1: 012d5bda1c0f229494c67098d00edfa24c531ea5 nuke-on-error: true overrides: ceph: conf: global: ms inject delay max: 1 ms inject delay probability: 0.005 ms inject delay type: osd ms inject socket failures: 2500 fs: ext4 log-whitelist: - slow request sha1: 2bdf753d7d771062b03f47d79f6783c75d18ea38 s3tests: branch: master workunit: sha1: 2bdf753d7d771062b03f47d79f6783c75d18ea38 roles: - - mon.a - mon.b - osd.0 - osd.1 - osd.2 - - mon.c - mds.a - osd.3 - osd.4 - osd.5 - - client.0 tasks: - chef: null - clock: null - ceph: log-whitelist: - wrongly marked me down - objects unfound and apparently lost - thrashosds: timeout: 1200 - rados: clients: - client.0 objects: 500 op_weights: delete: 50 read: 100 rollback: 50 snap_create: 50 snap_remove: 50 write: 100 ops: 4000
Related issues
Associated revisions
OSD: always activate_map in advance_pgs, only send messages if up
We should always handle_activate_map() after handle_advance_map() in
order to kick the pg into a valid peering state for processing requests
prior to dropping the lock.
Additionally, we would prefer to avoid sending irrelevant messages
during boot, so only send if we are up according to the current service
osdmap.
Fixes: #4064
Backport: bobtail
Signed-off-by: Samuel Just <sam.just@inktank.com>
Reviewed-by: Sage Weil <sage@inktank.com>
History
#1 Updated by Sage Weil about 11 years ago
ubuntu@plana85:/tmp/cephtest/data/osd.3.data/current$ find FORREMOVAL_219_0.a FORREMOVAL_219_0.a FORREMOVAL_219_0.a/plana8923779-62__head_D1B2C56A__0 ubuntu@plana85:/tmp/cephtest/data/osd.3.data/current$ find . | grep a8923779-62__head_D1B2C5 ./FORREMOVAL_219_0.a/plana8923779-62__head_D1B2C56A__0
#2 Updated by Sage Weil about 11 years ago
Related (i think) crash, on latest next:
-3> 2013-02-09 14:11:48.421681 7f216f2e7780 0 filestore(/tmp/cephtest/data/osd.4.data) error (39) Directory not empty not handled on operation 21 (14054.0.0, or op 0, counting from 0) -2> 2013-02-09 14:11:48.421703 7f216f2e7780 0 filestore(/tmp/cephtest/data/osd.4.data) ENOTEMPTY suggests garbage data in osd data dir -1> 2013-02-09 14:11:48.421706 7f216f2e7780 0 filestore(/tmp/cephtest/data/osd.4.data) transaction dump: { "ops": [ { "op_num": 0, "op_name": "rmcoll", "collection": "0.c_TEMP"}]} 0> 2013-02-09 14:11:48.435430 7f216f2e7780 -1 os/FileStore.cc: In function 'unsigned int FileStore::_do_transaction(ObjectStore::Transaction&, uint64_t, int)' thread 7f216f2e7780 time 2013-02-09 14:11:48.421768 os/FileStore.cc: 2667: FAILED assert(0 == "unexpected error") ceph version 0.56-641-gb19b6dc (b19b6dced85617d594c15631571202aab2f94ae8) 1: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x95) [0x11bd4c1] 2: (FileStore::_do_transaction(ObjectStore::Transaction&, unsigned long, int)+0x2cf3) [0x10605bd] 3: (FileStore::_do_transactions(std::list<ObjectStore::Transaction*, std::allocator<ObjectStore::Transaction*> >&, unsigned long, ThreadPool::TPHandle*)+0xec) [0x105bb12] 4: (FileStore::do_transactions(std::list<ObjectStore::Transaction*, std::allocator<ObjectStore::Transaction*> >&, unsigned long)+0x2d) [0x107a877] 5: (JournalingObjectStore::journal_replay(unsigned long)+0x8c8) [0x1087e56] 6: (FileStore::mount()+0x48c9) [0x105827f] 7: (OSD::do_convertfs(ObjectStore*)+0x32) [0xea0802] 8: (OSD::convertfs(std::string const&, std::string const&)+0x61) [0xea1755] 9: (main()+0x30b5) [0xdd617f] 10: (__libc_start_main()+0xed) [0x7f216cd7b76d] 11: /tmp/cephtest/binary/usr/local/bin/ceph-osd() [0xdd2c29] NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.
Looking at the journal dump, there is an rmcoll on the temp colletion, then it is created shortly after and a bunch of stuff is written to it. I think this is coming out now because clear_temp() is getting called and wasn't before.
The problem i think is that
rmdir
mkdir
touch a
<crash>
won't replay cleanly because the rmdir will fail. One easy fix is probably just to make rmdir and mkdir tolerate ENOTEMPTY and EEXIST... but that makes me nervous. Another might be to just store->sync() after load_pgs(), since that is (almost) the only clear_temp caller.. except for convertfs(). :/
#3 Updated by Sage Weil about 11 years ago
this was the job:
kernel: kdb: true sha1: 012d5bda1c0f229494c67098d00edfa24c531ea5 nuke-on-error: true overrides: ceph: conf: global: ms inject socket failures: 5000 fs: xfs log-whitelist: - slow request sha1: b19b6dced85617d594c15631571202aab2f94ae8 s3tests: branch: next workunit: sha1: b19b6dced85617d594c15631571202aab2f94ae8 roles: - - mon.a - mon.b - osd.0 - osd.1 - osd.2 - - mon.c - mds.a - osd.3 - osd.4 - osd.5 - - client.0 tasks: - chef: null - clock: null - ceph: log-whitelist: - wrongly marked me down - objects unfound and apparently lost - thrashosds: timeout: 1200 - rados: clients: - client.0 objects: 50 op_weights: delete: 50 read: 100 rollback: 50 snap_create: 50 snap_remove: 50 write: 100 ops: 4000
ubuntu@teuthology:/a/sage-2013-02-09_10:18:33-regression-next-testing-basic/3714
#4 Updated by Ian Colle about 11 years ago
- Assignee set to Sage Weil
#5 Updated by Sage Weil about 11 years ago
- Assignee changed from Sage Weil to Samuel Just
#6 Updated by Sage Weil about 11 years ago
- Status changed from New to Resolved