From 9f05e31e92c278c25aceb0ed74fc16f5718842ac Mon Sep 17 00:00:00 2001 From: Vitaliy Mysak Date: Thu, 7 Dec 2023 15:42:20 -0800 Subject: [PATCH] Simplify structured logger utility --- micall/core/contig_stitcher.py | 16 +++++++--------- micall/tests/test_contig_stitcher.py | 22 +++++++++------------- micall/utils/structured_logger.py | 24 +++++++++++++----------- 3 files changed, 29 insertions(+), 33 deletions(-) diff --git a/micall/core/contig_stitcher.py b/micall/core/contig_stitcher.py index d74c1253c..026305fba 100644 --- a/micall/core/contig_stitcher.py +++ b/micall/core/contig_stitcher.py @@ -12,11 +12,10 @@ from micall.utils.cigar_tools import Cigar, connect_cigar_hits, CigarHit from micall.utils.consensus_aligner import CigarActions -from micall.utils.structured_logger import register_structured_logger logger = logging.getLogger(__name__) -register_structured_logger(logger) + @dataclass class Contig: @@ -239,8 +238,8 @@ def logpart(i, part_name, part, is_rev): " (rev)" if is_rev else "", extra={"action": "alignment", "type": "hit", "contig": contig, "part": part, "i": i}) - logger.debug("Part %r of contig %r aligned as %s%s.", i, contig.name, part, - " (rev)" if is_rev else "") + logger.debug("Part %r of contig %r aligned as %r at %s%s.", i, contig.name, + part_name, part, " (rev)" if is_rev else "") to_return = connected + reversed_alignments if len(to_return) == 0: @@ -390,8 +389,8 @@ def combine_overlaps(contigs: List[AlignedContig]) -> Iterable[AlignedContig]: # Find overlap. If there isn't one - we are done with the current contig. overlapping_contig = find_overlapping_contig(current, contigs) if not overlapping_contig: - logger.info("Nothing overlaps with %r.", - current.name, extra={"action": "nooverlap", "contig": current}) + logger.info("Nothing overlaps with %r.", current.name, + extra={"action": "nooverlap", "contig": current}) yield current continue @@ -551,8 +550,7 @@ def stitch_contigs(contigs: Iterable[GenotypedContig]) -> Iterable[AlignedContig extra={"action": "intro", "contig": contig}) logger.debug("Introduced contig %r (seq = %s) of ref %r, group_ref %r (seq = %s), and length %s.", contig.name, contig.seq, contig.ref_name, - contig.group_ref, contig.ref_seq, len(contig.seq), - extra={"action": "intro", "contig": contig}) + contig.group_ref, contig.ref_seq, len(contig.seq)) aligned = align_all_to_reference(contigs) @@ -589,7 +587,7 @@ def combine(group_ref): [repr(x.name) for x in contigs], ret.name, ret.alignment.q_st, ret.alignment.q_ei, ret.alignment.r_st, ret.alignment.r_ei, - extra={"action": "finalcombine", "contigs": contigs}) + extra={"action": "finalcombine", "contigs": contigs, "result": ret}) return ret yield from map(combine, consensus_parts) diff --git a/micall/tests/test_contig_stitcher.py b/micall/tests/test_contig_stitcher.py index 057c16ee7..091073079 100644 --- a/micall/tests/test_contig_stitcher.py +++ b/micall/tests/test_contig_stitcher.py @@ -6,7 +6,7 @@ from micall.core.contig_stitcher import split_contigs_with_gaps, stitch_contigs, GenotypedContig, merge_intervals, find_covered_contig, stitch_consensus, calculate_concordance, align_all_to_reference, main from micall.tests.utils import MockAligner, fixed_random_seed -from micall.utils.structured_logger import iterate_messages +from micall.utils.structured_logger import add_structured_handler from micall.tests.test_denovo import check_hcv_db @@ -655,27 +655,23 @@ def test_correct_processing_complex_logs(exact_aligner): logger = logging.getLogger("micall.core.contig_stitcher") logger.setLevel(logging.DEBUG) + handler = add_structured_handler(logger) - messages = list(iterate_messages()) - assert len(messages) == 0 - + assert len(handler.logs) == 0 list(stitch_consensus(contigs)) + assert len(handler.logs) == 76 - messages = list(iterate_messages()) - assert len(messages) == 76 - assert all(name == "micall.core.contig_stitcher" for name, m in messages) - - info_messages = [m for name, m in messages if m.levelname == 'INFO'] - debug_messages = [m for name, m in messages if m.levelname == 'DEBUG'] + info_messages = [m for m in handler.logs if m.levelname == 'INFO'] + debug_messages = [m for m in handler.logs if m.levelname == 'DEBUG'] assert len(info_messages) == 42 - assert len(debug_messages) == len(messages) - len(info_messages) + assert len(debug_messages) == len(handler.logs) - len(info_messages) actions = [m.__dict__.get('action', '') + ':' + m.__dict__.get('type', '') - for name, m in messages] + for m in handler.logs] actions = [action for action in actions if action != ':'] assert actions == \ - ['intro:'] * 16 + \ + ['intro:'] * 8 + \ ['alignment:reversenumber', 'alignment:hitnumber', 'alignment:hit'] * 8 + \ ['stitchcut:', 'concordance:', 'munge:', 'stitch:'] * 2 + \ ['nooverlap:'] + \ diff --git a/micall/utils/structured_logger.py b/micall/utils/structured_logger.py index 249ce232f..c0f5ae687 100644 --- a/micall/utils/structured_logger.py +++ b/micall/utils/structured_logger.py @@ -1,25 +1,27 @@ import logging -from typing import List, Tuple, Iterable - - -LoggerName = str -_structured_logs: List[Tuple[LoggerName, logging.LogRecord]] = [] +from typing import List, Tuple, Iterable, Callable class InMemoryLogHandler(logging.Handler): def __init__(self, name: str, *args, **kwargs) -> None: super().__init__(*args, **kwargs) self.name: str = name + self.logs: List[logging.LogRecord] = [] + self.callbacks = [] + def emit(self, record: logging.LogRecord): - _structured_logs.append((self.name, record)) + self.logs.append(record) + for callback in self.callbacks: + callback(record) -def register_structured_logger(logger: logging.Logger): - memory_handler = InMemoryLogHandler(logger.name) - logger.addHandler(memory_handler) + def addCallback(self, callback: Callable[[logging.LogRecord], object]): + self.callbacks.append(callback) -def iterate_messages() -> Iterable[Tuple[LoggerName, logging.LogRecord]]: - yield from _structured_logs +def add_structured_handler(logger: logging.Logger): + memory_handler = InMemoryLogHandler(logger.name) + logger.addHandler(memory_handler) + return memory_handler