Flaskのログ設定(dictConfig)をカスタマイズして特定ロガー名のログ出力やログレベル毎のログの出し分け

# はじめに〜ロギングはロガーオブジェクトを使用する〜

pythonでログ処理を実装しようとするときは[logging](https://docs.python.org/ja/3/howto/logging.html)の[基本チュートリアル](https://docs.python.org/ja/3/howto/logging.html#basic-logging-tutorial)を参考に構築すると思います。


```src/logging/logging_test.py
import logging

def main():
    logging.info("it is logging.")
```

しかし、[この記事](https://qiita.com/amedama/items/b856b2f30c2f38665701)でも指摘されているように、
この方法は不適切です。基本的には[ロガーオブジェクト](https://docs.python.org/ja/3/library/logging.html#logger-objects)を使用することが推奨されています。

```src/logging/logger_test.py
from logging import getLogger
logger = getLogger(__name__)

def main():
    logger.info("it is logger.")
```

# Flaskのログ処理(logging)

一方、Flaskの[ログ処理（Logging）](https://msiz07-flask-docs-ja.readthedocs.io/ja/latest/logging.html)では、以下のような[dictConfig](https://docs.python.org/ja/3/library/logging.config.html#logging.config.dictConfig)による記法が紹介されています。

## 基本設定(Basic Configuration)

```app.py
from flask import Flask
from logging.config import dictConfig
from src.logging import logging_test, logger_test

dictConfig({
    'version': 1,
    'formatters': {'default': {
        'format': '[%(asctime)s] %(levelname)s in %(module)s: %(message)s',
    }},
    'handlers': {'wsgi': {
        'class': 'logging.StreamHandler',
        'stream': 'ext://flask.logging.wsgi_errors_stream',
        'formatter': 'default'
    }},
    'root': {
        'level': 'INFO',
        'handlers': ['wsgi']
    }
})

app = Flask(__name__)

@app.route('/')
def hello_world():
    logging_test.main()
    logger_test.main()
    return 'Hello, World!'

if __name__ == "__main__":
    app.run(debug=True)
```

## 問題点

しかしこうすると、ロガーオブジェクトを設定したログが出力されません。何故？

http://127.0.0.1:5000/

```
[2020-11-12 09:47:05,506] INFO in logging_test: it is logging.
[2020-11-12 09:47:05,506] INFO in _internal: 127.0.0.1 - - [12/Nov/2020 09:47:05] "GET / HTTP/1.1" 200 -
```

これは、上記の記法ではルートロガー以外のロガーが出力されないためです。

## 解決方法 ~loggersの導入~

ルートロガー以外のロガーを[dictConfig](https://docs.python.org/ja/3/library/logging.config.html#logging.config.dictConfig)の`loggers`に追加すると解決できます。

```python
    'loggers': {'src': {}},
```

こうすると`src`ロガーを出力できるようになります。
`logger_test.py`の`__name__`は`src.logging.logger_test`のため、出力されています。

```
[2020-11-12 10:02:17,987] INFO in logging_test: it is logging.
[2020-11-12 10:02:17,987] INFO in logger_test: it is logger.
[2020-11-12 10:02:17,988] INFO in _internal: 127.0.0.1 - - [12/Nov/2020 10:02:17] "GET / HTTP/1.1" 200 -
```

またログを出力するハンドラを個別に指定することもできます。

```python
    'loggers': {'src': {
        'handlers': ['wsgi']
    }},
```

しかしハンドラがルートロガーのハンドラと被っている場合、ログが二重に出力されます。
これはロガーのログが上位(ルート)ロガーに伝播しているためです。
[propagate](https://docs.python.org/ja/3/library/logging.html#logging.Logger.propagate)を`False`に設定することでログの伝播を防止できます。

```python
    'loggers': {'src': {
        'handlers': ['wsgi'],
        'propagate': False
    }},
```

# dictConfigについて

[ロギングの環境設定](https://docs.python.org/ja/3/library/logging.config.html)に記載されているように、`dictConfig`はロギングの環境設定を行いための関数です。
`dictConfig`に渡せる辞書は以下の通りです。

| キー |必須| 意味 |
|:-:|:-:|:-:|
| version  | ○ | スキーマのバージョン。ここは1でOK  |
| formatters  |  | ログのフォーマットを定義  |
| filters  |  | 出力するログなどをフィルタリングする設定  |
| handlers  |  | ログをどこにどう出力するのかといったハンドラの設定  |
| loggers  |  | 各ロガーに対してどのレベルのログをどのハンドラーに出力するのかといったことを定義する  |
| root  |  | ルートロガーの設定。propagateが設定できない点を除けばロガーと基本的に同じ  |

参考：[辞書スキーマの詳細](https://docs.python.org/ja/3/library/logging.config.html#dictionary-schema-details)

各キーが実際にどのように処理されていくのかについてはソースコードの[この辺り](https://github.com/python/cpython/blob/46abfc1416ff8e450999611ef8f231ff871ab133/Lib/logging/config.py#L492)を読むのをお勧めします。

```python
dictConfigClass = DictConfigurator

def dictConfig(config):
    """Configure logging using a dictionary."""
    dictConfigClass(config).configure()
```

## formatters

これはログのフォーマットを設定するスキーマになります。

```python
                formatters = config.get('formatters', EMPTY_DICT)
                for name in formatters:
                    try:
                        formatters[name] = self.configure_formatter(
                                                            formatters[name])
```

内部では[Formatter](https://docs.python.org/ja/3/library/logging.html#logging.Formatter)インスタンスの生成を行っています。

```python
    def configure_formatter(self, config):
        """Configure a formatter from a dictionary."""
        if '()' in config:
            factory = config['()'] # for use in exception handler
            try:
                result = self.configure_custom(config)
            except TypeError as te:
                if "'format'" not in str(te):
                    raise
                config['fmt'] = config.pop('format')
                config['()'] = factory
                result = self.configure_custom(config)
        else:
            fmt = config.get('format', None)
            dfmt = config.get('datefmt', None)
            style = config.get('style', '%')
            cname = config.get('class', None)
            if not cname:
                c = logging.Formatter
            else:
                c = _resolve(cname)
            result = c(fmt, dfmt, style)
        return result
```

以下は`default`フォーマッタの定義です。

```python
    'default': {
        'format': '[%(asctime)s] %(levelname)s in %(module)s:%(lineno)d: %(message)s',
    }
```

`format`ではログの属性を以下の形式で出力すると定義しています。
`[時刻] ログレベル  in モジュール:行番号: メッセージ`

使用できるフォーマットの属性名：[LogRecord 属性](https://docs.python.org/ja/3/library/logging.html#logrecord-attributes)

### カスタムフォーマッタ

[リクエストの情報の注入](https://msiz07-flask-docs-ja.readthedocs.io/ja/latest/logging.html#injecting-request-information)で記載されているフォーマッタのサブクラスを定義することができます。

```python
class RequestFormatter(Formatter):
    def format(self, record):
        if has_request_context():
            record.remote_addr = request.remote_addr
            record.method = request.method
            record.url = request.url
        else:
            record.remote_addr = None
            record.method = None
            record.url = None

        return super().format(record)
```

指定できる属性: [flask.Request](https://tedboy.github.io/flask/generated/generated/flask.Request.html)
ソースコード: [werkzeug/src/werkzeug/wrappers/base_request.py](https://github.com/pallets/werkzeug/blob/6868ede8ba4e1f883952154ba68883efac0021a0/src/werkzeug/wrappers/base_request.py)

以下のように`dictconfig`に記載することで設定完了です。

```python
    'request': {
        '()': RequestFormatter,
        'fmt': '[%(asctime)s] %(remote_addr)s requested %(url)s\n'
               '%(levelname)s in %(module)s: %(message)s'
    }
```

## filters

フィルターはログのフィルターに関する設定を行うことができます。

```python
                filters = config.get('filters', EMPTY_DICT)
                for name in filters:
                    try:
                        filters[name] = self.configure_filter(filters[name])
```

[Filter](https://docs.python.org/ja/3/library/logging.html#logging.Filter) インスタンスを精製しています。

```python
    def configure_filter(self, config):
        """Configure a filter from a dictionary."""
        if '()' in config:
            result = self.configure_custom(config)
        else:
            name = config.get('name', '')
            result = logging.Filter(name)
        return result
```

### カスタムフィルター

指定したログレベル以下のログを出力するフィルターのサブクラスを定義します。

```python
class LogLevelFilter(Filter):
    def __init__(self, level):
        super().__init__()
        self.__level = level

    def filter(self, record):
        return record.levelno <= self.__level
```

参考：[Pythonのロギング標準ライブラリでファイル出力をログレベル毎にする](https://qiita.com/usatosi/items/25e357a3fad6376ebcaf)

以下は`le_info`フィルターの定義です。

```python
    'filters': {
        'le_info': {
            '()': LogLevelFilter,
            'level': logging.INFO
        }
    },
```

`()`でサブクラスを指定します。
`level`引数に制限するログレベルを指定します。
これでINFOレベル以下のログのみ出力するようになります。

これは`filters['le_info']=LogLevelFilter(level=logging.INFO)`と同等です。

## ユーザー定義オブジェクト

カスタムフォーマッタでも記載したように、作成したサブクラスは`()`で指定できます。
`()`をキーに[configure_custom](https://github.com/python/cpython/blob/46abfc1416ff8e450999611ef8f231ff871ab133/Lib/logging/config.py#L466)関数が呼び出されます。

```python
        if '()' in config:
            result = self.configure_custom(config)
```

```python
        c = config.pop('()')
        if not callable(c):
            c = self.resolve(c)
        props = config.pop('.', None)
        # Check for valid identifiers
        kwargs = {k: config[k] for k in config if valid_ident(k)}
        result = c(**kwargs)
```

詳細については[ユーザー定義オブジェクト](https://docs.python.org/ja/3/library/logging.config.html#user-defined-objects)を参照ください。

## handlers

ハンドラでは、ログの出力先に関する設定を行なっています。

```python
                handlers = config.get('handlers', EMPTY_DICT)
                deferred = []
                for name in sorted(handlers):
                    try:
                        handler = self.configure_handler(handlers[name])
                        handler.name = name
                        handlers[name] = handler
```

```python
    def configure_handler(self, config):
        """Configure a handler from a dictionary."""
        config_copy = dict(config)  # for restoring in case of error
        formatter = config.pop('formatter', None)
        if formatter:
            try:
                formatter = self.config['formatters'][formatter]
            except Exception as e:
                raise ValueError('Unable to set formatter '
                                 '%r' % formatter) from e
        level = config.pop('level', None)
        filters = config.pop('filters', None)
        if '()' in config:
            c = config.pop('()')
            if not callable(c):
                c = self.resolve(c)
            factory = c
        else:
            cname = config.pop('class')
            klass = self.resolve(cname)
            #Special case for handler which refers to another handler
            if issubclass(klass, logging.handlers.MemoryHandler) and\
                'target' in config:
                try:
                    th = self.config['handlers'][config['target']]
                    if not isinstance(th, logging.Handler):
                        config.update(config_copy)  # restore for deferred cfg
                        raise TypeError('target not configured yet')
                    config['target'] = th
                except Exception as e:
                    raise ValueError('Unable to set target handler '
                                     '%r' % config['target']) from e
            elif issubclass(klass, logging.handlers.SMTPHandler) and\
                'mailhost' in config:
                config['mailhost'] = self.as_tuple(config['mailhost'])
            elif issubclass(klass, logging.handlers.SysLogHandler) and\
                'address' in config:
                config['address'] = self.as_tuple(config['address'])
            factory = klass
        props = config.pop('.', None)
        kwargs = {k: config[k] for k in config if valid_ident(k)}
        try:
            result = factory(**kwargs)
        except TypeError as te:
            if "'stream'" not in str(te):
                raise
            kwargs['strm'] = kwargs.pop('stream')
            result = factory(**kwargs)
        if formatter:
            result.setFormatter(formatter)
        if level is not None:
            result.setLevel(logging._checkLevel(level))
        if filters:
            self.add_filters(result, filters)
        if props:
            for name, value in props.items():
                setattr(result, name, value)
        return result
```

以下は`wsgi`ハンドラの定義です。

```python
    'wsgi': {
        'class': 'logging.StreamHandler',
        'stream': 'ext://flask.logging.wsgi_errors_stream',
        'formatter': 'default'
    },
```

`class`でハンドラのクラスを指定します。
[StreamHandler](https://docs.python.org/ja/3/library/logging.handlers.html#streamhandler)はストリームに送信するハンドラです。
`stream`で出力先を[flask.logging.wsgi_errors_stream](https://github.com/pallets/flask/blob/024f0d384cf5bb65c76ac59f8ddce464b2dc2ca1/src/flask/logging.py#L10)に指定します。
これは、[WSGI サーバのエラーストリーム](https://docs.pylonsproject.org/projects/pylons-webframework/en/v1.0.1rc1/logging.html#wsgi-errors)または標準エラー出力に出力するストリームです。
フォーマッタは`formatters`で作成した`default`を使用します。

### 出力先を標準出力に

[StreamHandler](https://docs.python.org/ja/3/library/logging.handlers.html#logging.StreamHandler)の出力先を`ext://sys.stdout`にすることで標準出力させることが可能です。

```python
    'console': {
        'class': 'logging.StreamHandler',
        'stream': 'ext://sys.stdout',
        'formatter': 'default'
    },
```

## loggers

こちらは各種ロガーに対する設定を記載する箇所になります。

```python
                loggers = config.get('loggers', EMPTY_DICT)
                for name in loggers:
                    try:
                        self.configure_logger(name, loggers[name], True)
                    except Exception as e:
                        raise ValueError('Unable to configure logger '
                                         '%r' % name) from e
```

```python
    def configure_logger(self, name, config, incremental=False):
        """Configure a non-root logger from a dictionary."""
        logger = logging.getLogger(name)
        self.common_logger_config(logger, config, incremental)
        propagate = config.get('propagate', None)
        if propagate is not None:
            logger.propagate = propagate
```

以下は`src`ロガーの定義です。

```python
    'src': {
        'level': 'INFO',
        'handlers': ['wsgi'],
        'propagate': False
    }
```

ハンドラに`wsgi`を指定しています。
上位のハンドラに伝播させない=ルートロガーへの出力を無効に設定するために、
`propagate`を`False`にしています。


### インポートしたパッケージのログ出力

[Flask-OAuthlib](https://flask-oauthlib.readthedocs.io/en/latest/)をインポートしており、
そのログを出力したい場合は`flask_oauthlib`を`loggers`に追加します。

```python
    'flask_oauthlib': {
        'level': 'DEBUG'
    }
```

[flask-oauthlib/flask_oauthlib/client.py](https://github.com/lepture/flask-oauthlib/blob/f91e92d51a63053895445fde0689b418954012c5/flask_oauthlib/client.py#L28)で設定されているようにロガー名が`flask_oauthlib`なので、ログを出力することができるようになります。

```python
log = logging.getLogger('flask_oauthlib')
```

## root

こちらはルートロガーに対する設定です。

```python
                root = config.get('root', None)
                if root:
                    try:
                        self.configure_root(root, True)
                    except Exception as e:
                        raise ValueError('Unable to configure root '
                                         'logger') from e
```

```python
    def configure_root(self, config, incremental=False):
        """Configure a root logger from a dictionary."""
        root = logging.getLogger()
        self.common_logger_config(root, config, incremental)
```

ルートは最上位のロガーなため、上位ロガーへの伝播の有無を決定する`propagate`がないこと以外はルートロガーと違いはありません。
以下の例の場合は、DEBUGレベル以上のログを`console`と`wsgi`ハンドラに出力しています。

```python
    {
        'level': 'DEBUG',
        'handlers': ['console', 'wsgi']
    }
```

### ログレベル毎に標準出力と標準エラー出力に出し分け

以下は指定したログレベルより上のレベルのログを除外するフィルタークラスです。

```python
class LogLevelFilter(Filter):
    def __init__(self, level):
        super().__init__()
        self.__level = level

    def filter(self, record):
        return record.levelno <= self.__level
```

INFOレベル以下のログのみ取得するフィルターを作成します。

```python
    'filters': {
        'le_filter': {
            '()': LogLevelFilter,
            'level': logging.INFO
        }
    },
```

ハンドラにフィルターを追加することで適用されます。
また標準エラー出力用のハンドラにWARNING以上のログのみを出力するためにログレベルを設定します

```python
    'handlers': {
        'console': {
            'class': 'logging.StreamHandler',
            'stream': 'ext://sys.stdout',
            'formatter': 'default',
            'filters': ['le_filter']
        },
        'wsgi': {
            'class': 'logging.StreamHandler',
            'stream': 'ext://flask.logging.wsgi_errors_stream',
            'level': 'WARNING',
            'formatter': 'default'
        },
    },
    'root': {
        'level': 'DEBUG',
        'handlers': ['console', 'wsgi']
    }
```

これで標準出力にはINFOログレベル以下のログが出力され、標準エラー出力にはWARNINGログレベル以上のログが出力されるようになります。