search

socketry / async-http

MIT License
320 stars 46 forks source link

Async-HTTP appears to not send the body under some circumstances #62

Closed TimWillard closed 4 years ago

TimWillard commented 4 years ago

In some scenarios it appears that async-http fails the get the payload body of the HTTP request to the server. The only repeatable case I've found is when posting against Microsoft's "IncomingWebhook" connector (such as seen here). Using the following code snippet:

url = "https://outlook.office.com/webhook/3ede2385-2f4d-40e5-b6ac-edf702d9cf24@b43b36f6-5b80-4089-9486-92c4dbcade64/IncomingWebhook/ee3e46ffaa6546b9b8f7106ea98b4acf/5af78e95-1a16-4335-bd6f-8d77e828aa56"
body = Oj.dump({"text" => "Hello!"})
headers = {}

case 1
when 1
  # succeeds
  HTTParty.post(url, headers: headers, body: body)
when 2
  # Fails with "Invalid webhook request - Empty Payload"
  Async do; internet = Async::HTTP::Internet.new; internet.post(url, headers, body).read; end.wait
when 3
  # succeeds
  options = {
    socket_class: Async::IO::TCPSocket,
    ssl_socket_class: Async::IO::SSLSocket,
  }
  Async do; http = HTTP::Client.new(options); http.post(url, headers: headers, body: body); end.wait
end

Both http.rb and httparty successfully post to the provided webhook, but async-http instead gets an error of "Invalid webhook request - Empty Payload".

Given that setting up this webhook was annoying to accomplish, feel free to the use the above url in testing: its for testing only, send whatever spam to it you want.

ioquatix commented 4 years ago

Thanks, I will take a look.

ioquatix commented 4 years ago

My initial investigations seem to indicate that the body is being sent, but the difference is Async::HTTP is negotiating HTTP/2 while the other clients are using HTTP/1.

So it could be a bug somewhere in the HTTP/2 code path either on our end or their end. I'll continue investigating.

  0.0s     info: Object [oid=0x26c] [pid=2150183] [2020-11-16 10:31:35 +1300]
               | Sending request...
  0.0s    debug: Async::Pool::Controller [oid=0x280] [pid=2150183] [2020-11-16 10:31:35 +1300]
               | No resources resources, allocating new one...
  0.0s    debug: Async::HTTP::Client [oid=0x294] [pid=2150183] [2020-11-16 10:31:35 +1300]
               | Making connection to #<Async::HTTP::Endpoint https://outlook.office.com/webhook/3ede2385-2f4d-40e5-b6ac-edf702d9cf24@b43b36f6-5b80-4089-9486-92c4dbcade64/IncomingWebhook/ee3e46ffaa6546b9b8f7106ea98b4acf/5af78e95-1a16-4335-bd6f-8d77e828aa56 {}>
  0.0s    debug: Async::IO::Socket [pid=2150183] [2020-11-16 10:31:35 +1300]
               | Connecting to #<Addrinfo: 40.100.144.242:443 TCP (outlook.office.com)>
 0.14s    debug: Async::HTTP::Protocol::HTTPS [pid=2150183] [2020-11-16 10:31:35 +1300]
               | Negotiating protocol "h2"...
 0.14s    debug: Async::Pool::Controller [oid=0x280] [pid=2150183] [2020-11-16 10:31:35 +1300]
               | Wait for resource -> #<Async::HTTP::Protocol::HTTP2::Client 0 active streams>
 0.14s    debug: Async::HTTP::Protocol::HTTP2::Response [oid=0x2e4] [pid=2150183] [2020-11-16 10:31:35 +1300]
               | [[":scheme", "https"], [":method", "POST"], [":path", "/webhook/3ede2385-2f4d-40e5-b6ac-edf702d9cf24@b43b36f6-5b80-4089-9486-92c4dbcade64/IncomingWebhook/ee3e46ffaa6546b9b8f7106ea98b4acf/5af78e95-1a16-4335-bd6f-8d77e828aa56"], [":authority", "outlook.office.com"]]
               | #<Protocol::HTTP::Body::Buffered 1 chunks, 17 bytes>
  0.4s    debug: Async::Pool::Controller [oid=0x280] [pid=2150183] [2020-11-16 10:31:36 +1300]
               | Reuse #<Async::HTTP::Protocol::HTTP2::Client 0 active streams>
"Invalid webhook request - Empty Payload"
  0.4s    debug: Async::Reactor [oid=0x2f8] [pid=2150183] [2020-11-16 10:31:36 +1300]
               | Exiting run-loop because finished.
ioquatix commented 4 years ago

By the way, here is the data frame which contains the payload:

 0.15s    debug: Async::HTTP::Protocol::HTTP2::Client [oid=0x2d0] [pid=2150785] [2020-11-16 10:34:39 +1300]
               | #<Protocol::HTTP2::DataFrame stream_id=1 flags=0 17b>
ioquatix commented 4 years ago

Here is nghttp sending an HTTP/2 request:

> echo '{"text":"Hello!"}' | nghttp -v -d - -H ":method: POST" "https://outlook.office.com/webhook/3ede2385-2f4d-40e5-b6ac-edf702d9cf24@b43b36f6-5b80-4089-9486-92c4dbcade64/IncomingWebhook/ee3e46ffaa6546b9b8f7106ea98b4acf/5af78e95-1a16-4335-bd6f-8d77e828aa56"
[  0.054] Connected
The negotiated protocol: h2
[  0.145] recv SETTINGS frame <length=18, flags=0x00, stream_id=0>
          (niv=3)
          [SETTINGS_MAX_CONCURRENT_STREAMS(0x03):100]
          [UNKNOWN(0x10):2]
          [SETTINGS_INITIAL_WINDOW_SIZE(0x04):1048576]
[  0.145] recv WINDOW_UPDATE frame <length=4, flags=0x00, stream_id=0>
          (window_size_increment=983041)
[  0.145] send SETTINGS frame <length=12, flags=0x00, stream_id=0>
          (niv=2)
          [SETTINGS_MAX_CONCURRENT_STREAMS(0x03):100]
          [SETTINGS_INITIAL_WINDOW_SIZE(0x04):65535]
[  0.145] send SETTINGS frame <length=0, flags=0x01, stream_id=0>
          ; ACK
          (niv=0)
[  0.145] send PRIORITY frame <length=5, flags=0x00, stream_id=3>
          (dep_stream_id=0, weight=201, exclusive=0)
[  0.145] send PRIORITY frame <length=5, flags=0x00, stream_id=5>
          (dep_stream_id=0, weight=101, exclusive=0)
[  0.145] send PRIORITY frame <length=5, flags=0x00, stream_id=7>
          (dep_stream_id=0, weight=1, exclusive=0)
[  0.145] send PRIORITY frame <length=5, flags=0x00, stream_id=9>
          (dep_stream_id=7, weight=1, exclusive=0)
[  0.145] send PRIORITY frame <length=5, flags=0x00, stream_id=11>
          (dep_stream_id=3, weight=1, exclusive=0)
[  0.145] send HEADERS frame <length=169, flags=0x24, stream_id=13>
          ; END_HEADERS | PRIORITY
          (padlen=0, dep_stream_id=11, weight=16, exclusive=0)
          ; Open new stream
          :method: POST
          :path: /webhook/3ede2385-2f4d-40e5-b6ac-edf702d9cf24@b43b36f6-5b80-4089-9486-92c4dbcade64/IncomingWebhook/ee3e46ffaa6546b9b8f7106ea98b4acf/5af78e95-1a16-4335-bd6f-8d77e828aa56
          :scheme: https
          :authority: outlook.office.com
          accept: */*
          accept-encoding: gzip, deflate
          user-agent: nghttp2/1.41.0
          content-length: 18
[  0.145] send DATA frame <length=18, flags=0x01, stream_id=13>
          ; END_STREAM
[  0.187] recv SETTINGS frame <length=0, flags=0x01, stream_id=0>
          ; ACK
          (niv=0)
[  0.187] recv WINDOW_UPDATE frame <length=4, flags=0x00, stream_id=0>
          (window_size_increment=18)
[  0.961] recv (stream_id=13) :status: 200
[  0.961] recv (stream_id=13) cache-control: no-cache
[  0.961] recv (stream_id=13) pragma: no-cache
[  0.961] recv (stream_id=13) content-type: text/plain; charset=utf-8
[  0.961] recv (stream_id=13) content-encoding: gzip
[  0.961] recv (stream_id=13) expires: -1
[  0.961] recv (stream_id=13) vary: Accept-Encoding
[  0.961] recv (stream_id=13) server: Microsoft-IIS/10.0
[  0.961] recv (stream_id=13) request-id: 7e9fd17d-afb6-4927-aa23-28ccfecfd916
[  0.961] recv (stream_id=13) strict-transport-security: max-age=31536000; includeSubDomains; preload
[  0.961] recv (stream_id=13) x-calculatedfetarget: YQBPR01CU003.internal.outlook.com
[  0.961] recv (stream_id=13) x-backendhttpstatus: 200
[  0.961] recv (stream_id=13) strict-transport-security: max-age=31536000; includeSubDomains; preload
[  0.961] recv (stream_id=13) x-feproxyinfo: YQBPR01CA0087.CANPRD01.PROD.OUTLOOK.COM
[  0.961] recv (stream_id=13) x-calculatedbetarget: QB1PR01MB2883.CANPRD01.PROD.OUTLOOK.COM
[  0.961] recv (stream_id=13) x-backendhttpstatus: 200
[  0.961] recv (stream_id=13) x-aspnet-version: 4.0.30319
[  0.961] recv (stream_id=13) x-cafeserver: YQBPR01CA0087.CANPRD01.PROD.OUTLOOK.COM
[  0.961] recv (stream_id=13) x-beserver: QB1PR01MB2883
[  0.961] recv (stream_id=13) x-rum-validated: 1
[  0.961] recv (stream_id=13) x-proxy-routingcorrectness: 1
[  0.961] recv (stream_id=13) x-proxy-backendserverstatus: 200
[  0.961] recv (stream_id=13) x-feserver: YQBPR01CA0087
[  0.961] recv (stream_id=13) x-powered-by: ASP.NET
[  0.961] recv (stream_id=13) x-feserver: SYBPR01CA0120
[  0.961] recv (stream_id=13) date: Sun, 15 Nov 2020 21:38:58 GMT
[  0.961] recv HEADERS frame <length=532, flags=0x04, stream_id=13>
          ; END_HEADERS
          (padlen=0)
          ; First response header
[  0.961] recv DATA frame <length=110, flags=0x00, stream_id=13>
1[  0.961] recv DATA frame <length=10, flags=0x00, stream_id=13>
[  0.961] recv DATA frame <length=0, flags=0x01, stream_id=13>
          ; END_STREAM
[  0.961] send GOAWAY frame <length=8, flags=0x00, stream_id=0>
          (last_stream_id=0, error_code=NO_ERROR(0x00), opaque_data(0)=[])
ioquatix commented 4 years ago

Okay, looking at that, I see the content-length header was given:

require 'async'
require_relative '../../lib/async/http/internet'
require 'json'

url = "https://outlook.office.com/webhook/3ede2385-2f4d-40e5-b6ac-edf702d9cf24@b43b36f6-5b80-4089-9486-92c4dbcade64/IncomingWebhook/ee3e46ffaa6546b9b8f7106ea98b4acf/5af78e95-1a16-4335-bd6f-8d77e828aa56"
body = JSON.dump({"text" => "Hello!"})
headers = {'content-length' => body.bytesize}

Console.logger.debug!

# Fails with "Invalid webhook request - Empty Payload"
Async do
    Console.logger.info(self, "Sending request...")
    internet = Async::HTTP::Internet.new
    pp internet.post(url, headers, body).read
end

This works.

However, I'm not sure that content-length is a requirement of HTTP/2 since the data stream has an implicit length attached to the frames... odd. But nghttp is doing it so maybe it is a good idea?

ioquatix commented 4 years ago

Okay, I found this:

https://bz.apache.org/bugzilla/show_bug.cgi?id=63009

It seems like as I said, content-length is optional.

In this case, the outlook server is wrong, IMHO. It must be checking content length rather than whether there is actual data.

ioquatix commented 4 years ago

I'm happy to add this header automatically if it can be determined. However, this won't work in all cases because the length isn't always known (e.g. streaming a request body).

ioquatix commented 4 years ago 
  0.0s     info: Object [oid=0x26c] [pid=2153483] [2020-11-16 10:52:42 +1300]
               | Sending request...
  0.0s    debug: Async::Pool::Controller [oid=0x280] [pid=2153483] [2020-11-16 10:52:42 +1300]
               | No resources resources, allocating new one...
  0.0s    debug: Async::HTTP::Client [oid=0x294] [pid=2153483] [2020-11-16 10:52:42 +1300]
               | Making connection to #<Async::HTTP::Endpoint https://outlook.office.com/webhook/3ede2385-2f4d-40e5-b6ac-edf702d9cf24@b43b36f6-5b80-4089-9486-92c4dbcade64/IncomingWebhook/ee3e46ffaa6546b9b8f7106ea98b4acf/5af78e95-1a16-4335-bd6f-8d77e828aa56 {}>
  0.0s    debug: Async::IO::Socket [pid=2153483] [2020-11-16 10:52:42 +1300]
               | Connecting to #<Addrinfo: 40.100.144.242:443 TCP (outlook.office.com)>
 0.14s    debug: Async::HTTP::Protocol::HTTPS [pid=2153483] [2020-11-16 10:52:42 +1300]
               | Negotiating protocol "h2"...
 0.14s    debug: Async::Pool::Controller [oid=0x280] [pid=2153483] [2020-11-16 10:52:42 +1300]
               | Wait for resource -> #<Async::HTTP::Protocol::HTTP2::Client 0 active streams>
 0.14s    debug: Async::HTTP::Protocol::HTTP2::Response [oid=0x2e4] [pid=2153483] [2020-11-16 10:52:42 +1300]
               | [[":scheme", "https"], [":method", "POST"], [":path", "/webhook/3ede2385-2f4d-40e5-b6ac-edf702d9cf24@b43b36f6-5b80-4089-9486-92c4dbcade64/IncomingWebhook/ee3e46ffaa6546b9b8f7106ea98b4acf/5af78e95-1a16-4335-bd6f-8d77e828aa56"], [":authority", "outlook.office.com"], ["content-length", "17"]]
 1.26s    debug: Async::Pool::Controller [oid=0x280] [pid=2153483] [2020-11-16 10:52:44 +1300]
               | Reuse #<Async::HTTP::Protocol::HTTP2::Client 0 active streams>
"1"
 1.26s    debug: Async::Reactor [oid=0x2f8] [pid=2153483] [2020-11-16 10:52:44 +1300]
               | Exiting run-loop because finished.

It is working now on my local code.

ioquatix commented 4 years ago

So...

I'm not sure about adding this.

Firstly, it won't fix the problem in all cases (we are just adding length if we can determine it).

Secondly, there IS an overhead to doing this and it's on a critical path.

Finally, it adds a header which CAN cause problems if the content length is different from the frame length. That shouldn't happen, except the semantics for this are unclear w.r.t. compression, etc.

Therefore, I think the first thing we should do is approach Microsoft about it. Since essentially it feels like a bug on their end.

There are two work-arounds:

ioquatix commented 4 years ago

@TCourtneyOwen Hi, I'm pulling you into this issue after trying to find someone who might have the relevant knowledge/ownership to help triage this issue at Microsoft. Do you mind helping with this or helping us find someone who can help?

ioquatix commented 4 years ago

Okay, I checked, and we are doing this on the server response side. So, it makes sense to do it on the client side too. However, this is still a bug in Microsoft's server.