Python 3でのログの使用方法

はじめに

loggingモジュールは、標準のPythonライブラリの一部であり、ソフトウェアが実行されている間に発生したイベントを追跡します。コードにログ呼び出しを追加して、どのイベントが発生したかを示すことができます。

loggingモジュールは、アプリケーションの動作に関連するイベントを記録する診断ログと、ユーザーのトランザクションのイベントを記録する監査ログの両方を可能にします。特に、イベントをファイルに記録するために使用されます。

前提条件

Python 3がインストールされており、コンピューターまたはサーバーにプログラミング環境が設定されている必要があります。プログラミング環境が設定されていない場合は、適切なオペレーティングシステム（Ubuntu、CentOS、Debianなど）用のローカルプログラミング環境またはサーバー上のプログラミング環境のインストールおよびセットアップガイドを参照できます。

なぜloggingモジュールを使用するのですか

loggingモジュールは、プログラム内で発生するイベントの記録を保持し、ソフトウェアのランタイム全体で発生するイベントに関連する出力を見ることができるようにします。

おそらく、コード全体にprint()ステートメントを使用してイベントが発生しているかどうかを確認することにより、より馴染みがあるかもしれません。 print()ステートメントは、コード全体に埋め込まれた場合、実行フローとプログラムの現在の状態を追跡するための基本的な方法を提供しますが、このソリューションはloggingモジュールを使用するよりも保守性に欠けることがいくつかあります：

• デバッグ出力と通常のプログラム出力を区別するのが難しくなります
• コード全体に分散してprint()ステートメントを使用すると、デバッグ出力を提供するものを効率的に無効にする方法がありません
• デバッグが完了した後にすべてのprint()ステートメントを削除するのが難しくなります
• すぐに利用可能な診断情報を含むログレコードがありません

loggingモジュールをコードで使用する習慣を身につけるのは良い考えです。これは、小さなPythonスクリプトを超えて成長するアプリケーションに適しており、デバッグの持続可能なアプローチを提供します。

ログは時間の経過とともに動作とエラーを示すため、アプリケーション開発プロセス全体の状況をよりよく把握できます。

コンソールにデバッグメッセージを出力する

プログラム内で何が起こっているかを確認するためにprint()ステートメントを使用するのに慣れている場合、おそらく次のようなプログラムを見慣れているかもしれません：クラスを定義し、オブジェクトをインスタンス化するプログラムは次のようなものを生成します：

class Pizza():
    def __init__(self, name, price):
        self.name = name
        self.price = price
        print("Pizza created: {} (${})".format(self.name, self.price))

    def make(self, quantity=1):
        print("Made {} {} pizza(s)".format(quantity, self.name))

    def eat(self, quantity=1):
        print("Ate {} pizza(s)".format(quantity, self.name))

pizza_01 = Pizza("artichoke", 15)
pizza_01.make()
pizza_01.eat()

pizza_02 = Pizza("margherita", 12)
pizza_02.make(2)
pizza_02.eat()

上記のコードには、Pizzaクラスのオブジェクトのnameとpriceを定義する__init__メソッドがあります。それに続いて、ピザを作るためのmake()メソッドと、ピザを食べるためのeat()メソッドが2つあります。これらの2つのメソッドは、quantityのパラメータを受け取り、これは1で初期化されています。

さて、プログラムを実行してみましょう：

python pizza.py

次の出力が得られます：

Output
Pizza created: artichoke ($15)
Made 1 artichoke pizza(s)
Ate 1 pizza(s)
Pizza created: margherita ($12)
Made 2 margherita pizza(s)
Ate 1 pizza(s)

print()ステートメントを使用してコードが機能していることを確認できますが、代わりにloggingモジュールを使用して同じことができます。

コード全体からprint()ステートメントを削除またはコメントアウトし、ファイルの先頭にimport loggingを追加しましょう：

import logging


class Pizza():
    def __init__(self, name, value):
        self.name = name
        self.value = value
...

loggingモジュールはDEBUGよりも上のレベルであるWARNINGのデフォルトレベルを持っています。この例ではデバッグにloggingモジュールを使用するため、logging.DEBUGのレベルで情報をコンソールに返すように構成を変更する必要があります。それには、インポートステートメントの下に次の行を追加します：

import logging

logging.basicConfig(level=logging.DEBUG)


class Pizza():
...

このlogging.DEBUGレベルは、閾値を設定するためにコードで参照する定数整数値を指します。DEBUGレベルは10です。

これで、すべてのprint()ステートメントをlogging.debug()ステートメントに置き換えます。定数であるlogging.DEBUGとは異なり、logging.debug()はloggingモジュールのメソッドです。このメソッドを使用する際には、同じstringをprint()に渡したものを使用できます。次に示すように、：

import logging

logging.basicConfig(level=logging.DEBUG)


class Pizza():
    def __init__(self, name, price):
        self.name = name
        self.price = price
        logging.debug("Pizza created: {} (${})".format(self.name, self.price))

    def make(self, quantity=1):
        logging.debug("Made {} {} pizza(s)".format(quantity, self.name))

    def eat(self, quantity=1):
        logging.debug("Ate {} pizza(s)".format(quantity, self.name))

pizza_01 = Pizza("artichoke", 15)
pizza_01.make()
pizza_01.eat()

pizza_02 = Pizza("margherita", 12)
pizza_02.make(2)
pizza_02.eat()

この段階で、python pizza.pyコマンドでプログラムを実行すると、次の出力が得られます：

Output
DEBUG:root:Pizza created: artichoke ($15)
DEBUG:root:Made 1 artichoke pizza(s)
DEBUG:root:Ate 1 pizza(s)
DEBUG:root:Pizza created: margherita ($12)
DEBUG:root:Made 2 margherita pizza(s)
DEBUG:root:Ate 1 pizza(s)

ログメッセージには、Pythonモジュールのレベルを指すDEBUGという深刻度レベルの他に、rootという単語が埋め込まれています。異なる名前を持つロガーの階層を持つloggingモジュールを使用できるため、各モジュールに異なるロガーを使用できます。

例えば、異なる名前と異なる出力を持つ異なるロガーにロガーを設定できます:

logger1 = logging.getLogger("module_1")
logger2 = logging.getLogger("module_2")

logger1.debug("Module 1 debugger")
logger2.debug("Module 2 debugger")

Output
DEBUG:module_1:Module 1 debugger
DEBUG:module_2:Module 2 debugger

今、loggingモジュールを使用してメッセージをコンソールに表示する方法を理解したので、loggingモジュールを使用してメッセージをファイルに出力する方法に移りましょう。

loggingモジュールの主な目的は、メッセージをコンソールではなくファイルに記録することです。メッセージのファイルを保持することで、時間の経過とともにデータを参照し、コードに必要な変更を把握して量化できます。

ファイルにログを記録するには、logging.basicConfig()メソッドを変更してfilenameパラメータを含めることができます。この場合、ファイル名をtest.logと呼びましょう:

import logging

logging.basicConfig(filename="test.log", level=logging.DEBUG)


class Pizza():
    def __init__(self, name, price):
        self.name = name
        self.price = price
        logging.debug("Pizza created: {} (${})".format(self.name, self.price))

    def make(self, quantity=1):
        logging.debug("Made {} {} pizza(s)".format(quantity, self.name))

    def eat(self, quantity=1):
        logging.debug("Ate {} pizza(s)".format(quantity, self.name))

pizza_01 = Pizza("artichoke", 15)
pizza_01.make()
pizza_01.eat()

pizza_02 = Pizza("margherita", 12)
pizza_02.make(2)
pizza_02.eat()

上記のコードは、前のセクションと同じですが、ログの出力先としてファイル名が追加されています。python pizza.pyコマンドでコードを実行すると、ディレクトリにtest.logという新しいファイルが作成されるはずです。

test.logファイルをnano（またはお好みのテキストエディタ）で開きましょう：

nano test.log

ファイルが開くと、次のようなものが表示されます：

DEBUG:root:Pizza created: artichoke ($15)
DEBUG:root:Made 1 artichoke pizza(s)
DEBUG:root:Ate 1 pizza(s)
DEBUG:root:Pizza created: margherita ($12)
DEBUG:root:Made 2 margherita pizza(s)
DEBUG:root:Ate 1 pizza(s)

これは、前のセクションで遭遇したコンソール出力と似ていますが、今回はtest.logファイルにあります。

CTRL + xを押してファイルを閉じ、コードを修正できるようにpizza.pyファイルに戻りましょう。

コードの大部分は同じままにしておきますが、2つのピザインスタンス、pizza_01とpizza_02のパラメータを修正します：

import logging

logging.basicConfig(filename="test.log", level=logging.DEBUG)


class Pizza():
    def __init__(self, name, price):
        self.name = name
        self.price = price
        logging.debug("Pizza created: {} (${})".format(self.name, self.price))

    def make(self, quantity=1):
        logging.debug("Made {} {} pizza(s)".format(quantity, self.name))

    def eat(self, quantity=1):
        logging.debug("Ate {} pizza(s)".format(quantity, self.name))

# pizza_01オブジェクトのパラメータを修正
pizza_01 = Pizza("Sicilian", 18)
pizza_01.make(5)
pizza_01.eat(4)

# pizza_02オブジェクトのパラメータを修正
pizza_02 = Pizza("quattro formaggi", 16)
pizza_02.make(2)
pizza_02.eat(2)

これらの変更を加えたら、python pizza.pyコマンドでプログラムを再実行しましょう。

プログラムが実行されたら、再びnanoでtest.logファイルを開くことができます：

nano test.log

ファイルを確認すると、いくつかの新しい行が追加され、前回プログラムが実行された時の行が保持されていることがわかります：

DEBUG:root:Pizza created: artichoke ($15)
DEBUG:root:Made 1 artichoke pizza(s)
DEBUG:root:Ate 1 pizza(s)
DEBUG:root:Pizza created: margherita ($12)
DEBUG:root:Made 2 margherita pizza(s)
DEBUG:root:Ate 1 pizza(s)
DEBUG:root:Pizza created: Sicilian ($18)
DEBUG:root:Made 5 Sicilian pizza(s)
DEBUG:root:Ate 4 pizza(s)
DEBUG:root:Pizza created: quattro formaggi ($16)
DEBUG:root:Made 2 quattro formaggi pizza(s)
DEBUG:root:Ate 2 pizza(s)

この情報は確かに有用ですが、追加のLogRecord属性を追加してログをより情報豊かにすることができます。主に、LogRecordが作成された時刻を示す人間が読めるタイムスタンプを追加したいと考えています。

属性を追加して、formatというパラメータにその属性を追加できます。属性は、テーブルで示されているように文字列%(asctime)sで参照します。さらに、DEBUGレベル名を保持するには、文字列%(levelname)sを含める必要があり、ロガーが出力するメッセージを保持するには%(message)sを含めます。これらの属性は、追加されたコードに示されているように、colonで区切られます。

import logging

logging.basicConfig(
    filename="test.log",
    level=logging.DEBUG,
    format="%(asctime)s:%(levelname)s:%(message)s"
    )


class Pizza():
    def __init__(self, name, price):
        self.name = name
        self.price = price
        logging.debug("Pizza created: {} (${})".format(self.name, self.price))

    def make(self, quantity=1):
        logging.debug("Made {} {} pizza(s)".format(quantity, self.name))

    def eat(self, quantity=1):
        logging.debug("Ate {} pizza(s)".format(quantity, self.name))

pizza_01 = Pizza("Sicilian", 18)
pizza_01.make(5)
pizza_01.eat(4)

pizza_02 = Pizza("quattro formaggi", 16)
pizza_02.make(2)
pizza_02.eat(2)

上記のコードを追加した状態でpython pizza.pyコマンドを使用してコードを実行すると、test.logファイルに新しい行が追加され、人が読める時刻のタイムスタンプと、DEBUGのレベル名、そしてロガーに渡されたメッセージが文字列として含まれます。

DEBUG:root:Pizza created: Sicilian ($18)
DEBUG:root:Made 5 Sicilian pizza(s)
DEBUG:root:Ate 4 pizza(s)
DEBUG:root:Pizza created: quattro formaggi ($16)
DEBUG:root:Made 2 quattro formaggi pizza(s)
DEBUG:root:Ate 2 pizza(s)
2021-08-19 23:31:34,484:DEBUG:Pizza created: Sicilian ($18)
2021-08-19 23:31:34,484:DEBUG:Made 5 Sicilian pizza(s)
2021-08-19 23:31:34,484:DEBUG:Ate 4 pizza(s)
2021-08-19 23:31:34,484:DEBUG:Pizza created: quattro formaggi ($16)
2021-08-19 23:31:34,484:DEBUG:Made 2 quattro formaggi pizza(s)
2021-08-19 23:31:34,484:DEBUG:Ate 2 pizza(s)

必要に応じて、コード内で追加のLogRecord属性を使用して、プログラムファイルのログを自分に関連付けることができます。

デバッグやその他のメッセージを別々のファイルに記録することで、Pythonプログラムの全体像を時間の経過とともに把握することができ、プログラムに取り組んできた歴史的な作業や発生したイベントやトランザクションによって情報を得て、コードをトラブルシューティングしたり修正したりする機会が得られます。

ログレベルの表

開発者として、ログにキャプチャされたイベントに重要度レベルを割り当てることができます。重要度レベルは以下の表に示されています。

ログレベルは技術的には整数（定数）であり、NOTSETから始まり、数値0でロガーを初期化します。

また、定義済みのレベルに相対的な独自のレベルを定義することもできます。同じ数値を持つレベルを定義すると、その値に関連付けられた名前が上書きされます。

以下の表に、各レベル名、数値、そのレベルを呼び出すために使用できる関数、およびそのレベルの使用方法が示されています。

loggingモジュールはデフォルトでレベルをWARNINGに設定しているため、WARNING、ERROR、CRITICALはすべてデフォルトでログに記録されます。上記の例では、次のコードを使用してDEBUGレベルを含めた構成を変更しました。

logging.basicConfig(level=logging.DEBUG)

デバッガーのコマンドや動作についての詳細は、公式のloggingドキュメントを参照してください。

結論

デバッグは、どんなソフトウェア開発プロジェクトにおいても重要なステップです。 logging モジュールは、標準のPythonライブラリの一部であり、ソフトウェアが実行されている間に発生するイベントを追跡し、これらのイベントを別のログファイルに出力する機能を提供します。これにより、コードが実行される過程で発生するさまざまなイベントを理解することに基づいてコードをデバッグする機会が提供されます。