Google Git
Sign in
apache / qpid-dispatch / refs/heads/DISPATCH-938 / . / doc / new-book / logging.adoc
blob: 2f929c9eb0ef9868835a57bcdfd7d323151b9820 [file] [log] [blame]
////
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
////
[id='logging']
= Logging
Logging enables you to diagnose error and performance issues with {RouterName}.
{RouterName} consists of internal modules that provide important information about the router. For each module, you can specify logging levels, the format of the log file, and the location to which the logs should be written.
[id='logging-modules-you-can-configure']
== Logging Modules
{RouterName} logs are broken into different categories called _logging modules_. Each module provides important information about a particular aspect of {RouterName}.
=== The `DEFAULT` Logging Module
The default module. This module applies defaults to all of the other logging modules.
=== The `ROUTER` Logging Module
This module provides information and statistics about the local router. This includes how the router connects to other routers in the network, and information about the remote destinations that are directly reachable from the router (link routes, waypoints, autolinks, and so on).
In this example, on `Router.A`, the `ROUTER` log shows that `Router.B` is the next hop. It also shows the cost for `Router.A` to reach the other routers on the network:
[options="nowrap"]
----
Tue Jun 7 13:28:27 2016 ROUTER (trace) Node Router.C next hop set: Router.B
Tue Jun 7 13:28:27 2016 ROUTER (trace) Node Router.C valid origins: []
Tue Jun 7 13:28:27 2016 ROUTER (trace) Node Router.C cost: 2
Tue Jun 7 13:28:27 2016 ROUTER (trace) Node Router.B valid origins: []
Tue Jun 7 13:28:27 2016 ROUTER (trace) Node Router.B cost: 1
----
On `Router.B`, the `ROUTER` log provides more information about valid origins:
[options="nowrap"]
----
Tue Jun 7 13:28:25 2016 ROUTER (trace) Node Router.C cost: 1
Tue Jun 7 13:28:26 2016 ROUTER (trace) Node Router.A created: maskbit=2
Tue Jun 7 13:28:26 2016 ROUTER (trace) Node Router.A link set: link_id=1
Tue Jun 7 13:28:26 2016 ROUTER (trace) Node Router.A valid origins: ['Router.C']
Tue Jun 7 13:28:26 2016 ROUTER (trace) Node Router.A cost: 1
Tue Jun 7 13:28:27 2016 ROUTER (trace) Node Router.C valid origins: ['Router.A']
----
=== The `ROUTER_CORE` Logging Module
This module provides information about the local router's operations on active connections and links. This includes operations related to opened and closed connections, messages sent, deliveries, and flow control.
[options="nowrap"]
----
Tue Jun 7 13:42:07 2016 ROUTER_CORE (trace) Core action 'link_flow'
Tue Jun 7 13:42:08 2016 ROUTER_CORE (trace) Core action 'link_deliver'
Tue Jun 7 13:42:08 2016 ROUTER_CORE (trace) Core action 'send_to'
Tue Jun 7 13:42:08 2016 ROUTER_CORE (trace) Core action 'link_flow'
----
=== The `ROUTER_HELLO` Logging Module
This module provides information about the _Hello_ protocol used by interior routers to exchange Hello messages, which include information about the router's ID and a list of its reachable neighbors (the other routers with which this router has bidirectional connectivity).
The logs for this module are helpful for monitoring or resolving issues in the network topology, and for determining to which other routers a router is connected, and the hop-cost for each of those connections.
In this example, on `Router.A`, the `ROUTER_HELLO` log shows 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`.
=== The `ROUTER_LS` Logging Module
This module provides information about link-state data between routers, including Router Advertisement (RA), Link State Request (LSR), and Link State Update (LSU) messages.
Periodically, each router sends an LSR to the other routers and receives an LSU with the requested information. Exchanging the above information, each router can compute the next hops in the topology, and the related costs.
This example shows 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.
=== The `ROUTER_MA` Logging Module
This module provides information about the exchange of mobile address information between routers, including Mobile Address Request (MAR) and Mobile Address Update (MAU) messages exchanged between routers. You can use this log to monitor the state of mobile addresses attached to each router.
This example shows the MAR and 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).
=== The `MESSAGE` Logging Module
This module provides information about AMQP messages sent and received by the router, including information about the address, body, and link. You can use this log to find high-level information about messages on a particular router.
In this example, `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
----
=== The `SERVER` Logging Module
This module provides information about how the router is listening for and connecting to other containers in the network (such as clients, routers, and brokers). This includes the state of AMQP messages sent and received by the broker (open, begin, attach, transfer, flow, and so on), and the related content of those messages.
For example, this log shows details about how the router handled a link attachment:
[options="nowrap"]
----
Tue Jun 7 14:39:52 2016 SERVER (trace) [2]: <- AMQP
Tue Jun 7 14:39:52 2016 SERVER (trace) [1]: <- AMQP
Tue Jun 7 14:39:52 2016 SERVER (trace) [1]:0 <- @open(16) [container-id="Router.B", max-frame-size=16384, channel-max=32767, idle-time-out=8000, offered-capabilities=:"ANONYMOUS-RELAY", properties={:product="qpid-dispatch-router", :version="0.6.0"}]
Tue Jun 7 14:39:52 2016 SERVER (trace) [1]:0 -> @begin(17) [next-outgoing-id=0, incoming-window=15, outgoing-window=2147483647]
Tue Jun 7 14:39:52 2016 SERVER (trace) [1]:RAW: "\x00\x00\x00\x1e\x02\x00\x00\x00\x00S\x11\xd0\x00\x00\x00\x0e\x00\x00\x00\x04@R\x00R\x0fp\x7f\xff\xff\xff"
Tue Jun 7 14:39:52 2016 SERVER (trace) [1]:1 -> @begin(17) [next-outgoing-id=0, incoming-window=15, outgoing-window=2147483647]
Tue Jun 7 14:39:52 2016 SERVER (trace) [1]:RAW: "\x00\x00\x00\x1e\x02\x00\x00\x01\x00S\x11\xd0\x00\x00\x00\x0e\x00\x00\x00\x04@R\x00R\x0fp\x7f\xff\xff\xff"
Tue Jun 7 14:39:52 2016 SERVER (trace) [1]:0 -> @attach(18) [name="qdlink.uSSeXPSfTHhxo8d", handle=0, role=true, snd-settle-mode=2, rcv-settle-mode=0, source=@source(40) [durable=0, expiry-policy=:"link-detach", timeout=0, dynamic=false, capabilities=:"qd.router"], target=@target(41) [durable=0, expiry-policy=:"link-detach", timeout=0, dynamic=false, capabilities=:"qd.router"], initial-delivery-count=0]
Tue Jun 7 14:39:52 2016 SERVER (trace) [1]:RAW: "\x00\x00\x00\x91\x02\x00\x00\x00\x00S\x12\xd0\x00\x00\x00\x81\x00\x00\x00\x0a\xa1\x16qdlink.uSSeXPSfTHhxo8dR\x00AP\x02P\x00\x00S(\xd0\x00\x00\x00'\x00\x00\x00\x0b@R\x00\xa3\x0blink-detachR\x00B@@@@@\xa3\x09qd.router\x00S)\xd0\x00\x00\x00#\x00\x00\x00\x07@R\x00\xa3\x0blink-detachR\x00B@\xa3\x09qd.router@@R\x00"
----
=== The `AGENT` Logging Module
This module provides information about configuration changes made to the router from either editing the router's configuration file or using `qdmanage`.
In this example, 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(addr=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(addr=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)
----
=== The `CONTAINER` Logging Module
This module provides information about the nodes related to the router. This includes only the AMQP relay node.
[options="nowrap"]
----
Tue Jun 7 14:46:18 2016 CONTAINER (trace) Container Initialized
Tue Jun 7 14:46:18 2016 CONTAINER (trace) Node Type Registered - router
Tue Jun 7 14:46:18 2016 CONTAINER (trace) Node of type 'router' installed as default node
----
=== The `ERROR` Logging Module
This module provides detailed information about error conditions encountered during execution.
In this example, `Router.A` failed to start when an incorrect path was specified for the router's configuration file:
[options="nowrap"]
----
$ sudo qdrouterd --conf xxx
Wed Jun 15 09:53:28 2016 ERROR (error) Python: Exception: Cannot load configuration file xxx: [Errno 2] No such file or directory: 'xxx'
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 xxx: [Errno 2] No such file or directory: 'xxx'
Wed Jun 15 09:53:28 2016 MAIN (critical) Router start-up failed: Python: Exception: Cannot load configuration file xxx: [Errno 2] No such file or directory: 'xxx'
qdrouterd: Python: Exception: Cannot load configuration file xxx: [Errno 2] No such file or directory: 'xxx'
----
=== The `POLICY` Logging Module
This module provides information about policies that have been configured for the router.
In this example, `Router.A` 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
----
[id='configure-default-logging']
== Configuring Logging
You can specify the types of events that should be logged, the format of the log entries, and where those entries should be sent.
.Procedure
. In the router's configuration file, add a `log` section to set the default logging properties:
+
--
[options="nowrap",subs="+quotes"]
----
log {
module: DEFAULT
enable: _LOGGING_LEVEL_
timestamp: yes
...
}
----
`module`:: Specify `DEFAULT`.
`enable`:: The logging level. You can specify any of the following levels (from lowest to highest):
+
//tag::logging-levels[]
* `trace` - provides the most information, but significantly affects system performance
* `debug` - useful for debugging, but affects system performance
* `info` - provides general information without affecting system performance
* `notice` - provides general information, but is less verbose than `info`
* `warning` - provides information about issues you should be aware of, but which are not errors
* `error` - error conditions that you should address
* `critical` - critical system issues that you must address immediately
+
To specify multiple levels, use a comma-separated list. You can also use `+` to specify a level and all levels above it. For example, `trace,debug,warning+` enables trace, debug, warning, error, and critical levels. For default logging, you should typically use the `info+` or `notice+` level. These levels will provide general information, warnings, and errors for all modules without affecting the performance of {RouterName}.
//end::logging-levels[]
`timestamp`:: Set this to `yes` to include the timestamp in all logs.
For information about additional log attributes, see link:{qdrouterdConfManPageUrl}#_log[the `qdrouterd.conf` man page].
--
. Add an additional `log` section for each logging module that should not follow the default logging configuration:
+
--
[options="nowrap",subs="+quotes"]
----
log {
module: _MODULE_NAME_
enable: _LOGGING_LEVEL_
...
}
----
`module`:: The name of the module for which you are configuring logging. For a list of valid modules, see xref:logging-modules-you-can-configure[].
`enable`:: The logging level. You can specify any of the following levels (from lowest to highest):
+
include::logging.adoc[tags=logging-levels]
For information about additional log attributes, see link:{qdrouterdConfManPageUrl}#_log[the `qdrouterd.conf` man page].
--
== 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.
=== Viewing Log Entries on the Console
By default, log entries 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).
=== Viewing Log Entries on the CLI
You can use the `qdstat` tool to view a list of recent log entries.
.Procedure
* 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 {qdstatManPageLink}.
This example displays the last three log entries for `Router.A`:
[options="nowrap",subs="+quotes"]
----
$ qdstat --log --limit=3 -r ROUTER.A
Wed Jun 7 17:49:32 2017 ROUTER_CORE (none) Core action 'link_deliver'
Wed Jun 7 17:49:32 2017 ROUTER_CORE (none) Core action 'send_to'
Wed Jun 7 17:49:32 2017 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]
----
--