HTTP Connection Pool: how to filter debug logging?

[bormotov]

akka-http 10.0.5
logging via SLF4J (logback).

we use <pattern>%d{ISO8601} [%-5p] %m%n</pattern> and got in log a lot of

2017-04-05 15:03:42,079 [DEBUG] [12] <unconnected> Slot was stopped
2017-04-05 15:03:42,079 [DEBUG] [13] <unconnected> Slot was stopped
2017-04-05 15:03:42,079 [DEBUG] [14] <unconnected> Slot was stopped
2017-04-05 15:03:42,079 [DEBUG] [15] <unconnected> Slot was stopped

How filter this from log?

First try - add %c, to get log event category (typicaly hold className), but

2017-04-05 15:09:29,683 [DEBUG] WE/Pool(shared->http://host.url:80) [7] <unconnected> Slot was stopped
2017-04-05 15:09:29,683 [DEBUG] WE/Pool(shared->http://host.url:80) [8] <unconnected> Slot was stopped
2017-04-05 15:09:29,683 [DEBUG] WE/Pool(shared->http://host.url:80) [9] <unconnected> Slot was stopped
2017-04-05 15:09:43,477 [DEBUG] akka.io.TcpOutgoingConnection Could not establish connection to ....

but why?

Any ideas?

[jrudolph]

These are log messages for the connection pool. We have both a logSource and a logClass but, unfortunately, because of the way the logger is constructed the logSource is the string you see (which is fine) but the logClass is DummyClassForStringSources.

We should make sure the logClass is something specific to the connection pool so it can be easily matched using the common logging tools.

[ochrons]

This is extremely annoying, bloating logs with no easy way to filter them out. Please provide a workaround or a logback config how to filter these away ASAP.

[ktoso]

If you want a thing to be done "ASAP" you can provide a pull request or get commercial support.
We all have some priorities, and going around requesting something ASAP will not help a thing be done sooner in face of actual other real high priority things.

Thanks in advance.

[jrudolph]

I agree with @ochrons on this one. I messed up that logging. I thought that at least the DummyClassForStringSources would end up in slf4j so you could filter on that one but that is filtered out specifically in akka-slf4j.

The way it is now, you cannot use the Akka Http 10.0.5 client because you have to completely disable DEBUG logging for your application otherwise you will drown in those logs and cannot do much about it.

[jrudolph]

A workaround is to define a custom LoggingFilter and configure it in akka.logging-filter that filters out those messages before they are even posted.

The default slf4j logging filter will use whatever settings you define in your logging backend's client configuration but you could provide a custom one as well that filters out those message directly.

See here for sl4j's default filter: https://github.com/akka/akka/blob/master/akka-slf4j/src/main/scala/akka/event/slf4j/Slf4jLogger.scala#L134

A custom implementation that filters out all debug messages from them pool (as witnessed by containing "/Pool(" in the logSource) could look like this:

package xyz
import akka.event.slf4j.Logger

class CustomAkkaHttpSlf4jLoggingFilter(settings: ActorSystem.Settings, eventStream: EventStream) extends LoggingFilter {
  def isErrorEnabled(logClass: Class[_], logSource: String) =
    (eventStream.logLevel >= ErrorLevel) && Logger(logClass, logSource).isErrorEnabled
  def isWarningEnabled(logClass: Class[_], logSource: String) =
    (eventStream.logLevel >= WarningLevel) && Logger(logClass, logSource).isWarnEnabled
  def isInfoEnabled(logClass: Class[_], logSource: String) =
    (eventStream.logLevel >= InfoLevel) && Logger(logClass, logSource).isInfoEnabled
  def isDebugEnabled(logClass: Class[_], logSource: String) =
    !logSource.contains("/Pool(") &&
    (eventStream.logLevel >= DebugLevel) && Logger(logClass, logSource).isDebugEnabled
}

You enable it by setting

akka.log-filter = xyz.CustomAkkaHttpSlf4jLoggingFilter

[ochrons]

Got it working fine with this filter, thanks for the quick response!