From 4bcbb3b0bc03033b24aa49667b28d1c194403a29 Mon Sep 17 00:00:00 2001 From: Jonathan Stewmon Date: Thu, 19 Jul 2018 16:04:49 -0500 Subject: [PATCH 1/7] feat: add timeouts for lookup and response events - Refactor timed-out to optimistically defer errors until after the poll phase of the current event loop tick. - Timeouts begin and end when their respective phase of the lifecycle begins and ends. - Timeouts result in a `got.TimeoutError` --- readme.md | 8 +- source/errors.js | 9 ++ source/request-as-event-emitter.js | 28 +++-- source/timed-out.js | 169 +++++++++++++++++----------- test/timeout.js | 170 +++++++++++++++++++++++++---- 5 files changed, 283 insertions(+), 101 deletions(-) diff --git a/readme.md b/readme.md index 5e20aaf6d..b41e0e2d8 100644 --- a/readme.md +++ b/readme.md @@ -188,7 +188,13 @@ Type: `number` `Object` Milliseconds to wait for the server to end the response before aborting request with `ETIMEDOUT` error (a.k.a. `request` property). By default there's no timeout. -This also accepts an object with separate `connect`, `socket`, and `request` fields for connection, socket, and entire request timeouts. +This also accepts an object with separate `lookup`, `connect`, `socket`, `response` and `request` fields to specify granular timeouts for each phase of the request. + +- `lookup` starts when a socket is assigned and ends when the hostname has been resolved. Does not apply when using a unix domain socket. +- `connect` starts when `lookup` completes (or when the socket is assigned if lookup does not apply to the request) and ends when the socket is connected. +- `socket` starts when the socket is connected. See [request.setTimeout](https://nodejs.org/api/http.html#http_request_settimeout_timeout_callback). +- `response` starts when the socket is connected and ends when the response headers are received. +- `request` starts when the request is initiated and ends when the response's end event fires. ###### retry diff --git a/source/errors.js b/source/errors.js index ad833881f..dff0576f8 100644 --- a/source/errors.js +++ b/source/errors.js @@ -19,6 +19,7 @@ class GotError extends Error { hostname: opts.hostname, method: opts.method, path: opts.path, + socketPath: opts.socketPath, protocol: opts.protocol, url: opts.href }); @@ -89,4 +90,12 @@ module.exports.UnsupportedProtocolError = class extends GotError { } }; +module.exports.TimeoutError = class extends GotError { + constructor(threshold, event, opts) { + super(`Timeout awaiting '${event}' for ${threshold}ms`, {code: 'ETIMEDOUT'}, opts); + this.name = 'TimeoutError'; + this.event = event; + } +}; + module.exports.CancelError = PCancelable.CancelError; diff --git a/source/request-as-event-emitter.js b/source/request-as-event-emitter.js index 0f9f3bc36..7631b5342 100644 --- a/source/request-as-event-emitter.js +++ b/source/request-as-event-emitter.js @@ -10,7 +10,7 @@ const timedOut = require('./timed-out'); const getBodySize = require('./get-body-size'); const getResponse = require('./get-response'); const progress = require('./progress'); -const {CacheError, UnsupportedProtocolError, MaxRedirectsError, RequestError} = require('./errors'); +const {GotError, CacheError, UnsupportedProtocolError, MaxRedirectsError, RequestError} = require('./errors'); const getMethodRedirectCodes = new Set([300, 301, 302, 303, 304, 305, 307, 308]); const allMethodRedirectCodes = new Set([300, 303, 307, 308]); @@ -91,13 +91,11 @@ module.exports = (options = {}) => { return; } - setImmediate(() => { - try { - getResponse(response, options, emitter, redirects); - } catch (error) { - emitter.emit('error', error); - } - }); + try { + getResponse(response, options, emitter, redirects); + } catch (error) { + emitter.emit('error', error); + } }); cacheReq.on('error', error => { @@ -119,10 +117,12 @@ module.exports = (options = {}) => { return; } - const err = new RequestError(error, options); - emitter.emit('retry', err, retried => { + if (!(error instanceof GotError)) { + error = new RequestError(error, options); + } + emitter.emit('retry', error, retried => { if (!retried) { - emitter.emit('error', err); + emitter.emit('error', error); } }); }); @@ -130,12 +130,10 @@ module.exports = (options = {}) => { progress.upload(req, emitter, uploadBodySize); if (options.gotTimeout) { - timedOut(req, options.gotTimeout); + timedOut(req, options); } - setImmediate(() => { - emitter.emit('request', req); - }); + emitter.emit('request', req); }); }; diff --git a/source/timed-out.js b/source/timed-out.js index 0c43bf169..85ceb94d5 100644 --- a/source/timed-out.js +++ b/source/timed-out.js @@ -1,79 +1,120 @@ 'use strict'; +const net = require('net'); +const {TimeoutError} = require('./errors'); -// Forked from https://github.com/floatdrop/timed-out +const reentry = Symbol('reentry'); -module.exports = function (req, delays) { - if (req.timeoutTimer) { - return req; - } - - const host = req._headers ? (' to ' + req._headers.host) : ''; +function addTimeout(delay, callback, ...args) { + // Event loop order is timers, poll, immediates. + // The timed event may emit during the current tick poll phase, so + // defer calling the handler until the poll phase completes. + let immediate; + const timeout = setTimeout( + () => { + immediate = setImmediate(callback, delay, ...args); + if (immediate.unref) { + // Added in node v9.7.0 + immediate.unref(); + } + }, + delay + ); + timeout.unref(); + return () => { + clearTimeout(timeout); + clearImmediate(immediate); + }; +} - function throwESOCKETTIMEDOUT() { - req.abort(); - const e = new Error('Socket timed out on request' + host); - e.code = 'ESOCKETTIMEDOUT'; - req.emit('error', e); +module.exports = function (req, options) { + if (req[reentry]) { + return; } - - function throwETIMEDOUT() { + req[reentry] = true; + const {gotTimeout: delays, host, hostname} = options; + const timeoutHandler = (delay, event) => { req.abort(); - const e = new Error('Connection timed out on request' + host); - e.code = 'ETIMEDOUT'; - req.emit('error', e); - } + req.emit('error', new TimeoutError(delay, event, options)); + }; + const cancelers = []; + const cancelTimeouts = () => { + cancelers.forEach(cancelTimeout => cancelTimeout()); + }; - if (delays.connect !== undefined) { - req.timeoutTimer = setTimeout(throwETIMEDOUT, delays.connect); - } + req.on('error', cancelTimeouts); + req.once('response', response => { + response.once('end', cancelTimeouts); + }); if (delays.request !== undefined) { - req.requestTimeoutTimer = setTimeout(() => { - clear(); - - if (req.connection.connecting) { - throwETIMEDOUT(); - } else { - throwESOCKETTIMEDOUT(); + const cancelTimeout = addTimeout( + delays.request, + timeoutHandler, + 'request' + ); + cancelers.push(cancelTimeout); + } + if (delays.socket !== undefined) { + req.setTimeout( + delays.socket, + () => { + timeoutHandler(delays.socket, 'socket'); } - }, delays.request); + ); } - - // Clear the connection timeout timer once a socket is assigned to the - // request and is connected. - req.on('socket', socket => { - // Socket may come from Agent pool and may be already connected. - if (!socket.connecting) { - connect(); - return; - } - - socket.once('connect', connect); - }); - - function clear() { - if (req.timeoutTimer) { - clearTimeout(req.timeoutTimer); - req.timeoutTimer = null; - } + if (delays.lookup !== undefined && !req.socketPath && !net.isIP(hostname || host)) { + req.once('socket', socket => { + if (socket.connecting) { + const cancelTimeout = addTimeout( + delays.lookup, + timeoutHandler, + 'lookup' + ); + cancelers.push(cancelTimeout); + socket.once('lookup', cancelTimeout); + } + }); } - - function connect() { - clear(); - - if (delays.socket !== undefined) { - // Abort the request if there is no activity on the socket for more - // than `delays.socket` milliseconds. - req.setTimeout(delays.socket, throwESOCKETTIMEDOUT); - } - - req.on('response', res => { - res.on('end', () => { - // The request is finished, cancel request timeout. - clearTimeout(req.requestTimeoutTimer); - }); + if (delays.connect !== undefined) { + req.once('socket', socket => { + if (socket.connecting) { + const timeConnect = () => { + const cancelTimeout = addTimeout( + delays.connect, + timeoutHandler, + 'connect' + ); + cancelers.push(cancelTimeout); + return cancelTimeout; + }; + if (req.socketPath || net.isIP(hostname || host)) { + socket.once('connect', timeConnect()); + } else { + socket.once('lookup', () => { + socket.once('connect', timeConnect()); + }); + } + } + }); + } + if (delays.response !== undefined) { + req.once('socket', socket => { + const timeResponse = () => { + const cancelTimeout = addTimeout( + delays.response, + timeoutHandler, + 'response' + ); + cancelers.push(cancelTimeout); + return cancelTimeout; + }; + if (socket.connecting) { + socket.once('connect', () => { + req.once('response', timeResponse()); + }); + } else { + req.once('response', timeResponse()); + } }); } - - return req.on('error', clear); }; diff --git a/test/timeout.js b/test/timeout.js index fb29a88dd..66091ff43 100644 --- a/test/timeout.js +++ b/test/timeout.js @@ -1,3 +1,5 @@ +import http from 'http'; +import net from 'net'; import getStream from 'get-stream'; import test from 'ava'; import pEvent from 'p-event'; @@ -7,13 +9,24 @@ import {createServer} from './helpers/server'; let s; const reqDelay = 160; +const reqTimeout = reqDelay - 10; +const errorMatcher = { + instanceOf: got.TimeoutError, + code: 'ETIMEDOUT' +}; +const keepAliveAgent = new http.Agent({ + keepAlive: true +}); test.before('setup', async () => { s = await createServer(); s.on('/', async (req, res) => { await delay(reqDelay); - res.statusCode = 200; + res.end('OK'); + }); + + s.on('/prime', (req, res) => { res.end('OK'); }); @@ -27,69 +40,183 @@ test('timeout option (ETIMEDOUT)', async t => { retry: 0 }), { - code: 'ETIMEDOUT' + ...errorMatcher, + message: `Timeout awaiting 'request' for 0ms` } ); }); -test('timeout option (ESOCKETTIMEDOUT)', async t => { +test('timeout option as object (ETIMEDOUT)', async t => { await t.throws( got(s.url, { - timeout: reqDelay, + timeout: {socket: reqDelay * 2.5, request: 1}, retry: 0 }), { - code: 'ESOCKETTIMEDOUT' + ...errorMatcher, + message: `Timeout awaiting 'request' for 1ms` } ); }); -test('timeout option as object (ETIMEDOUT)', async t => { +test('socket timeout', async t => { await t.throws( got(s.url, { - timeout: {socket: reqDelay * 2.5, request: 0}, + timeout: {socket: reqTimeout}, retry: 0 }), { - code: 'ETIMEDOUT' + instanceOf: got.TimeoutError, + code: 'ETIMEDOUT', + message: `Timeout awaiting 'socket' for ${reqTimeout}ms` } ); }); -test('timeout option as object (ESOCKETTIMEDOUT)', async t => { +test('response timeout', async t => { await t.throws( got(s.url, { - timeout: {socket: reqDelay * 1.5, request: reqDelay}, + timeout: {response: 1}, retry: 0 }), { - code: 'ESOCKETTIMEDOUT' + ...errorMatcher, + message: `Timeout awaiting 'response' for 1ms` } ); }); -test('socket timeout', async t => { +test('response timeout (keepalive)', async t => { + await got(`${s.url}/prime`, {agent: keepAliveAgent}); + await delay(100); + const request = got(s.url, { + agent: keepAliveAgent, + timeout: {response: 1}, + retry: 0 + }).on('request', req => { + req.once('socket', socket => { + t.false(socket.connecting); + socket.once('connect', () => { + t.fail(`'connect' event fired, invalidating test`); + }); + }); + }); + await t.throws(request, { + ...errorMatcher, + message: `Timeout awaiting 'response' for 1ms` + }); +}); + +test('connect timeout', async t => { await t.throws( - got(s.url, { - timeout: {socket: reqDelay / 20}, + got({ + host: s.host, + port: s.port, + createConnection: options => { + const socket = new net.Socket(options); + socket.connecting = true; + setImmediate( + socket.emit.bind(socket), + 'lookup', + null, + '127.0.0.1', + 4, + 'localhost' + ); + return socket; + } + }, { + timeout: {connect: 1}, retry: 0 }), { - code: 'ESOCKETTIMEDOUT' + ...errorMatcher, + message: `Timeout awaiting 'connect' for 1ms` } ); }); -test.todo('connection timeout'); +test('connect timeout (ip address)', async t => { + await t.throws( + got({ + hostname: s.address().address, + port: s.port, + createConnection: options => { + const socket = new net.Socket(options); + socket.connecting = true; + return socket; + } + }, { + timeout: {connect: 1}, + retry: 0 + }), + { + ...errorMatcher, + message: `Timeout awaiting 'connect' for 1ms` + } + ); +}); + +test('lookup timeout', async t => { + await t.throws( + got({ + host: s.host, + port: s.port, + lookup: () => { } + }, { + timeout: {lookup: 1}, + retry: 0 + }), + { + ...errorMatcher, + message: `Timeout awaiting 'lookup' for 1ms` + } + ); +}); + +test('lookup timeout no error (ip address)', async t => { + await got({ + hostname: s.address().address, + port: s.port + }, { + timeout: {lookup: 100}, + retry: 0 + }).on('request', request => { + request.on('error', error => { + t.fail(`error emitted: ${error}`); + }); + }); + await delay(100); + t.pass('no error emitted'); +}); + +test('lookup timeout no error (keepalive)', async t => { + await got(`${s.url}/prime`, {agent: keepAliveAgent}); + await got(s.url, { + agent: keepAliveAgent, + timeout: {lookup: 100}, + retry: 0 + }).on('request', request => { + request.once('connect', () => { + t.fail('connect event fired, invalidating test'); + }); + request.on('error', error => { + t.fail(`error emitted: ${error}`); + }); + }); + await delay(100); + t.pass('no error emitted'); +}); test('request timeout', async t => { await t.throws( got(s.url, { - timeout: {request: reqDelay}, + timeout: {request: reqTimeout}, retry: 0 }), { - code: 'ESOCKETTIMEDOUT' + ...errorMatcher, + message: `Timeout awaiting 'request' for ${reqTimeout}ms` } ); }); @@ -98,7 +225,7 @@ test('retries on timeout (ESOCKETTIMEDOUT)', async t => { let tried = false; await t.throws(got(s.url, { - timeout: reqDelay, + timeout: reqTimeout, retry: { retries: () => { if (tried) { @@ -110,7 +237,8 @@ test('retries on timeout (ESOCKETTIMEDOUT)', async t => { } } }), { - code: 'ESOCKETTIMEDOUT' + ...errorMatcher, + message: `Timeout awaiting 'request' for ${reqTimeout}ms` }); t.true(tried); @@ -131,7 +259,7 @@ test('retries on timeout (ETIMEDOUT)', async t => { return 1; } } - }), {code: 'ETIMEDOUT'}); + }), {...errorMatcher}); t.true(tried); }); From 0ff85f5851c582f57b006413009a14f62e2303a0 Mon Sep 17 00:00:00 2001 From: Jonathan Stewmon Date: Mon, 23 Jul 2018 16:44:22 -0500 Subject: [PATCH 2/7] fix: hardcode ipv4 loopback address in tests to appease travis-ci https://docs.travis-ci.com/user/reference/precise/#Networking --- test/timeout.js | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/test/timeout.js b/test/timeout.js index 66091ff43..01c830dae 100644 --- a/test/timeout.js +++ b/test/timeout.js @@ -139,7 +139,7 @@ test('connect timeout', async t => { test('connect timeout (ip address)', async t => { await t.throws( got({ - hostname: s.address().address, + hostname: '127.0.0.1', port: s.port, createConnection: options => { const socket = new net.Socket(options); @@ -176,7 +176,7 @@ test('lookup timeout', async t => { test('lookup timeout no error (ip address)', async t => { await got({ - hostname: s.address().address, + hostname: '127.0.0.1', port: s.port }, { timeout: {lookup: 100}, From a8bee0536d8c7911f5eb0b2a07d256b4e019c892 Mon Sep 17 00:00:00 2001 From: Jonathan Stewmon Date: Tue, 24 Jul 2018 16:31:53 -0500 Subject: [PATCH 3/7] fix: response timer should start when request has been written to the socket --- readme.md | 2 +- source/as-promise.js | 7 ++++++- source/as-stream.js | 9 +++++++-- source/timed-out.js | 25 ++++++++----------------- test/timeout.js | 24 ++++++++++++++++++++++-- 5 files changed, 44 insertions(+), 23 deletions(-) diff --git a/readme.md b/readme.md index b41e0e2d8..61a989a87 100644 --- a/readme.md +++ b/readme.md @@ -193,7 +193,7 @@ This also accepts an object with separate `lookup`, `connect`, `socket`, `respon - `lookup` starts when a socket is assigned and ends when the hostname has been resolved. Does not apply when using a unix domain socket. - `connect` starts when `lookup` completes (or when the socket is assigned if lookup does not apply to the request) and ends when the socket is connected. - `socket` starts when the socket is connected. See [request.setTimeout](https://nodejs.org/api/http.html#http_request_settimeout_timeout_callback). -- `response` starts when the socket is connected and ends when the response headers are received. +- `response` starts when the request has been written to the socket and ends when the response headers are received. - `request` starts when the request is initiated and ends when the response's end event fires. ###### retry diff --git a/source/as-promise.js b/source/as-promise.js index fcd261d2f..1b4ff00b8 100644 --- a/source/as-promise.js +++ b/source/as-promise.js @@ -24,17 +24,22 @@ module.exports = options => { proxy.emit('request', req); + const uploadComplete = () => { + req.emit('upload-complete'); + }; + onCancel(() => { req.abort(); }); if (is.nodeStream(options.body)) { + options.body.once('end', uploadComplete); options.body.pipe(req); options.body = undefined; return; } - req.end(options.body); + req.end(options.body, uploadComplete); }); emitter.on('response', async response => { diff --git a/source/as-stream.js b/source/as-stream.js index 35f14c589..501da2bad 100644 --- a/source/as-stream.js +++ b/source/as-stream.js @@ -28,23 +28,28 @@ module.exports = options => { emitter.on('request', req => { proxy.emit('request', req); + const uploadComplete = () => { + req.emit('upload-complete'); + }; if (is.nodeStream(options.body)) { + options.body.once('end', uploadComplete); options.body.pipe(req); return; } if (options.body) { - req.end(options.body); + req.end(options.body, uploadComplete); return; } if (options.method === 'POST' || options.method === 'PUT' || options.method === 'PATCH') { + input.once('end', uploadComplete); input.pipe(req); return; } - req.end(); + req.end(uploadComplete); }); emitter.on('response', response => { diff --git a/source/timed-out.js b/source/timed-out.js index 85ceb94d5..a4ebf3479 100644 --- a/source/timed-out.js +++ b/source/timed-out.js @@ -98,23 +98,14 @@ module.exports = function (req, options) { }); } if (delays.response !== undefined) { - req.once('socket', socket => { - const timeResponse = () => { - const cancelTimeout = addTimeout( - delays.response, - timeoutHandler, - 'response' - ); - cancelers.push(cancelTimeout); - return cancelTimeout; - }; - if (socket.connecting) { - socket.once('connect', () => { - req.once('response', timeResponse()); - }); - } else { - req.once('response', timeResponse()); - } + req.once('upload-complete', () => { + const cancelTimeout = addTimeout( + delays.response, + timeoutHandler, + 'response' + ); + cancelers.push(cancelTimeout); + return cancelTimeout; }); } }; diff --git a/test/timeout.js b/test/timeout.js index 01c830dae..8d236a6aa 100644 --- a/test/timeout.js +++ b/test/timeout.js @@ -1,6 +1,8 @@ +import fs from 'fs'; import http from 'http'; import net from 'net'; import getStream from 'get-stream'; +import SlowStream from 'slow-stream'; import test from 'ava'; import pEvent from 'p-event'; import delay from 'delay'; @@ -22,8 +24,11 @@ test.before('setup', async () => { s = await createServer(); s.on('/', async (req, res) => { - await delay(reqDelay); - res.end('OK'); + req.pipe(fs.createWriteStream('/dev/null')); + req.on('end', async () => { + await delay(reqDelay); + res.end('OK'); + }); }); s.on('/prime', (req, res) => { @@ -86,6 +91,21 @@ test('response timeout', async t => { ); }); +test('response timeout (slow upload)', async t => { + const body = fs.createReadStream('/dev/urandom', { + end: (1 << 20) + }).pipe(new SlowStream({maxWriteInterval: 100})); + await got(s.url, { + timeout: {response: reqDelay * 2}, + retry: 0, + body + }).on('error', error => { + t.fail(`unexpected error: ${error}`); + }); + await delay(100); + t.pass('no error emitted'); +}); + test('response timeout (keepalive)', async t => { await got(`${s.url}/prime`, {agent: keepAliveAgent}); await delay(100); From e54cc20e8509549d0dec455203ee6528d54ad424 Mon Sep 17 00:00:00 2001 From: Jonathan Stewmon Date: Tue, 24 Jul 2018 16:34:05 -0500 Subject: [PATCH 4/7] fix: remove connect timeout from retry tests to mitigate false-negatives --- test/retry.js | 11 +++++------ 1 file changed, 5 insertions(+), 6 deletions(-) diff --git a/test/retry.js b/test/retry.js index a25c7a8b4..ed4d3356a 100644 --- a/test/retry.js +++ b/test/retry.js @@ -10,7 +10,6 @@ let fifth = 0; let lastTried413access = Date.now(); const retryAfterOn413 = 2; -const connectTimeout = 500; const socketTimeout = 100; test.before('setup', async () => { @@ -69,12 +68,12 @@ test.before('setup', async () => { }); test('works on timeout error', async t => { - t.is((await got(`${s.url}/knock-twice`, {timeout: {connect: connectTimeout, socket: socketTimeout}})).body, 'who`s there?'); + t.is((await got(`${s.url}/knock-twice`, {timeout: {socket: socketTimeout}})).body, 'who`s there?'); }); test('can be disabled with option', async t => { const err = await t.throws(got(`${s.url}/try-me`, { - timeout: {connect: connectTimeout, socket: socketTimeout}, + timeout: {socket: socketTimeout}, retry: 0 })); t.truthy(err); @@ -83,7 +82,7 @@ test('can be disabled with option', async t => { test('function gets iter count', async t => { await got(`${s.url}/fifth`, { - timeout: {connect: connectTimeout, socket: socketTimeout}, + timeout: {socket: socketTimeout}, retry: { retries: iteration => iteration < 10 } @@ -93,7 +92,7 @@ test('function gets iter count', async t => { test('falsy value prevents retries', async t => { const err = await t.throws(got(`${s.url}/long`, { - timeout: {connect: connectTimeout, socket: socketTimeout}, + timeout: {socket: socketTimeout}, retry: { retries: () => 0 } @@ -103,7 +102,7 @@ test('falsy value prevents retries', async t => { test('falsy value prevents retries #2', async t => { const err = await t.throws(got(`${s.url}/long`, { - timeout: {connect: connectTimeout, socket: socketTimeout}, + timeout: {socket: socketTimeout}, retry: { retries: (iter, err) => { t.truthy(err); From 77a96c98a62ed5099a1a3b105540a4807669defa Mon Sep 17 00:00:00 2001 From: Jonathan Stewmon Date: Tue, 24 Jul 2018 16:43:56 -0500 Subject: [PATCH 5/7] feat: add send timeout --- readme.md | 1 + source/timed-out.js | 20 ++++++++++++++++++++ test/timeout.js | 13 +++++++++++++ 3 files changed, 34 insertions(+) diff --git a/readme.md b/readme.md index 61a989a87..07e52d06e 100644 --- a/readme.md +++ b/readme.md @@ -194,6 +194,7 @@ This also accepts an object with separate `lookup`, `connect`, `socket`, `respon - `connect` starts when `lookup` completes (or when the socket is assigned if lookup does not apply to the request) and ends when the socket is connected. - `socket` starts when the socket is connected. See [request.setTimeout](https://nodejs.org/api/http.html#http_request_settimeout_timeout_callback). - `response` starts when the request has been written to the socket and ends when the response headers are received. +- `send` starts when the socket is connected and ends with the request has been written to the socket. - `request` starts when the request is initiated and ends when the response's end event fires. ###### retry diff --git a/source/timed-out.js b/source/timed-out.js index a4ebf3479..441c10674 100644 --- a/source/timed-out.js +++ b/source/timed-out.js @@ -97,6 +97,26 @@ module.exports = function (req, options) { } }); } + if (delays.send !== undefined) { + req.once('socket', socket => { + const timeRequest = () => { + const cancelTimeout = addTimeout( + delays.send, + timeoutHandler, + 'send' + ); + cancelers.push(cancelTimeout); + return cancelTimeout; + }; + if (socket.connecting) { + socket.once('connect', () => { + req.once('upload-complete', timeRequest()); + }); + } else { + req.once('upload-complete', timeRequest()); + } + }); + } if (delays.response !== undefined) { req.once('upload-complete', () => { const cancelTimeout = addTimeout( diff --git a/test/timeout.js b/test/timeout.js index 8d236a6aa..2167f4735 100644 --- a/test/timeout.js +++ b/test/timeout.js @@ -78,6 +78,19 @@ test('socket timeout', async t => { ); }); +test('send timeout', async t => { + await t.throws( + got(s.url, { + timeout: {send: 1}, + retry: 0 + }), + { + ...errorMatcher, + message: `Timeout awaiting 'send' for 1ms` + } + ); +}); + test('response timeout', async t => { await t.throws( got(s.url, { From 09753722ca2bffeb7f3bf7f44070b3e2c60d7f47 Mon Sep 17 00:00:00 2001 From: Jonathan Stewmon Date: Tue, 24 Jul 2018 22:32:16 -0500 Subject: [PATCH 6/7] fix: response timer should cancel on response - add response timeout tests for slow upload and download - add send test with keepalive - increase timeouts to mitigate intermittent false negatives --- source/timed-out.js | 2 +- test/retry.js | 2 +- test/timeout.js | 78 ++++++++++++++++++++++++++++++++++++++------- 3 files changed, 68 insertions(+), 14 deletions(-) diff --git a/source/timed-out.js b/source/timed-out.js index 441c10674..aeb51343e 100644 --- a/source/timed-out.js +++ b/source/timed-out.js @@ -125,7 +125,7 @@ module.exports = function (req, options) { 'response' ); cancelers.push(cancelTimeout); - return cancelTimeout; + req.once('response', cancelTimeout); }); } }; diff --git a/test/retry.js b/test/retry.js index ed4d3356a..364097bbc 100644 --- a/test/retry.js +++ b/test/retry.js @@ -10,7 +10,7 @@ let fifth = 0; let lastTried413access = Date.now(); const retryAfterOn413 = 2; -const socketTimeout = 100; +const socketTimeout = 200; test.before('setup', async () => { s = await createServer(); diff --git a/test/timeout.js b/test/timeout.js index 2167f4735..309dfab28 100644 --- a/test/timeout.js +++ b/test/timeout.js @@ -1,8 +1,7 @@ -import fs from 'fs'; import http from 'http'; import net from 'net'; +import stream from 'stream'; import getStream from 'get-stream'; -import SlowStream from 'slow-stream'; import test from 'ava'; import pEvent from 'p-event'; import delay from 'delay'; @@ -10,7 +9,19 @@ import got from '../source'; import {createServer} from './helpers/server'; let s; -const reqDelay = 160; +const reqDelay = 250; +const slowDataStream = () => { + const slowStream = new stream.PassThrough(); + let count = 0; + const interval = setInterval(() => { + if (count++ < 10) { + return slowStream.push('data\n'.repeat(100)); + } + clearInterval(interval); + slowStream.push(null); + }, 100); + return slowStream; +}; const reqTimeout = reqDelay - 10; const errorMatcher = { instanceOf: got.TimeoutError, @@ -24,13 +35,21 @@ test.before('setup', async () => { s = await createServer(); s.on('/', async (req, res) => { - req.pipe(fs.createWriteStream('/dev/null')); + req.on('data', () => {}); req.on('end', async () => { await delay(reqDelay); res.end('OK'); }); }); + s.on('/download', async (req, res) => { + res.writeHead(200, { + 'transfer-encoding': 'chunked' + }); + res.flushHeaders(); + slowDataStream().pipe(res); + }); + s.on('/prime', (req, res) => { res.end('OK'); }); @@ -91,6 +110,29 @@ test('send timeout', async t => { ); }); +test('send timeout (keepalive)', async t => { + await got(`${s.url}/prime`, {agent: keepAliveAgent}); + await t.throws( + got(s.url, { + agent: keepAliveAgent, + timeout: {send: 1}, + retry: 0, + body: slowDataStream() + }).on('request', req => { + req.once('socket', socket => { + t.false(socket.connecting); + socket.once('connect', () => { + t.fail(`'connect' event fired, invalidating test`); + }); + }); + }), + { + ...errorMatcher, + message: `Timeout awaiting 'send' for 1ms` + } + ); +}); + test('response timeout', async t => { await t.throws( got(s.url, { @@ -104,18 +146,30 @@ test('response timeout', async t => { ); }); -test('response timeout (slow upload)', async t => { - const body = fs.createReadStream('/dev/urandom', { - end: (1 << 20) - }).pipe(new SlowStream({maxWriteInterval: 100})); +test('response timeout unaffected by slow upload', async t => { await got(s.url, { timeout: {response: reqDelay * 2}, retry: 0, - body - }).on('error', error => { - t.fail(`unexpected error: ${error}`); + body: slowDataStream() + }).on('request', request => { + request.on('error', error => { + t.fail(`unexpected error: ${error}`); + }); }); - await delay(100); + await delay(reqDelay * 3); + t.pass('no error emitted'); +}); + +test('response timeout unaffected by slow download', async t => { + await got(`${s.url}/download`, { + timeout: {response: 100}, + retry: 0 + }).on('request', request => { + request.on('error', error => { + t.fail(`unexpected error: ${error}`); + }); + }); + await delay(reqDelay * 3); t.pass('no error emitted'); }); From caae92111a3f612bd7813db21d4447fc536247be Mon Sep 17 00:00:00 2001 From: Sindre Sorhus Date: Wed, 25 Jul 2018 11:43:07 +0700 Subject: [PATCH 7/7] Update readme.md --- readme.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/readme.md b/readme.md index 07e52d06e..a988c4d2b 100644 --- a/readme.md +++ b/readme.md @@ -190,7 +190,7 @@ Milliseconds to wait for the server to end the response before aborting request This also accepts an object with separate `lookup`, `connect`, `socket`, `response` and `request` fields to specify granular timeouts for each phase of the request. -- `lookup` starts when a socket is assigned and ends when the hostname has been resolved. Does not apply when using a unix domain socket. +- `lookup` starts when a socket is assigned and ends when the hostname has been resolved. Does not apply when using a Unix domain socket. - `connect` starts when `lookup` completes (or when the socket is assigned if lookup does not apply to the request) and ends when the socket is connected. - `socket` starts when the socket is connected. See [request.setTimeout](https://nodejs.org/api/http.html#http_request_settimeout_timeout_callback). - `response` starts when the request has been written to the socket and ends when the response headers are received.