Problema de archivo bloqueado intermitente log4net RollingFileAppender


Estamos viendo un problema intermitente en las máquinas de desarrollo y producción por el cual nuestros archivos de registro no se registran.

Cuando se ejecuta en desarrollo y depuración usando Visual Studio, obtenemos los siguientes mensajes de error de log4net en la ventana VS output:

log4net:ERROR [RollingFileAppender] Unable to acquire lock on file C:\folder\file.log.

El proceso no puede acceder al archivo 'C:\folder\file.log ' porque está siendo utilizado por otro proceso.

log4net:ERROR XmlConfigurator: Failed to find configuration section 'log4net' in the application's .config file.
Check your .config file for the <log4net> and <configSections> elements.

La sección de configuración debería tener el siguiente aspecto:

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

Nuestra solución actual para el problema es cambiar el nombre del último archivo de registro. Por supuesto, esperaríamos que esto fallara (debido al bloqueo de archivos mencionado anteriormente), pero normalmente no lo hace. Una o dos veces el cambio de nombre ha fallado debido a un bloqueo desde el aspnet_wp.proceso exe .

Nuestra sección de configuración de log4net se muestra a continuación:

<log4net>
  <appender name="RollingLogFileAppender" type="log4net.Appender.RollingFileAppender">
    <file value="C:\folder\file.log"/>
    <appendToFile value="true" />
    <datePattern value="yyyyMMdd" />
    <rollingStyle value="Date" />
    <maximumFileSize value="10MB" />
    <maxSizeRollBackups value="100" />
    <layout type="log4net.Layout.PatternLayout">
      <header value="[Header]&#xA;"/>
      <footer value="[Footer]&#xA;"/>
      <conversionPattern value="%date %-5level %logger ${COMPUTERNAME} %property{UserHostAddress} [%property{SessionID}] - %message%newline"/>
    </layout>
  </appender>
  <root>
    <level value="INFO"/>
    <appender-ref ref="RollingLogFileAppender"/>
  </root>
</log4net>

Como se mencionó, estamos viendo esto intermitentemente en las máquinas, pero una vez que ocurre el problema persiste.

Author: Mark, 2010-01-04

3 answers

Intenta agregar

<lockingModel type="log4net.Appender.FileAppender+MinimalLock" />

A tu elemento <appender />. Hay cierto impacto en el rendimiento porque esto significa que log4net bloqueará el archivo, escribirá en él y lo desbloqueará para cada operación de escritura (a diferencia del comportamiento predeterminado, que adquiere y mantiene el bloqueo durante mucho tiempo).

Una implicación del comportamiento predeterminado es que si lo está utilizando en un sitio web que se está ejecutando en varios procesos de trabajo que se ejecutan en la misma máquina, cada uno intentará adquirir y sostenga esa cerradura indefinidamente, y dos de ellos van a perder. Cambiar el modelo de bloqueo al bloqueo mínimo soluciona este problema.

(Al depurar, terminaciones ingratas y girar muchos procesos de trabajo nuevos es exactamente el tipo de cosa que es probable que suceda.)

¡Buena suerte!

 151
Author: Nicholas Piasecki,
Warning: date(): Invalid date.timezone value 'Europe/Kyiv', we selected the timezone 'UTC' for now. in /var/www/agent_stack/data/www/ajaxhispano.com/template/agent.layouts/content.php on line 61
2010-01-04 13:12:15

También tenga en cuenta el log4net FAQ :

¿Cómo puedo hacer que varios procesos se registren en el mismo archivo?

Antes de empezar a probar cualquiera de las alternativas proporcionadas, pregunte si realmente necesita tener varios procesos de registro en el el mismo archivo, entonces no lo hagas ;-).

FileAppender ofrece modelos de bloqueo enchufables para este caso de uso, pero todos las implementaciones existentes tienen problemas e inconvenientes.

Por defecto el FileAppender mantiene un bloqueo de escritura exclusivo en el registro archivo mientras está registrando. Esto evita que otros procesos escriban al archivo. Este modelo es conocido por romper con (al menos en algunos versiones de) Mono en Linux y los archivos de registro pueden corromperse tan pronto como otro proceso intenta acceder al archivo de registro.

MinimalLock solo adquiere el bloqueo de escritura mientras se escribe un registro. Esto permite que varios procesos intercalen las escrituras en el mismo archivo, aunque con un considerable pérdida de rendimiento.

InterProcessLock no bloquea el archivo en absoluto, sino que se sincroniza mutex en todo el sistema. Esto solo funcionará si todos los procesos cooperan (y utilice el mismo modelo de bloqueo). La adquisición y liberación de un Mutex por cada entrada de registro que se escribirá resultará en una pérdida de rendimiento, pero el Mutex es preferible al uso de MinimalLock.

Si utiliza RollingFileAppender las cosas se vuelven aún peor como varios proceso puede intentar comenzar a rodar el archivo de registro simultáneamente. RollingFileAppender ignora completamente el modelo de bloqueo al rodar archivos, archivos rodantes simplemente no es compatible con este escenario.

Una mejor alternativa es tener sus procesos de registro a Servidores remotos. Usando el RemoteLoggingServerPlugin (o IRemoteLoggingSink) un proceso puede recibir todos los eventos y registrarlos a un único archivo de registro. Uno de los ejemplos muestra cómo utilizar el RemoteLoggingServerPlugin.

 29
Author: Ciprian Teiosanu,
Warning: date(): Invalid date.timezone value 'Europe/Kyiv', we selected the timezone 'UTC' for now. in /var/www/agent_stack/data/www/ajaxhispano.com/template/agent.layouts/content.php on line 61
2013-06-06 15:30:54

Si tiene

<staticLogFileName value="true" />
<rollingStyle value="Date" />
<datePattern value="yyyyMMdd" />

Y añadir

<lockingModel type="log4net.Appender.FileAppender+MinimalLock" />

Entonces habrá un error mientras ocurre el balanceo. El primer proceso creará el nuevo archivo y renombrará el archivo actual. Luego, el siguiente proceso hará lo mismo y tomará el archivo recién creado y sobrescribirá el archivo recién renombrado. El logfiel del último día está vacío.

 6
Author: Jonte,
Warning: date(): Invalid date.timezone value 'Europe/Kyiv', we selected the timezone 'UTC' for now. in /var/www/agent_stack/data/www/ajaxhispano.com/template/agent.layouts/content.php on line 61
2010-12-20 10:45:09