Fix the log levels mapping #597
Conversation
The `INFO` log level is usually not enough to get useful information from the libssh regarding the low-level issues that we would like to be able to resolve. This can be made even more fine grained, but I do not think less verbose logs would be much useful anyway. Related is the issue in pylibssh, which maps the DEBUG verbosity to something that is not debug in libssh itself: ansible/pylibssh#597
|
It'd be useful to have tests in such PRs. I'm unable to verify what this patch affects without them. |
|
Congratulations! One of the builds has completed. 🍾 You can install the built RPMs by following these steps:
Please note that the RPMs should be used only in a testing environment. |
psf-chronographer
bot
added
the
bot:chronographer:provided
Jakuje
force-pushed
the
patch-1
branch
3 times, most recently
from
68dd501 to
a55aea1
Compare
|
@webknjaz the current version should be working version with tests of what, I hope, you were trying to describe. I think it will need some polishing so I would be happy for your inputs. |
|
|
src/pylibsshext/logging.pyx
Outdated
| const char *function, | ||
| const char *buffer, | ||
| void *userdata) noexcept nogil: | ||
| with gil: |
There was a problem hiding this comment.
Will this be problematic in free-threading builds of CPython?
|
Turns out that also the |
Jakuje
force-pushed
the
patch-1
branch
3 times, most recently
from
808a4aa to
2c034b8
Compare
Welcome to Codecov 🎉Once you merge this PR into your default branch, you're all set! Codecov will compare coverage reports and display results in all future pull requests. Thanks for integrating Codecov - We've got you covered ☂️ |
If you want a "log nothing", I'd probably set the threshold high in the mapping. Something like $ python
Python 3.13.2 (main, Feb 28 2025, 20:34:46) [GCC 14.2.1 20241221] on linux
Type "help", "copyright", "credits" or "license" for more information.
>>> import logging
>>> logging.getLevelNamesMapping()
{'CRITICAL': 50, 'FATAL': 50, 'ERROR': 40, 'WARN': 30, 'WARNING': 30, 'INFO': 20, 'DEBUG': 10, 'NOTSET': 0}
>>> logging.fatal
<function fatal at 0x7fa77ea62fc0>
>>> logging.CRITICAL
50
>>> logging.FATAL
50
>>> logging.ERROR
40P.S. I wonder if |
| if level not in LOG_MAP: | ||
| raise LibsshSessionException(f'Invalid log level [{level:d}]') | ||
|
|
||
| rc = libssh.ssh_set_log_level(LOG_MAP[level]) |
There was a problem hiding this comment.
Should this special-case NOTSET and just skip calling this?
There was a problem hiding this comment.
It is not clear to me as the libssh mapping and python is that different.
I understand the NOTSET value that we should log everything and let the underlying code handle that. If we would skip this call on NOTSET, we would just keep the previously set log level, which might be TRACE, NONE, or anything in between, which does not sound right to me.
There was a problem hiding this comment.
@Jakuje so the way the logging infrastructure works in python is that the loggers are called throughout the application code with explicit levels. And then, there's a level of logging set on the logger, which allows disregarding messages below the set level (this is simple integer comparison). But then, there's also handlers of which there can be many. And you can have a handler for stdout, stderr, some file and some network logging service. So a logged message that cleared the first gate (the logger log level) goes into all of the handlers which would have their own logging levels as well. And the handlers can be set up to output a debug log file and a normal log file + normal stderr + critical-only messages going to a network server (as an example).
logging.NOTSET is 0. Meaning that if a logger has logging.NOTSET, no messages are going to be disregarded “on entry”. This is a semantic “log everything”.
>>> import logging
>>> logging.NOTSET
0I should note, though, that loggers have hierarchy. And so there's a "root logger" and "child" loggers. When a logger has a level of logging.NOTSET, the actual level is being computed by traversing the parent relationships. And only if the root logger has it as logging.NOTSET, this value of 0 is used (otherwise, some other value may end up being considered as the current logging level). logging.NOTSET is not the default of the root logger, logging.WARNING is.
So I'd say logging.NOTSET may be considered a special-cased sentinel in some contexts.
src/pylibsshext/logging.pyx
Outdated
| }, | ||
| } | ||
|
|
||
| logger = logging.getLogger("libssh") |
There was a problem hiding this comment.
Should this be called libssh? or perhaps
| logger = logging.getLogger("libssh") | |
| _logger = logging.getLogger('ansible-pylibssh') |
?
Should we be exposing this _logger object to the end-users or just have it internal?
There was a problem hiding this comment.
What if we initialize the logger object in session.pyx (module-level or as an instance on Session) and then pass it to set_level() as an argument instead of having a global thing here?
There was a problem hiding this comment.
Indeed, it should be internal. I think the problem was accessing the logger from the callback _pylibssh_log_wrapper(), which gets called by the libssh. I probably did not want to mess with passing it as a userdata, but it should be an option. Let me have a look into that.
There was a problem hiding this comment.
Yeah, the thing is that the logging is really not tied to the session so if we allocate the logger in session and then free it we might crash, which is why I went with the global.
The other option would be to unset the callback + userdata when session is freed, but it would still be mess if more sessions would get allocated in one thread.
So the only viable option I see could creating some singleton Logging object, encapsulating the logging context, if you prefer.
There was a problem hiding this comment.
I think it's okay to have it global, just have it underscored so that it doesn't look like public API.
Jakuje
force-pushed
the
patch-1
branch
3 times, most recently
from
6c229ee to
7841ba9
Compare
|
Ugh. Is the ubi/fedora RPM builds still/again broken? This does not look like an issue in this PR if I see right: |
|
Not sure about the RPMs but the test job is slow on Python 3.8: https://github.com/ansible/pylibssh/actions/runs/14712178586/job/41287439642?pr=597#step:16:696 |
|
Building things under QEMU was slow and timed out too https://github.com/ansible/pylibssh/actions/runs/14712178586/job/41287253557?pr=597 |
They weren't broken on the last commit to The UBI 9 job in this PR uses libssh-devel 0.10.4-13.el9 as well. So there's no difference there. It's a mystery, so far. Can it be that CFLAGS / LDFLAGS is being broken in the upstream images? I'm not sure. |
|
And the container images are the same too. F40: |
|
@Jakuje The RPM jobs are not failing in other PRs, so this is related to something you changed here. |
Interesting. Locally it works, in other jobs it works too but we got import error on RPM build. This is not even a new symbol being used, the |
|
So it looks like the issue is the pyx file without the related pxd one. I removed the empty pxd in some of the previous iterations, which is probably the time when this started failing. Adding just an empty file logging.pxd solves the issue (but raises warnings obviously). Given how few information is now left in the logging module, I would even consider merging it into the session or moving the constants to the pxd. What would you suggest to be the cleanest way? |
|
I wonder why it works for |
AFAIK the difference is in how the |
The libssh provides the most verbose logging with SSH_LOG_TRACE, which was not mapped to any of the standard values so the users are unable to get full debug logs. These are critical for libssh developers to be able to investigate issues. Signed-off-by: Jakub Jelen <[email protected]>
Signed-off-by: Jakub Jelen <[email protected]>
Signed-off-by: Jakub Jelen <[email protected]>
|
|
Sounds like now we have only the python 3.12 tests failing. |
SUMMARY
The libssh provides the most verbose logging with SSH_LOG_TRACE, which was mapped to
logging.CRITICAL, causing the users being unable to get full debug logs. These are critical for libssh developers to be able to investigate issues.ISSUE TYPE