Effective Logging

Runtime diagnostics

There are 3 major ways to diagnose code at runtime.

I think most .NET developers use the debugger everyday in Visual Studio, and Automated tests (actually mostly unit tests) get a lot of blog space. But interestingly logging i not mentioned often? In some scenarios on way is more useful than the 2 other, and some times it does not matter which one is used. But all 3 ways have distinct advantages that can be used, to ease our busy developer lives.

Advantages

If your application has crashed, It does not matter how many unit tests or how good you are with the debugger. A good log will help you identify the problem.

In a live application the performance degradation(amount of log messages) can be controlled, by setting a log level. The application does not even have to be restarted. Unit tests does not do much with live applications and usually it is not wise to attach a debugger to a live application.

Statistics can be gathered from logs, like key performance indicators, number of exceptions etc. WMI can also be used, but that is actually just an other kind of logging (internal vs external).

Logs (often log files) act as an alternative UI, administrators/supporters etc. can read logs and determine out of process usage of the application.

If there is a good log there is no reason to call the user and start a “shared screen” so you can see what he does.

Messages

Don't just output values, describe what the values mean. When reading the log, you don't have the source code to help you - only the previous and next message(s).

Logging as a global error handler

As far as I can tell this is where most applications have some form of logging. The implementation looks differently depending on the type application.

In a WinForms app it looks something like this.

And in an ASP.NET app it could looks like this.

However this at the application boundary, it should be the only place in your code where the type Exception is caught. All uncaught exceptions should be allowed to bubble up to the global error handler and properly logged.

Logging is not error handling for the user

Don't log an exception just to re-throw the exception. But if you actually catch an specific exception type, always log the exception. The fact that the exception was caught could come in handy when diagnosing a problem with the application.

Decision Points

Are where the code branch, like if, switch and the like.

Don’t log inside a decision point, and don’t log where there is no decision point. Also don't log values that are not used for the decision.

 

Do log before a decision point and do log the value(s) that are used to determine what branch to use. Do log all the values in a single formatted message. There are more decision points than “if”’s, logical operators also act as a decision point.

Things to log even though it is not a decision point

When the application uses out of process resources (File system, starts a process etc.), Do log the resource used.

This could help an administrator understand how the application works.

 

Another thing to always log is the use of DateTime.Now

 

DateTime.Now problems are often elusive and hard to replicate in a debugging environment, having the exact value help to understand under what conditions a problem can occur.

 

Point of indirection (like events) where there is no clear path to the calling code. It can be helpful to see what events get called and in what order.

Assertion

Don’t use logging for assertion, a manual test with the debugger or a repeatable automated test are better suited for this.

Message Context

Every log message should have context values that determines this usage from others. Often things like:

• Timestamp
• Level (debug, trace, info, warning, error, fatal)
• Thread
• Principal (username)
• Url (for web apps)
• Request hashcode (for web apps)
• Session hashcode (for web apps)

Using these message contexts, it should be easy to grab interrelated messages for analysis.

Conclusion

Don't neglect logging just because your more familiar with the debugger or you and your agile team has the code base covered with automated tests. In some scenarios logging is a vital view into your running application.

Recommended Reading

http://nirajrules.wordpress.com/2008/06/14/blogging-best-practicies/

http://www.kdgregory.com/index.php?page=java.logging

http://esmithy.net/2004/11/09/effective-logging/

http://www.ibm.com/developerworks/java/library/j-logging/

The beauty of 2 state enums

The .NET type system already has a type for 2 states, it is of cause the Boolean. So why would I want to make a custom type?

Lets look at some code.

   1: var export = new SchemaExport(_cfg);

   2: var sb = new StringBuilder();

   3: TextWriter output = new StringWriter(sb);

   4: export.Execute(true, false, false, null, output);

The code above is from NHibernate, more specifically it is NHibernates schema export.

The documentation looks like the following.

public void Execute(bool script, bool export, bool justDrop, System.Data.IDbConnection connection, System.IO.TextWriter exportOutput)
    Member of NHibernate.Tool.hbm2ddl.SchemaExport

Summary:
Executes the Export of the Schema in the given connection

Parameters:
script: true if the ddl should be outputted in the Console.
export: true if the ddl should be executed against the Database.
justDrop: true if only the ddl to drop the Database objects should be executed.
connection: The connection to use when executing the commands when export is true.  Must be an opened connection. The method doesn't close the connection.
exportOutput: The writer used to output the generated schema

Remarks:
This method allows for both the drop and create ddl script to be executed.  This overload is provided mainly to enable use of in memory databases. It does NOT close the given connection!

Now I don't necessarily remember method signatures all to well. So custom type too the rescue, or rather custom enum too the rescue.

   1: public enum Script

   2: {

   3:     OutputToConsole,

   4:     NoConsoleOutput

   5: }

   6: pulic enum Export

   7: {

   8:     ExecuteScriptAgainstDatabase,

   9:     DontExecuteAgainstDatabase

  10: }

  11: public enum DDL

  12: {

  13:     DropOnly,

  14:     CreateAndDrop

  15: }

  16: export.Execute(Script.OutputToConsole, Export.DontExecuteAgainstDatabase, DDL.CreateAndDrop, null, output);

Another alternative is to make several methods that can be named, or create a class that takes the arguments as properties, so that they can be optional.

Data, objects and abstractions – Are there more to DIP?

If we define the following:

Data is just raw data, with no context and no logic associated.

Objects contains both data and behavior that operates on that state.

Abstractions defines behavior by naming, with out any details of how the desired behavior is implemented.

 

A common definition of DIP states that:

High level modules should not depend upon low level modules. Both should depend upon abstractions. Abstractions should not depend upon details. Details should depend upon abstractions.

That keeps the objects from referencing each other, creating low coupling = a good thing :-)

In C# code following DIP, there is often an “IFooBar” and a “FooBar”. So we have a 1 to 1 between abstractions and object classes. I never really liked it, I don't know why it just don't feels right. Another side effect is that objects that depend on the abstraction can now be unit tested, but often we need to mock the abstraction. In my opinion this leads to hard-to-read and brittle tests.

Is there a simple alternative?

So if objects should not depend upon other object and an abstraction is not desirable, what should the dependency be?

Data

It just like messaging between systems, only this is inside an system. Instead of having a direct dependency to the “CustomerRepository” or having to create a “ICustomerRepository”, just depend on a Customer or a Customer[], nice and simple. This assumes that the Customer is data, and not a object or abstraction.

Move as much if/else/switch/loop code to object classes that depend on and creates data, that way they are easily read, tested and understood. As close to the user action (button click etc. – I call them “Controllers”), get the data needed(possible from a database), pass it to or create the objects, and then take action based on the data result(SubmitChanges to the database, send the MailMessage or what not). These “Controllers” are hard to test and need mocking because of all the database work, mail sending etc., so here classic DIP applies. The Controllers should have a minimum of conditional statements (if) and the few if statements needed should not be nested. This is extremely procedural in nature, and is easy to read.

 

Sometimes we actually need an abstraction, and by all means make one. But code reads better when it just data flowing through logic.

Data Structures vs Encapsulation

Having read Clean Code I really wanted to blog about data structures (DTO) and encapsulated objects. But I have been busy and someone else beat me to the punch. Uncle Bob also has an article where he outlines his view.

Data Structure Objects

In C# a Data Structure is represented by a class or struct, that has has no logic and exposes all its state through properties(public fields or get/set methods). Its primarily used near the system boundaries, like UI, Service end points, and database access. Anyone can use the exposed data and operate on it, so adding new behavior is easy, but adding new or changing existing data is troublesome.

Encapsulated Objects

Are represented by C# classes/interfaces with methods that operate on data. The data is hidden(encapsulated). Internally the object can have Data Structure Objects as state, and operate on that state. Methods define the operation that can either be a command (changes the state, and returns nothing) or a query (does not change state, and returns something). A Validator could have a Validate command method that validates the internal state, and a ValidationNotifications query that returns the result of the last validation.

Changing the state is easy because it is only know internal in the class, but adding new or changing existing behavior is troublesome, because it changes the contract of the class.

Hybrid Objects

Hybrids often appear because of database and UI concerns. A class exposes it state so that the UI can data bind and the DAL can save the entity. But the same class should also be encapsulated so that the logic only lives with in the object.

So now the class has two distinct responsibilities:

1. Exposing state for the UI and DAL to use.
2. Exposing logic for validation etc.

And guess what, if it is combined in a Hybrid Class it has the drawbacks of both, and non of the benefits. So Hybrids should really be avoided, and interesting happen when you don't create hybrids.

Should all my classes be Encapsulated Objects?

NO!

Even though all the cool kids show off their OO skilz, many problems are best solved with a simple Data Structure Class. If your application starts out as a 1 to 1 mapping from the UI to the database tables, there is little need for encapsulated objects. However as the application gets more logic, be sure to place this logic in encapsulated objects. Avoiding the Hybrid trap, this should help make the application more maintainable.

My advice

Keep your data(from a database or the user etc.) in Data Structures and your logic(anything like if/for/while etc) in Encapsulated Classes. The encapsulated Objects are free to use Data Structures directly or contain them as state. Just like adding string, int, bool and any other simple type feels natural, adding a custom made Data Structure as state should also be natural.

How to create fully encapsulated and simple Domain Models

Background

Udi wrote about this topic, but I never really liked the solution. To me it seemed complex and over architected, even the solutions from the commenter's where surprisingly complex (No disrespect for Udi or any of the commenter's intended).

Business Context

The core domain revolves around renting video games. I am working on a new feature to allow customers to trade in old video games. Customers can trade in multiple games at a time so we have a TradeInCart entity that works similar to most shopping carts that everybody is familiar with. However there are several rules that limit the items that can be placed into the TradeInCart. The core rules are:

1. Only 3 games of the same title can be added to the cart.
2. The total number of items in the cart cannot exceed 10.
3. No games can be added to the cart that the customer had previously reported lost with regards to their rental membership.
    a. If an attempt is made to add a previously reported lost game, then we need to log a BadQueueStatusAddAttempt to the persistence store.

A solution

The service layer service looks like this.

   1: using System.Transactions;

   2:  

   3: namespace VideoGameRenting

   4: {

   5:     public class TradeInService

   6:     {

   7:         private readonly Repository _repository;

   8:  

   9:         private GameDTO _gameDTO;

  10:         private TradeInCartDTO _tradeInCartDTO;

  11:         private LineItemDTO[] _lineItemDTOS;

  12:         private GameReportedLostDTO _gameReportedLostDTO;

  13:         private TradeInCart _tradeInCart;

  14:  

  15:         public TradeInService(Repository repository)

  16:         {

  17:             _repository = repository;

  18:         }

  19:  

  20:         //This is an outer boundry of the system.

  21:         //The operation below is a complete operation aganst the system.

  22:         public void AddGameToCart(int gameId, int tradeInCartId)

  23:         {

  24:             using(TransactionScope scope = new TransactionScope(TransactionScopeOption.RequiresNew))

  25:             {

  26:                 LoadAllDataNeeded(gameId, tradeInCartId);

  27:  

  28:                 ApplyBusinessRulesToData();

  29:  

  30:                 SaveDataIfNeeded();

  31:    

  32:                 scope.Complete();

  33:             }

  34:  

  35:             //If it is a GUI application, "redirect" to a method that renders a view with data

  36:         }

  37:  

  38:         private void LoadAllDataNeeded(int gameId, int tradeInCartId)

  39:         {

  40:             _gameDTO = _repository.Find<GameDTO>(gameId);

  41:             _tradeInCartDTO = _repository.Find<TradeInCartDTO>(tradeInCartId);

  42:             _lineItemDTOS = _repository.Query<LineItemDTO>(x => x.TradeInCartId == _tradeInCartDTO.Id);

  43:             _gameReportedLostDTO = _repository.FindBy<GameReportedLostDTO>(

  44:                 x => x.Customer == _tradeInCartDTO.CustomerId && x.GameId == _gameDTO.Id);

  45:         }

  46:  

  47:         private void ApplyBusinessRulesToData()

  48:         {

  49:             _tradeInCart = new TradeInCart(_tradeInCartDTO, _lineItemDTOS);

  50:             _tradeInCart.AttemptToAddGameAndLogAnyAbuse(_gameDTO, _gameReportedLostDTO);

  51:         }

  52:  

  53:         private void SaveDataIfNeeded()

  54:         {

  55:             _repository.Save(_tradeInCartDTO);

  56:             foreach (LineItemDTO line in _tradeInCart.GetItems())

  57:             {

  58:                 _repository.Save(line);

  59:             }

  60:             foreach (AbuseLogEntryDTO abuseLogEntry in _tradeInCart.GetAbuseLogEntries())

  61:             {

  62:                 _repository.Save(abuseLogEntry);

  63:             }

  64:         }

  65:     }

  66: }

Basically I treat data as pure data structures(DTO) and I have objects that operate on the data.

The TradeInCart DDD Entity looks like this, it is the agregate root for TradeInCartDTO, LinetemDTO and AbuseLogEntryDTO.

   1: using System;

   2: using System.Collections.Generic;

   3:  

   4: namespace VideoGameRenting

   5: {

   6:     public class TradeInCart

   7:     {

   8:         private readonly TradeInCartDTO _tradeInCartDTO;

   9:         private readonly List<LineItemDTO> _items;

  10:         private readonly List<AbuseLogEntryDTO> _abuseLogEntries;

  11:  

  12:         public TradeInCart(TradeInCartDTO tradeInCartDTO, IEnumerable<LineItemDTO> items)

  13:         {

  14:             _tradeInCartDTO = tradeInCartDTO;

  15:             _items = new List<LineItemDTO>(items);

  16:             _abuseLogEntries = new List<AbuseLogEntryDTO>();

  17:         }

  18:  

  19:         public IEnumerable<LineItemDTO> GetItems()

  20:         {

  21:             return _items.AsReadOnly();

  22:         }

  23:  

  24:         public IEnumerable<AbuseLogEntryDTO> GetAbuseLogEntries()

  25:         {

  26:             return _abuseLogEntries.AsReadOnly();

  27:         }

  28:  

  29:         public void AttemptToAddGameAndLogAnyAbuse(GameDTO game, GameReportedLostDTO gameReportedLost)

  30:         {

  31:             if (GameHasBeenReportedLost(gameReportedLost))

  32:             {

  33:                 LogAbuse();

  34:                 return;

  35:             }

  36:             if (GameCannotBeAddedToCart(game)) return;

  37:  

  38:             AddGameToNewLineItem(game);

  39:         }

  40:  

  41:         private bool GameHasBeenReportedLost(GameReportedLostDTO gameReportedLost)

  42:         {

  43:             return gameReportedLost != null;

  44:         }

  45:  

  46:         private void LogAbuse()

  47:         {

  48:             AbuseLogEntryDTO abuseLogEntry = new AbuseLogEntryDTO();

  49:             abuseLogEntry.Message = "BadQueueStatusAddAttempt";

  50:             abuseLogEntry.TimeStamp = DateTime.Now;

  51:             _abuseLogEntries.Add(abuseLogEntry);

  52:         }

  53:  

  54:         private bool GameCannotBeAddedToCart(GameDTO game)

  55:         {

  56:             return _items.Count > 10 || CountGamesWithSameTitle(game.Id) > 3;

  57:         }

  58:  

  59:         private void AddGameToNewLineItem(GameDTO game)

  60:         {

  61:             LineItemDTO lineItemDTO = new LineItemDTO();

  62:             lineItemDTO.GameId = game.Id;

  63:             lineItemDTO.TradeInCartId = _tradeInCartDTO.Id;

  64:             _items.Add(lineItemDTO);

  65:         }

  66:  

  67:         private int CountGamesWithSameTitle(int gameId)

  68:         {

  69:             int gameCount = 0;

  70:             foreach (LineItemDTO line in _items)

  71:             {

  72:                 if(line.GameId == gameId)

  73:                 {

  74:                     gameCount++;

  75:                 }

  76:             }

  77:             return gameCount;

  78:         }

  79:  

  80:  

  81:     }

  82: }

The full source code is in my trunk.

Conclusion

I think my solution is simpler and easier to understand. I think it communicates very well.

I am actually in doubt... Do I need a AddToCartAttempt class, with GameDTO and GameReportedLostDTO as fields and the appropriate logic? Then I would not need to pass around parameters in TradeInCart's GameHasBeenReportedLost, GameCannotBeAddedToCart and AddGameToNewLineItem