Readable metabox output in CI (#644)

* Log in error output streams on failure

Minor: Black changes here and there

* Changed the log level from TRACE to INFO

* INFO is now the default metabox log level

* Output full stdout/err log cronological and use that

.github/workflows/metabox.yaml

@@ -65,4 +65,4 @@ jobs:
  - name: Install Metabox
  run: python3 -m pip install -e .
  - name: Run Metabox scenarios
- run: metabox configs/${{ matrix.mode }}-source-${{ matrix.os }}.py --log TRACE
+ run: metabox configs/${{ matrix.mode }}-source-${{ matrix.os }}.py

metabox/metabox/core/lxd_execute.py

@@ -29,17 +29,16 @@
 
 
 base_env = {
- 'PYTHONUNBUFFERED': '1',
- 'DISABLE_URWID_ESCAPE_CODES': '1',
- 'XDG_RUNTIME_DIR': '/run/user/1000'
+ "PYTHONUNBUFFERED": "1",
+ "DISABLE_URWID_ESCAPE_CODES": "1",
+ "XDG_RUNTIME_DIR": "/run/user/1000",
 }
-login_shell = ['sudo', '--user', 'ubuntu', '--login']
+login_shell = ["sudo", "--user", "ubuntu", "--login"]
 
 
 class InteractiveWebsocket(WebSocketClient):
-
  # https://stackoverflow.com/a/14693789/1154487
- ansi_escape = re.compile(r'\x1B(?:[@-Z\\-_]|\[[0-?]*[ -/]*[@-~])')
+ ansi_escape = re.compile(r"\x1B(?:[@-Z\\-_]|\[[0-?]*[ -/]*[@-~])")
 
  def __init__(self, *args, **kwargs):
  super().__init__(*args, **kwargs)
@@ -54,7 +53,8 @@ def received_message(self, message):
  self.close()
  if self.verbose:
  raw_msg = self.ansi_escape.sub(
- '', message.data.decode('utf-8', errors='ignore'))
+ "", message.data.decode("utf-8", errors="ignore")
+ )
  logger.trace(raw_msg.rstrip())
  with self.stdout_lock:
  self.stdout_data += message.data
@@ -69,47 +69,50 @@ def expect(self, data, timeout=0):
  if type(data) != str:
  check = data.search(self.stdout_data)
  else:
- check = data.encode('utf-8') in self.stdout_data
+ check = data.encode("utf-8") in self.stdout_data
  if check:
  with self.stdout_lock:
  if type(data) != str:
  self.stdout_data = data.split(self.stdout_data)
  else:
  self.stdout_data = self.stdout_data.split(
- data.encode('utf-8'), maxsplit=1)[-1]
+ data.encode("utf-8"), maxsplit=1
+ )[-1]
  not_found = False
  if timeout and time.time() > start_time + timeout:
  logger.warning(
  "'{}' not found! Timeout is reached (set to {})",
- data, timeout)
+ data,
+ timeout,
+ )
  raise TimeoutError
  return not_found is False
 
  def select_test_plan(self, data, timeout=0):
  if not self._lookup_by_id:
- self.send(('i' + keys.KEY_HOME).encode('utf-8'), binary=True)
+ self.send(("i" + keys.KEY_HOME).encode("utf-8"), binary=True)
  self._lookup_by_id = True
  else:
- self.send(keys.KEY_HOME.encode('utf-8'), binary=True)
+ self.send(keys.KEY_HOME.encode("utf-8"), binary=True)
  not_found = True
  max_attemps = 10
  attempt = 0
  still_on_first_screen = True
- old_stdout_data = b''
+ old_stdout_data = b""
  if len(data) > 67:
- data = data[:67] + ' │\r\n│ ' + data[67:]
+ data = data[:67] + " │\r\n│ " + data[67:]
  while attempt < max_attemps:
  if self._new_data and self.stdout_data:
  if old_stdout_data == self.stdout_data:
  break
- check = data.encode('utf-8') in self.stdout_data
+ check = data.encode("utf-8") in self.stdout_data
  if not check:
  self._new_data = False
  with self.stdout_lock:
  old_stdout_data = self.stdout_data
  self.stdout_data = bytearray()
  stdin_payload = keys.KEY_PAGEDOWN + keys.KEY_SPACE
- self.send(stdin_payload.encode('utf-8'), binary=True)
+ self.send(stdin_payload.encode("utf-8"), binary=True)
  still_on_first_screen = False
  attempt = 0
  else:
@@ -121,19 +124,19 @@ def select_test_plan(self, data, timeout=0):
  if not_found:
  logger.warning("test plan {} not found!", data)
  return False
- data = '(X) ' + data
+ data = "(X) " + data
  attempt = 0
  if still_on_first_screen:
- self.send(keys.KEY_PAGEDOWN.encode('utf-8'), binary=True)
+ self.send(keys.KEY_PAGEDOWN.encode("utf-8"), binary=True)
  while attempt < max_attemps:
  if self._new_data and self.stdout_data:
- check = data.encode('utf-8') in self.stdout_data
+ check = data.encode("utf-8") in self.stdout_data
  if not check:
  self._new_data = False
  with self.stdout_lock:
  self.stdout_data = bytearray()
  stdin_payload = keys.KEY_UP + keys.KEY_SPACE
- self.send(stdin_payload.encode('utf-8'), binary=True)
+ self.send(stdin_payload.encode("utf-8"), binary=True)
  attempt = 0
  else:
  not_found = False
@@ -146,7 +149,7 @@ def select_test_plan(self, data, timeout=0):
  return not_found is False
 
  def send_signal(self, signal):
- self.ctl.send(json.dumps({'command': 'signal', 'signal': signal}))
+ self.ctl.send(json.dumps({"command": "signal", "signal": signal}))
 
  @property
  def container(self):
@@ -174,17 +177,18 @@ def verbose(self, verbose):
 
 
 def env_wrapper(env):
- env_cmd = ['env']
+ env_cmd = ["env"]
  env.update(base_env)
  env_cmd += [
  "{key}={value}".format(key=key, value=value)
- for key, value in sorted(env.items())]
+ for key, value in sorted(env.items())
+ ]
  return env_cmd
 
 
 def timeout_wrapper(timeout):
  if timeout:
- return ['timeout', '--signal=KILL', str(timeout)]
+ return ["timeout", "--signal=KILL", str(timeout)]
  else:
  return []
 
@@ -193,13 +197,14 @@ def interactive_execute(container, cmd, env={}, verbose=False, timeout=0):
  if verbose:
  logger.trace(cmd)
  ws_urls = container.raw_interactive_execute(
- login_shell + env_wrapper(env) + shlex.split(cmd))
+ login_shell + env_wrapper(env) + shlex.split(cmd)
+ )
  base_websocket_url = container.client.websocket_url
  ctl = WebSocketClient(base_websocket_url)
- ctl.resource = ws_urls['control']
+ ctl.resource = ws_urls["control"]
  ctl.connect()
  pts = InteractiveWebsocket(base_websocket_url)
- pts.resource = ws_urls['ws']
+ pts.resource = ws_urls["ws"]
  pts.verbose = verbose
  pts.container = container
  pts.ctl = ctl
@@ -208,34 +213,44 @@ def interactive_execute(container, cmd, env={}, verbose=False, timeout=0):
 
 
 def run_or_raise(container, cmd, env={}, verbose=False, timeout=0):
- stdout_data = ''
- stderr_data = ''
+ stdout_data = []
+ stderr_data = []
+ # Full cronological stdout/err output
+ outdata_full = []
 
  def on_stdout(msg):
- nonlocal stdout_data
- stdout_data += msg
+ nonlocal stdout_data, outdata_full
+ stdout_data.append(msg)
+ outdata_full.append(msg)
  logger.trace(msg.rstrip())
 
  def on_stderr(msg):
- nonlocal stderr_data
- stderr_data += msg
+ nonlocal stderr_data, outdata_full
+ stderr_data.append(msg)
+ outdata_full.append(msg)
  logger.trace(msg.rstrip())
 
  if verbose:
  logger.trace(cmd)
  res = container.execute(
- login_shell + env_wrapper(env) + timeout_wrapper(timeout)
+ login_shell
+ + env_wrapper(env)
+ + timeout_wrapper(timeout)
  + shlex.split(cmd), # noqa 503
- stdout_handler=on_stdout if verbose else None,
- stderr_handler=on_stderr if verbose else None,
- stdin_payload=open(__file__))
+ stdout_handler=on_stdout,
+ stderr_handler=on_stderr,
+ stdin_payload=open(__file__),
+ )
  if timeout and res.exit_code == 137:
  logger.warning("{} Timeout is reached (set to {})", cmd, timeout)
  raise TimeoutError
  elif res.exit_code:
  msg = "Failed to run command in the container! Command: \n"
- msg += cmd + ' ' + res.stderr
+ msg += cmd + " " + res.stderr
  # raise SystemExit(msg)
- if verbose:
- return (ExecuteResult(res.exit_code, stdout_data, stderr_data))
- return res
+ return ExecuteResult(
+ res.exit_code,
+ "".join(stdout_data),
+ "".join(stderr_data),
+ "".join(outdata_full),
+ )

metabox/metabox/core/runner.py

@@ -35,7 +35,6 @@
 class Runner:
  """Metabox scenario discovery and runner."""
 
-
  def __init__(self, args):
  self.args = args
  # logging
@@ -135,15 +134,22 @@ def setup(self):
  scenarios_modes_origins = (
  (scenario_cls, mode, origin)
  for scenario_cls in self.scenarios
- for (mode, origin) in product(scenario_cls.modes, scenario_cls.origins)
+ for (mode, origin) in product(
+ scenario_cls.modes, scenario_cls.origins
+ )
  )
  for scenario_cls, mode, origin in scenarios_modes_origins:
  if mode not in self.config:
- logger.debug("Skipping a scenario: [{}] {}", mode, scenario_cls.name)
+ logger.debug(
+ "Skipping a scenario: [{}] {}", mode, scenario_cls.name
+ )
  continue
  if origin != self.config[mode]["origin"]:
  logger.debug(
- "Skipping a scenario: [{}][{}] {}", mode, origin, scenario_cls.name
+ "Skipping a scenario: [{}][{}] {}",
+ mode,
+ origin,
+ scenario_cls.name,
  )
  continue
  scn_config = scenario_cls.config_override
@@ -183,13 +189,17 @@ def setup(self):
  raise ValueError("Unknown mode {}".format(mode))
  for args, kwargs in releases:
  logger.debug(
- "Adding scenario: [{}][{}] {}", mode, origin, scenario_cls.name
+ "Adding scenario: [{}][{}] {}",
+ mode,
+ origin,
+ scenario_cls.name,
  )
  self.scn_variants.append(scenario_cls(*args, **kwargs))
  if self.args.tags or self.args.exclude_tags:
  if self.args.tags:
  logger.info(
- "Including scenario tag(s): %s" % ", ".join(sorted(self.args.tags))
+ "Including scenario tag(s): %s"
+ % ", ".join(sorted(self.args.tags))
  )
  if self.args.exclude_tags:
  logger.info(
@@ -215,7 +225,9 @@ def _load(self, mode, release_alias):
  config = self.config[mode].copy()
  config["alias"] = release_alias
  config["role"] = mode
- return self.machine_provider.get_machine_by_config(MachineConfig(mode, config))
+ return self.machine_provider.get_machine_by_config(
+ MachineConfig(mode, config)
+ )
 
  def _get_scenario_description(self, scn):
  scenario_description_fmt = "[{mode}][{release_version}] {name}"
@@ -256,12 +268,17 @@ def run(self):
 
  scenario_description = self._get_scenario_description(scn)
  logger.info(
- "Starting scenario ({}/{}): {}".format(idx, total, scenario_description)
+ "Starting scenario ({}/{}): {}".format(
+ idx, total, scenario_description
+ )
  )
  scn.run()
  if not scn.has_passed():
  self.failed = True
  logger.error(scenario_description + " scenario has failed.")
+ logger.error(
+ "Scenario output:\n" + scn.get_output_streams().strip()
+ )
  if self.hold_on_fail:
  if scn.mode == "remote":
  msg = (
@@ -288,9 +305,7 @@ def run(self):
  timeTaken = stopTime - startTime
  print("-" * 80)
  form = "scenario" if total == 1 else "scenarios"
- status = "Ran {} {} in {:.3f}s".format(
- total, form, timeTaken
- )
+ status = "Ran {} {} in {:.3f}s".format(total, form, timeTaken)
  if self.wasSuccessful():
  logger.success(status)
  else: