在本地开发环境和GCP Stackdriver Logging中更好的输出日志

[mrdulin]

前言

日志组件是开发调试过程必不可少的一个组件，对于开发测试等技术人员快速定位问题很有帮助，好的日志可读性强，容易理解，甚至对于BA，产品经理，老板等非技术人员，理解起来也没什么难度。持久化的日志对于回溯，复盘问题，数据统计，数据分析也有帮助。

这篇文章很浅显易懂，不会讲Logstash, ElasticSearch, fluentd等等类似的东西，只简单讲一下如何在本地开发阶段，以及部署到GCP上的运行阶段，如何在本地和GCP Stackdriver Logging服务中更好的输出日志，作为抛砖引玉。需要熟悉以下云服务和技术栈：

• GCP Cloud Function
• GCP Stackdriver Logging
• Express.js/Node.js

不友好的日志

飞先来看一个使用JavaScript语言原生API打印日志的例子：

const faker = require('faker');

const aLog = {
  context: 'UserService.findById',
  arguments: {
    id: faker.random.uuid(),
    extra: {
      campaignId: faker.random.uuid(),
      location: {
        id: faker.random.uuid(),
        latitude: faker.address.latitude(),
        longitude: faker.address.longitude()
      }
    }
  },
  labels: ['UserService', 'bad logging', 'info']
};

console.log(aLog);

输出：

☁  nodejs-gcp [master] ⚡  node /Users/ldu020/workspace/github.com/mrdulin/nodejs-gcp/src/stackdriver/better-logging/bad-logger.spec.js
{ context: 'UserService.findById',
  arguments: 
   { id: '99f37477-2608-4312-a8e0-623baa05113a',
     extra: 
      { campaignId: '1a93cd81-6b12-4676-a8b6-6973475fe6cc',
        location: [Object] } },
  labels: [ 'UserService', 'bad logging', 'info' ] }

这样的日志显而易见有三个问题：

• 没有时间戳
• 没有日志级别
• 没有好的格式

更友好的日志

现在来改进这三个问题，使用winston模块，改造后本地开发环境日志输出如下：

Debug日志：

Error日志:

改进后的日志包含如下信息：

• 时间戳(timestamp): 根据时间戳定位日志范围
• 日志级别(log level): debug, info, error 等等
• 当前服务（应用程序）名称(service name)：我用了package.json的name字段作为当前服务（应用程序）名称
• 上下文信息(context): UserService.findById
• 元数据信息(metadata): 这里是arguments字段，包含一些调试用的id，入参等信息
• 标签(labels): 用于筛选日志，本地开发，最简单的，最没有成本的筛选操作就是终端通过搜索label定位日志
• 日志主体(log body): 这里是message字段
• 错误堆栈(error stack)

以上信息对于日常开发调试基本够用了。

在GCP Stackdriver Logging中打印日志

部署到GCP上，本例的应用程序运行在cloud function环境。GCP官方提供了Stackdriver Logging Winston 插件@google-cloud/logging-winston，使用该插件来优化日志组件。不过在优化之前，先来看一个使用console打印日志的例子：

首先构造一个user对象，是个有三层嵌套的对象，作为我们的日志主体。

const faker = require('faker');

const user = {
  id: faker.random.uuid(),
  name: faker.name.findName(),
  email: faker.internet.email(),
  address: {
    city: faker.address.city(),
    country: faker.address.country(),
    street: {
      streetPrefix: faker.address.streetPrefix(),
      streetSuffix: faker.address.streetSuffix()
    }
  }
};

module.exports = { user };

然后我们使用console.log，传入各种形式的入参来打印该user对象，测试哪种方式打印的日志可读性更强，格式更好。Cloud Function如下：

const { user } = require('../data');

exports.consoleLogging = async (req, res) => {
  console.log('[log 1] user: ', user);
  console.log(`[log 2] user: ${user}`);
  console.log('[log 3] user: %o', user);
  console.log(`[log 4] user: ${JSON.stringify(user)}`);
  console.log('[log 5] user');
  console.log(user);
  console.log('[log 6] user: \n ', user);
  console.log('[log 7] user: %s', JSON.stringify(user));
  console.log(`[log 8] user: ${JSON.stringify(user, null, 2)}`);
  console.log(`[log 9] user:\n${JSON.stringify(user, null, 2)}`);
  console.log('[log 10] user');
  console.log(JSON.stringify(user, null, 2));

  try {
    await findById();
    res.sendStatus(200);
  } catch (error) {
    console.error(error);
    res.sendStatus(500);
  }
};

function findById() {
  return new Promise((resolve, reject) => {
    process.nextTick(() => {
      reject(new Error('something bad happened'));
    });
  });
}

我们来看上下文是[log 1]的日志在GCP Stackdriver Logging中打印出来长什么样，点击Expand all，展开日志：

看到这个日志，有这么几个问题：

• 没有格式化(prettify)
• 无法添加标签(labels)
• 无法使用Stackdriver Logging提供的日志过滤和筛选功能(filter)
• 没有上下文(context)，本例没有加入上下文信息，如果加入，为了区分日志主体和上下文，我们可能会构造这样的日志数据：{user, context}
• 整个日志主体和上下文都以字符串的形式存在textpayload字段中，没有区分，不够“结构化”，并且嵌套越深可读性越差。

另外9个测试打印的日志都不尽人意，感兴趣的同学可以部署源码到Cloud Function查看各个测试用例的输出。

改造后的日志输出如下：

Info日志：

Error日志：

日志筛选和过滤：

可用的日志筛选条件：

可以看到改造后的日志更“结构化”(JSON-structured log messages)，这种结构化带来了更好的日志筛选和过滤功能，可以根据日志的相关字段进行筛选过滤。这是textpayload这种字符串形式的日志做不到的。封装后的日志组件可以根据需要进行配置，还可以更方便的开启与关闭，比如生产环境(process.env.NODE_ENV === 'production')，我们日志级别设置为error。最好避免在代码各处直接使用原生console，一方面无法配置，另一方面违反tslint,jslint等代码检查工具的规则，当然，我们可以使用grunt, gulp,webpack等这样的资源依赖打包工具来移除console。

日志组件关键配置如下：

const winston = require('winston');
const { LoggingWinston } = require('@google-cloud/logging-winston');
const { format } = require('winston');
const pkg = require('./package.json');

function jsonFormat(obj) {
  return JSON.stringify(obj, null, 2);
}

let transports = [];
let level = 'debug';
if (process.env.NODE_ENV === 'production') {
  const loggingWinston = new LoggingWinston({
    serviceContext: {
      service: pkg.name,
      version: pkg.version
    }
  });
  transports = [new winston.transports.Console(), loggingWinston];
  level = 'error';
} else {
  const printf = format.printf((info) => {
    const { level, ...rest } = info;
    let log;
    if (rest.stack) {
      const { stack, ...others } = rest;
      log =
        `[${info.timestamp}][${info.level}]: ${jsonFormat(others)}\n\n` +
        `[${info.timestamp}][${info.level}]: ${stack}\n\n`;
    } else {
      log = `[${info.timestamp}][${info.level}]: ${jsonFormat(rest)}\n\n`;
    }
    return log;
  });
  transports = [
    new winston.transports.Console({
      format: format.combine(format.colorize(), format.timestamp(), format.errors({ stack: true }), printf)
    })
  ];
}

const logger = winston.createLogger({
  level,
  defaultMeta: { service: pkg.name },
  transports
});

logger.debug(`process.env.NODE_ENV: ${process.env.NODE_ENV}`);

module.exports = { logger };

好的日志不仅能提升开发测试效率，看起来也赏心悦目，让生活少点痛苦。兼容各个云平台，容器环境，系统环境，本地和线上环境的日志组件需要不断进化，一个日志组件最开始在一个项目中使用 ，随着时间推移，更好的封装，更方便的使用，更多场景的覆盖，更强的稳定性，那么就可以作为一个通用的模块在多个项目中使用，然后是产品线，接着是公司的所有产品线，最后就可以按照心情决定是否开源，推广到全世界。

源码地址

• https://github.com/mrdulin/nodejs-gcp/tree/master/src/stackdriver/better-logging
• https://github.com/mrdulin/dl-toolkits/blob/master/src/logger/index.ts - 更好的版本

参考

• 设置 Node.js 版 Stackdriver Logging
• https://palantir.github.io/tslint/rules/no-console/
• 结构化日志记录
• Go语言如何更好的在GCP Stackdriver Logging中打印日志

---