AWS LambdaのNode.jsバージョンを上げるときはログのフォーマット変更にも注意

バージョンでログ出力が違うから注意

2019年末にlambdaのNode.js 8.10がEOLを迎えます。
ログ出力の部分で微妙に動作が違うので念の為確認してからバージョンアップしましょう。
特にログ出力をライブラリで行っている場合、そちらの実装がどうなっているか見ておいた方が良いです。
kibanaとかでパースするロジックに変更が必要になるかも。

Node.js 8.10

関数コード

exports.handler = async (event) => {
    // TODO implement
    const response = {
        statusCode: 200,
        body: JSON.stringify('Hello from Lambda!'),
    };
    // デフォルトのテンプレートにconsole.log入れただけ
    console.log(`"This is Node.js 8.10 log."`);
    return response;
};

Execution Result

Function Logs:
START RequestId: fcfedef6-ed16-4236-a407-5cc3d38bb2fe Version: $LATEST
2019-12-15T06:42:13.112Z fcfedef6-ed16-4236-a407-5cc3d38bb2fe "This is Node.js 8.10 log."
END RequestId: fcfedef6-ed16-4236-a407-5cc3d38bb2fe
REPORT RequestId: fcfedef6-ed16-4236-a407-5cc3d38bb2fe Duration: 0.49 ms Billed Duration: 100 ms Memory Size: 128 MB Max Memory Used: 58 MB

2019-12-15T06:42:13.112Z fcfedef6-ed16-4236-a407-5cc3d38bb2fe "This is Node.js 8.10 log."

が

実行日時 リクエストID console.logで出力した文字列

になってますね。

Node.js 10.x

関数コード

exports.handler = async (event) => {
    // TODO implement
    const response = {
        statusCode: 200,
        body: JSON.stringify('Hello from Lambda!'),
    };
    console.log(`"This is Node.js 10.x log."`);
    return response;
};

Execution Result

Function Logs:
START RequestId: b7b8a64d-0bcf-405e-8257-0fc6d3f62419 Version: $LATEST
2019-12-15T06:46:11.635Z b7b8a64d-0bcf-405e-8257-0fc6d3f62419 INFO "This is Node.js 10.x log."
END RequestId: b7b8a64d-0bcf-405e-8257-0fc6d3f62419
REPORT RequestId: b7b8a64d-0bcf-405e-8257-0fc6d3f62419 Duration: 59.33 ms Billed Duration: 100 ms Memory Size: 128 MB Max Memory Used: 76 MB Init Duration: 174.25 ms

2019-12-15T06:46:11.635Z b7b8a64d-0bcf-405e-8257-0fc6d3f62419 INFO "This is Node.js 10.x log."

が

実行日時 リクエストID ログレベル console.logで出力した文字列

と、出力されるようになっています。
8.10と比較するとログレベルが出力されるようになっていることに注意しましょう。

Node.js 12.x

Execution Result

Function Logs:
START RequestId: 786d807b-6bb9-4267-88f7-4df1f4955a7f Version: $LATEST
2019-12-15T06:47:52.767Z 786d807b-6bb9-4267-88f7-4df1f4955a7f INFO "This is Node.js 12.x log."END RequestId: 786d807b-6bb9-4267-88f7-4df1f4955a7f
REPORT RequestId: 786d807b-6bb9-4267-88f7-4df1f4955a7f Duration: 2.80 ms Billed Duration: 100 ms Memory Size: 128 MB Max Memory Used: 70 MB Init Duration: 111.41 ms

2019-12-15T06:47:52.767Z 786d807b-6bb9-4267-88f7-4df1f4955a7f INFO "This is Node.js 12.x log."END RequestId: 786d807b-6bb9-4267-88f7-4df1f4955a7f

が

実行日時 リクエストID ログレベル console.logで出力した文字列END RequestId: リクエストID

と、10.xとも違う、おそらくAWS側も意図していない動作をしてるように見受けられます。
(コピペミスとかでもなかったです)

とはいえ、CloudWatchには意図どおりに出力されてそうなので特に問題にはならないと思います。

補足

consoleオブジェクトの関数に応じてログレベルを出力するようになっているようです。

Node.js 8.10

関数コード

exports.handler = async (event) => {
  // TODO implement
  const response = {
      statusCode: 200,
      body: JSON.stringify('Hello from Lambda!'),
  };
  console.log(`"This is Node.js 8.10 log."`);
  console.info(`"This is Node.js 8.10 info log."`);
  console.warn(`"This is Node.js 8.10 warn log."`);
  console.error(`"This is Node.js 8.10 error log."`);
  return response;
};

Execution Result

Function Logs:
START RequestId: c2a0c056-7623-4c4f-bbad-6b458800cd7d Version: $LATEST
2019-12-15T07:18:36.692Z c2a0c056-7623-4c4f-bbad-6b458800cd7d "This is Node.js 8.10 log."
2019-12-15T07:18:36.692Z c2a0c056-7623-4c4f-bbad-6b458800cd7d "This is Node.js 8.10 info log."
2019-12-15T07:18:36.692Z c2a0c056-7623-4c4f-bbad-6b458800cd7d "This is Node.js 8.10 warn log."
2019-12-15T07:18:36.692Z c2a0c056-7623-4c4f-bbad-6b458800cd7d "This is Node.js 8.10 error log."
END RequestId: c2a0c056-7623-4c4f-bbad-6b458800cd7d
REPORT RequestId: c2a0c056-7623-4c4f-bbad-6b458800cd7d Duration: 0.50 ms Billed Duration: 100 ms Memory Size: 128 MB Max Memory Used: 58 MB

ログを見てもどんなレベルのログかが分からない。

Node.js 10.x

関数コード

exports.handler = async (event) => {
  // TODO implement
  const response = {
      statusCode: 200,
      body: JSON.stringify('Hello from Lambda!'),
  };
  console.log(`"This is Node.js 10.x log."`);
  console.info(`"This is Node.js 10.x info log."`);
  console.trace(`"This is Node.js 10.x trace log."`);
  console.debug(`"This is Node.js 10.x debug log."`);
  console.warn(`"This is Node.js 10.x warn log."`);
  console.error(`"This is Node.js 10.x error log."`);
  console.fatal(`"This is Node.js 10.x fatal log."`);
  return response;
};

Execution Result

Function Logs:
START RequestId: d12b8a86-62eb-4caa-9d09-ed66b1ec08ed Version: $LATEST
2019-12-15T07:15:02.460Z d12b8a86-62eb-4caa-9d09-ed66b1ec08ed INFO "This is Node.js 10.x log."
2019-12-15T07:15:02.465Z d12b8a86-62eb-4caa-9d09-ed66b1ec08ed INFO "This is Node.js 10.x info log."
2019-12-15T07:15:02.465Z d12b8a86-62eb-4caa-9d09-ed66b1ec08ed TRACE "This is Node.js 10.x trace log."
2019-12-15T07:15:02.465Z d12b8a86-62eb-4caa-9d09-ed66b1ec08ed DEBUG "This is Node.js 10.x debug log."
2019-12-15T07:15:02.465Z d12b8a86-62eb-4caa-9d09-ed66b1ec08ed WARN "This is Node.js 10.x warn log."
2019-12-15T07:15:02.465Z d12b8a86-62eb-4caa-9d09-ed66b1ec08ed ERROR "This is Node.js 10.x error log."
2019-12-15T07:15:02.465Z d12b8a86-62eb-4caa-9d09-ed66b1ec08ed FATAL "This is Node.js 10.x fatal log."
END RequestId: d12b8a86-62eb-4caa-9d09-ed66b1ec08ed
REPORT RequestId: d12b8a86-62eb-4caa-9d09-ed66b1ec08ed Duration: 47.48 ms Billed Duration: 100 ms Memory Size: 128 MB Max Memory Used: 76 MB Init Duration: 151.14 ms

どんなレベルのログが一目瞭然だし、ログのパースするときに便利そう。
8.10と比較すると種類も増えてます。他にもあるかも。

リンク

• https://docs.aws.amazon.com/ja_jp/lambda/latest/dg/nodejs-prog-model-logging.html
• https://docs.aws.amazon.com/ja_jp/lambda/latest/dg/programming-model.html