Hi Azat > On 4. Feb 2018, at 20:49, Azat Khuzhin <a3at.m...@gmail.com> 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 majord...@freehaven.net 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 majord...@freehaven.net with unsubscribe libevent-users in the body.