Wildfly 10.1.0.Final stops logging

[coenenpe]

Hi,

Our Wildfly 10.1.0.Final server sometimes stops logging to a certain Periodic-file-handler after rotating a file.

The problem didn't occur for months but now it pops up regularly.

Going through the code it looks like the PeriodicSizeRotatingFileHandler crashes during a rotate because he can't move a certain file.

It says that the file is being used by another process, but I have no idea which process that could be. I even think it's detecting itself.

It happens on a Windows-Server 2012 R2 server but also on my developer-pc (Windows 7).

The following exception is visible:

[Server:server-one] LogManager error of type OPEN_FAILURE: Unable to rotate log file
[Server:server-one] java.nio.file.FileSystemException: W:\wildfly\domain\servers\server-one\log\server.log -> W:\wildfly\domain\servers\serv
er-one\log\server.log.2017-05-02.1: The process cannot access the file because it is being used by another process.
[Server:server-one]
[Server:server-one]     at sun.nio.fs.WindowsException.translateToIOException(WindowsException.java:86)
[Server:server-one]     at sun.nio.fs.WindowsException.rethrowAsIOException(WindowsException.java:97)
[Server:server-one]     at sun.nio.fs.WindowsFileCopy.move(WindowsFileCopy.java:387)
[Server:server-one]     at sun.nio.fs.WindowsFileSystemProvider.move(WindowsFileSystemProvider.java:287)
[Server:server-one]     at java.nio.file.Files.move(Files.java:1395)
[Server:server-one]     at org.jboss.logmanager.handlers.PeriodicSizeRotatingFileHandler.rotate(PeriodicSizeRotatingFileHandler.java:251)
[Server:server-one]     at org.jboss.logmanager.handlers.PeriodicSizeRotatingFileHandler.preWrite(PeriodicSizeRotatingFileHandler.java:232)
[Server:server-one]     at org.jboss.logmanager.handlers.WriterHandler.doPublish(WriterHandler.java:60)
[Server:server-one]     at org.jboss.logmanager.ExtHandler.publish(ExtHandler.java:76)
[Server:server-one]     at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:314)
[Server:server-one]     at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:322)
[Server:server-one]     at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:322)
[Server:server-one]     at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:322)
[Server:server-one]     at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:322)
[Server:server-one]     at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:322)
[Server:server-one]     at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:322)
[Server:server-one]     at org.jboss.logmanager.Logger.logRaw(Logger.java:850)
[Server:server-one]     at org.slf4j.impl.Slf4jLogger.log(Slf4jLogger.java:326)
[Server:server-one]     at org.slf4j.impl.Slf4jLogger.log(Slf4jLogger.java:320)
[Server:server-one]     at org.slf4j.impl.Slf4jLogger.debug(Slf4jLogger.java:159)

My config:

 <periodic-size-rotating-file-handler name="FILE" autoflush="true">
                    <formatter>
                        <named-formatter name="PATTERN"/>
                    </formatter>
                    <file relative-to="jboss.server.log.dir" path="server.log"/>
                    <rotate-size value="10000"/>
                    <max-backup-index value="10"/>
                    <suffix value=".yyyy-MM-dd"/>
                    <append value="true"/>
                </periodic-size-rotating-file-handler>

Pom:

<dependency>
   <groupId>org.slf4j</groupId>
   <artifactId>slf4j-api</artifactId>
   <version>1.7.7</version>
   <scope>provided</scope>
</dependency>

Do you have any idea how I can solve this?

Many thanks in advance!

Peter

[mayerw01]

I don't think it is the 'same' process that locks the file.

But to approach this issue I'd suggest to use the Windows Resource Monitor.

In the search field on the CPU tab you may enter the name of the file that causes this issue.

[coenenpe]

Hi thanks for your response.

I think I found the problem:

jamezp I checked the code on Github and it seems you changed the code in release Jboss-Logmanager 2.0.4. (Default used by Wildfly 10.1.0.final).

In release 2.0.3 (version used by Wildfly 10.0, which was working fine) the file was getting 'renamed' when rotating, but in release 2.0.4 you're moving the file. This causes problems on Windows machines.

The change happened in commit : "[LOGMGR-125] Move files instead of renaming to ensure they're overwrite, https://github.com/jamezpcommitted on 21 Oct 2015, https://github.com/jboss-logging/jboss-logmanager/commit/57c59c02290e30f07080110e5c690d72dca535ae

Can you propose a fix for this?

For now, can I safely downgrade the logging library to 2.0.3? What's the best approach in doing this? Do I just overwrite the Jboss-logmanager lib with version 2.0.3 or do I need to change other things as well?

[jamezp]

Do you have an anti-virus running? I've seen issues before where the anti-virus has a lock on the file so it can't be moved.

Maybe the handler itself should be more resilient to failed rotations. Feel free to file a bug if you feel it should be more resilient.

For now, can I safely downgrade the logging library to 2.0.3? What's the best approach in doing this? Do I just overwrite the Jboss-logmanager lib with version 2.0.3 or do I need to change other things as well?

It should be fairly safe to downgrade, but note that the issue may just appear to go away. It's likely the file itself won't rotate at all, it just may not throw an exception.

To do the downgrade you'd have to replace the jboss-logmanager-$version.jar with the version you want to use and change the module.xml to point to the correct resource. That should be it though.

--

James R. Perkins

[coenenpe]

Hi,

We don't have an anti-virus running on the server. The file rotation is succesfull 99% of the time.

The name shifting of the other files prior to the move are succesfully as well, once the exception occurs the whole logging stops and the Wildfly server should be restarted to get it going again.

Even with the exception thrown, saying that the 'file is in use' we notice that the file is actually succesfully moved.

With version 2.0.3 I've never seen a 'bad rotation', so I think it's related to the new file moving code.

[jamezp]

The reason it likely shows up in the new code is the Files.move() will throw an exception where as java.io.File.renameTo() will not. I would imagine the same issue would exist it would just be hidden instead. I'll explore if there are some custom options for Windows or what the ATOMIC_MOVE copy option does on Windows.

I did go ahead a file a JIRA to allow the rotations to be more resilient to failures, [LOGMGR-154] Log rotations should be more resilient to failed rotations - JBoss Issue Tracker..

FWIW while it's likely a pain you could probably just use a write-attribute(name=file, file={relative-to=jboss.server.log.dir, path=server.log}) operation. This should reset the file and allow the handler to start working again without having to reload the server.

--

James R. Perkins

[coenenpe]

James,

Thank you for your response and for filing the bug!

I'll upgrade our server as soon as the bug is resolved.

Kind regards,

Peter

[icemaker]

We have the same problem here.

Wildlfy 9.0.2-Final.

We needed to upgrade jboss-logmanager from 2.0.3 to 2.0.4 to fix a problem with ELK.

Since then we also noticed the same problem where the server sometimes stops logging when using size-rotating-file-handler.

Never had this problem with 2.0.3

[jamezp]

Is WildFly running on Windows? It's likely the same issue described above.

--

James R. Perkins

[icemaker]

Yes our Wildlfy is running on Windows.

Strangely I get the exception written in the log only when I restarted the server 10 days later :

My server was restarted on 2017-06-08 and the log file named wildfly-stderr.2017-05-29.log was generated (yes on the 2017-06-08 !) with this exception :

2017-05-29 11:01:48 Commons Daemon procrun stderr initialized

LogManager error of type OPEN_FAILURE: Unable to rotate log file

java.nio.file.FileSystemException: C:\wildfly-9.0.2.Final\standalone\log\server.log -> C:\wildfly-9.0.2.Final\standalone\log\server.log.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)

[icemaker]

Sorry I meant the file wildfly-stderr.2017-05-29.log was updated and not generated  (Cannot find a way to edit my previous message)

[jamezp]

Great information thanks! I do think this is a Windows issue, whether it's with the JVM's FileSystem implementation or Windows itself I'm not sure. Either way the log manager should definitely be fixed to deal with a rotation failure better.

--

James R. Perkins