MDC propagation via Akka dispatcher not extending to Play filters

jsw...@ebay.com

unread,

Sep 26, 2016, 2:38:25 PM9/26/16

to Play Framework

I've setup my Play 2.5 app to use an MDC propagating dispatcher via the instructions here

http://yanns.github.io/blog/2014/05/04/slf4j-mapped-diagnostic-context-mdc-with-play-framework/

It works great for most cases, but one particular case it doesn't is Play filters.

An example thread name is "ForkJoinPool-1-worker-10", which may give a clue that it's not an akka thread?

I am using compile-time DI and manually instantiating the filters, and making sure that play.api.libs.concurrent.Execution.Implicits.defaultContext is in scope.

Is this expected? Is there a workaround?

jeff

Will Sargent

unread,

Sep 26, 2016, 3:41:02 PM9/26/16

to play-fr...@googlegroups.com

MDC is always thread based, so it's a fragile solution in general for Play, which is not using the same paradigm. You may have a custom execution context that you have to extend (it's mentioned as one of the other solutions in the blog post).

You can also try using an SLF4J marker instead and passing it through methods as an implicit context -- this does require you to have your own logging wrapper, but it's checked at compile time and can pass between threads.

--

Will Sargent

Engineer, Lightbend, Inc.

will.s...@lightbend.com

--
You received this message because you are subscribed to the Google Groups "Play Framework" group.
To unsubscribe from this group and stop receiving emails from it, send an email to play-framework+unsubscribe@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/play-framework/cdad6623-4b47-4c54-afa9-cde736ade5e6%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

jsw...@ebay.com

unread,

Sep 27, 2016, 11:31:19 AM9/27/16

to Play Framework

Will,

I understand that MDC uses thread-local, and is fragile in Play, but I was under the impression that all the Play components would be run in Akka threads, including the filters, so would expect my solution to work here. I like that this solution doesn't require creating a custom EC, and so I make sure to use play.api.libs.concurrent.Execution.Implicits.defaultContext everywhere, which does work in nearly all of my log statements. Is there something special about the play filters that prevents this solution from working?

As for the marker solution, I'm not sure how that would work as the play filters are not invoked by application code, and even if so, they have a defined signature. I wonder if you're suggesting I use a wrapping Action instead of a filter. For my case, this is an access log filter, which I'd really like to use application-wide.

jeff

On Monday, September 26, 2016 at 12:41:02 PM UTC-7, Will Sargent wrote:

MDC is always thread based, so it's a fragile solution in general for Play, which is not using the same paradigm. You may have a custom execution context that you have to extend (it's mentioned as one of the other solutions in the blog post).

You can also try using an SLF4J marker instead and passing it through methods as an implicit context -- this does require you to have your own logging wrapper, but it's checked at compile time and can pass between threads.

--
Will Sargent
Engineer, Lightbend, Inc.
will.s...@lightbend.com

On Mon, Sep 26, 2016 at 11:38 AM, <jsw...@ebay.com> wrote:

I've setup my Play 2.5 app to use an MDC propagating dispatcher via the instructions here

http://yanns.github.io/blog/2014/05/04/slf4j-mapped-diagnostic-context-mdc-with-play-framework/

It works great for most cases, but one particular case it doesn't is Play filters.

An example thread name is "ForkJoinPool-1-worker-10", which may give a clue that it's not an akka thread?

I am using compile-time DI and manually instantiating the filters, and making sure that play.api.libs.concurrent.Execution.Implicits.defaultContext is in scope.

Is this expected? Is there a workaround?

jeff

--
You received this message because you are subscribed to the Google Groups "Play Framework" group.

To unsubscribe from this group and stop receiving emails from it, send an email to play-framewor...@googlegroups.com.

jsw...@ebay.com

unread,

Nov 21, 2016, 4:25:43 PM11/21/16

to Play Framework

Bump. I have since seen evidence that filters sometimes run in a ForkJoinPool thread and sometimes run in an Akka thread. Is this expected?

application-akka.actor.default-dispatcher-4

ForkJoinPool-1-worker-18

jeff

Igmar Palsenberg

unread,

Nov 21, 2016, 5:02:29 PM11/21/16

to Play Framework

Bump. I have since seen evidence that filters sometimes run in a ForkJoinPool thread and sometimes run in an Akka thread. Is this expected?

application-akka.actor.default-dispatcher-4
ForkJoinPool-1-worker-18

As a sidenote : I can confirm this. Leads to very awkward, very strange to debug issues.

Igmar

Will Sargent

unread,

Nov 21, 2016, 7:57:44 PM11/21/16

to play-fr...@googlegroups.com

Are you talking about https://github.com/playframework/playframework/issues/6670 ?

--

Will Sargent

Engineer, Lightbend, Inc.

will.s...@lightbend.com

--

You received this message because you are subscribed to the Google Groups "Play Framework" group.

To unsubscribe from this group and stop receiving emails from it, send an email to play-framework+unsubscribe@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/play-framework/f8e7e22b-2461-4dcf-a461-2faa4e3b0f66%40googlegroups.com.

jsw...@ebay.com

unread,

Nov 21, 2016, 8:08:55 PM11/21/16

to Play Framework

Likely. I see the relevant PR made it in to 2.5.10, so I will upgrade to verify the issue is fixed. Thanks!

jeff

On Monday, November 21, 2016 at 4:57:44 PM UTC-8, Will Sargent wrote:

Are you talking about https://github.com/playframework/playframework/issues/6670 ?

--
Will Sargent
Engineer, Lightbend, Inc.
will.s...@lightbend.com

On Mon, Nov 21, 2016 at 2:02 PM, Igmar Palsenberg <ig...@palsenberg.com> wrote:

Bump. I have since seen evidence that filters sometimes run in a ForkJoinPool thread and sometimes run in an Akka thread. Is this expected?

application-akka.actor.default-dispatcher-4
ForkJoinPool-1-worker-18

As a sidenote : I can confirm this. Leads to very awkward, very strange to debug issues.

Igmar

--
You received this message because you are subscribed to the Google Groups "Play Framework" group.

To unsubscribe from this group and stop receiving emails from it, send an email to play-framewor...@googlegroups.com.

jsw...@ebay.com

unread,

Nov 21, 2016, 10:23:26 PM11/21/16

to Play Framework

Updating to 2.5.10 did not fix my particular issue, but I did locate the root cause.

I have a logging filter that uses implicit parameters to inject the ExecutionContext

class AccessLogFilter @Inject()(implicit val mat: Materializer, ec: ExecutionContext) extends Filter

The filter is manually constructed in a custom ApplicationLoader which imports play.api.libs.concurrent.Execution.Implicits.defaultContext. I discovered in play.core.Execution.scala

def internalContext: ExecutionContextExecutor = {
  val appOrNull: Application = Play._currentApp
  appOrNull match {
    case null => common
    case app: Application => app.actorSystem.dispatcher
  }
}
...
private val common = ExecutionContext.fromExecutor(new ForkJoinPool())

So evidently, the EC is being bound to the ForkJoinPool because there is no currentApp yet, which makes sense.

I tested that changing my filter to not accept the EC parameter and instead directly import the play EC works as expected.

From looking at the filters documentation, I see examples that import the play EC and examples that inject the EC.

Is my workaround an expected but unfortunate aspect of using compile-time DI?

I'm happy moving forward with my workaround (I do not need the flexibility of injecting the EC), but wanted to see if there's a better solution, or possible opportunity to improve play default EC implementation.

jeff

Greg Methvin

unread,

Nov 22, 2016, 1:40:45 AM11/22/16

to play-framework

Hi jeff,

On Mon, Nov 21, 2016 at 7:23 PM, <jsw...@ebay.com> wrote:

Updating to 2.5.10 did not fix my particular issue, but I did locate the root cause.

I have a logging filter that uses implicit parameters to inject the ExecutionContext

class AccessLogFilter @Inject()(implicit val mat: Materializer, ec: ExecutionContext) extends Filter

The filter is manually constructed in a custom ApplicationLoader which imports play.api.libs.concurrent.Execution.Implicits.defaultContext. I discovered in play.core.Execution.scala

If the ApplicationLoader uses BuiltInComponents you can use actorSystem.dispatcher as the execution context:

implicit lazy val executionContext: ExecutionContext = actorSystem.dispatcher

(This is being added to BuiltInComponents in 2.6)

def internalContext: ExecutionContextExecutor = { val appOrNull: Application = Play._currentApp appOrNull match { case null => common case app: Application => app.actorSystem.dispatcher } } ... private val common = ExecutionContext.fromExecutor(new ForkJoinPool())
So evidently, the EC is being bound to the ForkJoinPool because there is no currentApp yet, which makes sense.
I tested that changing my filter to not accept the EC parameter and instead directly import the play EC works as expected.

From looking at the filters documentation, I see examples that import the play EC and examples that inject the EC.

I would prefer injecting the EC whenever possible. The import was designed for apps that used static state, and we should eventually rewrite those examples to use DI.

Is my workaround an expected but unfortunate aspect of using compile-time DI?
I'm happy moving forward with my workaround (I do not need the flexibility of injecting the EC), but wanted to see if there's a better solution, or possible opportunity to improve play default EC implementation.

No. If you tried to do the equivalent thing using runtime DI you would have the same issue. The problem is that the Application depends on your filter to be constructed, so the filter has to be created first. That means anything (like Execution.defaultContext) that requires a running app won't work. It's basically a circular dependency.

Greg

jeff

On Monday, November 21, 2016 at 5:08:55 PM UTC-8, jsw...@ebay.com wrote:
Likely. I see the relevant PR made it in to 2.5.10, so I will upgrade to verify the issue is fixed. Thanks!

jeff

On Monday, November 21, 2016 at 4:57:44 PM UTC-8, Will Sargent wrote:
Are you talking about https://github.com/playframework/playframework/issues/6670 ?

--
Will Sargent
Engineer, Lightbend, Inc.
will.s...@lightbend.com

On Mon, Nov 21, 2016 at 2:02 PM, Igmar Palsenberg <ig...@palsenberg.com> wrote:

Bump. I have since seen evidence that filters sometimes run in a ForkJoinPool thread and sometimes run in an Akka thread. Is this expected?

application-akka.actor.default-dispatcher-4
ForkJoinPool-1-worker-18

As a sidenote : I can confirm this. Leads to very awkward, very strange to debug issues.

Igmar

--
You received this message because you are subscribed to the Google Groups "Play Framework" group.
To unsubscribe from this group and stop receiving emails from it, send an email to play-framewor...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/play-framework/f8e7e22b-2461-4dcf-a461-2faa4e3b0f66%40googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

--
You received this message because you are subscribed to the Google Groups "Play Framework" group.

To unsubscribe from this group and stop receiving emails from it, send an email to play-framework+unsubscribe@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/play-framework/aca44432-5e9f-45c1-bade-a018e8376b7f%40googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

--

Greg Methvin

Senior Software Engineer

Lightbend, Inc.

jsw...@ebay.com

unread,

Nov 22, 2016, 2:12:55 AM11/22/16

to Play Framework

Greg,

Since the filter already has a Materializer injected in order to implement the trait, would it be better or worse to use its EC as in this example, thus not needing the additional parameter?

class AccessLogFilter @Inject()(implicit val mat: Materializer) extends Filter {
  def apply(nextFilter: RequestHeader => Future[Result])(requestHeader: RequestHeader) = {
    nextFilter(requestHeader).map { result =>
      ...
    } (mat.executionContext)
  }
}

jeff

Hi jeff,

To view this discussion on the web visit https://groups.google.com/d/msgid/play-framework/aca44432-5e9f-45c1-bade-a018e8376b7f%40googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

Greg Methvin

unread,

Nov 22, 2016, 3:01:35 AM11/22/16

to Play Framework

I can't think of any reason you'd want to configure them separately, so it'd probably be fine to just inject the materializer.

_____________________________
From: jsw...@ebay.com
Sent: Monday, November 21, 2016 23:12
Subject: Re: [play-framework] MDC propagation via Akka dispatcher not extending to Play filters
To: Play Framework <play-fr...@googlegroups.com>

To view this discussion on the web visit https://groups.google.com/d/msgid/play-framework/673c383f-56b1-4c5c-983c-d769ad1296e9%40googlegroups.com.

Reply all

Reply to author

Forward