Logging settings

1,184 views
Skip to first unread message

Sam Halliday

unread,
Nov 30, 2012, 6:24:53 AM11/30/12
to akka...@googlegroups.com
Hi all,


I would like to make use of the following settings

  actor.debug.unhandled = true
  loglevel = DEBUG

but it means that lots of third party Actors (e.g. Spray Client) are now printing lots of debugging that I don't want to see.

Is there any way to turn on "unhandled" DEBUG messages without opening up DEBUG logging for everything?

Furthermore, is there any reason why Akka has rolled its own Logging system instead of simply building on java.util.logging or SLF4J? I would have thought J2SE logging would have been more than enough for Akka's requirements.

√iktor Ҡlang

unread,
Nov 30, 2012, 7:33:33 AM11/30/12
to Akka User List
Hi Sam!

For the debug logging: You can install your own LoggingAdapter and filter out the irrelevant parts.

Synchronous logging does not work in a highly concurrent/parallel system, and we didn't want a dependency on non-jdk for akka-actor.jar and we wanted people to use whatever logging lib they wanted. Akka Logging achieves all of that. (and j.u.logging is possibly the worst logging tool since System.out)

Happy hAkking!

Cheers,


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



--
Viktor Klang

Director of Engineering
Typesafe - The software stack for applications that scale

Twitter: @viktorklang

Samuel Halliday

unread,
Nov 30, 2012, 8:05:50 AM11/30/12
to akka...@googlegroups.com
Thanks Victor,

It does make sense to have an asynchronous logger. It's a shame this isn't simply a thin layer on top of Java solutions.

I see the same thing happening in Scala – regarding logging – as I did in Java. I hope there is some consensus before somebody has to write SLF4S !

Is there a nice config file syntax (like in J2SE) to set the logging filter level of packages?

--
Sam

√iktor Ҡlang

unread,
Nov 30, 2012, 8:10:45 AM11/30/12
to Akka User List
You're welcome!

As for the config of the logging, you can use any logging backend you like, see: http://doc.akka.io/docs/akka/2.1.0-RC3/scala/logging.html

Happy hAkking!

Samuel Halliday

unread,
Nov 30, 2012, 9:32:46 AM11/30/12
to akka...@googlegroups.com
Thanks Victor,

I've enabled SLF4J and the jdk14 backend.

However, two things still puzzle me:

1. I'm getting stdout messages coming directly from Akka, e.g.
[default-akka.actor.default-dispatcher-10] [EventStream] shutting down: StandardOutLogger started

2. The source class in all my logs is
akka.event.slf4j.Slf4jEventHandler$$anonfun$receive$1$$anonfun$applyOrElse$3 apply$mcV$sp

so I don't seem to be able to filter the output by classname (and realistically, I will change the formatter because that's just awful).


Ideally, the source Actor would be the source class in the logs here, and the logger name would be the actorOf reference name of that instance.

Any help please?

--
Sam

Evan chan

unread,
Nov 30, 2012, 10:21:49 AM11/30/12
to akka...@googlegroups.com, akka...@googlegroups.com
Pretty interested in this thread, as I have the exact same thoughts.... Akka's default logging system does not allow one to take advantage of Logback's nice features, like dynamic config file reloading (pretty important feature for long running processes, IMHO)

-Evan
Carry your candle, run to the darkness
Seek out the helpless, deceived and poor
Hold out your candle for all to see it
Take your candle, and go light your world

Alec Zorab

unread,
Nov 30, 2012, 12:01:32 PM11/30/12
to akka...@googlegroups.com
The akka logging framework is *tiny*.

Just roll your own :)

Samuel Halliday

unread,
Nov 30, 2012, 12:03:12 PM11/30/12
to akka...@googlegroups.com
On 30 Nov 2012, at 17:01, Alec Zorab wrote:
> The akka logging framework is *tiny*.
>
> Just roll your own :)

WARNING: Here be Dragons!

Alec Zorab

unread,
Nov 30, 2012, 12:35:56 PM11/30/12
to akka...@googlegroups.com
trait MyLogging {
 ths: Actor =>
 val log = MyLoggingExtension(context.system)
}

class MyActor extends MyLogging {
  log.info("This goes straight to logback, if that's what I want to do")
}


Alec Zorab

unread,
Nov 30, 2012, 12:37:51 PM11/30/12
to akka...@googlegroups.com
Apologies for the double post, but I thought I should clarify - I'm not actually suggesting you synchronously log to disk unless you really like having terrible scaling and performance.

Evan Chan

unread,
Nov 30, 2012, 12:51:30 PM11/30/12
to akka...@googlegroups.com
Does the Akka logging actor batch stuff before sending it to SLF4J etc?  Otherwise it is also writing to disk every time.

I believe this is configurable in most backends....

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

Samuel Halliday

unread,
Nov 30, 2012, 12:53:59 PM11/30/12
to akka...@googlegroups.com
That doesn't work for me – I want to be able to see the unhandled messages and that's all Akka internals. Trying to get that to talk to SLF4J has made me lose all information about the calling Actor.

Other than the unhandled responses, I don't see why a slim wrapper around SLF4J or JDK14 logging (which launch the actual logging calls in a Future} wouldn't do. Can somebody enlighten me?

If the main problem was synchronous/asynchronous logging, I don't see why it was necessary to write an entire logging system from scratch. I love Akka, but when I found out about this NIH Logging I had to go for some fresh air.

--
Sam

Alec Zorab

unread,
Nov 30, 2012, 12:57:49 PM11/30/12
to akka...@googlegroups.com
I could not be more confused. There is exactly what you want (a slim wrapper on around slf4j) included with akka and desribed in the docs (http://doc.akka.io/docs/akka/2.1.0-RC1/scala/logging.html).

Which part of what's there isn't what you want?

Samuel Halliday

unread,
Nov 30, 2012, 1:31:01 PM11/30/12
to akka...@googlegroups.com
What I want to do is to use SLF4J to handle all output (actually, I use java.util.logging, but SLF4J is sufficient) and:

1. the name of the Logger to be the name of the Actor's instance name (e.g. "/user/application/my/actor").

2. the class property of the message to be set to the Actor's class.

3. the thread property of the message to be set to the Thread that produced the log.


That then allows me to implement simple rules to filter the log levels on a per instance, per class and per thread level, in the same logging config file as the rest of my application.

This may well be possible, but after reading all the Akka docs on Logging (and I'm currently reading Derek's book, which might enlighten me) the closest I can come up with is:

1. SLF4J for "most" logs – there are still some messages being logged to stdout.

2. The source class name for all log messages is the Akka SLF4J interface.

3. The Logger's name is set to the name of the Actor's class

4. The Thread name is a number – I cannot confirm if it is the logger's thread number or the original thread that triggered the log message.


If I were to write a "thin layer" – using my definition of 50 lines maximum ;-) – to asynchronously send log messages off to SLF4J/JDK14 then I would still not be able to view and filter the messages that are being sent using the existing Akka system. Most importantly, this includes unhandled messages.



Does that help explain things a little better Alec?


--
Sam

Alec Zorab

unread,
Nov 30, 2012, 1:52:11 PM11/30/12
to akka...@googlegroups.com
In logback.xml

    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%date{ISO8601} %-5level %logger{0} %X{sourceThread} %X{akkaSource} - %msg%n</pattern>
        </encoder>
    </appender>

class ManagingActor extends ActorLogging {

  log.debug("Log Message")

  def receive = {case _ => ()}
}

2012-11-30 18:46:09,685 DEBUG ManagingActor ActorSystem-akka.actor.default-dispatcher-3 akka://ActorSystem/user/Managers/Manager1 - Log Message

So logging thread is called sourceThread, the logging class is logger and the actor path is akkaSource. This is all in docs.

Hope that helps.

√iktor Ҡlang

unread,
Nov 30, 2012, 2:01:11 PM11/30/12
to Akka User List
As I said earlier, we can't have any external deps, it'd be j.u.l.Logger, which is horrible, just look at the "minimalistic" interface: http://docs.oracle.com/javase/6/docs/api/java/util/logging/Logger.html

I still don't understand the problem, just install your own LoggingAdapter.

Cheers,

Samuel Halliday

unread,
Nov 30, 2012, 2:09:09 PM11/30/12
to akka...@googlegroups.com
I'm using the J2SE backend to SLF4J, and this information is not available in the correct fields.

My custom formatter allows me to do something similar to logback's formatter

http://code.google.com/p/zibaldone/source/browse/fommil.zibaldone/src/main/java/uk/me/fommil/logging/CustomFormatter.java

I can assure you that LogRecord.getSourceClassName() is pointing to the Akka SLF4J interface [Slf4jEventHandler$$anonfun$receive$1$$anonfun$applyOrElse$3.apply$mcV$sp]


The default J2SE "Handler" uses class based "level" statements to filter the output. Since everything in Akka is coming from the SLF4J interface class, this means I can't do filtering.


Furthermore, no matter what your backend is – there are still messages being printed directly to stdout by Akka Logging.


I'm seriously considering writing a very thin layer to do my own asynchronous J2SE Logging. I'm hesitant to do this because it means it will only work for my Actors, and not those already defined in Akka.

If I were able to register a callback on the "unhandled" messages, it might be all I need.

--
Sam

√iktor Ҡlang

unread,
Nov 30, 2012, 2:16:26 PM11/30/12
to Akka User List
On Fri, Nov 30, 2012 at 8:09 PM, Samuel Halliday <sam.ha...@gmail.com> wrote:
I'm using the J2SE backend to SLF4J, and this information is not available in the correct fields.

My custom formatter allows me to do something similar to logback's formatter

http://code.google.com/p/zibaldone/source/browse/fommil.zibaldone/src/main/java/uk/me/fommil/logging/CustomFormatter.java

I can assure you that LogRecord.getSourceClassName() is pointing to the Akka SLF4J interface [Slf4jEventHandler$$anonfun$receive$1$$anonfun$applyOrElse$3.apply$mcV$sp]


Which version of Akka?
 

The default J2SE "Handler" uses class based "level" statements to filter the output. Since everything in Akka is coming from the SLF4J interface class, this means I can't do filtering.

Why dont't you add your own EventHandler and use that instead?
 


Furthermore, no matter what your backend is – there are still messages being printed directly to stdout by Akka Logging.


Akka only prints to stdout _before_ logging is available or after it is shut down. Do you have any examples of where this is not the case?
 

I'm seriously considering writing a very thin layer to do my own asynchronous J2SE Logging. I'm hesitant to do this because it means it will only work for my Actors, and not those already defined in Akka.

I still don't understand what the problem is with adding your own EventHandler/LoggerAdapter.
Doesn't that solve your use case?
 

If I were able to register a callback on the "unhandled" messages, it might be all I need.

Tried just overriding unhandled and log the message you want to log?

Cheers,



--

Samuel Halliday

unread,
Nov 30, 2012, 2:23:24 PM11/30/12
to akka...@googlegroups.com
Akka version: 2.1.0-RC3

I may well write my own EventHandler, but I don't see why the SLF4J one isn't doing what it's supposed to. I'll investigate further before implementing anything.

The messages do seem to be after Akka is shutdown. I'd like to log those with SLF4J/J2SE please! :-D

--
Sam

Alec Zorab

unread,
Nov 30, 2012, 2:52:07 PM11/30/12
to akka...@googlegroups.com
Sam - the extra information is inside the mdc. Are you saying that you don't see the relevant information in there?

Samuel Halliday

unread,
Nov 30, 2012, 4:55:37 PM11/30/12
to akka...@googlegroups.com
On 30 Nov 2012, at 19:52, Alec Zorab wrote:
> Sam - the extra information is inside the mdc. Are you saying that you don't see the relevant information in there?

I'm using the J2SE backend of SLF4J, so I don't even see the MDC.


As background for those who do not know the Java Logging API: the core customisable elements of J2SE Logging are the Handler and the Formatter. I find the default Handler to be sufficient for most situations, but the default Formatter is ugly as sin (it manages to be verbose whilst also avoiding giving detail – the perfect politician!).

Both the Handler and the Formatter accept LogRecord instances. Given a published LogRecord, one can read off:

* message
* log level
* name of the logger
* a timestamp
* source method name
* source class name
* Thread ID (not it's name, sadly)

(which is what my Formatter does)


But the Akka Logger is not setting the classname/method correctly and I have no way to check if the Thread ID is correct without further empirical study. It's probably constructing SLF4J's equivalent of the LogRecord in a Future.


Assuming that the classname issue is a bug with Akka – and is fixed shortly – I would like to have the option to specify the name format given to the Logger: I want to use the Actor's name.


I would also like to know if, by using this SLF4J interface, are my logs still asynchronous? (e.g. will log.info("message") return instantly?)


Forgive the digression, but I would have thought that enabling logging in Scala / Akka could have been a simple case of providing traits along the lines of the following (change it for SLF4J if you like...), which could easily be refactored to hide J2SE classes entirely:


/** Makes `java.util.logging` available as a `log` field.
* WARNING: Synchronous. Use ActorLogging for Actors.
*/
trait Logging {
protected lazy val log = Logger.getLogger(getClass.getName)
}


/** Makes a simple logger available as a `log` field,
* backed by J2SE's `Logger` with asynchronous execution.
*/
trait ActorLogging {
val system: ActorSystem
protected val log = new {
// I assume "context.system.name" never changes. Otherwise,
// always grab a new Logger in asyncLog below...
private lazy val log = Logger.getLogger(context.system.name)

private def asyncLog(record: LogRecord) {
import ExecutionContext.Implicits.global
Future { log.log(record) }
}

@elidable(INFO)
def info(message: Any) {
// we could even construct the LogRecord in the Future block,
// but we need to grab the thread ID and calling class / method
// before doing so.
asyncLog(new LogRecord(Level.INFO, message.toString))
}

@elidable(INFO)
def info(message: Any, thrown: Throwable) {
val record = new LogRecord(Level.INFO, message.toString)
record.setThrown(thrown)
asyncLog(record)
}

// ... similar for warn/error/severe/etc
}
}


Could somebody please enlighten me why this isn't suitable?

Is it not a good idea to have the logging independent of the Actor system itself?

--
Sam

History getting too big, follow it at: https://groups.google.com/d/topic/akka-user/S1bwDHbju94/discussion

√iktor Ҡlang

unread,
Nov 30, 2012, 5:09:48 PM11/30/12
to Akka User List
On Fri, Nov 30, 2012 at 10:55 PM, Samuel Halliday <sam.ha...@gmail.com> wrote:
On 30 Nov 2012, at 19:52, Alec Zorab wrote:
> Sam - the extra information is inside the mdc. Are you saying that you don't see the relevant information in there?

I'm using the J2SE backend of SLF4J, so I don't even see the MDC.

… use your own EventHandler/LoggingAdapter and customize it to your needs.
 


As background for those who do not know the Java Logging API: the core customisable elements of J2SE Logging are the Handler and the Formatter. I find the default Handler to be sufficient for most situations, but the default Formatter is ugly as sin (it manages to be verbose whilst also avoiding giving detail – the perfect politician!).

Both the Handler and the Formatter accept LogRecord instances. Given a published LogRecord, one can read off:

 * message
 * log level
 * name of the logger
 * a timestamp
 * source method name
 * source class name
 * Thread ID (not it's name, sadly)

(which is what my Formatter does)


But the Akka Logger is not setting the classname/method correctly and I have no way to check if the Thread ID is correct without further empirical study. It's probably constructing SLF4J's equivalent of the LogRecord in a Future.

Please open a ticket with an attached test as per http://doc.akka.io/docs/akka/2.1.0-RC3/project/issue-tracking.html
 


Assuming that the classname issue is a bug with Akka – and is fixed shortly – I would like to have the option to specify the name format given to the Logger: I want to use the Actor's name.

You can do that already, see Logging.apply
 


I would also like to know if, by using this SLF4J interface, are my logs still asynchronous? (e.g. will log.info("message") return instantly?)

I don't understand what you mean, what is "this" in the above sentence?
You can publish LogEvents to the eventStream and use your own API, and for the "backend" there's the EventHandler.
 

Is it not a good idea to have the logging independent of the Actor system itself?

It is independent, EventHandler + LoggingAdapter. Of course the ActorSystem needs to do logging, so there is a dependency for the ActorSystem to have a logging facility.

Cheers!

 

--
Sam

History getting too big, follow it at: https://groups.google.com/d/topic/akka-user/S1bwDHbju94/discussion
--
>>>>>>>>>>      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.


Alec Zorab

unread,
Nov 30, 2012, 5:12:10 PM11/30/12
to akka...@googlegroups.com
http://www.slf4j.org/api/org/slf4j/MDC.html  - appears to abstract over mdc in general and offers a basic mdc implementation for the java logging api...

Samuel Halliday

unread,
Nov 30, 2012, 5:22:46 PM11/30/12
to akka...@googlegroups.com
Thanks Victor,

I can, of course, write my own handlers and adapters for this – but I would rather not have to resort to such things. I am first trying to solve the problem with existing tools. It pained me greatly to have to write my own J2SE Formatter, and I'll be damned if I have to do it again for Akka.

I will submit an issue with the tracker as you have suggested, regarding the classname. I will try to see if the thread ID is broken within the same test.

Thanks for the heads up on Logging.apply, if we can fix the bug I'm about to submit, then I will probably create my own trait to replace ActorLogging.

--
Sam

√iktor Ҡlang

unread,
Nov 30, 2012, 5:28:37 PM11/30/12
to Akka User List



On Fri, Nov 30, 2012 at 11:22 PM, Samuel Halliday <sam.ha...@gmail.com> wrote:
Thanks Victor,

You're most welcome!
 

I can, of course, write my own handlers and adapters for this – but I would rather not have to resort to such things. I am first trying to solve the problem with existing tools. It pained me greatly to have to write my own J2SE Formatter, and I'll be damned if I have to do it again for Akka.

Well, since you have decided to use a non-default approach it normally entails some customization, right? We do not see the value proposition or performance of j.u.l so we focused on making something performant, asynchronous that was extensible/customizable with a sane default.
 

I will submit an issue with the tracker as you have suggested, regarding the classname. I will try to see if the thread ID is broken within the same test.

Great, thanks
 

Thanks for the heads up on Logging.apply, if we can fix the bug I'm about to submit, then I will probably create my own trait to replace ActorLogging.

Happy hAkking!

Cheers,
 

--
Sam

On 30 Nov 2012, at 22:09, √iktor Ҡlang <viktor...@gmail.com> wrote:

> … use your own EventHandler/LoggingAdapter and customize it to your needs.

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


√iktor Ҡlang

unread,
Nov 30, 2012, 5:32:47 PM11/30/12
to Akka User List
On Fri, Nov 30, 2012 at 11:28 PM, √iktor Ҡlang <viktor...@gmail.com> wrote:



On Fri, Nov 30, 2012 at 11:22 PM, Samuel Halliday <sam.ha...@gmail.com> wrote:
Thanks Victor,

You're most welcome!
 

I can, of course, write my own handlers and adapters for this – but I would rather not have to resort to such things. I am first trying to solve the problem with existing tools. It pained me greatly to have to write my own J2SE Formatter, and I'll be damned if I have to do it again for Akka.

Well, since you have decided to use a non-default approach it normally entails some customization, right? We do not see the value proposition or performance of j.u.l so we focused on making something performant, asynchronous that was extensible/customizable with a sane default.

Correction:

We did not see the value proposition or performance of j.u.l so we focused on making something performant, asynchronous that was extensible/customizable with a sane default.

Samuel Halliday

unread,
Nov 30, 2012, 5:46:57 PM11/30/12
to akka...@googlegroups.com
Victor,

How come you didn't just wrap j.u.l with a really trivial async layer – I'm keen to know why my proposed approach wouldn't work. Is there some subtlety that I'm missing, or is this simply all to just plain avoid both j.u.l and dependencies?

--
Sam

√iktor Ҡlang

unread,
Dec 1, 2012, 7:23:33 AM12/1/12
to Akka User List

Hi Sam,

I believe I have already answered that quedtion in the previous emails.

Cheers,
V

Samuel Halliday

unread,
Dec 1, 2012, 10:30:26 AM12/1/12
to akka...@googlegroups.com
Alec, Victor,

I have gone into the details of SLF4J and concluded that the bug cannot be fixed directly. Akka using SLF4J with j.u.l incorrectly logs the originating source classes, methods and threads.

I'll detail this below, but I think it is safe to say that you should warn developers against using akka-slf4j with a j.u.l backend.

As a workaround, I will contribute an appropriate LoggingAdapter that talks directly to j.u.l. Watch out for a pull request on github – I hope you are willing to accept it. I will try to also write a "clean" trait to abstract away the j.u.l Logger API, just for Victor ;-)


Details...

SLF4J uses a class named JDK14LoggerAdapter to implement logging with j.u.l. This does several things that are universal quirks of placing another logging layer on top of SLF4J, and cannot be fixed:

1. The Thread ID field is set to the thread that is executing inside JDK14LoggerAdapter: the threadName passed by Akka is ignored. If Akka has launched the logging process in a new Thread, then this field will not match the source.

2. JDK14LoggerAdapter.fillCallerData finds the last non-SLF4J FQCN in the calling stack: the Slf4jEventHandler anonymous class. Any Akka info about the sourceClass (or method) is therefore ignored.



--
Sam

√iktor Ҡlang

unread,
Dec 1, 2012, 10:38:07 AM12/1/12
to Akka User List
On Sat, Dec 1, 2012 at 4:30 PM, Samuel Halliday <sam.ha...@gmail.com> wrote:
Alec, Victor,

I have gone into the details of SLF4J and concluded that the bug cannot be fixed directly. Akka using SLF4J with j.u.l incorrectly logs the originating source classes, methods and threads.

I'll detail this below, but I think it is safe to say that you should warn developers against using akka-slf4j with a j.u.l backend.

As a workaround, I will contribute an appropriate LoggingAdapter that talks directly to j.u.l.

But as that won't scale we cannot use it.
 
Watch out for a pull request on github – I hope you are willing to accept it. I will try to also write a "clean" trait to abstract away the j.u.l Logger API, just for Victor ;-)


Details...

SLF4J uses a class named JDK14LoggerAdapter to implement logging with j.u.l. This does several things that are universal quirks of placing another logging layer on top of SLF4J, and cannot be fixed:

1. The Thread ID field is set to the thread that is executing inside JDK14LoggerAdapter: the threadName passed by Akka is ignored. If Akka has launched the logging process in a new Thread, then this field will not match the source.

2. JDK14LoggerAdapter.fillCallerData finds the last non-SLF4J FQCN in the calling stack: the Slf4jEventHandler anonymous class. Any Akka info about the sourceClass (or method) is therefore ignored.

It seems to me like all of the issues above are bugs in the SLF4J->j.u.l bridge, not in Akka.

Cheers,

Samuel Halliday

unread,
Dec 1, 2012, 11:10:37 AM12/1/12
to akka...@googlegroups.com
Victor,

Yes: the bug is in putting another logging layer above SLF4J – it has not been designed to handle this. To fix it would involve a significant rewrite of the SLF4J JDK14 backend.


It's a shame you're not willing to accept the pull request for a lightweight akka-jul package (alternative to akka-slf4j).

I don't see how j.u.l itself can be such a bottleneck – all of its elements can be customised at runtime. If its synchronous nature is the concern, then surely we could just wrap the writing in a Future. If somebody has an intense logging I/O burden, then I'm guessing they will probably want to use a customised logging backend anyway.

--
Sam

Alec Zorab

unread,
Dec 1, 2012, 11:26:45 AM12/1/12
to akka...@googlegroups.com
Sam,

Have you got the code you used to test this and diagnose the bug? I'll have a little play around with it this evening.

Samuel Halliday

unread,
Dec 1, 2012, 11:57:40 AM12/1/12
to akka...@googlegroups.com
Alec,

I was intending to write a unit test, but the amount of runtime configuration made it prohibitive. When I seen the SLF4J source code, the problem was obvious.


You should be able to see the bug if you use akka-slf4j and then add slf4j-jdk14 to your dependencies.

You might want to grab my CustomFormatter from here

https://code.google.com/p/zibaldone/source/browse/fommil.zibaldone/src/main/java/uk/me/fommil/logging/CustomFormatter.java

and set it up with these logging.properties

```
handlers = java.util.logging.ConsoleHandler
.level = CONFIG
java.util.logging.ConsoleHandler.level = FINEST
java.util.logging.ConsoleHandler.formatter = uk.me.fommil.logging.CustomFormatter
uk.me.fommil.logging.CustomFormatter.format = %n: %m %T [%C.%M]
```

(fiddle with the format parameters to output what you want).

Pass "-Djava.util.logging.config.file=logging.properties" to your java binary on startup.


Try the following code:

class Scratch extends Actor {
val log = akka.event.Logging(context.system, self.path.name)
def receive = {
case msg =>
println("println: " + msg + " " + Thread.currentThread().getId)
log.info(msg.toString)
}
}

object JavaLoggingBug extends App {
val system = ActorSystem("MySystem")
val actor = system.actorOf(Props[Scratch], name = "scratch")
actor ! "HELLO WORLD"
}


I get the following output (although obviously the thread numbers can sometimes agree due to OS scheduling)

println: HELLO WORLD 12
scratch(akka://MySystem): HELLO WORLD 11 [Slf4jEventHandler$$anonfun$receive$1$$anonfun$applyOrElse$3.apply$mcV$sp]

The expected output here is

scratch(akka://MySystem): HELLO WORLD 12 Scratch$receive


--
Sam

√iktor Ҡlang

unread,
Dec 1, 2012, 12:59:40 PM12/1/12
to akka...@googlegroups.com


On Dec 1, 2012 5:10 PM, "Samuel Halliday" <sam.ha...@gmail.com> wrote:
>
> Victor,
>
> Yes: the bug is in putting another logging layer above SLF4J – it has not been designed to handle this. To fix it would involve a significant rewrite of the SLF4J JDK14 backend.

It works perfectly fine with logback, so I don't think it's a bug in slf4j. As I've said countless times, you can implement whatever you like with your own LoggingAdapter + EventHandler.

Cheers,
V

Samuel Halliday

unread,
Dec 1, 2012, 1:05:36 PM12/1/12
to akka...@googlegroups.com
Victor,

Yes – a JavaLogger {LoggingAdapter, EventHandler} is exactly what I was intending to send you in a pull request. I'll send it and you can reject it if you want, but that's what I'll be using going forward.

The bug is definitely with the SLF4J backend – I've even tracked it down to their source code. But it would require a significant rewrite to fix (along the lines of what Alec suggested with the MDC) as they assume the thread writing the LogRecord is the thread that has created the log message. I'm not going to touch it.

--
Sam

Samuel Halliday

unread,
Dec 1, 2012, 1:07:13 PM12/1/12
to akka...@googlegroups.com
Actually, Victor, what is the chances of you breaking the Logging trait into two?

I'd quite like to work to a trait (let's call it "Logger") which has all the bits you've implemented in Logging.

--
Sam

Alec Zorab

unread,
Dec 1, 2012, 1:07:31 PM12/1/12
to akka...@googlegroups.com
Seriously, this looks like a two line fix... In your formatter, get the thread and the class from the mdc. It's not a bug in slf4j, nor in jul or logback. Everything is behaving as specced, you're just doing it wrong :p

Samuel Halliday

unread,
Dec 1, 2012, 1:14:46 PM12/1/12
to akka...@googlegroups.com
Alec – there is no MDC in j.u.l. Have a look at JDK14LoggerAdapter (from SLF4J) and you will see that it is not even passed on to j.u.l.

The closest the MDC gets to j.u.l is in the JDK14LoggerAdapter calls to MessageFormatter.format(format, arg) which could insert it into the message.

--
Sam

Alec Zorab

unread,
Dec 1, 2012, 1:28:10 PM12/1/12
to akka...@googlegroups.com
there is an MDC implementation in slf4j. In your logging formatter, try doing

println(org.slf4j.MDC.get("sourceThread")
println(org.slf4j.MDC.get("akkaSource")

and see what it spits out.

Alec Zorab

unread,
Dec 1, 2012, 1:28:29 PM12/1/12
to akka...@googlegroups.com
... add closing parens as appropriate.

Samuel Halliday

unread,
Dec 1, 2012, 1:42:49 PM12/1/12
to akka...@googlegroups.com
Alec,

That is a really nasty workaround. I would almost rather rewrite the SLF4J JDK14 backend.

To access the MDC from my Formatter would mean introducing a needless dependency on SLF4J, and it would only work for Akka.

Also, if your interpretation of the MDC API is correct (static get method), then it is completely unfit for use in multi-threaded environments.

--
Sam

Alec Zorab

unread,
Dec 1, 2012, 1:47:42 PM12/1/12
to akka...@googlegroups.com
It's threadlocal, that's the whole point. Did you actually read the docs for it at all?

You're basically saying that you want jul to magically know it's supposed to not actually refer to the class and thread that's calling to it. You want it to know how to do this without telling it.

This clearly isn't a bug, and I'm not sure how you think this would ever work.


Samuel Halliday

unread,
Dec 1, 2012, 2:03:34 PM12/1/12
to akka...@googlegroups.com
Alec,

I am quite simply saying that a j.u.l LogRecord should have the correct fields available at the point when it is handed to the Formatter.

The only way to fix it properly would be to write an MDC implementation for JDK14 that knows about the Akka fields and assigns them to the LogRecord before passing it off. And even then, I don't believe it has access to the Thread ID (just the name).

The cleaner workaround is the Adapter that I'm about to pull request.

--
Sam

Samuel Halliday

unread,
Dec 1, 2012, 7:05:40 PM12/1/12
to akka...@googlegroups.com
Dear All,

(especially Victor and Alec)

I have implemented JavaLogging and Specs as originally suggested.

I have created a pull request with the justification for why I feel this is a useful addition to the project:

https://github.com/akka/akka/pull/913


Victor, it's now up to you whether you feel this is something that would benefit other users.

Here is a direct link to the implementation and spec

https://github.com/fommil/akka/blob/master/akka-contrib/src/main/scala/akka/contrib/jul/JulEventHandler.scala

https://github.com/fommil/akka/blob/master/akka-contrib/src/test/scala/akka/contrib/jul/JulEventHandlerSpec.scala

--
Sam

√iktor Ҡlang

unread,
Dec 1, 2012, 7:16:15 PM12/1/12
to Akka User List
Hi Samuel!


On Sun, Dec 2, 2012 at 1:05 AM, Samuel Halliday <sam.ha...@gmail.com> wrote:
Dear All,

(especially Victor and Alec)

I have implemented JavaLogging and Specs as originally suggested.

I have created a pull request with the justification for why I feel this is a useful addition to the project:

  https://github.com/akka/akka/pull/913


Victor, it's now up to you whether you feel this is something that would benefit other users.

I'm sure that if there is a consensus amongst the committers that this is useful then it will make it in – most likely as a contrib until it has more than 1 user.

I've commented on the PR but everyone will get a chance to chime in.

Cheers!

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





--

Samuel Halliday

unread,
Dec 1, 2012, 7:23:04 PM12/1/12
to akka...@googlegroups.com
Thanks Victor,

I've already pushed a few changes to address your comments.

You were right about

classOf[JavaLogging].getName + "$class"

... I don't know what I was doing wrong earlier when I tried this. Must have had a bad binary on my build path or something, a clean build and this worked a charm.

--
Sam
Reply all
Reply to author
Forward
0 new messages