Skip to content

http keepAliveTimeout triggers while writing large http responses #15082

@tlbtlbtlb

Description

@tlbtlbtlb

While writing a large response, the http keepalive timeout closes the socket after 5 seconds of writing. I can reproduce with 8.0.0 and 8.4.0 on both OSX and Linux.

The documented behavior of http.server.keepAliveTimeout is

The number of milliseconds of inactivity a server needs to wait for additional incoming data, after it has finished writing the last response, before a socket will be destroyed

The script below writes 30 MB of data, but when you use curl to fetch it times out after 5 seconds, having written about 5 MB.

It seems to start the 5 second timer from when the uv_write call happened, not from when uv_write calls the callback.

Here's a server, bigreq.js

const http = require('http');

const server = http.createServer((req, res) => {

  var content = Buffer.alloc(30000000, 0x44);

  res.writeHead(200, {
    'Content-Type': 'application/octet-stream',
    'Content-Length': content.length.toString(),
    'Vary': 'Accept-Encoding'
  });

  var endRc = res.end(content, function() {
    console.log(`bigreq: wrote ${content.length}`);
  });
  console.log(`bigreq: res.end returns ${endRc}`);

  res.end();
});

server.listen(8000);

Start with node bigreq.js. Then run this curl command. The dd bs=1 slows it down to about a MB/sec. After 5 seconds Node closes the connection despite it blasting out data.

curl -v http://london:8000/ | dd bs=1 of=/dev/null
*   Trying 172.17.1.20...
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0* Connected to london (172.17.1.20) port 8000 (#0)
  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0> GET / HTTP/1.1
> Host: london:8000
> User-Agent: curl/7.49.0
> Accept: */*
>
< HTTP/1.1 200 OK
< Content-Type: application/octet-stream
< Content-Length: 36000000
< Vary: Accept-Encoding
< Date: Wed, 30 Aug 2017 00:02:03 GMT
< Connection: keep-alive
<
{ [1279 bytes data]
 14 34.3M   14 5152k    0     0  1026k      0  0:00:34  0:00:05  0:00:29 1029k* transfer closed with 30254505 bytes remaining to read
 15 34.3M   15 5610k    0     0  1022k      0  0:00:34  0:00:05  0:00:29 1024k
* Closing connection 0
curl: (18) transfer closed with 30254505 bytes remaining to read
5745495+0 records in
5745495+0 records out
5745495 bytes transferred in 5.540233 secs (1037049 bytes/sec)

Putting a breakpoint on uv__stream_close, I can see it getting called in the socketOnTimeout logic:

(lldb) v8 bt
 * thread #1: tid = 26063, 0x00000000015fdad1 node`uv__stream_close [inlined] fprintf(__fmt="uv__stream_close(fd=%d)\n", __stream=<unavailable>) at stdio2.h:97, name = 'node', stop reason = breakpoint 1.1
  * frame #0: 0x00000000015fdad1 node`uv__stream_close [inlined] fprintf(__fmt="uv__stream_close(fd=%d)\n", __stream=<unavailable>) at stdio2.h:97
    frame #1: 0x00000000015fdad1 node`uv__stream_close(handle=0x000000000241c488) + 1 at stream.c:1628
    frame #2: 0x00000000015f17c5 node`uv_close(handle=0x000000000241c488, close_cb=<unavailable>) + 261 at core.c:116
    frame #3: 0x00000000013c8dde node`node::HandleWrap::Close(v8::FunctionCallbackInfo<v8::Value> const&) + 158
    frame #4: 0x0000000000a4be02 node`v8::internal::FunctionCallbackArguments::Call(void (*)(v8::FunctionCallbackInfo<v8::Value> const&)) + 274
    frame #5: 0x0000000000acf607 node`v8::internal::MaybeHandle<v8::internal::Object> v8::internal::(anonymous namespace)::HandleApiCallHelper<false>(v8::internal::Isolate*, v8::internal::Handle<v8::internal::HeapObject>, v8::internal::Handle<v8::internal::HeapObject>, v8::internal::Handle<v8::internal::FunctionTemplateInfo>, v8::internal::Handle<v8::internal::Object>, v8::internal::BuiltinArguments) + 407
    frame #6: 0x0000000000acff5e node`v8::internal::Builtin_HandleApiCall(int, v8::internal::Object**, v8::internal::Isolate*) + 206
    frame #7: 0x000032b88e30437d <exit>
    frame #8: 0x000032b88e70eaf0 Socket._destroy(this=0x00000a4e7433ba59:<Object: Socket>, 0x0000392901c02201:<null>, 0x000000d2b3c8bf09:<function: _destroy at internal/streams/destroy.js:32:30>) at net.js:526:37 fn=0x00003dbb38dde0a1
    frame #9: 0x000032b88e70e581 destroy(this=0x00000a4e7433ba59:<Object: Socket>, 0x0000392901c02311:<undefined>, 0x0000392901c02311:<undefined>) at internal/streams/destroy.js:4:17 fn=0x00000328eb47d931
    frame #10: 0x000032b88e30579b <adaptor>
    frame #11: 0x000032b88e726753 socketOnTimeout(this=0x00000a4e7433ba59:<Object: Socket>) at _http_server.js:381:25 fn=0x00002430d86aff31
    frame #12: 0x000032b88e5466dd emitNone(this=0x0000392901c02311:<undefined>, 0x00002430d86aff31:<function: socketOnTimeout at _http_server.js:381:25>, 0x0000392901c023b1:<true>, 0x00000a4e7433ba59:<Object: Socket>) at events.js:103:18 fn=0x00003dbb38d90571
    frame #13: 0x000032b88e56f679 emit(this=0x00000a4e7433ba59:<Object: Socket>, 0x00003321f1d036e1:<String: "timeout">) at events.js:155:44 fn=0x00003321f1d426c1
    frame #14: 0x000032b88e726389 Socket._onTimeout(this=0x00000a4e7433ba59:<Object: Socket>) at net.js:399:39 fn=0x00003dbb38dddcf9
    frame #15: 0x000032b88e725259 ontimeout(this=0x0000392901c02311:<undefined>, 0x00000a4e7433ba59:<Object: Socket>) at timers.js:89:18 fn=0x00003dbb38d93299
    frame #16: 0x000032b88e3e82ab <stub>
    frame #17: 0x000032b88e3baffc tryOnTimeout(this=0x0000392901c02311:<undefined>, 0x00000a4e7433ba59:<Object: Socket>, 0x00000a4e7432a9a1:<Object: TimersList>) at timers.js:89:18 fn=0x00003dbb38d93179
    frame #18: 0x000032b88e724ae8 listOnTimeout(this=0x00000a4e7432a9e9:<Object: Timer>) at timers.js:89:18 fn=0x00003dbb38d93131
    frame #19: 0x000032b88e3b9ed9 <internal>
    frame #20: 0x000032b88e326c2d <entry>
    frame #21: 0x0000000000e650ff node`v8::internal::Execution::Call(v8::internal::Isolate*, v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::Object>, int, v8::internal::Handle<v8::internal::Object>*) + 319
    frame #22: 0x0000000000a2bd21 node`v8::Function::Call(v8::Local<v8::Context>, v8::Local<v8::Value>, int, v8::Local<v8::Value>*) + 417
    frame #23: 0x00000000013bb5bf node`node::AsyncWrap::MakeCallback(v8::Local<v8::Function>, int, v8::Local<v8::Value>*) + 447
    frame #24: 0x000000000143f69b node`node::(anonymous namespace)::TimerWrap::OnTimeout(uv_timer_s*) + 139
    frame #25: 0x00000000015ff305 node`uv__run_timers(loop=0x000000000230b400) + 53 at timer.c:165
    frame #26: 0x00000000015f1d8a node`uv_run(loop=0x000000000230b400, mode=UV_RUN_ONCE) + 826 at core.c:366
    frame #27: 0x00000000013de8f7 node`node::Start(uv_loop_s*, int, char const* const*, int, char const* const*) + 2295
    frame #28: 0x00000000013d8ed3 node`node::Start(int, char**) + 275
    frame #29: 0x00007ffff6b64830 libc.so.6`__libc_start_main(main=(node`main), argc=8, argv=0x00007fffffffe158, init=<unavailable>, fini=<unavailable>, rtld_fini=<unavailable>, stack_end=0x00007fffffffe148) + 240 at libc-start.c:291
    frame #30: 0x0000000000866319 node`_start + 41

Metadata

Metadata

Assignees

No one assigned

    Labels

    confirmed-bugIssues with confirmed bugs.httpIssues or PRs related to the http subsystem.

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions