実務に生かすPythonサンプル

Pythonでログを出力する方法【もう迷わない決定版】

こんにちは。投資エンジニアの三年坊主(@SannenBouzu)です。

今回は、Pythonでログを出力したい人の疑問に答えます。

Pythonでログを出力するための基本的な書き方を教えてほしい。自分で作ったPythonプログラムが異常なく動いたか、実行中や実行後に一目で確認したい。

logging入門というQiita記事では、このような内容が分かりやすく説明されています。

  • できる限り公式の情報源を明示しながら「基本の使い方」を説明している
  • 有名な外部ライブラリを例にその説明を補強している

 

今回の記事では、Qiita記事の情報も参考にしながら、自分で作ったPythonプログラムの実行結果や解説を、実際に動くサンプルコードとともに紹介したいと思います。

合計5年以上Pythonを使ってきた私ですが、その経験も踏まえて、Pythonでログを出力する方法を紹介します。よければ参考にしてください。

この記事はこんな方におすすめ!

  • Pythonでログを出力する方法を知りたい方
  • コピペで動くサンプルを使ってすぐにログ出力をはじめたい方
  • printデバッグから卒業してloggingを使うログ出力をきちんと理解しておきたい方
【2019年版】Pythonインストール・Mac編【長く安全に使える環境構築】PythonをMacにインストールする環境構築方法を具体的に紹介します。インストール後、バージョン切り替え・アップデート・アンインストールが気軽にできて、Pythonを長く安全に使える方法です。この記事を読んでMacで楽しいPythonライフをはじめましょう!...

Pythonでログを出力する方法【コピペで動くサンプル付】

ライブラリ側(使われる側)とユーザ側(使う側)でログ出力のための書き方が違います。

まず、ライブラリ側とそれを使う側(ユーザー側)でloggingの書き方が違います。ここをごっちゃにすると、話が絶対に錯綜するので、必ず意識するようにします。

ライブラリ側では、module毎にloggerを定義しておいて、logとして出したい情報に関して、debug, info, (warning)等を使い分けます

引用:logging入門

 

ライブラリ側(使われる側)では、

  • 先頭にlogger = logging.getLogger(__name__)を指定してモジュールごとにロガーを作成する
  • ログを出力したい場所にlogger.debug(‘メッセージ’)のように書く

ユーザ側(使う側)では、

  • 細かな出力方法はユーザー側で設定する

この方法に従うことで、後からでも見やすいPythonのログを出力することができます。

使われる側?使う側?ロガー?ちょっと何言ってるか分からない…

たしかに文字だけではよく分からないですよね・・・最初に具体例を見ておきましょう。

 

loggingを使ったログ出力の具体例【コピペで動くサンプル】

この記事で使う表記法

  • コメント
  • ターミナル上で実行するコマンド($マークは入力不要)
  • Pythonを起動した状態で実行するコマンド

 

説明のためにこのようなディレクトリ構造をつくります。(logsという名前のディレクトリを作っておけば、sample.logはtest.pyを実行したときに自動で生成されます)

 

日時の計算をするためのdatetime_module.pyを自分で用意して、それをtest.pyから「使う」シチュエーションを考えてみましょう。

test.pyの中で”import datetime_module”しているので、datetime_module.pyが「使われる側」、test.pyが「使う側」になります。

 

▼クリックしてdatetime_module.pyのサンプルを見る▼

 

▼クリックしてtest.pyのサンプルを見る▼

 

細かい補足はプログラム中にコメントとして記入していますが、

ライブラリ側(使われる側)では、

  • 先頭にlogger = logging.getLogger(__name__)を指定してモジュールごとにロガーを作成する
  • ログを出力したい場所にlogger.debug(‘メッセージ’)のように書く

ユーザ側(使う側)では、

  • 細かな出力方法はユーザー側で設定する

このようになっているのが確認できると思います。

 

test.pyを実行すると、INFOレベル以上のログがコンソールに出力されて、

 

DEBUGレベル以上のログがlogs/sample.logファイルに記録されます。

 

_detail_formattingで指定していたので、プログラムが正常に動いたか確認するために役立つ情報がたくさん盛り込まれています。

このくらい出力しておくと、「どのモジュールの何行目で問題があったか」一目で分かります。

 

属性名説明
asctimeLogRecord が生成された時刻を人間が読める書式で表したもの。デフォルトでは “2003-07-08 16:49:45,896” 形式 (コンマ以降の数字は時刻のミリ秒部分) です。
levelnameメッセージのための文字のロギングレベル (‘DEBUG’, ‘INFO’, ‘WARNING’, ‘ERROR’, ‘CRITICAL’)。
moduleモジュール (filename の名前部分)。
funcNameロギングの呼び出しを含む関数の名前。
linenoロギングの呼び出しが発せられたソース行番号 (利用できる場合のみ)。
messagemsg % args として求められた、ログメッセージ。 Formatter.format() が呼び出されたときに設定されます。

一部抜粋:16.6.7. LogRecord 属性

 

ロガー・ハンドラ・フィルタ・フォーマッタ

Python公式の上級ロギングチュートリアルによると、「ロガー」「ハンドラ」「フィルタ」「フォーマッタ」はこのように説明されています。

  • ロガーは、アプリケーションコードが直接使うインタフェースを公開します。
  • ハンドラは、(ロガーによって生成された) ログ記録を適切な送信先に送ります。
  • フィルタは、どのログ記録を出力するかを決定する、きめ細かい機能を提供します。
  • フォーマッタは、ログ記録が最終的に出力されるレイアウトを指定します。

 

紹介したサンプルコードでも、Pythonプログラムからロガーを使ってログを生成し、ハンドラでそのログをどこに送信するか(ファイルに保存するのか、コンソールに出力するのか、など)を決めていました。

フィルタは使いませんでしたが、フォーマッタを使ってログの出力形式を決めていました。

 

基本ロギングチュートリアルを読むと、このあたりの話を出さずに「ただログが出力できればいい」という目的で書かれているようです。

たしかにスムーズにログ出力がはじめられそうですが、「スムーズにはじめて後々困る」ことはプログラミング学習ではよく起こるので、あえて「ロガー」「ハンドラ」「フィルタ」「フォーマッタ」の概念を紹介しました。

ライブラリ側(使われる側)とユーザ側(使う側)でログ出力のための書き方が違うことを意識した上で、”logger = logging.getLogger(__name__)”を使ってモジュール(≒一つのファイル)ごとにロガーを作ってからログ出力しましょう。

 

「Pythonでログを出力する方法」メリット【printデバッグから卒業】

上の見出しで紹介した「Pythonでログを出力する方法」のメリットは、「print文を書いて問題箇所を特定する方法のデメリットを解消」していることです。

ロガー・ハンドラ・フォーマッタを使って、どの内容のログをどこに出力するか制御しているので、ログを一目見ただけでPythonプログラムの実行状態や、不具合があればその問題箇所がすぐに分かるからです。

 

print文で問題箇所を特定する「printデバッグ」はたしかにお手軽で早いんですけど、

 

 

出力結果を見てみるとずいぶん貧弱で見にくいですし、モジュールの名前を変えたらprint文の中身も全部自分で変えないといけません。

 

ファイルとコンソールの両方に同時に出力しようとすると、できなくはないですが、少なくともログレベルを設定したり、それに応じて出し分けをするようなことは難しいと思います。

 

短くて簡単なpythonプログラムの動きを確かめるだけなら、正直printデバッグではじめるのは悪くはないと思います。

ですが、少し大きなプログラムを書き始めて、そろそろprintデバッグをやめてログ出力したいと思う人にとっては、インターネットで検索して見つかるprint文やlogging.log()だけでは限界を感じることがあるでしょう

 

繰り返しになりますが、「Pythonでログを出力する方法」のメリットは、「print文を書いて問題箇所を特定する方法のデメリットを解消」していることです。

サンプルコードを参考に、少しずつ使いこなせるようにしていきましょう。

 

Pythonプログラムの実行結果に異常がないか一目で確認するには

そもそもPythonでログを出力するのはなぜでしょうか?

一番の目的は「Pythonプログラムの実行結果に異常がないか一目で確認するため」だと思います。

Pythonプログラムが異常なく動いたか一目で確認するために、出力したログをうまく活用する方法を紹介します。

 

tail -fやlessコマンドでファイル出力を確認する

ひとつのコンソール画面でPythonプログラムを実行し、別のコンソール画面で”tail -f”を実行すれば、Pythonプログラムを実行しながら、書き込まれていくログをリアルタイムで確認できます。

 

ロガーを使ってログレベルを使い分けたログ出力をしていると、そのレベルを含む行だけ見ることもできて便利です。

 

私自身は、このあたりの記事を読んで、lessコマンドという別のコマンドを使って監視していた時期もありました。

[Linux]「tail -f」での監視はもう古い!?超絶便利なlessコマンド

tail -fやtailfを使うのはやめてless +Fを使おう

 

loggingの出力に色をつけて見やすくする

Pythonで色つきログを出力できるrainbow_logging_handlerを開発した人もいるようです。

たしかに、ログレベルごとに色が分かれていると見やすいですよね。

参考:Pythonで色つきログを – rainbow_logging_handler をPyPIにリリースしました

 

監視ツールを使う

面倒なことは機械に任せましょう。

詳しくは紹介しませんが、ZabbixSplunkElasticsearch + Kibanaなど、システムのログなどを監視して、異常があれば通知してくれるようなツールもたくさんあります。

 

出力したログは、活用してこそ意味があります。

Pythonプログラムが異常なく動いたか確認するために、うまく活用していきましょう。

 

関連記事:こちらも読まれています

【2019年版】Pythonインストール・Mac編【長く安全に使える環境構築】

Pythonでcsvファイルの読み込み【csvモジュール】

エンジニア転職・部署異動:ただ「真面目に」働いていませんか?

 

▼経験の棚卸しで納得のキャリアを▼
▼相場に消耗しない資産運用▼
マネースクエア
Pythonチュートリアル

Pythonをインストール、サンプルを通して使い方を学んだら、次は実際に何か作ってみませんか?

手元のパソコンで環境構築不要・Webブラウザだけで、パッと見た人の印象に残るコンテンツを作る手順を一から説明しています。

チュートリアルを見てみる

COMMENT

メールアドレスが公開されることはありません。 * が付いている欄は必須項目です

このサイトはスパムを低減するために Akismet を使っています。コメントデータの処理方法の詳細はこちらをご覧ください