Qmonus SDK デバッグのベストプラクティス

本ページではQmonus SDKがフレームワーク側で出力するログの見方について簡単に解説します。

Qmonus SDK logの見方について

ログの構成

ログは改行を含む場合を除き、基本的に以下の構成をとります。

[I 230727 06:18:37 boot:115] {"status":200,"method":"GET","url":"/plugins","remote":"10.98.33.48","elapsed":"10.45ms"}
[(ログレベル) (YYMMDD) (HH:mm:SS) (file名):(行)] (ログ本体)
種類 説明
ログレベル ログの重大度です。D I W E Cのいずれかをとります。
file名 フレームワーク側のファイル名です。
ファイル内においてフレームワーク側で出力されているログの位置を示す行数です。
ログ本体 ログの内容です。

ログの出力方法

詳しくはScenarioにおけるプログラミングを参照ください。

フレームワークが出力するログの種類

フレームワークが出力するログには主に以下のような種類があります。

起動ログ

アプリケーションの起動中に出力される最初

リクエストログ

scenario call ログ

[I 230728 03:40:33 factory:72] 
    #============================#
    #    Native Scenario CALL    #
    #============================#
    POST /v1/sample
    Headers:
    Host: scenario:9000
    Accept: */*
    Accept-Encoding: gzip,deflate
    User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/115.0.0.0 Safari/537.36
    X-Xaas-Auth-Token: npvnt60Y8MRWxjnwSWwhwkqk9xoh9NaKaAo3cjNeNDps+0qokFI7g7qhF0TkwvmH9J45yV+FqGDa88rhrLRacJ8xu8o5c5+n48mui3CuOqm7YLJhF6Ibl1BzdWdqiJ/CXbsW3jbb5IqaOmz4rV3OHQ==
    X-Xaas-Trace-Id: 820066c0-2cf8-11ee-ac96-73d95c090404
    Connection: close
    Content-Length: 2
    Content-Type: application/x-www-form-urlencoded

    Querys:
    {}
    Body:
    {}

scenario call ログ (abortしているtransactionの操作)

abortしているscenarioの処理をリカバリ/キャンセルで復旧させる場合にリクエストされる、拡張ヘッダが付与された状態のリクエストログです。 X-Xaas-Family-KeyX-Xaas-XidX-Xaas-XnameX-Xaas-Scenario-Resume-IndexX-Xaas-Scenario-CancellableX-Xaas-Commandの拡張ヘッダが付与されます。

[I 230728 07:06:45 factory:72] 
    #============================#
    #    Native Scenario CALL    #
    #============================#
    POST /v1/sample
    Headers:
    Host: scenario:9000
    User-Agent: Qmonus/v23.1LTS-patch20230703
    Accept: */*
    Accept-Encoding: gzip,deflate
    Content-Type: application/json; charset=UTF-8
    X-Xaas-Auth-Token: DPMkMdXSSE8yhi2DMqHa/p5RI9HMRsGEr06x5t15HQRtbK6tmOG70luzyyqHeFCjuCEunuG+7RsWj6ljt6isSFimDRjnmPvGAjYMeunNRfMhlC7wdM6cuhRrSaNcsULCp4JkwGe6227kcqfcqo9j2TBMvl06iE99JBBlYpAKM6lGW8BB+GSBgngXtDSF1io17AyvRx4iwebhoyL/woX7LGXmC+xxTj6ZyPT+tlSjNYk=
    X-Xaas-Family-Key: hogehoge
    X-Xaas-Xid: c4852098507111ee842c0a5f0d0b9b25
    X-Xaas-Xname: c4852098507111ee842c0a5f0d0b9b25
    X-Xaas-Scenario-Resume-Index: 1
    X-Xaas-Scenario-Cancellable: follow
    X-Xaas-Command: cancel
    X-Xaas-Qmonus: local
    Connection: close
    Content-Length: 2

    Querys:
    {}
    Body:
    {}

routing ログ

APIGWで表示されるrouting logです。request/reqponse両方のログがそれそれ出力されます。

[I 230728 04:08:22 base:1378] 
    !!
    !! [Accept] POST /v1/sample
    !!
    User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/115.0.0.0 Safari/537.36
    X-Xaas-Auth-Token: npvnt60Y8MRWxjnwSWwhwkqk9xoh9NaKaAo3cjNeNDps+0qokFI7g7qhF0TkwvmH9J45yV+FqGDa88rhrLRacJ8xu8o5c5+n48mui3CuOqm7YLJhF6Ibl1BzdWdqiJ/CXbsW3jbb5IqaOmz4rV3OHQ==
    X-Xaas-Trace-Id: 649b1590-2cfc-11ee-84dc-61a0e36a14ac
    Host: 127.0.0.1:19090
    Connection: keep-alive
    Content-Length: 2

    {}

[I 230728 04:08:22 base:1337] 
    !!!
    !!! POST http://scenario:9000/v1/sample
    !!!
    Code:
    200
    Headers:
    X-Http-Reason: OK
    Server: Qmonus/v23.1LTS-patch20230614
    Content-Type: application/json
    Date: Fri, 28 Jul 2023 04:08:22 GMT
    Connection: close
    Content-Length: 2

    Body:{}

stacktrace ログ

アプリケーション実行中やフレームワークの処理中に送出されるpythonの例外です。

[I 230728 03:41:26 script_runner:7628] Traceback (most recent call last):
      File "/root/axis-stable/axis/hotspot/script_runner.py", line 7625, in run
        return_value = await asyncio.wait_for(G[task], timeout)
      File "/usr/local/lib/python3.10/asyncio/tasks.py", line 445, in wait_for
        return fut.result()
      File "hotspot.scenario.sample[0].code", line 2, in __func_a14dcbee2cf811ee9737e69d03de7df9
    NameError: name 'b' is not defined

[E 230728 03:41:26 script_runner:7631] 
    !!! Script runtime error !!!
      File hotspot.scenario.aaa[0].code, line 0, in __func_a14dcbee2cf811ee9737e69d03de7df9
            a = b
    NameError:name 'b' is not defined

起動バナー

以下のバナーがログ出力されている場合にはアプリケーションの起動に成功しています。

[I 230727 06:18:33 boot:134] 
    #==========================================================================#
    #                                                                          #
    #   Welcome to Qmonus v23.1LTS                                             #
    #   ╔═╗ ┌┬┐┌─┐┌┐┌┬ ┬┌─┐   ╔═╗╔╦╗╦╔═                                        #
    #   ║═╬╗││││ │││││ │└─┐───╚═╗ ║║╠╩╗                                        #
    #   ╚═╝╚┴ ┴└─┘┘└┘└─┘└─┘   ╚═╝═╩╝╩ ╩                                        #
    #                                                                          #
    #   Copyright(C) 2015-2023 NTT Communications, Inc. All rights reserved.   #
    #   Author Shoji Hashimoto                                                 #
    #                                                                          #
    #==========================================================================#

サービスステータスバナー

以下のバナーが出力されている場合にはサービスが提供できる状態になっています。

[I 230727 06:18:33 context:3650] 
    #======================================================#
    #   ╦╔╗╔  ╔═╗┌─┐┬─┐┬  ┬┬┌─┐┌─┐  ┌─┐┌┬┐┌─┐┌┬┐┬ ┬┌─┐     #
    #   ║║║║  ╚═╗├┤ ├┬┘└┐┌┘││  ├┤   └─┐ │ ├─┤ │ │ │└─┐     #
    #   ╩╝╚╝  ╚═╝└─┘┴└─ └┘ ┴└─┘└─┘  └─┘ ┴ ┴ ┴ ┴ └─┘└─┘     #
    #======================================================#
    PID:            16
    MASTER NODE:    redis:6379
    MASTER PROCESS: True

以下のバナーが出力されている場合にはサービスが提供できる状態ではありません。直前のログを確認し、ミドルウェアとの接続が失われていないか等の確認が必要です。

[C 230728 03:21:16 context:3827]
    !=================================================================!
    !   ╔═╗╦ ╦┌┬┐  ┌─┐┌─┐  ╔═╗┌─┐┬─┐┬  ┬┬┌─┐┌─┐  ┌─┐┌┬┐┌─┐┌┬┐┬ ┬┌─┐   !
    !   ║ ║║ ║ │   │ │├┤   ╚═╗├┤ ├┬┘└┐┌┘││  ├┤   └─┐ │ ├─┤ │ │ │└─┐   !
    !   ╚═╝╚═╝ ┴   └─┘└    ╚═╝└─┘┴└─ └┘ ┴└─┘└─┘  └─┘ ┴ ┴ ┴ ┴ └─┘└─┘   !
    !=================================================================!
    PID: 15
    MASTER: None:None

pluginステータスバナー

以下のバナーがログ出力される場合、ユーザー側plugin資材が読み込まれた状態となっています。

[I 230727 06:19:45 installer:464] 
    #=========================================================================================================================#
    #   ╔═╗┌─┐┌┐┌┌─┐┬─┐┌─┐┌┬┐┬ ┬┬  ┌─┐┌┬┐┬┌─┐┌┐┌┌─┐   ╔═╗┬  ┬ ┬┌─┐┬┌┐┌┌─┐  ╦┌┐┌┌─┐┌┬┐┌─┐┬  ┬    ╔═╗╦ ╦╔═╗╔═╗╔═╗╔═╗╔╦╗╔═╗╔╦╗   #
    #   ║  │ │││││ ┬├┬┘├─┤ │ │ ││  ├─┤ │ ││ ││││└─┐   ╠═╝│  │ ││ ┬││││└─┐  ║│││└─┐ │ ├─┤│  │    ╚═╗║ ║║  ║  ║╣ ║╣  ║║║╣  ║║   #
    #   ╚═╝└─┘┘└┘└─┘┴└─┴ ┴ ┴ └─┘┴─┘┴ ┴ ┴ ┴└─┘┘└┘└─┘┘  ╩  ┴─┘└─┘└─┘┴┘└┘└─┘  ╩┘└┘└─┘ ┴ ┴ ┴┴─┘┴─┘  ╚═╝╚═╝╚═╝╚═╝╚═╝╚═╝═╩╝╚═╝═╩╝   #
    #=========================================================================================================================#

pluginのinstallに失敗した場合、以下のバナーがログ出力されます。直前のログを参照し原因を解決してください。

[I 230727 06:19:45 installer:464] 
    !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
    !   ╔═╗┬  ┬ ┬┌─┐┬┌┐┌┌─┐  ╦┌┐┌┌─┐┌┬┐┌─┐┬  ┬    ╔═╗╔═╗╦╦  ╦ ╦╦═╗╔═╗  ╔═╗┌─┐┌─┐┬ ┬┬─┐┬─┐┌─┐┌┬┐   !
    !   ╠═╝│  │ ││ ┬││││└─┐  ║│││└─┐ │ ├─┤│  │    ╠╣ ╠═╣║║  ║ ║╠╦╝║╣   ║ ║│  │  │ │├┬┘├┬┘├┤  ││   !
    !   ╩  ┴─┘└─┘└─┘┴┘└┘└─┘  ╩┘└┘└─┘ ┴ ┴ ┴┴─┘┴─┘  ╚  ╩ ╩╩╩═╝╚═╝╩╚═╚═╝  ╚═╝└─┘└─┘└─┘┴└─┴└─└─┘─┴┘   !
    !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!

初回のplugin installを除くplugin更新が成功した場合は以下のバナーがログ出力されます。

[I 230727 06:19:45 installer:464] 
    $=================================================================$
    $  ╦ ╦┌─┐┌┬┐  ╦ ╦┌─┐┌─┐┬─┐┌─┐┌┬┐┌─┐  ╔═╗┬ ┬┌─┐┌─┐┌─┐┌─┐┌┬┐┌─┐┌┬┐  $
    $  ╠═╣│ │ │   ║ ║├─┘│ ┬├┬┘├─┤ ││├┤   ╚═╗│ ││  │  ├┤ ├┤  ││├┤  ││  $
    $  ╩ ╩└─┘ ┴   ╚═╝┴  └─┘┴└─┴ ┴─┴┘└─┘  ╚═╝└─┘└─┘└─┘└─┘└─┘─┴┘└─┘─┴┘  $
    $=================================================================$