`test/net/integration/http` fails because the response is not parsed correctly

[ricarkol]

Hello,

test/net/integration/http (master branch) fails sometimes (approx. once every ten runs) in my box (specs at the end). This seems to happen when the HTTP response is split into too many packets (see the TCP dump below). There seem to be two issues happening:

(1) the HTTP response is (sometimes) ended before parsing the last packet. Specifically, end_response in client_connection.cpp is called too early.

(2) the response is not parsed correctly and the body includes some lines that should belong to the header. Specifically, https://github.com/hioa-cs/IncludeOS/blob/master/src/net/http/client_connection.cpp#L98 is treating the last packet, that has a portion of the header and the body, as just the body.

Here is the output of test.py when failing because of issue (1) (service.cpp was slightly changed to print the response and body before the failing assert):

<vm>      [ Kernel ] Starting HTTP Test Service
<vm> ================================================================================
<vm> ================================================================================
<vm>  IncludeOS v0.10.0-dirty
<vm>  +--> Running [ HTTP Test Service ]
<vm> ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
<vm> [ Super stack ] Constructing stacks
<vm> [ Super stack ] Creating stack for Nic eth0
<vm>       [ Inet4 ] Bringing up a IPv4 stack
<vm>       [ Inet4 ] Network configured
<vm>                 IP: 		10.0.0.44
<vm>                 Netmask: 	255.255.255.0
<vm>                 Gateway: 	10.0.0.1
<vm>                 DNS Server: 	8.8.8.8
<vm>      [ Client ] Testing against local server
<vm>      [ Client ] Testing against Acorn
<vm> Response: ===============================> printing the full response before doing the checks.
<vm> HTTP/1.0 200 OK
<vm> Server: BaseHTTP/0.3 Python/2.7.12
<vm> Date: Wed, 05 Apr 2017 19:04:02 GMT
<vm> Content-type: text/plain:
<vm> 
<vm> Body: 
<vm> ===============================> body is empty
<vm>                 [x] No error
<vm> assertion "res->body() == "/testing"" failed: file "/root/IncludeOS/test/net/integration/http/service.cpp", line 56, function: auto Service::ready()::(anonymous class)::operator()(type-parameter-0-0, type-parameter-0-1) const
<vm> !!! Kill PID: 1, SIG: 6 - IOT trap / ABORT

Here is is the tcpdump for bridge43 for a case of issue (1). The last packet is not included in the HTTP response and that seems to be the reason for the failure.

19:18:47.659514 c0:01:0a:00:00:2a (oui Unknown) > c0:01:0a:00:00:01 (oui Unknown), ethertype IPv4 (0x0800), length 54: 10.0.0.44.57134 > 10.0.0.1.9011: Flags [.], ack 1, win 65535, length 0
        0x0000:  4500 0028 0000 0000 4006 66a4 0a00 002c  E..(....@.f....,
        0x0010:  0a00 0001 df2e 2333 1814 4399 df93 89d8  ......#3..C.....
        0x0020:  5010 ffff d42c 0000                      P....,..
19:18:47.659576 c0:01:0a:00:00:2a (oui Unknown) > c0:01:0a:00:00:01 (oui Unknown), ethertype IPv4 (0x0800), length 146: 10.0.0.44.57134 > 10.0.0.1.9011: Flags [P.], seq 1:93, ack 1, win 65535, length 92
        0x0000:  4500 0084 0000 0000 4006 6648 0a00 002c  E.......@.fH...,
        0x0010:  0a00 0001 df2e 2333 1814 4399 df93 89d8  ......#3..C.....
        0x0020:  5018 ffff b3d5 0000 4745 5420 2f74 6573  P.......GET./tes
        0x0030:  7469 6e67 2048 5454 502f 312e 310d 0a55  ting.HTTP/1.1..U
        0x0040:  7365 722d 4167 656e 743a 2049 6e63 6c75  ser-Agent:.Inclu
        0x0050:  6465 4f53 2f30 2e39 0d0a 436f 6e6e 6563  deOS/0.9..Connec
        0x0060:  7469 6f6e 3a20 636c 6f73 650d 0a48 6f73  tion:.close..Hos
        0x0070:  743a 2031 302e 302e 302e 313a 3930 3131  t:.10.0.0.1:9011
        0x0080:  0d0a 0d0a                                ....
19:18:47.659591 c0:01:0a:00:00:01 (oui Unknown) > c0:01:0a:00:00:2a (oui Unknown), ethertype IPv4 (0x0800), length 54: 10.0.0.1.9011 > 10.0.0.44.57134: Flags [.], ack 93, win 29200, length 0
        0x0000:  4500 0028 29ce 4000 4006 fcd5 0a00 0001  E..().@.@.......
        0x0010:  0a00 002c 2333 df2e df93 89d8 1814 43f5  ...,#3........C.
        0x0020:  5010 7210 1447 0000                      P.r..G..
19:18:47.659893 c0:01:0a:00:00:01 (oui Unknown) > c0:01:0a:00:00:2a (oui Unknown), ethertype IPv4 (0x0800), length 71: 10.0.0.1.9011 > 10.0.0.44.57134: Flags [P.], seq 1:18, ack 93, win 29200, length 17
        0x0000:  4500 0039 29cf 4000 4006 fcc3 0a00 0001  E..9).@.@.......
        0x0010:  0a00 002c 2333 df2e df93 89d8 1814 43f5  ...,#3........C.
        0x0020:  5018 7210 1458 0000 4854 5450 2f31 2e30  P.r..X..HTTP/1.0
        0x0030:  2032 3030 204f 4b0d 0a                   .200.OK..
19:18:47.659958 c0:01:0a:00:00:2a (oui Unknown) > c0:01:0a:00:00:01 (oui Unknown), ethertype IPv4 (0x0800), length 54: 10.0.0.44.57134 > 10.0.0.1.9011: Flags [.], ack 18, win 65535, length 0
        0x0000:  4500 0028 0000 0000 4006 66a4 0a00 002c  E..(....@.f....,
        0x0010:  0a00 0001 df2e 2333 1814 43f5 df93 89e9  ......#3..C.....
        0x0020:  5010 ffff d3bf 0000                      P.......
19:18:47.659975 c0:01:0a:00:00:01 (oui Unknown) > c0:01:0a:00:00:2a (oui Unknown), ethertype IPv4 (0x0800), length 90: 10.0.0.1.9011 > 10.0.0.44.57134: Flags [P.], seq 18:54, ack 93, win 29200, length 36
        0x0000:  4500 004c 29d0 4000 4006 fcaf 0a00 0001  E..L).@.@.......
        0x0010:  0a00 002c 2333 df2e df93 89e9 1814 43f5  ...,#3........C.
        0x0020:  5018 7210 146b 0000 5365 7276 6572 3a20  P.r..k..Server:.
        0x0030:  4261 7365 4854 5450 2f30 2e33 2050 7974  BaseHTTP/0.3.Pyt
        0x0040:  686f 6e2f 322e 372e 3132 0d0a            hon/2.7.12..

====> This next packet is ignored by the HTTP client.

19:18:47.660047 c0:01:0a:00:00:01 (oui Unknown) > c0:01:0a:00:00:2a (oui Unknown), ethertype IPv4 (0x0800), length 127: 10.0.0.1.9011 > 10.0.0.44.57134: Flags [FP.], seq 54:127, ack 93, win 29200, length 73
        0x0000:  4500 0071 29d1 4000 4006 fc89 0a00 0001  E..q).@.@.......
        0x0010:  0a00 002c 2333 df2e df93 8a0d 1814 43f5  ...,#3........C.
        0x0020:  5019 7210 1490 0000 4461 7465 3a20 5765  P.r.....Date:.We
        0x0030:  642c 2030 3520 4170 7220 3230 3137 2031  d,.05.Apr.2017.1
        0x0040:  393a 3138 3a34 3720 474d 540d 0a43 6f6e  9:18:47.GMT..Con
        0x0050:  7465 6e74 2d74 7970 653a 2074 6578 742f  tent-type:.text/
        0x0060:  706c 6169 6e0d 0a0d 0a2f 7465 7374 696e  plain..../testin
        0x0070:  67                                       g

This is the output of a run failing because of issue (2):

<vm>       [ Inet4 ] Bringing up a IPv4 stack
<vm>       [ Inet4 ] Network configured
<vm>                IP:             10.0.0.44
<vm>                 Netmask:        255.255.255.0
<vm>                 Gateway:        10.0.0.1
<vm>                 DNS Server:     8.8.8.8
<vm>      [ Client ] Testing against local server
<vm>      [ Client ] Testing against Acorn
<vm> Response:
<vm> HTTP/1.1 1866664461 Internal Server Error
<vm> Server: BaseHTTP/0.3 Python/2.7.12
<vm>
<vm> Date: Wed, 05 Apr 2017 20:25:07 GMT
<vm> Content-type: text/plain
<vm>
<vm> /testing
<vm> Body: ===============================> body includes some header stuff like Content-Type
<vm> Date: Wed, 05 Apr 2017 20:25:07 GMT
<vm> Content-type: text/plain
<vm>
<vm> /testing
<vm>                 [x] No error
<vm> assertion "res->body() == "/testing"" failed: file "/root/IncludeOS/test/net/integration/http/service.cpp", line 56, function: auto Service::ready()::(anonymous class)::operator()(type-parameter-0-0, type-parameter-0-1) const
<vm> !!! Kill PID: 1, SIG: 6 - IOT trap / ABORT

As another datapoint, this hacky change "fixes" the test (no failures in 50 runs). I'm not suggesting this change as the actual fix (it's just a datapoint).

--- a/src/net/http/client_connection.cpp
+++ b/src/net/http/client_connection.cpp
@@ -86,17 +86,11 @@ namespace http {
     else
     {
       // this is the case when Status line is received, but not yet headers.
-      if(res_->header().is_empty() && req_->method() != HEAD)
+      if(req_->method() != HEAD)
       {
         *res_ << data;
         res_->parse();
       }
-      // here we assume all headers has already been received (could not be true?)
-      else
-      {
-        // add chunks of body data
-        res_->add_chunk(data);
-      }
     }
 
     const auto& header = res_->header();
@@ -121,8 +115,6 @@ namespace http {
         catch(...)
         { end_response({Error::INVALID}); }
       }
-      else
-        end_response();
     }
     else if(req_->method() == HEAD)
     {
@@ -158,7 +150,7 @@ namespace http {
       auto callback = std::move(on_response_);
       on_response_.reset();
       timer_.stop();
-      callback(Error::CLOSING, std::move(res_));
+      callback(Error::NONE, std::move(res_));
     }
 
     client_.close(*this);

Just in case, this can be reproduced in a Lenovo x1 carbon (Intel(R) Core(TM) i7-5600U CPU @ 2.60GHz), RHEL 7.3, 3.10.0-514.10.2.el7.x86_64. Let me know if you can't reproduce it and need some more info (or tests).

Thanks,
Ricardo

[AndreasAakesson]

Thanks for a really detailed report! I will look into it.

[AndreasAakesson]

The hacky change you posted was how it looked before, it's just so expensive. It means we need to concat the response string with the new chunk, and the re parse the whole response again, for every chunk of data. It's OK in the test case, but when the responses starts to get bigger (more payload) it gets really ugly. The problem is the way we parse and concat the response is not good enough. Any ideas on how to improve it are welcome!

[AndreasAakesson]

If I understands the http_parser correctly it seems the on_headers_complete callback can be used to determine if the data is header or body. I tried adding a bool for this (see 3ac1abf). I ran the test plenty of times without any issue. Would you mind trying my dev branch?

There are still some changes that can be done on how to build a HTTP response/request, but I'm not sure how yet.

[ricarkol]

Thanks Andreas. Tested your dev branch and it works (no failures in 50 runs).

[AndreasAakesson]

Happy to help :) Thanks for thoroughly testing!