process.exit导致的控制台输出不全

案例程序

for(var i = 0; i < 10000; ++i) {
    console.log("this is long long long long long long long long long long long long long long long long long long long long long long long long long long long long long log " + i);
}
process.exit(0);

这个程序输出 10000 行日志，然后结束进程。

  • Emacs Shell 以及 GNOME Terminal 下运行

    省略中间部分输出 

    $ node /home/tangxinfa/Examples/test_exit.js
this is long long long long long long long long long long long long long long long long long long long long long long long long long long long long long log 0
...
this is long long long long long long long long long long long long long long long long long long long long long long long long long long long long long log 119
$

    程序只输出了前面 200 行日志。

  • 按 Ctrl+Alt+F2 进入 2 号系统终端下运行

    省略中间部分输出 

    $ node /home/tangxinfa/Examples/test_exit.js
this is long long long long long long long long long long long long long long long long long long long long long long long long long long long long long log 0
...
this is long long long long long long long long long long long long long long long long long long long long long long long long long long long long long log 9999
$

    程序输出了全部日志。

  • Emacs Shell 以及 GNOME Terminal 下运行时将日志重定向到文件

    省略中间部分输出 

    $ node /home/tangxinfa/Examples/test_exit.js > /tmp/test_exit.log
$ tail -1 /tmp/test_exit.log
this is long long long long long long long long long long long long long long long long long long long long long long long long long long long long long log 9999
$

    程序输出了全部日志。

  • 原因

    引用自 process.exit(0): output disappears?

    当输出目标为终端或文件时，console 函数是同步的（避免程序过早退出导致丢消息），目标为管道时则为异步（避免长时间堵塞）。

    The console functions are synchronous when the destination is a terminal or a file (to avoid lost messages in case of premature exit) and asynchronous when it's a pipe (to avoid blocking for long periods of time).

    上面这段描述来自 Node.js V0.12 官方文档。

    Emacs Shell 以及 GNOME Terminal 并非真正的终端，所以会丢消息。

解决方案

主要解决问题的思路是要确保调用 process.exit 时标准输出及错误输出中的日志输出完毕。

  • 通过关闭流确保流输出完毕然后再退出

    process.stdout 及 process.stderr 是 Writable 流，通过关闭流确保流输出完毕然后再退出 

    process.stderr.end(function () {
    process.exit(1);
});

    运行以上码会出错 

    events.js:141
      throw er; // Unhandled 'error' event
      ^

Error: process.stderr cannot be closed.
    at WriteStream.stderr.destroy.stderr.destroySoon (node.js:649:20)
    at WriteStream.onSocketFinish (net.js:202:17)
    at emitNone (events.js:67:13)
    at WriteStream.emit (events.js:166:7)
    at finishMaybe (_stream_writable.js:478:14)
    at endWritable (_stream_writable.js:488:3)
    at WriteStream.Writable.end (_stream_writable.js:453:5)
    at WriteStream.Socket.end (net.js:406:31)
    at Object.<anonymous> (/home/tangxinfa/Examples/flush_on_exit.js:1:78)
    at Module._compile (module.js:409:26)

    这是因为 process.stdout 及 process.stderr 比较特殊，不可关闭且无 finish 事件，引用自 process.error 官方文档

    The process.stderr property returns a Writable stream equivalent to or associated with stderr (fd 2).

    Note: process.stderr and process.stdout differ from other Node.js streams in several ways:

    1. They cannot be closed (end() will throw).
    2. They never emit the 'finish' event.

    3. Writes can block when output is redirected to a file.

      Note that disks are fast and operating systems normally employ write-back caching so this is very uncommon.

    4. Writes on UNIX will block by default if output is going to a TTY (a terminal).
    5. Windows functionality differs. Writes block except when output is going to a TTY.

  • 在 write 的回调函数中退出

    writable.write 的 callback 在数据写成功后调用，此时退出可以保证日志消息不丢失。 

    1:   process.stdout.write('', function () {
2:     process.stderr.write('', function () {
3:         process.exit(1);
4:     });
5: });

    需要注意的是，此时的写日志后进程退出是异步的，进程退出前系统可能会在异常状态下运行一小段时间。

    早期的 pm2 版本运行 node.js 应用时，由于它会通过重写 process.stdout.write 和 process.stderr.write 方法，接管标准输出和错误输出，改写后的函数无返回值并忽略传入的回调函数（见 node.js's process.stderr.write or process.stdout.write behavier changed by pm2 #2011），导致进程不退出。可针对 pm2 做特殊处理，使用 pm2 后日志还是会有丢失。 

    if (typeof(process.env.pm_id) == 'undefined') {
    process.stdout.write('', function () {
        process.stderr.write('', function () {
            process.exit(1);
        });
    });
} else {
    process.exit(1);
}

  • 使用 fs.writeSync

    在查阅最新的 node.js 官方文档时，惊喜地发现以下代码片段 

    process.on('uncaughtException', (err) => {
  fs.writeSync(1, `Caught exception: ${err}`);
});

    使用 fs.writeSync 同步输出日志后再退出进程 

    process.on('uncaughtException', (err) => {
    fs.writeSync(1, `Caught exception: ${err}`);
    process.exit(1);
});

    process.stdout 和 process.stderr 流中滞留的数据没有机会输出，进程就退出了，只能保证使用 fs.writeSync 进行输出的日志不丢失，用来日志记录 uncaughtException 还是很合适的，使用 pm2 时，上面的代码会将异常日志写到 root.pm2/pm2.log，可以考虑改用 fs.appendFileSync 将异常日志写到应用的日志文件中。 

    process.on('uncaughtException', function(e) {
    fs.appendFileSync('/root/.pm2/app.log', e.stack);
    process.exit(1);
});

    但要注意的是，服务往往为了安全起见切换（setuid、setgid）到非特权帐号，可能没有权限写 pm2 为应用创建的日志文件。


node