laforge has submitted this change. ( https://gerrit.osmocom.org/c/pysim/+/41229?usp=email )

Change subject: pySim-shell: add a logger class to centralize logging ......................................................................

pySim-shell: add a logger class to centralize logging

In many sub modules we still use print() to occassionally print status messages or warnings. This technically does not hurt, but it is an unclean solution which we should replace with something more mature.

Let's use python's built in logging framework to create a static logger class that fits our needs. To maintain compatibility let's also make sure that the logger class will behave like a normal print() statement when no configuration parameters are supplied by the API user.

To illustrate how the approach can be used in sub-modules, this patch replaces the print statements in runtime.py. The other print statements will the be fixed in follow-up patches.

Related: OS#6864 Change-Id: I187f117e7e1ccdb2a85dfdfb18e84bd7561704eb --- M pySim-shell.py A pySim/log.py M pySim/runtime.py M tests/pySim-trace_test/pySim-trace_test_gsmtap.pcapng.ok A tests/unittests/test_log.py 5 files changed, 289 insertions(+), 13 deletions(-)

Approvals: laforge: Looks good to me, approved Jenkins Builder: Verified

diff --git a/pySim-shell.py b/pySim-shell.py index 977666c..5a2e4b6 100755 --- a/pySim-shell.py +++ b/pySim-shell.py @@ -22,19 +22,24 @@ import json import traceback import re - import cmd2 from packaging import version from cmd2 import style + +import logging +from pySim.log import PySimLogger + # cmd2 >= 2.3.0 has deprecated the bg/fg in favor of Bg/Fg :( if version.parse(cmd2.__version__) < version.parse("2.3.0"): from cmd2 import fg, bg # pylint: disable=no-name-in-module RED = fg.red + YELLOW = fg.yellow LIGHT_RED = fg.bright_red LIGHT_GREEN = fg.bright_green else: from cmd2 import Fg, Bg # pylint: disable=no-name-in-module RED = Fg.RED + YELLOW = Fg.YELLOW LIGHT_RED = Fg.LIGHT_RED LIGHT_GREEN = Fg.LIGHT_GREEN from cmd2 import CommandSet, with_default_category, with_argparser @@ -67,6 +72,7 @@

from pySim.app import init_card

+log = PySimLogger.get("main")

class Cmd2Compat(cmd2.Cmd): """Backwards-compatibility wrapper around cmd2.Cmd to support older and newer @@ -92,15 +98,19 @@ (C) 2021-2023 by Harald Welte, sysmocom - s.f.m.c. GmbH and contributors Online manual available at https://downloads.osmocom.org/docs/pysim/master/html/shell.html """

- def __init__(self, card, rs, sl, ch, script=None): + def __init__(self, verbose, card, rs, sl, ch, script=None): if version.parse(cmd2.__version__) < version.parse("2.0.0"): kwargs = {'use_ipython': True} else: kwargs = {'include_ipy': True}

+ self.verbose = verbose + self._onchange_verbose('verbose', False, self.verbose); + # pylint: disable=unexpected-keyword-arg super().__init__(persistent_history_file='~/.pysim_shell_history', allow_cli_args=False, auto_load_commands=False, startup_script=script, **kwargs) + PySimLogger.setup(self.poutput, {logging.WARN: YELLOW}) self.intro = style(self.BANNER, fg=RED) self.default_category = 'pySim-shell built-in commands' self.card = None @@ -126,6 +136,9 @@ self.add_settable(Settable2Compat('apdu_strict', bool, 'Enforce APDU responses according to ISO/IEC 7816-3, table 12', self, onchange_cb=self._onchange_apdu_strict)) + self.add_settable(Settable2Compat('verbose', bool, + 'Enable/disable verbose logging', self, + onchange_cb=self._onchange_verbose)) self.equip(card, rs)

def equip(self, card, rs): @@ -210,6 +223,13 @@ else: self.card._scc._tp.apdu_strict = False

+ def _onchange_verbose(self, param_name, old, new): + PySimLogger.set_verbose(new) + if new == True: + PySimLogger.set_level(logging.DEBUG) + else: + PySimLogger.set_level() + class Cmd2ApduTracer(ApduTracer): def __init__(self, cmd2_app): self.cmd2 = cmd2_app @@ -1081,6 +1101,8 @@ action='store_true', default=False) global_group.add_argument("--skip-card-init", help="Skip all card/profile initialization", action='store_true', default=False) +global_group.add_argument("--verbose", help="Enable verbose logging", + action='store_true', default=False)

adm_group = global_group.add_mutually_exclusive_group() adm_group.add_argument('-a', '--pin-adm', metavar='PIN_ADM1', dest='pin_adm', default=None, @@ -1095,12 +1117,16 @@ option_parser.add_argument('command_args', nargs=argparse.REMAINDER, help="Optional Arguments for command")

- if __name__ == '__main__': - startup_errors = False opts = option_parser.parse_args()

+ # Ensure that we are able to print formatted warnings from the beginning. + PySimLogger.setup(print, {logging.WARN: YELLOW}) + if (opts.verbose): + PySimLogger.set_verbose(True) + PySimLogger.set_level(logging.DEBUG) + # Register csv-file as card data provider, either from specified CSV # or from CSV file in home directory csv_column_keys = {} @@ -1127,7 +1153,7 @@ # able to tolerate and recover from that. try: rs, card = init_card(sl, opts.skip_card_init) - app = PysimApp(card, rs, sl, ch) + app = PysimApp(opts.verbose, card, rs, sl, ch) except: startup_errors = True print("Card initialization (%s) failed with an exception:" % str(sl)) @@ -1139,7 +1165,7 @@ print(" it should also be noted that some readers may behave strangely when no card") print(" is inserted.)") print("") - app = PysimApp(None, None, sl, ch) + app = PysimApp(opts.verbose, None, None, sl, ch)

# If the user supplies an ADM PIN at via commandline args authenticate # immediately so that the user does not have to use the shell commands diff --git a/pySim/log.py b/pySim/log.py new file mode 100644 index 0000000..997627f --- /dev/null +++ b/pySim/log.py @@ -0,0 +1,125 @@ +# -*- coding: utf-8 -*- + +""" pySim: Logging +""" + +# +# (C) 2025 by Sysmocom s.f.m.c. GmbH +# All Rights Reserved +# +# Author: Philipp Maier pmaier@sysmocom.de +# +# This program is free software: you can redistribute it and/or modify +# it under the terms of the GNU General Public License as published by +# the Free Software Foundation, either version 2 of the License, or +# (at your option) any later version. +# +# This program 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 General Public License for more details. +# +# You should have received a copy of the GNU General Public License +# along with this program. If not, see http://www.gnu.org/licenses/. +# + +import logging +from cmd2 import style + +class _PySimLogHandler(logging.Handler): + def __init__(self, log_callback): + super().__init__() + self.log_callback = log_callback + + def emit(self, record): + formatted_message = self.format(record) + self.log_callback(formatted_message, record) + +class PySimLogger: + """ + Static class to centralize the log output of PySim applications. This class can be used to print log messages from + any pySim module. Configuration of the log behaviour (see setup and set_ methods) is entirely optional. In case no + print callback is set (see setup method), the logger will pass the log messages directly to print() without applying + any formatting to the original log message. + """ + + LOG_FMTSTR = "%(levelname)s: %(message)s" + LOG_FMTSTR_VERBOSE = "%(module)s.%(lineno)d -- %(name)s - " + LOG_FMTSTR + __formatter = logging.Formatter(LOG_FMTSTR) + __formatter_verbose = logging.Formatter(LOG_FMTSTR_VERBOSE) + + # No print callback by default, means that log messages are passed directly to print() + print_callback = None + + # No specific color scheme by default + colors = {} + + # The logging default is non-verbose logging on logging level DEBUG. This is a safe default that works for + # applications that ignore the presence of the PySimLogger class. + verbose = False + logging.root.setLevel(logging.DEBUG) + + def __init__(self): + raise RuntimeError('static class, do not instantiate') + + @staticmethod + def setup(print_callback = None, colors:dict = {}): + """ + Set a print callback function and color scheme. This function call is optional. In case this method is not + called, default settings apply. + Args: + print_callback : A callback function that accepts the resulting log string as input. The callback should + have the following format: print_callback(message:str) + colors : An optional dict through which certain log levels can be assigned a color. + (e.g. {logging.WARN: YELLOW}) + """ + PySimLogger.print_callback = print_callback + PySimLogger.colors = colors + + @staticmethod + def set_verbose(verbose:bool = False): + """ + Enable/disable verbose logging. (has no effect in case no print callback is set, see method setup) + Args: + verbose: verbosity (True = verbose logging, False = normal logging) + """ + PySimLogger.verbose = verbose; + + @staticmethod + def set_level(level:int = logging.DEBUG): + """ + Set the logging level. + Args: + level: Logging level, valis log leves are: DEBUG, INFO, WARNING, ERROR and CRITICAL + """ + logging.root.setLevel(level) + + @staticmethod + def _log_callback(message, record): + if not PySimLogger.print_callback: + # In case no print callback has been set display the message as if it were printed trough a normal + # python print statement. + print(record.message) + else: + # When a print callback is set, use it to display the log line. Apply color if the API user chose one + if PySimLogger.verbose: + formatted_message = logging.Formatter.format(PySimLogger.__formatter_verbose, record) + else: + formatted_message = logging.Formatter.format(PySimLogger.__formatter, record) + color = PySimLogger.colors.get(record.levelno) + if color: + PySimLogger.print_callback(style(formatted_message, fg = color)) + else: + PySimLogger.print_callback(formatted_message) + + @staticmethod + def get(log_facility: str): + """ + Set up and return a new python logger object + Args: + log_facility : Name of log facility (e.g. "MAIN", "RUNTIME"...) + """ + logger = logging.getLogger(log_facility) + handler = _PySimLogHandler(log_callback=PySimLogger._log_callback) + logger.addHandler(handler) + return logger diff --git a/pySim/runtime.py b/pySim/runtime.py index 5bb730e..ab21912 100644 --- a/pySim/runtime.py +++ b/pySim/runtime.py @@ -23,6 +23,9 @@

from pySim.exceptions import * from pySim.filesystem import * +from pySim.log import PySimLogger + +log = PySimLogger.get("RUNTIME")

def lchan_nr_from_cla(cla: int) -> int: """Resolve the logical channel number from the CLA byte.""" @@ -44,6 +47,7 @@ card : pysim.cards.Card instance profile : CardProfile instance """ + self.mf = CardMF(profile=profile) self.card = card self.profile = profile @@ -66,7 +70,7 @@ for addon_cls in self.profile.addons: addon = addon_cls() if addon.probe(self.card): - print("Detected %s Add-on "%s"" % (self.profile, addon)) + log.info("Detected %s Add-on "%s"" % (self.profile, addon)) for f in addon.files_in_mf: self.mf.add_file(f)

@@ -100,18 +104,18 @@ apps_taken = [] if aids_card: aids_taken = [] - print("AIDs on card:") + log.info("AIDs on card:") for a in aids_card: for f in apps_profile: if f.aid in a: - print(" %s: %s (EF.DIR)" % (f.name, a)) + log.info(" %s: %s (EF.DIR)" % (f.name, a)) aids_taken.append(a) apps_taken.append(f) aids_unknown = set(aids_card) - set(aids_taken) for a in aids_unknown: - print(" unknown: %s (EF.DIR)" % a) + log.info(" unknown: %s (EF.DIR)" % a) else: - print("warning: EF.DIR seems to be empty!") + log.warn("EF.DIR seems to be empty!")

# Some card applications may not be registered in EF.DIR, we will actively # probe for those applications @@ -126,7 +130,7 @@ _data, sw = self.card.select_adf_by_aid(f.aid) self.selected_adf = f if sw == "9000": - print(" %s: %s" % (f.name, f.aid)) + log.info(" %s: %s" % (f.name, f.aid)) apps_taken.append(f) except (SwMatchError, ProtocolError): pass diff --git a/tests/pySim-trace_test/pySim-trace_test_gsmtap.pcapng.ok b/tests/pySim-trace_test/pySim-trace_test_gsmtap.pcapng.ok index 395acbf..423f25e 100644 --- a/tests/pySim-trace_test/pySim-trace_test_gsmtap.pcapng.ok +++ b/tests/pySim-trace_test/pySim-trace_test_gsmtap.pcapng.ok @@ -2,7 +2,7 @@ Detected UICC Add-on "GSM-R" Detected UICC Add-on "RUIM" Can't read AIDs from SIM -- 'list' object has no attribute 'lower' -warning: EF.DIR seems to be empty! +EF.DIR seems to be empty! ADF.ECASD: a0000005591010ffffffff8900000200 ADF.ISD-R: a0000005591010ffffffff8900000100 ISIM: a0000000871004 diff --git a/tests/unittests/test_log.py b/tests/unittests/test_log.py new file mode 100755 index 0000000..cc67b78 --- /dev/null +++ b/tests/unittests/test_log.py @@ -0,0 +1,121 @@ +#!/usr/bin/env python3 + +# (C) 2025 by Sysmocom s.f.m.c. GmbH +# All Rights Reserved +# +# Author: Philipp Maier pmaier@sysmocom.de +# +# This program is free software: you can redistribute it and/or modify +# it under the terms of the GNU General Public License as published by +# the Free Software Foundation, either version 2 of the License, or +# (at your option) any later version. +# +# This program 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 General Public License for more details. +# +# You should have received a copy of the GNU General Public License +# along with this program. If not, see http://www.gnu.org/licenses/. + +import unittest +import logging +from pySim.log import PySimLogger +import io +import sys +from inspect import currentframe, getframeinfo + +log = PySimLogger.get("TEST") + +TEST_MSG_DEBUG = "this is a debug message" +TEST_MSG_INFO = "this is an info message" +TEST_MSG_WARNING = "this is a warning message" +TEST_MSG_ERROR = "this is an error message" +TEST_MSG_CRITICAL = "this is a critical message" + +expected_message = None + +class PySimLogger_Test(unittest.TestCase): + + def __test_01_safe_defaults_one(self, callback, message:str): + # When log messages are sent to an unconfigured PySimLogger class, we expect the unmodified message being + # logged to stdout, just as if it were printed via a normal print() statement. + log_output = io.StringIO() + sys.stdout = log_output + callback(message) + assert(log_output.getvalue().strip() == message) + sys.stdout = sys.__stdout__ + + def test_01_safe_defaults(self): + # When log messages are sent to an unconfigured PySimLogger class, we expect that all messages are logged, + # regardless of the logging level. + self.__test_01_safe_defaults_one(log.debug, TEST_MSG_DEBUG) + self.__test_01_safe_defaults_one(log.info, TEST_MSG_INFO) + self.__test_01_safe_defaults_one(log.warning, TEST_MSG_WARNING) + self.__test_01_safe_defaults_one(log.error, TEST_MSG_ERROR) + self.__test_01_safe_defaults_one(log.critical, TEST_MSG_CRITICAL) + + @staticmethod + def _test_print_callback(message): + assert(message.strip() == expected_message) + + def test_02_normal(self): + # When the PySimLogger is set up with its default values, we expect formatted log messages on all logging + # levels. + global expected_message + PySimLogger.setup(self._test_print_callback) + expected_message = "DEBUG: " + TEST_MSG_DEBUG + log.debug(TEST_MSG_DEBUG) + expected_message = "INFO: " + TEST_MSG_INFO + log.info(TEST_MSG_INFO) + expected_message = "WARNING: " + TEST_MSG_WARNING + log.warning(TEST_MSG_WARNING) + expected_message = "ERROR: " + TEST_MSG_ERROR + log.error(TEST_MSG_ERROR) + expected_message = "CRITICAL: " + TEST_MSG_CRITICAL + log.critical(TEST_MSG_CRITICAL) + + def test_03_verbose(self): + # When the PySimLogger is set up with its default values, we expect verbose formatted log messages on all + # logging levels. + global expected_message + PySimLogger.setup(self._test_print_callback) + PySimLogger.set_verbose(True) + frame = currentframe() + expected_message = __name__ + "." + str(getframeinfo(frame).lineno + 1) + " -- TEST - DEBUG: " + TEST_MSG_DEBUG + log.debug(TEST_MSG_DEBUG) + expected_message = __name__ + "." + str(getframeinfo(frame).lineno + 1) + " -- TEST - INFO: " + TEST_MSG_INFO + log.info(TEST_MSG_INFO) + expected_message = __name__ + "." + str(getframeinfo(frame).lineno + 1) + " -- TEST - WARNING: " + TEST_MSG_WARNING + log.warning(TEST_MSG_WARNING) + expected_message = __name__ + "." + str(getframeinfo(frame).lineno + 1) + " -- TEST - ERROR: " + TEST_MSG_ERROR + log.error(TEST_MSG_ERROR) + expected_message = __name__ + "." + str(getframeinfo(frame).lineno + 1) + " -- TEST - CRITICAL: " + TEST_MSG_CRITICAL + log.critical(TEST_MSG_CRITICAL) + + def test_04_level(self): + # When the PySimLogger is set up with its default values, we expect formatted log messages but since we will + # limit the log level to INFO, we should not see any messages of level DEBUG + global expected_message + PySimLogger.setup(self._test_print_callback) + PySimLogger.set_level(logging.INFO) + + # We test this in non verbose mode, this will also confirm that disabeling the verbose mode works. + PySimLogger.set_verbose(False) + + # Debug messages should not appear + expected_message = None + log.debug(TEST_MSG_DEBUG) + + # All other messages should appear normally + expected_message = "INFO: " + TEST_MSG_INFO + log.info(TEST_MSG_INFO) + expected_message = "WARNING: " + TEST_MSG_WARNING + log.warning(TEST_MSG_WARNING) + expected_message = "ERROR: " + TEST_MSG_ERROR + log.error(TEST_MSG_ERROR) + expected_message = "CRITICAL: " + TEST_MSG_CRITICAL + log.critical(TEST_MSG_CRITICAL) + +if __name__ == '__main__': + unittest.main()