ReFrame crashes if its output is piped to an inexistent program

[vkarak]

karakasv@tresa reframe [feature/summary-rerun-failures] $ ./bin/reframe -c unittests/resources/checks/hellocheck.py -l | foo
-bash: foo: command not found
--- Logging error ---
Traceback (most recent call last):
  File "/Users/karakasv/Repositories/reframe/reframe/frontend/cli.py", line 295, in main
    non_default_craype=options.non_default_craype)
  File "/Users/karakasv/Repositories/reframe/reframe/core/runtime.py", line 305, in init_runtime
    _runtime_context = RuntimeContext(dict_config, sysname, **options)
  File "/Users/karakasv/Repositories/reframe/reframe/core/runtime.py", line 205, in __init__
    self._system = HostSystem(self._autodetect_system())
  File "/Users/karakasv/Repositories/reframe/reframe/core/runtime.py", line 233, in _autodetect_system
    raise SystemAutodetectionError
reframe.core.exceptions.SystemAutodetectionError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/logging/__init__.py", line 1038, in emit
    self.flush()
  File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/logging/__init__.py", line 1018, in flush
    self.stream.flush()
BrokenPipeError: [Errno 32] Broken pipe
Call stack:
  File "./bin/reframe", line 11, in <module>
    cli.main()
  File "/Users/karakasv/Repositories/reframe/reframe/frontend/cli.py", line 298, in main
    'could not find a configuration entry for the current system; '
  File "/Users/karakasv/Repositories/reframe/reframe/core/logging.py", line 505, in warning
    super().warning(message, *args, **kwargs)
  File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/logging/__init__.py", line 1736, in warning
    self.log(WARNING, msg, *args, **kwargs)
  File "/Users/karakasv/Repositories/reframe/reframe/core/logging.py", line 495, in log
    super().log(level, msg, *args, **kwargs)
Message: '\x1b[33m./bin/reframe: could not find a configuration entry for the current system; falling back to a generic system configuration; please check the online documentation on how to configure ReFrame for your system.\x1b[0m'
Arguments: ()
--- Logging error ---
Traceback (most recent call last):
  File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/logging/__init__.py", line 1038, in emit
    self.flush()
  File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/logging/__init__.py", line 1018, in flush
    self.stream.flush()
BrokenPipeError: [Errno 32] Broken pipe
Call stack:
  File "./bin/reframe", line 11, in <module>
    cli.main()
  File "/Users/karakasv/Repositories/reframe/reframe/frontend/cli.py", line 445, in main
    printer.info('Command line: %s' % ' '.join(sys.argv))
  File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/logging/__init__.py", line 1730, in info
    self.log(INFO, msg, *args, **kwargs)
  File "/Users/karakasv/Repositories/reframe/reframe/core/logging.py", line 495, in log
    super().log(level, msg, *args, **kwargs)
Message: 'Command line: ./bin/reframe -c unittests/resources/checks/hellocheck.py -l'
Arguments: ()
--- Logging error ---
Traceback (most recent call last):
  File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/logging/__init__.py", line 1038, in emit
    self.flush()
  File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/logging/__init__.py", line 1018, in flush
    self.stream.flush()
BrokenPipeError: [Errno 32] Broken pipe
Call stack:
  File "./bin/reframe", line 11, in <module>
    cli.main()
  File "/Users/karakasv/Repositories/reframe/reframe/frontend/cli.py", line 446, in main
    printer.info('Reframe version: '  + reframe.VERSION)
  File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/logging/__init__.py", line 1730, in info
    self.log(INFO, msg, *args, **kwargs)
  File "/Users/karakasv/Repositories/reframe/reframe/core/logging.py", line 495, in log
    super().log(level, msg, *args, **kwargs)
Message: 'Reframe version: 3.0-dev2'
Arguments: ()
--- Logging error ---
Traceback (most recent call last):
  File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/logging/__init__.py", line 1038, in emit
    self.flush()
  File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/logging/__init__.py", line 1018, in flush
    self.stream.flush()
BrokenPipeError: [Errno 32] Broken pipe
Call stack:
  File "./bin/reframe", line 11, in <module>
    cli.main()
  File "/Users/karakasv/Repositories/reframe/reframe/frontend/cli.py", line 447, in main
    printer.info('Launched by user: ' + (os_ext.osuser() or '<unknown>'))
  File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/logging/__init__.py", line 1730, in info
    self.log(INFO, msg, *args, **kwargs)
  File "/Users/karakasv/Repositories/reframe/reframe/core/logging.py", line 495, in log
    super().log(level, msg, *args, **kwargs)
Message: 'Launched by user: karakasv'
Arguments: ()
--- Logging error ---
Traceback (most recent call last):
  File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/logging/__init__.py", line 1038, in emit
    self.flush()
  File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/logging/__init__.py", line 1018, in flush
    self.stream.flush()
BrokenPipeError: [Errno 32] Broken pipe
Call stack:
  File "./bin/reframe", line 11, in <module>
    cli.main()
  File "/Users/karakasv/Repositories/reframe/reframe/frontend/cli.py", line 448, in main
    printer.info('Launched on host: ' + socket.gethostname())
  File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/logging/__init__.py", line 1730, in info
    self.log(INFO, msg, *args, **kwargs)
  File "/Users/karakasv/Repositories/reframe/reframe/core/logging.py", line 495, in log
    super().log(level, msg, *args, **kwargs)
Message: 'Launched on host: dhcp-133-242.cscs.ch'
Arguments: ()
--- Logging error ---
Traceback (most recent call last):
  File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/logging/__init__.py", line 1038, in emit
    self.flush()
  File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/logging/__init__.py", line 1018, in flush
    self.stream.flush()
BrokenPipeError: [Errno 32] Broken pipe
Call stack:
  File "./bin/reframe", line 11, in <module>
    cli.main()
  File "/Users/karakasv/Repositories/reframe/reframe/frontend/cli.py", line 451, in main
    printer.info('Reframe paths')
  File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/logging/__init__.py", line 1730, in info
    self.log(INFO, msg, *args, **kwargs)
  File "/Users/karakasv/Repositories/reframe/reframe/core/logging.py", line 495, in log
    super().log(level, msg, *args, **kwargs)
Message: 'Reframe paths'
Arguments: ()
--- Logging error ---
Traceback (most recent call last):
  File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/logging/__init__.py", line 1038, in emit
    self.flush()
  File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/logging/__init__.py", line 1018, in flush
    self.stream.flush()
BrokenPipeError: [Errno 32] Broken pipe
Call stack:
  File "./bin/reframe", line 11, in <module>
    cli.main()
  File "/Users/karakasv/Repositories/reframe/reframe/frontend/cli.py", line 452, in main
    printer.info('=============')
  File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/logging/__init__.py", line 1730, in info
    self.log(INFO, msg, *args, **kwargs)
  File "/Users/karakasv/Repositories/reframe/reframe/core/logging.py", line 495, in log
    super().log(level, msg, *args, **kwargs)
Message: '============='
Arguments: ()
--- Logging error ---
Traceback (most recent call last):
  File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/logging/__init__.py", line 1038, in emit
    self.flush()
  File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/logging/__init__.py", line 1018, in flush
    self.stream.flush()
BrokenPipeError: [Errno 32] Broken pipe
Call stack:
  File "./bin/reframe", line 11, in <module>
    cli.main()
  File "/Users/karakasv/Repositories/reframe/reframe/frontend/cli.py", line 453, in main
    printer.info('    Check prefix      : %s' % loader.prefix)
  File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/logging/__init__.py", line 1730, in info
    self.log(INFO, msg, *args, **kwargs)
  File "/Users/karakasv/Repositories/reframe/reframe/core/logging.py", line 495, in log
    super().log(level, msg, *args, **kwargs)
Message: '    Check prefix      : '
Arguments: ()
--- Logging error ---
Traceback (most recent call last):
  File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/logging/__init__.py", line 1038, in emit
    self.flush()
  File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/logging/__init__.py", line 1018, in flush
    self.stream.flush()
BrokenPipeError: [Errno 32] Broken pipe
Call stack:
  File "./bin/reframe", line 11, in <module>
    cli.main()
  File "/Users/karakasv/Repositories/reframe/reframe/frontend/cli.py", line 456, in main
    "'%s'" % ':'.join(loader.load_path)))
  File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/logging/__init__.py", line 1730, in info
    self.log(INFO, msg, *args, **kwargs)
  File "/Users/karakasv/Repositories/reframe/reframe/core/logging.py", line 495, in log
    super().log(level, msg, *args, **kwargs)
Message: "    Check search path : '/Users/karakasv/Repositories/reframe/unittests/resources/checks/hellocheck.py'"
Arguments: ()
--- Logging error ---
Traceback (most recent call last):
  File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/logging/__init__.py", line 1038, in emit
    self.flush()
  File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/logging/__init__.py", line 1018, in flush
    self.stream.flush()
BrokenPipeError: [Errno 32] Broken pipe
Call stack:
  File "./bin/reframe", line 11, in <module>
    cli.main()
  File "/Users/karakasv/Repositories/reframe/reframe/frontend/cli.py", line 457, in main
    printer.info('    Current working dir  : %s' % os.getcwd())
  File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/logging/__init__.py", line 1730, in info
    self.log(INFO, msg, *args, **kwargs)
  File "/Users/karakasv/Repositories/reframe/reframe/core/logging.py", line 495, in log
    super().log(level, msg, *args, **kwargs)
Message: '    Current working dir  : /Users/karakasv/Repositories/reframe'
Arguments: ()
--- Logging error ---
Traceback (most recent call last):
  File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/logging/__init__.py", line 1038, in emit
    self.flush()
  File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/logging/__init__.py", line 1018, in flush
    self.stream.flush()
BrokenPipeError: [Errno 32] Broken pipe
Call stack:
  File "./bin/reframe", line 11, in <module>
    cli.main()
  File "/Users/karakasv/Repositories/reframe/reframe/frontend/cli.py", line 458, in main
    printer.info('    Stage dir prefix     : %s' % rt.resources.stage_prefix)
  File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/logging/__init__.py", line 1730, in info
    self.log(INFO, msg, *args, **kwargs)
  File "/Users/karakasv/Repositories/reframe/reframe/core/logging.py", line 495, in log
    super().log(level, msg, *args, **kwargs)
Message: '    Stage dir prefix     : /Users/karakasv/Repositories/reframe/stage/'
Arguments: ()
--- Logging error ---
Traceback (most recent call last):
  File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/logging/__init__.py", line 1038, in emit
    self.flush()
  File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/logging/__init__.py", line 1018, in flush
    self.stream.flush()
BrokenPipeError: [Errno 32] Broken pipe
Call stack:
  File "./bin/reframe", line 11, in <module>
    cli.main()
  File "/Users/karakasv/Repositories/reframe/reframe/frontend/cli.py", line 459, in main
    printer.info('    Output dir prefix    : %s' % rt.resources.output_prefix)
  File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/logging/__init__.py", line 1730, in info
    self.log(INFO, msg, *args, **kwargs)
  File "/Users/karakasv/Repositories/reframe/reframe/core/logging.py", line 495, in log
    super().log(level, msg, *args, **kwargs)
Message: '    Output dir prefix    : /Users/karakasv/Repositories/reframe/output/'
Arguments: ()
--- Logging error ---
Traceback (most recent call last):
  File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/logging/__init__.py", line 1038, in emit
    self.flush()
  File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/logging/__init__.py", line 1018, in flush
    self.stream.flush()
BrokenPipeError: [Errno 32] Broken pipe
Call stack:
  File "./bin/reframe", line 11, in <module>
    cli.main()
  File "/Users/karakasv/Repositories/reframe/reframe/frontend/cli.py", line 462, in main
    os.path.abspath(logging.LOG_CONFIG_OPTS['handlers.filelog.prefix']))
  File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/logging/__init__.py", line 1730, in info
    self.log(INFO, msg, *args, **kwargs)
  File "/Users/karakasv/Repositories/reframe/reframe/core/logging.py", line 495, in log
    super().log(level, msg, *args, **kwargs)
Message: '    Perf. logging prefix : /Users/karakasv/Repositories/reframe/perflogs'
Arguments: ()
--- Logging error ---
Traceback (most recent call last):
  File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/logging/__init__.py", line 1038, in emit
    self.flush()
  File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/logging/__init__.py", line 1018, in flush
    self.stream.flush()
BrokenPipeError: [Errno 32] Broken pipe
Call stack:
  File "./bin/reframe", line 11, in <module>
    cli.main()
  File "/Users/karakasv/Repositories/reframe/reframe/frontend/cli.py", line 566, in main
    list_checks(list(checks_matched), printer)
  File "/Users/karakasv/Repositories/reframe/reframe/frontend/cli.py", line 52, in list_checks
    printer.info('List of matched checks')
  File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/logging/__init__.py", line 1730, in info
    self.log(INFO, msg, *args, **kwargs)
  File "/Users/karakasv/Repositories/reframe/reframe/core/logging.py", line 495, in log
    super().log(level, msg, *args, **kwargs)
Message: 'List of matched checks'
Arguments: ()
--- Logging error ---
Traceback (most recent call last):
  File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/logging/__init__.py", line 1038, in emit
    self.flush()
  File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/logging/__init__.py", line 1018, in flush
    self.stream.flush()
BrokenPipeError: [Errno 32] Broken pipe
Call stack:
  File "./bin/reframe", line 11, in <module>
    cli.main()
  File "/Users/karakasv/Repositories/reframe/reframe/frontend/cli.py", line 566, in main
    list_checks(list(checks_matched), printer)
  File "/Users/karakasv/Repositories/reframe/reframe/frontend/cli.py", line 53, in list_checks
    printer.info('======================')
  File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/logging/__init__.py", line 1730, in info
    self.log(INFO, msg, *args, **kwargs)
  File "/Users/karakasv/Repositories/reframe/reframe/core/logging.py", line 495, in log
    super().log(level, msg, *args, **kwargs)
Message: '======================'
Arguments: ()
--- Logging error ---
Traceback (most recent call last):
  File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/logging/__init__.py", line 1038, in emit
    self.flush()
  File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/logging/__init__.py", line 1018, in flush
    self.stream.flush()
BrokenPipeError: [Errno 32] Broken pipe
Call stack:
  File "./bin/reframe", line 11, in <module>
    cli.main()
  File "/Users/karakasv/Repositories/reframe/reframe/frontend/cli.py", line 566, in main
    list_checks(list(checks_matched), printer)
  File "/Users/karakasv/Repositories/reframe/reframe/frontend/cli.py", line 55, in list_checks
    printer.info(format_check(c, detailed))
  File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/logging/__init__.py", line 1730, in info
    self.log(INFO, msg, *args, **kwargs)
  File "/Users/karakasv/Repositories/reframe/reframe/core/logging.py", line 495, in log
    super().log(level, msg, *args, **kwargs)
Message: '  * hellocheck (found in /Users/karakasv/Repositories/reframe/unittests/resources/checks/hellocheck.py)'
Arguments: ()
--- Logging error ---
Traceback (most recent call last):
  File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/logging/__init__.py", line 1038, in emit
    self.flush()
  File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/logging/__init__.py", line 1018, in flush
    self.stream.flush()
BrokenPipeError: [Errno 32] Broken pipe
Call stack:
  File "./bin/reframe", line 11, in <module>
    cli.main()
  File "/Users/karakasv/Repositories/reframe/reframe/frontend/cli.py", line 566, in main
    list_checks(list(checks_matched), printer)
  File "/Users/karakasv/Repositories/reframe/reframe/frontend/cli.py", line 57, in list_checks
    printer.info('Found %d check(s).' % len(checks))
  File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/logging/__init__.py", line 1730, in info
    self.log(INFO, msg, *args, **kwargs)
  File "/Users/karakasv/Repositories/reframe/reframe/core/logging.py", line 495, in log
    super().log(level, msg, *args, **kwargs)
Message: 'Found 1 check(s).'
Arguments: ()
Exception ignored in: <_io.TextIOWrapper name='<stdout>' mode='w' encoding='UTF-8'>
BrokenPipeError: [Errno 32] Broken pipe

[teojgo]

This seems to be a Python issue not a ReFrame one per se. The following links are useful:

• https://stackoverflow.com/questions/14207708/ioerror-errno-32-broken-pipe-python
• https://stackoverflow.com/questions/34718208/catch-broken-pipe-in-python-2-and-python-3
• http://newbebweb.blogspot.com/2012/02/python-head-ioerror-errno-32-broken.html

[teojgo]

The official Python documentation has also a note on it:
https://docs.python.org/3/library/signal.html#note-on-sigpipe

[teojgo]

This happens when the self.stream.flush from the standard library logging is called. @vkarak do you think I should handle SIGPIPE?

[vkarak]

Can you give more insight on how is it actually happening?

[teojgo]

It tries to flush to a pipe that is closed so it gets the BrokenPipeError. It seems to be related to the handler related to stdout.

[teojgo]

One possible solution is to use signal(SIGPIPE,SIG_DFL) therefore restoring the default behavior of the system in case of broken pipes.

[vkarak]

One possible solution is to use signal(SIGPIPE,SIG_DFL) therefore restoring the default behavior of the system in case of broken pipes.

No, this should be avoided according to the official documentation. We should handle the BrokenPipeError.