Logging errors caused by exceptions deep in the application

Question

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?

Answer 1

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.

Answer 2

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.

Answer 3

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.

Answer 4

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.