Return-Path: X-Original-To: apmail-logging-log4net-user-archive@www.apache.org Delivered-To: apmail-logging-log4net-user-archive@www.apache.org Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by minotaur.apache.org (Postfix) with SMTP id 6AB7B11449 for ; Thu, 24 Jul 2014 14:32:54 +0000 (UTC) Received: (qmail 46216 invoked by uid 500); 24 Jul 2014 14:32:54 -0000 Delivered-To: apmail-logging-log4net-user-archive@logging.apache.org Received: (qmail 46179 invoked by uid 500); 24 Jul 2014 14:32:54 -0000 Mailing-List: contact log4net-user-help@logging.apache.org; run by ezmlm Precedence: bulk list-help: list-unsubscribe: List-Post: Reply-To: "Log4NET User" List-Id: Delivered-To: mailing list log4net-user@logging.apache.org Received: (qmail 46162 invoked by uid 99); 24 Jul 2014 14:32:54 -0000 Received: from athena.apache.org (HELO athena.apache.org) (140.211.11.136) by apache.org (qpsmtpd/0.29) with ESMTP; Thu, 24 Jul 2014 14:32:54 +0000 X-ASF-Spam-Status: No, hits=1.5 required=5.0 tests=HTML_MESSAGE,RCVD_IN_DNSWL_LOW,SPF_PASS X-Spam-Check-By: apache.org Received-SPF: pass (athena.apache.org: domain of ananth.tatachar@gmail.com designates 74.125.82.182 as permitted sender) Received: from [74.125.82.182] (HELO mail-we0-f182.google.com) (74.125.82.182) by apache.org (qpsmtpd/0.29) with ESMTP; Thu, 24 Jul 2014 14:32:48 +0000 Received: by mail-we0-f182.google.com with SMTP id k48so2807753wev.13 for ; Thu, 24 Jul 2014 07:32:25 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20120113; h=mime-version:in-reply-to:references:date:message-id:subject:from:to :content-type; bh=tGZWRaXt35uNPs9Qo5BKWuaPT64uePhkbBu2TPUrZxw=; b=H77Z3eE6god+caOF9jRWL1ylFoOpndHBdhS+OYDFjQeua2AMwaQakgYtRptQ52k7uC pFdgVVQBEW0VrDF6A/KLul/BGpqrf3+fu4yCBeucqUsCbcY0AbMcAc/9zxYC8FqyFyiL TSJteIg1YWkFiDHLDJwzOXL+/RX2kETHWjIHdX5nQCA4gpJRb9vGNUSjDYzSc2mpBeY2 pUpkgWZOqqkwlpcdMW+uEZhiRHtfXDXmKo/88F60S2/OGtAw1pZMVgzxOrORWprAxi1B qd2KmWktI2HwlKWjPHVB1bVyfUUs8ilkCn8xJ1aAJPbbsKpi8xdSQTEKA4t0TK+KoRiC 6/xg== MIME-Version: 1.0 X-Received: by 10.180.72.98 with SMTP id c2mr10008527wiv.68.1406212345252; Thu, 24 Jul 2014 07:32:25 -0700 (PDT) Received: by 10.216.222.198 with HTTP; Thu, 24 Jul 2014 07:32:25 -0700 (PDT) In-Reply-To: References: Date: Thu, 24 Jul 2014 10:32:25 -0400 Message-ID: Subject: Re: Log4net.ThreadContext.Properties Having stale data. How to resolve it? From: Ananth Tatachar To: Log4NET User Content-Type: multipart/alternative; boundary=001a11c2b05051552304fef153a4 X-Virus-Checked: Checked by ClamAV on apache.org --001a11c2b05051552304fef153a4 Content-Type: text/plain; charset=UTF-8 Hi Dominik Psenner , Thanks a lot for replying , I am really sorry about my bad explanation of my problem. I am trying to create a custom Json Layout , ---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- 1) The custom layout class: class MyJsonLayout:LayoutSkeleton { private HashSet IncludeFieldsList { get; set; } public override void ActivateOptions() { } public override void Format(TextWriter writer, LoggingEvent loggingEvent) { if(writer == null || loggingEvent == null) { throw new ArgumentNullException(); } var myJsonObj = new MyJsonObject(loggingEvent, IncludeFieldsList ); var json = JsonConvert.SerializeObject(myJsonObj,Formatting.None); writer.WriteLine(json); } } ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- 2) The MyJsonObject class: [JsonObject(MemberSerialization.OptIn)] class MyJsonObject { [JsonProperty("@timestamp")] private DateTime TimeStamp { get; set; } [JsonProperty("@message", NullValueHandling = NullValueHandling.Ignore)] private String Message { get; set; } [JsonProperty("@tid", NullValueHandling = NullValueHandling.Ignore)] private String Tid {get;set;} [JsonObject(MemberSerialization.OptIn)] private String MyGuid {get;set;} public MyJsonObject(LoggingEvent loggingEvent) { var lgData = loggingEvent.GetLoggingEventData(); // For some reason if I dont do this , all the loggingEvent.Properties are null. I did not understand this. TimeStamp = loggingEvent.TimeStamp; MyGuid = loggingEvent.Properties["myguid"]; //loggingEvent.Properties.Remove("myguid"); I tried doing this , but nothing changed in my output. Message = loggingEvent.Properties["message"]; Tid = loggingEvent.Properties["tid"]; } } -------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- 3) The Place where I put data into log4net.ThreadContext.Properties: class MyInstatntiationClass { log4net.ThreadContext.Properties["myguid"] = Guid.NewGuid().ToString(); log4net.ThreadContext.Properties["tid"] = System.Threading.Thread.CurrentThread.ManagedThreadId.ToString(); } --------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- 4) My Web.config file: -------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- 5) Output file: {"@timestamp":"2014-07-24T10:20:32.1223183-04:00" ,"@tid":"5","@myguid":dfg134xcd_dfe-123uier00"} {"@timestamp":"2014-07-24T10:20:32.3213382-04:00","@tid":"5","@myguid": dfg134xcd_dfe-123uier00"} {"@timestamp":"2014-07-24T10:20:32.8273888-04:00","@tid":"5","@myguid": dfg134xcd_dfe-123uier00"} {"@timestamp":"2014-07-24T10:20:32.8273888-04:00","@tid":"6","@myguid":fgsg 4678xzv-adfry-2356i"} Expected behaviour: Each of my calls should result in unique guids. But as you can see I am getting stale guids. --------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- I have two concerns : 1) As you can see in the output file the guid are stale. While executing I carefully monitered the place where guid is being generated : in file number 3 in this file: MyInstatntiationClass. All the generated guids were unique , however while logging I got stale data. Also One other thing I noticed was , when I put the current thread to sleep for 50 ms , I see valid unique guids in the output. I believe old thread data is being used. 2) I did not understand the use of LoggingEventData. In file number 2 : MyJsonObject , If I dont make this call :var lgData = loggingEvent.GetLoggingEventData(); I get null values from loggingEvent.Properties. Thanks a lot for your help in advance ... On Thu, Jul 24, 2014 at 2:40 AM, Dominik Psenner wrote: > Hi Ananth Tatachar, > > I'm having a hard time understanding your problem. Can you provide us a > sample application including all the code together with both a broken > sample output and a expected sample output? It would also be interesting > which exact version of log4net you are using. > > Best regards > > > > 2014-07-24 2:31 GMT+02:00 Ananth Tatachar : > > >> >> ---------- Forwarded message ---------- >> From: Ananth Tatachar >> Date: Wed, Jul 23, 2014 at 8:24 PM >> Subject: Log4net.ThreadContext.Properties Having stale data. How to >> resolve it? >> To: log4net-user@logging.apache.org >> >> >> I am using a RollingFileAppender , and my own custom layout. My >> application is multithreaded. Each thread will generate unique random data >> and is supposed to log it using log4net framework. However if I create >> multiple threads in quick succession I notice stale data in my logs , this >> goes away if each thread sleeps for 50 ms before logging. I am not able to >> figure out a solution to this issue or find its cause please do help me. >> >> My logging function looks like this: >> >> >> log4net.ThreadContext.properties["randomGeneratedData"] = >> randomGeneratedData; >> private ILog myLog = >> LogManager.GetLogger(typeof(LogTest)); >> using (log4net.NDC.Push("ndcTest1")) >> { >> using (log4net.NDC.Push("ndcTest2")) >> { >> myLog.Info("myLogTest"); >> } >> } >> >> >> >> >> >> Result of logging: >> >> NDC = "ndcTest1 ndcTest2" , randomGeneratedData = rad1 >> NDC = "ndcTest1 ndcTest2" , randomGeneratedData = rad2 >> NDC = "", randomGeneratedData = rad2 >> >> and so on ... >> >> >> I tried to clear log4net.ThreadContext.Properties before filling it again >> , but it was of no use. Please help. >> >> > > > -- > Dominik Psenner > --001a11c2b05051552304fef153a4 Content-Type: text/html; charset=UTF-8 Content-Transfer-Encoding: quoted-printable
Hi Dominik Psenner ,

Thanks a lot for r= eplying , I am really sorry about my bad explanation of my problem.

I am trying to create a custom Json Layout ,=C2=A0
<= div>
------------------------------------------------------------= ---------------------------------------------------------------------------= -------------------------------------------
1) The custom layout = class:


=C2=A0class MyJsonLayout:LayoutSkel= eton
=C2=A0 =C2=A0 {
=C2=A0 =C2=A0 =C2=A0 =C2=A0 privat= e HashSet<String> IncludeFieldsList { get; set; }

=C2=A0 =C2=A0 =C2=A0 =C2=A0 public override void ActivateOptions()
=C2=A0 =C2=A0 =C2=A0 =C2=A0 {

=C2=A0 =C2=A0 = =C2=A0 =C2=A0 }

=C2=A0 =C2=A0 =C2=A0 =C2=A0 public= override void Format(TextWriter writer, LoggingEvent loggingEvent)
=C2=A0 =C2=A0 =C2=A0 =C2=A0 {
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2= =A0 =C2=A0 if(writer =3D=3D null || loggingEvent =3D=3D null)
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 {
=C2=A0 =C2=A0 = =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 throw new ArgumentNullException()= ;
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 }
=C2=A0 = =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 var myJsonObj =3D new MyJsonObject(loggi= ngEvent, IncludeFieldsList );
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 = =C2=A0 var json =3D JsonConvert.SerializeObject(myJsonObj,Formatting.None);=
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 writer.WriteLine(json);
=C2=A0 =C2=A0 =C2=A0 =C2=A0 }
=C2=A0 =C2=A0 }

---------------------------------------------------------= ---------------------------------------------------------------------------= -------------------------------------------------------

2) The MyJsonObject class:

[Js= onObject(MemberSerialization.OptIn)]
class MyJsonObject
=
=C2=A0 =C2=A0 {
=C2=A0 =C2=A0 =C2=A0 =C2=A0 [JsonProperty(&q= uot;@timestamp")]
=C2=A0 =C2=A0 =C2=A0 =C2=A0 private DateTime TimeStamp { get; set; }

=C2=A0 =C2=A0 =C2=A0 =C2=A0 [JsonProperty("@me= ssage", NullValueHandling =3D NullValueHandling.Ignore)]
=C2= =A0 =C2=A0 =C2=A0 =C2=A0 private String Message { get; set; }

=C2=A0 =C2=A0 =C2=A0 =C2=A0 [JsonProperty("@tid&qu= ot;, NullValueHandling =3D NullValueHandling.Ignore)]
=C2=A0 =C2= =A0 =C2=A0 =C2=A0 private String Tid {get;set;}

= =C2=A0 =C2=A0 =C2=A0 =C2=A0=C2=A0[JsonObject(MemberSerialization.OptIn)]
=C2=A0 =C2=A0 =C2=A0 =C2=A0 private String MyGuid {get;set;}

=C2=A0 =C2=A0 =C2=A0 =C2=A0public MyJsonObject(LoggingEvent= loggingEvent)
=C2=A0 =C2=A0 =C2=A0 =C2=A0{
=C2=A0= =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 var lgData =3D = loggingEvent.GetLoggingEventData(); // For some reason if I dont do this , = all the loggingEvent.Properties are null. I did not understand this.=
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0=C2=A0TimeStamp =3D log= gingEvent.TimeStamp;
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 My= Guid =3D loggingEvent.Properties["myguid"];
=C2=A0 =C2= =A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 //loggingEvent.Properties.Remove("mygu= id"); I tried doing this , but nothing changed in my output.
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 Message =3D loggingEvent.Pro= perties["message"];
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 = =C2=A0 Tid =3D loggingEvent.Properties["tid"];
=C2=A0 = =C2=A0 =C2=A0 =C2=A0}

=C2=A0 =C2=A0 }
--------------------------------------------------------------= ---------------------------------------------------------------------------= ---------------------------------------------------------------------------=

3) The Place where I put data into log4net.ThreadContex= t.Properties:

class MyInstatntiationClass
=C2=A0 =C2=A0 {
=C2=A0 =C2=A0 =C2=A0 =C2=A0 log4net.ThreadConte= xt.Properties["myguid"] =3D Guid.NewGuid().ToString();
=C2=A0 =C2=A0 =C2=A0 =C2=A0 log4net.ThreadContext.Properties["tid= "] =3D=C2=A0System.Threading.Thread.CurrentThread.ManagedThreadId.ToSt= ring();
=C2=A0 =C2=A0 }


-= ---------------------------------------------------------------------------= ---------------------------------------------------------------------------= --------------------------------------------------------------

4) My Web.config file:



<appender name=3D"RollingLocalFileAppen= der" type=3D"log4net.Appender.RollingFileAppender">
=C2=A0 =C2=A0 =C2=A0 <file type=3D"log4net.Util.PatternString&= quot; value=3D"C:\Logs\JSON.log" />
=C2=A0 =C2=A0 = =C2=A0 <rollingStyle value=3D"Date" />
=C2=A0 =C2= =A0 =C2=A0 <datePattern value=3D"yyyy-MM-dd" />
=C2=A0 =C2=A0 =C2=A0 <maxSizeRollBackups value=3D"10" /&g= t;
=C2=A0 =C2=A0 =C2=A0 <appendToFile value=3D"true"= />
=C2=A0 =C2=A0 =C2=A0 <layout type=3D"MyJsonLayout,= Version=3D1.0.0.0, Culture=3Dneutral">
=C2=A0 =C2=A0 =C2=A0 </layout>
=C2=A0 =C2=A0 </appe= nder>


--------------------= ---------------------------------------------------------------------------= ---------------------------------------------------------------------------= ------------------------------------------------------

5) Output file:


{"@timestamp":"2014-07-24T10:20:32.1223183-04:00" ,&qu= ot;@tid":"5","@myguid":dfg134xcd_dfe-123uier00&quo= t;}
{"@timestamp":"2014-07-24T10:20:32.3213382-04:00",= "@tid":"5","@myguid= ":dfg134xcd_dfe-123uier00"}
{"@timestamp":"2014-07-24T10:20:32.8273888-04:00",= "@tid":"5","@myguid= ":dfg134xcd_dfe-123uier00"}
{"@timestamp":"2014-07-24T10:20:32.8273888-04:00",= "@tid":"6","@myguid= ":fgsg4678xzv-adfry-2356i"}

=C2=A0
Expected behaviour:

=
Each of my calls should result in unique guids. But as you can s= ee I am getting stale guids.


------= ---------------------------------------------------------------------------= ---------------------------------------------------------------------------= ---------------------------------------------------------------------


I have two concerns :

1) As you can see in the output file the guid are stale. While execu= ting I carefully monitered the place where guid is being generated : in fil= e number 3 in this file: MyInstatntiationClass.
All the generated guids were unique , however while logging I got stal= e data. Also One other thing I noticed was , when I put the current thread t= o sleep for 50 ms , I see valid unique guids in the output.
I believe old thread data is being used.


=
2) I did not understand the use of LoggingEventData. In file num= ber 2 : MyJsonObject , If I dont make this call :var lgData =3D loggingEvent.GetLoggingEventData(); I get null values from loggingEvent.Properties.




Thanks a lot for your help in advance ...









=



On Thu, Jul 24, 2014 at 2:40 AM, Dominik P= senner <dpsenner@gmail.com> wrote:
Hi Ananth Tatacha= r,

I'm having a hard time understanding your problem. Can = you provide us a sample application including all the code together with bo= th a broken sample output and a expected sample output? It would also be in= teresting which exact version of log4net you are using.

Best regards



2014-07-24 2:31 GMT+02:00 Ananth Tatachar <ananth.tatachar@gmail.com>:



---------- Forwarded message ----------
From: Ananth Tatachar &= lt;ananth.ta= tachar@gmail.com>
Date: Wed, Jul 23, 2014 at 8:24 PM
Subject: Log4net.ThreadContext.Proper= ties Having stale data. How to resolve it?
To: log4net-user@logging.apache.org=


I am using a RollingFileAppender , and my own custom = layout. My application is multithreaded. Each thread will generate unique r= andom data and is supposed to log it using log4net framework. However if I = create multiple threads in quick succession I notice stale data in my logs = , this goes away if each thread sleeps for 50 ms before logging. I am not a= ble to figure out a solution to this issue or find its cause please do help= me.

My logging function looks like this:


=C2=A0 =C2=A0 log4net.ThreadContext.properties["= randomGeneratedData"] =3D randomGeneratedData;
=C2=A0 =C2=A0= private ILog myLog =3D=C2=A0
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0LogManager.GetLogger(typeof(L= ogTest));
=C2=A0 =C2=A0 using (log4net.NDC.Push("ndcTest1&qu= ot;))
=C2=A0 =C2=A0 {
=C2=A0 =C2=A0 =C2=A0 =C2=A0 using= (log4net.NDC.Push("ndcTest2"))
=C2=A0 =C2=A0 =C2=A0 = =C2=A0 =C2=A0 =C2=A0 {
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 myLog.Info(&qu= ot;myLogTest");
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 }<= /div>
=C2=A0 =C2=A0 }





Result of logging:

=C2=A0 =C2=A0 =C2=A0 =C2=A0NDC =3D "ndcTest1 ndcTest2" , randomGe= neratedData =3D rad1
=C2=A0 =C2=A0 =C2=A0 =C2=A0NDC =3D "ndc= Test1 ndcTest2" , randomGeneratedData =3D rad2
=C2=A0 =C2=A0= =C2=A0 =C2=A0NDC =3D "", randomGeneratedData =3D rad2=C2=A0

and so on ...


I= tried to clear log4net.ThreadContext.Properties before filling it again , = but it was of no use. Please help.=C2=A0




--
Dominik Ps= enner

--001a11c2b05051552304fef153a4--