Univention Bugzilla – Bug 56336
UMC-Server: RuntimeError: fetch() called on closed AsyncHTTPClient
Last modified: 2023-12-08 10:42:39 CET
Version: 5.0-4 errata740 Error: Traceback (most recent call last): File "%PY3%/tornado/web.py", line 1595, in _execute result = yield result File "%PY3%/tornado/gen.py", line 1133, in run value = future.result() File "%PY3%/univention/management/console/resources.py", line 728, in get self.future = process.request(self.request.method, self.request.full_url(), body=self.request.body or None, headers=headers) File "%PY3%/univention/management/console/resources.py", line 263, in request response = self.do_request(method, uri, headers, body, self.socket) File "%PY3%/univention/management/console/resources.py", line 147, in do_request return self._wrap_future(self._client.fetch(request, raise_error=True)) File "%PY3%/tornado/httpclient.py", line 256, in fetch raise RuntimeError("fetch() called on closed AsyncHTTPClient") RuntimeError: fetch() called on closed AsyncHTTPClient
Occured several times in a customer environment. 20.07.23 11:40:06 ERROR ( 31556) : 500 POST /univention/command/udm/reports/query (127.0.0.1) 4.08ms 20.07.23 11:40:06 ERROR ( 31556) : Uncaught exception POST /univention/command/udm/types (127.0.0.1) HTTPServerRequest(protocol='https', host='ucs.annonymized-customer.de', method='POST', uri='/univention/command/udm/types', version='HTTP/1.1', remote_ip='127.0.0.1') Traceback (most recent call last): File "/usr/lib/python3/dist-packages/tornado/web.py", line 1595, in _execute result = yield result File "/usr/lib/python3/dist-packages/tornado/gen.py", line 1133, in run value = future.result() File "/usr/lib/python3/dist-packages/univention/management/console/resources.py", line 728, in get self.future = process.request(self.request.method, self.request.full_url(), body=self.request.body or None, headers=headers) File "/usr/lib/python3/dist-packages/univention/management/console/resources.py", line 263, in request response = self.do_request(method, uri, headers, body, self.socket) File "/usr/lib/python3/dist-packages/univention/management/console/resources.py", line 147, in do_request return self._wrap_future(self._client.fetch(request, raise_error=True)) File "/usr/lib/python3/dist-packages/tornado/httpclient.py", line 256, in fetch raise RuntimeError("fetch() called on closed AsyncHTTPClient") RuntimeError: fetch() called on closed AsyncHTTPClient
This is caused by Bug #56198 - errata721.
happens in combination with: Traceback (most recent call last): File "/usr/lib/python3/dist-packages/tornado/http1connection.py", line 735, in _server_request_loop ret = yield conn.read_response(request_delegate) File "/usr/lib/python3/dist-packages/tornado/gen.py", line 1133, in run value = future.result() File "/usr/lib/python3/dist-packages/tornado/gen.py", line 1147, in run yielded = self.gen.send(value) File "/usr/lib/python3/dist-packages/tornado/http1connection.py", line 245, in _read_message self.stream.set_close_callback(self._on_connection_close) File "/usr/lib/python3/dist-packages/tornado/iostream.py", line 606, in set_close_callback self._maybe_add_error_listener() File "/usr/lib/python3/dist-packages/tornado/iostream.py", line 1128, in _maybe_add_error_listener self._add_io_state(ioloop.IOLoop.READ) File "/usr/lib/python3/dist-packages/tornado/iostream.py", line 1158, in _add_io_state self.fileno(), self._handle_events, self._state) File "/usr/lib/python3/dist-packages/tornado/platform/asyncio.py", line 76, in add_handler raise ValueError("fd %s added twice" % fd) ValueError: fd 17 added twice So if the browser closes the HTTP socket connection we are closing the socket to the module processes manually. Tornado provides no way to abort open connections/requests. We don't remove the file descriptor from tornado/asyncio's select()-poll() implementation. Therefore when a new socket with the same FD number is added above exception happens. This might be the reason for the follow up RuntimeError exceptions.
commit 45c125a118a31945a5f3470ce6b8efa0a8d948d2 fix(umc): defer delegation of socket closing to session end timeout Closing a HTTP socket connection should not immediately cause that the UMC module process socket is closed as well. Otherwise we have to intefere into Tornado/asyncio socket handling which causes follow up errors. When the session ends it's safer to close the connection. Still follow up error can occur. The session timeout nowadays defaults to 28800 seconds. So module processes are still opened very long in case of aborted requests. But that's 1. more like the behavior from the old UMC-Webserver and 2. better than blocking further requests in the same session.
-> reopened for now During the QA we observed that the inspected appcenter module process was never terminated after its socket connections had been closed. We have to investigate this behavior further. Tested with: Log output: tail -f /var/log/univention/management-console-{module-appcenter,server}.log Settings: ucr set umc/module/timeout=30 systemctl restart univention-management-console-server touch /var/run/univention-appcenter.lock Execute: pgrep -fl 'univention-management-console-module.*appcenter' # no process curl http://Administrator:univention@localhost:8090/command/appcenter/keep_alive -X POST ^C # after some seconds just exit that request pgrep -fl 'univention-management-console-module.*appcenter' # process runs, seems to never stop..
Do we have a workaround for that, so that the customer can use the reports again?
(In reply to Christina Scheinig from comment #7) > Do we have a workaround for that, so that the customer can use the reports > again? you could apply this patch temporarily, https://github.com/univention/univention-corporate-server/commit/45c125a118a31945a5f3470ce6b8efa0a8d948d2.patch It won't make it worse. In bad cases there would be processes which don't end themself only after a UMC-Server restart.
Version: 5.0-4 errata740 Error: Traceback (most recent call last): File "%PY3%/tornado/web.py", line 1595, in _execute result = yield result File "%PY3%/tornado/gen.py", line 1133, in run value = future.result() File "%PY3%/univention/management/console/resources.py", line 728, in get self.future = process.request(self.request.method, self.request.full_url(), body=self.request.body or None, headers=headers) File "%PY3%/univention/management/console/resources.py", line 263, in request response = self.do_request(method, uri, headers, body, self.socket) File "%PY3%/univention/management/console/resources.py", line 147, in do_request return self._wrap_future(self._client.fetch(request, raise_error=True)) File "%PY3%/tornado/httpclient.py", line 256, in fetch raise RuntimeError("fetch() called on closed AsyncHTTPClient") RuntimeError: fetch() called on closed AsyncHTTPClient Role: domaincontroller_master
Also reported by customer during training as happening on a productive school replica with e750.
(In reply to Christian Castens from comment #6) > -> reopened for now Split into Bug #56391. The behavior is better than before and more equal to before Bug #56198 except that the requests are aborted at session-timeout. We release this now and provide a proper fix via Bug #56391 later on.
ok, status -> verified fixed
<https://errata.software-univention.de/#/?erratum=5.0x765>
2023091221000414 5.0-4 errata771 Traceback (most recent call last): File "%PY3%/tornado/web.py", line 1595, in _execute result = yield result File "%PY3%/tornado/gen.py", line 1133, in run value = future.result() File "%PY3%/univention/management/console/resources.py", line 726, in get self.future = process.request(self.request.method, self.request.full_url(), body=self.request.body or None, headers=headers) File "%PY3%/univention/management/console/resources.py", line 263, in request response = self.do_request(method, uri, headers, body, self.socket) File "%PY3%/univention/management/console/resources.py", line 147, in do_request return self._wrap_future(self._client.fetch(request, raise_error=True)) File "%PY3%/tornado/httpclient.py", line 256, in fetch raise RuntimeError("fetch() called on closed AsyncHTTPClient") RuntimeError: fetch() called on closed AsyncHTTPClient
2023100521000131 5.0-4 errata783 - UCS@school 5.0 v3 Remark: Tritt vermehrt auf. Zufälliges Auftreten. Meist beim bearbeiten von Nutzereinstellungen Traceback (most recent call last): File "%PY3%/tornado/web.py", line 1595, in _execute result = yield result File "%PY3%/tornado/gen.py", line 1133, in run value = future.result() File "%PY3%/univention/management/console/resources.py", line 726, in get self.future = process.request(self.request.method, self.request.full_url(), body=self.request.body or None, headers=headers) File "%PY3%/univention/management/console/resources.py", line 263, in request response = self.do_request(method, uri, headers, body, self.socket) File "%PY3%/univention/management/console/resources.py", line 147, in do_request return self._wrap_future(self._client.fetch(request, raise_error=True)) File "%PY3%/tornado/httpclient.py", line 256, in fetch raise RuntimeError("fetch() called on closed AsyncHTTPClient") RuntimeError: fetch() called on closed AsyncHTTPClient
2023120121000269 5.0-4 errata783 - UCS@school 5.0 v3 Traceback (most recent call last): File "%PY3%/tornado/web.py", line 1595, in _execute result = yield result File "%PY3%/tornado/gen.py", line 1133, in run value = future.result() File "%PY3%/univention/management/console/resources.py", line 726, in get self.future = process.request(self.request.method, self.request.full_url(), body=self.request.body or None, headers=headers) File "%PY3%/univention/management/console/resources.py", line 263, in request response = self.do_request(method, uri, headers, body, self.socket) File "%PY3%/univention/management/console/resources.py", line 147, in do_request return self._wrap_future(self._client.fetch(request, raise_error=True)) File "%PY3%/tornado/httpclient.py", line 256, in fetch raise RuntimeError("fetch() called on closed AsyncHTTPClient") RuntimeError: fetch() called on closed AsyncHTTPClient