Zenn
🚥

NodeでのCloud LoggingとError Reportの最適な使用方法を実験で導き出す

2022/12/28に公開
Google Cloud
Node.js
Cloud Run
logging
tech

GCP の Cloud Run で Node のサーバを稼働させ、Cloud Logging にログを出力して、更にエラーが発生したときは Error Report で通知を受けるというような構成を組む際に、

  • どのようなケースで「重要度」が正しくマークされるのか
  • どのような形式でログを吐けば Error Report が自動生成されるのか

ドキュメントを読んでも、これらのことがいまいちわからなかったので実験してみました。

また、標準の console だけではなく、Node の主要なロガーライブラリーのうち、どれが一番 Cloud Logging と Error Report との相性が良いのかも実験から導き出しました。

前提

ロギング方法

Cloud Run で express サーバを用意し、下記のように文字列と Error をロガーで標準出力および標準エラーに出力

app.get("/", (req, res) => {
  logger.info('error massage')            
  logger.info(new Error('error message'))
  logger.warn('error massage')            
  logger.warn(new Error('error message'))
  logger.error('error massage')          
  logger.error(new Error('error message'))

  res.send();
});

使用ロガー

npmlog はロガーライブラリの中で一番ダウンロード数が多い有名なロガーだが、Error を出力するのにはあまり向いていないため本調査では対象外とする。

調査観点

  • Cloud Logging の「重要度」がどうなるか
  • Error Report が生成されるかどうか

そもそも...

@google-cloud/logging を利用したり、あるいは、GCP が公式に用意している winston や bunyan 用のプラグインを用いれば、Logging と Reporting はきめ細かく設定可能です。

https://cloud.google.com/logging/docs/setup/nodejs?hl=ja

しかし内部的には GRPC での通信を発生させて API をリクエストしているので、ロギングにそこまでコストをかけたくない(標準出力に吐くだけでいいのであれば、それに越したことはない)という気持ちが強かったので、この実験に至りました。

こちらの記事で moga さんも同様のことを述べられています。

https://zenn.dev/moga/articles/cloudrun-structured-log

仕様に関する補足

Cloud Logging の重要度に関して

https://cloud.google.com/logging/docs/reference/v2/rest/v2/LogEntry?hl=ja#LogSeverity

ログをオブジェクトにして構造化し、severity を与えることで「重要度」をマークすることが可能です。
INFO, WARNING, ERRORなどを取ることが可能です。(他の値は上記サイトを確認してください。)
severity が与えられていないときは DEFAULT となります。

また、severity が与えられていないときでも、ログの内容がスタックトレース場合は、自動的に ERROR としてマークされます。

この記事では Cloud Logging のスクリーンショットをそのまま載せます。重要度は次のようなアイコンで示されています。

DEFAULT INFO WARNING ERROR

Cloud Logging から Error Report が自動生成される条件

https://cloud.google.com/error-reporting/docs/formatting-error-messages?hl=ja

スタック トレースまたは例外を含むログエントリ

この条件に当てはまるのは下記のどちらか

  • プレーンテキストでError.prototype.stackを出力
  • 下記形式のオブジェクトデータ
{
  "err": {
    "message": string,
    "name": string,
    "stack": string
  }
}

ReportedErrorEvent のような形式のログエントリ

  • 形式は下記の通り
{
  "@type": "type.googleapis.com/google.devtools.clouderrorreporting.v1beta1.ReportedErrorEvent",
  "message": "A simple text message"
}

こちらは severity の有無によらず、すべてのケースで Error Report が生成されます。

ただし、この方法だと発生場所をマークすることができないため注意です。例外以外のもの(プレーンテキストなど)を Error Report に残したい場合はこれを使うと良いでしょう。

この記事では Cloud Logging のスクリーンショットをそのまま載せます。Error Report が生成された旨に関しては次のようなアイコンで示されています。

実験①: console

console.log, console.warn, console.error を使用し、文字列と Error をそのままダイレクトに出力させました。

console.log('error massage')              // 重要度: DEFAULT | ErrorReport:
console.log(new Error('error message'))   // 重要度: ERROR   | ErrorReport: ✅
console.warn('error massage')             // 重要度: DEFAULT | ErrorReport:
console.warn(new Error('error message'))  // 重要度: ERROR   | ErrorReport: ✅
console.error('error massage')            // 重要度: DEFAULT | ErrorReport:
console.error(new Error('error message')) // 重要度: ERROR   | ErrorReport: ✅
// 実際の出力に使用している文字列は上記と異なるので、スクリーンショットの内容と若干異なります。

上記の記述順と出力順に若干のズレがあることに注意して下さい。

Error を出力したものに関してはログレベルに関係なく、Error Report が生成されました。
また、severity を設定していないので、重要度は文字列は一律でデフォルト、Error を出力したものは一律エラーとなりました。

補足

ちなみに、こちらの記事で suin さんが、

https://qiita.com/suin/items/d5d5d7199b62eed63bde

JavaScriptのConsole APIのメソッドの違いは、基本的にGCPの重大度に影響しません。ただし、console.warnとconsole.errorがErrorオブジェクトをロギングした場合に限り、重大度が「ERROR」になります。

と述べられていますが。2022年12月時点では、Error を出力した場合はすべて(.logでも)重要度は ERROR になりました。
suin さんが記事を書かれたのが2020年8月なので、それ以降で仕様変更があったのか、あるいはCloud Runからの出力が原因なのかはわかりません。

カスタムロガーを作る

出力する内容を、オブジェクトの JSON.stringify したものにすると、Cloud Logging が構造化データとして扱います。
severity に重要度のレベルが与えられていると、意図したとおりに重要度をマークすることができます。

const makeLogger = (severity: "INFO" | "WARNING" | "ERROR") => {
  return (entry: any, meta?: Record<string, any>) => {
    console.log(
      JSON.stringify({
        severity,
        message: entry instanceof Error ? entry.stack : entry,
        ...meta,
      })
    );
  };
};

const logger = {
  info: makeLogger("INFO"),
  warn: makeLogger("WARNING"),
  error: makeLogger("ERROR"),
};

logger.info('error massage')             // 重要度: INFO    | ErrorReport:
logger.info(new Error('error message'))  // 重要度: INFO    | ErrorReport:
logger.warn('error massage')             // 重要度: WARNING | ErrorReport:
logger.warn(new Error('error message'))  // 重要度: WARNING | ErrorReport:
logger.error('error massage')            // 重要度: ERROR   | ErrorReport:
logger.error(new Error('error message')) // 重要度: ERROR   | ErrorReport: ✅
// 実際の出力に使用している文字列は上記と異なるので、スクリーンショットの内容と若干異なります。

severity が与えられたことで、loggerのログレベルと重要度が一致しました。
また、severity が付与されているときに Error を出力した場合に、Error Report が生成されるのは重要度がエラー以上のものだけになります。

実験②: winston

https://github.com/winstonjs/winston

const logger = winston.createLogger({
  level: "info",
  format: winston.format.combine(
    winston.format.errors({ stack: true }),
    winston.format.json()
  ),
  transports: [new winston.transports.Console()],
});

logger.info('error massage')             // 重要度: DEFAULT | ErrorReport: 
logger.info(new Error('error message'))  // 重要度: DEFAULT | ErrorReport:
logger.warn('error massage')             // 重要度: DEFAULT | ErrorReport: 
logger.warn(new Error('error message'))  // 重要度: DEFAULT | ErrorReport:
logger.error('error massage')            // 重要度: DEFAULT | ErrorReport:
logger.error(new Error('error message')) // 重要度: DEFAULT | ErrorReport:
// 実際の出力に使用している文字列は上記と異なるので、スクリーンショットの内容と若干異なります。

winston を使用することで、ログ自体は構造化されたデータになっていますが、severity が付与されるわけではないので、重要度はすべてデフォルトになります。
また、winston の標準のエラーフォーマッター winston.format.errors({ stack: true }) は Error を次のような構造で吐き出しており、このフォーマットでは Error Report は生成されません。

{
  "message": "エラーメッセージ",
  "stack": "スタックトレース"
}

よって、winston をカスタマイズせずにプーレンに使う状態では、Cloud Logging および Error Report との相性はよくないと言えるでしょう。

winston のフォーマッターをカスタムして使用する

プレーンな状態では、あまり相性はよくありませんが、カスタムフォーマッターを定義してあげれば、重要度の設定と Error Report の自動生成が可能になります。

const severity = winston.format((info) => {
  info["severity"] = info.level.toUpperCase();
  return info;
});

const errorReport = winston.format((info) => {
  if (info instanceof Error) {
    info.err = {
      name: info.name,
      message: info.message,
      stack: info.stack,
    };
  }
  return info;
});

const logger = winston.createLogger({
  level: "info",
  format: winston.format.combine(
    severity(),
    errorReport(),
    winston.format.json()
  ),
  transports: [new winston.transports.Console()],
});

logger.info('error massage')             // 重要度: INFO    | ErrorReport:
logger.info(new Error('error message'))  // 重要度: INFO    | ErrorReport:
logger.warn('error massage')             // 重要度: WARNING | ErrorReport:
logger.warn(new Error('error message'))  // 重要度: WARNING | ErrorReport:
logger.error('error massage')            // 重要度: ERROR   | ErrorReport:
logger.error(new Error('error message')) // 重要度: ERROR   | ErrorReport: ✅ 
// 実際の出力に使用している文字列は上記と異なるので、スクリーンショットの内容と若干異なります。

ログにスタックトレースを出力することで Error Report が自動生成されることは前述したとおりですが、次のような構造のデータを出力することでも Error Report を生成することが可能です。

{
  "err": {
    "message": string,
    "name": string,
    "stack": string
  }
}

winston そのものはログデータのオブジェクトをログに出力するので、この構造のデータを吐き出すようにするのが良いでしょう。

実験③: bunyan

https://github.com/trentm/node-bunyan

const logger = bunyan.createLogger({
  name: "cloud-logging-test",
  level: "info",
});

logger.info('error massage')             // 重要度: DEFAULT | ErrorReport:
logger.info(new Error('error message'))  // 重要度: DEFAULT | ErrorReport: ✅
logger.warn('error massage')             // 重要度: DEFAULT | ErrorReport:
logger.warn(new Error('error message'))  // 重要度: DEFAULT | ErrorReport: ✅
logger.error('error massage')            // 重要度: DEFAULT | ErrorReport:
logger.error(new Error('error message')) // 重要度: DEFAULT | ErrorReport: ✅
// 実際の出力に使用している文字列は上記と異なるので、スクリーンショットの内容と若干異なります。

severity が設定されていないので、重要度はすべてデフォルトになります。
Error を引数に渡したときのログは、デフォルトのフォーマッタで { err: { ... } } の形式で出力されるため、プレーンな状態で bunyan を利用しても Error Report が自動生成されます。
また、スタックトレースをプレーンテキストとして出力しているわけではないので、重要度はデフォルトのままです。その点で若干 console と異なります。

bunyan はフォーマットのカスタマイズがやりにくいので、重要度を最適化するためのカスタマイズできませんでした。
(stream のオプションをうまく設定すればできるのかもしれませんが、あきらめました。)

Cloud Logging の重要度を特に気にせず、例外が発生したときに Error Report を生成するだけでよいのであれば、bunyan でも良いかもしれません。
ただ、console とほぼ同じ結果になるので、Cloud Logging と Error Report の観点だけで見ると、console を使わずに、あえて bunyan を選択するメリットは薄いでしょう。

実験④: pino

https://github.com/pinojs/pino

const logger = pino({
  level: "info",
});

logger.info('error massage')             // 重要度: DEFAULT | ErrorReport:
logger.info(new Error('error message'))  // 重要度: DEFAULT | ErrorReport: ✅
logger.warn('error massage')             // 重要度: DEFAULT | ErrorReport:
logger.warn(new Error('error message'))  // 重要度: DEFAULT | ErrorReport: ✅
logger.error('error massage')            // 重要度: DEFAULT | ErrorReport:
logger.error(new Error('error message')) // 重要度: DEFAULT | ErrorReport: ✅
// 実際の出力に使用している文字列は上記と異なるので、スクリーンショットの内容と若干異なります。

severity が設定されていないので、重要度はすべてデフォルトになります。
Error を引数に渡したときのログは、デフォルトのフォーマッタで { err: { ... } } の形式で出力されるため、プレーンな状態で pino を利用しても Error Report が自動生成されます。
また、スタックトレースをプレーンテキストとして出力しているわけではないので、重要度はデフォルトのままです。結果的には bunyan と全く同じになりました。

pino をカスタムして重要度を最適化する

mixin オプションを使用すれば、簡単に severity を付与することができます。

const labels = pino().levels.labels;
const logger = pino({
  level: "info",
  mixin: (_, level) => {
    return { severity: labels[level].toUpperCase() };
  },
});

logger.info('error massage')             // 重要度: INFO    | ErrorReport: 
logger.info(new Error('error message'))  // 重要度: INFO    | ErrorReport:
logger.warn('error massage')             // 重要度: WARNING | ErrorReport: 
logger.warn(new Error('error message'))  // 重要度: WARNING | ErrorReport:
logger.error('error massage')            // 重要度: ERROR   | ErrorReport: 
logger.error(new Error('error message')) // 重要度: ERROR   | ErrorReport: ✅ 
// 実際の出力に使用している文字列は上記と異なるので、スクリーンショットの内容と若干異なります。

再三の説明になりますが、severity が設定されているときは、Error Report が生成されるのは、重要度がエラーのときのみです。

今回の各実験の中では、一番記述量少なく重要度の最適化ができるので、pino を使用して mixin を設定するこのカスタマイズが一番おすすめです。

実験⑤: loglevel

https://github.com/pimterry/loglevel

loglevel.setLevel('info')
const logger = loglevel;

logger.log('error massage')              // 重要度: DEFAULT | ErrorReport:
logger.log(new Error('error message'))   // 重要度: ERROR   | ErrorReport: ✅
logger.warn('error massage')             // 重要度: DEFAULT | ErrorReport:
logger.warn(new Error('error message'))  // 重要度: ERROR   | ErrorReport: ✅
logger.error('error massage')            // 重要度: DEFAULT | ErrorReport:
logger.error(new Error('error message')) // 重要度: ERROR   | ErrorReport: ✅
// 実際の出力に使用している文字列は上記と異なるので、スクリーンショットの内容と若干異なります。

上記の記述順と出力順に若干のズレがあることに注意して下さい。

Error を出力したものに関してはログレベルに関係なく、Error Report が生成されました。
また、severity を設定しておらず、かつ Error はスタックトレースがブレーンテキストで出力されるため、引数に Error を渡したものは自動的に重要度が ERROR となります。
つまり、console と全く同じ結果となりました。

loglevel はログを構造化するフォーマットの変更が行えなかったので、severity を付与して重要度を最適化するというカスタマイズは行いませんでした。

console と全く同じ結果になり、また、重要度の最適化も行いにくいので、Cloud Logging と Error Report の観点だけで見ると console を使わずにあえて loglevel を使うメリットは薄いでしょう。

番外編

個人的には、例外を出力したときだけでなく、文字列やオブジェクトを logger.error() で出力したときも Error Report が生成されるとありがたいです。
3rd パーティーのライブラリによっては、処理中に例外をスローせず、独自のエラーオブジェクトやメッセージで返却するものもありますので、そういったものを手動で Error Report に残せると助かります。

要するにこういうことです。(logger.error を使用した場合、引数によらず Error Report が生成されてほしい)

logger.info('error massage')             // 重要度: INFO    | ErrorReport: 
logger.info(new Error('error message'))  // 重要度: INFO    | ErrorReport:
logger.warn('error massage')             // 重要度: WARNING | ErrorReport: 
logger.warn(new Error('error message'))  // 重要度: WARNING | ErrorReport:
logger.error('error massage')            // 重要度: ERROR   | ErrorReport: ✅ 
logger.error(new Error('error message')) // 重要度: ERROR   | ErrorReport: ✅

この要件を満たすようにロガーをカスタマイズするには、先の「Cloud Logging から Error Report が自動生成される条件」の項で記述したとおり、このようなデータ形式になっていれば良さそうです。

{
  "@type": "type.googleapis.com/google.devtools.clouderrorreporting.v1beta1.ReportedErrorEvent",
  "message": "A simple text message"
}

winston で実現する

console.log 以外で一番簡単にカスタムできたのは、winston でした。

const severity = winston.format((info) => {
  info["severity"] = info.level.toUpperCase();
  return info;
});

const errorReport = winston.format((info) => {
  if (info instanceof Error) {
    info.err = {
      name: info.name,
      message: info.message,
      stack: info.stack,
    };
  } else if (info.level === "error") {
    info["@type"] =
            "type.googleapis.com/google.devtools.clouderrorreporting.v1beta1.ReportedErrorEvent";
  }
  return info;
});

export const logger = winston.createLogger({
  level: "info",
  format: winston.format.combine(
    severity(),
    errorReport(),
    winston.format.json()
  ),
  transports: [new winston.transports.Console()],
});

logger.info('error massage')             // 重要度: INFO    | ErrorReport: 
logger.info(new Error('error message'))  // 重要度: INFO    | ErrorReport:
logger.warn('error massage')             // 重要度: WARNING | ErrorReport: 
logger.warn(new Error('error message'))  // 重要度: WARNING | ErrorReport:
logger.error('error massage')            // 重要度: ERROR   | ErrorReport: ✅ 
logger.error(new Error('error message')) // 重要度: ERROR   | ErrorReport: ✅
// 実際の出力に使用している文字列は上記と異なるので、スクリーンショットの内容と若干異なります。

pino はうまくできなかった

pino は、デフォルトのメッセージキーが msg となっており、messageKey: 'message' としてやる必要があります。
ただ、そうすると例外を処理する場合に err と message が競合してしまうために、Error Report は生成されれるもののスタックトレースが正しく記録されなくなってしまいました。
transport api などを使用すれば、競合しないようにできるのかもしれませんが、一旦これ以上の追求はやめておきます。

const logger = pino({
  level: "info",
  messageKey: "message",
  mixin: (context, level) => {
    if (labels[level] === "error")
      return {
        severity: labels[level].toUpperCase(),
        "@type":
          "type.googleapis.com/google.devtools.clouderrorreporting.v1beta1.ReportedErrorEvent",
      };
    return { severity: labels[level].toUpperCase() };
  },
});

出力結果 (err よりも、message が優先されて Error Report が生成されてしまうのでうまくいかない)

{
  "err": {
    "message": "..."
    "name": "..."
    "stack": "..."
  },
  "message": "err.messageと同じものが入る",
  "@type": "type.googleapis.com/google.devtools.clouderrorreporting.v1beta1.ReportedErrorEvent"
}

まとめ

実験の結果を簡単にまとめるとこんな感じになりました。カバーしたい要件に応じて、最適なロガーが変わってきます。

  • 重要度の最適化はせず、一旦、Error 出力時に Error Report が生成されていればよいのであれば console
    • winson 以外 (bunyan, pino, loglevel) なら、すべてデフォルトで要件を満たせるが、この条件なら、わざわざ 3rd パーティーなロガーを入れる必要はない
  • 重要度の最適化と Error 出力時の Error Report 生成の両方を取るの出れば pino
    • console, winston でも実現できるが、pino が一番カスタマイズの記述量が少なく済む
  • Error だけでなく文字列(エラーメッセージ)でも Error Report を生成したいのであれば console or winston
    • どちらにしてもカスタマイズは必要
GitHubで編集を提案

Discussion