Skip to content

Commit

Permalink
rewrote flowtracing #2535
Browse files Browse the repository at this point in the history
  • Loading branch information
@grobmeier
grobmeier committed May 10, 2024
1 parent 261b894 commit f1de65f
Showing 1 changed file with 152 additions and 199 deletions.
351 changes: 152 additions & 199 deletions src/site/antora/modules/ROOT/pages/manual/flowtracing.adoc
View file
Expand Up @@ -16,151 +16,188 @@
////
= Flow Tracing
The `Logger` class provides logging methods that are quite useful for
following the execution path of applications. These methods generate
logging events that can be filtered separately from other debug logging.
Liberal use of these methods is encouraged as the output has been found
to
* aid in problem diagnosis in development without requiring a debug
session
* aid in problem diagnosis in production where no debugging is possible
* help educate new developers in learning the application.
The most used methods are the entry() or traceEntry() and exit() or
traceExit() methods. entry() or traceEntry() should be placed at the
beginning of methods, except perhaps for simple getters and setters.
entry() can be called passing from 0 to 4 parameters. Typically these
will be parameters passed to the method. traceEntry() can be passed a
format String and a variable list of parameters, or a Message. The
entry() and traceEntry() methods log with a level of TRACE and uses a
Marker with a name of "ENTER" which is also a "FLOW" Marker and all
message strings will begin with "event", even if a format String or
Message is used.
The main difference between the entry and traceEntry methods is that the
entry method accepts a variable list of objects where presumably each is
a method parameter. The traceEntry method accepts a format string
followed by a variable list of objects, presumably included in the
format String. It is not possible to have a single method that includes
both of these as it would be ambiguous whether the first String is a
parameter or a format String.
An exit() or traceExit() method should be placed before any return
statement or as the last statement of methods without a return. exit()
and traceExit() can be called with or without a parameter. Typically,
methods that return void will use exit() or traceExit() while methods
that return an Object will use exit(Object obj) or traceExit(object, new
SomeMessage(object)). The exit() and traceExit() methods log with a
level of TRACE and uses a Marker with a name of "EXIT" which is also a
"FLOW" Marker and all message strings will begin with "exit", even if a
format String or Message is used.
The throwing() method can be used by an application when it is throwing
an exception that is unlikely to be handled, such as a RuntimeException.
This will insure that proper diagnostics are available if needed. The
logging event generated will have a level of ERROR and will have an
associated Marker with a name of "THROWING" which is also an "EXCEPTION"
Marker.
Flow tracing in Log4j is an advanced logging technique designed to enhance
the visibility of application processes. With this technique, developers can track
the flow of data through their application by using special methods that log entry
and exit points within the code.
The catching() method can be used by an application when it catches an
Exception that it is not going to rethrow, either explicitly or attached
to another Exception. The logging event generated will have a level of
ERROR and will have an associated Marker with a name of "CATCHING" which
is also an "EXCEPTION" Marker.
These methods are:
The following example shows a simple application using these methods in
a fairly typical manner. The throwing() is not present since no
Exceptions are explicitly thrown and not handled.
* `entry()` or `traceEntry()`
* `exit()` or `traceExit()`
* `throwing()`
* `catching()`
[source,java]
----
package com.test;
With these methods, we can investigate environments where traditional debugging is not possible,
such as in production or during live application monitoring.
Furthermore, new developers can be educated on the application's behavior by examining the logs.
import org.apache.logging.log4j.Logger;
import org.apache.logging.log4j.LogManager;
Flow tracing offers a structured approach to all this.
import java.util.Random;
== Flow Tracing Methods
public class TestService {
private Logger logger = LogManager.getLogger(TestService.class.getName());
The methods used most often are `entry()` or `traceEntry()` and `exit()` or `traceExit()`.
As the name suggests, the "entry" methods are used at the beginning of a method,
while the "exit" methods are used at the end of a method.
private String[] messages = new String[] {
"Hello, World",
"Goodbye Cruel World",
"You had me at hello"
};
private Random rand = new Random(1);
[source, java]
----
public void someMethod() {
logger.entry(); <1>
// method body
logger.exit(); <2>
}
----
<1> The `entry()` method is called at the beginning of the method.
<2> The `exit()` method is called at the end of the method.
public void setMessages(String[] messages) {
logger.traceEntry(new JsonMessage(messages));
this.messages = messages;
logger.traceExit();
}
Both `entry()` and `exit()` methods can be called with or without parameters.
In the case of `entry()` it makes sense to pass the method parameters as arguments.
public String[] getMessages() {
logger.traceEntry();
return logger.traceExit(messages, new JsonMessage(messages));
}
[source, java]
----
public void someMethod(String param) {
logger.entry(param); <1>
// method body
logger.exit(); <2>
}
----
<1> The `entry()` method is called at the beginning of the method.
public String retrieveMessage() {
logger.entry();
The `traceEntry()` also supports messages.
String testMsg = getMessage(getKey());
[source, java]
----
public void someMethod(String[] text) {
logger.traceEntry(new JsonMessage(text)); <1>
// method body
}
----
<1> Using the `JsonMessage` class to log the `text` parameter.
return logger.exit(testMsg);
}
Very similar, it is possible to use `exit()` with methods that return a value.
public void exampleException() {
logger.entry();
try {
String msg = messages[messages.length];
logger.error("An exception should have been thrown");
} catch (Exception ex) {
logger.catching(ex);
}
logger.exit();
}
[source, java]
----
public String someMethod() {
String result = "Hello";
// method body
return logger.exit(result); <1>
}
----
<1> The `exit()` method can also return a value.
public String getMessage(int key) {
logger.entry(key);
To work with exceptions, the `catching()` and `throwing()` methods are used.
String value = messages[key];
The following code shows, how to use the `catching()` method. It will be called
inside the `catch` block of a try-catch statement.
return logger.exit(value);
}
The `catching()` method can be used by an application when it catches an
Exception that it is not going to rethrow, either explicitly or attached
to another Exception. The logging event generated will have a level of `ERROR`.
private int getKey() {
logger.entry();
int key = rand.nextInt(messages.length);
return logger.exit(key);
[source, java]
----
public void someMethod() {
try {
// Lets assume an exception is thrown here
String msg = messages[messages.length];
} catch (Exception ex) {
logger.catching(ex); <1>
}
}
----
<1> The `catching()` method is used to log exceptions that are caught and not rethrown.
This test application uses the preceding service to generate logging
events.
The `throwing()` method is used to log exceptions that are thrown and not caught.
The code shows how to use the `throwing()` method- like `catching()` it will be called
inside the `catch` block of a try-catch statement.
[source,java]
----
package com.test;
public class App {
The `throwing()` method can be used by an application when it is throwing
an exception that is unlikely to be handled, such as a RuntimeException.
This will ensure that proper diagnostics are available if needed. The
logging event generated will have a level of `ERROR`.
public static void main( String[] args ) {
TestService service = new TestService();
service.retrieveMessage();
service.retrieveMessage();
service.exampleException();
[source, java]
----
public void someMethod() {
try {
// Lets assume an exception is thrown here
String msg = messages[messages.length];
} catch (Exception ex) {
logger.throwing(ex); <1>
}
}
----
<1> The `throwing()` method is used to log exceptions that are thrown and not caught.
== Differences in flow tracing methods
Flow tracing methods have specific markers assigned and logs with a level of `TRACE`.
It's also noteworthy that all messages will begin with the word "event".
The table below shows the methods and their special features.
[cols="3,3,3", options="header"]
|===
| Method Name | Marker Name | Special Features
| `entry()`
| `ENTER`, `FLOW`
| Accepts 0 to 4 parameters
| `traceEntry()`
| `ENTER`, `FLOW`
| Can take a format string and a variable list of parameters.
| `exit()`
| `EXIT`, `FLOW`
| Can be called with or without parameters.
| `traceExit()`
| `EXIT`, `FLOW`
| Handles return values differently based on the method signature.
| `throwing()`
| `THROWING`, `EXCEPTION`
| Typically used when an application throws an exception that is unlikely to be handled, such as a RuntimeException.
| `catching()`
| `CATCHING`, `EXCEPTION`
| Used when catching exceptions that are not rethrown; logs with ERROR level.
|===
== Flow Tracing Example Configuration
The following example demonstrates how to configure Log4j to use flow tracing.
While it is recommended to use the `JsonTemplateLayout` in production, we are using the
`PatternLayout` in this example for simplicity.
The configuration below will cause all output to be routed to
target/test.log. The pattern for the FileAppender includes the class
name, line number and method name. Including these in the pattern are
name, line number and method name. Including these in the pattern is
critical for the log to be of value.
The following example demonstrates how you could use flow tracing.
The Configuration element is set with a status of "error," which means Log4j
will only report issues that are of error severity or higher.
Within the Appenders section, two appenders are defined: Console and File.
The Console appender is configured to output logs to `SYSTEM_OUT`, typically the console.
It includes a `ThresholdFilter` set to only accept messages at the `ERROR` level or above.
This filters out less severe messages.
The output format is specified by a `PatternLayout`, designed to include detailed
trace information such as time, log level, class name, line number, and method name.
Please note, that we are recommending `JsonTemplateLayout` over `PatternLayout` in production.
Similarly, the File appender directs logs to a file named `target/test.log`.
The appenders configuration will create a new file for every application run.
Finally, in the Loggers section, the Root logger is set to a `TRACE` level which is necessary
to see flow tracing in action. The Root logger references the File appender, directing
its output to the configured file.
[source,xml]
----
<?xml version="1.0" encoding="UTF-8"?>
Expand All @@ -184,88 +221,4 @@ critical for the log to be of value.
</Configuration>
----
Here is the output that results from the Java classes and configuration
above.
....
19:08:07.056 TRACE com.test.TestService 19 retrieveMessage - entry
19:08:07.060 TRACE com.test.TestService 46 getKey - entry
19:08:07.060 TRACE com.test.TestService 48 getKey - exit with (0)
19:08:07.060 TRACE com.test.TestService 38 getMessage - entry parms(0)
19:08:07.060 TRACE com.test.TestService 42 getMessage - exit with (Hello, World)
19:08:07.060 TRACE com.test.TestService 23 retrieveMessage - exit with (Hello, World)
19:08:07.061 TRACE com.test.TestService 19 retrieveMessage - entry
19:08:07.061 TRACE com.test.TestService 46 getKey - entry
19:08:07.061 TRACE com.test.TestService 48 getKey - exit with (1)
19:08:07.061 TRACE com.test.TestService 38 getMessage - entry parms(1)
19:08:07.061 TRACE com.test.TestService 42 getMessage - exit with (Goodbye Cruel World)
19:08:07.061 TRACE com.test.TestService 23 retrieveMessage - exit with (Goodbye Cruel World)
19:08:07.062 TRACE com.test.TestService 27 exampleException - entry
19:08:07.077 DEBUG com.test.TestService 32 exampleException - catching java.lang.ArrayIndexOutOfBoundsException: 3
at com.test.TestService.exampleException(TestService.java:29) [classes/:?]
at com.test.App.main(App.java:9) [classes/:?]
at com.test.AppTest.testApp(AppTest.java:15) [test-classes/:?]
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.6.0_29]
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) ~[?:1.6.0_29]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) ~[?:1.6.0_29]
at java.lang.reflect.Method.invoke(Method.java:597) ~[?:1.6.0_29]
at org.junit.internal.runners.TestMethodRunner.executeMethodBody(TestMethodRunner.java:99) [junit-4.3.1.jar:?]
at org.junit.internal.runners.TestMethodRunner.runUnprotected(TestMethodRunner.java:81) [junit-4.3.1.jar:?]
at org.junit.internal.runners.BeforeAndAfterRunner.runProtected(BeforeAndAfterRunner.java:34) [junit-4.3.1.jar:?]
at org.junit.internal.runners.TestMethodRunner.runMethod(TestMethodRunner.java:75) [junit-4.3.1.jar:?]
at org.junit.internal.runners.TestMethodRunner.run(TestMethodRunner.java:45) [junit-4.3.1.jar:?]
at org.junit.internal.runners.TestClassMethodsRunner.invokeTestMethod(TestClassMethodsRunner.java:66) [junit-4.3.1.jar:?]
at org.junit.internal.runners.TestClassMethodsRunner.run(TestClassMethodsRunner.java:35) [junit-4.3.1.jar:?]
at org.junit.internal.runners.TestClassRunner$1.runUnprotected(TestClassRunner.java:42) [junit-4.3.1.jar:?]
at org.junit.internal.runners.BeforeAndAfterRunner.runProtected(BeforeAndAfterRunner.java:34) [junit-4.3.1.jar:?]
at org.junit.internal.runners.TestClassRunner.run(TestClassRunner.java:52) [junit-4.3.1.jar:?]
at org.apache.maven.surefire.junit4.JUnit4TestSet.execute(JUnit4TestSet.java:35) [surefire-junit4-2.7.2.jar:2.7.2]
at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:115) [surefire-junit4-2.7.2.jar:2.7.2]
at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:97) [surefire-junit4-2.7.2.jar:2.7.2]
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.6.0_29]
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) ~[?:1.6.0_29]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) ~[?:1.6.0_29]
at java.lang.reflect.Method.invoke(Method.java:597) ~[?:1.6.0_29]
at org.apache.maven.surefire.booter.ProviderFactory$ClassLoaderProxy.invoke(ProviderFactory.java:103) [surefire-booter-2.7.2.jar:2.7.2]
at $Proxy0.invoke(Unknown Source) [?:?]
at org.apache.maven.surefire.booter.SurefireStarter.invokeProvider(SurefireStarter.java:150) [surefire-booter-2.7.2.jar:2.7.2]
at org.apache.maven.surefire.booter.SurefireStarter.runSuitesInProcess(SurefireStarter.java:91) [surefire-booter-2.7.2.jar:2.7.2]
at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:69) [surefire-booter-2.7.2.jar:2.7.2]
19:08:07.087 TRACE com.test.TestService 34 exampleException - exit
....
Simply changing the root logger level to DEBUG in the example above will
reduce the output considerably.
....
19:13:24.963 DEBUG com.test.TestService 32 exampleException - catching java.lang.ArrayIndexOutOfBoundsException: 3
at com.test.TestService.exampleException(TestService.java:29) [classes/:?]
at com.test.App.main(App.java:9) [classes/:?]
at com.test.AppTest.testApp(AppTest.java:15) [test-classes/:?]
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.6.0_29]
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) ~[?:1.6.0_29]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) ~[?:1.6.0_29]
at java.lang.reflect.Method.invoke(Method.java:597) ~[?:1.6.0_29]
at org.junit.internal.runners.TestMethodRunner.executeMethodBody(TestMethodRunner.java:99) [junit-4.3.1.jar:?]
at org.junit.internal.runners.TestMethodRunner.runUnprotected(TestMethodRunner.java:81) [junit-4.3.1.jar:?]
at org.junit.internal.runners.BeforeAndAfterRunner.runProtected(BeforeAndAfterRunner.java:34) [junit-4.3.1.jar:?]
at org.junit.internal.runners.TestMethodRunner.runMethod(TestMethodRunner.java:75) [junit-4.3.1.jar:?]
at org.junit.internal.runners.TestMethodRunner.run(TestMethodRunner.java:45) [junit-4.3.1.jar:?]
at org.junit.internal.runners.TestClassMethodsRunner.invokeTestMethod(TestClassMethodsRunner.java:66) [junit-4.3.1.jar:?]
at org.junit.internal.runners.TestClassMethodsRunner.run(TestClassMethodsRunner.java:35) [junit-4.3.1.jar:?]
at org.junit.internal.runners.TestClassRunner$1.runUnprotected(TestClassRunner.java:42) [junit-4.3.1.jar:?]
at org.junit.internal.runners.BeforeAndAfterRunner.runProtected(BeforeAndAfterRunner.java:34) [junit-4.3.1.jar:?]
at org.junit.internal.runners.TestClassRunner.run(TestClassRunner.java:52) [junit-4.3.1.jar:?]
at org.apache.maven.surefire.junit4.JUnit4TestSet.execute(JUnit4TestSet.java:35) [surefire-junit4-2.7.2.jar:2.7.2]
at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:115) [surefire-junit4-2.7.2.jar:2.7.2]
at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:97) [surefire-junit4-2.7.2.jar:2.7.2]
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.6.0_29]
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) ~[?:1.6.0_29]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) ~[?:1.6.0_29]
at java.lang.reflect.Method.invoke(Method.java:597) ~[?:1.6.0_29]
at org.apache.maven.surefire.booter.ProviderFactory$ClassLoaderProxy.invoke(ProviderFactory.java:103) [surefire-booter-2.7.2.jar:2.7.2]
at $Proxy0.invoke(Unknown Source) [?:?]
at org.apache.maven.surefire.booter.SurefireStarter.invokeProvider(SurefireStarter.java:150) [surefire-booter-2.7.2.jar:2.7.2]
at org.apache.maven.surefire.booter.SurefireStarter.runSuitesInProcess(SurefireStarter.java:91) [surefire-booter-2.7.2.jar:2.7.2]
at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:69) [surefire-booter-2.7.2.jar:2.7.2]
....
By changing the level of the Root logger to `DEBUG`, you can reduce the amount of output.

0 comments on commit f1de65f

Please sign in to comment.