Repository: ocr-d/core
Issue: ocrd process fails due to processor's logging mixed with JSON dump

**Problem Description**
We use the docker image `ocrd/all:minimum` for testing purposes. We are running the [ocrd process example from the documentation](https://ocr-d.de/en/user_guide#calling-several-processors) in a slightly derived form:

```
ocrd process -l DEBUG --overwrite  
'cis-ocropy-binarize -I OCR-D-IMG -O OCR-D-SEG-PAGE'   
'tesserocr-segment-region -I OCR-D-SEG-PAGE -O OCR-D-SEG-BLOCK'  
 'tesserocr-segment-line -I OCR-D-SEG-BLOCK -O OCR-D-SEG-LINE'  
 'tesserocr-recognize -I OCR-D-SEG-LINE -O OCR-D-OCR-TESSEROCR'
```

(Please not that we removed `-p param-tess-fraktur.json` from the original example)
When running these processes each seperately, everything is fine and runs without error.

However, the `ocrd process` pipeline causes the following log output:

```
2020-07-15 14:13:32,208.208 INFO root - Overriding log level globally to DEBUG
2020-07-15 14:13:32,209.209 DEBUG ocrd.resolver - Deriving dst_dir /data/images from /data/images/mets.xml
2020-07-15 14:13:32,209.209 DEBUG ocrd.resolver - workspace_from_url
mets_basename='mets.xml'
mets_url='/data/images/mets.xml'
src_baseurl='/data/images'
dst_dir='/data/images'
2020-07-15 14:13:32,210.210 DEBUG ocrd.resolver.download_to_directory - directory=|/data/images| url=|/data/images/mets.xml| basename=|mets.xml| if_exists=|skip| subdir=|None|
2020-07-15 14:13:32,210.210 DEBUG ocrd.resolver.download_to_directory - Stop early, src_path and dst_path are the same: '/data/images/mets.xml' (url: '/data/images/mets.xml')
Traceback (most recent call last):
  File "/usr/bin/ocrd", line 8, in <module>
    sys.exit(cli())
  File "/usr/lib/python3.6/site-packages/click/core.py", line 829, in __call__
    return self.main(*args, **kwargs)
  File "/usr/lib/python3.6/site-packages/click/core.py", line 782, in main
    rv = self.invoke(ctx)
  File "/usr/lib/python3.6/site-packages/click/core.py", line 1259, in invoke
    return _process_result(sub_ctx.command.invoke(sub_ctx))
  File "/usr/lib/python3.6/site-packages/click/core.py", line 1066, in invoke
    return ctx.invoke(self.callback, **ctx.params)
  File "/usr/lib/python3.6/site-packages/click/core.py", line 610, in invoke
    return callback(*args, **kwargs)
  File "/usr/lib/python3.6/site-packages/ocrd/cli/process.py", line 27, in process_cli
    run_tasks(mets, log_level, page_id, tasks, overwrite)
  File "/usr/lib/python3.6/site-packages/ocrd/task_sequence.py", line 125, in run_tasks
    validate_tasks(tasks, workspace, page_id, overwrite)
  File "/usr/lib/python3.6/site-packages/ocrd/task_sequence.py", line 94, in validate_tasks
    first_task.validate()
  File "/usr/lib/python3.6/site-packages/ocrd/task_sequence.py", line 71, in validate
    param_validator = ParameterValidator(self.ocrd_tool_json)
  File "/usr/lib/python3.6/site-packages/ocrd/task_sequence.py", line 49, in ocrd_tool_json
    self._ocrd_tool_json = json.loads(result.stdout)
  File "/usr/lib/python3.6/json/__init__.py", line 354, in loads
    return _default_decoder.decode(s)
  File "/usr/lib/python3.6/json/decoder.py", line 342, in decode
    raise JSONDecodeError("Extra data", s, end)
json.decoder.JSONDecodeError: Extra data: line 1 column 5 (char 4)
```

Then, running the same script again, without changing anything. The log gives:

```
2020-07-15 13:30:10,292.292 INFO root - Overriding log level globally to DEBUG
2020-07-15 13:30:10,293.293 DEBUG ocrd.resolver - Deriving dst_dir /data/images from /data/images/mets.xml
2020-07-15 13:30:10,293.293 DEBUG ocrd.resolver - workspace_from_url
mets_basename='mets.xml'
mets_url='/data/images/mets.xml'
src_baseurl='/data/images'
dst_dir='/data/images'
2020-07-15 13:30:10,293.293 DEBUG ocrd.resolver.download_to_directory - directory=|/data/images| url=|/data/images/mets.xml| basename=|mets.xml| if_exists=|skip| subdir=|None|
2020-07-15 13:30:10,294.294 DEBUG ocrd.resolver.download_to_directory - Stop early, src_path and dst_path are the same: '/data/images/mets.xml' (url: '/data/images/mets.xml')
2020-07-15 13:30:12,289.289 DEBUG ocrd.workspace_validator - input_file_grp=['OCR-D-IMG'] output_file_grp=[]
2020-07-15 13:30:15,959.959 INFO ocrd.task_sequence.run_tasks - Start processing task 'tesserocr-segment-region -I OCR-D-SEG-PAGE -O OCR-D-SEG-BLOCK'
2020-07-15 13:30:15,960.960 DEBUG ocrd.processor - Running subprocess 'ocrd-tesserocr-segment-region --working-dir /data/images --mets mets.xml --log-level DEBUG --input-file-grp OCR-D-SEG-PAGE --output-file-grp OCR-D-SEG-BLOCK --overwrite'
2020-07-15 13:30:17,160.160 INFO root - Overriding log level globally to DEBUG
2020-07-15 13:30:17,162.162 DEBUG ocrd.resolver - workspace_from_url
mets_basename='mets.xml'
mets_url='/data/images/mets.xml'
src_baseurl='/data/images'
dst_dir='/data/images'
2020-07-15 13:30:17,162.162 DEBUG ocrd.resolver.download_to_directory - directory=|/data/images| url=|/data/images/mets.xml| basename=|mets.xml| if_exists=|skip| subdir=|None|
2020-07-15 13:30:17,163.163 DEBUG ocrd.resolver.download_to_directory - Stop early, src_path and dst_path are the same: '/data/images/mets.xml' (url: '/data/images/mets.xml')
2020-07-15 13:30:17,164.164 DEBUG ocrd.workspace_validator - input_file_grp=['OCR-D-SEG-PAGE'] output_file_grp=[]
Traceback (most recent call last):
  File "/usr/bin/ocrd-tesserocr-segment-region", line 8, in <module>
    sys.exit(ocrd_tesserocr_segment_region())
  File "/usr/lib/python3.6/site-packages/click/core.py", line 829, in __call__
    return self.main(*args, **kwargs)
  File "/usr/lib/python3.6/site-packages/click/core.py", line 782, in main
    rv = self.invoke(ctx)
  File "/usr/lib/python3.6/site-packages/click/core.py", line 1066, in invoke
    return ctx.invoke(self.callback, **ctx.params)
  File "/usr/lib/python3.6/site-packages/click/core.py", line 610, in invoke
    return callback(*args, **kwargs)
  File "/usr/lib/python3.6/site-packages/ocrd_tesserocr/cli.py", line 16, in ocrd_tesserocr_segment_region
    return ocrd_cli_wrap_processor(TesserocrSegmentRegion, *args, **kwargs)
  File "/usr/lib/python3.6/site-packages/ocrd/decorators.py", line 81, in ocrd_cli_wrap_processor
    raise Exception("Invalid input/output file grps:\\n\\t%s" % '\\n\\t'.join(report.errors))
Exception: Invalid input/output file grps:
	Input fileGrp[@USE='OCR-D-SEG-PAGE'] not in METS!
Traceback (most recent call last):
  File "/usr/bin/ocrd", line 8, in <module>
    sys.exit(cli())
  File "/usr/lib/python3.6/site-packages/click/core.py", line 829, in __call__
    return self.main(*args, **kwargs)
  File "/usr/lib/python3.6/site-packages/click/core.py", line 782, in main
    rv = self.invoke(ctx)
  File "/usr/lib/python3.6/site-packages/click/core.py", line 1259, in invoke
    return _process_result(sub_ctx.command.invoke(sub_ctx))
  File "/usr/lib/python3.6/site-packages/click/core.py", line 1066, in invoke
    return ctx.invoke(self.callback, **ctx.params)
  File "/usr/lib/python3.6/site-packages/click/core.py", line 610, in invoke
    return callback(*args, **kwargs)
  File "/usr/lib/python3.6/site-packages/ocrd/cli/process.py", line 27, in process_cli
    run_tasks(mets, log_level, page_id, tasks, overwrite)
  File "/usr/lib/python3.6/site-packages/ocrd/task_sequence.py", line 148, in run_tasks
    raise Exception("%s exited with non-zero return value %s" % (task.executable, returncode))
Exception: ocrd-tesserocr-segment-region exited with non-zero return value 1
```

So, in the second attempt, the script goes on, when in the first try it had an error.

Also, in the second attempt, although the first process in the given pipeline (`cis-ocropy-binarize -I OCR-D-IMG -O OCR-D-SEG-PAGE`) should generate a `fileGrp[@USE='OCR-D-SEG-PAGE']` in the `mets.xml`, this process seems to not run and consequently the next process cannot access this information.

**Reproduction**
On the host, I am in a folder with an `images` folder, containing two digitized page images `Bild1.jpg` and `Bild2.jpg` and a Shell script `problem.sh`:

```
> ls
images/    problem.sh
> ls images/
Bild1.jpg   Bild2.jpg
```

The content of `problem.sh` is:
```
ocrd-import -P -i -r 300 images/
cd images
ocrd process -l DEBUG --overwrite \\
  'cis-ocropy-binarize -I OCR-D-IMG -O OCR-D-SEG-PAGE' \\
  'tesserocr-segment-region -I OCR-D-SEG-PAGE -O OCR-D-SEG-BLOCK' \\
  'tesserocr-segment-line -I OCR-D-SEG-BLOCK -O OCR-D-SEG-LINE' \\
  'tesserocr-recognize -I OCR-D-SEG-LINE -O OCR-D-OCR-TESSEROCR'
```

Then I run:
```
docker run -v $PWD:/data:Z -w /data -it ocrd/all:minimum problem.sh
# The first error occurs
docker run -v $PWD:/data:Z -w /data -it ocrd/all:minimum problem.sh
# The second error occurs
```

Note that we use skip the `-u $(id -u)` parameter, because we have podman running in the background and this parameter causes issues with file permissions.

Changed files:
tests/model/test_ocrd_page.py, ocrd/ocrd/decorators.py, tests/validator/test_workspace_validator.py

diff --git a/ocrd/ocrd/decorators.py b/ocrd/ocrd/decorators.py
index 397900cb..0b5b7705 100644
--- a/ocrd/ocrd/decorators.py
+++ b/ocrd/ocrd/decorators.py
@@ -8,7 +8,7 @@ from ocrd_utils import (
     get_local_filename,
     setOverrideLogLevel,
     parse_json_string_or_file,
-    set_json_key_value_overrides
+    set_json_key_value_overrides,
 )
 
 from ocrd_utils import getLogger
@@ -51,17 +51,12 @@ def ocrd_cli_wrap_processor(
     overwrite=False,
     **kwargs
 ):
-    LOG = getLogger('ocrd_cli_wrap_processor')
-    if dump_json:
-        processorClass(workspace=None, dump_json=True)
-        sys.exit()
-    elif help:
-        processorClass(workspace=None, show_help=True)
-        sys.exit()
-    elif version:
-        processorClass(workspace=None, show_version=True)
+    if dump_json or help or version:
+        setOverrideLogLevel('OFF')
+        processorClass(workspace=None, dump_json=dump_json, show_help=help, show_version=version)
         sys.exit()
     else:
+        LOG = getLogger('ocrd_cli_wrap_processor')
         if not mets or (is_local_filename(mets) and not isfile(get_local_filename(mets))):
             processorClass(workspace=None, show_help=True)
             sys.exit(1)
diff --git a/tests/model/test_ocrd_page.py b/tests/model/test_ocrd_page.py
index 327cd637..bad0b4bf 100644
--- a/tests/model/test_ocrd_page.py
+++ b/tests/model/test_ocrd_page.py
@@ -92,7 +92,7 @@ class TestOcrdPage(TestCase):
         #  self.assertTrue(True)
 
     def test_pcGtsId(self):
-        self.assertEqual(self.pcgts.pcGtsId, 'glyph-test')
+        self.assertEqual(self.pcgts.pcGtsId, 'FAULTY_GLYPHS_FILE')
 
     def test_delete_region(self):
         pcgts = parseString(simple_page, silence=True)
diff --git a/tests/validator/test_workspace_validator.py b/tests/validator/test_workspace_validator.py
index 39527561..e67942c3 100644
--- a/tests/validator/test_workspace_validator.py
+++ b/tests/validator/test_workspace_validator.py
@@ -8,7 +8,7 @@ from ocrd.resolver import Resolver
 from ocrd_validators import WorkspaceValidator
 from ocrd_validators.page_validator import ConsistencyError
 
-from tests.base import TestCase, assets, main # pylint: disable=import-error,no-name-in-module
+from tests.base import TestCase, assets, main, copy_of_directory # pylint: disable=import-error,no-name-in-module
 
 class TestWorkspaceValidator(TestCase):
 
@@ -222,8 +222,12 @@ class TestWorkspaceValidator(TestCase):
         self.assertEqual(len(report.errors), 0)
 
     def test_pcgtsid(self):
-        report = WorkspaceValidator.validate(self.resolver, assets.path_to('kant_aufklaerung_1784/data/mets.xml'))
-        self.assertIn('pc:PcGts/@pcGtsId differs from mets:file/@ID: "" !== "PAGE_0017_PAGE"', report.warnings)
+        with copy_of_directory(assets.path_to('kant_aufklaerung_1784/data')) as wsdir:
+            with pushd_popd(wsdir):
+                # remove the @pcGtsId attribute for testing
+                os.system("""sed -i 's,pcGtsId.*,pcGtsId="foo">,' OCR-D-GT-PAGE/PAGE_0017_PAGE.xml""")
+                report = WorkspaceValidator.validate(self.resolver, join(wsdir, 'mets.xml'))
+                self.assertIn('pc:PcGts/@pcGtsId differs from mets:file/@ID: "foo" !== "PAGE_0017_PAGE"', report.warnings)
 
 
 if __name__ == '__main__':