close handlers and free all associated resources. #5535

machi1990 · 2019-11-17T02:44:04Z

I noticed that the handlers were never closed while trying to figure out the causes for
#5522.

gsmet

Makes sense to me but let's have @dmlloyd check it.

dmlloyd · 2019-11-18T13:05:08Z

core/runtime/src/main/java/io/quarkus/runtime/Timing.java

+        /**
+         * We can safely close log handlers after stop time has been printed.
+         */
+        InitialConfigurator.DELAYED_HANDLER.close();


I would instead do something like:

for (Handler h : InitialConfigurator.DELAYED_HANDLER.clearHandlers()) { try { h.close(); } catch (Throwable ignored) { } }

This way a subsequent dev mode iteration is more likely to work correctly.

Okay, thanks for the feedback David. Let me do the change.

dmlloyd · 2019-11-18T13:53:27Z

Just waiting for CI now.

gastaldi · 2019-11-18T14:03:44Z

I tested in my Windows 10 VM and I still see the error. It seems to be a bug in JBoss Logging ? (I managed to reproduce it by reducing the quarkus.log.file.rotation.max-file-size):

2019-11-18 10:58:48,064 ERROR [null] (main) Failed to publish log record (GENERIC_FAILURE[0]): Failed to move file log\dataprocessor.log to log\dataprocessor.log.2019-11-18.1.: java.nio.file.FileSystemException: log\dataprocessor.log -> log\dataprocessor.log.2019-11-18.1: O arquivo já está sendo usado por outro processo.

        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.SuffixRotator.rotate(SuffixRotator.java:226)
        at org.jboss.logmanager.handlers.PeriodicSizeRotatingFileHandler.setFile(PeriodicSizeRotatingFileHandler.java:154)
        at org.jboss.logmanager.handlers.PeriodicSizeRotatingFileHandler.preWrite(PeriodicSizeRotatingFileHandler.java:224)
        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.LoggerNode.publish(LoggerNode.java:324)
        at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:324)
        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.logmanager.Logger.log(Logger.java:719)
        at org.jboss.logging.JBossLogManagerLogger.doLog(JBossLogManagerLogger.java:42)
        at org.jboss.logging.Logger.error(Logger.java:1507)
        at io.quarkus.dev.DevModeMain.doStart(DevModeMain.java:200)
        at io.quarkus.dev.DevModeMain.start(DevModeMain.java:95)
        at io.quarkus.dev.DevModeMain.main(DevModeMain.java:66)

dmlloyd · 2019-11-18T14:05:41Z

I guess we must be missing this recent commit: jboss-logging/jboss-logmanager@f2e0eb3

dmlloyd · 2019-11-18T14:05:55Z

I'll cherry-pick it and prep a release to go along with this change.

gastaldi · 2019-11-18T14:08:10Z

Stupid question, but isn't it easier to bump Quarkus to JBoss LogManager 2.1.14.Final?

dmlloyd · 2019-11-18T14:09:32Z

No, this bug is in the JBoss LogManager, not in the logging API. We have a fork of the JBoss LogManager with changes to support embedded bootstrapping that has to be brought up to date.

Before you ask, yes, I am working on upstreaming the changes so that we can go back to the upstream LogManager code at some point.

gastaldi · 2019-11-18T14:10:12Z

Awesome, I corrected my comment above after I realized it's JBoss Logmanager. Thanks!

dmlloyd · 2019-11-18T14:49:42Z

I've released jboss-logmanager-embedded version 1.0.4 with three rotation-related bug fixes picked from upstream. It should be up on central within 24 hours; feel free to update this PR with the updated version once it appears.

gastaldi · 2019-11-18T14:51:02Z

@machi1990 let me know when the PR is updated so I can test the changes in my Windows VM 😉

machi1990 · 2019-11-18T15:25:45Z

Thanks @dmlloyd @gastaldi I'll update the PR once jboss-logmanager-embedded is on central.

gsmet · 2019-11-18T16:10:11Z

@machi1990 just FYI, better refresh this page than rely on the various Maven Central UIs (they are lagging a bit): https://repo1.maven.org/maven2/org/jboss/logmanager/jboss-logmanager-embedded/

machi1990 · 2019-11-18T16:16:44Z

Thanks for the heads up @gsmet

gastaldi · 2019-11-18T16:29:16Z

@machi1990 You can also use https://www.artifact-listener.org/ to receive library updates in your e-mail or (as I do) use bash to do that for you 😉 https://gist.github.com/gastaldi/41bd76a2b539711a81943e3ff8254b1b

machi1990 · 2019-11-18T16:34:42Z

@machi1990 You can also use https://www.artifact-listener.org/ to receive library updates in your e-mail or (as I do) use bash to do that for you 😉 https://gist.github.com/gastaldi/41bd76a2b539711a81943e3ff8254b1b

Okay, this is super handy. Bookmarked. Thanks @gastaldi :-)

I noticed that the handlers were never closed while trying to figure out the causes for quarkusio#5522. Fixes quarkusio#5522

gsmet · 2019-11-18T16:36:40Z

Artifact Listener is updated at ~2:30pm Paris time every day so you have a delay too. I would know it, I created the project :).

machi1990 · 2019-11-18T16:38:20Z

I have updated the PR with the log manager update. CI should fail, until we have jboss-logmanager-embedded in central. I did this for convenience, this way I would just have to re-launch CI.

machi1990 · 2019-11-19T06:51:54Z

https://repo1.maven.org/maven2/org/jboss/logmanager/jboss-logmanager-embedded/ is up to date and version 1.0.4 is available. Asked for a CI re-run. Let's wait and see.

FYI @gsmet

machi1990 · 2019-11-19T09:07:56Z

CI green, let's merge this. @gsmet @dmlloyd

machi1990 · 2019-11-19T09:09:53Z

@machi1990 let me know when the PR is updated so I can test the changes in my Windows VM 😉

@gastaldi you wanted to test this.

Also @mcrose confirmed that this fixed the issue for him #5522 (comment)

machi1990 · 2019-11-19T09:36:28Z

Thanks @gsmet

machi1990 requested a review from dmlloyd November 17, 2019 02:44

machi1990 added the area/logging label Nov 17, 2019

gsmet mentioned this pull request Nov 17, 2019

LogManager GENERIC_FAILURE on Windows 10 #5522

Closed

gsmet approved these changes Nov 17, 2019

View reviewed changes

gsmet added the backport? label Nov 18, 2019

dmlloyd requested changes Nov 18, 2019

View reviewed changes

gastaldi added this to the 1.1.0 milestone Nov 18, 2019

machi1990 force-pushed the fix/5522 branch from 6c4452e to 4d02d9a Compare November 18, 2019 13:50

machi1990 requested a review from dmlloyd November 18, 2019 13:51

dmlloyd approved these changes Nov 18, 2019

View reviewed changes

fix(logging): close handlers and free all associated resources.

87eb7cf

I noticed that the handlers were never closed while trying to figure out the causes for quarkusio#5522. Fixes quarkusio#5522

machi1990 force-pushed the fix/5522 branch from 4d02d9a to 87eb7cf Compare November 18, 2019 16:35

machi1990 changed the title ~~fix(logging): close handlers and free all associated resources.~~ WIP: fix(logging): close handlers and free all associated resources. Nov 18, 2019

machi1990 changed the title ~~WIP: fix(logging): close handlers and free all associated resources.~~ WIP: close handlers and free all associated resources. Nov 18, 2019

machi1990 changed the title ~~WIP: close handlers and free all associated resources.~~ close handlers and free all associated resources. Nov 19, 2019

machi1990 added the triage/waiting-for-ci Ready to merge when CI successfully finishes label Nov 19, 2019

gsmet merged commit 1eb0423 into quarkusio:master Nov 19, 2019

gsmet removed the backport? label Nov 19, 2019

gsmet modified the milestones: 1.1.0, 1.0.0.Final Nov 19, 2019

machi1990 deleted the fix/5522 branch November 19, 2019 09:36

close handlers and free all associated resources. #5535

close handlers and free all associated resources. #5535

Uh oh!

Conversation

machi1990 commented Nov 17, 2019

Uh oh!

gsmet left a comment

Choose a reason for hiding this comment

Uh oh!

dmlloyd Nov 18, 2019

Choose a reason for hiding this comment

Uh oh!

machi1990 Nov 18, 2019

Choose a reason for hiding this comment

Uh oh!

dmlloyd commented Nov 18, 2019

Uh oh!

gastaldi commented Nov 18, 2019

Uh oh!

dmlloyd commented Nov 18, 2019

Uh oh!

dmlloyd commented Nov 18, 2019

Uh oh!

gastaldi commented Nov 18, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

dmlloyd commented Nov 18, 2019

Uh oh!

gastaldi commented Nov 18, 2019

Uh oh!

dmlloyd commented Nov 18, 2019

Uh oh!

gastaldi commented Nov 18, 2019

Uh oh!

machi1990 commented Nov 18, 2019

Uh oh!

gsmet commented Nov 18, 2019

Uh oh!

machi1990 commented Nov 18, 2019

Uh oh!

gastaldi commented Nov 18, 2019

Uh oh!

machi1990 commented Nov 18, 2019

Uh oh!

gsmet commented Nov 18, 2019

Uh oh!

machi1990 commented Nov 18, 2019

Uh oh!

machi1990 commented Nov 19, 2019

Uh oh!

machi1990 commented Nov 19, 2019

Uh oh!

machi1990 commented Nov 19, 2019

Uh oh!

machi1990 commented Nov 19, 2019

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

4 participants

gastaldi commented Nov 18, 2019 •

edited

Loading