🎃
標準出力にタイムスタンプをつけて再出力
はじめに
定期実行のバッチなどで、実行時に日時を出力したい場合がありますが、バッチプログラムでは雑にprintなりechoしておいて、後付で日時を行に追加する処理を作りました。
処理としては標準出力と標準エラーにたいして、呼び出し側のコマンドで時間等をつけて出力という動きになります。
基本はログファイルに出す想定なので、結果は判別できるようにして、標準出力だけにしています。
バッファリングされると出力が遅延する場合があるのでflash=Trueなどをつけるほうがベターです。
使い方1
python3 with_timestamp.py ls -latr
python3 with_timestamp.py ls -asdf1234
出力例
2025/03/30 16:51:27.259 +0900 637363 STDOUT drwxrwxrwx 25 root root 4096 Mar 30 07:40 ..
2025/03/30 16:51:27.259 +0900 637363 STDOUT -rwxrw-rw- 1 root root 79 Mar 30 07:48 test.py
2025/03/30 16:51:27.259 +0900 637363 STDOUT -rwxrw-rw- 1 root root 2374 Mar 30 07:50 with_timestamp.py
2025/03/30 16:51:27.259 +0900 637363 STDOUT drwxrwxrwx 2 root root 4096 Mar 30 07:51 .
2025/03/30 16:52:15.674 +0900 637366 STDERR ls: invalid option -- '2'
2025/03/30 16:52:15.675 +0900 637366 STDERR Try 'ls --help' for more information.
使い方2
python3 with_timestamp.py netstat -anop
出力例
2025/03/30 16:45:59.940 +0900 637270 STDERR (Not all processes could be identified, non-owned process info
2025/03/30 16:45:59.941 +0900 637270 STDOUT Active Internet connections (servers and established)
2025/03/30 16:45:59.941 +0900 637270 STDOUT Proto Recv-Q Send-Q Local Address Foreign Address State PID/Program name Timer
2025/03/30 16:45:59.941 +0900 637270 STDOUT tcp 0 0 0.0.0.0:22 0.0.0.0:* LISTEN - off (0.00/0/0)
2025/03/30 16:45:59.941 +0900 637270 STDOUT tcp 0 0 0.0.0.0:111 0.0.0.0:* LISTEN - off (0.00/0/0)
2025/03/30 16:45:59.941 +0900 637270 STDOUT tcp 0 0 0.0.0.0:34429 0.0.0.0:* LISTEN - off (0.00/0/0)
2025/03/30 16:45:59.941 +0900 637270 STDOUT tcp 0 0 127.0.0.53:53 0.0.0.0:* LISTEN - off (0.00/0/0)
2025/03/30 16:45:59.941 +0900 637270 STDOUT tcp6 0 0 :::22 :::* LISTEN - off (0.00/0/0)
2025/03/30 16:45:59.941 +0900 637270 STDOUT tcp6 0 0 :::111 :::* LISTEN - off (0.00/0/0)
2025/03/30 16:45:59.941 +0900 637270 STDOUT tcp6 0 0 :::44855 :::* LISTEN - off (0.00/0/0)
2025/03/30 16:45:59.941 +0900 637270 STDOUT udp 0 0 127.0.0.53:53 0.0.0.0:* - off (0.00/0/0)
2025/03/30 16:45:59.941 +0900 637270 STDOUT udp 0 0 0.0.0.0:111 0.0.0.0:* - off (0.00/0/0)
2025/03/30 16:45:59.941 +0900 637270 STDOUT udp6 0 0 :::111 :::* - off (0.00/0/0)
2025/03/30 16:45:59.941 +0900 637270 STDOUT raw6 0 0 :::58 :::* 7 - off (0.00/0/0)
2025/03/30 16:45:59.941 +0900 637270 STDOUT Active UNIX domain sockets (servers and established)
2025/03/30 16:45:59.942 +0900 637270 STDOUT Proto RefCnt Flags Type State I-Node PID/Program name Path
2025/03/30 16:45:59.942 +0900 637270 STDOUT unix 2 [ ACC ] STREAM LISTENING 11235687 - /run/systemd/private
2025/03/30 16:45:59.942 +0900 637270 STDOUT unix 2 [ ACC ] STREAM LISTENING 11235690 - /run/systemd/userdb/io.systemd.DynamicUser
2025/03/30 16:45:59.942 +0900 637270 STDOUT unix 2 [ ACC ] STREAM LISTENING 11235691 - /run/systemd/io.system.ManagedOOM
2025/03/30 16:45:59.942 +0900 637270 STDOUT unix 2 [ ] DGRAM 11219806 636757/systemd /run/user/1000/systemd/notify
2025/03/30 16:45:59.942 +0900 637270 STDOUT unix 2 [ ACC ] STREAM LISTENING 11219809 636757/systemd /run/user/1000/systemd/private
使い方3
python3 with_timestamp.py bash -x test.sh
出力例
2025/03/30 16:48:21.456 +0900 637314 STDOUT 標準出力
2025/03/30 16:48:21.456 +0900 637314 STDERR 標準エラー
実装
import sys
import subprocess
from datetime import datetime
import pytz
import os
import select
def create_timestamp_prefix(process_id, output_channel):
"""タイムスタンプ付きの出力プレフィックスを生成する"""
current_time = datetime.now(pytz.timezone("Asia/Tokyo"))
time_str = current_time.strftime("%Y/%m/%d %H:%M:%S.%f")[:-3]
tz_str = current_time.strftime("%z")
return f"{time_str} {tz_str} {process_id} {output_channel}"
def execute_command():
# コマンドライン引数のチェック
if len(sys.argv) <= 1:
print("使用方法: python3 with_timestamp.py <実行するスクリプト> [引数...]")
return 1
# 指定されたコマンドを実行
cmd = subprocess.Popen(
sys.argv[1:],
stdout=subprocess.PIPE,
stderr=subprocess.PIPE,
text=True,
bufsize=1,
universal_newlines=True,
)
# ファイルディスクリプタを監視するためのポーラーを設定
poller = select.poll()
poller.register(cmd.stdout, select.POLLIN)
poller.register(cmd.stderr, select.POLLIN)
# ファイルディスクリプタとチャンネルの対応マップ
descriptors = {
cmd.stdout.fileno(): ("STDOUT", cmd.stdout),
cmd.stderr.fileno(): ("STDERR", cmd.stderr),
}
# 出力を処理するループ
while cmd.poll() is None:
# 利用可能なデータがあるかポーリング
for descriptor, flags in poller.poll(100):
if flags & select.POLLIN:
channel_type, stream = descriptors[descriptor]
content = stream.readline()
if content:
prefix = create_timestamp_prefix(cmd.pid, channel_type)
print(f"{prefix} {content.rstrip()}", flush=True)
# プロセス終了後、残りの出力を処理
for channel_type, stream in descriptors.values():
remaining_lines = stream.readlines()
for content in remaining_lines:
if content:
prefix = create_timestamp_prefix(cmd.pid, channel_type)
print(f"{prefix} {content.rstrip()}", flush=True)
return cmd.returncode
if __name__ == "__main__":
exit_code = execute_command()
sys.exit(exit_code)
その他
実行時の引数や、終了コード、実行時間の合計なども出力するとなおログの情報が増えます。
また後でパースできるように、追加部分と、元の文字列の境になにかわかりやすい区切り文字入れておくのもよさそうです。
Discussion