Log.debug, Log.Info, Log.warn....

[Gregg Bolinger]

I think I am on an anti-conformity kick or something lately. So feel free to take this with a grain of salt. Also, this isn't about a logging API specifically. Just the concept of logging in general.

I was talking to a fellow developer about some problems he was having with his code. So we kicked off Eclipse's debugger and got to, well, debugging. Found the problem. All is well with the world. So we continued talking about how cool debugging is in IDE's these days. And that eventually led into us questioning the purpose of logging API's. This is what we came up with.

DEBUG - This level is worthless. With local and remote application debugging capabilities this is just extra code that serves no purpose. What I see way too much of are folks using DEBUG level statements when they should just put a comment there.

INFO - This is really only good for things like when the client wants to track activity. So info messages like "DATETIME: User foofoo logged in". I see way too much INFO level debug in API's that have nothing to do with activity tracking. If I care that much about what an API is doing I'll turn on my debugger and step through things.

WARN - We were a bit torn on this one. While we can see a few cases where this might be helpful it doesn't come up very often. The only real use case I can think of right now is warnning message for client activity tracking. But again, not really useful for general application development messages.

ERROR - The only really useful logging message. If the app breaks down and/or there is a serious error/problem, having a log of this error is a good idea. No brainer.

I'm sure most people will disagree with me but it makes for good conversation.

[Jesper de Jong]

In the project that I am currently working on, we use the DEBUG level to be able to trace what the software does. The logging level is on DEBUG only on the development and test systems. We have an unwritten rule that every public method should start with a debug log statement (logging the name of the method and possibly the arguments), so that if something goes wrong, we can track down in the logfiles where and how things went wrong. In production, the debug log level is on INFO. We use Log4J and we wrap debug logging statements in an "if (log.isDebugEnabled()) { ... }", so that if the level is higher than debug, it doesn't cost a lot of performance.

What you describe under the INFO level, sounds like audit trail logging to me. Audit trail logging is something entirely different than debug logging. It's both logging, but for very different purposes. For this kind of logging, we do not use Log4J in our project; instead, we log such events in a database table. (I know you can also use Log4J to store log messages in a database, but that's not how we're using it). We (almost) don't use the INFO level in Log4J. In fact, I'd say that the INFO level is the most useless level.

We use WARN for logging non-fatal, recoverable errors. For example, when a database connection is not available - the application can retry the same operation later.

We use ERROR for fatal, non-recoverable errors, which require the attention of an administrator.

[Stan James]

FWIW:

I've been using DEBUG extensively lately just to confirm the path through the code is what I expect. Stepping through with debug is deathly slow. Some of the framework is not "under test" and does some surprising things now & then.

I'd expect INFO to be usage metrics or business metrics and such, which really ought to be someplace else.

I put WARN on a few exceptions that are not expected but are recoverable. This might be nice in a situation where ERROR goes to help desk or problem escalation but WARN is just interesting to the developers.

[Gregg Bolinger]

we can track down in the logfiles where and how things went wrong.

Or you can take the information provided about the issue and run through a debugger. Seems easier than scanning log files. I have a ton more comments but just don't have time right now. But later...

[Paul Clapham]

DEBUG: no, I don't use it either. If you have it everywhere then turning it on just produces an unusable mass of output. If I need to debug something I will put in temporary debugging statements (at INFO level) that I take out when the problem is fixed.

I haven't found ERROR to be very useful, either. You may find that surprising. But we do a lot of dumping files on FTP sites and grabbing files from FTP sites. I used to have ERROR logs e-mailed, but when over 90% of the ERROR situations are network issues that go away after some retries, pretty soon people stop reading those e-mails.

What is the most useful is actually the INFO messages. When one of these file-grabbing tasks runs, we log the fact that it started and the fact that it stopped. And also the fact that it grabbed a file, if it did. If one of those tasks hangs up then bad things happen (or rather, good things don't happen) and mad elephants start rampaging through our hallways. So we have a monitoring system that reads the log messages and reports to people if they don't appear regularly.

Oh, and we now write our logs to a database, which simplifies the monitoring process and allows us to analyze log information in various other ways. It's a lot more convenient than parsing a collection of text files.

[Jim Yingst]

I used to use DEBUG a lot, but not much now. However I do think there can be times when it's useful. E.g. for getting info on intermittent problems that can't be easily or reliably recreated on demand, like threading issues. Or problems that only show up in one particular environment, and it's an environment that I personally don't have access to. Or when a program block or errors without a stack trace (because some schmuck has failed to log the stack trace correctly), and I can't easily determine where in the program the problem occurred. In these circumstances I can at least lower the logging level to DEBUG (or have the appropriate sysadmin do it) so that we can get more info if and when the next bug occurs. If nothing else, I can learn more about what was going on shortly before the error occurred.

INFO: I generally don't use it much, but it's of some value. I usually think of it as the type of info that a user might reasonably expect to see displayed on the command line if they run your program. Just a high-level summary of what's going on. Never so much info that it's moving too fast to read.

WARN: I use this seldom, but occasionally. Usually WARN is for something that I need to study more, and eventually I'll either change this to an ERROR, or decide to ignore entirely (becuase I've determined that the situation is not a problem).

ERROR: Yes, this is by far the most useful log level in most of my code. I just don't think it's the only one.

[Stan James]

I always make sure I can change all these flags in a running system without changing config files and restarting. In one previous systems, we could turn logging on and off at package, classes and method levels for fine grained analysis. I added the "running system" bit to a vendor framework for that one. We worked long and hard to remove a ton of junk logging with a goal of a perfectly quiet log in the absence of errors. Never quite got there.

[Jesper de Jong]

Originally posted by Gregg Bolinger:
we can track down in the logfiles where and how things went wrong.

Or you can take the information provided about the issue and run through a debugger. Seems easier than scanning log files. I have a ton more comments but just don't have time right now. But later...

That's not always an option. The software we're developing is running on big servers, and sometimes something goes wrong in the test environment and things are not easily reproducible on the development environment, and then it's good to be able to track down what happened exactly in the test environment.