MDC: Worth the hassle?

[Timothy Perrett]

Hey all,

I've read the back posts here around SLF4J MDC and the issues it has given its based on thread-locals... its a shame these issues exist as in principal it's a very convenient mechanism for certain types of diagnostics. 

I was just wondering if anyone had played around with or considered implementing their own MDC adaptor on top of Akka agents? I'm not an MDC expert by any means, but its an interesting enough topic to make me wonder if it can be implemented in a more async-friendly way. Clearly there are issues around using logback for the rest of the logging infrastructure, but assuming that was resolved, the whole MDC cycle looks to me like a shared map with lots of writers and readers. 

Alternatively, what sane ways do people have of using MDC within Akka? I notice that MDC is used internally just to correlate threads and sources, but otherwise there is no easily consumable api to make using it easier (unless i've missed it?). I'm assuming thats for one of two reasons: 1) people dont care about MDC 2) people dont have cycles to implement it. 

Cheers, Tim 

[Alec Zorab]

I use slf4j -> logback for all my logging without issue. 

You can bolt extra bits into the logging system by abusing LoggingAdapter and the fact that the actual message go onto the event bus as type Any, but I suspect you're in dangerous territory by then. That said, I think you could make your custom adapter ship the mdc along with the message itself, copy that into the thread mdc inside your eventhandler and then you're done.

Either that or just make your own logging infrastructure where you attach a Map[String, String] in the logging call and then pass that around. The logging in akka is pretty simple, so it should be easy enough to duplicate.

Hope that helps!

--
>>>>>>>>>> Read the docs: http://akka.io/docs/
>>>>>>>>>> Check the FAQ: http://akka.io/faq/
>>>>>>>>>> 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 post to this group, send email to akka...@googlegroups.com.
To unsubscribe from this group, send email to akka-user+...@googlegroups.com.
Visit this group at http://groups.google.com/group/akka-user?hl=en.
 
 

[Roland Kuhn]

Hi Tim,

the MDC thingy is—to my mind—just an ugly hack to pass arguments “around” the real interface, presumably because someone thought that doing it properly would look too cumbersome in Java (just guessing).

I completely understand the desire to add more data to log statements. The most obvious choice would be to include those data in the log message. If some more structure is needed, why not pass a Map[String, AnyRef] along with the log event? Then you could use the MDC for the SLF4J “back-end façade” or whatever else in some other case (is anybody still logging directly into MySQL?). As Alec said, Logging.scala is a rather simple thing, so the only thing missing (taking an educated guess here) is that you’d need to pass along your auxiliary data through the call stack. Using Scala I’d recommend trying out using implicit arguments of type

case class MoreLogData(val dict: Map[String, AnyRef])

object MoreLogData {

def add(key: String, value: AnyRef)(implicit mld: MoreLogData) = mld.copy(mld.dict + (key -> value))

def remove(key: String)(implicit mld: MoreLogData) = mld.copy(mld.dict - key)

}

in your code. I’d call that a “more principled replacement for thread-locals” ;-)

def myMethod(...)(implicit mld: MoreLogData) = {

  ...

  myOtherMethod(...) // implicitly picks up mld

  ...

  yetAnotherMethod(...)(MoreLogData add "hello" -> "world") // explicit addition

}

If you try this and find it to work well, please let us know (possibly in the form of a pull request?).

Regards,

Roland

--
>>>>>>>>>> Read the docs: http://akka.io/docs/
>>>>>>>>>> Check the FAQ: http://akka.io/faq/
>>>>>>>>>> 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 post to this group, send email to akka...@googlegroups.com.
To unsubscribe from this group, send email to akka-user+...@googlegroups.com.
Visit this group at http://groups.google.com/group/akka-user?hl=en.
 
 

Roland Kuhn
Typesafe – The software stack for applications that scale.
twitter: @rolandkuhn

[Timothy Perrett]

Hey Roland,

Yeah I looked at the source code already and after having slept on it think i'll just implement my own LoggingAdaptor type thing that has the extra features I want (implementing my own SLF4J event handler to pass through markers and MDC would also be trivial).

I'll work on it this morning and see how it pans out - if I didn't have to support more imperative use cases it could probably be implemented quite nicely with a combination of Writer & State monads, but c'est la vie. 

Cheers, Tim 

[Timothy Perrett]

By way of an update - I did implement this with implicits in the end; only time will tell how it works out in practice. I did origionally start modifying the akka codebase, but then recalled that using implicits will break the java API (break in terms of making other params mandatory that wouldn't "make sense"), so for the moment I can't really contribute it back.

As you said Roland, there isnt really a decent way to do it in Java that isn't noisy for users - luckily not a concern for me, but it is for Akka :-( 

Cheers, Tim 

[Evan Chan]

By the way, I started looking at Logback and really like it.   I don't think MDC is a hack actually.  It is designed for the use case when individual threads have thread-specific context, so that you initialize the MDC once for that thread, or don't change it much, and the data is used for all logging messages in that thread.   Why waste passing in extra data with each message when, in the intended use case, it will mostly be the same?

Obviously, this model doesn't fit with Actors that well.   What we'd want is a per-Actor-class/instance context for logging.   If you had to set the MDC map every time a new actor came into a thread, that would be pretty expensive.

Maybe we should chat with the creator(s) of Logback/SLF4J and see what they think.  Ideally Logback would hook into the currently running actor context, instead of a thread-local map.

Tim, I'd be curious about your custom log adaptor to see how well that works.

-Evan

--
--
Evan Chan
Senior Software Engineer | 
e...@ooyala.com | (650) 996-4600
www.ooyala.com | blog | @ooyala

[Alec Zorab]

MDC seems, to me, to be designed for a threading model which most of us seem to have moved away from as we've discovered how unscalable it is.

[Roland Kuhn]

26 nov 2012 kl. 20:26 skrev Evan Chan:

By the way, I started looking at Logback and really like it.   I don't think MDC is a hack actually.  It is designed for the use case when individual threads have thread-specific context, so that you initialize the MDC once for that thread, or don't change it much, and the data is used for all logging messages in that thread.   Why waste passing in extra data with each message when, in the intended use case, it will mostly be the same?

Obviously, this model doesn't fit with Actors that well.   What we'd want is a per-Actor-class/instance context for logging.   If you had to set the MDC map every time a new actor came into a thread, that would be pretty expensive.

Maybe we should chat with the creator(s) of Logback/SLF4J and see what they think.  Ideally Logback would hook into the currently running actor context, instead of a thread-local map.

The problem here is that the context of the log.XXX() call is not where logback gets involved, because those messages in effect just send events to an actor which calls into SLF4J. Which brings me back to the original point: the LoggingAdapter needs to pick up that extra information an package it into the Logging.Event so that it can then be properly passed on to the back-end by the logging actor.

Regards,

Roland

[Tim Perrett]

Alec, agreed :-) 

[Yung-Lin Ho]

IMHO, the old threading application model is to have one thread serving one request. As a result, the MDC become the request specific logging context. MDC is a great tool to trace the processing of a request and record state changes.

However, in the actor model, we would fan out multiple threads to serve one request. The hard problem is how to relate logs, generated from different threads and from remote actors, into one set of logs.