about_logging.ipynb

{
 "cells": [
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "<a href=\"https://speakerdeck.com/pistatium/sutukirifen-karu-python-falserogu\"><img src=\"https://github.com/pistatium/about_python_logging/blob/master/etc/slide_thumb.png?raw=true\" width=300></a>\n",
    "\n",
    "\n",
    "# すっきり分かる Python のログ\n",
    "\n",
    "Python のロガー周りを理解するための資料です。\n",
    "\n",
    "\n",
    "## Loggerを使う"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "metadata": {},
   "outputs": [],
   "source": [
    "from logging import getLogger\n",
    "\n",
    "# Setup logger\n",
    "logger = getLogger(__name__)"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "python の Logger はこうやって初期化するのが一般的です。\n",
    "あとで解説するので `__name__` とかはおまじないだと思ってください。  \n",
    "\n",
    "早速このloggerを使ってみましょう。"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "metadata": {},
   "outputs": [],
   "source": [
    "from logging import getLogger\n",
    "\n",
    "logger = getLogger(__name__)\n",
    "\n",
    "def main():\n",
    "    logger.debug('This is a Debug message')\n",
    "    logger.info('This is a Info message')\n",
    "    logger.warning('This is a Warning message')\n",
    "    logger.error('This is a Error message')\n",
    "    logger.critical('This is a Critical message')\n",
    "    \n",
    "if __name__ == '__main__':\n",
    "    main()"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "他の言語にもあるように Python でも `debug` `info` `warning` `error` `critical` の5種類のログレベルが使用できます。\n",
    "特に難しいことはないですね。\n",
    "\n",
    "実行結果も見てみましょう。\n",
    "\n",
    ">This is a Warning message  \n",
    ">This is a Error message  \n",
    ">This is a Critical message\n",
    "\n",
    "あれ`debug`,` info` はどこへ…。"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "metadata": {},
   "outputs": [],
   "source": [
    "from logging import getLogger, DEBUG\n",
    "\n",
    "logger = getLogger(__name__)\n",
    "\n",
    "# これかな?\n",
    "logger.setLevel(DEBUG)\n",
    "\n",
    "\n",
    "def main():\n",
    "    logger.debug('This is a Debug message')\n",
    "    logger.info('This is a Info message')\n",
    "    logger.warning('This is a Warning message')\n",
    "    logger.error('This is a Error message')\n",
    "    logger.critical('This is a Critical message')\n",
    "    \n",
    "if __name__ == '__main__':\n",
    "    main()"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "`logger` には `setLevel` という、どのレベル以上のものを表示するかという設定があります。\n",
    "これで `info` や `debug` が無視されていたに違いないので、早速 `DEBUG` 以上をセットしてみましょう。\n",
    "\n",
    ">This is a Warning message  \n",
    ">This is a Error message  \n",
    ">This is a Critical message\n",
    "\n",
    "ぐぬぬ…"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "metadata": {},
   "outputs": [],
   "source": [
    "import sys\n",
    "from logging import getLogger, DEBUG, StreamHandler\n",
    "\n",
    "logger = getLogger(__name__)\n",
    "logger.setLevel(DEBUG)\n",
    "\n",
    "#  これも？\n",
    "handler = StreamHandler(sys.stderr)\n",
    "handler.setLevel(DEBUG)\n",
    "logger.addHandler(handler)\n",
    "\n",
    "\n",
    "def main():\n",
    "    logger.debug('This is a Debug message')\n",
    "    logger.info('This is a Info message')\n",
    "    logger.warning('This is a Warning message')\n",
    "    logger.error('This is a Error message')\n",
    "    logger.critical('This is a Critical message')\n",
    "    \n",
    "if __name__ == '__main__':\n",
    "    main()"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "Python の Logger には Handler という概念があります。\n",
    "Handler というのは書き込まれたログをどう扱うかを決めるためのものです。\n",
    "デフォルトだと標準エラー出力にログが表示されるだけですが、これをカスタマイズすることで、ファイルに書き込むようにしたり、出力のフォーマットや要素を好きなように変更することが出来ます。\n",
    "この Handler も ログレベルのしきい値を持っているので、こっちのレベルも変更してみましょう。\n",
    "\n",
    ">This is a Debug message  \n",
    ">This is a Info message  \n",
    ">This is a Warning message  \n",
    ">This is a Error message  \n",
    ">This is a Critical message  \n",
    "\n",
    "👏  \n",
    "無事全部のログが出せましたね。"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "## Logger について"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "metadata": {},
   "outputs": [],
   "source": [
    "logger = getLogger(__name__)"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "とは一体何なのか\n",
    "\n",
    "\n",
    "まず引数の中身から。\n",
    "\n",
    "`__name__`\n",
    "\n",
    "この Python 組み込みの変数には現在のモジュール名が入っています。\n",
    "\n",
    "```\n",
    "* myapp/\n",
    "     * __init__.py\n",
    "     * views.py\n",
    "     * models/\n",
    "          * __init__.py\n",
    "          * items.py\n",
    "```\n",
    "\n",
    "みたいなパッケージ構成の場合、 \n",
    "\n",
    "* `myapp/views.py` での `__name__` は `myapp.views`\n",
    "* `myapp/models/items.py` での `__name__` は `myapp.models.items`\n",
    "\n",
    "のようになります。\n",
    "\n",
    "(但し `if __name__ == '__main__':` のイディオムからも分かるように、対象のファイルを直接実行した場合は、モジュール名ではなく `__main__` という固定値が入るようになっています。今回はややこしくなるので、モジュール名が常に入っているものとして進めさせてください。)\n",
    "\n",
    "つまり getLogger の1文は、 `logger = getLogger('myapp.views')`  のようにモジュール名を入れて呼び出している事と等価です。\n",
    "実はこの引数、文字列であればなんでもよかったりします。ロガーに名前をつけてるだけですね。\n",
    "\n",
    "\n",
    "### なぜ __name__ で呼び出すか \n",
    "では、なぜ慣例的に `logger = getLogger(__name__)` のように呼び出すかというと、2つのメリットがあるからです。\n",
    "\n",
    "1つ目はシンプルで直感的だからという点です。利用する際は毎回この定型文を挿入してあげるだけですし、正しくファイルを分割していれば、それがそのまま適切なロガー名になります。ログからどのファイルでエラーが発生したかも簡単に辿ることができます。他のパッケージのログと混同することもありません。\n",
    "\n",
    "2つ目の理由は、**ロガーが階層関係を持てる** という点です。ロガーの名前をドットで区切るとそれが階層になります。なので、`myapp.views` と `myapp.models.items` の2つのロガーは共通の `myapp` というロガーを親に持っています。また名前無しで初期化したロガーはルートロガーと呼ばれ、全てのロガーの親となります。\n",
    "\n",
    "```\n",
    "* (ルート)\n",
    "    * myapp\n",
    "        * views\n",
    "        * models\n",
    "            * items\n",
    "```\n",
    "\n",
    "上のパッケージ構成でそれぞれが `__name__` で初期化したロガーをもつ場合、こんな感じの階層が自動的に出来上がります。\n",
    "\n",
    "この階層関係、何が嬉しいのかというと Handler で扱う時に非常に便利になります。\n",
    "自然にパッケージごとにロガーがグループ分けされますし、後述する Handler の機能を利用すればログの出し分けも自在にできるようになります。\n",
    "基本のログは標準出力に吐き出すけど、このパッケージの Error 以上のログはファイルに書き出すみたいなことも可能です。"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "## Handler について\n",
    "\n",
    "Handler の仕事は、渡ってきたログを適切に処理することです。ログを受取り、必要に応じてフィルターし、指定されたログ出力先に指定されたフォーマットで書き込みます。\n",
    "\n",
    "代表的な Handler は 標準出力などのストリームに書き込む `StreamHandler` と、ファイルに書き込む `FileHandler` です。その他にも `NullHandler` `SocketHandler` `SMTPHandler` などなどあります。\n",
    "\n",
    "HandlerがどのようにLogを処理するかはこの図をみると分かりやすいです。\n",
    "\n",
    "<img src='https://docs.python.jp/3/_images/logging_flow.png'>\n",
    "([Logging HOWTO - Python 3.6.3 ドキュメント](https://docs.python.jp/3/howto/logging.html#useful-handlers)より)\n",
    "\n",
    "この図のポイントは 左側の \"Set current logger to parent\" という部分ですね。 \n",
    "\n",
    "Logger は階層関係になっていると言いましたが、この部分で再帰的に親の Handler を呼び出しています。なので `myapp.models` 以下のエラーをファイルに書き込み、かつ `myapp` 以下のエラーを標準出力に流したい場合は、 `myapp.models` に `FileHandler` を、 `myapp` に `StreamHandler` を設定してあげれば実現可能です。\n",
    "\n",
    "また Loggerは `propagate`(伝播) という属性を持っていて、これを `False` にセットすれば親のログをたどることを止めることが出来ます。上の例で言うと、 `myapp.models` のログをファイルだけの書き込みだけに制限できます。\n",
    "\n",
    "### Formatter\n",
    "Handler には ログをどう出力するかという Formatter を指定できます。Handler ごとに持っているので、出力先に応じた適切なフォーマットでログを返せます。\n",
    "https://docs.python.jp/3/library/logging.html#logrecord-attributes\n",
    "使える変数はこちら。"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "## スッキリ書く\n"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 6,
   "metadata": {},
   "outputs": [],
   "source": [
    "import sys\n",
    "from logging import getLogger, DEBUG, ERROR, StreamHandler, FileHandler, NullHandler, Formatter\n",
    "\n",
    "# フォーマッターを定義\n",
    "simple_formatter = Formatter('%(asctime)s: %(message)s')\n",
    "\n",
    "# 標準エラー出力に出すためのハンドラを定義\n",
    "console_handler = StreamHandler(sys.stderr)\n",
    "console_handler.setLevel(ERROR)\n",
    "console_handler.setFormatter(simple_formatter)\n",
    "\n",
    "# 自作アプリ用に全てのログをファイルに書き出すようハンドラを定義\n",
    "myapp_file_handler = FileHandler('myapp.log')\n",
    "myapp_file_handler.setLevel(DEBUG)\n",
    "\n",
    "# ルートロガーにセット\n",
    "root_logger = getLogger()\n",
    "root_logger.addHandler(console_handler)\n",
    "\n",
    "# 自作アプリのパッケージのロガーにセット\n",
    "myapp_logger = getLogger('myapp')\n",
    "myapp_logger.setLevel(DEBUG)\n",
    "myapp_logger.addHandler(myapp_file_handler)\n",
    "\n",
    "# hoge パッケージのログは全て出さない\n",
    "hoge_handler = getLogger('hoge')\n",
    "hoge_handler.addHandler(NullHandler)\n",
    "hoge_handler.propergate = False"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "ログの設定を書き連ねると結構長くなってしまいます。\n",
    "\n",
    "ログはエントリポイントなど最初の方で設定してあげる必要があるので、これらをコードで挿入すると見通しが悪くなってしまいます。\n",
    "別ファイルにコードをまとめて import する方法もありますが、もうちょっとスマートなやり方があります。\n",
    "\n",
    "### 設定ファイルでログの設定をする\n",
    "\n",
    "```\n",
    "{\n",
    "    \"version\": 1,\n",
    "    \"formatters\": {\n",
    "        \"simple\": {\n",
    "            \"format\": \"%(asctime)s: %(message)s\"\n",
    "        }\n",
    "    },\n",
    "    \"handlers\": {\n",
    "        \"console\": {\n",
    "            \"class\": \"logging.StreamHandler\",\n",
    "            \"level\": \"ERROR\",\n",
    "            \"formatter\": \"simple\",\n",
    "            \"stream\": \"ext://sys.stderr\"\n",
    "        },\n",
    "        \"myapp_file\": {\n",
    "            \"class\": \"logging.FileHandler\",\n",
    "            \"level\": \"DEBUG\",\n",
    "            \"filename\": \"myapp.log\"\n",
    "        },\n",
    "        \"blackhole\": {\n",
    "            \"class\": \"logging.NullHandler\"\n",
    "        }\n",
    "    },\n",
    "    \"loggers\": {\n",
    "        \"myapp\": {\n",
    "            \"level\": \"DEBUG\",\n",
    "            \"handlers\": [\n",
    "                \"myapp_file\"\n",
    "            ]\n",
    "        },\n",
    "        \"hoge\": {\n",
    "            \"handlers\": [\n",
    "                \"blackhole\"\n",
    "            ],\n",
    "            \"propagate\": false\n",
    "        }\n",
    "    },\n",
    "    \"root\": {\n",
    "        \"handlers\": [\n",
    "            \"console\"\n",
    "        ]\n",
    "    }\n",
    "}\n",
    " ```\n",
    " \n",
    " このような JSON ファイルを用意して、"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 1,
   "metadata": {},
   "outputs": [],
   "source": [
    "import json\n",
    "from logging.config import dictConfig\n",
    "\n",
    "# 設定ファイルから読み込む\n",
    "with open('logging.json') as f:\n",
    "    dictConfig(json.load(f))"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "のようにすれば上の Python のコードと同じ設定が可能です。(ルートのロガーだけ、`loggers` の外で定義している点に注意してください)\n",
    "\n",
    "JSON だと改行や綴じカッコの分長くなってしまいますが、コードと設定を分離するという意味ではこちらの形式を利用したほうが好ましいです。\n",
    "\n",
    "ちなみに dictConfig の引数は Python の辞書オブジェクトなので、JSON以外の形式でも定義可能です。\n",
    "公式ドキュメントでは YAML の例が使われていますね。 Python のようにインデントで制御しているので、かなり簡潔に書く事ができます。\n",
    "ただ YAML のパーサーは Python 標準で付属していないため、 pip 等からインストールする必要があります。\n",
    "\n",
    "`fileConfig` という confファイル形式で定義する方法も用意されていますが、dictConfig の方が新しく細かい設定も出来るため、こちらのほうが推奨されているみたいです。"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 10,
   "metadata": {},
   "outputs": [
    {
     "name": "stderr",
     "output_type": "stream",
     "text": [
      "2017-10-25 15:29:39,322: RootLogger: error\n",
      "2017-10-25 15:29:39,324: myapp: error\n"
     ]
    }
   ],
   "source": [
    "import json\n",
    "from logging.config import dictConfig\n",
    "\n",
    "with open('logging.json') as f:\n",
    "    dictConfig(json.load(f))\n",
    "\n",
    "\n",
    "# 動作確認\n",
    "from logging import getLogger\n",
    "\n",
    "# RootLogger: error のみが標準エラーに\n",
    "root_logger = getLogger()\n",
    "root_logger.debug('RootLogger: debug')\n",
    "root_logger.error('RootLogger: error')\n",
    "\n",
    "# myapp: debug は指定したファイルに\n",
    "# myapp: error は指定したファイルと標準エラーに\n",
    "myapp_logger = getLogger('myapp.test')\n",
    "myapp_logger.debug('myapp: debug')\n",
    "myapp_logger.error('myapp: error')\n",
    "\n",
    "# これはすべて無視される\n",
    "hoge_logger = getLogger('hoge.fuga.piyo')\n",
    "hoge_logger.debug('hoge: debug')\n",
    "hoge_logger.error('hoge: error')"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "最後に動作確認例を載せておきます。\n",
    "\n",
    "この挙動を理解できれば思い通りのログ処理ができるようになるのではないでしょうか。\n",
    "\n",
    "\n",
    "\n",
    "# 参考\n",
    "\n",
    " Logging HOWTO - Python3 公式ドキュメント\n",
    "https://docs.python.jp/3/howto/logging.html  \n",
    "\n",
    " \n",
    "ログ出力のための print と import logging はやめてほしい - Qiita\n",
    "https://qiita.com/amedama/items/b856b2f30c2f38665701 "
   ]
  }
 ],
 "metadata": {
  "kernelspec": {
   "display_name": "Python 3",
   "language": "python",
   "name": "python3"
  },
  "language_info": {
   "codemirror_mode": {
    "name": "ipython",
    "version": 3
   },
   "file_extension": ".py",
   "mimetype": "text/x-python",
   "name": "python",
   "nbconvert_exporter": "python",
   "pygments_lexer": "ipython3",
   "version": "3.6.3"
  }
 },
 "nbformat": 4,
 "nbformat_minor": 2
}