Logging errors caused by exceptions deep in the application

Posted by Kaleb Pederson on Programmers See other posts from Programmers or by Kaleb Pederson
Published on 2012-06-07T22:29:35Z Indexed on 2012/06/07 22:47 UTC
Read the original article Hit count: 325

Filed under:

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?

© Programmers or respective owner

Related posts about logging