While Heroku is expensive, it does provide a nice UI for deployment.

However, after using Heroku for a while at $WORK I came to realize that the deployment UI isn’t completely honest about when a release is finished.

I assumed that a release marked as finished meant that the new version of the code was released and the old version was no longer running. This isn’t the case, instead a release is “finished” once the release phase has run.

Putting it to the test

Project

The test project consists of main.py, a Procfile that calls main.py, and an empty requirements.txt so Heroku will detect the project as being Python (might not be necessary).

# main.py
import time
import subprocess
import os

def main() -> None:
    # bind to the port provided by Heroku so the dyno is marked as having
    # started successfully
    subprocess.Popen(['nc', '-k', '-l', os.getenv('PORT')])
    while True:
        print(f"current version: 3")
        time.sleep(1)

if __name__ == '__main__':
    main()
# Procfile
web: python3 main.py

After connecting a repo on GitHub I enabled preboot so the deploys are zero downtime, mimicking a production setting.

Finally, I spun up 10 dynos for a cool $250/month.

Testing

Now that we have a version running in production we can start tailing the logs from Heroku and then release a new version to monitor the transition from the current version to the new version.

heroku logs -t -a release-time-test | tee release-time-test.logs

Example snippet from the logs:

2020-09-18T23:51:30.746156+00:00 app[web.1]: current version: 2
2020-09-18T23:51:30.789786+00:00 app[web.10]: current version: 2
2020-09-18T23:51:31.032672+00:00 app[web.5]: current version: 2
2020-09-18T23:51:31.141032+00:00 app[web.9]: current version: 2
2020-09-18T23:51:31.359043+00:00 app[web.4]: current version: 2
2020-09-18T23:51:31.392026+00:00 app[web.7]: current version: 2
2020-09-18T23:51:31.409204+00:00 app[web.6]: current version: 2
2020-09-18T23:51:31.404687+00:00 app[web.3]: current version: 2
2020-09-18T23:51:31.481608+00:00 app[web.8]: current version: 2
2020-09-18T23:51:31.544343+00:00 app[web.2]: current version: 2

And then we release a new version and watch as Heroku deploys the new version.

The Heroku UI says the release has completed before the logs even mention a new release.

Using the Heroku API we can check the created_at and updated_at times to get the start and end time of the release.

curl -n https://api.heroku.com/apps/release-time-test/releases/ \
    -H "Accept: application/vnd.heroku+json; version=3" \
    -H 'Range: id; order=desc,max=1' \
    | jq '.[0] | {created_at: .created_at, updated_at: .updated_at}'
{
  "created_at": "2020-09-18T23:51:33Z",
  "updated_at": "2020-09-18T23:51:33Z"
}

Release timeline

2020-09-18T23:51:33Z: Release started

2020-09-18T23:51:33Z: Release “finished” in the UI

2020-09-18T23:51:38Z: First dyno on the new version starts running.

2020-09-18T23:51:41Z: the last of the 10 dynos starts

2020-09-18T23:54:44Z: Heroku starts killing the old dynos

2020-09-18T23:56:41Z: Heroku finishes killing the last of the 10 dynos

So it takes a little over 5 minutes after Heroku claims the release is finished for all of previous dynos to be killed.

Conclusion

You can’t trust Heroku’s release info, it doesn’t actually say when the new version is running or when the old version is no longer running.

Also I think the disparity between the release being marked as finished in the UI and actually being finished will be larger in proper production scenarios due to slug sizes, longer dyno boot times, and a larger number of dynos.