last release (21.1.0) sends a lot of errors #3032

wind-shift · 2023-07-18T13:05:55Z

Throwing random errors

[2023-07-18 13:04:10 +0000] [3150] [ERROR] Exception in worker process
Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/gunicorn/arbiter.py", line 609, in spawn_worker
    worker.init_process()
  File "/usr/local/lib/python3.11/site-packages/gunicorn/workers/gthread.py", line 95, in init_process
    super().init_process()
  File "/usr/local/lib/python3.11/site-packages/gunicorn/workers/base.py", line 142, in init_process
    self.run()
  File "/usr/local/lib/python3.11/site-packages/gunicorn/workers/gthread.py", line 232, in run
    self.murder_keepalived()
  File "/usr/local/lib/python3.11/site-packages/gunicorn/workers/gthread.py", line 176, in murder_keepalived
    self.poller.unregister(conn.sock)
  File "/usr/local/lib/python3.11/selectors.py", line 366, in unregister
    key = super().unregister(fileobj)
          ^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/selectors.py", line 249, in unregister
    key = self._fd_to_key.pop(self._fileobj_lookup(fileobj))
                              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/selectors.py", line 225, in _fileobj_lookup
    return _fileobj_to_fd(fileobj)
           ^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/selectors.py", line 42, in _fileobj_to_fd
    raise ValueError("Invalid file descriptor: {}".format(fd))
ValueError: Invalid file descriptor: -1
[2023-07-18 13:04:10 +0000] [3150] [INFO] Worker exiting (pid: 3150)
[2023-07-18 13:04:11 +0000] [1] [ERROR] Worker (pid:3150) exited with code 255
[2023-07-18 13:04:11 +0000] [1] [ERROR] Worker (pid:3150) exited with code 255.

The previous versions did not have this issue at all, was triggered in our latest build, so we’ll rollback version but still the problem remains in your latest release.

rafaeljuzwiak · 2023-07-18T13:18:13Z

I was about to create a ticket regarding this update as well. I manage an API that processes around 2k-3K calls / second distribuite a couple of pods inside Kubernetes with an average of 150ms.

Yesterday I had a hotfix regarding the API applied and I didn't notice I didn't have freeze the gunicorn in the requirements.txt file. As a result, Gunicorned instaled the latested version. I didn't notice at the time but, I notice after applying the patch my response times were averaging 600ms. It was a prod workload, so I undo de PR asap but couldn't get the response back to 150ms regardless what I did.

Only today I decided to compare the packages and notice this in gunicorn. Put it back to 20.1.0 and now it looks beutiful again. Maybe that is related to the "send a lot of errors" above, that is taking too much CPU time away, idk, I know that performance to the 21.1.0 compared to the 20.1.0 went down by a LOT.

benoitc · 2023-07-18T13:37:07Z

@dkr-sahar 21.1.0 (out today) fix this error that was in 21.0.1. (out last night) Look at #3026. Are you sure about the version ? I don't reproduce it anymore after applying the fix.

Please confirm. @rafaeljuzwiak same question :)

rafaeljuzwiak · 2023-07-18T14:01:07Z

Positive, I did restart my pods and built again (on version 21) this morning and I still had issues.
Only after locking down the requirements.txt to 20.1.0 I got fixed.
You can see attachment, Purple is stage, Yellow Sandbox and Blue production. Lines goes down as soon I had the requirements.txt locked and and restart each environment.

I had to increase 4 pods in order to get production around the 250ms and still, with 4 less pods before I had around 150ms.

I really don't want to test this on prod now as it already caused some fuzz, I can update sandbox latter today to give another try and get the feedback to you.

rafaeljuzwiak · 2023-07-18T14:14:14Z

Ps: Morning I mean around 8AM UTC, not sure what tz you are in and if I still got the previous unpatched version when I made the rebuild.

benoitc · 2023-07-18T14:44:34Z

i don't reproduce it. I don't see how it can be rzproduced in current version with the error catched. can you provide an example? Or more contewt ? What return the command line gunicorn --version ? Gunicorn 21.1.0 has been released 2h ago. (14:00 UTC)

xkobal · 2023-07-18T15:10:51Z

I had same problem with the latest gunicorn version. A rollback to 20.1.0 fix the problem.

# gunicorn --version
gunicorn (version 21.1.0)

benoitc · 2023-07-18T15:23:48Z

Please provide a way to reproduce it. I don't anymore since the patch :(

xkobal · 2023-07-18T15:36:16Z

I will try.

Meanwhile, I am using the gunicorn[gthread]==20.1.0 version.

wind-shift · 2023-07-18T15:36:24Z

@dkr-sahar 21.1.0 (out today) fix this error that was in 21.0.1. (out last night) Look at #3026. Are you sure about the version ? I don't reproduce it anymore after applying the fix.

Please confirm. @rafaeljuzwiak same question :)

@benoitc I confirm that 21.1.0 fixed our issue (did not notice that it was 2hours ago)

However we still have this problem that just appaeared.

[2023-07-18 15:33:24 +0000] [17] [ERROR] Socket error processing request.
Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/gunicorn/workers/gthread.py", line 280, in handle
    req = next(conn.parser)
          ^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/gunicorn/http/parser.py", line 42, in __next__
    self.mesg = self.mesg_class(self.cfg, self.unreader, self.source_addr, self.req_count)
                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/gunicorn/http/message.py", line 184, in __init__
    super().__init__(cfg, unreader, peer_addr)
  File "/usr/local/lib/python3.11/site-packages/gunicorn/http/message.py", line 55, in __init__
    unused = self.parse(self.unreader)
             ^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/gunicorn/http/message.py", line 196, in parse
    self.get_data(unreader, buf, stop=True)
  File "/usr/local/lib/python3.11/site-packages/gunicorn/http/message.py", line 187, in get_data
    data = unreader.read()
           ^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/gunicorn/http/unreader.py", line 37, in read
    d = self.chunk()
        ^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/gunicorn/http/unreader.py", line 64, in chunk
    return self.sock.recv(self.mxchunk)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
OSError: [Errno 9] Bad file descriptor

It seems that it appears when a 500 error is raised (backend: django).

xkobal · 2023-07-18T15:39:08Z

I confirm that it seems to happen only when my backend (django too) is raising an exception.

wind-shift · 2023-07-18T15:40:40Z

I confirm that it seems to happen only when my backend (django too) is raising an exception.

It could also arise in the following sequence:

backend takes too much time to answer (but still succeed to proceed the HTTP request)
gunicorn raise this exception with bad file descriptor
returns a 500 anyway.

Not totally sure of which way it works.

xkobal · 2023-07-18T15:42:58Z

Same as @dkr-sahar.
And when I call a second time the same endpoint, it works, I have a normal 500 error.

All of this is happening in Docker in my case.

mihalikv · 2023-07-18T15:51:56Z

Hi, same issue here.

Gunicorn version:

Error stack trace:

Gunicorn.conf:

Env is production.

Let me know if I can help you with more information.

geudrik · 2023-07-18T17:44:55Z

Our CI (shame on us) installed 21.1.0 at 10:45 EST this am, upgrading us from 20.1.0, and we get tons of the following, causing 502's to return from nginx (sitting in front of gunicorn)

 [2023-07-18 17:33:38 +0000] [55] [ERROR] Socket error processing request.                                                                                                         │
 Traceback (most recent call last):                                                                                                                                                │
   File "/root/.pyenv/versions/3.8/lib/python3.8/site-packages/gunicorn/workers/gthread.py", line 285, in handle                                                                   │
     keepalive = self.handle_request(req, conn)                                                                                                                                    │
   File "/root/.pyenv/versions/3.8/lib/python3.8/site-packages/gunicorn/workers/gthread.py", line 357, in handle_request                                                           │
     util.reraise(*sys.exc_info())                                                                                                                                                 │
   File "/root/.pyenv/versions/3.8/lib/python3.8/site-packages/gunicorn/util.py", line 641, in reraise                                                                             │
     raise value                                                                                                                                                                   │
   File "/root/.pyenv/versions/3.8/lib/python3.8/site-packages/gunicorn/workers/gthread.py", line 343, in handle_request                                                           │
     resp.write(item)                                                                                                                                                              │
   File "/root/.pyenv/versions/3.8/lib/python3.8/site-packages/gunicorn/http/wsgi.py", line 326, in write                                                                          │
     self.send_headers()                                                                                                                                                           │
   File "/root/.pyenv/versions/3.8/lib/python3.8/site-packages/gunicorn/http/wsgi.py", line 322, in send_headers                                                                   │
     util.write(self.sock, util.to_bytestring(header_str, "latin-1"))                                                                                                              │
   File "/root/.pyenv/versions/3.8/lib/python3.8/site-packages/gunicorn/util.py", line 299, in write                                                                               │
     sock.sendall(data)                                                                                                                                                            │
 OSError: [Errno 9] Bad file descriptor

isra17 · 2023-07-18T18:14:16Z

Same here, we have emissary in front of gunicorn. My logs shows around 10% of upstream connection closed with the following logs:

2023-07-18T17:52:40Z: [error] Socket error processing request.
Traceback (most recent call last):
  File "/opt/venv/lib/python3.11/site-packages/gunicorn/workers/gthread.py", line 280, in handle
    req = next(conn.parser)
          ^^^^^^^^^^^^^^^^^
  File "/opt/venv/lib/python3.11/site-packages/gunicorn/http/parser.py", line 42, in __next__
    self.mesg = self.mesg_class(self.cfg, self.unreader, self.source_addr, self.req_count)
                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/opt/venv/lib/python3.11/site-packages/gunicorn/http/message.py", line 184, in __init__
    super().__init__(cfg, unreader, peer_addr)
  File "/opt/venv/lib/python3.11/site-packages/gunicorn/http/message.py", line 55, in __init__
    unused = self.parse(self.unreader)
             ^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/opt/venv/lib/python3.11/site-packages/gunicorn/http/message.py", line 196, in parse
    self.get_data(unreader, buf, stop=True)
  File "/opt/venv/lib/python3.11/site-packages/gunicorn/http/message.py", line 187, in get_data
    data = unreader.read()
           ^^^^^^^^^^^^^^^
  File "/opt/venv/lib/python3.11/site-packages/gunicorn/http/unreader.py", line 37, in read
    d = self.chunk()
        ^^^^^^^^^^^^
  File "/opt/venv/lib/python3.11/site-packages/gunicorn/http/unreader.py", line 64, in chunk
    return self.sock.recv(self.mxchunk)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
OSError: [Errno 9] Bad file descriptor

gunicorn is ran as gunicorn -b 0.0.0.0:80 --workers 4 --threads 4 --timeout 300 --access-logfile - inside docker.

benoitc · 2023-07-18T22:15:13Z

can someone test with the gh-thread branch ? #3033

alpden550 · 2023-07-19T07:57:23Z

Python 3.10.12 and latest gunicorn stil nas this error:

OSError: [Errno 9] Bad file descriptor

revanthmahesh · 2023-07-19T08:07:20Z

@alpden550 you can use pip install git+https://github.com/benoitc/gunicorn.git@fix-gthread or downgrade the gunicorn version for now. Until the fix is deployed by @benoitc

alpden550 · 2023-07-19T08:08:49Z

@revanthmahesh
thanks, I know and fixed gunicorn as gunicorn==20.1.0

oxtime · 2023-07-19T08:54:49Z

Python 3.6.7

OSError: [Errno 9] Bad file descriptor

benoitc · 2023-07-19T09:36:48Z

can someone test with the gh-thread branch ? #3033 Complaining that current release has an issue doesn't help that much. I don't reproduce the issue myself. thanks :)

geudrik · 2023-07-19T11:27:07Z

If it helps others down the road, we had a flask endpoint that would reliably fail / cause the bad file descriptor stack using 21.1.0. All it did was use requests to make an API call upstream and return the results.

I can't easily test with the gthread branch @benoitc, but maybe this info is enough for you to update your test and check?

benoitc · 2023-07-19T11:54:05Z

gunicorn 21.2.0 has been released which is fixing this issue.

benoitc self-assigned this Jul 18, 2023

benoitc added the unconfirmed label Jul 18, 2023

rporres mentioned this issue Jul 18, 2023

proper gunicorn version app-sre/github-mirror#97

Merged

snarfed mentioned this issue Jul 18, 2023

build(deps): bump gunicorn from 20.1.0 to 21.0.1 snarfed/bridgy-fed#591

Closed

benoitc mentioned this issue Jul 18, 2023

revert change considering connection as idle #3033

Merged

benoitc closed this as completed in #3033 Jul 19, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

last release (21.1.0) sends a lot of errors #3032

last release (21.1.0) sends a lot of errors #3032

wind-shift commented Jul 18, 2023

rafaeljuzwiak commented Jul 18, 2023

benoitc commented Jul 18, 2023 •

edited

Loading

rafaeljuzwiak commented Jul 18, 2023 •

edited

Loading

rafaeljuzwiak commented Jul 18, 2023

benoitc commented Jul 18, 2023 •

edited

Loading

xkobal commented Jul 18, 2023

benoitc commented Jul 18, 2023

xkobal commented Jul 18, 2023

wind-shift commented Jul 18, 2023 •

edited

Loading

xkobal commented Jul 18, 2023

wind-shift commented Jul 18, 2023 •

edited

Loading

xkobal commented Jul 18, 2023

mihalikv commented Jul 18, 2023

geudrik commented Jul 18, 2023 •

edited

Loading

isra17 commented Jul 18, 2023 •

edited

Loading

benoitc commented Jul 18, 2023

alpden550 commented Jul 19, 2023

revanthmahesh commented Jul 19, 2023

alpden550 commented Jul 19, 2023

oxtime commented Jul 19, 2023

benoitc commented Jul 19, 2023 •

edited

Loading

geudrik commented Jul 19, 2023 •

edited

Loading

benoitc commented Jul 19, 2023

last release (21.1.0) sends a lot of errors #3032

last release (21.1.0) sends a lot of errors #3032

Comments

wind-shift commented Jul 18, 2023

rafaeljuzwiak commented Jul 18, 2023

benoitc commented Jul 18, 2023 • edited Loading

rafaeljuzwiak commented Jul 18, 2023 • edited Loading

rafaeljuzwiak commented Jul 18, 2023

benoitc commented Jul 18, 2023 • edited Loading

xkobal commented Jul 18, 2023

benoitc commented Jul 18, 2023

xkobal commented Jul 18, 2023

wind-shift commented Jul 18, 2023 • edited Loading

xkobal commented Jul 18, 2023

wind-shift commented Jul 18, 2023 • edited Loading

xkobal commented Jul 18, 2023

mihalikv commented Jul 18, 2023

geudrik commented Jul 18, 2023 • edited Loading

isra17 commented Jul 18, 2023 • edited Loading

benoitc commented Jul 18, 2023

alpden550 commented Jul 19, 2023

revanthmahesh commented Jul 19, 2023

alpden550 commented Jul 19, 2023

oxtime commented Jul 19, 2023

benoitc commented Jul 19, 2023 • edited Loading

geudrik commented Jul 19, 2023 • edited Loading

benoitc commented Jul 19, 2023

benoitc commented Jul 18, 2023 •

edited

Loading

rafaeljuzwiak commented Jul 18, 2023 •

edited

Loading

benoitc commented Jul 18, 2023 •

edited

Loading

wind-shift commented Jul 18, 2023 •

edited

Loading

wind-shift commented Jul 18, 2023 •

edited

Loading

geudrik commented Jul 18, 2023 •

edited

Loading

isra17 commented Jul 18, 2023 •

edited

Loading

benoitc commented Jul 19, 2023 •

edited

Loading

geudrik commented Jul 19, 2023 •

edited

Loading