16.2. ログを使用したトラブルシューティング
AMQ Interconnect ログエントリーを使用すると、ネットワークのルーターに関するエラーおよびパフォーマンスの問題を診断できます。
例16.1 接続およびリンクのトラブルシューティング
この例では、ROUTER ログには接続のライフサイクルと、それに関連するリンクが表示されます。
2019-04-05 14:54:38.037248 -0400 ROUTER (info) [C1] Connection Opened: dir=in host=127.0.0.1:55440 vhost= encrypted=no auth=no user=anonymous container_id=95e55424-6c0a-4a5c-8848-65a3ea5cc25a props= 1 2019-04-05 14:54:38.038137 -0400 ROUTER (info) [C1][L6] Link attached: dir=in source={<none> expire:sess} target={$management expire:sess} 2 2019-04-05 14:54:38.041103 -0400 ROUTER (info) [C1][L6] Link lost: del=1 presett=0 psdrop=0 acc=1 rej=0 rel=0 mod=0 delay1=0 delay10=0 3 2019-04-05 14:54:38.041154 -0400 ROUTER (info) [C1] Connection Closed 4
注記
必要な場合は qdmanage を使用して特定の接続のプロトコルレベルのトレースロギングを有効にすることができます。これを使用して、AMQP フレームを追跡できます。以下は例になります。
$ qdmanage update --type=connection --id=C1 enableProtocolTrace=true
例16.2 ネットワークトポロジーのトラブルシューティング
この例では、Router.A の ROUTER_HELLO ログは Router.B に接続されており、その Router.B がその Router.A および Router.C に接続されていることを示しています。
Tue Jun 7 13:50:21 2016 ROUTER_HELLO (trace) RCVD: HELLO(id=Router.B area=0 inst=1465307413 seen=['Router.A', 'Router.C']) 1 Tue Jun 7 13:50:21 2016 ROUTER_HELLO (trace) SENT: HELLO(id=Router.A area=0 inst=1465307416 seen=['Router.B']) 2 Tue Jun 7 13:50:22 2016 ROUTER_HELLO (trace) RCVD: HELLO(id=Router.B area=0 inst=1465307413 seen=['Router.A', 'Router.C']) Tue Jun 7 13:50:22 2016 ROUTER_HELLO (trace) SENT: HELLO(id=Router.A area=0 inst=1465307416 seen=['Router.B'])
Router.B では、ROUTER_HELLO ログは、別のパースペクティブからの同じルータートポロジーを表示します。
Tue Jun 7 13:50:18 2016 ROUTER_HELLO (trace) SENT: HELLO(id=Router.B area=0 inst=1465307413 seen=['Router.A', 'Router.C']) 1 Tue Jun 7 13:50:18 2016 ROUTER_HELLO (trace) RCVD: HELLO(id=Router.A area=0 inst=1465307416 seen=['Router.B']) 2 Tue Jun 7 13:50:19 2016 ROUTER_HELLO (trace) RCVD: HELLO(id=Router.C area=0 inst=1465307411 seen=['Router.B']) 3
例16.3 ルーター間のリンク状態のトレース
定期的に、各ルーターは他のルーターに Link State Request (LSR) を送信し、要求された情報で Link State Update (LSU) を受信します。上記の情報を試すことで、各ルーターはトポロジー内の次のホップを計算し、関連するコストを計算できます。
この例では、ROUTER_LS のログは、3 つのルーター間で送信される RA、LSR、および LSU メッセージを表示します。
Tue Jun 7 14:10:02 2016 ROUTER_LS (trace) SENT: LSR(id=Router.A area=0) to: Router.C Tue Jun 7 14:10:02 2016 ROUTER_LS (trace) SENT: LSR(id=Router.A area=0) to: Router.B Tue Jun 7 14:10:02 2016 ROUTER_LS (trace) SENT: RA(id=Router.A area=0 inst=1465308600 ls_seq=1 mobile_seq=1) 1 Tue Jun 7 14:10:02 2016 ROUTER_LS (trace) RCVD: LSU(id=Router.B area=0 inst=1465308595 ls_seq=2 ls=LS(id=Router.B area=0 ls_seq=2 peers={'Router.A': 1L, 'Router.C': 1L})) 2 Tue Jun 7 14:10:02 2016 ROUTER_LS (trace) RCVD: LSR(id=Router.B area=0) Tue Jun 7 14:10:02 2016 ROUTER_LS (trace) SENT: LSU(id=Router.A area=0 inst=1465308600 ls_seq=1 ls=LS(id=Router.A area=0 ls_seq=1 peers={'Router.B': 1})) Tue Jun 7 14:10:02 2016 ROUTER_LS (trace) RCVD: RA(id=Router.C area=0 inst=1465308592 ls_seq=1 mobile_seq=0) Tue Jun 7 14:10:02 2016 ROUTER_LS (trace) SENT: LSR(id=Router.A area=0) to: Router.C Tue Jun 7 14:10:02 2016 ROUTER_LS (trace) RCVD: LSR(id=Router.C area=0) 3 Tue Jun 7 14:10:02 2016 ROUTER_LS (trace) SENT: LSU(id=Router.A area=0 inst=1465308600 ls_seq=1 ls=LS(id=Router.A area=0 ls_seq=1 peers={'Router.B': 1})) Tue Jun 7 14:10:02 2016 ROUTER_LS (trace) RCVD: LSU(id=Router.C area=0 inst=1465308592 ls_seq=1 ls=LS(id=Router.C area=0 ls_seq=1 peers={'Router.B': 1L})) 4 Tue Jun 7 14:10:03 2016 ROUTER_LS (trace) Computed next hops: {'Router.C': 'Router.B', 'Router.B': 'Router.B'} 5 Tue Jun 7 14:10:03 2016 ROUTER_LS (trace) Computed costs: {'Router.C': 2L, 'Router.B': 1} Tue Jun 7 14:10:03 2016 ROUTER_LS (trace) Computed valid origins: {'Router.C': [], 'Router.B': []}
- 1
Router.Aは LSR 要求を送信し、RA アドバータイズメントをネットワーク上の他のルーターに送信します。- 2
Router.AはRouter.Bから LSU を受信しました。これには、Router.A, とRouter.C(1の消費) の 2 つのピアがあります。- 3
Router.AはRouter.BおよびRouter.Cから LSR を受信し、LSU と共に復元します。- 4
Router.AはRouter.Cから LSU を受け取ります。これには、1 つのピアRouter.B(コストは1) のみがあります。- 5
- LSR および LSU メッセージが交換されると、
Router.Aは関連するコストでルータートポロジーを計算します。
例16.4 ルーターに割り当てられたモバイルアドレスの状態の追跡
この例では、ROUTER_MA ログには、3 つのルーター間で送信される Mobile Address Request (MAR) および Mobile Address Update (MAU) メッセージが表示されています。
Tue Jun 7 14:27:20 2016 ROUTER_MA (trace) SENT: MAU(id=Router.A area=0 mobile_seq=1 add=['Cmy_queue', 'Dmy_queue', 'M0my_queue_wp'] del=[]) 1 Tue Jun 7 14:27:21 2016 ROUTER_MA (trace) RCVD: MAR(id=Router.C area=0 have_seq=0) 2 Tue Jun 7 14:27:21 2016 ROUTER_MA (trace) SENT: MAU(id=Router.A area=0 mobile_seq=1 add=['Cmy_queue', 'Dmy_queue', 'M0my_queue_wp'] del=[]) Tue Jun 7 14:27:22 2016 ROUTER_MA (trace) RCVD: MAR(id=Router.B area=0 have_seq=0) 3 Tue Jun 7 14:27:22 2016 ROUTER_MA (trace) SENT: MAU(id=Router.A area=0 mobile_seq=1 add=['Cmy_queue', 'Dmy_queue', 'M0my_queue_wp'] del=[]) Tue Jun 7 14:27:39 2016 ROUTER_MA (trace) RCVD: MAU(id=Router.C area=0 mobile_seq=1 add=['M0my_test'] del=[]) 4 Tue Jun 7 14:27:51 2016 ROUTER_MA (trace) RCVD: MAU(id=Router.C area=0 mobile_seq=2 add=[] del=['M0my_test']) 5
- 1
Router.Aは、my_queueおよびmy_queue_wpに追加されたアドレスについて通知するために、ネットワーク内の他のルーターに MAU メッセージを送信しました。- 2
Router.AはRouter.Cから応答で MAR メッセージを受信しました。- 3
Router.Aは、Router.Bから応答として別の MAR メッセージを受信しました。- 4
Router.Cは MAU メッセージを送信して、my_testの追加およびアドレスを他のルーターに通知します。- 5
Router.Cは別の MAU メッセージを送信し、my_testのアドレスが削除されたことを他のルーターに通知します (受信側はデタッチされます)。
例16.5 ルーターによって送受信されたメッセージに関する情報の検索
以下の例では、MESSAGE ログには Router.A が Hello プロトコルに関連する一部のメッセージが送受信され、モバイルアドレスのリンク上の他のメッセージを送信および受信したことを示しています。
Tue Jun 7 14:36:54 2016 MESSAGE (trace) Sending Message{to='amqp:/_topo/0/Router.B/qdrouter' body='\d1\00\00\00\1b\00\00\00\04\a1\02id\a1\08R'} on link qdlink.p9XmBm19uDqx50R
Tue Jun 7 14:36:54 2016 MESSAGE (trace) Received Message{to='amqp:/_topo/0/Router.A/qdrouter' body='\d1\00\00\00\8e\00\00\00
\a1\06ls_se'} on link qdlink.phMsJOq7YaFsGAG
Tue Jun 7 14:36:54 2016 MESSAGE (trace) Received Message{ body='\d1\00\00\00\10\00\00\00\02\a1\08seque'} on link qdlink.FYHqBX+TtwXZHfV
Tue Jun 7 14:36:54 2016 MESSAGE (trace) Sending Message{ body='\d1\00\00\00\10\00\00\00\02\a1\08seque'} on link qdlink.yU1tnPs5KbMlieM
Tue Jun 7 14:36:54 2016 MESSAGE (trace) Sending Message{to='amqp:/_local/qdhello' body='\d1\00\00\00G\00\00\00\08\a1\04seen\d0'} on link qdlink.p9XmBm19uDqx50R
Tue Jun 7 14:36:54 2016 MESSAGE (trace) Sending Message{to='amqp:/_topo/0/Router.C/qdrouter' body='\d1\00\00\00\1b\00\00\00\04\a1\02id\a1\08R'} on link qdlink.p9XmBm19uDqx50R例16.6 ルーターへの設定変更の追跡
この例では、AGENT ログは Router.A、address、linkRoute、および autoLink エンティティー上がルーターの設定ファイルに追加されていることを示しています。ルーターが起動すると AGENT モジュールがこれらの変更を適用し、それらがログで表示可能になりました。
Tue Jun 7 15:07:32 2016 AGENT (debug) Add entity: ConnectorEntity(addr=127.0.0.1, allowRedirect=True, cost=1, host=127.0.0.1, identity=connector/127.0.0.1:5672:BROKER, idleTimeoutSeconds=16, maxFrameSize=65536, name=BROKER, port=5672, role=route-container, stripAnnotations=both, type=org.apache.qpid.dispatch.connector, verifyHostname=True) Tue Jun 7 15:07:32 2016 AGENT (debug) Add entity: RouterConfigAddressEntity(distribution=closest, identity=router.config.address/0, name=router.config.address/0, prefix=my_address, type=org.apache.qpid.dispatch.router.config.address, waypoint=False) Tue Jun 7 15:07:32 2016 AGENT (debug) Add entity: RouterConfigAddressEntity(distribution=balanced, identity=router.config.address/1, name=router.config.address/1, prefix=my_queue_wp, type=org.apache.qpid.dispatch.router.config.address, waypoint=True) Tue Jun 7 15:07:32 2016 AGENT (debug) Add entity: RouterConfigLinkrouteEntity(connection=BROKER, direction=in, distribution=linkBalanced, identity=router.config.linkRoute/0, name=router.config.linkRoute/0, prefix=my_queue, type=org.apache.qpid.dispatch.router.config.linkRoute) Tue Jun 7 15:07:32 2016 AGENT (debug) Add entity: RouterConfigLinkrouteEntity(connection=BROKER, direction=out, distribution=linkBalanced, identity=router.config.linkRoute/1, name=router.config.linkRoute/1, prefix=my_queue, type=org.apache.qpid.dispatch.router.config.linkRoute) Tue Jun 7 15:07:32 2016 AGENT (debug) Add entity: RouterConfigAutolinkEntity(address=my_queue_wp, connection=BROKER, direction=in, identity=router.config.autoLink/0, name=router.config.autoLink/0, type=org.apache.qpid.dispatch.router.config.autoLink) Tue Jun 7 15:07:32 2016 AGENT (debug) Add entity: RouterConfigAutolinkEntity(address=my_queue_wp, connection=BROKER, direction=out, identity=router.config.autoLink/1, name=router.config.autoLink/1, type=org.apache.qpid.dispatch.router.config.autoLink)
例16.7 ポリシーおよび vhost アクセスルールのトラブルシューティング
以下の例では、POLICY ログにはこのルーターに最大接続に制限がなく、デフォルトのアプリケーションポリシーが無効になっていることが分かります。
Tue Jun 7 15:07:32 2016 POLICY (info) Policy configured maximumConnections: 0, policyFolder: '', access rules enabled: 'false' Tue Jun 7 15:07:32 2016 POLICY (info) Policy fallback defaultApplication is disabled
例16.8 エラーの診断
以下の例では、ERROR ログには、ルーターの設定ファイルに対して正しくないパスが指定されている場合にルーターの開始に失敗することを示しています。
$ qdrouterd --conf my_config
Wed Jun 15 09:53:28 2016 ERROR (error) Python: Exception: Cannot load configuration file my_config: [Errno 2] No such file or directory: 'my_config'
Wed Jun 15 09:53:28 2016 ERROR (error) Traceback (most recent call last):
File "/usr/lib/qpid-dispatch/python/qpid_dispatch_internal/management/config.py", line 155, in configure_dispatch
config = Config(filename)
File "/usr/lib/qpid-dispatch/python/qpid_dispatch_internal/management/config.py", line 41, in __init__
self.load(filename, raw_json)
File "/usr/lib/qpid-dispatch/python/qpid_dispatch_internal/management/config.py", line 123, in load
with open(source) as f:
Exception: Cannot load configuration file my_config: [Errno 2] No such file or directory: 'my_config'
Wed Jun 15 09:53:28 2016 MAIN (critical) Router start-up failed: Python: Exception: Cannot load configuration file my_config: [Errno 2] No such file or directory: 'my_config'
qdrouterd: Python: Exception: Cannot load configuration file my_config: [Errno 2] No such file or directory: 'my_config'関連情報
- ロギングモジュールの詳細は、「ロギングモジュール」 を参照してください。
