Add a logging (/monitor) interface

Patch to this issue. Please review and comment.

I trust you to commit things without having to be revised beforehand.

Don't worry. I revise all changes when doing CVS update. If I am not happy with anything I will change it.

[A comment by Justin Sampson:]

Very nice!

A few thoughts:

Now that SimpleInputStream takes a ClassLoader, readingTransactionLogFile
could take the loader as well as the file (since it had been included in
the System.out message). Same for loggerInitialized in PersistentLogger.

It would also be nice for lastSnapshotRecovered and snapshotTaken to take
the systemVersion.

Besides that, I expect new methods can be added to Monitor in the
future... External implementations can extend either NullMonitor or
SimpleMonitor in order to keep up with changes in the interface. Dynamic
proxies might also come into play, come to think of it.

Just a few comments about the Monitor stuff...

1. Should there be generic monitor.log(int level, Object message) and monitor.log(int level, Object message, Throwable t) methods? It's nice to have the descriptive method names, but what if there were 200 different messages that we'd like to provide through the monitor? That's not very scaleable. Having generic methods would help here. Heck, the more descriptive methods could delegate to the two methods above to do the logging.

2. Should we provide a properties file and load it as a resource bundle to provide different messages in different languages? Besides that, SimpleMonitor contains messages that a theoretical Log4jMonitor would probably want to have. Actually, if we wanted to take the simple route and forget about the resource bundle for a moment, we could look back to what I said in #1 and delegate the actual logging of messages to the two generic monitor.log() methods. That way, an implementation like Log4jMonitor could simply extend SimpleMonitor and only worry about overriding the two monitor.log() methods. Of course, one might want to override the other methods as well simply because one could improve performance by doing...

public void snapshotTaken() {
if (logger.isInfoEnabled()) super.snapshotTaken();
}

This would avoid the string concatenation in super.snapshotTaken() which, based on my other suggestion, would look like this...

public void snapshotTaken() {
this.log(INFO, "Snapshot taken at " + new Date());
}

...and then SimpleMonitor would just do a System.out.println() on the object sent to it in its log(int, Object) method, where the Log4jMonitor would do...

public void log(int level, Object message) {
//Where FQCN = Log4jMonitor.class.getName() + ".";
//possibly do a translation on Prevayler custom levels
//into Log4j Levels before doing below...
logger.log(FQCN, Level.toLevel(level), message, null);
}

3. If there is a single monitor being used throughout the Prevayler, how is logging going to be controlled per class performing logging? Is there a way in Java to do somthing like this.getCallerClass()? In that case, we could get the fully qualified name of the class and use it as the logger name. The logging above would look like...

Logger.getLogger(callerClazz.getName()).log(FQCN, Level.toLevel(level), message, null);

Now that I think about it, this probably wouldn't necessitate the FQCN argument since we create the logger inside the monitor rather than Log4j seeing the monitor as the delegating logger itself as would be the case in a normal Log4j wrapper class. Hmm... It's getting too late think clearly.

Anyway, things to think about.

Jake

Nice work by Carlos so far.

Jake, let's just stick to english for now.

I am taking a look at the design now. Some changes I will make:

• org.prevayler.foundation cannot depend on anything inside org.prevayler.
• The DeepCopier still calls printStackTrace() in it.
• Put the Monitor in the SnapshotManager instead of in PrevaylerImpl.

Most importantly:

• Use one simplified monitor for each case, instead of a large monitor handling all the cases.

Having a simplified monitor being used several time in the factory like this:

PrevaylerFactory.configureLoggingSnapshots(Monitor);
PrevaylerFactory.configureLoggingJournal(Monitor);
PrevaylerFactory.configureLoggingWhatever(Monitor);

instead of a single large monitor will take care of most of the issues Jake brought up above.

Carlos, be sure to run org.prevayler.AllTestSuite before committing.

Some test were still using the old ".transactionLog" extension and broke.

I am still in the middle of refactoring (moving Monitor to foundation) but I committed my changes to CVS because I fixed the broken tests.

I am removing debug notifications, for now.

Hi Klaus, just a few comments...

<quote>
Jake, let's just stick to english for now.
</quote>

You can treat the il8n stuff as an aside. I shouldn't have even mentioned it because it caused you to miss the basic point. The basic point is that we ought to be able to log the same messages in any implementation of a Monitor, whether it be the SimpleMonitor or a Log4jMonitor. The log() methods I mentioned would take care of this since Log4jMonitor would simply extend SimpleMonitor and only have to override the log() methods. Same goes for any other Monitor implementation. Whether the messages are stored directly in SimpleMonitor or properties files is an extraneous detail.

<quote>
Having a simplified monitor being used several time in the factory like this:

PrevaylerFactory.configureLoggingSnapshots(Monitor);
PrevaylerFactory.configureLoggingJournal(Monitor);
PrevaylerFactory.configureLoggingWhatever(Monitor);

instead of a single large monitor will take care of most of the issues Jake brought up above.
</quote>

How, exactly, does this address any of the issues I brought up? As I see it, it does nothing but make dealing with monitors and configuring Prevayler more complex/tedious. Let's say there are 20 different areas in Prevayler that require monitors. You are saying that we are going to have a configureLoggingBlah(Monitor) for each and every one of those 20 different areas? What if I forget to configure some of them? The two I remember to configure will log using the Log4jMonitor and the ones I forget will log to the default SimpleMonitor. That is not the least bit intuitive and logging via two different systems is most certainly not what most users would have in mind.

Besides that, it doesn't address the issue of getting the name of the class which contains the monitor to be used for Logger of the underlying logging implementation, that is unless there is a setLoggerName() method on the interface or something and it is set inside one of those many configureLoggingBlah(Monitor) methods, but I already detailed the problems with that.

Anyhow, maybe I'm missing something, but I don't see the current proposal as a good solution. I guess maybe I'll have to wait until I see the finished product to make more informed judgement.

Thoughts?

Jake

Carlos finds it interesting to have debug notifications such as "Reading journal x" and "Taking snapshot y" for the Monitor.

Is anyone else in favour or against this?

If we add admin info (I think we should not call it "debug info"), we could do something like:

PrevaylerFactory.configureMonitorForErrors(Monitor); (System.err by default)
PrevaylerFactory.configureMonitorForAdminInfo(Monitor); (Null by default)

I wonder: do we really need separate Monitoring strategies for separate things, such as:

PrevaylerFactory.configureMonitorForSnapshots(Monitor);
PrevaylerFactory.configureMonitorForJournal(Monitor);
PrevaylerFactory.configureMonitorForReplication(Monitor);
etc. ?

<quote>
I wonder: do we really need separate Monitoring strategies for separate things, such as:

PrevaylerFactory.configureMonitorForSnapshots(Monitor);
PrevaylerFactory.configureMonitorForJournal(Monitor);
PrevaylerFactory.configureMonitorForReplication(Monitor);
etc. ?
</quote>

Yes, I think so. Keep in mind that I may want to use monitor to send me e-mails, or SNMP messages, and knowing when a snapshot is taken, for instance, is a good thing (this monitor could also inform the backup system to copy those files to a safer place after a snapshot is taken, or something to that effect).

Hmm, I was really looking forward to the explicit method names for each event.

And I can see the desire to have separate monitor classes for different parts of the system, but I'm inclined to start with one and only split it once we've used it a while so it's clearer how it should be split... I'm particularly inclined against splitting based on "admin" vs. "error" etc. as that seems too suggestive of the old "info" vs. "error" vs. "warn" etc. logging levels.

How about this:

• A single Monitor interface with explicit method names (no "log" or "notify" or whatever).

• NullMonitor implementing the interface to do nothing.

• LoggingMonitor implementing the interface to call abstract "info" and "error" methods with appropriate textual messages.

• ConsoleMonitor extending LoggingMonitor using System.out.

• Log4JMonitor extending LoggingMonitor using Log4J.

• ChainingMonitor delegating to each of a list of Monitors in turn.

If you only want to listen to a couple of events, extend NullMonitor and just override those methods. (Though perhaps there's a better name than "NullMonitor" – maybe "MuteMonitor"?)

PrevaylerFactory could have a list of Monitors configured by "addMonitor" and "clearMonitors" methods, with just ConsoleMonitor by default. If no Monitors are configured (i.e., clearMonitors was called without subsequent calls to addMonitor) then a new NullMonitor is passed down; if one Monitor is configured it is passed down by itself; and if multiple Monitors are configured they're put into a ChainingMonitor which is then passed down to the rest of the code.

– Justin

Here's a Log4jMonitor implementation based upon the current state of the Monitor stuff. It's a bit hacky in the way that it obtains the name of calling class to name the logger, but it does it without imposing on the Monitor interface.

I hope this implementation will help point out issues in the current Monitor design (and I'm not necessarily implying there are any).

Jake

Jake, I didn´t understand what you are doing with the stack there in the Log4JMonitor.

OK. Lets try separate monitors for separate components.

"and knowing when a snapshot is taken, for instance, is a good thing (this monitor could also inform the backup system to copy those files to a safer place after a snapshot is taken, or something to that effect)."

A snapshot is taken every time takeSnapshot() returns successfully and it is you who calls it. You don´t need to be notified.

"Hmm, I was really looking forward to the explicit method names for each event."

Why?

"I'm inclined to start with one and only split it once we've used it a while so it's clearer how it should be split..."

A single huge monitor interface is really weird from a dependencies point of view. All components depend on it, because they call it, and it sort of semantically depends on all components because it doesn´t really do anything. It exists only to be called by them.

We can solve this by breaking the "all components depend on it" dependency and still have a single huge monitor interface, but I want to know why you want the explicit method names for each event.

• LoggingMonitor implementing the interface to call abstract "info" and "error" methods with appropriate textual messages."

Yes.

• ConsoleMonitor extending LoggingMonitor using System.out.

Yes.

• Log4JMonitor extending LoggingMonitor using Log4J.

Yes.

• ChainingMonitor delegating to each of a list of Monitors in turn.

Too fancy. Will help 0.1% of users and waste the time of 99.9% of API readers.

• PrevaylerFactory could have a list of Monitors configured by "addMonitor" and "clearMonitors" methods, with just ConsoleMonitor by default. If no Monitors are configured (i.e., clearMonitors was called without subsequent calls to addMonitor) then a new NullMonitor is passed down; if one Monitor is configured it is passed down by itself; and if multiple Monitors are configured they're put into a ChainingMonitor which is then passed down to the rest of the code.

Too fancy as well.

One important consideration:
At the level we are talking about, I oftentimes prefer frameworks that let me do stuff rather than frameworks that try and do stuff for me.

"Jake, I didn´t understand what you are doing with the stack there in the Log4JMonitor."

In Log4j, the most common way to name a logger is by using the fully qualified name of the class using the logger. The stack trace hack obtains the class name of the calling class. Keep in mind that normally, one would specify a logger for a given class such as below...

package com.mycompany.mypackage;

public class MyClass {
private static final Logger logger = Logger.getLogger(MyClass.class.getName());

...
...
...
}

So, now we have a Logger named "com.mycompany.mypackage.MyClass" and can control its logging behavior easily using a config file such as...

<logger name="com.mycompany.mypackage">
<!-- Inherit the appender from root, but log at info instead of warn for any logger inheriting this one -->
<level value="info"/>
</logger>

<root>
<!-- All loggers inherit from this one -->
<level value="warn"/>
<appender-ref ref="FileAppender"/>
</root>

However, in the case of the Log4jMonitor, we can't just define a logger like Logger.getLogger(Log4jMonitor.class.getName()) because now all logging looks like it comes from the Monitor, not the class using the monitor. We want to control the logging of the class using the monitor. The logger() method returns a logger named after the calling class.

Does that make sense now? It is kind of central to the issue I've been trying to get across over the last number of emails and posts here. Hopefully I've made it clear this time.

Jake

"OK. Lets try separate monitors for separate components."

You've said this a few times but haven't actually mentioned why you think this will be of any benefit. What is the benefit? It doesn't solve the issue of naming loggers based on the calling class. That is, unless you create not just separate instances of monitors but physically separate classes of each monitor. So, if you have 5 components, you will have 5 Log4j implementations; one for each component. That way you could name the logger for the component. Of course, by component, you mean "set of related classes", so loggers would be named very generally for the component as a whole. As such, logging specified down to the class name would not be possible here.

Now, if you say, but I don't mean physically separate classes but just separate instances. Well, then we'll have to have a method that allows one to name the logger. If you don't like that, then we're right back to my logger() method with no real added benefit to having separate monitors for separate components for reasons I've stated in previous posts.

Let's not make monitors tedious to configure. They should be mostly an afterthought. A one time thing. One shoudn't have to remember to configure a monitor for each component in Prevayler to get the logging output the way they desire.

Jake

Wow, this is just going on and on.

My current project needs: (a) to suppress messages to
System.out while running most tests; and (b) to send
messages to Log4J in production and some tests. Any
approach discussed here would accomplish that.

Klaus wrote:

> "Hmm, I was really looking forward to the explicit method
> names for each event."
>
> Why?

The first concrete example that comes to mind is in
testing: I'd like to mock the Monitor interface and make
assertions about what's happening.

With explicitly named methods, I can assert that
readingTransactionJournal() was called with a parameter of
type File equal to "basedir/00000001.whatever" and
transaction number 1.

With generic "notify" or "log" or "info" or "error"
methods, I have to assert that notify() was called with
message "Reading transaction journal 000001..."

If I want to assert two events, I'd rather assert that each
of readingTransactionJoural() and
ignoringStreamCorruption() were called exactly once, rather
than that notify() was called twice with two different
messages.

Of course either way works, and in fact we do the latter
for testing our Log4J logging. I just got excited by the
idea of pushing the textual messages out a level.

> "I'm inclined to start with one and only split it once
> we've used it a while so it's clearer how it should be
> split..."
>
> A single huge monitor interface is really weird from a
> dependencies point of view. All components depend on it,
> because they call it, and it sort of semantically depends
> on all components because it doesn't really do anything.
> It exists only to be called by them.

How many events are we talking about? It would not be
"huge", I think. The original patch attached to this issue
had seven, some of which could be removed.

> * ChainingMonitor delegating to each of a list of
> Monitors in turn.
>
> Too fancy. Will help 0.1% of users and waste the time of
> 99.9% of API readers.

Agreed; my point was only that things like multiple
monitors can be easily achieved (if anyone so desires) with
a single interface.

– Justin

Jake wrote:

> However, in the case of the Log4jMonitor, we can't just
> define a logger like
> Logger.getLogger(Log4jMonitor.class.getName()) because
> now all logging looks like it comes from the Monitor, not
> the class using the monitor. We want to control the
> logging of the class using the monitor. The logger()
> method returns a logger named after the calling class.

If such a thing is really needed, why not just add the
Class as the first parameter to each notify method?

– Justin

Hi Justin,

I guess I can kind of understand how explicit methods would make unit testing the Monitor interface easier, but it seems a misuse of the interface. Any time we figure out that we want new messages to log, we'd be adding to the interface and vice-versa for removing methods that we, in retrospect, decide that we don't need. Leaving the interface more generic and letting other classes decide what messages they want to log is the most flexible and we can can count on the Monitor interface not changing on the whims of developers logging needs. And for people extending Prevayler and using the Monitor interface for their own code, or simply creating their own Monitor implementations, having a stable interface is important.

On the other hand, putting the methods in the interface does allow us to do stuff like logger.isInfoEnabled() before doing concatenation of strings to avoid the cost when that logging level isn't currently enabled for the named logger. Actually, the NullMonitor would avoid all costs of string concatenation if the explicit methods were added to the interface It's a tough choice.

"If such a thing is really needed, why not just add the
Class as the first parameter to each notify method?"

I'm all for it. In fact, this is partially why I created the Log4jMonitor; to highlight any possible issues with the current design. The way Log4jMonitor is designed currently, it doesn't impose any concepts of the underlying logging implementation such as logger naming or levels. On the other hand, the private loggger() method could be a performance issue. If adding the Class parameter to each notify() method is acceptable to everyone, then the performance issue with the logger() method is pretty much solved. It also makes the configuration of separate Monitors for each component even more unnecessary than they were before.

Jake

I will be travelling in the next couple of days but give me some time after that and I will try an implementation.

I think there is a design that solves all the issues we agree on:

• Explicit methods
• Generic logger interface
• Named Loggers
  etc.

None of them are conflicting, so it is just a matter of doing it.

"OK. Lets try separate monitors for separate components."

"You've said this a few times"

I haven´t. Carlos was the one who convinced me.

"but haven't actually mentioned why you think this will be of any benefit. What is the benefit?"

Well, we can do different things with different events. That doesn't mean we can't also channel all events, by default, to a common logger interface (that can have an implementation creating named Log4JLoggers, for example).

See you, Klaus.

"I'd like to mock the Monitor interface and make assertions about what's happening."

I don't like white-box testing. It sort of violates encapsulation. I should be able to change the order in which I read the journal files, for optimization, for example, and the tests should not give me grief about it.

I have seen major XP Gurus do it - under the excuse of writing finer grained tests - and I didn't like what I saw.

Here's a little refactor of the Monitor stuff taking into account Justin's comments here:
http://jira.codehaus.org/browse/PRV-23#action_19862

I've added the abstract LoggingMonitor which the other implementations (other than the NullMonitor) extend. I've modified all methods to take a Class as the first parameter so we can obtain the logger name being to be used (and modified PersistentJournal and SimpleInputStream to account for this change). I also modified SimpleInputStream to log to the info level and modified the MainXStream class to use the Log4jMonitor so I could quickly test the Log4jMonitor implementation.

To test this out, grab a fresh copy of CVS, extract the zip file over the root module ("prevayler"), and everything should be put into place. It includes a log4j.xml configured to log to the info level for org.prevayler. Use the Ant build to run the XStream bank demo such as...

ant run.demo.bank.xstream

Now look in prevayler/target/logs/main.log to see the logging and prove it is working.

Note that I left the notify() methods there. I don't care if we use notify() or go with explicit methods. I just wanted to get this out there for comment.

Jake

This is implemented. However, we may want to think about dumping the monitors in favor of using the SLF4J interfaces when they get released as 1.0. It would be much more flexible and would only be a few K dependency for the NOP version. Users can drop other statically bound logging implementations of SLF4J as needed into their classpath.

Jake