valskalla / odin

Fast & Functional logger in Scala
Apache License 2.0
312 stars 20 forks source link

[slf4j bridge] Printed error when logging from an interrupted thread #364

Open tyoras opened 2 years ago

tyoras commented 2 years ago

Hello there, I'm having an issue with the slf4j bridge since I've updated odin to version 0.13.0 which is including the CE3 upgrade. I have the slf4j bridge configured as shown here https://github.com/valskalla/odin#slf4j-bridge but I'm also using an external java library which is running its own threads for some operations and one of those boils down to something similar to this :

package com.external.library;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class MyThread extends Thread {
    private final Logger logger;

    public MyThread() {
        logger = LoggerFactory.getLogger("my_thread_logger");
        setName("my_thread");
        setDaemon(true);
    }

    @Override
    public void run() {
        try {
            while (!isInterrupted()) {
                if (isInterrupted()) {
                    throw new Exception("interrupted!");
                }
            }
        } catch (Exception e) {
        }

        logger.info("Stopping");
    }
}

and for the sake of reproducing my issue I'm using this simple main :

package com.example

import cats.effect.{IO, IOApp}
import com.external.library.MyThread

import scala.concurrent.duration.DurationInt

object Main extends IOApp.Simple {

  override def run: IO[Unit] = IO(new MyThread).flatMap { myThread =>
    IO(myThread.start()) *>
      IO.sleep(2.seconds) *>
      IO(myThread.interrupt()) *>
      IO.sleep(2.seconds)
  }
}

My issue is that this stacktrace happens to be printed directly on the standard error:

Exception in thread "my_thread" java.lang.InterruptedException
    at java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1343)
    at scala.concurrent.impl.Promise$DefaultPromise.tryAwait0(Promise.scala:207)
    at scala.concurrent.impl.Promise$DefaultPromise.result(Promise.scala:225)
    at scala.concurrent.Await$.$anonfun$result$1(package.scala:201)
    at scala.concurrent.BlockContext$DefaultBlockContext$.blockOn(BlockContext.scala:62)
    at scala.concurrent.Await$.result(package.scala:124)
    at cats.effect.std.DispatcherPlatform.unsafeRunTimed(DispatcherPlatform.scala:61)
    at cats.effect.std.DispatcherPlatform.unsafeRunTimed$(DispatcherPlatform.scala:59)
    at cats.effect.std.Dispatcher$$anon$2.unsafeRunTimed(Dispatcher.scala:190)
    at cats.effect.std.DispatcherPlatform.unsafeRunSync(DispatcherPlatform.scala:52)
    at cats.effect.std.DispatcherPlatform.unsafeRunSync$(DispatcherPlatform.scala:51)
    at cats.effect.std.Dispatcher$$anon$2.unsafeRunSync(Dispatcher.scala:190)
    at io.odin.slf4j.OdinLoggerAdapter.run(OdinLoggerAdapter.scala:23)
    at io.odin.slf4j.OdinLoggerAdapter.info(OdinLoggerAdapter.scala:73)
    at com.external.library.MyThread.run(MyThread.java:27)

It looks like there is an issue related to the Dispatcher coming from the slf4j bridge when the log happens to me made from a thread in an interrupted state. I'm not sure it is a normal behaviour, what do you think?

janstenpickle commented 2 years ago

I've also seen this issue with the bridge. It seems to be related to the dispatcher's resource being allocated using the global runtime. I don't know enough about the CE3 internals to understand why interrupting a different thread also interrupts dispatcher and can't be recovered.

I have managed to work around this using an atomic value with a Odin logger proxy in it, which uses a dispatcher with a proper resource lifecycle inside an IOApp. When this gets set at runtime, the bridge starts working and continues to work even after a thread interrupt. I had to do a fair amount of hacking to get this working nicely and ended up not using the odin-slf4j module.