docs/books/modules/user-guide/troubleshooting-using-logs.adoc

////
Licensed to the Apache Software Foundation (ASF) under one
or more contributor license agreements.  See the NOTICE file
distributed with this work for additional information
regarding copyright ownership.  The ASF licenses this file
to you under the Apache License, Version 2.0 (the
"License"); you may not use this file except in compliance
with the License.  You may obtain a copy of the License at

  http://www.apache.org/licenses/LICENSE-2.0

Unless required by applicable law or agreed to in writing,
software distributed under the License is distributed on an
"AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
KIND, either express or implied.  See the License for the
specific language governing permissions and limitations
under the License
////

// This module is included in the following assemblies:
//
// troubleshooting.adoc

[id='troubleshooting-using-logs-{context}']
= Troubleshooting using logs

You can use {RouterName} log entries to help diagnose error and performance issues with the routers in your network.

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

[options="nowrap"]
----
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:

[options="nowrap"]
----
$ qdmanage update --type=connection id=C1 enableProtocolTrace=true
----
====

.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`:

[options="nowrap"]
----
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:

[options="nowrap"]
----
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`.
====

.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:

[options="nowrap"]
----
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.
====

.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:

[options="nowrap"]
----
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).
====

.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:

[options="nowrap"]
----
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
----
====

.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:

[options="nowrap"]
----
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)
----
====

.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:

[options="nowrap"]
----
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
----
====

.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:

[options="nowrap"]
----
$ 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

* For more information about logging modules, see xref:logging-modules-{context}[].