pythonでLOG情報を所得する方法を教えてください

Question

前提・実現したいこと

現在pymodbusのパッケージを使ってMODBUS通信を試みているのですが、通信メッセージの履歴をCSVに残したいためlogのデバッグメッセージの中でも
DEBUG:pymodbus.transaction:SEND: 0x1 0x6 0x0 0x7d 0x0 0x38 0x18 0x0
と
DEBUG:pymodbus.transaction:RECV: 0x1 0x6 0x0 0x7d 0x0 0x38 0x18 0x0
の情報を文字列として所得したいと考えています。何を使い、どのように宣言すれば取得できるのでしょうか？

一応ですが、現在
logging.basicConfig()
log = logging.getLogger()
log.setLevel(logging.DEBUG)
で宣言して
client.write_register
で書き込みをした時に出力されるものが以下となります
DEBUG:pymodbus.transaction:Current transaction state - IDLE
DEBUG:pymodbus.transaction:Running transaction 1
DEBUG:pymodbus.transaction:SEND: 0x1 0x6 0x0 0x7d 0x0 0x38 0x18 0x0
DEBUG:pymodbus.client.sync:New Transaction state 'SENDING'
DEBUG:pymodbus.transaction:Changing transaction state from 'SENDING' to 'WAITING FOR REPLY'
DEBUG:pymodbus.transaction:Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
DEBUG:pymodbus.transaction:RECV: 0x1 0x6 0x0 0x7d 0x0 0x38 0x18 0x0
DEBUG:pymodbus.framer.rtu_framer:Getting Frame - 0x6 0x0 0x7d 0x0 0x38
DEBUG:pymodbus.factory:Factory Response[WriteSingleRegisterResponse: 6]
DEBUG:pymodbus.framer.rtu_framer:Frame advanced, resetting header!!
DEBUG:pymodbus.transaction:Adding transaction 1
DEBUG:pymodbus.transaction:Getting transaction 1
DEBUG:pymodbus.transaction:Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'

Answer 1

ログメッセージを操作の対象にしたい場合は、ログをインメモリのテキストバッファに出力させます。
このテキストバッファの内容を任意のタイミングで取得し処理し、ファイルに保存します。
保存後はテキストバッファを空にし、次のログ出力に備えます。

以下がログをインメモリのテキストバッファに出力させるためのログ設定の例です。
現在のコンソールへのログ出力はそのままに、新たな出力設定を定義して追加しています(コンソールへは出力させないように変更することも可能)。新たに標準ライブラリの io モジュールが必要になります。

ファイルに保存するログについては、ログレベルやロガー名よりも、トランザクションの実行された日時情報の方が重要ではないかと考え、ログのフォーマットをそのように変更しています。何かログに追加したい情報があれば、フォーマット定義に追加することにより可能です。
コンソールに出力されるログと同じフォーマットがよければ、
IN_MEMORY_STREAM_FORMAT = ('%(levelname)s:%(name)s:%(message)s')
です。

import io
import logging

logging.basicConfig()
log = logging.getLogger()
log.setLevel(logging.DEBUG)

log_stream = io.StringIO()
in_memory_stream_handler = logging.StreamHandler(stream=log_stream)
in_memory_stream_handler.setLevel(logging.DEBUG)
IN_MEMORY_STREAM_FORMAT = ('%(asctime)s %(message)s')
in_memory_stream_formatter = logging.Formatter(IN_MEMORY_STREAM_FORMAT, datefmt='%Y-%m-%d %H:%M:%S')
in_memory_stream_handler.setFormatter(in_memory_stream_formatter)
in_memory_stream_filter = logging.Filter(name='pymodbus.transaction')
in_memory_stream_handler.addFilter(in_memory_stream_filter)
log.addHandler(in_memory_stream_handler)

この結果、インメモリのテキストバッファに次のようなログが出力されます。

2021-09-03 01:08:12 Current transaction state - IDLE
2021-09-03 01:08:12 Running transaction 1
2021-09-03 01:08:12 SEND: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x1 0x0 0x1 0x0 0x1
2021-09-03 01:08:12 Changing transaction state from 'SENDING' to 'WAITING FOR REPLY'
2021-09-03 01:08:12 Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
2021-09-03 01:08:12 RECV: 0x0 0x1 0x0 0x0 0x0 0x4 0x1 0x1 0x1 0x0
2021-09-03 01:08:12 Adding transaction 1
2021-09-03 01:08:12 Getting transaction 1
2021-09-03 01:08:12 Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
2021-09-03 01:08:12 Current transaction state - TRANSACTION_COMPLETE
2021-09-03 01:08:12 Running transaction 2
2021-09-03 01:08:12 SEND: 0x0 0x2 0x0 0x0 0x0 0x6 0x1 0x5 0x0 0x0 0xff 0x0
2021-09-03 01:08:12 Changing transaction state from 'SENDING' to 'WAITING FOR REPLY'
2021-09-03 01:08:12 Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
2021-09-03 01:08:12 RECV: 0x0 0x2 0x0 0x0 0x0 0x6 0x1 0x5 0x0 0x0 0xff 0x0
2021-09-03 01:08:12 Adding transaction 2
2021-09-03 01:08:12 Getting transaction 2
2021-09-03 01:08:12 Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
2021-09-03 01:08:12 Current transaction state - TRANSACTION_COMPLETE
2021-09-03 01:08:12 Running transaction 3
2021-09-03 01:08:12 SEND: 0x0 0x3 0x0 0x0 0x0 0x6 0x1 0x1 0x0 0x0 0x0 0x1
2021-09-03 01:08:12 Changing transaction state from 'SENDING' to 'WAITING FOR REPLY'
2021-09-03 01:08:12 Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
2021-09-03 01:08:12 RECV: 0x0 0x3 0x0 0x0 0x0 0x4 0x1 0x1 0x1 0x1
2021-09-03 01:08:12 Adding transaction 3
2021-09-03 01:08:12 Getting transaction 3
2021-09-03 01:08:12 Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
2021-09-03 01:08:12 Current transaction state - TRANSACTION_COMPLETE

このログを任意のタイミングで取得し、処理し、ファイルに保存します。
インメモリのテキストバッファにはlog_stream = io.StringIO()で log_stream という名前をつけていますので、log_stream.getvalue()でその内容をまとめて取得できます。

以下の例では、「SEND:」と「RECV:」が含まれる行のみを抜き出して、各行を「日付」「時刻」「ログメッセージ」に分割しています(この3つを列とするcsvとして保存すると仮定)。
またこの分割を容易にするために、ログ定義にさかのぼって、ログのフォーマットを変更しています(「日付」「時刻」「ログメッセージ」の間に@を挿入)。

(前略)
IN_MEMORY_STREAM_FORMAT = ('%(asctime)s@%(message)s')
in_memory_stream_formatter = logging.Formatter(IN_MEMORY_STREAM_FORMAT, datefmt='%Y-%m-%d@%H:%M:%S')
(中略)

raw_log = log_stream.getvalue()
pckt_log = [msg for msg in raw_log.split("\n") if "SEND:" in msg or "RECV:" in msg]
pckt_log_for_csv = []
for msg in pckt_log:
    pckt_log_for_csv.append(msg.split("@"))
print(pckt_log_for_csv)

この出力結果は以下のようになっています。

[['2021-09-03', '09:04:29', 'SEND: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x1 0x0 0x1 0x0 0x1'], ['2021-09-03', '09:04:29', 'RECV: 0x0 0x1 0x0 0x0 0x0 0x4 0x1 0x1 0x1 0x0'], ['2021-09-03', '09:04:29', 'SEND: 0x0 0x2 0x0 0x0 0x0 0x6 0x1 0x5 0x0 0x0 0xff 0x0'], ['2021-09-03', '09:04:29', 'RECV: 0x0 0x2 0x0 0x0 0x0 0x6 0x1 0x5 0x0 0x0 0xff 0x0'], ['2021-09-03', '09:04:29', 'SEND: 0x0 0x3 0x0 0x0 0x0 0x6 0x1 0x1 0x0 0x0 0x0 0x1'], ['2021-09-03', '09:04:29', 'RECV: 0x0 0x3 0x0 0x0 0x0 0x4 0x1 0x1 0x1 0x1']]

ログの保存が終了したら、テキストバッファのサイズを0に切り詰めて空にし、次のログ出力に備えます。これをしないと同じログが何度も保存されてしまいます。もちろん、保存と共にプログラムを終了する場合は、これは不要です。

log_stream.truncate(0)

（なお、質問文中の「所得する」は「取得する」の間違いでしょうか。）

Comments

[NKJSM]

わかりやすい説明のうえ、実装例も提示していただき本当にありがとうございました。
(所得は誤字でございます)