Between October 31, 2019, at 11:45 UTC, and November 1, 2019, at 03:00 UTC, customers experienced delayed builds which utilized Release Phase, and those utilizing the US Common Runtime experienced delays in dyno booting. We sincerely apologize for the negative effects our customers experienced.
Who was affected?
Applications in the US Common Runtime experienced elevated dyno boot times between 45 and 120 seconds. This would have affected applications that were deployed, manually restarted (when available), or if dynos crashed. We also disabled restarts which meant some customers who needed to restart their app were unable to do so. Releases for all apps using Release Phase were significantly delayed, with delays peaking at 6.5 hours.
Additionally, App Webhooks experienced delivery delays of up to 3.5 hours. Attempts to reset passwords, transfer applications, confirm new accounts, and other actions that relied on generated emails were delayed up to 75 minutes. Finally, the CLI and Heroku Dashboard returned elevated error rates when attempting to use dyno, SSL Endpoint, and Heroku SSL functionality.
What happened?
Background
At the time of the incident, the US Common Runtime orchestration layer was split into 6 “shards,” each having their own independent services, databases, and runtime environment. Applications are assigned to a particular shard. Other services that serve Common Runtime applications, like the Heroku API and build services, are shared between shards.
Incident Response
At 12:25 UTC, engineers were alerted by monitoring regarding an event affecting our US Common Runtime dyno orchestration systems. The team responded to the alerts and began investigating the cause. This investigation led to a possible database issue affecting 2 shards. We also noticed dynos were experiencing delayed in starting. At 13:57 UTC, in order to alleviate pressure and prevent healthy dynos from becoming affected, we disabled dyno restarts (both manual and automated) on these shards.
In parallel, our engineers analyzed the various factors that could potentially lead us to identifying the underlying cause. This included reviewing recent deployments and background scripts, as well as other factors. As a precautionary step, a script that was running was halted at 14:24 UTC to reduce the number of variables in play. Over the next several hours, multiple additional remediation steps were taken but these did not have a positive effect.
Separately, we were alerted to two other issues. At 12:46 UTC, we were alerted to delays in Release Phase processing time. Engineers responsible for this component began investigating this issue. Secondly, at 14:15 UTC, our engineers noticed delays of both App Webhooks deliveries, elevated HTTP 5xx errors from dyno management endpoints of the Platform API, and delays in Platform API job processing. Teams responsible for these components investigated these issues in parallel. However, these issues did not appear to have the same cause as the issue affecting the Common Runtime orchestration layer.
At 15:26 UTC, we started observing the same database issue in 3 of the 4 remaining shards and proactively disabled dyno restarts. We continued to investigate, and believed that the database delays may be related to the script we halted at 14:24 UTC, and spent considerable time digging what this script may have changed to cause the issue. We also investigated how the remaining unaffected shard was different from the rest of the shards. Unfortunately, these investigations did not lead to actionable results.
At 15:59 UTC, we noticed that internal event volume had increased significantly and was causing the delays to both the App Webhooks and Release Phase systems. We scaled these services to respond to the increased volume and began investigating the cause of the increased volume.
At 17:04 UTC, we disabled idling on the US Common Runtime to prevent apps that were still up from being taken offline, as any app that was idle would experience delays booting dynos. This also further reduced load on the system.
At 17:31 UTC we confirmed that the issue was impacting customers in both the Common Runtime regions (US and EU) and Private Spaces as well since the process we use to power our Release Phase feature is shared across all runtimes. The impact to Private Spaces was limited to apps utilizing Release Phase. Other parts of Private Spaces were not impacted.
At 18:56 UTC, we observed some duplicate data in the dyno orchestration systems which possibly hinted at some network latencies. The duplicate data was later explained, but we were experiencing connectivity issues that hinted at network instability. We were also able to confirm that this duplicate data led to the backlog of events affecting our App Webhooks and Release Phase features. We reached out to our service provider to see if they were noticing any issues that could point to some of the behaviors we were observing. While they were not able to confirm any issues at the time, post-incident analysis has led us to the conclusion that a networking issue was a significant factor in the incident.
At 19:20 UTC, several metrics began to show signs of recovery with the exception of the App Webhooks and Release Phase backlog. The databases in the affected shards, as well as the issues affecting our Platform API, began to recover. Over the next 2 hours, we slowly re-enabled features as our metrics improved. This was completed at 21:17 UTC, at which point only the App Webhooks and Release Phase impact remained.
At this time, delays in processing App Webhooks and Release Phase releases were up to 6 hours. We had already scaled up these processing pipelines, but this had not significantly improved processing speed. At 21:21 UTC, we deployed a code change to handle some errors we had observed. We observed the processing backlog was shrinking, so the decision was made to monitor the recovery.
At 00:36 UTC, to alleviate the large backlog of Release Phase events, we attempted to delete the backlog. However, this was unsuccessful. At this point, we began to see minor improvements in processing delays. We decided to continue to monitor the Release Phase backlog and delay until it had caught up without further remediation steps. At 02:51 UTC, Release Phase metrics begin to improve dramatically.
At 03:54 UTC, we confirmed that both the App Webhooks and Release Phase systems had fully recovered and were back to normal processing latencies.
Root Cause Summary
We believe this incident was caused by an underlying networking issue, which began around 12:00 UTC and resolved at 19:20 UTC. This issue led to a significant amount of duplicate data being inserted into a data feed that affected the US Common Runtime directly, causing delays in boot time. This data feed also drives an event feed that is consumed by other services on the platform, which then enqueue jobs in response to those events. As a result of the duplicate data, the number of events and jobs to process grew substantially faster than our systems could process them. Once the underlying issue subsided, these queues were processed over the subsequent hours until normal operation resumed.
What did we do to prevent wider impact?
We enabled various control rods throughout the incident, including disabling dyno restarts and idling, in order to maximize customer uptime. This meant that the automatic dyno cycling and any manually requested restart would return an error. We disabled idling to ensure that the apps that might idle during the incident were not impacted when the app was coming back up. However, this could have caused some increased quota usage for free dynos.
What will we do to mitigate problems like this in the future?
To mitigate the issues we saw with dyno boot times, we are investigating ways to create automated testing that continually exercises our systems in the event of networking-related failures like those that were seen during the incident. Issues discovered by this testing, like the duplicated data which was experienced during this incident, can then be remediated. We will also create dashboards and alerting mechanisms to more closely monitor connection issues to underlying Postgres databases.
We experienced two classes of problems with Release Phase that require remediation. First, we need to improve event processing performance so that spikes in platform load don’t cause Release Phase execution to fall behind. Additionally, we need to improve the ability of the backing data store for Release Phase to scale with significantly increased usage. We also plan to implement enhancements in our metrics to project future system resource usage for internal alerting in advance of system degradation.
Lastly, we will be adding alerting and making several improvements to the background processing of our Platform API system to prevent capacity starvation by high priority jobs. We will add alarms to make us aware of the increased event volume the App Webhooks and Release Phase experienced. We will also be making improvements to the architecture of the event system, on which App Webhooks and Release Phase is based.