On 3/23/20 11:32 AM, Graham Leggett wrote:
> On 23 Mar 2020, at 09:40, Ruediger Pluem <rpl...@apache.org
> <mailto:rpl...@apache.org>> wrote:
>
>> In short: The async filter code currently corrupts responses in certain
>> situations. For the whole story please look here:
>>
>> https://lists.apache.org/thread.html/r94fc303b3d2d8d0a057c150cbbcf8841b313e4de9a97b79203ac62a5%40%3Cdev.httpd.apache.org%3E
>>
>> I know that my proposal is not the final solution, but at least it avoids
>> response corruption until a better solution is
>> available. Maybe Yann already has a better one in his latest post to the
>> original thread.
>
> I’ve read the thread a number of times, and I’l not been able to fully
> understand it.
>
> Can someone describe the problem specifically?
I guess the best description is from here (Joe at 1/7/20, 5:06 PM):
> [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.
>
and the analysis fro Yann (1/7/20, 7:31 PM) here:
> > [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.
To sum it up:
ap_request_core_filter might setaside an EOR and data before this and return,
but it is never called again, because after EOR was
sent only connection and later filters (c->output_filters) are called
afterwards, but nothing before.
Regards
Rüdiger
