[Author Prev][Author Next][Thread Prev][Thread Next][Author Index][Thread Index]

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


On 14. Feb 2018, at 16:52, Azat Khuzhin <a3at.mail@xxxxxxxxx> wrote:

On Wed, Feb 14, 2018 at 04:33:07PM +0100, Alexander Rojas wrote:
Really hard to achieve, I was playing around and failed to get a minimal reproducer.

Maybe you have a container with all this stuff (+debug symbols) ?
So that I can play in it.

I’ll try to build that soon.


[debug] ../event.c: asked to terminate loop.

H, who asked this?

which is called in teardown. I don’t see any other place which calls `event_base_loopexit()`


[debug] timeout_next: event: 0x7f70d0000df0, in 0 seconds, 71990 useconds
Error was 2
Error was 5

So:
- 2 is SSL_ERROR_WANT_READ
- 5 is SSL_ERROR_SYSCALL
(according to openssl/ssl.h)

So can you add printing of errno along with SSL_get_error() in print_err()?

It looks like it got SSL_ERROR_WANT_READ and then tried to read() but
failed, and hence SSL_ERROR_SYSCALL.
***********************************************************************
To unsubscribe, send an e-mail to majordomo@xxxxxxxxxxxxx with
unsubscribe libevent-users    in the body.

I also redirect the output of the forked client, the output is now mixed between
server and client but may be useful:

```
[debug] event_add: event: 0x19804c0 (fd 5), EV_READ    call 0x7ff904576f10
[debug] ../event.c: no events registered.
[debug] event_add: event: 0x1972cc0 (fd 6), EV_READ    call 0xd58520
[debug] event_add: event: 0x7ff8d4000df0 (fd -1),    EV_TIMEOUT call 0xd56130
[debug] event_add: event 0x7ff8d4000df0, timeout in 0 seconds 99990 useconds, call 0xd56130
[debug] ../poll.c: poll reports 1
[debug] event_active: 0x19804c0 (fd 5), res 2, callback 0x7ff904576f10
[debug] event_process_active: event: 0x19804c0, EV_READ   call 0x7ff904576f10
[debug] timeout_next: event: 0x7ff8d4000df0, 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: 0x7ff8d4000df0 (fd -1), callback 0xd56130
[debug] timeout_process: event: 0x7ff8d4000df0, call 0xd56130
[debug] event_active: 0x7ff8d4000df0 (fd -1), res 1, callback 0xd56130
[debug] event_del: 0x7ff8d4000df0 (fd -1), callback 0xd56130
[debug] event_process_active: event: 0x7ff8d4000df0,    call 0xd56130
[debug] event_del: 0x7ff8d4000df0 (fd -1), callback 0xd56130
[debug] ../event.c: asked to terminate loop.
[debug] event_add: event: 0x7ff8cc000df0 (fd -1),    EV_TIMEOUT call 0xd56130
[debug] event_add: event 0x7ff8cc000df0, timeout in 0 seconds 99992 useconds, call 0xd56130
[debug] ../poll.c: poll reports 1
[debug] event_active: 0x19804c0 (fd 5), res 2, callback 0x7ff904576f10
[debug] event_process_active: event: 0x19804c0, EV_READ   call 0x7ff904576f10
[debug] timeout_next: event: 0x7ff8cc000df0, in 0 seconds, 99992 useconds
WARNING: Logging before InitGoogleLogging() is written to STDERR
I0214 16:49:48.387568  7747 openssl.cpp:504] CA file path is unspecified! NOTE: Set CA file path with LIBPROCESS_SSL_CA_FILE=<filepath>
I0214 16:49:48.387590  7747 openssl.cpp:509] CA directory path unspecified! NOTE: Set CA directory path with LIBPROCESS_SSL_CA_DIR=<dirpath>
I0214 16:49:48.387595  7747 openssl.cpp:514] Will not verify peer certificate!
NOTE: Set LIBPROCESS_SSL_VERIFY_CERT=1 to enable peer certificate verification
I0214 16:49:48.387600  7747 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: 0x19aeb18 (fd 7), EV_READ    call 0x7ff904580b50
[debug] ../poll.c: poll reports 1
[debug] event_active: 0x19804c0 (fd 5), res 2, callback 0x7ff904576f10
[debug] event_process_active: event: 0x19804c0, EV_READ   call 0x7ff904576f10
[debug] timeout_next: event: 0x7ff8cc000df0, in 0 seconds, 27992 useconds
WARNING: Logging before InitGoogleLogging() is written to STDERR
I0214 16:49:48.394479  7761 openssl.cpp:504] CA file path is unspecified! NOTE: Set CA file path with LIBPROCESS_SSL_CA_FILE=<filepath>
I0214 16:49:48.394526  7761 openssl.cpp:509] CA directory path unspecified! NOTE: Set CA directory path with LIBPROCESS_SSL_CA_DIR=<dirpath>
I0214 16:49:48.394531  7761 openssl.cpp:514] Will not verify peer certificate!
NOTE: Set LIBPROCESS_SSL_VERIFY_CERT=1 to enable peer certificate verification
I0214 16:49:48.394534  7761 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: 0x2c56700 (fd 5), EV_READ    call 0x7f47e2940f10
[debug] ../event.c: no events registered.
[debug] ../event.c: no events registered.
[debug] event_add: event: 0x2c57fb8 (fd 6), EV_READ    call 0x7f47e294ab50
[debug] event_add: event: 0x7f47b0000df0 (fd -1),    EV_TIMEOUT call 0x69e5b0
[debug] event_add: event 0x7f47b0000df0, timeout in 0 seconds 99992 useconds, call 0x69e5b0
[debug] ../poll.c: poll reports 1
[debug] event_active: 0x2c56700 (fd 5), res 2, callback 0x7f47e2940f10
[debug] event_process_active: event: 0x2c56700, EV_READ   call 0x7f47e2940f10
[debug] timeout_next: event: 0x7f47b0000df0, in 0 seconds, 99992 useconds
[==========] Running 1 test from 1 test case.
[----------] Global test environment set-up.
[----------] 1 test from SSLClientTest
[ RUN      ] SSLClientTest.client
[debug] event_add: event: 0x2c62ea0 (fd 7),  EV_WRITE   call 0x7f47e2950c30
[debug] ../poll.c: poll reports 1
[debug] event_active: 0x2c56700 (fd 5), res 2, callback 0x7f47e2940f10
[debug] event_process_active: event: 0x2c56700, EV_READ   call 0x7f47e2940f10
[debug] timeout_next: event: 0x7f47b0000df0, in 0 seconds, 99992 useconds
[debug] ../poll.c: poll reports 1
[debug] event_active: 0x2c62ea0 (fd 7), res 4, callback 0x7f47e2950c30
[debug] event_process_active: event: 0x2c62ea0,  EV_WRITE  call 0x7f47e2950c30
[debug] event_del: 0x2c62e20 (fd 7), callback 0x7f47e2950c30
[debug] event_del: 0x2c62ea0 (fd 7), callback 0x7f47e2950c30
[debug] ../event.c: asked to terminate loop.
[debug] timeout_next: event: 0x7f47b0000df0, in 0 seconds, 99992 useconds
[debug] event_active: 0x2c61170 (fd -1), res 1, callback 0x69dec0
[debug] ../poll.c: poll reports 1
[debug] event_active: 0x2c56700 (fd 5), res 2, callback 0x7f47e2940f10
[debug] event_del: 0x2c61170 (fd -1), callback 0x69dec0
[debug] event_process_active: event: 0x2c61170,    call 0x69dec0
[debug] event_del: 0x2c61170 (fd -1), callback 0x69dec0
[debug] event_del: 0x2c62e20 (fd 7), callback 0x7f47e2950c30
[debug] event_del: 0x2c62ea0 (fd 7), callback 0x7f47e2950c30
[debug] event_add: event: 0x2c62ea0 (fd 7),  EV_WRITE   call 0x7f47e2950c30
[debug] event_add: event: 0x2c62ea0 (fd 7),  EV_WRITE   call 0x7f47e2950c30
[debug] event_process_active: event: 0x2c56700, EV_READ   call 0x7f47e2940f10
[debug] ../event.c: asked to terminate loop.
[debug] ../poll.c: poll reports 1
[debug] timeout_next: event: 0x7f47b0000df0, in 0 seconds, 99992 useconds
[debug] event_active: 0x19aeb18 (fd 7), res 2, callback 0x7ff904580b50
[debug] ../poll.c: poll reports 1
[debug] event_active: 0x2c62ea0 (fd 7), res 4, callback 0x7f47e2950c30
[debug] event_process_active: event: 0x19aeb18, EV_READ   call 0x7ff904580b50
[debug] event_process_active: event: 0x2c62ea0,  EV_WRITE  call 0x7f47e2950c30
[debug] event_del: 0x2c62e20 (fd 7), callback 0x7f47e2950c30
[debug] event_del: 0x2c62ea0 (fd 7), callback 0x7f47e2950c30
[debug] event_process_active: event_callback 0x2c62fb0, closure 3, call 0x7f47e292b180
[debug] event_add: event: 0x7ff8f0001aa0 (fd 8),  EV_WRITE   call 0x7ff904586c30
[debug] ../event.c: 3 events finalizing
[debug] event_del: 0x2c62e20 (fd 7), callback 0x7f47e2950c30
[debug] ../event.c: asked to terminate loop.
[debug] event_del: 0x2c62ea0 (fd 7), callback 0x7f47e2950c30
[debug] timeout_next: event: 0x7ff8cc000df0, in 0 seconds, 15992 useconds
[debug] event_process_active: event_callback 0x2c62fb0, closure 4, call 0x7f47e292c1f0
[debug] ../poll.c: poll reports 1
[debug] event_active: 0x7ff8f0001aa0 (fd 8), res 4, callback 0x7ff904586c30
[debug] ../event.c: asked to terminate loop.
[debug] event_process_active: event: 0x7ff8f0001aa0,  EV_WRITE  call 0x7ff904586c30
[debug] timeout_next: event: 0x7f47b0000df0, in 0 seconds, 99992 useconds
[debug] event_del: 0x7ff8f0001aa0 (fd 8), callback 0x7ff904586c30
[debug] event_add: event: 0x7ff8f0001a20 (fd 8), EV_READ    call 0x7ff904586c30
[debug] ../event.c: asked to terminate loop.
[debug] timeout_next: event: 0x7ff8cc000df0, in 0 seconds, 15992 useconds
Error was 5
Error was 1
ssl23 doing session id reuse in SSL routines ssl23_connect
../../../3rdparty/libprocess/src/tests/ssl_client.cpp:151: Failure
(connect).failure(): Failed connect: connection closed
[debug] event_active: 0x2c656e0 (fd -1), res 1, callback 0x69dec0
[debug] ../poll.c: poll reports 1
[debug] event_active: 0x2c56700 (fd 5), res 2, callback 0x7f47e2940f10
[debug] event_del: 0x2c656e0 (fd -1), callback 0x69dec0
[debug] event_process_active: event: 0x2c656e0,    call 0x69dec0
[debug] event_del: 0x2c656e0 (fd -1), callback 0x69dec0
[debug] ../poll.c: poll reports 0
[debug] event_del: 0x7ff8cc000df0 (fd -1), callback 0xd56130
[debug] timeout_process: event: 0x7ff8cc000df0, call 0xd56130
[debug] event_active: 0x7ff8cc000df0 (fd -1), res 1, callback 0xd56130
[debug] event_del: 0x7ff8cc000df0 (fd -1), callback 0xd56130
[debug] event_process_active: event: 0x7ff8cc000df0,    call 0xd56130
[debug] event_add: event: 0x7ff8d4000df0 (fd -1),    EV_TIMEOUT call 0xd56130
[debug] event_add: event 0x7ff8d4000df0, timeout in 0 seconds 1155 useconds, call 0xd56130
[debug] event_del: 0x7ff8cc000df0 (fd -1), callback 0xd56130
[debug] ../event.c: asked to terminate loop.
[debug] timeout_next: event: 0x7ff8d4000df0, in 0 seconds, 1155 useconds
[debug] ../poll.c: poll reports 0
[debug] timeout_next: event: 0x7ff8d4000df0, in 0 seconds, 1155 useconds
[debug] ../poll.c: poll reports 0
[debug] event_del: 0x7ff8d4000df0 (fd -1), callback 0xd56130
[debug] timeout_process: event: 0x7ff8d4000df0, call 0xd56130
[debug] event_active: 0x7ff8d4000df0 (fd -1), res 1, callback 0xd56130
[debug] event_del: 0x7ff8d4000df0 (fd -1), callback 0xd56130
[debug] event_process_active: event: 0x7ff8d4000df0,    call 0xd56130
[debug] event_add: event: 0x7ff8cc000df0 (fd -1),    EV_TIMEOUT call 0xd56130
[debug] event_add: event 0x7ff8cc000df0, timeout in 14 seconds 968515 useconds, call 0xd56130
[debug] event_del: 0x7ff8d4000df0 (fd -1), callback 0xd56130
[debug] ../event.c: asked to terminate loop.
[debug] timeout_next: event: 0x7ff8cc000df0, in 14 seconds, 968515 useconds
[debug] event_add: event: 0x7ff8dc000df0 (fd -1),    EV_TIMEOUT call 0xd56130
[debug] event_add: event 0x7ff8dc000df0, timeout in 0 seconds 99990 useconds, call 0xd56130
[debug] ../poll.c: poll reports 1
[debug] event_active: 0x19804c0 (fd 5), res 2, callback 0x7ff904576f10
[debug] event_process_active: event: 0x19804c0, EV_READ   call 0x7ff904576f10
[debug] timeout_next: event: 0x7ff8dc000df0, in 0 seconds, 99990 useconds
[debug] ../poll.c: poll reports 1
[debug] event_active: 0x7ff8f0001a20 (fd 8), res 2, callback 0x7ff904586c30
[debug] event_process_active: event: 0x7ff8f0001a20, EV_READ   call 0x7ff904586c30
[debug] event_del: 0x7ff8f0001a20 (fd 8), callback 0x7ff904586c30
[debug] event_del: 0x7ff8f0001aa0 (fd 8), callback 0x7ff904586c30
[debug] ../event.c: 3 events finalizing
[debug] event_del: 0x7ff8f0001a20 (fd 8), callback 0x7ff904586c30
[debug] event_del: 0x7ff8f0001aa0 (fd 8), callback 0x7ff904586c30
[debug] event_process_active: event: 0x7ff8f0001a20, EV_READ   call 0x7ff9045621f0
[debug] ../event.c: asked to terminate loop.
[debug] timeout_next: event: 0x7ff8dc000df0, in 0 seconds, 3990 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: 0x19ad2c0 (fd -1), res 1, callback 0xd55a40
[debug] ../poll.c: poll reports 1
[debug] event_active: 0x19804c0 (fd 5), res 2, callback 0x7ff904576f10
[debug] event_del: 0x19ad2c0 (fd -1), callback 0xd55a40
[debug] event_process_active: event: 0x19ad2c0,    call 0xd55a40
[debug] event_del: 0x19ad2c0 (fd -1), callback 0xd55a40
[debug] event_del: 0x19aeb18 (fd 7), callback 0x7ff904580b50
[debug] event_process_active: event: 0x19804c0, EV_READ   call 0x7ff904576f10
[debug] ../event.c: asked to terminate loop.
[debug] timeout_next: event: 0x7ff8dc000df0, in 0 seconds, 3990 useconds
[  FAILED  ] SSLTest.SSLSocket (301 ms)
[----------] 1 test from SSLTest (301 ms total)

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

 1 FAILED TEST
[debug] event_active: 0x19b0670 (fd -1), res 1, callback 0xd55a40
[debug] ../poll.c: poll reports 1
[debug] event_active: 0x19804c0 (fd 5), res 2, callback 0x7ff904576f10
[debug] event_del: 0x19b0670 (fd -1), callback 0xd55a40
[debug] event_process_active: event: 0x19b0670,    call 0xd55a40
[debug] event_del: 0x19b0670 (fd -1), callback 0xd55a40
[debug] event_active: 0x1972cc0 (fd 6), res 2, callback 0xd58520
[debug] event_process_active: event: 0x19804c0, EV_READ   call 0x7ff904576f10
[debug] event_del: 0x1972cc0 (fd 6), callback 0xd58520
[debug] event_process_active: event: 0x1972cc0, EV_READ   call 0xd58520
I0214 16:49:48.518049  7760 process.cpp:929] Stopped the socket accept loop
[debug] event_del: 0x1972cc0 (fd 6), callback 0xd58520
[debug] ../event.c: asked to terminate loop.
[debug] timeout_next: event: 0x7ff8dc000df0, in 0 seconds, 3990 useconds
[debug] event_active: 0x19aebb0 (fd -1), res 1, callback 0x7ff90456fe30
[debug] ../poll.c: poll reports 1
[debug] event_active: 0x19804c0 (fd 5), res 2, callback 0x7ff904576f10
[debug] event_del: 0x7ff8dc000df0 (fd -1), callback 0xd56130
[debug] timeout_process: event: 0x7ff8dc000df0, call 0xd56130
[debug] event_active: 0x7ff8dc000df0 (fd -1), res 1, callback 0xd56130
[debug] event_del: 0x19aebb0 (fd -1), callback 0x7ff90456fe30
[debug] event_process_active: event: 0x19aebb0,    call 0x7ff90456fe30
[debug] event_process_active: event: 0x19804c0, EV_READ   call 0x7ff904576f10
[debug] event_del: 0x7ff8dc000df0 (fd -1), callback 0xd56130
[debug] event_process_active: event: 0x7ff8dc000df0,    call 0xd56130
[debug] event_add: event: 0x1972cc0 (fd -1),    EV_TIMEOUT call 0xd56130
[debug] event_add: event 0x1972cc0, timeout in 0 seconds 1468 useconds, call 0xd56130
[debug] event_del: 0x7ff8dc000df0 (fd -1), callback 0xd56130
[debug] ../event.c: asked to terminate loop.

```