logback turboFilter and akka LoggingReceive incompatible?

[Sam Halliday]

Hi all,

I'm seeing something very weird.

When I enable the logback turboFilter DuplicateMessageFilter:

  http://logback.qos.ch/manual/filters.html#DuplicateMessageFilter

  https://github.com/qos-ch/logback/blob/master/logback-classic/src/main/java/ch/qos/logback/classic/turbo/DuplicateMessageFilter.java

all my LoggingReceive messages go silent.

Uncommenting the one line in my config that enables the filter is the only change and introduces the regression. Latest scala, latest akka, latest logback.

I can workaround it at the moment, but this is extremely concerning because I have used the duplicate filter in chatty production systems in the past and to see an incompatibility between two stable libraries is never good. 

Turning on logback debug (when it reads its own config) is looking good, no problems reported.

Best regards,

Sam

[Patrik Nordwall]

What akka.loglevel are you using?

I guess that you see the changed behavior in 2.4-M1 compared to 2.3.11.

In 2.4 we have added a check in LoggingReceive that it will only be active if the loglevel is DEBUG.

if (context.system.eventStream.logLevel >= Logging.DebugLevel) {

/Patrik

--
>>>>>>>>>> Read the docs: http://akka.io/docs/
>>>>>>>>>> Check the FAQ: http://doc.akka.io/docs/akka/current/additional/faq.html
>>>>>>>>>> Search the archives: https://groups.google.com/group/akka-user
---
You received this message because you are subscribed to the Google Groups "Akka User List" group.
To unsubscribe from this group and stop receiving emails from it, send an email to akka-user+...@googlegroups.com.
To post to this group, send email to akka...@googlegroups.com.
Visit this group at http://groups.google.com/group/akka-user.
For more options, visit https://groups.google.com/d/optout.

--

Patrik Nordwall
Typesafe -  Reactive apps on the JVM
Twitter: @patriknw

[Sam Halliday]

Everything is DEBUG, and this is akka 2.3.11.

[Patrik Nordwall]

On Sun, Jun 21, 2015 at 4:04 PM, Sam Halliday <sam.ha...@gmail.com> wrote:

Everything is DEBUG, and this is akka 2.3.11.

ok

We log these (and all other things) with 

Logger(logClass, logSource).debug("{}", message.asInstanceOf[AnyRef])

"{}" is the part that the duplicate filter will use to identify the log message, i.e. all log messages are identical :(

This is not something that we have changed.

/Patrik

[Sam Halliday]

Patrik,

Thanks for investigating! You saved me a few hours off my Monday as I
was going to go through this in detail and put together a minimal test
case :-)

Unfortunately, your conclusion seems to be pretty damning. It might just
be this one turbofilter that is incompatible with akka, but its likely
there are more.

Can you think of any workarounds, other that doing duplicate filtering
in the application tier? (eek!) I could investigate writing my own
turbofilter that handles the {} case... performance is not a major
concern here as the consequences of not duplicate filtering is more
far more significant than rendering log messages twice.

Best regards,
Sam

[Viktor Klang]

Doing the filtering pre-substitution seems like a bug.

--
Cheers,
√

--
>>>>>>>>>>      Read the docs: http://akka.io/docs/
>>>>>>>>>>      Check the FAQ: http://doc.akka.io/docs/akka/current/additional/faq.html
>>>>>>>>>>      Search the archives: https://groups.google.com/group/akka-user
---
You received this message because you are subscribed to the Google Groups "Akka User List" group.
To unsubscribe from this group and stop receiving emails from it, send an email to akka-user+...@googlegroups.com.
To post to this group, send email to akka...@googlegroups.com.
Visit this group at http://groups.google.com/group/akka-user.
For more options, visit https://groups.google.com/d/optout.

>>> Typesafe <http://typesafe.com/> -  Reactive apps on the JVM

>>> Twitter: @patriknw
>>>
>>>   --
>> >>>>>>>>>> Read the docs: http://akka.io/docs/
>> >>>>>>>>>> Check the FAQ:
>> http://doc.akka.io/docs/akka/current/additional/faq.html
>> >>>>>>>>>> Search the archives: https://groups.google.com/group/akka-user
>> ---
>> You received this message because you are subscribed to the Google Groups
>> "Akka User List" group.
>> To unsubscribe from this group and stop receiving emails from it, send an
>> email to akka-user+...@googlegroups.com.
>> To post to this group, send email to akka...@googlegroups.com.
>> Visit this group at http://groups.google.com/group/akka-user.
>> For more options, visit https://groups.google.com/d/optout.
>>
>
>
>
> --
>
> Patrik Nordwall

> Typesafe <http://typesafe.com/> -  Reactive apps on the JVM

> Twitter: @patriknw
>
> --
>>>>>>>>>>>      Read the docs: http://akka.io/docs/
>>>>>>>>>>>      Check the FAQ: http://doc.akka.io/docs/akka/current/additional/faq.html
>>>>>>>>>>>      Search the archives: https://groups.google.com/group/akka-user
> ---

> You received this message because you are subscribed to a topic in the Google Groups "Akka User List" group.
> To unsubscribe from this topic, visit https://groups.google.com/d/topic/akka-user/YVri58taWsM/unsubscribe.
> To unsubscribe from this group and all its topics, send an email to akka-user+...@googlegroups.com.

[Roland Kuhn]

It depends on what you want to achieve: not doing the substitution for non-logged events is an explicit goal in our infrastructure.

Regards,

Roland

Dr. Roland Kuhn
Akka Tech Lead
Typesafe – Reactive apps on the JVM.
twitter: @rolandkuhn

[Sam Halliday]

On Monday, 22 June 2015 10:02:06 UTC+1, √ wrote:

Doing the filtering pre-substitution seems like a bug.

If you're suggesting that there is a bug in the filter, then that is not true: it's a well documented, incredibly useful, feature: http://logback.qos.ch/manual/filters.html#DuplicateMessageFilter

  "Note that in case of parameterized logging, only the raw message is taken into consideration."

The problem is in Akka's SLF4J because *everything* the user logs is being converted into `{}` with parameters, even if the user actually logged a fully generated String. This means it's impossible to use this (very useful filter) in a meaningful way with Akka and de-duplication of logging messages must be performed in the application tier (yuck!).

The only practical workaround I can see to fix this today in my codebase is to reimplement Slf4jLogger.scala... but suggestions welcome.

Incidentally, I don't see why you don't just create the log message in Slf4jLogger because at this point we're running in the log actor and not in the thread / actor that initiated the log message. If you really want to delay logging, can't you just ask SLF4J "is debugging enabled for this source/class?"?

Best regards,

Sam

[Sam Halliday]

Does anyone see any major problems with this workaround? If not, I recommend it as a patch to the mainline.

package akka.event.slf4j

import akka.actor._

import akka.event.Logging._

/**

 * Stock Slf4jLogger actually logs everything as "{}" with a

 * parameter, which is incompatible with much of the logback

 * machinary. See

 * https://groups.google.com/d/msg/akka-user/YVri58taWsM/X6-XR0_i1nwJ

 * for a discussion.

 */

class FixedSlf4jLogger extends Slf4jLogger {

  override def receive = {

    case event @ Error(cause, logSource, logClass, message) =>

      withMdc(logSource, event) {

        val logger = Logger(logClass, logSource)

        if (logger.isErrorEnabled()) {

          cause match {

            case Error.NoCause | null => logger.error(if (message != null) message.toString else null)

            case _ => logger.error(if (message != null) message.toString else cause.getLocalizedMessage, cause)

          }

        }

      }

    case event @ Warning(logSource, logClass, message) =>

      withMdc(logSource, event) {

        val logger = Logger(logClass, logSource)

        if (logger.isWarnEnabled()) {

          logger.warn(message.toString)

        }

      }

    case event @ Info(logSource, logClass, message) =>

      withMdc(logSource, event) {

        val logger = Logger(logClass, logSource)

        if (logger.isInfoEnabled()) {

          logger.info(message.toString)

        }

      }

    case event @ Debug(logSource, logClass, message) =>

      withMdc(logSource, event) {

        val logger = Logger(logClass, logSource)

        if (logger.isDebugEnabled()) {

          logger.debug(message.toString)

        }

      }

    case InitializeLogger(_) =>

      sender() ! LoggerInitialized

  }

}

[Viktor Klang]

Why deduplicate non-logged events at all?

Doing the substitution but not incurring the IO cost must be worth it?

--
Cheers,
√

[Sam Halliday]

On Monday, 22 June 2015 11:30:30 UTC+1, √ wrote:

Why deduplicate non-logged events at all?

Doing the substitution but not incurring the IO cost must be worth it?

Turbo Filters are a well defined concept in Logback land: http://logback.qos.ch/manual/filters.html#TurboFilter

The only logic is to add a string to an LRUCache, so I don't believe there is a great overhead here in the typical case.

With my workaround, logger.debug isn't even called if the debugging is not enabled for that class/source.

Unfortunately, when logged through the LoggingAdapter, we lose the ability to dedupe based on log template and it is instead performed on the full String. I can live with that as a caveat.

[Patrik Nordwall]

One problem could be if the string contains placeholders {}.

I would guess that the reason why we used debug("{}", message) was to avoid the toString of the message if the level is not enabled. Checking the level as you suggest might be enough.

When using LoggingAdapter we materialize it to a string at call site.

/Patrik

--

Patrik Nordwall
Typesafe -  Reactive apps on the JVM
Twitter: @patriknw

[Roland Kuhn]

Ah, it seems that I misunderstood: this filter is not part of the pre-filtering that is done before even sending to the logger actor. Then disregard my comment about saving some cycles, within the logger actor it is obviously too late for that anyway.

Patrik, your comment brought back a dim recollection of using "{}" to safe-guard against "{}" occurring within the message itself, but I just checked the sources of SLF4J and that case does not (no longer?) lead to an error condition, so we can simply remove that first argument AFAICS.

Regards,

Roland

[Patrik Nordwall]

ok

Sam, please open an issue.

/Patrik

[Sam Halliday]

No problem, raised as https://github.com/akka/akka/issues/17801