Reinstate logging of page numbers

src/ocrmypdf/_jobcontext.py

@@ -58,7 +58,6 @@ class PageContext:
         self.name = pdf_context.name
         self.pageno = pageno
         self.pageinfo = pdf_context.pdfinfo[pageno]
-        self._log = None
 
     def get_path(self, name):
         return os.path.join(self.work_folder, "%06d_%s" % (self.pageno + 1, name))
@@ -69,18 +68,3 @@ def cleanup_working_files(work_folder, options):
         print(f"Temporary working files retained at:\n{work_folder}", file=sys.stderr)
     else:
         shutil.rmtree(work_folder, ignore_errors=True)
-
-
-class LogNameAdapter(logging.LoggerAdapter):
-    def process(self, msg, kwargs):
-        # return '[%s] %s' % (self.extra['input_filename'], msg), kwargs
-        return '%s' % (msg,), kwargs
-
-
-class LogNamePageAdapter(logging.LoggerAdapter):
-    def process(self, msg, kwargs):
-        return (
-            #'[%s:%05u] %s' % (self.extra['input_filename'], self.extra['page'], msg),
-            '%4u: %s' % (self.extra['page'], msg),
-            kwargs,
-        )

src/ocrmypdf/_logging.py

@@ -0,0 +1,60 @@
+# © 2020 James R. Barlow: github.com/jbarlow83
+#
+# This file is part of OCRmyPDF.
+#
+# OCRmyPDF is free software: you can redistribute it and/or modify
+# it under the terms of the GNU General Public License as published by
+# the Free Software Foundation, either version 3 of the License, or
+# (at your option) any later version.
+#
+# OCRmyPDF is distributed in the hope that it will be useful,
+# but WITHOUT ANY WARRANTY; without even the implied warranty of
+# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+# GNU General Public License for more details.
+#
+# You should have received a copy of the GNU General Public License
+# along with OCRmyPDF.  If not, see <http://www.gnu.org/licenses/>.
+
+import logging
+import sys
+from contextlib import suppress
+
+from tqdm import tqdm
+
+
+class PageNumberFilter(logging.Filter):
+    def filter(self, record):
+        pageno = getattr(record, 'pageno', None)
+        if pageno is not None:
+            record.pageno = f' [{pageno:5d}]'
+        else:
+            record.pageno = ''
+        return True
+
+
+class TqdmConsole:
+    """Wrapper to log messages in a way that is compatible with tqdm progress bar
+
+    This routes log messages through tqdm so that it can print them above the
+    progress bar, and then refresh the progress bar, rather than overwriting
+    it which looks messy.
+
+    For some reason Python 3.6 prints extra empty messages from time to time,
+    so we suppress those.
+    """
+
+    def __init__(self, file):
+        self.file = file
+        self.py36 = sys.version_info[0:2] == (3, 6)
+
+    def write(self, msg):
+        # When no progress bar is active, tqdm.write() routes to print()
+        if self.py36:
+            if msg.strip() != '':
+                tqdm.write(msg.rstrip(), end='\n', file=self.file)
+        else:
+            tqdm.write(msg.rstrip(), end='\n', file=self.file)
+
+    def flush(self):
+        with suppress(AttributeError):
+            self.file.flush()

src/ocrmypdf/_sync.py

@@ -31,6 +31,7 @@ from tqdm import tqdm
 
 from ._graft import OcrGrafter
 from ._jobcontext import PDFContext, cleanup_working_files
+from ._logging import PageNumberFilter
 from ._pipeline import (
     convert_to_pdfa,
     copy_final,
@@ -72,6 +73,9 @@ PageResult = namedtuple(
     'PageResult', 'pageno, pdf_page_from_image, ocr, text, orientation_correction'
 )
 
+tls = threading.local()
+tls.pageno = None
+
 
 def preprocess(page_context, image, remove_background, deskew, clean):
     if remove_background:
@@ -83,8 +87,23 @@ def preprocess(page_context, image, remove_background, deskew, clean):
     return image
 
 
+old_factory = logging.getLogRecordFactory()
+
+
+def record_factory(*args, **kwargs):
+    record = old_factory(*args, **kwargs)
+    if hasattr(tls, 'pageno'):
+        record.pageno = tls.pageno
+    return record
+
+
+logging.setLogRecordFactory(record_factory)
+
+
 def exec_page_sync(page_context):
     options = page_context.options
+    tls.pageno = page_context.pageno + 1
+
     orientation_correction = 0
     pdf_page_from_image_out = None
     ocr_out = None
@@ -346,7 +365,7 @@ def configure_debug_logging(log_filename, prefix=''):
     log_file_handler = logging.FileHandler(log_filename, delay=True)
     log_file_handler.setLevel(logging.DEBUG)
     formatter = logging.Formatter(
-        '[%(asctime)s] - %(name)s - %(levelname)7s - %(message)s'
+        '[%(asctime)s] - %(name)s - %(levelname)7s -%(pageno)s %(message)s'
     )
     log_file_handler.setFormatter(formatter)
     logging.getLogger(prefix).addHandler(log_file_handler)

src/ocrmypdf/api.py

@@ -23,41 +23,12 @@ from enum import IntEnum
 from pathlib import Path
 from typing import Dict, Iterable
 
-from tqdm import tqdm
-
+from ._logging import PageNumberFilter, TqdmConsole
 from ._sync import run_pipeline
 from ._validation import check_options
 from .cli import parser
 
 
-class TqdmConsole:
-    """Wrapper to log messages in a way that is compatible with tqdm progress bar
-
-    This routes log messages through tqdm so that it can print them above the
-    progress bar, and then refresh the progress bar, rather than overwriting
-    it which looks messy.
-
-    For some reason Python 3.6 prints extra empty messages from time to time,
-    so we suppress those.
-    """
-
-    def __init__(self, file):
-        self.file = file
-        self.py36 = sys.version_info[0:2] == (3, 6)
-
-    def write(self, msg):
-        # When no progress bar is active, tqdm.write() routes to print()
-        if self.py36:
-            if msg.strip() != '':
-                tqdm.write(msg.rstrip(), end='\n', file=self.file)
-        else:
-            tqdm.write(msg.rstrip(), end='\n', file=self.file)
-
-    def flush(self):
-        with suppress(AttributeError):
-            self.file.flush()
-
-
 class Verbosity(IntEnum):
     """Verbosity level for configure_logging."""
 
@@ -98,6 +69,7 @@ def configure_logging(
     """
 
     prefix = '' if manage_root_logger else 'ocrmypdf'
+
     log = logging.getLogger(prefix)
     log.setLevel(logging.DEBUG)
 
@@ -113,9 +85,14 @@ def configure_logging(
     else:
         console.setLevel(logging.INFO)
 
-    formatter = logging.Formatter('%(levelname)7s - %(message)s')
+    console.addFilter(PageNumberFilter())
+
     if verbosity >= 2:
-        formatter = logging.Formatter('%(name)s - %(levelname)7s - %(message)s')
+        fmt = '%(levelname)7s %(name)s -%(pageno)s %(message)s'
+    else:
+        fmt = '%(levelname)7s -%(pageno)s %(message)s'
+
+    formatter = logging.Formatter(fmt=fmt)
 
     console.setFormatter(formatter)
     log.addHandler(console)