I spent rounds of an active production incident convinced a firewall rule wasn’t working. The log timestamps looked like they fell after the rule went in, and the bad traffic was still showing up. The rule was working the whole time. The logs were in UTC, the server clock is EST, and I had been reading the two against each other without noticing.

That is an embarrassing way to lose an hour during a fire, so this post is the calibration step I now run before I let myself reason about whether any time-sensitive fix took effect. It is small. It would have saved the whole detour.

The setup

The site runs on Windows, IIS, and MSSQL. During a bot swarm the box was pinned, I had pushed a Windows Firewall rule to drop a hosting range, and I wanted to confirm the bad requests stopped after the rule landed. The obvious move is to look at the IIS log and check the timestamps before and after.

Here is the trap. IIS writes its W3C logs in UTC. The server’s wall clock is Eastern. So a request that hits the box late evening local time gets logged with a timestamp several hours later, on what reads like the next day. If your head is anchored to the local clock, and mine was, every line in the log looks like it happened hours in the future. You push a rule, you glance at the log, and the timestamps on requests that landed before your rule look like they came after it. Your brain quietly concludes the attack kept going after the block. It didn’t. Those were old requests, you were just reading them in the wrong timezone.

When you are calm this is obvious. When the site is slow and CPU is at the ceiling, you do not stop to convert timezones in your head. You pattern-match, and the pattern is wrong.

The second trap: the log file is lying about being empty

Before the timezone problem even bites you, there is a buffering one. IIS buffers log writes. After the daily log rollover, today’s file can sit at 0 bytes for hours until IIS flushes its buffer to disk. So you open today’s log to check “the last hour” of traffic, see an empty or nearly empty file, and conclude either that nothing is hitting the box or that logging is broken. Neither is true. The requests happened, they are sitting in a buffer.

appcmd flushlog forces the flush. Run it before you analyze recent activity, every time, or you are reasoning about a file that hasn’t caught up to reality yet.

There is a related gotcha in just finding today’s file. The instinct is to grab the most recently written one:

Terminal window
Get-ChildItem | Sort-Object LastWriteTime -Descending | Select-Object -First 1

That is unreliable. At the rollover IIS stamps both today’s and yesterday’s file at the same moment, so they share a LastWriteTime and your “newest by mtime” pick is a coin flip. Don’t sort by mtime. Construct the path from the date instead. The logs are named u_ex<yymmdd>.log, and because the rollover is on UTC midnight, the date in the filename is the UTC date, not your local one. Build it from UTC so you don’t grab yesterday’s file in the evening:

Terminal window
$f = "D:\LOGS\<SiteName>\u_ex" + ([DateTime]::UtcNow.ToString("yyMMdd")) + ".log"

Name the file from the date, not from the filesystem’s idea of which one is freshest. And use the same UTC the log itself uses, or you reintroduce the exact clock mismatch you are trying to kill.

The fix: fire a canary first

The single move that collapses all of this is a canary request. Before you analyze anything, send a request you can uniquely identify, then go find it in the log. I tag it with a one-off user-agent string so nothing else on the planet matches it:

Terminal window
curl -A "CANARY-UNIQ-XYZ" https://<site-hostname>/

Then flush and grep:

Terminal window
appcmd flushlog
Select-String "CANARY-UNIQ-XYZ" $f

That one canary tells you three things you otherwise would have assumed:

  1. The timezone. You know exactly when you fired it on your own clock. Whatever timestamp it carries in the log is, by definition, that same instant rendered in the log’s timezone. The offset is right there in front of you, measured, not remembered. No more mental UTC math under pressure.

  2. The flush state. If the canary shows up after the flush, logging is current and you are looking at live data. If it doesn’t, the file is still behind and any conclusion you draw about “the last few minutes” is premature.

  3. The request-to-log delay. The gap between when you fired the canary and when it lands in the flushed file is the real latency between a request hitting the box and that request being visible to you. On this box it was under five seconds. Now you know that “I see nothing in the last 10 seconds” means nothing yet, and “I see nothing in the last 5 minutes” actually means something.

All three of those are exactly the assumptions that, left uncalibrated, send you chasing a fix you already shipped.

Why this beats just remembering “logs are UTC”

You might think the lesson is simply “remember IIS logs are UTC.” It isn’t enough. I knew IIS logs were UTC. I still got it wrong, because under load you stop applying things you know and start pattern-matching on what’s in front of you. A fact you have to remember to apply is a fact you will skip during an incident.

The canary doesn’t ask you to remember anything. It makes the timezone, the flush state, and the delay observable in the same place you are about to do your analysis. You are not converting offsets in your head, you are reading a row you just created and trusting the row. That is the whole point of calibrating with a known signal: you replace recall with measurement at the exact moment recall is least reliable.

The same shape applies well beyond IIS. Any time you are about to judge whether a change worked by looking at logs or metrics, ask what timezone the log is in, whether it has flushed, and how long it takes for an event to become visible. If you can’t answer all three from memory with confidence, fire a canary and read the answer instead of guessing it. Application logs, load balancer logs, a metrics pipeline with a scrape interval, a database that batches writes: every one of them has a delay and a clock, and every one of them will let you conclude your fix failed when it didn’t.

The takeaway

Before you reason about “did my fix work,” calibrate the clock and the log delay with a canary. Fire one uniquely-tagged request, flush the buffer, find it, and let it tell you the timezone, the flush state, and the request-to-log lag in a single move. Assume your logs are UTC and your instinct is local, assume the file hasn’t flushed yet, and you will stop debugging phantoms that your own clock invented.