qos-ch / logback

The reliable, generic, fast and flexible logging framework for Java.
http://logback.qos.ch
Other
2.97k stars 1.28k forks source link

ExecutorServiceUtil throws java.lang.SecurityException from 1.5.0 onwards with jdk21 #815

Closed AlexChalk closed 3 months ago

AlexChalk commented 3 months ago

Hi, thanks for all your work on this project.

Since version 1.5.0, calling setContextClassLoader when using logback is throwing the following exception:

java.lang.SecurityException: setContextClassLoader
        at java.base/jdk.internal.misc.CarrierThread.setContextClassLoader(CarrierThread.java:90)
        at lambdaisland.classpath$install_priority_loader_BANG_$fn__34678.invoke(classpath.clj:399)
        at clojure.core$binding_conveyor_fn$fn__5823.invoke(core.clj:2047)
        at clojure.lang.AFn.call(AFn.java:18)
        at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:317)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
        at java.base/java.lang.Thread.run(Thread.java:1583)

I don't know much java, but I took a look at logback's diff history, and I narrowed the issue down to the modification of ExecutorServiceUtil for jdk21 builds in logback-core/src/main/java21/ch/qos/logback/core/util/ExecutorServiceUtil.java, specifically

private ThreadFactory makeThreadFactory() {
    return Executors.defaultThreadFactory();
}
// ->
private ThreadFactory makeThreadFactory() {
    ThreadFactory tf = Thread.ofVirtual().factory();
    return tf;
}
// and/or
static public ExecutorService newAlternateThreadPoolExecutor() {
    return newThreadPoolExecutor();
}
// ->
static public ExecutorService newAlternateThreadPoolExecutor() {
    return Executors.newVirtualThreadPerTaskExecutor();
}

I cloned the repo, replaced the contents of that file with the non-jdk21 ExecutorServiceUtil, got it to build, and used that version in my project, and I can confirm this resolved my issue https://github.com/qos-ch/logback/compare/master...AlexChalk:logback:revert-ExecutorServiceUtil. However, I'm aware reverting the change might not be your preferred solution.

Do you have any thoughts on how to address this?

ceki commented 3 months ago

@AlexChalk Thank you for reporting this issue. It is not clear whether the problem is Closure specific or not. Can it be that Closure does not support virtual threads?

AlexChalk commented 3 months ago

Hi @ceki, I don't think that's the issue, https://andersmurphy.com/2024/05/06/clojure-managing-throughput-with-virtual-threads.html suggests they work fine with Clojure.

AlexChalk commented 3 months ago

Clojure actually has full interop with java, the line that's throwing is (.setContextClassLoader thread new-loader), which is equivalent to thread.setContextClassLoader(new-loader). So you could try and repro this in pure java code if you wanted.

AlexChalk commented 3 months ago

The java docs on setContextClassLoader (https://docs.oracle.com/en/java/javase/21/docs/api/java.base/java/lang/Thread.html#setContextClassLoader(java.lang.ClassLoader)) say

Throws: SecurityException - if the current thread cannot set the context ClassLoader

so my guess is that you can't do this when using virtual threads.

ceki commented 3 months ago

@AlexChalk Test code reproducing this issue (without Closure) would be great.

AlexChalk commented 3 months ago

I've never written Java before, so might be difficult 😅, but I can try and modify the branch I linked to above to get it to throw.

AlexChalk commented 3 months ago

@ceki where would be a good place in the codebase to call Thread.getAllStackTraces after some virtual threads have been created and are in use? I can then do what the clojure code does: take .keySet, iterate over the threads, and call .setContextClassLoader on each one. That should make it throw.

ceki commented 3 months ago

I reckon the following under JDK 21 will create a virtual thread:

  import ch.qos.logback.classic.LoggerContext;
  import java.util.concurrent.*;

 void aTestMethod() {
    LoggerContext context= new LoggerContext();
    Runnable aRunnable = new Runnable() {
        public void run() {
           System.out.println("hello");
        }
    };
    ScheduledExecutorService scheduledExecutorService = context.getScheduledExecutorService();
    ScheduledFuture<?> scheduledFuture = scheduledExecutorService.scheduleAtFixedRate(aRunnable,
                    0, 1000, TimeUnit.MILLISECONDS);
    Thread.sleep(100);
  // call Thread.getAllStackTraces()
}
AlexChalk commented 3 months ago

@ceki awesome thanks! Here's a minimal repro of the issue written in java: https://github.com/AlexChalk/logback-repro

ceki commented 3 months ago

@AlexChalk Thank you for the code reproducing the issue. I tried your code and then tried the following code

import java.util.Set;

public class Main815 {

    public static void main(String[] args) {
        Set<Thread> threads = Thread.getAllStackTraces().keySet();
        ClassLoader classLoader = Thread.currentThread().getContextClassLoader();

        for (Thread thread : threads) {
            System.out.println("thread: " + thread.getName() + " of class "+ thread.getClass());
            thread.setContextClassLoader(classLoader);
        }
    }
}

which results in

thread: Reference Handler of class class java.lang.ref.Reference$ReferenceHandler
thread: Notification Thread of class class java.lang.Thread
thread: Finalizer of class class java.lang.ref.Finalizer$FinalizerThread
thread: main of class class java.lang.Thread
thread: Attach Listener of class class java.lang.Thread
thread: Common-Cleaner of class class jdk.internal.misc.InnocuousThread
Exception in thread "main" java.lang.SecurityException: setContextClassLoader
    at java.base/jdk.internal.misc.InnocuousThread.setContextClassLoader(InnocuousThread.java:168)
    at ch.qos.logback.core.issue.lbcore258.Main815.main(Main815.java:30)

There is no logback related code but the exception is the same. Running under Java 21, 19, 17, 16 all yield the same exception.

AlexChalk commented 3 months ago

Hi @ceki, my bad, I forgot to check it didn't throw on jdk17.

I've pushed some changes to the repo to bring the business logic closer to what lambdaisland/classpath is doing, and it now throws on jdk21 but not jdk17.

With the new version, I think the only differences from the clojure code are the calls to baseLoader and DynamicClassLoader, which I simplified to avoid having to figure out how to import all of clojure into the repo.

AlexChalk commented 3 months ago

Ok, I think I've got it, the class that breaks is jdk.internal.misc.CarrierThread, which explicitly overrides setContextClassLoader to throw: https://github.com/openjdk/jdk22/blob/master/src/java.base/share/classes/jdk/internal/misc/CarrierThread.java#L89-L91

AlexChalk commented 3 months ago

Going to close this as I don't think it's an issue with logback, but please reopen if I'm mistaken. Thanks for all your help!