Overview
Adding the header Expect: 100-continue to WebClient causes an improper response to be returned because HTTP 100 is not handled correctly. In my case, the body of the HTTP 100 was blank and that is the value returned to my service. But, the initial response with HTTP 100 does not contain the response the client is looking for.
Below, you will see that Received last HTTP packet is emitted from the reactor netty code. But, the netty HttpClient shows the wiretap for the actual message the service was waiting for.
Found using Spring Framework 5.2.10
WireTap Output
Reactor netty wiretap output:
2020-12-09 14:29:20.678 DEBUG 13379 --- [ctor-http-nio-2] reactor.netty.http.client.HttpClient : [id: 0xe76f6179, L:/127.0.0.1:63115 - R:localhost/127.0.0.1:18080] FLUSH
2020-12-09 14:29:20.684 DEBUG 13379 --- [ctor-http-nio-2] reactor.netty.http.client.HttpClient : [id: 0xe76f6179, L:/127.0.0.1:63115 - R:localhost/127.0.0.1:18080] READ: 25B
+-------------------------------------------------+
| 0 1 2 3 4 5 6 7 8 9 a b c d e f |
+--------+-------------------------------------------------+----------------+
|00000000| 48 54 54 50 2f 31 2e 31 20 31 30 30 20 43 6f 6e |HTTP/1.1 100 Con|
|00000010| 74 69 6e 75 65 0d 0a 0d 0a |tinue.... |
+--------+-------------------------------------------------+----------------+
2020-12-09 14:29:20.684 DEBUG 13379 --- [ctor-http-nio-2] r.n.http.client.HttpClientOperations : [id: 0xe76f6179, L:/127.0.0.1:63115 - R:localhost/127.0.0.1:18080] Received response (auto-read:false) : []
2020-12-09 14:29:20.686 DEBUG 13379 --- [ctor-http-nio-2] r.n.http.client.HttpClientOperations : [id: 0xe76f6179, L:/127.0.0.1:63115 - R:localhost/127.0.0.1:18080] Received last HTTP packet
2020-12-09 14:29:20.686 ERROR 13379 --- [ctor-http-nio-2] c.m.f.s.lead_manager.LeadManagerService : HTTP call complete
2020-12-09 14:29:20.744 DEBUG 13379 --- [ctor-http-nio-2] reactor.netty.http.client.HttpClient : [id: 0xe76f6179, L:/127.0.0.1:63115 - R:localhost/127.0.0.1:18080] READ COMPLETE
2020-12-09 14:29:21.135 DEBUG 13379 --- [ctor-http-nio-2] reactor.netty.http.client.HttpClient : [id: 0xe76f6179, L:/127.0.0.1:63115 - R:localhost/127.0.0.1:18080] READ: 328B
+-------------------------------------------------+
| 0 1 2 3 4 5 6 7 8 9 a b c d e f |
+--------+-------------------------------------------------+----------------+
|00000000| 48 54 54 50 2f 31 2e 30 20 32 30 30 20 4f 4b 0d |HTTP/1.0 200 OK.|
|00000010| 0a 44 61 74 65 3a 20 57 65 64 2c 20 30 39 20 44 |.Date: Wed, 09 D|
|00000020| 65 63 20 32 30 32 30 20 32 32 3a 32 39 3a 32 30 |ec 2020 22:29:20|
|00000030| 20 47 4d 54 0d 0a 53 65 72 76 65 72 3a 20 41 70 | GMT..Server: Ap|
|00000040| 61 63 68 65 2f 32 2e 32 2e 31 35 20 28 43 65 6e |ache/2.2.15 (Cen|
|00000050| 74 4f 53 29 0d 0a 41 63 63 65 73 73 2d 43 6f 6e |tOS)..Access-Con|
|00000060| 74 72 6f 6c 2d 41 6c 6c 6f 77 2d 4f 72 69 67 69 |trol-Allow-Origi|
|00000070| 6e 3a 20 2a 0d 0a 43 6f 6e 74 65 6e 74 2d 4c 65 |n: *..Content-Le|
|00000080| 6e 67 74 68 3a 20 31 32 31 0d 0a 43 6f 6e 6e 65 |ngth: 121..Conne|
|00000090| 63 74 69 6f 6e 3a 20 63 6c 6f 73 65 0d 0a 43 6f |ction: close..Co|
|000000a0| 6e 74 65 6e 74 2d 54 79 70 65 3a 20 61 70 70 6c |ntent-Type: appl|
|000000b0| 69 63 61 74 69 6f 6e 2f 6a 73 6f 6e 3b 20 63 68 |ication/json; ch|
|000000c0| 61 72 73 65 74 3d 75 74 66 2d 38 0d 0a 0d 0a 0a |arset=utf-8.....|
|000000d0| 7b 22 66 6f 72 6d 49 64 22 3a 22 31 22 2c 22 66 |{"formId":"1","f|
|000000e0| 6f 6c 6c 6f 77 55 70 55 72 6c 22 3a 6e 75 6c 6c |ollowUpUrl":null|
|000000f0| 2c 22 61 6c 69 49 64 22 3a 22 65 79 4a 70 49 6a |,"aliId":"eyJpIj|
|00000100| 6f 69 52 54 55 31 52 55 39 68 54 6e 70 59 64 6b |oiRTU1RU9hTnpYdk|
|00000110| 35 48 63 32 39 6c 55 79 49 73 49 6e 51 69 4f 69 |5Hc29lUyIsInQiOi|
|00000120| 4a 34 53 55 46 6c 53 6e 42 49 58 43 39 70 59 30 |J4SUFlSnBIXC9pY0|
|00000130| 6c 51 52 58 6f 30 57 6b 74 63 4c 32 4e 77 57 58 |lQRXo0WktcL2NwWX|
|00000140| 63 39 50 53 4a 39 22 7d |c9PSJ9"} |
+--------+-------------------------------------------------+----------------+
2020-12-09 14:29:21.136 DEBUG 13379 --- [ctor-http-nio-2] reactor.netty.http.client.HttpClient : [id: 0xe76f6179, L:/127.0.0.1:63115 - R:localhost/127.0.0.1:18080] READ COMPLETE
2020-12-09 14:29:21.136 DEBUG 13379 --- [ctor-http-nio-2] reactor.netty.http.client.HttpClient : [id: 0xe76f6179, L:/127.0.0.1:63115 - R:localhost/127.0.0.1:18080] READ COMPLETE
2020-12-09 14:29:21.136 DEBUG 13379 --- [ctor-http-nio-2] reactor.netty.http.client.HttpClient : [id: 0xe76f6179, L:/127.0.0.1:63115 ! R:localhost/127.0.0.1:18080] INACTIVE
2020-12-09 14:29:21.136 DEBUG 13379 --- [ctor-http-nio-2] reactor.netty.http.client.HttpClient : [id: 0xe76f6179, L:/127.0.0.1:63115 ! R:localhost/127.0.0.1:18080] UNREGISTERED
2020-12-09 14:51:15.457 DEBUG 13379 --- [ctor-http-nio-3] reactor.netty.http.client.HttpClient : [id: 0x002182d6] REGISTERED
2020-12-09 14:51:15.457 DEBUG 13379 --- [ctor-http-nio-3] reactor.netty.http.client.HttpClient : [id: 0x002182d6] CONNECT: localhost/127.0.0.1:8086
2020-12-09 14:51:15.458 DEBUG 13379 --- [ctor-http-nio-3] reactor.netty.http.client.HttpClient : [id: 0x002182d6, L:/127.0.0.1:52563 - R:localhost/127.0.0.1:8086] ACTIVE
2020-12-09 14:51:15.458 DEBUG 13379 --- [ctor-http-nio-3] r.netty.http.client.HttpClientConnect : [id: 0x002182d6, L:/127.0.0.1:52563 - R:localhost/127.0.0.1:8086] Handler is being applied: {uri=http://localhost:8086/assetapi/internal/rest/asset/v1/form/fields.json?_munchkinId=622-LME-718&filterValues=1, method=GET}
2020-12-09 14:51:15.468 DEBUG 13379 --- [ctor-http-nio-3] reactor.netty.http.client.HttpClient : [id: 0x002182d6, L:/127.0.0.1:52563 - R:localhost/127.0.0.1:8086] WRITE: 213B
What I Am Working On
How can I better test this? I would like to: - Manually test this fix - Add comprehensive unit tests - Understand if I am missing more places to fix this
I have attempted to test this code form a unit test by calling out to a server that returns HTTP 100. I keep getting a socket error even though curl works on the same machine. Have you seen this before?
And, how would you suggest I add uint tests for this. I know the netty server emits with this the proper header in the request. Should I spin up that server in case the mock server does not return a HTTP 100?
Reference
RFC2616 - HTTP 1.1 - Use of the 100 (Continue) Status
Comment From: pivotal-issuemaster
@tweiand Please sign the Contributor License Agreement!
Click here to manually synchronize the status of this Pull Request.
See the FAQ for frequently asked questions.
Comment From: pivotal-issuemaster
@tweiand Thank you for signing the Contributor License Agreement!
Comment From: sbrannen
@tweiand, can you briefly share why you closed this issue?
Comment From: tweiand
Hey @sbrannen - I close it because I was not able to code a fix for it. If I recall correctly, that was a prerequisite to filing the bug and getting traction. Closed because I didn’t have a fix and it appeared to only be affecting Netty.
FYI - I looked into the issue and it seemed to be coming from the interaction between the netty client and WebClient. I am up for trying to fix it if I can get help :-).