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

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

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

## Node.js 8.10

### 関数コード

```js
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

### 関数コード

```js
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側も意図していない動作をしてるように見受けられます。
(コピペミスとかでもなかったです)

![2019-12-15-15-52-35.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/221955/fbc96394-768b-d368-a8e5-f1d74276184e.png)

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

# 補足

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

## Node.js 8.10

### 関数コード

```js
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

### 関数コード

```js
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