Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add a way to create log without side effects #116

Open
wants to merge 2 commits into
base: master
Choose a base branch
from
Open

Add a way to create log without side effects #116

Show file tree
Hide file tree
Changes from 1 commit
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
0da55fa
add cached Log and a simple log factory for it;
evo-funfunfine Nov 16, 2021
3ff3a89
add test with POC;
evo-funfunfine Nov 16, 2021
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
123 changes: 112 additions & 11 deletions core/src/main/scala/com/evolutiongaming/catshelper/Log.scala
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -3,7 +3,7 @@ package com.evolutiongaming.catshelper
import cats.data.NonEmptyMap
import cats.effect.Sync
import cats.{Applicative, Semigroup, ~>}
import org.slf4j.{Logger, MDC}
import org.slf4j.{ILoggerFactory, Logger, MDC}

import scala.collection.immutable.SortedMap

Expand Down Expand Up @@ -41,9 +41,11 @@ trait Log[F[_]] {
object Log {

sealed trait Mdc

object Mdc {

private object Empty extends Mdc

private final case class Context(values: NonEmptyMap[String, String]) extends Mdc {
override def toString: String = s"MDC(${values.toSortedMap.mkString(", ")})"
}
Expand All @@ -53,7 +55,7 @@ object Log {
def apply(head: (String, String), tail: (String, String)*): Mdc = Context(NonEmptyMap.of(head, tail: _*))

def fromSeq(seq: Seq[(String, String)]): Mdc =
NonEmptyMap.fromMap(SortedMap(seq: _*)).fold(empty){ nem => Context(nem) }
NonEmptyMap.fromMap(SortedMap(seq: _*)).fold(empty) { nem => Context(nem) }

def fromMap(map: Map[String, String]): Mdc = fromSeq(map.toSeq)

Expand All @@ -76,7 +78,92 @@ object Log {

def summon[F[_]](implicit F: Log[F]): Log[F] = F

def apply[F[_]: Sync](logger: Logger): Log[F] = new Log[F] {
def cached[F[_] : Sync](source: String, factory: ILoggerFactory): Log[F] = new Log[F] {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

this is still an effectful unpure code, hence - NO from my side. however you can already use logOf(…).toTry.get in your code base, which will clearly express to readers unsafeness, and this is easy to use

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why is that an effectual code?

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If you worry about getting the factory in safe manner then check out test file in this PR. It shows that we still should get ILoggerFactory by delaying slf4j stuff.

Copy link
Contributor

@t3hnar t3hnar Nov 16, 2021 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

because any manipulations with factory are not safe, and in runtime it really references mutable shared state and changes it

Copy link
Author

@FunFunFine FunFunFine Nov 16, 2021 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Well, I see what you mean. It easily can be solved by putting function here (it should be done anyway because of Logback) like so

def cached[F[_] : Sync](source: String, factory: String => F[Logger]): Log[F] = ???

or by putting factory inside of Ref. I guess it would be pure code then, right?

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Also I see that every manipulation with factory is delayed here, isn't it enough to be pure?

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

right!

however such changes would enforce your Log implementation to call factory.getLogger as part of log.info/debug/etc - adds some runtime overhead

Copy link
Author

@FunFunFine FunFunFine Nov 16, 2021 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Such runtime overhead is so little we can ignore it. If you dive in (not so deep) to the implementation, you can see that:

private Map<String, Logger> loggerCache;
//...
public final Logger getLogger(final String name) {

        if (name == null) {
            throw new IllegalArgumentException("name argument cannot be null");
        }

        // if we are asking for the root logger, then let us return it without
        // wasting time
        if (Logger.ROOT_LOGGER_NAME.equalsIgnoreCase(name)) {
            return root;
        }

        int i = 0;
        Logger logger = root;

        // check if the desired logger exists, if it does, return it
        // without further ado.
        Logger childLogger = (Logger) loggerCache.get(name);
    //^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ this line   
        // if we have the child, then let us return it without wasting time
        if (childLogger != null) {
            return childLogger;
        }

        // if the desired logger does not exist, them create all the loggers
        // in between as well (if they don't already exist)

//....

}

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

You know when you create instances of IO and flatMap classes for every operation you make this overhead seems totally fine.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

sure it might be totally fine, it depends on actual implementation :)

def cached[F[_] : Sync](source: String, factory: String => F[Logger]): Log[F]

signaturewise & typewise - is ok


def withMDC(mdc: Log.Mdc)(log: => Unit): Unit = {
import Mdc.MdcOps
mdc.context match {
case None => log
case Some(mdc) =>
val backup = MDC.getCopyOfContextMap
MDC.clear()
mdc.toSortedMap foreach { case (k, v) => MDC.put(k, v) }
log
if (backup == null) MDC.clear() else MDC.setContextMap(backup)
}
}

def trace(msg: => String, mdc: Log.Mdc) = {
Sync[F].delay {
val logger = factory.getLogger(source)
if (logger.isTraceEnabled) withMDC(mdc) {
logger.trace(msg)
}
}
}

def debug(msg: => String, mdc: Log.Mdc) = {
Sync[F].delay {
val logger = factory.getLogger(source)

if (logger.isDebugEnabled) withMDC(mdc) {
logger.debug(msg)
}
}
}

def info(msg: => String, mdc: Log.Mdc) = {
Sync[F].delay {
val logger = factory.getLogger(source)

if (logger.isInfoEnabled) withMDC(mdc) {
logger.info(msg)
}
}
}

def warn(msg: => String, mdc: Log.Mdc) = {
Sync[F].delay {
val logger = factory.getLogger(source)

if (logger.isWarnEnabled) withMDC(mdc) {
logger.warn(msg)
}
}
}

def warn(msg: => String, cause: Throwable, mdc: Log.Mdc) = {
Sync[F].delay {
val logger = factory.getLogger(source)

if (logger.isWarnEnabled) withMDC(mdc) {
logger.warn(msg, cause)
}
}
}

def error(msg: => String, mdc: Log.Mdc) = {
Sync[F].delay {
val logger = factory.getLogger(source)

if (logger.isErrorEnabled) withMDC(mdc) {
logger.error(msg)
}
}
}

def error(msg: => String, cause: Throwable, mdc: Log.Mdc) = {
Sync[F].delay {
val logger = factory.getLogger(source)

if (logger.isErrorEnabled) withMDC(mdc) {
logger.error(msg, cause)
}
}
}
}

def apply[F[_] : Sync](logger: Logger): Log[F] = new Log[F] {

def withMDC(mdc: Log.Mdc)(log: => Unit): Unit = {
import Mdc.MdcOps
Expand All @@ -93,43 +180,57 @@ object Log {

def trace(msg: => String, mdc: Log.Mdc) = {
Sync[F].delay {
if (logger.isTraceEnabled) withMDC(mdc) { logger.trace(msg) }
if (logger.isTraceEnabled) withMDC(mdc) {
logger.trace(msg)
}
}
}

def debug(msg: => String, mdc: Log.Mdc) = {
Sync[F].delay {
if (logger.isDebugEnabled) withMDC(mdc) { logger.debug(msg) }
if (logger.isDebugEnabled) withMDC(mdc) {
logger.debug(msg)
}
}
}

def info(msg: => String, mdc: Log.Mdc) = {
Sync[F].delay {
if (logger.isInfoEnabled) withMDC(mdc) { logger.info(msg) }
if (logger.isInfoEnabled) withMDC(mdc) {
logger.info(msg)
}
}
}

def warn(msg: => String, mdc: Log.Mdc) = {
Sync[F].delay {
if (logger.isWarnEnabled) withMDC(mdc) { logger.warn(msg) }
if (logger.isWarnEnabled) withMDC(mdc) {
logger.warn(msg)
}
}
}

def warn(msg: => String, cause: Throwable, mdc: Log.Mdc) = {
Sync[F].delay {
if (logger.isWarnEnabled) withMDC(mdc) { logger.warn(msg, cause) }
if (logger.isWarnEnabled) withMDC(mdc) {
logger.warn(msg, cause)
}
}
}

def error(msg: => String, mdc: Log.Mdc) = {
Sync[F].delay {
if (logger.isErrorEnabled) withMDC(mdc) { logger.error(msg) }
if (logger.isErrorEnabled) withMDC(mdc) {
logger.error(msg)
}
}
}

def error(msg: => String, cause: Throwable, mdc: Log.Mdc) = {
Sync[F].delay {
if (logger.isErrorEnabled) withMDC(mdc) { logger.error(msg, cause) }
if (logger.isErrorEnabled) withMDC(mdc) {
logger.error(msg, cause)
}
}
}
}
Expand Down Expand Up @@ -183,7 +284,7 @@ object Log {
def error(msg: => String, cause: Throwable, mdc: Log.Mdc) = unit
}

def empty[F[_]: Applicative]: Log[F] = const(Applicative[F].unit)
def empty[F[_] : Applicative]: Log[F] = const(Applicative[F].unit)

implicit class LogOps[F[_]](val self: Log[F]) extends AnyVal {

Expand Down
30 changes: 28 additions & 2 deletions core/src/main/scala/com/evolutiongaming/catshelper/LogOf.scala
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -6,6 +6,8 @@ import cats.{Applicative, Functor, ~>}
import ch.qos.logback.classic.util.ContextInitializer
import org.slf4j.{ILoggerFactory, LoggerFactory}

import scala.reflect.ClassTag

trait LogOf[F[_]] {

def apply(source: String): F[Log[F]]
Expand All @@ -15,6 +17,25 @@ trait LogOf[F[_]] {

object LogOf {


trait Safe[F[_]] {
def apply(source: String): Log[F]

def apply[Source: ClassTag]: Log[F]
}

def slf4jSafe[F[_] : Sync]: F[LogOf.Safe[F]] = {
for {
factory <- Sync[F].delay {
LoggerFactory.getILoggerFactory
}
} yield new Safe[F] {
override def apply(source: String): Log[F] = Log.cached(source, factory)

override def apply[Source: ClassTag]: Log[F] = Log.cached(implicitly[ClassTag[Source]].runtimeClass.getName.stripSuffix("$"), factory)
}
}

def apply[F[_]](implicit F: LogOf[F]): LogOf[F] = F

def summon[F[_]](implicit F: LogOf[F]): LogOf[F] = F
Expand All @@ -24,11 +45,14 @@ object LogOf {

def apply(source: String) = {
for {
log <- Sync[F].delay { factory.getLogger(source) }
log <- Sync[F].delay {
factory.getLogger(source)
}
} yield {
Log[F](log)
}
}

def apply(source: Class[_]) = apply(source.getName.stripSuffix("$"))
}

Expand All @@ -38,7 +62,9 @@ object LogOf {

def slf4j[F[_] : Sync]: F[LogOf[F]] = {
for {
factory <- Sync[F].delay { LoggerFactory.getILoggerFactory }
factory <- Sync[F].delay {
LoggerFactory.getILoggerFactory
}
} yield {
apply(factory)
}
Expand Down