Bug 66597 - HTTP/2 chunk requests conflict with proxy-sendcl option in mod_proxy_fcgi
Summary: HTTP/2 chunk requests conflict with proxy-sendcl option in mod_proxy_fcgi
Status: RESOLVED FIXED
Alias: None
Product: Apache httpd-2
Classification: Unclassified
Component: mod_proxy_fcgi (show other bugs)
Version: 2.4.57
Hardware: PC Linux
: P2 normal (vote)
Target Milestone: ---
Assignee: Apache HTTPD Bugs Mailing List
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2023-05-10 14:16 UTC by dreamt_catsup403
Modified: 2023-05-24 09:14 UTC (History)
1 user (show)



Attachments
Deterministic order between H2_C2_REQUEST_IN and HTTP_IN (701 bytes, patch)
2023-05-14 19:32 UTC, Yann Ylavic
Details | Diff
Deterministic order between H2_C2_REQUEST_IN and HTTP_IN (v2) (699 bytes, patch)
2023-05-15 10:31 UTC, Yann Ylavic
Details | Diff
config files, traces, commands (432.88 KB, application/zip)
2023-05-19 09:48 UTC, dreamt_catsup403
Details
H2_C2_REQUEST_IN added once (554 bytes, patch)
2023-05-19 10:24 UTC, Yann Ylavic
Details | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description dreamt_catsup403 2023-05-10 14:16:09 UTC
In cases where an HTTP/2 request is chunked (sent without a CONTENT_LENGTH header but with the END_STREAM flag (RFC 7540)).

In cases where the proxy-sendcl env variable is set: 
"HTTP/1.0 required all HTTP requests that include a body (e.g. POST requests) to include a Content-Length header. This environment variable forces the Apache proxy to send this header to the backend server, regardless of what the Client sent to the proxy..."

mod_proxy_fcgi also chunks the body. This can cause problems for the PHP-FPM back-end, which is not expecting chunk fields since the content length is specified.

It looks a side effect of https://bz.apache.org/bugzilla/show_bug.cgi?id=57087

It can easily be reproduce:
curl -v -k -H 'Content-Length:' --http2 -X POST https://127.0.0.1/ -d '{"thisis":"atest"}'

The FCGI_STDIN will look:
12
{"thisis":"atest"}
0
Comment 1 Yann Ylavic 2023-05-12 14:45:24 UTC
(In reply to dreamt_catsup403 from comment #0)
> mod_proxy_fcgi also chunks the body. This can cause problems for the PHP-FPM
> back-end, which is not expecting chunk fields since the content length is
> specified.

It looks like proxy-sendcl is not taken into account, how do you set it?
Does it work without HTTP/2, i.e. using HTTP/1.1 only?


> It looks a side effect of
> https://bz.apache.org/bugzilla/show_bug.cgi?id=57087

Before v2.4.47 (r1885607) proxy-sendcl was ignored in mod_proxy_fcgi, so it's possible that this change does not work for you but it didn't really introduce a regression..


> It can easily be reproduce:

Could you please attach the logs with "LogLevel trace8"?
Unfortunately there seems to be no (few?) debug logs for Content-Length vs Transfer-Encoding forwarding in mod_proxy_fcgi, so this might not help much.
I could provide a patch for more visibility if you compile httpd by yourself..
Comment 2 dreamt_catsup403 2023-05-12 14:53:25 UTC

With exact same setup, it is working fine if the request is  HTTP/1.1. Only HTTP/2 is affected. 

I did traffic dump before and after Apache. To me proxy-sendcl is not ignored, I can see that content-lenght header has been added in the FCGI header, where it's not in the Http/2 calls prior Apache.

I'll attach debug logs early next week
Comment 3 Yann Ylavic 2023-05-12 15:37:34 UTC
If a Content-Length is sent to the fgci backend that's the whole/sole point of prxy-sendcl, data are always sent in "chunks" in the fgci protocol if I'm not mistaken, at least that's what mod_proxy_fcgi does (regardless of content-length vs chunked).
Is the framing different in FCGI_STDIN if you send an original request with Content-Length?
I'm not sure what your problem is actually if the framing is (supposed to be) the same with C-L forwading or chunked+sendcl.
Comment 4 dreamt_catsup403 2023-05-12 16:43:24 UTC
> Is the framing different in FCGI_STDIN if you send an original request with Content-Length?

For the for 4 cases below, having proxy-sendcl 1

- Doing HTTP/1.1 request, with Transfer-enconding: chunked [OK]
FCGI PARAMS: content-lenght 18
FCGI_STDIN body:
{"thisis":"atest"}

- Doing HTTP/1.1 request, with Content-lenght [OK]
FCGI PARAMS: content-lenght 18
{"thisis":"atest"}

- Doing HTTP/2 request, with Content-lenght [OK]
FCGI PARAMS: content-lenght 18
FCGI_STDIN body:
{"thisis":"atest"}

FCGI PARAMS: content-lenght 29
- Doing HTTP/2 request, without Content-lenght [KO]
FCGI_STDIN body:
12
{"thisis":"atest"}
0

My problem is with HTTP/2 and no content-length. The backend receives a body with extra chunk fields.
Comment 5 Yann Ylavic 2023-05-14 19:32:33 UTC
Created attachment 38556 [details]
Deterministic order between H2_C2_REQUEST_IN and HTTP_IN

Could you please try this patch (again 2.4.57)?
Comment 6 Yann Ylavic 2023-05-14 19:33:42 UTC
(In reply to Yann Ylavic from comment #5)
> (again 2.4.57)?

*against
Comment 7 Yann Ylavic 2023-05-15 10:31:01 UTC
Created attachment 38557 [details]
Deterministic order between H2_C2_REQUEST_IN and HTTP_IN (v2)

By using this v2 patch instead and this configuration:

  # main config
  LoadModule dumpio_module modules/mod_dumpio.so
  # main or vhost config
  LogLevel trace8
  DumpIOInput on
  DumpIOoutput on

we could better debug the case I think. Please use this if possible.
Comment 8 dreamt_catsup403 2023-05-16 14:33:22 UTC
tested the 2nd attachment, got a seg fault:

[Tue May 16 14:30:54.129226 2023] [core:notice] [pid 1561030:tid 140704993326976] AH00052: child pid 1564094 exit signal Segmentation fault (11)
[Tue May 16 14:30:54.129266 2023] [core:trace4] [pid 1561030:tid 140704993326976] mpm_common.c(540): mpm child 1564094 (gen 0/slot 70) exited
[Tue May 16 14:30:54.129272 2023] [mpm_event:debug] [pid 1561030:tid 140704993326976] event.c(721): Child 70 stopped: pid 1564094, gen 0, active 25/76, total 25/74/128, quiescing 0
[Tue May 16 14:30:54.131497 2023] [core:trace4] [pid 1561030:tid 140704993326976] mpm_common.c(540): mpm child 1569445 (gen 0/slot 0) started
[Tue May 16 14:30:54.131504 2023] [mpm_event:debug] [pid 1561030:tid 140704993326976] event.c(746): Child 0 started: pid 1569445, gen 0, active 26/76, total 26/74/128
[Tue May 16 14:30:54.134227 2023] [watchdog:debug] [pid 1569445:tid 140704993326976] mod_watchdog.c(583): AH02981: Watchdog: Created child worker thread (_proxy_hcheck_).
[Tue May 16 14:30:54.134286 2023] [http2:info] [pid 1569445:tid 140704993326976] h2_workers: created with min=40 max=60 idle_ms=600000
Comment 9 Yann Ylavic 2023-05-16 17:24:37 UTC
Sorry this patch is broken.

I tried to reproduce (with httpd-2.4.57) but couldn't.
Using HTTP/1 or HTTP/2, with or without proxy-sendcl, the body is never sent "chunked" to the fcgi server (I'm using tcpdump/wireshark to capture the FCGI protocol to a simple `php-cgi -b 127.0.0.1:9000` server to look at the fcgi protocol data sent by mod_proxy_fcgi).

With your curl command from comment 1, HTTP/1 or /2 with or without "SetEnv proxy-sendcl 1", a content-length is always sent too. But this depends on whether the full request body is immediately available (along with the HTTP header) on the proxy, which may not be your case.
So I also tried with `curl --limit-rate 10 ...` so that 10 bytes are sent at a time only (by curl), and then without proxy-sendcl I could make mod_proxy_fcgi NOT send the content-length, but the body is still not sent with "chunked" encoding (it's sent in multiple FGCI_STDIN records, but that's not the HTTP "chunked" encoding that you describe). With proxy-sendcl, the content-length is always there regardless of --limit-rate (as expected), and no chunking still.

So I can't see where your issue is coming from..
Could you attach the full error log of the request with the configuration snippet from comment 7 (trace8, mod_dumpio) but without applying the patch oviously?
Comment 10 Stefan Eissing 2023-05-17 08:58:42 UTC
One thought I had was that we could see the outcome of a *double* chunked encoding. But I fail to see how that could happen either.
Comment 11 Yann Ylavic 2023-05-17 09:14:17 UTC
I was thinking of an input filter chain ending up like:
   H2_C2_NET_IN <- HTTP_IN <- H2_C2_REQUEST_IN
instead of the correct:
   H2_C2_NET_IN <- H2_C2_REQUEST_IN <- HTTP_IN
and tried to avoid that with (broken) attachment 38557 [details].

But with my simple reproducer configuration I always get the correct chain (with no patch), maybe some specifics in the one of dreamt_catsup403 (which should be shared for us to be able to test..).
Comment 12 dreamt_catsup403 2023-05-19 09:48:17 UTC
Created attachment 38562 [details]
config files, traces, commands

Hi,

Indeed you are right, it's not happening by default.
It's actually happening only when passing through a mod_rewrite rule.

If I use this vhost configuration:
<VirtualHost *:443>
    ServerAdmin support@test.com
    DocumentRoot /var/www/
    ServerName thisis.atest

    SetEnv proxy-sendcl 1

    <Directory /var/www/api-v1>
        <FilesMatch \.php$>
           SetHandler "proxy:fcgi://127.0.0.1:9000"
        </FilesMatch>
        RewriteEngine On
        RewriteRule ^ index.php [QSA,END]
    </Directory>

   <Proxy fcgi://127.0.0.1:9000>
       ProxySet connectiontimeout=5 timeout=300 keepalive=On enablereuse=Off max=100 
   </Proxy>
</VirtualHost>

I'm facing the issue only if I use:
curl -k  -v --http2 -H 'Content-Length:' --resolve thisis.atest:443:127.0.0.1 https://thisis.atest/api-v1/something -X POST -d '{thisis:atest}'

with CL it's ok
curl -k  -v --http2  --resolve thisis.atest:443:127.0.0.1 https://thisis.atest/api-v1/something -X POST -d '{thisis:atest}'

And without CL but with full path it's ok
curl -k  -v --http2 -H 'Content-Length:' --resolve thisis.atest:443:127.0.0.1 https://thisis.atest/api-v1/index.php -X POST -d '{thisis:atest}'


I'm attaching configuration, curl commands, and tcpdump.
Comment 13 Yann Ylavic 2023-05-19 10:24:29 UTC
Created attachment 38563 [details]
H2_C2_REQUEST_IN added once

OK, this makes sense, the H2_C2_REQUEST_IN filter is added twice (for the initial h1 request and the internal redirect caused by the RewriteRule).

Can you please try this patch?
Comment 14 Stefan Eissing 2023-05-19 11:51:59 UTC
Ah, nice find. Added a test case and Yann's fix that resolves the issue.
Comment 15 dreamt_catsup403 2023-05-19 13:02:02 UTC
Much better! It seems to have resolved the issue in my development environment. I will test more deeper in  pre-production early next week and keep you informed.

Thank you very much for your support!
Comment 16 dreamt_catsup403 2023-05-24 09:14:14 UTC
Hi,

Confirmed it works with 2.4.57. Would it be possible to get the fix on next release ?