Logging errors caused by exceptions deep in the application
- by Kaleb Pederson
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?
