第六十九期：聊一聊Node程序调试(二)

Node调试日志的核心

了解Node的核心中有哪些内容，对于我们开发应用来说非常有用。

我们还用前两天的那个小项目，稍微改动一下index.js:

const express = require('express')
const routes = require('./routes')
const app = express()

app.get('/', (req, res) => {
  res.send('但是如果有机会的话，也许...')
})

app.listen(3000)

然后我们启动调试，在NODE_DEBUG后面跟上timer:

NODE_DEBUG=timer node index.js

然后在终端你可以看到timer。

然后我们重启一下，这时候带上http

NODE_DEBUG=timer,http node index.js

这时候终端中大致会显示，请求的过程。

这是怎么一回事儿呢

NODE_DEBUG 这个环境变量可以设置为下面几个标识的组合：

• http
• net
• tls
• stream
• module
• timer
• cluster
• child_process
• fs

上面的例子中，我们只启用了timer和http。

当我们将NODE_DEBUG设置为timer时，第一条日志消息表明它正在创建一个长度为120000的列表。我们的代码传递120000作为传递给setTimeout的第二个参数，在内部，第一个参数（超时回调）被添加到一个回调队列中，该队列应在120000毫秒后运行。接下来，我们看到一条消息，timeout callback 5000，这意味着现在将调用每5000毫秒的超时回调。

大多数HTTP输出都是可以直接看明白的。我们可以看到何时与服务器建立了新连接，何时消息结束，何时套接字关闭。剩下的两条神秘消息是write ret=true和SERVER socketOnParserExecute 78。

write ret=true与服务器尝试写入套接字的时间有关。如果该值为false，则意味着套接字已关闭，服务器将（再次在内部）开始处理该场景。至于socketOnParserExecute消息，这需要使用节点的内部HTTP解析器（用C++写的，数字78是从客户端发送到服务器的头的字符串长度。

多个标识的组合对我们来说非常有用。我们将NODE_DEBUG设置为timer，http，这样我们能够看到http模块如何与内部计时器模块交互。我们可以在服务器上看到新的http连接消息，设置了两个时间间隔（基于创建的超时列表），一个是120000毫秒（两分钟，默认套接字超时），另一个（在示例中）是146毫秒。

第二个间隔（146）与HTTP日期头的内部缓存机制有关。由于日期头中的最小单位是秒，因此会为下一秒之前剩余的毫秒数设置超时，并为该秒的剩余时间向日期头提供相同的字符串。

设置自己调试标识

核心模块倾向于使用util包的方法去创建日志方法，将日志信息写入标准输出STDOUT中。

我们也可以使用util.debuglog()方法创建我们自己的调试标识。

// require('cute-stack')()
const express = require('express')
const routes = require('./routes')
const app = express()
const stylus = require('stylus')
const util = require('util')
// 自己的调试标识
const debug = util.debuglog('terrence')

debug('但是如果有机会的话，也许...')
app.get('/', (req, res) => {
  debug('但是如果有机会的话，也许...', req)
  res.send('但是如果有机会的话，也许...')
})

app.listen(3000)

启动项目，

NODE_DEBUG=terrene node index.js

我们就可以看到自己的标识。