You can clone with
I am passing a custom -Djava.util.logging.config.file=logging.properties to my forked tests and I'm confident that my log formatter is being overridden by SBT. e.g. I see logs like the following:
INFO: resetting mongo [java.lang.Thread.getStackTrace 2013-03-07 18:58:45 +0000]
whereas I'm using a very specific formatter which - although can be configured to output logs in this format - should be producing logs according to my own preference.
The log format is also completely different to the default Java logging formatter, so something is highjacking the logging settings.
Note, I am using
outputStrategy := Some(StdoutOutput),
fork := true,
sbt doesn't do anything with Java loggers. Please use the mailing list for support.
@harrah hmm, well something in SBT is definitely changing the logging output. I suppose I'll have to investigate it further.
I've already asked on the mailing list and you said the same thing, IIRC.
@harrah I've created a small project to demonstrate that this is a real issue.
Ok, so the equivalent command line to what sbt runs isn't java ... but scala ... Indeed, when running your project with the scala command, the behavior is the same as in sbt. If you put this line in Sbt702:
you see that Scala sets up the boot classpath with a bunch of jars that aren't specified to be on the classpath. Perhaps one of the jars put on the boot classpath overrides logging somehow, but because I'm not familiar with how the logging configuration works, I would appreciate it if you could figure out why this affects things. Then, I'll follow up with the Scala project if appropriate.
or maybe scala is dropping the properties passed to it.
It is straightforward to verify that the property is being set with println(System.getProperty("java.util.logging.config.file")). The getInputArguments shows you exactly the classpath to java is, so you can run java directly yourself without going through scala. So, the only difference I see between running through scala and running through java are those jars on the boot classpath. What I was asking from you was whether you could see why those jars would affect anything. You don't need to run through scala, just use the command line printed from getInputArguments. If you can't see anything, I will look at it, but I am not familiar with the details of the logging configuration being used. The smaller a reproduction you can make, the easier it is for me to help.
@harrah I replied to the mailing list, but I'll reply here also for reference.
Indeed, printing the property shows that it has been set.
BUT, logging setup and properties is non-trivial: the "java.util.logging.config.file" property is magical. The JVM tries to load the logging configuration really early during startup, which means that it must be given to the runtime binary. Maybe something is happening that disrupts this startup procedure, or maybe the scala binary is attempting to set the properties AFTER the JVM has started.
(I guess the reason for this magic is because one may wish to log some information before the whole classpath is loaded. Anyway, there is certainly a lot of funkiness going on inside the JUL that always looked superfluous to me, but maybe it's there for a reason.)
FYI, this is the output from the getInputArguments
[info] [-Xmx2G, -Djava.util.logging.config.file=logging.properties, -Xbootclasspath/a:/Users/samuel/.sbt/boot/scala-2.10.1/lib/scala-library.jar:/Users/samuel/.sbt/boot/scala-2.10.1/lib/scala-compiler.jar:/Users/samuel/.sbt/boot/scala-2.10.1/lib/jansi.jar:/Users/samuel/.sbt/boot/scala-2.10.1/lib/jline.jar:/Users/samuel/.sbt/boot/scala-2.10.1/lib/scala-reflect.jar]
I don't know enough about Xbootclasspaths to say anything, but nothing looks particularly suspicious here.
replied on the mailing list- either here or there is fine, but let's pick one ;)
@harrah here! :-)
It gets weirder... when I change my java binary to use Xbootclasspath instead of adding scala-library to the classpath, it seems to work fine
java -Djava.util.logging.config.file=logging.properties -cp target/scala-2.10/classes:$HOME/.ivy2/cache/com.github.fommil/java-logging/jars/java-logging-1.0.jar:$HOME/.ivy2/cache/com.typesafe.akka/akka-contrib_2.10/jars/akka-contrib_2.10-2.1.2.jar:$HOME/.ivy2/cache/com.typesafe.akka/akka-actor_2.10/jars/akka-actor_2.10-2.1.2.jar -Xbootclasspath/a:/Users/samuel/.sbt/boot/scala-2.10.1/lib/scala-library.jar:/Users/samuel/.sbt/boot/scala-2.10.1/lib/scala-compiler.jar:/Users/samuel/.sbt/boot/scala-2.10.1/lib/jansi.jar:/Users/samuel/.sbt/boot/scala-2.10.1/lib/jline.jar:/Users/samuel/.sbt/boot/scala-2.10.1/lib/scala-reflect.jar com.github.fommil.Sbt702
so I guess we can eliminate the classpath/xbootclasspath from the cause...
Yeah, I guess it isn't boot classpath related then. How about class loaders? What are the class loader requirements for that custom logger? The Scala runner needs to create a new class loader containing the classpath you provide it whereas the classpath for java gets put in the application class loader. I wouldn't be surprised if logging requires any custom loggers to be in the application class loader. Otherwise I'm not sure how it would find the class.
The custom logger is really trivial... you can check it out here
But if there are custom class loaders being used by the scala binary, maybe the logging configuration is not kicking in when expected.
hmm, but maybe my custom log formatter needs to be on the xbootclasspath when started by the scala binary...
(I have no idea how to do that)
The actual custom logger code isn't important. What is important is how java.util.logging finds that code. If you are implementing java.util.logging and a configuration file specifies a class name, what class loader would load that class from?
It might try to be too smart like ObjectInputStream, but I'd guess it tries the application class loader. This class loader can access everything on the classpaths directly passed to java. However, the classpath passed to Scala is not in this loader- it is in a child class loader that Scala creates. So, how would java.util.logging find that class loader? I'm guessing it doesn't and that's why you see this problem.
The best confirmation I found on this is actually from API docs from a logging wrapper by @bmc. His advice is in this situation is: use something better like Log4j (or presumably its successor Logback).
Going forward, I'll reopen this bug to have sbt's forked run not go through Scala's runner.
awesome, thanks @harrah !
(and don't forget to do the same for forked tests)
I'm pretty sure forked tests already do not use the Scala runner. If they didn't in 0.12, they do in 0.13.
The sad thing is that LogManager ignores the failed loadClass. Wouldn't it be great if there were a core logging facility so you could always log errors?
If you love JUL because it's always there for you, you don't have to rely on the built-in config mechanism.
@som-snytt I'm not sure what you mean here --- we're still seeing the logs using the default formatter in this issue. Nothing is being lost in that sense (although, it does mean that logs are essentially corrupted, and if I wanted to direct them to, e.g. MongoDB, then I would get log loss).
I just meant LogManager should log its own failures instead making you guess about the point of failure. It catches and ignores the exception.
@harrah @som-snytt made an interesting comment on scala-user: "The problem is that the custom Formatter isn't seen by the system class loader; from the command line, adding cwd with scala -toolcp is a work around for that"
Does that help with the workaround, or would it mean doing some extra with my customer formatter?
It is indeed a useful workaround for the command line, but I doubt it would work here. -toolcp has to be interpreted by the script before it starts the jvm. So, it is only handled by the scala script and not the actual runner that sbt invokes. As far as the changes to sbt to deal with this, it is one line (besides the tests) and already done, I just have to push it.
Fork run directly with 'java' to avoid additional class loader from '…
…scala' command. Fixes #702.