Investigation of bug #40698
-
The reporter is using OpenSSL in version
1.0.2k-8.el7.x86_64. -
Packages used during the analysis: https://cbs.centos.org/koji/buildinfo?buildID=19048
- https://github.com/rzarzynski/ceph/pull/new/wip-bug-40698
- https://github.com/rzarzynski/ceph/pull/new/wip-bug-40698-2 (fix for name uniquity)
Kefu points out that MondoDB uses recursive locks:
// Note: see SERVER-8734 for why we are using a recursive mutex here.
// Once the deadlock fix in OpenSSL is incorporated into most distros of
// Linux, this can be changed back to a nonrecursive mutex.
static std::vector<std::unique_ptr<stdx::recursive_mutex>> _mutex;
Source: ssl_manager_openssl.cpp, line 328-331
The SERVER-8734 ticket is hosted at MondoDB's JIRA.
The crash happened in debug build with lockdep available. However, the provided log doesn't contain any backtrace showing where the lock has been initially taken as this information has not been collected.
int lockdep_will_lock(const char *name, int id, bool force_backtrace,
bool recursive)
{
// ...
lockdep_dout(20) << "_will_lock " << name << " (" << id << ")" << dendl;
// check dependency graph
map<int, BackTrace *> &m = held[p];
for (map<int, BackTrace *>::iterator p = m.begin();
p != m.end();
++p) {
if (p->first == id) {
if (!recursive) {
lockdep_dout(0) << "\n";
*_dout << "recursive lock of " << name << " (" << id << ")\n";
BackTrace *bt = new BackTrace(BACKTRACE_SKIP);
bt->print(*_dout);
if (p->second) {
*_dout << "\npreviously locked at\n";
p->second->print(*_dout);
}
delete bt;
*_dout << dendl;
ceph_abort();
}
}Likely the reason is lockdep_force_backtrace() returning false during the recording step.
int lockdep_will_lock(const char *name, int id, bool force_backtrace,
bool recursive)
{
// ...
BackTrace *bt = NULL;
if (force_backtrace || lockdep_force_backtrace()) {
bt = new BackTrace(BACKTRACE_SKIP);
}
// ...
}This can happen when the lockdep_force_backtrace configurable has not been set.
static bool lockdep_force_backtrace()
{
return (g_lockdep_ceph_ctx != NULL &&
g_lockdep_ceph_ctx->_conf->lockdep_force_backtrace);
}Reading through the source code of OpenSSL points out that two mutexes can be involved:
CRYPTO_LOCK_MALLOCand- the long-standing
CRYPTO_LOCK_MALLOC2.
On Apr 10 2019 the reporter provided a log with the lockdep_force_backtrace turned on. The important part of the log is:
-2> 2019-07-10T14:38:34.834+0800 7f26c1c7eb80 0
recursive lock of (4)
ceph version v15.0.0-2493-g5d3fd87101 (5d3fd87101e1e45fe372eade4a15a48caed73ba6) octopus (dev)
1: (ceph::mutex_debug_detail::mutex_debugging_base::_will_lock(bool)+0x4a) [0x7f26b89794ba]
2: (ceph::shared_mutex_debug::lock()+0x3a) [0x7f26b8a1780c]
3: (()+0x143a0c0) [0x7f26b88b70c0]
4: (CRYPTO_mem_ctrl()+0x39) [0x7f26b626dbe9]
5: (()+0x4a60e) [0x7f26a08f760e]
6: (SSL_COMP_get_compression_methods()+0x9) [0x7f26a08f9899]
7: (SSL_library_init()+0x179) [0x7f26a08ff7c9]
8: (init_hashlib()+0x1f) [0x7f26a0b2214f]
9: (_PyImport_LoadDynamicModule()+0x99) [0x7f26b71aad69]
10: (()+0xf7e41) [0x7f26b71a8e41]
...
previously locked at
ceph version v15.0.0-2493-g5d3fd87101 (5d3fd87101e1e45fe372eade4a15a48caed73ba6) octopus (dev)
1: (ceph::mutex_debug_detail::mutex_debugging_base::_locked()+0x3b) [0x7f26b897950b]
2: (ceph::shared_mutex_debug::lock()+0xb7) [0x7f26b8a17889]
3: (()+0x143a0c0) [0x7f26b88b70c0]
4: (()+0x4a5de) [0x7f26a08f75de]
5: (SSL_COMP_get_compression_methods()+0x9) [0x7f26a08f9899]
6: (SSL_library_init()+0x179) [0x7f26a08ff7c9]
7: (init_hashlib()+0x1f) [0x7f26a0b2214f]
8: (_PyImport_LoadDynamicModule()+0x99) [0x7f26b71aad69]
9: (()+0xf7e41) [0x7f26b71a8e41]
...
-1> 2019-07-10T14:38:34.851+0800 7f26c1c7eb80 -1 /home/xuxuehan/mnt/github-ceph/src/common/lockdep.cc: In function 'int lockdep_will_lock(const char*, int, bool, bool)' thread 7f26c1c7eb80 time 2019-07-10T14:38:34.844019+0800
/home/xuxuehan/mnt/github-ceph/src/common/lockdep.cc: 305: ceph_abort_msg("abort() called")
6: (SSL_COMP_get_compression_methods()+0x9) [0x7f26a08f9899]:
000000000004c890 <SSL_COMP_get_compression_methods@@libssl.so.10>:
4c890: 48 83 ec 08 sub $0x8,%rsp
4c894: e8 c7 dc ff ff callq 4a560 <PEM_write_SSL_SESSION@@libssl.so.10+0x100>
4c899: 48 8b 05 d0 49 22 00 mov 0x2249d0(%rip),%rax # 271270 <_edata@@libssl.so.10+0x70>
5: (()+0x4a60e) [0x7f26a08f760e]:
4a604: bf 03 00 00 00 mov $0x3,%edi
4a609: e8 e2 01 fd ff callq 1a7f0 <CRYPTO_mem_ctrl@plt>
4a60e: 48 8d 3d 9b fe ff ff lea -0x165(%rip),%rdi # 4a4b0 <PEM_write_SSL_SESSION@@libssl.so.10+0x50>
4: (CRYPTO_mem_ctrl()+0x39) [0x7f26b626dbe9]:
The symbol is at offset 0x6ebb0 in /lib64/libcrypto.so.1.0.2k. After adding 0x39 we get 0x6ebe9.
000000000006ebb0 <CRYPTO_mem_ctrl@@libcrypto.so.10>:
6ebb0: 55 push %rbp
6ebb1: 48 8d 15 fa 65 13 00 lea 0x1365fa(%rip),%rdx # 1a51b2 <_fini@@libcrypto.so.10+0x5da>
6ebb8: b9 d4 00 00 00 mov $0xd4,%ecx
6ebbd: be 14 00 00 00 mov $0x14,%esi
6ebc2: 53 push %rbx
6ebc3: 89 fb mov %edi,%ebx
6ebc5: bf 09 00 00 00 mov $0x9,%edi
6ebca: 48 83 ec 28 sub $0x28,%rsp
6ebce: 8b 2d 84 d7 3e 00 mov 0x3ed784(%rip),%ebp # 45c358 <OPENSSL_NONPIC_relocated@@libcrypto.so.10+0xb0>
6ebd4: 64 48 8b 04 25 28 00 mov %fs:0x28,%rax
6ebdb: 00 00
6ebdd: 48 89 44 24 18 mov %rax,0x18(%rsp)
6ebe2: 31 c0 xor %eax,%eax
6ebe4: e8 a7 ed ff ff callq 6d990 <CRYPTO_lock@@libcrypto.so.10>
6ebe9: 83 fb 01 cmp $0x1,%ebx
The signature of CRYPTO_lock is:
void CRYPTO_lock(int mode, int type, const char *file, int line)The rigster mapping according to the ABI:
mode -> RDI,
type -> RSI,
file -> RDX,
line -> RCX
# define CRYPTO_LOCK_MALLOC 20
5: (SSL_COMP_get_compression_methods()+0x9) [0x7f26a08f9899]:
000000000004c890 <SSL_COMP_get_compression_methods@@libssl.so.10>:
4c890: 48 83 ec 08 sub $0x8,%rsp
4c894: e8 c7 dc ff ff callq 4a560 <PEM_write_SSL_SESSION@@libssl.so.10+0x100>
4c899: 48 8b 05 d0 49 22 00 mov 0x2249d0(%rip),%rax # 271270 <_edata@@libssl.so.10+0x70>
4: (()+0x4a5de) [0x7f26a08f75de]:
4a5c3: 48 8d 15 12 d8 00 00 lea 0xd812(%rip),%rdx # 57ddc <dtls1_version_str@@libssl.so.10+0x6fc>
4a5ca: b9 e0 01 00 00 mov $0x1e0,%ecx
4a5cf: be 10 00 00 00 mov $0x10,%esi
4a5d4: bf 09 00 00 00 mov $0x9,%edi
4a5d9: e8 c2 f2 fc ff callq 198a0 <CRYPTO_lock@plt>
4a5de: 48 83 3d 8a 6c 22 00 cmpq $0x0,0x226c8a(%rip) # 271270 <_edata@@libssl.so.10+0x70>
# define CRYPTO_LOCK_SSL 16
Compiler has optimized the call to user-provided locking callback.
void CRYPTO_lock(int mode, int type, const char *file, int line)
{
// ...
if (type < 0) {
// ...
} else if (locking_callback != NULL)
locking_callback(mode, type, file, line);
}000000000006d990 <CRYPTO_lock@@libcrypto.so.10>:
6d990: 41 54 push %r12
6d992: 49 89 d4 mov %rdx,%r12
6d995: 55 push %rbp
6d996: 89 fd mov %edi,%ebp
6d998: 53 push %rbx
6d999: 89 f3 mov %esi,%ebx
6d99b: 48 83 ec 10 sub $0x10,%rsp
6d99f: 85 f6 test %esi,%esi
6d9a1: 78 1d js 6d9c0 <CRYPTO_lock@@libcrypto.so.10+0x30>
6d9a3: 48 8b 05 36 e9 3e 00 mov 0x3ee936(%rip),%rax # 45c2e0 <OPENSSL_NONPIC_relocated@@libcrypto.so.10+0x38>
6d9aa: 48 85 c0 test %rax,%rax
6d9ad: 74 51 je 6da00 <CRYPTO_lock@@libcrypto.so.10+0x70>
6d9af: 48 83 c4 10 add $0x10,%rsp
6d9b3: 5b pop %rbx
6d9b4: 5d pop %rbp
6d9b5: 41 5c pop %r12
6d9b7: ff e0 jmpq *%rax
lockdep signalizes recursive locking issue for two independent locks represented by CRYPTO_LOCK_MALLOC and CRYPTO_LOCK_SSL.
shared_mutex_debug in conjunction with lockdep name generation relies on the assumption std::string::c_str() always returns different addresses for different instances of the std::string.
void mutex_debugging_base::_register() {
id = lockdep_register(name.c_str());
}This is fine for the std::string available on a Ubuntu machine:
rzarzynski@ubulap:/tmp/openssl-pkg$ g++ /tmp/c_str_on_empty_string.cc -o /tmp/c_str_on_empty_string
rzarzynski@ubulap:/tmp/openssl-pkg$ /tmp/c_str_on_empty_string
a.c_str()=0x7ffdec0a6aa0
b.c_str()=0x7ffdec0a6ac0
rzarzynski@ubulap:/tmp/openssl-pkg$ cat /tmp/c_str_on_empty_string.cc
#include <string>
#include <iostream>
int main (void) {
std::string a(std::string{});
std::string b(std::string{});
std::cout << "a.c_str()=" << static_cast<const void*>(a.c_str()) << std::endl;
std::cout << "b.c_str()=" << static_cast<const void*>(b.c_str()) << std::endl;
}
However, on incerta07:
[rzarzynski@incerta07 ~]$ /tmp/test
a.c_str()=0x7f4e13a8de38
b.c_str()=0x7f4e13a8de38
[rzarzynski@incerta07 ~]$ cat /tmp/test.cc
#include <string>
#include <iostream>
int main (void) {
std::string a(std::string{});
std::string b(std::string{});
std::cout << "a.c_str()=" << static_cast<const void*>(a.c_str()) << std::endl;
std::cout << "b.c_str()=" << static_cast<const void*>(b.c_str()) << std::endl;
}
UPDATE: this was a red herring. lockdep converts const char* backs to std::string. Thefore, the lock_ids map uses comparison operators of std::stirng.
static int _lockdep_register(const char *name)
{
int id = -1;
if (!g_lockdep)
return id;
ceph::unordered_map<std::string, int>::iterator p = lock_ids.find(name);
if (p == lock_ids.end()) {
id = lockdep_get_free_id();
// ...
} else {
id = p->second;
lockdep_dout(20) << "had '" << name << "' as " << id << dendl;
}
++lock_refs[id];
return id;
}While e.g. constructor of shared_mutex_debug is
// Mutex concept is DefaultConstructible
shared_mutex_debug()
: shared_mutex_debug{std::string{}}
{}From BlueFS:
struct FileReader {
// ...
ceph::shared_mutex lock {
ceph::make_shared_mutex(std::string(), false, false, false)
};
FileReader(FileRef f, uint64_t mpf, bool rand, bool ie)
: file(f),
buf(mpf),
random(rand),
ignore_eof(ie) {
++file->num_readers;
}
~FileReader() {
--file->num_readers;
}