ACTUALIZACIÓN: 11/12/2014 - Véase la primera parte de mi post aquí:
What is the difference between log4net.ThreadContext and log4net.LogicalThreadContext?
para una actualización reciente. LogicalThreadContext de Log4Net se ha actualizado hace poco (en los últimos años) para que funcione correctamente ahora. La actualización en la publicación vinculada proporciona algunos detalles.
FIN ACTUALIZAR.
Aquí hay una idea que podría ayudarlo. Parte del problema es que los objetos de contexto de log4net (ThreadContext y LogicalThreadContext) no "transfieren" sus propiedades a los hilos "secundarios". LogicalThreadContext da la falsa impresión de que sí lo hace, pero no es así. Internamente usa CallContext.SetData para almacenar sus propiedades. El conjunto de datos a través de SetData está adjunto AL HILO, pero NO es "heredado" por hilos hijo. Por lo tanto, si se establece una propiedad a través de la siguiente manera:
log4net.LogicalThreadContext.Properties["myprop"] = "abc";
Esa propiedad será registrable a través del convertidor patrón de la propiedad% y contendrá un valor al iniciar sesión desde el mismo hilo donde se establece la propiedad en el primer lugar, pero no contendrá ningún valor en ningún subproceso secundario generado a partir de ese subproceso.
Si puede guardar sus propiedades a través de CallContext.LogicalSetData (ver enlace arriba), entonces las propiedades son "fluidas" a (o heredadas por) cualquier subproceso secundario. Por lo tanto, si se puede hacer algo como esto:
CallContext.LogicalSetData("MyLogicalData", nameStr + Thread.CurrentThread.ManagedThreadId);
Entonces "MyLogicalData" estarán disponibles en el hilo donde se establece que, así como en todos los hilos del niño.
Consulte this blog posting by Jeffrey Richter para obtener más información sobre el uso de CallContext.LogicalSetData.
Puede almacenar fácilmente su propia información a través de CallContext.LogicalSetData Y tenerlo disponible para iniciar sesión en log4net escribiendo su propio PatternLayoutConverter. He adjuntado un código de muestra para dos nuevos PatternLayoutConverters.
El primero le permite registrar la información almacenada en Trace.CorrelationManager 's LogicalOperationStack. El convertidor de diseño le permite registrar la parte superior de la LogicalOperationStack o la LogicalOperationStack completa.
using System;
using System.Collections.Generic;
using System.Linq;
using System.Text;
using log4net;
using log4net.Util;
using log4net.Layout.Pattern;
using log4net.Core;
using System.Diagnostics;
namespace Log4NetTest
{
class LogicalOperationStackPatternConverter : PatternLayoutConverter
{
protected override void Convert(System.IO.TextWriter writer, LoggingEvent loggingEvent)
{
string los = "";
if (String.IsNullOrWhiteSpace(Option) || String.Compare(Option.Substring(0, 1), "A", true) == 0)
{
//Log ALL of stack
los = Trace.CorrelationManager.LogicalOperationStack.Count > 0 ?
string.Join(">>",Trace.CorrelationManager.LogicalOperationStack.ToArray()) :
"";
}
else
if (String.Compare(Option.Substring(0, 1), "T", true) == 0)
{
//Log TOP of stack
los = Trace.CorrelationManager.LogicalOperationStack.Count > 0 ?
Trace.CorrelationManager.LogicalOperationStack.Peek().ToString() : "";
}
writer.Write(los);
}
}
}
El segundo le permite registrar la información almacenada mediante CallContext.LogicalSetData. Tal como está escrito, extrae un valor usando CallContext.LogicalGetData usando un nombre fijo. Se podría modificar fácilmente para usar la propiedad Options (como se demuestra en el convertidor LogicalOperationStack) para especificar un valor particular para tirar usando CallContext.LogicalGetData.
using log4net;
using log4net.Util;
using log4net.Layout.Pattern;
using log4net.Core;
using System.Runtime.Remoting.Messaging;
namespace Log4NetTest
{
class LogicalCallContextPatternConverter : PatternLayoutConverter
{
protected override void Convert(System.IO.TextWriter writer, LoggingEvent loggingEvent)
{
string output = "";
object value = CallContext.LogicalGetData("MyLogicalData");
if (value == null)
{
output = "";
}
else
{
output = value.ToString();
}
writer.Write(output);
}
}
}
Aquí es cómo configurar:
<layout type="log4net.Layout.PatternLayout">
<param name="ConversionPattern" value="%d [%t] %logger %-5p [PROP = %property] [LOS.All = %LOS{a}] [LOS.Top = %LOS{t}] [LCC = %LCC] %m%n"/>
<converter>
<name value="LOS" />
<type value="Log4NetTest.LogicalOperationStackPatternConverter" />
</converter>
<converter>
<name value="LCC" />
<type value="Log4NetTest.LogicalCallContextPatternConverter" />
</converter>
</layout>
Aquí está mi código de prueba:
//Start the threads
new Thread(TestThis).Start("ThreadA");
new Thread(TestThis).Start("ThreadB");
//Execute this code in the threads
private static void TestThis(object name)
{
var nameStr = (string)name;
Thread.CurrentThread.Name = nameStr;
log4net.ThreadContext.Properties["ThreadContext"] = nameStr;
log4net.LogicalThreadContext.Properties["LogicalThreadContext"] = nameStr;
CallContext.LogicalSetData("MyLogicalData", nameStr + Thread.CurrentThread.ManagedThreadId);
Trace.CorrelationManager.StartLogicalOperation(nameStr + Thread.CurrentThread.ManagedThreadId);
logger.Debug("From Thread itself");
ThreadPool.QueueUserWorkItem(x =>
{
logger.Debug("From threadpool Thread_1: " + nameStr);
Trace.CorrelationManager.StartLogicalOperation(nameStr + Thread.CurrentThread.ManagedThreadId);
CallContext.LogicalSetData("MyLogicalData", nameStr + Thread.CurrentThread.ManagedThreadId);
logger.Debug("From threadpool Thread_2: " + nameStr);
CallContext.FreeNamedDataSlot("MyLogicalData");
Trace.CorrelationManager.StopLogicalOperation();
logger.Debug("From threadpool Thread_3: " + nameStr);
});
}
Aquí está la salida:
Form1: 2011-01-14 09:18:53,145 [ThreadA] Form1 DEBUG [PROP = {LogicalThreadContext=ThreadA, log4net:HostName=WILLIE620, ThreadContext=ThreadA}] [LOS.All = ThreadA10] [LOS.Top = ThreadA10] [LCC = ThreadA10] From Thread itself
Form1: 2011-01-14 09:18:53,160 [ThreadB] Form1 DEBUG [PROP = {LogicalThreadContext=ThreadB, log4net:HostName=WILLIE620, ThreadContext=ThreadB}] [LOS.All = ThreadB11] [LOS.Top = ThreadB11] [LCC = ThreadB11] From Thread itself
Form1: 2011-01-14 09:18:53,192 [12] Form1 DEBUG [PROP = {log4net:HostName=WILLIE620}] [LOS.All = ThreadB11] [LOS.Top = ThreadB11] [LCC = ThreadB11] From threadpool Thread_1: ThreadB
Form1: 2011-01-14 09:18:53,207 [12] Form1 DEBUG [PROP = {log4net:HostName=WILLIE620}] [LOS.All = ThreadB12>>ThreadB11] [LOS.Top = ThreadB12] [LCC = ThreadB12] From threadpool Thread_2: ThreadB
Form1: 2011-01-14 09:18:53,207 [12] Form1 DEBUG [PROP = {log4net:HostName=WILLIE620}] [LOS.All = ThreadB11] [LOS.Top = ThreadB11] [LCC = ] From threadpool Thread_3: ThreadB
Form1: 2011-01-14 09:18:53,207 [13] Form1 DEBUG [PROP = {log4net:HostName=WILLIE620}] [LOS.All = ThreadA10] [LOS.Top = ThreadA10] [LCC = ThreadA10] From threadpool Thread_1: ThreadA
Form1: 2011-01-14 09:18:53,223 [13] Form1 DEBUG [PROP = {log4net:HostName=WILLIE620}] [LOS.All = ThreadA13>>ThreadA10] [LOS.Top = ThreadA13] [LCC = ThreadA13] From threadpool Thread_2: ThreadA
Form1: 2011-01-14 09:18:53,223 [13] Form1 DEBUG [PROP = {log4net:HostName=WILLIE620}] [LOS.All = ThreadA10] [LOS.Top = ThreadA10] [LCC = ] From threadpool Thread_3: ThreadA
Cuando hice esta prueba (y algunas otras pruebas en las que he estado trabajando), creé mi propio objeto de pila de "contexto" (similar a la implementación de "pila" de log4net) almacenando mi Pila a través de CallContext.LogicalSetData en lugar de a través de CallContext.SetData (que es cómo lo almacena log4net). Descubrí que mi pila se confundió cuando tenía varios hilos de ThreadPool. Tal vez fue a partir de la fusión de los datos de nuevo al contexto principal cuando salió el contexto secundario. No hubiera pensado que sería el caso, ya que en mi prueba, explícitamente presioné el nuevo valor en la entrada al hilo ThreadPool y lo abrí al salir. Una prueba similar con una implementación Trace.CorrelationManager.LogicalOperationStack-based (escribí una abstracción sobre ella) pareció comportarse correctamente. Supongo que tal vez la lógica de flujo automático (hacia abajo Y hacia atrás) es responsable de CorrelationManager ya que es un objeto "conocido" en el sistema ???
Algunas cosas a tener en cuenta en la salida:
Trace.CorrelationManager inforamation se almacena a través CallContext.LogicalSetData por lo que es "fluyó" a procesos hijo. TestThis utiliza Trace.CorrelationManager.StartLogicalOperation para "presionar" una operación lógica (llamada así por el nombre pasado) en LogicalOperationStack. La primera instrucción logger.Debug en el subproceso ThreadPool muestra que el subproceso ThreadPool ha heredado el mismo LogicalOperationStack como el subproceso padre. Dentro del hilo ThreadPool, comienzo una nueva operación lógica que se apila en LogicalOperationStack heredado. Puede ver el resultado de eso en el segundo registrador. Salida de depuración. Finalmente, antes de irme, detengo la operación lógica. La tercera salida de logger.Debug muestra eso.
Como puede ver en la salida, CallContext.LogicalSetData también se "transfiere" a subprocesos secundarios. En mi código de prueba elegí establecer un nuevo valor en LogicalSetData dentro del hilo ThreadPool y luego limpiarlo antes de salir (FreeNamedDataSlot).
Siéntase libre de probar estos convertidores de diseño de patrones y ver si se puede lograr los resultados que usted está buscando. Como lo he demostrado, al menos debería poder reflejar en su resultado de registro qué hilos de ThreadPool fueron iniciados/usados por qué otros hilos (padre?).
Nota que hay algunos problemas, incluso con CallContext.LogicalSetData en ciertos ambientes:
"Niño" de datos lógicos se fusiona de nuevo en "padre" de datos lógicos: EndInvoke changes current CallContext - why?
Nested multithread operations tracing
(No un problema, pero una buena publicación sobre Trace.CorrelationManager.ActivityId y Task Parallel Library):
How do Tasks in the Task Parallel Library affect ActivityID?
Publicación de un blog enlazado sobre problemas con varios mecanismos de almacenamiento de "contexto" en el contexto de ASP.Net
http://piers7.blogspot.com/2005/11/threadstatic-callcontext-and_02.html
[EDIT]
he encontrado que manteniendo el contexto correcto, mientras que en gran medida (o tal vez incluso no tan fuertemente - mi prueba ejecuta DoLongRunningWork utilizando diversas técnicas Tema/Tarea/paralelo) utilizando hilos puede lanzar algunos conjuntos de datos con CallContext.LogicalSetData fuera de sintonía.
Vea this question about using Trace.CorrelationManager.ActivityId aquí en StackOverflow. Publiqué una respuesta sobre el uso de Trace.CorrelationManager.LogicalOperationStack y algunas de mis observaciones.
Más tarde utilicé mi respuesta a esa pregunta como la base for my own question about using Trace.CorrelationManager.LogicalOperationStack in the context of Threads/Tasks/Parallel.
También publiqué a very similar question on Microsoft's Parallel Extensions forum.
Puedes leer esas publicaciones ver mis observaciones. Para resumir brevemente:
Con un patrón de código como este:
DoLongRunningWork //Kicked off as a Thread/Task/Parallel(.For or .Invoke)
StartLogicalOperation
Sleep(3000) //Or do actual work
StopLogicalOperation
El contenido de la LogicalOperationStack siguen siendo coherentes si DoLongRunningWork se inició por medio de hilos de rosca/ThreadPool explícitas/Tareas/Paralelo (.Para o .Invoke)
Con un patrón de código como este:
StartLogicalOperation //In Main thread (or parent thread)
DoLongRunningWork //Kicked off as a Thread/Task/Parallel(.For or .Invoke)
StartLogicalOperation
Sleep(3000) //Or do actual work
StopLogicalOperation
StopLogicalOperation
El contenido de la LogicalOperationStack permanecen consistente SALVO cuando DoLongRunningWork se inició por Parallel.For o Parallel.Invoke. El motivo parece estar relacionado con el hecho de que Parallel.For y Parallel.Invoke utilizan el hilo principal como uno de los hilos para ejecutar las operaciones paralelas.
Esto significa que si desea encerrar toda la operación paralelizada (o roscada) como una operación lógica individual y cada iteración (es decir, cada invocación del delegado) como una operación lógica anidada dentro de la operación externa, la mayoría de las técnicas que probado (Thread/ThreadPool/Task) funciona correctamente. En cada iteración, LogicalOperationStack refleja que hay una tarea externa (para el hilo principal) y una tarea interna (el delegado).
Si usa Parallel.For o Paralelo.Invocar, LogicalOperationStack no funciona correctamente. En el código de muestra en las publicaciones que se vinculó anteriormente, LogicalOperationStack nunca debe tener más de 2 entradas. Uno para el hilo principal y otro para el delegado. Cuando se utiliza Parallel.For o Parallel.Invoke, LogicalOperationStack eventualmente obtendrá muchas más de 2 entradas.
El uso de CallContext.LogicalSetData es aún peor (al menos si se trata de emular LogicalOperationStack almacenando una pila con LogicalSetData). Con un patrón de llamada similar al anterior (el que tiene la operación lógica adjunta, así como la operación lógica de delegado), una pila almacenada con LogicalSetData y mantenida de manera idéntica (por lo que yo sé) se corromperá en casi todos los casos.
CallContext.LogicalSetData podría funcionar mejor para tipos más simples o para tipos que no se modifican dentro del "hilo lógico". Si tuviera que almacenar un diccionario de valores con LogicalSetData (similar a log4net.LogicalThreadContext.Properties), probablemente se heredaría con éxito mediante hilos secundarios/Tareas/etc.
No tengo ninguna gran explicación de por qué esto está sucediendo o la mejor manera de evitarlo.Es posible que la forma en que estaba probando el "contexto" haya pasado un poco por la borda, o puede que no.
Si mira esto un poco más, puede probar los programas de prueba que publiqué en los enlaces de arriba. Los programas de prueba solo prueban LogicalOperationStack. Realicé pruebas similares con código más complicado creando una abstracción de contexto que admite una interfaz como IContextStack. Una implementación utiliza una pila almacenada mediante CallContext.LogicalSetData (similar a cómo se almacena LogicalThreadContext.Stacks de log4net, excepto que utilicé LogicalSetData en lugar de SetData). La otra implementación implementa esa interfaz sobre Trace.CorrelationManager.LogicalOperationStack. Eso me facilita ejecutar las mismas pruebas con diferentes implementaciones de contexto.
Aquí es mi interfaz IContextStack:
public interface IContextStack
{
IDisposable Push(object item);
object Pop();
object Peek();
void Clear();
int Count { get; }
IEnumerable<object> Items { get; }
}
Aquí es el implementaiton basada en LogicalOperationStack:
class CorrelationManagerStack : IContextStack, IEnumerable<object>
{
#region IContextStack Members
public IDisposable Push(object item)
{
Trace.CorrelationManager.StartLogicalOperation(item);
return new StackPopper(Count - 1, this);
}
public object Pop()
{
object operation = null;
if (Count > 0)
{
operation = Peek();
Trace.CorrelationManager.StopLogicalOperation();
}
return operation;
}
public object Peek()
{
object operation = null;
if (Count > 0)
{
operation = Trace.CorrelationManager.LogicalOperationStack.Peek();
}
return operation;
}
public void Clear()
{
Trace.CorrelationManager.LogicalOperationStack.Clear();
}
public int Count
{
get { return Trace.CorrelationManager.LogicalOperationStack.Count; }
}
public IEnumerable<object> Items
{
get { return Trace.CorrelationManager.LogicalOperationStack.ToArray(); }
}
#endregion
#region IEnumerable<object> Members
public IEnumerator<object> GetEnumerator()
{
return (IEnumerator<object>)(Trace.CorrelationManager.LogicalOperationStack.ToArray().GetEnumerator());
}
#endregion
#region IEnumerable Members
System.Collections.IEnumerator System.Collections.IEnumerable.GetEnumerator()
{
return Trace.CorrelationManager.LogicalOperationStack.ToArray().GetEnumerator();
}
#endregion
}
Aquí está la implementación basada en CallContext.LogicalSetData:
class ThreadStack : IContextStack, IEnumerable<object>
{
const string slot = "EGFContext.ThreadContextStack";
private static Stack<object> GetThreadStack
{
get
{
Stack<object> stack = CallContext.LogicalGetData(slot) as Stack<object>;
if (stack == null)
{
stack = new Stack<object>();
CallContext.LogicalSetData(slot, stack);
}
return stack;
}
}
#region IContextStack Members
public IDisposable Push(object item)
{
Stack<object> s = GetThreadStack;
int prevCount = s.Count;
GetThreadStack.Push(item);
return new StackPopper(prevCount, this);
}
public object Pop()
{
object top = GetThreadStack.Pop();
if (GetThreadStack.Count == 0)
{
CallContext.FreeNamedDataSlot(slot);
}
return top;
}
public object Peek()
{
return Count > 0 ? GetThreadStack.Peek() : null;
}
public void Clear()
{
GetThreadStack.Clear();
CallContext.FreeNamedDataSlot(slot);
}
public int Count { get { return GetThreadStack.Count; } }
public IEnumerable<object> Items
{
get
{
return GetThreadStack;
}
}
#endregion
#region IEnumerable<object> Members
public IEnumerator<object> GetEnumerator()
{
return GetThreadStack.GetEnumerator();
}
#endregion
#region IEnumerable Members
System.Collections.IEnumerator System.Collections.IEnumerable.GetEnumerator()
{
return GetThreadStack.GetEnumerator();
}
#endregion
}
Aquí es el StackPopper utilizado por ambos:
internal class StackPopper : IDisposable
{
int pc;
IContextStack st;
public StackPopper(int prevCount, IContextStack stack)
{
pc = prevCount;
st = stack;
}
#region IDisposable Members
public void Dispose()
{
while (st.Count > pc)
{
st.Pop();
}
}
#endregion
}
¡Es mucho para digerir, pero quizás encuentre algo de esto útil!
@My Other Me - (Agregue este comentario esperando que reciba una notificación ya sea ella en mi comentario más largo a continuación) Consulte mi comentario/pregunta en respuesta a su comentario del 4 de noviembre de 2010 por @TskTsk – wageoghe