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 was 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 investigated 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.

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 time trying to match the scan’s timestamps against the 0.4-second burst. They didn’t line up cleanly, and the whole exercise rested 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 died. Under load, a batch of blocked inserts unblocks and flushes together, landing in the same second with contiguous errorlogIDs. That is 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 incidents over 120 days, about 0.6 a day. That is a 7.1x amplification, entirely from how the table gets written, not from how often things break.

What was failing

With the noise gone, the pattern was per-account, not per-page. One organization’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 second organization clustered on pageedit, a third on schedule, another on ScheduleWizard. A handful of accounts had data shapes that made specific pages slow. It was 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 script limits at all, so both pages were inheriting whatever IIS defaults to, documented as 90 seconds, though we couldn’t confirm that against prod’s applicationHost.config from where we were working.

Three admin pages were 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 turned 69 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.

Takeaway

A table that records when a row was written does not tell you when the event happened, and everything downstream of that column (dashboards, weekly reviews, ticket priority) inherits the difference. Before prioritizing an error spike, ask whether the timestamp is set by the failing process or by the database at insert time, and whether recent and lifetime counts are shown in separate columns. In this case, 492 raw rows were 69 incidents.