Skip to content

Commit 43181c2

Browse files
committed
ported rewrite of flowtracing #2535
1 parent 891c08e commit 43181c2

File tree

1 file changed

+148
-206
lines changed

1 file changed

+148
-206
lines changed

src/site/antora/modules/ROOT/pages/manual/flowtracing.adoc

Lines changed: 148 additions & 206 deletions
Original file line numberDiff line numberDiff line change
@@ -16,155 +16,181 @@
1616
////
1717
= Flow Tracing
1818
19-
The `Logger` class provides logging methods that are quite useful for
20-
following the execution path of applications. These methods generate
21-
logging events that can be filtered separately from other debug logging.
22-
Liberal use of these methods is encouraged as the output has been found
23-
to
24-
25-
* aid in problem diagnosis in development without requiring a debug
26-
session
27-
* aid in problem diagnosis in production where no debugging is possible
28-
* help educate new developers in learning the application.
29-
30-
The most used methods are the entry() or traceEntry() and exit() or
31-
traceExit() methods. entry() or traceEntry() should be placed at the
32-
beginning of methods, except perhaps for simple getters and setters.
33-
entry() can be called passing from 0 to 4 parameters. Typically these
34-
will be parameters passed to the method. traceEntry() can be passed a
35-
format String and a variable list of parameters, or a Message. The
36-
entry() and traceEntry() methods log with a level of TRACE and uses a
37-
Marker with a name of "ENTER" which is also a "FLOW" Marker and all
38-
message strings will begin with "event", even if a format String or
39-
Message is used.
40-
41-
The main difference between the entry and traceEntry methods is that the
42-
entry method accepts a variable list of objects where presumably each is
43-
a method parameter. The traceEntry method accepts a format string
44-
followed by a variable list of objects, presumably included in the
45-
format String. It is not possible to have a single method that includes
46-
both of these as it would be ambiguous whether the first String is a
47-
parameter or a format String.
48-
49-
An exit() or traceExit() method should be placed before any return
50-
statement or as the last statement of methods without a return. exit()
51-
and traceExit() can be called with or without a parameter. Typically,
52-
methods that return void will use exit() or traceExit() while methods
53-
that return an Object will use exit(Object obj) or traceExit(object, new
54-
SomeMessage(object)). The exit() and traceExit() methods log with a
55-
level of TRACE and uses a Marker with a name of "EXIT" which is also a
56-
"FLOW" Marker and all message strings will begin with "exit", even if a
57-
format String or Message is used.
58-
59-
The throwing() method can be used by an application when it is throwing
60-
an exception that is unlikely to be handled, such as a RuntimeException.
61-
This will insure that proper diagnostics are available if needed. The
62-
logging event generated will have a level of ERROR and will have an
63-
associated Marker with a name of "THROWING" which is also an "EXCEPTION"
64-
Marker.
65-
66-
The catching() method can be used by an application when it catches an
67-
Exception that it is not going to rethrow, either explicitly or attached
68-
to another Exception. The logging event generated will have a level of
69-
ERROR and will have an associated Marker with a name of "CATCHING" which
70-
is also an "EXCEPTION" Marker.
71-
72-
The following example shows a simple application using these methods in
73-
a fairly typical manner. The throwing() is not present since no
74-
Exceptions are explicitly thrown and not handled.
75-
76-
[source,java]
77-
----
78-
package com.test;
79-
80-
import org.apache.logging.log4j.Logger;
81-
import org.apache.logging.log4j.LogManager;
19+
Flow tracing in Log4j is an advanced logging technique designed to enhance
20+
the visibility of application processes. With this technique, developers can track
21+
data flow through their application using unique methods that log entry
22+
and exit points within the code.
8223
83-
import java.util.Random;
24+
These methods are:
8425
85-
public class TestService {
86-
private Logger logger = LogManager.getLogger(TestService.class.getName());
26+
* `traceEntry()` (Deprecated `entry()`)
27+
* `traceExit()` (Deprecated: `exit()`)
28+
* `throwing()`
29+
* `catching()`
8730
88-
private String[] messages = new String[] {
89-
"Hello, World",
90-
"Goodbye Cruel World",
91-
"You had me at hello"
92-
};
93-
private Random rand = new Random(1);
31+
With these methods, we can investigate environments where traditional debugging is not possible,
32+
such as in production or during live application monitoring.
33+
Furthermore, new developers can be educated on the application's behavior by examining the logs.
9434
95-
public void setMessages(String[] messages) {
96-
logger.traceEntry(new JsonMessage(messages));
97-
this.messages = messages;
98-
logger.traceExit();
99-
}
35+
Flow tracing offers a structured approach to all this.
10036
101-
public String[] getMessages() {
102-
logger.traceEntry();
103-
return logger.traceExit(messages, new JsonMessage(messages));
104-
}
37+
== Flow Tracing Methods
10538
106-
public String retrieveMessage() {
107-
logger.entry();
39+
The methods often used are `traceEntry()` and `traceExit()`.
40+
As the name suggests, the "entry" method is used at the beginning and the "exit" method at the end of a method.
10841
109-
String testMsg = getMessage(getKey());
42+
[source, java]
43+
----
44+
public void someMethod() {
45+
logger.traceEntry(); <1>
46+
// method body
47+
logger.traceExit(); <2>
48+
}
49+
----
50+
<1> The `entry()` method is called at the beginning of the method.
51+
<2> The `exit()` method is called at the end of the method.
11052
111-
return logger.exit(testMsg);
112-
}
53+
Developers can call both `traceEntry()` and `traceExit()` methods with or without parameters.
54+
In the case of `traceEntry()`, it makes sense to pass the method parameters on as arguments.
11355
114-
public void exampleException() {
115-
logger.entry();
116-
try {
117-
String msg = messages[messages.length];
118-
logger.error("An exception should have been thrown");
119-
} catch (Exception ex) {
120-
logger.catching(ex);
121-
}
122-
logger.exit();
123-
}
56+
[source, java]
57+
----
58+
public void someMethod(String param) {
59+
logger.traceEntry(param); <1>
60+
// method body
61+
logger.traceExit(); <2>
62+
}
63+
----
64+
<1> The `traceEntry()` method is called at the beginning of the method.
65+
<2> The `traceExit()` method is called at the end of the method.
12466
125-
public String getMessage(int key) {
126-
logger.entry(key);
67+
The `traceEntry()` also supports messages.
12768
128-
String value = messages[key];
69+
[source, java]
70+
----
71+
public void someMethod(String[] text) {
72+
logger.traceEntry(new JsonMessage(text)); <1>
73+
// method body
74+
}
75+
----
76+
<1> Using the `JsonMessage` class to log the `text` parameter.
12977
130-
return logger.exit(value);
131-
}
78+
Very similar, it is possible to use `traceExit()` with methods that return a value.
13279
133-
private int getKey() {
134-
logger.entry();
135-
int key = rand.nextInt(messages.length);
136-
return logger.exit(key);
137-
}
80+
[source, java]
81+
----
82+
public String someMethod() {
83+
String result = "Hello";
84+
// method body
85+
return logger.traceExit(result); <1>
13886
}
13987
----
88+
<1> The `traceExit()` method can also return a value.
89+
90+
Developers can use the `catching()` and `throwing()` methods to work with exceptions.
14091
141-
This test application uses the preceding service to generate logging
142-
events.
92+
The following code shows the `catching()` method. It will be called
93+
inside the `catch` block of a try-catch statement.
14394
144-
[source,java]
95+
The `catching()` method can be used by an application when it catches an
96+
Exception that it will not rethrow, either explicitly or attached
97+
to another Exception. The generated logging event will have an `ERROR` level.
98+
99+
[source, java]
100+
----
101+
public void someMethod() {
102+
try {
103+
// Let's assume an exception is thrown here
104+
String msg = messages[messages.length];
105+
} catch (Exception ex) {
106+
logger.catching(ex); <1>
107+
}
108+
}
145109
----
146-
package com.test;
110+
<1> The `catching()` method logs exceptions that are caught and not rethrown.
111+
112+
The `throwing()` method is used to log exceptions that are thrown and not caught.
113+
The code shows how to use the `throwing()` method- like `catching()`, which will be called
114+
inside the `catch` block of a try-catch statement.
147115
148-
public class App {
116+
The `throwing()` method can be used by an application when it is throwing
117+
an exception that is unlikely to be handled, such as a RuntimeException.
118+
This will ensure that proper diagnostics are available if needed.
119+
The generated logging event will have an `ERROR` level.
149120
150-
public static void main( String[] args ) {
151-
TestService service = new TestService();
152-
service.retrieveMessage();
153-
service.retrieveMessage();
154-
service.exampleException();
121+
[source, java]
122+
----
123+
public void someMethod() {
124+
try {
125+
// Let's assume an exception is thrown here
126+
String msg = messages[messages.length];
127+
} catch (Exception ex) {
128+
logger.throwing(ex); <1>
155129
}
156130
}
157131
----
132+
<1> The `throwing()` method logs exceptions that are thrown and not caught.
133+
134+
== Differences in flow tracing methods
135+
136+
Flow tracing methods have specific markers assigned and logs with a level of `TRACE`.
137+
It's also noteworthy that all messages begin with "event".
138+
139+
The table below shows the methods and their unique features.
140+
141+
[cols="3,3,3", options="header"]
142+
|===
143+
| Method Name | Marker Name | Special Features
144+
145+
| `traceEntry()`
146+
| `ENTER`, `FLOW`
147+
| Can take a format string and a variable list of parameters.
148+
149+
| `entry()`
150+
| `ENTER`, `FLOW`
151+
| DEPRECATED. Accepts 0 to 4 parameters
152+
153+
| `traceExit()`
154+
| `EXIT`, `FLOW`
155+
| Handles return values differently based on the method signature.
156+
157+
| `exit()`
158+
| `EXIT`, `FLOW`
159+
| DEPRECATED. Can be called with or without parameters.
160+
161+
| `throwing()`
162+
| `THROWING`, `EXCEPTION`
163+
| Typically used when an application throws an exception that is unlikely to be handled, such as a RuntimeException.
164+
165+
| `catching()`
166+
| `CATCHING`, `EXCEPTION`
167+
| Used when catching exceptions that are not rethrown; logs with ERROR level.
168+
169+
|===
170+
171+
== Flow Tracing Example Configuration
172+
173+
The following example demonstrates how to configure Log4j to use flow tracing.
174+
Note: While developers should prefer the `JsonTemplateLayout` in production, this example uses `PatternLayout` for simplicity.
175+
176+
Two appenders are defined: `Console` and `File`.
177+
178+
The `Console` appender outputs logs to `SYSTEM_OUT`, typically the console.
179+
It includes a `ThresholdFilter` set to only accept messages at the `ERROR` level or above.
180+
Less severe messages are filtered.
181+
182+
Similarly, the File appender directs logs to a file named `target/test.log`.
183+
The appenders configuration will create a new file for every application run.
184+
185+
Both appenders use the already mentioned `PatternLayout`, which includes detailed information such as time, log level, class name, line number, and method name.
158186
159-
The configuration below will cause all output to be routed to
160-
target/test.log. The pattern for the FileAppender includes the class
161-
name, line number and method name. Including these in the pattern are
162-
critical for the log to be of value.
187+
Finally, in the Loggers section, the Root logger is set to a `TRACE` level, which is necessary to see flow tracing in action.
188+
The Root logger references the File appender, directing its output to the configured file.
163189
164190
[source,xml]
165191
----
166192
<?xml version="1.0" encoding="UTF-8"?>
167-
<Configuration status="error">
193+
<Configuration>
168194
<Appenders>
169195
<Console name="Console" target="SYSTEM_OUT">
170196
<ThresholdFilter level="ERROR" onMatch="ACCEPT" onMismatch="DENY"/>
@@ -184,88 +210,4 @@ critical for the log to be of value.
184210
</Configuration>
185211
----
186212
187-
Here is the output that results from the Java classes and configuration
188-
above.
189-
190-
....
191-
19:08:07.056 TRACE com.test.TestService 19 retrieveMessage - entry
192-
19:08:07.060 TRACE com.test.TestService 46 getKey - entry
193-
19:08:07.060 TRACE com.test.TestService 48 getKey - exit with (0)
194-
19:08:07.060 TRACE com.test.TestService 38 getMessage - entry parms(0)
195-
19:08:07.060 TRACE com.test.TestService 42 getMessage - exit with (Hello, World)
196-
19:08:07.060 TRACE com.test.TestService 23 retrieveMessage - exit with (Hello, World)
197-
19:08:07.061 TRACE com.test.TestService 19 retrieveMessage - entry
198-
19:08:07.061 TRACE com.test.TestService 46 getKey - entry
199-
19:08:07.061 TRACE com.test.TestService 48 getKey - exit with (1)
200-
19:08:07.061 TRACE com.test.TestService 38 getMessage - entry parms(1)
201-
19:08:07.061 TRACE com.test.TestService 42 getMessage - exit with (Goodbye Cruel World)
202-
19:08:07.061 TRACE com.test.TestService 23 retrieveMessage - exit with (Goodbye Cruel World)
203-
19:08:07.062 TRACE com.test.TestService 27 exampleException - entry
204-
19:08:07.077 DEBUG com.test.TestService 32 exampleException - catching java.lang.ArrayIndexOutOfBoundsException: 3
205-
at com.test.TestService.exampleException(TestService.java:29) [classes/:?]
206-
at com.test.App.main(App.java:9) [classes/:?]
207-
at com.test.AppTest.testApp(AppTest.java:15) [test-classes/:?]
208-
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.6.0_29]
209-
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) ~[?:1.6.0_29]
210-
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) ~[?:1.6.0_29]
211-
at java.lang.reflect.Method.invoke(Method.java:597) ~[?:1.6.0_29]
212-
at org.junit.internal.runners.TestMethodRunner.executeMethodBody(TestMethodRunner.java:99) [junit-4.3.1.jar:?]
213-
at org.junit.internal.runners.TestMethodRunner.runUnprotected(TestMethodRunner.java:81) [junit-4.3.1.jar:?]
214-
at org.junit.internal.runners.BeforeAndAfterRunner.runProtected(BeforeAndAfterRunner.java:34) [junit-4.3.1.jar:?]
215-
at org.junit.internal.runners.TestMethodRunner.runMethod(TestMethodRunner.java:75) [junit-4.3.1.jar:?]
216-
at org.junit.internal.runners.TestMethodRunner.run(TestMethodRunner.java:45) [junit-4.3.1.jar:?]
217-
at org.junit.internal.runners.TestClassMethodsRunner.invokeTestMethod(TestClassMethodsRunner.java:66) [junit-4.3.1.jar:?]
218-
at org.junit.internal.runners.TestClassMethodsRunner.run(TestClassMethodsRunner.java:35) [junit-4.3.1.jar:?]
219-
at org.junit.internal.runners.TestClassRunner$1.runUnprotected(TestClassRunner.java:42) [junit-4.3.1.jar:?]
220-
at org.junit.internal.runners.BeforeAndAfterRunner.runProtected(BeforeAndAfterRunner.java:34) [junit-4.3.1.jar:?]
221-
at org.junit.internal.runners.TestClassRunner.run(TestClassRunner.java:52) [junit-4.3.1.jar:?]
222-
at org.apache.maven.surefire.junit4.JUnit4TestSet.execute(JUnit4TestSet.java:35) [surefire-junit4-2.7.2.jar:2.7.2]
223-
at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:115) [surefire-junit4-2.7.2.jar:2.7.2]
224-
at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:97) [surefire-junit4-2.7.2.jar:2.7.2]
225-
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.6.0_29]
226-
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) ~[?:1.6.0_29]
227-
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) ~[?:1.6.0_29]
228-
at java.lang.reflect.Method.invoke(Method.java:597) ~[?:1.6.0_29]
229-
at org.apache.maven.surefire.booter.ProviderFactory$ClassLoaderProxy.invoke(ProviderFactory.java:103) [surefire-booter-2.7.2.jar:2.7.2]
230-
at $Proxy0.invoke(Unknown Source) [?:?]
231-
at org.apache.maven.surefire.booter.SurefireStarter.invokeProvider(SurefireStarter.java:150) [surefire-booter-2.7.2.jar:2.7.2]
232-
at org.apache.maven.surefire.booter.SurefireStarter.runSuitesInProcess(SurefireStarter.java:91) [surefire-booter-2.7.2.jar:2.7.2]
233-
at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:69) [surefire-booter-2.7.2.jar:2.7.2]
234-
19:08:07.087 TRACE com.test.TestService 34 exampleException - exit
235-
....
236-
237-
Simply changing the root logger level to DEBUG in the example above will
238-
reduce the output considerably.
239-
240-
....
241-
19:13:24.963 DEBUG com.test.TestService 32 exampleException - catching java.lang.ArrayIndexOutOfBoundsException: 3
242-
at com.test.TestService.exampleException(TestService.java:29) [classes/:?]
243-
at com.test.App.main(App.java:9) [classes/:?]
244-
at com.test.AppTest.testApp(AppTest.java:15) [test-classes/:?]
245-
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.6.0_29]
246-
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) ~[?:1.6.0_29]
247-
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) ~[?:1.6.0_29]
248-
at java.lang.reflect.Method.invoke(Method.java:597) ~[?:1.6.0_29]
249-
at org.junit.internal.runners.TestMethodRunner.executeMethodBody(TestMethodRunner.java:99) [junit-4.3.1.jar:?]
250-
at org.junit.internal.runners.TestMethodRunner.runUnprotected(TestMethodRunner.java:81) [junit-4.3.1.jar:?]
251-
at org.junit.internal.runners.BeforeAndAfterRunner.runProtected(BeforeAndAfterRunner.java:34) [junit-4.3.1.jar:?]
252-
at org.junit.internal.runners.TestMethodRunner.runMethod(TestMethodRunner.java:75) [junit-4.3.1.jar:?]
253-
at org.junit.internal.runners.TestMethodRunner.run(TestMethodRunner.java:45) [junit-4.3.1.jar:?]
254-
at org.junit.internal.runners.TestClassMethodsRunner.invokeTestMethod(TestClassMethodsRunner.java:66) [junit-4.3.1.jar:?]
255-
at org.junit.internal.runners.TestClassMethodsRunner.run(TestClassMethodsRunner.java:35) [junit-4.3.1.jar:?]
256-
at org.junit.internal.runners.TestClassRunner$1.runUnprotected(TestClassRunner.java:42) [junit-4.3.1.jar:?]
257-
at org.junit.internal.runners.BeforeAndAfterRunner.runProtected(BeforeAndAfterRunner.java:34) [junit-4.3.1.jar:?]
258-
at org.junit.internal.runners.TestClassRunner.run(TestClassRunner.java:52) [junit-4.3.1.jar:?]
259-
at org.apache.maven.surefire.junit4.JUnit4TestSet.execute(JUnit4TestSet.java:35) [surefire-junit4-2.7.2.jar:2.7.2]
260-
at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:115) [surefire-junit4-2.7.2.jar:2.7.2]
261-
at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:97) [surefire-junit4-2.7.2.jar:2.7.2]
262-
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.6.0_29]
263-
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) ~[?:1.6.0_29]
264-
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) ~[?:1.6.0_29]
265-
at java.lang.reflect.Method.invoke(Method.java:597) ~[?:1.6.0_29]
266-
at org.apache.maven.surefire.booter.ProviderFactory$ClassLoaderProxy.invoke(ProviderFactory.java:103) [surefire-booter-2.7.2.jar:2.7.2]
267-
at $Proxy0.invoke(Unknown Source) [?:?]
268-
at org.apache.maven.surefire.booter.SurefireStarter.invokeProvider(SurefireStarter.java:150) [surefire-booter-2.7.2.jar:2.7.2]
269-
at org.apache.maven.surefire.booter.SurefireStarter.runSuitesInProcess(SurefireStarter.java:91) [surefire-booter-2.7.2.jar:2.7.2]
270-
at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:69) [surefire-booter-2.7.2.jar:2.7.2]
271-
....
213+
By changing the Root logger's level to `DEBUG`, developers can reduce the amount of output.

0 commit comments

Comments
 (0)