Project

General

Profile

Actions
Copy link

Bug #23463

closed

src/os/bluestore/StupidAllocator.cc: 336: FAILED assert(rm.empty())

Added by Alfredo Deza about 6 years ago. Updated over 4 years ago.

Status:
Can't reproduce
Priority:
Normal
Assignee:
-
Target version:
-
% Done:

0%

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

Description

The ceph-volume nightly tests have seen this failure on one run so far (March 25th) with 2 out of 6 OSDs deployed. We have been unable to replicate or see it again
in any of our tests.

The failure happened for:

  • ceph master (235f2119010484c12c5bd29421aeef7d44df38a1)
  • CentOS 7
  • Using `ceph-volume lvm`
  • With dmcrypt
  • With bluestore
changed: [osd0] => (item={u'data_vg': u'test_group', u'db': u'journal1', u'db_vg': u'journals', u'data': u'data-lv2'}) => {
    "changed": true, 
    "cmd": [
        "ceph-volume", 
        "--cluster", 
        "ceph", 
        "lvm", 
        "create", 
        "--bluestore", 
        "--data", 
        "test_group/data-lv2", 
        "--block.db", 
        "journals/journal1", 
        "--dmcrypt" 
    ], 
    "delta": "0:00:41.484166", 
    "end": "2018-03-25 23:30:31.592695", 
    "failed": false, 
    "item": {
        "data": "data-lv2", 
        "data_vg": "test_group", 
        "db": "journal1", 
        "db_vg": "journals" 
    }, 
    "rc": 0, 
    "start": "2018-03-25 23:29:50.108529" 
}

STDOUT:

Running command: /bin/ceph-authtool --gen-print-key
Running command: /bin/ceph-authtool --gen-print-key
Running command: /bin/ceph --cluster ceph --name client.bootstrap-osd --keyring /var/lib/ceph/bootstrap-osd/ceph.keyring -i - osd new d45ce6aa-8a19-42a3-8be4-2832d652cbc5
Running command: /bin/ceph-authtool --gen-print-key
Running command: /usr/sbin/cryptsetup --batch-mode --key-file - luksFormat /dev/test_group/data-lv2
Running command: /usr/sbin/cryptsetup --key-file - luksOpen /dev/test_group/data-lv2 uktWUg-OTJe-hT0L-kqJX-q1Qk-8m3g-vmEtoY
Running command: /usr/sbin/cryptsetup --batch-mode --key-file - luksFormat /dev/journals/journal1
Running command: /usr/sbin/cryptsetup --key-file - luksOpen /dev/journals/journal1 H7sf8A-FbTy-isn3-J1Xe-0bdT-L9se-0ApudF
Running command: /bin/mount -t tmpfs tmpfs /var/lib/ceph/osd/ceph-1
Running command: /bin/chown -R ceph:ceph /dev/dm-6
Running command: /bin/ln -s /dev/mapper/uktWUg-OTJe-hT0L-kqJX-q1Qk-8m3g-vmEtoY /var/lib/ceph/osd/ceph-1/block
Running command: /bin/ceph --cluster ceph --name client.bootstrap-osd --keyring /var/lib/ceph/bootstrap-osd/ceph.keyring mon getmap -o /var/lib/ceph/osd/ceph-1/activate.monmap
 stderr: got monmap epoch 1
Running command: /bin/ceph-authtool /var/lib/ceph/osd/ceph-1/keyring --create-keyring --name osd.1 --add-key AQDuMLhaM1A1DRAAJvexOz8zvevay+tMktd2qA==
 stdout: creating /var/lib/ceph/osd/ceph-1/keyring
 stdout: added entity osd.1 auth auth(auid = 18446744073709551615 key=AQDuMLhaM1A1DRAAJvexOz8zvevay+tMktd2qA== with 0 caps)
Running command: /bin/chown -R ceph:ceph /var/lib/ceph/osd/ceph-1/keyring
Running command: /bin/chown -R ceph:ceph /var/lib/ceph/osd/ceph-1/
Running command: /bin/chown -R ceph:ceph /dev/dm-7
Running command: /bin/ceph-osd --cluster ceph --osd-objectstore bluestore --mkfs -i 1 --monmap /var/lib/ceph/osd/ceph-1/activate.monmap --keyfile - --bluestore-block-db-path /dev/mapper/H7sf8A-FbTy-isn3-J1Xe-0bdT-L9se-0ApudF --osd-data /var/lib/ceph/osd/ceph-1/ --osd-uuid d45ce6aa-8a19-42a3-8be4-2832d652cbc5 --setuser ceph --setgroup ceph
 stderr: 2018-03-25 23:30:25.082 7f38b9406040 -1 bluestore(/var/lib/ceph/osd/ceph-1/) _read_fsid unparsable uuid
 stderr: /home/jenkins-build/build/workspace/ceph-dev-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos7/DIST/centos7/MACHINE_SIZE/huge/release/13.0.1-3240-g235f211/rpm/el7/BUILD/ceph-13.0.1-3240-g235f211/src/os/bluestore/StupidAllocator.cc: In function 'virtual void StupidAllocator::init_rm_free(uint64_t, uint64_t)' thread 7f38b9406040 time 2018-03-25 23:30:25.339214
 stderr: /home/jenkins-build/build/workspace/ceph-dev-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos7/DIST/centos7/MACHINE_SIZE/huge/release/13.0.1-3240-g235f211/rpm/el7/BUILD/ceph-13.0.1-3240-g235f211/src/os/bluestore/StupidAllocator.cc: 336: FAILED assert(rm.empty())
 stderr: ceph version 13.0.1-3240-g235f211 (235f2119010484c12c5bd29421aeef7d44df38a1) mimic (dev)
 stderr: 1: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0xff) [0x7f38b0847c8f]
 stderr: 2: (()+0x278e77) [0x7f38b0847e77]
 stderr: 3: (StupidAllocator::init_rm_free(unsigned long, unsigned long)+0x20c2) [0x563e13931a22]
 stderr: 4: (BlueFS::mount()+0x222) [0x563e13911172]
 stderr: 5: (BlueStore::_open_db(bool, bool)+0x1531) [0x563e138388d1]
 stderr: 6: (BlueStore::mkfs()+0x699) [0x563e1386e429]
 stderr: 7: (OSD::mkfs(CephContext*, ObjectStore*, std::string const&, uuid_d, int)+0x177) [0x563e134391a7]
 stderr: 8: (main()+0x29fe) [0x563e1331324e]
 stderr: 9: (__libc_start_main()+0xf5) [0x7f38ace3ec05]
 stderr: 10: (()+0x37ea80) [0x563e133efa80]
 stderr: NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.
 stderr: 2018-03-25 23:30:25.343 7f38b9406040 -1 /home/jenkins-build/build/workspace/ceph-dev-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos7/DIST/centos7/MACHINE_SIZE/huge/release/13.0.1-3240-g235f211/rpm/el7/BUILD/ceph-13.0.1-3240-g235f211/src/os/bluestore/StupidAllocator.cc: In function 'virtual void StupidAllocator::init_rm_free(uint64_t, uint64_t)' thread 7f38b9406040 time 2018-03-25 23:30:25.339214
 stderr: /home/jenkins-build/build/workspace/ceph-dev-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos7/DIST/centos7/MACHINE_SIZE/huge/release/13.0.1-3240-g235f211/rpm/el7/BUILD/ceph-13.0.1-3240-g235f211/src/os/bluestore/StupidAllocator.cc: 336: FAILED assert(rm.empty())
 stderr: ceph version 13.0.1-3240-g235f211 (235f2119010484c12c5bd29421aeef7d44df38a1) mimic (dev)
 stderr: 1: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0xff) [0x7f38b0847c8f]
 stderr: 2: (()+0x278e77) [0x7f38b0847e77]
 stderr: 3: (StupidAllocator::init_rm_free(unsigned long, unsigned long)+0x20c2) [0x563e13931a22]
 stderr: 4: (BlueFS::mount()+0x222) [0x563e13911172]
 stderr: 5: (BlueStore::_open_db(bool, bool)+0x1531) [0x563e138388d1]
 stderr: 6: (BlueStore::mkfs()+0x699) [0x563e1386e429]
 stderr: 7: (OSD::mkfs(CephContext*, ObjectStore*, std::string const&, uuid_d, int)+0x177) [0x563e134391a7]
 stderr: 8: (main()+0x29fe) [0x563e1331324e]
 stderr: 9: (__libc_start_main()+0xf5) [0x7f38ace3ec05]
 stderr: 10: (()+0x37ea80) [0x563e133efa80]
 stderr: NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.
 stderr: -21> 2018-03-25 23:30:25.082 7f38b9406040 -1 bluestore(/var/lib/ceph/osd/ceph-1/) _read_fsid unparsable uuid
 stderr: 0> 2018-03-25 23:30:25.343 7f38b9406040 -1 /home/jenkins-build/build/workspace/ceph-dev-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos7/DIST/centos7/MACHINE_SIZE/huge/release/13.0.1-3240-g235f211/rpm/el7/BUILD/ceph-13.0.1-3240-g235f211/src/os/bluestore/StupidAllocator.cc: In function 'virtual void StupidAllocator::init_rm_free(uint64_t, uint64_t)' thread 7f38b9406040 time 2018-03-25 23:30:25.339214
 stderr: /home/jenkins-build/build/workspace/ceph-dev-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos7/DIST/centos7/MACHINE_SIZE/huge/release/13.0.1-3240-g235f211/rpm/el7/BUILD/ceph-13.0.1-3240-g235f211/src/os/bluestore/StupidAllocator.cc: 336: FAILED assert(rm.empty())
 stderr: ceph version 13.0.1-3240-g235f211 (235f2119010484c12c5bd29421aeef7d44df38a1) mimic (dev)
 stderr: 1: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0xff) [0x7f38b0847c8f]
 stderr: 2: (()+0x278e77) [0x7f38b0847e77]
 stderr: 3: (StupidAllocator::init_rm_free(unsigned long, unsigned long)+0x20c2) [0x563e13931a22]
 stderr: 4: (BlueFS::mount()+0x222) [0x563e13911172]
 stderr: 5: (BlueStore::_open_db(bool, bool)+0x1531) [0x563e138388d1]
 stderr: 6: (BlueStore::mkfs()+0x699) [0x563e1386e429]
 stderr: 7: (OSD::mkfs(CephContext*, ObjectStore*, std::string const&, uuid_d, int)+0x177) [0x563e134391a7]
 stderr: 8: (main()+0x29fe) [0x563e1331324e]
 stderr: 9: (__libc_start_main()+0xf5) [0x7f38ace3ec05]
 stderr: 10: (()+0x37ea80) [0x563e133efa80]
 stderr: NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.
 stderr: *** Caught signal (Aborted) **
 stderr: in thread 7f38b9406040 thread_name:ceph-osd
 stderr: ceph version 13.0.1-3240-g235f211 (235f2119010484c12c5bd29421aeef7d44df38a1) mimic (dev)
 stderr: 1: (()+0x8e6e00) [0x563e13957e00]
 stderr: 2: (()+0xf5e0) [0x7f38ade295e0]
 stderr: 3: (gsignal()+0x37) [0x7f38ace521f7]
 stderr: 4: (abort()+0x148) [0x7f38ace538e8]
 stderr: 5: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x25d) [0x7f38b0847ded]
 stderr: 6: (()+0x278e77) [0x7f38b0847e77]
 stderr: 7: (StupidAllocator::init_rm_free(unsigned long, unsigned long)+0x20c2) [0x563e13931a22]
 stderr: 8: (BlueFS::mount()+0x222) [0x563e13911172]
 stderr: 9: (BlueStore::_open_db(bool, bool)+0x1531) [0x563e138388d1]
 stderr: 10: (BlueStore::mkfs()+0x699) [0x563e1386e429]
 stderr: 11: (OSD::mkfs(CephContext*, ObjectStore*, std::string const&, uuid_d, int)+0x177) [0x563e134391a7]
 stderr: 12: (main()+0x29fe) [0x563e1331324e]
 stderr: 13: (__libc_start_main()+0xf5) [0x7f38ace3ec05]
 stderr: 14: (()+0x37ea80) [0x563e133efa80]
 stderr: 2018-03-25 23:30:25.349 7f38b9406040 -1 *** Caught signal (Aborted) **
 stderr: in thread 7f38b9406040 thread_name:ceph-osd
 stderr: ceph version 13.0.1-3240-g235f211 (235f2119010484c12c5bd29421aeef7d44df38a1) mimic (dev)
 stderr: 1: (()+0x8e6e00) [0x563e13957e00]
 stderr: 2: (()+0xf5e0) [0x7f38ade295e0]
 stderr: 3: (gsignal()+0x37) [0x7f38ace521f7]
 stderr: 4: (abort()+0x148) [0x7f38ace538e8]
 stderr: 5: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x25d) [0x7f38b0847ded]
 stderr: 6: (()+0x278e77) [0x7f38b0847e77]
 stderr: 7: (StupidAllocator::init_rm_free(unsigned long, unsigned long)+0x20c2) [0x563e13931a22]
 stderr: 8: (BlueFS::mount()+0x222) [0x563e13911172]
 stderr: 9: (BlueStore::_open_db(bool, bool)+0x1531) [0x563e138388d1]
 stderr: 10: (BlueStore::mkfs()+0x699) [0x563e1386e429]
 stderr: 11: (OSD::mkfs(CephContext*, ObjectStore*, std::string const&, uuid_d, int)+0x177) [0x563e134391a7]
 stderr: 12: (main()+0x29fe) [0x563e1331324e]
 stderr: 13: (__libc_start_main()+0xf5) [0x7f38ace3ec05]
 stderr: 14: (()+0x37ea80) [0x563e133efa80]
 stderr: NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.
 stderr: 0> 2018-03-25 23:30:25.349 7f38b9406040 -1 *** Caught signal (Aborted) **
 stderr: in thread 7f38b9406040 thread_name:ceph-osd
 stderr: ceph version 13.0.1-3240-g235f211 (235f2119010484c12c5bd29421aeef7d44df38a1) mimic (dev)
 stderr: 1: (()+0x8e6e00) [0x563e13957e00]
 stderr: 2: (()+0xf5e0) [0x7f38ade295e0]
 stderr: 3: (gsignal()+0x37) [0x7f38ace521f7]
 stderr: 4: (abort()+0x148) [0x7f38ace538e8]
 stderr: 5: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x25d) [0x7f38b0847ded]
 stderr: 6: (()+0x278e77) [0x7f38b0847e77]
 stderr: 7: (StupidAllocator::init_rm_free(unsigned long, unsigned long)+0x20c2) [0x563e13931a22]
 stderr: 8: (BlueFS::mount()+0x222) [0x563e13911172]
 stderr: 9: (BlueStore::_open_db(bool, bool)+0x1531) [0x563e138388d1]
 stderr: 10: (BlueStore::mkfs()+0x699) [0x563e1386e429]
 stderr: 11: (OSD::mkfs(CephContext*, ObjectStore*, std::string const&, uuid_d, int)+0x177) [0x563e134391a7]
 stderr: 12: (main()+0x29fe) [0x563e1331324e]
 stderr: 13: (__libc_start_main()+0xf5) [0x7f38ace3ec05]
 stderr: 14: (()+0x37ea80) [0x563e133efa80]
 stderr: NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.

Files

Download all files
jenkins-log.txt (576 KB) jenkins-log.txt Full Log output from Jenkins run Alfredo Deza, 03/26/2018 03:30 PM
ceph-osd.6.log (73.6 KB) ceph-osd.6.log Christian Wahl, 07/17/2019 03:37 PM
ceph-osd.0.log (75.5 KB) ceph-osd.0.log Christian Wahl, 07/17/2019 03:55 PM
Actions
Copy link
 #2

Updated by Sage Weil over 5 years ago

  • Status changed from New to Can't reproduce
Actions
Copy link
 #3

Updated by Christian Wahl almost 5 years ago

I encountered this bug in ceph version 13.2.6 mimic (stable) and it pulled down 6 out of 8 deployed OSDs, however I was unable to recreate it.

Jul 17 16:46:13 tecoceph systemd[1]: Started Ceph object storage daemon osd.6.
Jul 17 16:46:13 tecoceph ceph-osd[28384]: 2019-07-17 16:46:13.944 7efc39aa0d80 -1 Public network was set, but cluster network was not set
Jul 17 16:46:13 tecoceph ceph-osd[28384]: 2019-07-17 16:46:13.944 7efc39aa0d80 -1     Using public network also for cluster network
Jul 17 16:46:13 tecoceph ceph-osd[28384]: starting osd.6 at - osd_data /var/lib/ceph/osd/ceph-6 /var/lib/ceph/osd/ceph-6/journal
Jul 17 16:46:14 tecoceph ceph-osd[28384]: /home/jenkins-build/build/workspace/ceph-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos7/DIST/centos7/MACHINE_SIZE/huge/release/13.2.6/rpm/el7/BUILD/ceph-13.2.6/src/os/bluestore/StupidAllocator.cc: In function 'virtual void StupidAllocator::init_rm_free(uint64_t, uint64_t)' thread 7efc39aa0d80 time 2019-07-17 16:46:14.249837
Jul 17 16:46:14 tecoceph ceph-osd[28384]: /home/jenkins-build/build/workspace/ceph-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos7/DIST/centos7/MACHINE_SIZE/huge/release/13.2.6/rpm/el7/BUILD/ceph-13.2.6/src/os/bluestore/StupidAllocator.cc: 336: FAILED assert(rm.empty())
Jul 17 16:46:14 tecoceph ceph-osd[28384]: ceph version 13.2.6 (7b695f835b03642f85998b2ae7b6dd093d9fbce4) mimic (stable)
Jul 17 16:46:14 tecoceph ceph-osd[28384]: 1: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x14b) [0x7efc30e8536b]
Jul 17 16:46:14 tecoceph ceph-osd[28384]: 2: (()+0x26e4f7) [0x7efc30e854f7]
Jul 17 16:46:14 tecoceph ceph-osd[28384]: 3: (StupidAllocator::init_rm_free(unsigned long, unsigned long)+0x1fb6) [0x55593f576c46]
Jul 17 16:46:14 tecoceph ceph-osd[28384]: 4: (BlueFS::mount()+0x260) [0x55593f55bd60]
Jul 17 16:46:14 tecoceph ceph-osd[28384]: 5: (BlueStore::_open_db(bool, bool)+0x170f) [0x55593f47d93f]
Jul 17 16:46:14 tecoceph ceph-osd[28384]: 6: (BlueStore::_mount(bool, bool)+0x4d1) [0x55593f4ae071]
Jul 17 16:46:14 tecoceph ceph-osd[28384]: 7: (OSD::init()+0x28f) [0x55593f055edf]
Jul 17 16:46:14 tecoceph ceph-osd[28384]: 8: (main()+0x23a3) [0x55593ef347a3]
Jul 17 16:46:14 tecoceph ceph-osd[28384]: 9: (__libc_start_main()+0xf5) [0x7efc2ca053d5]
Jul 17 16:46:14 tecoceph ceph-osd[28384]: 10: (()+0x385900) [0x55593f00c900]
Jul 17 16:46:14 tecoceph ceph-osd[28384]: *** Caught signal (Aborted) **
Jul 17 16:46:14 tecoceph ceph-osd[28384]: in thread 7efc39aa0d80 thread_name:ceph-osd
Jul 17 16:46:14 tecoceph ceph-osd[28384]: 2019-07-17 16:46:14.250 7efc39aa0d80 -1 /home/jenkins-build/build/workspace/ceph-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos7/DIST/centos7/MACHINE_SIZE/huge/release/13.2.6/rpm/el7/BUILD/ceph-13.2.6/src/os/bluestore/StupidAllocator.cc: In function 'virtual void StupidAllocator::init_rm_free(uint64_t, uint64_t)' thread 7efc39aa0d80 time 2019-07-17 16:46:14.249837
Jul 17 16:46:14 tecoceph ceph-osd[28384]: /home/jenkins-build/build/workspace/ceph-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos7/DIST/centos7/MACHINE_SIZE/huge/release/13.2.6/rpm/el7/BUILD/ceph-13.2.6/src/os/bluestore/StupidAllocator.cc: 336: FAILED assert(rm.empty())
Actions
Copy link
 #4

Updated by Igor Fedotov almost 5 years ago

Christian - could you please set debug bluestore to 20 restart the osd and collect the log?

Actions
Copy link
 #5

Updated by Igor Fedotov almost 5 years ago

Nevermind - I missed the note that you can't reproduce it...

Actions
Copy link Download all files
 #6

Updated by Christian Wahl almost 5 years ago

Full log file with osd debug = 20 is attached.

The meta data ceph gathered:

{
    "crash_id": "2019-07-17_15:35:13.279700Z_688f56e9-cafd-42eb-9338-8d1fdaa8af86",
    "timestamp": "2019-07-17 15:35:13.279700Z",
    "entity_name": "osd.6",
    "ceph_version": "13.2.6",
    "utsname_hostname": "tecoceph",
    "utsname_sysname": "Linux",
    "utsname_release": "3.10.0-957.21.3.el7.x86_64",
    "utsname_version": "#1 SMP Tue Jun 18 16:35:19 UTC 2019",
    "utsname_machine": "x86_64",
    "os_name": "CentOS Linux",
    "os_id": "centos",
    "os_version_id": "7",
    "os_version": "7 (Core)",
    "assert_condition": "rm.empty()",
    "assert_func": "virtual void StupidAllocator::init_rm_free(uint64_t, uint64_t)",
    "assert_file": "/home/jenkins-build/build/workspace/ceph-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos7/DIST/centos7/MACHINE_SIZE/huge/release/13.2.6/rpm/el7/BUILD/ceph-13.2.6/src/os/bluestore/StupidAllocator.cc",
    "assert_line": 336,
    "assert_thread_name": "ceph-osd",
    "backtrace": [
        "(()+0xf5d0) [0x7ff05d6f35d0]",
        "(gsignal()+0x37) [0x7ff05c714207]",
        "(abort()+0x148) [0x7ff05c7158f8]",
        "(ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x248) [0x7ff060b80468]",
        "(()+0x26e4f7) [0x7ff060b804f7]",
        "(StupidAllocator::init_rm_free(unsigned long, unsigned long)+0x1fb6) [0x55e845ee9c46]",
        "(BlueFS::mount()+0x260) [0x55e845eced60]",
        "(BlueStore::_open_db(bool, bool)+0x170f) [0x55e845df093f]",
        "(BlueStore::_mount(bool, bool)+0x4d1) [0x55e845e21071]",
        "(OSD::init()+0x28f) [0x55e8459c8edf]",
        "(main()+0x23a3) [0x55e8458a77a3]",
        "(__libc_start_main()+0xf5) [0x7ff05c7003d5]",
        "(()+0x385900) [0x55e84597f900]" 
    ]
}

Actions
Copy link
 #7

Updated by Igor Fedotov almost 5 years ago

Christian - please tell more about the drive layout at these OSDs.. Is this just a single drive config?

Actions
Copy link
 #8

Updated by Igor Fedotov almost 5 years ago

Would you share file listing for root folder of osd-0 and any other working OSD?

Actions
Copy link
 #9

Updated by Zoltan Arnold Nagy over 4 years ago

we've also hit this on a 12.2.12:

@ -4> 2019-08-15 13:29:40.208068 7ff0a6eabe00 1 bdev(0x55bae6cc7440 /var/lib/ceph/osd/ceph-325/block) open path /var/lib/ceph/osd/ceph-325/block
-3> 2019-08-15 13:29:40.208253 7ff0a6eabe00 1 bdev(0x55bae6cc7440 /var/lib/ceph/osd/ceph-325/block) open size 8001561821184 (0x74702400000, 7.28TiB) block_size 4096 (4KiB) rotational
-2> 2019-08-15 13:29:40.208265 7ff0a6eabe00 1 bluefs add_block_device bdev 2 path /var/lib/ceph/osd/ceph-325/block size 7.28TiB
-1> 2019-08-15 13:29:40.208303 7ff0a6eabe00 1 bluefs mount
0> 2019-08-15 13:29:40.212962 7ff0a6eabe00 -1 /build/ceph-12.2.12/src/os/bluestore/StupidAllocator.cc: In function 'virtual void StupidAllocator::init_rm_free(uint64_t, uint64_t)' thread 7ff0a6eabe00 time 2019-08-15 13:29:40.209874
/build/ceph-12.2.12/src/os/bluestore/StupidAllocator.cc: 335: FAILED assert(rm.empty())

ceph version 12.2.12 (1436006594665279fe734b4c15d7e08c13ebd777) luminous (stable)
 1: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x102) [0x55badcc87a02]
 2: (StupidAllocator::init_rm_free(unsigned long, unsigned long)+0x2c6c) [0x55badcc2eb8c]
 3: (BlueFS::mount()+0x3f9) [0x55badcc00849]
 4: (BlueStore::_open_db(bool)+0x169c) [0x55badcb0fcdc]
 5: (BlueStore::_mount(bool)+0x3ad) [0x55badcb43ded]
 6: (OSD::init()+0x3e2) [0x55badc695f12]
 7: (main()+0x2f0a) [0x55badc59f0ca]
 8: (__libc_start_main()+0xf0) [0x7ff0a410e830]
 9: (_start()+0x29) [0x55badc62c329]
 NOTE: a copy of the executable, or `objdump -rdS &lt;executable&gt;` is needed to interpret this.
@
Actions
Copy link
 #10

Updated by lei zhang over 4 years ago

@Zoltan Arnold Nagy Arnold Nagy,Did you change bluefs_buffered_io to true on 12.2.12?
We suspect this is due to the use of two file handles for reads and writes, fd_direct for writes and fd_buffered for reads.

we hit this on 13.2.5

We tried to reproduce this problem using the bluefs unit test case. Then we found that when the disk pressure is high, there is a chance that the data written is inconsistent with the data read.However, using hexdump to read the data on the disk found that the data written was fine.

   -83> 2019-08-16 18:27:12.929 7fe969c46200  1 bluefs mkfs osd_uuid 00000000-0000-0000-0000-000000000000
   -82> 2019-08-16 18:27:12.929 7fe955401700 20 bdev(0x5580b262ce00 /dev/sdjvg/wal) _discard_thread sleep
   -81> 2019-08-16 18:27:12.929 7fe969c46200 20 bluefs _init_alloc
   -80> 2019-08-16 18:27:12.929 7fe969c46200  1 bluefs mkfs uuid 1cc0f0ed-120d-4d7c-bb6c-7db5f3374021
   -79> 2019-08-16 18:27:12.929 7fe969c46200 10 bluefs _allocate len 0x400000 from 0
   -78> 2019-08-16 18:27:12.929 7fe969c46200 20 bluefs mkfs op_alloc_add 0 0x100000~7f00000
   -77> 2019-08-16 18:27:12.929 7fe969c46200 20 bluefs mkfs op_alloc_add 1 0x100000~7f00000
   -76> 2019-08-16 18:27:12.929 7fe969c46200 20 bluefs mkfs op_alloc_add 2 0x100000~7f00000
   -75> 2019-08-16 18:27:12.929 7fe969c46200 10 bluefs _flush_and_sync_log txn(seq 1 len 0x37 crc 0x72979537)
   -74> 2019-08-16 18:27:12.929 7fe969c46200 10 bluefs _pad_bl padding with 0xfa3 zeros
   -73> 2019-08-16 18:27:12.929 7fe969c46200 10 bluefs _flush 0x5580b2628140 0x0~1000 to file(ino 1 size 0x0 mtime 0.000000 bdev 0 allocated 400000 extents [0:0x100000+400000])
   -72> 2019-08-16 18:27:12.929 7fe969c46200 10 bluefs _flush_range 0x5580b2628140 pos 0x0 0x0~1000 to file(ino 1 size 0x0 mtime 0.000000 bdev 0 allocated 400000 extents [0:0x100000+400000])
   -71> 2019-08-16 18:27:12.929 7fe969c46200 20 bluefs _flush_range file now file(ino 1 size 0x1000 mtime 0.000000 bdev 0 allocated 400000 extents [0:0x100000+400000])
   -70> 2019-08-16 18:27:12.929 7fe969c46200 20 bluefs _flush_range in 0:0x100000+400000 x_off 0x0
   -69> 2019-08-16 18:27:12.929 7fe969c46200 30 bluefs dump:
00000000  01 01 57 00 00 00 1c c0  f0 ed 12 0d 4d 7c bb 6c  |..W.........M|.l|
00000010  7d b5 f3 37 40 21 01 00  00 00 00 00 00 00 37 00  |}..7@!........7.|
00000020  00 00 01 02 00 00 00 10  00 00 00 00 00 00 00 f0  |................|
00000030  07 00 00 00 00 02 01 00  00 10 00 00 00 00 00 00  |................|
00000040  00 f0 07 00 00 00 00 02  02 00 00 10 00 00 00 00  |................|
00000050  00 00 00 f0 07 00 00 00  00 37 95 97 72 00 00 00  |.........7..r...|
00000060  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
*
00000ff0  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
00001000

   -68> 2019-08-16 18:27:12.930 7fe969c46200 20 bdev(0x5580b262ce00 /dev/sdjvg/wal) aio_write 0x100000~1000 (direct)
   -67> 2019-08-16 18:27:12.930 7fe969c46200 20 bdev(0x5580b262ce00 /dev/sdjvg/wal) aio_write rebuilding buffer to be aligned
   -66> 2019-08-16 18:27:12.930 7fe969c46200 20 bdev(0x5580b262ce00 /dev/sdjvg/wal) _aio_log_start 0x100000~1000
   -65> 2019-08-16 18:27:12.930 7fe969c46200  5 bdev(0x5580b262ce00 /dev/sdjvg/wal) aio_write 0x100000~1000 aio 0x5580b2628290
   -64> 2019-08-16 18:27:12.930 7fe969c46200 20 bdev(0x5580b262ce00 /dev/sdjvg/wal) aio_submit ioc 0x5580b2624840 pending 1 running 0
   -63> 2019-08-16 18:27:12.930 7fe969c46200 20 bluefs _flush_range h 0x5580b2628140 pos now 0x1000
   -62> 2019-08-16 18:27:12.930 7fe969c46200 10 bluefs _claim_completed_aios got 1 aios
   -61> 2019-08-16 18:27:12.930 7fe969c46200 10 bluefs wait_for_aio 0x5580b2628140
   -60> 2019-08-16 18:27:12.930 7fe969c46200 10 bdev aio_wait 0x5580b2624840 waiting for 1 aios to complete
   -59> 2019-08-16 18:27:13.411 7fe955c02700 20 bdev(0x5580b262ce00 /dev/sdjvg/wal) _aio_log_finish 1 0x100000~1000
   -58> 2019-08-16 18:27:13.411 7fe955c02700 10 bdev(0x5580b262ce00 /dev/sdjvg/wal) _aio_thread finished aio 0x5580b2628290 r 4096 ioc 0x5580b2624840 with 0 aios left
   -57> 2019-08-16 18:27:13.411 7fe969c46200 20 bdev aio_wait 0x5580b2624840 done
   -56> 2019-08-16 18:27:13.411 7fe969c46200 20 bdev aio_wait 0x5580b2620d80 done
   -55> 2019-08-16 18:27:13.411 7fe969c46200 20 bdev aio_wait 0x5580b262a6c0 done
   -54> 2019-08-16 18:27:13.411 7fe969c46200 10 bluefs wait_for_aio 0x5580b2628140 done in 0.481119
   -53> 2019-08-16 18:27:13.411 7fe969c46200 20 bluefs flush_bdev
   -52> 2019-08-16 18:27:13.411 7fe969c46200 10 bdev(0x5580b262ce00 /dev/sdjvg/wal) flush start
   -51> 2019-08-16 18:27:13.411 7fe969c46200  5 bdev(0x5580b262ce00 /dev/sdjvg/wal) flush in 0.000008
   -50> 2019-08-16 18:27:13.411 7fe969c46200 10 bdev(0x5580b262d180 /dev/sdjvg/db) flush no-op (no ios since last flush), flag is 0
   -49> 2019-08-16 18:27:13.411 7fe969c46200 10 bdev(0x5580b262d500 /dev/sdjvg/slow) flush no-op (no ios since last flush), flag is 0
   -48> 2019-08-16 18:27:13.411 7fe969c46200 20 bluefs _flush_and_sync_log log_seq_stable 1
   -47> 2019-08-16 18:27:13.411 7fe969c46200 10 bluefs _write_super super block length(encoded): 89
   -46> 2019-08-16 18:27:13.411 7fe969c46200 10 bluefs _write_super superblock 1
   -45> 2019-08-16 18:27:13.411 7fe969c46200 10 bluefs _write_super log_fnode file(ino 1 size 0x1000 mtime 0.000000 bdev 0 allocated 400000 extents [0:0x100000+400000])
   -44> 2019-08-16 18:27:13.411 7fe969c46200 20 bdev(0x5580b262d180 /dev/sdjvg/db) write 0x1000~1000 (direct)
   -43> 2019-08-16 18:27:13.411 7fe969c46200 20 bdev(0x5580b262d180 /dev/sdjvg/db) write rebuilding buffer to be aligned
   -42> 2019-08-16 18:27:13.411 7fe969c46200  5 bdev(0x5580b262d180 /dev/sdjvg/db) _sync_write 0x1000~1000 buffered
   -41> 2019-08-16 18:27:13.415 7fe969c46200 20 bluefs _write_super v 1 crc 0x60a485e6 offset 0x1000
   -40> 2019-08-16 18:27:13.415 7fe969c46200 20 bluefs flush_bdev
   -39> 2019-08-16 18:27:13.415 7fe969c46200 10 bdev(0x5580b262ce00 /dev/sdjvg/wal) flush no-op (no ios since last flush), flag is 0
   -38> 2019-08-16 18:27:13.415 7fe969c46200 10 bdev(0x5580b262d180 /dev/sdjvg/db) flush start
   -37> 2019-08-16 18:27:13.415 7fe969c46200  5 bdev(0x5580b262d180 /dev/sdjvg/db) flush in 0.000003
   -36> 2019-08-16 18:27:13.415 7fe969c46200 10 bdev(0x5580b262d500 /dev/sdjvg/slow) flush no-op (no ios since last flush), flag is 0
   -35> 2019-08-16 18:27:13.415 7fe969c46200 10 bluefs _close_writer 0x5580b2628140 type 0
   -34> 2019-08-16 18:27:13.415 7fe969c46200 20 bdev aio_wait 0x5580b2624840 done
   -33> 2019-08-16 18:27:13.415 7fe969c46200 20 bdev aio_wait 0x5580b2620d80 done
   -32> 2019-08-16 18:27:13.415 7fe969c46200 20 bdev aio_wait 0x5580b262a6c0 done
   -31> 2019-08-16 18:27:13.415 7fe969c46200 20 bluefs _stop_alloc
   -30> 2019-08-16 18:27:13.415 7fe969c46200 10 bdev(0x5580b262ce00 /dev/sdjvg/wal) discard_drain
   -29> 2019-08-16 18:27:13.415 7fe969c46200 10 bdev(0x5580b262d180 /dev/sdjvg/db) discard_drain
   -28> 2019-08-16 18:27:13.415 7fe969c46200 10 bdev(0x5580b262d500 /dev/sdjvg/slow) discard_drain
   -27> 2019-08-16 18:27:13.415 7fe969c46200  1 stupidalloc 0x0x5580b2401e30 shutdown
   -26> 2019-08-16 18:27:13.415 7fe969c46200  1 stupidalloc 0x0x5580b2401ea0 shutdown
   -25> 2019-08-16 18:27:13.415 7fe969c46200  1 stupidalloc 0x0x5580b2401f10 shutdown
   -24> 2019-08-16 18:27:13.415 7fe969c46200 10 bluefs mkfs success
   -23> 2019-08-16 18:27:13.415 7fe969c46200  1 bluefs mount
   -22> 2019-08-16 18:27:13.415 7fe969c46200 10 bluefs _open_super
   -21> 2019-08-16 18:27:13.415 7fe969c46200  5 bdev(0x5580b262d180 /dev/sdjvg/db) read 0x1000~1000 (direct)
   -20> 2019-08-16 18:27:13.415 7fe969c46200 20 bdev(0x5580b262d180 /dev/sdjvg/db) _aio_log_start 0x1000~1000
   -19> 2019-08-16 18:27:13.417 7fe969c46200 20 bdev(0x5580b262d180 /dev/sdjvg/db) _aio_log_finish 1 0x1000~1000
   -18> 2019-08-16 18:27:13.417 7fe969c46200 10 bluefs _open_super superblock 1
   -17> 2019-08-16 18:27:13.417 7fe969c46200 10 bluefs _open_super log_fnode file(ino 1 size 0x1000 mtime 0.000000 bdev 0 allocated 400000 extents [0:0x100000+400000])
   -16> 2019-08-16 18:27:13.417 7fe969c46200 20 bluefs _init_alloc
   -15> 2019-08-16 18:27:13.417 7fe969c46200 10 bluefs _replay
   -14> 2019-08-16 18:27:13.417 7fe969c46200 30 bluefs _get_file ino 1 = 0x5580b25c8960 (new)
   -13> 2019-08-16 18:27:13.417 7fe969c46200 10 bluefs _replay log_fnode file(ino 1 size 0x1000 mtime 0.000000 bdev 0 allocated 400000 extents [0:0x100000+400000])
   -12> 2019-08-16 18:27:13.417 7fe969c46200 10 bluefs _read h 0x5580b236b980 0x0~1000 from file(ino 1 size 0x1000 mtime 0.000000 bdev 0 allocated 400000 extents [0:0x100000+400000])
   -11> 2019-08-16 18:27:13.417 7fe969c46200 20 bluefs _read fetching 0x0~100000 of 0:0x100000+400000
   -10> 2019-08-16 18:27:13.417 7fe969c46200  5 bdev(0x5580b262ce00 /dev/sdjvg/wal) read 0x100000~100000 (buffered)
    -9> 2019-08-16 18:27:13.417 7fe969c46200 20 bdev(0x5580b262ce00 /dev/sdjvg/wal) _aio_log_start 0x100000~100000
    -8> 2019-08-16 18:27:13.418 7fe969c46200 20 bdev(0x5580b262ce00 /dev/sdjvg/wal) _aio_log_finish 1 0x100000~100000
    -7> 2019-08-16 18:27:13.418 7fe969c46200 20 bluefs _read left 0x100000 len 0x1000
    -6> 2019-08-16 18:27:13.418 7fe969c46200 30 bluefs _read result chunk (0x1000 bytes):
00000000  01 01 57 00 00 00 54 30  98 68 0f ec 41 96 b5 07  |..W...T0.h..A...|
00000010  90 30 98 be 89 4e 01 00  00 00 00 00 00 00 37 00  |.0...N........7.|
00000020  00 00 01 02 00 00 00 10  00 00 00 00 00 00 00 f0  |................|
00000030  07 00 00 00 00 02 01 00  00 10 00 00 00 00 00 00  |................|
00000040  00 f0 07 00 00 00 00 02  02 00 00 10 00 00 00 00  |................|
00000050  00 00 00 f0 07 00 00 00  00 37 95 97 72 00 00 00  |.........7..r...|
00000060  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
*
00000ff0  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
00001000

    -5> 2019-08-16 18:27:13.418 7fe969c46200 20 bluefs _read got 4096
    -4> 2019-08-16 18:27:13.418 7fe969c46200 10 bluefs _replay 0x0: stop: uuid 54309868-0fec-4196-b507-903098be894e != super.uuid 1cc0f0ed-120d-4d7c-bb6c-7db5f3374021
    -3> 2019-08-16 18:27:13.418 7fe969c46200 10 bluefs _replay log file size was 0x1000
    -2> 2019-08-16 18:27:13.418 7fe969c46200 10 bluefs _replay done
    -1> 2019-08-16 18:27:13.418 7fe969c46200 30 bluefs mount noting alloc for file(ino 1 size 0x1000 mtime 0.000000 bdev 0 allocated 400000 extents [0:0x100000+400000])
     0> 2019-08-16 18:27:13.419 7fe969c46200 -1 /home/ceph-13.2.5/src/os/bluestore/StupidAllocator.cc: In function 'virtual void StupidAllocator::init_rm_free(uint64_t, uint64_t)' thread 7fe969c46200 time 2019-08-16 18:27:13.419844
/home/ceph-13.2.5/src/os/bluestore/StupidAllocator.cc: 361: FAILED assert(rm.empty())

 ceph version 13.2.5-67-g2959d4f (2959d4f645a8ebd0057831b7a7d3e35da89d893c) mimic (stable)
 1: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0xff) [0x7fe95f935f5f]
 2: (()+0x28c147) [0x7fe95f936147]
 3: (StupidAllocator::init_rm_free(unsigned long, unsigned long)+0x1e0f) [0x5580b01d48ff]
 4: (BlueFS::mount()+0x332) [0x5580b01b0412]
 5: (BlueFS_mkfs_mount_Test::TestBody()+0x26e) [0x5580b016c0ce]
 6: (void testing::internal::HandleExceptionsInMethodIfSupported<testing::Test, void>(testing::Test*, void (testing::Test::*)(), char const*)+0x4a) [0x5580b019f1aa]
 7: (testing::Test::Run()+0xba) [0x5580b0194a0a]
 8: (testing::TestInfo::Run()+0xac) [0x5580b0194aec]
 9: (testing::TestCase::Run()+0xb5) [0x5580b0194c25]
 10: (testing::internal::UnitTestImpl::RunAllTests()+0x468) [0x5580b0195118]
 11: (bool testing::internal::HandleExceptionsInMethodIfSupported<testing::internal::UnitTestImpl, bool>(testing::internal::UnitTestImpl*, bool (testing::internal::UnitTestImpl::*)(), char const*)+0x4a) [0x5580b019f69a]
 12: (testing::UnitTest::Run()+0x60) [0x5580b01952a0]
 13: (main()+0x1ea) [0x5580b0169b1a]
 14: (__libc_start_main()+0xf5) [0x7fe95c978c05]
 15: (()+0x53d10) [0x5580b016ad10]
 NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.
Actions
Copy link

Also available in: Atom PDF