Chapter 16. Troubleshooting AMQ Interconnect

You can use the AMQ Interconnect logs to diagnose and troubleshoot error and performance issues with the routers in your router network.

16.1. Viewing log entries

You may need to view log entries to diagnose errors, performance problems, and other important issues. A log entry consists of an optional timestamp, the logging module, the logging level, and the log message.

Procedure

  • Do one of the following:

    • View log entries on the console.

      By default, events are logged to the console, and you can view them there. However, if the output attribute is set for a particular logging module, then you can find those log entries in the specified location (stderr, syslog, or a file).

    • Use the qdstat --log command to view recent log entries.

      You can use the --limit parameter to limit the number of log entries that are displayed. For more information about qdstat, see qdstat man page.

      This example displays the last three log entries for Router.A: 

      $ qdstat --log --limit=3 -r ROUTER.A
Wed Jun  7 17:49:32 2019 ROUTER (none) Core action 'link_deliver'
Wed Jun  7 17:49:32 2019 ROUTER (none) Core action 'send_to'
Wed Jun  7 17:49:32 2019 SERVER (none) [2]:0 -> @flow(19) [next-incoming-id=1, incoming-window=61, next-outgoing-id=0, outgoing-window=2147483647, handle=0, delivery-count=1, link-credit=250, drain=false]
Note

vhost entries are only populated if multiTenant is set to true in the /etc/qpid-dispatch/qdrouterd.conf configuration file.

Additional resources

16.2. Troubleshooting using logs

You can use AMQ Interconnect log entries to help diagnose error and performance issues with the routers in your network.

Example 16.1. Troubleshooting connections and links

In this example, ROUTER logs show the lifecycle of a connection and a link that is associated with it. 

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
1
The connection is opened. Each connection has a unique ID (C1). The log also shows some information about the connection.
2
A link is attached over the connection. The link is identified with a unique ID (L6). The log also shows the direction of the link, and the source and target addresses.
3
The link is detached. The log shows the link’s terminal statistics.
4
The connection is closed.
Note

If necessary, you can use qdmanage to enable protocol-level trace logging for a particular connection. You can use this to trace the AMQP frames. For example: 

$ qdmanage update --type=connection --id=C1 enableProtocolTrace=true

Example 16.2. Troubleshooting the network topology

In this example, on Router.A, the ROUTER_HELLO logs show that it is connected to Router.B, and that Router.B is connected to Router.A and 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'])
1
Router.A received a Hello message from Router.B, which can see Router.A and Router.C.
2
Router.A sent a Hello message to Router.B, which is the only router it can see.

On Router.B, the ROUTER_HELLO log shows the same router topology from a different perspective: 

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
1
Router.B sent a Hello message to Router.A and Router.C.
2
Router.B received a Hello message from Router.A, which can only see Router.B.
3
Router.B received a Hello message from Router.C, which can only see Router.B.

Example 16.3. Tracing the link state between routers

Periodically, each router sends a Link State Request (LSR) to the other routers and receives a Link State Update (LSU) with the requested information. Exchanging the above information, each router can compute the next hops in the topology, and the related costs.

In this example, the ROUTER_LS logs show the RA, LSR, and LSU messages sent between three routers: 

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 sent LSR requests and an RA advertisement to the other routers on the network.
2
Router.A received an LSU from Router.B, which has two peers: Router.A, and Router.C (with a cost of 1).
3
Router.A received an LSR from both Router.B and Router.C, and replied with an LSU.
4
Router.A received an LSU from Router.C, which only has one peer: Router.B (with a cost of 1).
5
After the LSR and LSU messages are exchanged, Router.A computed the router topology with the related costs.

Example 16.4. Tracing the state of mobile addresses attached to a router

In this example, the ROUTER_MA logs show the Mobile Address Request (MAR) and Mobile Address Update (MAU) messages sent between three routers: 

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 sent MAU messages to the other routers in the network to notify them about the addresses added for my_queue and my_queue_wp.
2
Router.A received a MAR message in response from Router.C.
3
Router.A received another MAR message in response from Router.B.
4
Router.C sent a MAU message to notify the other routers that it added and address for my_test.
5
Router.C sent another MAU message to notify the other routers that it deleted the address for my_test (because the receiver is detached).

Example 16.5. Finding information about messages sent and received by a router

In this example, the MESSAGE logs show that Router.A has sent and received some messages related to the Hello protocol, and sent and received some other messages on a link for a mobile address: 

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

Example 16.6. Tracking configuration changes to a router

In this example, the AGENT logs show that on Router.A, address, linkRoute, and autoLink entities were added to the router’s configuration file. When the router was started, the AGENT module applied these changes, and they are now viewable in the log: 

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)

Example 16.7. Troubleshooting policy and vhost access rules

In this example, the POLICY logs show that this router has no limits on maximum connections, and the default application policy is disabled: 

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

Example 16.8. Diagnosing errors

In this example, the ERROR logs show that the router failed to start when an incorrect path was specified for the router’s configuration file: 

$ 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'

Additional resources