Fix pikepdf PdfMatrix deprecation warning; v15.4.3 release notes

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,21 @@ tagged yet.
 
 .. |OCRmyPDF PyPI| image:: https://img.shields.io/pypi/v/ocrmypdf.svg
 
+v15.4.3
+=======
+
+-  Fixed deprecation warning in pikepdf older than 8.7.1; pikepdf >= 8.7.1 is
+   now required.
+
+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
 =======
 

pyproject.toml

@@ -17,7 +17,7 @@ dependencies = [
   "img2pdf>=0.4.4",
   "packaging>=20",
   "pdfminer.six>=20220319",
-  "pikepdf>=8",
+  "pikepdf>=8.7.1",
   "pluggy>=0.13.0",
   "reportlab>=3.6.8",
   "rich>=13",

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/_graft.py

@@ -12,12 +12,12 @@ from pathlib import Path
 
 from pikepdf import (
     Dictionary,
+    Matrix,
     Name,
     Operator,
     Page,
     Pdf,
     PdfError,
-    PdfMatrix,
     Stream,
     parse_content_stream,
     unparse_content_stream,
@@ -268,13 +268,13 @@ class OcrGrafter:
             mediabox = base_page.mediabox
             wp, hp = mediabox[2] - mediabox[0], mediabox[3] - mediabox[1]
 
-            translate = PdfMatrix().translated(-wt / 2, -ht / 2)
-            untranslate = PdfMatrix().translated(wp / 2, hp / 2)
-            corner = PdfMatrix().translated(mediabox[0], mediabox[1])
+            translate = Matrix().translated(-wt / 2, -ht / 2)
+            untranslate = Matrix().translated(wp / 2, hp / 2)
+            corner = Matrix().translated(mediabox[0], mediabox[1])
             # -rotation because the input is a clockwise angle and this formula
             # uses CCW
             text_rotation = -text_rotation % 360
-            rotate = PdfMatrix().rotated(text_rotation)
+            rotate = Matrix().rotated(text_rotation)
 
             # Because of rounding of DPI, we might get a text layer that is not
             # identically sized to the target page. Scale to adjust. Normally this
@@ -285,12 +285,13 @@ class OcrGrafter:
             scale_y = hp / ht
 
             # log.debug('%r', scale_x, scale_y)
-            scale = PdfMatrix().scaled(scale_x, scale_y)
+            scale = Matrix().scaled(scale_x, scale_y)
 
             # Translate the text so it is centered at (0, 0), rotate it there, adjust
             # for a size different between initial and text PDF, then untranslate, and
-            # finally move the lower left corner to match the mediabox
-            ctm = translate @ rotate @ scale @ untranslate @ corner
+            # finally move the lower left corner to match the mediabox. All transforms
+            # must be premultiplied so they are applied in reverse order here.
+            ctm = corner @ untranslate @ scale @ rotate @ translate
 
             base_resources = _ensure_dictionary(base_page.obj, Name.Resources)
             base_xobjs = _ensure_dictionary(base_resources, Name.XObject)

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.
+        """
+    )

src/ocrmypdf/pdfinfo/info.py

@@ -25,13 +25,13 @@ from warnings import warn
 
 from pdfminer.layout import LTPage, LTTextBox
 from pikepdf import (
+    Matrix,
     Name,
     Object,
     Page,
     Pdf,
     PdfImage,
     PdfInlineImage,
-    PdfMatrix,
     Stream,
     UnsupportedImageTypeError,
     parse_content_stream,
@@ -209,7 +209,7 @@ def _interpret_contents(contentstream: Object, initial_shorthand=UNIT_SQUARE):
     CTM unchanged.
     """
     stack = []
-    ctm = PdfMatrix(initial_shorthand)
+    ctm = Matrix(initial_shorthand)
     xobject_settings: list[XobjectSettings] = []
     inline_images: list[InlineSettings] = []
     name_index = defaultdict(lambda: [])
@@ -240,7 +240,7 @@ def _interpret_contents(contentstream: Object, initial_shorthand=UNIT_SQUARE):
                 # to do. Just pretend nothing happened, keep calm and carry on.
                 warn("PDF graphics stack underflowed - PDF may be malformed")
         elif operator == 'cm':
-            ctm = PdfMatrix(operands) @ ctm
+            ctm = Matrix(operands) @ ctm
         elif operator == 'Do':
             image_name = operands[0]
             settings = XobjectSettings(
@@ -614,12 +614,12 @@ def _process_content_streams(
     ):
         # Set the CTM to the state it was when the "Do" operator was
         # encountered that is drawing this instance of the Form XObject
-        ctm = PdfMatrix(shorthand) if shorthand else PdfMatrix.identity()
+        ctm = Matrix(shorthand) if shorthand else Matrix()
 
         # A Form XObject may provide its own matrix to map form space into
         # user space. Get this if one exists
-        form_shorthand = container.get(Name.Matrix, PdfMatrix.identity())
-        form_matrix = PdfMatrix(form_shorthand)
+        form_shorthand = container.get(Name.Matrix, Matrix())
+        form_matrix = Matrix(form_shorthand)
 
         # Concatenate form matrix with CTM to ensure CTM is correct for
         # drawing this instance of the XObject

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