说说nodejs的日志问题

作为一个曾经辗转使用过java，php，ruby（ror）的小白，一见到nodejs就疯狂的迷恋上了。终于可以在服务端写js了。不过nodejs毕竟发展的时间太短，所以呢很多东西还不完善。比如我最近就遇到了比较麻烦的日志处理的问题。

曾几何时，我在使用php或者ruby的时候，日志啦，数据库orm啦这些东西都有很成熟的框架去自动帮你弄好。而nodejs现在最出名的koa实在是太简单纯粹了，只是帮你完成了中间件的结构，其他全部都撒手不管了。所以呢日志模块需要自己去找的。

遇到的问题

首先我们看个例子：

var http = require('http');
var server = http.createServer(function (req, res) {
  setTimeout(function(){
    console.log("我开始打第一段日志了。。。");
    res.write("处理中。。。");
  },1000)
  setTimeout(function(){
    console.log("我要打第二段日志了。。。");
    res.write("处理中。。。");
  },5000)
  setTimeout(function(){
    console.log("日志打完了。。。");
    res.end("请求结束。。。");
  },10000)
}).listen(3000);
console.log('listening on port ' + 3000);

程序会针对每个请求打出一些日志，需要注意的是这些日志都是异步的。每个请求都要10秒才能结束。

运行程序后，我们再开两个终端前后运行：

curl http://localhost:3000
//你也可以用浏览器，开两个窗口访问

我们期待的效果应该是：

//第一个请求进来：
开始打第一段日志了。。。
我要打第二段日志了。。
。日志打完了。。。
//第二个请求进来：
开始打第一段日志了。。。
我要打第二段日志了。。。
日志打完了。。。

但是你会发现结果是：

我开始打第一段日志了。。。
我开始打第一段日志了。。。
我要打第二段日志了。。。
我要打第二段日志了。。。
日志打完了。。。
日志打完了。。。

你会发现发生了串行的现象，也就是第一个请求日志打了一半，第二个请求也开始打日志了。

试想一下，当我们的应用很大时，我们肯定是希望针对当前的一个请求的日志记录在一起的。这样才好方便排查某个请求的问题。如果不加处理的话，全是串行在一起。那完全就不知道错误属于哪个请求的。

缘起

为什么会发生这种问题呢，这要从nodejs的请求模型开始聊起了。

首先单进程的ruby，php这类的服务是不会有这个问题的，因为他们都是同步机制，一个进程处理一个请求。注意这边强调的是单进程。比如我们在服务端开一个进程。当来了一个请求时，一个请求就使用其中的一个进程。再来一个请求怎么办呢？没办法，只能等着。等前面的请求结束了。你才可以进来。所以对于一个请求来说他是独享各种环境的，是不怕被其它请求打扰的。

而nodejs是单进程单线程异步处理所有的请求：

这边盗个图，出处这里。这篇文章很好的讲解了一些请求模型。

来了一个请求，nodejs就开始处理了，再来一个请求也可以使用这个进程。他们可以同时调用，这得益于nodejs本身的基于事件的异步编程模型。第一个请求过来了可能处理了一半下个请求就过来了。所以就会出现了我们上面的串行的问题。

我们上面说单进程的ruby，php是不会有这种问题的，因为一个进程一次只能处理一个请求。但是很不幸，一般使用ruby或者php的时候都是开启多个进程的，这样一个请求来了就去看有没有空闲的进程，有就使用，满了就等待。所以虽然 单个进程的模型不会有问题，但是多进程下的php，ruby模型如果一起写日志文件，还是会有这种请求之间竞争资源的问题。解决方案或是文件锁，或是使用内存记录最后一次性输出等等，这边就先不讨论。

另外，nodejs目前也具有了多进程的结构，就是使用cluster。比如四核的处理器我们就可以开四个进程来做负载均衡。当然这又跟ruby，php的进程模型是两码事了。

那么对于nodejs我们怎么处理呢？

很简单，我们只需要针对每个请求维护一个局部变量。等到当前请求结束的时候一次性的输出。

针对koa的解决方案

由于项目使用koa架构，所以基于此我开发了个包来处理这样的日志的问题。koa很贴心的维护了一个针对每个请求的context对象。所以我们可以在这个对象上维护一个局部日志缓存，所有地方的输出日志都是先记录在这个缓存里等请求结束后再一次性输出到日志文件。

地址：https://github.com/purplebamboo/koa-logs-full

用来记录类似rails风格的日志。

结语

结语还是要滴，nodejs还很不完善，但是正是因为不完善，作为开发人员才有很多东西可以去做去挑战。每踩到一个坑，去了解相应的实现就可以学到很多知识，对于前端来说是个很好的机遇。