7636 – asyncore is deprecated

Bug 7636 - asyncore is deprecated

Summary: asyncore is deprecated

Status:	RESOLVED FIXED

Alias:	None

Product:	ThinLinc
Classification:	Unclassified
Component:	Other (show other bugs)

Target Milestone:	4.16.0
Assignee:	Pierre Ossman

URL:
Keywords:

Depends on:	8224 7648 8230 8232 8242
Blocks:
	Show dependency tree / graph

Reported:	2021-02-03 12:55 CET by Pierre Ossman
Modified:	2023-12-06 09:43 CET (History)
CC List:	5 users (show)

See Also:	8159 8161 8162 8222 2670 8230 5676
Acceptance Criteria:	MUST: * ThinLinc no longer relies on the system asyncore module * The main loop is asyncio based so that asyncio tasks and callbacks can be scheduled SHOULD: * There is no coroutine syntax in ThinLinc code (new or old syntax) * Everything uses asyncio terminology rather than asyncore such * There is no ThinLinc code that is redundant with asyncio functionality * Everything is converted to asyncio models and abstractions (e.g. protocols)

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

Description Pierre Ossman cendio

2021-02-03 12:55:47 CET

Python has decided that asyncore is deprecated in favour of asyncio. This is a major problem for us as asyncore is the foundation for vsmserver and vsmagent. We need to change those to get away from the asyncore dependency.

The recommended replacement, asyncio, is only available from Python 3.6. We are currently targeting 3.4 so we cannot use that until we've raised our system requirements. That likely means when SLE 12 and Ubuntu 16.04 are EOL in 2024.

Note that Python developers originally planned on removing asyncore in Python 3.8, but seemed to have come to their senses and are now keeping it around until they feel that everyone no longer has to support old versions of Python. We'll see what that means in practice.

Comment 1 William Sjöblom cendio

2022-01-26 11:34:39 CET

Here is the upstream issue discussing the matter: https://bugs.python.org/issue28533

It seems like the planned removal of asyncore is for Python 3.11. Since we are already at Python 3.10 in the current Fedora 35, this issue becomes somewhat more pressing.

Worth noting is that the Python documentation states that asyncio has been shipped with Python since version 3.4 on a provisional basis (see the first couple of sentences in https://docs.python.org/3.5/library/asyncio.html) which might be of value regarding a decision for this matter.

Comment 2 Samuel Mannehed cendio

2022-01-26 12:10:49 CET

I'm getting a deprecation warning now on Fedora 35 (Python 3.10.1):

> $ /opt/thinlinc/sbin/tl-show-licenses 
> /opt/thinlinc/modules/thinlinc/vsm/asyncbase.py:21: DeprecationWarning: The asyncore module is deprecated. The recommended replacement is asyncio
>   import asyncore

Comment 3 Pierre Ossman cendio

2022-01-26 12:48:53 CET

So upstream tried dropping this in 3.11:

https://github.com/python/cpython/commit/9bf2cbc4c498812e14f20d86acb61c53928a5a57

But it got reverted again:

https://github.com/python/cpython/commit/cf7eaa4617295747ee5646c4e2b7e7a16d7c64ab

The reasoning is found here:

https://github.com/python/steering-council/issues/86

Basically their rules say that they should have a deprecation notice for two releases before anything is allowed to be removed. That notice was added to 3.11, and also backported to 3.10.1.

That probably means that 3.12 is the earliest it will be removed. It could be delayed further, but I would say that is unlikely as they've already had a commit applied to remove it before.

Comment 4 Pierre Ossman cendio

2022-01-26 12:52:07 CET

Ubuntu 16.04 is now out of normal support (since April 2021), so the limiting factor here is SLES 12. I'll poke SUSE and see if I can get an update on getting a newer Python on that platform.

Comment 5 Samuel Mannehed cendio

2022-01-26 13:17:41 CET

(In reply to Samuel Mannehed from comment #2)
> I'm getting a deprecation warning now on Fedora 35 (Python 3.10.1):
> 
> > $ /opt/thinlinc/sbin/tl-show-licenses 
> > /opt/thinlinc/modules/thinlinc/vsm/asyncbase.py:21: DeprecationWarning: The asyncore module is deprecated. The recommended replacement is asyncio
> >   import asyncore

This only shows up on manual builds, won't show up for customers.

Comment 6 Pierre Ossman cendio

2022-07-05 13:11:20 CEST

That warning also shows up when tl-collect-licensestats is run, which results in a mail from cron every time.

Comment 7 Samuel Mannehed cendio

2023-08-29 19:41:18 CEST

Fedoras plans to include Python 3.12 in Fedora 39 [1] which will be released Q4 2023. That would likely translate into RHEL 10 (Q2 2025) [2].

Ubuntu 22.04 shipped with Python 3.10 [3] (which was released a few months prior [4]). Judging from the past, it is possible that Python 3.12 will be included in the next LTS (24.04) [5].

As far as SLES goes, I don't think we need to be concerned. SLES 15 ships with Python 3.6 which is old now.

[1]: https://fedoraproject.org/wiki/Changes/Python3.12
[2]: https://access.redhat.com/articles/3078
[3]: https://changelogs.ubuntu.com/changelogs/pool/main/p/python3.10/python3.10_3.10.2-1/changelog
[4]: https://devguide.python.org/versions/
[5]: https://wiki.ubuntu.com/Releases

Comment 10 Samuel Mannehed cendio

2023-09-01 15:50:17 CEST

Helpful reading material:

https://www.andy-pearce.com/blog/posts/2016/Jul/the-state-of-python-coroutines-asyncio-callbacks-vs-coroutines/
https://www.erichgrunewald.com/posts/gradually-migrating-python-code-to-asyncio/
https://docs.python.org/3/library/asyncore.html
https://docs.python.org/3.5/library/asyncio.html

Comment 11 Pierre Ossman cendio

2023-09-07 13:31:53 CEST

We've decided to go with the recommended approach of switching to asyncio. We won't fully embrace the asyncio style, though, in that we'll stick to their callback API rather than their coroutine API.

The reason for this is to make the system more robust, as it is easy to lose track of the control flow when using coroutines. For the servers, the robustness is more important than simpler code. Other parts of the product might use asyncio in the future.

This decision hopefully also means we can continue supporting Python 3.4. We'll need to test and see how it works, as Python haven't documented the changes between 3.4 and 3.6 in detail.


Also worth noting is that we cannot define our own coroutines without raising the requirements to Python 3.6. The reason being that the async/await syntax isn't available until Python 3.6, and Python are dropping support for abusing "yield from" to write coroutines soon.

Comment 16 Pierre Ossman cendio

2023-09-12 14:52:23 CEST

It looks like asyncio.ensure_future() is useful and maybe critical to bridge coroutines and callbacks. Unfortunately, it was renamed from asyncio.async() in 3.4.4. That older name is no longer present in modern Python.

So it might be problematic to support Python 3.4.0, like we currently state. SLES 12 seems to have Python 3.4.6, so we can probably get away with raising the requirement a bit, though.

Comment 17 Pierre Ossman cendio

2023-09-13 15:04:53 CEST

Apparently, there is a big mess around reference counting and asyncio tasks. The documentation warns about this:

https://docs.python.org/3/library/asyncio-task.html#asyncio.create_task

> Important
> 
> Save a reference to the result of this function, to avoid a task disappearing
> mid-execution. The event loop only keeps weak references to tasks. A task that
> isn’t referenced elsewhere may get garbage collected at any time, even before
> it’s done. For reliable “fire-and-forget” background tasks, gather them in a
> collection: 

There are some upstream issues discussing this:

https://github.com/python/cpython/issues/88831
https://github.com/python/cpython/issues/91887

And a lot of discussion on stack overflow, where this post explains the problem best:

https://stackoverflow.com/questions/71938799/python-asyncio-create-task-really-need-to-keep-a-reference/76823668#76823668

This is likely something we need to keep in mind.

Comment 18 Pierre Ossman cendio

2023-09-13 16:14:31 CEST

As mentioned in the comments on that Stack Overflow, I think this can only happen if your code is already buggy. The short of it is this:

1. The loop holds STRONG references to everything that is scheduled to run. Doesn't matter if it is now, or later. I.e. all loop.call_*().

2. If a task isn't scheduled to run, that means it is waiting for something.

3. Task can only wait for one thing; futures. So the task must be waiting for a future.

4. The task has registered a callback with said future. Meaning the future has a  STRONG reference to the task.

5. If that future is ever to complete, then someone must be holding a reference to it. Likely a STRONG one.

If it's unreferenced, then the task can never continue, and maybe it's a good thing it gets mopped up by the garbage collector?

Comment 28 Adam Halim cendio

2023-10-19 17:29:22 CEST

Here is a summary of how error handling/logging is done 4.15.0 compared to the current build.

In general, 4.15.0 has no higher level catch-all to prevent the process from dying in case of programmer error. A crash in AsyncProcess.handle_read() for example would kill the server. Behaviours are similar between 4.15.0 and 4.15.post, where some information is less detailed in some places, but more detailed in others.

In the current implementation, it seems that as long as the initial startup works without issue, any uncaught exceptions will be handled by the exception handler in asyncbase.py

extproc
----------------------------------------
4.15.0:
A timeout in /opt/thinlinc/etc/sessionstartup.d/ is logged as 
> 2023-10-17 09:42:42 WARNING vsmserver.extproc: Timeout running ['/opt/thinlinc/etc/sessionstartup.d/test.sh']
> 2023-10-17 09:42:42 INFO vsmserver.extproc: ['/opt/thinlinc/etc/sessionstartup.d/test.sh'] exited with exit code -15
and a startup script that crashes is logged as
> 2023-10-17 09:40:20 INFO vsmserver.extproc: ['/opt/thinlinc/etc/sessionstartup.d/test.sh'] exited with exit code 127
> 2023-10-17 09:40:20 WARNING vsmserver.extproc: ['/opt/thinlinc/etc/sessionstartup.d/test.sh'] wrote to stderr: /opt/thinlinc/etc/sessionstartup.d/test.sh: line 2: bogus: command not found

4.15post:
This is very similar to how logging is done currently, where a timeout is logged as 
> 2023-10-17 14:23:31 ERROR vsmserver: Timeout running /opt/thinlinc/etc/sessionstartup.d/test.sh
and a crash is logged as 
> 2023-10-17 14:24:35 WARNING vsmserver: /opt/thinlinc/etc/sessionstartup.d/test.sh wrote to stderr: /opt/thinlinc/etc/sessionstartup.d/test.sh: line 3: bogus: command not found
> 
> 2023-10-17 14:24:35 INFO vsmserver: /opt/thinlinc/etc/sessionstartup.d/test.sh exited with exit code 127

4.15.0:
Exceptions that occur when running a subprocess are logged as follows:
> 2023-10-19 14:43:11 ERROR vsmagent.extproc: OSError: "Exception!" when trying to start ss
This was tested by raising an OSError() before running subprocess.Popen().

4.15post:
This behaviour is similar in the current implementation, but the responsibility of error handling has been moved to subclasses of VSMAgentHandler::handle(). The error is also now logged on both the server and the client.
> 2023-10-18 09:16:32 ERROR vsmagent: Exception when running ss: Exception!
> 
> 2023-10-18 09:16:32 WARNING vsmserver.session: Exception when getting user groups: <class 'Exception'>
Inside of subprocess_run(), there are three layers where an exception could occur. The first place is the outmost layer of the function, before any async calls are made. If something crashes here, the following message is logged (tested by raising an exception at the beginning of subprocess_run()):

> 2023-10-19 14:59:22 ERROR vsmserver: Unhandled XMLRPC exception: <class 'Exception'> Exception! Traceback (most recent call last):
>   File "/opt/thinlinc/modules/thinlinc/vsm/xmlrpc.py", line 486, in _handle_request
>     self . handle_method ( )
>   File "/opt/thinlinc/modules/thinlinc/vsm/usersocketserverchannel.py", line 86, in handle_method
>     ii1iIi1i11i ( self . vsmserver , sock = self . socket ) . handle ( self . methodname ,
>   File "/opt/thinlinc/modules/thinlinc/vsm/handler_getusersessions.py", line 64, in handle
>     iii111 = get_user_groups ( iiIi1 , self . log . session )
>              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
>   File "/opt/thinlinc/modules/thinlinc/vsm/extproc.py", line 123, in get_user_groups
>     process_result = subprocess_run(*args, env={"USER": username})
>                      ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
>   File "/opt/thinlinc/modules/thinlinc/vsm/extproc.py", line 37, in subprocess_run
>     raise Exception("Exception!")
> Exception: Exception!
The second layer is inside the asynchronous function, but outside a try-catch block. Raising an exception at the beginning of get_result() gives the following log:

> 2023-10-19 15:03:02 ERROR vsmserver: Exception in callback subprocess_run.<locals>.get_result(<Process 26534>, <Future pendi...extproc.py:78>, encoding=None, errors=None)(<Task finishe.../tasks.py:670>) at /opt/thinlinc/modules/thinlinc/vsm/extproc.py:37
> 2023-10-19 15:03:02 ERROR vsmserver: handle: <Handle subprocess_run.<locals>.get_result(<Process 26534>, <Future pendi...extproc.py:78>, encoding=None, errors=None)(<Task finishe.../tasks.py:670>) at /opt/thinlinc/modules/thinlinc/vsm/extproc.py:37 created at /usr/lib64/python3.11/asyncio/events.py:80>
> 2023-10-19 15:03:02 ERROR vsmserver: ----------------------------------------
> 2023-10-19 15:03:02 ERROR vsmserver: Object created at (most recent call last):
> 2023-10-19 15:03:02 ERROR vsmserver:   File "/opt/thinlinc/sbin/vsmserver", line 74, in <module>
> 2023-10-19 15:03:02 ERROR vsmserver:     iIi1ii1I1iI11 ( )
> 2023-10-19 15:03:02 ERROR vsmserver:   File "/opt/thinlinc/sbin/vsmserver", line 63, in iIi1ii1I1iI11
> 2023-10-19 15:03:02 ERROR vsmserver:     OoO . loop ( )
> 2023-10-19 15:03:02 ERROR vsmserver:   File "/opt/thinlinc/modules/thinlinc/vsm/asyncbase.py", line 224, in loop
> 2023-10-19 15:03:02 ERROR vsmserver:     self . run_forever ( )
> 2023-10-19 15:03:02 ERROR vsmserver:   File "/usr/lib64/python3.11/asyncio/base_events.py", line 607, in run_forever
> 2023-10-19 15:03:02 ERROR vsmserver:     self._run_once()
> 2023-10-19 15:03:02 ERROR vsmserver:   File "/usr/lib64/python3.11/asyncio/base_events.py", line 1914, in _run_once
> 2023-10-19 15:03:02 ERROR vsmserver:     handle._run()
> 2023-10-19 15:03:02 ERROR vsmserver:   File "/usr/lib64/python3.11/asyncio/events.py", line 80, in _run
> 2023-10-19 15:03:02 ERROR vsmserver:     self._context.run(self._callback, *self._args)
> 2023-10-19 15:03:02 ERROR vsmserver: ----------------------------------------
> 2023-10-19 15:03:02 ERROR vsmserver: Traceback (most recent call last):
> 2023-10-19 15:03:02 ERROR vsmserver:   File "/usr/lib64/python3.11/asyncio/events.py", line 80, in _run
> 2023-10-19 15:03:02 ERROR vsmserver:     self._context.run(self._callback, *self._args)
> 2023-10-19 15:03:02 ERROR vsmserver:   File "/opt/thinlinc/modules/thinlinc/vsm/extproc.py", line 38, in get_result
> 2023-10-19 15:03:02 ERROR vsmserver:     raise Exception("Exception!")
> 2023-10-19 15:03:02 ERROR vsmserver: Exception: Exception!
> 2023-10-19 15:03:02 ERROR vsmserver: ----------------------------------------
Lastly, an exception that occurs in a try-catch block will set the exception on the future, and the exception is handled by the VSMAgentHandler::handle():
> 2023-10-18 09:16:32 ERROR vsmagent: Exception when running ss: Exception!
> 2023-10-18 09:16:32 WARNING vsmserver.session: Exception when getting user groups: <class 'Exception'>
xmlrpc
----------------------------------------
4.15.0
Following is the behaviour when a crash occurs in the callback of an RPC call, which was tested by raising an exception in call_unbindports.py::handle_returnvalue():

> 2023-10-18 14:50:35 ERROR vsmserver.session: Unhandled exception trying to unbind ports for display 14 on VSM Agent 127.0.0.1:904: <class 'Exception'> Exception! Traceback (most recent call last):
>   File "/opt/thinlinc/modules/thinlinc/vsm/asyncbase.py", line 105, in handle_read
>     obj.handle_read_event()
>   File "/usr/lib64/python3.11/asyncore.py", line 425, in handle_read_event
>     self.handle_read()
>   File "/usr/lib64/python3.11/asynchat.py", line 158, in handle_read
>     self.found_terminator()
>   File "/opt/thinlinc/modules/thinlinc/vsm/xmlrpc.py", line 424, in found_terminator
>     self.handle_response()
>   File "/opt/thinlinc/modules/thinlinc/vsm/xmlrpc.py", line 456, in handle_response
>     self.handle_returnvalue()
>   File "/opt/thinlinc/modules/thinlinc/vsm/call_unbindports.py", line 41, in handle_returnvalue
>     raise Exception("Exception!")
> Exception: Exception!
> . Marking agent as down.
Note that the agent is not actually marked as down, and the session is created as usual.

4.15post
The entire VSMXMLRPCCall class has been removed in the current implementation, and functionality has been moved to a more general function in vsmxmlrpccall.py::call_method(). The equivalent callback is now loginhandler_common.py::_unbind_ports_done(), which also is responsible for the error handling. Currently, none of the handlers print a traceback, which all previous calls did. Raising an exception in _unbind_ports_done() gives the following error message:

> 2023-10-18 14:52:41 WARNING vsmserver: Error unbinding ports for session 127.0.0.1:13: Exception!

LicenseHandler
----------------------------------------
The function update_licenses() is first called synchronously, and later asynchronously repeatedly at a set interval. In the synchronous case, an exception was simply raised at the beginning of the function. For the asynchronous case, I added a boolean to only raise the exception the second time the function is called. When the function is run synchronously and crashes, we get the following error message:

4.15.0
> 2023-10-16 13:16:16 INFO vsmserver.license: Updating license data from disk to memory
> Traceback (most recent call last):
>   File "/opt/thinlinc/sbin/vsmserver", line 18, in <module>
>     OOoOoo000O00 ( )
>   File "/opt/thinlinc/sbin/vsmserver", line 15, in OOoOoo000O00
>     VSMServer ( sys . argv )
>   File "/opt/thinlinc/modules/thinlinc/vsm/vsmserver.py", line 114, in __init__
>     self . licensehandler . update_licenses ( )
>   File "/opt/thinlinc/modules/thinlinc/vsm/licensehandler.py", line 188, in update_licenses
>     raise Exception("Exception!")
> Exception: Exception!
When the function is run in an asynchronous context and crashes, the following error message is produced:
> Traceback (most recent call last):
>   File "/opt/thinlinc/sbin/vsmserver", line 18, in <module>
>     OOoOoo000O00 ( )
>   File "/opt/thinlinc/sbin/vsmserver", line 15, in OOoOoo000O00
>     VSMServer ( sys . argv )
>   File "/opt/thinlinc/modules/thinlinc/vsm/vsmserver.py", line 168, in __init__
>     self . loop ( )
>   File "/opt/thinlinc/modules/thinlinc/vsm/asyncbase.py", line 426, in loop
>     OooO0O00o0 = self . run_delayed_calls ( )
>                 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
>   File "/opt/thinlinc/modules/thinlinc/vsm/asyncbase.py", line 384, in run_delayed_calls
>     I1I1IIi1IIIi . func ( * I1I1IIi1IIIi . args , ** I1I1IIi1IIIi . kw )
>   File "/opt/thinlinc/modules/thinlinc/vsm/licensehandler.py", line 190, in update_licenses
>     raise Exception("Exception!")
> Exception: Exception!
4.15post
The synchronous behaviour is unchanged in the current implementation
> 2023-10-16 13:12:51 INFO vsmserver.license: Updating license data from disk to memory
> Traceback (most recent call last):
>   File "/opt/thinlinc/sbin/vsmserver", line 74, in <module>
>     iIi1ii1I1iI11 ( )
>   File "/opt/thinlinc/sbin/vsmserver", line 56, in iIi1ii1I1iI11
>     iiI1111IIi1 = VSMServer ( oOooo0OOO , Iio0 )
>                   ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
>   File "/opt/thinlinc/modules/thinlinc/vsm/vsmserver.py", line 77, in __init__
>     self._update_licenses()
>   File "/opt/thinlinc/modules/thinlinc/vsm/vsmserver.py", line 154, in _update_licenses
>     self.licensehandler.update_licenses()
>   File "/opt/thinlinc/modules/thinlinc/vsm/licensehandler.py", line 186, in update_licenses
>     raise Exception("Exception!")
> Exception: Exception!
but in the async contxt, the error is caught by the error handler in asyncbase.py:
> 2023-10-16 13:31:00 INFO vsmserver.license: Updating license data from disk to memory
> 2023-10-16 13:31:00 ERROR vsmserver: Exception in callback VSMServer._update_licenses()
> 2023-10-16 13:31:00 ERROR vsmserver: handle: <TimerHandle when=18730.975908411 VSMServer._update_licenses() created at /opt/thinlinc/modules/thinlinc/vsm/vsmserver.py:156>
> 2023-10-16 13:31:00 ERROR vsmserver: ----------------------------------------
> 2023-10-16 13:31:00 ERROR vsmserver: Object created at (most recent call last):
> 2023-10-16 13:31:00 ERROR vsmserver:   File "/opt/thinlinc/sbin/vsmserver", line 74, in <module>
> 2023-10-16 13:31:00 ERROR vsmserver:     iIi1ii1I1iI11 ( )
> 2023-10-16 13:31:00 ERROR vsmserver:   File "/opt/thinlinc/sbin/vsmserver", line 56, in iIi1ii1I1iI11
> 2023-10-16 13:31:00 ERROR vsmserver:     iiI1111IIi1 = VSMServer ( oOooo0OOO , Iio0 )
> 2023-10-16 13:31:00 ERROR vsmserver:   File "/opt/thinlinc/modules/thinlinc/vsm/vsmserver.py", line 77, in __init__
> 2023-10-16 13:31:00 ERROR vsmserver:     self._update_licenses()
> 2023-10-16 13:31:00 ERROR vsmserver:   File "/opt/thinlinc/modules/thinlinc/vsm/vsmserver.py", line 156, in _update_licenses
> 2023-10-16 13:31:00 ERROR vsmserver:     get_event_loop().call_later(10, self._update_licenses)
> 2023-10-16 13:31:00 ERROR vsmserver: ----------------------------------------
> 2023-10-16 13:31:00 ERROR vsmserver: Traceback (most recent call last):
> 2023-10-16 13:31:00 ERROR vsmserver:   File "/usr/lib64/python3.11/asyncio/events.py", line 80, in _run
> 2023-10-16 13:31:00 ERROR vsmserver:     self._context.run(self._callback, *self._args)
> 2023-10-16 13:31:00 ERROR vsmserver:   File "/opt/thinlinc/modules/thinlinc/vsm/vsmserver.py", line 154, in _update_licenses
> 2023-10-16 13:31:00 ERROR vsmserver:     self.licensehandler.update_licenses()
> 2023-10-16 13:31:00 ERROR vsmserver:   File "/opt/thinlinc/modules/thinlinc/vsm/licensehandler.py", line 188, in update_licenses
> 2023-10-16 13:31:00 ERROR vsmserver:     raise Exception("Exception!")
> 2023-10-16 13:31:00 ERROR vsmserver: Exception: Exception!
> 2023-10-16 13:31:00 ERROR vsmserver: ----------------------------------------

CheckTCPPortOpen
----------------------------------------
To test what happens in the case of a timeout, I put a sleep(50) in handle_connect_event() and got timed out after 40 seconds as expected:

4.15.0
> 2023-10-16 14:44:27 INFO vsmserver.session: User with uid 1000 (cendio) requested a new session
> 2023-10-16 14:45:07 WARNING vsmserver: Timeout trying to start new session for cendio on VSM Agent 127.0.0.1:904
> 2023-10-16 14:45:07 WARNING vsmserver.loadinfo: Agent 127.0.0.1 failed to start session, Increasing penalty points by 5 to 5
> 2023-10-16 14:45:07 WARNING vsmserver: No working agents found trying to start new session for cendio
The class still depends on asyncore and will be tested after it is converted fully to asynico.

Comment 30 Linn cendio

2023-10-27 16:35:40 CEST

(In reply to Adam Halim from comment #28)
> Here is a summary of how error handling/logging is done 4.15.0 compared to
> the current build.
> ...
> extproc
> ----------------------------------------
> 4.15.0:
> A timeout in /opt/thinlinc/etc/sessionstartup.d/ is logged as 
> > 2023-10-17 09:42:42 WARNING vsmserver.extproc: Timeout running ['/opt/thinlinc/etc/sessionstartup.d/test.sh']
> > 2023-10-17 09:42:42 INFO vsmserver.extproc: ['/opt/thinlinc/etc/sessionstartup.d/test.sh'] exited with exit code -15
> ...
> 4.15post:
> This is very similar to how logging is done currently, where a timeout is
> logged as 
> > 2023-10-17 14:23:31 ERROR vsmserver: Timeout running /opt/thinlinc/etc/sessionstartup.d/test.sh
When updating extproc to use asyncio, the timeout logging was accidentally changed from WARNING to ERROR. This was changed back in commit r40578, and the updated logging for a timeout is:
> 2023-10-27 16:30:50 WARNING vsmserver: Timeout running /opt/thinlinc/etc/sessionstartup.d/10-echo-startup.sh

Comment 32 Linn cendio

2023-11-01 09:32:09 CET

xmlrpc.py
---------
Timeouts
========
To start the countdown for a timeout, function _activate_timeout() is called. I added sleep calls right after the countdown had been started.

4.15.0
A timeout in XMLRPCClientChannel is logged as:
> 2023-10-31 12:57:17 INFO vsmserver.session: User with uid 1000 (cendio) requested a new session
> 2023-10-31 12:58:57 WARNING vsmserver: Timeout getting load from VSM Agent 127.0.0.1:904, marking as down
> 2023-10-31 12:58:57 WARNING vsmserver: No working agents found trying to start new session for cendio
> 2023-10-31 12:58:57 WARNING vsmserver: Timeout getting load from VSM Agent 127.0.0.1:904, marking as down
A timeout in XMLRPXServerChannel is logged as:
When calling sleep in __init__:
> 2023-10-31 14:43:54 WARNING vsmserver: Timeout getting load from VSM Agent 127.0.0.1:904, marking as down
> 2023-10-31 14:44:45 WARNING vsmserver: Timeout communicating with socket ('127.0.0.1', 35116), closing
When calling sleep in handle_response:
> 2023-10-31 16:20:11 INFO vsmserver.session: User with uid 1000 (cendio) requested a new session
> 2023-10-31 16:20:21 WARNING vsmserver: Timeout getting load from VSM Agent 127.0.0.1:904, marking as down
> 2023-10-31 16:20:21 WARNING vsmserver: No working agents found trying to start new session for cendio

4.15.post:
After the changes, ClientProtocol does no longer internally use _activate_timeout. This kind of timeout is instead handled by VSMXMLRPCCall.call_method, which was tested in comment 28.

A timeout when calling sleep in ServerProtocol.connection_made is logged as:
> 2023-10-31 16:38:34 WARNING vsmserver.loadinfo: Error getting load from agent 127.0.0.1: Operation timed out
> 2023-10-31 16:38:34 WARNING vsmserver.loadinfo: Marking agent 127.0.0.1 as down
> Executing <Handle ServerProtocol.connection_made(<_SelectorSoc...e, bufsize=0>>) created at /usr/lib64/python3.9/asyncio/selector_events.py:774> took 50.032 seconds
A timeout when calling sleep in ServerProtocol._write_response is logged as:
> 2023-10-31 17:09:41 WARNING vsmserver.loadinfo: Marking agent 127.0.0.1 as down
> Executing <Handle ServerProtocol._callback_done(<Future finis...server.py:309>) created at /opt/thinlinc/modules/thinlinc/vsm/vsmserver.py:391> took 50.051 seconds
The last line in both cases looks very similar to the one as found in comment 31. I did not dig deeper into why/when this kind of logging occurs, or if the logging only is shown in devmode or not.

Comment 34 Samuel Mannehed cendio

2023-11-10 11:46:57 CET

I'm also getting similar log lines in vsmserver.log as described in comment 32:

> 2023-11-10 11:40:51 INFO vsmagent.session: Verified connectivity to newly started Xvnc for test9
> Executing <Handle ReqSessionHandler._checked_vnc_socket(<Task finishe.../tasks.py:685>) created at /usr/lib64/python3.12/asyncio/events.py:84> took 0.144 seconds
> Executing <TimerHandle when=8007.594749 VSMAgent.housekeeping() created at /opt/thinlinc/modules/thinlinc/vsm/vsmagent.py:135> took 0.134 seconds

Comment 35 Linn cendio

2023-11-10 14:39:27 CET

Differences between error handling between XMLRPCClientChannel and ClientProtocol in xmlrpc

Some of the error handling has been moved out of the XMLRPCClientChannel from its constructor into call_method, which was covered when testing xmlrpc calls in comment 28. Below are the categories of exceptions I found.

XML marshalling exceptions
==========================

4.15.0
There are two places that can raise errors regarding XML marshalling in 4.15.0. I have manually raised exceptions to trigger them. In the logging below, some values of variables have been replaced with "..." to save space.

Logging when raising an exception in XMLRPCClientChannel.create_xmlrpc_call:
> Traceback (most recent call last):
>   File "/opt/thinlinc/modules/thinlinc/vsm/xmlrpc.py", line 369, in create_xmlrpc_call
>     raise ValueError("LINN custom error")
> ValueError: LINN custom error
> 
> During handling of the above exception, another exception occurred:
> 
> Traceback (most recent call last):
>   File "/opt/thinlinc/sbin/vsmserver", line 18, in <module>
>     OOoOoo000O00 ( )
>   File "/opt/thinlinc/sbin/vsmserver", line 15, in OOoOoo000O00
>     VSMServer ( sys . argv )
>   File "/opt/thinlinc/modules/thinlinc/vsm/vsmserver.py", line 168, in __init__
>     self . loop ( )
>   File "/opt/thinlinc/modules/thinlinc/vsm/asyncbase.py", line 426, in loop
>     OooO0O00o0 = self . run_delayed_calls ( )
>   File "/opt/thinlinc/modules/thinlinc/vsm/asyncbase.py", line 384, in run_delayed_calls
>     I1I1IIi1IIIi . func ( * I1I1IIi1IIIi . args , ** I1I1IIi1IIIi . kw )
>   File "/opt/thinlinc/modules/thinlinc/vsm/loadbalancer.py", line 198, in periodic_update
>     GetLoadCall ( OO00OOooO , ii , self . periodic_update ,
>   File "/opt/thinlinc/modules/thinlinc/vsm/call_getload.py", line 25, in __init__
>     self . xmlrpc_call ( 'get_load' )
>   File "/opt/thinlinc/modules/thinlinc/vsm/xmlrpc.py", line 335, in xmlrpc_call
>     self . create_xmlrpc_call ( methodname , params )
>   File "/opt/thinlinc/modules/thinlinc/vsm/xmlrpc.py", line 371, in create_xmlrpc_call
>     raise XMLMarshallingError ( [ str ( o0o0Oo00000o ) , params , methodname ] )
> thinlinc.vsm.xmlrpc.XMLMarshallingError: ['LINN custom error', (), 'get_load']
Logging when raising an exception in XMLRPCClientChannel.handle_response:
> 2023-11-01 14:00:33 ERROR vsmserver: Exception in error handler for <thinlinc.vsm.call_verifysessions.VerifySessionsCall 127.0.0.1:904 at 0x7f5f6f
> 89b430, callback: <bound method SessionStore.verify_sessions_finished of <thinlinc.vsm.sessionstore.SessionStore object at 0x7f5f6f86a100>>>: <class 'IndexError'> tuple index out of range
> Traceback (most recent call last):
>   File "/opt/thinlinc/modules/thinlinc/vsm/xmlrpc.py", line 451, in handle_response
>     raise ValueError("LINN custom error")
> ValueError: LINN custom error
> 
> During handling of the above exception, another exception occurred:
> 
> Traceback (most recent call last):
>   File "/opt/thinlinc/modules/thinlinc/vsm/asyncbase.py", line 104, in ooOOOoOO0
>     obj . handle_read_event ( )
>   File "/usr/lib64/python3.9/asyncore.py", line 420, in handle_read_event
>     self.handle_read()
>   File "/usr/lib64/python3.9/asynchat.py", line 151, in handle_read
>     self.found_terminator()
>   File "/opt/thinlinc/modules/thinlinc/vsm/xmlrpc.py", line 425, in found_terminator
>     self . handle_response ( )
>   File "/opt/thinlinc/modules/thinlinc/vsm/xmlrpc.py", line 453, in handle_response
>     raise XMLDeMarshallingError ( [ str ( o0o0Oo00000o ) , self . payload ] )
> thinlinc.vsm.xmlrpc.XMLDeMarshallingError: ['LINN custom error', b"..."]
We see that both these exceptions are not handled with the correct logging format, since most or all lines are missing the logging prefix with date and time.

4.15post
In 4.15 post there are still two places that raises errors regarding XML marshalling and demarshalling. In the logging below, some values of variables have been replaced with "..." to save space.

When raising exception in ClientProtocol._write_request:
> 2023-11-01 14:54:28 ERROR vsmserver: handle: <Handle call_method.<locals>.IiI1I(<Task finishe...xmlrpc.py:472>) at /opt/thinlinc/modules/thinlinc/vsm/xmlrpc.py:435 created at /usr/lib64/python3.9/asyncio/events.py:80>
> 2023-11-01 14:54:28 ERROR vsmserver: ----------------------------------------
> 2023-11-01 14:54:28 ERROR vsmserver: Object created at (most recent call last):
> 2023-11-01 14:54:28 ERROR vsmserver:   File "/opt/thinlinc/sbin/vsmserver", line 74, in <module>
> 2023-11-01 14:54:28 ERROR vsmserver:     iIi1ii1I1iI11 ( )
> 2023-11-01 14:54:28 ERROR vsmserver:   File "/opt/thinlinc/sbin/vsmserver", line 63, in iIi1ii1I1iI11
> 2023-11-01 14:54:28 ERROR vsmserver:     OoO . loop ( )
> 2023-11-01 14:54:28 ERROR vsmserver:   File "/opt/thinlinc/modules/thinlinc/vsm/asyncbase.py", line 218, in loop
> 2023-11-01 14:54:28 ERROR vsmserver:     self . run_forever ( )
> 2023-11-01 14:54:28 ERROR vsmserver:   File "/usr/lib64/python3.9/asyncio/base_events.py", line 601, in run_forever
> 2023-11-01 14:54:28 ERROR vsmserver:     self._run_once()
> 2023-11-01 14:54:28 ERROR vsmserver:   File "/usr/lib64/python3.9/asyncio/base_events.py", line 1897, in _run_once
> 2023-11-01 14:54:28 ERROR vsmserver:     handle._run()
> 2023-11-01 14:54:28 ERROR vsmserver:   File "/usr/lib64/python3.9/asyncio/events.py", line 80, in _run
> 2023-11-01 14:54:28 ERROR vsmserver:     self._context.run(self._callback, *self._args)
> 2023-11-01 14:54:28 ERROR vsmserver: ----------------------------------------
> 2023-11-01 14:54:28 ERROR vsmserver: Traceback (most recent call last):
> 2023-11-01 14:54:28 ERROR vsmserver:   File "/opt/thinlinc/modules/thinlinc/vsm/xmlrpc.py", line 100, in _write_request
> 2023-11-01 14:54:28 ERROR vsmserver:     raise ValueError("LINN custom error")
> 2023-11-01 14:54:28 ERROR vsmserver: ValueError: LINN custom error
> 2023-11-01 14:54:28 ERROR vsmserver:
> 2023-11-01 14:54:28 ERROR vsmserver: The above exception was the direct cause of the following exception:
> 2023-11-01 14:54:28 ERROR vsmserver:
> 2023-11-01 14:54:28 ERROR vsmserver: Traceback (most recent call last):
> 2023-11-01 14:54:28 ERROR vsmserver:   File "/usr/lib64/python3.9/asyncio/events.py", line 80, in _run
> 2023-11-01 14:54:28 ERROR vsmserver:     self._context.run(self._callback, *self._args)
> 2023-11-01 14:54:28 ERROR vsmserver:   File "/opt/thinlinc/modules/thinlinc/vsm/xmlrpc.py", line 447, in IiI1I
> 2023-11-01 14:54:28 ERROR vsmserver:     IiI111111i1 = i1i1 . call_method ( methodname , * params )
> 2023-11-01 14:54:28 ERROR vsmserver:   File "/opt/thinlinc/modules/thinlinc/vsm/xmlrpc.py", line 82, in call_method
> 2023-11-01 14:54:28 ERROR vsmserver:     self . _write_request ( methodname , * params )
> 2023-11-01 14:54:28 ERROR vsmserver:   File "/opt/thinlinc/modules/thinlinc/vsm/xmlrpc.py", line 102, in _write_request
> 2023-11-01 14:54:28 ERROR vsmserver:     raise XMLMarshallingError ( "Error encoding XML-RPC call %s%r: %s" %
> 2023-11-01 14:54:28 ERROR vsmserver: thinlinc.vsm.xmlrpc.XMLMarshallingError: Error encoding XML-RPC call get_load(): LINN custom error
> 2023-11-01 14:54:28 ERROR vsmserver: ----------------------------------------
When raising exception in ClientProtocol._handle_response:
> 2023-11-01 15:02:54 WARNING vsmserver: Error checking if agent 127.0.0.1 is alive: Error parsing XML-RPC response b"...": LINN custom error
When using asyncio, the traceback have the correct logging format and the demarshalling error is now logged as a regular log line instead of a traceback.


Exceptions when handling data
=============================

4.15.0
There are also some exceptions that can be cast when incoming data is handled, found in XMLRPCClientChannel.found_terminator.

Logging for XMLRPCClientChannel.collect_incoming_data when incoming data is too long:
> 2023-11-10 09:35:12 WARNING vsmserver.loadinfo: Connection to 127.0.0.1:904 closed before receiving response in request for loadinfo. Marking as down.
Logging when XMLRPCClientChannel.found_terminator casts InvalidHTTPResponse due to encoding error:
> 2023-11-07 12:30:29 WARNING vsmserver.loadinfo: HTTP Error from VSM Agent 127.0.0.1:904 in request for loadinfo. Marking as down.
Logging when XMLRPCClientChannel.found_terminator casts HTTPResponseNotOK (I set the response code to 44444):
> 2023-11-07 15:57:42 ERROR vsmserver: Exception in error handler for <thinlinc.vsm.call_getload.GetLoadCall 127.0.0.1:904 at 0x7f36fc6c6400, callback: <bound method NewSessionHandler.find_best_agent of <thinlinc.vsm.handler_newsession.NewSessionHandler connected b'\x006eac4' at 0x7f36fc6c6160>>>: <class 'IndexError'> tuple index out of range
> Traceback (most recent call last):
>   File "/opt/thinlinc/modules/thinlinc/vsm/asyncbase.py", line 104, in ooOOOoOO0
>     obj . handle_read_event ( )
>   File "/usr/lib64/python3.9/asyncore.py", line 420, in handle_read_event
>     self.handle_read()
>   File "/usr/lib64/python3.9/asynchat.py", line 171, in handle_read
>     self.found_terminator()
>   File "/opt/thinlinc/modules/thinlinc/vsm/xmlrpc.py", line 414, in found_terminator
>     raise HTTPResponseNotOK ( self . response )
> thinlinc.vsm.xmlrpc.HTTPResponseNotOK: ['HTTP/1.1', '44444', 'OK']
The first two exceptions are logged appropriately, but the last one does not follow the logging format for the traceback.

4.15post
The replacement for 4.15.0's XMLRPCClientChannel.found_terminator and XMLRPCClientChannel.collect_incoming_data can be found in ClientProtocol._process_data.

Logging for ClientProtocol._process_data when incoming data is too long:
> 2023-11-10 10:03:26 WARNING vsmserver: Error checking if agent 127.0.0.1 is alive: Excessive response data
> 2023-11-10 10:03:26 WARNING vsmserver: Marking agent 127.0.0.1 as down
Logging when ClientProtocol._process_data casts InvalidHTTPResponse due to raised encoding error (note that a real HTTP status line would include a non-ascii character to cast this error):
> 2023-11-07 16:41:21 WARNING vsmserver: Error checking if agent 127.0.0.1 is alive: Invalid HTTP status line: b'HTTP/1.1 200 OK\r\n'
> 2023-11-07 16:41:21 WARNING vsmserver: Marking agent 127.0.0.1 as down
Logging when ClientProtocol._process_data casts HTTPResponseNotOK due to bad response code (when setting the response code to 44444):
> 2023-11-07 16:45:26 WARNING vsmserver: Error checking if agent 127.0.0.1 is alive: Request rejected by server: '44444' 'OK\r\n'
> 2023-11-07 16:45:26 WARNING vsmserver: Marking agent 127.0.0.1 as down
All these exceptions are now logged in a very similar format, explaining what went wrong and when it happened, as well as logging the marking agent as down.

Comment 36 Linn cendio

2023-11-13 15:45:28 CET

Here are the differences between error handling between XMLRPCServerChannel and ServerProtocol in xmlrpc. In the logging below, some values of variables have been replaced with "..." to save space.

XML marshalling exceptions
==========================

4.15.0
There are two places that can raise errors regarding XML marshalling in 4.15.0. I have manually raised exceptions to trigger them.

Logging when raising an exception in XMLRPCServerChannel.handle_response:
> 2023-11-13 10:39:40 ERROR vsmserver: Unhandled XMLRPC exception: <class 'thinlinc.vsm.xmlrpc.XMLMarshallingError'> ['LINN custom error', ('/var/run/thinlinc/master/1000',), None]
> Traceback (most recent call last):
>   File "/opt/thinlinc/modules/thinlinc/vsm/xmlrpc.py", line 608, in handle_response
>     raise TypeError("LINN custom error")
> TypeError: LINN custom error
> 
> During handling of the above exception, another exception occurred:
> 
> Traceback (most recent call last):
>   File "/opt/thinlinc/modules/thinlinc/vsm/asyncbase.py", line 104, in ooOOOoOO0
>     obj . handle_read_event ( )
>   File "/usr/lib64/python3.9/asyncore.py", line 420, in handle_read_event
>     self.handle_read()
>   File "/usr/lib64/python3.9/asynchat.py", line 151, in handle_read
>     self.found_terminator()
>   File "/opt/thinlinc/modules/thinlinc/vsm/xmlrpc.py", line 565, in found_terminator
>     self . handle_request ( )
>   File "/opt/thinlinc/modules/thinlinc/vsm/xmlrpc.py", line 580, in handle_request
>     self . handle_method ( )
>   File "/opt/thinlinc/modules/thinlinc/vsm/vsmserverchannel.py", line 120, in handle_method
>     O0o0OOoOOOO ( self . vsmserver , sock = self . socket ) . handle ( self . methodname ,
>   File "/opt/thinlinc/modules/thinlinc/vsm/handler_createusersocket.py", line 28, in handle
>     self . create_socket ( Ooo )
>   File "/opt/thinlinc/modules/thinlinc/vsm/handler_createusersocket.py", line 44, in create_socket
>     self . handle_response ( i11IiIIiii1II )
>   File "/opt/thinlinc/modules/thinlinc/vsm/xmlrpc.py", line 610, in handle_response
>     raise XMLMarshallingError ( [ str ( o0o0Oo00000o ) , params , None ] )
> thinlinc.vsm.xmlrpc.XMLMarshallingError: ['LINN custom error', ('/var/run/thinlinc/master/1000',), None]
Logging when raising an exception in XMLRPCServerChannel.handle_request:
> 2023-11-13 10:27:52 ERROR vsmserver: Unhandled XMLRPC exception: <class 'thinlinc.vsm.xmlrpc.XMLDeMarshallingError'> ['LINN custom error', b"..."] Traceback (most recent call last):
>   File "/opt/thinlinc/modules/thinlinc/vsm/xmlrpc.py", line 576, in handle_request
>     raise ValueError("LINN custom error")
> ValueError: LINN custom error
> 
> During handling of the above exception, another exception occurred:
> 
> Traceback (most recent call last):
>   File "/opt/thinlinc/modules/thinlinc/vsm/asyncbase.py", line 104, in ooOOOoOO0
>     obj . handle_read_event ( )
>   File "/usr/lib64/python3.9/asyncore.py", line 420, in handle_read_event
>     self.handle_read()
>   File "/usr/lib64/python3.9/asynchat.py", line 151, in handle_read
>     self.found_terminator()
>   File "/opt/thinlinc/modules/thinlinc/vsm/xmlrpc.py", line 565, in found_terminator
>     self . handle_request ( )
>   File "/opt/thinlinc/modules/thinlinc/vsm/xmlrpc.py", line 578, in handle_request
>     raise XMLDeMarshallingError ( [ str ( o0o0Oo00000o ) , self . payload ] )
> thinlinc.vsm.xmlrpc.XMLDeMarshallingError: ['LINN custom error', b"..."]
> 
> 2023-11-13 10:27:54 WARNING vsmserver.loadinfo: Connection to 127.0.0.1:904 closed before receiving response in request for loadinfo. Marking as down.
We see that the traceback in both cases have the wrong logging format, since the lines are missing the logging prefix.

4.15post
Logging when raising an exception in ServerProtocol._write_response:
> 2023-11-13 11:19:12 ERROR vsmserver: handle: <Handle ServerProtocol._callback_done(<Future finis...server.py:309>) created at /opt/thinlinc/modules/thinlinc/vsm/vsmserver.py:391>
> 2023-11-13 11:19:12 ERROR vsmserver: ----------------------------------------
> 2023-11-13 11:19:12 ERROR vsmserver: Object created at (most recent call last):
> 2023-11-13 11:19:12 ERROR vsmserver:   File "/opt/thinlinc/sbin/vsmserver", line 74, in <module>
> 2023-11-13 11:19:12 ERROR vsmserver:     iIi1ii1I1iI11 ( )
> 2023-11-13 11:19:12 ERROR vsmserver:   File "/opt/thinlinc/sbin/vsmserver", line 63, in iIi1ii1I1iI11
> 2023-11-13 11:19:12 ERROR vsmserver:     OoO . loop ( )
> 2023-11-13 11:19:12 ERROR vsmserver:   File "/opt/thinlinc/modules/thinlinc/vsm/asyncbase.py", line 218, in loop
> 2023-11-13 11:19:12 ERROR vsmserver:     self . run_forever ( )
> 2023-11-13 11:19:12 ERROR vsmserver:   File "/usr/lib64/python3.9/asyncio/base_events.py", line 601, in run_forever
> 2023-11-13 11:19:12 ERROR vsmserver:     self._run_once()
> 2023-11-13 11:19:12 ERROR vsmserver:   File "/usr/lib64/python3.9/asyncio/base_events.py", line 1897, in _run_once
> 2023-11-13 11:19:12 ERROR vsmserver:     handle._run()
> 2023-11-13 11:19:12 ERROR vsmserver:   File "/usr/lib64/python3.9/asyncio/events.py", line 80, in _run
> 2023-11-13 11:19:12 ERROR vsmserver:     self._context.run(self._callback, *self._args)
> 2023-11-13 11:19:12 ERROR vsmserver:   File "/opt/thinlinc/modules/thinlinc/vsm/vsmserver.py", line 391, in _handle_method_done
> 2023-11-13 11:19:12 ERROR vsmserver:     response . set_result ( call . result ( ) )
> 2023-11-13 11:19:12 ERROR vsmserver: ----------------------------------------
> 2023-11-13 11:19:12 ERROR vsmserver: Traceback (most recent call last):
> 2023-11-13 11:19:12 ERROR vsmserver:   File "/opt/thinlinc/modules/thinlinc/vsm/xmlrpc.py", line 387, in _write_response
> 2023-11-13 11:19:12 ERROR vsmserver:     raise TypeError("LINN custom error")
> 2023-11-13 11:19:12 ERROR vsmserver: TypeError: LINN custom error
> 2023-11-13 11:19:12 ERROR vsmserver: 
> 2023-11-13 11:19:12 ERROR vsmserver: The above exception was the direct cause of the following exception:
> 2023-11-13 11:19:12 ERROR vsmserver: 
> 2023-11-13 11:19:12 ERROR vsmserver: Traceback (most recent call last):
> 2023-11-13 11:19:12 ERROR vsmserver:   File "/usr/lib64/python3.9/asyncio/events.py", line 80, in _run
> 2023-11-13 11:19:12 ERROR vsmserver:     self._context.run(self._callback, *self._args)
> 2023-11-13 11:19:12 ERROR vsmserver:   File "/opt/thinlinc/modules/thinlinc/vsm/xmlrpc.py", line 370, in _callback_done
> 2023-11-13 11:19:12 ERROR vsmserver:     self . _write_response ( II1I1Ii1IIi )
> 2023-11-13 11:19:12 ERROR vsmserver:   File "/opt/thinlinc/modules/thinlinc/vsm/xmlrpc.py", line 390, in _write_response
> 2023-11-13 11:19:12 ERROR vsmserver:     raise XMLMarshallingError ( "Error encoding XML-RPC response %r: %s" %
> 2023-11-13 11:19:12 ERROR vsmserver: thinlinc.vsm.xmlrpc.XMLMarshallingError: Error encoding XML-RPC response '/var/run/thinlinc/master/1000': LINN custom error
> 2023-11-13 11:19:12 ERROR vsmserver: ----------------------------------------
Logging when raising an exception in ServerProtocol._handle_request:
> 2023-11-13 11:11:19 WARNING vsmserver.loadinfo: Error getting load from agent 127.0.0.1: [Errno 111] Connect call failed ('127.0.0.1', 904)
> 2023-11-13 11:11:19 WARNING vsmserver.loadinfo: Marking agent 127.0.0.1 as down
After swapping to asyncio, the first traceback is now logged with the correct logging format. The other traceback has been shortened to a regular log message, and the agent is still marked as down.


Exceptions when handling data
=============================

There are also some exceptions that can be cast when incoming data is handled.

4.15.0
Logging for XMLRPCServerChannel.found_terminator when incoming data is too long:
> 2023-11-13 13:29:48 WARNING vsmserver.loadinfo: [Errno 111] Connection refused talking to VSM Agent 127.0.0.1:904 in request for loadinfo. Marking as down.
> 2023-11-13 13:30:37 WARNING vsmserver: Timeout communicating with socket ('127.0.0.1', 36764), closing
Logging when raising UnicodeDecodeError in XMLRPCServerChannel.found_terminator:
> 2023-11-13 10:44:43 WARNING vsmserver.loadinfo: [Errno 111] Connection refused talking to VSM Agent 127.0.0.1:904 in request for loadinfo. Marking as down.
We see that too long incoming data triggered a timeout, and that a unicode error triggered a regular log line.

4.15post
Logging for ServerProtocol.data_recieved when incoming data is too long:
> 2023-11-13 13:32:12 WARNING vsmserver.loadinfo: Error getting load from agent 127.0.0.1: [Errno 111] Connect call failed ('127.0.0.1', 904)
> 2023-11-13 13:32:12 WARNING vsmserver.loadinfo: Marking agent 127.0.0.1 as down
> 2023-11-13 13:33:32 ERROR vsmserver: Exception in callback call_method.<locals>.OO(<Future finis...xmlrpc.py:477>) at /opt/thinlinc/modules/thinlinc/vsm/vsmxmlrpccall.py:140
> 2023-11-13 13:33:32 ERROR vsmserver: handle: <Handle call_method.<locals>.OO(<Future finis...xmlrpc.py:477>) at /opt/thinlinc/modules/thinlinc/vsm
> /vsmxmlrpccall.py:140 created at /opt/thinlinc/modules/thinlinc/vsm/xmlrpc.py:465>
> 2023-11-13 13:33:32 ERROR vsmserver: ----------------------------------------
> 2023-11-13 13:33:32 ERROR vsmserver: Object created at (most recent call last):
> 2023-11-13 13:33:32 ERROR vsmserver:   File "/opt/thinlinc/sbin/vsmserver", line 74, in <module>
> 2023-11-13 13:33:32 ERROR vsmserver:     iIi1ii1I1iI11 ( )
> 2023-11-13 13:33:32 ERROR vsmserver:   File "/opt/thinlinc/sbin/vsmserver", line 63, in iIi1ii1I1iI11
> 2023-11-13 13:33:32 ERROR vsmserver:     OoO . loop ( )
> 2023-11-13 13:33:32 ERROR vsmserver:   File "/opt/thinlinc/modules/thinlinc/vsm/asyncbase.py", line 218, in loop
> 2023-11-13 13:33:32 ERROR vsmserver:     self . run_forever ( )
> 2023-11-13 13:33:32 ERROR vsmserver:   File "/usr/lib64/python3.9/asyncio/base_events.py", line 601, in run_forever
> 2023-11-13 13:33:32 ERROR vsmserver:     self._run_once()
> 2023-11-13 13:33:32 ERROR vsmserver:   File "/usr/lib64/python3.9/asyncio/base_events.py", line 1897, in _run_once
> 2023-11-13 13:33:32 ERROR vsmserver:     handle._run()
> 2023-11-13 13:33:32 ERROR vsmserver:   File "/usr/lib64/python3.9/asyncio/events.py", line 80, in _run
> 2023-11-13 13:33:32 ERROR vsmserver:     self._context.run(self._callback, *self._args)
> 2023-11-13 13:33:32 ERROR vsmserver:   File "/opt/thinlinc/modules/thinlinc/vsm/xmlrpc.py", line 465, in i1iiiIii
> 2023-11-13 13:33:32 ERROR vsmserver:     I1II1IIIi . set_exception ( i11iIii )
> 2023-11-13 13:33:32 ERROR vsmserver: ----------------------------------------
> 2023-11-13 13:33:32 ERROR vsmserver: Traceback (most recent call last):
> 2023-11-13 13:33:32 ERROR vsmserver:   File "/opt/thinlinc/modules/thinlinc/vsm/vsmxmlrpccall.py", line 144, in OO
> 2023-11-13 13:33:32 ERROR vsmserver:     II . set_result ( call . result ( ) )
> 2023-11-13 13:33:32 ERROR vsmserver:   File "/opt/thinlinc/modules/thinlinc/vsm/xmlrpc.py", line 463, in i1iiiIii
> 2023-11-13 13:33:32 ERROR vsmserver:     I1II1IIIi . set_result ( call . result ( ) )
> 2023-11-13 13:33:32 ERROR vsmserver: thinlinc.vsm.xmlrpc.ConnectionClosed: Connection closed unexpectedly
> 2023-11-13 13:33:32 ERROR vsmserver: 
> 2023-11-13 13:33:32 ERROR vsmserver: During handling of the above exception, another exception occurred:
> 2023-11-13 13:33:32 ERROR vsmserver: 
> 2023-11-13 13:33:32 ERROR vsmserver: Traceback (most recent call last):
> 2023-11-13 13:33:32 ERROR vsmserver:   File "/usr/lib64/python3.9/asyncio/events.py", line 80, in _run
> 2023-11-13 13:33:32 ERROR vsmserver:     self._context.run(self._callback, *self._args)
> 2023-11-13 13:33:32 ERROR vsmserver:   File "/opt/thinlinc/modules/thinlinc/vsm/vsmxmlrpccall.py", line 146, in OO
> 2023-11-13 13:33:32 ERROR vsmserver:     II . set_exception ( OO0000 )
> 2023-11-13 13:33:32 ERROR vsmserver: asyncio.exceptions.InvalidStateError: invalid state
> 2023-11-13 13:33:32 ERROR vsmserver: ----------------------------------------
> 2023-11-13 13:33:32 WARNING vsmserver.loadinfo: Error getting load from agent 127.0.0.1: Operation timed out
> 2023-11-13 13:33:32 WARNING vsmserver.loadinfo: Marking agent 127.0.0.1 as down
Logging when raising UnicodeDecodeError in ServerProtocol.data_recieved:
> 2023-11-13 11:27:40 WARNING vsmserver.loadinfo: Error getting load from agent 127.0.0.1: Request rejected by server: '400' 'Invalid request\r\n'
> 2023-11-13 11:27:40 WARNING vsmserver.loadinfo: Marking agent 127.0.0.1 as down
Logging when incoming data is too long still warns about failed connection and that a timeout occured, but now it also logs a traceback. InvalidStateError can occur when trying to set a result value to a Future that already has a result. A personal theory is that the cancel call on the Future is what is triggering this "double result call", but I have not confirmed.

When raising a UnicodeDecodeError, the logging contains much of the info as in 4.15.0, and in my opinion even better communicates the code for this scenario.

Comment 41 Adam Halim cendio

2023-11-14 17:02:18 CET

The portopencheck module has been re-written with bug 8242, where it in 4.15.0 consisted of the classes CheckTCPPortOpen and CheckUnixSocketOpen.
In 4.15post, these classes have been replaced with the functions check_tcp_port_open() and check_unix_socket_open() which provide the same functionality.

The following is a summary of how the module behaves differently between 4.15.0 and 4.15post when it comes to error handling.

This was tested using Fedora 38 (Python 3.11.4)

Timeout handling
================

4.15post:
Putting an asynchronous sleep inside of check_tcp_port_open() will cause a timeout (tested with a 26 second sleep), which results in the agent's penalty points being increased by five, the client seeing a "ThinLinc login failed. (No agent server was available)", and this being logged:
> 2023-11-14 08:00:16 WARNING vsmagent.session: Xvnc start for username cendio failed (timeout waiting for vnc port)

4.15.0
The check_tcp_port_open() equivalent in 4.15.0 is instantiating CheckTCPPortOpen.
To trigger a timeout, I simply added a delayed call to delay_connect with the same timeout value as the timeout handler.
I could verify that both delay_connect and handle_timeout were called by logging in the functions.
The result was the same as in 4.15post.

4.15post
The handler that uses portopencheck also has a timeout, where a parent function calls check_tcp_port_open() recursively until the correct value is returned, which will make the function progress.
We can trigger this timeout by forcing check_tcp_port_open() to always return False, causing it to be called repeatedly until the timeout is reached.
Triggering a timeout this way has the same effect as putting an asynchronous sleep inside the function as described previously (the same branch in the parent function is reached):
> 2023-11-14 08:05:12 WARNING vsmagent.session: Xvnc start for username cendio failed (timeout waiting for vnc port)

4.15.0
We can acheive the same behaviour in 4.15.0 by making sure CheckTCPPortOpen always passes SOCKET_NOT_INUSE to its callback, which will make sure CheckTCPPortOpen is instantiated recursively until the timeout is reached. The result is the same as in 4.15post.

4.15post
Making the a call to check_(tcp|unix)_port_open take >40 seconds (shouldn't be possible in a real-world scenario, there are mechanisms to ensure a timeout of 25 seconds), xmlrpc will cancel the handler after 40 seconds. The client will receive the message "ThinLinc login failed. (No agent server was available)", and the following is output in the logs:
> 2023-11-14 15:34:19 WARNING vsmserver: Error requesting a new session from agent 127.0.0.1: Operation timed out
> 2023-11-14 15:34:19 WARNING vsmserver.loadinfo: Agent 127.0.0.1 failed to start session, Increasing penalty points by 5 to 5
> 2023-11-14 15:34:19 WARNING vsmserver: No working agents found trying to start new session for cendio

> 2023-11-14 15:34:19 ERROR vsmagent: Exception in callback ServerProtocol._callback_done(<Future cance...magent.py:249>)
> 2023-11-14 15:34:19 ERROR vsmagent: handle: <Handle ServerProtocol._callback_done(<Future cance...magent.py:249>) created at /opt/thinlinc/modules/thinlinc/vsm/xmlrpc.py:241>
> 2023-11-14 15:34:19 ERROR vsmagent: ----------------------------------------
> 2023-11-14 15:34:19 ERROR vsmagent: Object created at (most recent call last):
> 2023-11-14 15:34:19 ERROR vsmagent:   File "/opt/thinlinc/sbin/vsmagent", line 63, in iIi1ii1I1iI11
> 2023-11-14 15:34:19 ERROR vsmagent:     OoO . loop ( )
> 2023-11-14 15:34:19 ERROR vsmagent:   File "/opt/thinlinc/modules/thinlinc/vsm/asyncbase.py", line 218, in loop
> 2023-11-14 15:34:19 ERROR vsmagent:     self . run_forever ( )
> 2023-11-14 15:34:19 ERROR vsmagent:   File "/usr/lib64/python3.11/asyncio/base_events.py", line 607, in run_forever
> 2023-11-14 15:34:19 ERROR vsmagent:     self._run_once()
> 2023-11-14 15:34:19 ERROR vsmagent:   File "/usr/lib64/python3.11/asyncio/base_events.py", line 1914, in _run_once
> 2023-11-14 15:34:19 ERROR vsmagent:     handle._run()
> 2023-11-14 15:34:19 ERROR vsmagent:   File "/usr/lib64/python3.11/asyncio/events.py", line 80, in _run
> 2023-11-14 15:34:19 ERROR vsmagent:     self._context.run(self._callback, *self._args)
> 2023-11-14 15:34:19 ERROR vsmagent:   File "/usr/lib64/python3.11/asyncio/selector_events.py", line 1117, in _call_connection_lost
> 2023-11-14 15:34:19 ERROR vsmagent:     super()._call_connection_lost(exc)
> 2023-11-14 15:34:19 ERROR vsmagent:   File "/usr/lib64/python3.11/asyncio/selector_events.py", line 896, in _call_connection_lost
> 2023-11-14 15:34:19 ERROR vsmagent:     self._protocol.connection_lost(exc)
> 2023-11-14 15:34:19 ERROR vsmagent:   File "/opt/thinlinc/modules/thinlinc/vsm/xmlrpc.py", line 241, in connection_lost
> 2023-11-14 15:34:19 ERROR vsmagent:     self . _response . cancel ( )
> 2023-11-14 15:34:19 ERROR vsmagent: ----------------------------------------
> 2023-11-14 15:34:19 ERROR vsmagent: Traceback (most recent call last):
> 2023-11-14 15:34:19 ERROR vsmagent:   File "/usr/lib64/python3.11/asyncio/events.py", line 80, in _run
> 2023-11-14 15:34:19 ERROR vsmagent:     self._context.run(self._callback, *self._args)
> 2023-11-14 15:34:19 ERROR vsmagent:   File "/opt/thinlinc/modules/thinlinc/vsm/xmlrpc.py", line 348, in _callback_done
> 2023-11-14 15:34:19 ERROR vsmagent:     assert future is self . _response
> 2023-11-14 15:34:19 ERROR vsmagent:            ^^^^^^^^^^^^^^^^^^^^^^^^^^
> 2023-11-14 15:34:19 ERROR vsmagent: AssertionError
> 2023-11-14 15:34:19 ERROR vsmagent: ----------------------------------------

4.15.0
To test what happens if CheckTCPPortOpen takes more than 40 seconds to finish, I simply changed the delayed call to happen after 1000 seconds (I also set the timeout handler to trigger after 1000 seconds).
The results are the same as in 4.15post, except that there is nothing logged in vsmagent.log

Exception handling
==================

Exception handling has changed between 4.15.0 and 4.15post.
In 4.15.0, the CheckTCPPortOpen class was more responsible for exception handling, where it had an internal handle_error() method that was automatically invoked if an uncaught exception was raised.
In 4.15post, the caller is responsible for any uncaught exceptions, as they are set on the future object that is returned.

4.15post
Inside check_(tcp|unix)_port_open(), it seems all possible exceptions are managed (OSError).
Simply raising an OSError inside either function will have different effects depending on the caller, as it is up to the caller to manage the results from the future.
If some other unexpected exception is unpacked from the future, the exception is propagated to the default exception handler in asyncio:
> 2023-11-14 12:24:03 ERROR vsmagent: Exception in callback ReqSessionHandler._checked_vnc_socket(<Task finishe.../tasks.py:670>)
> 2023-11-14 12:24:03 ERROR vsmagent: handle: <Handle ReqSessionHandler._checked_vnc_socket(<Task finishe.../tasks.py:670>) created at /usr/lib64/python3.11/asyncio/events.py:80>
> 2023-11-14 12:24:03 ERROR vsmagent: ----------------------------------------
> 2023-11-14 12:24:03 ERROR vsmagent: Object created at (most recent call last):
> 2023-11-14 12:24:03 ERROR vsmagent:   File "/opt/thinlinc/sbin/vsmagent", line 74, in <module>
> 2023-11-14 12:24:03 ERROR vsmagent:     iIi1ii1I1iI11 ( )
> 2023-11-14 12:24:03 ERROR vsmagent:   File "/opt/thinlinc/sbin/vsmagent", line 63, in iIi1ii1I1iI11
> 2023-11-14 12:24:03 ERROR vsmagent:     OoO . loop ( )
> 2023-11-14 12:24:03 ERROR vsmagent:   File "/opt/thinlinc/modules/thinlinc/vsm/asyncbase.py", line 218, in loop
> 2023-11-14 12:24:03 ERROR vsmagent:     self . run_forever ( )
> 2023-11-14 12:24:03 ERROR vsmagent:   File "/usr/lib64/python3.11/asyncio/base_events.py", line 607, in run_forever
> 2023-11-14 12:24:03 ERROR vsmagent:     self._run_once()
> 2023-11-14 12:24:03 ERROR vsmagent:   File "/usr/lib64/python3.11/asyncio/base_events.py", line 1914, in _run_once
> 2023-11-14 12:24:03 ERROR vsmagent:     handle._run()
> 2023-11-14 12:24:03 ERROR vsmagent:   File "/usr/lib64/python3.11/asyncio/events.py", line 80, in _run
> 2023-11-14 12:24:03 ERROR vsmagent:     self._context.run(self._callback, *self._args)
> 2023-11-14 12:24:03 ERROR vsmagent: ----------------------------------------
> 2023-11-14 12:24:03 ERROR vsmagent: Traceback (most recent call last):
> 2023-11-14 12:24:03 ERROR vsmagent:   File "/usr/lib64/python3.11/asyncio/events.py", line 80, in _run
> 2023-11-14 12:24:03 ERROR vsmagent:     self._context.run(self._callback, *self._args)
> 2023-11-14 12:24:03 ERROR vsmagent:   File "/opt/thinlinc/modules/thinlinc/vsm/handler_reqsession.py", line 413, in _checked_vnc_socket
> 2023-11-14 12:24:03 ERROR vsmagent:     IiI111IIi = socket_status . result ( )
> 2023-11-14 12:24:03 ERROR vsmagent:                 ^^^^^^^^^^^^^^^^^^^^^^^^^^
> 2023-11-14 12:24:03 ERROR vsmagent:   File "/usr/lib64/python3.11/asyncio/tasks.py", line 479, in wait_for
> 2023-11-14 12:24:03 ERROR vsmagent:     return fut.result()
> 2023-11-14 12:24:03 ERROR vsmagent:            ^^^^^^^^^^^^
> 2023-11-14 12:24:03 ERROR vsmagent: ValueError: ADAM custom error
> 2023-11-14 12:24:03 ERROR vsmagent: ----------------------------------------

4.15.0
Inside the CheckTCPPortOpen class, OSError exceptions are also managed, which has different outcomes depending on the callback being passed to the constructor.
If any unexpected exceptions occur in the class, it is managed by handle_error() which gives the following output in vsmagent.log:
> Traceback (most recent call last):
>   File "/opt/thinlinc/sbin/vsmagent", line 18, in <module>
>     OOoOoo000O00 ( )
>   File "/opt/thinlinc/sbin/vsmagent", line 15, in OOoOoo000O00
>     VSMAgent ( sys . argv )
>   File "/opt/thinlinc/modules/thinlinc/vsm/vsmagent.py", line 168, in __init__
>     self . loop ( )
>   File "/opt/thinlinc/modules/thinlinc/vsm/asyncbase.py", line 426, in loop
>     OooO0O00o0 = self . run_delayed_calls ( )
>                  ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
>   File "/opt/thinlinc/modules/thinlinc/vsm/asyncbase.py", line 384, in run_delayed_calls
>     I1I1IIi1IIIi . func ( * I1I1IIi1IIIi . args , ** I1I1IIi1IIIi . kw )
>   File "/opt/thinlinc/modules/thinlinc/vsm/portopencheck.py", line 36, in delay_connect
>     raise ValueError("ADAM error")
> ValueError: ADAM error
The agent is also given 5 penalty points.

4.15.post
By forcing check_unix_port_open() to always return True for each unix socket being checked (i.e. there are no free displays), the parent function will never progress. The client receives the following message: "ThinLinc login failed. (No agent server was available)", and the following is logged:
> 2023-11-14 10:14:31 WARNING vsmagent.session: Unable to find free display number when starting session for cendio. Reporting to VSM Server
The agent also receives five penalty points.

4.15.0
We can test the same behaviour here by making CheckUnixSocketOpen always passes SOCKET_IN_USE to its callback. (I ran into some recursion depth issues here, so I manually set the starting display to 1950 to test this).
The same message is logged:
> 2023-11-14 10:28:11 WARNING vsmagent.session: Unable to find free display number when starting session for cendio. Reporting to VSM Server

In both 4.15.0 and 4.15post, the client is given the same message: "ThinLinc login failed. (No agent server was available)", and the agent service keeps running.

When it comes to logging, there is an improvment in 4.15post where logging is managed by the default exception handler in asyncio.

Comment 42 Linn cendio

2023-11-16 16:48:26 CET

We also want to check a caller of xmlrpc to see how errors are handled in those handlers. I choose handler_createusersocket. Tested on RHEL 9 with Python 3.9.16.

The log messages below are triggered when logging in to a session. For all scenarios, the client fails to log in and reports back the following:
> ThinLinc login failed.
> (The SSH connection succeeded, but the ThinLinc server connection failed.
> Perhaps this server doesn't run a ThinLinc server?)
4.15.0
Logging as below when casting KeyError in CreateUserSocketHandler.handle.
> 2023-11-16 09:09:54 WARNING vsmserver.session: create_user_socket: User with uid 1000 does not exist
Logging when casting ValueError in CreateUserSocketHandler.handle (outside try/except-case):
> 2023-11-14 16:23:43 ERROR vsmserver: Unhandled XMLRPC exception: <class 'ValueError'> LINN custom error Traceback (most recent call last):
>   File "/opt/thinlinc/modules/thinlinc/vsm/asyncbase.py", line 104, in ooOOOoOO0
>     obj . handle_read_event ( )
>   File "/usr/lib64/python3.9/asyncore.py", line 420, in handle_read_event
>     self.handle_read()
>   File "/usr/lib64/python3.9/asynchat.py", line 151, in handle_read
>     self.found_terminator()
>   File "/opt/thinlinc/modules/thinlinc/vsm/xmlrpc.py", line 555, in found_terminator
>     self . handle_request ( )
>   File "/opt/thinlinc/modules/thinlinc/vsm/xmlrpc.py", line 569, in handle_request
>     self . handle_method ( )
>   File "/opt/thinlinc/modules/thinlinc/vsm/vsmserverchannel.py", line 120, in handle_method
>     O0o0OOoOOOO ( self . vsmserver , sock = self . socket ) . handle ( self . methodname ,
>   File "/opt/thinlinc/modules/thinlinc/vsm/handler_createusersocket.py", line 24, in handle
>     raise ValueError("LINN custom error")
> ValueError: LINN custom error
When casting a KeyError we are unable to find the user, as is indicated by the logging. We also see that an uncaught exception has no special handling, and that the traceback we get is missing the logging prefix. 


4.15post
Logging when casting KeyError in CreateUserSocketHandler.handle:
> 2023-11-14 16:55:03 WARNING vsmserver.session: create_user_socket: User with uid 1000 does not exist
Logging when casting ValueError in CreateUserSocketHandler.handle (outside try/except-case):
> 2023-11-14 17:08:23 ERROR vsmserver: Exception in callback ServerProtocol._call_callback('create_user_socket', 0)
> 2023-11-14 17:08:23 ERROR vsmserver: handle: <Handle ServerProtocol._call_callback('create_user_socket', 0) created at /opt/thinlinc/modules/thinlinc/vsm/xmlrpc.py:332>
> 2023-11-14 17:08:23 ERROR vsmserver: ----------------------------------------
> 2023-11-14 17:08:23 ERROR vsmserver: Object created at (most recent call last):
> 2023-11-14 17:08:23 ERROR vsmserver:   File "/opt/thinlinc/modules/thinlinc/vsm/asyncbase.py", line 218, in loop
> 2023-11-14 17:08:23 ERROR vsmserver:     self . run_forever ( )
> 2023-11-14 17:08:23 ERROR vsmserver:   File "/usr/lib64/python3.9/asyncio/base_events.py", line 601, in run_forever
> 2023-11-14 17:08:23 ERROR vsmserver:     self._run_once()
> 2023-11-14 17:08:23 ERROR vsmserver:   File "/usr/lib64/python3.9/asyncio/base_events.py", line 1897, in _run_once
> 2023-11-14 17:08:23 ERROR vsmserver:     handle._run()
> 2023-11-14 17:08:23 ERROR vsmserver:   File "/usr/lib64/python3.9/asyncio/events.py", line 80, in _run
> 2023-11-14 17:08:23 ERROR vsmserver:     self._context.run(self._callback, *self._args)
> 2023-11-14 17:08:23 ERROR vsmserver:   File "/usr/lib64/python3.9/asyncio/selector_events.py", line 811, in _read_ready
> 2023-11-14 17:08:23 ERROR vsmserver:     self._read_ready_cb()
> 2023-11-14 17:08:23 ERROR vsmserver:   File "/usr/lib64/python3.9/asyncio/selector_events.py", line 868, in _read_ready__data_received
> 2023-11-14 17:08:23 ERROR vsmserver:     self._protocol.data_received(data)
> 2023-11-14 17:08:23 ERROR vsmserver:   File "/opt/thinlinc/modules/thinlinc/vsm/xmlrpc.py", line 316, in data_received
> 2023-11-14 17:08:23 ERROR vsmserver:     self . _handle_request ( )
> 2023-11-14 17:08:23 ERROR vsmserver:   File "/opt/thinlinc/modules/thinlinc/vsm/xmlrpc.py", line 332, in _handle_request
> 2023-11-14 17:08:23 ERROR vsmserver:     get_event_loop ( ) . call_soon ( self . _call_callback , oOoOO0O0 , * O00 )
> 2023-11-14 17:08:23 ERROR vsmserver: ----------------------------------------
> 2023-11-14 17:08:23 ERROR vsmserver: Traceback (most recent call last):
> 2023-11-14 17:08:23 ERROR vsmserver:   File "/usr/lib64/python3.9/asyncio/events.py", line 80, in _run
> 2023-11-14 17:08:23 ERROR vsmserver:     self._context.run(self._callback, *self._args)
> 2023-11-14 17:08:23 ERROR vsmserver:   File "/opt/thinlinc/modules/thinlinc/vsm/xmlrpc.py", line 340, in _call_callback
> 2023-11-14 17:08:23 ERROR vsmserver:     self . _response = self . _callback ( methodname , * params )
> 2023-11-14 17:08:23 ERROR vsmserver:   File "/opt/thinlinc/modules/thinlinc/vsm/vsmserver.py", line 308, in _handle_method
> 2023-11-14 17:08:23 ERROR vsmserver:     ooO0oOO0 = oOOoO0o . handle ( method , params )
> 2023-11-14 17:08:23 ERROR vsmserver:   File "/opt/thinlinc/modules/thinlinc/vsm/handler_createusersocket.py", line 29, in handle
> 2023-11-14 17:08:23 ERROR vsmserver:     raise ValueError("LINN custom error")
> 2023-11-14 17:08:23 ERROR vsmserver: ValueError: LINN custom error
> 2023-11-14 17:08:23 ERROR vsmserver: ----------------------------------------
In 4.15post, we still do the same logging when unable to find the user. We still get a traceback for uncaught exceptions, but the now have the correct logging format. The behaviour for exceptions in xmlrpc handlers still seem to be the same as before the swap to asyncio.

Comment 43 Linn cendio

2023-11-17 10:31:03 CET

As a last test to see how errors are handled in handlers calling xmlrpc, I briefly tested handler_reqsession. Tested on RHEL 9 with Python 3.9.16.

The log messages below are triggered when logging in to a session. For all scenarios, the client fails to log in and reports back the following:
> ThinLinc login failed.
> (No agent server was available)
4.15.0
Logging when raising a general exception in ReqSessionHandler.start_session:
> 2023-11-16 16:16:48 INFO vsmserver.session: User with uid 1000 (cendio) requested a new session
> 2023-11-16 16:16:48 WARNING vsmserver.session: Connection to 127.0.0.1:904 closed before receiving response in request for new session. 
> 2023-11-16 16:16:48 WARNING vsmserver.loadinfo: Agent 127.0.0.1 failed to start session, Increasing penalty points by 5 to 5
> 2023-11-16 16:16:48 WARNING vsmserver: No working agents found trying to start new session for cendio
Logging when raising an OSError in ReqSessionHandler.check_homedir. This will happen when unable to create a home directory for the user:
> 2023-11-16 16:35:57 INFO vsmserver.session: User with uid 1000 (cendio) requested a new session
> 2023-11-16 16:35:57 WARNING vsmserver: VSM Agent 127.0.0.1 reported failure creating session for cendio
> 2023-11-16 16:35:57 WARNING vsmserver.loadinfo: Agent 127.0.0.1 failed to start session, Increasing penalty points by 5 to 5
> 2023-11-16 16:35:57 WARNING vsmserver: No working agents found trying to start new session for cendio
Logging contains no tracebacks and in both cases the pentaly points for the agent are increased by 5.

4.15post
Logging when raising a general exception in ReqSessionHandler._start_session:
> 2023-11-17 09:24:42 INFO vsmserver.session: User with uid 1000 (cendio) requested a new session
> 2023-11-17 09:24:42 WARNING vsmserver: Error requesting a new session from agent 127.0.0.1: Request rejected by server: '500' 'Internal error\r\n'
> 2023-11-17 09:24:42 WARNING vsmserver.loadinfo: Agent 127.0.0.1 failed to start session, Increasing penalty points by 5 to 5
> 2023-11-17 09:24:42 WARNING vsmserver: No working agents found trying to start new session for cendio
Logging when raising an OSError in ReqSessionHandler._check_homedir:
> 2023-11-17 09:26:39 INFO vsmserver.session: User with uid 1000 (cendio) requested a new session
> 2023-11-17 09:26:39 WARNING vsmserver: VSM Agent 127.0.0.1 reported failure creating session for cendio
> 2023-11-17 09:26:39 WARNING vsmserver.loadinfo: Agent 127.0.0.1 failed to start session, Increasing penalty points by 5 to 5
> 2023-11-17 09:26:39 WARNING vsmserver: No working agents found trying to start new session for cendio
We see that the logging has been slightly for altered when raising a general exception compared to 4.15.0. In this case, the agent now reports "500 Internal error" while in 4.15.0 it had the more generic "Connection [...] closed before receiving response [...]".

Otherwise, the logging is the same as in 4.15.0 and the agent still get penalty points when failing to create a session, so the error handling is comparable to before.

Comment 44 Adam Halim cendio

2023-11-20 13:22:04 CET

(In reply to Linn from comment #32)

> A timeout when calling sleep in ServerProtocol.connection_made is logged as:
> > 2023-10-31 16:38:34 WARNING vsmserver.loadinfo: Error getting load from agent 127.0.0.1: Operation timed out
> > 2023-10-31 16:38:34 WARNING vsmserver.loadinfo: Marking agent 127.0.0.1 as down
> > Executing <Handle ServerProtocol.connection_made(<_SelectorSoc...e, bufsize=0>>) created at /usr/lib64/python3.9/asyncio/selector_events.py:774> took 50.032 seconds
> A timeout when calling sleep in ServerProtocol._write_response is logged as:
> > 2023-10-31 17:09:41 WARNING vsmserver.loadinfo: Marking agent 127.0.0.1 as down
> > Executing <Handle ServerProtocol._callback_done(<Future finis...server.py:309>) created at /opt/thinlinc/modules/thinlinc/vsm/vsmserver.py:391> took 50.051 seconds
> The last line in both cases looks very similar to the one as found in
> comment 31. I did not dig deeper into why/when this kind of logging occurs,
> or if the logging only is shown in devmode or not.
These lines only get logged when running in debug mode and happens if a callback takes >0.1s to finish. This is 0.1s of actual execution, and not any asynchronous waiting. I tested this by adding a time.sleep(0.1) in a callback, which triggered  the line to be logged:
> Executing <TimerHandle when=623115.182962302 ReqSessionHandler._wait_on_vnc_port() created at /opt/thinlinc/modules/thinlinc/vsm/handler_reqsession.py:377> took 0.101 seconds
Replacing time.sleep(0.1) with await asyncio.sleep(0.1) does not trigger the line (I tested with 1 second as well). Disabling developer mode does not produce the line in the log (tested with time.sleep(1)).

Comment 51 Linn cendio

2023-11-22 09:23:38 CET

Regarding the testing for error handling/logging, we now consider this covered. Below is a summary of what was tested.

In general, we wanted to test both the "core parts" of the error handling, as well as the callers of those core parts. In 4.15.0, the core parts were the files containing function "handle_error", listed below:
  - asyncbase
  - extproc
  - portopencheck
  - xmlrpc

The callers of these files were our different handler classes. Asyncbase has been removed as part of this bug, but extproc, portopencheck and xmlrpc have all been tested, both by triggering errors in those files as well as in the callers of those files.

Xmlrpc is a bit special, since it has more than one layer to get to its caller:
  xmlrpc <--> vsmxmlrpccall <--> handler

Testing related to xmlrpc were done in all three layers.

Comment 52 Linn cendio

2023-11-22 09:32:59 CET

The result from the error handling was that we wanted to examine two scenarios a bit closer.

The first one has already been examined in comment 44, and was regarding the following line in the log:
> Executing <Handle ServerProtocol._callback_done(<Future finis...server.py:309>) created at /opt/thinlinc/modules/thinlinc/vsm/vsmserver.py:391> took 50.051 seconds
Since it is not triggered outside of dev mode and seems to exist to bring attention to async calls that takes longer than 0.1 sec to execute. I don't believe this logging is an issue for us as it currently is.


The second scenario to look closer too in the error handling was a traceback in comment 36, seen ServerProtocol.data_recieved when incoming data is too long. Note that be exact, rather than sending too much data, I simulated too much data by setting the allowed maxdata to -1 in the following code.

> class ServerProtocol():
>     ....
>     def data_received(self, data):
>         ...
>         self.max_datalength = -1
>         if self._datalength > self.max_datalength:
>             return
It is correct that we get a timeout in this scenario, but we should not get a traceback. It seems to be related to how our xmlrpc calls are handled, so I'm moving this to bug 8224.

With that, all things for the error handling should be taken care of regarding to this bug.

Comment 57 Pierre Ossman cendio

2023-11-27 13:19:45 CET

https://community.thinlinc.com/t/thinlinc-server-fails-to-start-fedora-39/789

Comment 58 Samuel Mannehed cendio

2023-12-01 10:25:21 CET

Build 3430 has stopped working on Fedora 39. I once again see this warning in the log:

> /opt/thinlinc/modules/thinlinc/vsm/vsmserver.py:405: DeprecationWarning: There is no current event loop
>   asyncio . get_event_loop ( ) . call_later ( 3600 * 12 , self . _update_licenses ) 

And the master doesn't seem to work. Web Admin shows “Connection refused” on the pages talking to the vsmserver service, same with tlctl. Logging in with a ThinLinc client doesn't work either.

Build 3421 works well.

Comment 60 Samuel Mannehed cendio

2023-12-01 17:02:24 CET

(In reply to Samuel Mannehed from comment #58)
> Build 3430 has stopped working on Fedora 39. I once again see this warning
> in the log:
> 
> > /opt/thinlinc/modules/thinlinc/vsm/vsmserver.py:405: DeprecationWarning: There is no current event loop
> >   asyncio . get_event_loop ( ) . call_later ( 3600 * 12 , self . _update_licenses ) 
> 
> And the master doesn't seem to work. Web Admin shows “Connection refused” on
> the pages talking to the vsmserver service, same with tlctl. Logging in with
> a ThinLinc client doesn't work either.
> 
> Build 3421 works well.

It seems like Python changed how asyncio works regarding forked processes in python 3.12:

https://github.com/python/cpython/issues/66285

In practice, this means we need to call “set_event_loop()” after forking (daemon_init).

Comment 61 Samuel Mannehed cendio

2023-12-01 18:10:09 CET

We simply get a “Connection refused”, and no other error during the startup of vsmserver. This is because, as of Python 3.12, when asyncio detects that it runs in a forked process, it will reset the loop and create a new one. This means the forked process runs on a different loop than the initial process. So, the 'loop' that we have initiated at the top is different from the one that the VSMServer object gets when it runs “get_event_loop()”.

The loop that has an exception handler and starts running, is not the same loop that VSMServer has used for “create_server()”. The effect is that things just quietly stop — no errors, no progress.

Comment 63 Samuel Mannehed cendio

2023-12-06 09:43:08 CET

I looked through all the comments on this bug so far. It seems we have covered or have moved things to separate bugs for everything that was discovered.

The resulting functionality works well and is a step-up in terms of logging and error handling. This is ready for testing.

Note You need to log in before you can comment on or make changes to this bug.