• Artigo

Abril de 2016

Volume 31, Número 4

Essential .NET - Registro em log com o .NET Core

Por Mark Michaelis

Mark MichaelisNa edição de fevereiro, abordei a nova API de configuração incluída na recém-nomeada plataforma .NET Core 1.0 (confira bit.ly/1OoqmkJ). (Presumo que a maioria dos leitores tenha ouvido falar sobre a recém-renomeada plataforma .NET Core 1.0, que era conhecida anteriormente como .NET Core 5 e faz parte da plataforma ASP.NET 5 [confira bit.ly/1Ooq7WI].) Naquele artigo, usei o teste de unidade para explorar a API do Microsoft.Extensions.Configuration. Neste artigo, vou adotar uma abordagem semelhante, com a exceção de que vou usar o Microsoft.Extensions.Logging. A principal diferença em minha abordagem é que a estou testando por meio de um arquivo CSPROJ do .NET 4.6, em vez de um projeto do ASP.NET Core. Isso enfatiza o fato de que o .NET Core está disponível para que você considere seu uso imediatamente, mesmo que não tenha migrado para projetos ASP.NET Core.

Está fazendo registro em log? Por que precisamos de uma nova estrutura de registro em log? Já temos NLog, Log4Net, Loggr, Serilog e o Microsoft.Diagnostics.Trace/Debug/TraceSource interno, para citar apenas alguns. Como se vê, o fato de existirem tantas estruturas de registro em log é realmente um dos fatores determinantes para tornar o Microsoft.Extensions.Logging relevante. Como um desenvolvedor confrontado com a infinidade de opções, é provável que você selecione uma delas sabendo que talvez tenha que mudar para outra mais tarde. Portanto, você provavelmente está tentado escrever seu próprio wrapper de API de registro em log para invocar qualquer estrutura de registro em log específica que você ou sua empresa escolherem esta semana. Da mesma forma, você pode usar uma estrutura de registro em log específica em seu aplicativo, só para descobrir que uma das bibliotecas que está utilizando está usando outra, fazendo com que você tenha que escrever um ouvinte que leva as mensagens de uma para a outra.

Com o Microsoft.Extensions.Logging, a Microsoft está fornecendo um wrapper para que ninguém precise escrever o seu próprio. Esse wrapper fornece um conjunto de APIs que são então encaminhadas para o provedor de sua escolha. Embora a Microsoft inclua provedores para itens como Console (Microsoft.Extensions.Logging.Console), depuração (Microsoft.Extensions.Logging.Debug), log de eventos (Microsoft.Extensions.Logging.EventLog) e TraceSource (Microsoft.Estensions.Logging.TraceSource), ela também colaborou com as várias equipes de estruturas de registro em log (incluindo terceiros, como NLog, Serilog, Loggr, Log4Net e outros), assim, também há provedores deles que são compatíveis com o Microsoft.Extensions.Logging.

Introdução

A raiz da atividade de registro em log começa com um log factory, como mostrado na Figura 1.

Figura 1 - Como usar o Microsoft.Extensions.Logging

public static void Main(string[] args = null)
{
  ILoggerFactory loggerFactory = new LoggerFactory()
    .AddConsole()
    .AddDebug();
  ILogger logger = loggerFactory.CreateLogger<Program>();
  logger.LogInformation(
    "This is a test of the emergency broadcast system.");
}

Como o código demonstra, para começar, você instancia um Microsoft.Extensions.Logging.LoggerFactory, que implementa ILoggerFactory no mesmo namespace. Em seguida, você especifica quais provedores deseja utilizar, aproveitando o método de extensão de ILoggerFactory. Na Figura 1, uso especificamente Microsoft.Extensions.Logging.ConsoleLoggerExtensions.AddConsole e Microsoft.Extensions.Log­ging.DebugLoggerFactoryExtensions.AddDebug. (Embora ambas as classes estejam no namespace Microsoft.Extensions.Logging, realmente são encontradas nos pacotes Microsoft.Extensions.Log­ging.Console e Microsoft.Extensions.Logging.Debug NuGet, respectivamente).

Os métodos de extensão são simplesmente atalhos convenientes para a maneira mais geral de adicionar um provedor: ILoggerFactory.AddProvider (provedor ILoggerProvider). O atalho é que o método AddProvider requer uma instância de um provedor de log (provavelmente um cujo construtor exija uma expressão de filtro de nível de log), enquanto os métodos de extensão fornecem padrões para essas expressões. Por exemplo, a assinatura de construtor de ConsoleLoggerProvider é:

public ConsoleLoggerProvider(Func<string, LogLevel, bool> filter,
  bool includeScopes);

Esse primeiro parâmetro é uma expressão de predicado que permite definir se uma mensagem será exibida na saída com base no valor do texto registrado em log e no nível de log.

Por exemplo, você poderia chamar AddProvider com uma instância específica de ConsoleLoggerProvider que foi construída com base em um filtro de todas as mensagens mais elevadas (mais significativas) do que LogLevel.Information:

loggerFactory.AddProvider(
  new ConsoleLoggerProvider(
    (text, logLevel) => logLevel >= LogLevel.Verbose , true));

(O interessante é que, diferentemente dos métodos de extensão que retornam um ILoggerFactory, AddProvider retorna um nulo, impedindo a sintaxe de tipo fluido mostrada na Figura 1.)

É importante estar ciente de que, infelizmente, há alguma inconsistência entre os provedores de log para determinar se um valor de alto nível de log é mais ou menos significativo. Um nível de log 6 indica que ocorreu um erro crítico ou é apenas uma mensagem de diagnóstico detalhada? Microsoft.Extensions.Logging.LogLevel usa valores elevados para indicar maior prioridade com a seguinte declaração de enumeração LogLevel:

public enum LogLevel
{
  Debug = 1,
  Verbose = 2,
  Information = 3,
  Warning = 4,
  Error = 5,
  Critical = 6,
  None = int.MaxValue
}

Portanto, instanciando um ConsoleLoggerProvider que grava mensagens somente quando logLevel >= LogLevel.Verbose, você exclui apenas a gravação de mensagens de nível de depuração na saída.

Observe que você pode adicionar vários provedores ao log factory, até mesmo vários provedores do mesmo tipo. Portanto, se eu adicionar uma invocação de ILoggerFactory.AddProvider à Figura 1, uma chamada a ILogger.LogInformation exibirá uma mensagem no console duas vezes. O primeiro provedor de console (aquele adicionado por AddConsole) adota como padrão a exibição de LogLevel.Information ou superior. No entanto, uma chamada a ILogger.LogVerbose seria mostrada apenas uma vez, pois apenas o segundo provedor (adicionado por meio do método AddProvider) teria êxito ao evitar ser filtrado.

Padrões de registro em log

Como demonstra a Figura 1, a raiz de todo o registro em log começa com um log factory do qual você pode solicitar uma ILogger por meio do método ILoggerFactory.CreateLogger<T>. O tipo genérico T nesse método serve para identificar a classe em que o código é executado. Assim, é possível gravar o nome da classe em que o agente está gravando mensagens. Em outras palavras, chamando loggerFactory.CreateLogger<Program>, essencialmente você inicia um agente específico para a classe Program, de modo que sempre que uma mensagem for gravada, também seja possível gravar o contexto de execução como estando dentro da classe Program. Assim, a saída do console da Figura 1 é:

info: SampleWebConsoleApp.Program[0]
      This is a test of the emergency broadcast system.

Essa saída é baseada no seguinte:

  • "info" resulta do fato de que essa é uma chamada de método LogInformation.
  • "SampleWebConsoleApp.Program" é determinado com base em T.
  • "[0]" é o eventId, um valor que não especifiquei, por isso, ele usa 0 por padrão.
  • "Este é um teste do sistema de difusão de emergência." é o argumento de mensagens passado para LogInformation.

Como o valor Program indica o contexto de nível de classe, provavelmente convém instanciar uma instância do agente diferente para cada classe da qual deseja fazer registro em log. Por exemplo, se Program cria e chama uma instância de classe Controller, convém ter uma nova instância do agente dentro da classe Controller que foi criada por meio de outra chamada de método em que T agora é Controller:

loggerFactory.CreateLogger<Controller>()

Como você pode perceber, isso requer acesso à mesma instância do logger factory em que os provedores foram configurados anteriormente. Embora seja concebível que você possa passar a instância do logger factory para todas as classes das quais deseja realizar o registro em log, isso logo se tornaria um aborrecimento que exigiria a refatoração.

A solução é salvar um único ILoggerFactory estático como uma propriedade estática que está disponível para todas as classes ao instanciar a instância de ILoggger específica de seu objeto. Por exemplo, considere a adição de uma classe estática ApplicationLogging que inclua uma instância estática de ILoggerFactory:

public static class ApplicationLogging
{
  public static ILoggerFactory LoggerFactory {get;} = new LoggerFactory();
  public static ILogger CreateLogger<T>() =>
    LoggerFactory.CreateLogger<T>();
}

A preocupação óbvia para essa classe é se o LoggerFactory é thread-safe. Felizmente, como demonstra o método AddProvider mostrado na Figura 2, ele é.

Figura 2 - A Implementação de Microsoft.Extensions.Logging.LoggerFactory AddProvider

public void AddProvider(ILoggerProvider provider)
{
  lock (_sync)
  {
    _providers = _providers.Concat(new[] { provider }).ToArray();
    foreach (var logger in _loggers)
    {
      logger.Value.AddProvider(provider);
    }
  }
}

Como os únicos dados na instância de ILogger são determinados com base no tipo genérico T, você pode argumentar que cada classe poderia ter um ILogger estático que o objeto de cada classe poderia aproveitar. No entanto, pressupondo-se o padrão de programação de garantir o acesso thread-safe para todos os membros estáticos, essa abordagem exigiria o controle de concorrência na implementação de ILogger (que não existe por padrão) e o resultado provável seria um afunilamento significativo à medida que bloqueios fossem obtidos e liberados. Por esse motivo, a recomendação, de fato, é ter uma instância de ILogger individual para cada instância de uma classe. Portanto, o resultado é uma propriedade ILogger em cada classe para a qual você deseja dar suporte ao registro em log (confira a Figura 3).

Figura 3 - Como adicionar uma instância de ILogger a cada objeto que precisa de registro em log

public class Controller
{
  ILogger Logger { get; } =
    ApplicationLogging.CreateLogger<Controller>();
  // ...
  public void Initialize()
  {
    using (Logger.BeginScopeImpl(
      $"=>{ nameof(Initialize) }"))
    {
      Logger.LogInformation("Initialize the data");
      //...
      Logger.LogInformation("Initialize the UI");
      //...
    }
  }
}

Noções básicas sobre escopos

Frequentemente, os provedores dão suporte ao conceito de "escopo" de tal forma que você possa (por exemplo) registrar em log como o código percorre uma cadeia de chamada. Continuando o exemplo, se Program invoca um método em uma classe Controller, essa classe, por sua vez, instancia sua própria instância de agente com seu próprio contexto do tipo T. No entanto, em vez de simplesmente exibir uma mensagem contexto de informações: SampleWebConsoleApp.Program[0] seguido de informações: SampleWebConsoleApp.Controller[0], convém registrar em log que Program invocou Controller e, possivelmente, até mesmo incluir os nomes dos próprios métodos. Para fazer isso, você ativa o conceito de escopo dentro do provedor. A Figura 3 fornece um exemplo dentro do método Initialize por meio da invocação de Logger.BeginScopeImpl.

O uso do padrão de registro em log ao aproveitar a ativação de escopo resultará em uma classe Program que pode ser semelhante à Figura 4.

Figura 4 - Uma implementação atualizada de Program

public class Program
{
  static ILogger Logger { get; } =
    ApplicationLogging.CreateLogger<Program>();
  public static void Main(string[] args = null)
  {
    ApplicationLogging.LoggerFactory.AddConsole(true);
    Logger.LogInformation(
      "This is a test of the emergency broadcast system.");
    using (Logger.BeginScopeImpl(nameof(Main)))
    {
      Logger.LogInformation("Begin using controller");
      Controller controller = new Controller();
      controller.Initialize();
      Logger.LogInformation("End using controller");
    }
    Logger.Log(LogLevel.Information, 0, "Shutting Down...", null, null);
  }
}

A saída da Figura 3 combinada à Figura 4 é mostrada na Figura 5.

Figura 5 - Saída de registro em log do console com escopos incluídos

info: SampleWebConsoleApp.Program[0]
      This is a test of the emergency broadcast system.
info: SampleWebConsoleApp.Program[0]
      => Main
      Begin using controller
info: SampleWebConsoleApp.Controller[0]
      => Main => Initialize
      Initialize the data
info: SampleWebConsoleApp.Controller[0]
      => Main => Initialize
      Initialize the UI
info: SampleWebConsoleApp.Program[0]
      => Main
      End using controller
info: SampleWebConsoleApp.Program[0]
      Shutting down...

Observe como o escopo é desenrolado automaticamente para deixar de incluir Initialize ou Main. Essa funcionalidade é fornecida pelo fato de que BeginScopeImpl retorna uma instância IDisposable que desenrola automaticamente o escopo quando a instrução using chama Dispose.

Como utilizar um provedor de terceiros

Para disponibilizar algumas das estruturas de registro em log de terceiros mais importantes, a Microsoft colaborou com seus desenvolvedores e assegurou que haja provedores para cada uma delas. Sem indicar uma preferência, considere como conectar a estrutura NLog, como demonstrado na Figura 6.

Figura 6 - Como configurar NLog como um provedor de Microsoft.Extensions.Logging

[TestClass]
public class NLogLoggingTests
{
  ILogger Logger {get;}
    = ApplicationLogging.CreateLogger<NLogLoggingTests>();
  [TestMethod]
  public void LogInformation_UsingMemoryTarget_LogMessageAppears()
  {
    // Add NLog provider
    ApplicationLogging.LoggerFactory.AddNLog(
      new global::NLog.LogFactory(
        global::NLog.LogManager.Configuration));
    // Configure target
    MemoryTarget target = new MemoryTarget();
    target.Layout = "${message}";
    global::NLog.Config.SimpleConfigurator.ConfigureForTargetLogging(
      target, global::NLog.LogLevel.Info);
    Logger.LogInformation(Message);
     Assert.AreEqual<string>(
      Message, target.Logs.FirstOrDefault<string>());
  }
}

A maior parte do código é bem conhecida por quem está familiarizado com NLog. Primeiro, instancio e configuro um alvo de NLog do tipo NLog.Targets.MemoryTarget. (Há numerosos alvos de NLog, e cada um deles pode ser identificado e configurado no arquivo de configuração de NLog, além de usar o código de configuração conforme mostrado na Figura 6.) Observe que, embora tenham aparência semelhante, é atribuído ao Layout um valor literal de ${message}, não um valor de cadeia de caracteres interpolada.

Após ser adicionado a LoggerFactory e configurado, o código é idêntico a qualquer outro código de provedor.

Manipulação de exceção

Naturalmente, uma das razões mais comuns para fazer o registro em log é gravar quando uma exceção é lançada, mais especificamente, quando a exceção está sendo manipulada em vez de relançada ou quando a exceção é inteiramente não manipulada (confira bit.ly/1LYGBVS). Como seria de se esperar, Microsoft.Extensions.Logging tem métodos específicos para manipular uma exceção. A maioria desses métodos é implementada em Microsoft.Extensions.Logging.LoggerExtensions como métodos de extensão para ILogger. É dessa classe que cada método específico para determinado nível de log (ILogger.LogInformation, ILogger.LogDebug, ILogger.LogCritical e assim por diante) é implementado. Por exemplo, para registrar em log uma mensagem LogLevel.Critical sobre uma exceção (talvez antes de desligar normalmente o aplicativo), você chamaria:

Logger.LogCritical(message,
  new InvalidOperationException("Yikes..."));

Outro aspecto importante do registro em log e da manipulação de exceções é que o registro em log, principalmente ao manipular exceções, não deve lançar uma exceção. Se uma exceção for lançada quando você fizer o registro em log, presumivelmente a mensagem ou a exceção nunca será gravada e poderá não ser notada, não importa quão crítica. Infelizmente, a implementação pronta para uso de ILogger (Microsoft.Extensions.Logging.Logger) não tem essa manipulação de exceções. Por isso, se ocorrer uma exceção, o código de chamada precisará manipulá-la e fazer isso sempre que Logger.LogX for chamado. Uma abordagem geral para resolver isso é possivelmente envolver ILogger, de modo a capturar a exceção. No entanto, convém implementar suas próprias versões de ILogger e ILoggerFactory (confira bit.ly/1LYHq0Q para obter um exemplo). Como o .NET Core é um software livre, você pode até mesmo clonar a classe e propositadamente implementar a manipulação de exceções em suas próprias implementações de LoggerFactory e ILogger.

Conclusão

Comecei perguntando: "Por que precisamos de mais uma estrutura de registro em log no .NET?" Espero que agora isso esteja claro. A nova estrutura cria uma camada de abstração ou wrapper que o habilita a usar qualquer estrutura de registro em log que você deseje como provedor. Isso lhe assegura o máximo de flexibilidade em seu trabalho como desenvolvedor. Além disso, embora só esteja disponível com o .NET Core, não é problema referenciar pacotes NuGet do .NET Core como Microsoft.Extensions.Logging para um projeto padrão do Visual Studio .NET 4.6.

Mark Michaelis é fundador da IntelliTect, onde atua como arquiteto técnico principal e instrutor. Há quase 20 anos trabalha como Microsoft MVP, e é Diretor Regional da Microsoft desde 2007. Michaelis atua em diversas equipes de análise de design de software da Microsoft, incluindo C#, Microsoft Azure, SharePoint e Visual Studio ALM. Ele dá palestras em conferências de desenvolvedores e escreveu diversos livros, incluindo o mais recente, "Essential C# 6.0 (5th Edition)" (itl.tc/­EssentialCSharp). Você pode entrar em contato com ele pelo Facebook, em facebook.com/Mark.Michaelis, pelo seu blog, em IntelliTect.com/Mark, no Twitter, em @markmichaelis, ou por email, em mark@IntelliTect.com.

Agradecemos aos seguintes especialistas técnicos da IntelliTect pela revisão deste artigo: Kevin Bost, Chris Finlayson e Michael Stokesbary