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.

What are best-practices for logging deep within an application's source? Is it bad practice to have multiple event log entries for a single error?

For example, let's say that I have an ETL system whose transform step involves: a transformer, pipeline, processing algorithm, and processing engine.

In brief, the transformer takes in an input file, parses out records, and sends the records through the pipeline. The pipeline aggregates the results of the processing algorithm (which could do serial or parallel processing). The processing algorithm sends each record through one or more processing engines. So, I have at least four levels: Transformer -> Pipeline -> Algorithm -> Engine.

My code might then look something like the following:

class Transformer {
    void Process(InputSource input) {
        try {
            var inRecords = _parser.Parse(input.Stream);
            var outRecords = _pipeline.Transform(inRecords);
        } catch (Exception ex) {
            var inner = new ProcessException(input, ex);
            _logger.Error("Unable to parse source " + input.Name, inner);
            throw inner;
        }
    }
}

class Pipeline {
    IEnumerable<Result> Transform(IEnumerable<Record> records) {
        // NOTE: no try/catch as I have no useful information to provide
        // at this point in the process
        var results = _algorithm.Process(records);

        // examine and do useful things with results
        return results;
    }
}

class Algorithm {
    IEnumerable<Result> Process(IEnumerable<Record> records) {
        var results = new List<Result>();
        foreach (var engine in Engines) {
            foreach (var record in records) {
                try {
                    engine.Process(record);
                } catch (Exception ex) {
                    var inner = new EngineProcessingException(engine, record, ex);
                    _logger.Error("Engine {0} unable to parse record {1}", engine, record);
                    throw inner;
                }
            }
        }
    }
}


class Engine {
    Result Process(Record record) {
        for (int i=0; i<record.SubRecords.Count; ++i) {
            try { 
                Validate(record.subRecords[i]);
            } catch (Exception ex) {
                var inner = new RecordValidationException(record, i, ex);
                _logger.Error(
                    "Validation of subrecord {0} failed for record {1}",
                    i, record
                    );
            }
        }
    }
}

There's a few important things to notice:

  • A single error at the deepest level causes three log entries (ugly? DOS?)
  • Thrown exceptions contain all important and useful information
  • Logging only happens when failure to do so would cause loss of useful information at a lower level.

Thoughts and concerns:

  • I don't like having so many log entries for each error
  • I don't want to lose important, useful data; the exceptions contain all the important but the stacktrace is typically the only thing displayed besides the message.
  • I can log at different levels (e.g., warning, informational)
  • The higher level classes should be completely unaware of the structure of the lower-level exceptions (which may change as the different implementations are replaced).
  • The information available at higher levels should not be passed to the lower levels.

So, to restate the main questions:

What are best-practices for logging deep within an application's source? Is it bad practice to have multiple event log entries for a single error?

share|improve this question
add comment

4 Answers

up vote 8 down vote accepted

I prefer to:

  1. Wrap exceptions with any useful information that I may have available at the level where they are caught.
  2. Always log exceptions if they are not getting rethrown.
  3. Only log exceptions if they are not getting rethrown.

It looks like you're following #1 and #2 already, so you just need to apply #3, and you can ensure that each error is only logged once, with the maximum amount of information possible.

class Transformer {
    void Process(InputSource input) {
        try {
            var inRecords = _parser.Parse(input.Stream);
            var outRecords = _pipeline.Transform(inRecords);
        } catch (Exception ex) {
            // Make sure the message string on this exception class produces
            // a verbose error message like "Unable to parse source " + input.Name
            throw new ProcessException(input, ex);
        }
    }
}

class Pipeline {
    IEnumerable<Result> Transform(IEnumerable<Record> records) {
        // NOTE: no try/catch as I have no useful information to provide
        // at this point in the process
        var results = _algorithm.Process(records);

        // examine and do useful things with results
        return results;
    }
}

class Algorithm {
    IEnumerable<Result> Process(IEnumerable<Record> records) {
        var results = new List<Result>();
        foreach (var engine in Engines) {
            foreach (var record in records) {
                try {
                    engine.Process(record);
                } catch (Exception ex) {
                    // Likewise, ensure the message string for this class records
                    // the specifics, so that logging a stack trace will contain
                    // all the necessary details to reproduce.
                    throw new EngineProcessingException(engine, record, ex);
                }
            }
        }
    }
}


class Engine {
    Result Process(Record record) {
        for (int i=0; i<record.SubRecords.Count; ++i) {
            try { 
                Validate(record.subRecords[i]);
            } catch (Exception ex) {
                var inner = new RecordValidationException(record, i, ex);
                // Since you're not rethrowing, make sure you log this error.
                _logger.Error(
                    ex,
                    "Validation of subrecord {0} failed for record {1}",
                    i, record
                    );
            }
        }
    }
}

Be aware that this does open up the possibility that your exception could end up in code where the author didn't follow rule #2, and no log is produced. But if you can ensure that these three rules are followed consistently, I've found this to be an ideal approach.

share|improve this answer
    
In your modification of the code sample the error is swallowed and any higher-level information (like input source) is missing. So, assuming I take this approach and catch the exception at the highest possible (reasonable) level, would the goal be to make the ToString() of every exception perfectly readable and include the message of any inner exceptions? It seems this would allow me to catch it at the highest-level and still provide all the information even though the outer-level exception remained unaware of the details of the inner exceptions. –  Kaleb Pederson Jun 8 '12 at 0:31
1  
@KalebPederson: Yes, that's precisely the idea. Most logging frameworks have a way for you to pass an exception as an argument separately from the log message, and they can be configured to log the full stack trace, with all the Messages of all the inner exceptions. I updated the code sample to reflect this. –  StriplingWarrior Jun 8 '12 at 2:25
    
debug or trace level logs at the lower levels should be OK. Presumably they will be configured off in production, and a developer will know how to silence them if they aren't interested in them... –  Bill Michell Dec 6 '13 at 14:12
    
@BillMichell: While the log messages will be less obtrusive at lower levels, I'd still argue that they only add needless complexity in most cases. I would only log information about exceptions that get handled and aren't re-thrown. –  StriplingWarrior Dec 6 '13 at 19:52
    
@StriplingWarrior That is a valid opinion and if my team were to agree on that code style, I wouldn't argue too strongly against it. Personally, I'd rather have the extra info, but not enough to cause friction with other team members. –  Bill Michell Dec 9 '13 at 9:29
show 1 more comment

I believe the Aspect Oriented Programming paradigm may offer some insight into the general solution to your problem. In researching various languages / technologies, i've read that AOP is especially suited for "cross cutting" needs including ideas such as "logging"

Logging exemplifies a crosscutting concern because a logging strategy necessarily affects every logged part of the system. Logging thereby crosscuts all logged classes and methods.

Some technologies make it easy to implement, others do not. Wish i could offer you more insight.

share|improve this answer
    
Good idea. I haven't yet seen a enough of a pattern that I can use to extract the functionality out to AOP because all of my log calls take in different data. –  Kaleb Pederson Jun 7 '12 at 23:11
add comment

If you add some sort of component information to your log messages, you will be able to filter out everything but the top levels when viewing the logs. Then if you need more information about an error you can go and look for it.

I don't find it wrong to log multiple entries for a single error. Many programs do it already.

For example, if you are using Windows and have security event audits turned on, you may get a sequence of events that includes a failed access attempt error from the OS and then a service error for being unable to open a configuration file or registry entry. Then you might get an event from the service for being unable to start because of missing configuration.

share|improve this answer
    
I actually have a LoggingEvent class that contains the event information which is passed as the first parameter in place of the description that I used in the example above. It contains component information (and more) and allows me to filter by Component, task, opcode, keyword, level, etc. –  Kaleb Pederson Jun 7 '12 at 23:18
add comment

I used work writing software for reference boards. We had no debugger facilities for these boards (employer too cheap to buy JTAG HW) only writing logs out through serial ports. Logging as a debugging scheme is extremely useful but you need to know what to log and when. I've found the following quite useful:

Make the difference between 'got here' logs and error logs very obvious. I used prefix error logs with 3 asterixes, i.e. "* Call to foo(ptr=0x00000000, value=6) failed with -2 *", so I could search the log file quickly for errors in a text editor (they'd be several megabytes in size).

Don't just record that something went wrong, record what went wrong, preferably in the function where the exception is thrown or, if you don't have access to the code, as close as possible to that point.

Don't record something for the sake of it; only if it'll be of use to you. I used encounter situations where the entire call stack would continually be logged. It sounds useful but all it did was pollute logs and when you're dealing with asynchronous behaviour it turns out not to be all that useful. Excessive logging can even change the runtime behaviour and hide multi-threaded issues that only appear when you use Release builds. If you do go down the route of logging the execution trace you may as well log the parameter values passed to functions where possible.

As for multiple logs entires for the same error... no big deal. The first one is usually the culprit and as long as you can find it, and have logs that provide enough information for you to quickly reproduce/isolate the error, the rest should only be confirmation that your program doesn't fall over itself when an error does occur.

share|improve this answer
add comment

Your Answer

 
discard

By posting your answer, you agree to the privacy policy and terms of service.

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