Take the 2-minute tour ×
Programmers Stack Exchange is a question and answer site for professional programmers interested in conceptual questions about software development. It's 100% free, no registration required.

I recently had to investigate a field issue for our large enterprise application. I was horrified by the logs that I had to comb through in an attempt to find the problem and at the end of the day the logs did not help at all identifying/isolating the bug.

Note: I understand not all bugs are discoverable through logs. This does not change the fact that the logs are horrible.

There are some obvious problems with our logging that we can already attempt to fix. I do not want to list those here and I cannot simply show you our log files so you can give advice on what to do.

Instead, in order to assess how bad we are doing on the logging front, I would like to know:

  1. What are some guidelines, if any, when it comes to logging for an application, especially large application.
  2. Are there any patterns we should follow or anti-patterns we should be aware of?
  3. Is this an important thing to fix or can it even be fixed or all log files are simply huge and you need supplemental scripts to analyze them?

Side note: we use log4j.

share|improve this question
add comment

closed as too broad by gnat, GlenH7, Bart van Ingen Schenau, MichaelT, ChrisF Dec 7 '13 at 13:46

There are either too many possible answers, or good answers would be too long for this format. Please add details to narrow the answer set or to isolate an issue that can be answered in a few paragraphs.If this question can be reworded to fit the rules in the help center, please edit the question.

9 Answers

up vote 35 down vote accepted

A few points that my practice proved useful:

  • Keep all logging code in your production code. Have an ability to enable more/less detailed logging in production, preferably per subsystem and without restarting your program.

  • Make logs easy to parse by grep and by eye. Stick to several common fields at the beginning of each line. Identify time, severity, and subsystem in every line. Clearly formulate the message. Make every log message easy to map to its source code line.

  • If an error happens, try to collect and log as much information as possible. It may take long but it's OK because normal processing has failed anyway. Not having to wait when the same condition happens in production with a debugger attached is priceless.

Logs are mostly needed for monitoring and troubleshooting. Put yourself in a troubleshooter's shoes and think what kind of logs you'd like to have when something wrong is happening or has happened in the dead of night.

share|improve this answer
8  
I like this answer but I would add that it's important to log what choice was made at decision points. I've seen many systems where a lot of junk was logged but key decisions were not loggged. So 95% of the logging is basically useless. Also for request/response type systems it's more important to be able to log per request than by subsystem. –  Kevin Oct 5 '11 at 0:20
2  
+1. I like your point about putting yourself in a troubleshooter's shoes. It sounds like log statements should contain a lot more quality messages then what we have been doing... –  c_maker Oct 5 '11 at 0:45
1  
It's important to note that error logging should be logged to the appropiate eventlog as well as application logs. –  Steve Evers Oct 5 '11 at 19:55
2  
@SnOrfus: There are multiple ways to store logs, but the essence is that log messages need to be available up to the very last second the system crashed - like an aircraft black box. If you use any kind of buffering, provide an option to bypass it / flush every message. –  rwong Oct 6 '11 at 4:06
1  
@Rig: on the other hand, many home-grown loggers did not implement any buffering (and dutifully flush every message), leading to very poor performance. This is why it must be made optional. –  rwong Dec 5 '13 at 21:53
show 5 more comments

My favorite public resource for logging guidelines are Apache JCL Best Practices.

Best practices for JCL are presented in two categories: General and Enterprise. The general principles are fairly clear. Enterprise practices are a bit more involved and it is not always as clear as to why they are important.

Enterprise best-practice principles apply to middleware components and tooling that is expected to execute in an "Enterprise" level environment. These issues relate to Logging as Internationalization, and fault detection. Enterprise requires more effort and planning, but are strongly encouraged (if not required) in production level systems. Different corporate enterprises/environments have different requirements, so being flexible always helps...

Despite targeting JCL, these seem to be generic enough to be adopted for logging in general.

  • My personal "guidelines" for logging is that at debug level, I try to make my logs read like a story - with understandable logic and sufficient (but not overloaded) details.

Most famous anti-pattern is probably "swallowing exceptions" - just search the web for it.

As for huge logging files, in my practice this was mostly the normal case. And yes, supplemental scripts as you call them and/or tools like Chainsaw also look normal to me.

  • Above doesn't mean though that you must always blindly put all the logs in one huge file. Sometimes it could be useful to write / copy some of the logs to separate files. Eg in my recent project QA guys asked for dedicated files for metrics and timing data and for brief reports on system operations. They said they will benefit from that and dev did it (benefit from brief reports file turned out indeed significant).

PS. Regarding anti-patterns, others that come to mind are "flooding" and senseless messages.

  • I call it flooding when I see multiple similar messages coming from a loop with many iterations. To me, flooding is annoying enough to try to get rid of it when I detect it in source code. Usually improving it requires some art - because, well, things that happen within the loop may be interesting. When I don't have time to improve it deeper, I try to at least change logging level of such messages to lowest one to make it easier to filter out.

  • Senseless messages seem to be pretty popular garbage. These look harmless when read in source code - I guess one has to go through the pain of analyzing debug output looking like...

    step #1
    step #2
    step #3
    

    ...to deeply appreciate their inherent ugliness. My favorite heuristics to detect this kind of problems at source code level (proposed by colleague in one of my past projects) is to calculate number of space symbol occurrences in string literals used in logging. In my experience, zero spaces basically guarantees the logging statement is senseless, one space is also a good indicator of the potential issue.

share|improve this answer
3  
To avoid flooding I usually gather the heuristics of the loop and output it after the loop. Meaning anything interesting happening in the loop should be stored in a variable (like somethingSpecialHappenedCount) and then output to the logger. –  Spoike Oct 5 '11 at 8:27
    
@Spoike good point! storing in a variable is indeed one of my personal favorite tricks to fight flooding –  gnat Oct 5 '11 at 8:57
1  
I do output all the different counters to the logger as an ASCII-table in the log after the loop ends so that they can easily compared. The table idea was inspired by the one that Spring's StopWatch.prettyPrint() generate. Other than that, making the log text readable and relevant is still an "art" as mentioned earlier in the answer. –  Spoike Oct 5 '11 at 10:10
    
@Spoike: (and @gnat) This is interesting. So basically you add actual code to business logic just for the purpose of logging? I have never heard of this or done this before and not sure how I would justify it to my coworkers. I am afraid that if we start doing this, some of our developers will clutter the source code to such a degree that the business logic becomes convoluted and hard to read. Just simply logging a statement is already making the source look uglier. –  c_maker Oct 5 '11 at 11:04
2  
@c_maker your point about mixing logging with business logic looks worth a dedicated question. Personally I don't yet have strong opinion about these matters. In theory can imagine some separation improvements using AOP and iirc there are even practical applications for this approach. In practice, however, I stick with "mixed" approach and so far I had no major problems with it. Cluttering source code is real danger but, again, so far I was able to make it coexist with logging code quite er "peacefully". This of course requires certain effort. –  gnat Oct 5 '11 at 12:49
show 4 more comments

I work with safety critical real-time systems and logging is often the only way to catch rare bugs that turn up once a blue moon on every 53rd tuesday when it's a full moon, if you catch my drift. This kind of makes you obsessive about the subject, so I'll apologise now if I start to froth at the mouth. The following was written for native code debug logs, but most of it is applicable to the managed world too...

Use text log files. Seems obvious, but some people do try to generate binary log files: that's just dumb because I don't need to be looking for a reader tool when I'm out in the field. Plus if it's text and the debug is verbose there's a good chance the field engineer can read the file and diagnose the problem without ever coming back to me. Everybody wins.

I design systems which are capable of logging pretty much everything, but I don't turn everything on by default. The debug information is sent to a hidden debug dialog which timestamps it and outputs it to a listbox (limited to around 500 lines before deletion), and the dialog allows me to stop it, save it to a log file automatically, or divert it to an attached debugger. That diversion allows me to see the debug output from multiple applications all neatly serialized, which can be a life saver sometimes. I used to use numeric logging levels (the higher you set the level, the more you capture):

off
errors only
basic
detailed
everything

but this is too inflexible - as you work your way towards a bug it's much more efficient to be able to focus logging in on exactly what you need without having to wade through tons of detritus, and it may be one particular kind of transaction or operation that causes the error. If that requires you to turn everything on, you're just making your own job harder. You need something finer-grained.

So now I'm in the process of switching to logging based on a flag system. Everything that gets logged has a flag detailing what kind of operation it is, and there's a set of checkboxes allowing me to define what gets logged. Typically that list looks like this:

#define DEBUG_ERROR          1
#define DEBUG_BASIC          2
#define DEBUG_DETAIL         4
#define DEBUG_MSG_BASIC      8
#define DEBUG_MSG_POLL       16
#define DEBUG_MSG_STATUS     32
#define DEBUG_METRICS        64
#define DEBUG_EXCEPTION      128
#define DEBUG_STATE_CHANGE   256
#define DEBUG_DB_READ        512
#define DEBUG_DB_WRITE       1024
#define DEBUG_SQL_TEXT       2048
#define DEBUG_MSG_CONTENTS   4096

This logging system ships with the release build, turned on and saving to file by default. It's too late to find out you should have been logging AFTER the bug has occurred, if that bug only occurs once every six months on average and you have no way of reproducing it. Logging that only works with debug builds is just. plain. dumb.

The software typically ships with ERROR, BASIC, STATE_CHANGE and EXCEPTION turned on, but this can be changed in the field via the debug dialog (or a registry/ini/cfg setting, where these things get saved).

Oh and one thing - my debug system generates one file per day. Your requirements may be different. But make sure your debug code starts every file with the date, version of the code you're running, and if possible some marker for the customer ID, location of the system or whatever. You can get a mish-mash of log files coming in from the field, and you need some record of what came from where and what version of the system they were running that's actually in the data itself, and you can't trust the customer/field engineer to tell you what version they've got - they may just tell you what version they THINK they've got. Worse, they may report the exe version that's on the disk, but the old version is still running because they forgot to reboot after replacing. Have your code tell you itself.

Lastly, you don't want your code to generate its own problems, so put in a timer function to purge the log files after so many days or weeks (just check the difference between time now and time of file creation). This is OK for a server app that runs all the time, on a client side app you can get by with purging any old data when you start up. We typically purge after 30 days or so, on a system without frequent engineer visits you might want to leave it longer. Obviously this is dependent upon the size of your log files as well.

share|improve this answer
    
+1 In general excellent answer, but especially for putting application id and version info in the log file, unfortunately this is missed so very often. –  Binary Worrier Dec 5 '13 at 13:30
add comment

Log the exception only once!

One of the common pain points that I have noticed is logging and rethrowing an exception. As a result, the log files contains the same exceptions several times on several stack levels.

share|improve this answer
add comment

Here's an anti-pattern: Making two dozen "genericvariable" fields in a database table to track anything conceivable and then having 88 (and counting) different enum values for different types of logs.

share|improve this answer
    
+1 - I've seen this. "Error Tables" that have columns like string1, string2, string3, string4, string5, where concatinating all the columns will result in an error code that is not referenced in any of the documentation. The result is logging that is both confusing and useless; also known as "3rd-party-enterprise-app-with-custom-development-debugging-hell". –  Morgan Herlocker Oct 5 '11 at 17:23
    
In my case it's "hand-rolled logging system without any idea of what logging actually involves" –  Wayne M Oct 5 '11 at 18:07
add comment

My experience with logs is the bigger the better, but be consistent enough to make it filterable by machine, and be able to configure a severity level for every component of your application individually.

Also, it's very difficult to predict what logging you will need to find a future bug. Most of the obvious places to log for bugs are fixed before the product goes out the door. It's not uncommon for the result of a bug report to be that you just added logging to help diagnose it if it happens again.

share|improve this answer
add comment

Apart from the stacktrace, log the current application state and the input.

Software is deterministic, these two are usually the only thing you need to reproduce the bug. Storing the full state might in some cases be troublesome so ways to reproduce the current state, by for example previous inputs, are also good.

Of course more data is always better but at minimum these two are a good start for the easiest crashes.

share|improve this answer
    
"Software is deterministic" => not always unfortunately. Think concurrency bugs for example. –  assylias Oct 26 '12 at 8:40
add comment

Couple of notes from the operations side of the house here:

1) Make sure the logs are locally configurable, preferably with a tool no heavier than a text editor. Most of the time we don't want to get TRACE level logging, but we love to be able to turn it on.

2) If at all possible, make sure the logs can be read with a tool no heavier than a text editor. Nothing is worse than having to go on a tool hunt at an odd hour when the production system is failing.

share|improve this answer
add comment

From my own experience working with web-applications:

(& considering storage is very cheap now-days)

  • Log as much available (at that very moment) info as you can.
  • I always include DateTime.Now in my log-strings.
  • I always (if it's possible) log time-duration of some specific "action".
  • Be consistent with your log-strings. Since always I use this kind of pattern:

    • "[Info X] [Info Y] [Info Z] [etc.]"
share|improve this answer
add comment

Not the answer you're looking for? Browse other questions tagged or ask your own question.