Heroku Django Application Error: Worker Timout Issue (H12)

Question

After fighting for a while, my first python (django) app is deployed successfully, the database is pushed and can be accessed (meaning I can access and play with it using heroku pg:psql), and I can run the app both locally as python manage.py runserver or within heroku. However, the end result is still the 'Applications Error' page.

The heroku logs shows the following:

2018-01-16T18:43:18.905263+00:00 heroku[web.1]: Restarting
2018-01-16T18:43:18.906518+00:00 heroku[web.1]: State changed from up to     starting
2018-01-16T18:43:19.978422+00:00 heroku[web.1]: Stopping all processes with SIGTERM
2018-01-16T18:43:19.998918+00:00 app[web.1]: [2018-01-16 18:43:19 +0000] [4] [INFO] Handling signal: term
2018-01-16T18:43:26.659760+00:00 heroku[web.1]: Starting process with command `gunicorn extend_sp_radii.wsgi --timeout 20 --keep-alive 5 --log-level debug --log-file -`
2018-01-16T18:43:29.067589+00:00 app[web.1]: [2018-01-16 18:43:29 +0000] [4] [DEBUG] Current configuration:
2018-01-16T18:43:29.067608+00:00 app[web.1]:   config: None
2018-01-16T18:43:29.067609+00:00 app[web.1]:   bind: ['0.0.0.0:48177']
2018-01-16T18:43:29.067616+00:00 app[web.1]:   max_requests_jitter: 0
2018-01-16T18:43:29.067617+00:00 app[web.1]:   timeout: 20
2018-01-16T18:43:29.067618+00:00 app[web.1]:   graceful_timeout: 30
2018-01-16T18:43:29.067619+00:00 app[web.1]:   keepalive: 5
2018-01-16T18:43:29.067620+00:00 app[web.1]:   limit_request_line: 4094
2018-01-16T18:43:29.067621+00:00 app[web.1]:   limit_request_fields: 100
2018-01-16T18:43:29.067624+00:00 app[web.1]:   reload: False
2018-01-16T18:43:29.067623+00:00 app[web.1]:   limit_request_field_size: 8190
2018-01-16T18:43:29.067625+00:00 app[web.1]:   reload_engine: auto
2018-01-16T18:43:29.067626+00:00 app[web.1]:   spew: False
2018-01-16T18:43:29.067627+00:00 app[web.1]:   check_config: False
2018-01-16T18:43:29.067628+00:00 app[web.1]:   preload_app: False
2018-01-16T18:43:29.067629+00:00 app[web.1]:   sendfile: None
2018-01-16T18:43:29.067630+00:00 app[web.1]:   chdir: /app
2018-01-16T18:43:29.067631+00:00 app[web.1]:   daemon: False
2018-01-16T18:43:29.067633+00:00 app[web.1]:   pidfile: None
2018-01-16T18:43:29.067632+00:00 app[web.1]:   raw_env: []
2018-01-16T18:43:29.067634+00:00 app[web.1]:   worker_tmp_dir: None
2018-01-16T18:43:29.067635+00:00 app[web.1]:   user: 55457
2018-01-16T18:43:29.067636+00:00 app[web.1]:   group: 55457
2018-01-16T18:43:29.067637+00:00 app[web.1]:   umask: 0
2018-01-16T18:43:29.067638+00:00 app[web.1]:   initgroups: False
2018-01-16T18:43:29.067639+00:00 app[web.1]:   tmp_upload_dir: None
2018-01-16T18:43:29.067640+00:00 app[web.1]:   secure_scheme_headers: {'X-FORWARDED-PROTOCOL': 'ssl', 'X-FORWARDED-PROTO': 'https', 'X-FORWARDED-SSL': 'on'}
2018-01-16T18:43:29.067641+00:00 app[web.1]:   forwarded_allow_ips: ['*']
2018-01-16T18:43:29.067642+00:00 app[web.1]:   accesslog: -
2018-01-16T18:43:29.067644+00:00 app[web.1]:   access_log_format: %(h)s %(l)s %(u)s %(t)s "%(r)s" %(s)s %(b)s "%(f)s" "%(a)s"
2018-01-16T18:43:29.067644+00:00 app[web.1]:   errorlog: -
2018-01-16T18:43:29.067645+00:00 app[web.1]:   loglevel: debug
2018-01-16T18:43:29.067646+00:00 app[web.1]:   capture_output: False
2018-01-16T18:43:29.067647+00:00 app[web.1]:   logger_class: gunicorn.glogging.Logger
2018-01-16T18:43:29.067648+00:00 app[web.1]:   logconfig: None
2018-01-16T18:43:29.067649+00:00 app[web.1]:   syslog_addr: udp://localhost:514
2018-01-16T18:43:29.067650+00:00 app[web.1]:   syslog: False
2018-01-16T18:43:29.067651+00:00 app[web.1]:   syslog_prefix: None
2018-01-16T18:43:29.067652+00:00 app[web.1]:   syslog_facility: user
2018-01-16T18:43:29.067654+00:00 app[web.1]:   statsd_host: None
2018-01-16T18:43:29.067655+00:00 app[web.1]:   statsd_prefix:
2018-01-16T18:43:29.067653+00:00 app[web.1]:   enable_stdio_inheritance: False
2018-01-16T18:43:29.067658+00:00 app[web.1]:   pythonpath: None
2018-01-16T18:43:29.067656+00:00 app[web.1]:   proc_name: None
2018-01-16T18:43:29.067659+00:00 app[web.1]:   paste: None
2018-01-16T18:43:29.067657+00:00 app[web.1]:   default_proc_name: extend_sp_radii.wsgi
2018-01-16T18:43:29.067660+00:00 app[web.1]:   on_starting: <function OnStarting.on_starting at 0x7fe971d827b8>
2018-01-16T18:43:29.067661+00:00 app[web.1]:   on_reload: <function OnReload.on_reload at 0x7fe971d82950>
2018-01-16T18:43:29.067662+00:00 app[web.1]:   when_ready: <function WhenReady.when_ready at 0x7fe971d82ae8>
2018-01-16T18:43:29.067663+00:00 app[web.1]:   pre_fork: <function Prefork.pre_fork at 0x7fe971d82c80>
2018-01-16T18:43:29.067664+00:00 app[web.1]:   post_fork: <function Postfork.post_fork at 0x7fe971d82e18>
2018-01-16T18:43:29.067665+00:00 app[web.1]:   post_worker_init: <function PostWorkerInit.post_worker_init at 0x7fe971d8b048>
2018-01-16T18:43:29.067667+00:00 app[web.1]:   worker_abort: <function WorkerAbort.worker_abort at 0x7fe971d8b378>
2018-01-16T18:43:29.067666+00:00 app[web.1]:   worker_int: <function WorkerInt.worker_int at 0x7fe971d8b1e0>
2018-01-16T18:43:29.067668+00:00 app[web.1]:   pre_exec: <function PreExec.pre_exec at 0x7fe971d8b510>
2018-01-16T18:43:29.067669+00:00 app[web.1]:   pre_request: <function PreRequest.pre_request at 0x7fe971d8b6a8>
2018-01-16T18:43:29.067670+00:00 app[web.1]:   post_request: <function PostRequest.post_request at 0x7fe971d8b7b8>
2018-01-16T18:43:29.067671+00:00 app[web.1]:   child_exit: <function ChildExit.child_exit at 0x7fe971d8b950>
2018-01-16T18:43:29.067672+00:00 app[web.1]:   worker_exit: <function WorkerExit.worker_exit at 0x7fe971d8bae8>
2018-01-16T18:43:29.067673+00:00 app[web.1]:   nworkers_changed: <function NumWorkersChanged.nworkers_changed at 0x7fe971d8bc80>
2018-01-16T18:43:29.067674+00:00 app[web.1]:   on_exit: <function OnExit.on_exit at 0x7fe971d8be18>
2018-01-16T18:43:29.067675+00:00 app[web.1]:   proxy_protocol: False
2018-01-16T18:43:29.067676+00:00 app[web.1]:   proxy_allow_ips: ['127.0.0.1']
2018-01-16T18:43:29.067677+00:00 app[web.1]:   keyfile: None
2018-01-16T18:43:29.067678+00:00 app[web.1]:   certfile: None
2018-01-16T18:43:29.067679+00:00 app[web.1]:   ssl_version: 2
2018-01-16T18:43:29.067680+00:00 app[web.1]:   cert_reqs: 0
2018-01-16T18:43:29.067681+00:00 app[web.1]:   ca_certs: None
2018-01-16T18:43:29.067682+00:00 app[web.1]:   suppress_ragged_eofs: True
2018-01-16T18:43:29.067683+00:00 app[web.1]:   do_handshake_on_connect: False
2018-01-16T18:43:29.067684+00:00 app[web.1]:   ciphers: TLSv1
2018-01-16T18:43:29.067741+00:00 app[web.1]:   raw_paste_global_conf: []
2018-01-16T18:43:29.068476+00:00 app[web.1]: [2018-01-16 18:43:29 +0000] [4] [INFO] Starting gunicorn 19.7.1
2018-01-16T18:43:29.069362+00:00 app[web.1]: [2018-01-16 18:43:29 +0000] [4] [DEBUG] Arbiter booted
2018-01-16T18:43:29.069534+00:00 app[web.1]: [2018-01-16 18:43:29 +0000] [4] [INFO] Listening at: http://0.0.0.0:48177 (4)
2018-01-16T18:43:29.069693+00:00 app[web.1]: [2018-01-16 18:43:29 +0000] [4] [INFO] Using worker: sync
2018-01-16T18:43:29.073666+00:00 app[web.1]: [2018-01-16 18:43:29 +0000] [8] [INFO] Booting worker with pid: 8
2018-01-16T18:43:29.078910+00:00 app[web.1]: [2018-01-16 18:43:29 +0000] [4] [DEBUG] 2 workers
2018-01-16T18:43:29.079662+00:00 app[web.1]: [2018-01-16 18:43:29 +0000] [9] [INFO] Booting worker with pid: 9
2018-01-16T18:43:30.447420+00:00 heroku[web.1]: State changed from starting to up
2018-01-16T18:43:49.109780+00:00 app[web.1]: [2018-01-16 18:43:49 +0000] [4] [CRITICAL] WORKER TIMEOUT (pid:8)
2018-01-16T18:43:49.109987+00:00 app[web.1]: [2018-01-16 18:43:49 +0000] [4] [CRITICAL] WORKER TIMEOUT (pid:9)
2018-01-16T18:43:49.110840+00:00 app[web.1]: [2018-01-16 18:43:49 +0000] [9] [INFO] Worker exiting (pid: 9)
2018-01-16T18:43:49.110842+00:00 app[web.1]: [2018-01-16 18:43:49 +0000] [8] [INFO] Worker exiting (pid: 8)
2018-01-16T18:43:49.281692+00:00 app[web.1]: [2018-01-16 18:43:49 +0000] [30] [INFO] Booting worker with pid: 30
2018-01-16T18:43:49.380464+00:00 app[web.1]: [2018-01-16 18:43:49 +0000] [32] [INFO] Booting worker with pid: 32
2018-01-16T18:43:49.377014+00:00 app[web.1]: [2018-01-16 18:43:49 +0000] [4] [DEBUG] 1 workers
2018-01-16T18:43:49.448823+00:00 app[web.1]: [2018-01-16 18:43:49 +0000] [4] [DEBUG] 2 workers
2018-01-16T18:43:50.022770+00:00 app[web.1]: [2018-01-16 18:43:50 +0000] [4] [INFO] Shutting down: Master
2018-01-16T18:43:50.127138+00:00 heroku[web.1]: Process exited with status 0
2018-01-16T18:44:09.485886+00:00 app[web.1]: [2018-01-16 18:44:09 +0000] [4] [CRITICAL] WORKER TIMEOUT (pid:30)
2018-01-16T18:44:09.486055+00:00 app[web.1]: [2018-01-16 18:44:09 +0000] [4] [CRITICAL] WORKER TIMEOUT (pid:32)
2018-01-16T18:44:09.486851+00:00 app[web.1]: [2018-01-16 18:44:09 +0000] [30] [INFO] Worker exiting (pid: 30)
2018-01-16T18:44:09.487248+00:00 app[web.1]: [2018-01-16 18:44:09 +0000] [32] [INFO] Worker exiting (pid: 32)
2018-01-16T18:44:09.668483+00:00 app[web.1]: [2018-01-16 18:44:09 +0000] [48] [INFO] Booting worker with pid: 48
2018-01-16T18:44:09.714502+00:00 app[web.1]: [2018-01-16 18:44:09 +0000] [4] [DEBUG] 1 workers
2018-01-16T18:44:09.717941+00:00 app[web.1]: [2018-01-16 18:44:09 +0000] [49] [INFO] Booting worker with pid: 49
2018-01-16T18:44:09.730783+00:00 app[web.1]: [2018-01-16 18:44:09 +0000] [4] [DEBUG] 2 workers
2018-01-16T18:44:29.767004+00:00 app[web.1]: [2018-01-16 18:44:29 +0000] [4] [CRITICAL] WORKER TIMEOUT (pid:48)
2018-01-16T18:44:29.767176+00:00 app[web.1]: [2018-01-16 18:44:29 +0000] [4] [CRITICAL] WORKER TIMEOUT (pid:49)
2018-01-16T18:44:29.767790+00:00 app[web.1]: [2018-01-16 18:44:29 +0000] [49] [INFO] Worker exiting (pid: 49)
2018-01-16T18:44:29.773510+00:00 app[web.1]: [2018-01-16 18:44:29 +0000] [48] [INFO] Worker exiting (pid: 48)
2018-01-16T18:44:30.021919+00:00 app[web.1]: [2018-01-16 18:44:30 +0000] [66] [INFO] Booting worker with pid: 66
2018-01-16T18:44:30.029798+00:00 app[web.1]: [2018-01-16 18:44:30 +0000] [67] [INFO] Booting worker with pid: 67

After a while or when trying to access the page I receive H12 errors:

2018-01-16T18:37:51.863461+00:00 heroku[router]: at=error code=H12 desc="Request timeout" method=GET path="/admin" host=extend-sp-radii-new.herokuapp.com request_id=a709bf23-e1f8-42c9-9e7e-3aeb0eeccf58 fwd="130.91.250.209" dyno=web.1 connect=0ms service=30001ms status=503 bytes=0 protocol=https

Unfortunately, I don't think those are very telling, other that heroku seems to not allow anything longer than 30 sec

https://devcenter.heroku.com/articles/error-codes#h12-request-timeout

https://devcenter.heroku.com/articles/request-timeout

Infact, I set the timeout to only 20 sec (as can be seen in the logs output) by using the following line in Procfile

web: gunicorn extend_sp_radii.wsgi --timeout 20 --keep-alive 5 --log-level debug --log-file -

However, this was only done as attempt trying to get more information, the same problem arises when using the (maximum) of 30 sec. The problem I am facing now is figuring out what exactly the problem is and what to do. I see the following possibilities:

Is this really an error because my app accesses the database in a way that is too slow? Can this be tested/prevented?
Is it some heroku/gunicorn problem that can be fixed without changing the app?
Is heroku (at least with its free plan) simply not able to host my app and I should start crying?

I am happy to provide any additional information including the full app if this might help. Hope anybody has ideas.

(I am running from Windows, the database is postgresql)

score 3 · Accepted Answer · answered Jan 16 '18 at 20:35

Okay, I think I can give a partway answer.

I think that it is really a limitation, i.e. if heroku would allow to run gunicorn with a larger limit, this error would not occur. In short, in my main python model.py, I was initializing the database (I need to be able to update it, so this was just a convenient way of doing it). However, this step can of course also be handled separated. I did so now and the app runs like a charm. I still need to check closely whether or not I can update my database in the way I want, but in any case, removing the data base (re)initialization, which seems to be require more time than 30 sec (although it does not locally), solved my issue.

Heroku Django Application Error: Worker Timout Issue (H12)

1 Answers1