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.

Sign up for GitHub

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

Jump to bottom

A lot about logging... #434

Merged
merged 6 commits into from
Sep 27, 2023
Merged

A lot about logging... #434

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
6 commits
Select commit Hold shift + click to select a range
334807b
feat(log): Turn _COLOR_ENABLED to class variable instead of global
ferdinandjarisch Aug 2, 2023
b9a69b9
feat(log): Add --no-volatile-info as class option to all scanners
ferdinandjarisch May 16, 2023
fbe9aa6
fix(scan_identifiers): Increase log level of scan_identifiers
ferdinandjarisch May 16, 2023
a3e384c
feat(log): Rework setup_logging and separate add_handlers
ferdinandjarisch Sep 15, 2023
9d00bf0
!feat(log): Group loggers in gallia context and remove from objects
ferdinandjarisch Jul 31, 2023
781c4be
doc(logging): Remove no longer existing parameter
ferdinandjarisch Sep 27, 2023
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
2 changes: 1 addition & 1 deletion docs/logging.md
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -29,7 +29,7 @@ from gallia.log import get_logger, setup_logging, Loglevel

# The logfile's loglevel is Loglevel.DEBUG.
# It can be set with the keyword argument file_level.
setup_logging(level=Loglevel.INFO, path="log.json.zst")
setup_logging(level=Loglevel.INFO)
logger = get_logger("test")
logger.info("hello world")
logger.debug("hello debug")
Expand Down
12 changes: 9 additions & 3 deletions src/gallia/cli.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -32,6 +32,7 @@
load_ecu_plugin_eps,
load_transport_plugin_eps,
)
from gallia.utils import get_log_level


def load_parsers() -> Parsers:
Expand Down Expand Up @@ -328,6 +329,7 @@ def cmd_show_plugins() -> None:
def cmd_template(args: argparse.Namespace) -> None:
template = """# [gallia]
# verbosity = <int>
# no-volatile-info = <bool>
# trace_log = <bool>
# lock_file = <str>

Expand Down Expand Up @@ -391,9 +393,6 @@ def main() -> None:
argcomplete.autocomplete(parser)
args = parser.parse_args()

# Will be set to the correct verbosity later.
setup_logging()

if args.show_config:
cmd_show_config(args, config, config_path)
sys.exit(exitcode.OK)
Expand All @@ -418,6 +417,13 @@ def main() -> None:
args.help_func()
parser.exit(exitcode.USAGE)

setup_logging(
level=get_log_level(args),
no_volatile_info=args.no_volatile_info
if hasattr(args, "no_volatile_info")
else True,
)

sys.exit(args.cls_object.entry_point(args))


Expand Down
67 changes: 27 additions & 40 deletions src/gallia/command/base.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -25,12 +25,12 @@
from gallia.config import Config
from gallia.db.handler import DBHandler
from gallia.dumpcap import Dumpcap
from gallia.log import Loglevel, get_logger, setup_logging, tz
from gallia.log import add_zst_log_handler, get_logger, tz
from gallia.plugins import load_transport
from gallia.powersupply import PowerSupply, PowerSupplyURI
from gallia.services.uds.core.exception import UDSException
from gallia.transports import BaseTransport, TargetURI
from gallia.utils import camel_to_snake, dump_args
from gallia.utils import camel_to_snake, dump_args, get_file_log_level


@unique
Expand Down Expand Up @@ -68,6 +68,9 @@ def json(self) -> str:
return msgspec.json.encode(self).decode()


logger = get_logger("gallia.base")


class BaseCommand(ABC):
"""BaseCommand is the baseclass for all gallia commands.
This class can be used in standalone scripts via the
Expand All @@ -93,8 +96,6 @@ class BaseCommand(ABC):
#: The string which is shown at the bottom of --help.
EPILOG: str | None = None

#: The name of the logger when this command is run.
LOGGER_NAME = "gallia"
#: Enable a artifacts_dir. Setting this property to
#: True enables the creation of a logfile.
HAS_ARTIFACTS_DIR: bool = False
Expand All @@ -105,7 +106,6 @@ class BaseCommand(ABC):

def __init__(self, parser: ArgumentParser, config: Config = Config()) -> None:
self.id = camel_to_snake(self.__class__.__name__)
self.logger = get_logger(self.LOGGER_NAME)
self.parser = parser
self.config = config
self.artifacts_dir = Path()
Expand All @@ -128,19 +128,6 @@ def __init__(self, parser: ArgumentParser, config: Config = Config()) -> None:
def run(self, args: Namespace) -> int:
...

def get_log_level(self, args: Namespace) -> Loglevel:
level = Loglevel.INFO
if args.verbose == 1:
level = Loglevel.DEBUG
elif args.verbose >= 2:
level = Loglevel.TRACE
return level

def get_file_log_level(self, args: Namespace) -> Loglevel:
if args.trace_log:
return Loglevel.TRACE
return Loglevel.TRACE if args.verbose >= 2 else Loglevel.DEBUG

def run_hook(
self,
variant: HookVariant,
Expand Down Expand Up @@ -185,16 +172,14 @@ def run_hook(
stdout = p.stdout
stderr = p.stderr
except CalledProcessError as e:
self.logger.warning(
f"{variant.value}-hook failed (exit code: {p.returncode})"
)
logger.warning(f"{variant.value}-hook failed (exit code: {p.returncode})")
stdout = e.stdout
stderr = e.stderr

if stdout:
self.logger.info(p.stdout.strip(), extra={"tags": [hook_id, "stdout"]})
logger.info(p.stdout.strip(), extra={"tags": [hook_id, "stdout"]})
if stderr:
self.logger.info(p.stderr.strip(), extra={"tags": [hook_id, "stderr"]})
logger.info(p.stderr.strip(), extra={"tags": [hook_id, "stderr"]})

def configure_class_parser(self) -> None:
group = self.parser.add_argument_group("generic arguments")
Expand All @@ -205,6 +190,12 @@ def configure_class_parser(self) -> None:
default=self.config.get_value("gallia.verbosity", 0),
help="increase verbosity on the console",
)
group.add_argument(
"--no-volatile-info",
action="store_true",
default=self.config.get_value("gallia.no-volatile-info", False),
help="do not overwrite log lines with level info or lower in terminal output",
)
group.add_argument(
"--trace-log",
action=argparse.BooleanOptionalAction,
Expand Down Expand Up @@ -328,9 +319,9 @@ def _aquire_flock(self, path: Path) -> None:
# log a message and do a blocking wait afterwards.
fcntl.flock(self._lock_file_fd, fcntl.LOCK_EX | fcntl.LOCK_NB)
except BlockingIOError:
self.logger.notice(f"Waiting for flock: {path}")
logger.notice(f"Waiting for flock: {path}")
fcntl.flock(self._lock_file_fd, fcntl.LOCK_EX)
self.logger.info("Acquired lock. Continuing.")
logger.info("Acquired lock. Continuing.")

def _release_flock(self) -> None:
assert self._lock_file_fd
Expand All @@ -342,21 +333,19 @@ def entry_point(self, args: Namespace) -> int:
try:
self._aquire_flock(p)
except OSError as e:
self.logger.critical(f"Unable to lock {p}: {e}")
logger.critical(f"Unable to lock {p}: {e}")
return exitcode.OSFILE

if self.HAS_ARTIFACTS_DIR:
self.artifacts_dir = self.prepare_artifactsdir(
args.artifacts_base,
args.artifacts_dir,
)
setup_logging(
self.get_log_level(args),
self.get_file_log_level(args),
self.artifacts_dir.joinpath(FileNames.LOGFILE.value),
add_zst_log_handler(
logger_name="gallia",
filepath=self.artifacts_dir.joinpath(FileNames.LOGFILE.value),
file_log_level=get_file_log_level(args),
)
else:
setup_logging(self.get_log_level(args))

if args.hooks:
self.run_hook(HookVariant.PRE, args)
Expand All @@ -379,14 +368,14 @@ def entry_point(self, args: Namespace) -> int:
if isinstance(e, t):
# TODO: Map the exitcode to superclass of builtin exceptions.
exit_code = exitcode.IOERR
self.logger.critical(
logger.critical(
f"Caught expected exception, stack trace on debug level: {e!r}"
)
self.logger.debug(e, exc_info=True)
logger.debug(e, exc_info=True)
break
else:
exit_code = exitcode.SOFTWARE
self.logger.critical(e, exc_info=True)
logger.critical(e, exc_info=True)
finally:
self.run_meta.exit_code = exit_code
self.run_meta.end_time = datetime.now(tz).isoformat()
Expand All @@ -395,7 +384,7 @@ def entry_point(self, args: Namespace) -> int:
self.artifacts_dir.joinpath(FileNames.META.value).write_text(
self.run_meta.json() + "\n"
)
self.logger.notice(f"Stored artifacts at {self.artifacts_dir}")
logger.notice(f"Stored artifacts at {self.artifacts_dir}")

if args.hooks:
self.run_hook(HookVariant.POST, args, exit_code)
Expand Down Expand Up @@ -521,16 +510,14 @@ async def _db_finish_run_meta(self, args: Namespace, exit_code: int) -> None:
self.artifacts_dir,
)
except Exception as e:
self.logger.warning(
logger.warning(
f"Could not write the run meta to the database: {e!r}"
)

try:
await self.db_handler.disconnect()
except Exception as e:
self.logger.error(
f"Could not close the database connection properly: {e!r}"
)
logger.error(f"Could not close the database connection properly: {e!r}")

async def setup(self, args: Namespace) -> None:
if args.target is None:
Expand Down
23 changes: 11 additions & 12 deletions src/gallia/command/uds.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -9,11 +9,14 @@

from gallia.command.base import FileNames, Scanner
from gallia.config import Config
from gallia.log import get_logger
from gallia.plugins import load_ecu, load_ecu_plugins
from gallia.services.uds.core.service import NegativeResponse, UDSResponse
from gallia.services.uds.ecu import ECU
from gallia.services.uds.helpers import raise_for_error

logger = get_logger("gallia.base.udsscan")


class UDSScanner(Scanner):
"""UDSScanner is a baseclass, particularly for scanning tasks
Expand Down Expand Up @@ -134,19 +137,17 @@ async def setup(self, args: Namespace) -> None:
await self.db_handler.insert_scan_run(args.target.raw)
self._apply_implicit_logging_setting()
except Exception as e:
self.logger.warning(
f"Could not write the scan run to the database: {e:!r}"
)
logger.warning(f"Could not write the scan run to the database: {e:!r}")

if args.ecu_reset is not None:
resp: UDSResponse = await self.ecu.ecu_reset(args.ecu_reset)
if isinstance(resp, NegativeResponse):
self.logger.warning(f"ECUReset failed: {resp}")
self.logger.warning("Switching to default session")
logger.warning(f"ECUReset failed: {resp}")
logger.warning("Switching to default session")
raise_for_error(await self.ecu.set_session(0x01))
resp = await self.ecu.ecu_reset(args.ecu_reset)
if isinstance(resp, NegativeResponse):
self.logger.warning(f"ECUReset in session 0x01 failed: {resp}")
logger.warning(f"ECUReset in session 0x01 failed: {resp}")

# Handles connecting to the target and waits
# until it is ready.
Expand All @@ -171,7 +172,7 @@ async def setup(self, args: Namespace) -> None:
)
self._apply_implicit_logging_setting()
except Exception as e:
self.logger.warning(
logger.warning(
f"Could not write the properties_pre to the database: {e!r}"
)

Expand All @@ -187,17 +188,15 @@ async def teardown(self, args: Namespace) -> None:
prop_pre = json.loads(await file.read())

if args.compare_properties and await self.ecu.properties(False) != prop_pre:
self.logger.warning("ecu properties differ, please investigate!")
logger.warning("ecu properties differ, please investigate!")

if self.db_handler is not None:
try:
await self.db_handler.complete_scan_run(
await self.ecu.properties(False)
)
except Exception as e:
self.logger.warning(
f"Could not write the scan run to the database: {e!r}"
)
logger.warning(f"Could not write the scan run to the database: {e!r}")

if args.tester_present:
await self.ecu.stop_cyclic_tester_present()
Expand Down Expand Up @@ -226,6 +225,6 @@ async def setup(self, args: Namespace) -> None:
try:
await self.db_handler.insert_discovery_run(args.target.url.scheme)
except Exception as e:
self.logger.warning(
logger.warning(
f"Could not write the discovery run to the database: {e!r}"
)
Loading
Loading