debug sodium_misuse issue

[oliverkurth]

I have an issue in one of my projects, see oliverkurth/rhizofs#6 . It only seems to happens on MacOS, so far I haven't seen it on Linux (although I use it more often on MacOS).

The code is very simple (see https://github.com/oliverkurth/rhizofs/blob/master/src/fs/socketpool.c#L112) , it just calls zmq_curve_keypair() (from libzmq, see https://github.com/zeromq/libzmq/blob/de5ee18203f4ba472812fd08665603cd3f88955d/src/zmq_utils.cpp#L190), which is calling crypto_box_keypair(). zmq_curve_keypair() will be called multiple times, every time the socket is renewed. After some time, seemingly random, I get crashes where libsodium aborts. Here is a stack trace:

Process 9732 resuming
Process 9732 stopped
* thread #10, stop reason = signal SIGABRT
    frame #0: 0x00007ff80a1e1202 libsystem_kernel.dylib`__pthread_kill + 10
libsystem_kernel.dylib`:
->  0x7ff80a1e1202 <+10>: jae    0x7ff80a1e120c            ; <+20>
    0x7ff80a1e1204 <+12>: movq   %rax, %rdi
    0x7ff80a1e1207 <+15>: jmp    0x7ff80a1daceb            ; cerror_nocancel
    0x7ff80a1e120c <+20>: retq   
Target 0: (rhizofs) stopped.
(lldb) bt
* thread #10, stop reason = signal SIGABRT
  * frame #0: 0x00007ff80a1e1202 libsystem_kernel.dylib`__pthread_kill + 10
    frame #1: 0x00007ff80a218ee6 libsystem_pthread.dylib`pthread_kill + 263
    frame #2: 0x00007ff80a13fb45 libsystem_c.dylib`abort + 123
    frame #3: 0x0000000108813fdf libsodium.23.dylib`sodium_misuse + 63
    frame #4: 0x000000010881e1f7 libsodium.23.dylib`randombytes_sysrandom_buf + 160
    frame #5: 0x00000001087fce5b libsodium.23.dylib`crypto_box_curve25519xsalsa20poly1305_keypair + 26
    frame #6: 0x0000000108754ba3 libzmq.5.dylib`zmq_curve_keypair + 61
    frame #7: 0x0000000108619f0b rhizofs`create_socket(ctx=0x00007fc35e104db0, type=3, server_public_key="K%aa{YTm3[k8Zg:jz.dW<Dz*aZU]tI>u]M!}2Pks", client_public_key=0x0000000000000000, client_secret_key=0x0000000000000000) at socketpool.c:112:13
    frame #8: 0x000000010861a33d rhizofs`SocketPool_get_socket(sp=0x000000010862d3d8) at socketpool.c:145:16
    frame #9: 0x000000010861443b rhizofs`Rhizofs_communicate(req=0x000070000b1e53a0, err=0x000070000b1e5414, socket_to_use=0x0000000000000000, check_fuse_interrupts=true) at rhizofs.c:193:16
    frame #10: 0x000000010861845e rhizofs`Rhizofs_statfs(path="/", svfs=0x000070000b1e5540) at rhizofs.c:910:5
    frame #11: 0x00000001086befd2 libfuse.2.dylib`___lldb_unnamed_symbol328 + 34
    frame #12: 0x00000001086bef90 libfuse.2.dylib`fuse_fs_statfs + 96
    frame #13: 0x00000001086d5147 libfuse.2.dylib`___lldb_unnamed_symbol830 + 55
    frame #14: 0x00000001086befd2 libfuse.2.dylib`___lldb_unnamed_symbol328 + 34
    frame #15: 0x00000001086bef90 libfuse.2.dylib`fuse_fs_statfs + 96
    frame #16: 0x00000001086c3e81 libfuse.2.dylib`___lldb_unnamed_symbol393 + 209
    frame #17: 0x00000001086cb8d9 libfuse.2.dylib`___lldb_unnamed_symbol557 + 25
    frame #18: 0x00000001086cac75 libfuse.2.dylib`___lldb_unnamed_symbol528 + 1077
    frame #19: 0x00000001086cd9b9 libfuse.2.dylib`fuse_session_process_buf + 25
    frame #20: 0x00000001086c8b16 libfuse.2.dylib`___lldb_unnamed_symbol498 + 326
    frame #21: 0x00007ff80a2191d3 libsystem_pthread.dylib`_pthread_start + 125
    frame #22: 0x00007ff80a214bd3 libsystem_pthread.dylib`thread_start + 15
(lldb) 

Both libsodium and zeromq are installed with brew:

okurth@okurth-a01 ~ % brew info libsodium
==> libsodium: stable 1.0.18 (bottled), HEAD
...
okurth@okurth-a01 ~ % brew info zeromq   
==> zeromq: stable 4.3.4 (bottled), HEAD

How can I debug this further?

I have a utility that also calls zmq_curve_keypair(), and I ran that 10000 times without any issues.

[jedisct1]

Did you initialize the library with sodium_init() before using it?

[oliverkurth]

Did you initialize the library with sodium_init() before using it?

Looks like libzmq does it in zmq_curve_keypair() - see https://github.com/zeromq/libzmq/blob/de5ee18203f4ba472812fd08665603cd3f88955d/src/zmq_utils.cpp#L200 and https://github.com/zeromq/libzmq/blob/master/src/random.cpp#L59

[oliverkurth]

When I have some time, hopefully this weekend, I will try to rebuild libsodium with debug symbols and try again. Is there anything else I can do to find out why sodium_misuse is called?

[jedisct1]

Maybe your application closed the wrong descriptor and accidentally closed the one used by libsodium to get randomness?

[oliverkurth]

Who knows? It's all speculation. It would be nice if sodium_init() gave a reason before aborting so we wouldn't need to guess. That was my question: can we find out, or do I need to rebuild with debug symbols?

[jedisct1]

/dev/random cannot be read. Maybe you are running out of file descriptors, or maybe your application is closing a descriptor it doesn't own.

Try running a simplified version of your application. Also try removing the calls to close() to see if that makes a difference.

[oliverkurth]

I rebuilt with debug symbols (brew reinstall --debug-symbols --build-from-source libsodium ), and this stack trace gives a little more information:

* thread #20, stop reason = signal SIGABRT
  * frame #0: 0x00007ff80a1e1202 libsystem_kernel.dylib`__pthread_kill + 10
    frame #1: 0x00007ff80a218ee6 libsystem_pthread.dylib`pthread_kill + 263
    frame #2: 0x00007ff80a13fb45 libsystem_c.dylib`abort + 123
    frame #3: 0x000000010021e21d libsodium.23.dylib`sodium_misuse at core.c:199:5 [opt]
    frame #4: 0x000000010022846f libsodium.23.dylib`randombytes_sysrandom_buf(buf=<unavailable>, size=32) at randombytes_sysrandom.c:358:9 [opt]
    frame #5: 0x0000000100207121 libsodium.23.dylib`crypto_box_curve25519xsalsa20poly1305_keypair(pk="", sk="\xd0\xef/\U00000003") at box_curve25519xsalsa20poly1305.c:29:5 [opt]
    frame #6: 0x0000000100143ba3 libzmq.5.dylib`zmq_curve_keypair + 61
    frame #7: 0x0000000100008f0b rhizofs`create_socket(ctx=0x0000000100604190, type=3, server_public_key="K%aa{YTm3[k8Zg:jz.dW<Dz*aZU]tI>u]M!}2Pks", client_public_key=0x0000000000000000, client_secret_key=0x0000000000000000) at socketpool.c:112:13
    frame #8: 0x000000010000933d rhizofs`SocketPool_get_socket(sp=0x000000010001c3d8) at socketpool.c:145:16
    frame #9: 0x000000010000343b rhizofs`Rhizofs_communicate(req=0x00007000032ff3a0, err=0x00007000032ff414, socket_to_use=0x0000000000000000, check_fuse_interrupts=true) at rhizofs.c:193:16
    frame #10: 0x000000010000745e rhizofs`Rhizofs_statfs(path="/", svfs=0x00007000032ff540) at rhizofs.c:910:5
    frame #11: 0x00000001000adfd2 libfuse.2.dylib`___lldb_unnamed_symbol328 + 34
    frame #12: 0x00000001000adf90 libfuse.2.dylib`fuse_fs_statfs + 96
    frame #13: 0x00000001000c4147 libfuse.2.dylib`___lldb_unnamed_symbol830 + 55
    frame #14: 0x00000001000adfd2 libfuse.2.dylib`___lldb_unnamed_symbol328 + 34
    frame #15: 0x00000001000adf90 libfuse.2.dylib`fuse_fs_statfs + 96
    frame #16: 0x00000001000b2e81 libfuse.2.dylib`___lldb_unnamed_symbol393 + 209
    frame #17: 0x00000001000ba8d9 libfuse.2.dylib`___lldb_unnamed_symbol557 + 25
    frame #18: 0x00000001000b9c75 libfuse.2.dylib`___lldb_unnamed_symbol528 + 1077
    frame #19: 0x00000001000bc9b9 libfuse.2.dylib`fuse_session_process_buf + 25
    frame #20: 0x00000001000b7b16 libfuse.2.dylib`___lldb_unnamed_symbol498 + 326
    frame #21: 0x00007ff80a2191d3 libsystem_pthread.dylib`_pthread_start + 125
    frame #22: 0x00007ff80a214bd3 libsystem_pthread.dylib`thread_start + 15
(lldb) 

The line number doesn't comletely match up, but looks like it's here: randombytes_sysrandom.c#L360

    if (stream.random_data_source_fd == -1 ||
        safe_read(stream.random_data_source_fd, buf, size) != (ssize_t) size) {
        sodium_misuse(); /* LCOV_EXCL_LINE */
    }

[oliverkurth]

This happened right away, btw. Sometimes it takes a while to happen, but sometimes it happens right at the beginning. This is probably the second time zmq_curve_keypair() was invoked.