iKcamp｜基于Koa2搭建Node.js实战（含视频）☞ 记录日志

沪江CCtalk视频地址：https://www.cctalk.com/v/15114923883523

log.png

log 日志中间件

最困难的事情就是认识自己。

在一个真实的项目中，开发只是整个投入的一小部分，版本迭代和后期维护占了极其重要的部分。项目上线运转起来之后，我们如何知道项目运转的状态呢？如何发现线上存在的问题，如何及时进行补救呢？记录日志就是解决困扰的关键方案。正如我们每天写日记一样，不仅能够记录项目每天都做了什么，便于日后回顾，也可以将做错的事情记录下来，进行自我反省。完善的日志记录不仅能够还原问题场景，还有助于统计访问数据，分析用户行为。

日志的作用

  • 显示程序运行状态
  • 帮助开发者排除问题故障
  • 结合专业的日志分析工具（如 ELK ）给出预警

关于编写 log 中间件的预备知识

log4js

本项目中的 log 中间件是基于 log4js 2.x 的封装，Log4js 是 Node.js 中一个成熟的记录日志的第三方模块，下文也会根据中间件的使用介绍一些 log4js 的使用方法。

日志分类

日志可以大体上分为访问日志和应用日志。访问日志一般记录客户端对项目的访问，主要是 http 请求。这些数据属于运营数据，也可以反过来帮助改进和提升网站的性能和用户体验；应用日志是项目中需要特殊标记和记录的位置打印的日志，包括出现异常的情况，方便开发人员查询项目的运行状态和定位 bug 。应用日志包含了debug、info、warn 和 error等级别的日志。

日志等级

log4js 中的日志输出可分为如下7个等级：

LOG_LEVEL.957353bf.png

在应用中按照级别记录了日志之后，可以按照指定级别输出高于指定级别的日志。

日志切割

当我们的项目在线上环境稳定运行后，访问量会越来越大，日志文件也会越来越大。日益增大的文件对查看和跟踪问题带来了诸多不便，同时增大了服务器的压力。虽然可以按照类型将日志分为两个文件，但并不会有太大的改善。所以我们按照日期将日志文件进行分割。比如：今天将日志输出到 task-2017-10-16.log 文件，明天会输出到 task-2017-10-17.log 文件。减小单个文件的大小不仅方便开发人员按照日期排查问题，还方便对日志文件进行迁移。

代码实现

安装 log4js 模块

npm i log4js -S

log4js 官方简单示例

在 middleware/ 目录下创建 mi-log/demo.js，并贴入官方示例代码：

var log4js = require('log4js');
var logger = log4js.getLogger();
logger.level = 'debug';
logger.debug("Some debug messages");

然后在 /middleware/mi-log/ 目录下运行：

cd ./middleware/mi-log/ && node demo.js

可以在终端看到如下输出：

[2017-10-24 15:45:30.770] [DEBUG] default - Some debug messages

一段带有日期、时间、日志级别和调用 debug 方法时传入的字符串的文本日志。实现了简单的终端日志输出。

log4js 官方复杂示例

替换 mi-log/demo.js 中的代码为如下：

const log4js = require('log4js');
log4js.configure({
  appenders: { cheese: { type: 'file', filename: 'cheese.log' } },
  categories: { default: { appenders: ['cheese'], level: 'error' } }
});

const logger = log4js.getLogger('cheese');
logger.trace('Entering cheese testing');
logger.debug('Got cheese.');
logger.info('Cheese is Gouda.');
logger.warn('Cheese is quite smelly.');
logger.error('Cheese is too ripe!');
logger.fatal('Cheese was breeding ground for listeria.');

再次在 /middleware/mi-log/ 目录下运行：

node demo.js

运行之后，在当前的目录下会生成一个日志文件 cheese.log文件，文件中有两条日志并记录了 error 及以上级别的信息，也就是如下内容：

[2017-10-24 15:51:30.770] [ERROR] cheese - Cheese is too ripe!
[2017-10-24 15:51:30.774] [FATAL] cheese - Cheese was breeding ground for listeria.

注意： 日志文件产生的位置就是当前启动环境的位置。

分析以上代码就会发现，configure 函数配置了日志的基本信息

{
  /**
   * 指定要记录的日志分类 cheese
   * 展示方式为文件类型 file
   * 日志输出的文件名 cheese.log
   */
  appenders: { cheese: { type: 'file', filename: 'cheese.log' } },

  /**
   * 指定日志的默认配置项
   * 如果 log4js.getLogger 中没有指定，默认为 cheese 日志的配置项
   * 指定 cheese 日志的记录内容为 error 及 error 以上级别的信息
   */
  categories: { default: { appenders: ['cheese'], level: 'error' } }
}

改写为log中间件

创建 /mi-log/logger.js 文件，并增加如下代码：

const log4js = require('log4js');
module.exports = ( options ) => {
  return async (ctx, next) => {
    const start = Date.now()
    log4js.configure({
      appenders: { cheese: { type: 'file', filename: 'cheese.log' } },
      categories: { default: { appenders: ['cheese'], level: 'info' } }
    }); 
    const logger = log4js.getLogger('cheese');
    await next()
    const end = Date.now()
    const responseTime = end - start;
    logger.info(`响应时间为${responseTime/1000}s`);
  }
}

创建 /mi-log/index.js 文件，并增加如下代码：

const logger = require("./logger")
module.exports = () => {
   return logger()
}

修改 middleware/index.js 文件，并增加对 log 中间件的注册， 如下代码：

const path = require('path')
const bodyParser = require('koa-bodyparser')
const nunjucks = require('koa-nunjucks-2')
const staticFiles = require('koa-static')

const miSend = require('./mi-send')
// 引入日志中间件
const miLog = require('./mi-log')
module.exports = (app) => {
  // 注册中间件
  app.use(miLog())

  app.use(staticFiles(path.resolve(__dirname, "../public")))
  app.use(nunjucks({
    ext: 'html',
    path: path.join(__dirname, '../views'),
    nunjucksConfig: {
      trimBlocks: true
    }
  }));
  app.use(bodyParser())
  app.use(miSend())
}

打开浏览器并访问 http://localhost:3000， 来发送一个http 请求。

如上，按照前几节课程中讲解的中间件的写法，将以上代码改写为中间件。 基于 koa 的洋葱模型，当 http 请求经过此中间件时便会在 cheese.log 文件中打印一条日志级别为 info 的日志并记录了请求的响应时间。如此，便实现了访问日志的记录。

实现应用日志，将其挂载到 ctx 上

若要在其他中间件或代码中通过 ctx 上的方法打印日志，首先需要在上下文中挂载 log 函数。打开 /mi-log/logger.js 文件：

const log4js = require('log4js');
const methods = ["trace", "debug", "info", "warn", "error", "fatal", "mark"]

module.exports = () => {
  const contextLogger = {}
  log4js.configure({
    appenders: { cheese: { type: 'file', filename: 'cheese.log' } },
    categories: { default: { appenders: ['cheese'], level: 'info' } }
  }); 
 
  const logger = log4js.getLogger('cheese');
  
  return async (ctx, next) => {
     // 记录请求开始的时间
    const start = Date.now()
     // 循环methods将所有方法挂载到ctx 上
    methods.forEach((method, i) => {
       contextLogger[method] = (message) => {
         logger[method](message)
       }
    })
    ctx.log = contextLogger;

    await next()
    // 记录完成的时间 作差 计算响应时间
    const responseTime = Date.now() - start;
    logger.info(`响应时间为${responseTime/1000}s`);
  }
}

创建 contextLogger 对象，将所有的日志级别方法赋给对应的 contextLogger 对象方法。在将循环后的包含所有方法的 contextLogger 对象赋给 ctx 上的 log 方法。

打开 /mi-send/index.js 文件， 并调用 ctx 上的 log 方法：

module.exports = () => {
  function render(json) {
      this.set("Content-Type", "application/json")
      this.body = JSON.stringify(json)
  }
  return async (ctx, next) => {
      ctx.send = render.bind(ctx)
      // 调用ctx上的log方法下的error方法打印日志
      ctx.log.error('ikcamp');
      await next()
  }
}

在其他中间件中通过调用 ctx 上的 log 方法，从而实现打印应用日志。

const log4js = require('log4js');
const methods = ["trace", "debug", "info", "warn", "error", "fatal", "mark"]

module.exports = () => {
  const contextLogger = {}
  const config = {
    appenders: {
        cheese: {
         type: 'dateFile', // 日志类型 
         filename: `logs/task`,  // 输出的文件名
         pattern: '-yyyy-MM-dd.log',  // 文件名增加后缀
         alwaysIncludePattern: true   // 是否总是有后缀名
       }
    },
    categories: {
      default: {
        appenders: ['cheese'],
        level:'info'
      }
    }
  }

  const logger = log4js.getLogger('cheese');

  return async (ctx, next) => {
    const start = Date.now()

    log4js.configure(config)
    methods.forEach((method, i) => {
      contextLogger[method] = (message) => {
        logger[method](message)
      }
    })
    ctx.log = contextLogger;

    await next()
    const responseTime = Date.now() - start;
    logger.info(`响应时间为${responseTime/1000}s`);
  }
}

修改日志类型为日期文件，按照日期切割日志输出，以减小单个日志文件的大小。这时候打开浏览器并访问 http://localhost:3000，这时会自动生成一个 logs 目录，并生成一个 cheese-2017-10-24.log 文件， 中间件执行便会在其中中记录下访问日志。

├── node_modules/
├── logs/ 
│     ├── cheese-2017-10-24.log 
├── ……
├── app.js

抽出可配置量

const log4js = require('log4js');
const methods = ["trace", "debug", "info", "warn", "error", "fatal", "mark"]

// 提取默认公用参数对象
const baseInfo = {
  appLogLevel: 'debug',  // 指定记录的日志级别
  dir: 'logs',      // 指定日志存放的目录名
  env: 'dev',   // 指定当前环境，当为开发环境时，在控制台也输出，方便调试
  projectName: 'koa2-tutorial',  // 项目名，记录在日志中的项目信息
  serverIp: '0.0.0.0'       // 默认情况下服务器 ip 地址
}

const { env, appLogLevel, dir } = baseInfo
module.exports = () => {
  const contextLogger = {}
  const appenders = {}
  
  appenders.cheese = {
    type: 'dateFile',
    filename: `${dir}/task`,
    pattern: '-yyyy-MM-dd.log',
    alwaysIncludePattern: true
  }
  // 环境变量为dev local development 认为是开发环境
  if (env === "dev" || env === "local" || env === "development") {
    appenders.out = {
      type: "console"
    }
  }
  let config = {
    appenders,
    categories: {
      default: {
        appenders: Object.keys(appenders),
        level: appLogLevel
      }
    }
  }

  const logger = log4js.getLogger('cheese');

  return async (ctx, next) => {
    const start = Date.now()

    log4js.configure(config)
    methods.forEach((method, i) => {
      contextLogger[method] = (message) => {
        logger[method](message)
      }
    })
    ctx.log = contextLogger;

    await next()
    const responseTime = Date.now() - start;
    logger.info(`响应时间为${responseTime/1000}s`);
  }
}

代码中，我们指定了几个常量以方便后面提取，比如 appLogLevel、dir、env 等。 。并判断当前环境为开发环境则将日志同时输出到终端， 以便开发人员在开发是查看运行状态和查询异常。

丰富日志信息

在 ctx 对象中，有一些客户端信息是我们数据统计及排查问题所需要的，所以完全可以利用这些信息来丰富日志内容。在这里，我们只需要修改挂载 ctx 对象的 log 函数的传入参数：

logger[method](message)

参数 message 是一个字符串，所以我们封装一个函数，用来把信息与上下文 ctx 中的客户端信息相结合，并返回字符串。

增加日志信息的封装文件 mi-log/access.js：

module.exports = (ctx, message, commonInfo) => {
  const {
    method,  // 请求方法 get post或其他
    url,          // 请求链接
    host,     // 发送请求的客户端的host
    headers   // 请求中的headers
  } = ctx.request;
  const client = {
    method,
    url,
    host,
    message,
    referer: headers['referer'],  // 请求的源地址
    userAgent: headers['user-agent']  // 客户端信息 设备及浏览器信息
  }
  return JSON.stringify(Object.assign(commonInfo, client));
}

注意： 最终返回的是字符串。

取出 ctx 对象中请求相关信息及客户端 userAgent 等信息并转为字符串。

在 mi-log/logger.js 文件中调用：

const log4js = require('log4js');
// 引入日志输出信息的封装文件
const access = require("./access.js");
const methods = ["trace", "debug", "info", "warn", "error", "fatal", "mark"]

const baseInfo = {
  appLogLevel: 'debug',
  dir: 'logs',
  env: 'dev',
  projectName: 'koa2-tutorial',
  serverIp: '0.0.0.0'
}
const { env, appLogLevel, dir, serverIp, projectName } = baseInfo
// 增加常量，用来存储公用的日志信息
const commonInfo = { projectName, serverIp }
module.exports = () => {
  const contextLogger = {}
  const appenders = {}

  appenders.cheese = {
    type: 'dateFile',
    filename: `${dir}/task`,
    pattern: '-yyyy-MM-dd.log',
    alwaysIncludePattern: true
  }
  
  if (env === "dev" || env === "local" || env === "development") {
    appenders.out = {
      type: "console"
    }
  }
  let config = {
    appenders,
    categories: {
      default: {
        appenders: Object.keys(appenders),
        level: appLogLevel
      }
    }
  }

  const logger = log4js.getLogger('cheese');

  return async (ctx, next) => {
    const start = Date.now()

    log4js.configure(config)
    methods.forEach((method, i) => {
      contextLogger[method] = (message) => {
       // 将入参换为函数返回的字符串
        logger[method](access(ctx, message, commonInfo))
      }
    })
    ctx.log = contextLogger;

    await next()
    const responseTime = Date.now() - start;
    logger.info(access(ctx, {
      responseTime: `响应时间为${responseTime/1000}s`
    }, commonInfo))
  }
}

重启服务器并访问 http://localhost:3000 就会发现，日志文件的记录内容已经变化。代码到这里，已经完成了大部分的日志功能。下面我们完善下其他功能：自定义配置参数和捕捉错误。

项目自定义内容

安装依赖文件 ip:

npm i ip -S

修改 middleware/index.js 中的调用方法

const path = require('path')
const ip = require('ip')
const bodyParser = require('koa-bodyparser')
const nunjucks = require('koa-nunjucks-2')
const staticFiles = require('koa-static')

const miSend = require('./mi-send')
const miLog = require('./mi-log/logger')
module.exports = (app) => {
  // 将配置中间件的参数在注册中间件时作为参数传入
  app.use(miLog({
    env: app.env,  // koa 提供的环境变量
    projectName: 'koa2-tutorial',
    appLogLevel: 'debug',
    dir: 'logs',
    serverIp: ip.address()
  }))

  app.use(staticFiles(path.resolve(__dirname, "../public")))

  app.use(nunjucks({
    ext: 'html',
    path: path.join(__dirname, '../views'),
    nunjucksConfig: {
      trimBlocks: true
    }
  }));

  app.use(bodyParser())
  app.use(miSend())
}

再次修改 mi-log/logger.js 文件：

const log4js = require('log4js');
const access = require("./access.js");
const methods = ["trace", "debug", "info", "warn", "error", "fatal", "mark"]

const baseInfo = {
  appLogLevel: 'debug',
  dir: 'logs',
  env: 'dev',
  projectName: 'koa2-tutorial',
  serverIp: '0.0.0.0'
}

module.exports = (options) => {
  const contextLogger = {}
  const appenders = {}
  
  // 继承自 baseInfo 默认参数
  const opts = Object.assign({}, baseInfo, options || {})
  // 需要的变量解构 方便使用
  const { env, appLogLevel, dir, serverIp, projectName } = opts
  const commonInfo = { projectName, serverIp }
    
  appenders.cheese = {
    type: 'dateFile',
    filename: `${dir}/task`,
    pattern: '-yyyy-MM-dd.log',
    alwaysIncludePattern: true
  }
  
  if (env === "dev" || env === "local" || env === "development") {
    appenders.out = {
      type: "console"
    }
  }
  let config = {
    appenders,
    categories: {
      default: {
        appenders: Object.keys(appenders),
        level: appLogLevel
      }
    }
  }

  const logger = log4js.getLogger('cheese');

  return async (ctx, next) => {
    const start = Date.now()

    log4js.configure(config)
    methods.forEach((method, i) => {
      contextLogger[method] = (message) => {
        logger[method](access(ctx, message, commonInfo))
      }
    })
    ctx.log = contextLogger;

    await next()
    const responseTime = Date.now() - start;
    logger.info(access(ctx, {
      responseTime: `响应时间为${responseTime/1000}s`
    }, commonInfo))
  }
}

将项目中自定义的量覆盖默认值，解构使用。以达到项目自定义的目的。

对日志中间件进行错误处理

对于日志中间件里面的错误，我们也需要捕获并处理。在这里，我们提取一层进行封装。

打开 mi-log/index.js 文件，修改代码如下：

const logger = require("./logger")
module.exports = (options) => {
  const loggerMiddleware = logger(options)

  return (ctx, next) => {
    return loggerMiddleware(ctx, next)
    .catch((e) => {
        if (ctx.status < 500) {
            ctx.status = 500;
        }
        ctx.log.error(e.stack);
        ctx.state.logged = true;
        ctx.throw(e);
    })
  }
}

如果中间件里面有抛出错误，这里将通过 catch 函数捕捉到并处理，将状态码小于 500 的错误统一按照 500 错误码处理，以方便后面的 http-error 中间件显示错误页面。 调用 log 中间件打印堆栈信息并将错误抛出到最外层的全局错误监听进行处理。

到这里我们的日志中间件已经制作完成。当然，还有很多的情况我们需要根据项目情况来继续扩展，比如结合『监控系统』、『日志分析预警』和『自动排查跟踪机制』等。可以参考一下官方文档。

下一节中，我们将学习下如何处理请求错误。

移动Web前端高效开发实战.png

上一篇：iKcamp新课程推出啦～～～～～iKcamp｜基于Koa2搭建Node.js实战（含视频）☞ 处理静态资源

推荐： 翻译项目Master的自述：

1. 干货｜人人都是翻译项目的Master

2. iKcamp出品微信小程序教学共5章16小节汇总(含视频)

©著作权归作者所有,转载或内容合作请联系作者
  • 人面猴
    序言：七十年代末，一起剥皮案震惊了整个滨河市，随后出现的几起案子，更是在滨河造成了极大的恐慌，老刑警刘岩，带你破解...
    沈念sama阅读 204,684评论 6赞 478
  • 死咒
    序言：滨河连续发生了三起死亡事件，死亡现场离奇诡异，居然都是意外死亡，警方通过查阅死者的电脑和手机，发现死者居然都...
    沈念sama阅读 87,143评论 2赞 381
  • 救了他两次的神仙让他今天三更去死
    文/潘晓璐 我一进店门，熙熙楼的掌柜王于贵愁眉苦脸地迎上来，“玉大人，你说我怎么就摊上这事。” “怎么了？”我有些...
    开封第一讲书人阅读 151,214评论 0赞 337
  • 道士缉凶录：失踪的卖姜人
    文/不坏的土叔 我叫张陵，是天一观的道长。 经常有香客问我，道长，这世上最难降的妖魔是什么？ 我笑而不...
    开封第一讲书人阅读 54,788评论 1赞 277
  • 港岛之恋（遗憾婚礼）
    正文 为了忘掉前任，我火速办了婚礼，结果婚礼上，老公的妹妹穿的比我还像新娘。我一直安慰自己，他们只是感情好，可当我...
    茶点故事阅读 63,796评论 5赞 368
  • 恶毒庶女顶嫁案：这布局不是一般人想出来的
    文/花漫 我一把揭开白布。 她就那样静静地躺着，像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上，一...
    开封第一讲书人阅读 48,665评论 1赞 281
  • 城市分裂传说
    那天，我揣着相机与录音，去河边找鬼。 笑死，一个胖子当着我的面吹牛，可吹牛的内容都是我干的。 我是一名探鬼主播，决...
    沈念sama阅读 38,027评论 3赞 399
  • 双鸳鸯连环套：你想象不到人心有多黑
    文/苍兰香墨 我猛地睁开眼，长吁一口气：“原来是场噩梦啊……” “哼！你这毒妇竟也来了？” 一声冷哼从身侧响起，我...
    开封第一讲书人阅读 36,679评论 0赞 258
  • 万荣杀人案实录
    序言：老挝万荣一对情侣失踪，失踪者是张志新（化名）和其女友刘颖，没想到半个月后，有当地人在树林里发现了一具尸体，经...
    沈念sama阅读 41,346评论 1赞 299
  • 护林员之死
    正文 独居荒郊野岭守林人离奇死亡，尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 35,664评论 2赞 321
  • 白月光启示录
    正文 我和宋清朗相恋三年，在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 37,766评论 1赞 331
  • 活死人
    序言：一个原本活蹦乱跳的男人离奇死亡，死状恐怖，灵堂内的尸体忽然破棺而出，到底是诈尸还是另有隐情，我是刑警宁泽，带...
    沈念sama阅读 33,412评论 4赞 321
  • 日本核电站爆炸内幕
    正文 年R本政府宣布，位于F岛的核电站，受9级特大地震影响，放射性物质发生泄漏。R本人自食恶果不足惜，却给世界环境...
    茶点故事阅读 39,015评论 3赞 307
  • 男人毒药：我在死后第九天来索命
    文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹，春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 29,974评论 0赞 19
  • 一桩弑父案，背后竟有这般阴谋
    文/苍兰香墨 我抬头看了看天上的太阳。三九已至，却和暖如春，着一层夹袄步出监牢的瞬间，已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 31,203评论 1赞 260
  • 情欲美人皮
    我被黑心中介骗来泰国打工， 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留，地道东北人。 一个月前我还...
    沈念sama阅读 45,073评论 2赞 350
  • 代替公主和亲
    正文 我出身青楼，却偏偏与公主长得像，于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子，可洞房花烛夜当晚...
    茶点故事阅读 42,501评论 2赞 343

推荐阅读更多精彩内容