Tweet

Pocket

はじめに

システム開発にあたり、ログ収集は避けては通れない問題です。
IaaS に導入したミドルウェアのログを収集するとなった場合、ミドルウェアの出力したログをそのまま取り込むことでできればベストですが、なんらかの変換をしないと取り込めないといったこともあります。

今回は、単一行のテキストログを JSON に変換してみます。
ログ管理システムに取り込むところは試さないので、ご留意ください。

使用するツール類

• VM の OS : Red Hat Enterprise Linux 9.1
  • タイムゾーン = Asia/Tokyo
• Bash : Ver.5.1.8

検証

■ ソース ログファイルの内容

今回、変換したいログファイルは、下記のような内容を想定します。

2023-01-05-08.30.00.123456 <SampleApp::start> MDGID=001 "This is sample log (1).".
2023-01-05-12.00.00.234567 <SampleApp::info> MDGID=002 "This is sample log (2).".
2023-01-06-10.30.00.345678 <SampleApp::stop> MDGID=003 "This is sample log (3).".

タイムスタンプが私としてはあまり見慣れない形式 (yyyy-mm-dd-hh.mm.ss.mmmmmm) ですが…
OS のタイムゾーンを Asia/Tokyo に設定しているので、上記の日時は JST ということになります。

■ 変換後の内容

[
{"Time": "2023-01-04T23:30:00.123456Z", "Computer": "【VM の hostname】", "AdditionalContext": "<SampleApp::start> MDGID=001 \"This is sample log (1).\"."},
{"Time": "2023-01-05T03:00:00.234567Z", "Computer": "【VM の hostname】", "AdditionalContext": "<SampleApp::info> MDGID=002 \"This is sample log (2).\"."},
{"Time": "2023-01-06T01:30:00.345678Z", "Computer": "【VM の hostname】", "AdditionalContext": "<SampleApp::stop> MDGID=003 \"This is sample log (3).\"."}
]

タイムスタンプを ISO 8601 形式の UTC に変換します。
また、JSON に変換するにあたり、ログ内容のエスケープも行います。

■ 変換処理

下記の流れで変換しようと思います。

(1) ソース ログファイルを作業用フォルダにコピーする。
(2) タイムスタンプ部分を抽出し、ISO 8601 形式の UTC に変換する。
(2) ログの本文を抽出し、JSON 用にエスケープする。
(4) JSON 生成

(1) に関しては、ただファイルをコピーするだけなので、詳細は割愛します。

◇ タイムスタンプ部分を抽出し、ISO 8601 形式の UTC に変換する

下記のような while 文で、ログファイルを 1 行ずつ処理していきます。

while IFS="\n", read row
do

done < "${WORK_FILE_PATH_1}"

タイムスタンプ部分の抽出は、下記のコマンドで可能です。

replaceTarget=$(echo "${row}" | sed -e "s/^\([0-9]\{4\}-[0-9]\{1,2\}-[0-9]\{1,2\}-[0-9]\{1,2\}\.[0-9]\{1,2\}\.[0-9]\{1,2\}\.[0-9]\+\) .\+$/\1/g")

【抽出前】
2023-01-05-08.30.00.123456 <SampleApp::start> MDGID=001 "This is sample log (1).".

【抽出後】
2023-01-05-08.30.00.123456

こうすると、変数 replaceTarget に 2022-01-05-08.30.00.123456 といった感じでタイムスタンプ部分が格納されます。
sed コマンドで一部を抽出していますが、上記のコマンドは /【置換前文字列 (正規表現)】/【置換後文字列】/ の 2 つのパーツに分かれています。

• 【置換前文字列】
  “タイムスタンプで始まっている行で、タイムスタンプの後ろは空白を 1 つ挟んで、1 文字以上の文字列が存在する行” という正規表現。
  • ^\([0-9]\{4\}-[0-9]\{1,2\}-[0-9]\{1,2\}-[0-9]\{1,2\}\.[0-9]\{1,2\}\.[0-9]\{1,2\}\.[0-9]\+\) .\+$
• 【置換後文字列】
  置換前文字列の正規表現の中で、() で囲んだ範囲の 1 つめ。
  • [0-9]\{4\}-[0-9]\{1,2\}-[0-9]\{1,2\}-[0-9]\{1,2\}\.[0-9]\{1,2\}\.[0-9]\{1,2\}\.[0-9]\+ の部分 = タイムスタンプの部分。

次に、ISO 8601 形式に変換します。

dateStr=$(echo "${replaceTarget}" | sed -e "s/^\([0-9]\{4\}-[0-9]\{1,2\}-[0-9]\{1,2\}\)-\([0-9]\{1,2\}\)\.\([0-9]\{1,2\}\)\.\([0-9]\{1,2\}\)\.\([0-9]\+\)$/\1T\2:\3:\4.\5/g")

【変換前】
2023-01-05-08.30.00.123456

【変換後】
2022-01-05T08:30:00.123456

このコマンドにおける置換前文字列と置換後文字列の対応は、下記のとおりです。

ISO 8601 形式に変換した後は、UTC に変換します。

timeGenerated=$(date --date "${dateStr} 9 hours ago" +'%Y-%m-%dT%H:%M:%S.%6NZ')

【変換前】
2022-01-05T08:30:00.123456

【変換後】
2022-01-04T23:30:00.123456Z

◇ ログの本文を抽出し、JSON 用にエスケープする

ログの本文の抽出は、タイムスタンプと同様の方法で () で囲む位置を変えて対応します。

logText=$(echo "${row}" | sed -e "s/^[0-9]\{4\}-[0-9]\{1,2\}-[0-9]\{1,2\}-[0-9]\{1,2\}\.[0-9]\{1,2\}\.[0-9]\{1,2\}\.[0-9]\+ \(.\+\)$/\1/g")

【抽出前】
2023-01-05-08.30.00.123456 <SampleApp::start> MDGID=001 "This is sample log (1).".

【抽出後】
<SampleApp::start> MDGID=001 "This is sample log (1).".

ログ本文は、このまま JSON にするわけにはいきません。
主に下表の文字をエスケープする必要があります。

additionalContext=$(echo "${logText}" | sed -e 's/\\/\\\\/g' -e 's/"/\\"/g' -e 's/\//\\\//g' -e 's/\f/\\f/g' -e 's/\n/\\n/g' -e 's/\r/\\r/g' -e 's/\t/\\t/g' -e "s/[^[:print:]]//g")

【変換前】
<SampleApp::start> MDGID=001 "This is sample log (1).".

【変換後】
<SampleApp::start> MDGID=001 \"This is sample log (1).\".

スクリプト全体

ここまでの内容を組み込んで、全体を整えたのが下記のスクリプトです。

#!/bin/bash

# ================================================================================
#  単一行ログを JSON に変換するスクリプト
# ================================================================================

# エラーが発生したら停止
# 未定義の変数の使用防止
set -eu

# ==================================================
#  定数など
# ==================================================

# ソース ログファイルのディレクトリパス
ORIGIN_LOG_DIR_PATH="/home/opst/sample"

# 変換後のログファイルのパス
THIS_TIME_FILE_PATH="/home/opst/sample/conv_$(date +%Y%m%d).log"

# 作業用ディレクトリ
WORK_DIR_PATH="/home/opst/sample/work"

# 作業用ファイルのパス
WORK_FILE_PATH="${WORK_DIR_PATH}/work.txt"

# ロガーのタグ
LOG_TAG="Log_convert"

# ==================================================
#  関数
# ==================================================

# 通常ログ出力
logInfo () {
    logger --id=$ -p syslog.info -t "${LOG_TAG}" "$1"
}

# 警告ログの出力
logWarning () {
    logger --id=$ -p syslog.warning -t "${LOG_TAG}" "$1"
}

# デバッグログの出力
logDebug () {
    logger --id=$ -p syslog.debug -t "${LOG_TAG}" "$1"
}

# 作業用ファイルの削除
removeWorkFiles () {

    if [ -f "${WORK_FILE_PATH}" ]; then
        rm -f "${WORK_FILE_PATH}"
    fi

}

# ==================================================
#  メイン
# ==================================================

# 作業用ファイルの削除
removeWorkFiles

vmName=$(hostname)
logFilePath="${ORIGIN_LOG_DIR_PATH}/sample.log"

# ソース ログファイルの存在チェック
if [ -f "${logFilePath}" ] && [ -s "${logFilePath}" ]; then
    # ソース ログファイルがある
    logInfo "${logFilePath} found."

    # 作業用フォルダにコピー
    cp -f "${logFilePath}" "${WORK_FILE_PATH}"

    # 空行を削除
    sed -i '/^$/d' "${WORK_FILE_PATH}"
else
    # ソース ログファイルがない
    logWarning "${logFilePath} not found or empty file."
    exit 0
fi

echo "[" > "${THIS_TIME_FILE_PATH}"

allRowsCount=`wc -l "${WORK_FILE_PATH}" | cut -d " " -f 1`
rowNo=0

while IFS="\n", read row
do
    # 進捗状況
    rowNo=$((($rowNo + 1)))
    logDebug "progress: ${rowNo} / ${allRowsCount}"

    # 空行なら処理なし
    if [ "${row}" = "" ]; then
        continue
    fi

    # --------------------------------------------------
    #  タイムスタンプ
    # --------------------------------------------------

    # タイムスタンプのみ抽出 & ISO 8601 形式に変換
    # 例) Before: 2023-01-05-08.30.00.123456
    #      After: 2022-01-05T08:30:00.123456
    replaceTarget=$(echo "${row}" | sed -e "s/^\([0-9]\{4\}-[0-9]\{1,2\}-[0-9]\{1,2\}-[0-9]\{1,2\}\.[0-9]\{1,2\}\.[0-9]\{1,2\}\.[0-9]\+\) .\+$/\1/g")
    # 稀に正規表現で日付部分のみを取得できないことがあるので、そのときは文字数で抽出する
    if [ ${#replaceTarget} -gt 26 ]; then
        replaceTarget="${replaceTarget:0:26}"
    fi
    dateStr=$(echo "${replaceTarget}" | sed -e "s/^\([0-9]\{4\}-[0-9]\{1,2\}-[0-9]\{1,2\}\)-\([0-9]\{1,2\}\)\.\([0-9]\{1,2\}\)\.\([0-9]\{1,2\}\)\.\([0-9]\+\)$/\1T\2:\3:\4.\5/g")

    # タイムスタンプを計算 (UTC を求める)
    timeGenerated=$(date --date "${dateStr} 9 hours ago" +'%Y-%m-%dT%H:%M:%S.%6NZ')

    # --------------------------------------------------
    #  ログ本文
    # --------------------------------------------------

    # ログ本文のみ抽出
    logText=$(echo "${row}" | sed -e "s/^[0-9]\{4\}-[0-9]\{1,2\}-[0-9]\{1,2\}-[0-9]\{1,2\}\.[0-9]\{1,2\}\.[0-9]\{1,2\}\.[0-9]\+ \(.\+\)$/\1/g")

    # 特殊文字をエスケープ
    additionalContext=$(echo "${logText}" | sed -e 's/\\/\\\\/g' -e 's/"/\\"/g' -e 's/\//\\\//g' -e 's/\f/\\f/g' -e 's/\n/\\n/g' -e 's/\r/\\r/g' -e 's/\t/\\t/g' -e "s/[^[:print:]]//g")

    # --------------------------------------------------
    #  最終出力
    # --------------------------------------------------

    # 変換後のログファイルに書き込み
    jsonRow=$(echo "{\"Time\": \"${timeGenerated}\", \"Computer\": \"${vmName}\", \"AdditionalContext\": \"${additionalContext}\"}")
    if [ $rowNo -lt $allRowsCount ]; then
        jsonRow="${jsonRow},"
    fi
    echo "${jsonRow}" >> "${THIS_TIME_FILE_PATH}"

done < "${WORK_FILE_PATH}"

echo "]" >> "${THIS_TIME_FILE_PATH}"

# 作業用ファイルの削除
removeWorkFiles

logInfo "End conversion of Log."

このスクリプトは必要最低限の処理しか実装していないため、ミドルウェアが出力する単一行のログファイルを定期的に変換する場合、下記の考慮が追加で必要になるかと思います。

• スクリプトが同時実行されないように排他処理の実装
• ソース ログファイルの変換済みの部分について、複数回変換しないように、前回変換時の続きから処理をする仕組みの実装。
• ログ管理システムに送信する処理の実装。
• ログファイルが複数存在するケースの対応。

参考情報

• JSON RFC
  • 2.5. Strings

おわりに

そもそもログ管理システムで取り込める形 (今回の想定では JSON) でログを出力できれば、それがベストです。
ただミドルウェアのログなどは、なかなかそうもいきません。
どうしてもログの変換が必要になったとき、この記事が参考になればと思います。

Tweet

Pocket