v11.3.1 release notes

Closes #663

docs/release_notes.rst

@@ -12,6 +12,32 @@ may be unreliable. Use the API to depend on precise behavior.
 The public API may be useful in scripts that launch OCRmyPDF processes or that
 wish to use some of its features for working with PDFs.
 
+v11.3.1
+=======
+
+-  Declare support for new versions: pdfminer.six 20201018 and pikepdf 2.x
+-  Fix warning related to ``--pdfa-image-compression`` that appears at the wrong
+   time.
+
+v11.3.0
+=======
+
+-  The "OCR" step is describing as "Image processing" in the output messages when
+   OCR is disabled, to better explain the application's behavior.
+-  Debug logs are now only created when run as a command line, and not when OCR
+   is performed for an API call. It is the calling application's responsibility
+   to set up logging.
+-  For PDFs with a low number of pages, we gathered information about the input PDF
+   in a thread rather than process (when there are more pages). When run as a
+   thread, we did not close the file handle to the working PDF, leaking one file
+   handle per call of ``ocrmypdf.ocr``.
+-  Fixed an issue where debug messages send by child worker processes did not match
+   the log settings of parent process, causing messages to be dropped. This affected
+   macOS and Windows only where the parent process is not forked.
+-  Fixed the hookspec of rasterize_pdf_page to remove default parameters that
+   were not handled in an expected way by pluggy.
+-  Fixed another issue with automatic page rotation (#658) due to the issue above.
+
 v11.2.1
 =======
 

setup.py

@@ -63,7 +63,6 @@ setup(
     python_requires=' >= 3.6',
     setup_requires=[  # can be removed whenever we can drop pip 9 support
         'cffi >= 1.9.1',  # to build the leptonica module
-        'pytest-runner',  # to enable python setup.py test
         'setuptools_scm',  # so that version will work
         'setuptools_scm_git_archive',  # enable version from github tarballs
     ],
@@ -73,10 +72,10 @@ setup(
         'cffi >= 1.9.1',  # must be a setup and install requirement
         'coloredlogs >= 14.0',  # strictly optional
         'img2pdf >= 0.3.0, < 0.5',  # pure Python, so track HEAD closely
-        'pdfminer.six >= 20191110, != 20200720, <= 20200726',
-        'pikepdf >= 1.14.0, < 2',
+        'pdfminer.six >= 20191110, != 20200720, <= 20201018',
+        'pikepdf >= 1.14.0, < 3',
         'Pillow >= 7.0.0',
-        'pluggy >= 0.13.0',
+        'pluggy >= 0.13.0, < 1.0',
         'reportlab >= 3.3.0',  # oldest released version with sane image handling
         'tqdm >= 4',
     ],

src/ocrmypdf/_concurrent.py

@@ -49,7 +49,7 @@ def process_sigbus(*args):
     raise InputFileError("A worker process lost access to an input file")
 
 
-def process_init(queue, user_init):
+def process_init(queue, user_init, loglevel):
     """Initialize a process pool worker"""
 
     # Ignore SIGINT (our parent process will kill us gracefully)
@@ -62,6 +62,7 @@ def process_init(queue, user_init):
     # Reconfigure the root logger for this process to send all messages to a queue
     h = logging.handlers.QueueHandler(queue)
     root = logging.getLogger()
+    root.setLevel(loglevel)
     root.handlers = []
     root.addHandler(h)
 
@@ -69,7 +70,7 @@ def process_init(queue, user_init):
         user_init()
 
 
-def thread_init(_queue, user_init):
+def thread_init(_queue, user_init, _loglevel):
     # As a thread, block SIGBUS so the main thread deals with it...
     if hasattr(signal, 'SIGBUS'):
         signal.pthread_sigmask(signal.SIG_BLOCK, {signal.SIGBUS})
@@ -102,7 +103,7 @@ def exec_progress_pool(
         pool = pool_class(
             processes=max_workers,
             initializer=initializer,
-            initargs=(log_queue, task_initializer),
+            initargs=(log_queue, task_initializer, logging.getLogger("").level),
         )
         try:
             results = pool.imap_unordered(task, task_arguments)

src/ocrmypdf/_exec/ghostscript.py

@@ -81,8 +81,8 @@ def rasterize_pdf(
     raster_device: str,
     raster_dpi: Resolution,
     pageno: int = 1,
-    page_dpi: Resolution = None,
-    rotation: int = None,
+    page_dpi: Optional[Resolution] = None,
+    rotation: Optional[int] = None,
     filter_vector: bool = False,
 ):
     """Rasterize one page of a PDF at resolution raster_dpi in canvas units."""

src/ocrmypdf/_graft.py

@@ -109,6 +109,7 @@ class OcrGrafter:
         if textpdf and not self.font:
             self.font, self.font_key = self._find_font(textpdf)
 
+        emplaced_page = False
         content_rotation = self.pdfinfo[pageno].rotation
         path_image = Path(image).resolve() if image else None
         if path_image is not None and path_image != self.path_base:
@@ -122,24 +123,21 @@ class OcrGrafter:
                 local_image_page = self.pdf_base.pages[-1]
                 self.pdf_base.pages[pageno].emplace(local_image_page)
                 del self.pdf_base.pages[-1]
-            # The pdf_image_page will always be created with any /Rotate applied
-            # applied already
-            content_rotation = 0
+            emplaced_page = True
 
-        if content_rotation != 0:
-            # Text can be misaligned on a /Rotate'd page.
-            # That is because we rasterize pages with /Rotate applied,
-            # so that the OCR image text is upright and comes back upright.
-            text_misaligned = (autorotate_correction - content_rotation) % 360
-            log.debug(
-                f"Text rotation: (autorotate, content) -> text misalignment = "
-                f"({autorotate_correction}, {content_rotation}) -> {text_misaligned}"
-            )
-        else:
-            text_misaligned = 0
+        # Calculate if the text is misaligned compared to the content
+        if emplaced_page:
+            content_rotation = autorotate_correction
+        text_rotation = autorotate_correction
+        text_misaligned = (text_rotation - content_rotation) % 360
+        log.debug(
+            f"Text rotation: (text, autorotate, content) -> text misalignment = "
+            f"({text_rotation}, {autorotate_correction}, {content_rotation}) -> {text_misaligned}"
+        )
 
         if textpdf and self.font:
-            # Graft the text layer onto this page, whether new or old
+            # 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
             self._graft_text_layer(
                 page_num=pageno + 1,
@@ -151,14 +149,14 @@ class OcrGrafter:
                 strip_old_text=strip_old,
             )
 
-        # Correct the page rotation
+        # Correct the overall page rotation if needed, now that the text and content
+        # are aligned
         page_rotation = (content_rotation - autorotate_correction) % 360
         self.pdf_base.pages[pageno].Rotate = page_rotation
         log.debug(
             f"Page rotation: (content, auto) -> page = "
             f"({content_rotation}, {autorotate_correction}) -> {page_rotation}"
         )
-
         if self.emplacements % MAX_REPLACE_PAGES == 0:
             self.save_and_reload()
 

src/ocrmypdf/_pipeline.py

@@ -332,8 +332,10 @@ def rasterize_preview(input_file: Path, page_context: PageContext):
         output_file=output_file,
         raster_device='jpeggray',
         raster_dpi=canvas_dpi,
-        page_dpi=page_dpi,
         pageno=page_context.pageinfo.pageno + 1,
+        page_dpi=page_dpi,
+        rotation=0,
+        filter_vector=False,
     )
     return output_file
 
@@ -433,7 +435,7 @@ def rasterize(
 
     device = colorspaces[device_idx]
 
-    log.debug(f"Rasterize with {device}")
+    log.debug(f"Rasterize with {device}, rotation {correction}")
 
     # Produce the page image with square resolution or else deskew and OCR
     # will not work properly.
@@ -534,6 +536,9 @@ def create_ocr_image(image: Path, page_context: PageContext):
 
         # Pillow requires integer DPI
         dpi = tuple(round(coord) for coord in im.info['dpi'])
+        if page_context.pageinfo.rotation != 0:
+            log.info(f"Rotating {page_context.pageinfo.rotation}")
+            im = im.rotate(page_context.pageinfo.rotation)
         im.save(output_file, dpi=dpi)
     return output_file
 

src/ocrmypdf/_sync.py

@@ -209,9 +209,10 @@ def exec_page_sync(page_context: PageContext):
     if options.pdf_renderer == 'hocr':
         (hocr_out, text_out) = ocr_engine_hocr(ocr_image_out, page_context)
         ocr_out = render_hocr_page(hocr_out, page_context)
-
-    if options.pdf_renderer == 'sandwich':
+    elif options.pdf_renderer == 'sandwich':
         (ocr_out, text_out) = ocr_engine_textonly_pdf(ocr_image_out, page_context)
+    else:
+        raise NotImplementedError(f"pdf_renderer {options.pdf_renderer}")
 
     return PageResult(
         pageno=page_context.pageno,
@@ -244,7 +245,8 @@ def exec_concurrent(context: PdfContext):
     """Execute the pipeline concurrently"""
 
     # Run exec_page_sync on every page context
-    max_workers = min(len(context.pdfinfo), context.options.jobs)
+    options = context.options
+    max_workers = min(len(context.pdfinfo), options.jobs)
     if max_workers > 1:
         log.info("Start processing %d pages concurrently", max_workers)
 
@@ -267,14 +269,14 @@ def exec_concurrent(context: PdfContext):
             tls.pageno = None
 
     exec_progress_pool(
-        use_threads=context.options.use_threads,
+        use_threads=options.use_threads,
         max_workers=max_workers,
         tqdm_kwargs=dict(
             total=(2 * len(context.pdfinfo)),
-            desc='OCR',
+            desc='OCR' if options.tesseract_timeout > 0 else 'Image processing',
             unit='page',
             unit_scale=0.5,
-            disable=not context.options.progress_bar,
+            disable=not options.progress_bar,
         ),
         task_initializer=partial(worker_init, PIL.Image.MAX_IMAGE_PIXELS),
         task=exec_page_sync,
@@ -283,10 +285,10 @@ def exec_concurrent(context: PdfContext):
     )
 
     # Output sidecar text
-    if context.options.sidecar:
+    if options.sidecar:
         text = merge_sidecars(sidecars, context)
         # Copy text file to destination
-        copy_final(text, context.options.sidecar, context)
+        copy_final(text, options.sidecar, context)
 
     # Merge layers to one single pdf
     pdf = ocrgraft.finalize()
@@ -296,7 +298,7 @@ def exec_concurrent(context: PdfContext):
     pdf = post_process(pdf, context)
 
     # Copy PDF file to destination
-    copy_final(pdf, context.options.output_file, context)
+    copy_final(pdf, options.output_file, context)
 
 
 class NeverRaise(Exception):
@@ -328,9 +330,12 @@ def run_pipeline(options, *, plugin_manager, api=False):
 
     work_folder = Path(mkdtemp(prefix="com.github.ocrmypdf."))
     debug_log_handler = None
-    if (options.keep_temporary_files or options.verbose >= 1) and not os.environ.get(
-        'PYTEST_CURRENT_TEST', ''
+    if (
+        (options.keep_temporary_files or options.verbose >= 1)
+        and not os.environ.get('PYTEST_CURRENT_TEST', '')
+        and not api
     ):
+        # Debug log for command line interface only with verbose output
         debug_log_handler = configure_debug_logging(Path(work_folder) / "debug.log")
 
     pikepdf_enable_mmap()

src/ocrmypdf/_validation.py

@@ -213,12 +213,12 @@ def check_options_optimizing(options):
 
 
 def check_options_advanced(options):
-    if options.pdfa_image_compression != 'auto' and options.output_type.startswith(
+    if options.pdfa_image_compression != 'auto' and not options.output_type.startswith(
         'pdfa'
     ):
         log.warning(
-            "--pdfa-image-compression argument has no effect when "
-            "--output-type is not 'pdfa', 'pdfa-1', or 'pdfa-2'"
+            "--pdfa-image-compression argument only applies when "
+            "--output-type is one of 'pdfa', 'pdfa-1', or 'pdfa-2'"
         )
 
 

src/ocrmypdf/api.py

@@ -11,6 +11,7 @@ import sys
 from enum import IntEnum
 from pathlib import Path
 from typing import BinaryIO, Iterable, Union
+from warnings import warn
 
 from ocrmypdf._logging import PageNumberFilter, TqdmConsole
 from ocrmypdf._plugin_manager import get_plugin_manager
@@ -44,16 +45,28 @@ def configure_logging(
 ):
     """Set up logging.
 
-    Library users may wish to use this function if they want their log output to be
-    similar to ocrmypdf command line interface. If not used, the external application
-    should configure logging on its own.
+    Before calling :func:`ocrmypdf.ocr()`, you can use this function to
+    configure logging, if you want ocrmypdf's output to look like the ocrmypdf
+    command line interface. It will register log handlers, log filters, and
+    formatters, configure color logging to standard error, and adjust the log
+    levels of third party libraries. Details of this are fine-tuned and subject
+    to change. The ``verbosity`` argument is equivalent to the argument
+    ``--verbose`` and applies those settings.
 
-    ocrmypdf will perform all of its logging under the ``"ocrmypdf"`` logging namespace.
-    In addition, ocrmypdf imports pdfminer, which logs under ``"pdfminer"``. A library
-    user may wish to configure both; note that pdfminer is extremely chatty at the log
-    level ``logging.INFO``.
+    If this function is not called, ocrmypdf will not configure logging, and it
+    is up to the caller of ``ocrmypdf.ocr()`` to set up logging as it wishes using
+    the Python standard library's logging module. If this function is called,
+    the caller may of course make further adjustments to logging.
 
-    Library users may perform additional configuration afterwards.
+    Regardless of whether this function is called, ocrmypdf will perform all of
+    its logging under the ``"ocrmypdf"`` logging namespace. In addition,
+    ocrmypdf imports pdfminer, which logs under ``"pdfminer"``. A library user
+    may wish to configure both; note that pdfminer is extremely chatty at the
+    log level ``logging.INFO``.
+
+    This function does not set up the ``debug.log`` log file that the command
+    line interface does at certain verbosity levels. Applications should configure
+    their own debug logging.
 
     Args:
         verbosity (Verbosity): Verbosity level.
@@ -294,6 +307,9 @@ def ocr(  # pylint: disable=unused-argument
     }
     create_options_kwargs.update(kwargs)
 
+    if 'verbose' in kwargs:
+        warn("ocrmypdf.ocr(verbose=) is ignored. Use ocrmypdf.configure_logging().")
+
     options = create_options(**create_options_kwargs)
     check_options(options, _plugin_manager)
     return run_pipeline(options=options, plugin_manager=_plugin_manager, api=True)

src/ocrmypdf/builtin_plugins/ghostscript.py

@@ -61,9 +61,9 @@ def rasterize_pdf_page(
     raster_device,
     raster_dpi,
     pageno,
-    page_dpi=None,
-    rotation=None,
-    filter_vector=False,
+    page_dpi,
+    rotation,
+    filter_vector,
 ):
     ghostscript.rasterize_pdf(
         input_file,

src/ocrmypdf/builtin_plugins/tesseract_ocr.py

@@ -121,9 +121,7 @@ def validate(pdfinfo, options):
         os.environ['OMP_THREAD_LIMIT'] = str(tess_threads)
     else:
         tess_threads = int(os.environ['OMP_THREAD_LIMIT'])
-
-    if tess_threads > 1:
-        log.info("Using Tesseract OpenMP thread limit %d", tess_threads)
+    log.debug("Using Tesseract OpenMP thread limit %d", tess_threads)
 
 
 class TesseractOcrEngine(OcrEngine):

src/ocrmypdf/optimize.py

@@ -613,7 +613,7 @@ def optimize(input_file: Path, output_file: Path, context, save_settings) -> Non
         )
     ratio = input_size / output_size
     savings = 1 - output_size / input_size
-    log.info(f"Optimize ratio: {ratio:.2f} savings: {(100 * savings):.1f}%")
+    log.info(f"Optimize ratio: {ratio:.2f} savings: {(savings):.1%}")
 
     if savings < 0:
         log.info("Image optimization did not improve the file - discarded")

src/ocrmypdf/pdfinfo/info.py

@@ -630,6 +630,9 @@ worker_pdf = None
 def _pdf_pageinfo_sync_init(infile):
     global worker_pdf  # pylint: disable=global-statement
     pikepdf_enable_mmap()
+    # If this function is called as a thread initializer, we need a messy hack
+    # to close worker_pdf. If called as a process, it will be released when the
+    # process is terminated.
     worker_pdf = pikepdf.open(infile)
 
 
@@ -643,6 +646,7 @@ def _pdf_pageinfo_sync(args):
 def _pdf_pageinfo_concurrent(
     pdf, infile, progbar, max_workers, check_pages, detailed_analysis=False
 ):
+    global worker_pdf  # pylint: disable=global-statement
     pages = [None] * len(pdf.pages)
 
     def update_pageinfo(result, pbar):
@@ -663,17 +667,23 @@ def _pdf_pageinfo_concurrent(
         # a separate process.
         use_threads = True
 
-    exec_progress_pool(
-        use_threads=use_threads,
-        max_workers=n_workers,
-        tqdm_kwargs=dict(
-            total=total, desc="Scanning contents", unit='page', disable=not progbar
-        ),
-        task_initializer=partial(_pdf_pageinfo_sync_init, infile),
-        task=_pdf_pageinfo_sync,
-        task_arguments=contexts,
-        task_finished=update_pageinfo,
-    )
+    try:
+        exec_progress_pool(
+            use_threads=use_threads,
+            max_workers=n_workers,
+            tqdm_kwargs=dict(
+                total=total, desc="Scanning contents", unit='page', disable=not progbar
+            ),
+            task_initializer=partial(_pdf_pageinfo_sync_init, infile),
+            task=_pdf_pageinfo_sync,
+            task_arguments=contexts,
+            task_finished=update_pageinfo,
+        )
+    finally:
+        if worker_pdf and use_threads:
+            assert n_workers == 1, "Should have only one worker when threaded"
+            # This is messy, but if we ran in thread, close worker_pdf
+            worker_pdf.close()
     return pages
 
 

src/ocrmypdf/pluginspec.py

@@ -89,9 +89,9 @@ def rasterize_pdf_page(
     raster_device: str,
     raster_dpi: Resolution,
     pageno: int,
-    page_dpi: Optional[Resolution] = None,
-    rotation: Optional[int] = None,
-    filter_vector: bool = False,
+    page_dpi: Optional[Resolution],
+    rotation: Optional[int],
+    filter_vector: bool,
 ) -> Path:
     """Rasterize one page of a PDF at resolution raster_dpi in canvas units.
 

tests/test_rotation.py

@@ -15,6 +15,7 @@ from PIL import Image
 
 from ocrmypdf import leptonica
 from ocrmypdf._exec import ghostscript, tesseract
+from ocrmypdf._plugin_manager import get_plugin_manager
 from ocrmypdf.helpers import Resolution
 from ocrmypdf.pdfinfo import PdfInfo
 
@@ -256,3 +257,33 @@ def test_tesseract_orientation(resources, tmp_path):
     tesseract.get_orientation(  # Test results of this are unreliable
         tmp_path / '000001.png', engine_mode='3', timeout=10
     )
+
+
+def test_rasterize_rotates(resources, tmp_path):
+    pm = get_plugin_manager([])
+
+    img = tmp_path / 'img90.png'
+    pm.hook.rasterize_pdf_page(
+        input_file=resources / 'graph.pdf',
+        output_file=img,
+        raster_device='pngmono',
+        raster_dpi=Resolution(20, 20),
+        page_dpi=Resolution(20, 20),
+        pageno=1,
+        rotation=90,
+        filter_vector=False,
+    )
+    assert Image.open(img).size == (123, 151), "Image not rotated"
+
+    img = tmp_path / 'img180.png'
+    pm.hook.rasterize_pdf_page(
+        input_file=resources / 'graph.pdf',
+        output_file=img,
+        raster_device='pngmono',
+        raster_dpi=Resolution(20, 20),
+        page_dpi=Resolution(20, 20),
+        pageno=1,
+        rotation=180,
+        filter_vector=False,
+    )
+    assert Image.open(img).size == (151, 123), "Image not rotated"