Simplify structured logger utility

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)

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:'] + \

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