Project

General

Profile

Bug #4064

osd: filestore assert on FORREMOVAL_* collection removal

Added by Sage Weil about 11 years ago. Updated about 11 years ago.

Status:
Resolved
Priority:
Urgent
Assignee:
Category:
OSD
Target version:
-
% Done:

0%

Source:
Q/A
Tags:
Backport:
Regression:
No
Severity:
3 - minor
Reviewed:
Affected Versions:
ceph-qa-suite:
Pull request ID:
Crash signature (v1):
Crash signature (v2):

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

Duplicated by Ceph - Bug #4059: osd: ENOTEMPTY unhandled for remove op Duplicate 02/08/2013

Associated revisions

Revision 4dfcad44 (diff)
Added by Samuel Just about 11 years ago

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 <>
Reviewed-by: Sage Weil <>

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

Also available in: Atom PDF