search

Kitura / Kitura-net

Kitura networking
Apache License 2.0
104 stars 79 forks source link

Kitura-net ignores an Expect: 100-continue header #293

Open djones6 opened 5 years ago

djones6 commented 5 years ago

I noticed that when posting data with curl over a certain size (in my experiments, > 1024 bytes) there was a 1 second (or occasionally 2 second) delay. I tracked this down to the behaviour of the Expect: 100-continue header which Kitura-net does not handle.

Here's 'normal' behaviour, where the entire payload is received as a single HTTP message:

[2019-03-01T09:35:34.568Z] [DEBUG] [HTTPServer.swift:288 listen(listenSocket:socketManager:)] Accepted HTTP connection from: 192.168.1.35:53472
[2019-03-01T09:35:34.569Z] [DEBUG] [IncomingSocketHandler.swift:114 init(socket:using:)] Socket connection 7 established
[2019-03-01T09:35:34.638Z] [DEBUG] [IncomingSocketHandler.swift:158 handleRead()] Read 1162 bytes from socket 7
[2019-03-01T09:35:34.639Z] [DEBUG] [IncomingSocketHandler.swift:158 handleRead()] Read 0 bytes from socket 7
[2019-03-01T09:35:34.639Z] [DEBUG] [IncomingHTTPSocketProcessor.swift:137 process] Processing buffer of size 1162 for socket 7
[2019-03-01T09:35:34.639Z] [DEBUG] [IncomingHTTPSocketProcessor.swift:241 parse(_:from:completeBuffer:)] HTTP parser parsed 1162 out of 1162 bytes for socket 7
[2019-03-01T09:35:34.639Z] [DEBUG] [IncomingHTTPSocketProcessor.swift:242 parse(_:from:completeBuffer:)] Buffered bytes:
POST /post HTTP/1.1
User-Agent: curl/7.35.0
Host: gruffalo10G:8080
Accept: */*
Content-Type: application/raw
Content-Length: 1024

1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef
[2019-03-01T09:35:34.639Z] [VERBOSE] [HTTPServerRequest.swift:333 parsingCompleted()] HTTP request from=192.168.1.35; proto=http;
[2019-03-01T09:35:34.640Z] [DEBUG] [IncomingSocketHandler.swift:337 write(from:)] writing data
[2019-03-01T09:35:34.640Z] [DEBUG] [IncomingSocketHandler.swift:353 write(from:length:)] writing bytes with length 123

Sending 1 byte more (1025 bytes payload), curl sends the headers and body separately, the former with a Expect: 100-continue header:

[2019-03-01T09:35:42.416Z] [DEBUG] [HTTPServer.swift:288 listen(listenSocket:socketManager:)] Accepted HTTP connection from: 192.168.1.35:53474
[2019-03-01T09:35:42.417Z] [DEBUG] [IncomingSocketHandler.swift:114 init(socket:using:)] Socket connection 9 established
[2019-03-01T09:35:42.417Z] [DEBUG] [IncomingSocketHandler.swift:158 handleRead()] Read 160 bytes from socket 9
[2019-03-01T09:35:42.417Z] [DEBUG] [IncomingSocketHandler.swift:158 handleRead()] Read 0 bytes from socket 9
[2019-03-01T09:35:42.417Z] [DEBUG] [IncomingHTTPSocketProcessor.swift:137 process] Processing buffer of size 160 for socket 9
[2019-03-01T09:35:42.417Z] [DEBUG] [IncomingHTTPSocketProcessor.swift:241 parse(_:from:completeBuffer:)] HTTP parser parsed 160 out of 160 bytes for socket 9
[2019-03-01T09:35:42.417Z] [DEBUG] [IncomingHTTPSocketProcessor.swift:242 parse(_:from:completeBuffer:)] Buffered bytes:
POST /post HTTP/1.1
User-Agent: curl/7.35.0
Host: gruffalo10G:8080
Accept: */*
Content-Type: application/raw
Content-Length: 1025
Expect: 100-continue

[2019-03-01T09:35:43.418Z] [DEBUG] [IncomingSocketHandler.swift:158 handleRead()] Read 1025 bytes from socket 9
[2019-03-01T09:35:43.418Z] [DEBUG] [IncomingSocketHandler.swift:158 handleRead()] Read 0 bytes from socket 9
[2019-03-01T09:35:43.418Z] [DEBUG] [IncomingHTTPSocketProcessor.swift:137 process] Processing buffer of size 1025 for socket 9
[2019-03-01T09:35:43.418Z] [DEBUG] [IncomingHTTPSocketProcessor.swift:241 parse(_:from:completeBuffer:)] HTTP parser parsed 1025 out of 1025 bytes for socket 9
[2019-03-01T09:35:43.418Z] [DEBUG] [IncomingHTTPSocketProcessor.swift:242 parse(_:from:completeBuffer:)] Buffered bytes:
1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef1
[2019-03-01T09:35:43.418Z] [VERBOSE] [HTTPServerRequest.swift:333 parsingCompleted()] HTTP request from=192.168.1.35; proto=http;
[2019-03-01T09:35:43.419Z] [DEBUG] [IncomingSocketHandler.swift:337 write(from:)] writing data
[2019-03-01T09:35:43.419Z] [DEBUG] [IncomingSocketHandler.swift:353 write(from:length:)] writing bytes with length 123

Note there is a 1 second delay between the parsing of the first 160 byte transmission (headers) and the second 1025 bytes (body). Kitura-net did not respond to the Expect header, as it was waiting for the message to be completely sent, and curl eventually decided to send it anyway.

djones6 commented 5 years ago

There is a workaround for curl: by explicitly setting an empty Expect header, this feature can be disabled and it'll send the entire payload in one shot:

https://stackoverflow.com/questions/17383089/libcurl-delays-for-1-second-before-uploading-data-command-line-curl-does-not