Segfault when mongodb, curl, openssl extensions are loaded

[glensc]

Description

php -m crashes, if curl and mongodb shared extensions loaded together (both compiled with system openssl support):

# rpm -qf /etc/php71/conf.d/curl.ini /etc/php71/conf.d/mongodb.ini
php71-curl-7.1.9-1.x86_64
php71-pecl-mongodb-1.2.11-1.x86_64

[root at blodnatt ~]# rpm -q curl
curl-7.55.1-1.x86_64

some openssl global lock again?

Source: http://lists.pld-linux.org/mailman/pipermail/pld-devel-en/2017-October/025436.html

See the full thread for discussion: http://lists.pld-linux.org/mailman/pipermail/pld-devel-en/2017-October/thread.html

The reproducer has been baked into docker container: https://gitlab.com/glensc/php71-mongodb-crash

$ ➔ docker run --rm registry.gitlab.com/glensc/php71-mongodb-crash:20171028_1 php71 -i | grep -E 'mongodb|libmongoc|libbson'
/etc/php71/conf.d/mongodb.ini,
mongodb
libbson headers version => 1.8.0
libbson library version => 1.8.0
libmongoc headers version => 1.8.1
libmongoc library version => 1.8.1
libmongoc SSL => enabled
libmongoc SSL library => OpenSSL
libmongoc crypto => enabled
libmongoc crypto library => libcrypto
libmongoc crypto system profile => enabled
libmongoc SASL => enabled
mongodb.debug => no value => no value

While the reproducer has been made for older versions, I just re-tested today with recent versions (libbson 1.9.3, libmongoc 1.9.3, openssl-1.0.2m-1.x86_64, php71-pecl-mongodb-1.4.2-0.1.x86_64) and the problem hasn't magically gone away :(

Currently the workaround exists, load mongodb ext after openssl ext:

➔ LC_ALL=C ls -1 /etc/php71/conf.d/*ssl*.ini /etc/php71/conf.d/*mongo*.ini

/etc/php71/conf.d/z-1-openssl.ini
/etc/php71/conf.d/z-2-mongodb.ini

Source: http://lists.pld-linux.org/mailman/pipermail/pld-devel-en/2017-October/025438.html

Which means the problem is somewhere in openssl cleanup routines.

[jmikola]

Using https://gitlab.com/glensc/php71-mongodb-crash, I ran the following to build and execute the test:

$ docker build . -t php71-mongodb-crash
$ docker run --rm -it php71-mongodb-crash gdb --ex 'set pagination off' --ex run --ex bt --args php71 -m

This produced a permissions error ("ptrace: Operation not permitted"), but https://stackoverflow.com/a/42030182/162228 suggested that I specify --cap-add=SYS_PTRACE on as a command line option to docker run. That fixed the problem and running php71 -m through GDB produced the following output:

$ docker run --cap-add=SYS_PTRACE --rm -it php71-mongodb-crash gdb --ex 'set pagination off' --ex run --ex bt --args php71 -m
GNU gdb (GDB) 8.1-1 (PLD Linux)
Copyright (C) 2018 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-pld-linux".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
<http://www.gnu.org/software/gdb/documentation/>.
For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from php71...Reading symbols from /usr/lib/debug/usr/bin/php71.debug...done.
done.
Starting program: /usr/bin/php71 -m
warning: Error disabling address space randomization: Operation not permitted
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/libthread_db.so.1".
[PHP Modules]
Core
curl
date
json
libxml
mongodb
openssl
pcre
Reflection
SimpleXML
SPL
standard

[Zend Modules]

[Inferior 1 (process 8) exited normally]
No stack.
(gdb) 

I did not observe a segfault.

When compiled with OpenSSL, the mongodb extension's own startup and shutdown functions execute the following functions in libmongoc:

• At startup, _mongoc_do_init() calls _mongoc_openssl_init(), which in turn calls a number of OpenSSL functions.
• At shutdown _mongoc_do_cleanup() calls _mongoc_openssl_cleanup(), which then calls _mongoc_openssl_thread_cleanup() for versions of OpenSSL before 1.1.0; otherwise, it is a no-op.

Since the crash happens at shutdown, let's look at _mongoc_openssl_thread_cleanup(). There, we see that libmongoc sets the locking and id callbacks to null iff the locking callback was _mongoc_openssl_thread_locking_callback. Beyond that, libmongoc just frees up some previously allocated memory.

Let's look at what the curl and openssl and extensions do during shutdown:

• PHP_MSHUTDOWN_FUNCTION(openssl) always sets the locking callback to null. AFAICT, the locking callback is never assigned elsewhere in the openssl extension.
• PHP_MSHUTDOWN_FUNCTION(curl) starts by calling curl_global_cleanup(), followed by a number of other OpenSSL functions. If the curl extension was built with OpenSSL, the locking and id callbacks are assigned to null. Those callbacks would have originally been assigned in PHP_MSTARTUP_FUNCTION(curl). I'll note that the curl extension isn't checking if its own handler was still registered at shutdown (as libmongoc does); however, I'm not sure how important that is.

Referring back to your segfault backtrace, we have the following:

#0  0x00007ffff07d4830 in ?? ()
#1  0x00007ffff33725e2 in CRYPTO_THREADID_current (id=0x7fffffffe7b0) at cryptlib.c:493
#2  0x00007ffff34316b8 in ERR_remove_thread_state (id=id@entry=0x0) at err.c:1001
#3  0x00007ffff4b72eaa in Curl_ossl_cleanup () at vtls/openssl.c:797
#4  0x00007ffff4b73d99 in Curl_ssl_cleanup () at vtls/vtls.c:173
#5  0x00007ffff4b43c45 in curl_global_cleanup () at easy.c:323
#6  0x00007ffff4d9a818 in zm_shutdown_curl (type=<optimized out>, module_number=8) at /usr/src/debug/php-7.1.9/ext/curl/interface.c:1408

This takes our focus to curl_global_cleanup(). I'm not sure what version of cURL is used by PHP 7.1, but for the purposes of navigating the source code I will use the latest stable release: 7.59.0.

Continuing from there, we call Curl_ssl_cleanup() and then Curl_ossl_cleanup(). That function indiscriminately calls ERR_remove_thread_state(). Even if ERR_remove_state() is called, control ultimately reaches ERR_remove_thread_state() so I will focus there.

Noting that you're using OpenSSL 1.0.2m, we can refer to this definition of ERR_remove_thread_state(). cURL does not pass an ID, which is why we see OpenSSL call CRYPTO_THREADID_current() to copy it into the output variable. Looking at the implementation of CRYPTO_THREADID_current(), it looks like the exception occurs when the function attempts to invoke threadid_callback. That callback would have been assigned via CRYPTO_THREADID_set_callback().

When libmongoc initializes, it would have used the deprecated CRYPTO_set_id_callback() API, which assigns id_callback. That is the variable that CRYPTO_THREADID_current() checks after threadid_callback.

OpenSSL initializes threadid_callback to zero and I don't see any calls to CRYPTO_THREADID_set_callback() in cURL, so it's unclear to me how threadid_callback would come to have a non-zero value and be called in your backtrace -- assuming we're correctly interpreting the backtrace and cause of the segfault.

The last frame being "??" stands out as an unknown. Since we apparently have debug symbols for cURL, OpenSSL, and PHP in the backtrace, I might guess that we're missing symbols for the mongodb extension and/or libmongoc. Would it be possible for you to modify the test environment to compile the extension from source instead of using a binary? Assuming you can still reproduce the crash, that might reveal the top-most frame.

---

If you need an immediate work-around, I could suggest the following:

• As of 1.4.0, the mongodb extension supports TLS libraries other than OpenSSL when building from source. This is discussed in the 1.4.0 release notes.
• In the event this is only a problem for versions of OpenSSL before 1.1, you may be able to circumvent it by upgrading OpenSSL (assuming PHP supports 1.1+).

[glensc]

you could use the prebuilt image from that project, it definitely crashes.

• images list: https://gitlab.com/glensc/php71-mongodb-crash/container_registry
• tested image (4 months ago): registry.gitlab.com/glensc/php71-mongodb-crash:20171028_1

ps: great response!

[glensc]

some missing details, maybe useful:

$ docker run --rm -it registry.gitlab.com/glensc/php71-mongodb-crash:20171028_1 rpm -q openssl curl-libs php71-pecl-mongodb mongo-c-driver-libs libbson
openssl-1.0.2l-1.x86_64
curl-libs-7.55.1-1.x86_64
php71-pecl-mongodb-1.2.11-1.x86_64
mongo-c-driver-libs-1.8.1-1.x86_64
libbson-1.8.0-1.x86_64

$ docker run --rm -it registry.gitlab.com/glensc/php71-mongodb-crash:20171028_1 gdb --ex 'set pagination off' --ex run --ex bt --args php71 -m
...


Program received signal SIGSEGV, Segmentation fault.
0x00007ffff07d4830 in ?? ()
#0  0x00007ffff07d4830 in ?? ()
#1  0x00007ffff33725e2 in CRYPTO_THREADID_current (id=0x7fffffffe7b0) at cryptlib.c:493
#2  0x00007ffff34316b8 in ERR_remove_thread_state (id=id@entry=0x0) at err.c:1001
#3  0x00007ffff4b72eaa in Curl_ossl_cleanup () at vtls/openssl.c:797
#4  0x00007ffff4b73d99 in Curl_ssl_cleanup () at vtls/vtls.c:173
#5  0x00007ffff4b43c45 in curl_global_cleanup () at easy.c:323
#6  0x00007ffff4d9a818 in zm_shutdown_curl (type=<optimized out>, module_number=8) at /usr/src/debug/php-7.1.9/ext/curl/interface.c:1408
#7  0x00007ffff7a1ebe7 in module_destructor (module=module@entry=0x6599c0) at /usr/src/debug/php-7.1.9/Zend/zend_API.c:2501
#8  0x00007ffff7a173bc in module_destructor_zval (zv=<optimized out>) at /usr/src/debug/php-7.1.9/Zend/zend.c:633
#9  0x00007ffff7a2a418 in _zend_hash_del_el_ex (prev=<optimized out>, p=<optimized out>, idx=<optimized out>, ht=<optimized out>) at /usr/src/debug/php-7.1.9/Zend/zend_hash.c:997
#10 _zend_hash_del_el (p=0x627e60, idx=7, ht=0x7ffff7dd5620 <module_registry>) at /usr/src/debug/php-7.1.9/Zend/zend_hash.c:1020
#11 zend_hash_graceful_reverse_destroy (ht=ht@entry=0x7ffff7dd5620 <module_registry>) at /usr/src/debug/php-7.1.9/Zend/zend_hash.c:1476
#12 0x00007ffff7a1cfbc in zend_destroy_modules () at /usr/src/debug/php-7.1.9/Zend/zend_API.c:1978
#13 0x00007ffff7a17ea1 in zend_shutdown () at /usr/src/debug/php-7.1.9/Zend/zend.c:876
#14 0x00007ffff79b4dab in php_module_shutdown () at /usr/src/debug/php-7.1.9/main/main.c:2420
#15 0x0000000000404d3f in main (argc=2, argv=0x61e1c0) at /usr/src/debug/php-7.1.9/sapi/cli/php_cli.c:1396
(gdb)

as for "??" in trace, i interpreted those as memory being corrupted, overwritten, etc.

[glensc]

i recall now, why fresh build doesn't crash anymore. the binary package from distribution has openssl disabled: pld-linux/mongo-c-driver@46f3613

[jmikola]

Upon further testing, it looks like "??" is indeed the result of trying to execute an invalid function pointer. Using GDB to step through the program, I did the following:

• Set a breakpoint at Curl_ossl_cleanup
• Allowed the program to run until that point
• Set another breakpoint at CRYPTO_THREADID_current
• Step through the function and verify that the segfault occurred when attempting to execute id_callback

At that point, I printed id_callback and noted that it had a non-zero value. I'm not sure what address space it was pointing to, though. I'll resume looking into this tomorrow with a fresh set of eyes.

At the moment, I think we might be able to set a watch point on the variable to determine exactly when it's being set over the course of php -m.

[glensc]

btw, i don't really need tls connections, i need to enable ssl in build to support authentication:

"Previous MongoConnectionException:The "SCRAM-SHA-1" authentication mechanism requires libmongoc built with --enable-ssl"

is it wise to switch to MongoDB-CR Authentication? it would be troublesome to switch it later (need to recreate users: https://stackoverflow.com/questions/29006887/mongodb-cr-authentication-failed/35732229)

[jmikola]

I wasn't able to make any progress with debugging. There doesn't appear to be a binary package for ext-mongodb debug symbols, so I resorted to shelling into the Docker container to manually install the extension from source so I could build it with debug symbols. This also required installing php71-devel and build-essential packages. Once I did so, running GDB from within the Docker shell didn't pull up the usual debug symbols for OpenSSL that I saw when running GDB directly from docker run, which made debugging a bit more complicated as I wouldn't be able to set a watch point on id_callback that way.

When running GDB directly withdocker run, I was able to watch id_callback and it looks like it was only set once from libmongoc's startup routines. I don't see it altered again before the segfault, which seems very odd. Best I can tell, it is still assigned the address of the libmongoc function and we just get a segfault when attempting to invoke that function later. Assuming mongodb.so is still loaded in memory (and I don't see why it wouldn't be), I'm at a loss for why that happens.

MongoDB-CR is deprecated, so I would not rely on it going forward. That said, it may be a viable workaround if you're only using MongoDB 3.4 and 3.6.

If you can easily work around this issue by changing the order in which the openssl and mongodb extensions are loaded, that may be preferable.

The best solution IMO is to manually compile the mongodb extension with LibreSSL if that's available for PLD Linux. Alternatively, find a way to upgrade OpenSSL to 1.1, which will allow libmongoc to not assign these callbacks in the first place. AFAIK, PHP 7.1 and later should support OpenSSL 1.1.

Side note: I'm going to be unavailable for the coming week, so the next time I'll be able to personally revisit this issue will be the week of April 9.

[glensc]

i've created new image with current versions with php71-devel and build-essential packages installed as well:

docker pull registry.gitlab.com/glensc/php71-mongodb-crash:20180402_1

the -debuginfo packages are in th-debuginfo package repository, so when installing poldek -n th -n th-debuginfo is needed (see the Dockerfile)

[jmikola]

Thanks for updating the Docker image. Since we previously established that the crash was due to attempted invocation of id_callback (despite it being non-null), I decided to debug the program with watchpoints set on the id_callback and locking_callback globals, which libmongoc initializes and cleans up during module init and shutdown, respectively. While the cURL extension doesn't appear to modify these directly, we previously noted that the OpenSSL extension indiscriminately assigns null to locking_callback upon shutdown.

Here's a GDB session paste:

$ docker run --cap-add=SYS_PTRACE --rm -it registry.gitlab.com/glensc/php71-mongodb-crash:20180402_1 gdb --ex 'set pagination off' --ex run --ex bt --args php71 -m

...

Program received signal SIGSEGV, Segmentation fault.
0x00007fb267563e40 in ?? ()
#0  0x00007fb267563e40 in ?? ()
#1  0x00007fb26a56e8a2 in CRYPTO_THREADID_current (id=0x7fff852b9400) at cryptlib.c:500
#2  0x00007fb26a62df58 in ERR_remove_thread_state (id=id@entry=0x0) at err.c:1007
#3  0x00007fb26bd6ccda in Curl_ossl_cleanup () at vtls/openssl.c:991
#4  0x00007fb26bd71c47 in Curl_ssl_cleanup () at vtls/vtls.c:177
#5  0x00007fb26bd36fce in curl_global_cleanup () at easy.c:329
#6  0x00007fb26bf9a828 in zm_shutdown_curl (type=<optimized out>, module_number=8) at /usr/src/debug/php-7.1.15/ext/curl/interface.c:1419
#7  0x00007fb26ecae157 in module_destructor (module=module@entry=0x16aebc0) at /usr/src/debug/php-7.1.15/Zend/zend_API.c:2501
#8  0x00007fb26eca697c in module_destructor_zval (zv=<optimized out>) at /usr/src/debug/php-7.1.15/Zend/zend.c:633
#9  0x00007fb26ecb9998 in _zend_hash_del_el_ex (prev=<optimized out>, p=<optimized out>, idx=<optimized out>, ht=<optimized out>) at /usr/src/debug/php-7.1.15/Zend/zend_hash.c:997
#10 _zend_hash_del_el (p=0x166f0b0, idx=7, ht=0x7fb26f05e620 <module_registry>) at /usr/src/debug/php-7.1.15/Zend/zend_hash.c:1020
#11 zend_hash_graceful_reverse_destroy (ht=ht@entry=0x7fb26f05e620 <module_registry>) at /usr/src/debug/php-7.1.15/Zend/zend_hash.c:1476
#12 0x00007fb26ecac53c in zend_destroy_modules () at /usr/src/debug/php-7.1.15/Zend/zend_API.c:1978
#13 0x00007fb26eca7421 in zend_shutdown () at /usr/src/debug/php-7.1.15/Zend/zend.c:876
#14 0x00007fb26ec4403b in php_module_shutdown () at /usr/src/debug/php-7.1.15/main/main.c:2445
#15 0x0000000000404d3f in main (argc=2, argv=0x1665410) at /usr/src/debug/php-7.1.15/sapi/cli/php_cli.c:1396

(gdb) watch id_callback
Hardware watchpoint 1: id_callback
(gdb) watch locking_callback
Hardware watchpoint 2: locking_callback
(gdb) run
The program being debugged has been started already.
Start it from the beginning? (y or n) y
Starting program: /usr/bin/php71 -m
warning: Error disabling address space randomization: Operation not permitted
Error in re-setting breakpoint 1: No symbol "id_callback" in current context.
Error in re-setting breakpoint 2: No symbol "locking_callback" in current context.
Error in re-setting breakpoint 1: No symbol "id_callback" in current context.
Error in re-setting breakpoint 2: No symbol "locking_callback" in current context.
Error in re-setting breakpoint 1: No symbol "id_callback" in current context.
Error in re-setting breakpoint 2: No symbol "locking_callback" in current context.
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/libthread_db.so.1".
Error in re-setting breakpoint 1: No symbol "id_callback" in current context.
Error in re-setting breakpoint 2: No symbol "locking_callback" in current context.
Error in re-setting breakpoint 1: No symbol "id_callback" in current context.
Error in re-setting breakpoint 2: No symbol "locking_callback" in current context.
Error in re-setting breakpoint 1: No symbol "id_callback" in current context.
Error in re-setting breakpoint 2: No symbol "locking_callback" in current context.

Hardware watchpoint 2: locking_callback

Old value = (void (*)(int, int, const char *, int)) 0x0
New value = (void (*)(int, int, const char *, int)) 0x7f02d9363fa0
CRYPTO_set_locking_callback (func=0x7f02d9363fa0) at cryptlib.c:414
414	}
(gdb) bt 5
#0  CRYPTO_set_locking_callback (func=0x7f02d9363fa0) at cryptlib.c:414
#1  0x00007f02d936406c in _mongoc_openssl_init () from /usr/lib64/libmongoc-1.0.so.0
#2  0x00007f02d9340869 in ?? () from /usr/lib64/libmongoc-1.0.so.0
#3  0x00007f02dec7cef7 in __pthread_once_slow () from /lib64/libpthread.so.0
#4  0x00007f02d9596f29 in zm_startup_mongodb (type=1, module_number=10) at /usr/src/debug/php71-pecl-mongodb-1.4.2/php_phongo.c:2684
(More stack frames follow...)
(gdb) c
Continuing.

Hardware watchpoint 1: id_callback

Old value = (unsigned long (*)(void)) 0x0
New value = (unsigned long (*)(void)) 0x7f02d9363e40
CRYPTO_set_id_callback (func=0x7f02d9363e40) at cryptlib.c:540
540	}
(gdb) bt 5  
#0  CRYPTO_set_id_callback (func=0x7f02d9363e40) at cryptlib.c:540
#1  0x00007f02d9364078 in _mongoc_openssl_init () from /usr/lib64/libmongoc-1.0.so.0
#2  0x00007f02d9340869 in ?? () from /usr/lib64/libmongoc-1.0.so.0
#3  0x00007f02dec7cef7 in __pthread_once_slow () from /lib64/libpthread.so.0
#4  0x00007f02d9596f29 in zm_startup_mongodb (type=1, module_number=10) at /usr/src/debug/php71-pecl-mongodb-1.4.2/php_phongo.c:2684
(More stack frames follow...)
(gdb) c
Continuing.
[PHP Modules]
Core
curl
date
json
libxml
mongodb
openssl
pcre
Reflection
SimpleXML
SPL
standard

[Zend Modules]


Hardware watchpoint 2: locking_callback

Old value = (void (*)(int, int, const char *, int)) 0x7f02d9363fa0
New value = (void (*)(int, int, const char *, int)) 0x0
CRYPTO_set_locking_callback (func=func@entry=0x0) at cryptlib.c:414
414	}
(gdb) bt 5
#0  CRYPTO_set_locking_callback (func=func@entry=0x0) at cryptlib.c:414
#1  0x00007f02d8695b5f in zm_shutdown_openssl (type=<optimized out>, module_number=11) at /usr/src/debug/php-7.1.15/ext/openssl/openssl.c:1592
#2  0x00007f02e0b40157 in module_destructor (module=module@entry=0xdbf730) at /usr/src/debug/php-7.1.15/Zend/zend_API.c:2501
#3  0x00007f02e0b3897c in module_destructor_zval (zv=<optimized out>) at /usr/src/debug/php-7.1.15/Zend/zend.c:633
#4  0x00007f02e0b4b998 in _zend_hash_del_el_ex (prev=<optimized out>, p=<optimized out>, idx=<optimized out>, ht=<optimized out>) at /usr/src/debug/php-7.1.15/Zend/zend_hash.c:997
(More stack frames follow...)
(gdb) c
Continuing.

Program received signal SIGSEGV, Segmentation fault.
0x00007f02d9363e40 in ?? ()

From this session we can see that the callbacks are originally assigned addresses that appear to be in the same vicinity of 0x7f02d93.

• locking_callback is assigned 0x7f02d9363fa0
• id_callback is assigned 0x7f02d9363e40
• _mongoc_openssl_init is 0x00007f02d9364078

I think we can reasonably conclude that libmongoc is assigning its own callback here, as 0x7f02d93 is quite different from the other address spaces we see in the original segfault backtrace (from cURL and PHP).

After those two assignments, we see locking_callback assigned back to 0 when the OpenSSL extension shuts down.

This is followed by the segfault described in #789 (comment). At the time of the segfault, the id_callback still has its originally assigned value of 0x7f02d9363fa0.

My hypothesis is that PHP is unloading the mongodb extension (and libmongoc) with dlclose() after OpenSSL zeroes out logging_callback. This prevents libmongoc from clearing it's original id_callback, since _mongoc_openssl_thread_cleanup() sees that locking_callback is no longer assigned to its own function.

I still don't understand why OpenSSL is indiscriminantly calling
CRYPTO_set_locking_callback(NULL);, since it never appears to assign a locking callback in the first place, but there's a clue in the comment above that line. The original intention was to avoid leaving behind a dangling pointer to a function after the extension is unloaded.

I believe a quick fix for this in libmongoc may be to split the logic so that locking_callback and id_callback can be cleared independently if either is still assigned to the libmongoc function at shutdown time. I'll try to address this in libmongoc and follow up once I have a ticket to cross-reference. I'm not sure if we'll be able to get this backported to libmongoc 1.9.x and ext-mongodb 1.4.x, but I don't see any reason we won't be able to address this in the next minor version of both libraries.