search

Dim0N22 / elmah

Automatically exported from code.google.com/p/elmah
Apache License 2.0
0 stars 0 forks source link

Logging out of sequence when using XmlFileErrorLog #258

Open GoogleCodeExporter opened 9 years ago

GoogleCodeExporter commented 9 years ago 
What steps will reproduce the problem?
1. Log a set of messages in step by step process. Make sure the messages are 
able to show the order in which they were logged
2. View the xml log file (elmah.axd)

What is the expected output? What do you see instead?
messages were logged out of sequence

What version of the product are you using? On what operating system?
1.2.13605

Please provide any additional information below.
relevant post in SO: 
http://stackoverflow.com/questions/7789501/out-of-sequence-logging-by-elmah

Original issue reported on code.google.com by andrew.a...@gmail.com on 20 Oct 2011 at 5:41

GoogleCodeExporter commented 9 years ago 
Hi there!

The one crucial piece of information we're missing here is where are you 
storing the errors???
SqlErrorLog, XmlErrorLog etc

Cheers,

James

Original comment by jamesdriscoll71 on 20 Oct 2011 at 8:40

GoogleCodeExporter commented 9 years ago 
We use the xmlErrorLog.

Thanks

Original comment by andrew.a...@gmail.com on 20 Oct 2011 at 9:26

GoogleCodeExporter commented 9 years ago 
Are these all errors that occur within the same second??
Or are they occurring at larger time intervals??

Original comment by jamesdriscoll71 on 20 Oct 2011 at 10:25

GoogleCodeExporter commented 9 years ago 
yes, they all occured within the same second.

for larger intervals, they seem to be working fine.

Original comment by andrew.a...@gmail.com on 20 Oct 2011 at 10:31

GoogleCodeExporter commented 9 years ago 
OK... this all makes sense. It's down to the way that ELMAH generates its 
filename for the XML file. Look here: 
http://code.google.com/p/elmah/source/browse/branches/RB-1.2/src/Elmah/XmlFileEr
rorLog.cs#133

            string errorId = Guid.NewGuid().ToString();

            DateTime timeStamp = (error.Time > DateTime.MinValue ? error.Time : DateTime.Now);

            string fileName = string.Format(CultureInfo.InvariantCulture, 
                                  @"error-{0:yyyy-MM-ddHHmmssZ}-{1}.xml", 
                                  /* 0 */ timeStamp.ToUniversalTime(), 
                                  /* 1 */ errorId);

ELMAH uses the current time to generate a sortable filename.
Unfortunately, the granularity of this portion of the filename is only to the 
nearest second.

The rest of the filename is generated using a GUID.
So what is happening is that the GUIDs being generated are not sortable in 
terms of when they were generated.

This should be fairly straightforward to fix though!

Original comment by jamesdriscoll71 on 20 Oct 2011 at 10:53

GoogleCodeExporter commented 9 years ago 
cool. thanks for looking into this.

Original comment by andrew.a...@gmail.com on 20 Oct 2011 at 11:20

GoogleCodeExporter commented 9 years ago

Original comment by azizatif on 18 Dec 2011 at 3:35

GoogleCodeExporter commented 9 years ago

Original comment by azizatif on 20 Dec 2011 at 6:28

GoogleCodeExporter commented 9 years ago 
I regret to say after some test and careful considering that it would best to 
defer the fix to a later release. While the fix may seem easy, it has some 
ramifications in other areas that needs more thought and a consistent approach. 
Meanwhile, on the occasions where errors occurring within the same second need 
to be diagnosed in their chronological order, a workaround would be to use the 
value of the time attribute that is embedded within the XML detail of each 
error. The value of this attribute contains fractions of seconds. Another 
possibility is to download the log in CSV and sort on the "Unix Time" column, 
which represents seconds since Jan 1, 1970, (UTC) and includes fractions of 
seconds as well.

I am attaching and posting online[1] a program that demonstrates the issue and 
the workaround. It uses the XmlFileErrorLog to log 250 errors in a tight loop 
and without any other ceremony. It then displays the errors back twice. The 
first time, it renders them in the same order as returned by the log and indeed 
those falling in the same second appear out of sequence (ordered nonsensically 
by the trailing GUID component). The second time, it sorts the returned errors 
by their Time property and in descending order and these appear chronologically 
(most recent first) correct.

[1] https://gist.github.com/1503395

Original comment by azizatif on 20 Dec 2011 at 10:05

Attachments:

GoogleCodeExporter commented 9 years ago 
As a temporary fix for users like me, can you simply introduce a config option 
to override the default ordering of the elmah.axd list and order by the unix 
time instead? Rather than investing in fixing the underlying issue?

Original comment by cott...@gmail.com on 23 Jan 2012 at 6:06