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