Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

SABnzbd client - ENGINE Error in HTTP server: shutting down #710

Open
1 of 3 tasks
ZoltrixGFC opened this issue May 12, 2024 · 16 comments
Open
1 of 3 tasks

SABnzbd client - ENGINE Error in HTTP server: shutting down #710

ZoltrixGFC opened this issue May 12, 2024 · 16 comments
Labels
bug Something is broken triage

Comments

@ZoltrixGFC
Copy link

ZoltrixGFC commented May 12, 2024

❓ I'm submitting a ...

  • 🐞 bug report
  • 🐣 feature request
  • ❓ question about the decisions made in the repository

🐞 Describe the bug. What is the current behavior?
Using SABnzbd 4.3.1 on Windows 11 Enterprise 23H2. Recently it has started to hang, displaying the following error in the logs just before it does hang:

Please, report this on the Cheroot tracker at <https://github.com/cherrypy/cheroot/issues/new/choose>, providing a full reproducer with as much context and details as possible.
Traceback (most recent call last):
  File "cheroot\workers\threadpool.py", line 119, in run
  File "cheroot\workers\threadpool.py", line 216, in _process_connections_until_interrupted
  File "cheroot\server.py", line 1364, in close
  File "cheroot\server.py", line 1484, in _close_kernel_socket
  File "ssl.py", line 1291, in shutdown
OSError: [WinError 10022] An invalid argument was supplied

2024-05-12 16:40:03,087::ERROR::[_cplogging:213] [12/May/2024:16:40:03] ENGINE Error in HTTP server: shutting down
Traceback (most recent call last):
  File "cherrypy\process\servers.py", line 225, in _start_http_thread
  File "cheroot\server.py", line 1845, in start
  File "cheroot\server.py", line 1833, in serve
  File "threading.py", line 1073, in _bootstrap_inner
  File "cheroot\workers\threadpool.py", line 119, in run
  File "cheroot\workers\threadpool.py", line 216, in _process_connections_until_interrupted
  File "cheroot\server.py", line 1364, in close
  File "cheroot\server.py", line 1484, in _close_kernel_socket
  File "ssl.py", line 1291, in shutdown
OSError: [WinError 10022] An invalid argument was supplied

πŸ’‘ To Reproduce
Queue up downloads in the SABnzbd client, after a period of time the client will hang and stop responding.

πŸ’‘ Expected behavior
Client not hang.

πŸ“‹ Details
Logs shown above.

πŸ“‹ Environment

  • Cheroot version: 10.0.1
  • CherryPy version: 18.9.0 (if applicable)
  • Python version: 3.12.3
  • OS: Windows 11 Enterprise
@Safihre
Copy link
Contributor

Safihre commented May 12, 2024

cheroot==10.0.1
cherrypy==18.9.0

Python version we use is 3.12.3, not 3.8 :)

@ZoltrixGFC
Copy link
Author

Just adding a more info.

It had been sitting idle for a while, then threw out the errors below and crashed.

2024-05-12 20:36:11,033::INFO::[postproc:138] Saving postproc queue
2024-05-12 20:36:11,033::INFO::[downloader:409] Post-processing finished, resuming download
2024-05-12 20:36:15,047::INFO::[nzbqueue:230] Saving queue
2024-05-12 20:36:15,049::INFO::[postproc:138] Saving postproc queue
2024-05-12 20:36:15,051::INFO::[notifier:157] Sending notification: SABnzbd - Queue finished (type=queue_done, job_cat=None)
2024-05-12 20:36:21,625::INFO::[_cplogging:213] [12/May/2024:20:36:21] ENGINE Client ('192.168.0.26', 58176) lost   peer dropped the TLS connection suddenly, during handshake: (8, '[SSL: UNEXPECTED_EOF_WHILE_READING] EOF occurred in violation of protocol (_ssl.c:1000)')
2024-05-12 20:36:21,628::INFO::[_cplogging:213] [12/May/2024:20:36:21] ENGINE Client ('192.168.0.26', 58164) lost   peer dropped the TLS connection suddenly, during handshake: (8, '[SSL: UNEXPECTED_EOF_WHILE_READING] EOF occurred in violation of protocol (_ssl.c:1000)')
2024-05-12 20:37:29,339::INFO::[database:208] [N/A] Moved job SABnzbd_nzo_2a1nfhb6 to archive
2024-05-12 21:10:33,102::INFO::[notifier:157] Sending notification: Error - [12/May/2024:21:10:33] ENGINE A fatal exception happened. Setting the server interrupt flag to OSError(22, 'An invalid argument was supplied', None, 10022, None) and giving up.

Please, report this on the Cheroot tracker at <https://github.com/cherrypy/cheroot/issues/new/choose>, providing a full reproducer with as much context and details as possible.
Traceback (most recent call last):
  File "cheroot\workers\threadpool.py", line 119, in run
  File "cheroot\workers\threadpool.py", line 216, in _process_connections_until_interrupted
  File "cheroot\server.py", line 1364, in close
  File "cheroot\server.py", line 1484, in _close_kernel_socket
  File "ssl.py", line 1291, in shutdown
OSError: [WinError 10022] An invalid argument was supplied
 (type=error, job_cat=None)
2024-05-12 21:10:33,102::CRITICAL::[_cplogging:213] [12/May/2024:21:10:33] ENGINE A fatal exception happened. Setting the server interrupt flag to OSError(22, 'An invalid argument was supplied', None, 10022, None) and giving up.

Please, report this on the Cheroot tracker at <https://github.com/cherrypy/cheroot/issues/new/choose>, providing a full reproducer with as much context and details as possible.
Traceback (most recent call last):
  File "cheroot\workers\threadpool.py", line 119, in run
  File "cheroot\workers\threadpool.py", line 216, in _process_connections_until_interrupted
  File "cheroot\server.py", line 1364, in close
  File "cheroot\server.py", line 1484, in _close_kernel_socket
  File "ssl.py", line 1291, in shutdown
OSError: [WinError 10022] An invalid argument was supplied

2024-05-12 21:10:33,250::ERROR::[_cplogging:213] [12/May/2024:21:10:33] ENGINE Error in HTTP server: shutting down
Traceback (most recent call last):
  File "cherrypy\process\servers.py", line 225, in _start_http_thread
  File "cheroot\server.py", line 1845, in start
  File "cheroot\server.py", line 1833, in serve
  File "threading.py", line 1073, in _bootstrap_inner
  File "cheroot\workers\threadpool.py", line 119, in run
  File "cheroot\workers\threadpool.py", line 216, in _process_connections_until_interrupted
  File "cheroot\server.py", line 1364, in close
  File "cheroot\server.py", line 1484, in _close_kernel_socket
  File "ssl.py", line 1291, in shutdown
OSError: [WinError 10022] An invalid argument was supplied

2024-05-12 21:10:33,250::INFO::[_cplogging:213] [12/May/2024:21:10:33] ENGINE Bus STOPPING
2024-05-12 21:10:33,354::INFO::[_cplogging:213] [12/May/2024:21:10:33] ENGINE HTTP Server cherrypy._cpwsgi_server.CPWSGIServer(('192.168.0.31', 10443)) shut down
2024-05-12 21:10:33,354::INFO::[_cplogging:213] [12/May/2024:21:10:33] ENGINE Bus STOPPED
2024-05-12 21:10:33,354::INFO::[_cplogging:213] [12/May/2024:21:10:33] ENGINE Bus EXITING
2024-05-12 21:10:33,354::INFO::[_cplogging:213] [12/May/2024:21:10:33] ENGINE Bus EXITED

@webknjaz
Copy link
Member

Are you able to come up with a Cheroot-only reproducer / regression test that would run in our CI? I haven't used Windows for like a decade so can't test it locally but a CI failure can be inspected remotely, if the need be...

@webknjaz
Copy link
Member

FWIW 10.0.1 contains some bugfixes that I thought should be backwards compatible. If 10.0.0 didn't fail, the regression is somewhere in the diff. Although, it's also possible that the problem existed before and got more evident with the patches around exception processing and logging..

@webknjaz
Copy link
Member

dupe of #375?

@ZoltrixGFC
Copy link
Author

Now starting to wonder if it was my reverse proxy causing the issue. I posted the following info on the SABnzbd thread:

In the errors I posted above, 192.168.0.26 is a docker host running nginx proxy. I had SSL enabled on SABnzbd running via the reverse proxy, and I noticed the SSL error listed above:

2024-05-12 20:36:21,625::INFO::[_cplogging:213] [12/May/2024:20:36:21] ENGINE Client ('192.168.0.26', 58176) lost   peer dropped the TLS connection suddenly, during handshake: (8, '[SSL: UNEXPECTED_EOF_WHILE_READING] EOF occurred in violation of protocol (_ssl.c:1000)')
2024-05-12 20:36:21,628::INFO::[_cplogging:213] [12/May/2024:20:36:21] ENGINE Client ('192.168.0.26', 58164) lost   peer dropped the TLS connection suddenly, during handshake: (8, '[SSL: UNEXPECTED_EOF_WHILE_READING] EOF occurred in violation of protocol (_ssl.c:1000)')

Last night I did a fresh install of SABnzbd, left SSL off, and set my other services to correct directly to SABnzbd (not via nginx), so far it has stayed up.

No idea if the reverse proxy could have been an issue at all?

@Safihre
Copy link
Contributor

Safihre commented May 14, 2024

@webknjaz Seems indeed #375.
This is not one that can just be caught like you implemented for the other problems?

@webknjaz
Copy link
Member

That was my working theory and I started researching it by checking out what Python stdlib does. Though, I didn't get to test it. If someone wants to check out if such a patch would work, please do and report back.

P.S. This issue also claims hanging which is something I'd expect to be impossible in v10.0.1. So it'd be nice to unpack what it means actually..

@webknjaz
Copy link
Member

2024-05-12 20:36:21,625::INFO::[_cplogging:213] [12/May/2024:20:36:21] ENGINE Client ('192.168.0.26', 58176) lost peer dropped the TLS connection suddenly, during handshake: (8, '[SSL: UNEXPECTED_EOF_WHILE_READING] EOF occurred in violation of protocol (_ssl.c:1000)')
2024-05-12 20:36:21,628::INFO::[_cplogging:213] [12/May/2024:20:36:21] ENGINE Client ('192.168.0.26', 58164) lost peer dropped the TLS connection suddenly, during handshake: (8, '[SSL: UNEXPECTED_EOF_WHILE_READING] EOF occurred in violation of protocol (_ssl.c:1000)')

I added these log entries in the last release to make it cleaner what's happening.. Hoping to improve the formatting later.

@webknjaz
Copy link
Member

No idea if the reverse proxy could have been an issue at all?

For that, I'd need to know how it's set up. The latest version shouldn't run out of threads and hang..

If you set it up to use plain http when connecting to the https port, it would obviously not work.

@dguilloryjr
Copy link

I have this issue happening on my device right now. I will post logs the next time it stops. I just turned on debug logging today...

@thezoggy
Copy link

thezoggy commented May 21, 2024

seen a few others reporting this issue, so far it seems like its only been reported since we upgraded cheroot from 10.0.0 to 10.0.1 (cherrypy==18.9.0 been the same on both versions).

Most of the users seem to be on windows. This morning a Windows 11 Enterprise (build 22631) user reported the issue has happening, goes to sleep and wakes up the next day to find application broken. It was just idling, but there are a few apps querying every 30s to check on status.. so 4x hits every 1 min (two hits from each app). So nothing to excessive, but per logs you just see the hits every 30s until eventually cheroot throws the error:

2024-05-20 18:19:31,125::CRITICAL::[_cplogging:213] [20/May/2024:18:19:31] ENGINE A fatal exception happened. Setting the server interrupt flag to OSError(22, 'An invalid argument was supplied', None, 10022, None) and giving up.

Please, report this on the Cheroot tracker at <https://github.com/cherrypy/cheroot/issues/new/choose>, providing a full reproducer with as much context and details as possible.
Traceback (most recent call last):
  File "cheroot\workers\threadpool.py", line 119, in run
  File "cheroot\workers\threadpool.py", line 216, in _process_connections_until_interrupted
  File "cheroot\server.py", line 1364, in close
  File "cheroot\server.py", line 1484, in _close_kernel_socket
OSError: [WinError 10022] An invalid argument was supplied

Confirmed with user they are not using a reverse proxy or anything. Only thing change was they upgraded to newer version of our app which included newer cheroot. Asked user to downgrade back to previous version of the app so it downgrades cheroot to 10.0.0 so we can confirm issue goes away.. which he has done now. So waiting to see.

I tried to replicate it myself on window10 but I have not been able to. :(

@Safihre
Copy link
Contributor

Safihre commented May 22, 2024

Since we got more complaints, I will 'fix' this for us by extending errors.acceptable_sock_shutdown_exceptions with OSError.
I (somewhat) understand you first want a reproducer before catching this, but I have end-users that I need to keep happy πŸ˜…

@AzureIP
Copy link

AzureIP commented Sep 17, 2024

Is there a version that endusers like me can update to, to become happy again?

@Safihre
Copy link
Contributor

Safihre commented Sep 17, 2024

Do you have the latest SABnzbd? Because it should catch those errors.

@AzureIP
Copy link

AzureIP commented Sep 17, 2024

Sorry, I read not enougth. I don't use SABnzbd. My problem is more in the direction of issue 375, and only because someone asked if this is related, it does not mean it is really related.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something is broken triage
Projects
None yet
Development

No branches or pull requests

6 participants