Problem with multiline logging

[ekouts]

I am not sure why exactly this happens but when I set the perflog_compat to True I am getting a weird error:

ERROR: run session stopped: attribute error: 'AsynchronousExecutionPolicy' object has no attribute '_advance_retired'
ERROR: Traceback (most recent call last):
  File "/users/eirinik/repos/reframe-test/reframe/frontend/cli.py", line 1267, in main
    runner.runall(testcases, restored_cases)
  File "/users/eirinik/repos/reframe-test/reframe/core/logging.py", line 892, in _fn
    return fn(*args, **kwargs)
  File "/users/eirinik/repos/reframe-test/reframe/frontend/executors/__init__.py", line 518, in runall
    self._runall(testcases)
  File "/users/eirinik/repos/reframe-test/reframe/frontend/executors/__init__.py", line 579, in _runall
    self._policy.exit()
  File "/users/eirinik/repos/reframe-test/reframe/frontend/executors/policies.py", line 340, in exit
    self._advance_all(self._current_tasks, timeout)
  File "/users/eirinik/repos/reframe-test/reframe/frontend/executors/policies.py", line 411, in _advance_all
    bump_state = getattr(self, f'_advance_{t.state}')
AttributeError: 'AsynchronousExecutionPolicy' object has no attribute '_advance_retired'

I think the problem is coming from https://github.com/reframe-hpc/reframe/blob/master/reframe/core/logging.py#L737
Somehow the self.extra['__rfm_check__'] is None and then an exception should have been raised in check.perfvalues.items. No exception is actually raised there but the test fails subsequently with the error above.

This is one test that reproduces the failure but I don't see anything obviously wrong with it: https://github.com/eth-cscs/cscs-reframe-tests/blob/main/checks/prgenv/affinity_check.py

[ekouts]

Reframe finishes normally if I change the code to

        if multiline:
            # Log one record for each performance variable
            check = self.extra['__rfm_check__']
            if check:
                for var, info in check.perfvalues.items():
                    self.extra['check_perf_var'] = var.split(':')[-1]
                    ...

But I think check should not be None in any case 🤔

[ekouts]

Btw no need for a complicated test to reproduce the problem. Any test that doesn't have performance vars will fail when perflog_compat = True

@rfm.simple_test
class Foo(rfm.RunOnlyRegressionTest):
    valid_systems = ['*']
    valid_prog_environs = ['*']
    executable = 'echo'
    executable_opts = ['Hello']

    @sanity_function
    def check_true(self):
        return True