[LOG4J2-3054] BasicContextSelector.hasContext should take default CONTEXT into account

• Type: Bug
• Status: Closed
• Priority: Minor
• Resolution: Fixed
• Affects Version/s: 2.14.1
• Fix Version/s: 2.15.0
• Component/s: Core
• Assignee: Carter Kozak
• Reporter: Alexey Barsov
• Created: 23/Mar/21 19:33
• Updated: 03/Apr/21 10:45
• Resolved: 24/Mar/21 01:00

Description

Issue was introduced in release 2.13.0 as a side effect of implementation of LOG4J2-2621.

New method 

BasicContextSelector.hasContext

 returns false even if Default context is started and have some appenders.
This way

LogManager.shutdown() 

do nothing in such case and all appenders from started Default context are not closed after LogManager.shutdown() returned.

 

This in turn prevents log files from being deleted further from that process (at least on Windows).

I have faced the issue in my functional tests that try to cleanup log files created in scope of the test.
Cleanup code at first calls 

LogManager.shutdown()

and then 

Files.deleteIfExists(logFilePath);

The latter fails with the following error:

 

Can not remove file [C:\Users\xxx\AppData\Local\Temp\logA.log]Can not remove file at org.testng.Assert.fail(Assert.java:83) at com.jetbrains.service.util.logging.SLF4JBridgeTest.removeFile(SLF4JBridgeTest.java:157) at com.jetbrains.service.util.logging.SLF4JBridgeTest.cleanUpLogFiles(SLF4JBridgeTest.java:134) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at org.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:80) at org.testng.internal.Invoker.invokeConfigurationMethod(Invoker.java:564) at org.testng.internal.Invoker.invokeConfigurations(Invoker.java:213) at org.testng.internal.Invoker.invokeConfigurations(Invoker.java:138) at org.testng.TestRunner.afterRun(TestRunner.java:1021) at org.testng.TestRunner.run(TestRunner.java:621) at org.testng.SuiteRunner.runTest(SuiteRunner.java:334) at org.testng.SuiteRunner.runSequentially(SuiteRunner.java:329) at org.testng.SuiteRunner.privateRun(SuiteRunner.java:291) at org.testng.SuiteRunner.run(SuiteRunner.java:240) at org.testng.SuiteRunnerWorker.runSuite(SuiteRunnerWorker.java:52) at org.testng.SuiteRunnerWorker.run(SuiteRunnerWorker.java:86) at org.testng.TestNG.runSuitesSequentially(TestNG.java:1198) at org.testng.TestNG.runSuitesLocally(TestNG.java:1123) at org.testng.TestNG.run(TestNG.java:1031) at org.gradle.api.internal.tasks.testing.testng.TestNGTestClassProcessor.runTests(TestNGTestClassProcessor.java:140) at org.gradle.api.internal.tasks.testing.testng.TestNGTestClassProcessor.stop(TestNGTestClassProcessor.java:89) at org.gradle.api.internal.tasks.testing.SuiteTestClassProcessor.stop(SuiteTestClassProcessor.java:61) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:35) at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:24) at org.gradle.internal.dispatch.ContextClassLoaderDispatch.dispatch(ContextClassLoaderDispatch.java:32) at org.gradle.internal.dispatch.ProxyDispatchAdapter$DispatchingInvocationHandler.invoke(ProxyDispatchAdapter.java:93) at com.sun.proxy.$Proxy2.stop(Unknown Source) at org.gradle.api.internal.tasks.testing.worker.TestWorker.stop(TestWorker.java:132) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:35) at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:24) at org.gradle.internal.remote.internal.hub.MessageHubBackedObjectConnection$DispatchWrapper.dispatch(MessageHubBackedObjectConnection.java:175) at org.gradle.internal.remote.internal.hub.MessageHubBackedObjectConnection$DispatchWrapper.dispatch(MessageHubBackedObjectConnection.java:157) at org.gradle.internal.remote.internal.hub.MessageHub$Handler.run(MessageHub.java:404) at org.gradle.internal.concurrent.ExecutorPolicy$CatchAndRecordFailures.onExecute(ExecutorPolicy.java:63) at org.gradle.internal.concurrent.ManagedExecutorImpl$1.run(ManagedExecutorImpl.java:46) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) at org.gradle.internal.concurrent.ThreadFactoryImpl$ManagedThreadRunnable.run(ThreadFactoryImpl.java:55) at java.lang.Thread.run(Thread.java:748)Caused by: java.nio.file.FileSystemException: C:\Users\xxx\AppData\Local\Temp\logA.log: The process cannot access the file because it is being used by another process.

 
The same cleanup code run successfully for version 2.12.1 (because it resolve Default context and close its appenders)

It looks as if current method BasicContextSelector.hasContext

 

@Override
public boolean hasContext(String fqcn, ClassLoader loader, boolean currentContext) {
    LoggerContext ctx = ContextAnchor.THREAD_CONTEXT.get();
    return ctx != null && ctx.isStarted();
} 

should be replaced with 

@Override
public boolean hasContext(String fqcn, ClassLoader loader, boolean currentContext) {
    LoggerContext ctx = getContext(fqcn, loader, currentContext);
    return ctx.isStarted();
}

 

Issue Links

• links to: GitHub Pull Request #478