Last updated: 18-December-2023
Tracelogger
Examples
(1) Simple Use
(2) Access by Name
(3) Access by Thread
(4) Access by Queue

(1) Simple Use

It is possible to directly use tracers by invoking suitable constructors:
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
final FileTracer tracer = new FileTracer("Example");
tracer.setLogDirPath(Path.of(".", "log", "examples"));
tracer.open();
try {
class Foo {
void bar() {
tracer.entry("void", this, "bar()");
try {
tracer.out().printfIndentln("This is an example.");
} finally {
tracer.wayout();
}
}
}
Foo foo = new Foo();
foo.bar(); // nothing will be printed because no tracing context has been provided
tracer.initCurrentTracingContext(1, true);
foo.bar(); // this generates output
} finally {
tracer.close();
}
A FileTracer instance will be created in line 1. The filename of the associated logfile Example.log corresponds to the name of the tracer. The default location of the logfile would be ./log/Example.log but this is overwritten in line 2 and therefore the logfile is located at ./log/examples/Example.log. The logfile will be opened in line 3. It is strongly recommended to put the related close() directive into a finally block otherwise you are risking data loss, see line 20. Within this example we would like to monitor the bar()-method of the nested class Foo. The corresponding method image will be pushed onto the stack in line 7 and will be popped from the stack in line 11. The tracing output given in line 9 will be indented according to the stack size at that time. It is of vital importance that every entry()-call is matched by a related wayout()-call within a finally block. A so called tracing context will be needed to actually generate output. The corresponding directive in line 17 instructs the tracer to activate print-statements for the current thread until the stack size exceeds one. Below, you can see the tracing output of this simple example:
1 --> TraceLog opened! 2 Time : 2023-11-07T14:26:27.711423+01:00[Europe/Berlin] 3 Bufsize : 512 4 Autoflush: true 5 6 ENTRY--void Foo[1765795529].bar()--main[1] 7 This is an example. 8 RETURN-void Foo[1765795529].bar()--(+0ms)--(+0ms)--main[1] 9 10 --> TraceLog closing! 11 Time : 2023-11-07T14:26:27.7270374+01:00[Europe/Berlin]
The tracer notes the time of its opening and closing together with the configured buffer size and autoflush status. You see the default values. Autoflush means that after every call to wayout() the underlying PrintStream will be automatically flushed. The numbers within the rectangular braces are the hash code given by System.identityHashCode(java.lang.Object). The output has been produced by the main-thread with thread-id 1.

top

(2) Access by Name

When using the TracerFactory together with a suitable configuration, tracer instances can be accessed by name. The corresponding method returns a polymorphic AbstractTracer instance. E.g., by configuration, a regular FileTracer might be replaced by a NetTracer. The latter one streams its output to a designated socket address. Consider the simple configuration given below:
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
<?xml version="1.0" encoding="UTF-8" ?>
<TraceConfig xmlns="http://www.christofreichardt.de/java/tracer">
<Pool>
<TraceLogger name="ExampleTracer" class="de.christofreichardt.diagnosis.file.FileTracer">
<LogDir>./log/examples</LogDir>
<AutoFlush>true</AutoFlush>
<BufSize>1024</BufSize>
<Limit>1048576</Limit>
<Context>
<Thread name="main">
<Online>true</Online>
<DebugLevel>5</DebugLevel>
</Thread>
</Context>
</TraceLogger>
</Pool>
</TraceConfig>
From line 4 onwards a FileTracer named 'ExampleTracer' is defined. The accompanying log will be located at ./log/examples/ExampleTracer.log. AutoFlush is set to true, that is after every call to wayout() the underlying PrintStream will be flushed. The buffer size is equal to 1 Kibibyte (=1024 bytes). If the logfile grows to roughly 1 MebiByte (=1024*1024 bytes) the logfile will be rotated. The 'ExampleTracer' is interested in output created by the main-Thread up to a stack depth of 5. Further tracers aren't defined in the pool. Under the assumption that the configuration file is located at ./config/ExampleConfig.xml, the configuration can be used as follows:
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
TracerFactory.getInstance().readConfiguration(Path.of(".", "config", "ExampleConfig.xml").toFile());
final AbstractTracer tracer = TracerFactory.getInstance().getTracer("ExampleTracer"); // this will throw an exception if the 'ExampleTracer' doesn't exist
tracer.open();
try {
class Foo {
void bar() {
tracer.entry("void", this, "bar()");
try {
tracer.out().printfIndentln("Within bar().");
baz();
} finally {
tracer.wayout();
}
}
void baz() {
tracer.entry("void", this, "baz()");
try {
tracer.out().printfIndentln("Within baz().");
} finally {
tracer.wayout();
}
}
}
Foo foo = new Foo();
foo.bar(); // nothing will be printed because no tracing context has been provided
tracer.initCurrentTracingContext(); // the configured tracing context will be used
foo.bar(); // this generates output
} finally {
tracer.close();
}
This will result in the following output:
1 --> TraceLog opened! 2 Time : 2023-11-13T14:40:49.4799299+01:00[Europe/Berlin] 3 Bufsize : 1024 4 Autoflush: true 5 6 ENTRY--void Foo[2106592975].bar()--main[1] 7 Within bar(). 8 ENTRY--void Foo[2106592975].baz()--main[1] 9 Within baz(). 10 RETURN-void Foo[2106592975].baz()--(+0ms)--(+0ms)--main[1] 11 RETURN-void Foo[2106592975].bar()--(+11ms)--(+15ms)--main[1] 12 13 --> TraceLog closing! 14 Time : 2023-11-13T14:40:49.5019298+01:00[Europe/Berlin]
This approach makes sense if you want to analyze a single-threaded application. Within a multi-threaded environment only the main-thread would generate output when executing the given code. It is possible to register a tracer for more than one thread but then you would have to synchronize the access to the output stream by yourself. The class IndentablePrintStream provides synchronization primitives for this purpose. Instead of this, the approach shown in the next section is desired:

top

(3) Access by Thread

This procedure is recommended if you have control over the creation of the utilized threads, e.g. through a ThreadFactory. For every to be observed thread an associated tracer must be defined. Thereupon the appropriate tracer can be retrieved via convenient access methods. The association between thread and tracer is carried out by mapping thread names on tracers since prior to program execution no thread ids exist. Consequently, care must be taken to ensure that the utilized threads are uniquely named.
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
<?xml version="1.0" encoding="UTF-8" ?>
<TraceConfig xmlns="http://www.christofreichardt.de/java/tracer">
<Pool>
<TraceLogger name="WorkerTracer-0" class="de.christofreichardt.diagnosis.file.FileTracer">
<LogDir>./log/examples</LogDir>
<AutoFlush>true</AutoFlush>
<BufSize>1024</BufSize>
<Limit>1048576</Limit>
<Context>
<Thread name="Worker-0">
<Online>true</Online>
<DebugLevel>5</DebugLevel>
</Thread>
</Context>
</TraceLogger>
<TraceLogger name="WorkerTracer-1" class="de.christofreichardt.diagnosis.file.FileTracer">
<LogDir>./log/examples</LogDir>
<AutoFlush>true</AutoFlush>
<BufSize>1024</BufSize>
<Limit>1048576</Limit>
<Context>
<Thread name="Worker-1">
<Online>true</Online>
<DebugLevel>5</DebugLevel>
</Thread>
</Context>
</TraceLogger>
<TraceLogger name="WorkerTracer-2" class="de.christofreichardt.diagnosis.file.FileTracer">
<LogDir>./log/examples</LogDir>
<AutoFlush>true</AutoFlush>
<BufSize>1024</BufSize>
<Limit>1048576</Limit>
<Context>
<Thread name="Worker-2">
<Online>true</Online>
<DebugLevel>5</DebugLevel>
</Thread>
</Context>
</TraceLogger>
</Pool>
<Map>
<Threads>
<Thread name="Worker-0">
<TraceLogger ref="WorkerTracer-0"/>
</Thread>
<Thread name="Worker-1">
<TraceLogger ref="WorkerTracer-1"/>
</Thread>
<Thread name="Worker-2">
<TraceLogger ref="WorkerTracer-2"/>
</Thread>
</Threads>
</Map>
</TraceConfig>
in the above shown configuration we define three tracers (WorkerTracer-0, WorkerTracer-1 and WorkerTracer-2) which are interested in the output of three worker threads (Worker-0, Worker-1 and Worker-2). Furthermore, a mapping between threads and tracers has been specified (Worker-0 -> WorkerTracer-0, Worker-1 -> WorkerTracer-1 and Worker-2 -> WorkerTracer-2). The following code snippet illustrates how the given configuration can be applied:
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
class Foo implements Callable<Integer>, Traceable {
final int id;
public Foo(int id) {
this.id = id;
}
@Override
public Integer call() throws java.lang.Exception {
AbstractTracer tracer = getCurrentTracer();
tracer.initCurrentTracingContext();
tracer.entry("Integer", this, "call()");
try {
tracer.logMessage(LogLevel.INFO, "Consumer(" + this.id + ")", getClass(), "call()");
bar();
return this.id;
} finally {
tracer.wayout();
}
}
void bar() {
getCurrentTracer().entry("void", this, "bar()");
try {
getCurrentTracer().out().printfIndentln("Within bar().");
baz();
} finally {
getCurrentTracer().wayout();
}
}
void baz() {
getCurrentTracer().entry("void", this, "baz()");
try {
getCurrentTracer().out().printfIndentln("Within baz().");
} finally {
getCurrentTracer().wayout();
}
}
@Override
public AbstractTracer getCurrentTracer() {
return TracerFactory.getInstance().getCurrentPoolTracer();
}
}
TracerFactory.getInstance().readConfiguration(Path.of(".", "config", "ExampleConfig_2.xml").toFile());
TracerFactory.getInstance().openPoolTracer();
try {
final int THREAD_NUMBER = 3;
final int ITERATIONS = 100;
final int TIMEOUT = 5;
List<Future<Integer>> futures = new ArrayList<>();
ExecutorService executorService = Executors.newFixedThreadPool(THREAD_NUMBER, new ThreadFactory() {
final AtomicInteger threadNr = new AtomicInteger();
@Override
public Thread newThread(Runnable r) {
return new Thread(r, "Worker-" + this.threadNr.getAndIncrement());
}
});
try {
for (int i = 0; i < ITERATIONS; i++) {
futures.add(executorService.submit(new Foo(i)));
}
try {
int i = 0;
for (Future<Integer> future : futures) {
assert future.get() == i;
i++;
}
} catch (ExecutionException ex) {
ex.getCause().printStackTrace(System.err);
}
} finally {
executorService.shutdown();
assert executorService.awaitTermination(TIMEOUT, TimeUnit.SECONDS);
}
} finally {
TracerFactory.getInstance().closePoolTracer();
}
The class Foo implements the Callable interface and is therefore suited to be submitted to an Executorservice for parallel execution. In addition the interface Traceable is implemented, see lines 42-44. The expression TracerFactory.getInstance().getCurrentPoolTracer() returns the associated tracer for the current thread. The given configuration could be easily overwritten by e.g. TracerFactory.getInstance().getDefaultTracer() which would return a NullTracer. A NullTracer discards all tracing output. Specialized NullTracers may route the INFO-, WARNING- and ERROR-messages to conventional Logger systems, such like Logback. If no mapping is defined for a given thread, TracerFactory.getInstance().getCurrentPoolTracer() would return a NullTracer, too. We get ourselves an Executorservice in line 54. This Executorservice provides a pool containing of three threads operating on a shared unbounded queue of work tasks. The given ThreadFactory creates the threads with the intended names. 100 Foo objects are submitted to the specified Executorservice from line 63 to line 65. Which of the three threads works on a particular Foo task is not predictable, that is the output of the 100 Foo instances will be more or less evenly distributed between the three accompanying logs. However, output generated from thread Worker-0 will always be routed to WorkerTracer-0, output generated from thread Worker-1 will be routed to WorkerTracer-1 and so on. An excerpt from WorkerTracer-0.log is shown below:
1 --> TraceLog opened! 2 Time : 2023-11-15T13:01:52.6094606+01:00[Europe/Berlin] 3 Bufsize : 1024 4 Autoflush: true ... 61 ENTRY--Integer Foo[1724272678].call()--Worker-1[35] 62 +------+ 63 | INFO | [2023-11-15T13:01:52.6576449] [35,Worker-1] [de.christofreichardt.diagnosis.ExampleUnit5$2Foo] [call()] "Consumer(16)" 64 +------+ 65 ENTRY--void Foo[1724272678].bar()--Worker-1[35] 66 Within bar(). 67 ENTRY--void Foo[1724272678].baz()--Worker-1[35] 68 Within baz(). 69 RETURN-void Foo[1724272678].baz()--(+0ms)--(+0ms)--Worker-1[35] 70 RETURN-void Foo[1724272678].bar()--(+2ms)--(+0ms)--Worker-1[35] 71 RETURN-Integer Foo[1724272678].call()--(+2ms)--(+0ms)--Worker-1[35] ... 370 --> TraceLog closing! 371 Time : 2023-11-15T13:01:52.7162078+01:00[Europe/Berlin]
Sometimes we didn't control the thread creation, like shown in the example above. Thus, we are not in the position to guarantee the uniqueness of thread names, nor do we even sometimes know the thread names prior to program execution. Consequently we cannot define a mapping between threads and tracers. In this case, we can use the Tracer-Queue, see the next section.

top

(4) Access by Queue

Jakarta EE applications are operating under the control of an application server, e.g. Tomcat. Incoming requests will be served by (virtual) threads which might (or might not) originate from a thread pool. In either case we might not be able to configure the thread pool or the thread creation to suit our requirements. Thus, we define a (blocking) queue containing some uniform tracers which can be used to track the incoming requests. The queue blocks if no tracer is available at the moment. This will effectively limit the number of requests which can be concurrently processed, notwithstanding the size of the server's thread pool or other policies when working with virtual threads. The current tracing context of some active tracer will be automatically cleared when the last method image has been popped from its stack and the now inactive tracer will be returned to the queue. Consider the following configuration defining a queue with three tracers:
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
<?xml version="1.0" encoding="UTF-8"?>
<TraceConfig xmlns="http://www.christofreichardt.de/java/tracer">
<Pool/>
<DefaultTracer class="de.christofreichardt.diagnosis.JDKLoggingRouter"/>
<Queue>
<Enabled />
<Size>3</Size>
<TraceLogger name="servlet-tracer-"
class="de.christofreichardt.diagnosis.file.QueueFileTracer">
<LogDir>${catalina.base}/logs</LogDir>
<AutoFlush>true</AutoFlush>
<BufSize>1024</BufSize>
</TraceLogger>
<Online>true</Online>
<DebugLevel>5</DebugLevel>
</Queue>
</TraceConfig>
Note the declaration regarding the log directory in line 10. Since the example application has been developed using a Apache Tomcat 10, we apply its catalina.base system property to denote the logs-directory of the Tomcat distribution. (You can use system properties wherever you want within the XML configuration, that is element content or attributs.) Under the assumption that the configuration file has been attached to the package de.christofreichardt.tracefilter as resource, we can implement the following ServletContextListener:
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
public class MyContextListener implements ServletContextListener {
final static Logger LOGGER = Logger.getLogger("de.christofreichardt.tracefilter");
@Override
public void contextInitialized(ServletContextEvent servletContextEvent) {
LOGGER.info("Context initialized ...");
LOGGER.info("Context path = %s".formatted(servletContextEvent.getServletContext().getContextPath()));
InputStream resourceAsStream = MyContextListener.class.getClassLoader().getResourceAsStream("de/christofreichardt/tracefilter/trace-config.xml");
if (resourceAsStream != null) {
try {
TracerFactory.getInstance().reset();
TracerFactory.getInstance().readConfiguration(resourceAsStream);
TracerFactory.getInstance().openQueueTracer();
} catch (TracerFactory.Exception ex) {
LOGGER.log(Level.WARNING, "Problems occured when reading the tracer configuration.", ex);
} finally {
try {
resourceAsStream.close();
} catch (IOException ex) {
}
}
} else {
LOGGER.warning("Missing tracer configuration.");
}
}
@Override
public void contextDestroyed(ServletContextEvent servletContextEvent) {
TracerFactory.getInstance().closeQueueTracer();
LOGGER.info("Context destroyed ...");
}
}
ServletContextListeners are notified before the initialization of filters and servlets or rather are notified after the release of all servlets and filters. Thus, context listeners work well for the initialization or rather for the cleanup of the tracers. Conversely, WebFilters can be used for the activation of tracers, see below:
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
@WebFilter(filterName = "MyTraceFilter", servletNames = {"MyServlet"}, initParams = {
@WebInitParam(name = "tracing", value = "on")
})
public class MyTraceFilter implements Filter {
FilterConfig filterConfig;
final AtomicInteger atomicInteger = new AtomicInteger();
@Override
public void init(FilterConfig filterConfig) throws ServletException {
this.filterConfig = filterConfig;
}
@Override
public void doFilter(ServletRequest servletRequest, ServletResponse servletResponse, FilterChain filterChain) throws IOException, ServletException {
HttpServletRequest httpServletRequest = (HttpServletRequest) servletRequest;
int requestCounter = this.atomicInteger.getAndIncrement();
servletRequest.setAttribute("de.christofreichardt.tracefilter.requestCounter", requestCounter);
if ("on".equalsIgnoreCase(this.filterConfig.getInitParameter("tracing"))) {
AbstractTracer tracer = TracerFactory.getInstance().takeTracer();
tracer.initCurrentTracingContext();
tracer.entry("void", this, "doFilter(ServletRequest request, ServletResponse response, FilterChain chain)");
try {
tracer.out().printfIndentln("method = %s", httpServletRequest.getMethod());
tracer.out().printfIndentln("contextPath = %s", httpServletRequest.getContextPath());
tracer.out().printfIndentln("requestCounter = %d", requestCounter);
filterChain.doFilter(servletRequest, servletResponse);
} finally {
tracer.wayout();
}
} else {
filterChain.doFilter(servletRequest, servletResponse);
}
}
}
Consider line 20: Without fetching a tracer from the queue like this TracerFactory.getInstance().getCurrentQueueTracer() would return a NullTracer. That is, simply removing the WebFilter from the filter chain would deactivate the tracing. The stament in line 29 does not only pop the method image from the stack but also puts the the tracer back into the blocking queue, because the stack is then empty. The tracer can be deactivated by editing the tracing-WebInitParam, too. The to be observed Servlet is shown next:
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
@WebServlet(name = "MyServlet", urlPatterns = {"/*"})
public class MyServlet extends HttpServlet implements Traceable {
@Override
protected void doPost(HttpServletRequest httpServletRequest, HttpServletResponse httpServletResponse) throws ServletException, IOException {
AbstractTracer tracer = getCurrentTracer();
tracer.entry("void", this, "doPost(HttpServletRequest httpServletRequest, HttpServletResponse httpServletResponse)");
try {
int requestCounter = (int) httpServletRequest.getAttribute("de.christofreichardt.tracefilter.requestCounter");
tracer.logMessage(LogLevel.INFO, "%d. request ...".formatted(requestCounter),
getClass(), "doPost(HttpServletRequest httpServletRequest, HttpServletResponse httpServletResponse)");
String command;
try (BufferedReader bufferedReader = httpServletRequest.getReader()) {
command = bufferedReader.readLine();
}
tracer.out().printfIndentln("command = %s", command);
long pause = ThreadLocalRandom.current().nextLong(100L);
try {
Thread.sleep(pause);
} catch (InterruptedException ex) {
throw new RuntimeException(ex);
}
if ("REQUEST_LocalDateTime".equals(command)) {
try (PrintWriter printWriter = httpServletResponse.getWriter()) {
printWriter.printf("%3d: %s", requestCounter, LocalDateTime.now().format(DateTimeFormatter.ISO_LOCAL_DATE_TIME));
}
}
} finally {
tracer.wayout();
}
}
@Override
public AbstractTracer getCurrentTracer() {
return TracerFactory.getInstance().getCurrentQueueTracer();
}
}
The servlet acts on POST requests by returning the present local date-time in ISO-8601 format. It pauses a random interval (<100ms) before committing the result to simulate some internal computations. We can trigger the servlet with the following client code:
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
final int THREAD_NUMBER = 5;
ExecutorService executorService = Executors.newFixedThreadPool(THREAD_NUMBER, new ThreadFactory() {
final AtomicInteger threadNr = new AtomicInteger();
@Override
public Thread newThread(Runnable r) {
return new Thread(r, "Worker-" + this.threadNr.getAndIncrement());
}
});
HttpClient httpClient = HttpClient.newBuilder()
.executor(executorService)
.build();
HttpRequest httpRequest = HttpRequest.newBuilder()
.uri(URI.create("http://localhost:8080/trace-filter-example"))
.POST(HttpRequest.BodyPublishers.ofString("REQUEST_LocalDateTime"))
.build();
final int REQUESTS = 25;
List<CompletableFuture<Stream<String>>> completableFutures = IntStream.range(0, REQUESTS)
.mapToObj(i -> {
return httpClient.sendAsync(httpRequest, HttpResponse.BodyHandlers.ofLines())
.thenApply(httpResponse -> {
assert httpResponse.statusCode() == 200;
return httpResponse.body();
});
})
.collect(Collectors.toList());
List<String> responses = completableFutures.stream()
.map(completableFuture -> {
try {
return completableFuture.get();
} catch (ExecutionException | InterruptedException ex) {
throw new RuntimeException(ex);
}
})
.flatMap(bodies -> bodies)
.collect(Collectors.toList());
assert responses.size() == REQUESTS;
responses.forEach(response -> System.out.printf("response = %s%n", response));
We are asynchronously sending 25 POST requests by using a thread pool containing five threads. Since we are asynchronously posting the requests and since the service waits some random time interval during the processing of each request, the responses won't be in order:
response = 12: 2023-11-20T16:39:19.2222441 response = 1: 2023-11-20T16:39:18.8867623 response = 4: 2023-11-20T16:39:18.9627704 response = 18: 2023-11-20T16:39:19.1919087 response = 0: 2023-11-20T16:39:18.824767 response = 7: 2023-11-20T16:39:19.0556773 response = 23: 2023-11-20T16:39:19.3301539 response = 11: 2023-11-20T16:39:18.9807705 response = 17: 2023-11-20T16:39:19.1378188 response = 20: 2023-11-20T16:39:19.2712295 response = 22: 2023-11-20T16:39:19.2865033 response = 10: 2023-11-20T16:39:18.8547792 response = 9: 2023-11-20T16:39:19.0054473 response = 14: 2023-11-20T16:39:19.0264472 response = 13: 2023-11-20T16:39:19.0348963 response = 8: 2023-11-20T16:39:18.8687806 response = 2: 2023-11-20T16:39:19.0264472 response = 16: 2023-11-20T16:39:19.0959044 response = 6: 2023-11-20T16:39:19.1949069 response = 19: 2023-11-20T16:39:19.2654991 response = 24: 2023-11-20T16:39:19.3205006 response = 5: 2023-11-20T16:39:18.9397622 response = 15: 2023-11-20T16:39:19.0988537 response = 21: 2023-11-20T16:39:19.3260907 response = 3: 2023-11-20T16:39:18.8607791
Now, we take a look at one of the trace-logs from the service. An excerpt is shown below:
1 --> TraceLog opened! 2 Time : 2023-11-20T16:39:09.6763475+01:00[Europe/Berlin] 3 Bufsize : 1024 4 Autoflush: true ... 39 ENTRY--void MyTraceFilter[418479555].doFilter(ServletRequest request, ServletResponse response, FilterChain chain)--http-nio-8080-exec-6[41] 40 method = POST 41 contextPath = /trace-filter-example 42 requestCounter = 7 43 ENTRY--void MyServlet[1075871170].doPost(HttpServletRequest httpServletRequest, HttpServletResponse httpServletResponse)--http-nio-8080-exec-6[41] 44 +------+ 45 | INFO | [2023-11-20T16:39:19.0379308] [41,http-nio-8080-exec-6] [de.christofreichardt.tracefilter.MyServlet] [doPost(HttpServletRequest httpServletRequest, HttpServletResponse httpServletResponse)] "7. request ..." 46 +------+ 47 command = REQUEST_LocalDateTime 48 RETURN-void MyServlet[1075871170].doPost(HttpServletRequest httpServletRequest, HttpServletResponse httpServletResponse)--(+20ms)--(+0ms)--http-nio-8080-exec-6[41] 49 RETURN-void MyTraceFilter[418479555].doFilter(ServletRequest request, ServletResponse response, FilterChain chain)--(+20ms)--(+0ms)--http-nio-8080-exec-6[41] ... 84 --> TraceLog closing! 85 Time : 2023-11-20T16:52:25.1624224+01:00[Europe/Berlin]
With a disabled trace filter, this would become (within the catalina.yyyy-MM-dd.log):
236 20-Nov-2023 17:03:57.174 INFO [main] de.christofreichardt.tracefilter.MyContextListener.contextInitialized Context initialized ... 237 20-Nov-2023 17:03:57.176 INFO [main] de.christofreichardt.tracefilter.MyContextListener.contextInitialized Context path = /trace-filter-example ... 252 20-Nov-2023 17:04:09.199 INFO [http-nio-8080-exec-13] de.christofreichardt.tracefilter.MyServlet.doPost(HttpServletRequest httpServletRequest, HttpServletResponse httpServletResponse) 13. request ... 253 20-Nov-2023 17:04:09.199 INFO [http-nio-8080-exec-25] de.christofreichardt.tracefilter.MyServlet.doPost(HttpServletRequest httpServletRequest, HttpServletResponse httpServletResponse) 8. request ... 254 20-Nov-2023 17:04:09.199 INFO [http-nio-8080-exec-18] de.christofreichardt.tracefilter.MyServlet.doPost(HttpServletRequest httpServletRequest, HttpServletResponse httpServletResponse) 16. request ... 255 20-Nov-2023 17:04:09.199 INFO [http-nio-8080-exec-14] de.christofreichardt.tracefilter.MyServlet.doPost(HttpServletRequest httpServletRequest, HttpServletResponse httpServletResponse) 19. request ... 256 20-Nov-2023 17:04:09.199 INFO [http-nio-8080-exec-12] de.christofreichardt.tracefilter.MyServlet.doPost(HttpServletRequest httpServletRequest, HttpServletResponse httpServletResponse) 3. request ... 257 20-Nov-2023 17:04:09.199 INFO [http-nio-8080-exec-20] de.christofreichardt.tracefilter.MyServlet.doPost(HttpServletRequest httpServletRequest, HttpServletResponse httpServletResponse) 14. request ... 258 20-Nov-2023 17:04:09.199 INFO [http-nio-8080-exec-7] de.christofreichardt.tracefilter.MyServlet.doPost(HttpServletRequest httpServletRequest, HttpServletResponse httpServletResponse) 22. request ... 259 20-Nov-2023 17:04:09.199 INFO [http-nio-8080-exec-3] de.christofreichardt.tracefilter.MyServlet.doPost(HttpServletRequest httpServletRequest, HttpServletResponse httpServletResponse) 21. request ... 260 20-Nov-2023 17:04:09.199 INFO [http-nio-8080-exec-23] de.christofreichardt.tracefilter.MyServlet.doPost(HttpServletRequest httpServletRequest, HttpServletResponse httpServletResponse) 20. request ... 261 20-Nov-2023 17:04:09.199 INFO [http-nio-8080-exec-19] de.christofreichardt.tracefilter.MyServlet.doPost(HttpServletRequest httpServletRequest, HttpServletResponse httpServletResponse) 17. request ... 262 20-Nov-2023 17:04:09.199 INFO [http-nio-8080-exec-21] de.christofreichardt.tracefilter.MyServlet.doPost(HttpServletRequest httpServletRequest, HttpServletResponse httpServletResponse) 7. request ... 263 20-Nov-2023 17:04:09.199 INFO [http-nio-8080-exec-4] de.christofreichardt.tracefilter.MyServlet.doPost(HttpServletRequest httpServletRequest, HttpServletResponse httpServletResponse) 0. request ... 264 20-Nov-2023 17:04:09.199 INFO [http-nio-8080-exec-16] de.christofreichardt.tracefilter.MyServlet.doPost(HttpServletRequest httpServletRequest, HttpServletResponse httpServletResponse) 18. request ... 265 20-Nov-2023 17:04:09.199 INFO [http-nio-8080-exec-6] de.christofreichardt.tracefilter.MyServlet.doPost(HttpServletRequest httpServletRequest, HttpServletResponse httpServletResponse) 11. request ... 266 20-Nov-2023 17:04:09.199 INFO [http-nio-8080-exec-24] de.christofreichardt.tracefilter.MyServlet.doPost(HttpServletRequest httpServletRequest, HttpServletResponse httpServletResponse) 24. request ... 267 20-Nov-2023 17:04:09.199 INFO [http-nio-8080-exec-2] de.christofreichardt.tracefilter.MyServlet.doPost(HttpServletRequest httpServletRequest, HttpServletResponse httpServletResponse) 9. request ... 268 20-Nov-2023 17:04:09.199 INFO [http-nio-8080-exec-17] de.christofreichardt.tracefilter.MyServlet.doPost(HttpServletRequest httpServletRequest, HttpServletResponse httpServletResponse) 5. request ... 269 20-Nov-2023 17:04:09.199 INFO [http-nio-8080-exec-10] de.christofreichardt.tracefilter.MyServlet.doPost(HttpServletRequest httpServletRequest, HttpServletResponse httpServletResponse) 1. request ... 270 20-Nov-2023 17:04:09.199 INFO [http-nio-8080-exec-15] de.christofreichardt.tracefilter.MyServlet.doPost(HttpServletRequest httpServletRequest, HttpServletResponse httpServletResponse) 12. request ... 271 20-Nov-2023 17:04:09.199 INFO [http-nio-8080-exec-8] de.christofreichardt.tracefilter.MyServlet.doPost(HttpServletRequest httpServletRequest, HttpServletResponse httpServletResponse) 4. request ... 272 20-Nov-2023 17:04:09.199 INFO [http-nio-8080-exec-1] de.christofreichardt.tracefilter.MyServlet.doPost(HttpServletRequest httpServletRequest, HttpServletResponse httpServletResponse) 23. request ... 273 20-Nov-2023 17:04:09.199 INFO [http-nio-8080-exec-9] de.christofreichardt.tracefilter.MyServlet.doPost(HttpServletRequest httpServletRequest, HttpServletResponse httpServletResponse) 15. request ... 274 20-Nov-2023 17:04:09.199 INFO [http-nio-8080-exec-11] de.christofreichardt.tracefilter.MyServlet.doPost(HttpServletRequest httpServletRequest, HttpServletResponse httpServletResponse) 2. request ... 275 20-Nov-2023 17:04:09.199 INFO [http-nio-8080-exec-5] de.christofreichardt.tracefilter.MyServlet.doPost(HttpServletRequest httpServletRequest, HttpServletResponse httpServletResponse) 10. request ... 276 20-Nov-2023 17:04:09.199 INFO [http-nio-8080-exec-22] de.christofreichardt.tracefilter.MyServlet.doPost(HttpServletRequest httpServletRequest, HttpServletResponse httpServletResponse) 6. request ... ... 280 20-Nov-2023 17:09:29.413 INFO [main] de.christofreichardt.tracefilter.MyContextListener.contextDestroyed Context destroyed ...

top

imprint