c# - net - ¿Cómo Thread-Safe es NLog?

nlog levels

Question

Bien,

He esperado días antes de decidir publicar este problema, ya que no estaba seguro de cómo expresarlo, y me detuve en una publicación larga y detallada. Sin embargo, creo que es relevante pedir la ayuda de la comunidad en este momento.

Básicamente, intenté usar NLog para configurar registradores para cientos de subprocesos. Pensé que esto sería muy sencillo, pero obtuve esta excepción después de algunas decenas de segundos: " InvalidOperationException: la colección se modificó, la operación de enumeración no se puede ejecutar "

Aquí está el código.

//Launches threads that initiate loggers
class ThreadManager
{
    //(...)
    for (int i = 0; i<500; i++)
    {
        myWorker wk = new myWorker();
        wk.RunWorkerAsync();
    }

    internal class myWorker : : BackgroundWorker
    {             
       protected override void OnDoWork(DoWorkEventArgs e)
       {              
           // "Logging" is Not static - Just to eliminate this possibility 
           // as an error culprit
           Logging L = new Logging(); 
           //myRandomID is a random 12 characters sequence
           //iLog Method is detailed below
          Logger log = L.iLog(myRandomID);
          base.OnDoWork(e);
       }
    }
}

public class Logging
{   
        //ALL THis METHOD IS VERY BASIC NLOG SETTING - JUST FOR THE RECORD
        public Logger iLog(string loggerID)
        {
        LoggingConfiguration config;
        Logger logger;
        FileTarget FileTarget;            
        LoggingRule Rule; 

        FileTarget = new FileTarget();
        FileTarget.DeleteOldFileOnStartup = false;
        FileTarget.FileName =  "X://" + loggerID + ".log";

        AsyncTargetWrapper asyncWrapper = new AsyncTargetWrapper();
        asyncWrapper.QueueLimit = 5000;
        asyncWrapper.OverflowAction = AsyncTargetWrapperOverflowAction.Discard;
        asyncWrapper.WrappedTarget = FileTarget;

        //config = new LoggingConfiguration(); //Tried to Fool NLog by this trick - bad idea as the LogManager need to keep track of all config content (which seems to cause my problem;               
        config = LogManager.Configuration;                
        config.AddTarget("File", asyncWrapper);                
        Rule = new LoggingRule(loggerID, LogLevel.Info, FileTarget);

        lock (LogManager.Configuration.LoggingRules)
            config.LoggingRules.Add(Rule);                

        LogManager.Configuration = config;
        logger = LogManager.GetLogger(loggerID);

        return logger;
    }
}   

Así que hice mi trabajo y no solo publicando mi pregunta aquí y teniendo un tiempo de calidad familiar, pasé el fin de semana investigando sobre eso (¡Lucky Boy!) Descargué el último lanzamiento estable de NLOG 2.0 y lo incluí en mi proyecto. Pude rastrear el lugar exacto donde explotó:

en LogFactory.cs:

    internal void GetTargetsByLevelForLogger(string name, IList<LoggingRule> rules, TargetWithFilterChain[] targetsByLevel, TargetWithFilterChain[] lastTargetsByLevel)
    {
        //lock (rules)//<--Adding this does not fix it
            foreach (LoggingRule rule in rules)//<-- BLOWS HERE
            {
            }
     }

en LoggingConfiguration.cs:

internal void FlushAllTargets(AsyncContinuation asyncContinuation)
    {            
        var uniqueTargets = new List<Target>();
        //lock (LoggingRules)//<--Adding this does not fix it
        foreach (var rule in this.LoggingRules)//<-- BLOWS HERE
        {
        }
     }

El problema según yo
Entonces, según tengo entendido, lo que sucede es que el LogManager se confunde ya que hay llamadas a config.LoggingRules.Add (Rule) desde diferentes subprocesos mientras GetTargetsByLevelForLogger y FlushAllTargets están siendo llamados. Traté de atornillar el foreach y reemplazarlo por un bucle for, pero el registrador se volvió pícaro (omitiendo la creación de muchos archivos de registro)

SOoooo FINALMENTE
Está escrito en todas partes que NLOG es seguro para subprocesos, pero he llegado a través de algunas publicaciones que profundizan más y afirman que esto depende del escenario de utilización. ¿Qué hay de mi caso? Tengo que crear miles de registradores (no todos al mismo tiempo, pero aún a un ritmo muy alto).

La solución que he encontrado es crear todos los registradores en SAME MASTER THREAD; esto es REALMENTE poco convencional, ya que creo todos mis registradores de aplicaciones al inicio de la aplicación (una especie de grupo de registradores). Y aunque funciona dulce, simplemente NO es un diseño aceptable.

Entonces lo sabes todo, amigos. Por favor, ayuda a un codificador a ver a su familia de nuevo.

Answer 1

Al enumerar una copia de la colección puede resolver este problema. Hice el siguiente cambio a la fuente NLog y parece solucionar el problema:

internal void GetTargetsByLevelForLogger(string name, IList<LoggingRule> rules, TargetWithFilterChain[] targetsByLevel, TargetWithFilterChain[] lastTargetsByLevel)
{
   foreach (LoggingRule rule in rules.ToList<LoggingRule>())
   {
   ... 

Answer 2

Creo que es posible que no estés usando el lock correctamente. Estás bloqueando objetos que se pasan a tu método, así que creo que esto significa que diferentes hilos pueden bloquearse en diferentes objetos.

La mayoría de las personas solo agrega esto a su clase:

private static readonly object Lock = new object();

Luego, asegúrate de eso y ten la garantía de que siempre será el mismo objeto.

No estoy seguro de que esto solucione tu problema, pero lo que estás haciendo ahora me resulta extraño. Otras personas podrían estar en desacuerdo.

Answer 3

No sé NLog, pero por lo que puedo ver en las piezas anteriores y en los documentos de API (http://nlog-project.org/help/), solo hay una configuración estática. Por lo tanto, si desea utilizar este método para agregar reglas a la configuración solo cuando se crea el registrador (cada una de un hilo diferente), está editando el mismo objeto de configuración. Por lo que puedo ver en los documentos NLog, no hay forma de usar una configuración separada para cada registrador, por eso es que necesita todas las reglas.

La mejor manera de agregar las reglas sería agregar las reglas antes de iniciar los trabajadores de sincronización, pero supongo que eso no es lo que desea.

También sería posible usar solo un registrador para todos los trabajadores. Pero supongo que necesita a cada trabajador en un archivo separado.

Si cada hilo está creando su propio registrador y agrega sus propias reglas a la configuración, deberá cerrarlo. Tenga en cuenta que incluso sincronizando su código, existe la posibilidad de que algún otro código enumere las reglas mientras las está modificando. Como muestra, NLog no bloquea estos bits de código. Por lo tanto, supongo que cualquier reclamo seguro para subprocesos es solo para los métodos reales de escritura de registro.

No estoy seguro de lo que hace tu bloqueo actual, pero no creo que esté haciendo lo que pretendías. Entonces, cambie

...
lock (LogManager.Configuration.LoggingRules)
config.LoggingRules.Add(Rule);                

LogManager.Configuration = config;
logger = LogManager.GetLogger(loggerID);

return logger;

a

...
lock(privateConfigLock){
    LogManager.Configuration.LoggingRules.Add(Rule);                

    logger = LogManager.GetLogger(loggerID);
}
return logger;

Tenga en cuenta que se considera una buena práctica bloquear solo objetos que usted posee, es decir, que sean privados para su clase. Esto evita que alguna clase en algún otro código (que no se adhiere a las mejores prácticas) se bloquee en el mismo código que puede crear un interbloqueo. Por lo tanto, debemos definir privateConfigLock como privado para su clase. También deberíamos hacerlo estático, para que cada hilo vea la misma referencia de objeto, así:

public class Logging{
    // object used to synchronize the addition of config rules and logger creation
    private static readonly object privateConfigLock = new object();
...

Answer 4

Realmente no tengo una respuesta a su problema, pero tengo algunas observaciones y algunas preguntas:

De acuerdo con su código, parece que desea crear un registrador por subproceso y desea tener ese registro de registrador en un archivo llamado para algún valor de Id. Transferido. Por lo tanto, el registrador cuyo id. Es "abc" registraría en "x: / abc.log", "def" se registraría en "x: / def.log", y así sucesivamente. Sospecho que puede hacer esto a través de la configuración de NLog en lugar de programáticamente. No sé si funcionaría mejor, o si NLog tendría el mismo problema que tú.

Mi primera impresión es que estás haciendo un montón de trabajo: creando un objetivo de archivo por subproceso, creando una nueva regla por subproceso, obteniendo una nueva instancia de registrador, etc., que quizás no necesites hacer para lograr lo que parece que quieres cumplir.

Sé que NLog permite que el archivo de salida tenga un nombre dinámico, en función de al menos algunos de los NLog LayoutRenderers. Por ejemplo, sé que esto funciona:

fileName="${level}.log"

y le dará nombres de archivos como este:

Trace.log
Debug.log
Info.log
Warn.log
Error.log
Fatal.log

Entonces, por ejemplo, parece que podría usar un patrón como este para crear archivos de salida basados ​​en el id. Del subproceso:

fileName="${threadid}.log"

Y si termina teniendo los hilos 101 y 102, entonces tendría dos archivos de registro: 101.log y 102.log.

En su caso, quiere nombrar el archivo según su propia identificación. Puede almacenar la identificación en el MappedDiagnosticContext (que es un diccionario que le permite almacenar pares de nombre-valor locales) y luego hacer referencia a eso en su patrón.

Su patrón para su nombre de archivo se vería así:

fileName="${mdc:myid}.log"

Entonces, en tu código puedes hacer esto:

         public class ThreadManager
         {
           //Get one logger per type.
           private static readonly Logger logger = LogManager.GetCurrentClassLogger();

           protected override void OnDoWork(DoWorkEventArgs e)
           {
             // Set the desired id into the thread context
             NLog.MappedDiagnosticsContext.Set("myid", myRandomID);

             logger.Info("Hello from thread {0}, myid {1}", Thread.CurrentThread.ManagedThreadId, myRandomID);
             base.OnDoWork(e);  

             //Clear out the random id when the thread work is finished.
             NLog.MappedDiagnosticsContext.Remove("myid");
           }
         }

Algo como esto debería permitirle a su clase ThreadManager tener un único registrador llamado "ThreadManager". Cada vez que registra un mensaje, registrará la cadena formateada en la llamada de información. Si el registrador está configurado para iniciar sesión en el destino de archivo (en el archivo de configuración, cree una regla que envíe "* .ThreadManager" a un destino de archivo cuyo formato de nombre de archivo sea similar a este:

fileName="${basedir}/${mdc:myid}.log"

En el momento en que se registra un mensaje, NLog determinará cuál debe ser el nombre del archivo, en función del valor del diseño del nombre del archivo (es decir, aplica los tokens de formato en el momento del registro). Si el archivo existe, entonces el mensaje se escribe en él. Si el archivo aún no existe, el archivo se crea y el mensaje se registra en él.

Si cada hilo tiene una identificación aleatoria como "aaaaaaaaaaaa", "aaaaaaaaaaab", "aaaaaaaaaaac", entonces debería obtener archivos de registro como este:

aaaaaaaaaaaa.log
aaaaaaaaaaab.log
aaaaaaaaaaac.log

Y así.

Si puede hacerlo de esta manera, entonces su vida debería ser más simple ya que no tiene que tener toda esa configuración programática de NLog (crear reglas y objetivos de archivos). Y puede dejar que NLog se preocupe por crear los nombres de los archivos de salida.

No estoy seguro de que esto funcione mejor de lo que estabas haciendo. O, incluso si lo hace, es posible que realmente necesite lo que está haciendo en su panorama más amplio. Debería ser fácil probar para ver si incluso funciona (es decir, que puede asignar un nombre al archivo de salida en función de un valor en MappedDiagnosticContext). Si funciona para eso, entonces puedes probarlo para tu caso donde estás creando miles de hilos.

ACTUALIZAR:

Aquí hay un código de muestra:

Usando este programa:

using System;
using System.Collections.Generic;
using System.Linq;
using System.Text;

using NLog;
using System.Threading;
using System.Threading.Tasks;

namespace NLogMultiFileTest
{
  class Program
  {
    public static Logger logger = LogManager.GetCurrentClassLogger();

    static void Main(string[] args)
    {

      int totalThreads = 50;
      TaskCreationOptions tco = TaskCreationOptions.None;
      Task task = null;

      logger.Info("Enter Main");

      Task[] allTasks = new Task[totalThreads];
      for (int i = 0; i < totalThreads; i++)
      {
        int ii = i;
        task = Task.Factory.StartNew(() =>
        {
          MDC.Set("id", "_" + ii.ToString() + "_");
          logger.Info("Enter delegate.  i = {0}", ii);
          logger.Info("Hello! from delegate.  i = {0}", ii);
          logger.Info("Exit delegate.  i = {0}", ii);
          MDC.Remove("id");
        });

        allTasks[i] = task;
      }

      logger.Info("Wait on tasks");

      Task.WaitAll(allTasks);

      logger.Info("Tasks finished");

      logger.Info("Exit Main");
    }
  }
}

Y este archivo NLog.config:

<?xml version="1.0" encoding="utf-8" ?>
<!-- 
  This file needs to be put in the application directory. Make sure to set 
  ''Copy to Output Directory'' option in Visual Studio.
  -->
<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd"
      xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">

    <targets>
        <target name="file" xsi:type="File" layout="${longdate} | ${processid} | ${threadid} | ${logger} | ${level} | id=${mdc:id} | ${message}" fileName="${basedir}/log_${mdc:item=id}.txt" />
    </targets>

    <rules>
        <logger name="*" minlevel="Debug" writeTo="file" />
    </rules>
</nlog>

Puedo obtener un archivo de registro para cada ejecución del delegado. El archivo de registro se llama para el "id" almacenado en el MDC (MappedDiagnosticContext).

Entonces, cuando ejecuto el programa de ejemplo, obtengo 50 archivos de registro, cada uno de los cuales tiene tres líneas "Enter ...", "Hello ...", "Exit ...". Cada archivo se denomina log__X_.txt donde X es el valor del contador capturado (ii), por lo que tengo log_ 0 .txt, log_ 1 .txt, log_ 1 .txt, etc., log_ 49 .txt. Cada archivo de registro contiene solo aquellos mensajes de registro pertenecientes a una ejecución del delegado.

¿Es esto similar a lo que quieres hacer? Mi programa de ejemplo utiliza tareas en lugar de hilos porque ya lo había escrito hace algún tiempo. Creo que la técnica debería adaptarse a lo que estás haciendo con la suficiente facilidad.

También podría hacerlo de esta manera (obteniendo un nuevo registrador para cada ejecución del delegado), utilizando el mismo archivo NLog.config:

using System;
using System.Collections.Generic;
using System.Linq;
using System.Text;

using NLog;
using System.Threading;
using System.Threading.Tasks;

namespace NLogMultiFileTest
{
  class Program
  {
    public static Logger logger = LogManager.GetCurrentClassLogger();

    static void Main(string[] args)
    {

      int totalThreads = 50;
      TaskCreationOptions tco = TaskCreationOptions.None;
      Task task = null;

      logger.Info("Enter Main");

      Task[] allTasks = new Task[totalThreads];
      for (int i = 0; i < totalThreads; i++)
      {
        int ii = i;
        task = Task.Factory.StartNew(() =>
        {
          Logger innerLogger = LogManager.GetLogger(ii.ToString());
          MDC.Set("id", "_" + ii.ToString() + "_");
          innerLogger.Info("Enter delegate.  i = {0}", ii);
          innerLogger.Info("Hello! from delegate.  i = {0}", ii);
          innerLogger.Info("Exit delegate.  i = {0}", ii);
          MDC.Remove("id");
        });

        allTasks[i] = task;
      }

      logger.Info("Wait on tasks");

      Task.WaitAll(allTasks);

      logger.Info("Tasks finished");

      logger.Info("Exit Main");
    }
  }
}

Answer 5

Según la documentación en su wiki , están protegidos contra subprocesos:

Debido a que los registradores son seguros para subprocesos, simplemente puede crear el registrador una vez y almacenarlo en una variable estática

En función del error que está cometiendo, lo más probable es que esté haciendo exactamente lo que dice la excepción: modificar la colección en algún lugar del código mientras se repite el ciclo foreach. Dado que su lista se pasa por referencia, no es difícil imaginar dónde otro hilo estaría modificando la colección de reglas mientras está iterando sobre ella. Tienes dos opciones:

1. Crea todas tus reglas por adelantado y luego agrégalas a granel (esto es lo que creo que quieres).
2. Transfiere tu lista a alguna colección de solo lectura ( rules.AsReadOnly() ) pero te pierdes las actualizaciones que suceden cuando los hilos que has generado crean nuevas reglas.