diff --git a/docs/changelog-fragments/597.bugfix.rst b/docs/changelog-fragments/597.bugfix.rst new file mode 100644 index 000000000..3e16c561a --- /dev/null +++ b/docs/changelog-fragments/597.bugfix.rst @@ -0,0 +1 @@ +Fixed log level mapping to cover whole libssh range -- by :user:`Jakuje`. diff --git a/docs/changelog-fragments/597.feature.rst b/docs/changelog-fragments/597.feature.rst new file mode 100644 index 000000000..13020ff3f --- /dev/null +++ b/docs/changelog-fragments/597.feature.rst @@ -0,0 +1 @@ +Made libssh use python logging system -- by :user:`Jakuje`. diff --git a/src/pylibsshext/includes/callbacks.pxd b/src/pylibsshext/includes/callbacks.pxd index 698f5c60b..c875eafdd 100644 --- a/src/pylibsshext/includes/callbacks.pxd +++ b/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) diff --git a/src/pylibsshext/logging.pxd b/src/pylibsshext/logging.pxd new file mode 100644 index 000000000..add48fd6c --- /dev/null +++ b/src/pylibsshext/logging.pxd @@ -0,0 +1,22 @@ +# 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. + +""" +The Logging module of pylibssh providers interface between libssh logging and +python log facility. +""" diff --git a/src/pylibsshext/logging.pyx b/src/pylibsshext/logging.pyx new file mode 100644 index 000000000..75c2e85fd --- /dev/null +++ b/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) diff --git a/src/pylibsshext/session.pyx b/src/pylibsshext/session.pyx index e44746617..a5592ae8c 100644 --- a/src/pylibsshext/session.pyx +++ b/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: diff --git a/tests/conftest.py b/tests/conftest.py index 0770b3482..b329814dc 100644 --- a/tests/conftest.py +++ b/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 diff --git a/tests/unit/session_test.py b/tests/unit/session_test.py index d634289a3..6227df52c 100644 --- a/tests/unit/session_test.py +++ b/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)