Log4Net en Microsoft Azure Cloud Services: Centralizando logs

En el año 2011 estuve hablando de log4net como herramienta de trazado de aplicaciones .NET. Lo cierto es que a día de hoy muchos desarrolladores lo siguen utilizando y puede parecer un impedimento a la hora de migrar las aplicaciones al cloud, debido a la escalabilidad. ¿Os imagináis si tuvieramos que ir accediendo instancia por instancia (imaginemos 200) para procesar el archivo generado?

En este post os voy a mostrar cómo combinar log4net con Microsoft Azure Diagnostics (hace tiempo también traté esta librería en detalle).

log4net

He creado una aplicación en Web Forms y a través de Nuget he instalado el paquete de log4net:

PM> Install-Package log4net

Para almacenar el resultado de las trazas, voy a hacer uso del local storage de las máquinas virtuales que alojan la aplicación. Para ello, en la configuración del rol accedemos al apartado Local Storage y creamos una sección llamada MyLogs:

Local Storage MyLogs

El siguiente paso es definir en el archivo de configuración el tipo de traza que vamos a hacer y dónde se va a almacenar. Para ello, vamos a crear primero un nueva clase llamada AzureAppender que hereda de RollingFileAppender para tener las mismas propiedades y comportamiento que FileAppender.

using log4net.Appender;
using Microsoft.WindowsAzure.ServiceRuntime;
using System;
using System.Collections.Generic;
using System.Diagnostics;
using System.IO;
using System.Linq;
using System.Web;

namespace WebApplicationLog4NetAzure
{
    public class AzureAppender : RollingFileAppender
    {
        public override string File
        {
            set
            {
                base.File = RoleEnvironment.GetLocalResource("MyLogs").RootPath + @"\" + new FileInfo(value).Name;
            }

        }
    }
}

Como se puede ver en el código anterior, lo que hacemos es sobreescribir la propiedad File para poder ubicar el archivo generado en el apartado de local storage que acabamos de definir.

Una vez creado este nuevo appender, podemos añadir la sección de log4net en el archivo de configuración de la aplicación:

<?xml version="1.0" encoding="utf-8" ?>
<configuration>
  <configSections>
    <section name="log4net" type="log4net.Config.Log4NetConfigurationSectionHandler, log4net" />
  </configSections>
  <log4net>
    <logger name="FileText">
      <level value="INFO" />
      <appender-ref ref="FileAppender" />
    </logger>
    <appender name="FileAppender" type="WebApplicationLog4NetAzure.AzureAppender">
      <file value="workerrole_log.txt" />
      <appendToFile value="true" />
      <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%date [%thread] %-5level %logger - %message%newline" />
      </layout>
    </appender>
  </log4net>
</configuration>

Se define dentro del apartado configSections la sección de log4net y añadimos la misma dentro de configuration. Creamos un nuevo logger llamado FileText, el cual usa como appender FileAppender que es del tipo WebApplicationLog4NetAzure.AzureAppender, y dentro del mismo le indicamos el nombre del archivo (workerrole_log.txt). Utilizamos además otros valores para que se añada la información (y no sobreescriba) y el patrón que queremos que sigan los mensajes.

A partir de este momento, podemos hacer uso de log4net en nuestra aplicación a demanda:

        protected void btnLog_Click(object sender, EventArgs e)
        {
            ILog Logger = LogManager.GetLogger("FileText");
            XmlConfigurator.Configure();
                      
            Logger.Info("Log from btnLog_Click");
        }

O bien de forma automática (como ocurre por ejemplo en un worker role):

        public override void Run()
        {
            //log4net configuration
            ILog Logger = LogManager.GetLogger("FileText");
            XmlConfigurator.Configure();

            // This is a sample worker implementation. Replace with your logic.
            Logger.Info("WorkerRoleLog4net entry point called");

            while (true)
            {
                Thread.Sleep(10000);
                Logger.Info("Logging from Worker role");
            }
        }

Con esta configuración, los archivos generados a consecuencia de las trazas que se hayan ido ejecutando quedarán almacenados en local en cada una de las máquinas que ejecuten la solución.

Centralizar los logs de las instancias

El paso final es conseguir que la información generada por cada una de las máquinas virtuales se ubiquen en un mismo sitio, con el objetivo de que sea más fácil su procesamiento. Para ello, modificaremos la configuración por defecto de la parte de Diagnostics de Azure de la siguiente manera:

        public override bool OnStart()
        {
            // Set the maximum number of concurrent connections 
            ServicePointManager.DefaultConnectionLimit = 12;

            // For information on handling configuration changes
            // see the MSDN topic at http://go.microsoft.com/fwlink/?LinkId=166357.

            var logDir = new DirectoryConfiguration
            {
                Container = "wad-log4net",
                DirectoryQuotaInMB = 200,
                Path = RoleEnvironment.GetLocalResource("MyLogs").RootPath
            };

            var config = DiagnosticMonitor.GetDefaultInitialConfiguration();
            config.Directories.DataSources.Add(logDir);

            config.Directories.ScheduledTransferPeriod = TimeSpan.FromMinutes(1);

            DiagnosticMonitor.Start("Microsoft.WindowsAzure.Plugins.Diagnostics.ConnectionString", config);

            return base.OnStart();
        }

En el método OnStart de la clase que hereda de RoleEntryPoint (llamada WebRole o WorkerRole por defecto), creamos una instancia del tipo DirectoryConfiguration donde le indicamos el nombre del contenedor donde queremos que se almacenen los logs, cuota del directorio y el path donde está el contenido que queremos transferir.
Recuperamos la configuración por defecto de la instancia y agregamos dentro del apartado Directories esta nueva configuración. Es importante especificar cada cuánto tiempo queremos que se realice la transferencia del contenido, ya que de otra forma no se hará efectiva esta configuración.

Por último utilizamos DiagnosticMonitor.Start para inyectar la nueva configuración.

Por defecto, todo proyecto de Azure tiene definida una propiedad llamada Microsoft.WindowsAzure.Plugins.Diagnostics.ConnectionString dedicada exclusivamente a los diagnósticos. Cuando trabajamos en local, por defecto apunta al emulador, lo cual es perfecto para comprobar que todo funciona correctamente.

Antes era muy importante recordar cambiar dicha cadena de conexión antes de realizar la subida. Sin embargo, ahora por defecto tenemos una opción dentro de la configuración, habilitada por defecto, que se encarga de ello por nosotros ;)

Update development storage when publishing

El resultado de la recolección de logs podemos verlo, por ejemplo, directamente desde el portal de Azure (en este ejemplo se simulan 8 instancias):

logs Diagnostics portal Azure

Si nos fijamos en la imagen anterior, vemos que cada archivo está contenido dentro de un directorio virtual con el nombre y el número de la instancia a la que corresponde.

Espero que sea de utilidad.

¡Saludos!

Log4net: trazando nuestras aplicaciones

En ocasiones es importante almacenar un registro con información sobre los procesos realizados, principalmente en el entorno de desarrollo. Otra de las necesidades comunes puede ser recibir un correo cuando una acción finaliza correcta y/o incorrectamente o simplemente mantener un registro de un determinado nivel de información. Log4net cubre todas estas necesidades por nosotros de una forma altamente configurable :D

Esta librería es fruto de su antecesora log4j (log for Java) la cual ha derivado para diferentes lenguajes como C++, PHP y por supuesto .NET.

Configuración

Toda la configuración de la librería puede estar incluida en el archivo de configuración o programáticamente. Personalmente pienso que la configuración debe estar contenida en los archivos que tienen ese fin :)

<configSections>
   <section name="log4net" type="log4net.Config.Log4NetConfigurationSectionHandler, log4net" />
</configSections>

Una vez que tenemos definida la sección en configSections, personalizamos un apartado con la configuración para nuestras trazas. En este post mostraré una configuración para mostrar las mismas a través de la consola y por email.

<log4net>
    <logger name="Program">
      <level value="INFO" />
      <appender-ref ref="ConsoleAppender" />
    </logger>
    <logger name="ProductosRepository">
      <level value="WARN" />
      <appender-ref ref="SmtpAppender" />
    </logger>
    <appender name="ConsoleAppender" type="log4net.Appender.ConsoleAppender" >
      <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%date [%thread] %-5level %logger - %message%newline" />
      </layout>
    </appender>
    <appender name="SmtpAppender" type="log4net.Appender.SmtpAppender,log4net">
      <to value="destinatario@returngis.net" />
      <from value="remitente@returngis.net" />
      <subject value="Asunto del correo" />
      <smtpHost value="smtp.returngis.net" />
      <bufferSize value="512" />
      <lossy value="true" />
      <evaluator type="log4net.Core.LevelEvaluator,log4net">
        <threshold value="ERROR" />
      </evaluator>
      <layout type="log4net.Layout.PatternLayout,log4net">
        <conversionPattern value="%property{log4net:HostName} :: %level :: %message %newlineLogger: %logger%newlineThread: %thread%newlineDate: %date%newlineNDC: %newline%newline" />
      </layout>
    </appender>
</log4net>

Si nos fijamos en la configuración expuesta, vemos que tenemos en realidad dos apartados repetidos: logger y appender.

Elemento logger

Este elemento define la configuración para ser utilizada en un apartado específico de nuestro código. Me explico: Supongamos que queremos mostrar información por pantalla de los pasos que se van completando en una capa de nuestra aplicación, para saber qué parte de nuestro código se está ejecutando. Por otro lado, necesitamos recibir un email cada vez que en la lógica relacionada con la base de datos o los servicios se produzca un error. Gracias a este apartado, podemos definir diferentes configuraciones para poder usarlas conjuntamente en una misma aplicación. Como parámetros tenemos el nivel de información que queremos registrar y el tipo de salida (appender).

 El nivel de error es acumulativo, es decir, si nuestro nivel de error es de tipo INFO abarcará los niveles información, warnings, errores y errores fatales. Si por el contrario el nivel establecido es ERROR, este sólo cubrirá los errores y los errores fatales. Por lo tanto, el modo que habilita todos los niveles sería el modo DEBUG.

Elemento appender

Por otro lado, los appenders son los tipos de salida que podemos configurar. En este post voy a mostrar solamente la salida por consola y por SMTP para el envío de correos. Para más ejemplos sobre otros tipos podéis echar un vistazo a este enlace.

Como valores significativos podemos mencionar:

 Pattern.Layout para definir información a mostrar a través de patrones. En el caso del ConsoleAppender que tenemos definido en el ejemplo la información sería mostrada de la siguiente forma:

Lossy se utiliza de forma conjunta con el elemento evaluator para evitar el consumo excesivo de recursos en producción cuando la ejecución de nuestro programa es normal. Sin embargo, si la aplicación registra un error registrará esta información con un pequeño batch de lo ocurrido momentos antes de la excepción :)

Los appenders que soportan esta opción son los siguientes:

  • log4net.Appender.AdoNetAppender
  • log4net.Appender.RemotingAppender
  • log4net.Appender.SmtpAppender
  • log4net.Appender.SmtpPickupDirAppender
  • log4net.Appender.BufferingForwardingAppender

Recuperar la configuración

Como comenté en el apartado anterior, dependiendo del cuál queramos que sea el nivel y el tipo de salida, debemos solicitar una configuración u otra a la hora de la creación de nuestro objeto del tipo ILog. A través del mismo podremos registrar las trazas necesarias. En este caso, he utilizado el nombre de la clase en la que me encuentro para dar nombre a los distintos apartados, pero podríamos utilizar, por ejemplo, el nombre del proyecto o cualquier otro nombre significativo.

private static readonly ILog Logger = LogManager.GetLogger(typeof(Program).Name);

El siguiente paso sería cargar la configuración desde el archivo de configuración, a través del siguiente método:

XmlConfigurator.Configure();

A partir de este momento estamos listos para comenzar a trazar nuestro código :D Para ello, basta con utilizar el objeto logger creado anteriormente de manera bastante similar a Trace.

Logger.Info("Retrieving files...");

Del mismo modo, podemos formatear strings:

Logger.ErrorFormat("{0}:{1}", ex.InnerException, ex.StackTrace);

Espero que sea de utilidad :)

¡Saludos!