In March a refund service spent four hours failing to authenticate to its database, and we heard about it from customer support. We had an alert on error logs for every service. It had seen the errors and decided they were normal.
Two months earlier our Python services had moved to GKE. Within a week the log based metric counting entries with severity ERROR or above went from a few hundred a day to about four hundred thousand. The alert paged constantly, we looked, found nothing wrong, and assumed the old platform had been under counting. Somebody raised the threshold from fifty errors in five minutes to five thousand. The refund outage produced about two thousand.
The cause was a default on each side. Python's logging module, configured with basicConfig and no stream, writes through a StreamHandler to standard error. Every service we own was set up that way, so every request line, every startup message and every health check went to stderr. GKE's logging agent assigns a severity to plain text lines from the stream they arrive on: stdout becomes INFO and stderr becomes ERROR. Our log levels were in the text, in front of every message, and nothing was reading them.
What finally showed it was filtering the logs for severity ERROR and reading the top results. The first page was lines that began with INFO and ended with GET /healthz 200.
Our shared logging library now writes one JSON object per line to stdout, with a severity field, which Cloud Logging reads in place of the stream. All our services moved to it in a fortnight. The error count fell back to a few hundred a day and the threshold went back to fifty, now set per service, because one noisy service had been hiding the rest. Each service's container test starts it, makes a request and fails if anything at INFO appears on stderr. And when an alert is silenced by changing its threshold, the change needs a note of what the extra errors actually were.
We raised the threshold because the number was obviously wrong. The number was wrong for a reason, and the reason was still there when a real error arrived and looked exactly like the false ones.
– Sergey Shinder
Top comments (0)