MDC propagation breaks between 2.6.9 -> 2.6.10

123 views
Skip to first unread message

Jeff White

unread,
Jan 9, 2018, 1:19:30 PM1/9/18
to Play Framework
I have been using a combination of an MDC-propagating ExecutionContext and a Play filter to assign a requestId to every incoming request and have it included in every log statement by logback. This stopped working upon updating play 2.6.9 -> 2.6.10. I suspect it may be related to these changes


Example 2.6.9 logs

2018-01-09 09:52:14,100 [INFO ] [play-dev-mode-akka.actor.default-dispatcher-6] [requestId=+tFe6IIoQyiMt4YYfT1MmQ] c.e.n.p.s.c.HttpContextFilter:27 Hello HttpContextFilter
2018-01-09 09:52:14,102 [INFO ] [application-akka.actor.default-dispatcher-2] [requestId=+tFe6IIoQyiMt4YYfT1MmQ] c.e.n.p.s.c.AccessLogFilter:76 0:0:0:0:0:0:0:1

Example 2.6.10 logs (note missing requestId in the 2nd statement)

2018-01-09 09:54:55,343 [INFO ] [application-akka.actor.default-dispatcher-2] [requestId=z699KLkFQLG7BbTKoX+BGg] c.e.n.p.s.c.HttpContextFilter:27 Hello HttpContextFilter
2018-01-09 09:54:55,346 [INFO ] [application-akka.actor.default-dispatcher-9] [] c.e.n.p.s.c.AccessLogFilter:76 0:0:0:0:0:0:0:1

Details of the MDC propagation setup


Let me know if I should move this to a github issue

thanks
jeff

Greg Methvin

unread,
Jan 10, 2018, 3:52:26 AM1/10/18
to play-framework
I'm not sure exactly why your solution isn't working. You are using the deprecated ExecutionContext#prepare method, but it's hard to tell if that's not the actual problem. What are you doing in your AccessLogFilter?

--
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/efa535a7-fa60-4452-ad85-f5038b762027%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.



--
Greg Methvin
Tech Lead - Play Framework

Matthias Erche

unread,
Jan 10, 2018, 7:39:58 AM1/10/18
to play-fr...@googlegroups.com
I don't know if it helps but we're using the solution described in http://yanns.github.io/blog/2014/05/04/slf4j-mapped-diagnostic-context-mdc-with-play-framework/ to correlate requests via some kind of identifier which can be used for logging.

We don't encounter any issues after upgrading to 2.6.10.


Greg Methvin <gr...@lightbend.com> schrieb am Mi., 10. Jan. 2018 um 09:52 Uhr:
I'm not sure exactly why your solution isn't working. You are using the deprecated ExecutionContext#prepare method, but it's hard to tell if that's not the actual problem. What are you doing in your AccessLogFilter?
On Tue, Jan 9, 2018 at 10:19 AM, Jeff White <jsw...@ebay.com> wrote:
I have been using a combination of an MDC-propagating ExecutionContext and a Play filter to assign a requestId to every incoming request and have it included in every log statement by logback. This stopped working upon updating play 2.6.9 -> 2.6.10. I suspect it may be related to these changes


Example 2.6.9 logs

2018-01-09 09:52:14,100 [INFO ] [play-dev-mode-akka.actor.default-dispatcher-6] [requestId=+tFe6IIoQyiMt4YYfT1MmQ] c.e.n.p.s.c.HttpContextFilter:27 Hello HttpContextFilter
2018-01-09 09:52:14,102 [INFO ] [application-akka.actor.default-dispatcher-2] [requestId=+tFe6IIoQyiMt4YYfT1MmQ] c.e.n.p.s.c.AccessLogFilter:76 0:0:0:0:0:0:0:1

Example 2.6.10 logs (note missing requestId in the 2nd statement)

2018-01-09 09:54:55,343 [INFO ] [application-akka.actor.default-dispatcher-2] [requestId=z699KLkFQLG7BbTKoX+BGg] c.e.n.p.s.c.HttpContextFilter:27 Hello HttpContextFilter
2018-01-09 09:54:55,346 [INFO ] [application-akka.actor.default-dispatcher-9] [] c.e.n.p.s.c.AccessLogFilter:76 0:0:0:0:0:0:0:1

Details of the MDC propagation setup


Let me know if I should move this to a github issue

thanks
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.

To view this discussion on the web visit https://groups.google.com/d/msgid/play-framework/efa535a7-fa60-4452-ad85-f5038b762027%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.
--
Greg Methvin
Tech Lead - Play Framework

--
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/CAA%3D11HxQ%2BV-mHPi3U_ww0n-KoiuphA%2BZwTJiHqoXN7kkRteuQA%40mail.gmail.com.

Greg Methvin

unread,
Jan 10, 2018, 6:20:07 PM1/10/18
to play-framework
Which solution are you using? The last solution mentioned there doesn't use prepare, so it will work on future versions of Scala.

Note that a more DI-friendly way of doing that would be to have something like:

class ExecutionContextProvider @Inject()(ec: ExecutionContext) {
  implicit def executionContext: ExecutionContext = MDCHttpExecutionContext.fromThread(ec)
}

then in your component:

class MyController @Inject()(ecProvider: ExecutionContextProvider) {
  import ecProvider._
  // now your custom implicit ExecutionContext will be used
}

On Wed, Jan 10, 2018 at 4:39 AM, Matthias Erche <erc...@gmail.com> wrote:
I don't know if it helps but we're using the solution described in http://yanns.github.io/blog/2014/05/04/slf4j-mapped-diagnostic-context-mdc-with-play-framework/ to correlate requests via some kind of identifier which can be used for logging.

We don't encounter any issues after upgrading to 2.6.10.


Greg Methvin <gr...@lightbend.com> schrieb am Mi., 10. Jan. 2018 um 09:52 Uhr:
I'm not sure exactly why your solution isn't working. You are using the deprecated ExecutionContext#prepare method, but it's hard to tell if that's not the actual problem. What are you doing in your AccessLogFilter?
On Tue, Jan 9, 2018 at 10:19 AM, Jeff White <jsw...@ebay.com> wrote:
I have been using a combination of an MDC-propagating ExecutionContext and a Play filter to assign a requestId to every incoming request and have it included in every log statement by logback. This stopped working upon updating play 2.6.9 -> 2.6.10. I suspect it may be related to these changes


Example 2.6.9 logs

2018-01-09 09:52:14,100 [INFO ] [play-dev-mode-akka.actor.default-dispatcher-6] [requestId=+tFe6IIoQyiMt4YYfT1MmQ] c.e.n.p.s.c.HttpContextFilter:27 Hello HttpContextFilter
2018-01-09 09:52:14,102 [INFO ] [application-akka.actor.default-dispatcher-2] [requestId=+tFe6IIoQyiMt4YYfT1MmQ] c.e.n.p.s.c.AccessLogFilter:76 0:0:0:0:0:0:0:1

Example 2.6.10 logs (note missing requestId in the 2nd statement)

2018-01-09 09:54:55,343 [INFO ] [application-akka.actor.default-dispatcher-2] [requestId=z699KLkFQLG7BbTKoX+BGg] c.e.n.p.s.c.HttpContextFilter:27 Hello HttpContextFilter
2018-01-09 09:54:55,346 [INFO ] [application-akka.actor.default-dispatcher-9] [] c.e.n.p.s.c.AccessLogFilter:76 0:0:0:0:0:0:0:1

Details of the MDC propagation setup


Let me know if I should move this to a github issue

thanks
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-framework+unsubscribe@googlegroups.com.
--
Greg Methvin
Tech Lead - Play Framework

--
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/CAA%3D11HxQ%2BV-mHPi3U_ww0n-KoiuphA%2BZwTJiHqoXN7kkRteuQA%40mail.gmail.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/CAOf-V-ymN%2B7nb2Htp%3Dxc1YvBXYrHgL_mF58DSthujExa9TOAxQ%40mail.gmail.com.

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

Jeff White

unread,
Jan 10, 2018, 6:42:50 PM1/10/18
to Play Framework
To add more context: my solution (details here) is originally based on that same blog post by Yann Simon (solution 1: custom Akka dispatcher) and has evolved with help from Yann's comment in this related Github issue I opened June 2017. The current solution has worked all the way up to play 2.6.9.


Yes, it uses ExecutionContext.prepare(), which is deprecated, however not removed and no plan for replacement.


Will the 2nd solution in the blog post work? I'm not sure if it's possible to direct Play internals to use a custom EC, compared to the first solution of configuring the Akka dispatcher.

Greg: The AccessLogFilter just logs standard request details and timing info after the request is handled. If the MDC is present in the log statement, then it demonstrates the MDC was successfully propagated all the way to the end.

jeff

To unsubscribe from this group and stop receiving emails from it, send an email to play-framewor...@googlegroups.com.
--
Greg Methvin
Tech Lead - Play Framework

--
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.

--
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.

Greg Methvin

unread,
Jan 10, 2018, 7:49:34 PM1/10/18
to play-framework
On Wed, Jan 10, 2018 at 3:42 PM, Jeff White <jsw...@ebay.com> wrote:
To add more context: my solution (details here) is originally based on that same blog post by Yann Simon (solution 1: custom Akka dispatcher) and has evolved with help from Yann's comment in this related Github issue I opened June 2017. The current solution has worked all the way up to play 2.6.9.


Yes, it uses ExecutionContext.prepare(), which is deprecated, however not removed and no plan for replacement.

Yes, but it's no longer supposed to be called. Though the standard library does call it, there's no guarantee that other libraries will, and it would now be incorrect for them to do so. I have no idea if that's why it's not working, though. Just pointing out that using prepare might not work going forward.
 


Will the 2nd solution in the blog post work? I'm not sure if it's possible to direct Play internals to use a custom EC, compared to the first solution of configuring the Akka dispatcher.

I think it should work. In general, your top-level EssentialAction (with filters) is executed once in the Play default execution context, and the only other significant "internal" place is in the ActionBuilder, which is customizable. You could override Action in BaseController to use your custom execution context, or just use a different action builder. Everywhere else a context switch occurs, you should have control over the ExecutionContext being passed.
 

Greg: The AccessLogFilter just logs standard request details and timing info after the request is handled. If the MDC is present in the log statement, then it demonstrates the MDC was successfully propagated all the way to the end.

So it's just an EssentialAction, with nothing being executed in a separate ExecutionContext?

Also are you using Netty or Akka HTTP? Does it make a difference which server you use?
 
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/cffa7a52-cef3-4b1f-a91c-2780e5f42134%40googlegroups.com.

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

Yann Simon

unread,
Jan 11, 2018, 2:56:50 AM1/11/18
to play-fr...@googlegroups.com
I'm glad that we are discussing this problem.

My 2 cents:

We are also using a custom akka dispatch + custom execution context.
(I have to update my blog post to write this there)

The "prepare" is deprecated, but is the only way to propagate the MDC context with a custom execution context.
I had a talk with Viktor about it. The last words was that he preferred deprecating the "prepare" method as it's more complex (and too easy to forget / mis-use - I fully understand this) and that there's no more solution for this this.

I guess we will have to find other alternatives ways.
Kamon.io for example relies on bytecode manipulation to propagate their TraceContext: http://kamon.io/documentation/0.6.x/kamon-akka/automatic-trace-context-propagation/
I'm personally not a big fan of bytecode manipulation, but this could be a way to go.
Lightbend also offers https://developer.lightbend.com/docs/monitoring/latest/extensions/mdc.html, which requires a commercial license.
MarkerContext can also help https://playframework.com/documentation/2.6.x/ScalaLogging#Using-Markers-and-Marker-Contexts, but only for methods that are implemented for that.

Cheers, Yann




--
Greg Methvin
Tech Lead - Play Framework

--
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/CAA%3D11HwCQcfs4bT6DDOoTWhqt87rJXSvyRuxLCWHQ4wEm%2BYvYQ%40mail.gmail.com.

Jeff White

unread,
Jan 11, 2018, 1:17:20 PM1/11/18
to Play Framework


On Wednesday, January 10, 2018 at 4:49:34 PM UTC-8, Greg Methvin wrote:
On Wed, Jan 10, 2018 at 3:42 PM, Jeff White <jsw...@ebay.com> wrote:
To add more context: my solution (details here) is originally based on that same blog post by Yann Simon (solution 1: custom Akka dispatcher) and has evolved with help from Yann's comment in this related Github issue I opened June 2017. The current solution has worked all the way up to play 2.6.9.


Yes, it uses ExecutionContext.prepare(), which is deprecated, however not removed and no plan for replacement.

Yes, but it's no longer supposed to be called. Though the standard library does call it, there's no guarantee that other libraries will, and it would now be incorrect for them to do so. I have no idea if that's why it's not working, though. Just pointing out that using prepare might not work going forward.
 

Fair. I am weaning myself off it, but log correlation via requestId is so helpful in troubleshooting live-site issues, especially across multiple services.
 


Will the 2nd solution in the blog post work? I'm not sure if it's possible to direct Play internals to use a custom EC, compared to the first solution of configuring the Akka dispatcher.

I think it should work. In general, your top-level EssentialAction (with filters) is executed once in the Play default execution context, and the only other significant "internal" place is in the ActionBuilder, which is customizable. You could override Action in BaseController to use your custom execution context, or just use a different action builder. Everywhere else a context switch occurs, you should have control over the ExecutionContext being passed.

I'll take a deeper look at that solution and start another thread if I have questions.
 
 

Greg: The AccessLogFilter just logs standard request details and timing info after the request is handled. If the MDC is present in the log statement, then it demonstrates the MDC was successfully propagated all the way to the end.

So it's just an EssentialAction, with nothing being executed in a separate ExecutionContext?


 

Also are you using Netty or Akka HTTP? Does it make a difference which server you use?

Akka. Slight preference for that as it's the default and seems to be what you guys are encouraging going forward.
 
 
Reply all
Reply to author
Forward
0 new messages