logging - structured - Log4Net RollingFileAppender no descarga el búfer de IO con registro de bajo volumen

log4net structured logging

Question

Estoy reflexionando sobre el mismo problema que hizo HENRI COOK . Ha sido reportado como un error en Apache Jira por lo que podemos ver en la breve descripción.

Mi problema en esencia es que los eventos solo se registran cuando la aplicación se apaga (incluso semanas después del evento). Eso sucede cuando el volumen de registro es muy bajo. Estoy viendo esto en un Windows Server 2008 R2. Esto nos impide capturar y reaccionar a los errores de producción.

Ahora el appender no es un buffering. Por defecto también llama a Flush () en la transmisión subyacente cada vez que se agrega un mensaje.

Mi pregunta es ¿POR QUÉ no se está sonrojando? ¿Y hay algún remedio aparte de descargar programáticamente a todos los appenders ? ¿Consideraría un appender pulsante una solución viable?

La configuración del appender:

<appender name="RollingErrorFileAppender" type="log4net.Appender.RollingFileAppender">
  <param name="File" value="D:/LogFiles/zzzz/xxxxxx__ERROR" />
  <param name="AppendToFile" value="true" />
  <param name="DatePattern" value="_yyyyMMddHH&quot;.log&quot;" />
  <param name="RollingStyle" value="Date" />
  <param name="StaticLogFileName" value="false" />
  <filter type="log4net.Filter.LevelRangeFilter">
    <param name="LevelMin" value="ERROR" />
    <param name="LevelMax" value="FATAL" />
  </filter>
  <layout type="log4net.Layout.PatternLayout">
    <param name="ConversionPattern" value="%utcdate{yyyy-MM-dd HH:mm:ss.fff},[%thread],%level,%logger,%m%n"/>
  </layout>
</appender>

ACTUALIZACIÓN 2013-06-19

No he podido reproducir el comportamiento con ningún código. No importa lo mal que lo intente, los datos siempre se escriben en el disco de inmediato. Sin embargo, se realizó una observación importante: si la primera escritura en un archivo es mayor que 1KiB, la hora modificada nunca se actualiza con escrituras subsiguientes. Solo se actualizará cuando el archivo se cierre con la hora de cierre. Si, por otro lado, la primera escritura es una línea corta, cualquier escritura subsiguiente actualizará la hora modificada. Este comportamiento es consistente entre log4net y la operación manual de E / S, entre 32bit WinXP y 64bit W2k8R2, entre .NET 2.0, 3.5 y .NET 4.0. Eso no resuelve el problema, pero al menos ahora puedo entender el extraño patrón de modificación del tiempo.

Gracias, Rob

Answer 1

Como solo está preocupado por el nivel de error o por eventos de registro peores, y ese tráfico es afortunadamente infrecuente, le sugiero que configure su appender para que se descargue inmediatamente.

<param name="ImmediateFlush" value="true" />

Esto le ahorra tener que vaciar programáticamente su appender en cada evento de registro (que no funcionaba por el sonido). Ahora, si desea abrir su appender a más niveles de registro, entonces, por supuesto, enjuagar inmediatamente todos los eventos podría tener un mayor problema de rendimiento.

EDITAR

Agregué el archivo de configuración y un programa principal simple que utilicé para probar. Utilizando lo siguiente, veo que los eventos de registro se vacían inmediatamente. Con respecto a su comentario, también puedo quitar la línea ImmediateFlush del xml y ver que el valor true predeterminado funciona para el lavado. Mantuve la línea en mi ejemplo a los efectos de indicar explícitamente el comportamiento deseado.

Prog principal básico:

class Program
{
    static void Main(string[] args)
    {
        ILog log = LogManager.GetLogger(typeof(Program));
        XmlConfigurator.Configure(new FileInfo(@"C:/temp/logTest.config"));

        string msg;
        while ((msg = Console.ReadLine()) != "Done")
        {
            log.Error(msg);
        }

        LogManager.Shutdown();
    }
}

logTest.config al que hace referencia el programa principal:

<log4net>
    <appender name="RollingErrorFileAppender" type="log4net.Appender.RollingFileAppender">
        <param name="File" value="C:/temp/log" />
        <param name="AppendToFile" value="true" />
        <param name="DatePattern" value="_yyyyMMddHH&quot;.log&quot;" />
        <param name="RollingStyle" value="Date" />
        <param name="StaticLogFileName" value="false" />
        <param name="ImmediateFlush" value="true" />
        <filter type="log4net.Filter.LevelRangeFilter">
            <param name="LevelMin" value="ERROR" />
            <param name="LevelMax" value="FATAL" />
        </filter>
        <layout type="log4net.Layout.PatternLayout">
            <param name="ConversionPattern" value="%utcdate{yyyy-MM-dd HH:mm:ss.fff},[%thread],%level,%logger,%m%n"/>
        </layout>
    </appender>
    <root>
        <level value="INFO" />
        <appender-ref ref="RollingErrorFileAppender" />
    </root>
</log4net>