node中请求超时的一些坑

Posted on May 2, 2020

背景

近期在做一个dns服务器切换的演练中出现了如下场景: op重启主dns服务器，期望服务访问经由另外一台从dns服务器进行解析，对线上服务无影响。但实际情况是nodejs服务耗时增加，且出现了部分502。nodejs作为站点渲染层收到请求后会利用axios库向下游服务发起http请求。我们正常情况下计算了进出nodejs的耗时大概在80毫秒以下，但是在重启主dns服务器的时间段内，nodejs耗时超过了1～3分钟。下游服务（java）耗时没有明显增加。

node版本10.16.3，axios使用版本0.19.2，请求下游服务有设置timeout: 3000，但是并未生效。所以本篇借着axios的实现说明一下在node中http模块的timeout有什么需要注意的地方。我们期待的是经过axios传递了timeout参数不论是dns查询还是tcp链接超时都能命中，但目前看并非这样。

准备工作

步骤1: 需要一个resolver.js提供dns解析能力，用来模拟慢dns查询的情况，这段代码主要来自于网络，连域名都没有改。我加了一个sleep函数是为了模拟3秒慢查询。代码如下

// The regular expression keyword in domain name.
const domain = /hursing/;
// When keyword matched, resolve to this IP.
const targetIp = '127.0.0.1';
// 这里写你原本的dns服务器地址作为备选
const fallbackServer = '192.168.1.1';

const dgram = require('dgram');
const server = dgram.createSocket('udp4');

let block = false;

function copyBuffer(src, offset, dst) {
    for (let i = 0; i < src.length; ++i) {
        dst.writeUInt8(src.readUInt8(i), offset + i)
    }
}

function resolve(msg, rinfo) {
    if (!block) {
        block = true;
        console.log('本次dns查询阻塞3秒');
        sleep(3);
    }

    const queryInfo = msg.slice(12);
    const response = Buffer.alloc(28 + queryInfo.length);
    let offset = 0;
    const id = msg.slice(0, 2);
    copyBuffer(id, 0, response);  // Transaction ID
    offset += id.length;
    response.writeUInt16BE(0x8180, offset);  // Flags
    offset += 2;
    response.writeUInt16BE(1, offset);  // Questions
    offset += 2;
    response.writeUInt16BE(1, offset);  // Answer RRs
    offset += 2;
    response.writeUInt32BE(0, offset);  // Authority RRs & Additional RRs
    offset += 4;
    copyBuffer(queryInfo, offset, response);
    offset += queryInfo.length;
    response.writeUInt16BE(0xC00C, offset);  // offset to domain name
    offset += 2;
    const typeAndClass = msg.slice(msg.length - 4);
    copyBuffer(typeAndClass, offset, response);
    offset += typeAndClass.length;
    response.writeUInt32BE(600, offset);  // TTL, in seconds
    offset += 4;
    response.writeUInt16BE(4, offset);  // Length of IP
    offset += 2;
    targetIp.split('.').forEach(value => {
        response.writeUInt8(parseInt(value), offset);
        offset += 1
    });
    // console.log(response.toString('hex'))
    server.send(response, rinfo.port, rinfo.address, (err) => {
        if (err) {
            console.error(err);
            server.close();
        }
        block = false;
    })
}

function forward(msg, rinfo) {
    const client = dgram.createSocket('udp4');
    client.on('error', (err) => {
        console.log(`client error:\n${err.stack}`);
        client.close()
    });
    client.on('message', (fbMsg, fbRinfo) => {
        server.send(fbMsg, rinfo.port, rinfo.address, (err) => {
            err && console.log(err)
        });
        client.close()
    });
    client.send(msg, 53, fallbackServer, (err) => {
        if (err) {
            console.log(err);
            client.close()
        }
    })
}

function parseHost(msg) {
    let num = msg.readUInt8(0);
    let offset = 1;
    let host = '';
    while (num !== 0) {
        host += msg.slice(offset, offset + num).toString();
        offset += num;
        num = msg.readUInt8(offset);
        offset += 1;
        if (num !== 0) {
            host += '.'
        }
    }
    return host
}

function sleep(duration) {
    let s = Date.now();
    duration *= 1000;
    while (Date.now() - s < duration) {}
}

server.on('message', (msg, rinfo) => {
    // console.log(msg.toString())
    const host = parseHost(msg.slice(12));
    console.log(`receive query: ${host}`);
    if (domain.test(host)) {
        console.log(`receive query: ${JSON.stringify(rinfo)}`);
        resolve(msg, rinfo);
    } else {
        forward(msg, rinfo)
    }
});

server.on('error', (err) => {
    console.log(`server error:\n${err.stack}`);
    server.close()
});

server.on('listening', () => {
    const address = server.address();
    // 0.0.0.0:53
    console.log(`server listening ${address.address}:${address.port}`)
});

// On linux or Mac, run node with sudo. Because port 53 is lower then 1024.
server.bind(53);

启动 node resolver.js。在Mac OS上，需要通过网络设置将dns解析从之前的ip换成127.0.0.1。完成之后可以通过浏览器正常访问任何网页，就能看到resolver.js打印的日志。

步骤2: 提供一个正常的http服务器server.js，代码如下

const http = require('http');

const hostname = '127.0.0.1';
const port = 3000;

const server = http.createServer((req, res) => {
    res.statusCode = 200;
    res.setHeader('Content-Type', 'text/plain');
    res.end('Hello, World!\n');
});

server.listen(port, hostname, () => {
    console.log(`Server running at http://${hostname}:${port}/`);
});

启动服务器node server.js。此时如果通过浏览器访问http://hursing.com:3000/这样的地址就可以观测到网页的打开速度很慢，而时间就消耗在dns查询的3秒上。

注意: 每次访问一个地址过后，如果短时间内再次访问会发现dns解析的日志不会打出来，这是因为mac系统有一些自己的dns缓存策略，我通过每次访问后执行 sudo killall -HUP mDNSResponder 来清除系统的dns缓存，其他的系统可能也会出现这样的问题，需要各自解决。

步骤3: 还需要一个node的http客户端，第一版client.js代码如下

const http = require('http');
const TIMEOUT = +process.env.TIMEOUT || 1000;

console.log(`设置的超时时间为: ${TIMEOUT}毫秒`);
let s = Date.now();
console.log(`请求时间为: ${s}`);

const req = http.request('http://hursing.com:3000/', {
    timeout: TIMEOUT
}, res => {
        console.log(`STATUS: ${res.statusCode}`);
        console.log(`HEADERS: ${JSON.stringify(res.headers)}`);
        res
            .setEncoding('utf8')
            .on('data', chunk => {
                console.log(`BODY: ${chunk}`);
            }).on('end', () => {
                console.log(`响应结束. ${Date.now() - s}`);
            });
    })
    .on('socket', socket => {
        console.error(`on绑定的socket事件触发: ${Date.now() - s}`);
    })
    .on('timeout', () => {
        console.error(`on绑定的timeout事件触发: ${Date.now() - s}`);
    })
    .on('error', (err) => {
        console.error(`problem with request: ${err.message}`);
    });

req.end();

这第一版的代码和axios的实现不同，我利用ClientRequest支持的配置属性timeout指定了一个超时时间，默认1秒。运行node client.js后发现1秒后timeout事件被触发，也就是说，如果axios按照这样的方式通过构造函数传入timeout则dns的解析超时也可以被检测到。

查看axios代码得知

// Handle request timeout
if (config.timeout) {
    // Sometime, the response will be very slow, and does not respond, the connect event will be block by event loop system.
    // And timer callback will be fired, and abort() will be invoked before connection, then get "socket hang up" and code ECONNRESET.
    // At this time, if we have a large number of request, nodejs will hang up some socket on background. and the number will up and up.
    // And then these socket which be hang up will devoring CPU little by little.
    // ClientRequest.setTimeout will be fired on the specify milliseconds, and can make sure that abort() will be fired after connect.
    req.setTimeout(config.timeout, function handleRequestTimeout() {
        req.abort();
        reject(createError('timeout of ' + config.timeout + 'ms exceeded', config, 'ECONNABORTED', req));
    });
}

axios通过ClientRequest实例的setTimeout设定了超时时间。为此将client.js稍作修改更名为client2.js，代码如下

const http = require('http');
const TIMEOUT = +process.env.TIMEOUT || 1000;

console.log(`设置的超时时间为: ${TIMEOUT}毫秒`);
let s = Date.now();
console.log(`请求时间为: ${s}`);

const req = http.request('http://hursing.com:3000/', 
    res => {
        console.log(`STATUS: ${res.statusCode}`);
        console.log(`HEADERS: ${JSON.stringify(res.headers)}`);
        res
            .setEncoding('utf8')
            .on('data', chunk => {
                console.log(`BODY: ${chunk}`);
            }).on('end', () => {
                console.log(`响应结束. ${Date.now() - s}`);
            });
    })
    .on('socket', socket => {
        console.error(`on绑定的socket事件触发: ${Date.now() - s}`);
    })
    .on('error', (err) => {
        console.error(`problem with request: ${err.message}`);
    });

req.setTimeout(TIMEOUT, () => {
    console.error(`req.setTimeout绑定的timeout事件触发: ${Date.now() - s}`)
});

req.end();

这第二版的代码和axios的实现就一致了。运行node client2.js发现1秒后timeout的回调函数没有被执行，3秒多后打印出了收到的响应全文，复现成功。

排查

根据第一版client.js的实现，http.request调用会返回ClientRequest的实例，初始化实例的时候利用了一个agent对象管理socket复用和事件通知等逻辑。详情可以看node源码的lib/_http_client.js文件。而agent对象在addRequest方法中有2个地方会根据ClientRequest的构造函数配置项的timeout属性调用socket.setTimeout，见lib/_http_agent.js的setRequestSocket方法。而socket.setTimeout代码如下：

Socket.prototype.setTimeout = function(msecs, callback) {
  this.timeout = msecs;
  // Type checking identical to timers.enroll()
  msecs = validateTimerDuration(msecs);

  // Attempt to clear an existing timer in both cases -
  //  even if it will be rescheduled we don't want to leak an existing timer.
  clearTimeout(this[kTimeout]);

  console.log(`### Socket.setTimeout. ${msecs}, callback是: ${typeof callback}, ${this[kTimeout]}`);

  if (msecs === 0) {
    if (callback) {
      this.removeListener('timeout', callback);
    }
  } else {
    console.log(`### Socket.setTimeout. 当前时间 ${Date.now()}`);
    this[kTimeout] = setUnrefTimeout(this._onTimeout.bind(this), msecs);

    if (callback) {
      this.once('timeout', callback);
    }
  }
  return this;
};

代码中调用的_onTimeout代码如下：

Socket.prototype._onTimeout = function() {
  const handle = this._handle;
  const lastWriteQueueSize = this[kLastWriteQueueSize];
  console.log(`### Socket._onTimeout will trigger timeout#1`);
  if (lastWriteQueueSize > 0 && handle) {
    // `lastWriteQueueSize !== writeQueueSize` means there is
    // an active write in progress, so we suppress the timeout.
    const { writeQueueSize } = handle;
    if (lastWriteQueueSize !== writeQueueSize) {
      this[kLastWriteQueueSize] = writeQueueSize;
      this._unrefTimer();
      return;
    }
  }
  debug('_onTimeout');
  console.log(`### Socket._onTimeout will trigger timeout#2`);
  this.emit('timeout');
};

由此可知，通过ClientRequest构造函数传递进来的timeout可以在第一时间绑定计时器，此时还没有开始dns的查询和socket的连接动作。这也就解释了为什么client.js通过构造函数设置的timeout可以满足dns满查询下仍然断掉请求并且报错的原因。我在node中加了一些日志后重新编译，运行~/custom-node/out/Release/node client.js得到如下的日志结果（注 加日志的整个过程是在梳理了源码的调用关系后，知道了每个函数具体实现，这里面比较细碎不单独说明）

设置的超时时间为: 1000毫秒
请求时间为: 1588392229021
### ClientRequest 初始化开始
### Socket.setTimeout. 1000, callback是: undefined, null
### Socket.setTimeout. 当前时间 1588392229024
### Socket.setTimeout. 1000, callback是: undefined, [object Object]
### Socket.setTimeout. 当前时间 1588392229034
### ClientRequest 初始化完毕, 耗时 13
### listenSocketTimeout, req - null
on绑定的socket事件触发: 15
### Socket._onTimeout will trigger timeout#1
### Socket._onTimeout will trigger timeout#2
on绑定的timeout事件触发: 1015
STATUS: 200
HEADERS: {"content-type":"text/plain","date":"Sat, 02 May 2020 04:03:52 GMT","connection":"close","content-length":"14"}
BODY: Hello, World!

响应结束. 3019
### Socket.setTimeout. 0, callback是: undefined, [object Object]

可以看出，首先ClientRequest的初始化时间很微小，而在初始化的时候就调用了socket.setTimeout方法，此时socket对象已经存在但是还没有开始dns查询和建立连接过程。而on绑定的timeout事件触发: 1015这行说明了1秒后即便dns查询没有完成，但是由于定时器时间已到，所以仍然触发了timeout事件。由于我们在timeout事件监听的函数里没做任何处理，所以client.js仍然会等到响应完毕，可以看到最后的时间是3秒多一点，也就是整个过程基本浪费在dns查询。

再来看client2.js里面用到的request.setTimeout方法。见lib/_http_client.js文件：

ClientRequest.prototype.setTimeout = function setTimeout(msecs, callback) {
  if (this._ended) {
    return this;
  }

  listenSocketTimeout(this);
  msecs = validateTimerDuration(msecs);
  if (callback) this.once('timeout', callback);

  console.log(`### ClientRequest.setTimeout. this.socket为: ${this.socket}, 当前时间 ${Date.now()}`);

  if (this.socket) {
    setSocketTimeout(this.socket, msecs);
  } else {
    this.once('socket', (sock) => {
      console.log(`### ClientRequest.setTimeout. 当前时间 ${Date.now()}`);
      setSocketTimeout(sock, msecs)
    });
  }

  return this;
};

在首次调用request.setTimeout的时候，socket对象没有存在于request对象上，所以程序会等待socket事件发生后调用setSocketTimeout方法。再来看setSocketTimeout方法：

function setSocketTimeout(sock, msecs) {
  if (sock.connecting) {
    sock.once('connect', function() {
      console.log(`### socket connect事件触发, 当前时间 ${Date.now()}`);
      sock.setTimeout(msecs);
    });
  } else {
    sock.setTimeout(msecs);
  }
}

这里面在socket对象生成后先判断其connecting状态，根据状态调用socket.setTimeout方法。那么socket的connecting状态是什么意义呢，代码如下：

Socket.prototype.connect = function(...args) {
  let normalized;
  // If passed an array, it's treated as an array of arguments that have
  // already been normalized (so we don't normalize more than once). This has
  // been solved before in https://github.com/nodejs/node/pull/12342, but was
  // reverted as it had unintended side effects.
  if (Array.isArray(args[0]) && args[0][normalizedArgsSymbol]) {
    normalized = args[0];
  } else {
    normalized = normalizeArgs(args);
  }
  var options = normalized[0];
  var cb = normalized[1];

  if (this.write !== Socket.prototype.write)
    this.write = Socket.prototype.write;

  if (this.destroyed) {
    this._undestroy();
    this._handle = null;
    this._peername = null;
    this._sockname = null;
  }

  const { path } = options;
  var pipe = !!path;
  debug('pipe', pipe, path);

  if (!this._handle) {
    this._handle = pipe ?
      new Pipe(PipeConstants.SOCKET) :
      new TCP(TCPConstants.SOCKET);
    initSocketHandle(this);
  }

  if (cb !== null) {
    this.once('connect', cb);
  }

  this._unrefTimer();

  this.connecting = true;
  this.writable = true;

  if (pipe) {
    validateString(path, 'options.path');
    defaultTriggerAsyncIdScope(
      this[async_id_symbol], internalConnect, this, path
    );
  } else {
    lookupAndConnect(this, options);
  }
  return this;
};

可以看到，当调用socket.connect的时候会将connecting状态置为true，而后才有了lookupAndConnect的调用，也就是说connecting状态在前，dns查询在后。具体到我们的实际情况可以很容易得到setSocketTimeout方法被调用时socket已经开始建立连接但是连接还没建立完毕，也就是说connecting为真，会在connect事件发生后再去调用socket.setTimeout方法。

结合client2.js的实现，继续打印日志得到如下结果

设置的超时时间为: 1000毫秒
请求时间为: 1588392126469
### ClientRequest 初始化开始
### ClientRequest 初始化完毕, 耗时 12
### listenSocketTimeout, req - null
### ClientRequest.setTimeout. this.socket为: null, 当前时间 1588392126482
on绑定的socket事件触发: 16
### ClientRequest.setTimeout. 当前时间 1588392126485
### socket connect事件触发, 当前时间 1588392129488
### Socket.setTimeout. 1000, callback是: undefined, null
### Socket.setTimeout. 当前时间 1588392129488
STATUS: 200
HEADERS: {"content-type":"text/plain","date":"Sat, 02 May 2020 04:02:09 GMT","connection":"close","content-length":"14"}
BODY: Hello, World!

响应结束. 3023

可以看到socket的connect事件触发时间距离程序开始调用时差了3秒多一点，也就是说connect事件是在dns查询后才会触发，而此时再去绑定socket的timeout事件已经对dns超时情况没有任何意义。这也就是事情的全貌。

结论

axios的timeout参数在0.19.2版本已经不是整个调用过程的超时，其不包含dns.lookup的时间。如果想得到预期的结果可以尝试将axios的timeout参数写成设置初始化ClientRequest的参数。需要提交pr，但是是否有其他的副作用需要社区讨论。

参考

  1. https://medium.com/@amirilovic/how-to-fix-node-dns-issues-5d4ec2e12e95
  2. http://man7.org/linux/man-pages/man5/resolv.conf.5.html
  3. https://github.com/hursing/dns-server
  4. https://github.com/axios/axios/issues/2710
  5. https://github.com/axios/axios/pull/1752
  6. https://nodejs.org/docs/latest-v10.x/api/dns.html

后记

  • 超时dns服务器的实现上，在访问hursing域名的时候发现会收到多次请求，修改/etc/resolv.conf的single-request和attempts属性都无效，因此代码加了block布尔变量逻辑，为的就是模拟单次请求的超时。不这样实现的话，发现多次请求会累积3秒的超时，比如多请求了5次则最后得到响应的时间就是3*5=15秒，我不确定这样的情况是否和线上一致，因为线上我们通过dig命令查看切换dns服务器的事件也就在秒级，但node耗时达到了分钟级别。

  • axios其实还用到了一个follow-redirect的库，根据默认配置会走这个库里面的实现。所以在node client的实现上，我先用axios做了一个对比，设置maxRedirects:0规避这个库带来的额外调试成本，发现不走这个库的逻辑仍然复现线上情况，于是才有了client2.js的简化实现。

  • 关于axios的timeout设置说明已经有了相关的issue和pr，在开始排查之前最好先读一下。我将axios的版本切换到0.19.0，查看lib/adapters/http.js文件，不难发现有以下代码

// Handle request timeout
if (config.timeout) {
    timer = setTimeout(function handleRequestTimeout() {
	    req.abort();
        reject(createError('timeout of ' + config.timeout + 'ms exceeded', config, 'ECONNABORTED', req));
    }, config.timeout);
}

也就是在之前的版本中，超时逻辑完全是axios自己控制的，一旦启动定时器，不论是dns查询还是tcp建联，只要耗时超过了预期就会触发reject并且请求被abort。这样的实现似乎没有问题，但是如果考虑node的事件循环引起的一些边界case，服务端代码可能未能如期。这也正是0.19.2做了这次代码变更的原因：https://github.com/axios/axios/pull/1752。正是因为这次改动，才导致了本文背景中提到的情况。

  • 需要持续关注2874这个pr的讨论，不论是之前的直接定时器是否无法正确释放socket对象导致内存和cpu上涨，还是新的0.19.2的实现都不尽如人意。总体上说构造函数传入timeout的方式虽然完成测试，但是很可能出现和之前版本一样无法释放socket对象的问题，这个问题需要较多条件，我没有在本地继续深入挖掘。

  • dns-lookup-cache这个库利用了ttl缓存，应该可以一定程度解决这个问题，但是没有从根本上解决。如果要替换需要测试，因为底层换了lookup的方法，同时要测试是否对resolv.conf文件生效。结合后记第一项，怀疑node client多次发送查询请求以致于最后的响应时间是Nx解析时间才是node服务耗时呈现分钟级的根本，需要进一步查证，也是一项最重要的TODO。同时需要想办法缩短底层查询时间，比如resolv.conf的options的timeout属性？

Recent Posts
Disclaimer
The views expressed on this blog are my personal views and do not reflect the views of my employer or campaigns I am supporting.