はじめに
皆さんPythonでログ出力する際に、print関数を使われることも多いと思います。もちろん、print関数を使うことに何ら問題はありません。ただし、少し待ってください。print関数でログを出力する際に将来のことをきちんと考えられてますか？将来、このログはどんな時に検索されるのか、検索される際に検索しやすいフォーマットになっているのかどうか、などです。
今回の文章の結論をいきなり書きますが、何も考えずにprint関数でログを出力するのではなく、時と場合にあった方法でログ出力しましょう、ということになります。
そもそもprint関数についておさらい
組み込み関数のprintのリファレンスを見てみましょう。
print
print(*objects, sep=' ', end='\n', file=sys.stdout, flush=False)
ざっくりと説明すると、キーワード引数無しで引数に追加したものはすべてstr()の形式でsepで指定した区切り文字を間に挟んで出力される、ということですね。
name_list = ['taro', 'jiro']
name_object = {'name': 'taro', 'age': 12}
print(name_list, name_object, 'Hello World!')
上記のようなコードの場合、出力は以下のようになります。
確かにprintの引数の内容がsepのデフォルトであるスペースで区切られて出力されていますね。
['taro', 'jiro'] {'name': 'taro', 'age': 12} Hello World!
では、次によくあるユースケースとして文字列の埋め込みを見てみましょう。
name = 'taro'
print('Your Name is ' + name + '.') # Your Name is taro.
Pythonも文字列を+で結合できるので、上記で実現したいことは可能です。
ただ、この書き方だと文字列内に変数を埋め込みたい箇所が複数あった場合、それぞれをすべて+でつないでいく必要があり、コードの文字数が多くなってしまいます。
プログラミングの原則として、コードの行数や文字数はできる限り少ないほうが良い、というのがあるので、できればもう少し見やすくしてみましょう。
name = 'taro'
print('Your Name is {}.'.format(name))
文字列のformat関数を使って書き直してみました。以前はこのformat関数が良く利用されていましたが、今はf文字列(f-string)の利用が多いかと思います。
f-stringで書き直すと以下のようになります。
name = 'taro'
print(f'Your Name is {name}.')
だいぶ直感的に分かりやすくなりましたね。
なお、formatではなくf-stringを推奨する理由としては、Pylintで以下のように説明されています。
consider-using-f-string / C0209
個人的には特別な条件が無い限りは、f-stringに統一するのがいいかと思っています。
ここまででprint関数を使ってログ出力する際の基礎的な内容をおさらいしました。
そのほかの情報については、公式の以下ページが分かりやすいので、一読頂くとより理解が深まると思います。
7. 入力と出力
pprintでのログ出力
みなさんpprintという関数をご存じでしょうか。
例えば、以下のような辞書をprintで出力する場合を考えます。
test_dict = {
'author': 'xxxxxx',
'author_email': 'yyyyyy',
'bugtrack_url': None,
'classifiers': [
'Development Status :: 3 - Alpha',
'Intended Audience :: Developers',
'License :: OSI Approved :: MIT License',
'Programming Language :: Python :: 2',
'Programming Language :: Python :: 2.6',
'Programming Language :: Python :: 2.7',
'Programming Language :: Python :: 3',
'Programming Language :: Python :: 3.2',
'Programming Language :: Python :: 3.3',
'Programming Language :: Python :: 3.4',
'Topic :: Software Development :: Build Tools',
],
'description': 'A sample Python project\n',
}
print(test_dict)
出力結果は以下のようになります。
{'author': 'xxxxxx', 'author_email': 'yyyyyy', 'bugtrack_url': None, 'classifiers': ['Development Status :: 3 - Alpha', 'Intended Audience :: Developers', 'License :: OSI Approved :: MIT License', 'Programming Language :: Python :: 2', 'Programming Language :: Python :: 2.6', 'Programming Language :: Python :: 2.7', 'Programming Language :: Python :: 3', 'Programming Language :: Python :: 3.2', 'Programming Language :: Python :: 3.3', 'Programming Language :: Python :: 3.4', 'Topic :: Software Development :: Build Tools'], 'description': 'A sample Python project\n'}
当然、結果は一行にまとめられるのですが、開発時などで出力結果が見にくいな、という経験はないでしょうか。
その悩みpprintを使えば解決できます。
使い方はとても簡単で、以下のように使います。
import pprint
test_dict = {
'author': 'xxxxxx',
'author_email': 'yyyyyy',
'bugtrack_url': None,
'classifiers': [
'Development Status :: 3 - Alpha',
'Intended Audience :: Developers',
'License :: OSI Approved :: MIT License',
'Programming Language :: Python :: 2',
'Programming Language :: Python :: 2.6',
'Programming Language :: Python :: 2.7',
'Programming Language :: Python :: 3',
'Programming Language :: Python :: 3.2',
'Programming Language :: Python :: 3.3',
'Programming Language :: Python :: 3.4',
'Topic :: Software Development :: Build Tools',
],
'description': 'A sample Python project\n',
}
pprint.pprint(test_dict)
すると、以下のような出力になります。
{'author': 'xxxxxx',
'author_email': 'yyyyyy',
'bugtrack_url': None,
'classifiers': ['Development Status :: 3 - Alpha',
'Intended Audience :: Developers',
'License :: OSI Approved :: MIT License',
'Programming Language :: Python :: 2',
'Programming Language :: Python :: 2.6',
'Programming Language :: Python :: 2.7',
'Programming Language :: Python :: 3',
'Programming Language :: Python :: 3.2',
'Programming Language :: Python :: 3.3',
'Programming Language :: Python :: 3.4',
'Topic :: Software Development :: Build Tools'],
'description': 'A sample Python project\n'}
見やすく改行、インデントされているのがわかるかと思います。
print関数だけの選択肢ではなく、場合によってはpprintを使う方が良い場面もあるかもしれません。
ログ出力について考える
やっとこの記事の本題です。ログ出力について考えていきましょう。
ログ出力で必要な情報は以下であるとします。
- 日時
- ログレベル
- ログメッセージ
日時は当然必要ですよね。ログを確認するのは、ログが出力されてから、数日後、数か月後の可能性があるので、いつ出力されたログなのかは必要です。日時には必ず、タイムゾーンを含めましょう。日本時間の場合は「2022-06-05T13:50:40+09:00」のような感じですね。ここでUTCを使うべき、という考えももちろんありだと思いますが、日本での利用のみである場合は、ローカルタイムゾーンでのログ出力もありだと思います。
ただし、以下のようなフォーマットは避けましょう。
「12/12/2010 11:46:36 AM」
まず、タイムゾーンが含まれていないので、JSTなのかUTCなのかわかりません。
また、AMやPM表記をすると、ログを検索するときの条件が複雑になるので、24時間表記にしましょう。
一番理想なのはISO形式での日時出力が無難で良いと思います。
ISO 8601
次にログレベルについてです。
ログレベルの説明はPythonのリファレンスから引用します。
明確にログレベルを分割することで、ログの調査を迅速に行うことができます。
皆さん経験があるかと思いますが、システムに何らかの障害が起きた時、まずはerrorやERRORのような文言でログを検索すると思います。
ただ、もしチームでのログ出力が統一されていない場合、もしかしたら障害のログが「CRITICAL」でログが出力されており、「ERROR」で検索しても見つからない、ということが起きるかもしれません。つまり、ログレベルを明確にすることで調査を迅速に行うことができるようになるが、チームで認識が統一されていることが前提、ということです。
では、実際にPythonのloggerを使ったログ出力の例を見てみましょう。
import logging
import time
custom_logger = logging.getLogger('custom_logger')
custom_logger.setLevel(logging.DEBUG)
# ハンドラーを作成
handler = logging.StreamHandler()
# ハンドラーのログレベルを設定
handler.setLevel(logging.DEBUG)
# カスタムロガーにハンドラーを紐づける
custom_logger.addHandler(handler)
# ログ出力のフォーマットを作成
handler_formatter = logging.Formatter(
'%(asctime)s - [%(levelname)s]: %(message)s', datefmt='%Y-%m-%dT%H:%M:%SZ'
)
# ログ出力の日時をGMTに変更
handler_formatter.converter = time.gmtime
# 作成したフォーマットをフォーマッタに設定
handler.setFormatter(handler_formatter)
custom_logger.warning('Watch out!')
custom_logger.info('I told you so')
コードの詳細については解説しませんが、上記で出力されるログは以下のようになります。
2022-06-05T16:22:41Z - [WARNING]: Watch out!
2022-06-05T16:22:41Z - [INFO]: I told you so
しっかりと、日時とログレベルとメッセージが出力されていますね。
通常は上記のコード部分を共通のクラスに実装して、共通のクラスを呼び出す形で、ログの出力をシステム全体で共通化することが大切だと思います。そうすれば、コードレビューの際にprint関数が利用されている箇所を見つけたら、ロガーを使って下さい、という指摘ができるようになります。また、コードレビュー時にログレベルについても議論が生まれ、ある程度適切なログレベルでログが出力されるようになると思います。
ちなみにロギングにpprintは使わないのか、と思われるかもしれませんが、使いません。ログは原則後から検索して使うユースケースがほとんどです。そうなってくると一番問題となるのが、ログ保存の容量、ディスクスペースです。できる限りログの容量は削減したい、ということになるのですが、pprintを使うとインデントや改行などで不要なサイズが増えます。なので、ログ出力に原則pprintは利用しませんが、開発時に一時的に利用する、ということはあります。
Pythonのロギングについてもっと深く知りたい、という人は以下も参照ください。
まとめ
Pythonでログ出力する際にprint以外の選択肢もありますよ、ということを記載しました。もちろん、printで出力することが悪いと言っているわけではありません。時と場合によってベストな選択肢があると思いますので、今回の記事で幅が広がればよいなと思います。loggerを使う、ということがチームで浸透してきたら次に問題になるのが、何をログに残すのか、ログレベルをどう選定するのか、ということかと思います。この課題はなかなか難しく、自分の中でもベストな解を模索している状況なので、自分の中でまとまったら記事を書くかもしれません。。。。