The log timestamps said the bad traffic kept arriving after the firewall rule went in. We spent rounds of an active production incident convinced the rule wasn’t working. It was working the whole time. The logs were in UTC, the server clock is EST, and we had been reading the two against each other without noticing.

That is an embarrassing way to lose an hour during a fire. This post covers the calibration step we now run before we reason about whether any time-sensitive fix took effect. It is small, and 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. We had pushed a Windows Firewall rule to drop a hosting range and wanted to confirm the bad requests stopped after the rule landed. The obvious move is to open the IIS log and compare timestamps before and after.

Here is the trap. IIS writes its W3C logs in UTC, and the server’s wall clock is Eastern. A request that hits the box late evening local time gets logged several hours later, on what reads like the next day. If your head is anchored to the local clock, and ours was, every line in the log looks like it happened hours in the future. We pushed the rule, glanced at the log, and saw requests that landed before the rule carrying timestamps that looked like they came after it. We concluded the attack continued past the block. Those were old requests, read 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 log file that looks empty

There is a buffering problem too. IIS buffers log writes. After the daily rollover, today’s file can sit at 0 bytes for hours until IIS flushes to disk. Open it to check the last hour of traffic and you see an empty or nearly empty file, which suggests nothing is hitting the box or logging is broken. Neither is true. The requests happened and 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.

Finding today’s file has its own gotcha. 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 the “newest by mtime” pick is a coin flip. Build the path from the date instead. The logs are named u_ex<yymmdd>.log, and because the rollover happens at UTC midnight, the date in the filename is the UTC date. 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"

Use the same UTC the log itself uses, or you reintroduce the clock mismatch you are trying to kill.

Fire a canary first

The one move that collapses all of this is a canary request. Before you analyze anything, send a request you can uniquely identify, then find it in the log. We tag it with a one-off user-agent string so nothing else 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 request tells you three things you would otherwise have assumed.

  1. The timezone. You know exactly when you fired it on your own clock. Whatever timestamp it carries in the log is that same instant rendered in the log’s timezone. The offset is measured, and sits right in front of you.

  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 about the last few minutes is premature.

  3. The request-to-log delay. The gap between firing the canary and seeing it in the flushed file is the latency between a request hitting the box and that request being visible to you. On this box it was under five seconds. So seeing nothing in the last 10 seconds means nothing yet, and seeing nothing in the last 5 minutes actually means something.

Each of those assumptions, left uncalibrated, sends you chasing a fix you already shipped.

Why remembering “logs are UTC” wasn’t enough

We still got it wrong, because under load you stop applying what 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 asks you to remember nothing. It makes the timezone, the flush state, and the delay observable in the same place you are about to do your analysis. You read a row you just created and trust the row. You replace recall with measurement at the moment recall is least reliable.

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

Fire one uniquely tagged request, flush the log buffer, and find it. In this incident, skipping that cost us rounds of work chasing a firewall rule that was already doing its job.