Unexpected error occurred in scheduled task - NullPointerException - when custom logging is applied

[mhdirkse]

I started the Frank!Framework with Docker with custom logging configured. My custom log4j2 appender was applied, but a NullPointerException occurred that seemed to be related to Ladybug. Here is the FF! version I am using:

FF! 8.3.0-20240830.042323: my-config Running on 995905131da0 using Apache Tomcat/10.1.28 Java Version: OpenJDK Runtime Environment (21.0.4+7-LTS) Heap size: 145.2 MiB, total JVM memory: 214.0 MiB Free memory: 68.8 MiB, max memory: 2.0 GiB Free disk space: 36.9 GiB, total disk space: 58.4 GiB Up since: 2024-09-09 16:47:05 (14s)

Here is a piece of logging:

customlogging-my-config-1  | MYLAYOUTUnexpected error occurred in scheduled task
customlogging-my-config-1  | java.lang.NullPointerException: Cannot invoke "nl.nn.testtool.TestTool.close(long, long, boolean, boolean, long, long)" because "this.testTool" is null
customlogging-my-config-1  |    at nl.nn.testtool.CloseReportsTask.closeReports(CloseReportsTask.java:43) ~[ibis-ladybug-3.0-20240806.151958.jar:3.0-20240806.151958]
customlogging-my-config-1  |    at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(Unknown Source) ~[?:?]
customlogging-my-config-1  |    at java.base/java.lang.reflect.Method.invoke(Unknown Source) ~[?:?]
customlogging-my-config-1  |    at org.springframework.scheduling.support.ScheduledMethodRunnable.runInternal(ScheduledMethodRunnable.java:130) ~[spring-context-6.1.12.jar:6.1.12]
customlogging-my-config-1  |    at org.springframework.scheduling.support.ScheduledMethodRunnable.lambda$run$2(ScheduledMethodRunnable.java:124) ~[spring-context-6.1.12.jar:6.1.12]
customlogging-my-config-1  |    at io.micrometer.observation.Observation.observe(Observation.java:499) ~[micrometer-observation-1.13.3.jar:1.13.3]
customlogging-my-config-1  |    at org.springframework.scheduling.support.ScheduledMethodRunnable.run(ScheduledMethodRunnable.java:124) ~[spring-context-6.1.12.jar:6.1.12]
customlogging-my-config-1  |    at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54) ~[spring-context-6.1.12.jar:6.1.12]
customlogging-my-config-1  |    at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source) ~[?:?]
customlogging-my-config-1  |    at java.base/java.util.concurrent.FutureTask.runAndReset(Unknown Source) ~[?:?]
customlogging-my-config-1  |    at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Unknown Source) ~[?:?]
customlogging-my-config-1  |    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) ~[?:?]
customlogging-my-config-1  |    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) ~[?:?]
customlogging-my-config-1  |    at java.base/java.lang.Thread.run(Unknown Source) [?:?]

The string MYLAYOUT comes from my custom appender. I have a file my-log4j2.yaml with the following contents:

Configuration:
  Appenders:
    Console:
      name: Customized-stdout
      target: SYSTEM_OUT
      PatternLayout:
        Pattern: "MYLAYOUT%m%n"
  Loggers:
    Root:
      AppenderRef:
        ref: Customized-stdout

And my docker compose file sets the property to use it:

services:
  my-config:
    image: frankframework/frankframework:8.3.0-SNAPSHOT
    ports:
      - 8080:8080
    volumes:
      - ./configurations:/opt/frank/configurations
      - ./my-log4j2.yaml:/opt/frank/my-log4j2.yaml
      - ./my-log4j2.xml:/opt/frank/my-log4j2.xml
      # - ./lib/log4j-core-2.24.0.jar:/usr/local/tomcat/lib/log4j-core-2.24.0.jar
    environment:
      instance.name: my-config
      dtap.stage: LOC
      configurations.directory.autoLoad: true
      log4j.configurationFile: log4j4ibis.xml,file:///opt/frank/my-log4j2.yaml

I also tried an .xml custom log configuration. Then in addition to the NPE my appender did not work. I propose we first fix the NPE so that other issues with logging are easier to debug.

Here is the full code: https://github.com/frankframework/frank-manual/tree/logging-for-issue/src/customLogging.

[jacodg]

Duplicate of https://github.com/wearefrank/ladybug/issues/257 It's strange that the Spring scheduler calls the task before the bean is initialized. I could not reproduce it in the test webapp. Documented and fixed it in https://github.com/wearefrank/ladybug/commit/5d16619d6663b2cf18ca2a01747372ebd4b6e719

[jacodg]

See https://github.com/wearefrank/ladybug/issues/257#issuecomment-2349531654