You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@httpd.apache.org by Stefan Eissing <st...@greenbytes.de> on 2021/03/08 11:38:37 UTC
event.c assert failed
Hi Yann,
I see an crash and log entries:
[mpm_event:error] [pid 28031:tid 4595580416] (9)Bad file descriptor: AH00468: error closing socket
[core:crit] [pid 28031:tid 4595580416] AH00102: [Mon Mar 08 11:32:48 2021] file event.c, line 565, assertion "0" failed
when a client opens a connection and closes it right away, not sending anything. My tls modules sees EOF in the in filter and returns it, setting c->aborted = 1.
I am not sure what the failed assertion is about. Is there a double close of the socket? Seems I do handle the connection state in such a case not quite as it is expected.
- Stefan
Re: event.c assert failed
Posted by Stefan Eissing <st...@greenbytes.de>.
FTR: this has been resolved by fixing my own mistake. ;-)
> Am 08.03.2021 um 13:59 schrieb Stefan Eissing <st...@greenbytes.de>:
>
>
>
>> Am 08.03.2021 um 13:49 schrieb Yann Ylavic <yl...@gmail.com>:
>>
>> Hi Stefan,
>>
>>>
>>> I see an crash and log entries:
>>>
>>> [mpm_event:error] [pid 28031:tid 4595580416] (9)Bad file descriptor: AH00468: error closing socket
>>> [core:crit] [pid 28031:tid 4595580416] AH00102: [Mon Mar 08 11:32:48 2021] file event.c, line 565, assertion "0" failed
>>>
>>> when a client opens a connection and closes it right away, not sending anything. My tls modules sees EOF in the in filter and returns it, setting c->aborted = 1.
>>>
>>> I am not sure what the failed assertion is about. Is there a double close of the socket? Seems I do handle the connection state in such a case not quite as it is expected.
>>
>> Hmm, if you breakpoint on apr_socket_close(), do you see it called
>> multiple times?
>> (I wonder if it could be the ones in core_create_conn() if/when
>> apr_socket_addr_get() fails..).
>
> Seems to happen on server shutdown and it looks as if the socket is in lingering close. I try to get more info what is happening...
> ...
> [Mon Mar 08 13:56:49.158001 2021] [tls:trace3] [pid 78522:tid 123145423650816] tls_filter.c(648): [client 127.0.0.1:53402] bb_dump(132): filter_conn_output(FLUSH EOC)
> [Mon Mar 08 13:56:49.158004 2021] [tls:trace2] [pid 78522:tid 123145423650816] tls_filter.c(724): (53)Software caused connection abort: [client 127.0.0.1:53402] tls_filter_conn_output: passed 0 bytes
> [Mon Mar 08 13:56:49.162077 2021] [core:trace3] [pid 78521:tid 123145421504512] request.c(361): [client 127.0.0.1:53403] request authorized without authentication by access_checker_ex hook: /
> [Mon Mar 08 13:56:49.273972 2021] [core:trace4] [pid 78518:tid 4427951616] mpm_common.c(558): mpm child 78527 (gen 0/slot 3) started
> [Mon Mar 08 13:56:49.274139 2021] [mpm_event:error] [pid 78522:tid 4427951616] (9)Bad file descriptor: AH00468: error closing socket
> [Mon Mar 08 13:56:49.274616 2021] [core:crit] [pid 78522:tid 4427951616] AH00102: [Mon Mar 08 12:56:49 2021] file event.c, line 565, assertion "0" failed
> [Mon Mar 08 13:56:49.275632 2021] [mpm_event:debug] [pid 78527:tid 123145420967936] event.c(2611): AH02471: start_threads: Using kqueue (wakeable)
> [Mon Mar 08 13:56:49.291162 2021] [core:trace4] [pid 78518:tid 4427951616] mpm_common.c(558): mpm child 78520 (gen 0/slot 0) exited
> [Mon Mar 08 13:56:49.291199 2021] [core:trace4] [pid 78518:tid 4427951616] mpm_common.c(558): mpm child 78521 (gen 0/slot 1) exited
> [Mon Mar 08 13:56:49.291213 2021] [core:notice] [pid 78518:tid 4427951616] AH00052: child pid 78522 exit signal Abort trap (6)
> [Mon Mar 08 13:56:49.291217 2021] [core:trace4] [pid 78518:tid 4427951616] mpm_common.c(558): mpm child 78522 (gen 0/slot 2) exited
> [Mon Mar 08 13:56:49.291222 2021] [core:trace4] [pid 78518:tid 4427951616] mpm_common.c(558): mpm child 78527 (gen 0/slot 3) exited
> [Mon Mar 08 13:56:49.291342 2021] [core:info] [pid 78518:tid 4427951616] AH00096: removed PID file /Users/sei/projects/abetterinternet/mod_tls/test/gen/apache/logs/httpd.pid (pid=78518)
> [Mon Mar 08 13:56:49.291359 2021] [mpm_event:notice] [pid 78518:tid 4427951616] AH00491: caught SIGTERM, shutting down
> [Mon Mar 08 13:56:49.301655 2021] [core:trace4] [pid 78518] mpm_common.c(454): end of generation 0
>
Re: event.c assert failed
Posted by Stefan Eissing <st...@greenbytes.de>.
> Am 08.03.2021 um 13:49 schrieb Yann Ylavic <yl...@gmail.com>:
>
> Hi Stefan,
>
>>
>> I see an crash and log entries:
>>
>> [mpm_event:error] [pid 28031:tid 4595580416] (9)Bad file descriptor: AH00468: error closing socket
>> [core:crit] [pid 28031:tid 4595580416] AH00102: [Mon Mar 08 11:32:48 2021] file event.c, line 565, assertion "0" failed
>>
>> when a client opens a connection and closes it right away, not sending anything. My tls modules sees EOF in the in filter and returns it, setting c->aborted = 1.
>>
>> I am not sure what the failed assertion is about. Is there a double close of the socket? Seems I do handle the connection state in such a case not quite as it is expected.
>
> Hmm, if you breakpoint on apr_socket_close(), do you see it called
> multiple times?
> (I wonder if it could be the ones in core_create_conn() if/when
> apr_socket_addr_get() fails..).
Seems to happen on server shutdown and it looks as if the socket is in lingering close. I try to get more info what is happening...
...
[Mon Mar 08 13:56:49.158001 2021] [tls:trace3] [pid 78522:tid 123145423650816] tls_filter.c(648): [client 127.0.0.1:53402] bb_dump(132): filter_conn_output(FLUSH EOC)
[Mon Mar 08 13:56:49.158004 2021] [tls:trace2] [pid 78522:tid 123145423650816] tls_filter.c(724): (53)Software caused connection abort: [client 127.0.0.1:53402] tls_filter_conn_output: passed 0 bytes
[Mon Mar 08 13:56:49.162077 2021] [core:trace3] [pid 78521:tid 123145421504512] request.c(361): [client 127.0.0.1:53403] request authorized without authentication by access_checker_ex hook: /
[Mon Mar 08 13:56:49.273972 2021] [core:trace4] [pid 78518:tid 4427951616] mpm_common.c(558): mpm child 78527 (gen 0/slot 3) started
[Mon Mar 08 13:56:49.274139 2021] [mpm_event:error] [pid 78522:tid 4427951616] (9)Bad file descriptor: AH00468: error closing socket
[Mon Mar 08 13:56:49.274616 2021] [core:crit] [pid 78522:tid 4427951616] AH00102: [Mon Mar 08 12:56:49 2021] file event.c, line 565, assertion "0" failed
[Mon Mar 08 13:56:49.275632 2021] [mpm_event:debug] [pid 78527:tid 123145420967936] event.c(2611): AH02471: start_threads: Using kqueue (wakeable)
[Mon Mar 08 13:56:49.291162 2021] [core:trace4] [pid 78518:tid 4427951616] mpm_common.c(558): mpm child 78520 (gen 0/slot 0) exited
[Mon Mar 08 13:56:49.291199 2021] [core:trace4] [pid 78518:tid 4427951616] mpm_common.c(558): mpm child 78521 (gen 0/slot 1) exited
[Mon Mar 08 13:56:49.291213 2021] [core:notice] [pid 78518:tid 4427951616] AH00052: child pid 78522 exit signal Abort trap (6)
[Mon Mar 08 13:56:49.291217 2021] [core:trace4] [pid 78518:tid 4427951616] mpm_common.c(558): mpm child 78522 (gen 0/slot 2) exited
[Mon Mar 08 13:56:49.291222 2021] [core:trace4] [pid 78518:tid 4427951616] mpm_common.c(558): mpm child 78527 (gen 0/slot 3) exited
[Mon Mar 08 13:56:49.291342 2021] [core:info] [pid 78518:tid 4427951616] AH00096: removed PID file /Users/sei/projects/abetterinternet/mod_tls/test/gen/apache/logs/httpd.pid (pid=78518)
[Mon Mar 08 13:56:49.291359 2021] [mpm_event:notice] [pid 78518:tid 4427951616] AH00491: caught SIGTERM, shutting down
[Mon Mar 08 13:56:49.301655 2021] [core:trace4] [pid 78518] mpm_common.c(454): end of generation 0
Re: event.c assert failed
Posted by Yann Ylavic <yl...@gmail.com>.
Hi Stefan,
>
> I see an crash and log entries:
>
> [mpm_event:error] [pid 28031:tid 4595580416] (9)Bad file descriptor: AH00468: error closing socket
> [core:crit] [pid 28031:tid 4595580416] AH00102: [Mon Mar 08 11:32:48 2021] file event.c, line 565, assertion "0" failed
>
> when a client opens a connection and closes it right away, not sending anything. My tls modules sees EOF in the in filter and returns it, setting c->aborted = 1.
>
> I am not sure what the failed assertion is about. Is there a double close of the socket? Seems I do handle the connection state in such a case not quite as it is expected.
Hmm, if you breakpoint on apr_socket_close(), do you see it called
multiple times?
(I wonder if it could be the ones in core_create_conn() if/when
apr_socket_addr_get() fails..).
Cheers;
Yann.