# Detailed logs and keeping code clean (not AOP)

I have two quite mutually exclusive desires - detailed logs and keeping my code clean. It appears that you can only get either of these. By "logging" I mean logging and not tracing, so AOP adepts wouldn't appreciate it.

What I want to have is real description of action my program does, why it does these actions and so forth. For instance, 'failures' could either be real failures like 'fatal errors', or absolutely normal behavior depending on context: I don't like to check whether or not file exists before reading, I'll just try to open it and that could either fail or succeed. If it fails, I'll have an exception. But if reading this file is not really critical, the exception I get is not an error, it could be treated as just 'warning'.

When something really interesting happens, I want to see it directly without scrolling up and down my 500KB log file and trying to remember the code.

I've implemented a draft solution for this problem and I'd like to know what you think:

sealed class FileReader
{

{
_fileName = fileName;
}

public string GetData(ExecutionContext context)
{
var fileExists = context.Execute(
string.Format("checking if {0} exists", _fileName),
ctx => File.Exists(_fileName));

if(!fileExists)
{
throw new FileNotFoundException();
}

var data = context.Execute(
delegate { // can easily use lambdas and anonymous delegates
});

return data;
}

public override string ToString()
{
}
}
...
sealed class FileProcessor
{

{
_dataProcessor = dataProcessor;
}

public void Process(ExecutionContext context)
{
context.Execute("processing data read", ctx => _dataProcessor.Process(ctx, data));
}

public override string ToString()
{
return string.Format(
_dataProcessor);
}
}
...
static void Main()
{
try
{
var context = new ExecutionContext("root");

// var dataProcessor = new DataProcessor()
var dataProcessor = context.Execute("creating data processor", ctx => new DataProcessor());

// var fileProcessor = new FileProcessor(fileReader, dataProcessor)
var fileProcessor =
context.Execute(
"creating file processor",

// fileProcessor.Process()
context.Execute("running file processor", ctx => fileProcessor.Process(ctx));
}
catch(Exception ex)
{
Console.WriteLine("Fatal error: {0}", ex.Message);
}
}


The results for this code:

/creating file reader - succeeded [FileReader(file=1.txt)]
/creating data processor - succeeded [DataProcessor]
/running file processor/reading data/checking if 1.txt exists - succeeded [False]
/running file processor/reading data - failed: Unable to find the specified file.
/running file processor - failed: Unable to find the specified file.
Fatal error: Unable to find the specified file.


I really like the result but I'm not sure if it's worth it. Any ideas?

• I'm a bit unclear on what the ExecutionContext object is. It appears that the ExecutionContext decides if the function is critical or not and handles writing log messages. The Execute function seems to returns the results of your delegate/lambda. Am I on the right track so far? – Nathanael Jul 19 '11 at 21:42
• Since you don't seem to be using the ExecutionContext root, why do you need to create a context object? – NetMage Aug 3 '11 at 18:33
• Without the definition of ExecutionContext, it is had to be thorough. Couldn't you create a class with static members and just reference the static class and not pass the ExecutionContext everywhere? Also, I don't like passing the executable steps into the logging code, it creates a funny execution flow (to me) plus overhead and peculiar function calling - I would prefer if context.Execute was always void and the delegate handled the assignment, for example. (SIGH split comment due to dumb Enter function plus DUMB comment timeout) – NetMage Aug 3 '11 at 18:40

For what it's worth after all this time you asked the question:

Is it worth it?

You said one requirement is to keep your code clean. You have fully achieved the total opposite of this. Lets take GetData() as an example. Without the ExecutionContext code the method would read this:

public string GetData(ExecutionContext context)
{
if(!File.Exists(_fileName))
{
throw new FileNotFoundException();
}
}


A reasonably experienced developer can read this code and understand what it is doing in about 5sec.

You have turned this four-liner into a mess of disjoint statements which take about 10 times longer to read through and understand what the code is doing.

You also run into the same problem as you do with commenting every statement: You write the code twice. Once for the compiler to execute and once for the developer/log file to read/record. Admittedly with detailed logging you can run into similar issues.

You also said you don't want tracing while in fact at least your example code boils down to exactly that. So using an AOP framework might be the better alternative in your case.

I think you should use a logging library instead of reinventing the wheel. See the very good log4net.

You can simply do

log.DebugFormat("creating file reader for file {0}", fileName);
log.Error("Unable to find the specified file");


And depending on the configuration you specify, it could be output like

Debug - 15:04:00.657 - (ThreadName) - FileReader - creating file reader for file foobar.txt
Error - 15:04:02.542 - (ThreadName) - FileReader - Unable to find the specified file


etc.

This allows you to specify a log level, that will help you with parsing the file while looking for the important bits.

You can also configure which messages get output at all by specifying the overall log level from an external XML file. For example the production version would be set on "Info" while the dev version would be on "Debug".

The line format is completely configurable so you can add many extra informations or change the order and formatting. It also handles log rotation and recycling.

When coding, you'll have some logging code around but if they are sufficiently clear, they can replace a comment.

• Did you even read the question? – Andrey Agibalov Sep 11 '12 at 5:23
• Sorry if I missed something, your goal is to have a real description of action your program does, why it does these actions and so forth, and to that end you have devised an (imho) overengineered solution, and coupled all your classes to a particular piece of infrastructure. Please enlighten me with what's wrong with log.Info("message");. – Joan Charmant Sep 11 '12 at 20:16
• The topic says: "Detailed logs and keeping code clean". Your advice of using log4net has nothing to do with both parts. Using log4net directly will cause the code to become twice longer, just because for every func(), you'll have to write corresponding log("func()"). The question is about getting rid of this boilerplate code. You may use Console.WriteLine() if there's anything you can advise from the design standpoint. The way messages are logged doesn't matter in fact. – Andrey Agibalov Sep 12 '12 at 7:12
• I certainly think the code is cleaner if you separate the concern of logging the operation with the one of performing it. Using a logging lib is better than Console.Writeline because it allows you to specify a log level, and later filter your logs based on that level without scrolling up and down your 500KB log file. – Joan Charmant Sep 12 '12 at 7:58

An alternative to resorting to AOP, could be to extract a IFileReader interface, and to decorate the FileReader with some LoggingEnabledFileReader - note that sealed explicitly prevents your code from being extensible, I'd drop it (un-sealing a class shouldn't be a breaking change). This solution is a bit of a merge of the other two answers.

One thing though, as this FileReader is a utility class, I'd pass the filename to the GetData method, not as a single-use, private readonly field - your code will be more flexible and reusable that way.

public interface IFileReader
{
string GetData(string fileName);
}


You keep the basic implementation to-the-point - note that I'm not throwing a FileNotFoundException and not bothering with verifying that the file exists - File.ReadAllText will throw that very same exception if the file can't be found, or it could throw some security exception if it's a permission issue. Basically, just let it throw whatever it throws:

public class FileReader : IFileReader
{
public string GetData(string fileName)
{
}
}


Then you implement the decorator - I like NLog, and with Ninject.Extensions.Logging I can constructor-inject a logger in any class without even thinking about it:

public class LoggingEnabledFileReader : IFileReader
{

{
_logger = logger;
}

public string GetData(string fileName)
{
string result;
try
{
}
catch(Exception ex)
{
// we only need a warning-level log entry here
_logger.WarnException(string.Format("Error with file '{0}'.", fileName), ex);
}

return result;
}
}


This way you have a very straightforward FileReader class, and a very straightforward LoggingEnabledFileReader class, both implementing the same IFileReader interface. If FileProcessor took an abstraction as a dependency instead of a specific implementation...

private readonly IFileReader _fileReader;


...then when a FileProcessor calls _fileReader.GetData, it has no clue whether the reader is logging-enabled or not, and it doesn't have to care either.
The FileReader code is as simple as it gets, and the LoggingEnabledFileReader code is nothing more and nothing less than what it says it is; the logging concern is taken care of in an explicitly logging-concerned class.
The ExecutionContext stuff looks over-engineered, over-complicated and overall over-the-top overboard with overusing lambdas and delegates and anonymous methods.