Bug in Summary of Failures

[casparvl]

TLDR: see my minimal reproducer in my reply below

=====

I have a designed a ReFrame test that

• uses find_modules
• checks if GPUs are present in the current partition
• if GPUs are present, calls skip_test if the module name does not include CUDA
• if GPUs are not present, calls skip_test if the module name does include CUDA

I have 5 modules on my system: 2 CPU based on 3 GPU based modules. When running on my GPU partition:

reframe --config-file=config/settings_cartesius.py --checkpath eessi-checks/applications/gromacs.py -r --performance-report --system=example_system:gpu -t singlenode

it correctly generates 5 tests, and skips 2 out of these 5 tests. For the remaining 3 tests, it fails one of the sanity checks (this is expected, that module is broken).

So far, so good. However, ReFrame's SUMMARY OF FAILURES output is unexpected:

...
[----------] started processing Gromacs_EESSI_singlenode___example_system_gpu_short____builtin____GROMACS_2020_3_foss_2020a__ (GROMACS Prace Benchmark Suite case A)
[ RUN      ] Gromacs_EESSI_singlenode___example_system_gpu_short____builtin____GROMACS_2020_3_foss_2020a__ on example_system:gpu_short using builtin
GPU is present on this partition, skipping CPU-based test
[     SKIP ] (1/5) None
[----------] finished processing Gromacs_EESSI_singlenode___example_system_gpu_short____builtin____GROMACS_2020_3_foss_2020a__ (GROMACS Prace Benchmark Suite case A)
...
[----------] started processing Gromacs_EESSI_singlenode___example_system_gpu_short____builtin____GROMACS_2020_3_intel_2020a_CUDA_11_0_3__ (GROMACS Prace Benchmark Suite case A)
[ RUN      ] Gromacs_EESSI_singlenode___example_system_gpu_short____builtin____GROMACS_2020_3_intel_2020a_CUDA_11_0_3__ on example_system:gpu_short using builtin
[----------] finished processing Gromacs_EESSI_singlenode___example_system_gpu_short____builtin____GROMACS_2020_3_intel_2020a_CUDA_11_0_3__ (GROMACS Prace Benchmark Suite case A)
...
[     FAIL ] (3/5) Gromacs_EESSI_singlenode___example_system_gpu_short____builtin____GROMACS_2020_3_intel_2020a_CUDA_11_0_3__ on example_system:gpu_short using builtin [compile: 0.007s run: 23.463s total: 2
3.554s]
==> test failed during 'sanity': test staged in '/nfs/home4/casparl/EESSI/software-layer/tests/reframe/stage/example_system/gpu_short/builtin/Gromacs_EESSI_singlenode___example_system_gpu_short____builtin__
__GROMACS_2020_3_intel_2020a_CUDA_11_0_3__'
...
[  FAILED  ] Ran 3/5 test case(s) from 5 check(s) (1 failure(s), 2 skipped)
[==========] Finished on Wed Jun  9 18:23:02 2021

==============================================================================
SUMMARY OF FAILURES
------------------------------------------------------------------------------
FAILURE INFO for Gromacs_EESSI_singlenode___example_system_gpu_short____builtin____GROMACS_2020_3_foss_2020a__
  * Test Description: GROMACS Prace Benchmark Suite case A
  * System partition: example_system:gpu_short
  * Environment: builtin
  * Stage directory: /nfs/home4/casparl/EESSI/software-layer/tests/reframe/stage/example_system/gpu_short/builtin/Gromacs_EESSI_singlenode___example_system_gpu_short____builtin____GROMACS_2020_3_foss_2020a__
  * Node list:
  * Job type: batch job (id=None)
  * Dependencies (conceptual): []
  * Dependencies (actual): []
  * Maintainers: ['casparvl']
  * Failing phase: None
  * Rerun with '-n Gromacs_EESSI_singlenode___example_system_gpu_short____builtin____GROMACS_2020_3_foss_2020a__ -p builtin --system example_system:gpu_short -r'
  * Reason: None
/home/casparl/.local/easybuild/RedHatEnterpriseServer7/2020/software/ReFrame/3.6.2/bin/reframe: run session stopped: key error: 'fail_info'
/home/casparl/.local/easybuild/RedHatEnterpriseServer7/2020/software/ReFrame/3.6.2/bin/reframe: Traceback (most recent call last):
  File "/home/casparl/.local/easybuild/RedHatEnterpriseServer7/2020/software/ReFrame/3.6.2/lib/python3.6/site-packages/ReFrame_HPC-3.6.2-py3.6.egg/reframe/frontend/cli.py", line 1022, in main
    runner.stats.print_failure_report(printer)
  File "/home/casparl/.local/easybuild/RedHatEnterpriseServer7/2020/software/ReFrame/3.6.2/lib/python3.6/site-packages/ReFrame_HPC-3.6.2-py3.6.egg/reframe/frontend/statistics.py", line 237, in print_failure_report
    tb = ''.join(traceback.format_exception(*r['fail_info'].values()))
KeyError: 'fail_info'

Log file(s) saved in: '/nfs/home4/casparl/EESSI/software-layer/tests/reframe/reframe.log'

There are three problems with this output:

1. It prints failure info for Gromacs_EESSI_singlenode___example_system_gpu_short____builtin____GROMACS_2020_3_foss_2020a__ (which is one of the tests that is actually skipped) rather than for Gromacs_EESSI_singlenode___example_system_gpu_short____builtin____GROMACS_2020_3_intel_2020a_CUDA_11_0_3__ (the test that actually failed).
2. The Traceback.
3. It doesn't print the performance log (though I guess that's because it crashes, resulting in the traceback).

The original test is here https://github.com/casparvl/software-layer/blob/gromacs_libtest/tests/reframe/eessi-checks/applications/gromacs.py (which uses the library test at https://github.com/casparvl/software-layer/tree/gromacs_libtest/tests/reframe/testlib/applications/gromacs).

I'll try to create a more minimal reproducer. My best guess is it has something to with the skipped tests. Maybe a list is being indexed based on 5 tests being run, but then this indexing fails since only 3 tests ran in the end? Anyway, I'll try to confirm that with a minimal reproducer that runs 2 tests of which one is skipped and the other fails...

[casparvl]

Here's a minimal reproducer:

import reframe as rfm
import reframe.utility.sanity as sn

@rfm.simple_test
class minimal(rfm.RunOnlyRegressionTest):
    num_tasks = 1
    num_tasks_per_node = 1
    num_cpus_per_task = 1

    valid_systems = ['*']
    valid_prog_environs = ['*']

    test_param = parameter(['a', 'b'])

    @rfm.run_after('setup')
    def skip_test(self):
        if self.test_param == 'a':
           self.skip_if(True)

    @rfm.run_before('sanity')
    def set_sanity(self):
        if self.test_param == 'a':
            self.sanity_patterns = sn.assert_eq(0, 0)
        elif self.test_param == 'b':
            self.sanity_patterns = sn.assert_eq(0, 1)

I.e. test variant 'a' will be skipped (but the sanity pattern would have been ok), while test variant 'b' will fail the sanity check. Running this gives

[----------] started processing minimal_a (minimal_a)
[ RUN      ] minimal_a on example_system:gpu_short using builtin
[     SKIP ] (1/2) None
[----------] finished processing minimal_a (minimal_a)

[----------] started processing minimal_b (minimal_b)
[ RUN      ] minimal_b on example_system:gpu_short using builtin
[----------] finished processing minimal_b (minimal_b)

[----------] waiting for spawned checks to finish
[     FAIL ] (2/2) minimal_b on example_system:gpu_short using builtin [compile: 0.006s run: 37.591s total: 37.617s]
==> test failed during 'sanity': test staged in '/nfs/home4/casparl/EESSI/software-layer/tests/reframe/stage/example_system/gpu_short/builtin/minimal_b'
[----------] all spawned checks have finished

[  FAILED  ] Ran 1/2 test case(s) from 2 check(s) (1 failure(s), 1 skipped)
[==========] Finished on Wed Jun  9 19:05:48 2021

==============================================================================
SUMMARY OF FAILURES
------------------------------------------------------------------------------
FAILURE INFO for minimal_a
  * Test Description: minimal_a
  * System partition: example_system:gpu_short
  * Environment: builtin
  * Stage directory: /nfs/home4/casparl/EESSI/software-layer/tests/reframe/stage/example_system/gpu_short/builtin/minimal_a
  * Node list:
  * Job type: batch job (id=None)
  * Dependencies (conceptual): []
  * Dependencies (actual): []
  * Maintainers: []
  * Failing phase: None
  * Rerun with '-n minimal_a -p builtin --system example_system:gpu_short -r'
  * Reason: None
/home/casparl/.local/easybuild/RedHatEnterpriseServer7/2020/software/ReFrame/3.6.2/bin/reframe: run session stopped: key error: 'fail_info'
/home/casparl/.local/easybuild/RedHatEnterpriseServer7/2020/software/ReFrame/3.6.2/bin/reframe: Traceback (most recent call last):
  File "/home/casparl/.local/easybuild/RedHatEnterpriseServer7/2020/software/ReFrame/3.6.2/lib/python3.6/site-packages/ReFrame_HPC-3.6.2-py3.6.egg/reframe/frontend/cli.py", line 1022, in main
    runner.stats.print_failure_report(printer)
  File "/home/casparl/.local/easybuild/RedHatEnterpriseServer7/2020/software/ReFrame/3.6.2/lib/python3.6/site-packages/ReFrame_HPC-3.6.2-py3.6.egg/reframe/frontend/statistics.py", line 237, in print_failure_report
    tb = ''.join(traceback.format_exception(*r['fail_info'].values()))
KeyError: 'fail_info'

[casparvl]

NB: since I thought it might be an indexing issue, I tried to swap the parameters around so that the second test gets skipped. I.e.

test_param = parameter(['b', 'a'])

Running that, I get both the failure info for the correct test (minimal_b) but ALSO for the skipped test (minimal_a):

[----------] started processing minimal_b (minimal_b)
[ RUN      ] minimal_b on example_system:gpu_short using builtin
[----------] finished processing minimal_b (minimal_b)

[----------] started processing minimal_a (minimal_a)
[ RUN      ] minimal_a on example_system:gpu_short using builtin
[     SKIP ] (1/2) None
[----------] finished processing minimal_a (minimal_a)

[----------] waiting for spawned checks to finish
[     FAIL ] (2/2) minimal_b on example_system:gpu_short using builtin [compile: 0.007s run: 27.633s total: 27.662s]
==> test failed during 'sanity': test staged in '/nfs/home4/casparl/EESSI/software-layer/tests/reframe/stage/example_system/gpu_short/builtin/minimal_b'
[----------] all spawned checks have finished

[  FAILED  ] Ran 1/2 test case(s) from 2 check(s) (1 failure(s), 1 skipped)
[==========] Finished on Wed Jun  9 19:08:46 2021

==============================================================================
SUMMARY OF FAILURES
------------------------------------------------------------------------------
FAILURE INFO for minimal_b
  * Test Description: minimal_b
  * System partition: example_system:gpu_short
  * Environment: builtin
  * Stage directory: /nfs/home4/casparl/EESSI/software-layer/tests/reframe/stage/example_system/gpu_short/builtin/minimal_b
  * Node list: gcn3
  * Job type: batch job (id=10399895)
  * Dependencies (conceptual): []
  * Dependencies (actual): []
  * Maintainers: []
  * Failing phase: sanity
  * Rerun with '-n minimal_b -p builtin --system example_system:gpu_short -r'
  * Reason: sanity error: 0 != 1
------------------------------------------------------------------------------
FAILURE INFO for minimal_a
  * Test Description: minimal_a
  * System partition: example_system:gpu_short
  * Environment: builtin
  * Stage directory: /nfs/home4/casparl/EESSI/software-layer/tests/reframe/stage/example_system/gpu_short/builtin/minimal_a
  * Node list:
  * Job type: batch job (id=None)
  * Dependencies (conceptual): []
  * Dependencies (actual): []
  * Maintainers: []
  * Failing phase: None
  * Rerun with '-n minimal_a -p builtin --system example_system:gpu_short -r'
  * Reason: None
/home/casparl/.local/easybuild/RedHatEnterpriseServer7/2020/software/ReFrame/3.6.2/bin/reframe: run session stopped: key error: 'fail_info'
/home/casparl/.local/easybuild/RedHatEnterpriseServer7/2020/software/ReFrame/3.6.2/bin/reframe: Traceback (most recent call last):
  File "/home/casparl/.local/easybuild/RedHatEnterpriseServer7/2020/software/ReFrame/3.6.2/lib/python3.6/site-packages/ReFrame_HPC-3.6.2-py3.6.egg/reframe/frontend/cli.py", line 1022, in main
    runner.stats.print_failure_report(printer)
  File "/home/casparl/.local/easybuild/RedHatEnterpriseServer7/2020/software/ReFrame/3.6.2/lib/python3.6/site-packages/ReFrame_HPC-3.6.2-py3.6.egg/reframe/frontend/statistics.py", line 237, in print_failure_report
    tb = ''.join(traceback.format_exception(*r['fail_info'].values()))
KeyError: 'fail_info'

I figured knowing that the order matters might help you find the issue...

[teojgo]

The problem lies here:
https://github.com/eth-cscs/reframe/blob/39c42bb4650dc6b8651ee9e7c909b387395f0fe3/reframe/frontend/statistics.py#L209

The continue should be valid in the case of skipped tests as well.

[casparvl]

I can confirm that works, I've made the edit locally, and the minimal example now reported the correct test in the Summary of Failures.

I created a PR that fixes it #2010