Skip to content

Commit b1a3b3b

Browse files
Alexandre Dutraolim7t
authored andcommitted
Documenting logging in general and QueryLogger in particular
1 parent 11718b1 commit b1a3b3b

2 files changed

Lines changed: 305 additions & 0 deletions

File tree

.gitignore

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -5,6 +5,7 @@ testing/
55
.classpath
66
.project
77
doc
8+
docs
89
notes
910
.DS_Store
1011

features/logging/README.md

Lines changed: 304 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,304 @@
1+
## Logging
2+
3+
### Setup
4+
5+
DataStax Java driver uses the popular [SLF4J](http://www.slf4j.org) library to emit log messages;
6+
SLF4J has the advantage of providing a logging API that is entirely decoupled from concrete
7+
implementations, letting client applications free to seamlessly connect SLF4J to their preferred logging backend.
8+
9+
The driver itself does not attempt to configure any concrete logging framework.
10+
It is up to client applications using the driver to correctly set up their classpath and
11+
runtime configuration to be able to capture log messages emitted by the driver.
12+
Concretely, client applications need to provide, at runtime, a *binding* to any logging framework
13+
of their choice that is [compatible with SLF4J](http://www.slf4j.org/manual.html#swapping).
14+
15+
If your application is built with Maven, this usually involves adding one (runtime) dependency to your POM file.
16+
For example, if you intend to use [Logback](http://logback.qos.ch), add the following dependency:
17+
18+
```xml
19+
<dependency>
20+
<groupId>ch.qos.logback</groupId>
21+
<artifactId>logback-classic</artifactId>
22+
<version>1.1.3</version>
23+
</dependency>
24+
```
25+
26+
If you are using Log4J 1.2 instead, add the following dependency:
27+
28+
```xml
29+
<dependency>
30+
<groupId>org.slf4j</groupId>
31+
<artifactId>slf4j-log4j12</artifactId>
32+
<version>1.7.12</version>
33+
</dependency>
34+
```
35+
36+
Check [SLF4J's documentation](http://www.slf4j.org/manual.html#projectDep) for examples for
37+
other logging frameworks, and for troubleshooting dependency resolution problems.
38+
39+
### Configuration
40+
41+
Each logging framework has its own configuration rules, but all of them provide
42+
different levels (DEBUG, INFO, WARN, ERROR...), different *loggers* or *categories*
43+
(messages from different categories or loggers can be filtered out separately or printed out
44+
differently), and different *appenders* (message receptacles such as the standard console,
45+
the error console, a file on disk, a socket...).
46+
47+
Check your logging framework documentation for more information about how to properly configure it.
48+
You can also find some configuration examples below.
49+
50+
### Useful loggers
51+
52+
When debugging the Java driver, the following loggers could be particularly useful
53+
and provide hints about what's going wrong.
54+
55+
* `com.datastax.driver.core.Cluster`
56+
* ERROR
57+
* Authentication errors
58+
* Unexpected errors when handling events, reconnecting, refreshing schemas
59+
* Unexpected events
60+
* WARN
61+
* Cluster name mismatches
62+
* Unreachable contact points
63+
* Unsupported protocol versions
64+
* Schema disagreements
65+
* Ignored notifications due to high contention
66+
* INFO
67+
* Hosts added or removed
68+
* DEBUG
69+
* Cluster lifecycle (start, shutdown)
70+
* Event delivery notifications (schema changes, topology changes)
71+
* Topology change events: hosts Up / Down / Added / Removed
72+
* Hosts being ignored
73+
* Protocol version negotiation
74+
* Reconnection attempts
75+
* Schema metadata refreshes
76+
* TRACE
77+
* Connection pools lifecycle (create, renew, refresh)
78+
* `com.datastax.driver.core.Session`
79+
* ERROR
80+
* Errors related to connection pools
81+
* WARN
82+
* Problems related to connection pools
83+
* DEBUG
84+
* Connection pools lifecycle (create, renew, refresh)
85+
* `com.datastax.driver.core.RequestHandler`
86+
* ERROR
87+
* Unexpected errors preparing queries
88+
* Queries sent to a bootstrapping host
89+
* Unexpected server errors
90+
* WARN
91+
* Queries sent to an overloaded host
92+
* INFO
93+
* Unprepared queries
94+
* DEBUG
95+
* Retry attempts
96+
* TRACE
97+
* Host currently being queried
98+
* `com.datastax.driver.core.Connection`
99+
* WARN
100+
* Problem setting keyspace
101+
* Errors closing Netty channel
102+
* DEBUG
103+
* Connection lifecycle (open, close, defunct)
104+
* Error connecting or writing requests
105+
* Heartbeats
106+
* TRACE
107+
* Authentication progress
108+
* Sending requests
109+
* Receiving responses
110+
111+
### Logging query latencies
112+
113+
Version 2.0.10 of the driver introduces a new feature: the `QueryLogger`.
114+
115+
This new API provides clients with the ability to log queries executed by the driver,
116+
and especially, it allows client to track slow queries, i.e. queries that take longer to
117+
complete than a configured threshold in milliseconds.
118+
119+
To turn on this feature, you first need to instantiate and register a `QueryLogger` instance:
120+
121+
```java
122+
Cluster cluster = ...
123+
QueryLogger queryLogger = QueryLogger.builder(cluster)
124+
.withConstantThreshold(...)
125+
.withMaxQueryStringLength(...)
126+
.build();
127+
cluster.register(queryLogger);
128+
```
129+
130+
Note that `QueryLogger` instances are thread-safe and can be shared cluster-wide.
131+
Besides, you can adjust several parameters such as the maximum query string length to be printed,
132+
the maximum number of parameters to print, etc. Refer to the
133+
`QueryLogger` [API docs][query_logger] for more information.
134+
135+
Secondly, you need to adjust your logging framework to accept log messages from the `QueryLogger`. The `QueryLogger`
136+
uses 3 different loggers:
137+
138+
* `com.datastax.driver.core.QueryLogger.NORMAL` : Used to log normal queries, i.e., queries that completed successfully within a configurable threshold in milliseconds.
139+
* `com.datastax.driver.core.QueryLogger.SLOW` : Used to log slow queries, i.e., queries that completed successfully but that took longer than a configurable threshold in milliseconds to complete.
140+
* `com.datastax.driver.core.QueryLogger.ERROR`: Used to log unsuccessful queries, i.e., queries that did not complete normally and threw an exception. Note this this logger will also print the full stack trace of the reported exception.
141+
142+
You need to set the above loggers to DEBUG level to turn them on. E.g. to track queries
143+
that take more than 300 ms to complete, configure your `QueryLogger` with that threshold (see above),
144+
then set the `com.datastax.driver.core.QueryLogger.SLOW` logger to DEBUG, e.g. with Log4J:
145+
146+
```xml
147+
<logger name="com.datastax.driver.core.QueryLogger.SLOW">
148+
<level value="DEBUG"/>
149+
</logger>
150+
```
151+
152+
The `QueryLogger` would then print messages such as this for every slow query:
153+
154+
```
155+
DEBUG [cluster1] [/127.0.0.1:9042] Query too slow, took 329 ms: SELECT * FROM users WHERE user_id=?;
156+
```
157+
158+
As you can see, actual query parameters are not logged; if you want them to be printed as well, set the `com.datastax.driver.core.QueryLogger.SLOW` logger
159+
to TRACE instead, e.g. with Log4J:
160+
161+
```xml
162+
<logger name="com.datastax.driver.core.QueryLogger.SLOW">
163+
<level value="TRACE"/>
164+
</logger>
165+
```
166+
167+
The `QueryLogger` would then print messages such as this for every slow query:
168+
169+
```
170+
TRACE [cluster1] [/127.0.0.1:9042] Query too slow, took 329 ms: SELECT * FROM users WHERE user_id=? [user_id=42];
171+
```
172+
173+
Be careful when logging large query strings (specially batches) and/or queries with considerable amounts of parameters.
174+
See the `QueryLogger` [API docs][query_logger] for examples of how to truncate the printed message when necessary.
175+
176+
#### Constant vs Dynamic thresholds
177+
178+
Currently the `QueryLogger` can be configured to track slow queries using either
179+
a constant threshold in milliseconds (which is the default behavior), or
180+
a dynamic threshold based on per-host latency percentiles, as computed by `PerHostPercentileTracker`.
181+
182+
**Dynamic thresholds are still a beta feature as of version 2.0.10: they
183+
haven't been extensively tested yet, and the API is still subject to
184+
change.**
185+
186+
Refer to the `QueryLogger` [API docs][query_logger] for an example of usage.
187+
188+
### Performance Tips
189+
190+
* Use asynchronous appenders; both [Log4J](http://logging.apache.org/log4j/1.2/apidocs/org/apache/log4j/AsyncAppender.html)
191+
and [Logback](http://logback.qos.ch/manual/appenders.html#AsyncAppender) provide asynchronous appenders
192+
that can significantly boost latencies when writing log messages.
193+
* While the driver does not provide such capability, it is possible for client applications to hot-reload the log configuration
194+
without stopping the application. This usually involves JMX and is available for [Logback](http://logback.qos.ch/manual/jmxConfig.html);
195+
Log4J provides a `configureAndWatch()` method but it is not recommended to use it inside J2EE containers (see [FAQ](https://logging.apache.org/log4j/1.2/faq.html#a3.6)).
196+
197+
### Logback Example
198+
199+
Here is a typical example configuration for Logback. *Please adapt it to your specific needs before using it!*
200+
201+
It logs messages to the console with levels equal to or higher than INFO, and logs all messages to a rolling file.
202+
By default, only messages with ERROR level or higher are logged.
203+
204+
It also turns on slow query tracing as described above.
205+
206+
```xml
207+
<?xml version="1.0" encoding="UTF-8"?>
208+
<configuration>
209+
210+
<!-- log INFO or higher messages to the console -->
211+
<appender name="console" class="ch.qos.logback.core.ConsoleAppender">
212+
<encoder>
213+
<pattern>%-5p %msg%n</pattern>
214+
</encoder>
215+
</appender>
216+
217+
<!-- log everything to a rolling file -->
218+
<appender name="file" class="ch.qos.logback.core.rolling.RollingFileAppender">
219+
<file>driver.log</file>
220+
<encoder>
221+
<pattern>%-5p [%d{ISO8601}] [%t] %F:%L - %msg%n</pattern>
222+
</encoder>
223+
<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
224+
<!-- daily rollover -->
225+
<fileNamePattern>driver.%d{yyyy-MM-dd}.log</fileNamePattern>
226+
<!-- keep 30 days' worth of history -->
227+
<maxHistory>30</maxHistory>
228+
</rollingPolicy>
229+
</appender>
230+
231+
<!-- use AsyncAppender for lower latencies -->
232+
<appender name="async" class="ch.qos.logback.classic.AsyncAppender">
233+
<appender-ref ref="console" />
234+
<appender-ref ref="file" />
235+
</appender>
236+
237+
<!--
238+
Turn on slow query logging by setting this logger to DEBUG;
239+
set level to TRACE to also log query parameters
240+
-->
241+
<logger name="com.datastax.driver.core.QueryLogger.SLOW" level="DEBUG" />
242+
243+
<root level="ERROR">
244+
<appender-ref ref="async" />
245+
</root>
246+
247+
</configuration>
248+
```
249+
250+
### Log4J Example
251+
252+
Here is a typical example configuration for Log4J. *Please adapt it to your specific needs before using it!*
253+
254+
It logs messages to the console with levels equal to or higher than INFO, and logs all messages to a rolling file.
255+
By default, only messages with ERROR level or higher are logged.
256+
257+
It also turns on slow query tracing as described above.
258+
259+
```xml
260+
<log4j:configuration>
261+
262+
<!-- log INFO or higher messages to the console -->
263+
<appender name="console" class="org.apache.log4j.ConsoleAppender">
264+
<param name="threshold" value="INFO"/>
265+
<layout class="org.apache.log4j.PatternLayout">
266+
<param name="ConversionPattern" value="%-5p %m%n"/>
267+
</layout>
268+
</appender>
269+
270+
<!-- log everything to a rolling file -->
271+
<appender name="file" class="org.apache.log4j.RollingFileAppender">
272+
<param name="file" value="driver.log"/>
273+
<param name="append" value="false"/>
274+
<param name="maxFileSize" value="1GB"/>
275+
<param name="maxBackupIndex" value="10"/>
276+
<layout class="org.apache.log4j.PatternLayout">
277+
<param name="ConversionPattern" value="%-5p [%d{ISO8601}] [%t] %F:%L - %m%n"/>
278+
</layout>
279+
</appender>
280+
281+
<!-- use AsyncAppender for lower latencies -->
282+
<appender name="async" class="org.apache.log4j.AsyncAppender">
283+
<param name="BufferSize" value="500"/>
284+
<appender-ref ref="file"/>
285+
<appender-ref ref="console"/>
286+
</appender>
287+
288+
<!--
289+
Turn on slow query logging by setting this logger to DEBUG;
290+
set level to TRACE to also log query parameters
291+
-->
292+
<logger name="com.datastax.driver.core.QueryLogger.SLOW">
293+
<level value="DEBUG"/>
294+
</logger>
295+
296+
<root>
297+
<priority value="ERROR"/>
298+
<appender-ref ref="async"/>
299+
</root>
300+
301+
</log4j:configuration>
302+
```
303+
304+
[query_logger]:http://docs.datastax.com/en/drivers/java/2.0/com/datastax/driver/core/QueryLogger.html

0 commit comments

Comments
 (0)