Logging stops if invalid xml configuration is loaded by scanner

I've found several problems in the code that relate to this and make it harder to patch.

1. status is printed from the Interpreter
Interpreter#callEndAction line 315
This means that errors are not printed in case the xml is invalid (SaxParseException), so the call to addError in ReconfigureOnChangeFilter line 163 is moot in that case

2. ReconfigureOnChangeFilter calls reset before doConfigure
This means that if doConfigure fails on invalid xml the old configuration is already reset. If I move reset to after doConfigure it won't work either obviously. I think there is a design problem here.

I've forked logback on github and I'll send a merge request for the test code I wrote.

I have mentioned this before. Even if there is nothing wrong with the new configuration there is still a timeframe where there is no logging configuration in effect and all logging is disabled. There is currently no good way to fix this in Logback due to how Loggers and the configuration are co-mingled. This is something I have fixed in my experimental implementation of Log4J 2.0 at Apache.

Wow, that's pretty amazing. How did you manage to roolback to a given configuration without loosing the ability to log in the mean time?

The key is that I don't have to roll back. Unlike Log4j 1.x and Logback the configuration is separate from the loggers created by getLogger(). This allows reconfiguration to be more or less atomic. If there is something wrong with the new configuration then nothing gets changed. Once the new configuration is constructed then loggers are reset to point to the new configuration instead of the old one. Thus no logger is ever in a state where it is "unconfigured", although there will be a point in time where some loggers point to the old configuration and some to the new one.

Of course, you are welcome to go look at the code. While the core of the system functions it is far from complete.

Ralph,
that sounds pretty awesome!

Are there any other downsides/shortcomings compared to the Logback way beside the (IMHO very acceptable) one while switching configuration?
It sounds like the actual switching would be very fast. (Optionally) locking the whole system during a switch to prevent that issue might be feasible in that case.

The biggest consequence is that there is one extra level of indirection between the logger and the log level and filters. I tried every way I could think of to squeeze that and was surprised at how fickle the JVM appears to be. What I ended up with is extremely close to Logback's performance when calling isDebugEnabled a million times when the result is false.

The second impact is what happens when you programmatically try to add a filter or appender to a logger. This is handled differently than processing a new configuration. In this case each change is done using thread-safe mechanisms since each change is done one at a time. I'm not going to go into the details, but this can get complicated. However, like SLF4J, the public API doesn't contain methods to do any of those operations.

The ideal solution is pretty clear to me: load the configuration first, then swap the contexts only if the loading was successful. Even if this doesn't happen entirely thread-safe, it would fix this issue. The relevant question is how to modify logback code to get close enough to this situation to fix this bug. After trying for an hour or so last week I can say it will be trickier than I hoped, but that's normal.

I came up with some strategies that are not very invasive and open the door to a larger refactoring that attacks the design problem I mentioned.

1. run the JoranConfigurator against a throwaway context first and only reset after that worked

2. wrap the context in a delegator that can swap the internal context instead of modifying it

I haven't tried these strategies yet, but I think they can be made to fix the problem and the second one could be made threadsafe and atomic. Thoughts?

There might be undesirable side effects even when running joran on a temporary context. For example, a RollingFileAppender might open/close an existing file as a result of running a config file.

Another strategy is to memorize a safe configuration script (as a DOM tree) and fallback to it if the current configuration file turns out to be bogus. However, correctly determining that a configuration file is bogus or alternatively safe can be rather difficult.

Note that any retained strategy must work correctly in presence of inclusions, i.e. the <include> directive.

One way to handle the issue with the files is to abstract out the file handling from the Appender. As appenders are created and destroyed the underlying FileManager remains intact with the stream, connection, etc associated with it.

This issue is now fixed. See http://github.com/ceki/logback/commit/690ac09e30d01

Joran will remember well-formed configuration files. In case an XML/SAX parsing error occurs (in the new configuration file), Joran will fall back to previous configuration file. This should work even in case of included configuration files.