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/plugins.rst

@@ -179,9 +179,11 @@ Execution and progress reporting
 
 .. autoclass:: ocrmypdf.pluginspec.ProgressBar
     :members:
+    :special-members: __init__, __enter__, __exit__
 
 .. autoclass:: ocrmypdf.pluginspec.Executor
     :members:
+    :special-members: __call__
 
 .. autofunction:: ocrmypdf.pluginspec.get_logging_console
 

docs/release_notes.rst

@@ -28,6 +28,25 @@ 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
+=======
+
+-  Fixed misc/watcher.py regressions: accept ``--ocr-json-settings`` as either
+   filename or JSON string, as previously; and argument count mismatch.
+   :issue:`1183,1185`
+-  We no longer attempt to set /ProcSet in the PDF output, since this is an
+   obsolete PDF feature.
+-  Documentation improvements.
+
 v15.4.0
 =======
 
@@ -50,6 +69,8 @@ v15.4.0
    rather than fork, since this is method is more robust and avoids some
    issues when threads are present.
 -  Fixed an instance where the user's request to ``--no-use-threads`` was ignored.
+-  If a PDF does not have language metadata on its top level object, we add
+   the OCR language.
 -  Replace some cryptic test error messages with more helpful ones.
 -  Debug messages for how OCRmyPDF picks the colorspace for a page are now
    more descriptive.

misc/watcher.py

@@ -92,7 +92,6 @@ def execute_ocrmypdf(
     file_path: Path,
     archive_dir: Path,
     output_dir: Path,
-    deskew: bool,
     ocrmypdf_kwargs: dict[str, Any],
     on_success_delete: bool,
     on_success_archive: bool,
@@ -108,10 +107,14 @@ def execute_ocrmypdf(
         log.info(f"Gave up waiting for {file_path} to become ready")
         return
     log.info(f'Attempting to OCRmyPDF to: {output_path}')
+
+    log.debug(
+        f'OCRmyPDF input_file={file_path} output_file={output_path} '
+        f'kwargs: {ocrmypdf_kwargs}'
+    )
     exit_code = ocrmypdf.ocr(
         input_file=file_path,
         output_file=output_path,
-        deskew=deskew,
         **ocrmypdf_kwargs,
     )
     if exit_code == 0:
@@ -146,7 +149,7 @@ class HandleObserverEvent(PatternMatchingEventHandler):
 
     def on_any_event(self, event):
         if event.event_type in ['created']:
-            execute_ocrmypdf(event.src_path, **self._settings)
+            execute_ocrmypdf(file_path=Path(event.src_path), **self._settings)
 
 
 @app.command()
@@ -213,10 +216,10 @@ def main(
         ),
     ] = False,
     ocr_json_settings: Annotated[
-        typer.FileText,
+        str,
         typer.Option(
             envvar='OCR_JSON_SETTINGS',
-            help='JSON settings to pass to OCRmyPDF',
+            help='JSON settings to pass to OCRmyPDF (JSON string or file path)',
         ),
     ] = None,
     poll_new_file_seconds: Annotated[
@@ -288,7 +291,10 @@ def main(
         f"LOGLEVEL: {loglevel.value}"
     )
 
-    json_settings = json.loads(ocr_json_settings.read() if ocr_json_settings else '{}')
+    if ocr_json_settings and Path(ocr_json_settings).exists():
+        json_settings = json.loads(Path(ocr_json_settings).read_text())
+    else:
+        json_settings = json.loads(ocr_json_settings or '{}')
 
     if 'input_file' in json_settings or 'output_file' in json_settings:
         log.error(
@@ -301,8 +307,7 @@ def main(
         settings={
             'archive_dir': archive_dir,
             'output_dir': output_dir,
-            'deskew': deskew,
-            'ocrmypdf_kwargs': json_settings,
+            'ocrmypdf_kwargs': json_settings | {'deskew': deskew},
             'on_success_delete': on_success_delete,
             'on_success_archive': on_success_archive,
             'poll_new_file_seconds': poll_new_file_seconds,

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

@@ -7,13 +7,14 @@ from __future__ import annotations
 
 import logging
 from contextlib import suppress
+from enum import Enum
 from pathlib import Path
 
 from pikepdf import (
     Dictionary,
     Name,
-    Object,
     Operator,
+    Page,
     Pdf,
     PdfError,
     PdfMatrix,
@@ -22,17 +23,30 @@ from pikepdf import (
     unparse_content_stream,
 )
 
+from ocrmypdf._jobcontext import PdfContext
+
+
+class RenderMode(Enum):
+    ON_TOP = 0
+    UNDERNEATH = 1
+
+
 log = logging.getLogger(__name__)
 MAX_REPLACE_PAGES = 100
 
 
-def _ensure_dictionary(obj, name):
+def _ensure_dictionary(obj: Dictionary | Stream, name: Name):
     if name not in obj:
         obj[name] = Dictionary({})
     return obj[name]
 
 
-def _update_resources(*, obj, font, font_key, procset):
+def _update_resources(
+    *,
+    obj: Dictionary | Stream,
+    font: Dictionary | None,
+    font_key: Name | None,
+):
     """Update this obj's fonts with a reference to the Glyphless font.
 
     obj can be a page or Form XObject.
@@ -42,13 +56,8 @@ def _update_resources(*, obj, font, font_key, procset):
     if font_key is not None and font_key not in fonts:
         fonts[font_key] = font
 
-    # Reassign /ProcSet to one that just lists everything - ProcSet is
-    # obsolete and doesn't matter but recommended for old viewer support
-    if procset:
-        resources['/ProcSet'] = procset
 
-
-def strip_invisible_text(pdf, page):
+def strip_invisible_text(pdf: Pdf, page: Page):
     stream = []
     in_text_obj = False
     render_mode = 0
@@ -79,22 +88,20 @@ def strip_invisible_text(pdf, page):
 class OcrGrafter:
     """Manages grafting text-only PDFs onto regular PDFs."""
 
-    def __init__(self, context):
+    def __init__(self, context: PdfContext):
         self.context = context
         self.path_base = context.origin
 
         self.pdf_base = Pdf.open(self.path_base)
-        self.font, self.font_key = None, None
+        self.font: Dictionary | None = None
+        self.font_key: Name | None = None
 
         self.pdfinfo = context.pdfinfo
         self.output_file = context.get_path('graft_layers.pdf')
 
-        self.procset = self.pdf_base.make_indirect(
-            Object.parse(b'[ /PDF /Text /ImageB /ImageC /ImageI ]')
-        )
-
         self.emplacements = 1
         self.interim_count = 0
+        self.render_mode = RenderMode.UNDERNEATH
 
     def graft_page(
         self,
@@ -119,7 +126,9 @@ class OcrGrafter:
                 foreign_image_page = pdf_image.pages[0]
                 self.pdf_base.pages.append(foreign_image_page)
                 local_image_page = self.pdf_base.pages[-1]
-                self.pdf_base.pages[pageno].emplace(local_image_page)
+                self.pdf_base.pages[pageno].emplace(
+                    local_image_page, retain=(Name.Parent,)
+                )
                 del self.pdf_base.pages[-1]
             emplaced_page = True
 
@@ -135,6 +144,8 @@ class OcrGrafter:
         )
 
         if textpdf and self.font:
+            if self.font_key is None:
+                raise ValueError("Font key is not set")
             # Graft the text layer onto this page, whether new or old, possibly
             # rotating the text layer by the amount is misaligned.
             strip_old = self.context.options.redo_ocr
@@ -144,7 +155,6 @@ class OcrGrafter:
                 font=self.font,
                 font_key=self.font_key,
                 text_rotation=text_misaligned,
-                procset=self.procset,
                 strip_old_text=strip_old,
             )
 
@@ -159,7 +169,7 @@ class OcrGrafter:
         if self.emplacements % MAX_REPLACE_PAGES == 0:
             self.save_and_reload()
 
-    def save_and_reload(self):
+    def save_and_reload(self) -> None:
         """Save and reload the Pdf.
 
         This will keep a lid on our memory usage for very large files. Attach
@@ -167,9 +177,7 @@ class OcrGrafter:
         back.
         """
         page0 = self.pdf_base.pages[0]
-        _update_resources(
-            obj=page0, font=self.font, font_key=self.font_key, procset=self.procset
-        )
+        _update_resources(obj=page0.obj, font=self.font, font_key=self.font_key)
 
         # We cannot read and write the same file, that will corrupt it
         # but we don't to keep more copies than we need to. Delete intermediates.
@@ -188,7 +196,6 @@ class OcrGrafter:
         self.pdf_base.close()
 
         self.pdf_base = Pdf.open(next_file)
-        self.procset = self.pdf_base.pages[0].Resources.ProcSet
         self.font, self.font_key = None, None  # Ensure we reacquire this information
         self.interim_count += 1
 
@@ -197,24 +204,32 @@ class OcrGrafter:
         self.pdf_base.close()
         return self.output_file
 
-    def _find_font(self, text):
+    def _find_font(self, text: Path) -> tuple[Dictionary | None, Name | None]:
         """Copy a font from the filename text into pdf_base."""
         font, font_key = None, None
         possible_font_names = ('/f-0-0', '/F1')
         try:
             with Pdf.open(text) as pdf_text:
                 try:
-                    pdf_text_fonts = pdf_text.pages[0].Resources.get('/Font', {})
+                    pdf_text_fonts = pdf_text.pages[0].Resources.get(
+                        Name.Font, Dictionary()
+                    )
                 except (AttributeError, IndexError, KeyError):
                     return None, None
+                if not isinstance(pdf_text_fonts, Dictionary):
+                    log.warning("Page fonts are not stored in a dictionary")
+                    return None, None
                 pdf_text_font = None
                 for f in possible_font_names:
                     pdf_text_font = pdf_text_fonts.get(f, None)
                     if pdf_text_font is not None:
-                        font_key = f
+                        font_key = Name(f)
                         break
                 if pdf_text_font:
                     font = self.pdf_base.copy_foreign(pdf_text_font)
+                if not isinstance(font, Dictionary):
+                    log.warning("Font is not a dictionary")
+                    font, font_key = None, None
                 return font, font_key
         except (FileNotFoundError, PdfError):
             # PdfError occurs if a 0-length file is written e.g. due to OCR timeout
@@ -225,9 +240,8 @@ class OcrGrafter:
         *,
         page_num: int,
         textpdf: Path,
-        font: Object,
-        font_key: Object,
-        procset: Object,
+        font: Dictionary,
+        font_key: Name,
         text_rotation: int,
         strip_old_text: bool,
     ):
@@ -278,7 +292,7 @@ class OcrGrafter:
             # finally move the lower left corner to match the mediabox
             ctm = translate @ rotate @ scale @ untranslate @ corner
 
-            base_resources = _ensure_dictionary(base_page, Name.Resources)
+            base_resources = _ensure_dictionary(base_page.obj, Name.Resources)
             base_xobjs = _ensure_dictionary(base_resources, Name.XObject)
             text_xobj_name = Name.random(prefix="OCR-")
             xobj = self.pdf_base.make_stream(pdf_text_contents)
@@ -287,9 +301,7 @@ class OcrGrafter:
             xobj.Subtype = Name.Form
             xobj.FormType = 1
             xobj.BBox = mediabox
-            _update_resources(
-                obj=xobj, font=font, font_key=font_key, procset=[Name.PDF]
-            )
+            _update_resources(obj=xobj, font=font, font_key=font_key)
 
             pdf_draw_xobj = (
                 (b'q %s cm\n' % ctm.encode()) + (b'%s Do\n' % text_xobj_name) + b'\nQ\n'
@@ -299,8 +311,8 @@ class OcrGrafter:
             if strip_old_text:
                 strip_invisible_text(self.pdf_base, base_page)
 
-            base_page.contents_add(new_text_layer, prepend=True)
-
-            _update_resources(
-                obj=base_page, font=font, font_key=font_key, procset=procset
+            base_page.contents_add(
+                new_text_layer, prepend=self.render_mode == RenderMode.UNDERNEATH
             )
+
+            _update_resources(obj=base_page.obj, font=font, font_key=font_key)

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
@@ -229,7 +235,17 @@ def cli_exception_handler(
     options: argparse.Namespace,
     plugin_manager: OcrmypdfPluginManager,
 ) -> ExitCode:
+    """Convert exceptions into command line error messages and exit codes.
+
+    When known exceptions are raised, the exception message is printed to stderr
+    and the program exits with a non-zero exit code. When unknown exceptions are
+    raised, the exception traceback is printed to stderr and the program exits
+    with a non-zero exit code.
+    """
     try:
+        # We cannot use a generator and yield here, as would be the usual pattern
+        # for exception handling context managers, because we need to return an exit
+        # code.
         return fn(options, plugin_manager)
     except KeyboardInterrupt:
         if options.verbose >= 1:

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