Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Fix the log levels mapping #597

Open
wants to merge 3 commits into
base: devel
Choose a base branch
from
Open
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 1 addition & 0 deletions docs/changelog-fragments/597.bugfix.rst
Original file line number Diff line number Diff line change
@@ -0,0 +1 @@
Fixed log level mapping to cover whole libssh range -- by :user:`Jakuje`.
7 changes: 7 additions & 0 deletions src/pylibsshext/includes/callbacks.pxd
Original file line number Diff line number Diff line change
Expand Up @@ -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)
23 changes: 23 additions & 0 deletions src/pylibsshext/logging.pxd
Original file line number Diff line number Diff line change
@@ -0,0 +1,23 @@
# 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.
#
from pylibsshext.includes cimport callbacks, libssh


cdef class Logging:
pass
101 changes: 101 additions & 0 deletions src/pylibsshext/logging.pyx
Original file line number Diff line number Diff line change
@@ -0,0 +1,101 @@
#
# 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.

import logging

from pylibsshext.errors cimport LibsshSessionException


ANSIBLE_PYLIBSSH_TRACE = 5

LOG_MAP = {
logging.NOTSET: libssh.SSH_LOG_NONE,
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_WARN
}

LOG_MAP_REV = {
libssh.SSH_LOG_NONE: logging.NOTSET,
libssh.SSH_LOG_TRACE: ANSIBLE_PYLIBSSH_TRACE,
libssh.SSH_LOG_DEBUG: logging.DEBUG,
libssh.SSH_LOG_INFO: logging.INFO,
libssh.SSH_LOG_WARN: logging.WARNING,
}

logger = logging.getLogger("libssh")


def add_trace_log_level():
level_num = ANSIBLE_PYLIBSSH_TRACE
level_name = "TRACE"
method_name = level_name.lower()
logger_class = logging.getLoggerClass()

if hasattr(logging, level_name):
raise AttributeError('{} already defined in logging module'.format(level_name))
if hasattr(logging, method_name):
raise AttributeError('{} already defined in logging module'.format(method_name))
if hasattr(logger_class, method_name):
raise AttributeError('{} already defined in logger class'.format(method_name))

def logForLevel(self, message, *args, **kwargs):
if self.isEnabledFor(level_num):
self._log(level_num, message, args, **kwargs)

def logToRoot(message, *args, **kwargs):
logging.log(level_num, message, *args, **kwargs)

logging.addLevelName(level_num, level_name)
setattr(logging, level_name, level_num)
setattr(logging, method_name, logToRoot)
setattr(logger_class, method_name, logForLevel)


cdef void _pylibssh_log_wrapper(int priority,
const char *function,
const char *buffer,
void *userdata) noexcept nogil:
with gil:
log_level = LOG_MAP_REV[priority]
logger.log(log_level, f"{buffer}")


def set_log_callback():
callbacks.ssh_set_log_callback(_pylibssh_log_wrapper)


def logging_init():
try:
add_trace_log_level()
except AttributeError:
pass
set_log_callback()


def set_level(level):
logging_init()
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))
logger.setLevel(level)
else:
raise LibsshSessionException("Invalid log level [%d]" % level)
21 changes: 5 additions & 16 deletions src/pylibsshext/session.pyx
Original file line number Diff line number Diff line change
Expand Up @@ -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

Expand All @@ -44,15 +46,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,
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This doesn't sound right. Why not just add another level called TRACE mapped to a low numeric value like 5? (DEBUG is 10 in stdlib)

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I am not much knowledgeable about python so sorry if I miss something.

How would callers discover and set such custom log level?

As I can see from ansible-collections/ansible.netcommon this is called like

            self.ssh.set_log_level(logging.INFO)

Would it mean we should define a new list of log levels that could be used instead of the standard one? I can certainly do that if it would be preferred. I would consider it as quite a barrier to cross for the users updating from older version to learn there is one more non-standard log level and how to set it.

This was an attempt to provide full mapping of standard log levels to libssh log levels for the price of lower granularity on the verbose end (the difference between DEBUG and TRACE is not that significant, but the later is much more useful).

If you want full granularity, maybe placing the libssh SSH_LOG_DEBUG between the DEBUG and INFO with value lets say 15 might be better to simplify the barrier to set up the most verbose debug level?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm leaning towards custom log level, but a precise one.

There's a warning recommending not to add custom log levels to libraries, though: https://docs.python.org/3/howto/logging.html#custom-levels.

Somewhere on the page, it's also suggested that https://docs.python.org/3/library/logging.html#logging.Logger.log should be used for such cases.

And https://docs.python.org/3/library/logging.html#logging.addLevelName exists for declaring additional log levels.

I wonder if we should declare some ANSIBLE_PYLIBSSH_-prefixed levels for custom in-between stuff. We could then also expose importable constants that the end-users of the library would be able to use w/o clushing with stdlib. This would address the concern of that stdlib docs warning.

I don't think we should shift what DEBUG means. And SSH_LOG_DEBUG shouldn't be reassigned to "something between debug and info". Instead, a new ANSIBLE_PYLIBSSH_TRACE could exist that would be represented by a number below 10.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don't know. I am not that much of a python programmer. The first linked paragraph explicitly discourages the use of custom log levels in libraries, but I did not dive into that deep enough.

My reasoning for shifting the stdlib DEBUG to libssh TRACE is that the DEBUG is the most verbose logging in stdlib and therefore it should map to the most verbose log level in libssh. If it does not, setting the "most verbose" log level becomes more complicated for users/developers using the pylibssh and debugging further issues that require more verbose log will become harder for us, libssh developers.

So if you have some idea/strong opinion how this should work, please, feel free to propose the changes.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

What I outlined above seems to be the way to go, API-wise. If we start re-assigning the log levels and create mismatches, that would cause more confusion, in my opinion. This library mostly supposed to be a way to re-expose the binding, not re-define the API though the own facade. New log levels would have to be exposed through an accessible import module. I believe that something like from pylibsshext.logging import ANSIBLE_PYLIBSSH_TRACE is ergonomic enough and aligns with the pythonic principles/expectations.

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: ",
Expand Down Expand Up @@ -334,6 +327,7 @@ cdef class Session(object):
if rc != libssh.SSH_OK:
return

# FIXME The SHA1 hashes are non-standard -- the most common these days are SHA256 hashes for fingerprints
rc = libssh.ssh_get_publickey_hash(srv_pubkey, libssh.SSH_PUBLICKEY_HASH_SHA1, &hash, &hash_len)

cdef libssh.ssh_keytypes_e key_type = libssh.ssh_key_type(srv_pubkey)
Expand Down Expand Up @@ -520,12 +514,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:
Expand Down
53 changes: 52 additions & 1 deletion tests/unit/session_test.py
Original file line number Diff line number Diff line change
Expand Up @@ -2,12 +2,18 @@

"""Tests suite for session."""

import logging

import pytest

from pylibsshext.errors import LibsshSessionException
from pylibsshext.logging import ANSIBLE_PYLIBSSH_TRACE
from pylibsshext.session import Session


LOCALHOST = '127.0.0.1'


def test_make_session():
"""Smoke-test Session instance creation."""
assert Session()
Expand All @@ -18,4 +24,49 @@ 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."""
ssh_session = Session()
ssh_session.set_log_level(logging.DEBUG)

# the connection will fail but first log lands before that
with pytest.raises(LibsshSessionException):
ssh_session.connect(host=LOCALHOST, port=free_port_num)

found_copyright = False
for record in caplog.records:
# This log message is shown at different log levels in different libssh versions
if record.levelname in {'DEBUG', 'INFO'} and 'and libssh contributors.' in record.msg:
found_copyright = True
assert found_copyright


def test_session_log_level_no_log(caplog, free_port_num):
"""Test setting the log level to NONE should be quiet."""
ssh_session = Session()
ssh_session.set_log_level(logging.NOTSET)

# the connection will fail but first log lands before that
with pytest.raises(LibsshSessionException):
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 even more 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):
ssh_session.connect(host=LOCALHOST, port=free_port_num)

found_trace = False
for record in caplog.records:
if record.levelname == 'TRACE' and 'ssh_socket_pollcallback: Poll callback on socket' in record.msg:
found_trace = True
assert found_trace
Loading