¿Cómo Thread-Safe es NLog?

Bien,

He esperado durante días antes de decidir publicar este problema, ya que no estaba seguro de cómo decir esto, resaltando en un post largo y detallado. Sin embargo, creo que es relevante pedir la ayuda de la comunidad en este momento.

Básicamente, traté de usar NLog para configurar los registradores para cientos de subprocesos. Pensé que esto sería muy sencillo, pero obtuve esta excepción después de unas pocas decenas de segundos: ” InvalidOperationException: la colección se modificó; la operación de enumeración puede no ejecutarse

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 eso (Lucky Boy!) Descargué la última versión estable de NLOG 2.0 y la incluí en mi proyecto. Pude rastrear el lugar exacto donde sopló:

en LogFactory.cs:

  internal void GetTargetsByLevelForLogger(string name, IList 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(); //lock (LoggingRules)//<--Adding this does not fix it foreach (var rule in this.LoggingRules)//<-- BLOWS HERE { } } 

El problema segun yo
Entonces, según mi entendimiento, lo que sucede es que el LogManager se confunde ya que hay llamadas a config.LoggingRules.Add (Rule) de diferentes subprocesos mientras se llama GetTargetsByLevelForLogger y FlushAllTargets . Intenté atornillar el foreach y reemplazarlo por un bucle for, pero el registrador se volvió malicioso (omitiendo muchos archivos de registro creados)

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

La solución que he encontrado es crear todos los registradores en el MISMO HILO MAESTRO; Esto es REALMENTE poco práctico , 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.

Así que ya lo saben todos, amigos. Por favor ayude a un progtwigdor a ver a su familia nuevamente.

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

Según su código, parece que desea crear un registrador por subproceso y desea tener ese registro de registrador en un archivo con el nombre de un valor de ID pasado. Por lo tanto, el registrador cuya id es “abc” registrará “x: \ abc.log”, “def” registrará en “x: \ def.log”, y así sucesivamente. Sospecho que puedes 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 usted.

Mi primera impresión es que está haciendo mucho trabajo: crear un objective de archivo por subproceso, crear una nueva regla por subproceso, obtener una nueva instancia de registrador, etc., que tal vez no necesite hacer para lograr lo que parece que desea cumplir.

Sé que NLog permite que el archivo de salida sea nombrado dinámicamente, basado en al menos algunos de los NLog LayoutRenderers. Por ejemplo, sé que esto funciona:

 fileName="${level}.log" 

y te daré nombres como este:

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

Entonces, por ejemplo, parece que podrías usar un patrón como este para crear archivos de salida basados ​​en la identificación del hilo:

 fileName="${threadid}.log" 

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

En su caso, desea asignar un nombre al archivo en función de su propia ID. Puede almacenar el ID en el MappedDiagnosticContext (que es un diccionario que le permite almacenar pares de nombre-valor de subprocesos 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 permitir que su clase ThreadManager tenga un solo registrador llamado “ThreadManager”. Cada vez que registra un mensaje, registra la cadena con formato en la llamada de información. Si el registrador está configurado para iniciar sesión en el destino del archivo (en el archivo de configuración haga una regla que envíe “* .ThreadManager” a un destino del archivo cuyo diseño de nombre de archivo sea algo como esto:

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

En el momento en que se registra un mensaje, NLog determinará cuál debe ser el nombre de archivo, según el valor del diseño de fileName (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 un ID aleatorio como “aaaaaaaaaaaa”, “aaaaaaaaaaab”, “aaaaaaaaaaac”, entonces debería obtener los archivos de registro como este:

 aaaaaaaaaaaa.log aaaaaaaaaaab.log aaaaaaaaaaac.log 

Y así.

Si puede hacerlo de esta manera, su vida debería ser más sencilla, ya que no tiene que ver con toda esa configuración programática de NLog (creación de reglas y objectives 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 que lo que estabas haciendo. O, incluso si lo hace, es posible que realmente necesite lo que está haciendo en su cuadro más grande. Debería ser lo suficientemente fácil de probar para ver que incluso funciona (es decir, que puede asignar un nombre a su archivo de salida basándose en un valor en el MappedDiagnosticContext). Si funciona para eso, entonces puede intentarlo en su caso en el que está creando miles de subprocesos.

ACTUALIZAR:

Aquí hay un código de ejemplo:

Utilizando este progtwig:

 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:

           

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

Entonces, cuando ejecuto el progtwig de muestra, obtengo 50 archivos de registro, cada uno de los cuales tiene tres líneas “Ingresar …”, “Hola …”, “Salir …”. Cada archivo se llama 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 los mensajes de registro que pertenecen a una ejecución del delegado.

¿Es esto similar a lo que quieres hacer? Mi progtwig de muestra usa 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á haciendo con la suficiente facilidad.

También puede 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"); } } } 

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

La mejor manera de agregar las reglas sería agregar las reglas antes de comenzar con los trabajadores asíncronos, pero voy a suponer que eso no es lo que quiere.

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

Si cada subproceso crea su propio registrador y agrega sus propias reglas a la configuración, tendrá que bloquearlo. Tenga en cuenta que incluso con la sincronización de su código, todavía existe la posibilidad de que algún otro código se esté enumerando sobre las reglas mientras las está cambiando. Como se muestra, NLog no bloquea estos bits de código. Así que supongo que cualquier reclamo seguro para subprocesos es solo para los métodos de escritura de registro reales.

No estoy seguro de lo que hace tu cerradura existente, pero no creo que no esté haciendo lo que pretendías. Entonces cambio

 ... 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 práctica recomendada bloquear solo los objetos que ‘posee’, es decir, que son privados para su clase. Esto evita que alguna clase en otro código (que no se adhiere a las mejores prácticas) se bloquee en el mismo código que puede crear un interlocking. Así que deberíamos 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(); ... 

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

La mayoría de la gente simplemente agrega esto a su clase:

 private static readonly object Lock = new object(); 

A continuación, fíjese en eso y tenga la garantía de que siempre será el mismo objeto.

No estoy seguro de que esto solucione su problema, pero lo que está haciendo ahora me parece extraño. Otras personas pueden estar en desacuerdo.

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

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

Según la documentación en su wiki , son seguros para los hilos:

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

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

  1. Cree todas sus reglas por adelantado y luego agréguelas en masa (esto es lo que creo que quiere).
  2. Convierta su lista en una colección de solo lectura ( rules.AsReadOnly() ), pero pierda las actualizaciones que se produzcan a medida que los subprocesos que ha generado crean nuevas reglas.