You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@logging.apache.org by gr...@apache.org on 2024/05/10 19:52:13 UTC
(logging-log4j2) branch 2.x updated: rewrote flowtracing #2535
This is an automated email from the ASF dual-hosted git repository.
grobmeier pushed a commit to branch 2.x
in repository https://gitbox.apache.org/repos/asf/logging-log4j2.git
The following commit(s) were added to refs/heads/2.x by this push:
new f1de65f839 rewrote flowtracing #2535
f1de65f839 is described below
commit f1de65f8398b7f9aa8cb62df98f365d8c3ec7c7f
Author: Christian Grobmeier <cg...@grobmeier.de>
AuthorDate: Fri May 10 21:52:07 2024 +0200
rewrote flowtracing #2535
---
.../modules/ROOT/pages/manual/flowtracing.adoc | 351 +++++++++------------
1 file changed, 152 insertions(+), 199 deletions(-)
diff --git a/src/site/antora/modules/ROOT/pages/manual/flowtracing.adoc b/src/site/antora/modules/ROOT/pages/manual/flowtracing.adoc
index 1ba1875feb..0b21f7d8ad 100644
--- a/src/site/antora/modules/ROOT/pages/manual/flowtracing.adoc
+++ b/src/site/antora/modules/ROOT/pages/manual/flowtracing.adoc
@@ -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"?>
@@ -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.