OpenVPNのログ行にあるus=の意味と変換方法

OpenVPNのテキストログは、日付、時刻、そしてus=の値を同じ行に並べます。三つのうち最後の部分を、読み手はよく誤解します。それはそのタイムスタンプのマイクロ秒成分であり、ゼロで埋めずに出力されます。セッション識別子でもユーザー名でもカウンタでもなく、そう扱うと一秒の端数が自信に満ちた誤った結論に変わります。表示された秒の端数として変換すれば、行の残りは読めるままです。

行の三つの部分が意味するもの

日付と整数秒が先に来て、us=が一秒未満の端数を運びます。12345という値は一万二千三百四十五マイクロ秒、つまり0.012345秒なので、印字された時刻が09:15:30なら、その行は09:15:30.012345を表します。カウンタは新しい一秒ごとに振り出しに戻るため、後の行がより小さな端数を出力しても、時計が逆戻りしているわけではありません。出来事を正しく並べるのは完全なタイムスタンプだけです。

2026-11-02 08:41:07 us=4820

単位は一秒の百万分の一で、us=の六桁は0.000000から0.999999までの全範囲を覆います。五桁なら十ミリ秒単位、六桁なら百ミリ秒単位でほぼ一秒まで表せます。変換結果が一を超える端数になったら、小数点がずれていて計算が誤っています。手計算では、印字された整数を百万で割り、整数秒に足します。

ゼロ埋めが落とし穴です。us=42は四十二マイクロ秒であり、.000042と書き、.42ではありません。変換前に整数を左から六桁までゼロで埋めれば、目に見える数字の小数部分のように見えることはなくなります。

電卓なしで行を変換する

印字された秒を基準にして、us=を端数として扱います。09:15:30とus=12345なら小数形式は09:15:30.012345、us=900000なら09:15:30.900000です。小数点以下の数字はゼロ埋めした整数であり、千で割った整数では決してありません。先に六桁の形を書けば、ほとんどの間違いを防げます。

ログをタイムスタンプに解析するなら、日付、整数秒、端数をまとめて解析します。ミリ秒だと仮定したパーサーは出来事を千倍の誤りで並べ、しかも出力はもっともらしく見えます。

ログにこのフィールドがない場合

マイクロ秒の部分はテキストログ形式に属し、詳細なタイムスタンプが有効なときだけ現れます。OpenVPN 2.6のタイムスタンプ整形器では、その出力が有効で保存値がゼロでないときに追加されます。したがってus=のないログは、時計やビルドについて何も語りません。ふつうは設定された詳細度が低すぎるだけです。時刻同期を疑う前に設定を確認してください。

設定はサーバー設定から簡単に確認できます。次のコマンドを実行し、返ってくる数値を読んでください。詳細なタイムスタンプ出力は詳細度4で現れるので、より低い値なら他の不具合なしにフィールド欠落を説明できます。同じ設定を--verb 4で実行すると、デーモンがそのレベルで再起動した時点でフィールドが表示されます。

grep -nE '^[[:space:]]*verb[[:space:]]+[0-9]' /etc/openvpn/server.conf

詳細度を上げるとログに情報が増えますが、時計は良くなりません。再起動後に新しい行と古い行を比べて形式が変わったことを確かめ、疑問が解決したらレベルをまた下げてください。

六桁が証明しないこと

六桁は分解能を表すだけで、分解能は二つのホストが時刻について一致しているかを何も語りません。クライアントとサーバーがどちらもマイクロ秒を出力していても、時計が数秒ずれていることがあります。マシン間で出来事を突き合わせるときは、タイムゾーンと既知のずれを記録し、どのタイムスタンプよりもピアやセッションを名指すフィールドを優先してください。同じ端数を共有する二行が同じ接続とは限りません。

コレクターが各行に到着時に刻印すると、OpenVPNではなくコレクターに属する二つ目のタイムスタンプが加わります。比べる前にどちらを読んでいるかを見極め、比較をやり直せるように生の行を残してください。

新しいus=の値は新しいクライアントがログインしたことを証明せず、繰り返された値も重複した出来事を証明しません。ピアと接続のフィールドがその問いに答えます。