Quarkus: *Rotating*LoggingTest failures on Windows

[rsvoboda]

*Rotating*LoggingTest failures on Windows
Module: core/test-extension/deployment

Issue with strict file locking on Windows comparing to Linux.

Maybe something can be done in https://github.com/quarkusio/quarkus/blob/master/test-framework/junit5-internal/src/main/java/io/quarkus/test/QuarkusUnitTest.java#L278, but not really sure.

First executed *Rotating*LoggingTest passes, but but I guess it keeps the file locked.

Stacktrace:

2019-05-16 10:21:55,441 ERROR [null] (main) Failed to publish log record (GENERIC_FAILURE[0]):
  Failed to move file target\quarkus.log to target\quarkus.log2019-05-16.1.: 
  java.nio.file.FileSystemException: target\quarkus.log -> target\quarkus.log2019-05-16.1:
  The process cannot access the file because it is being used by another process.

        at sun.nio.fs.WindowsException.translateToIOException(WindowsException.java:86)
        at sun.nio.fs.WindowsException.rethrowAsIOException(WindowsException.java:97)
        at sun.nio.fs.WindowsFileCopy.move(WindowsFileCopy.java:387)
        at sun.nio.fs.WindowsFileSystemProvider.move(WindowsFileSystemProvider.java:287)
        at java.nio.file.Files.move(Files.java:1395)
        at org.jboss.logmanager.handlers.SuffixRotator.move(SuffixRotator.java:239)
        at org.jboss.logmanager.handlers.SuffixRotator.rotate(SuffixRotator.java:167)
        at org.jboss.logmanager.handlers.PeriodicRotatingFileHandler.rollOver(PeriodicRotatingFileHandler.java:194)
        at org.jboss.logmanager.handlers.PeriodicRotatingFileHandler.preWrite(PeriodicRotatingFileHandler.java:112)
        at org.jboss.logmanager.handlers.WriterHandler.doPublish(WriterHandler.java:57)
        at org.jboss.logmanager.ExtHandler.publish(ExtHandler.java:66)
        at org.jboss.logmanager.handlers.DelayedHandler.publishToChildren(DelayedHandler.java:208)
        at org.jboss.logmanager.handlers.DelayedHandler.doPublish(DelayedHandler.java:49)
        at org.jboss.logmanager.ExtHandler.publish(ExtHandler.java:66)
        at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:316)
        at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:324)
        at org.jboss.logmanager.Logger.logRaw(Logger.java:748)
        at org.jboss.logmanager.Logger.log(Logger.java:706)
        at org.jboss.logging.JBossLogManagerLogger.doLogf(JBossLogManagerLogger.java:53)
        at org.jboss.logging.Logger.infof(Logger.java:1136)
        at io.quarkus.extest.runtime.RuntimeXmlConfigService.startService(RuntimeXmlConfigService.java:34)
        at io.quarkus.extest.runtime.TestTemplate.startRuntimeService(TestTemplate.java:65)
        at io.quarkus.deployment.steps.TestProcessor$startRuntimeService53.deploy(Unknown Source)
        at io.quarkus.runner.ApplicationImpl3.doStart(Unknown Source)
        at io.quarkus.runtime.Application.start(Application.java:100)
        at io.quarkus.runner.RuntimeRunner.run(RuntimeRunner.java:122)
        at io.quarkus.test.QuarkusUnitTest.beforeAll(QuarkusUnitTest.java:224)

[gsmet]

Looks like a JBoss Logging issue to me. @dmlloyd WDYT?

[rsvoboda]

I did small app which generates log entries and logs are properly rotated.
So I think it's more testsuite issue tbh. Anyway, lets hear from David.

[rsvoboda]

The app had this bean:

@ApplicationScoped
public class VerboseBean {
    final Logger logger = Logger.getLogger("io.quarkus");
    @Scheduled(every="1s")
    void xxx() {
        for (int i = 0; i < 25; i++) {
            logger.infof("Lorem Ipsum %s", i);
        }
    }
}

Executed with java -Dquarkus.log.level=ALL -Dquarkus.log.file.enable=true -Dquarkus.log.file.level=INFO -Dquarkus.log.file.rotation.max-file-size=9024 -Dquarkus.log.file.rotation.rotate-on-boot=false -Dquarkus.log.file.rotation.max-backup-index=10 -Dquarkus.log.file.rotation.file-suffix=yyyy-MM-dd -jar target\getting-started-1.0-SNAPSHOT-runner.jar command

[dmlloyd]

Maybe there are multiple tests running at once in the same directory? BTW it looks like we might want to fix that suffix from YYYY-MM-DD to .YYYY-MM-DD...

James's rotation code uses java.nio.file.Files#move so it doesn't hold it open AFAICT. Maybe the CI environment is opening these files for printing to the console? It would be nice if we could tell what other process was holding the file open.

Nice to see that error handler working as expected.

[rsvoboda]

I think it is NTFS related so maybe that's why we don't see it on CI.

[dmlloyd]

I think it is NTFS related so maybe that's why we don't see it on CI.

Ah I misread the issue. I thought we did see it on CI. Is CI not using NTFS then?

[dmlloyd]

I wonder, is it failing to access the source file or the destination file?

/cc @jamezp by the way.

[rsvoboda]

@CI - It's there too ...

Weird thing about this issue is that it doesn't fail the build, there are just errors in log but the tests are marked as passed - [INFO] Quarkus - Core - Test Extension - Deployment ....... SUCCESS [ 13.676 s].

I looked at https://dev.azure.com/quarkus-ci/quarkus/_build/results?buildId=2002&view=logs - download the log - unzip it - open it - search for Failed to move file target

[rsvoboda]

File locking - Process Explorer can help - https://www.mysysadmintips.com/windows/clients/593-find-what-is-locking-a-file-using-sysinternals-process-explorer

[dmlloyd]

File locking - Process Explorer can help - https://www.mysysadmintips.com/windows/clients/593-find-what-is-locking-a-file-using-sysinternals-process-explorer

I'll have to leave it to those of you who have Windows available :)

[rsvoboda]

Everybody has :) Our CI ...

I don't have bandwidth to look into this today, but I will dig a bit more tmr.

For now I did https://github.com/quarkusio/quarkus/pull/2466

[jamezp]

Looking at the properties file I don't see a file name specified. I assume it must get a default name of some sort. What the issue might be is the rotated file, whatever.logyyyy-MM-dd, is in use by something like a virus scanner so it can't be deleted then created during the move.

[machi1990]

Looking at the properties file I don't see a file name specified. I assume it must get a default name of some sort.

I think this could be the cause of the issue. Since file name is not specified, quarkus.log is picked by the four *FileHandler* tests cases: .

I am not on Windows, but what I would also try is to specify different file paths for each test case: I pushed a commit here. Can someone on Windows check if that fixes the issue?

[rsvoboda]

Yes, quarkus.log is picked by the three tests cases. Customization of file name doesn't work in tests.
I tried to define quarkus.log.file.path=xxx.log but the log file was still quarkus.log

It's because of PropertyTestUtil.setLogFileProperty(); in QuarkusUnitTest which sets quarkus.log.file.path to target/quarkus.log
See https://github.com/quarkusio/quarkus/blob/master/test-framework/common/src/main/java/io/quarkus/test/common/PropertyTestUtil.java#L24

I added thread sleep to one test and used Process Explorer to find process which holds that file and it was surefire process, there were 3 entries for that process for that quarkus.log file.

I'm considering second constructor for QuarkusUnitTest to add log file name. Any better idea ?
Scan of exported archive is possible too, but isn't it just too much work to be done with every test?

[rsvoboda]

@machi1990 your code proposal won't work because of PropertyTestUtil.java as I wrote above ...

[rsvoboda]

So I have prepared this change: https://github.com/rsvoboda/quarkus/commit/ac8fbc0ac33ce687847d7b9fe93b69ba067f6e45

It works nicely on Windows Server 2016.

@dmlloyd > we might want to fix that suffix from YYYY-MM-DD to .YYYY-MM-DD
I did this change for the tests in ^^^
Should we add it as default value for fileSuffix in https://github.com/quarkusio/quarkus/blob/master/core/runtime/src/main/java/io/quarkus/runtime/logging/FileConfig.java#L76 ?

[gsmet]

Should we add it as default value for fileSuffix?

IIRC, the rotation feature is enabled if it is defined so we can't define a default. But we could certainly improve the javadoc with an example.