Bug 56336 - UMC-Server: RuntimeError: fetch() called on closed AsyncHTTPClient
Summary: UMC-Server: RuntimeError: fetch() called on closed AsyncHTTPClient
Status: CLOSED FIXED
Alias: None
Product: UCS
Classification: Unclassified
Component: UMC (Generic)
Version: UCS 5.0
Hardware: Other Linux
: P5 normal
Target Milestone: UCS 5.0-4-errata
Assignee: Florian Best
QA Contact: Christian Castens
URL: https://git.knut.univention.de/univen...
Keywords:
: 57485 58530 (view as bug list)
Depends on: 56198
Blocks: 56391
  Show dependency tree / graph
 
Reported: 2023-07-18 22:40 CEST by Florian Best
Modified: 2025-08-25 09:30 CEST (History)
4 users (show)

See Also:
What kind of report is it?: Bug Report
What type of bug is this?: 3: Simply Wrong: The implementation doesn't match the docu
Who will be affected by this bug?: 3: Will affect average number of installed domains
How will those affected feel about the bug?: 2: A Pain – users won’t like this once they notice it
User Pain: 0.103
Enterprise Customer affected?:
School Customer affected?: Yes
ISV affected?:
Waiting Support:
Flags outvoted (downgraded) after PO Review:
Ticket number: 2023071821000452, 2023072021000181, 2023071821000452, 2023073021000134, 2023091121000265, 2023090521000277, 2023083121000121, 2023083021000294, 2023082921000386, 2023082521000188, 2023082421000199, 2023082421000206, 2023082421000181, 2023082421000117
Bug group (optional): External feedback
Customer ID: 09711
Max CVSS v3 score:

Attachments
Add an attachment (proposed patch, testcase, etc.)

Note You need to log in before you can comment on or make changes to this bug.
Description Florian Best univentionstaff 2023-07-18 22:40:38 CEST 
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
Comment 1 Christina Scheinig univentionstaff 2023-07-21 09:15:21 CEST 
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
Comment 2 Florian Best univentionstaff 2023-07-21 10:04:37 CEST 
This is caused by Bug #56198 - errata721.
Comment 3 Florian Best univentionstaff 2023-07-21 10:13:01 CEST 
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.
Comment 5 Florian Best univentionstaff 2023-07-25 17:09:00 CEST 
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.
Comment 6 Christian Castens univentionstaff 2023-07-26 13:54:28 CEST 
-> 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..
Comment 7 Christina Scheinig univentionstaff 2023-07-27 11:20:17 CEST 
Do we have a workaround for that, so that the customer can use the reports again?
Comment 8 Florian Best univentionstaff 2023-07-27 11:27:46 CEST 
(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.
Comment 9 Mika Westphal univentionstaff 2023-07-28 14:50:55 CEST 
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
Comment 10 Dirk Ahrnke univentionstaff 2023-07-28 17:18:59 CEST 
Also reported by customer during training as happening on a productive school replica with e750.
Comment 11 Florian Best univentionstaff 2023-08-02 11:34:05 CEST 
(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.
Comment 12 Christian Castens univentionstaff 2023-08-02 11:37:36 CEST 
ok, 
status -> verified fixed
Comment 13 Christian Castens univentionstaff 2023-08-02 16:06:27 CEST 
<https://errata.software-univention.de/#/?erratum=5.0x765>
Comment 15 Mika Westphal univentionstaff 2023-09-18 11:57:19 CEST 
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
Comment 16 Mika Westphal univentionstaff 2023-10-06 11:38:53 CEST 
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
Comment 17 Mika Westphal univentionstaff 2023-12-08 10:42:39 CET 
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
Comment 18 Florian Best univentionstaff 2025-08-25 09:30:31 CEST 
*** Bug 57485 has been marked as a duplicate of this bug. ***
Comment 19 Florian Best univentionstaff 2025-08-25 09:30:36 CEST 
*** Bug 58530 has been marked as a duplicate of this bug. ***