pyas2 built-in web server fails with chunked encoding transfer

[bkcsfi]

When receiving messages from MS Biztalk, we occasionally see this error during decryption:

An error occurred during the AS2 message processing: Failed to decrypt message, exception message is header too long

the debug output doesn't show any particular AS2 protocol header that's too long, so maybe its' some other header. What is strange is that the debug log does not show the raw contents that were received.

e.g. failed log shows this:

20170525 13:11:08 DEBUG    : Recevied an HTTP POST from 172.18.0.1 with payload :
caddy-rewrite-original-uri: /
ediint-features: multiple-attachments
message-id: <VMSERVER412_0F426FE6-58EB-4DD4-A67A-3B3BD61E724F>
x-real-ip: 217.6.54.146
content-length: 5376
user-agent: Microsoft (R) BizTalk (R) Server 2013 R2
connection: close
mime-version: 1.0
content-transfer-encoding: binary
as2-to: STRADERFERRISTEST
as2-version: 1.2
x-forwarded-proto: http
host: as2.strader-ferris.com:27202
expect: 100-continue
as2-from: Test-Schleich
disposition-notification-options: signed-receipt-protocol=required,pkcs7-signature; signed-receipt-micalg=required,sha1
disposition-notification-to: Test-Schleich
x-forwarded-for: 217.6.54.146
content-type: application/pkcs7-mime; smime-type=enveloped-data; name="smime.p7m"
accept-encoding: gzip

20170525 13:11:08 DEBUG    : Check payload to see if its an AS2 Message or ASYNC MDN.
20170525 13:11:08 INFO     : Received an AS2 message with id <VMSERVER412_0F426FE6-58EB-4DD4-A67A-3B3BD61E724F> for organization STRADERFERRISTEST from partner Test-Schleich
20170525 13:11:08 DEBUG    : Decrypting the payload :

20170525 13:11:08 DEBUG    : MDN for message VMSERVER412_0F426FE6-58EB-4DD4-A67A-3B3BD61E724F created:
Content-Type: multipart/report; report-type="disposition-notification";
 boundary="===============5931524620576249009=="

--===============5931524620576249009==
Content-Type: text/plain; charset="us-ascii"
Content-Transfer-Encoding: 7bit

The AS2 message could not be processed. The disposition-notification report has additional details.

--===============5931524620576249009==
Content-Type: message/disposition-notification; charset="us-ascii"
Content-Transfer-Encoding: 7bit

When we ask them to retransmit the same message again, it works and the message is decoded ok

In both cases the content-length is the same, 5376

How do we figure out what header is too long?

Why does the raw message contents not appear in the debug log in the failed case?

20170525 19:04:38 DEBUG    : Recevied an HTTP POST from 172.18.0.1 with payload :
caddy-rewrite-original-uri: /
ediint-features: multiple-attachments
message-id: <VMSERVER412_8C56C46A-4359-466F-931C-3DB2500A619E>
x-real-ip: 217.6.54.146
content-length: 5376
user-agent: Microsoft (R) BizTalk (R) Server 2013 R2
connection: close
mime-version: 1.0
content-transfer-encoding: binary
as2-to: STRADERFERRISTEST
as2-version: 1.2
x-forwarded-proto: http
host: as2.strader-ferris.com:27202
expect: 100-continue
as2-from: Test-Schleich
disposition-notification-options: signed-receipt-protocol=required,pkcs7-signature; signed-receipt-micalg=required,sha1
disposition-notification-to: Test-Schleich
x-forwarded-for: 217.6.54.146
content-type: application/pkcs7-mime; smime-type=enveloped-data; name="smime.p7m"
accept-encoding: gzip

0<82>^T<FC>^F   *<86>H<86><F7>^M^A^G^C<A0><82>^T<ED>0<82>^T<E9>^B^A^@1<82>^A<C1>0<82>^A<BD>^B^A^@0<81><A4>0<81><96>1^K0 ^F^CU^D^F^S^BUS1^K0     ^F^CU^D^H^L^BNY1^S0^Q^F^CU^D^G^L
Ogdensburg1*0(^F^CU^D
^L!Strader-Ferris International TEST1^Z0^X^F^CU^D^C^L^QSTRADERFERRISTEST1^]0    

[abhishek-ram]

Well the issue is that in the first request the request body is empty. This is strange and I have not seen this before, I will need to do some research and get back to you.

[bkcsfi]

I thought an empty message had been sent in the failed case, yet the content-length header value is the same as the non-failed case.

[abhishek-ram]

The content-length is just a header value and in this case the request body seems to be empty as indicated in the logs.

[abhishek-ram]

You could try to run the AS2 server on Apache instead of cherrypy. This could solve the issue.

[bkcsfi]

I am using tcpflow to troubleshoot this continuing problem. I have captured one failed transmission and I see that it's using chunked encoding whereas non-failed transmissions specify content-length.

I am using caddy as front-end server that then proxies to pyas2. I have setup another tcpflow session to capture proxy traffic to determine if caddy is messing up chunked transfer or not.

everything is running under docker, I'd rather not load pyas2 in apache.

Is there a known issue with chunked encoding using the built-in pyas2 http server?

[mevinbabuc]

@bkcsfi Hey i'm getting the same error too. Did you figure out what was going on and any workaround for this ?

[bkcsfi]

hello, sorry for the delay replying.

I am using Caddy as a front-end server, that then http proxies to pyas2. I have been pursuing this issue with the caddy project because tcpflow tests had shown that the issue was possibly caused by caddy and not pyas2.

today I was able to capture raw packets for analysis by wireshark and now I see that in fact there's nothing wrong with the request that caddy is proxying on to pyas2.

so now I'm back. I think there may be an issue with pyas2 default web server..

our workaround was to ask the trading partner to disable chunked encoding in MS Biztalk.. not ideal but we're up and running.