Make logger names unique

Fixes #1187

.reuse/dep5

@@ -70,6 +70,7 @@ Files: tests/resources/linn.png
  tests/resources/ccitt.pdf
  tests/resources/cardinal.pdf
  tests/resources/jbig2.pdf
+ tests/resources/jbig2_baddevicen.pdf
  tests/resources/skew.pdf
  tests/resources/rotated_skew.pdf
  tests/resources/poster.pdf

docs/release_notes.rst

@@ -28,6 +28,15 @@ tagged yet.
 
 .. |OCRmyPDF PyPI| image:: https://img.shields.io/pypi/v/ocrmypdf.svg
 
+v15.4.2
+=======
+
+-  We now raise an exception on a certain class of PDFs that likely need an
+   explicit color conversion strategy selected to display correctly
+   for PDF/A conversion.
+-  Fixed an error that occurred while trying to write a log message after the
+   debug log handler was removed.
+
 v15.4.1
 =======
 

src/ocrmypdf/_exec/ghostscript.py

@@ -8,6 +8,7 @@ from __future__ import annotations
 import logging
 import os
 import re
+from collections import deque
 from io import BytesIO
 from os import fspath
 from pathlib import Path
@@ -16,7 +17,7 @@ from subprocess import PIPE, CalledProcessError
 from packaging.version import Version
 from PIL import Image, UnidentifiedImageError
 
-from ocrmypdf.exceptions import SubprocessOutputError
+from ocrmypdf.exceptions import ColorConversionNeededError, SubprocessOutputError
 from ocrmypdf.helpers import Resolution
 from ocrmypdf.subprocess import get_version, run, run_polling_stderr
 
@@ -29,38 +30,44 @@ COLOR_CONVERSION_STRATEGIES = frozenset(
         'UseDeviceIndependentColor',
     ]
 )
+# Ghostscript executable - gswin32c is not supported
+GS = 'gswin64c' if os.name == 'nt' else 'gs'
+
 
 log = logging.getLogger(__name__)
 
 
 class DuplicateFilter(logging.Filter):
-    """Filter out duplicate log messages."""
+    """Filter out duplicate log messages.
 
-    def __init__(self, logger: logging.Logger):
-        self.last: logging.LogRecord | None = None
-        self.count = 0
+    A context window of default 5 messages is used to determine if a message is a
+    duplicate. This is because some Ghostscript messages are word wrapped.
+    """
+
+    def __init__(self, logger: logging.Logger, context_window=5):
+        self.window: deque[str] = deque([], maxlen=context_window)
         self.logger = logger
+        self.levelno = logging.DEBUG
+        self.count = 0
 
     def filter(self, record):
-        if self.last and record.msg == self.last.msg:
+        if record.msg in self.window:
             self.count += 1
+            self.levelno = record.levelno
             return False
         else:
             if self.count >= 1:
-                rep_msg = f"(previous message repeated {self.count} times)"
+                rep_msg = f"(suppressed {self.count} repeated lines)"
                 self.count = 0  # Avoid infinite recursion
-                self.logger.log(self.last.levelno, rep_msg)
-            self.last = record
+                self.logger.log(self.levelno, rep_msg)
+                self.window.clear()
+            self.window.append(record.msg)
             return True
 
 
 log.addFilter(DuplicateFilter(log))
 
 
-# Ghostscript executable - gswin32c is not supported
-GS = 'gswin64c' if os.name == 'nt' else 'gs'
-
-
 def version() -> Version:
     return Version(get_version(GS))
 
@@ -70,6 +77,20 @@ def _gs_error_reported(stream) -> bool:
     return bool(match)
 
 
+def _gs_devicen_reported(stream) -> bool:
+    """Did Ghostscript warn about a DeviceN with inappropriate alternate?
+
+    If so, we need the user to select a color conversion, or the resulting PDF will
+    not present correctly in some PDF viewers.
+    """
+    match = re.search(
+        r'DeviceN.*inappropriate alternate',
+        stream,
+        flags=re.IGNORECASE | re.MULTILINE,
+    )
+    return bool(match)
+
+
 def rasterize_pdf(
     input_file: os.PathLike,
     output_file: os.PathLike,
@@ -243,7 +264,6 @@ def generate_pdfa(
         ]
     )
     args_gs.extend(fspath(s) for s in pdf_pages)  # Stringify Path objs
-
     try:
         with Path(output_file).open('wb') as output:
             p = run_polling_stderr(
@@ -272,3 +292,5 @@ def generate_pdfa(
             # the **** pattern to split the stderr into parts.
             for part in stderr.split('****'):
                 log.error(part)
+        if _gs_devicen_reported(stderr):
+            raise ColorConversionNeededError()

src/ocrmypdf/_pipelines/_common.py

@@ -155,9 +155,11 @@ class HOCRResult:
 
 def configure_debug_logging(
     log_filename: Path, prefix: str = ''
-) -> logging.FileHandler:
+) -> tuple[logging.FileHandler, Callable[[], None]]:
     """Create a debug log file at a specified location.
 
+    Returns the log handler, and a function to remove the handler.
+
     Args:
         log_filename: Where to the put the log file.
         prefix: The logging domain prefix that should be sent to the log.
@@ -170,7 +172,15 @@ def configure_debug_logging(
     log_file_handler.setFormatter(formatter)
     log_file_handler.addFilter(PageNumberFilter())
     logging.getLogger(prefix).addHandler(log_file_handler)
-    return log_file_handler
+
+    def remover():
+        try:
+            logging.getLogger(prefix).removeHandler(log_file_handler)
+            log_file_handler.close()
+        except OSError as e:
+            print(e, file=sys.stderr)
+
+    return log_file_handler, remover
 
 
 def worker_init(max_pixels: int) -> None:
@@ -188,25 +198,21 @@ def manage_debug_log_handler(
     options: argparse.Namespace,
     work_folder: Path,
 ):
-    debug_log_handler = None
+    remover = None
     if (options.keep_temporary_files or options.verbose >= 1) and not os.environ.get(
         'PYTEST_CURRENT_TEST', ''
     ):
         # Debug log for command line interface only with verbose output
         # See https://github.com/pytest-dev/pytest/issues/5502 for why we skip this
         # when pytest is running
-        debug_log_handler = configure_debug_logging(
-            work_folder / "debug.log"
+        _debug_log_handler, remover = configure_debug_logging(
+            work_folder / "debug.log", prefix=""
         )  # pragma: no cover
     try:
         yield
     finally:
-        if debug_log_handler:
-            try:
-                debug_log_handler.close()
-                log.removeHandler(debug_log_handler)
-            except OSError as e:
-                print(e, file=sys.stderr)
+        if remover:
+            remover()
 
 
 @contextmanager

src/ocrmypdf/exceptions.py

@@ -137,3 +137,16 @@ class TaggedPDFError(InputFileError):
         override this error.
         """
     )
+
+
+class ColorConversionNeededError(BadArgsError):
+    """PDF needs color conversion."""
+
+    message = dedent(
+        """\
+        The input PDF has an unusual color space. Use
+        --color-conversion-strategy to convert to a common color space
+        such as RGB, or use --output-type pdf to skip PDF/A conversion
+        and retain the original color space.
+        """
+    )

tests/test_ghostscript.py

@@ -4,6 +4,7 @@
 from __future__ import annotations
 
 import logging
+import secrets
 import subprocess
 from decimal import Decimal
 from unittest.mock import patch
@@ -13,7 +14,7 @@ import pytest
 from PIL import Image, UnidentifiedImageError
 
 from ocrmypdf._exec.ghostscript import DuplicateFilter, rasterize_pdf
-from ocrmypdf.exceptions import ExitCode
+from ocrmypdf.exceptions import ColorConversionNeededError, ExitCode
 from ocrmypdf.helpers import Resolution
 
 from .conftest import check_ocrmypdf, run_ocrmypdf_api
@@ -126,6 +127,16 @@ def test_ghostscript_feature_elision(resources, outpdf):
     )
 
 
+def test_ghostscript_mandatory_color_conversion(resources, outpdf):
+    with pytest.raises(ColorConversionNeededError):
+        check_ocrmypdf(
+            resources / 'jbig2_baddevicen.pdf',
+            outpdf,
+            '--plugin',
+            'tests/plugins/tesseract_noop.py',
+        )
+
+
 def test_rasterize_pdf_errors(resources, no_outpdf, caplog):
     with patch('ocrmypdf._exec.ghostscript.run') as mock:
         # ghostscript can produce
@@ -144,9 +155,10 @@ def test_rasterize_pdf_errors(resources, no_outpdf, caplog):
 
 
 class TestDuplicateFilter:
-    @pytest.fixture(scope='class', autouse=True)
+    @pytest.fixture(scope='function')
     def duplicate_filter_logger(self):
-        logger = logging.getLogger(__name__)
+        # token_urlsafe: ensure the logger has a unique name so tests are isolated
+        logger = logging.getLogger(__name__ + secrets.token_urlsafe(8))
         logger.setLevel(logging.DEBUG)
         logger.addFilter(DuplicateFilter(logger))
         return logger
@@ -162,9 +174,9 @@ class TestDuplicateFilter:
 
         assert len(caplog.records) == 5
         assert caplog.records[0].msg == "test error message"
-        assert caplog.records[1].msg == "(previous message repeated 2 times)"
+        assert caplog.records[1].msg == "(suppressed 2 repeated lines)"
         assert caplog.records[2].msg == "another error message"
-        assert caplog.records[3].msg == "(previous message repeated 1 times)"
+        assert caplog.records[3].msg == "(suppressed 1 repeated lines)"
         assert caplog.records[4].msg == "yet another error message"
 
     def test_filter_does_not_affect_unique_messages(
@@ -179,3 +191,20 @@ class TestDuplicateFilter:
         assert caplog.records[0].msg == "test error message"
         assert caplog.records[1].msg == "another error message"
         assert caplog.records[2].msg == "yet another error message"
+
+    def test_filter_alt_messages(self, duplicate_filter_logger, caplog):
+        log = duplicate_filter_logger
+        log.error("test error message")
+        log.error("another error message")
+        log.error("test error message")
+        log.error("another error message")
+        log.error("test error message")
+        log.error("test error message")
+        log.error("another error message")
+        log.error("yet another error message")
+
+        assert len(caplog.records) == 4
+        assert caplog.records[0].msg == "test error message"
+        assert caplog.records[1].msg == "another error message"
+        assert caplog.records[2].msg == "(suppressed 5 repeated lines)"
+        assert caplog.records[3].msg == "yet another error message"

tests/test_logging.py

@@ -13,6 +13,6 @@ def test_debug_logging(tmp_path):
     # See https://github.com/pytest-dev/pytest/issues/5502 for pytest logging quirks
     prefix = 'test_debug_logging'
     log = logging.getLogger(prefix)
-    handler = configure_debug_logging(tmp_path / 'test.log', prefix)
+    _handler, remover = configure_debug_logging(tmp_path / 'test.log', prefix)
     log.info("test message")
-    log.removeHandler(handler)
+    remover()