object.LogInfo() – do logowania tożsamości obiektu

Niedawno przedstawiłem TokenContext, klasę pomocniczą upraszczającą wyławianie kontekstu z masy logów tworzonych w aplikacji wielowątkowej, gdzie wiele operacji przeplata się nawzajem.

Regularnie jednak zdarza się, że interesuje nas nie tyle jedna szczególna operacje co cały cykl życia konkretnego obiektu. Kumpel, z którym pracuję nad "głównym" projektem, zaproponował stosowanie takiej, bardzo prostej, logicznej i przydatnej, konwencji:

  1:  _log.Debug("User#{0} did something", user.Id);

Albo:

  1:  _log.Debug("Order#{0} processed", order.Id);

Oczywiście to uproszczony przykład, ale wiadomo o co chodzi. Dzięki temu przetwarzając logi w poszukiwaniu wszystkich informacji o użytkowniku ID=125 wyfiltruję linijki z tekstem "User#125" i mam czego potrzebowałem.

Ostatnio w mniejszym projekcie postanowiłem przetestować jak można by to uprościć jeszcze bardziej, żeby nie klepać ręcznie nazwy typu i hasha. Rozwiązanie przychodzi do głowy samo, a obrazują je te banalne testy:

  1:  public class ObjectLogInfoTests
  2:  {
  3:      public class WithId
  4:      {
  5:          public virtual int Id { get; set; }
  6:      }
  7:  
  8:      public class WithoutId
  9:      {
 10:          public virtual int SomeOtherProperty { get; set; }
 11:      }
 12:  
 13:      [Fact]
 14:      public void should_return_type_name_with_hash_and_id_if_class_has_Id_property()
 15:      {
 16:          var o = new WithId { Id = 8 };
 17:  
 18:          string logInfo = o.LogInfo();
 19:  
 20:          Assert.Equal("WithId#8", logInfo);
 21:      }
 22:  
 23:      [Fact]
 24:      public void should_return_type_name_if_class_does_not_have_Id_property()
 25:      {
 26:          var o = new WithoutId();
 27:  
 28:          string logInfo = o.LogInfo();
 29:  
 30:          Assert.Equal("WithoutId", logInfo);
 31:      }
 32:  }

Klasa implementująca te założenia jest jeszcze "banalniejsza":

  1:  public static class ObjectLoggingExtensions
  2:  {
  3:      public static string LogInfo(this object @this)
  4:      {
  5:          Type type = @this.GetType();
  6:          var idProperty = type.GetProperty("Id");
  7:          object idValue = null;
  8:          if (idProperty != null)
  9:          {
 10:              idValue = idProperty.GetValue(@this, null);
 11:          }
 12:          if (idValue == null)
 13:          {
 14:              return type.Name;
 15:          }
 16:          else
 17:          {
 18:              return "{0}#{1}".FormatWith(type.Name, idValue);
 19:          }
 20:      }
 21:  }

Dzięki temu podany na początku przykład wygląda teraz tak:

  1:  _log.Debug("{0} did something", user.LogInfo());

Oczywiście narzuca to na system konwencje nazywania właściwości "Id", jednak w tym konkretnym przypadku nie był to problem. Bez wielkiego nakładu pracy można by rozszerzyć tą klasę aby dodatkowo szukała na przykład właściwości o nazwie "[TypeName]Id".

Początkowo przez chwilę zastanowiłem się nad tym, czy wykorzystanie refleksji jest w tym przypadku słuszne ze względów wydajnościowych, jednak… nie oszukujmy się, przy kontakcie z bazą danych takie coś nie ma absolutnie żadnego znaczenia. Testowo puściłem wykonanie podobnej instrukcji w pętli milion razy i zajęło to około sekundy.

Tak czy siak rozwiązanie się póki co sprawdza (chociaż nie pokrywa wszystkich scenariuszy w których loguję informację o obiektach).

Coraz bardziej przekonuję się do tego, że zbudowanie odpowiednich pomocników wokół konceptu "logowania" jest istotną częścią systemu. Logowanie powinno być bezbolesne, momentalne i naturalne. Im mniej klawiszy trzeba wcisnąć do uzyskania informacji w logu – tym lepiej.