On 01/07/2020 07:31 PM, Yann Ylavic wrote:
> On Tue, Jan 7, 2020 at 5:06 PM Joe Orton <[email protected]> wrote:
>>
>> 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...
>
> OK, that explains why I can't reproduce..
> Based on your traces, I think I figured out how it happens though, see below.
>
>>
>> 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
>
> Here, the call stack is:
> ap_process_request()
> => ap_process_async_request()
> => ap_process_request_after_handler()
> => ap_pass_brigade()
> => ap_request_core_filter()
> so ap_request_core_filter() is called with the EOR bucket, but since
> there are still pending/setaside/unsent data in the core filter then
> ap_request_core_filter() returns without passing all of its own
> pending data (including the EOR).
>
>> [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
>
> Here, we are now at:
> ap_process_request()
> => ap_pass_brigade(c->output_filters, ...)
> but ap_request_core_filter() is not a connection filter (i.e. not part
> of c->output_filters), so it will never be called again.
> Since it's not called from ap_run_output_pending() either, I think
> mpm_event has the bug too.
>
>
> Could you please try the attached patch?
> The goal is to make ap_request_core_filter() a connection filter, so
> that it remains in c->output_filters until the EOR is handled.
> The patch has subtleties, but ap_request_core_filter() is really
> special. It has to do its best to use r->pool for setasides and
> morphing buckets until the EOR, and depending on network congestion
> there may be multiple ap_request_core_filter()s stacked (one per
> request not fully flushed) so I had to introduce
> AP_FILTER_PROTO_INSERT_BEFORE to stack them in the right order...
Thanks for the analysis. I am still hoping for something easier, but my initial
idea would possibly cause too much
blocking writes. So I need to dig in further. Just for my further analysis let
me try to get the purpose of the
ap_request_core_filter:
It should leverage at least parts of the benefits of the filter setaside /
yielding / brigade reinstate framework for
filters that do not use this, because e.g.
- they are not aware of this framework
- it seems to complex for them to use it and adjust their filter
Of course this is not perfect as some resource and content filters need to
handle this on their own e.g. deflate when
compressing contents of file buckets in order to avoid blocking writes.
Thinking out loudly a bit here: Except for ap_request_core_filter all other
resource and content filters should process
all the data they might have setaside when they see an EOS in a brigade,
correct?
Regards
Rüdiger
