Class in log output shown as the class where log was instantiated

[lightsaway]

Given the following code:

import io.chrisdavenport.log4cats.Logger
import io.chrisdavenport.log4cats.slf4j.Slf4jLogger
import cats.effect.{ExitCode, IO, IOApp, Sync}
import cats.implicits._

object MyOtherThing {
  def doSomething[F[_]: Sync: Logger]: F[Unit] =
    Logger[F].info("Other stuff to do ")
}

object MyThing extends IOApp {

  // Arbitrary Local Function Declaration
  def doSomething[F[_]: Sync]: F[Unit] = {
    // Impure But What 90% of Folks I know do with log4s
    implicit def unsafeLogger[F[_]: Sync] = Slf4jLogger.getLogger[F]

    Logger[F].info("Logging Start Something") *>
      Sync[F].delay(println("I could be doing anything")).attempt.flatMap {
        case Left(e)  => Logger[F].error(e)("Something Went Wrong")
        case Right(_) => Sync[F].pure(())
      }
  }

  def safelyDoThings[F[_]: Sync]: F[Unit] =
    for {
      logger <- Slf4jLogger.create[F]
      _      <- logger.info("Logging at start of safelyDoThings")
      something <- Sync[F]
        .delay(println("I could do anything"))
        .onError { case e => logger.error(e)("Something Went Wrong in safelyDoThings") }
      _ <- logger.info("Logging at end of safelyDoThings")
    } yield something

  def passForEasierUse[F[_]: Sync: Logger] =
    for {
      _ <- Logger[F].info("Logging at start of passForEasierUse")
      something <- Sync[F]
        .delay(println("I could do anything"))
        .onError { case e => Logger[F].error(e)("Something Went Wrong in passForEasierUse") }
      _ <- Logger[F].info("Logging at end of passForEasierUse")
    } yield something

  override def run(args: List[String]): IO[ExitCode] =
    doSomething[IO] *>
      MyThing.safelyDoThings[IO] *> {

      // Impure But What 90% of Folks I know do with log4s
      implicit def unsafeLogger[F[_]: Sync] = Slf4jLogger.getLogger[F]    // (A)

      MyThing.passForEasierUse[IO] *> MyOtherThing.doSomething[IO]
    } *>
      IO(ExitCode.Success)
}

and following logback.xml:

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
    <appender name="stdout" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%logger{35} - [%class] - %msg%n</pattern>
        </encoder>
    </appender>

    <root level="INFO">
        <appender-ref ref="stdout"/>
    </root>
</configuration>

this produces following output:

.util.MyThing - [io.chrisdavenport.log4cats.slf4j.internal.Slf4jLoggerInternal$Slf4jLogger] - Logging Start Something
I could be doing anything
.util.MyThing - [io.chrisdavenport.log4cats.slf4j.internal.Slf4jLoggerInternal$Slf4jLogger] - Logging at start of safelyDoThings
I could do anything
.util.MyThing - [io.chrisdavenport.log4cats.slf4j.internal.Slf4jLoggerInternal$Slf4jLogger] - Logging at end of safelyDoThings
.util.MyThing - [io.chrisdavenport.log4cats.slf4j.internal.Slf4jLoggerInternal$Slf4jLogger] - Logging at start of passForEasierUse
I could do anything
.util.MyThing - [io.chrisdavenport.log4cats.slf4j.internal.Slf4jLoggerInternal$Slf4jLogger] - Logging at end of passForEasierUse
.util.MyThing - [io.chrisdavenport.log4cats.slf4j.internal.Slf4jLoggerInternal$Slf4jLogger] - Other stuff to do 

As you can see the last log line shows that logging is coming from Mything(whereas in reality it is MyOtherThing) Wondering if there is any trickery to make this show MyOtherThing as a source?

[nigredo-tori]

@lightsaway, it's not really a Log4Cats question. Choosing the caller is handled by Logback, and SLF4J knows nothing about it.

You can probably set up Logback somehow, but it definitely would not just a config tweak. Looking at the code here, it seems like you'll need to inject custom framework packages into the LoggerContext. From what I can gather, you should be able to do that with a custom LoggerContextListener.

[gbogard]

Hi! We hit the same problem in my team, and I came up with a solution to address this (#439), without dealing with LoggerContexts.
Right now it's in a separate repository, but I'm looking for feedback before opening a PR :)

[nigredo-tori]

@gbogard, from what I can tell, this issue is about the %class thing, which is specific to Logback. See the log example above. .util.MyThing is %logger, but io.chrisdavenport.log4cats.slf4j.internal.Slf4jLoggerInternal$Slf4jLogger is %class. There's no nice way to override %class, because it's a Logback hack for which there is no ready-made API. Managing multiple loggers doesn't solve this.

[gbogard]

@nigredo-tori, you're right, my apologies :)