Hey everyone,
To start, we'd like to thank you for bearing with us. While it's been an intense 18 hours, our systems are now smoothly humming along.
The goal of this postmortem is to provide you with a satisfactory explanation of what caused the ingestion delays you saw today. While nobody likes outages or service degradation (especially us), it is important to learn why it happened in order to prevent issues like this in the future.
Around midnight PST, our systems began reporting a small delay inserting your logs into our ElasticSearch databases. These delays grew in frequency, and eventually log lines buffered onto disk when our workers simply could not insert logs fast enough. Socket timeout errors began occurring at an alarming rate, and try as we might, none of our initial approaches improved the situation.
While we were investigating the cause, we realized we needed more time than the amount of disk space left would safely allow, so we shut off the flow of parsed lines to the workers and buffered unparsed lines to the substantially larger disks on other machines. As a result, live tail and alerting became unavailable for several hours.
After much investigation, we finally identified the cause as a calculation error in the line buffer size sent from our workers to ElasticSearch. Although Elasticsearch measures maximum accepted buffer size for insertion in bytes, our workers limit the buffer size by the number of lines. The number of lines in the buffer was calculated based on average line size, rather than our enforced maximum line size of 32 KB. When our average line size suddenly spiked as a result of new high volume traffic, the buffer size began to regularly exceed Elasticsearch's maximum limit and fail to insert.
What made this issue particularly difficult to identify, is that we were looking at what code could have changed recently, rather than an increase in the average line size. We're glad that once it was identified, the issue was quickly resolved. However, we still needed to recover the unparsed lines buffered to disk, as well as the parsed lines waiting to be inserted into ES.
After the insertion issue was resolved, our top priority was restoring live tail and alerting, as we know many of you heavily depend on these features. We created new pipelines to process new logs for live tail, while leaving the old ones to chew through the backlog. However, upon scaling new machines, we ran into hosting provider limits, but ultimately found a workaround.
Once both pipelines were up, live tail and alerting was restored immediately and all logs were backfilled within a couple of hours. Our biggest regret is that we had to disable alerting during the incident. But, if faced with the dilemma of preserving alerts or losing logs, we would make the same choice again.
Moving forward, we've identified a number of ways to prevent this issue in the future, as well as several approaches to decrease downtime if and when an issue occurs. For example:
At the end of the day, we also realize that ultimately, scaling and growing pains are some of the best problems for us to have, and we wouldn't have them without you guys, our awesome customers. Although we may sometimes lose sleep keeping everything afloat, we're happy that you have given us the opportunity to face these challenges together.
Please let us know if you have any questions, concerns or feedback, and we look forward to continuing our journey with you.
- The LogDNA Team