Node 中如何更好地打日誌

shanyue發表於2020-07-15
原文網址 : https://segmentfault.com/a/1190000023232275

Node 中如何更好地打日誌

本文收錄於 GitHub 山月行部落格: shfshanyue/blog，內含我在實際工作中碰到的問題、關於業務的思考及在全棧方向上的學習

在伺服器應用(後端專案)中，完善並結構化的日誌不僅可以更好地幫助定位問題及復現，也能夠發現效能問題的端倪，甚至能夠幫忙用來解決線上 CPU 及記憶體爆掉的問題。

本篇文章將講解如何使用 Node 在服務端更好地打日誌

  • 哪裡應該打日誌: AccessLog、SQLLog、BusinessLog
  • 應該打什麼日誌: server_name、timestamp 以及相關型別日誌
  • 用什麼去打日誌: winston、log4j、bunyan

產生日誌後，將在下一章講解日誌的收集處理及檢索

日誌型別

在一個伺服器應用中，或作為生產者，或作為消費者，需要與各方資料進行互動。除了最常見的與客戶端互動外，還有資料庫、快取、訊息佇列、第三方服務。對於重要的資料互動需要打日誌記錄。

除了外界互動外，自身產生的異常資訊、關鍵業務邏輯及定時任務資訊，也需要打日誌。

以下簡述需要打日誌的型別及涉及欄位

  • AccessLog: 這是最常見的日誌型別，一般在 nginx 等方向代理中也有日誌記錄，但在業務系統中有時需要更詳細的日誌記錄，如 API 耗時，詳細的 request body 與 response body
  • SQLLog: 關於資料庫查詢的日誌，記錄 SQL、涉及到的 table、以及執行時間，從此可以篩選出執行過慢的SQL，也可以篩選出某條API對應的SQL條數
  • RequestLog: 請求第三方服務產生的日誌
  • Exception: 異常
  • RedisLog: 快取，也有一些非快取的操作如 zset 及分散式鎖等
  • Message Queue Log: 記錄生產訊息及消費訊息的日誌
  • CronLog: 記錄定時任務執行的時間以及是否成功
  • 關鍵業務邏輯

日誌的基本欄位

對於所有的日誌，都會有一些共用的基本欄位，如在那臺伺服器，在那個點產生的日誌

app

即當前專案的命名，在生產環境有可能多個專案的日誌聚合在一起，通過 app 容易定位到當前專案

serverName

即伺服器的 hostname，通過它很容易定位到出問題的伺服器/容器。

現已有相當多公司的生產環境應用使用 kubernetes 進行編排，而在 k8s 中每個 POD 的 hostname 如下所示，因此很容易定位到

  1. Deployment: 哪一個應用/專案
  2. ReplicaSet: 哪一次上線
  3. Pod: 哪一個 Pod
# shanyue-production 指 Deployment name
# 69d9884864 指某次升級時 ReplicaSet 對應的 hash
# vt22t 指某個 Pod 對應的 hash
$ hostname
shanyue-production-69d9884864-vt22t

timestamp

即該條日誌產生的時間，使用 ISO 8601 格式有更好的人可讀性與機器可讀性

{
  "timestamp": "2020-04-24T04:50:57.651Z",
}

requestId/traceId

及全鏈路式日誌中的唯一id，通過 requestId，可以把相關的微服務同一條日誌連結起來、包括前端、後端、上游微服務、資料庫及 redis

全鏈路式日誌平臺可以更好地分析一條請求在各個微服務的生命週期，目前流行的有以下幾種，以下使他們的官網介紹

  • zipkin: Zipkin is a distributed tracing system. It helps gather timing data needed to troubleshoot latency problems in service architectures. Features include both the collection and lookup of this data.
  • jaeger: open source, end-to-end distributed tracing

label

即日誌的型別，如 SQL、Request、Access、Corn 等

userId

即使用者資訊，當然有的服務可能沒有使用者資訊，這個要視後端服務的性質而定。當使用者未登入時，以 -1 替代，方便索引。

{
  "userId": 10086,
  // 當使用者在未狀態時，以 -1 替代
  "userId": -1,
}

Node 中如何打日誌: winston

winston 是 Node 中最為流行的日誌工具，支援各種各樣的 Transport，能夠讓你定義各種儲存位置及日誌格式

當然還有其它可選的方案：如 []

{
  defaultMeta: {
    app: 'shici-service',
    serverName: os.hostname(),
    label
  }
}
import winston, { format } from 'winston'
import os from 'os'
import { session } from './session'

const requestId = format((info) => {
  // 關於 CLS 中的 requestId
  info.requestId = session.get('requestId')
  return info
})

function createLogger (label: string) {
  return winston.createLogger({
    defaultMeta: {
      serverName: os.hostname(),
      // 指定日誌型別，如 SQL / Request / Access
      label
    },
    format: format.combine(
      // 列印時間戳
      format.timestamp(),
      // 列印 requestId
      requestId(),
      // 以 json 格式進行列印
      format.json()
    ),
    transports: [
      // 儲存在檔案中
      new winston.transports.File({
        dirname: './logs',
        filename: `${label}.log`,
      })
    ]
  })
}

const accessLogger = createLogger('access')

日誌結構化

結構化的日誌方便索引，而 JSON 是最容易被解析的格式，因此生產環境日誌常被列印為 JSON 格式。

那其它格式可以嗎，可以，就是解析有點麻煩。當然 JSON 也有缺點，即資料冗餘太多，會造成頻寬的浪費。

http {
    include       mime.types;
    default_type  application/octet-stream;

    json_log_fields main 'remote_addr'
                         'remote_user'
                         'request'
                         'time_local'
                         'status'
                         'body_bytes_sent'
                         'http_user_agent'
                         'http_x_forwarded_for';
}

npm scripts: 優化本地日誌及篩選

在 morgan 中可以優化日誌的可讀性並列印在終端

morgan(':method :url :status :res[content-length] - :response-time ms')

而以上無論生產環境還是測試環境本地環境，都使用了 json 格式，並輸出到了檔案中，此時的可讀性是不很差？

別急，這裡用 npm scripts 處理一下，不僅有更好的可讀性，而且更加靈活

{
  "log": "tail -f logs/api-$(date +'%Y-%m-%d').log | jq",
  "log:db": "tail -f logs/db-$(date +'%Y-%m-%d').log | jq"
}

通過命令列 tail 及 jq，做一個更棒的視覺化。jq 是一款 json 處理的命令列工具，需提前下載

$ brew install jq

列印後的請求日誌

因為列印日誌是基於 jq 的，因此你也可以寫 jq script 對日誌進行篩選

$ npm run log  '. | { message, req}'

只列印部分欄位

請求日誌: AccessLog

AccessLog 幾乎是一個後端專案中最重要的日誌，在傳統 Node 專案中常用 morgan，但是它對機器讀並不是很友好。

以下是基於 koa 的日誌中介軟體:

  1. 對於 Options、健康檢查及一些不重要請求不打日誌
  2. 使用 duration 欄位記錄該響應的執行時間
  3. 對於請求的 body 及 query 需要做序列化(stringify)處理，避免在 EliticSearch 或一些日誌平臺中索引過多及錯亂
  4. 記錄全域性的上下文資訊，如 User 及一些業務相關聯的資料
// 建立一個 access 的 log，並儲存在 ./logs/access.log 中
const accessLogger = createLogger('access')

app.use(async (ctx, next) => {
  if (
    // 如果是 Options 及健康檢查或不重要 API，則跳過日誌
    ctx.req.method === 'OPTIONS' ||
    _.includes(['/healthCheck', '/otherApi'], ctx.req.url)
  ) {
    await next()
  } else {
    const now = Date.now()
    const msg = `${ctx.req.method} ${ctx.req.url}`
    await next()
    apiLogger.info(msg, {
      req: {
        ..._.pick(ctx.request, ['url', 'method', 'httpVersion', 'length']),
        // body/query 進行序列化，避免索引過多
        body: JSON.stringify(ctx.request.body),
        query: JSON.stringify(ctx.request.query)
      },
      res: _.pick(ctx.response, ['status']),

      // 使用者資訊
      userId: ctx.user.id || -1,

      // 一些重要的業務相關資訊
      businessId: ctx.business.id || -1,
      duration: Date.now() - now
    })
  }
})

資料庫日誌: SQLLog

對於流行的伺服器框架而言，運算元據庫一般使用 ORM 操作，對於 Node，這裡選擇 sequelize

以下是基於 sequelize 的資料庫日誌及程式碼解釋:

  1. 繫結 CLS (Continues LocalStorage)，即可通過 requestId 查得每條 API 對應的查庫次數，方便定位效能問題
  2. 使用 duration 欄位記錄該查詢的執行時間，可過濾 1s 以上資料庫操作，方便發現效能問題
  3. 使用 tableNames 欄位記錄該查詢涉及的表，方便發現效能問題
// 建立一個 access 的 log，並儲存在 ./logs/sql.log 中
const sqlLogger = createLogger('sql')

// 繫結 Continues LocalStorage
Sequelize.useCLS(session)

const sequelize = new Sequelize({
  ...options,
  benchmark: true,
  logging (msg, duration, context) {
    sqlLogger.info(msg, {
      // 記錄涉及到的 table 與 type
      ...__.pick(context, ['tableNames', 'type']),
      // 記錄SQL執行的時間
      duration
    })
  },
})

Redis日誌: RedisLog

redis 日誌一般來說不是很重要，如果有必要也可以記錄。

如果使用 ioredis 作為 redis 操作庫，可侵入 Redis.prototype.sendCommand 來列印日誌，對 redis 進行封裝如下

import Redis from 'ioredis'
import { redisLogger } from './logger'

const redis = new Redis()

const { sendCommand } = Redis.prototype
Redis.prototype.sendCommand = async function (...options: any[]) {
  const response = await sendCommand.call(this, ...options);
  // 記錄查詢日誌
  redisLogger.info(options[0].name, {
    ...options[0],
    // 關於結果，可考慮不列印，有時資料可能過大
    response
  })
  return response
}

export { redis }

微服務請求日誌: RequestLog

第三方請求可以通過 axios 傳送請求，並在 axios.interceptors 中攔截請求列印日誌。

主要，此時不僅注入了日誌，而且注入了 requestId，傳遞給下一個微服務

import { requestLogger } from './logger'

axios.interceptors.request.use(function (config) {
  // Do something before request is sent
  const message = `${config.method} ${config.url}`
  requestLogger.info(message, config)
  // 從 CLS 中獲取 RequestId，傳遞給微服務，組成全鏈路
  config.headers['X-Request-Id'] = session.requestId
  return config
}, function (error) {
  return Promise.reject(error)
})

總結

本文收錄於 GitHub 山月行部落格: shfshanyue/blog，內含我在實際工作中碰到的問題、關於業務的思考及在全棧方向上的學習

在一個後端專案中，以下型別需要打日誌記錄，本篇文章介紹瞭如何使用 Node 來做這些處理並附有程式碼

  • AccessLog: 這是最常見的日誌型別，一般在 nginx 等方向代理中也有日誌記錄，但在業務系統中有時需要更詳細的日誌記錄，如 API 耗時，詳細的 request body 與 response body
  • SQLLog: 關於資料庫查詢的日誌，記錄 SQL、涉及到的 table、以及執行時間，從此可以篩選出執行過慢的SQL，也可以篩選出某條API對應的SQL條數
  • RequestLog: 請求第三方服務產生的日誌
  • Exception: 異常
  • RedisLog: 快取，也有一些非快取的操作如 zset 及分散式鎖等
  • Message Queue Log: 記錄生產訊息及消費訊息的日誌
  • CronLog: 記錄定時任務執行的時間以及是否成功
  • 關鍵業務邏輯

關注我

掃碼新增我的微信，備註進群，加入高階前端進階群

<figure>
<img width="240" src="https://user-gold-cdn.xitu.io/2020/6/29/172fe14e18d2b38c?w=430&h=430&f=jpeg&s=38173" alt="加我微信拉你進入面試交流群">
<figcaption>加我微信拉你進入面試交流群</figcaption>
</figure>

歡迎關注公眾號【全棧成長之路】，定時推送 Node 原創及全棧成長文章

<figure>
<img width="240" src="https://shanyue.tech/qrcode.jpg" alt="歡迎關注">
<figcaption>歡迎關注全棧成長之路</figcaption>
</figure>

相關文章