はじめに
App Service Linux 環境ではコンテナからの標準出力/標準エラーがファイルとしては default_docker.log、診断設定では AppServiceConsoleLogs に出力される。
この記事では AppServiceConsoleLogsに出力される内容を改善して、ログを見やすくする工夫を試みます。
解決したい課題
下記の記事にあるように、AppServiceConsoleLogs では、標準出力は Informational レベル, 標準エラーはError レベルで出力される。
そのため、AppServiceConsoleLogs に対してクエリをする際に、デフォルトの Level フィールドはあまり役に立たない。
お題
以下のようなコードを用意する。
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ワークスペースでログを確認
AppServiceConsoleLogs
| where TimeGenerated >= ago(30m)
| order by TimeGenerated asc
この状態だと、TimeGenerated ≒ ログが保存された時間、ResultDescriptionとしてログ出力メッセージ、Host としてアプリケーションを実行しているインスタンスの情報しか得られません。
また、エラーのスタックトレースも複数レコードに分かれてしまっています。
処理が集中している場合、複数プロセスで動作している場合なども判断に困りそうです。
構造化ログにしてみる
python-json-logger というライブラリがあるようなのでそれを使ってみる。
参考
テストクラスを参考に、目ぼしいフィールドをカスタムフォーマットとして指定
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")
ローカルでの実行時の状況
$ 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ワークスペースでログを確認
先頭の方に見られる Python Blessed Image 利用時に必ず出ちゃうところはしょうがないですが、Python アプリとして出力した部分はJSONでちゃんと入ってそうです。
少し見やすく整形します。
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
見やすくなりました。
補足 1
logger 側でフォーマットを行う分だけ幾ばくかのパフォーマンスのオーバーヘッドが生じる可能性があります。
補足 2
この記事では、Application insights/Azure Monitor 連携していないので、次は以下の OpenTelemetry を試してみようと思います。