Reformat and redesign the recording output.

## Changes

  - Formats command events into properly related JSON.
  - Properly record status responses (ok, warning, errors).
  - Record API requests as a chain related to each command.
  - Record the raw command issued, the actual command executed, and the command filter applied (if any).
  - Moves comment handling to OutputManager.
  - Consolidates stop_recording and save_recording.
  - Renamed some variables and methods for consistency.

## Issues

  - We want timestamps in the logs, but they will differ for CI runs and thus fail. There needs to be a configuration option to disable logging timestamps...
  - The stack details for errors and warnings is bugged. See unioslo#185
  - We buffer the entire recording blob in memory until we stop recording (or we exit). This is to ensure valid JSON for the output, as writing (valid) JSON streams to a file is non-trivial. A solution is to write after each command, reload the file and append the data, then write again. This may or may not be a good idea, and it would look something like:

```python
            existing_data = []

            # Read the existing data from the file
            try:
                with open(self._filename, "r") as rec_file:
                    existing_data = json.load(rec_file)
            except (FileNotFoundError, json.JSONDecodeError):
                pass

            existing_data.append(recording_entry)

            # Write the updated data back to the file
            with open(self._filename, "w") as rec_file:
                json.dump(existing_data, rec_file, indent=2)
```

## Failing tests

As this completely redefines the recording output, tests fail miserably.

mreg_cli/cli.py

@@ -147,7 +147,7 @@ def parse(self, command: str) -> None:
 
         except CliExit:
             # If we have active recordings going on, save them before exiting
-            OutputManager().save_recording()
+            OutputManager().stop_recording()
             sys.exit(0)
 
         else:
@@ -212,7 +212,6 @@ def complete(self, cur, words):
 
     def process_command_line(self, line: str) -> None:
         """Process a line containing a command."""
-        line = remove_comments(line)
         # OutputManager is a singleton class so we
         # need to clear it before each command.
         output = OutputManager()
@@ -245,7 +244,7 @@ def _start_recording(args) -> None:
 
 def _stop_recording(args):
     """Stop recording commands and output to the given file."""
-    OutputManager().save_recording()
+    OutputManager().stop_recording()
 
 
 # Always need a quit command
@@ -339,7 +338,7 @@ def source(files: List[str], ignore_errors: bool, verbose: bool) -> Generator[st
                                 )
                             )
                         )
-                        OutputManager().record_extra_output(f"{filename}: Error on line {i + 1}")
+                        OutputManager().add_error(f"{filename}: Error on line {i + 1}")
                         if not ignore_errors:
                             return
         except FileNotFoundError:

mreg_cli/log.py

@@ -42,14 +42,10 @@ def cli_error(
         msg,
     )
     _write_log(s)
+    msg = "ERROR: {}: {}".format(pre, msg)
+    OutputManager().add_error(msg)
     if raise_exception:
         # A simplified message for console
-        msg = "ERROR: {}: {}".format(pre, msg)
-        manager = OutputManager()
-        if manager.is_recording():
-            # If recording traffic, also record the console output
-            manager.record_extra_output(msg)
-        # Raise the exception
         raise exception(msg)
     return None
 
@@ -66,13 +62,10 @@ def cli_warning(
         msg,
     )
     _write_log(s)
+    msg = "WARNING: {}: {}".format(pre, msg)
+    OutputManager().add_warning(msg)
     if raise_exception:
         # A simplified message for console
-        msg = "WARNING: {}: {}".format(pre, msg)
-        manager = OutputManager()
-        if manager.is_recording():
-            # If recording traffic, also record the console output
-            manager.record_extra_output(msg)
         raise exception(msg)
     return None
 
@@ -87,11 +80,8 @@ def cli_info(msg: str, print_msg: bool = False) -> None:
         msg,
     )
     _write_log(s)
+    msg = "OK: {}: {}".format(pre, msg)
+    OutputManager().add_ok(msg)
     if print_msg:
         # A simplified message for console
-        msg = "OK: {}: {}".format(pre, msg)
         print(msg)
-        manager = OutputManager()
-        if manager.is_recording():
-            # If recording traffic, also record the console output
-            manager.record_extra_output(msg)

mreg_cli/outputmanager.py

@@ -6,6 +6,7 @@
 """
 
 import atexit
+import datetime
 import json
 import os
 import re
@@ -114,26 +115,32 @@ class OutputManager:
     def __new__(cls):
         if cls._instance is None:
             cls._instance = super().__new__(cls)
-
-            # Recording related attributes. These must come first as they may
-            # be encountered when calling clear(). Note that these attributes are
-            # not reset between commands, which is why they are not themselves
-            # manipulated in clear().
-            cls._recording: bool = False
-            cls._filename: str = None
-            cls._recorded_data: List[str] = []
-
             cls._instance.clear()
+            cls._instance.clear_recording()
 
         return cls._instance
 
     def clear(self) -> None:
         """Clears the object."""
-        self._lines = []
+        self._output: [str] = []
         self._filter_re = None
-        self._negate = False
-        self._command = None
-        self.command = None
+        self._filter_negate = False
+        self._command_executed = None
+        self._command_issued = None
+
+        self._ok: [str] = []  # This is typically commands that went OK but returned no content
+        self._warnings: [str] = []
+        self._errors: [str] = []
+
+        self._api_requests: [str] = []
+
+        self._exceptions: [Exception] = []
+
+    def clear_recording(self) -> None:
+        """Clears the recording data."""
+        self._recorded_data = []
+        self._recording = False
+        self._filename = None
 
     def start_recording(self, filename: str) -> None:
         """Declare intent to start recording to the given filename.
@@ -152,25 +159,14 @@ def start_recording(self, filename: str) -> None:
         self._recording = True
         self._filename = filename
 
-        atexit.register(self.save_recording)
+        atexit.register(self.stop_recording)
         try:
             os.remove(filename)
         except OSError:
             pass
 
     def stop_recording(self) -> None:
-        """Declare intent to stop recording.
-
-        This will delete the recorded data if it has not been saved.
-
-        Note: This does not save the recording, use save_recording() for that.
-        """
-        self._recorded_data = []
-        self._recording = False
-        self._filename = None
-
-    def save_recording(self) -> None:
-        """Save the recording to the file.
+        """Stop the recording and save the recording to the file.
 
         Returns gracefully if recording is not active.
         """
@@ -180,7 +176,47 @@ def save_recording(self) -> None:
         with open(self._filename, "w") as rec_file:
             json.dump(self._recorded_data, rec_file, indent=2)
 
-        self.stop_recording()
+        self.clear_recording()
+
+    def create_recording_entry(self) -> Dict[str, Any]:
+        """Create a recording entry."""
+
+        return {
+            "command": self._command_executed,
+            "command_filter": self._filter_re.pattern if self._filter_re else None,
+            "command_issued": self._command_issued,
+            "ok": self._ok,
+            "warning": self._warnings,
+            "error": self._errors,
+            "output": self.filtered_output(),
+            # We probably want timestamps in the recording, but we need to disable
+            # this for CI runs as they will obviously fail if the timestamp changes.
+            # TODO: Make this configurable
+            #            "timestamp": datetime.datetime.now().isoformat(sep=" ", timespec="seconds"),
+            #            "timestamp_as_epoch": int(datetime.datetime.now().timestamp()),
+            "api_requests": self._api_requests,
+        }
+
+    def add_warning(self, msg: str) -> None:
+        """Add a warning event to the output.
+
+        :param msg: The warning message.
+        """
+        self._warnings.append(msg)
+
+    def add_error(self, msg: str) -> None:
+        """Add an error event to the output.
+
+        :param msg: The error message.
+        """
+        self._errors.append(msg)
+
+    def add_ok(self, msg: str) -> None:
+        """Add an OK event to the output.
+
+        :param msg: The ok message.
+        """
+        self._ok.append(msg)
 
     def is_recording(self) -> bool:
         """Returns True if recording is active."""
@@ -195,45 +231,18 @@ def recording_filename(self) -> Optional[str]:
             return None
         return self._filename
 
-    def record_command(self, command: str) -> None:
-        """Record a command, if recording is active.
-
-        :param command: The command to record.
-        """
-        if not self.is_recording() or not command:
-            return
-
-        # Do not record commands starting with any of the commands in
-        # COMMANDS_NOT_TO_RECORD
-        if any(command.startswith(cmd) for cmd in self.COMMANDS_NOT_TO_RECORD):
-            return
-
-        # Do not record empty commands
-        if command and command != "\n":
-            self._recorded_data.append({"command": command})
-
-    def record_extra_output(self, output: str) -> None:
-        """Record extra output, if recording is active.
-
-        :param output: The output to record.
-        """
-        if not self.is_recording() or not output:
-            return
-
-        self._recorded_data.append({"output": output})
-
     def record_output(self) -> None:
         """Record the output, if recording is active."""
-        # Don't record if we're not recording, and don't record
-        # output as the  empty output
-        if not self.is_recording() or not self._recorded_data:
+        command = self._command_executed
+        # Note that we may record commands without output as they may have
+        # warnings or errors.
+        if not command or not self.is_recording():
             return
 
-        if not self.lines():
+        if any(command.startswith(cmd) for cmd in self.COMMANDS_NOT_TO_RECORD):
             return
 
-        output = "\n".join(self.lines())
-        self._recorded_data.append({"output": output})
+        self._recorded_data.append(self.create_recording_entry())
 
     def record_request(
         self, method: str, url: str, params: str, data: Dict[str, Any], result: requests.Response
@@ -257,11 +266,11 @@ def record_request(
             # false-like values (0, False, etc)
             if s != "":
                 ret_dict["response"] = s
-        self._recorded_data.append(ret_dict)
+        self._api_requests.append(ret_dict)
 
     def has_output(self) -> bool:
         """Returns True if there is output to display."""
-        return len(self._lines) > 0
+        return len(self._output) > 0
 
     def from_command(self, command: str) -> str:
         """Adds the command that generated the output.
@@ -272,16 +281,18 @@ def from_command(self, command: str) -> str:
         :raises CliError: If the command is invalid.
         :return: The cleaned command, devoid of filters and other noise.
         """
-        self._command, self._filter_re, self._negate = self.get_filter(command)
-        self.record_command(command)
-        return self._command
+        self._command_issued = command.rstrip()
+        self._command_executed, self._filter_re, self._filter_negate = self.get_filter(
+            remove_comments(self._command_issued)
+        )
+        return self._command_executed
 
     def add_line(self, line: str) -> None:
         """Adds a line to the output.
 
         :param line: The line to add.
         """
-        self._lines.append(line)
+        self._output.append(line)
 
     def add_formatted_line(self, key: str, value: str, padding: int = 14) -> None:
         """Formats and adds a key-value pair as a line.
@@ -373,7 +384,7 @@ def add_formatted_table(
         for d in data:
             self.add_line(raw_format.format(*[d[key] for key in keys]))
 
-    def lines(self) -> List[str]:
+    def filtered_output(self) -> List[str]:
         """Return the lines of output.
 
         If the command is set, and it has a filter, the lines will
@@ -382,23 +393,23 @@ def lines(self) -> List[str]:
         Note: This filtering is not cached, so repeated calls will
         re-filter the output (to the same result, presumably).
         """
-        lines = self._lines
+        lines = self._output
         filter_re = self._filter_re
 
         if filter_re is None:
             return lines
 
-        if self._negate:
+        if self._filter_negate:
             return [line for line in lines if not filter_re.search(line)]
 
         return [line for line in lines if filter_re.search(line)]
 
     def render(self) -> None:
         """Prints the output to stdout, and records it if recording is active."""
         self.record_output()
-        for line in self.lines():
+        for line in self.filtered_output():
             print(line)
 
     def __str__(self) -> str:
         """Returns the formatted output as a single string."""
-        return "\n".join(self._lines)
+        return "\n".join(self._output)