Problème intermittent de verrouillage des fichiers de log4net RollingFileAppender

Question

Nous constatons un problème intermittent sur les machines de développement et de production où nos fichiers journaux ne sont pas enregistrés.

Lors de l'exécution en développement et du débogage avec Visual Studio, nous obtenons les messages d'erreur log4net suivants dans la fenêtre de sortie VS :

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

Le processus ne peut pas accéder au fichier ' C:\folder\file.log car il est utilisé par un autre processus.

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 section de configuration devrait ressembler à ceci :

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

Notre solution actuelle pour résoudre ce problème consiste à renommer le dernier fichier journal. Nous nous attendons bien sûr à ce que cette opération échoue (en raison du verrouillage de fichier susmentionné), mais ce n'est généralement pas le cas. Une ou deux fois, le renommage a échoué à cause d'un verrouillage de l'application aspnet_wp.exe processus.

Notre section de configuration de log4net est présentée ci-dessous :

<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>

Comme nous l'avons mentionné, nous constatons ce problème par intermittence sur les machines, mais une fois que le problème se produit, il persiste.

Answer 1

Essayez d'ajouter

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

à votre <appender /> élément. Il y a un certain impact sur les performances car cela signifie que log4net verrouillera le fichier, y écrira et le déverrouillera pour chaque opération d'écriture (par opposition au comportement par défaut, qui acquiert et conserve le verrou pendant une longue période).

L'une des conséquences du comportement par défaut est que si vous l'utilisez dans le cadre d'un site Web exécuté par plusieurs processus de travail tournant sur la même machine, chacun d'entre eux essaiera d'acquérir et de conserver ce verrou indéfiniment, et deux d'entre eux seront perdants. La modification du modèle de verrouillage en un verrou minimal permet de contourner ce problème.

(Lors du débogage, les terminaisons non gracieuses et le lancement de nombreux nouveaux processus de travail sont exactement le type de choses qui sont susceptibles de se produire).

Bonne chance !

Answer 2

Soyez également conscient de la log4net FAQ :

Comment faire pour que plusieurs processus soient enregistrés dans le même fichier ?

Avant même de commencer à essayer l'une des alternatives proposées, demandez-vous demandez-vous si vous avez vraiment besoin que plusieurs processus se connectent au même fichier, puis ne le faites pas ;-).

FileAppender offre des modèles de verrouillage enfichables pour ce cas d'utilisation mais toutes les implémentations existantes présentent des problèmes et des inconvénients.

Par défaut, le FileAppender détient un verrou exclusif en écriture sur le fichier pendant la journalisation. Cela empêche les autres processus d'écrire dans le fichier. Ce modèle est connu pour tomber en panne avec (au moins sur certaines versions de) Mono sur Linux et les fichiers journaux peuvent être corrompus dès que dès qu'un autre processus tente d'accéder au fichier journal.

MinimalLock n'acquiert le verrou d'écriture que pendant l'écriture d'un journal. Cela permet à plusieurs processus d'intercaler les écritures dans le même fichier, mais avec une perte considérable de performance.

InterProcessLock ne verrouille pas le fichier du tout mais synchronise en utilisant un Mutex à l'échelle du système. Cela ne fonctionnera que si tous les processus coopèrent (et utilisent le même modèle de verrouillage). L'acquisition et la libération d'un Mutex pour chaque entrée de journal à écrire entraînera une perte de performance, mais le Mutex est préférable à l'utilisation de MinimalLock.

Si vous utilisez RollingFileAppender les choses deviennent encore pires car plusieurs processus peuvent essayer de faire rouler le fichier journal en même temps. RollingFileAppender ignore complètement le modèle de verrouillage lors du roulement des fichiers. rolling files, le rolling files n'est tout simplement pas compatible avec ce scénario.

Une meilleure alternative est de faire en sorte que vos processus se connectent à RemotingAppenders. En utilisant le RemoteLoggingServerPlugin (ou IRemoteLoggingSink) un processus peut recevoir tous les événements et les enregistrer dans un seul fichier journal. L'un des exemples montre comment utiliser le RemoteLoggingServerPlugin.

Answer 3

Si vous avez

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

et ajouter

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

alors il y aura une erreur pendant que le roulement se produit. Le premier processus va créer le nouveau fichier et renommer le fichier actuel. Ensuite, le processus suivant fera de même et prendra le fichier nouvellement créé et écrasera le fichier nouvellement renommé. Le résultat est que le fichier journal du dernier jour est vide.