This is a classic heisenbug since it is timing related, when you add
more debugging it slows the server down enough that the client can keep
up, write never returns EAGAIN, and the bug disappears, I think...
I see from 2016 people have reported similar failures before ("Subject:
Some test failures in trunk") and they have been seen with prefork too.
I'm afraid I don't understand the dance being done with setaside and
reinstate in the filters. Following the debugging through from the last
ap_pass_brigade from mod_test_pass_brigade -
[Tue Jan 07 13:09:32.090818 2020] [:info] [pid 117876:tid 140235421763328]
[client 127.0.0.1:41112] [mod_test_pass_brigade] wrote 8192 of 8192 bytes
[Tue Jan 07 13:09:32.090821 2020] [:info] [pid 117876:tid 140235421763328]
[client 127.0.0.1:41112] [mod_test_pass_brigade] done writing 10240000 of
10240000 bytes
[Tue Jan 07 13:09:32.090824 2020] [core:trace6] [pid 117876:tid
140235421763328] util_filter.c(1015): [client 127.0.0.1:41112] reinstate full
brigade to full brigade in 'req_core' output filter
[Tue Jan 07 13:09:32.090827 2020] [core:trace8] [pid 117876:tid
140235421763328] util_filter.c(1133): [client 127.0.0.1:41112] brigade
contains: bytes: 49205, non-file bytes: 49205, eor buckets: 1, morphing buckets
: 0
[Tue Jan 07 13:09:32.090829 2020] [core:trace6] [pid 117876:tid
140235421763328] util_filter.c(942): [client 127.0.0.1:41112] setaside full
brigade to empty brigade in 'req_core' output filter
[Tue Jan 07 13:09:32.090835 2020] [core:trace6] [pid 117876:tid
140235421763328] util_filter.c(1015): [client 127.0.0.1:41112] reinstate full
brigade to full brigade in 'core' output filter
>From the above we can see there is 48K of data buffered in one of the
filters. At this point we've passed through:
/* Prepend buckets set aside, if any. */
ap_filter_reinstate_brigade(f, bb, NULL);
if (APR_BRIGADE_EMPTY(bb)) {
return APR_SUCCESS;
}
I then dumped the contents of bb to the error log directly after:
[Tue Jan 07 13:09:32.090837 2020] [core:trace1] [pid 117876:tid
140235421763328] core_filters.c(373): [client 127.0.0.1:41112] sbb: cof -
bucket 0 HEAP length 1654
[Tue Jan 07 13:09:32.090839 2020] [core:trace1] [pid 117876:tid
140235421763328] core_filters.c(373): [client 127.0.0.1:41112] sbb: cof -
bucket 1 IMMORTAL length 2
[Tue Jan 07 13:09:32.090842 2020] [core:trace1] [pid 117876:tid
140235421763328] core_filters.c(373): [client 127.0.0.1:41112] sbb: cof -
bucket 2 FLUSH length 0
[Tue Jan 07 13:09:32.090844 2020] [core:trace1] [pid 117876:tid
140235421763328] core_filters.c(373): [client 127.0.0.1:41112] sbb: cof -
bucket 3 EOC length 0
so the 48K does not make it back to the core output filter and is never
sent.
[Tue Jan 07 13:09:32.090846 2020] [core:trace1] [pid 117876:tid
140235421763328] core_filters.c(655): [client 127.0.0.1:41112] sbb: 2 vectors,
bytes to write 1656
[Tue Jan 07 13:09:32.090849 2020] [core:trace6] [pid 117876:tid
140235421763328] core_filters.c(710): (11)Resource temporarily unavailable:
[client 127.0.0.1:41112] writev_nonblocking: 0/1656
[Tue Jan 07 13:09:32.090852 2020] [core:trace1] [pid 117876:tid
140235421763328] core_filters.c(431): (11)Resource temporarily unavailable:
[client 127.0.0.1:41112] sbb: cof - send_brigade_nonblocking RETURNED
[Tue Jan 07 13:09:32.090856 2020] [core:trace6] [pid 117876:tid
140235421763328] util_filter.c(1015): [client 127.0.0.1:41112] reinstate empty
brigade to full brigade in 'core' output filter
[Tue Jan 07 13:09:32.090858 2020] [core:trace6] [pid 117876:tid
140235421763328] util_filter.c(1108): [client 127.0.0.1:41112] will flush
because of FLUSH bucket
[Tue Jan 07 13:09:32.090861 2020] [core:trace8] [pid 117876:tid
140235421763328] util_filter.c(1110): [client 127.0.0.1:41112] seen in brigade
so far: bytes: 1656, non-file bytes: 1656, eor buckets: 0, morphing buc
kets: 0
[Tue Jan 07 13:09:32.090863 2020] [core:trace8] [pid 117876:tid
140235421763328] util_filter.c(1133): [client 127.0.0.1:41112] brigade
contains: bytes: 0, non-file bytes: 0, eor buckets: 0, morphing buckets: 0
[Tue Jan 07 13:09:32.090865 2020] [core:trace1] [pid 117876:tid
140235421763328] core_filters.c(446): [client 127.0.0.1:41112] sbb: BLOCKED
EAGAIN, polling
[Tue Jan 07 13:09:32.094662 2020] [core:trace1] [pid 117876:tid
140235421763328] core_filters.c(655): [client 127.0.0.1:41112] sbb: 2 vectors,
bytes to write 1656
[Tue Jan 07 13:09:32.094678 2020] [core:trace6] [pid 117876:tid
140235421763328] core_filters.c(710): [client 127.0.0.1:41112]
writev_nonblocking: 1656/1656
[Tue Jan 07 13:09:32.094681 2020] [core:trace1] [pid 117876:tid
140235421763328] core_filters.c(431): [client 127.0.0.1:41112] sbb: cof -
send_brigade_nonblocking RETURNED
[Tue Jan 07 13:09:32.094683 2020] [core:trace1] [pid 117876:tid
140235421763328] core_filters.c(431): [client 127.0.0.1:41112] sbb: cof -
send_brigade_nonblocking RETURNED
[Tue Jan 07 13:09:32.094686 2020] [core:trace6] [pid 117876:tid
140235421763328] util_filter.c(942): [client 127.0.0.1:41112] setaside empty
brigade to empty brigade in 'core' output filter
