Possible bug: Logging on 2023.12.31 produce invalid log entries 2024.12.31

[jk-1]

I have simple backup tool written in scala. Run command is:

java -Xmx6144m -Dlogback.configurationFile=/home/jk/binh/BckpTool.xml -cp /home/jk/bin2/BckpTool/BckpTool-assembly-1.0.jar

Part of the build.sbt file with versions is below:

lazy val logbackV = "1.2.3" 
lazy val slf4j_apiV = "1.7.25"
lazy val joda_timeV = "2.9.9"

libraryDependencies ++= Seq(
  "joda-time" % "joda-time" % joda_timeV withSources() withJavadoc(), 
  "ch.qos.logback" % "logback-classic" % logbackV withSources() withJavadoc(), 
  "ch.qos.logback" % "logback-core" % logbackV withSources() withJavadoc(), 
  "ch.qos.logback" % "logback-access" % logbackV withSources() withJavadoc(), 
  "org.slf4j" % "slf4j-api" % slf4j_apiV withSources() withJavadoc(), 
)

parts of the BckpTool.scala is below:

import org.slf4j.{Logger, LoggerFactory}
import org.joda.time.{DateTime, Duration}

object BckpTool {
  val log: Logger  = LoggerFactory.getLogger(getClass())
 
  // lines deleted...
  
  // logging lines:
  // line 484:
  // This is current system millisecond time using ISOChronology in the default time zone.
  // See https://www.joda.org/joda-time/apidocs/org/joda/time/DateTime.html
  val dt1 = new DateTime() 
  log.debug(GenUtil.currentMethodName + " Begin: " + dt1.toString )
 
  // lines deleted...

  // line 596:
  val summaryLog = LoggerFactory.getLogger("SummaryLog") 
    summaryLog.info("cpVM " + copyVMArgs.srcPath + " " + copyVMArgs.vMName + " " + copyVMArgs.dstPath + " " + copyVMArgs.vMNameExtension.getOrElse("") + " " + ( if ( copyVMArgs.stopIfTargetExists ) "Y" else "N" ) + " " + ( copyVMArgs.vMSuspendSleepTime / 1000 ) +
        "  ==>>  " + labelStr + "  Runtime " + durationStr)
}

Content of /home/jk/binh/BckpTool.xml

<configuration>

  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
      <level>DEBUG</level>
    </filter>
    <!-- encoders are assigned the type
         ch.qos.logback.classic.encoder.PatternLayoutEncoder by default -->
    <encoder>
      <pattern>%d{YYYY.MM.dd HH:mm:ss.SSS} [%thread] %-5level %logger{36} [%file:%line] - %msg%n</pattern>
    </encoder>
  </appender>

  <appender name="FILE1" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <file>/home/jk/tmp/cpVM.log</file>

    <encoder>
      <pattern>%d{YYYY.MM.dd HH:mm:ss.SSS} [%thread] %-5level %logger{36} [%file:%line] - %msg%n</pattern>
    </encoder>

    <rollingPolicy class="ch.qos.logback.core.rolling.FixedWindowRollingPolicy">
        <FileNamePattern>/home/jk/tmp/cpVM.%i.log.zip</FileNamePattern>
        <MinIndex>1</MinIndex>
        <MaxIndex>5</MaxIndex>
    </rollingPolicy>
 
    <triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">
        <MaxFileSize>10MB</MaxFileSize>
    </triggeringPolicy>
  </appender>

  <appender name="FILE2" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <file>/home/jk/tmp/cpVMSummary.log</file>

    <encoder>
      <pattern>%d{YYYY.MM.dd HH:mm:ss.SSS} [%thread] %-5level %logger{36} [%file:%line] - %msg%n</pattern>
    </encoder>

    <rollingPolicy class="ch.qos.logback.core.rolling.FixedWindowRollingPolicy">
        <FileNamePattern>/home/jk/tmp/cpVMSummary.%i.log.zip</FileNamePattern>
        <MinIndex>1</MinIndex>
        <MaxIndex>5</MaxIndex>
    </rollingPolicy>
 
    <triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">
        <MaxFileSize>10MB</MaxFileSize>
    </triggeringPolicy>

  </appender>

  <root level="debug">
    <appender-ref ref="FILE1" />
    <appender-ref ref="STDOUT" />
  </root>

  <logger name="SummaryLog" level="debug">
    <appender-ref ref="FILE2" />
  </logger>

</configuration>

Content of /home/jk/tmp/cpVMSummary.log

2023.12.28 03:08:37.245 [main] INFO  SummaryLog [BckpTool.scala:596] - cpVM /home/jk/VM U22-tra /home/jk/usbbckpdev/VM-bckp 01 N 0  ==>>  Backup_A4  Runtime 25min 23sec 
2023.12.30 02:22:11.116 [main] INFO  SummaryLog [BckpTool.scala:596] - cpVM /home/jk/VM U22-tra /home/jk/usbbckpdev/VM-bckp 03 N 0  ==>>  Backup_A4  Runtime 1h 1min 20sec 
2024.12.31 01:59:09.151 [main] INFO  SummaryLog [BckpTool.scala:596] - cpVM /home/jk/VM U22-tra /home/jk/ssd2t/home/jk/VM-bckp 02 N 0  ==>>  SSD2T  Runtime 28min 58sec 
2024.12.31 11:50:03.039 [main] INFO  SummaryLog [BckpTool.scala:596] - cpVM /home/jk/VM U22-tra /home/jk/usbbckpdev/VM-bckp 02 N 0  ==>>  Backup_B4  Runtime 1h 10min 10sec 
2024.01.02 00:53:49.304 [main] INFO  SummaryLog [BckpTool.scala:596] - cpVM /home/jk/VM U22-tra /home/jk/ssd2t/home/jk/VM-bckp 01 N 0  ==>>  SSD2T  Runtime 27min 36sec 

And short content of /home/jk/tmp/cpVM.log

2023.12.30 01:20:37.057 [main] INFO  Backup$ [Backup.scala:11] - cpVM /home/jk/binh/BckpTool.json
2023.12.30 01:20:50.526 [main] DEBUG com.mycomp.tools.BckpTool$ [BckpTool.scala:484] - copyVM Begin: 2023-12-30T01:20:50.506+02:00
...lines deleted...
2023.12.30 02:22:11.116 [main] INFO  SummaryLog [BckpTool.scala:596] - cpVM /home/jk/VM U22-tra /home/jk/usbbckpdev/VM-bckp 03 N 0  ==>>  Backup_A4  Runtime 1h 1min 20sec 
2023.12.30 02:22:11.117 [main] INFO  Backup$ [Backup.scala:19] - copyVM exitValue = 0
2024.12.31 01:29:57.422 [main] INFO  Backup$ [Backup.scala:11] - cpVM /home/jk/binh/BckpTool.json
2024.12.31 01:30:10.967 [main] DEBUG com.mycomp.tools.BckpTool$ [BckpTool.scala:484] - copyVM Begin: 2023-12-31T01:30:10.950+02:00
...lines deleted...
2024.12.31 01:59:09.151 [main] INFO  SummaryLog [BckpTool.scala:596] - cpVM /home/jk/VM U22-tra /home/jk/ssd2t/home/jk/VM-bckp 02 N 0  ==>>  SSD2T  Runtime 28min 58sec 
2024.12.31 01:59:09.152 [main] INFO  Backup$ [Backup.scala:19] - copyVM exitValue = 0
2024.12.31 10:39:37.361 [main] INFO  Backup$ [Backup.scala:11] - cpVM /home/jk/binh/BckpTool.json
2024.12.31 10:39:52.499 [main] DEBUG com.mycomp.tools.BckpTool$ [BckpTool.scala:484] - copyVM Begin: 2023-12-31T10:39:52.479+02:00
...lines deleted...
2024.12.31 11:50:03.039 [main] INFO  SummaryLog [BckpTool.scala:596] - cpVM /home/jk/VM U22-tra /home/jk/usbbckpdev/VM-bckp 02 N 0  ==>>  Backup_B4  Runtime 1h 10min 10sec 
2024.12.31 11:50:03.039 [main] INFO  Backup$ [Backup.scala:19] - copyVM exitValue = 0
2024.01.02 00:26:03.687 [main] INFO  Backup$ [Backup.scala:11] - cpVM /home/jk/binh/BckpTool.json
2024.01.02 00:26:12.874 [main] DEBUG com.mycomp.tools.BckpTool$ [BckpTool.scala:484] - copyVM Begin: 2024-01-02T00:26:12.855+02:00
...lines deleted...
2024.01.02 00:53:49.304 [main] INFO  SummaryLog [BckpTool.scala:596] - cpVM /home/jk/VM U22-tra /home/jk/ssd2t/home/jk/VM-bckp 01 N 0  ==>>  SSD2T  Runtime 27min 36sec 
2024.01.02 00:53:49.305 [main] INFO  Backup$ [Backup.scala:19] - copyVM exitValue = 0

Zoned/LocalDateTime and time zone using Ammonite Repl:

amm
Loading...
Welcome to the Ammonite Repl 2.4.0 (Scala 2.12.13 Java 17.0.9)

@ import java.time.LocalDateTime 
import java.time.LocalDateTime 

@ import java.time.ZonedDateTime 
import java.time.ZonedDateTime

@ ZonedDateTime.now() 
res3: ZonedDateTime = 2024-01-03T08:50:35.047248596+02:00[Europe/Helsinki]

@ LocalDateTime.now() 
res4: LocalDateTime = 2024-01-03T08:50:44.022873313

So both log files have entries with invalid date 2024.12.31 when it was 2023.12.31. Especially this line makes me wonder if there is a bug in the slf4j, in logback, in my comfiguration (or in joda time DateTime class):

2024.12.31 10:39:52.499 [main] DEBUG com.mycomp.tools.BckpTool$ [BckpTool.scala:484] - copyVM Begin: 2023-12-31T10:39:52.479+02:00

It seems that for some reason logging cannot handle year correctly on 2023.12.31. so logging on 2023.12.31 produce invalid log entries 2024.12.31.

Any ideas what is the problem here? Bug in lsf4j or in logback or in my config?