📄
tslogで実現するセキュアなメタデータ管理とロギング
こんにちは、sugar-catです。
はじめに
皆さんはTypeScriptでバックエンド開発を行う際に、どのようにロギングをしていますか。
この記事では、TypeScript製のロギングライブラリであるtslogの紹介と、その内部の仕組み、秘匿情報を含むログを出力しないための方法について解説します。
ログの種類
この記事ではアプリケーションログを扱います。アプリケーションコンテナで出力された標準出力を収集し、任意の監視ツールに送信し表示されるようなログを指します。
アクセスログや監査ログ、システムログのようなものは扱いません。
tslogとは
tslogはTypeScript製で作成された、構造化ロギングを行うためのロギングライブラリです。
主な特徴として、Node.jsとブラウザのどちらにも対応しており、他のロギングライブラリと異なり外部のライブラリへの依存が一切ない点や、コードベースがTypeScriptであることが挙げられます。
構造化ログは一般的にJSONまたはlogfmt形式で出力されるログのことを指します。
お使いの監視SaaS（Grafana Loki、Datadogなど）であればどちらの形式でも対応していますが、JSON形式でのみ受けられるサポート（特定のメタデータを紐づけることでUIの表示をリッチにしてくれる等）やCloud LoggingのようなそもそもJSONしかサポートしていないサービスもあるので、基本はJSON形式で出力することが無難です。
tslogでもJSON形式のログが出力可能になっています。
対応形式としてはpretty、jsonが対応しています。
- pretty
開発時などに人間が読みやすい形でログを出力してくれるものです。
- JSON
その名の通りJSON形式でログを出力してくれます。
構造化ロギングライブラリの内部
ここではデフォルトの設定をオーバーライドせずに使用した際のtslogで、どのような処理が行われるかを見てみます。
import http from 'http';
import { Logger } from 'tslog';
const server = http.createServer(handle);
const logger = new Logger({ type: "json" });
function handle(req, res) {
logger.info(`[Request received]: ${req.method} ${req.url}`);
res.end('hello world');
}
server.listen(3000)
マスキングの過程を挟まない場合、tslogでは以下のような処理が行われます。
ユーザー指定のメッセージ、上記例では[Request received]:~という文字列を受け取り、それに対してメタデータ(ランタイムやバージョン、ホスト情報など)を付与してオブジェクトを作り、それをJSON.stringifyで文字列化してconsole.logに通して出力しています。
これらのそれぞれのステップはオーバーライド可能であり、必要があればユーザー側でカスタマイズすることが可能です。
マスキングについて
ここではログに秘匿情報を出力しない方法を考えます。
秘匿情報は氏名、住所のような個人情報を指し、一度ログに出力されてしまうと削除が難しい（出力先の権限やすぐにアーカイブされる等）ため、可能な限りアプリケーションレイヤーで秘匿情報の部分をマスキング、またはフィールドから削除することが望ましいです。
しかし多くの場合、実装者が気づかずに秘匿情報を含むオブジェクトをログの出力に含めてしまうことが起こりがちです。
レビュー等で弾ければ良いですが、可能なら人間の手を介さずに機械的にサニタイズすることが望ましいです。
tslogではマスキングを行うための仕組みが用意されています（再帰的にネストされたオブジェクトを探索し、文字列の場合にreplaceを挟む単純なものですが、結構自前で実装すると面倒なものです）。
この仕組みに乗っかることで、下記のようにログを簡単にマスキングすることができます。
import http from 'http';
import { Logger } from 'tslog';
const server = http.createServer(handle);
const logger = new Logger({
type: "json",
maskValuesOfKeys: ["password"],
maskPlaceholder: "[###]",
});
function handle(req, res) {
logger.info("Secret!" ,{
password: "pass123",
otherKey: "otherKey456",
});
res.end('hello world');
}
server.listen(3000)
また部分的に置換したい場合などは、正規表現を使ってマスキングすることも可能です。
import http from 'http';
import { Logger } from 'tslog';
const server = http.createServer(handle);
const logger = new Logger({
type: "json",
maskValuesRegEx: [new RegExp("otherKey", "g")],
});
function handle(req, res) {
logger.info("Secret!" ,{
password: "pass123",
otherKey: "otherKey456",
});
res.end('hello world');
}
server.listen(3000)
このようにマスキングのための仕組みが用意されているので、秘匿情報を含むオブジェクトをログに出力する際には利用しましょう。
この方法ではあらかじめマスキング対象のキーが分かっている場合には有用ですが、事故で不必要なフィールドが含まれてしまった場合にはサニタイズすることはできません。
そのため、tslogでいうところの
1.メッセージ入力時またはtoLogObjectのオブジェクト生成時にあらかじめ型を定義しておきパースする
2.transportの際のJSON.stringifyでフィルタリングする
の方法でそもそもログに不要なフィールドを含まないようにすることが望ましいです。
1であればzodを使用してオブジェクトをparseしてあげることで、不要なフィールドを削除することができます。
これはデータベースから取得した行の不要な列を落とすなどの使い方がされています。
loggerでも同様に、ユーザー入力のオブジェクトをパースしてあげることで、不要なフィールドを削除することができます。
import http, { IncomingHttpHeaders, IncomingMessage, ServerResponse } from 'http';
import { IMeta, Logger } from 'tslog';
import z from 'zod';
const reqSchema = z.object({
requestId: z.string(),
nestedExample: z.object({
level1: z.object({
level2: z.object({
level3: z.string(),
}),
}),
}),
});
const server = http.createServer(handle);
function handle(req: IncomingMessage, res: ServerResponse): void {
const logger = new Logger({ type: "json", hideLogPositionForProduction: true });
logger.info('Request Start', reqSchema.parse({
secret: "secret",
requestId: 'test-id',
nestedExample: { level1: { level2: { level3: 'Deep Value' } } },
}));
res.end('hello world');
}
server.listen(3000);
このようにzodを使ってパースすることで、不要なフィールドを削除することができます。
これでログに秘匿情報を含まないようにすることができました。
しかし、logger内部の実行順序的にオブジェクトを作る段階でのパースだと、後続の処理で何かしら不要なフィールドが入りうる場合があります。
秘匿情報が混入する可能性は低いとは思いますが、metadata側での重い処理（例えばスタックフレームなど）を含める処理が何らかの拍子でオン(例えば環境変数で制御している場合など)になってしまっていた場合、パフォーマンスの問題を引き起こす可能性があります。
そこで2のように、tslogとしてtransport時にフィルタリングする方法で最後にログをフィルタリングしてあげることで、ユーザー起因のオブジェクト、メタデータのサニタイズを行うことができます。
デフォルトの実装(transportJSON)だと、渡ってきたオブジェクトをそのままJSON.stringifyしているので、不要なフィールドを含まないようにJSON.stringifyの実装を調整する必要があります。
上記コードでも使用されているように、JSON.stringifyは第二引数にreplacerを持ちます。
replacerは一般的に値を置き換える際に使用されます。
undifinedやBigInt, Symbol, functionの場合はそのままシリアライズできないので、replacerで置き換える対応がされます。
ここの部分に任意のフィルタリングを書いていくことも可能ですが、ログの出力が増えるたびにロジックの修正やテストが必要になり、あまりスマートな方法ではありません。
そこでtypiaを使用します。
typiaの説明は省きますが、TypeScriptの型情報を元にコンパイル時にValidationを生成することができるライブラリです。
下記の記事が参考になります。
typiaにはJSON.stringifyのreplacer部分をよしなにしてくれるstringifyという関数があります。
これを使用することによってTypeScriptの型情報を元にログの出力を強制することが可能になります。
オーバーライドを使用してtransportJSONをtypiaを使用したstringifyに差し替えます。
import http, { IncomingMessage, ServerResponse } from "http";
import { Logger } from "tslog";
import { IMeta } from "tslog/dist/types/runtime/nodejs";
import { is } from "typia";
import { createStringify } from "typia/lib/json";
type LoggerObj = {
message: string;
payload: {
nestedExample: { level1: { level2: { level3: string } } };
};
_meta: IMeta;
};
const stringifyLoggerObj = createStringify<LoggerObj>();
const server = http.createServer(handle);
function tj(json: unknown): void {
if (!typeGuardLoggerObj(json)) {
return;
}
console.log(stringifyLoggerObj(json));
}
function typeGuardLoggerObj(json: unknown): json is LoggerObj {
return is<LoggerObj>(json);
}
const logger = new Logger({
type: "json",
hideLogPositionForProduction: true,
overwrite: {
transportJSON: tj,
},
});
function handle(req: IncomingMessage, res: ServerResponse): void {
logger.info({
message: "Request Start",
payload: {
secret: "password",
nestedExample: { level1: { level2: { level3: "hoge" } } },
},
});
res.end("hello world");
}
server.listen(3000);
上記をtscでコンパイルし、実行すると以下のような出力になります。
このようにそもそも定義されていない型情報(今回の例だとsecret)は出力されません。
これはtypiaがコンパイル時にstringifyLoggerObj内部で型情報を元にフィルタリングを行うロジックを生成しているためです。
コンパイル結果
"use strict";
var __importDefault =
(this && this.__importDefault) ||
function (mod) {
return mod && mod.__esModule ? mod : { default: mod };
};
Object.defineProperty(exports, "__esModule", { value: true });
const http_1 = __importDefault(require("http"));
const tslog_1 = require("tslog");
const typia_1 = require("typia");
const json_1 = require("typia/lib/json");
const stringifyLoggerObj = (() => {
const $string = json_1.createStringify.string;
const $tail = json_1.createStringify.tail;
const $so0 = (input) =>
`{"message":${$string(input.message)},"payload":${$so1(
input.payload
)},"_meta":${$so5(input._meta)}}`;
const $so1 = (input) => `{"nestedExample":${$so2(input.nestedExample)}}`;
const $so2 = (input) => `{"level1":${$so3(input.level1)}}`;
const $so3 = (input) => `{"level2":${$so4(input.level2)}}`;
const $so4 = (input) => `{"level3":${$string(input.level3)}}`;
const $so5 = (input) =>
`{${
undefined === input.path
? ""
: `"path":${undefined !== input.path ? $so6(input.path) : undefined},`
}${
undefined === input.name
? ""
: `"name":${
undefined !== input.name ? $string(input.name) : undefined
},`
}${
undefined === input.parentNames
? ""
: `"parentNames":${
undefined !== input.parentNames
? `[${input.parentNames.map((elem) => $string(elem)).join(",")}]`
: undefined
},`
}${
undefined === input.hostname
? ""
: `"hostname":${
undefined !== input.hostname ? $string(input.hostname) : undefined
},`
}"date":${$string(input.date.toJSON())},"logLevelId":${
input.logLevelId
},"logLevelName":${$string(input.logLevelName)},"runtime":${$string(
input.runtime
)},"runtimeVersion":${$string(input.runtimeVersion)}}`;
const $so6 = (input) =>
`{${$tail(
`${
undefined === input.fullFilePath
? ""
: `"fullFilePath":${
undefined !== input.fullFilePath
? $string(input.fullFilePath)
: undefined
},`
}${
undefined === input.fileName
? ""
: `"fileName":${
undefined !== input.fileName ? $string(input.fileName) : undefined
},`
}${
undefined === input.fileNameWithLine
? ""
: `"fileNameWithLine":${
undefined !== input.fileNameWithLine
? $string(input.fileNameWithLine)
: undefined
},`
}${
undefined === input.filePath
? ""
: `"filePath":${
undefined !== input.filePath ? $string(input.filePath) : undefined
},`
}${
undefined === input.fileLine
? ""
: `"fileLine":${
undefined !== input.fileLine ? $string(input.fileLine) : undefined
},`
}${
undefined === input.fileColumn
? ""
: `"fileColumn":${
undefined !== input.fileColumn
? $string(input.fileColumn)
: undefined
},`
}${
undefined === input.filePathWithLine
? ""
: `"filePathWithLine":${
undefined !== input.filePathWithLine
? $string(input.filePathWithLine)
: undefined
},`
}${
undefined === input.method
? ""
: `"method":${
undefined !== input.method ? $string(input.method) : undefined
}`
}`
)}}`;
const $io1 = (input) =>
"object" === typeof input.nestedExample &&
null !== input.nestedExample &&
$io2(input.nestedExample);
const $io2 = (input) =>
"object" === typeof input.level1 &&
null !== input.level1 &&
$io3(input.level1);
const $io3 = (input) =>
"object" === typeof input.level2 &&
null !== input.level2 &&
$io4(input.level2);
const $io4 = (input) => "string" === typeof input.level3;
const $io5 = (input) =>
input.date instanceof Date &&
"number" === typeof input.logLevelId &&
"string" === typeof input.logLevelName &&
(undefined === input.path ||
("object" === typeof input.path &&
null !== input.path &&
false === Array.isArray(input.path) &&
$io6(input.path))) &&
(undefined === input.name || "string" === typeof input.name) &&
(undefined === input.parentNames ||
(Array.isArray(input.parentNames) &&
input.parentNames.every((elem) => "string" === typeof elem))) &&
"string" === typeof input.runtime &&
"string" === typeof input.runtimeVersion &&
(undefined === input.hostname || "string" === typeof input.hostname);
const $io6 = (input) =>
(undefined === input.fullFilePath ||
"string" === typeof input.fullFilePath) &&
(undefined === input.fileName || "string" === typeof input.fileName) &&
(undefined === input.fileNameWithLine ||
"string" === typeof input.fileNameWithLine) &&
(undefined === input.filePath || "string" === typeof input.filePath) &&
(undefined === input.fileLine || "string" === typeof input.fileLine) &&
(undefined === input.fileColumn || "string" === typeof input.fileColumn) &&
(undefined === input.filePathWithLine ||
"string" === typeof input.filePathWithLine) &&
(undefined === input.method || "string" === typeof input.method);
return (input) => $so0(input);
})();
const server = http_1.default.createServer(handle);
function tj(json) {
if (!typeGuardLoggerObj(json)) {
return;
}
console.log(stringifyLoggerObj(json));
}
function typeGuardLoggerObj(json) {
return (() => {
const $io0 = (input) =>
"string" === typeof input.message &&
"object" === typeof input.payload &&
null !== input.payload &&
$io1(input.payload) &&
"object" === typeof input._meta &&
null !== input._meta &&
$io5(input._meta);
const $io1 = (input) =>
"object" === typeof input.nestedExample &&
null !== input.nestedExample &&
$io2(input.nestedExample);
const $io2 = (input) =>
"object" === typeof input.level1 &&
null !== input.level1 &&
$io3(input.level1);
const $io3 = (input) =>
"object" === typeof input.level2 &&
null !== input.level2 &&
$io4(input.level2);
const $io4 = (input) => "string" === typeof input.level3;
const $io5 = (input) =>
input.date instanceof Date &&
"number" === typeof input.logLevelId &&
"string" === typeof input.logLevelName &&
(undefined === input.path ||
("object" === typeof input.path &&
null !== input.path &&
false === Array.isArray(input.path) &&
$io6(input.path))) &&
(undefined === input.name || "string" === typeof input.name) &&
(undefined === input.parentNames ||
(Array.isArray(input.parentNames) &&
input.parentNames.every((elem) => "string" === typeof elem))) &&
"string" === typeof input.runtime &&
"string" === typeof input.runtimeVersion &&
(undefined === input.hostname || "string" === typeof input.hostname);
const $io6 = (input) =>
(undefined === input.fullFilePath ||
"string" === typeof input.fullFilePath) &&
(undefined === input.fileName || "string" === typeof input.fileName) &&
(undefined === input.fileNameWithLine ||
"string" === typeof input.fileNameWithLine) &&
(undefined === input.filePath || "string" === typeof input.filePath) &&
(undefined === input.fileLine || "string" === typeof input.fileLine) &&
(undefined === input.fileColumn ||
"string" === typeof input.fileColumn) &&
(undefined === input.filePathWithLine ||
"string" === typeof input.filePathWithLine) &&
(undefined === input.method || "string" === typeof input.method);
return (input) =>
"object" === typeof input && null !== input && $io0(input);
})()(json);
}
const logger = new tslog_1.Logger({
type: "json",
hideLogPositionForProduction: true,
overwrite: {
transportJSON: tj,
},
});
function handle(req, res) {
logger.info({
message: "Request Start",
payload: {
secret: "password",
nestedExample: { level1: { level2: { level3: "hoge" } } },
},
});
res.end("hello world");
}
server.listen(3000);
以上のようにtypiaを使用することで、TypeScriptの型情報を元にログの出力を安全に扱うことができるようになりました。
おまけ
typiaは速度面でも優れているようなので、比較してみました。
実行環境
- アプリケーションサーバーが動くコンテナ（CPU 1、Memory 512MB）とリクエストを送るコンテナを用意し、
autocannonで負荷をかける
-
同一ネットワークに閉じて実行
-
アプリケーションではマスキングは行わず、ピュアにオブジェクトのパースのみの性能で検証するためにマスクの処理をスキップ(
maskValuesOfKeysがデフォルトで["password"]になっているので注意)
比較対象
- A.transportJSONを
JSON.stringifyにした場合 - B.transportJSONを
JSON.stringify+ loggerに渡すObjectをzodでパースした場合 - C.transportJSONを
typiaを使用したstringifyにした場合
負荷のかけ方
最初の3秒間でウォームアップを行い、その後30秒間にわたり、100の同時接続しつつ10のリクエストをパイプライン化して送信。コンテナを作り直し5回繰り返す。
比較の仕方
30秒間で得た総処理数からrpsを計算
計測に使用したコード
import http, {
IncomingHttpHeaders,
IncomingMessage,
ServerResponse,
} from "http";
import { Logger } from "tslog";
import { IMeta } from "tslog/dist/types/runtime/nodejs";
import { createStringify } from "typia/lib/json";
import z from "zod";
type LoggerObj = {
0: string;
1: {
url: string;
method: string;
headers: IncomingHttpHeaders;
requestId: string;
nestedExample: { level1: { level2: { level3: string } } };
};
_meta: IMeta;
};
const reqSchema = z.object({
url: z.string(),
method: z.string(),
headers: z.record(z.string()),
requestId: z.string(),
nestedExample: z.object({
level1: z.object({
level2: z.object({
level3: z.string(),
}),
}),
}),
});
const stringifyRequestInfo = createStringify<LoggerObj>();
const server = http.createServer(handle);
function tj(json: unknown): void {
// console.log(stringifyRequestInfo(json)); Cのパターン
// console.log(JSON.stringify(json)); A/Bのパターン
}
function handle(req: IncomingMessage, res: ServerResponse): void {
const logger = new Logger({
type: "json",
hideLogPositionForProduction: true,
maskValuesOfKeys:[],
overwrite: {
transportJSON: tj,
},
});
const obj = {
url: req.url,
method: req.method,
headers: req.headers,
requestId: "test-id",
nestedExample: { level1: { level2: { level3: "test" } } },
}; // A/Cのパターン
// const obj2 = reqSchema.parse(obj); // Bのパターン
logger.info("Request Start", obj);
res.end("hello world");
}
server.listen(3000);
FROM node:20
WORKDIR /app
COPY bench .
RUN npm install
ENV NODE_ENV=production
EXPOSE 3000
services:
server:
build: .
container_name: server_container
ports:
- "3000:3000"
command: ["node", "index.js"]
deploy:
resources:
limits:
cpus: '1'
memory: 512M
networks:
- app-network
autocannon:
image: node:20
container_name: autocannon_container
working_dir: /app
volumes:
- .:/app
depends_on:
- server
entrypoint: ["sh", "-c", "npm install -g autocannon && /app/run.sh"]
deploy:
resources:
limits:
cpus: '1'
memory: 256M
networks:
- app-network
networks:
app-network:
driver: bridge
#!/usr/bin/env sh
echo "##### Starting Load Test with Autocannon #####"
echo
# ウォームアップ実行
autocannon -c 100 -d 3 -p 10 http://server:3000 > /dev/null 2>&1
# 本番負荷テスト実行
autocannon -c 100 -d 30 -p 10 http://server:3000
echo "##### Load Test Completed #####"
echo
結果
結果は下記の通りです（単位時間あたりに処理したリクエスト数の平均値の5回分の平均を取った値です。小数点第一位を四捨五入しています）。
| テスト項目(rps) | 1回目 | 2回目 | 3回目 | 4回目 | 5回目 | 平均 (Avg) |
|---|---|---|---|---|---|---|
| A (素) | 37,845 | 36,756 | 37,708 | 37,166 | 36,679 | 37,231 |
| B (素 + Zod) | 32,618 | 32,830 | 33,100 | 32,965 | 32,990 | 32,901 |
| C (Typia) | 38,185 | 37,017 | 37,842 | 38,966 | 37,125 | 37,827 |
autocannonのログ例
##### Starting Load Test with Autocannon #####
Running 30s test @ http://server:3000
100 connections with 10 pipelining factor
┌─────────┬───────┬───────┬───────┬───────┬──────────┬─────────┬───────┐
│ Stat │ 2.5% │ 50% │ 97.5% │ 99% │ Avg │ Stdev │ Max │
├─────────┼───────┼───────┼───────┼───────┼──────────┼─────────┼───────┤
│ Latency │ 15 ms │ 31 ms │ 35 ms │ 37 ms │ 25.92 ms │ 8.21 ms │ 77 ms │
└─────────┴───────┴───────┴───────┴───────┴──────────┴─────────┴───────┘
┌───────────┬─────────┬─────────┬─────────┬─────────┬───────────┬──────────┬─────────┐
│ Stat │ 1% │ 2.5% │ 50% │ 97.5% │ Avg │ Stdev │ Min │
├───────────┼─────────┼─────────┼─────────┼─────────┼───────────┼──────────┼─────────┤
│ Req/Sec │ 33,023 │ 33,023 │ 38,335 │ 38,975 │ 37,845.34 │ 1,203.14 │ 32,992 │
├───────────┼─────────┼─────────┼─────────┼─────────┼───────────┼──────────┼─────────┤
│ Bytes/Sec │ 4.42 MB │ 4.42 MB │ 5.14 MB │ 5.22 MB │ 5.07 MB │ 162 kB │ 4.42 MB │
└───────────┴─────────┴─────────┴─────────┴─────────┴───────────┴──────────┴─────────┘
Req/Bytes counts sampled once per second.
# of samples: 30
1136k requests in 30.03s, 152 MB read
##### Load Test Completed #####
結果より、Bのzodのパースを挟んだ処理では明らかに処理性能が落ちていることがわかります。
一方でA、Cのパターンではほぼ変わらない結果となりました。これは渡されたオブジェクトが小さいおよび、別の処理がボトルネックとなり、stringifyの性能の差ではあまり影響がなかったためと考えられます。
Node.jsの組み込みのプロファイリングしてみた結果、Nodeのプロセスにおいてはconsole.logの内部関数(node:internal/console/constructor)やストリーム関連の内部関数writeGeneric、writeOrBuffer、_writeが支配的であることがわかりました。
プロファイリング結果
Testing v8 version different from logging version
Statistical profiling result from profiles/typia-nomask.log, (16417 ticks, 0 unaccounted, 0 excluded).
[Shared libraries]:
ticks total nonlib name
7829 47.7% /usr/lib/aarch64-linux-gnu/libc.so.6
6319 38.5% /usr/local/bin/node
82 0.5% [vdso]
82 0.5% /usr/lib/aarch64-linux-gnu/libstdc++.so.6.0.30
2 0.0% /usr/lib/aarch64-linux-gnu/libgcc_s.so.1
1 0.0% /usr/lib/aarch64-linux-gnu/libm.so.6
[JavaScript]:
ticks total nonlib name
143 0.9% 6.8% JS: *resOnFinish node:_http_server:968:21
112 0.7% 5.3% JS: *$string /app/node_modules/typia/lib/functional/$string.js:17:24
103 0.6% 4.9% JS: *$so2 /app/index.js:9:503
102 0.6% 4.9% JS: *log /app/node_modules/tslog/dist/cjs/BaseLogger.js:88:8
94 0.6% 4.5% JS: *BaseLogger /app/node_modules/tslog/dist/cjs/BaseLogger.js:25:16
89 0.5% 4.2% JS: *Readable.on node:internal/streams/readable:1125:33
85 0.5% 4.0% JS: *$so0 /app/index.js:9:189
80 0.5% 3.8% JS: *processTicksAndRejections node:internal/process/task_queues:67:35
78 0.5% 3.7% JS: *parserOnIncoming node:_http_server:1028:26
73 0.4% 3.5% JS: *endReadable node:internal/streams/readable:1680:21
66 0.4% 3.1% JS: *writeOrBuffer node:internal/streams/writable:546:23
55 0.3% 2.6% JS: *onwrite node:internal/streams/writable:613:17
54 0.3% 2.6% JS: *Readable node:internal/streams/readable:318:18
53 0.3% 2.5% JS: *clearBuffer node:internal/streams/writable:742:21
52 0.3% 2.5% JS: *Socket._writeGeneric node:net:923:42
47 0.3% 2.2% JS: *_write node:internal/streams/writable:451:16
46 0.3% 2.2% JS: *parserOnHeadersComplete node:_http_common:71:33
38 0.2% 1.8% JS: *log node:internal/console/constructor:384:6
37 0.2% 1.8% JS: *updateOutgoingData node:_http_server:753:28
37 0.2% 1.8% JS: *Writable.write node:internal/streams/writable:502:36
35 0.2% 1.7% JS: *handle /app/index.js:33:16
30 0.2% 1.4% JS: *end node:_http_outgoing:1030:45
29 0.2% 1.4% JS: *parserOnMessageComplete node:_http_common:136:33
29 0.2% 1.4% JS: *_storeHeader node:_http_outgoing:410:22
24 0.1% 1.1% JS: *detachSocket node:_http_server:292:62
24 0.1% 1.1% JS: *assignSocket node:_http_server:281:62
23 0.1% 1.1% JS: *get node:internal/console/constructor:214:14
22 0.1% 1.0% JS: *get node:internal/bootstrap/node:100:8
22 0.1% 1.0% JS: *_destroy node:_http_incoming:218:55
21 0.1% 1.0% JS: *callback node:internal/streams/writable:762:63
20 0.1% 1.0% JS: *onFinish node:_http_outgoing:1025:18
20 0.1% 1.0% JS: *emitReadable node:internal/streams/readable:817:22
20 0.1% 1.0% JS: *ServerResponse node:_http_server:195:24
17 0.1% 0.8% JS: *emitReadable_ node:internal/streams/readable:828:23
16 0.1% 0.8% JS: *write_ node:_http_outgoing:894:16
16 0.1% 0.8% JS: *value node:internal/console/constructor:277:20
16 0.1% 0.8% JS: *get node:_http_incoming:109:16
15 0.1% 0.7% JS: *resume node:internal/streams/readable:1245:16
14 0.1% 0.7% JS: *writeGeneric node:internal/stream_base_commons:148:22
14 0.1% 0.7% JS: *resume_ node:internal/streams/readable:1252:17
14 0.1% 0.7% JS: *addListener node:events:610:58
13 0.1% 0.6% JS: *endReadableNT node:internal/streams/readable:1690:23
13 0.1% 0.6% JS: *emitCloseNT node:internal/streams/destroy:132:21
13 0.1% 0.6% JS: *afterWriteTick node:internal/streams/writable:691:24
12 0.1% 0.6% JS: *writeHead node:_http_server:341:19
12 0.1% 0.6% JS: *onDestroy node:internal/streams/destroy:92:21
11 0.1% 0.5% JS: *matchKnownFields node:_http_incoming:276:26
11 0.1% 0.5% JS: *_dump node:_http_incoming:429:49
11 0.1% 0.5% JS: *Readable.read node:internal/streams/readable:645:35
10 0.1% 0.5% JS: *$so5 /app/index.js:20:196
9 0.1% 0.4% JS: *onParserExecuteCommon node:_http_server:905:31
9 0.1% 0.4% JS: *insertGuarded node:internal/timers:340:23
9 0.1% 0.4% JS: *Readable.push node:internal/streams/readable:385:35
8 0.0% 0.4% JS: *formatWithOptionsInternal node:internal/util/inspect:2185:35
8 0.0% 0.4% JS: *<anonymous> node:internal/validators:459:42
7 0.0% 0.3% JS: *setStreamTimeout node:internal/stream_base_commons:238:26
7 0.0% 0.3% JS: *emitCloseNT node:_http_server:1017:21
6 0.0% 0.3% RegExp: [^\t\x20-\x7e\x80-\xff]
6 0.0% 0.3% JS: *formatWithOptions node:internal/util/inspect:2164:27
6 0.0% 0.3% JS: *<anonymous> node:internal/console/constructor:364:10
5 0.0% 0.2% JS: *get node:internal/streams/writable:1008:8
3 0.0% 0.1% JS: *onParserExecute node:_http_server:832:25
3 0.0% 0.1% JS: *_finish node:_http_server:231:52
3 0.0% 0.1% JS: *Writable.uncork node:internal/streams/writable:518:37
2 0.0% 0.1% JS: ^resOnFinish node:_http_server:968:21
2 0.0% 0.1% JS: *slowCases node:internal/util:207:19
2 0.0% 0.1% JS: *setUnrefTimeout node:internal/timers:389:25
2 0.0% 0.1% JS: *processPromiseRejections node:internal/process/promises:436:34
2 0.0% 0.1% JS: *ReadableState node:internal/streams/readable:260:23
1 0.0% 0.0% JS: ^parserOnIncoming node:_http_server:1028:26
1 0.0% 0.0% JS: ^onwrite node:internal/streams/writable:613:17
1 0.0% 0.0% JS: ^insertGuarded node:internal/timers:340:23
1 0.0% 0.0% JS: ^emit node:events:466:44
1 0.0% 0.0% JS: ^checkError node:internal/streams/destroy:32:20
1 0.0% 0.0% JS: ^_addMetaToLogObj /app/node_modules/tslog/dist/cjs/BaseLogger.js:284:21
1 0.0% 0.0% JS: ^$so2 /app/index.js:9:503
1 0.0% 0.0% JS: *resetSocketTimeout node:_http_server:1147:28
1 0.0% 0.0% JS: *nop node:_http_outgoing:87:13
1 0.0% 0.0% JS: *checkListener node:events:275:23
1 0.0% 0.0% JS: *Writable.cork node:internal/streams/writable:511:35
1 0.0% 0.0% JS: *Socket.resume node:net:759:35
[C++]:
ticks total nonlib name
[Summary]:
ticks total nonlib name
2102 12.8% 100.0% JavaScript
0 0.0% 0.0% C++
678 4.1% 32.3% GC
14315 87.2% Shared libraries
[C++ entry points]:
ticks cpp total name
[Bottom up (heavy) profile]:
Note: percentage shows a share of a particular caller in the total
amount of its parent calls.
Callers occupying less than 1.0% are not shown.
ticks parent name
7829 47.7% /usr/lib/aarch64-linux-gnu/libc.so.6
3711 47.4% JS: *Socket._writeGeneric node:net:923:42
3706 99.9% JS: *clearBuffer node:internal/streams/writable:742:21
2838 76.6% JS: *assignSocket node:_http_server:281:62
2836 99.9% JS: *resOnFinish node:_http_server:968:21
2836 100.0% JS: *onFinish node:_http_outgoing:1025:18
868 23.4% JS: *Writable.uncork node:internal/streams/writable:518:37
868 100.0% JS: *end node:_http_outgoing:1030:45
868 100.0% JS: *handle /app/index.js:33:16
2627 33.6% JS: *writeGeneric node:internal/stream_base_commons:148:22
2623 99.8% JS: *writeOrBuffer node:internal/streams/writable:546:23
2623 100.0% JS: *_write node:internal/streams/writable:451:16
2623 100.0% JS: *value node:internal/console/constructor:277:20
2623 100.0% JS: *log node:internal/console/constructor:384:6
324 4.1% JS: *clearBuffer node:internal/streams/writable:742:21
257 79.3% JS: *assignSocket node:_http_server:281:62
256 99.6% JS: *resOnFinish node:_http_server:968:21
256 100.0% JS: *onFinish node:_http_outgoing:1025:18
256 100.0% JS: *callback node:internal/streams/writable:762:63
66 20.4% JS: *Writable.uncork node:internal/streams/writable:518:37
66 100.0% JS: *end node:_http_outgoing:1030:45
66 100.0% JS: *handle /app/index.js:33:16
66 100.0% JS: *parserOnIncoming node:_http_server:1028:26
255 3.3% /usr/local/bin/node
250 98.0% JS: *$so0 /app/index.js:9:189
249 99.6% JS: *log /app/node_modules/tslog/dist/cjs/BaseLogger.js:88:8
249 100.0% JS: *handle /app/index.js:33:16
245 98.4% JS: *parserOnIncoming node:_http_server:1028:26
4 1.6% JS: *emit node:events:466:44
251 3.2% JS: *writeOrBuffer node:internal/streams/writable:546:23
247 98.4% JS: *_write node:internal/streams/writable:451:16
247 100.0% JS: *value node:internal/console/constructor:277:20
247 100.0% JS: *log node:internal/console/constructor:384:6
247 100.0% /usr/local/bin/node
3 1.2% JS: ^_write node:internal/streams/writable:451:16
3 100.0% JS: *value node:internal/console/constructor:277:20
2 66.7% JS: *log node:internal/console/constructor:384:6
2 100.0% /usr/local/bin/node
1 33.3% JS: ^log node:internal/console/constructor:384:6
1 100.0% /usr/local/bin/node
6319 38.5% /usr/local/bin/node
947 15.0% JS: *log /app/node_modules/tslog/dist/cjs/BaseLogger.js:88:8
947 100.0% JS: *handle /app/index.js:33:16
939 99.2% JS: *parserOnIncoming node:_http_server:1028:26
939 100.0% JS: *parserOnHeadersComplete node:_http_common:71:33
684 10.8% JS: *Socket._writeGeneric node:net:923:42
684 100.0% JS: *clearBuffer node:internal/streams/writable:742:21
551 80.6% JS: *assignSocket node:_http_server:281:62
549 99.6% JS: *resOnFinish node:_http_server:968:21
549 100.0% JS: *onFinish node:_http_outgoing:1025:18
133 19.4% JS: *Writable.uncork node:internal/streams/writable:518:37
133 100.0% JS: *end node:_http_outgoing:1030:45
133 100.0% JS: *handle /app/index.js:33:16
584 9.2% /usr/local/bin/node
215 36.8% JS: *log /app/node_modules/tslog/dist/cjs/BaseLogger.js:88:8
215 100.0% JS: *handle /app/index.js:33:16
214 99.5% JS: *parserOnIncoming node:_http_server:1028:26
214 100.0% JS: *parserOnHeadersComplete node:_http_common:71:33
197 33.7% JS: *$so0 /app/index.js:9:189
195 99.0% JS: *log /app/node_modules/tslog/dist/cjs/BaseLogger.js:88:8
195 100.0% JS: *handle /app/index.js:33:16
194 99.5% JS: *parserOnIncoming node:_http_server:1028:26
2 1.0% JS: ^<anonymous> /app/index.js:27:1423
2 100.0% JS: ^tj /app/index.js:29:12
2 100.0% JS: ^log /app/node_modules/tslog/dist/cjs/BaseLogger.js:88:8
112 19.2% JS: *$so2 /app/index.js:9:503
112 100.0% JS: *$so0 /app/index.js:9:189
112 100.0% JS: *log /app/node_modules/tslog/dist/cjs/BaseLogger.js:88:8
112 100.0% JS: *handle /app/index.js:33:16
21 3.6% /usr/local/bin/node
21 100.0% JS: *$so0 /app/index.js:9:189
21 100.0% JS: *log /app/node_modules/tslog/dist/cjs/BaseLogger.js:88:8
21 100.0% JS: *handle /app/index.js:33:16
19 3.3% JS: *clearBuffer node:internal/streams/writable:742:21
18 94.7% JS: *assignSocket node:_http_server:281:62
18 100.0% JS: *resOnFinish node:_http_server:968:21
18 100.0% JS: *onFinish node:_http_outgoing:1025:18
1 5.3% JS: *Writable.uncork node:internal/streams/writable:518:37
1 100.0% JS: *end node:_http_outgoing:1030:45
1 100.0% JS: *handle /app/index.js:33:16
9 1.5% JS: *parserOnIncoming node:_http_server:1028:26
9 100.0% JS: *parserOnHeadersComplete node:_http_common:71:33
382 6.0% JS: *$so0 /app/index.js:9:189
380 99.5% JS: *log /app/node_modules/tslog/dist/cjs/BaseLogger.js:88:8
380 100.0% JS: *handle /app/index.js:33:16
379 99.7% JS: *parserOnIncoming node:_http_server:1028:26
379 100.0% JS: *parserOnHeadersComplete node:_http_common:71:33
361 5.7% JS: *log node:internal/console/constructor:384:6
361 100.0% /usr/local/bin/node
361 100.0% JS: *log /app/node_modules/tslog/dist/cjs/BaseLogger.js:88:8
361 100.0% JS: *handle /app/index.js:33:16
358 99.2% JS: *parserOnIncoming node:_http_server:1028:26
343 5.4% JS: *writeGeneric node:internal/stream_base_commons:148:22
342 99.7% JS: *writeOrBuffer node:internal/streams/writable:546:23
342 100.0% JS: *_write node:internal/streams/writable:451:16
342 100.0% JS: *value node:internal/console/constructor:277:20
342 100.0% JS: *log node:internal/console/constructor:384:6
211 3.3% JS: *handle /app/index.js:33:16
207 98.1% JS: *parserOnIncoming node:_http_server:1028:26
207 100.0% JS: *parserOnHeadersComplete node:_http_common:71:33
133 2.1% JS: *Readable.on node:internal/streams/readable:1125:33
76 57.1% JS: *assignSocket node:_http_server:281:62
68 89.5% JS: *resOnFinish node:_http_server:968:21
68 100.0% JS: *onFinish node:_http_outgoing:1025:18
68 100.0% JS: *callback node:internal/streams/writable:762:63
8 10.5% JS: *parserOnIncoming node:_http_server:1028:26
8 100.0% JS: *parserOnHeadersComplete node:_http_common:71:33
53 39.8% JS: *value node:internal/console/constructor:277:20
53 100.0% JS: *log node:internal/console/constructor:384:6
53 100.0% /usr/local/bin/node
53 100.0% JS: *log /app/node_modules/tslog/dist/cjs/BaseLogger.js:88:8
4 3.0% JS: *resOnFinish node:_http_server:968:21
4 100.0% JS: *onFinish node:_http_outgoing:1025:18
4 100.0% JS: *callback node:internal/streams/writable:762:63
4 100.0% JS: *afterWriteTick node:internal/streams/writable:691:24
108 1.7% JS: *get node:_http_incoming:109:16
108 100.0% JS: *parserOnIncoming node:_http_server:1028:26
108 100.0% JS: *parserOnHeadersComplete node:_http_common:71:33
89 1.4% JS: *clearBuffer node:internal/streams/writable:742:21
65 73.0% JS: *assignSocket node:_http_server:281:62
64 98.5% JS: *resOnFinish node:_http_server:968:21
64 100.0% JS: *onFinish node:_http_outgoing:1025:18
64 100.0% JS: *callback node:internal/streams/writable:762:63
1 1.5% JS: ^resOnFinish node:_http_server:968:21
1 100.0% JS: *emit node:events:466:44
1 100.0% JS: ^onFinish node:_http_outgoing:1025:18
21 23.6% JS: *Writable.uncork node:internal/streams/writable:518:37
21 100.0% JS: *end node:_http_outgoing:1030:45
21 100.0% JS: *handle /app/index.js:33:16
21 100.0% JS: *parserOnIncoming node:_http_server:1028:26
3 3.4% JS: ^Writable.uncork node:internal/streams/writable:518:37
3 100.0% JS: *end node:_http_outgoing:1030:45
3 100.0% JS: *handle /app/index.js:33:16
2 66.7% JS: *emit node:events:466:44
1 33.3% JS: *parserOnIncoming node:_http_server:1028:26
78 1.2% JS: *$so2 /app/index.js:9:503
78 100.0% JS: *$so0 /app/index.js:9:189
78 100.0% JS: *log /app/node_modules/tslog/dist/cjs/BaseLogger.js:88:8
78 100.0% JS: *handle /app/index.js:33:16
78 100.0% JS: *parserOnIncoming node:_http_server:1028:26
70 1.1% JS: *parserOnIncoming node:_http_server:1028:26
70 100.0% JS: *parserOnHeadersComplete node:_http_common:71:33
70 1.1% JS: *parserOnHeadersComplete node:_http_common:71:33
69 1.1% JS: *value node:internal/console/constructor:277:20
69 100.0% JS: *log node:internal/console/constructor:384:6
69 100.0% /usr/local/bin/node
69 100.0% JS: *log /app/node_modules/tslog/dist/cjs/BaseLogger.js:88:8
69 100.0% JS: *handle /app/index.js:33:16
64 1.0% JS: *ServerResponse node:_http_server:195:24
64 100.0% JS: *parserOnIncoming node:_http_server:1028:26
64 100.0% JS: *parserOnHeadersComplete node:_http_common:71:33
これ以上のチューニングはバッファリングする等してconsole.logの呼び出し回数を減らす等の工夫をすれば、もう少しスループットをあげることができそうです。（疲れたのでここで終わる）
まとめ
- tslogを使用することでマスキングを行いながら構造化ログを出力できる
- typiaと組み合わせることで、コンパイル時に型情報からログの構造を決定でき、パフォーマンスとセキュリティを両立しながらログを出力できる
Discussion