diff --git a/pySim-shell.py b/pySim-shell.py index 977666c6..5a2e4b63 100755 --- a/pySim-shell.py +++ b/pySim-shell.py @@ -22,19 +22,24 @@ from typing import List, Optional 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.card_key_provider import CardKeyProviderCsv, card_key_provider_regist 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 @@ class PysimApp(Cmd2Compat): (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 @@ Online manual available at https://downloads.osmocom.org/docs/pysim/master/html/ 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 @@ Online manual available at https://downloads.osmocom.org/docs/pysim/master/html/ 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 @@ global_group.add_argument("--noprompt", help="Run in non interactive mode", 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", nargs='?', 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 @@ if __name__ == '__main__': # 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 @@ if __name__ == '__main__': 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 00000000..997627f4 --- /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 +# +# 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 . +# + +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 5bb730e4..ab21912f 100644 --- a/pySim/runtime.py +++ b/pySim/runtime.py @@ -23,6 +23,9 @@ from osmocom.tlv import bertlv_parse_one 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 @@ class RuntimeState: card : pysim.cards.Card instance profile : CardProfile instance """ + self.mf = CardMF(profile=profile) self.card = card self.profile = profile @@ -66,7 +70,7 @@ class RuntimeState: 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 @@ class RuntimeState: 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 @@ class RuntimeState: _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 395acbff..423f25ea 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 "SIM" 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 00000000..cc67b78f --- /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 +# +# 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 . + +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()