In my Design for Failure article, I mentioned how many of the common techniques we use to allegedly detect failure really don’t. This time, we’ll discuss your monitoring and why it is lying to you.
Well, you have some monitoring, don’t you, couldn’t it tell you if an application is down? Obviously not if you are just doing old SNMP/box level monitoring, but you’re all DevOps and you know you have to monitor the applications because that’s what counts. But even then, there are common antipatterns to be aware of.
Dirty secret time, most application monitoring is “synthetic,” which means it hits a specific URL or set of URLs once in a while, often 5-10 minutes apart. Also, since there are a lot of transient failures out there on the Internet, most ops groups have their monitors set where they have to see 2-5 consecutive failures – because ops teams don’t like being woken up at 3 AM because an application hiccuped once (or the Internet hiccuped on the way to the application). If the problem happens on only 1 of every 20 hits, and you have to see three errors in a row to alert, then I’ll leave it to your primary school math skills to determine how likely it is you’ll catch the problem.
You can improve on this a little bit, but in the end synthetic monitoring is mainly useful for coarse uptime checking and performance trending.
OK, so synthetic monitoring is only good for rough up/down stuff, but what about my metric monitoring? Maybe I have a spiffier tool that is continuously pulling metrics from Web servers or apps that should give me more of a continuous look. Hits per second over the last five minutes; current database space, etc.
Well, I have noticed that metrics monitors, with startling regularity, don’t really tell you if something is up or down, especially historically. If you pull current database space and the database is down, you’d think there would be a big nasty gap in your chart but many tools don’t do that – either they report the last value seen, or if it’s a timing report it happily reports you timing of errors. Unless you go to the trouble to say “if the thing is down, set a value of 0 or +infinity or something” then you can sometimes have a failure, then go back and look at your historical graphs and see no sign there’s anything wrong.
Well surely your app developers are logging if there’s a failure, right? Unfortunately logging is a bit of an art, and the simple statement “You should log the overall success or failure of each hit to your app, and you should log failures on any external dependency” can be… reinterpreted in many ways. Developers sometimes don’t log all the right things, or even decide to suppress certain logs.
You should always log everything. Log it at a lower log level, like INFO, if it’s routine, but then at least it can be reviewed if needed and can be turned into a metric for trending via tools like Splunk. My rules are simple:
- Log the start and end of each hit – are you telling the client success or failure? Don’t rely on the Web server log.
- Log every single hit to an external dependency at INFO
- Log every transient failure at WARN
- Log every error at ERROR
Real User Monitoring
Ah, this is more like it. The alleged Holy Grail of monitoring is real user monitoring, where you passively look at the transactions coming in and out and log them. Well, on the one hand, you don’t have to rely on the developers to log, you can log despite them. But you don’t get as much insight as you’d think. If the output from the app isn’t detectable as an error, then the monitoring doesn’t help. A surprising amount of the time, failures are not thrown as a 500 or other expected error code. And checking for content within a payload is often fragile.
Also, RUM tools tend to be network sniffer based, which don’t work well in the cloud or in many network topologies. And you get so much data, that it can be hard to find the real problems without spending a lot of time on it.
No, Really – One Real World Example
We had a problem just this week that managed to successfully slip through all our layers of monitoring – luckily, our keen eyes caught it in preproduction. We had been planning a bit app release and had been setting up monitoring for it. It seemed like everything was going fine. But then the back end databases (SQL Azure in this case) had a pretty long string of failures for about 10 minutes, which brought our attention to the issue. As I looked into it, I realized that it was very likely we would have seen smaller spates of SQL Azure connection issues and thus application outage before – why hadn’t we? I investigated.
We don’t have any good cloud-compliant real user monitoring in place yet. And the app was throwing a 200 http code on an error (the error page displayed said 401, but the actual http code was 200) so many of our synthetic monitors were fooled. Plus, the problem was usually occasional enough that hitting once every 10 minutes from Cloudkick didn’t detect it. We fixed that bad status code, and looked at our database monitors. “I know we have monitors directly on the databases, why aren’t those firing?”
Our database metric monitors through Cloudkick, I was surprised to see, had lovely normal looking graphs after the outage.I provoked another outage in test to see, and sure enough, though the monitors ‘went red,’ for some reason they were still providing what seemed to Cloudkick like legitimate data points, and once the monitors “went green,” nothing about any of the metric graphs indicated anything unusual! In other words, the historical graphs had legitimate looking data and did not reveal the outage. That’s a big problem. So we worked on those monitors.
I still wanted to know if this had been happening. “We use Splunk to aggregate our logs, I’ll go look there!” Well, there were no error lines in the log that would indicate a back end database problem. Upon inquiring, I heard that since SQL Azure connection issues are a known and semi-frequent problem, logging of them is suppressed, since we have retry logic in place. I recommended that we log all failures, with ones that are going to be retried simply logged at a lower severity level like WARN, but ERROR on failures after the whole spread of retries. I declared this a showstopper bug that had to be fixed before release – not everyone was happy with that, but sometimes DevOps requires tough love.
I was disturbed that we could have periods of outage that were going unnoticed despite our investment in synthetic monitoring, pulling metrics, and searching logs. When I looked back at all our metrics over periods of known outage and they all looked good, I admit I became somewhat irate. We fixed it and I’m happy with our detection now, but I hope this is instructive in showing you how bad assumptions and not fully understanding the pros and cons of each instrumentation approach can end up leaving “stacked holes” that end up profoundly compromising your view of your service!
10 responses to “Why Your Monitoring Is Lying To You”
Great post! Spot on in so many ways..
Pingback: A Smattering of Selenium #68 « Official Selenium Blog
Excellent post and so true!
Great post. The problems are obviously compounded if you cannot return “real” HTTP status codes to the outside world. Perhaps you needed to follow ScottGu’s advice here in relation to the ASP.NET encryption padding vulnerability 2416728:
“…explicitly configure your applications to always return the same error page – regardless of the error encountered on the server.”
You could proxy all web applications, having the proxy return the same error code and page for all actual errors, whilst logging the “real” return code sent by the web app, but that starts to get a bit complex.
The other approach to try would be to monitor the monitors (recursion!), and monitors which have logged exactly the same value for N cycles should be considered suspect if the monitor still claims that the feature under monitoring is in a non-error state. Almost anything worth monitoring will change slightly given a decent measurement precision, even if that’s just due to noise.
Good tips. Still not ironclad – our metric monitors actually were showing legit looking change during what I knew was an outage (still hunting down why on that one!). Also a good technique is to log a unique guid with each error that you expose to the end user as part of an otherwise uniform error page. That way if they contact support, you can get right to the erroring transaction on the ops side. We’re doing that on one of our apps and it is paying off.
+1 the GUID/UUID logging technique, @ernestm. I have used this technique for the last 7+ years (and wrote an article on it for ACCU), and it has spared me huge headaches.
You can search across all logs from all machines and stitch together the full “error journey” across machine/call boundaries based on the GUID. No need to rely on machine timestamps (which always seem to be wrong when you need to diagnose problems!).
What would be very cool is some kind of visualiser which maps out the error journey, showing the different machines. Perhaps I should write an output listener for LogStash (http://logstash.net/) or graphite.
Are you running on Windows or Linux?
We do both Windows and Linux. Currently we use splunk for log management, but are definitely interested in open source that might do the same thing for cheaper. We really get a lot of mileage out of the interface with developers, though – more than half the value of log management is the actual devs being motivated to look at/use them.
Ernest, I’m initially thinking of a fairly “quick and dirty” implementation which would nonetheless provide some decent benefit: plug in a GUID or other reliable (and close to unique) ID, and get the tool to show the error path across various machines. I reckon Python is a decent choice for implementation language – cross-platform and good for text processing.
I’ve just re-published the article I wrote for CVu, for reference:
Hope this is some use – I’ll let you know if I make some progress with the log-stitch tool.
Great post. I agree with Mathew on the value of stitching log entries across multiple sources and in fact we developed a solution that addresses that exact same problem. Where logs are parsed and related via some of kind of user defined identifiers. These in turn are related to other application activities such as HTTP, JMS, JDBC, .NET, SOAP requests. The idea is relate real application transactions as well log files into a continuous flow. We call that transaction flow analysis. Check out AutoPilot TransactionWorks (http://www.nastel.com).