search

benoitc / gunicorn

gunicorn 'Green Unicorn' is a WSGI HTTP Server for UNIX, fast clients and sleepy applications.
http://www.gunicorn.org
Other
9.66k stars 1.74k forks source link

gunicorn worker timeout #3233

Open doekman opened 3 weeks ago

doekman commented 3 weeks ago

I'm getting an error message with gunicorn I don't know why it happens, and don't know how to solve. The log:

Jul 03 14:54:42 webapps wsgi.sh[2977068]: [2024-07-03 14:54:42 +0200] [2977068] [CRITICAL] WORKER TIMEOUT (pid:2977081)
Jul 03 14:54:42 webapps wsgi.sh[2977081]: [2024-07-03 14:54:42 +0200] [2977081] [INFO] Worker exiting (pid: 2977081)
Jul 03 14:54:42 webapps wsgi.sh[2977081]: Aiwa gunicorn (env production), with bind unix:aiwa.sock

I use gunicorn on Debian via the example systemd configuration. There are some small differences. For one, I start gunicorn via a shell script. So my service-file has one different line:

ExecStart=/home/username/aiwa/wsgi.sh production

The shell-script (bash) is settings some environment variables, and then activating the virtual environment, and then starting the app:

#...settings some environment variables
. $(poetry env info --path)/bin/activate
gunicorn --config "${PWD}/gunicorn/config.py" 'aiwa:create_app()'

And the gunicorn/config.py file is settings some variables, and is printing the last line from the logging at the beginning of this issue.

The issue #3136 seems similar. However, the answer itself doesn't give me pointers where to look at. By using PrivateTmp=True, I guess the permissions should be OK.

Any pointers? I have three gunicorn instances, and they all suffer from this.

benoitc commented 3 weeks ago

What error does it return when debug level is enabled? Can you try it ? This seems an issue in a code blocking the worker notifications.

doekman commented 2 weeks ago

I switched it on now (sorry, never looked into gunicorn logging). See what comes up...

doekman commented 2 weeks ago

I've added loglevel='debug' to my gunicorn configuration, but around the error not much more is getting logged.

Jul 05 09:13:44 webapps wsgi.sh[3129704]: [2024-07-05 09:13:44 +0200] [3129704] [CRITICAL] WORKER TIMEOUT (pid:3129714)
Jul 05 09:13:44 webapps wsgi.sh[3129714]: [2024-07-05 09:13:44 +0200] [3129714] [INFO] Worker exiting (pid: 3129714)
Jul 05 09:13:44 webapps wsgi.sh[3129714]: Aiwa gunicorn (env production), with bind unix:aiwa.sock
Jul 05 09:13:44 webapps wsgi.sh[3129704]: [2024-07-05 09:13:44 +0200] [3129704] [ERROR] Worker (pid:3129714) exited with code 1
Jul 05 09:13:44 webapps wsgi.sh[3129704]: [2024-07-05 09:13:44 +0200] [3129704] [ERROR] Worker (pid:3129714) exited with code 1.
Jul 05 09:13:44 webapps wsgi.sh[3154335]: [2024-07-05 09:13:44 +0200] [3154335] [INFO] Booting worker with pid: 3154335

at the start of the application, the following is logged:

Jul 04 15:36:24 webapps systemd[1]: Starting aiwa.service - gunicorn daemon for aiwa...
Jul 04 15:36:26 webapps wsgi.sh[3129704]: [2024-07-06 12:51:06 +0200] [3195355] [DEBUG] Current configuration:
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   config: /home/webby/aiwa/gunicorn/config.py
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   wsgi_app: None
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   bind: ['unix:aiwa.sock']
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   backlog: 2048
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   workers: 3
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   worker_class: sync
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   threads: 1
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   worker_connections: 1000
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   max_requests: 0
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   max_requests_jitter: 0
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   timeout: 15
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   graceful_timeout: 30
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   keepalive: 2
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   limit_request_line: 4094
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   limit_request_fields: 100
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   limit_request_field_size: 8190
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   reload: False
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   reload_engine: auto
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   reload_extra_files: []
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   spew: False
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   check_config: False
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   print_config: False
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   preload_app: False
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   sendfile: None
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   reuse_port: False
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   chdir: /home/webby/aiwa
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   daemon: False
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   raw_env: []
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   pidfile: None
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   worker_tmp_dir: None
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   user: 1001
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   group: 33
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   umask: 0
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   initgroups: False
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   tmp_upload_dir: None
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   secure_scheme_headers: {'X-FORWARDED-PROTOCOL': 'ssl', 'X-FORWARDED-PROTO': 'https', 'X-FORWARDED-SSL': 'on'}
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   forwarded_allow_ips: ['127.0.0.1']
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   accesslog: None
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   disable_redirect_access_to_syslog: False
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   access_log_format: %(h)s %(l)s %(u)s %(t)s "%(r)s" %(s)s %(b)s "%(f)s" "%(a)s"
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   errorlog: -
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   loglevel: debug
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   capture_output: False
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   logger_class: gunicorn.glogging.Logger
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   logconfig: None
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   logconfig_dict: {}
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   logconfig_json: None
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   syslog_addr: udp://localhost:514
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   syslog: False
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   syslog_prefix: None
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   syslog_facility: user
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   enable_stdio_inheritance: False
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   statsd_host: None
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   dogstatsd_tags:
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   statsd_prefix:
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   proc_name: aiwa
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   default_proc_name: aiwa:create_app()
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   pythonpath: None
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   paste: None
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   on_starting: <function OnStarting.on_starting at 0x7fa52cc49ee0>
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   on_reload: <function OnReload.on_reload at 0x7fa52cc4a020>
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   when_ready: <function WhenReady.when_ready at 0x7fa52cc4a160>
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   pre_fork: <function Prefork.pre_fork at 0x7fa52cc4a2a0>
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   post_fork: <function Postfork.post_fork at 0x7fa52cc4a3e0>
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   post_worker_init: <function PostWorkerInit.post_worker_init at 0x7fa52cc4a520>
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   worker_int: <function WorkerInt.worker_int at 0x7fa52cc4a660>
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   worker_abort: <function WorkerAbort.worker_abort at 0x7fa52cc4a7a0>
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   pre_exec: <function PreExec.pre_exec at 0x7fa52cc4a8e0>
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   pre_request: <function PreRequest.pre_request at 0x7fa52cc4aa20>
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   post_request: <function PostRequest.post_request at 0x7fa52cc4aac0>
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   child_exit: <function ChildExit.child_exit at 0x7fa52cc4ac00>
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   worker_exit: <function WorkerExit.worker_exit at 0x7fa52cc4ad40>
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   nworkers_changed: <function NumWorkersChanged.nworkers_changed at 0x7fa52cc4ae80>
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   on_exit: <function OnExit.on_exit at 0x7fa52cc4afc0>
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   ssl_context: <function NewSSLContext.ssl_context at 0x7fa52cc4b1a0>
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   proxy_protocol: False
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   proxy_allow_ips: ['127.0.0.1']
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   keyfile: None
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   certfile: None
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   ssl_version: 2
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   cert_reqs: 0
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   ca_certs: None
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   suppress_ragged_eofs: True
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   do_handshake_on_connect: False
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   ciphers: None
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   raw_paste_global_conf: []
Jul 04 15:36:26 webapps wsgi.sh[3129704]:   strip_header_spaces: False
Jul 04 15:36:27 webapps wsgi.sh[3129704]: [2024-07-04 15:36:26 +0200] [3129704] [INFO] Starting gunicorn 21.2.0
Jul 04 15:36:27 webapps wsgi.sh[3129704]: [2024-07-04 15:36:26 +0200] [3129704] [DEBUG] Arbiter booted
Jul 04 15:36:27 webapps wsgi.sh[3129704]: [2024-07-04 15:36:26 +0200] [3129704] [INFO] Listening at: unix:aiwa.sock (3129704)
Jul 04 15:36:27 webapps wsgi.sh[3129704]: [2024-07-04 15:36:26 +0200] [3129704] [INFO] Using worker: sync
Jul 04 15:36:26 webapps systemd[1]: Started aiwa.service - gunicorn daemon for aiwa.
Jul 04 15:36:27 webapps wsgi.sh[3129705]: [2024-07-04 15:36:27 +0200] [3129705] [INFO] Booting worker with pid: 3129705
Jul 04 15:36:27 webapps wsgi.sh[3129714]: [2024-07-04 15:36:27 +0200] [3129714] [INFO] Booting worker with pid: 3129714
Jul 04 15:36:27 webapps wsgi.sh[3129716]: [2024-07-04 15:36:27 +0200] [3129716] [INFO] Booting worker with pid: 3129716
Jul 04 15:36:27 webapps wsgi.sh[3129704]: [2024-07-04 15:36:27 +0200] [3129704] [DEBUG] 3 workers
doekman commented 3 days ago

I see these lines now:

Jul 22 13:57:10 webapps wsgi.sh[3579811]: [2024-07-22 13:57:10 +0200] [3579811] [DEBUG] Ignoring EPIPE
Jul 22 13:57:10 webapps wsgi.sh[3579803]: [2024-07-22 13:57:10 +0200] [3579803] [DEBUG] Ignoring EPIPE