wildflylogbackslf4joptaplannerjboss-logging

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


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}).

Solution

  • 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.