こんにちは。投資エンジニアの三年坊主（@SannenBouzu）です。
今回は、Pythonでログを出力したい人の疑問に答えます。
Pythonでログを出力するための基本的な書き方を教えてほしい。自分で作ったPythonプログラムが異常なく動いたか、実行中や実行後に一目で確認したい。
logging入門というQiita記事では、このような内容が分かりやすく説明されています。
- できる限り公式の情報源を明示しながら「基本の使い方」を説明している
- 有名な外部ライブラリを例にその説明を補強している
今回の記事では、Qiita記事の情報も参考にしながら、自分で作ったPythonプログラムの実行結果や解説を、実際に動くサンプルコードとともに紹介したいと思います。
合計5年以上Pythonを使ってきた私ですが、その経験も踏まえて、Pythonでログを出力する方法を紹介します。よければ参考にしてください。
- Pythonでログを出力する方法を知りたい方
- コピペで動くサンプルを使ってすぐにログ出力をはじめたい方
- printデバッグから卒業してloggingを使うログ出力をきちんと理解しておきたい方
Pythonでログを出力する方法【コピペで動くサンプル付】
ライブラリ側（使われる側）とユーザ側（使う側）でログ出力のための書き方が違います。
まず、ライブラリ側とそれを使う側(ユーザー側)でloggingの書き方が違います。ここをごっちゃにすると、話が絶対に錯綜するので、必ず意識するようにします。
ライブラリ側では、module毎にloggerを定義しておいて、logとして出したい情報に関して、debug, info, (warning)等を使い分けます
引用：logging入門
ライブラリ側（使われる側）では、
- 先頭にlogger = logging.getLogger(__name__)を指定してモジュールごとにロガーを作成する
- ログを出力したい場所にlogger.debug(‘メッセージ’)のように書く
ユーザ側（使う側）では、
- 細かな出力方法はユーザー側で設定する
この方法に従うことで、後からでも見やすいPythonのログを出力することができます。
使われる側？使う側？ロガー？ちょっと何言ってるか分からない…
たしかに文字だけではよく分からないですよね・・・最初に具体例を見ておきましょう。
loggingを使ったログ出力の具体例【コピペで動くサンプル】
この記事で使う表記法
- コメント
1 | # コメントの例です |
- ターミナル上で実行するコマンド（$マークは入力不要）
1 | $ which python |
- py3envという名前の仮想環境を有効化した状態で実行するコマンド（”(py3env) $” は入力不要）
1 | (py3env) $ which python |
- Pythonを起動した状態で実行するコマンド
1 | >>> import os |
説明のためにこのようなディレクトリ構造をつくります。（logsという名前のディレクトリを作っておけば、sample.logはtest.pyを実行したときに自動で生成されます）
1 2 3 4 5 | . ├── datetime_module.py ├── logs │ └── sample.log └── test.py |
日時の計算をするためのdatetime_module.pyを自分で用意して、それをtest.pyから「使う」シチュエーションを考えてみましょう。
test.pyの中で”import datetime_module”しているので、datetime_module.pyが「使われる側」、test.pyが「使う側」になります。
▼クリックしてdatetime_module.pyのサンプルを見る▼
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 | # 必要なライブラリに加えてloggingもインポート import datetime import logging # ロガーを取得する logger = logging.getLogger(__name__) def get_datetime_now(): """プログラム実行時点での日時を計算する。 Returns: datetime_now (datetime.datetime): プログラム実行時点での日時 """ # ログを出力する方法(実際にはログを出力したい場所で記述する) logger.debug('DEBUGレベルのメッセージです') logger.info('INFOレベルのメッセージです') logger.warning('WARNINGレベルのメッセージです') logger.error('ERRORレベルのメッセージです') logger.critical('CRITICALレベルのメッセージです') datetime_now = datetime.datetime.now() return datetime_now def get_monday(time): """指定する日時が含まれる週の月曜日を計算する。 Args: time (datetime.datetime): 指定する日時 Returns: result (datetime.date): 指定する日時が含まれる週の月曜日 """ # ログを出力する方法(実際にはログを出力したい場所で記述する) logger.debug('DEBUGレベルのメッセージです') logger.info('INFOレベルのメッセージです') logger.warning('WARNINGレベルのメッセージです') logger.error('ERRORレベルのメッセージです') logger.critical('CRITICALレベルのメッセージです') time_date = time.date() weekday = time_date.weekday() delta = datetime.timedelta(days=weekday) result = time_date - delta return result |
▼クリックしてtest.pyのサンプルを見る▼
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 | # loggingと自作のdatetime_moduleをインポート import logging import datetime_module LOG_LEVEL_FILE = 'DEBUG' LOG_LEVEL_CONSOLE = 'INFO' # フォーマットを指定 (https://docs.python.jp/3/library/logging.html#logrecord-attributes) _detail_formatting = '%(asctime)s %(levelname)-8s [%(module)s#%(funcName)s %(lineno)d] %(message)s' """ LOG_LEVEL_FILEレベル以上のログをファイルに出力する設定 """ # datetime_moduleモジュールを呼び出す側(test.py)で出力形式などの基本設定をする logging.basicConfig( level=getattr(logging, LOG_LEVEL_FILE), # LOG_LEVEL_FILE = 'DEBUG' なら logging.DEBUGを指定していることになる format=_detail_formatting, filename='./logs/sample.log' ) """ LOG_LEVEL_CONSOLEレベル以上のログをコンソール(std.stderr)に出力する設定 """ # ログをコンソールに送るハンドラconsoleを作成 console = logging.StreamHandler() console.setLevel(getattr(logging, LOG_LEVEL_CONSOLE)) # LOG_LEVEL_CONSOLE = 'INFO' なら logging.INFOを指定していることになる console_formatter = logging.Formatter(_detail_formatting) console.setFormatter(console_formatter) """ consoleハンドラをロガーに追加する """ # test用のロガーを取得し、consoleハンドラを追加する logger = logging.getLogger(__name__) logger.addHandler(console) # datetime_module用のロガーを取得し、consoleハンドラを追加する。他に追加したいモジュールがあれば同じ形式で追加する logging.getLogger("datetime_module").addHandler(console) if __name__ == '__main__': datetime_now = datetime_module.get_datetime_now() # ログを出力する方法(実際にはログを出力したい場所で記述する) logger.debug('DEBUGレベルのメッセージです') logger.info('INFOレベルのメッセージです') logger.warning('WARNINGレベルのメッセージです') logger.error('ERRORレベルのメッセージです') logger.critical('CRITICALレベルのメッセージです') monday_of_current_week = datetime_module.get_monday(datetime_now) |
細かい補足はプログラム中にコメントとして記入していますが、
ライブラリ側（使われる側）では、
- 先頭にlogger = logging.getLogger(__name__)を指定してモジュールごとにロガーを作成する
- ログを出力したい場所にlogger.debug(‘メッセージ’)のように書く
ユーザ側（使う側）では、
- 細かな出力方法はユーザー側で設定する
このようになっているのが確認できると思います。
test.pyを実行すると、INFOレベル以上のログがコンソールに出力されて、
1 2 3 4 5 6 7 8 9 10 11 12 13 14 | (py3env) $ python test.py 2018-09-15 12:15:16,631 INFO [datetime_module#get_datetime_now 17] INFOレベルのメッセージです 2018-09-15 12:15:16,631 WARNING [datetime_module#get_datetime_now 18] WARNINGレベルのメッセージです 2018-09-15 12:15:16,631 ERROR [datetime_module#get_datetime_now 19] ERRORレベルのメッセージです 2018-09-15 12:15:16,631 CRITICAL [datetime_module#get_datetime_now 20] CRITICALレベルのメッセージです 2018-09-15 12:15:16,632 INFO [test#<module> 49] INFOレベルのメッセージです 2018-09-15 12:15:16,632 WARNING [test#<module> 50] WARNINGレベルのメッセージです 2018-09-15 12:15:16,632 ERROR [test#<module> 51] ERRORレベルのメッセージです 2018-09-15 12:15:16,632 CRITICAL [test#<module> 52] CRITICALレベルのメッセージです 2018-09-15 12:15:16,632 INFO [datetime_module#get_monday 41] INFOレベルのメッセージです 2018-09-15 12:15:16,632 WARNING [datetime_module#get_monday 42] WARNINGレベルのメッセージです 2018-09-15 12:15:16,633 ERROR [datetime_module#get_monday 43] ERRORレベルのメッセージです 2018-09-15 12:15:16,633 CRITICAL [datetime_module#get_monday 44] CRITICALレベルのメッセージです (py3env) $ |
DEBUGレベル以上のログがlogs/sample.logファイルに記録されます。
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 | (py3env) $ cat logs/sample.log 2018-09-15 12:15:16,630 DEBUG [datetime_module#get_datetime_now 16] DEBUGレベルのメッセージです 2018-09-15 12:15:16,631 INFO [datetime_module#get_datetime_now 17] INFOレベルのメッセージです 2018-09-15 12:15:16,631 WARNING [datetime_module#get_datetime_now 18] WARNINGレベルのメッセージです 2018-09-15 12:15:16,631 ERROR [datetime_module#get_datetime_now 19] ERRORレベルのメッセージです 2018-09-15 12:15:16,631 CRITICAL [datetime_module#get_datetime_now 20] CRITICALレベルのメッセージです 2018-09-15 12:15:16,632 DEBUG [test#<module> 48] DEBUGレベルのメッセージです 2018-09-15 12:15:16,632 INFO [test#<module> 49] INFOレベルのメッセージです 2018-09-15 12:15:16,632 WARNING [test#<module> 50] WARNINGレベルのメッセージです 2018-09-15 12:15:16,632 ERROR [test#<module> 51] ERRORレベルのメッセージです 2018-09-15 12:15:16,632 CRITICAL [test#<module> 52] CRITICALレベルのメッセージです 2018-09-15 12:15:16,632 DEBUG [datetime_module#get_monday 40] DEBUGレベルのメッセージです 2018-09-15 12:15:16,632 INFO [datetime_module#get_monday 41] INFOレベルのメッセージです 2018-09-15 12:15:16,632 WARNING [datetime_module#get_monday 42] WARNINGレベルのメッセージです 2018-09-15 12:15:16,633 ERROR [datetime_module#get_monday 43] ERRORレベルのメッセージです 2018-09-15 12:15:16,633 CRITICAL [datetime_module#get_monday 44] CRITICALレベルのメッセージです (py3env) $ |
_detail_formattingで指定していたので、プログラムが正常に動いたか確認するために役立つ情報がたくさん盛り込まれています。
このくらい出力しておくと、「どのモジュールの何行目で問題があったか」一目で分かります。
| 属性名 | 説明 |
|---|---|
| asctime | LogRecord が生成された時刻を人間が読める書式で表したもの。デフォルトでは “2003-07-08 16:49:45,896” 形式 (コンマ以降の数字は時刻のミリ秒部分) です。 |
| levelname | メッセージのための文字のロギングレベル (‘DEBUG’, ‘INFO’, ‘WARNING’, ‘ERROR’, ‘CRITICAL’)。 |
| module | モジュール (filename の名前部分)。 |
| funcName | ロギングの呼び出しを含む関数の名前。 |
| lineno | ロギングの呼び出しが発せられたソース行番号 (利用できる場合のみ)。 |
| message | msg % args として求められた、ログメッセージ。 Formatter.format() が呼び出されたときに設定されます。 |
一部抜粋：16.6.7. LogRecord 属性
ロガー・ハンドラ・フィルタ・フォーマッタ
Python公式の上級ロギングチュートリアルによると、「ロガー」「ハンドラ」「フィルタ」「フォーマッタ」はこのように説明されています。
- ロガーは、アプリケーションコードが直接使うインタフェースを公開します。
- ハンドラは、(ロガーによって生成された) ログ記録を適切な送信先に送ります。
- フィルタは、どのログ記録を出力するかを決定する、きめ細かい機能を提供します。
- フォーマッタは、ログ記録が最終的に出力されるレイアウトを指定します。
紹介したサンプルコードでも、Pythonプログラムからロガーを使ってログを生成し、ハンドラでそのログをどこに送信するか（ファイルに保存するのか、コンソールに出力するのか、など）を決めていました。
フィルタは使いませんでしたが、フォーマッタを使ってログの出力形式を決めていました。
基本ロギングチュートリアルを読むと、このあたりの話を出さずに「ただログが出力できればいい」という目的で書かれているようです。
たしかにスムーズにログ出力がはじめられそうですが、「スムーズにはじめて後々困る」ことはプログラミング学習ではよく起こるので、あえて「ロガー」「ハンドラ」「フィルタ」「フォーマッタ」の概念を紹介しました。
ライブラリ側（使われる側）とユーザ側（使う側）でログ出力のための書き方が違うことを意識した上で、”logger = logging.getLogger(__name__)”を使ってモジュール（≒一つのファイル）ごとにロガーを作ってからログ出力しましょう。
「Pythonでログを出力する方法」メリット【printデバッグから卒業】
上の見出しで紹介した「Pythonでログを出力する方法」のメリットは、「print文を書いて問題箇所を特定する方法のデメリットを解消」していることです。
ロガー・ハンドラ・フォーマッタを使って、どの内容のログをどこに出力するか制御しているので、ログを一目見ただけでPythonプログラムの実行状態や、不具合があればその問題箇所がすぐに分かるからです。
print文で問題箇所を特定する「printデバッグ」はたしかにお手軽で早いんですけど、
1 2 3 4 5 6 7 8 9 10 11 | import datetime def get_datetime_now(): print('datetime_now start') datetime_now = datetime.datetime.now() print('datetime_now end') return datetime_now def get_monday(time): print('time:', time) return time.date() - datetime.timedelta(days=time.date().weekday()) |
1 2 3 4 5 6 7 8 9 10 11 | import datetime_module if __name__ == '__main__': print('datetime_module.get_datetime_now start') datetime_now = datetime_module.get_datetime_now() print('datetime_module.get_datetime_now end') print('datetime_module.get_monday start') monday_of_current_week = datetime_module.get_monday(datetime_now) print('datetime_module.get_monday end') |
出力結果を見てみるとずいぶん貧弱で見にくいですし、モジュールの名前を変えたらprint文の中身も全部自分で変えないといけません。
1 2 3 4 5 6 7 8 9 | (py3env) $ python test.py datetime_module.get_datetime_now start datetime_now start datetime_now end datetime_module.get_datetime_now end datetime_module.get_monday start time: 2018-09-15 14:00:58.796678 datetime_module.get_monday end (py3env) $ |
ファイルとコンソールの両方に同時に出力しようとすると、できなくはないですが、少なくともログレベルを設定したり、それに応じて出し分けをするようなことは難しいと思います。
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 | (py3env) $ python test.py | tee logs/sample.log datetime_module.get_datetime_now start datetime_now start datetime_now end datetime_module.get_datetime_now end datetime_module.get_monday start time: 2018-09-15 14:03:02.302505 datetime_module.get_monday end (py3env) $ (py3env) $ cat logs/sample.log datetime_module.get_datetime_now start datetime_now start datetime_now end datetime_module.get_datetime_now end datetime_module.get_monday start time: 2018-09-15 14:03:02.302505 datetime_module.get_monday end (py3env) $ |
短くて簡単なpythonプログラムの動きを確かめるだけなら、正直printデバッグではじめるのは悪くはないと思います。
ですが、少し大きなプログラムを書き始めて、そろそろprintデバッグをやめてログ出力したいと思う人にとっては、インターネットで検索して見つかるprint文やlogging.log()だけでは限界を感じることがあるでしょう。
繰り返しになりますが、「Pythonでログを出力する方法」のメリットは、「print文を書いて問題箇所を特定する方法のデメリットを解消」していることです。
サンプルコードを参考に、少しずつ使いこなせるようにしていきましょう。
Pythonプログラムの実行結果に異常がないか一目で確認するには
そもそもPythonでログを出力するのはなぜでしょうか？
一番の目的は「Pythonプログラムの実行結果に異常がないか一目で確認するため」だと思います。
Pythonプログラムが異常なく動いたか一目で確認するために、出力したログをうまく活用する方法を紹介します。
tail -fやlessコマンドでファイル出力を確認する
ひとつのコンソール画面でPythonプログラムを実行し、別のコンソール画面で”tail -f”を実行すれば、Pythonプログラムを実行しながら、書き込まれていくログをリアルタイムで確認できます。
1 | $ tail -f logs/sample.log |
ロガーを使ってログレベルを使い分けたログ出力をしていると、そのレベルを含む行だけ見ることもできて便利です。
1 | $ tail -f logs/sample.log | grep "ERROR" |
私自身は、このあたりの記事を読んで、lessコマンドという別のコマンドを使って監視していた時期もありました。
[Linux]「tail -f」での監視はもう古い!?超絶便利なlessコマンド
tail -fやtailfを使うのはやめてless +Fを使おう
1 | less +F logs/sample.log |
loggingの出力に色をつけて見やすくする
Pythonで色つきログを出力できるrainbow_logging_handlerを開発した人もいるようです。
たしかに、ログレベルごとに色が分かれていると見やすいですよね。
参考：Pythonで色つきログを – rainbow_logging_handler をPyPIにリリースしました
監視ツールを使う
面倒なことは機械に任せましょう。
詳しくは紹介しませんが、ZabbixやSplunk、Elasticsearch + Kibanaなど、システムのログなどを監視して、異常があれば通知してくれるようなツールもたくさんあります。
出力したログは、活用してこそ意味があります。
Pythonプログラムが異常なく動いたか確認するために、うまく活用していきましょう。
関連記事：こちらも読まれています
【2019年版】Pythonインストール・Mac編【長く安全に使える環境構築】
より本格的にPythonを学ぶなら
より本格的にPythonを学びたい場合には、プログラミングスクールを活用するのがオススメです。
プログラミングスクールって、「プログラミングって何？」みたいな超初心者だけのものと思っていませんか？
最近では、経験者向けにも、レベルや希望に合わせた様々なコースが展開されています。
オススメなのが、Aidemyです。
特徴は、人工知能特化型のプログラミング学習サービスということ。
Pythonを学べるコース
- AIアプリ開発コース（画像認識）
- データ分析コース（数値予測）
- 自然言語処理コース
- E資格対策コース
- クラウドAI開発コース
- 実戦データサイエンスコース
Aidemyの教材は「理論よりもまずは実践」をうたっていて、他社と比較すると、かなり本格的に、現場でも実際に使われるスキルを身につけられます。
そして、どのコースも同じ料金で受け放題。
余裕があれば、AIアプリ開発コースの内容と、クラウドAI開発コースの内容を組み合わせて学習することもできてしまいます。
無料のカウンセリングで、不明点や学習したい内容をまずは相談してみましょう。
もう一つオススメなのが、TechAcademyです。
オンラインプログラミングスクール受講者数No.1の実績に加えて、受講生限定の転職サポートもあり、TechAcademyで学んだスキルを生かせる職場への転職も可能です。
Pythonを学べるコース
「セット割」を活用すると、Pythonを使った人工知能・データ分析のスキルを過不足なく身につけられます。
1週間の無料体験があるので、システムの使い心地やサポート体制をのぞいてみるのがいいかなと思います。
どちらのスクールも質問サポートが充実していて、早ければその場で、遅くとも次の日には疑問が解消するので、
「独学でプログラミングを勉強してきたけど、行き詰まるたびに時間が奪われるし、周りに気軽に聞ける人もいない」
みたいな無駄な一日を過ごすことがなくなります。
以上、Pythonを本格的に学べるプログラミングスクールを2校紹介しました。どちらも最初に20〜30万円くらいの投資が必要ですが、実際にスキルを身につけてしまえば、あとで簡単に回収できるはずです。例えば、
- Pythonエンジニアに転職して年収を上げる：50万円
- 副業で業務委託：20万円（時給5,000円で週10時間、1か月）
- クラウドソーシングの単発案件：5〜10万円
このように、プログラミングスクールにお金を払ってもすぐに回収できることが分かると思います。
実際に、Pythonを使う業務委託で時給5,000円というのは普通にあるので、スキルをつけたら「週末にちょっと作業」を1〜2か月続けるだけですよね。
Google検索で問題解決するのもいいですが、「毎回ちょっと場当たり的に対応していて苦しいな・・・」と感じているあなたは、一度腰を据えてPythonを本格的に学ぶことを選択肢に入れてみてはいかがでしょうか。
記事で紹介したプログラミングスクールの一覧
- Aidemy
→人工知能特化、無料カウンセリングあり - TechAcademy→受講者数No.1、1週間の無料体験あり
