---
title: "The Error Log That Lied: When Recent and Lifetime Counts Blur Together"
canonical: https://dxdev.com/blog/2026-09-07_error-log-conflates-recent-lifetime-diagnosis/
datePublished: 2026-08-08
---
## The 492 rows that weren't 492 incidents

The Error Log table had 492 rows tagged `Script timed out` over the trailing 120 days, and the ticket that came in described it like a site-wide admin outage. It got filed Highest priority and slotted straight into our working queue on the strength of two spikes in the raw counts. We almost worked it that way. Instead, we chose to investigate first, read-only, before cutting a branch.

The first query was simple: group the errorlog table by second, count rows, flag anything with three or more hits in the same second.

```sql
SELECT TOP 30 CONVERT(varchar(19), timeStamp, 120) AS sec, COUNT(*) AS n,
       COUNT(DISTINCT username) AS users, COUNT(DISTINCT fileName) AS files
FROM dbo.errorlog WITH (NOLOCK)
WHERE eoDescription = 'Script timed out' AND timeStamp >= DATEADD(day,-120,GETDATE())
GROUP BY CONVERT(varchar(19), timeStamp, 120)
HAVING COUNT(*) >= 3
ORDER BY n DESC
```

Two spikes fell out. The 7/28 10:20 one dissolved on inspection: 5 rows inside 14 milliseconds, four of them the same IP hammering refresh on a hung page. The 7/21 one looked real: 27 rows in a 0.4-second window, spread across 11 files and 8 IPs, the shape of a server-wide stall dumping every blocked request at once.

That one we chased. There had been an unrelated incident on the same date, an agent's prod-DB scan that had wedged the site for about four minutes, and lining up the two events felt like the obvious next move. We spent real time trying to match the scan's timestamps against the 0.4-second burst. They didn't line up cleanly, and the whole exercise was built on a bad premise: that the errorlog timestamp recorded when the error happened. It didn't.

`dbo.errorlog.timeStamp` defaults to DB-side `getdate()`, and the INSERT that writes each row never sets it explicitly, in the same error-logging routine every page calls into. So the column records when the insert reached the database, not when the script actually died. Under load, a batch of blocked inserts unblocks and flushes together, landing in the same second with contiguous errorlogIDs. That's not a server-wide stall event, that's a queuing artifact. Dedup the rows by clustering contiguous IDs that land within the same couple of seconds of each other, and the 492 raw rows collapse to 69 real incidents over 120 days, about 0.6 a day. A 7.1x amplification, entirely from how the table gets written, not from how often things actually break.

## What was actually failing

With the noise gone, the real pattern was per-account, not per-page. A basketball league's account had 13 timeouts in 45 days, repeatedly on the identical URL, `p=statsedit&a=1&sportsHQ=970573&gameID=2`, most recent hit 8/04, same gameID every time. A soccer league clustered on `pageedit`, a baseball league on `schedule`, another league on `ScheduleWizard`. A handful of accounts had data shapes that made specific pages slow, not a fleet-wide failure.

The biggest single cause was the image upload handler: 13 incidents across 6 accounts, and it sets no `Server.ScriptTimeout` at all. It pulls in the same third-party upload library as the general file-upload handler, which sets 600 seconds, as do the banner upload, photo upload, score-import upload, and registration upload handlers. Every sibling handler that touches that library sets an explicit timeout except this one. Same story for the PDF bulk registrant print page, 4 incidents, against the plain registrant print handler sitting at 600. The repo's `web.config` sets no ASP limits at all, so both pages were inheriting whatever IIS defaults to, documented as 90 seconds, though I couldn't confirm that against prod's `applicationHost.config` from where I was sitting.

Three admin pages missing a setting their neighbors already had. The fix was a `Server.ScriptTimeout` line in each, matching the 600 their siblings use.

The Error Log screen itself got a second fix. Its own counter had been folding recent problem counts into the same column as lifetime totals, so every weekly review would surface a page as having failed "N times this week" when most of that N was months old. That's what turned 69 real incidents into a number that read like a crisis. We split the columns and filed the counter as its own ticket, separate from the timeout fix, because it would have kept manufacturing false alarms for the next thing that landed in that table.

The whole incident started because a table telling you when a row was written isn't the same as a table telling you when the thing happened. Everything downstream of that column, dashboards, weekly reviews, ticket priority, inherited the lie.