Node 中如何更好地打日誌

時間  2020-07-16
標籤 node 如何 更好 日誌 简体版
原文   原文鏈接

Node 中如何更好地打日誌

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

在服務器應用(後端項目)中，完善並結構化的日誌不只能夠更好地幫助定位問題及復現，也可以發現性能問題的端倪，甚至可以幫忙用來解決線上 CPU 及內存爆掉的問題。node

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

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

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

日誌類型

在一個服務器應用中，或做爲生產者，或做爲消費者，須要與各方數據進行交互。除了最多見的與客戶端交互外，還有數據庫、緩存、消息隊列、第三方服務。對於重要的數據交互須要打日誌記錄。git

除了外界交互外，自身產生的異常信息、關鍵業務邏輯及定時任務信息，也須要打日誌。github

如下簡述須要打日誌的類型及涉及字段面試

  • AccessLog: 這是最多見的日誌類型，通常在 nginx 等方向代理中也有日誌記錄，但在業務系統中有時須要更詳細的日誌記錄，如 API 耗時，詳細的 request body 與 response body
  • SQLLog: 關於數據庫查詢的日誌，記錄 SQL、涉及到的 table、以及執行時間，今後能夠篩選出執行過慢的SQL，也能夠篩選出某條API對應的SQL條數
  • RequestLog: 請求第三方服務產生的日誌
  • Exception: 異常
  • RedisLog: 緩存，也有一些非緩存的操做如 zset 及分佈式鎖等
  • Message Queue Log: 記錄生產消息及消費消息的日誌
  • CronLog: 記錄定時任務執行的時間以及是否成功
  • 關鍵業務邏輯

日誌的基本字段

對於全部的日誌，都會有一些共用的基本字段，如在那臺服務器，在那個點產生的日誌redis

app

即當前項目的命名，在生產環境有可能多個項目的日誌聚合在一塊兒，經過 app 容易定位到當前項目sql

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>

相關文章
相關標籤/搜索
每日一句
    每一个你不满意的现在，都有一个你没有努力的曾经。
本站公眾號
   歡迎關注本站公眾號,獲取更多信息
聯繫我們 最近搜索 最新文章 沪ICP备13005482号-10 MyBatis教程 SQL 教程 MySQL教程 Java 教程 Thymeleaf 教程 Hibernate教程 Spring教程 Redis教程