fix(regtests): Colored per-instance log (#1971)

* fix(regtests): Colored per-instance log

---------

Signed-off-by: Vladislav Oleshko <vlad@dragonflydb.io>

.github/actions/regression-tests/action.yml

@@ -36,7 +36,7 @@ runs:
         export DRAGONFLY_PATH="${GITHUB_WORKSPACE}/${{inputs.build-folder-name}}/${{inputs.dfly-executable}}"
         export UBSAN_OPTIONS=print_stacktrace=1:halt_on_error=1 # to crash on errors
 
-        pytest -m "${{inputs.filter}}" --json-report --json-report-file=report.json -svr dragonfly --ignore=dragonfly/replication_test.py
+        pytest -m "${{inputs.filter}}" --json-report --json-report-file=report.json dragonfly --ignore=dragonfly/replication_test.py --log-cli-level=INFO
 
     - name: Run PyTests replication test
       if: ${{ inputs.run-only-on-ubuntu-latest == 'false' || matrix.runner  == 'ubuntu-latest' }}
@@ -47,8 +47,8 @@ runs:
         # used by PyTests
         export DRAGONFLY_PATH="${GITHUB_WORKSPACE}/${{inputs.build-folder-name}}/${{inputs.dfly-executable}}"
 
-        pytest -m "${{inputs.filter}}" --json-report --json-report-file=rep1_report.json -sv dragonfly/replication_test.py --df alsologtostderr --df enable_multi_shard_sync=true
+        pytest -m "${{inputs.filter}}" --json-report --json-report-file=rep1_report.json dragonfly/replication_test.py --df alsologtostderr --df enable_multi_shard_sync=true
-        pytest -m "${{inputs.filter}}" --json-report --json-report-file=rep2_report.json -sv dragonfly/replication_test.py --df alsologtostderr --df enable_multi_shard_sync=false
+        pytest -m "${{inputs.filter}}" --json-report --json-report-file=rep2_report.json dragonfly/replication_test.py --df alsologtostderr --df enable_multi_shard_sync=false
 
     - name: Send notification on failure
       if: failure() && github.ref == 'refs/heads/main'

tests/dragonfly/conftest.py

@@ -91,6 +91,7 @@ def df_factory(request, tmp_dir, test_env) -> DflyInstanceFactory:
         path=path,
         cwd=tmp_dir,
         gdb=request.config.getoption("--gdb"),
+        buffered_out=request.config.getoption("--buffered-output"),
         args=parse_args(request.config.getoption("--df")),
         existing_port=int(existing) if existing else None,
         existing_admin_port=int(existing_admin) if existing_admin else None,
@@ -205,17 +206,14 @@ async def async_client(async_pool):
 
 
 def pytest_addoption(parser):
-    """
-    Custom pytest options:
-        --gdb - start all instances inside gdb
-        --df arg - pass arg to all instances, can be used multiple times
-        --log-seeder file - to log commands of last seeder run
-        --existing-port - to provide a port to an existing process instead of starting a new instance
-        --existing-admin-port - to provide an admin port to an existing process instead of starting a new instance
-        --rand-seed - to set the global random seed
-    """
     parser.addoption("--gdb", action="store_true", default=False, help="Run instances in gdb")
     parser.addoption("--df", action="append", default=[], help="Add arguments to dragonfly")
+    parser.addoption(
+        "--buffered-output",
+        action="store_true",
+        default=False,
+        help="Makes instance output buffered, grouping it together",
+    )
     parser.addoption(
         "--log-seeder", action="store", default=None, help="Store last generator commands in file"
     )
@@ -237,7 +235,6 @@ def pytest_addoption(parser):
         default=None,
         help="Provide an admin port to the existing process for the test",
     )
-
     parser.addoption(
         "--existing-mc-port",
         action="store",

tests/dragonfly/instance.py

@@ -19,6 +19,7 @@ class DflyParams:
     path: str
     cwd: str
     gdb: bool
+    buffered_out: bool
     args: Dict[str, Union[str, None]]
     existing_port: int
     existing_admin_port: int
@@ -26,6 +27,17 @@ class DflyParams:
     env: any
 
 
+class Colors:
+    CLEAR = "\\o33[0m"
+    COLORS = [f"\\o33[0;{i}m" for i in range(31, 37)]
+    last_color = -1
+
+    @classmethod
+    def next(clz):
+        clz.last_color = (clz.last_color + 1) % len(clz.COLORS)
+        return clz.COLORS[clz.last_color]
+
+
 class DflyStartException(Exception):
     pass
 
@@ -104,8 +116,17 @@ class DflyInstance:
                 time.sleep(0.05)
         else:
             raise DflyStartException("Process didn't start listening on port in time")
+
         self.log_files = self.get_logs_from_psutil()
 
+        # Remove first 6 lines - our default header with log locations (as it carries no useful information)
+        # Next, replace log-level + date with port and colored arrow
+        sed_format = f"1,6d;s/[^ ]*/{self.port}{Colors.next()}➜{Colors.CLEAR}/"
+        sed_cmd = ["sed", "-u", "-e", sed_format]
+        if self.params.buffered_out:
+            sed_cmd.remove("-u")
+        subprocess.Popen(sed_cmd, stdin=self.proc.stdout)
+
     def stop(self, kill=False):
         proc, self.proc = self.proc, None
         if proc is None:
@@ -130,14 +151,17 @@ class DflyInstance:
         if self.dynamic_port:
             self._port = None
 
-        base_args = ["--use_zset_tree"]
+        base_args = []
         all_args = self.format_args(self.args) + base_args
         logging.debug(f"Starting instance with arguments {all_args} from {self.params.path}")
 
         run_cmd = [self.params.path, *all_args]
         if self.params.gdb:
             run_cmd = ["gdb", "--ex", "r", "--args"] + run_cmd
-        self.proc = subprocess.Popen(run_cmd, cwd=self.params.cwd)
+
+        self.proc = subprocess.Popen(
+            run_cmd, cwd=self.params.cwd, stdout=subprocess.PIPE, stderr=subprocess.STDOUT
+        )
 
     def _check_status(self):
         if not self.params.existing_port:
@@ -244,6 +268,8 @@ class DflyInstanceFactory:
     def create(self, **kwargs) -> DflyInstance:
         args = {**self.args, **kwargs}
         args.setdefault("dbfilename", "")
+        args.setdefault("use_zset_tree", None)
+
         for k, v in args.items():
             args[k] = v.format(**self.params.env) if isinstance(v, str) else v
 

tests/dragonfly/utility.py

@@ -436,7 +436,6 @@ class DflySeeder:
         self.gen.key_cnt_target = key_cnt
 
     async def _capture_db(self, port, target_db, keys):
-        eprint(f"Capture data on port {port}, db {target_db}")
         client = aioredis.Redis(port=port, db=target_db)
         capture = DataCapture(await self._capture_entries(client, keys))
         await client.connection_pool.disconnect()