catarrh/pysim-local
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

pySim-shell: add a logger class to centralize logging

Browse Source 
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
This commit is contained in:
Philipp Maier
2025-10-17 16:22:48 +02:00
committed by laforge
parent 1ab2f8dd9d
commit 4429e1cc70
5 changed files with 289 additions and 13 deletions
Download Patch File Download Diff File Expand all files Collapse all files

38
pySim-shell.py
View File

@@ -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

125
pySim/log.py Normal file
View File

@@ -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

16
pySim/runtime.py
View File

@@ -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

2
tests/pySim-trace_test/pySim-trace_test_gsmtap.pcapng.ok
View File

@@ -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

121
tests/unittests/test_log.py Executable file
View File

@@ -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()