Azure App Service Linux Python のログを見やすくする工夫

# はじめに

App Service Linux 環境ではコンテナからの標準出力/標準エラーがファイルとしては `default_docker.log`、診断設定では `AppServiceConsoleLogs`　に出力される。

https://azure.github.io/jpazpaas/2023/07/27/AppServiceOnLinux-Log.html

この記事では `AppServiceConsoleLogs`に出力される内容を改善して、ログを見やすくする工夫を試みます。

https://learn.microsoft.com/ja-jp/azure/app-service/troubleshoot-diagnostic-logs#supported-log-types

# 解決したい課題

下記の記事にあるように、`AppServiceConsoleLogs` では、標準出力は `Informational` レベル, 標準エラーは`Error` レベルで出力される。

https://azure.github.io/jpazpaas/2024/05/27/Logs-of-python-logging-library-recorded-in-AppServiceConsoleLogs.html

そのため、`AppServiceConsoleLogs` に対してクエリをする際に、デフォルトの `Level` フィールドはあまり役に立たない。

## お題

以下のようなコードを用意する。

```python:app.py
logging.basicConfig(stream=sys.stdout, level=logging.DEBUG)
logger = logging.getLogger("app")

@app.route("/")
def hello_world():
    return "<p>Hello, World!</p>"

# get 2 numbers from requests
# return divided value
logging.basicConfig(stream=sys.stdout, level=logging.DEBUG)
logger = logging.getLogger("app")

@app.route("/")
def hello_world():
    return "<p>Hello, World!</p>"

# get 2 numbers from requests
# return divided value
@app.route("/divide/<a>/<b>")
def divide(a, b):
    logger.debug('first arg = {}'.format(a))
    logger.debug('second arg = {}'.format(b))
    try:
      result = int(a)/int(b)
      logger.debug('{} divided by {} = {}'.format(a, b, result))
    except ZeroDivisionError as zde:
        logger.exception('division by zero error')
        result = 'division by zero error'
    except BaseException as e:
        logger.exception('unexpected error')
        result = 'unexpected error'
    finally:
        return "<p>{}</p>".format(result)


if __name__ == '__main__':
   app.run()
```

# ローカルでの出力内容
```stdout.log
$ python3 app.py
 * Serving Flask app 'app'
 * Debug mode: off
INFO:werkzeug:WARNING: This is a development server. Do not use it in a production deployment. Use a production WSGI server instead.
 * Running on http://127.0.0.1:5000
INFO:werkzeug:Press CTRL+C to quit
DEBUG:app:first arg = 2
DEBUG:app:second arg = 0
ERROR:app:division by zero error
Traceback (most recent call last):
  File "/home/toshida/Projects/sandbox/toshida-linux-python/app.py", line 54, in divide
    result = int(a)/int(b)
ZeroDivisionError: division by zero
INFO:werkzeug:127.0.0.1 - - [10/Jun/2024 15:23:22] "GET /divide/2/0 HTTP/1.1" 200 -
DEBUG:app:first arg = 2
DEBUG:app:second arg = hello
ERROR:app:unexpected error
Traceback (most recent call last):
  File "/home/toshida/Projects/sandbox/toshida-linux-python/app.py", line 54, in divide
    result = int(a)/int(b)
ValueError: invalid literal for int() with base 10: 'hello'
INFO:werkzeug:127.0.0.1 - - [10/Jun/2024 15:23:27] "GET /divide/2/hello HTTP/1.1" 200 -
```

# 初期状態

まずはそのまま App Service にデプロイしてみる。

Log Analyticsワークスペースでログを確認

```sql
AppServiceConsoleLogs 
| where TimeGenerated >= ago(30m)
| order by TimeGenerated asc
```
![image.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/4914/0db21ee6-9785-67e9-210e-85fa921dd257.png)


この状態だと、`TimeGenerated` ≒ ログが保存された時間、`ResultDescription`としてログ出力メッセージ、`Host` としてアプリケーションを実行しているインスタンスの情報しか得られません。
また、エラーのスタックトレースも複数レコードに分かれてしまっています。
処理が集中している場合、複数プロセスで動作している場合なども判断に困りそうです。

# 構造化ログにしてみる

[python-json-logger](https://github.com/madzak/python-json-logger) というライブラリがあるようなのでそれを使ってみる。

参考 

https://qiita.com/sakamossan/items/8e4141e789a2110e037b

テストクラスを参考に、目ぼしいフィールドをカスタムフォーマットとして指定

```app.py
supported_keys = [
            'asctime',
            'created',
            'filename',
            'funcName',
            'levelname',
            'levelno',
            'lineno',
            'module',
            'msecs',
            'message',
            'name',
            'pathname',
            'process',
            'processName',
            'relativeCreated',
            'thread',
            'threadName'
        ]

log_format = lambda x: ['%({0:s})s'.format(i) for i in x]
custom_format = ' '.join(log_format(supported_keys))
formatter = jsonlogger.JsonFormatter(custom_format)
stdoutHandler = logging.StreamHandler(stream=sys.stdout)
stdoutHandler.setLevel(logging.DEBUG)
stdoutHandler.setFormatter(formatter)

logging.basicConfig(handlers=[stdoutHandler], level=logging.DEBUG)
logger = logging.getLogger("app")
```
ローカルでの実行時の状況
```log
$ python3 app.py
 * Serving Flask app 'app'
 * Debug mode: off
{"asctime": "2024-06-10 15:33:49,864", "created": 1718001229.8643, "filename": "_internal.py", "funcName": "_log", "levelname": "INFO", "levelno": 20, "lineno": 97, "module": "_internal", "msecs": 864.0, "message": "\u001b[31m\u001b[1mWARNING: This is a development server. Do not use it in a production deployment. Use a production WSGI server instead.\u001b[0m\n * Running on http://127.0.0.1:5000", "name": "werkzeug", "pathname": "/home/toshida/.local/lib/python3.10/site-packages/werkzeug/_internal.py", "process": 62512, "processName": "MainProcess", "relativeCreated": 108.83021354675293, "thread": 140334408450496, "threadName": "MainThread"}
{"asctime": "2024-06-10 15:33:49,864", "created": 1718001229.8644762, "filename": "_internal.py", "funcName": "_log", "levelname": "INFO", "levelno": 20, "lineno": 97, "module": "_internal", "msecs": 864.0, "message": "\u001b[33mPress CTRL+C to quit\u001b[0m", "name": "werkzeug", "pathname": "/home/toshida/.local/lib/python3.10/site-packages/werkzeug/_internal.py", "process": 62512, "processName": "MainProcess", "relativeCreated": 109.00640487670898, "thread": 140334408450496, "threadName": "MainThread"}
{"asctime": "2024-06-10 15:34:00,694", "created": 1718001240.6949768, "filename": "app.py", "funcName": "divide", "levelname": "DEBUG", "levelno": 10, "lineno": 51, "module": "app", "msecs": 694.0, "message": "first arg = 2", "name": "app", "pathname": "/home/toshida/Projects/sandbox/toshida-linux-python/app.py", "process": 62512, "processName": "MainProcess", "relativeCreated": 10939.507007598877, "thread": 140334388057664, "threadName": "Thread-1 (process_request_thread)"}
{"asctime": "2024-06-10 15:34:00,695", "created": 1718001240.69543, "filename": "app.py", "funcName": "divide", "levelname": "DEBUG", "levelno": 10, "lineno": 52, "module": "app", "msecs": 695.0, "message": "second arg = 1", "name": "app", "pathname": "/home/toshida/Projects/sandbox/toshida-linux-python/app.py", "process": 62512, "processName": "MainProcess", "relativeCreated": 10939.960241317749, "thread": 140334388057664, "threadName": "Thread-1 (process_request_thread)"}
{"asctime": "2024-06-10 15:34:00,695", "created": 1718001240.6958265, "filename": "app.py", "funcName": "divide", "levelname": "DEBUG", "levelno": 10, "lineno": 55, "module": "app", "msecs": 695.0, "message": "2 divided by 1 = 2.0", "name": "app", "pathname": "/home/toshida/Projects/sandbox/toshida-linux-python/app.py", "process": 62512, "processName": "MainProcess", "relativeCreated": 10940.356731414795, "thread": 140334388057664, "threadName": "Thread-1 (process_request_thread)"}
{"asctime": "2024-06-10 15:34:00,696", "created": 1718001240.6969714, "filename": "_internal.py", "funcName": "_log", "levelname": "INFO", "levelno": 20, "lineno": 97, "module": "_internal", "msecs": 696.0, "message": "127.0.0.1 - - [10/Jun/2024 15:34:00] \"GET /divide/2/1 HTTP/1.1\" 200 -", "name": "werkzeug", "pathname": "/home/toshida/.local/lib/python3.10/site-packages/werkzeug/_internal.py", "process": 62512, "processName": "MainProcess", "relativeCreated": 10941.50161743164, "thread": 140334388057664, "threadName": "Thread-1 (process_request_thread)"}
{"asctime": "2024-06-10 15:34:03,573", "created": 1718001243.5735767, "filename": "app.py", "funcName": "divide", "levelname": "DEBUG", "levelno": 10, "lineno": 51, "module": "app", "msecs": 573.0, "message": "first arg = 2", "name": "app", "pathname": "/home/toshida/Projects/sandbox/toshida-linux-python/app.py", "process": 62512, "processName": "MainProcess", "relativeCreated": 13818.106889724731, "thread": 140334379664960, "threadName": "Thread-2 (process_request_thread)"}
{"asctime": "2024-06-10 15:34:03,573", "created": 1718001243.573846, "filename": "app.py", "funcName": "divide", "levelname": "DEBUG", "levelno": 10, "lineno": 52, "module": "app", "msecs": 573.0, "message": "second arg = 0", "name": "app", "pathname": "/home/toshida/Projects/sandbox/toshida-linux-python/app.py", "process": 62512, "processName": "MainProcess", "relativeCreated": 13818.376302719116, "thread": 140334379664960, "threadName": "Thread-2 (process_request_thread)"}
{"asctime": "2024-06-10 15:34:03,573", "created": 1718001243.573957, "filename": "app.py", "funcName": "divide", "levelname": "ERROR", "levelno": 40, "lineno": 57, "module": "app", "msecs": 573.0, "message": "division by zero error", "name": "app", "pathname": "/home/toshida/Projects/sandbox/toshida-linux-python/app.py", "process": 62512, "processName": "MainProcess", "relativeCreated": 13818.487167358398, "thread": 140334379664960, "threadName": "Thread-2 (process_request_thread)", "exc_info": "Traceback (most recent call last):\n  File \"/home/toshida/Projects/sandbox/toshida-linux-python/app.py\", line 54, in divide\n    result = int(a)/int(b)\nZeroDivisionError: division by zero"}
{"asctime": "2024-06-10 15:34:03,574", "created": 1718001243.574396, "filename": "_internal.py", "funcName": "_log", "levelname": "INFO", "levelno": 20, "lineno": 97, "module": "_internal", "msecs": 574.0, "message": "127.0.0.1 - - [10/Jun/2024 15:34:03] \"GET /divide/2/0 HTTP/1.1\" 200 -", "name": "werkzeug", "pathname": "/home/toshida/.local/lib/python3.10/site-packages/werkzeug/_internal.py", "process": 62512, "processName": "MainProcess", "relativeCreated": 13818.926095962524, "thread": 140334379664960, "threadName": "Thread-2 (process_request_thread)"}
{"asctime": "2024-06-10 15:34:06,379", "created": 1718001246.379361, "filename": "app.py", "funcName": "divide", "levelname": "DEBUG", "levelno": 10, "lineno": 51, "module": "app", "msecs": 379.0, "message": "first arg = 2", "name": "app", "pathname": "/home/toshida/Projects/sandbox/toshida-linux-python/app.py", "process": 62512, "processName": "MainProcess", "relativeCreated": 16623.8911151886, "thread": 140334388057664, "threadName": "Thread-3 (process_request_thread)"}
{"asctime": "2024-06-10 15:34:06,379", "created": 1718001246.3797786, "filename": "app.py", "funcName": "divide", "levelname": "DEBUG", "levelno": 10, "lineno": 52, "module": "app", "msecs": 379.0, "message": "second arg = hi", "name": "app", "pathname": "/home/toshida/Projects/sandbox/toshida-linux-python/app.py", "process": 62512, "processName": "MainProcess", "relativeCreated": 16624.308824539185, "thread": 140334388057664, "threadName": "Thread-3 (process_request_thread)"}
{"asctime": "2024-06-10 15:34:06,380", "created": 1718001246.38008, "filename": "app.py", "funcName": "divide", "levelname": "ERROR", "levelno": 40, "lineno": 60, "module": "app", "msecs": 380.0, "message": "unexpected error", "name": "app", "pathname": "/home/toshida/Projects/sandbox/toshida-linux-python/app.py", "process": 62512, "processName": "MainProcess", "relativeCreated": 16624.61018562317, "thread": 140334388057664, "threadName": "Thread-3 (process_request_thread)", "exc_info": "Traceback (most recent call last):\n  File \"/home/toshida/Projects/sandbox/toshida-linux-python/app.py\", line 54, in divide\n    result = int(a)/int(b)\nValueError: invalid literal for int() with base 10: 'hi'"}
{"asctime": "2024-06-10 15:34:06,380", "created": 1718001246.380754, "filename": "_internal.py", "funcName": "_log", "levelname": "INFO", "levelno": 20, "lineno": 97, "module": "_internal", "msecs": 380.0, "message": "127.0.0.1 - - [10/Jun/2024 15:34:06] \"GET /divide/2/hi HTTP/1.1\" 200 -", "name": "werkzeug", "pathname": "/home/toshida/.local/lib/python3.10/site-packages/werkzeug/_internal.py", "process": 62512, "processName": "MainProcess", "relativeCreated": 16625.28419494629, "thread": 140334388057664, "threadName": "Thread-3 (process_request_thread)"}
```

Log Analyticsワークスペースでログを確認

![image.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/4914/ed86b2c1-3140-f82c-a202-ce131a0e40e1.png)

先頭の方に見られる Python Blessed Image 利用時に必ず出ちゃうところはしょうがないですが、Python アプリとして出力した部分はJSONでちゃんと入ってそうです。

少し見やすく整形します。

```sql
AppServiceConsoleLogs
| where TimeGenerated >= ago(30m)
| extend json = parse_json(ResultDescription)
| where isnotempty(json["asctime"])
| extend EventTimeStamp = todatetime(replace_string(tostring(json["asctime"]),",","."))
| project TimeGenerated ,Host, EventTimeStamp, json
| evaluate bag_unpack(json, "python_")
| project-reorder EventTimeStamp,python_levelname,python_process,python_processName,python_module,python_threadName,python_thread,python_name,python_message,python_exc_info,python_filename,python_lineno
| order by EventTimeStamp asc
```

![image.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/4914/6e69f250-88ce-43cb-e18e-c9be59b38feb.png)

見やすくなりました。

# 補足 1

logger 側でフォーマットを行う分だけ幾ばくかのパフォーマンスのオーバーヘッドが生じる可能性があります。

# 補足 2

この記事では、Application insights/Azure Monitor 連携していないので、次は以下の OpenTelemetry を試してみようと思います。

https://learn.microsoft.com/ja-jp/azure/azure-monitor/app/opentelemetry-enable?tabs=python

https://learn.microsoft.com/ja-jp/azure/azure-monitor/app/opencensus-python