Logs from the "future" hide logs from the "present"

If errors are written to ELMAH from the "future" (system clock > wall clock), 
any logs written in the "present" (system clock = wall clock) will be hidden. 
Expected behavior is that all logs are shown, even if some were written out of 
chronological order.

In my case, I set my system time thirty days in the future. The application 
which I develop (which uses ELMAH) wrote several entries to the error log while 
the clock was configured as such. When I set my system time back to the 
present, I noticed that no additional logs were appearing in ELMAH.

I investigated this problem a bit. As it turns out, there are two ways to sort 
a list of error log entries. The first way is by ID. Each entry receives a 
sequential ID, so that the first log written is 1, the second is 2, and so on. 
The second way is by timestamp. When an entry is written to the log, its 
timestamp is recorded from the system clock.

Normally these two orderings are equivalent. However, if the system clock is 
set forward or backward in time, then the timestamp ordering will no longer be 
reliable.

In ELMAH (backed by MS SQL Server), before a page full of log entries is 
displayed, the log entries are fetched from the SQL Server database. First, the 
newest entry on the page (determined by means of the timestamp) is fetched. 
Then, the first N entries whose IDs are less than that of the newest entry are 
fetched, where N is the number of entries displayed on a page.  These N entries 
will populate the page being rendered.

Notice that the newest entry is identified by timestamp, but it is compared 
against other entries by ID. This is the problem. If log entry A has the most 
recent timestamp but a lower ID than B (meaning it was actually written earlier 
than B), then log entry A will be identified as the newest entry and log entry 
B will not be displayed (because its ID is not less than A's).

A potential fix might be to determine the "newest" entry by sorting by ID, not 
by timestamp.

Lines 187-198 in SQLServer.sql find the newest entry on a page:

  SET ROWCOUNT @StartRowIndex
  SELECT
    @FirstTimeUTC = [TimeUtc],
    @FirstSequence = [Sequence]
  FROM
    [ELMAH_Error]
  WHERE
    [Application] = @Application
  ORDER BY
  [TimeUtc] DESC,
  [Sequence] DESC

And lines 213-235 find the rest of the entries on a page:

  SELECT
    ...
  FROM
    [ELMAH_Error] error
  WHERE
    [Application] = @Application
  AND
    [TimeUtc] <= @FirstTimeUTC
  AND
    [Sequence] <= @FirstSequence
  ...
Original issue reported on code.google.com by louisw...@fastmail.fm on 21 Jun 2013 at 1:12
jglisson / elmah

Logs from the "future" hide logs from the "present" #335
