Loading...

Details

Type: Bug
Resolution: Done
Priority: Major
Fix Version/s: 1.5.10.Final, 2.0.12.Final, 2.1.14.Final, 3.0.0.Alpha1
Affects Version/s: 2.1.13.Final
Component/s: None
Labels:
None

Git Pull Request:
https://github.com/jboss-logging/jboss-logmanager/pull/263, https://github.com/jboss-logging/jboss-logmanager/pull/264, https://github.com/jboss-logging/jboss-logmanager/pull/265, https://github.com/jboss-logging/jboss-logmanager/pull/266, https://github.com/jboss-logging/jboss-logmanager/pull/267

Description

I've run into a similar error to the one described in ~~LOGMGR-154~~, using the jboss-logmanager 2.1.13.Final release on a system that's still running Windows 7.

Of note: The server.log file is configured to be rotated on boot.

LogManager error of type GENERIC_FAILURE: Failed to move file C:\wildfly\standalone\log\server.log to C:\wildfly\standalone\log\server.log.1.
java.nio.file.FileSystemException: C:\wildfly\standalone\log\server.log -> C:\wildfly\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)
	at org.jboss.logmanager.handlers.SuffixRotator.move(SuffixRotator.java:246)
	at org.jboss.logmanager.handlers.SuffixRotator.rotate(SuffixRotator.java:174)
	at org.jboss.logmanager.handlers.SuffixRotator.rotate(SuffixRotator.java:233)
	at org.jboss.logmanager.handlers.SuffixRotator.rotate(SuffixRotator.java:193)
	at org.jboss.logmanager.handlers.SizeRotatingFileHandler.setFile(SizeRotatingFileHandler.java:142)
	at org.jboss.logmanager.handlers.FileHandler.setFileName(FileHandler.java:189)
	at sun.reflect.GeneratedMethodAccessor6.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.jboss.logmanager.config.AbstractPropertyConfiguration$1.applyPostCreate(AbstractPropertyConfiguration.java:217)
	at org.jboss.logmanager.config.AbstractPropertyConfiguration$1.applyPostCreate(AbstractPropertyConfiguration.java:197)
	at org.jboss.logmanager.config.LogContextConfigurationImpl.doApplyPostCreate(LogContextConfigurationImpl.java:313)
	at org.jboss.logmanager.config.LogContextConfigurationImpl.doPrepare(LogContextConfigurationImpl.java:345)
	at org.jboss.logmanager.config.LogContextConfigurationImpl.prepare(LogContextConfigurationImpl.java:289)
	at org.jboss.as.logging.logmanager.ConfigurationPersistence.prepare(ConfigurationPersistence.java:299)
	at org.jboss.as.logging.LoggingOperations$CommitOperationStepHandler.execute(LoggingOperations.java:106)
	at org.jboss.as.controller.AbstractOperationContext.executeStep(AbstractOperationContext.java:999)
	at org.jboss.as.controller.AbstractOperationContext.processStages(AbstractOperationContext.java:743)
	at org.jboss.as.controller.AbstractOperationContext.executeOperation(AbstractOperationContext.java:467)
	at org.jboss.as.controller.OperationContextImpl.executeOperation(OperationContextImpl.java:1411)
	at org.jboss.as.controller.ModelControllerImpl.boot(ModelControllerImpl.java:521)
	at org.jboss.as.controller.AbstractControllerService.boot(AbstractControllerService.java:472)
	at org.jboss.as.controller.AbstractControllerService.boot(AbstractControllerService.java:434)
	at org.jboss.as.server.ServerService.boot(ServerService.java:435)
	at org.jboss.as.server.ServerService.boot(ServerService.java:394)
	at org.jboss.as.controller.AbstractControllerService$1.run(AbstractControllerService.java:374)
	at java.lang.Thread.run(Thread.java:748)

A similar error will also occur if a compression suffix is used, although it will be the Files.delete(File) instead the Files.move(File, File) call which will fail.

Debugging shows that SizeRotatingFileHandler.setFileName(String) is called once immediately during server boot (initialization via logging.properties) and again a short time after (via the logging subsystem I'm guessing).
This second call results in the error above, because the SizeRotatingFileHandler instance already holds a file lock via its outputStream field, but a rotation is still attempted, as the file should rotate on boot and already contains content at that point in time.

To confirm whether this process internal file lock is responsible, I additionally checked for other processes that might own such a handle. The only listed one is the Java process running Wildfly.

As far as I can tell, this kind of error case should be easily fixed by adding an additional setFileInternal(null) call to clean up the open lock before actually triggering the rotation, as seen in this snippet:

    public void setFile(final File file) throws FileNotFoundException {
        synchronized (outputLock) {
            // Check for a rotate
            if (rotateOnBoot && maxBackupIndex > 0 && file != null && file.exists() && file.length() > 0L) {
                setFileInternal(null);
                suffixRotator.rotate(getErrorManager(), file.toPath(), maxBackupIndex);
            }
            setFileInternal(file);
        }
    }

Manually adding the above mentioned call seems to allow everything to work as intended.

And while the fact that the second setting of the same file name triggers an additional log file rotation (as rotateOnBoot = true in the used configuration) slightly annoys me, that's probably a problem for a different followup bug.

Attachments

Issue Links

is incorporated by

WFCORE-4590 Upgrade jboss-logmanager from 2.1.13.Final to 2.1.14.Final

Closed

relates to

LOGMGR-246 Wildfly 16 incorrect working log zip rotator

Resolved

Failure to rotate logfile on Windows system because of already open file lock

Details

Description

Attachments

Issue Links

Activity

People

Dates