Fix the log levels mapping #597

Jakuje · 2024-05-23T14:00:29Z

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

Bugfix Pull Request

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

src/pylibsshext/session.pyx

webknjaz · 2024-05-31T15:19:23Z

It'd be useful to have tests in such PRs. I'm unable to verify what this patch affects without them.

packit-as-a-service · 2024-06-21T08:59:13Z

Congratulations! One of the builds has completed. 🍾

You can install the built RPMs by following these steps:

sudo yum install -y dnf-plugins-core on RHEL 8
sudo dnf install -y dnf-plugins-core on Fedora
dnf copr enable packit/ansible-pylibssh-597
And now you can install the packages.

Please note that the RPMs should be used only in a testing environment.

docs/changelog-fragments/597.bugfix.rst

tests/unit/session_test.py

Jakuje · 2024-08-29T14:56:12Z

@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.

sonarqubecloud · 2024-08-29T15:42:24Z

Quality Gate passed

Issues
0 New issues
0 Accepted issues

Measures
0 Security Hotspots
0.0% Coverage on New Code
0.0% Duplication on New Code

See analysis details on SonarCloud

sonarqubecloud · 2024-12-22T18:37:58Z

Quality Gate passed

Issues
0 New issues
0 Accepted issues

Measures
0 Security Hotspots
0.0% Coverage on New Code
0.0% Duplication on New Code

See analysis details on SonarQube Cloud

webknjaz

I wrote most of the review months ago. Submitting just now. This might need a few more iterations. Hopefully, a few things are actionable immediately.

src/pylibsshext/logging.pxd

src/pylibsshext/logging.pyx

src/pylibsshext/logging.pxd

src/pylibsshext/logging.pyx

webknjaz · 2025-04-01T18:47:24Z

src/pylibsshext/logging.pyx

+                                const char *function,
+                                const char *buffer,
+                                void *userdata) noexcept nogil:
+    with gil:


Will this be problematic in free-threading builds of CPython?

src/pylibsshext/session.pyx

Jakuje · 2025-04-11T08:48:24Z

Turns out that also the logging.NOTSET is misplaced. In python it means "ask above"/"log everything" but in libssh the currently mapped value libssh.SSH_LOG_NONE means do not log anything, which is quite the opposite so my suggestion would be to move this to logging.WARNING which is probably the closest ...

codecov · 2025-04-11T09:27:00Z

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 ☂️

webknjaz · 2025-04-24T13:28:10Z

Turns out that also the logging.NOTSET is misplaced. In python it means "ask above"/"log everything" but in libssh the currently mapped value libssh.SSH_LOG_NONE means do not log anything, which is quite the opposite so my suggestion would be to move this to logging.WARNING which is probably the closest ...

If you want a "log nothing", I'd probably set the threshold high in the mapping. Something like 55 or 60, or even 99:

$ 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
40

P.S. I wonder if float('inf') would be allowed since infinity is semantically what you're after...

webknjaz · 2025-04-24T14:27:20Z

src/pylibsshext/logging.pyx

+    if level not in LOG_MAP:
+        raise LibsshSessionException(f'Invalid log level [{level:d}]')
+
+    rc = libssh.ssh_set_log_level(LOG_MAP[level])


Should this special-case NOTSET and just skip calling this?

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.

@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 0

I 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.

webknjaz · 2025-04-24T14:30:07Z

src/pylibsshext/logging.pyx

+ANSIBLE_PYLIBSSH_TRACE = int(logging.DEBUG / 2)
+
+
+LOG_MAP = {
+    logging.NOTSET: libssh.SSH_LOG_TRACE,
+    ANSIBLE_PYLIBSSH_TRACE: libssh.SSH_LOG_TRACE,
+    logging.DEBUG: libssh.SSH_LOG_DEBUG,
+    logging.INFO: libssh.SSH_LOG_INFO,
+    logging.WARNING: libssh.SSH_LOG_WARN,
+    logging.ERROR: libssh.SSH_LOG_WARN,
+    logging.CRITICAL: libssh.SSH_LOG_NONE,
+}


What if we use a sentinel object for "not set" and special-case it later? Plus expose an explicit "no log".

Suggested change

ANSIBLE_PYLIBSSH_TRACE = int(logging.DEBUG / 2)

LOG_MAP = {

logging.NOTSET: libssh.SSH_LOG_TRACE,

ANSIBLE_PYLIBSSH_TRACE: libssh.SSH_LOG_TRACE,

logging.DEBUG: libssh.SSH_LOG_DEBUG,

logging.INFO: libssh.SSH_LOG_INFO,

logging.WARNING: libssh.SSH_LOG_WARN,

logging.ERROR: libssh.SSH_LOG_WARN,

logging.CRITICAL: libssh.SSH_LOG_NONE,

}

ANSIBLE_PYLIBSSH_NOLOG = float('inf')

ANSIBLE_PYLIBSSH_TRACE = int(logging.DEBUG / 2)

_NOT_SET_SENTINEL = object()

LOG_MAP = {

logging.NOTSET: _NOT_SET_SENTINEL,

ANSIBLE_PYLIBSSH_TRACE: libssh.SSH_LOG_TRACE,

logging.DEBUG: libssh.SSH_LOG_DEBUG,

logging.INFO: libssh.SSH_LOG_INFO,

logging.WARNING: libssh.SSH_LOG_WARN,

logging.ERROR: libssh.SSH_LOG_WARN,

logging.CRITICAL: libssh.SSH_LOG_NONE,

ANSIBLE_PYLIBSSH_NOLOG: libssh.SSH_LOG_NONE,

}

Note that duplicate values will cause a smaller LOG_MAP_REV. Should we consider having a smaller dict for determinism and then augmenting it with additional mappings post-reversal?

Having seen your hint that logging might require an int, this could be

Suggested change

ANSIBLE_PYLIBSSH_TRACE = int(logging.DEBUG / 2)

LOG_MAP = {

logging.NOTSET: libssh.SSH_LOG_TRACE,

ANSIBLE_PYLIBSSH_TRACE: libssh.SSH_LOG_TRACE,

logging.DEBUG: libssh.SSH_LOG_DEBUG,

logging.INFO: libssh.SSH_LOG_INFO,

logging.WARNING: libssh.SSH_LOG_WARN,

logging.ERROR: libssh.SSH_LOG_WARN,

logging.CRITICAL: libssh.SSH_LOG_NONE,

}

ANSIBLE_PYLIBSSH_NOLOG = logging.FATAL * 2

ANSIBLE_PYLIBSSH_TRACE = int(logging.DEBUG / 2)

_NOT_SET_SENTINEL = object()

LOG_MAP = {

logging.NOTSET: _NOT_SET_SENTINEL,

ANSIBLE_PYLIBSSH_TRACE: libssh.SSH_LOG_TRACE,

logging.DEBUG: libssh.SSH_LOG_DEBUG,

logging.INFO: libssh.SSH_LOG_INFO,

logging.WARNING: libssh.SSH_LOG_WARN,

logging.ERROR: libssh.SSH_LOG_WARN,

logging.CRITICAL: libssh.SSH_LOG_NONE,

ANSIBLE_PYLIBSSH_NOLOG: libssh.SSH_LOG_NONE,

}

Note that duplicate values will cause a smaller LOG_MAP_REV. Should we consider having a smaller dict for determinism and then augmenting it with additional mappings post-reversal?

If we remove the duplicates, we will fail to map in one of the ways. Note, that this maps X->Y and Y->X without any compicated logic like getting the first smaller/larger value. Yes, adding some logic to mapping can make the lists smaller by few items, but I think the complexity of the mapping/matching would not be worth the smaller map (unless there is some simple way to do that in python that I am not aware of).

Currently, libssh.SSH_LOG_WARN maps to one of logging.WARNING or logging.ERROR in LOG_MAP_REV. It's probably predictable, but I can't say which one by just looking at code. If we only keep one in LOG_MAP, then produce LOG_MAP_REV (like it is now) and only then extend LOG_MAP to add “aliases”, it should give us better control over what's in the main mapping vs. the extended one.

Thank you for the suggestion. This makes sense.

src/pylibsshext/logging.pyx

webknjaz · 2025-04-24T14:44:40Z

src/pylibsshext/logging.pyx

+
+cdef void _pylibssh_log_wrapper(int priority,
+                                const char *function,
+                                const char *buffer,


Note to myself: buffer is highlighted as blue. This is because buffer() used to be a builtin in Python 2. Python 3 has it as a memoryview().

tests/unit/session_test.py

src/pylibsshext/logging.pyx

webknjaz · 2025-04-25T15:29:47Z

src/pylibsshext/logging.pyx

+    },
+}
+
+logger = logging.getLogger("libssh")


Should this be called libssh? or perhaps

Suggested change

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?

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?

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.

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.

I think it's okay to have it global, just have it underscored so that it doesn't look like public API.

src/pylibsshext/logging.pyx

tests/unit/session_test.py

docs/changelog-fragments/597.feature.rst

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 <jjelen@redhat.com>

Signed-off-by: Jakub Jelen <jjelen@redhat.com>

sonarqubecloud · 2025-04-28T15:55:10Z

Quality Gate passed

Issues
1 New issue
0 Accepted issues

Measures
0 Security Hotspots
0.0% Coverage on New Code
0.0% Duplication on New Code

See analysis details on SonarQube Cloud

Jakuje · 2025-04-28T16:07:11Z

Ugh. Is the ubi/fedora RPM builds still/again broken? This does not look like an issue in this PR if I see right:

ImportError while loading conftest '/github/home/rpmbuild/BUILD/ansible-pylibssh-1.2.3.dev189+g6432716/tests/conftest.py'.
tests/conftest.py:16: in <module>
    from pylibsshext.logging import ANSIBLE_PYLIBSSH_TRACE
E   ImportError: /github/home/rpmbuild/BUILDROOT/python-ansible-pylibssh-1.2.3.dev189+g6432716-1.el9.x86_64/usr/lib64/python3.9/site-packages/pylibsshext/logging.cpython-39-x86_64-linux-gnu.so: undefined symbol: ssh_set_log_level

webknjaz · 2025-04-29T16:34:19Z

src/pylibsshext/logging.pyx

+                                const char *buffer,
+                                void *userdata) noexcept:
+    log_level = LOG_MAP_REV[priority]
+    _logger.log(log_level, str(buffer))


#597 (comment) revealed that the string conversion is borked here.

str(b'asdf') is converted into "b'asdf'" because it's going through repr().

It should be something like

Suggested change

_logger.log(log_level, str(buffer))

_logger.log(log_level, buffer.decode('utf-8'))

Are we sure what the actual encoding is? If not, this would have to become

Suggested change

_logger.log(log_level, str(buffer))

_logger.log(log_level, buffer.decode('utf-8', errors='surrogateescape'))

(https://docs.python.org/3/library/codecs.html#error-handlers)

webknjaz · 2025-04-29T16:38:07Z

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

webknjaz · 2025-04-29T16:43:28Z

Building things under QEMU was slow and timed out too https://github.com/ansible/pylibssh/actions/runs/14712178586/job/41287253557?pr=597

webknjaz · 2025-04-29T16:45:08Z

src/pylibsshext/logging.pyx

+python log facility.
+
+It provides two new log levels, that can be used with to set the log verbosity
+using `set_log_level()` method on `Session` object.


Suggested change

using `set_log_level()` method on `Session` object.

using ``set_log_level()`` method on ``Session`` object.

webknjaz · 2025-04-29T17:04:23Z

Ugh. Is the ubi/fedora RPM builds still/again broken? This does not look like an issue in this PR if I see right:

ImportError while loading conftest '/github/home/rpmbuild/BUILD/ansible-pylibssh-1.2.3.dev189+g6432716/tests/conftest.py'.
tests/conftest.py:16: in <module>
    from pylibsshext.logging import ANSIBLE_PYLIBSSH_TRACE
E   ImportError: /github/home/rpmbuild/BUILDROOT/python-ansible-pylibssh-1.2.3.dev189+g6432716-1.el9.x86_64/usr/lib64/python3.9/site-packages/pylibsshext/logging.cpython-39-x86_64-linux-gnu.so: undefined symbol: ssh_set_log_level

They weren't broken on the last commit to devel 4 days ago.
Back then, F40 used libssh-devel 0.10.6-5.fc40: https://github.com/ansible/pylibssh/actions/runs/14667486098/job/41165904433#step:16:22.
And UBI 9.0.0 used libssh-devel 0.10.4-13.el9: https://github.com/ansible/pylibssh/actions/runs/14667486098/job/41165904860#step:16:33

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.

webknjaz · 2025-04-29T17:06:43Z

And the container images are the same too.

F40: sha256:3c86d25fef9d2001712bc3d9b091fc40cf04be4767e48f1aa3b785bf58d300ed
UBI9: sha256:9db17fd5d0bbf8797d65d42c039f3a20ce9621d989cc173e3c616fa5e8588115

Jakuje mentioned this pull request May 23, 2024

libssh: Use more verbose logging ansible-collections/ansible.netcommon#638

Closed

webknjaz reviewed May 31, 2024

View reviewed changes

src/pylibsshext/session.pyx Show resolved Hide resolved

Jakuje force-pushed the patch-1 branch from eaca9ed to 7121d8a Compare June 21, 2024 08:48

Jakuje force-pushed the patch-1 branch from 7121d8a to 77582c1 Compare June 21, 2024 10:04

psf-chronographer bot added the bot:chronographer:provided There is a change note present in this PR label Jun 21, 2024

Jakuje force-pushed the patch-1 branch from 0ea2342 to 00a5c6a Compare June 21, 2024 10:07

webknjaz reviewed Jun 27, 2024

View reviewed changes

docs/changelog-fragments/597.bugfix.rst Outdated Show resolved Hide resolved

webknjaz reviewed Jun 27, 2024

View reviewed changes

tests/unit/session_test.py Outdated Show resolved Hide resolved

Jakuje mentioned this pull request Jun 27, 2024

Using ansible-pylibssh produces Unable to decode JSON from response to get_capabilities(). Received 'None'. error #360

Open

Jakuje force-pushed the patch-1 branch 3 times, most recently from 68dd501 to a55aea1 Compare August 29, 2024 14:54

Jakuje force-pushed the patch-1 branch from a55aea1 to 6d1f467 Compare August 29, 2024 15:42

Jakuje mentioned this pull request Oct 21, 2024

Intermittent SIGSEGV when running multiple ssh_channel.exec_command() #645

Closed

Jakuje force-pushed the patch-1 branch from 6d1f467 to 702de6c Compare December 22, 2024 18:37

webknjaz reviewed Apr 1, 2025

View reviewed changes

Jakuje mentioned this pull request Apr 10, 2025

Use standard SHA256 fingerprints #701

Open

Jakuje force-pushed the patch-1 branch 3 times, most recently from 808a4aa to 2c034b8 Compare April 11, 2025 09:13

webknjaz reviewed Apr 24, 2025

View reviewed changes

src/pylibsshext/logging.pyx Outdated Show resolved Hide resolved

webknjaz reviewed Apr 24, 2025

View reviewed changes

tests/unit/session_test.py Outdated Show resolved Hide resolved

Jakuje force-pushed the patch-1 branch from 2c034b8 to a6117b8 Compare April 24, 2025 17:01