WildFly logging: don't output classname (to preseve log message indentation) from a war file

Question

Requirements

The OptaPlanner logs are much more readable with preserved indentation:

10:34:46,442 INFO  Solving started: time spent (11), best score (-72init/0hard/0medium/0soft), environment mode (REPRODUCIBLE), random (JDK with seed 0).
10:34:46,467 DEBUG     CH step (0), time spent (36), score (-71init/0hard/-1000medium/0soft), selected move count (7), picked move (Day-0(0) {null -> Micha}).
10:34:46,474 DEBUG     CH step (1), time spent (43), score (-70init/0hard/-1414medium/-1000soft), selected move count (7), picked move (Day-0(1) {null -> Angelika}).
                       ... // 70 lines
10:34:46,608 DEBUG     CH step (71), time spent (177), score (0hard/-27239medium/-23706soft), selected move count (7), picked move (Day-17(3) {null -> Katrin}).
10:34:46,610 INFO  Construction Heuristic phase (0) ended: time spent (179), best score (0hard/-27239medium/-23706soft), score calculation speed (3023/sec), step total (72).
10:34:46,624 DEBUG     LS step (0), time spent (193), score (0hard/-27239medium/-23706soft),     best score (0hard/-27239medium/-23706soft), accepted/selected move count (1/25), picked move (Day-9(1) {Irene} <-> Day-15(1) {Susi}).
10:34:46,628 DEBUG     LS step (1), time spent (197), score (0hard/-27239medium/-23706soft),     best score (0hard/-27239medium/-23706soft), accepted/selected move count (1/17), picked move (Day-6(1) {Irene} <-> Day-6(2) {Kristina}).
                       ... // 643 lines
10:34:47,486 DEBUG     LS step (644), time spent (1055), score (-1hard/-27239medium/-23748soft),     best score (0hard/-27239medium/-23706soft), accepted/selected move count (0/1), picked move (Day-7(0) {Tobias} <-> Day-1(1) {Angelika}).
10:34:47,486 INFO  Local Search phase (1) ended: time spent (1055), best score (0hard/-27239medium/-23706soft), score calculation speed (14085/sec), step total (645).
10:34:47,487 INFO  Solving ended: time spent (1056), best score (0hard/-27239medium/-23706soft), score calculation speed (12124/sec), phase total (2), environment mode (REPRODUCIBLE).

The indentation above visualizes the begin and end of the outer loop. With the indentation in the example above it's hard to recognize when each phase ends, etc. This is even worse with TRACE logging, which also show the inner loop indentated deeper.

Therefore my logback.xml pattern uses <pattern>%d [%t] %-5p %m%n</pattern>.

The problem

WildFly (and other application servers) ignore my logback dependency and my logback.xml file and force me a logging pattern that includes the classname, which breaks my indentation:

10:50:51,317 INFO  [org.optaplanner.core.impl.solver.DefaultSolver] (EE-ManagedExecutorService-default-Thread-1) Solving started: time spent (60), best score (-62init/0hard/0soft), environment mode (REPRODUCIBLE), random (JDK with seed 0).
10:50:51,368 INFO  [org.optaplanner.openshift.employeerostering.server.solver.WannabeSolverManager] (EE-ManagedExecutorService-default-Thread-1)   New best solution found for rosterId (-1).
10:50:51,368 INFO  [org.optaplanner.core.impl.constructionheuristic.DefaultConstructionHeuristicPhase] (EE-ManagedExecutorService-default-Thread-1) Construction Heuristic phase (0) ended: time spent (112), best score (0hard/0soft), score calculation speed (42568/sec), step total (62).
10:50:58,986 INFO  [org.optaplanner.core.impl.localsearch.DefaultLocalSearchPhase] (EE-ManagedExecutorService-default-Thread-1) Local Search phase (1) ended: time spent (7730), best score (0hard/0soft), score calculation speed (331097/sec), step total (2520642).
10:50:58,986 INFO  [org.optaplanner.core.impl.solver.DefaultSolver] (EE-ManagedExecutorService-default-Thread-1) Solving ended: time spent (7730), best score (0hard/0soft), score calculation speed (326366/sec), phase total (2), environment mode (REPRODUCIBLE).

I can't read that, it's way too verbose for me. The last line has 113 characters of overhead before I can read the only thing that really matters "Solving ended". Scroll to the right to see it.

How can I change the logging pattern in my war file for my app? I am using OpenShift (which provides a WildFly instance for me), so I can't mess around in the Wildfly configuration itself.

False solutions

Adding jboss-deployment-structure.xml to exclude <subsystem name="logging" /> does not help, because then I get this ugly output that mentions my entire timestamp and the thread name twice per line:

10:46:19,236 INFO  [stdout] (EE-ManagedExecutorService-default-Thread-1) 2017-05-22 10:46:19,236 [EE-ManagedExecutorService-default-Thread-1] DEBUG     LS step (95814), time spent (4026), score (0hard/0soft),     best score (0hard/0soft), accepted/selected move count (1/1), picked move (Fort Collins 2017-02-01T06:00-14:00 {Jay Cole} <-> Saint Peter 2017-02-01T06:00-14:00 {Ivy Cole}).
10:46:19,236 INFO  [stdout] (EE-ManagedExecutorService-default-Thread-1) 2017-05-22 10:46:19,236 [EE-ManagedExecutorService-default-Thread-1] DEBUG     LS step (95815), time spent (4026), score (0hard/0soft),     best score (0hard/0soft), accepted/selected move count (1/1), picked move (Saint Peter 2017-02-01T06:00-14:00 {Jay Cole} <-> Santa Barbara 2017-02-01T14:00-22:00 {Flo Li}).
10:46:19,236 INFO  [stdout] (EE-ManagedExecutorService-default-Thread-1) 2017-05-22 10:46:19,236 [EE-ManagedExecutorService-default-Thread-1] DEBUG     LS step (95816), time spent (4026), score (0hard/0soft),     best score (0hard/0soft), accepted/selected move count (1/1), picked move (Los Angeles 2017-02-02T06:00-14:00 {Ivy Cole -> Elsa King}).

score 1 · Answer 1 · answered May 23 '17 at 18:12

With WildFly you can include a logging.properties file in your WAR in the WAR/WEB-INF/classes directory. Unfortunately the format for the properties file is not well documented. There is some unofficial documentation. Below is an example however.

loggers=

logger.level=INFO
logger.handlers=CONSOLE

handler.CONSOLE=org.jboss.logmanager.handlers.ConsoleHandler
handler.CONSOLE.level=INFO
handler.CONSOLE.formatter=PATTERN
handler.CONSOLE.properties=autoFlush,target,enabled
handler.CONSOLE.autoFlush=true
handler.CONSOLE.target=SYSTEM_OUT
handler.CONSOLE.enabled=true

formatter.PATTERN=org.jboss.logmanager.formatters.PatternFormatter
formatter.PATTERN.properties=pattern
formatter.PATTERN.pattern=%d{HH:mm:ss,SSS} [%t] %-5p %m%n

Note that the [%t] is the pattern for the thread name which may throw off the formatting you're looking for a bit.

That looks like the log4j 1.x format. Log4j 1 is dead for many years now. — Geoffrey De Smet, May 24 '17 at 12:55

score 1 · Accepted Answer · answered May 28 '17 at 11:06

You can easily adjust server log output to your liking using the JBoss configuration of logging sub-system. One of the advantages of this approach is that you can change/update it on runtime without having to redeploy your app or restart the server and that you can manage all your logging configuration from single place.
You did not specify, whether you want to change the output globally, or whether you have a specific log file, that stores your optaplanner logs. I would suggest to create a dedicated log with the format you request, while still preserving the default logs(with class names) in case you need it for some troubleshooting or some automated log processing. You can easily adjust this if your requirements are different. For our purpose, we need to setup a custom handler and category. Category usually corresponds to class or package and handler defines how are the log messages processed(e.g. to file, to console,...).
First, lets create a handler, that omits the class name from message entry. Via JBoss CLI we can do so with the following command:

/subsystem=logging/periodic-rotating-file-handler=OPTAPLANNER:add(append=true,formatter= "%d{HH:mm:ss,SSS} %-5p (%t) %s%e%n", suffix=".yyyy-MM-dd",file={path="opta.log",relative-to="jboss.server.llog.dir"},level=ALL)

This handler will output all messages to file opta.log within your server log directory. The file will be rolled every day at midnight and a cusrrent date will be appended as suffix. Formatter that we specified, omits the class name altogether and you can easily customize it to your needs.

Now we create a handler for classes within org.optaplanner package: via JBoss CLI you can define a custom category like so:

/subsystem=logging/logger=org.optaplanner:add(category=org.optaplanner,level=INFO,handlers=[OPTAPLANNER])

With this configuration, all log messages from org.optaplanner.* should be redirected to dedicated OPTAPLANNER handler, as well as to two default handlers(FILE and CONSOLE).

All operations could have been done via nice web based admin console of wildfly(available on http://server:9990) if that is what you prefer.

For more info, look at wildfly docs.

Any way I can do the same thing in the `.war` file, for example through `WEB-INF`? I am deploying towards OpenShift, so pods are created ad hoc, so I can't use JBoss CLI to do lasting changes such as this one. — Geoffrey De Smet, Jun 07 '17 at 22:30
JBoss stores all its conf in standalone.xml - which you have full access to on openshift via `{git repo}/.openshift/config/standalone.xml`. so just add your handler and logger directly to the logging subsystem in that file. I can update the answer with corresponding entries if it helps. — yntelectual, Jun 08 '17 at 05:42

WildFly logging: don't output classname (to preseve log message indentation) from a war file

2 Answers2