Heroku Django 应用程序错误：工作人员超时问题 (H12)

Posted 2023-02-24

【中文标题】Heroku Django 应用程序错误：工作人员超时问题 (H12)

【英文标题】：Heroku Django Application Error: Worker Timout Issue (H12)

【发布时间】：2018-06-25 13:36:04

【问题描述】：

折腾了一阵子，我的第一个python（django）应用部署成功，数据库推送可以访问了（也就是说我可以使用heroku pg:psql访问和玩），可以运行应用了在本地作为 python manage.py runserver 或在 heroku 中。但是，最终结果仍然是“应用程序错误”页面。

heroku 日志显示如下：

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 

一段时间后或尝试访问该页面时，我收到 H12 错误：

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

不幸的是，我认为这些不是很能说明问题，除了 heroku 似乎不允许超过 30 秒的时间

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

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

事实上，我通过在 Procfile 中使用以下行将超时设置为仅 20 秒（从日志输出中可以看出）

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

但是，这样做只是为了尝试获取更多信息，使用 30 秒的（最大值）时会出现同样的问题。我现在面临的问题是弄清楚问题到底是什么以及该怎么做。我看到以下可能性：

这真的是一个错误吗，因为我的应用程序以 太慢了？可以测试/预防这种情况吗？ 是不是一些 Heroku/gunicorn 问题可以在不更改应用程序的情况下解决？ heroku（至少在其免费计划中）根本无法托管我的应用程序，我应该开始哭泣吗？

如果这可能有帮助，我很乐意提供任何其他信息，包括完整的应用程序。希望大家有想法。

（我在Windows下运行，数据库是postgresql）

【参考方案1】：

好的，我想我可以给出一个半途而废的答案。

我认为这确实是一个限制，即如果 heroku 允许以更大的限制运行 gunicorn，则不会发生此错误。简而言之，在我的主要 python model.py 中，我正在初始化数据库（我需要能够更新它，所以这只是一种方便的方式）。然而，这个步骤当然也可以分开处理。我现在这样做了，该应用程序运行起来就像一个魅力。我仍然需要仔细检查是否可以按照我想要的方式更新我的数据库，但无论如何，删除数据库（重新）初始化，这似乎需要超过 30 秒的时间（尽管它不是在本地)，解决了我的问题。

【讨论】：

你不能超过 30 秒吗？这只是它在这里所说的 gunicorn 的默认值：docs.gunicorn.org/en/latest/…