Improve ability to capture error messages from tesseract on a crash

ocrmypdf/__init__.py

@@ -10,6 +10,7 @@ class ExitCode(IntEnum):
     invalid_output_pdfa = 4
     file_access_error = 5
     already_done_ocr = 6
+    child_process_error = 7
     other_error = 15
 
 

ocrmypdf/main.py

@@ -1011,10 +1011,17 @@ def run_pipeline():
         cmdline.run(options)
     except ruffus_exceptions.RethrownJobError as e:
         if options.verbose:
-            print(e)
+            _log.debug(e)
 
         # Yuck. Hunt through the ruffus exception to find out what the
         # return code is supposed to be.
+        # Ruffus flattens the exception to a string, throwing away all kinds
+        # of helpful details
+        # task_name, job_name - ruffus status
+        # exc_name - class name of exception
+        # exc_value - irritating string that makes impossible to recover
+        #   exception object
+        # exc_stack - string that contains traceback of exception
         for exc in e.args:
             task_name, job_name, exc_name, exc_value, exc_stack = exc
             if exc_name == 'builtins.SystemExit':
@@ -1023,17 +1030,25 @@ def run_pipeline():
                 exit_code = getattr(ExitCode, exit_code_name, 'other_error')
                 return exit_code
             elif exc_name == 'ruffus.ruffus_exceptions.MissingInputFileError':
-                print(cleanup_ruffus_error_message(exc_value))
+                _log.error(cleanup_ruffus_error_message(exc_value))
                 return ExitCode.input_file
             elif exc_name == 'builtins.TypeError':
                 # Even though repair_pdf will fail, ruffus will still try
                 # to call split_pages with no input files, likely due to a bug
                 if task_name == 'split_pages':
-                    print("Input file '{0}' is not a valid PDF".format(
+                    _log.error("Input file '{0}' is not a valid PDF".format(
                         options.input_file))
                     return ExitCode.input_file
+            elif exc_name == 'subprocess.CalledProcessError':
+                # It's up to the subprocess handler to report something useful
+                msg = "Error occurred while running this command:"
+                _log.error(msg + '\n' + exc_value)
+                return ExitCode.child_process_error
 
         return ExitCode.other_error
+    except Exception as e:
+        _log.error(e)
+        return ExitCode.other_error
 
     if not validate_pdfa(options.output_file, _log):
         _log.warning('Output file: The generated PDF/A file is INVALID')

ocrmypdf/tesseract.py

@@ -99,6 +99,10 @@ def get_orientation(input_file, language: list, timeout: float, log):
         stdout, _ = p.communicate()
         return OrientationConfidence(angle=0, confidence=0.0)
     else:
+        if p.returncode != 0:
+            log.error(stdout)
+            return OrientationConfidence(angle=0, confidence=0.0)
+
         osd = {}
         for line in stdout.splitlines():
             line = line.strip()
@@ -124,10 +128,17 @@ def tesseract_log_output(log, stdout, input_file):
             log.warning(prefix + "lots of diacritics - possibly poor OCR")
         elif line.startswith('OSD: Weak margin'):
             log.warning(prefix + "unsure about page orientation")
+        elif 'error' in line.lower():
+            log.error(prefix + line.strip())
         else:
             log.info(prefix + line.strip())
 
 
+def page_timedout(log, input_file):
+    prefix = "{0:4d}: [tesseract] ".format(page_number(input_file))
+    log.warning(prefix + " took too long to OCR - skipping")
+
+
 def generate_hocr(input_file, output_hocr, language: list, tessconfig: list,
                   timeout: float, pageinfo_getter, pagesegmode: int, log):
 
@@ -146,26 +157,25 @@ def generate_hocr(input_file, output_hocr, language: list, tessconfig: list,
         badxml,
         'hocr'
     ] + tessconfig)
-    p = Popen(args_tesseract, close_fds=True, stdout=PIPE, stderr=STDOUT,
-              universal_newlines=True)
     try:
-        stdout, _ = p.communicate(timeout=timeout)
+        stdout = check_output(
+            args_tesseract, close_fds=True, stderr=STDOUT,
+            universal_newlines=True, timeout=timeout)
     except TimeoutExpired:
-        p.kill()
-        stdout, _ = p.communicate()
         # Generate a HOCR file with no recognized text if tesseract times out
         # Temporary workaround to hocrTransform not being able to function if
         # it does not have a valid hOCR file.
+        page_timedout(input_file)
         with open(output_hocr, 'w', encoding="utf-8") as f:
             pageinfo = pageinfo_getter()
             f.write(HOCR_TEMPLATE.format(
                 pageinfo['width_pixels'],
                 pageinfo['height_pixels']))
+    except CalledProcessError as e:
+        tesseract_log_output(log, e.output, input_file)
+        raise e from e
     else:
         tesseract_log_output(log, stdout, input_file)
-        if p.returncode != 0:
-            raise CalledProcessError(p.returncode, args_tesseract)
-
         if os.path.exists(badxml + '.html'):
             # Tesseract 3.02 appends suffix ".html" on its own (.badxml.html)
             shutil.move(badxml + '.html', badxml)
@@ -213,14 +223,16 @@ def generate_pdf(input_image, skip_pdf, output_pdf, language: list,
         os.path.splitext(output_pdf)[0],  # Tesseract appends suffix
         'pdf'
     ] + tessconfig)
-    p = Popen(args_tesseract, close_fds=True, stdout=PIPE, stderr=STDOUT,
-              universal_newlines=True)
 
     try:
-        stdout, _ = p.communicate()
+        stdout = check_output(
+            args_tesseract, close_fds=True, stderr=STDOUT,
+            universal_newlines=True, timeout=timeout)
     except TimeoutExpired:
-        p.kill()
-        log.info("Tesseract - page timed out")
+        page_timedout(input_image)
         shutil.copy(skip_pdf, output_pdf)
+    except CalledProcessError as e:
+        tesseract_log_output(log, e.output, input_image)
+        raise e from e
     else:
         tesseract_log_output(log, stdout, input_image)

tests/test_main.py

@@ -83,22 +83,33 @@ def run_ocrmypdf_env(input_basename, output_basename, *args, env=None):
     return p, out, err
 
 
+def spoof(replace_program, with_spoof):
+    """Modify environment variables to override subprocess executables
+
+    Before running any executable, ocrmypdf checks the environment variable
+    OCRMYPDF_PROGRAMNAME to override default program name/location, e.g.
+    OCRMYPDF_GS redirects from the system path Ghostscript ("gs") to elsewhere.
+    """
+    env = os.environ.copy()
+    spoofer = os.path.join(SPOOF_PATH, with_spoof)
+    check_call(['chmod', "+x", spoofer])
+    env['OCRMYPDF_' + replace_program.upper()] = spoofer
+    return env
+
+
 @pytest.fixture
 def spoof_tesseract_noop():
-    env = os.environ.copy()
-    program = os.path.join(SPOOF_PATH, 'tesseract_noop.py')
-    check_call(['chmod', "+x", program])
-    env['OCRMYPDF_TESSERACT'] = program
-    return env
+    return spoof('tesseract', 'tesseract_noop.py')
 
 
 @pytest.fixture
 def spoof_tesseract_cache():
-    env = os.environ.copy()
-    program = os.path.join(SPOOF_PATH, "tesseract_cache.py")
-    check_call(['chmod', '+x', program])
-    env['OCRMYPDF_TESSERACT'] = program
-    return env
+    return spoof('tesseract', "tesseract_cache.py")
+
+
+@pytest.fixture
+def spoof_tesseract_crash():
+    return spoof('tesseract', 'tesseract_crash.py')
 
 
 def test_quick(spoof_tesseract_noop):
@@ -438,4 +449,14 @@ def test_pagesegmode(renderer, spoof_tesseract_cache):
         '--pdf-renderer', renderer, env=spoof_tesseract_cache)
 
 
-
+@pytest.mark.parametrize('renderer', [
+    'hocr',
+    'tesseract',
+    ])
+def test_tesseract_crash(renderer, spoof_tesseract_crash):
+    sh, out, err = run_ocrmypdf_env(
+        'ccitt.pdf', 'wontwork.pdf', '-v', '1',
+        '--pdf-renderer', renderer, env=spoof_tesseract_crash)
+    assert sh.returncode == ExitCode.child_process_error
+    assert not os.path.exists(_outfile('wontwork.pdf'))
+    assert "ERROR" in err