100日後にエンジニアになるキミ - 52日目 - プログラミング - ログについて

昨日までのはこちら

[100日後にエンジニアになるキミ - 42日目 - クラウド - クラウドサービスについて](https://qiita.com/otupy/items/d1765f1541a104ed6133)

[100日後にエンジニアになるキミ - 36日目 - データベース - データベースについて](https://qiita.com/otupy/items/7af17635d576677606dc)

[100日後にエンジニアになるキミ - 24日目 - Python - Python言語の基礎1](https://qiita.com/otupy/items/6d1e5453f530e07b7aec)

[100日後にエンジニアになるキミ - 18日目 - Javascript - JavaScriptの基礎1](https://qiita.com/otupy/items/2f71d5f9c754b29d9555)

[100日後にエンジニアになるキミ - 14日目 - CSS - CSSの基礎1](https://qiita.com/otupy/items/61a97863f6df14171994)

[100日後にエンジニアになるキミ - 6日目 - HTML - HTMLの基礎1](https://qiita.com/otupy/items/cd2315dcb38671cfded0)


本日はログに関するお話です。

## ロギング(logging)って何？

`ロギング`とはコンピューターやプログラム内で起こった出来事について一定の形式で時系列に記録・蓄積することです。
そのように記録されたデータのことを`log`ログと言います。

ログを出すとかログを取るとか言います。

記録される内容によって呼び名が変わったりします。
例えば

`アクセスログ`サイトに遊びに来た人がの行動を記録したもの
`実行ログ`プログラムの稼働状況を記録したもの
`エラーログ`やらかした時の記録
`ワーニングログ`やらかしそうになった時の記録

データはログファイルとして出力します。
`log`ログ ＋ `ing` で`logging`ロギングです。

プログラムの稼働時は通常プリント文などで出力結果を見ることができますが
何でもかんでも出力してしまうと大量の文字出力に耐えられなくなる時がきます。

そのため、サーバー上で動かすプログラムなどは、稼働に影響を与えないように
ファイルに記録を取るようにし、監視する際はそのログを見て稼働状況をチェックするようにします。

記録を取ってくれるプログラムや、装置のことを
`logger`ロガーとも言っています。

### ログレベル

ログの出力には段階があります。
ログの段階に応じて出力の制御を行うことができます。

Pythonの`logging`でのログレベルは以下のようになっています。

|ログレベル|意味|
|:--:|:--|
| CRITICAL | 致命的なエラー。プログラムの異常終了を伴うようなもの |
| ERROR | エラー。予期しないその他の実行時エラー |
| WARNING | 警告。エラーに近い事象など、実行時に生じた異常とは言い切れないが正常とも異なる何らかの予期しない問題 |
| INFO | 情報。実行時の何らかの注目すべき事象（開始や終了など） |
| DEBUG | デバッグ用の情報。システムの動作状況に関する詳細な情報。 |

### ロギングの例

pythonでは`logging`ライブラリでログの出力を行います。

簡単なログ出力をしてみましょう。
プログラムが置いてある場所の`sample.log`ファイルに出力するように設定します。

```python
import logging

# ロガーの呼び出し
logger = logging.getLogger()

# ハンドラーの追加
handler = logging.FileHandler(filename='log.log', mode='w')

# フォーマッターの追加
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
handler.setFormatter(formatter)

# ロガーにハンドラーを設定
logger.addHandler(handler)
logger.propagate = False

# ログレベルをDebugに設定
logger.setLevel(logging.DEBUG)
```

プログラムの実行時に上記のコードを先に実行させるようにします。
実行を終えたらログ出力ができる状態になっているので
ログを出力したければ次のコードを実行します。

```python
# クリティカルログ出力
logger.critical('critical')
# エラーログ出力
logger.error('error')
# ワーニングログ出力
logger.warning('warning')
# インフォログ出力
logger.info('info')
# デバッグログ出力
logger.debug('Debug')
```
DEBUG:root:Debug


実行した後はログファイルが出来ているはずです。
中身を見てみると、このような形になっています。

```sample.log
2020-05-11 18:29:44,576 - root - CRITICAL - critical
2020-05-11 18:29:44,578 - root - ERROR - error
2020-05-11 18:29:44,579 - root - WARNING - warning
2020-05-11 18:29:44,580 - root - INFO - info
2020-05-11 18:29:44,582 - root - DEBUG - Debug
```
時間と実行者、ログレベルとテキストがログ出力されます。

今度はログレベルをINFOに変えてみます。

```python
# ログレベルをINFOに設定
logger.setLevel(logging.INFO)

# クリティカルログ出力
logger.critical('critical')
# エラーログ出力
logger.error('error')
# ワーニングログ出力
logger.warning('warning')
# インフォログ出力
logger.info('info')
# デバッグログ出力
logger.debug('Debug')
```

```sample.log
2020-05-11 18:31:17,639 - root - CRITICAL - critical
2020-05-11 18:31:17,640 - root - ERROR - error
2020-05-11 18:31:17,642 - root - WARNING - warning
2020-05-11 18:31:17,643 - root - INFO - info
```

DEBUGレベルが出力されなくなりました。

細かなデバッグ出力は本番稼働ではあまり利用しませんので
テスト環境などではログのレベルを下げておき、通常稼働ではログレベルをあげておきます。

`handler = logging.FileHandler(filename='log.log', mode='w')`の部分で
ファイルの書き込みモードを`mode=w`にしていますが、`w`は上書きを表しており
プログラムの稼働毎にファイルが上書きされてしまいます。
追記したい場合はもモードを`mode=a`にします。

### yamlからの読み込み

プログラム内のコード上でログの設定を細かく行うこともできますが
それだとコードも長くなり、細かな設定を書くのも大変だったりします。

`yaml`ファイルの読み込みでログの設定を一括して行うことができます。

```sample.yaml
version: 1
formatters:
  customFormatter:
    format: '%(asctime)s : %(levelname)s : %(module)s : %(message)s'
handlers:
  fileRotatingHandler:
    class: logging.handlers.TimedRotatingFileHandler
    level: DEBUG
    filename: logger.log
    when: MIDNIGHT
    formatter: customFormatter
  consoleHandler:
    class: logging.StreamHandler
    level: DEBUG
    formatter: customFormatter
loggers:
  sample:
    level: DEBUG
    handlers: [fileRotatingHandler, consoleHandler]
    propagate: false
root:
  level: INFO
  handlers: [fileRotatingHandler, consoleHandler]
```

```python

import logging
import logging.config
import yaml

logging.config.dictConfig(yaml.load(open("sample.yaml").read()))
# create logger
logger = logging.getLogger('simpleExample')
# 'application' code
logger.debug('debug message')
logger.info('info message')
logger.warn('warn message')
logger.error('error message')
logger.critical('critical message')
```

INFOレベル以上がlogger.logに出力されます。

```logger.log
2020-05-11 18:48:24,469 : INFO : <ipython-input-37-2c5d2acee7c2> : info message
2020-05-11 18:48:24,470 : WARNING : <ipython-input-37-2c5d2acee7c2> : warn message
2020-05-11 18:48:24,470 : ERROR : <ipython-input-37-2c5d2acee7c2> : error message
2020-05-11 18:48:24,471 : CRITICAL : <ipython-input-37-2c5d2acee7c2> : critical message
```

### ログの分割

大規模なアプリケーションを作成するときは1つのログに納めずに
ファイルサイズや時間でファイルを分割するように設定します。

`RotatingFileHandler`などでファイルサイズに応じた分割ができます。
`logging.handlers.RotatingFileHandler(ログファイル, maxBytes=100000, backupCount=10)`

`TimedRotatingFileHandler`で時間分割が行えます。
`logging.handlers.TimedRotatingFileHandler(ログファイル,when='S',interval=10,backupCount=5,)`

### ファイルの分割

ログも1種類のログ出力ではなく、用途に応じたログ出力を行います。

`logger`に使用している変数などがかぶると同じファイルに出力してしまうので
適宜変更して設定します。

```python
error_logger = ...
excute_logger = ...
```


## まとめ

ログ出力は大規模なアプリケーション開発では必須になります。
現場毎でログ出力の方針が異なると思いますので
ここでは基本的な出力方法を押さえておきましょう。

君がエンジニアになるまであと48日

## 作者の情報
乙pyのHP：
http://www.otupy.net/

Youtube：
https://www.youtube.com/channel/UCaT7xpeq8n1G_HcJKKSOXMw

Twitter：
https://twitter.com/otupython