Repository: E3SM-Project/zstash

Issue:
zstash check reports success even if exceptions occur
`zstash check` reports success even if exceptions occur.

Exceptions like the following may occur, but `zstash check` still ends with `INFO: No failures detected when checking the files.`:
```
Process Process-3:
Traceback (most recent call last):
  File "/global/common/software/e3sm/anaconda_envs/base/envs/e3sm_unified_1.5.0_nompi/lib/python3.8/multiprocessing/process.py", line 315, in _bootstrap
    self.run()
  File "/global/common/software/e3sm/anaconda_envs/base/envs/e3sm_unified_1.5.0_nompi/lib/python3.8/multiprocessing/process.py", line 108, in run
    self._target(*self._args, **self._kwargs)
  File "/global/common/software/e3sm/anaconda_envs/base/envs/e3sm_unified_1.5.0_nompi/lib/python3.8/site-packages/zstash/extract.py", line 374, in extractFiles
    hpss_get(hpss, tfname, cache)
  File "/global/common/software/e3sm/anaconda_envs/base/envs/e3sm_unified_1.5.0_nompi/lib/python3.8/site-packages/zstash/hpss.py", line 99, in hpss_get
    hpss_transfer(hpss, file_path, "get", cache, False)
  File "/global/common/software/e3sm/anaconda_envs/base/envs/e3sm_unified_1.5.0_nompi/lib/python3.8/site-packages/zstash/hpss.py", line 76, in hpss_transfer
    run_command(command, error_str)
  File "/global/common/software/e3sm/anaconda_envs/base/envs/e3sm_unified_1.5.0_nompi/lib/python3.8/site-packages/zstash/utils.py", line 55, in run_command
    raise Exception(error_str)
Exception: Error=Transferring file from HPSS: 000029.tar, Command was `hsi -q "cd /home/f/forsyth/E3SMv2/v2.LR.hist-aer_0251; get 000029.tar"`. This command includes `hsi`. Be sure that you have logged into `hsi`.
```

Possible solutions:
- Fail on first `Exception`
- Create list of all `Exceptions` before failing

Discussion:
forsyth2: @golaz This change (adding `daemon=True` to the `multiprocessing.Process` call) at least seems to make `zstash` fail immediately. I tested it out and it exited after two errors `Exception: Error=Transferring file from HPSS: 000001.tar` and `Exception: Error=Transferring file from HPSS: 000000.tar`, as opposed to running through all tars. However, it still prints `INFO: No failures detected when checking the files.`, so it doesn't actually fix the bug.

Line 59 (`logger.info("No failures detected when {} the files.".format(verb))`) is run > `failures` was an empty list > `extract_database` returned an empty list > `multiprocess_extract` returned an empty list > there must be some problem in this code block:
```
    failures: List[FilesRow] = []
    while any(p.is_alive() for p in processes):
        while not failure_queue.empty():
            failures.append(failure_queue.get())
```
forsyth2: Note that this bug only happens when there are multiple workers. In the one-worker case, `ERROR: Error=Transferring file from HPSS: 000000.tar` is printed without being followed by `INFO: No failures detected when checking the files.`. (Interestingly, the `Exception: Error=Transferring file from HPSS: 000001.tar` was not printed in the one-worker case.)
golaz: @forsyth2 : thanks for investigating. Stopping immediately would at least be a step in the right direction.

The serial and parallel options use significantly different code, so it makes sense that they could behave differently. Based on what you have found, there might be an implementation issue with the failure queue. Unfortunately, I don't know how that code works.

Do you want to incorporate your change first as a partial solution?


forsyth2: > Stopping immediately would at least be a step in the right direction.

@golaz Alright, should we add something like `Run "grep -i Exception" on the check log to double check` to `INFO: No failures detected when checking the files.` until we get the issue fixed fully?

I tried debugging further, but the tars that were causing the Exception suddenly appear to not cause issues. In any case, code blocks to investigate would include the following (all in https://github.com/E3SM-Project/zstash/blob/master/zstash/extract.py):

In `multiprocess_extract`:
```
    failures: List[FilesRow] = []
    while any(p.is_alive() for p in processes):
        while not failure_queue.empty():
            failures.append(failure_queue.get())
```

In `extractFiles`:
```
        except Exception:
            # Catch all exceptions here.
            traceback.print_exc()
            logger.error("Retrieving {}".format(files_row.name))
            failures.append(files_row)
```
```
    if multiprocess_worker:
        # If there are things left to print, print them.
        multiprocess_worker.print_all_contents()

        # Add the failures to the queue.
        # When running with multiprocessing, the function multiprocess_extract()
        # that calls this extractFiles() function will return the failures as a list.
        for f in failures:
            multiprocess_worker.failure_queue.put(f)
```

Patch:
diff --git a/zstash/extract.py b/zstash/extract.py
index 5382609..9918bf4 100644
--- a/zstash/extract.py
+++ b/zstash/extract.py
@@ -57,7 +57,11 @@ def extract(keep_files: bool = True):
             logger.error(tar)
     else:
         verb: str = "extracting" if keep_files else "checking"
-        logger.info("No failures detected when {} the files.".format(verb))
+        logger.info(
+            'No failures detected when {} the files. If you have a log file, run "grep -i Exception <log-file>" to double check.'.format(
+                verb
+            )
+        )
 
 
 def setup_extract() -> Tuple[argparse.Namespace, str]:
@@ -352,7 +356,9 @@ def multiprocess_extract(
             monitor, tars_for_this_worker, failure_queue
         )
         process: multiprocessing.Process = multiprocessing.Process(
-            target=extractFiles, args=(matches, keep_files, keep_tars, cache, worker)
+            target=extractFiles,
+            args=(matches, keep_files, keep_tars, cache, worker),
+            daemon=True,
         )
         process.start()
         processes.append(process)


Test patch:
diff --git a/tests/test_check.py b/tests/test_check.py
index 6bc3910..1a97239 100644
--- a/tests/test_check.py
+++ b/tests/test_check.py
@@ -189,7 +189,7 @@ class TestCheck(TestZstash):
         )
         self.assertEqualOrStop(
             output + err,
-            "INFO: Opening tar archive {}/000000.tar\nINFO: Checking file1.txt\nINFO: Checking file2.txt\nINFO: No failures detected when checking the files.\n".format(
+            'INFO: Opening tar archive {}/000000.tar\nINFO: Checking file1.txt\nINFO: Checking file2.txt\nINFO: No failures detected when checking the files. If you have a log file, run "grep -i Exception <log-file>" to double check.\n'.format(
                 self.cache
             ),
         )