Ability to add log arguments per Log.Entry basis without using formatted message

[nartamonov]

We use LogStage for structured logging. For that we use JSON console sink, its output is parsed by Filebeats and then redirected to Graylog. All works fine except one thing: we want to be able to add additional diagnostic key-value arguments on a per Log.Entry basis, using LogIO facility, but in a such way that arguments don't have place in rendered log message.

For example, if our application will try to export some domain entity to external system and failed to do that, we may want to log entity's ID in message and attach formatted entity attributes (which may be quite complex in structure) in a form of JSON for diagnostic and debug purposes. Right now we must explicitly include formatted entity attributes in log message:

def importEntity(entity: Entity): IO[Unit] = /* ... */

importEntity(someEntity).handleErrorWith {
  case NonFatal(error) => LogIO[IO].log(Level.Error)(
    s"Failed to import entity ${someEntity.id -> "ID"}: $error. ${entity.asJson.pretty(Printer.spaces2) -> "entityAsJSON"}").void
}

It works, but such log message will be rather ugly and log entry will duplicate content of entityAsJSON twice: in the log message and in rendered arguments. It also means additional overhead for network traffic and processing of incoming log entries by Graylog.

Do you think it's meaningful use case?

[neko-kai]

You can use customContext to carry parameters in JSON without duplicating them in "message" string. See the example in docs - https://izumi.7mind.io/latest/release/doc/logstage/index.html:

val ctxLogger = logger("userId" -> "user@google.com", "company" -> "acme")
val delta = Random.nextInt(1000)

ctxLogger.info(s"Processing time: $delta")

As you can see, "userId" and "company" parameters are carried in "@context" object in JSON but are NOT duplicated in "@message":

The above API is with IzLogger, not LogIO though. The API for doing that with LogIO is currently a bit more involved, unfortunately:

1. You could recreate LogIO with a context-applied IzLogger, but you'd have to carry IzLogger around for that, not just LogIO:

   val myLogger: IzLogger
   
   ...handleErrorWith {
   case NonFatal(error) =>
     val errLogger = myLogger("ID" -> someEntity.id, "entityAsJSON" -> entity.asJson.pretty(Printer.spaces2))
     val logIOCtx = LogIO.fromLogger(errLogger)
   
     logIOCtx.log(Level.Error)(s"Failed to import entity: $error")
   }

2. You could add context to each Log.Entry manually -

   ...handleErrorWith {
   case NonFatal(error) =>
     val ctx = entityContext(someEntity.id, entity.asJson.pretty(Printer.spaces2))
   
     logWithCtx(ctx)(Level.Error, s"Failed to import entity: $error")
   }
   
   def logWithCtx(customContext: CustomContext)(level: Level, msg: Log.Message): IO[Unit] = {
   for {
     rawEntry <- LogIO[IO].createEntry(level, msg)
     ctxEntry = rawEntry.addCustomContext(customContext)
     _        <- LogIO[IO].log(ctxEntry)
   } yield ()
   }
   
   def entityContext(id: UUID, entityJson: String): CustomContext = {
   customContext(Map(
     "ID" -> id
   , "entityAsJSON" -> entityJson
   ))
   }
   
   def customContext(map: Map[String, Any]): CustomContext = {
   val logArgs = map.map {
     case (k, v) => LogArg(Seq(k), v, hidden = false)
   }.toList
   
   CustomContext(logArgs)
   }

Any suggestions for improvements are welcome! 😉

[neko-kai]

@nartamonov After https://github.com/7mind/izumi-r2/pull/521, your scenario can be expressed as follows:

def importEntity(entity: Entity)(implicit log: LogIO[IO]): IO[Unit] = {
  val ctxLog = log("ID" -> someEntity.id, "entityAsJSON" -> entity.asJson.pretty(Printer.spaces2))

  IO(???).handleErrorWith {
    case error =>
      ctxLog.error(s"Failed to import entity: $error.").void
      // message includes `ID` and `entityAsJSON` fields
  }

Is that okay?

[pshirshov]

@nartamonov are you happy with custom contexts?..

[nartamonov]

Sorry for late answer, thank you for suggestions! I decided to follow second advice from @kaishh and wrote simple wrapper around LogIO:

trait MonadLog[F[_]] {
  val monad: Monad[F]

  def log[E: ToLogMsg](level: Log.Level)(event: E)(implicit pos: CodePositionMaterializer): F[Unit]
}

object MonadLog {
  def apply[F[_]](implicit ev: MonadLog[F]): MonadLog[F] = ev

  def fromLogger[F[_]: SyncSafe: Monad](logger: IzLogger): MonadLog[F] = {
    implicit val logIO: LogIO[F] = LogIO.fromLogger[F](logger)
    new MonadLogForLogIO[F]
  }
}

class MonadLogForLogIO[F[_]: LogIO: Monad] extends MonadLog[F] {
  val monad: Monad[F] = Monad[F]

  def log[E: ToLogMsg](level: Log.Level)(event: E)(implicit pos: CodePositionMaterializer): F[Unit] = {
    val msg = ToLogMsg[E].toLogMsg(event)
    val ctx = buildCustomContext(msg.context, eventType = event.getClass.getSimpleName)
    for {
      entry    <- LogIO[F].createEntry(level,msg.message)
      ctxEntry = entry.addCustomContext(ctx)
      _        <- LogIO[F].log(ctxEntry)
    } yield ()
  }

  private def buildCustomContext(context: Map[String,Any], eventType: String): CustomContext = {
    val args = context.map { case (k,v) => LogArg(Seq(k), v, hidden = false) }.toList
    val eventTypeArg = LogArg(Seq("event_type"), eventType, hidden = false)
    CustomContext(args :+ eventTypeArg)
  }
}

trait ToLogMsg[-E] {
  def toLogMsg(e: E): LogMsg
}

object ToLogMsg {
  def apply[E](implicit ev: ToLogMsg[E]): ToLogMsg[E] = ev
}

case class LogMsg(message: Log.Message, context: Map[String,Any] = Map.empty)

It is typeclass for monad with logging capability (MTL style), which treats log messages not as simple strings but as ADTs - I prefer this approach in my current project. And it has simpler interface (1 method versus 4 in LogIO), so it's easy to write fake implementation for testing purposes - you need to implement single method.

Now I can use that typeclass this way:

sealed trait AppLogEvent
// ...
case class FailedToImportEntity(entity: Entity, error: Throwable) extends LogEvent
// ...

object LogEvent extends DiagnosticEncoders {
  implicit val toLogMsg: ToLogMsg[LogEvent] = {
    // ...
    case FailedToImportEntity(entity, error) =>
      LogMsg(s"Failed to import entity ${entity.id -> "entityId"}: $error.",
        context = Map("entity_data" -> stringify(entity)))
    // ...
  }
}

def importEntity(entity: Entity): IO[Unit] = /* ... */

implicit val monadLog: MonadLog[IO] = MonadLog.fromLogger[IO](izLogger);
import monadLog._

importEntity(someEntity).handleErrorWith {
  case NonFatal(error) => log(Level.Error)(FailedToImportEntity(entity, error)).void
}

It seems all works fine, thank you! :-)

[pshirshov]

Please note that this API is already available in latest snapshot. Also I would recommend you to join our gitter channel to follow our announcements.