ログを簡単に取りたい＋検索できるようにしたい。そういう理由でLokiが採用されました。
従来のログ
弊アプリのサーバーサイドはnode.jsで、もともとpm2でログが取られていました。障害が起きたらslackにエラーが飛びます。あとは入出力で不要な情報を除いたものがpm2のログとして溜まっていきます。適宜ログローテーションしてくれますが、結局ログを調べるのはgrepです。あるIPのログだけを追いたい、このエンドポイントの処理だけを追いつづけたい、などの要望があるとJSONを処理する必要があり、少し面倒くさいです。
また、負荷軽減のためにサーバーを増やしてアプリを起動した際、ログが各サーバーに分散してしまうという問題がありました。
ElasticsearchではなくLokiを選んだ理由
Elasticsearchも検討しましたが、 リソースと費用の観点からLokiを採用してみました。もともとgrafanaを利用してサーバーのメトリクスを監視していたのもあります。結構多めのログを取っていますが、そこまでディスクやリソースを使用しません。管理も簡単です。
それでは実践編。
Lokiをdocker-composeで起動する
下記ファイルを使用します。
networks:
loki:
services:
loki:
image: grafana/loki:2.9.2
ports:
- "3100:3100"
command: -config.file=/etc/loki/local-config.yaml
networks:
- loki
volumes:
- ./data/loki:/loki
promtail:
image: grafana/promtail:2.9.2
volumes:
- /var/log:/var/log
command: -config.file=/etc/promtail/config.yml
networks:
- loki
grafana:
environment:
- GF_PATHS_PROVISIONING=/etc/grafana/provisioning
- GF_AUTH_ANONYMOUS_ENABLED=false
entrypoint:
- sh
- -euc
- |
mkdir -p /etc/grafana/provisioning/datasources
cat <<EOF > /etc/grafana/provisioning/datasources/ds.yaml
apiVersion: 1
datasources:
- name: Loki
type: loki
access: proxy
orgId: 1
url: http://loki:3100
basicAuth: false
isDefault: true
version: 1
editable: false
EOF
/run.sh
image: grafana/grafana:10.0.0-ubuntu
ports:
- "3000:3000"
networks:
- loki
すでにgrafanaがある人は飛ばしても良いですが、ds.yamlは手動でなんとかする必要があります。
versionについては自分が動作確認したversionです。適宜アップしてもらっても大丈夫だと思います。
docker compose up -d
これでhttp://localhost:3000/でgrafanaが見えたら成功です。もし起動できなかったときは、作成されたdataディレクトリのpermissionが問題だったりするので適宜変更してください。id, passwordともにadminでgrafanaにログインしましょう。パスワードは適宜よろしいもの変えてください。
node.jsアプリからログを送り込む
以下、最低限の準備。自分の持っているtypescript+esbuldのテンプレを使ってもらって良いと思います。
npm init -y
npm install -D typescript esbuild tsx
npm install winston winston-loki
mkdir src
touch ./src/main.ts
以下、最低限の実装
import { createLogger, format } from "winston";
import LokiTransport from "winston-loki";
type UseLoggerProps = {
appName: string;
};
export const useLogger = ({ appName }: UseLoggerProps) =>
createLogger({
transports: [
new LokiTransport({
host: "http://localhost:3100",
labels: {
appName,
},
json: true,
format: format.json(),
replaceTimestamp: true,
onConnectionError: (err) => {
console.error(err);
},
})
],
});
const main = () => {
const logger = useLogger({ appName: "test-app" });
logger.info("Hello world!");
}
main()
useLoggerについてはモノレポにおける共通の関数として使用する感じです。ひとつのアプリケーションで動かすならわざわざ関数にする必要はないかと思います。モノレポであればuseLoggerの引数でappNameを分けることができ、後述しますがlabelによって検索ができるようになります。
それでは実行してみます。
npx tsx ./src/main.ts
するといい感じにログが取れているはずです。
grafanaからログを見てみる
grafanaのハンバーガーメニュー、Exploreと進んだところでBuilderからcodeに変えて以下のコマンドを打ちます。
{level="info"}
そうすると画像のようなログが見えるはずです。
ここまでは良いですが、次に実戦で使用することを考えたときにesbuildなどでトランスパイルするはずです。package.jsonに下記のようなコマンドを足してあげましょう。
{
"scripts": {
"build": "esbuild src/main.ts --bundle --platform=node --outfile=dist/main.js"
}
}
npm run build
こうしたときにsnappy関連のerrorが起こるかと思います。
snappyをesbuildのexternalに入れてあげれば解決します。
{
"scripts": {
"test": "echo \"Error: no test specified\" && exit 1",
"build": "esbuild src/main.ts --bundle --platform=node --outfile=dist/main.js --external:snappy"
}
}
実はpino-lokiの採用も検討したのですが、このビルドの際にめちゃくちゃハマったので諦めました。winston-lokiは、このsnappyの問題以外はそこまで落とし穴がありませんでした。pinoなどに比べると老舗です。少し重かったりするようですが個人的には許容範囲内でした。
Labelについて
ラベルは増やしすぎるとクエリのパフォーマンスが悪くなるようです。このラベルに基づいてindexしているんだったかな。詳しく知りたい方は下記リンクを参照のこと。とりあえずappNameで5アプリくらいのログをまとめていますが、特にパフォーマンスで困ったことはないです。
Middleware
弊プロジェクトではexpressやhonoが使用されています。まずはexpressでwinston-lokiを使用する例です。
ミドルウェアを作成し、必要な情報に絞っていきます。
expressのログを取る場合
app.use((req, res, next) => {
if (req.url.includes("no-log-url")) {
next();
return;
}
const originalJson = res.json;
if (!res.locals) {
res.locals = {};
} else if (Object.getPrototypeOf(res.locals) === null) {
res.locals = { ...res.locals };
}
res.json = (data) => {
res.locals.responseData = data;
return originalJson.call(res, data);
};
winstonMiddleware(req, res, next)(logger);
});
まずは全ルートを通るミドルウェアを作成します。このときログを取りたくないルートを除外してnextで次に回します。それ以外は後述するwinsotnMiddlewareに回します。
途中のoriginalJsonのあたりは、どういう値を返したのかを知りたいときに使います。正しい値が返っているのかどうかを判断します。ただ、大量のデータを持つconfig値などがログに残ると非常に重くなるので、そのあたりは適宜間引いていく必要があります。ユーザーに返した値を知りたいところでだけ使うとか、あとはそもそも返り値が重要な意味を持つエンドポイントに手動でログを仕込んだりしたほうが良いかもしれません。
ひとまず、このようにres.jsonにloggerを仕込むことですべてのエンドポイントの返り値をロギングできます。
export const winstonMiddleware =
(req: Request, res: Response, next: NextFunction) =>
(logger: winston.Logger) => {
const start = Date.now();
res.on("finish", () => {
const duration = Date.now() - start;
const logLevel = getLogLevels(res.statusCode);
const logObj = {
req: {
method: req.method,
url: req.url,
headers: req.headers,
remoteAddress: req.remoteAddress,
remotePort: req.remotePort,
body: req?.body ?? "body is empty",
params: req?.params,
query: req?.query,
version: process.env.VERSION ?? "no-version",
},
res: {
statusCode: res.statusCode,
responseData: res?.locals?.responseData,
duration,
responseSize: res.get("Content-Length") || 0,
},
path: req.originalUrl,
};
match(logLevel)
.with("error", () => logger.error(logObj))
.with("warn", () => logger.warn(logObj))
.with("info", () => logger.info(logObj))
.otherwise(() => logger.info(logObj));
});
next();
};
const getLogLevels = (code: number | undefined) => {
if (!code) {
return "info";
}
if (code >= 400 && code < 500) {
return "warn";
}
if (code >= 500) {
return "error";
}
return "info";
};
これがwinstonMiddlewareの実装です。普通の実装ですが、いくつか説明をしましょう。startと、res.on('finish')時のendでエンドポイントごとの掛かった時間を取得できます。とはいえ、そういう情報はnginxのログとかでも良いかもしれません。ログとしてはちょっと冗長な気もしますが、バグ報告の調査などでは多い方がやりやすいことも多いです。
trpcのログを取る場合
export const publicProcedure = t.procedure.use(async (opts) => {
const { path, type, input } = opts;
const version = process.env.VERSION ?? "no-version";
const route = "trpc_route";
const result = await opts.next();
if (path.includes(".get") || ignorePathList.includes(path)) {
wLogger.info({
path,
type,
input: opts?.rawInput,
version,
route,
ip: opts?.ctx?.ip,
});
return result;
}
if (result.ok) {
wLogger.info({
opts,
output: result.data,
path,
type,
input,
version,
route,
outputLength: JSON.stringify(result.data).length,
});
} else {
wLogger.error({
opts,
output: result.error,
path,
type,
input,
version,
route,
outputLength: JSON.stringify(result.error).length,
});
}
return result;
});
こんな感じでprocedureに.useでミドルウェアを作成します。適宜情報を除いていかないとすごい量のログになるので注意。DBへのupdate, insertが発生するようなところだけログを取って、selectに関しては、いつ誰がどういうqueryを投げたのかを調べやすくするくらいでも良いかもしれません。また、当然ですがexpress上にtrpcを構成していると二重にログが取られてしまいます。expressのミドルウェアでtrpcというpathを含むものを除外するなどの対応が必要です。
honoのミドルウェアを使用する場合
export const honoLoggerMiddleware =
(logger: Logger) => async (c: any, next: Next) => {
const start = Date.now();
await next();
const duration = Date.now() - start;
const responseData = await streamToString(c.res.body);
const connInfo = getConnInfo(c);
const logLevel = getLogLevels(c.res.status);
logger.log(logLevel, {
req: {
method: c.req.method,
url: c.req.url,
headers: c.req.header(),
remoteAddress: connInfo.remote.address,
remotePort: connInfo.remote.port,
params: c.req.param(),
query: c.req.query(),
body: c.req.parseBody(),
version: process.env.VERSION ?? "no-version",
},
res: {
statusCode: c.res.status,
responseData,
duration,
responseSize: responseData.length,
},
path: c.req.url,
});
};
こんな感じのミドルウェアを作成すればよいでしょう。適宜自分なりに必要な情報を集めたらよいかと思います。そもそもこれはwinston-lokiとはあんまり関係ない部分ですね。
大事なのが、どういうログを取りたいのかということです。ひとまずユーザーの入力は取得しておいたほうがデバッグはやりやすいですが、パスワードなどセンシティブなものはマスクしておきましょう。多めに取っておいて、単なるconfigとか情報取得系、大量のデータ取得系を除外するのが良いのかな、と考えております。
Lokiのクエリ
grafana + prometheusを使ったことがあれば、ある程度使いこなせるかと思いますが……。
初心者はこれだけ覚えましょう。
文字検索
{appName="test-app"} |= "hello"
これでhelloという文字の入ったログに絞り込みができます。これと時間とIPくらいで大体追える気もします。
除外は!=です。
エラーだけ
{appName="test=app", level="error"}
あとは正規表現で絞り込みもできますが、大体文字列検索で事が足りる気もします。jsonを解析したりもできます。
詳しく知りたい人は公式のdocumentを読みましょう。
以上になります。ログファイルを頑張ってgrepしていた頃よりも幾分か文化的な調査が可能になったかと思います。あと大事なのは、機密情報系のマスキングになるかと思いますが、それはまた各自頑張りましょう。