Fix the log levels mapping

docs/changelog-fragments/597.bugfix.rst

@@ -0,0 +1 @@
+Fixed log level mapping to cover whole libssh range -- by :user:`Jakuje`.

docs/changelog-fragments/597.feature.rst

@@ -0,0 +1 @@
+Made libssh use python logging system -- by :user:`Jakuje`.

src/pylibsshext/includes/callbacks.pxd

@@ -127,3 +127,10 @@ cdef extern from "libssh/callbacks.h":
     ctypedef ssh_channel_callbacks_struct * ssh_channel_callbacks
 
     int ssh_set_channel_callbacks(ssh_channel channel, ssh_channel_callbacks cb)
+
+    ctypedef void(*ssh_logging_callback)(
+        int priority,
+        const char *function,
+        const char *buffer,
+        void *userdata)
+    int ssh_set_log_callback(ssh_logging_callback cb)

src/pylibsshext/logging.pxd

@@ -0,0 +1,20 @@
+# distutils: libraries = ssh
+#
+# This file is part of the pylibssh library
+#
+# This library is free software; you can redistribute it and/or
+# modify it under the terms of the GNU Lesser General Public
+# License as published by the Free Software Foundation; either
+# version 2.1 of the License, or (at your option) any later version.
+#
+# This library is distributed in the hope that it will be useful,
+# but WITHOUT ANY WARRANTY; without even the implied warranty of
+# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the GNU
+# Lesser General Public License for more details.
+#
+# You should have received a copy of the GNU Lesser General Public
+# License along with this library; if not, see file LICENSE.rst in this
+# repository.
+#
+
+# This file is needed to allow imports from the adjacent pyx file

src/pylibsshext/logging.pyx

@@ -0,0 +1,131 @@
+#
+# This file is part of the pylibssh library
+#
+# This library is free software; you can redistribute it and/or
+# modify it under the terms of the GNU Lesser General Public
+# License as published by the Free Software Foundation; either
+# version 2.1 of the License, or (at your option) any later version.
+#
+# This library is distributed in the hope that it will be useful,
+# but WITHOUT ANY WARRANTY; without even the implied warranty of
+# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the GNU
+# Lesser General Public License for more details.
+#
+# You should have received a copy of the GNU Lesser General Public
+# License along with this library; if not, see file LICENSE.rst in this
+# repository.
+
+"""
+The Logging module of pylibssh providers interface between libssh logging and
+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.
+
+.. data:: ANSIBLE_PYLIBSSH_NOLOG
+
+    Indicates the pylibssh will not log any events.
+
+.. data:: ANSIBLE_PYLIBSSH_TRACE
+
+    Indicates the pylibssh will produce all possible logs, generally useful for debugging low-level libssh operations.
+
+"""
+
+import logging
+
+from pylibsshext.errors cimport LibsshSessionException
+from pylibsshext.includes cimport callbacks, libssh
+
+
+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,
+    ANSIBLE_PYLIBSSH_NOLOG: libssh.SSH_LOG_NONE,
+}
+
+LOG_MAP_REV = {
+    **{
+        libssh_name: py_name
+        for py_name, libssh_name in LOG_MAP.items()
+    },
+}
+
+# mapping aliases
+LOG_MAP[logging.ERROR] = libssh.SSH_LOG_WARN
+LOG_MAP[logging.CRITICAL] = libssh.SSH_LOG_WARN
+
+
+_logger = logging.getLogger("ansible-pylibssh")
+
+
+def _add_trace_log_level():
+    """
+    Adds a trace log level to the python logging system.
+    """
+    level_num = ANSIBLE_PYLIBSSH_TRACE
+    level_name = "TRACE"
+
+    logging.addLevelName(level_num, level_name)
+
+
+cdef void _pylibssh_log_wrapper(int priority,
+                                const char *function,
+                                const char *buffer,
+                                void *userdata) noexcept:
+    log_level = LOG_MAP_REV[priority]
+    _logger.log(log_level, buffer.decode('utf-8'))
+
+
+def _set_log_callback():
+    """
+    Note, that we could also set the set_log_userdata() to access the logger object,
+    but I did not find it much useful when it is global already.
+    """
+    callbacks.ssh_set_log_callback(_pylibssh_log_wrapper)
+
+
+def _initialize_logging():
+    """
+    This is done globally, as the libssh logging is not tied to specific session
+    (its thread-local state in libssh) so either very good care needs to be taken
+    to make sure the logger is in place when callback can be called almost from
+    anywhere in the code or just keep it global.
+    """
+    _add_trace_log_level()
+    _set_log_callback()
+
+
+def _set_level(level):
+    """
+    Set logging level to the given value from LOG_MAP
+
+    :param level: The level to set.
+
+    :raises LibsshSessionException: If the log level is not known by pylibssh.
+
+    :return: Nothing.
+    :rtype: NoneType
+    """
+    _initialize_logging()
+    if level not in LOG_MAP:
+        raise LibsshSessionException(f'Invalid log level [{level:d}]')
+
+    # Special case not-set does not go deeper
+    if level == _NOT_SET_SENTINEL:
+        return
+
+    rc = libssh.ssh_set_log_level(LOG_MAP[level])
+    if rc != libssh.SSH_OK:
+        raise LibsshSessionException(
+            f'Failed to set log level [{level:d}] with error [{rc:d}]',
+        )
+    _logger.setLevel(level)

src/pylibsshext/session.pyx

@@ -15,12 +15,14 @@
 # License along with this library; if not, see file LICENSE.rst in this
 # repository.
 import inspect
-import logging
 
 from cpython.bytes cimport PyBytes_AS_STRING
 
 from pylibsshext.channel import Channel
+
 from pylibsshext.errors cimport LibsshSessionException
+
+from pylibsshext.logging import _set_level
 from pylibsshext.scp import SCP
 from pylibsshext.sftp import SFTP
 
@@ -45,15 +47,6 @@ OPTS_DIR_MAP = {
     "add_identity": libssh.SSH_OPTIONS_ADD_IDENTITY,
 }
 
-LOG_MAP = {
-    logging.NOTSET: libssh.SSH_LOG_NONE,
-    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_TRACE
-}
-
 KNOW_HOST_MSG_MAP = {
     libssh.SSH_KNOWN_HOSTS_CHANGED: "Host key for server has changed: ",
     libssh.SSH_KNOWN_HOSTS_OTHER: "Host key type for server has changed: ",
@@ -528,12 +521,7 @@ cdef class Session(object):
         return SFTP(self)
 
     def set_log_level(self, level):
-        if level in LOG_MAP.keys():
-            rc = libssh.ssh_set_log_level(LOG_MAP[level])
-            if rc != libssh.SSH_OK:
-                raise LibsshSessionException("Failed to set log level [%d] with error [%d]" % (level, rc))
-        else:
-            raise LibsshSessionException("Invalid log level [%d]" % level)
+        _set_level(level)
 
     def close(self):
         if self._libssh_session is not NULL:

tests/conftest.py

@@ -3,7 +3,6 @@
 
 """Pytest plugins and fixtures configuration."""
 
-import logging
 import shutil
 import socket
 import subprocess
@@ -14,6 +13,7 @@
     ensure_ssh_session_connected, wait_for_svc_ready_state,
 )
 
+from pylibsshext.logging import ANSIBLE_PYLIBSSH_TRACE
 from pylibsshext.session import Session
 
 
@@ -116,8 +116,7 @@ def ssh_client_session(ssh_session_connect):
     # noqa: DAR101
     """
     ssh_session = Session()
-    # TODO Adjust when #597 will be merged
-    ssh_session.set_log_level(logging.CRITICAL)
+    ssh_session.set_log_level(ANSIBLE_PYLIBSSH_TRACE)
     ssh_session_connect(ssh_session)
     try:  # noqa: WPS501
         yield ssh_session

tests/unit/session_test.py

@@ -2,12 +2,18 @@
 
 """Tests suite for session."""
 
+import logging
+
 import pytest
 
 from pylibsshext.errors import LibsshSessionException
+from pylibsshext.logging import ANSIBLE_PYLIBSSH_NOLOG, ANSIBLE_PYLIBSSH_TRACE
 from pylibsshext.session import Session
 
 
+LOCALHOST = '127.0.0.1'
+
+
 def test_make_session():
     """Smoke-test Session instance creation."""
     assert Session()
@@ -27,4 +33,59 @@ def test_session_connection_refused(free_port_num):
     error_msg = '^ssh connect failed: Connection refused$'
     ssh_session = Session()
     with pytest.raises(LibsshSessionException, match=error_msg):
-        ssh_session.connect(host='127.0.0.1', port=free_port_num)
+        ssh_session.connect(host=LOCALHOST, port=free_port_num)
+
+
+def test_session_log_level_debug(caplog, free_port_num):
+    """Test setting the log level to DEBUG should reveal copyright information. But no trace messages."""
+    ssh_session = Session()
+    ssh_session.set_log_level(logging.DEBUG)
+
+    # the connection will fail but first log lands before that
+    with pytest.raises(LibsshSessionException, match='ssh connect failed: Connection refused'):
+        ssh_session.connect(host=LOCALHOST, port=free_port_num)
+
+    expected_copyright_substring = 'and libssh contributors.'
+    # This log message is shown at different log levels
+    # in different libssh versions:
+    expected_copyright_log_levels = {'DEBUG', 'INFO'}
+    informational_log_messages = (
+        record.msg
+        for record in caplog.records
+        if record.levelname in expected_copyright_log_levels
+    )
+    assert any(expected_copyright_substring in message for message in informational_log_messages)
+
+    for record in caplog.records:
+        if record.levelname == 'TRACE':
+            assert not 'Found unexpected TRACE message {msg}'.format(msg=record.msg)
+
+
+def test_session_log_level_no_log(caplog, free_port_num):
+    """Test setting the log level to NOLOG should be quiet."""
+    ssh_session = Session()
+    ssh_session.set_log_level(ANSIBLE_PYLIBSSH_NOLOG)
+
+    # the connection will fail but first log lands before that
+    with pytest.raises(LibsshSessionException, match='ssh connect failed: Connection refused'):
+        ssh_session.connect(host=LOCALHOST, port=free_port_num)
+
+    assert not caplog.records
+
+
+def test_session_log_level_trace(caplog, free_port_num):
+    """Test setting the log level to TRACE should provide all of the logs."""
+    ssh_session = Session()
+    ssh_session.set_log_level(ANSIBLE_PYLIBSSH_TRACE)
+
+    # the connection will fail but first log lands before that
+    with pytest.raises(LibsshSessionException, match='ssh connect failed: Connection refused'):
+        ssh_session.connect(host=LOCALHOST, port=free_port_num)
+
+    expected_poll_message = 'ssh_socket_pollcallback: Poll callback on socket'
+    informational_log_messages = (
+        record.msg
+        for record in caplog.records
+        if record.levelname == 'TRACE'
+    )
+    assert any(expected_poll_message in message for message in informational_log_messages)