Re: [Libevent-users] SSL problems after update to libeven 2.1.8

[Alexander Rojas <alexander@xxxxxxxxxxxxx>]

Hi Azat

> On 4. Feb 2018, at 20:49, Azat Khuzhin <a3at.mail@xxxxxxxxx> wrote:
> 
> Hi Alexander,
> 
> Sorry for the delay,
No problem, I have also been fixing other issues. Crunch time!
> 
>> So far, yes
> 
> Great.
> 
>> NOTE: Set LIBPROCESS_SSL_REQUIRE_CERT=1 to require peer certificate
>> verification
> 
> Hm, maybe something with require-cert (is this SSL_VERIFY_PEER?) ?

Not really an issue, we can configure if verify peer is active or not.

> 
>> [pid 13305] --- SIGPIPE (Broken pipe) ---
>> [pid 13305] libevent_openssl-2.1.so.6->SSL_get_error(0x204e3d0, 0xffffffff,
>> -192, 0)                                                        = 5
>> [pid 13305] libevent_openssl-2.1.so.6->SSL_get_error(0x204e3d0, 0xffffffff,
>> 0x140750dd, 0)                                                  = 1
>> [pid 13291] libevent_openssl-2.1.so.6->SSL_get_error(0x7f95b8000e60,
>> 0xffffffff, -192, 0)                                                   = 2
>> [pid 13305] --- SIGSEGV (Segmentation fault) ---
>> [pid 13292] +++ killed by SIGSEGV +++
>> [pid 13278] --- SIGCHLD (Child exited) ---
>> [pid 13291] libevent_openssl-2.1.so.6->SSL_get_error(0x7f95b8000e60, 0, 11,
>> 0)                                                              = 5
>> ../../../3rdparty/libprocess/src/tests/ssl_tests.cpp:254: Failure
>> (socket).failure(): Failed accept: connection error:
>> error:00000000:lib(0):func(0):reason(0)
>> ```
> 
> I don't like SIGPIPE here, seems that under ltrace it got SIGPIPE and
> you do not ignore it, am I right [1]? Could you add code to ignore it and
> retry again?
> 

Our code should ignore SIGPIPE by default. I added signal(SIGPIPE, SIG_IGN) close 
to the call site and nothing changed.

>  [1]: https://github.com/apache/mesos/blob/abd1751aa9a305b0648f4a630acbc84e7d837783/3rdparty/libprocess/src/process.cpp#L1029
> 
> I think that something like this before start in bash will do the trick:
>  trap '' SIGPIPE
> 
> Or maybe it will be better if you will remove #ifdef 0/#endif for
> print_err() in bufferevent_openssl.c and recompile it with it?
> 
> And the best thing that you can do is to produce a sample that I can
> compile and dig into, because I think that mesos is not the thing that I
> want to compile from sources for this.

Really hard to achieve, I was playing around and failed to get a minimal reproducer.

> 
>> I also verified our use of  `BEV_OPT_DEFER_CALLBACKS` and we do not use it
>> for listening sockets, so my backtrace should be alright. Connecting
>> sockets do use the flag however.
> 
> Regards,
> Azat.
> 
> P.S. you email client again messed up with long lines from ltrace
> ***********************************************************************
> To unsubscribe, send an e-mail to majordomo@xxxxxxxxxxxxx with
> unsubscribe libevent-users    in the body.

What I did do was to recompile libevent from the git tag `release-2.1.8-stable`
with the following flags:

```
cmake -DCMAKE_BUILD_TYPE=Debug \
    -GNinja \
    -DEVENT__DISABLE_THREAD_SUPPORT=off \
    -DEVENT__ENABLE_VERBOSE_DEBUG=on ..
```

I also enabled print_err(), so here is the output I got:

```
[debug] event_add: event: 0x1b094c0 (fd 5), EV_READ    call 0x7f710f1d5f10
[debug] ../event.c: no events registered. # This line repeats ~2000 times
...
[debug] event_add: event: 0x1afbcc0 (fd 6), EV_READ    call 0xd58520
[debug] event_add: event: 0x7f70dc000df0 (fd -1),    EV_TIMEOUT call 0xd56130
[debug] event_add: event 0x7f70dc000df0, timeout in 0 seconds 99990 useconds, call 0xd56130
[debug] ../poll.c: poll reports 1
[debug] event_active: 0x1b094c0 (fd 5), res 2, callback 0x7f710f1d5f10
[debug] event_process_active: event: 0x1b094c0, EV_READ   call 0x7f710f1d5f10
[debug] timeout_next: event: 0x7f70dc000df0, in 0 seconds, 99990 useconds
Note: Google Test filter = SSLTest.SSLSocket-
[==========] Running 1 test from 1 test case.
[----------] Global test environment set-up.
[----------] 1 test from SSLTest
[ RUN      ] SSLTest.SSLSocket
[debug] ../poll.c: poll reports 0
[debug] event_del: 0x7f70dc000df0 (fd -1), callback 0xd56130
[debug] timeout_process: event: 0x7f70dc000df0, call 0xd56130
[debug] event_active: 0x7f70dc000df0 (fd -1), res 1, callback 0xd56130
[debug] event_del: 0x7f70dc000df0 (fd -1), callback 0xd56130
[debug] event_process_active: event: 0x7f70dc000df0,    call 0xd56130
[debug] event_del: 0x7f70dc000df0 (fd -1), callback 0xd56130
[debug] ../event.c: asked to terminate loop.
[debug] event_add: event: 0x7f70d4000df0 (fd -1),    EV_TIMEOUT call 0xd56130
[debug] event_add: event 0x7f70d4000df0, timeout in 0 seconds 99993 useconds, call 0xd56130
[debug] ../poll.c: poll reports 1
[debug] event_active: 0x1b094c0 (fd 5), res 2, callback 0x7f710f1d5f10
[debug] event_process_active: event: 0x1b094c0, EV_READ   call 0x7f710f1d5f10
[debug] timeout_next: event: 0x7f70d4000df0, in 0 seconds, 99993 useconds
[debug] ../poll.c: poll reports 0
[debug] event_del: 0x7f70d4000df0 (fd -1), callback 0xd56130
[debug] timeout_process: event: 0x7f70d4000df0, call 0xd56130
[debug] event_active: 0x7f70d4000df0 (fd -1), res 1, callback 0xd56130
[debug] event_del: 0x7f70d4000df0 (fd -1), callback 0xd56130
[debug] event_process_active: event: 0x7f70d4000df0,    call 0xd56130
[debug] event_del: 0x7f70d4000df0 (fd -1), callback 0xd56130
[debug] ../event.c: asked to terminate loop.
[debug] event_add: event: 0x7f70d8000df0 (fd -1),    EV_TIMEOUT call 0xd56130
[debug] event_add: event 0x7f70d8000df0, timeout in 0 seconds 99993 useconds, call 0xd56130
[debug] ../poll.c: poll reports 1
[debug] event_active: 0x1b094c0 (fd 5), res 2, callback 0x7f710f1d5f10
[debug] event_process_active: event: 0x1b094c0, EV_READ   call 0x7f710f1d5f10
[debug] timeout_next: event: 0x7f70d8000df0, in 0 seconds, 99993 useconds
[debug] ../poll.c: poll reports 0
[debug] event_del: 0x7f70d8000df0 (fd -1), callback 0xd56130
[debug] timeout_process: event: 0x7f70d8000df0, call 0xd56130
[debug] event_active: 0x7f70d8000df0 (fd -1), res 1, callback 0xd56130
[debug] event_del: 0x7f70d8000df0 (fd -1), callback 0xd56130
[debug] event_process_active: event: 0x7f70d8000df0,    call 0xd56130
[debug] event_del: 0x7f70d8000df0 (fd -1), callback 0xd56130
[debug] ../event.c: asked to terminate loop.
[debug] event_add: event: 0x7f70cc000df0 (fd -1),    EV_TIMEOUT call 0xd56130
[debug] event_add: event 0x7f70cc000df0, timeout in 0 seconds 99992 useconds, call 0xd56130
[debug] ../poll.c: poll reports 1
[debug] event_active: 0x1b094c0 (fd 5), res 2, callback 0x7f710f1d5f10
[debug] event_process_active: event: 0x1b094c0, EV_READ   call 0x7f710f1d5f10
[debug] timeout_next: event: 0x7f70cc000df0, in 0 seconds, 99992 useconds
WARNING: Logging before InitGoogleLogging() is written to STDERR
I0214 16:19:31.610394  6918 openssl.cpp:504] CA file path is unspecified! NOTE: Set CA file path with LIBPROCESS_SSL_CA_FILE=<filepath>
I0214 16:19:31.610416  6918 openssl.cpp:509] CA directory path unspecified! NOTE: Set CA directory path with LIBPROCESS_SSL_CA_DIR=<dirpath>
I0214 16:19:31.610421  6918 openssl.cpp:514] Will not verify peer certificate!
NOTE: Set LIBPROCESS_SSL_VERIFY_CERT=1 to enable peer certificate verification
I0214 16:19:31.610426  6918 openssl.cpp:520] Will only verify peer certificate if presented!
NOTE: Set LIBPROCESS_SSL_REQUIRE_CERT=1 to require peer certificate verification
[debug] event_add: event: 0x1b37b28 (fd 7), EV_READ    call 0x7f710f1dfb50
[debug] ../poll.c: poll reports 1
[debug] event_active: 0x1b094c0 (fd 5), res 2, callback 0x7f710f1d5f10
[debug] event_process_active: event: 0x1b094c0, EV_READ   call 0x7f710f1d5f10
[debug] timeout_next: event: 0x7f70cc000df0, in 0 seconds, 87992 useconds
WARNING: Logging before InitGoogleLogging() is written to STDERR
I0214 16:19:31.617607  6932 openssl.cpp:504] CA file path is unspecified! NOTE: Set CA file path with LIBPROCESS_SSL_CA_FILE=<filepath>
I0214 16:19:31.617655  6932 openssl.cpp:509] CA directory path unspecified! NOTE: Set CA directory path with LIBPROCESS_SSL_CA_DIR=<dirpath>
I0214 16:19:31.617660  6932 openssl.cpp:514] Will not verify peer certificate!
NOTE: Set LIBPROCESS_SSL_VERIFY_CERT=1 to enable peer certificate verification
I0214 16:19:31.617664  6932 openssl.cpp:520] Will only verify peer certificate if presented!
NOTE: Set LIBPROCESS_SSL_REQUIRE_CERT=1 to require peer certificate verification
[debug] event_add: event: 0x2629700 (fd 5), EV_READ    call 0x7fb7eeefaf10
[debug] ../event.c: no events registered. # This line repeats 26 times.
...
[debug] event_add: event: 0x262afa8 (fd 6), EV_READ    call 0x7fb7eef04b50
[debug] event_add: event: 0x7fb7b4000df0 (fd -1),    EV_TIMEOUT call 0x69e5b0
[debug] event_add: event 0x7fb7b4000df0, timeout in 0 seconds 99993 useconds, call 0x69e5b0
[debug] ../poll.c: poll reports 1
[debug] event_active: 0x2629700 (fd 5), res 2, callback 0x7fb7eeefaf10
[debug] event_process_active: event: 0x2629700, EV_READ   call 0x7fb7eeefaf10
[debug] timeout_next: event: 0x7fb7b4000df0, in 0 seconds, 99993 useconds
[debug] event_add: event: 0x2635e90 (fd 7),  EV_WRITE   call 0x7fb7eef0ac30
[debug] ../poll.c: poll reports 1
[debug] event_active: 0x2629700 (fd 5), res 2, callback 0x7fb7eeefaf10
[debug] event_process_active: event: 0x2629700, EV_READ   call 0x7fb7eeefaf10
[debug] timeout_next: event: 0x7fb7b4000df0, in 0 seconds, 99993 useconds
[debug] ../poll.c: poll reports 1
[debug] event_active: 0x2635e90 (fd 7), res 4, callback 0x7fb7eef0ac30
[debug] event_process_active: event: 0x2635e90,  EV_WRITE  call 0x7fb7eef0ac30
[debug] event_del: 0x2635e10 (fd 7), callback 0x7fb7eef0ac30
[debug] event_del: 0x2635e90 (fd 7), callback 0x7fb7eef0ac30
[debug] ../event.c: asked to terminate loop.
[debug] timeout_next: event: 0x7fb7b4000df0, in 0 seconds, 99993 useconds
[debug] event_active: 0x2634160 (fd -1), res 1, callback 0x69dec0
[debug] ../poll.c: poll reports 1
[debug] event_active: 0x2629700 (fd 5), res 2, callback 0x7fb7eeefaf10
[debug] event_del: 0x2634160 (fd -1), callback 0x69dec0
[debug] event_process_active: event: 0x2634160,    call 0x69dec0
[debug] event_del: 0x2634160 (fd -1), callback 0x69dec0
[debug] event_del: 0x2635e10 (fd 7), callback 0x7fb7eef0ac30
[debug] event_del: 0x2635e90 (fd 7), callback 0x7fb7eef0ac30
[debug] event_add: event: 0x2635e90 (fd 7),  EV_WRITE   call 0x7fb7eef0ac30
[debug] event_add: event: 0x2635e90 (fd 7),  EV_WRITE   call 0x7fb7eef0ac30
[debug] event_process_active: event: 0x2629700, EV_READ   call 0x7fb7eeefaf10
[debug] ../event.c: asked to terminate loop.
[debug] timeout_next: event: 0x7fb7b4000df0, in 0 seconds, 99993 useconds
[debug] ../poll.c: poll reports 1
[debug] ../poll.c: poll reports 1
[debug] event_active: 0x2635e90 (fd 7), res 4, callback 0x7fb7eef0ac30
[debug] event_active: 0x1b37b28 (fd 7), res 2, callback 0x7f710f1dfb50
[debug] event_process_active: event: 0x2635e90,  EV_WRITE  call 0x7fb7eef0ac30
[debug] event_process_active: event: 0x1b37b28, EV_READ   call 0x7f710f1dfb50
[debug] event_del: 0x2635e10 (fd 7), callback 0x7fb7eef0ac30
[debug] event_del: 0x2635e90 (fd 7), callback 0x7fb7eef0ac30
[debug] event_process_active: event_callback 0x2635fa0, closure 3, call 0x7fb7eeee5180
[debug] event_add: event: 0x7f70fc001a60 (fd 8),  EV_WRITE   call 0x7f710f1e5c30
[debug] ../event.c: 3 events finalizing
[debug] event_del: 0x2635e10 (fd 7), callback 0x7fb7eef0ac30
[debug] event_del: 0x2635e90 (fd 7), callback 0x7fb7eef0ac30
[debug] ../event.c: asked to terminate loop.
[debug] event_process_active: event_callback 0x2635fa0, closure 4, call 0x7fb7eeee61f0
[debug] timeout_next: event: 0x7f70cc000df0, in 0 seconds, 79992 useconds
[debug] ../poll.c: poll reports 1
[debug] ../event.c: asked to terminate loop.
[debug] event_active: 0x7f70fc001a60 (fd 8), res 4, callback 0x7f710f1e5c30
[debug] timeout_next: event: 0x7fb7b4000df0, in 0 seconds, 99993 useconds
[debug] event_process_active: event: 0x7f70fc001a60,  EV_WRITE  call 0x7f710f1e5c30
[debug] event_del: 0x7f70fc001a60 (fd 8), callback 0x7f710f1e5c30
[debug] event_add: event: 0x7f70fc0019e0 (fd 8), EV_READ    call 0x7f710f1e5c30
[debug] ../event.c: asked to terminate loop.
[debug] timeout_next: event: 0x7f70cc000df0, in 0 seconds, 79992 useconds
[debug] event_active: 0x26386d0 (fd -1), res 1, callback 0x69dec0
[debug] ../poll.c: poll reports 1
[debug] event_active: 0x2629700 (fd 5), res 2, callback 0x7fb7eeefaf10
[debug] event_del: 0x26386d0 (fd -1), callback 0x69dec0
[debug] event_process_active: event: 0x26386d0,    call 0x69dec0
[debug] event_del: 0x26386d0 (fd -1), callback 0x69dec0
[debug] ../poll.c: poll reports 0
[debug] event_del: 0x7f70cc000df0 (fd -1), callback 0xd56130
[debug] timeout_process: event: 0x7f70cc000df0, call 0xd56130
[debug] event_active: 0x7f70cc000df0 (fd -1), res 1, callback 0xd56130
[debug] event_del: 0x7f70cc000df0 (fd -1), callback 0xd56130
[debug] event_process_active: event: 0x7f70cc000df0,    call 0xd56130
[debug] event_add: event: 0x7f70d8000df0 (fd -1),    EV_TIMEOUT call 0xd56130
[debug] event_add: event 0x7f70d8000df0, timeout in 0 seconds 29 useconds, call 0xd56130
[debug] event_del: 0x7f70cc000df0 (fd -1), callback 0xd56130
[debug] ../event.c: asked to terminate loop.
[debug] timeout_next: event: 0x7f70d8000df0, in 0 seconds, 29 useconds
[debug] ../poll.c: poll reports 0
[debug] timeout_next: event: 0x7f70d8000df0, in 0 seconds, 29 useconds
[debug] ../poll.c: poll reports 0
[debug] timeout_next: event: 0x7f70d8000df0, in 0 seconds, 29 useconds
[debug] ../poll.c: poll reports 0
[debug] event_del: 0x7f70d8000df0 (fd -1), callback 0xd56130
[debug] timeout_process: event: 0x7f70d8000df0, call 0xd56130
[debug] event_active: 0x7f70d8000df0 (fd -1), res 1, callback 0xd56130
[debug] event_del: 0x7f70d8000df0 (fd -1), callback 0xd56130
[debug] event_process_active: event: 0x7f70d8000df0,    call 0xd56130
[debug] event_add: event: 0x7f70cc000df0 (fd -1),    EV_TIMEOUT call 0xd56130
[debug] event_add: event 0x7f70cc000df0, timeout in 14 seconds 908605 useconds, call 0xd56130
[debug] event_del: 0x7f70d8000df0 (fd -1), callback 0xd56130
[debug] ../event.c: asked to terminate loop.
[debug] timeout_next: event: 0x7f70cc000df0, in 14 seconds, 908605 useconds
[debug] event_add: event: 0x7f70d0000df0 (fd -1),    EV_TIMEOUT call 0xd56130
[debug] event_add: event 0x7f70d0000df0, timeout in 0 seconds 99990 useconds, call 0xd56130
[debug] ../poll.c: poll reports 1
[debug] event_active: 0x1b094c0 (fd 5), res 2, callback 0x7f710f1d5f10
[debug] event_process_active: event: 0x1b094c0, EV_READ   call 0x7f710f1d5f10
[debug] timeout_next: event: 0x7f70d0000df0, in 0 seconds, 99990 useconds
[debug] ../poll.c: poll reports 1
[debug] event_active: 0x7f70fc0019e0 (fd 8), res 2, callback 0x7f710f1e5c30
[debug] event_process_active: event: 0x7f70fc0019e0, EV_READ   call 0x7f710f1e5c30
[debug] event_del: 0x7f70fc0019e0 (fd 8), callback 0x7f710f1e5c30
[debug] event_del: 0x7f70fc001a60 (fd 8), callback 0x7f710f1e5c30
[debug] ../event.c: 3 events finalizing
[debug] event_del: 0x7f70fc0019e0 (fd 8), callback 0x7f710f1e5c30
[debug] event_del: 0x7f70fc001a60 (fd 8), callback 0x7f710f1e5c30
[debug] event_process_active: event: 0x7f70fc0019e0, EV_READ   call 0x7f710f1c11f0
[debug] ../event.c: asked to terminate loop.
[debug] timeout_next: event: 0x7f70d0000df0, in 0 seconds, 71990 useconds
Error was 2
Error was 5
../../../3rdparty/libprocess/src/tests/ssl_tests.cpp:255: Failure
(socket).failure(): Failed accept: connection error: error:00000000:lib(0):func(0):reason(0)
[debug] event_active: 0x1b36240 (fd -1), res 1, callback 0xd55a40
[debug] ../poll.c: poll reports 1
[debug] event_active: 0x1b094c0 (fd 5), res 2, callback 0x7f710f1d5f10
[debug] event_del: 0x1b36240 (fd -1), callback 0xd55a40
[debug] event_process_active: event: 0x1b36240,    call 0xd55a40
[debug] event_del: 0x1b36240 (fd -1), callback 0xd55a40
[debug] event_del: 0x1b37b28 (fd 7), callback 0x7f710f1dfb50
[debug] event_process_active: event: 0x1b094c0, EV_READ   call 0x7f710f1d5f10
[debug] ../event.c: asked to terminate loop.
[debug] timeout_next: event: 0x7f70d0000df0, in 0 seconds, 71990 useconds
[  FAILED  ] SSLTest.SSLSocket (434 ms)
[----------] 1 test from SSLTest (434 ms total)

[----------] Global test environment tear-down
[==========] 1 test from 1 test case ran. (435 ms total)
[  PASSED  ] 0 tests.
[  FAILED  ] 1 test, listed below:
[  FAILED  ] SSLTest.SSLSocket

 1 FAILED TEST
[debug] event_active: 0x1b39820 (fd -1), res 1, callback 0xd55a40
[debug] ../poll.c: poll reports 1
[debug] event_active: 0x1b094c0 (fd 5), res 2, callback 0x7f710f1d5f10
[debug] event_del: 0x1b39820 (fd -1), callback 0xd55a40
[debug] event_process_active: event: 0x1b39820,    call 0xd55a40
[debug] event_del: 0x1b39820 (fd -1), callback 0xd55a40
[debug] event_active: 0x1afbcc0 (fd 6), res 2, callback 0xd58520
[debug] event_process_active: event: 0x1b094c0, EV_READ   call 0x7f710f1d5f10
[debug] event_del: 0x1afbcc0 (fd 6), callback 0xd58520
[debug] event_process_active: event: 0x1afbcc0, EV_READ   call 0xd58520
I0214 16:19:31.733451  6931 process.cpp:929] Stopped the socket accept loop
[debug] event_del: 0x1afbcc0 (fd 6), callback 0xd58520
[debug] ../event.c: asked to terminate loop.
[debug] timeout_next: event: 0x7f70d0000df0, in 0 seconds, 71990 useconds
[debug] event_active: 0x1b37bc0 (fd -1), res 1, callback 0x7f710f1cee30
[debug] ../poll.c: poll reports 1
[debug] event_active: 0x1b094c0 (fd 5), res 2, callback 0x7f710f1d5f10
[debug] event_del: 0x1b37bc0 (fd -1), callback 0x7f710f1cee30
[debug] event_process_active: event: 0x1b37bc0,    call 0x7f710f1cee30
[debug] event_process_active: event: 0x1b094c0, EV_READ   call 0x7f710f1d5f10
[debug] ../event.c: asked to terminate loop.
```

I just removed some repeated lines, and these lines:

```
Error was 2
Error was 5
```

which seemed to match the output from `ltrace`***********************************************************************
To unsubscribe, send an e-mail to majordomo@xxxxxxxxxxxxx with
unsubscribe libevent-users    in the body.