http body truncated sending to transparent proxy when transfer-encoding = chunked

[bkcsfi]

1. What version of Caddy are you using (caddy -version)?

0.9.5

2. What are you trying to do?

I am proxying incoming AS2 (http) connections to PyAS2

3. The Caddyfile

:27202 {
	rewrite / {
		to /proxy/pyas2/as2receive
	}
    proxy / http://myhost.com:5003 {
    	transparent
    	without /proxy
    }
    log / /data/logs/my-as2.log "{combined}"
    tls off
}

4. How did you run Caddy (give the full command and describe the execution environment)?

running in docker image zzrot/alpine-caddy, the command line is

caddy -quic --conf /etc/Caddyfile

5. Please paste any relevant HTTP request(s) here.

I used tcpflow to capture the inbound http request to caddy, and another tcpflow to capture the http proxied to pyas2.

I would like to provide those files privately, but here's a preview of some headers

A. the incoming http request sent to Caddy, some names have been changed

POST / HTTP/1.1
Content-Type: application/pkcs7-mime; smime-type=enveloped-data; name="smime.p7m"
Disposition-Notification-Options: signed-receipt-protocol=required,pkcs7-signature; signed-receipt-micalg=required,sha1
AS2-Version: 1.2
Content-Transfer-Encoding: binary
Mime-Version: 1.0
EDIINT-Features: multiple-attachments
AS2-To: mycompany
Message-ID: <VMSERVER402_B5DE822A-A357-48A5-954D-4E53397240B0>
AS2-From: Prod-Someone
Disposition-Notification-To: Prod-someone
User-Agent: Microsoft (R) BizTalk (R) Server 2013 R2
Host: as2.myhost.com:27202
Transfer-Encoding: chunked
Expect: 100-continue
Connection: Close

2000
<snipped encrypted body>

B. the proxied http request sent to PyAS2 from Caddy

POST /pyas2/as2receive HTTP/1.1
Host: as2.myhost.com:27202
User-Agent: Microsoft (R) BizTalk (R) Server 2013 R2
Connection: close
Transfer-Encoding: chunked
As2-From: Prod-someone
As2-To: mycompany
As2-Version: 1.2
Caddy-Rewrite-Original-Uri: /
Content-Transfer-Encoding: binary
Content-Type: application/pkcs7-mime; smime-type=enveloped-data; name="smime.p7m"
Disposition-Notification-Options: signed-receipt-protocol=required,pkcs7-signature; signed-receipt-micalg=required,sha1
Disposition-Notification-To: Prod-someone
Ediint-Features: multiple-attachments
Expect: 100-continue
Message-Id: <VMSERVER402_B5DE822A-A357-48A5-954D-4E53397240B0>
Mime-Version: 1.0
X-Forwarded-For: redacted
X-Forwarded-Proto: http
X-Real-Ip: redacted
Accept-Encoding: gzip

Notice the beginning chunk size 2000 is missing after the blank header line. There's no body at all

C. Response sent from PyAS2 back to caddy (partial, names changed)

HTTP/1.1 100 Continue

HTTP/1.1 200 OK
ediint-features: CEM
as2-from: mycompany
user-agent: PYAS2, A pythonic AS2 server
AS2-Version: 1.2
as2-to: Prod-someone
date: Fri, 09 Jun 2017 17:52:25 +0000
X-Frame-Options: SAMEORIGIN
Message-ID: <149703074556.8.7478745854709631934@ab1601fbdd10>
Content-Type: multipart/signed; protocol="application/pkcs7-signature"; micalg="sha1"; boundary="===============3745537928056051565=="
MIME-Version: 1.0
Transfer-Encoding: chunked
Connection: close
Server: pyas2-webserver

dc4
--===============3745537928056051565==
Content-Type: multipart/report; report-type="disposition-notification"; boundary="===============2927648526741051776=="
<snipped>

D. Response sent from Caddy to requester (partial, names changed)

HTTP/1.1 100 Continue

HTTP/1.1 200 OK
Alt-Svc: quic=":27202"; ma=2592000; v="36,35,34"
Alternate-Protocol: 27202:quic
As2-From: mycompany
As2-To: Prod-someone
As2-Version: 1.2
Content-Type: multipart/signed; protocol="application/pkcs7-signature"; micalg="sha1"; boundary="===============3745537928056051565=="
Date: Fri, 09 Jun 2017 17:52:25 +0000
Ediint-Features: CEM
Message-Id: <149703074556.8.7478745854709631934@ab1601fbdd10>
Mime-Version: 1.0
Server: pyas2-webserver
User-Agent: PYAS2, A pythonic AS2 server
X-Frame-Options: SAMEORIGIN
Connection: close
Transfer-Encoding: chunked

dc4
--===============3745537928056051565==
Content-Type: multipart/report; report-type="disposition-notification"; boundary="===============2927648526741051776=="
<snipped>

6. What did you expect to see?

I expect the downstream proxy to receive the same data that was sent to caddy

7. What did you see instead (give full error messages and/or log)?

It seems like caddy silently truncates the data sent to the proxy, entirely dropping the body portion from the forwarded request

8. How can someone who is starting from scratch reproduce the bug as minimally as possible?

I can send you the tcpflow file and you can send it to your own caddy server for testing

9. More thoughts

We are receiving many other messages from this trading partner, but as best I can tell the partner sends them either with content-length, or transfer-encoding: chunked. Whenever the transfer-encoding is chunked, the transmission fails, when it's content-length it works

Possibly the sending biztalk server isn't chunking data correctly, but caddy doesn't complain about a decode problem. I'm not sure where that complaint would go, here's the log entry

217.6.54.146 - [09/Jun/2017:17:52:25 +0000] "POST /pyas2/as2receive HTTP/1.1" 200 3524 "-" "Microsoft (R) BizTalk (R) Server 2013 R2"

I used the od program on another file to check the chunking and it seemed correct, example (not this transmission) shown below

examining chunked,  od -A d -c <file>::

    0000640   C   l   o   s   e  \r  \n  \r  \n   2   0   0   0  \r  \n   0
    0000656 202   #   [ 006  \t   * 206   H 206 367  \r 001  \a 003 240 202

should go to 0x2000+654  = 8192 + 654 = 8846::

    0008832 333 026 032   M 003 022 370 224 276   o 326 230   g 322   w  \r
    0008848  \n   3   5   F  \r  \n   9   h   X   e   o   $ 261 016   V   #

so 8854 + 0x35F (863) = 9717::

    0009712   Y   ' 332   r  \f  \r  \n   0  \r  \n  \r  \n

chunked encoding looks ok

[mholt]

Hi @bkcsfi - my first requirement before we dive into this further would be for you to upgrade Caddy to the latest and then update the issue. 😉 Thanks!

[bkcsfi]

aha, yes I will, sorry I didn't notice that.

[bkcsfi]

Still fails with Caddy 0.10.3, same problem

[mholt]

Okay. Does it happen without QUIC?

Gonna ping @lhecker on this just in case he has an idea.

[bkcsfi]

-quic option was only used with 0.9.5 in the zzrot/alpine-caddy docker image.

I switched to docker image abiosoft/caddy to upgrade to 0.10.3. That image does not use -quic,
instead the command it uses is:

/usr/bin/caddy --conf /etc/Caddyfile --log stdout

[lhecker]

@bkcsfi Do you have a full recording of a failed request including headers and the full body (fully unmodified)? If so please send that (only the incoming request) to [email protected] and I'll take a look at what's happening here. I wouldn't mind signing a NDA if you want to. 🙂

[bkcsfi]

I have sent a zip'd version of the original request flow.

[mholt]

Thanks Leonard, for going above and beyond! (Just a note for future reference, now that you made me think about it -- NO contributors to the Caddy project should have to sign an NDA. I would especially never volunteer to sign one. No point in volunteering away certain freedoms for volunteer work!)

[lhecker]

@mholt If I had an issue like this at my workplace and would have to share the request recording it might actually literally be forbidden to do so by certain (privacy protection) laws, without having every viewer of that data sign a NDA. So yeah, I can fully understand it if you have to sign one sometimes, since it might not even be in the submitters' or even the submitters' companies' hands to decide this. In fact it might actually even be a good thing in case of e.g. those privacy protection laws.

[lhecker]

@bkcsfi @mholt Sadly I've been unable to reproduce the problem. Can you maybe help me debug this by running through my steps below? Maybe I've done something wrong, or missed something…

I've written a small utility to debug this problem: https://github.com/lhecker/echoserver
This server hijacks all HTTP requests to create exact copies of the received data. It then replies with a 200-Ok status and the received binary data (including HTTP headers etc. of course) as the response body.
Using it here's what I've done:

Build caddy

go get -u -d github.com/mholt/caddy/caddy
cd $GOPATH/src/github.com/mholt/caddy/caddy
./build.bash

Created the Caddyfile in the current directory with:

:27202 {
    rewrite / {
        to /proxy/pyas2/as2receive
    }
    proxy / http://127.0.0.1:5003 {
        transparent
        without /proxy
    }
    log / stdout "{combined}"
    tls off
}

Run caddy

./caddy --conf Caddyfile --log stdout

Spawn the echoserver on :5003 in a second shell

go get -u github.com/lhecker/echoserver
$GOPATH/bin/echoserver

Send the sample payload in a third shell

cat [redacted filename] - | nc 127.0.0.1 27202

Note: By default netcat will close the connection as soon as it finished reading from stdin. To make it stay open and wait for the HTTP reply I've appended a - at the end of the cat command. This causes stdin and thus the pipe to stay open. Press [Enter] after receiving the reply to exit.

Result

You should receive the 100-Continue and a small 200-Ok status header like this:

HTTP/1.1 100 Continue

HTTP/1.1 200 OK
Content-Length: 10470
Content-Type: text/plain; charset=utf-8
Date: Sun, 11 Jun 2017 17:53:33 GMT
Server: Caddy
Connection: close

…followed by an exact copy of the sample payload (which, as mentioned, is what echoserver replies with).

[lhecker]

@mholt @bkcsfi I just got an idea... Maybe it has to do with the Expect: 100-Continue. If @bkcsfi's upstream backend server is really strict about it, it might close the connection if a client (in this case: caddy) sends the body before the server even had a chance to approve the request with a 100 Continue status.

Currently caddy doesn't handle the Expect header correctly: It should receive the headers, proxy them to the upstream and wait for the upstream's approval until it continues reading from the request .Body, which AFAIK causes Go to automatically send the 100 Continue status.
Instead we currently read the body and write it to the upstream as soon as data is available, which, I believe, thus also means that we always generate the 100 Continue status no matter what the upstream says (since we don't wait for it).

So in case that your upstream server is really strict about it, it might close the connection due to the violation of HTTP's Expect/Continue spec. Is it possible for you to verify that @bkcsfi?

On the other hand if it was really this problem, you should see the first few bytes of the body being sent to the upstream instead of there being none.

[bkcsfi]

I will try to setup wireshark to capture tcp flags and re-transmit the failed chunked encoding message to caddy to determine what is happening.

However I do not think this is the cause of the problem because the downstream app (pyas2) does in fact send back an 100 continue and then follows that up with a 200 OK plus return headers.

what I'm seeing is that caddy is not transmitting the initial chunk size nor any portion of the http request body to the downstream app. The downstream app does attempt to process the (empty) http body, and fails with a decryption error. The app then sends back headers and an http body indicating a decryption error.

Since the downstream app appears to respond within seconds of the initial request, I suspect that caddy is actually sending a TCP FIN on the downstream connection, which causes the downstream app to detect the half close and go ahead and process what it thinks it had read as the http body (i.e. 0 bytes).

[bkcsfi]

Hi all,

I'm beginning to think this issue should be closed.

In the previous tcpflow captures sent to @lhecker , the caddy->app tcpflow showed that there wasn't any body or chunked length being sent from caddy to the app.

today I setup tcpdump and wireshark to capture both client->caddy and caddy->app packets.

Now, wireshark shows that the message body is being sent correctly to the app from caddy. I exported the 'body' contents and checked md5sum, its the same as the body sent to caddy from the client.

I cannot explain why the previous tcpflows failed to show body contents, yet today tcpdump indicates everything is ok.

before opening this issue w/ caddy, I had opened an issue with the app I am using, pyas2, regarding chunked transfer. I didn't get a definitive response from the pyas2 issue but a few days ago someone else has posted to that issue indicating that they have the same issue with chunked transfer.

Therefore I now think that chunked transfer problem is most likely in the app, and not in caddy, and that somehow I had a mis-fire capturing the tcpflow's that I previously sent.

sorry for wasting your time on this, and thanks for your help.

[mholt]

@bkcsfi Thanks so much for your follow-up.

@lhecker I really appreciate your effort on this issue - I hope life is treating you well!