Implement the new test check watchdog

[happz]

Pull Request Checklist

• implement the feature
• extend the test coverage
• mention the version
• include a release note

[happz]

A building block for #1523 - it needs more testing, I started a test but it's not enough, and I need to get more input from users and owners of existing tools to do things correctly. And documentation, of course.

[lukaszachy]

Just stating obvious: Add 'nmap-ncat' (where 'nc' belongs) as a Require to tmt.spec. It is not guaranteed to be on the system.

[happz]

Just stating obvious: Add 'nmap-ncat' (where 'nc' belongs) as a Require to tmt.spec. It is not guaranteed to be on the system.

Good point, even though I'm not anywhere near even thinking about requirements, I would definitely forget to do add it :)

[lukaszachy]

Should we 'hide' watchdog messages (via log topic) from the log.txt?
Or at least keep just the [watchdog] Received successful response to SSH ping. and have the rest under separate topic.

Otherwise the log.txt will be full of

17:16:05 [watchdog]         checking SSH port
17:16:05 [watchdog]         Run command: nc -zv 127.0.0.1 10053
17:16:05 [watchdog]         environment
17:16:05 [watchdog]         err: Ncat: Version 7.93 ( https://nmap.org/ncat )
17:16:05 [watchdog]         err: Ncat: Connected to 127.0.0.1:10053.
17:16:05 [watchdog]         err: Ncat: 0 bytes sent, 0 bytes received in 0.01 seconds.
17:16:05 [watchdog]         Received successful response to SSH ping.
17:16:05 [watchdog]         failed 0 of 3 allowed

[thrix]

some small thing from me

[happz]

Should we 'hide' watchdog messages (via log topic) from the log.txt? Or at least keep just the [watchdog] Received successful response to SSH ping. and have the rest under separate topic.

Otherwise the log.txt will be full of

17:16:05 [watchdog]         checking SSH port
17:16:05 [watchdog]         Run command: nc -zv 127.0.0.1 10053
17:16:05 [watchdog]         environment
17:16:05 [watchdog]         err: Ncat: Version 7.93 ( https://nmap.org/ncat )
17:16:05 [watchdog]         err: Ncat: Connected to 127.0.0.1:10053.
17:16:05 [watchdog]         err: Ncat: 0 bytes sent, 0 bytes received in 0.01 seconds.
17:16:05 [watchdog]         Received successful response to SSH ping.
17:16:05 [watchdog]         failed 0 of 3 allowed

Tough question. I for one do not care that much about content of the log file, there's already plenty of stuff that makes it less usable for me, namely output of tests. So I'm not that worried. But I get the point, and there might be ways how to reduce it. E.g. those three lines from stderr are completely useless, interesting only when nc fails - we don't have "skip logging output unless command failed" flag for Command.run(), but maybe we should get one. No idea what produced environment, maybe some leftover or empty env, yet the header is still logged. That would cut away half of the lines listed above.

Not sure I'd like to block this PR on reducing verbosity, but I'd be very happy to help reduce it.

[thrix]

LGTM

[happz]

Should we 'hide' watchdog messages (via log topic) from the log.txt? Or at least keep just the [watchdog] Received successful response to SSH ping. and have the rest under separate topic.
Otherwise the log.txt will be full of

17:16:05 [watchdog]         checking SSH port
17:16:05 [watchdog]         Run command: nc -zv 127.0.0.1 10053
17:16:05 [watchdog]         environment
17:16:05 [watchdog]         err: Ncat: Version 7.93 ( https://nmap.org/ncat )
17:16:05 [watchdog]         err: Ncat: Connected to 127.0.0.1:10053.
17:16:05 [watchdog]         err: Ncat: 0 bytes sent, 0 bytes received in 0.01 seconds.
17:16:05 [watchdog]         Received successful response to SSH ping.
17:16:05 [watchdog]         failed 0 of 3 allowed

Tough question. I for one do not care that much about content of the log file, there's already plenty of stuff that makes it less usable for me, namely output of tests. So I'm not that worried. But I get the point, and there might be ways how to reduce it. E.g. those three lines from stderr are completely useless, interesting only when nc fails - we don't have "skip logging output unless command failed" flag for Command.run(), but maybe we should get one. No idea what produced environment, maybe some leftover or empty env, yet the header is still logged. That would cut away half of the lines listed above.

Not sure I'd like to block this PR on reducing verbosity, but I'd be very happy to help reduce it.

@lukaszachy would something like this make things better?

diff --git a/tmt/checks/watchdog.py b/tmt/checks/watchdog.py
index 00c2cb7b..9815d19d 100644
--- a/tmt/checks/watchdog.py
+++ b/tmt/checks/watchdog.py
@@ -200,12 +200,7 @@ class WatchdogCheck(Check):
 
             guest_context.ping_failures = 0
 
-            report_progress(
-                log,
-                'ping',
-                report,
-                command_output=ping_output
-                )
+            report_progress(log, 'ping', report)
 
         def _handle_output(ping_output: str) -> None:
             """ Process ``ping`` output and decide on its outcome """
@@ -243,7 +238,8 @@ class WatchdogCheck(Check):
                                        '-c',
                                        str(self.ping_packets),
                                        invocation.guest.primary_address) .run(cwd=Path.cwd(),
-                                                                              logger=logger)
+                                                                              logger=logger,
+                                                                              stream_output=False)
 
             _handle_output(output.stdout or '')
 
@@ -313,12 +309,7 @@ class WatchdogCheck(Check):
 
             guest_context.ssh_ping_failures = 0
 
-            report_progress(
-                log,
-                'ssh-ping',
-                report,
-                command_output=ncat_output
-                )
+            report_progress(log, 'ssh-ping', report)
 
         try:
             assert invocation.guest.primary_address is not None  # narrow type
@@ -327,7 +318,8 @@ class WatchdogCheck(Check):
                                        '-zv',
                                        invocation.guest.primary_address,
                                        str(invocation.guest.port or 22)) .run(cwd=Path.cwd(),
-                                                                              logger=logger)
+                                                                              logger=logger,
+                                                                              stream_output=False)
 
             _success(output.stderr or '')
 
diff --git a/tmt/utils.py b/tmt/utils.py
index 38015b11..cc9c82ca 100644
--- a/tmt/utils.py
+++ b/tmt/utils.py
@@ -965,7 +965,8 @@ class StreamLogger(Thread):
             *,
             stream: Optional[IO[bytes]] = None,
             logger: Optional[tmt.log.LoggingFunction] = None,
-            click_context: Optional[click.Context] = None) -> None:
+            click_context: Optional[click.Context] = None,
+            stream_output: bool = True) -> None:
         super().__init__(daemon=True)
 
         self.stream = stream
@@ -973,6 +974,7 @@ class StreamLogger(Thread):
         self.log_header = log_header
         self.logger = logger
         self.click_context = click_context
+        self.stream_output = stream_output
 
     def run(self) -> None:
         if self.stream is None:
@@ -986,7 +988,7 @@ class StreamLogger(Thread):
 
         for _line in self.stream:
             line = _line.decode('utf-8', errors='replace')
-            if line != '':
+            if line != '' and self.stream_output:
                 self.logger(
                     self.log_header,
                     line.rstrip('\n'),
@@ -1155,6 +1157,7 @@ class Command:
             friendly_command: Optional[str] = None,
             log: Optional[tmt.log.LoggingFunction] = None,
             silent: bool = False,
+            stream_output: bool = True,
             caller: Optional['Common'] = None,
             logger: tmt.log.Logger) -> CommandOutput:
         """
@@ -1277,7 +1280,8 @@ class Command:
                 'out',
                 stream=process.stdout,
                 logger=output_logger,
-                click_context=click.get_current_context(silent=True))
+                click_context=click.get_current_context(silent=True),
+                stream_output=stream_output)
 
             if join:
                 stderr_logger: StreamLogger = UnusedStreamLogger('err')
@@ -1287,7 +1291,8 @@ class Command:
                     'err',
                     stream=process.stderr,
                     logger=output_logger,
-                    click_context=click.get_current_context(silent=True))
+                    click_context=click.get_current_context(silent=True),
+                    stream_output=stream_output)
 
             stdout_logger.start()
             stderr_logger.start()
@@ -1347,6 +1352,15 @@ class Command:
         if process.returncode != 0:
             logger.debug(f"Command returned '{process.returncode}'.", level=3)
 
+            if not stream_output:
+                if stdout is not None:
+                    for line in stdout.splitlines():
+                        output_logger('out', value=line, color='yellow', level=3)
+
+                if stderr is not None:
+                    for line in stderr.splitlines():
+                        output_logger('err', value=line, color='yellow', level=3)
+
             raise RunError(
                 f"Command '{friendly_command or str(self)}' returned {process.returncode}.",
                 self,

[lukaszachy]

@happz Much better. thanks.

[happz]

@happz Much better. thanks.

Ok, I’ll make a PR out of it

[psss]

Looks very nice! Thanks for implementing this. Added just a few comments plus:

• would be good to mention this new feature in the release notes
• shall we update the check json schema as well with the new keys?

[happz]

Looks very nice! Thanks for implementing this. Added just a few comments plus:

Right, I forgot about these two:

• would be good to mention this new feature in the release notes

Added in 410efea.

• shall we update the check json schema as well with the new keys?

Yes, but it won't be that simple, I forgot we need to turn this part of the specification to load schema for plugins. It's lucky accident that avc and dmesg contain no extra keys, but that's not true for watchdog and we will need same functionality we have for steps and their plugins :/

[psss]

Yes, but it won't be that simple, I forgot we need to turn this part of the specification to load schema for plugins. It's lucky accident that avc and dmesg contain no extra keys, but that's not true for watchdog and we will need same functionality we have for steps and their plugins :/

Understood. So, I guess, we won't block this pull request on that.

[psss]

Thanks for the changes. I just fixed a typo in cd22384 plus added the provision-only tag to the avc test as it needs root so it should not be run by default.

[happz]

Thanks for the changes. I just fixed a typo in cd22384 plus added the provision-only tag to the avc test as it needs root so it should not be run by default.

Ture, it does need root-level access, but it seems to be running fine in our tests so far, e.g. https://artifacts.dev.testing-farm.io/be3c3e72-d3b6-492d-b34b-bfc46cf3977e/work-basicvfupy5_c/plans/features/basic/execute/data/guest/default-0/tests/test/check/avc-33/output.txt

[psss]

Ture, it does need root-level access, but it seems to be running fine in our tests so far

Yeah, but that is an unnecessary duplication as it is already running under /plans/provision/local like here. I think it's good if the regular set of sets (e.g. non-provision-specific) can be run under a regular user for quickly sanity checking from contributor laptop. I believe this one was the last leftover.

[happz]

Ture, it does need root-level access, but it seems to be running fine in our tests so far

Yeah, but that is an unnecessary duplication as it is already running under /plans/provision/local like here. I think it's good if the regular set of sets (e.g. non-provision-specific) can be run under a regular user for quickly sanity checking from contributor laptop. I believe this one was the last leftover.

Aha, I wasn't aware there's /provision/local running already. Makes sense then, good.

[happz]

@happz Much better. thanks.

A follow-up PR: #2751