Timestamped gNMI message logs (#396)

* Remove not-needed debug log

* Relative Timestamp gnmi Logs

These are timestamped to help on troubleshooting delays and retries.

Author: JoseIgnacioTamayo

oc_config_validate/README.md

@@ -116,7 +116,9 @@ looking for:
            [--target_cert_as_root_ca | --root_ca_cert FILE ] \
            [--cert_chain FILE --private_key FILE]
            [-init INIT_CONFIG_FILE -xpath INIT_CONFIG_XPATH] \
-           [--verbose] [--log_gnmi] [--stop_on_error]
+           [--gnmi_set_cooldown_secs GNMI_SET_COOLDOWN_SECS] \
+           [--log_gnmi] [--stop_on_error] \
+           [--verbose]
     ```
 
     For an example:
@@ -163,13 +165,34 @@ Run `python3 -m oc_config_validate -models` to get a list of the versions (revis
 #### Timing in gNMI Sets and Gets
 
 The Target can take some time to process configurations done via gNMI Set messages. By default, `oc_config_validate` waits 10 seconds after a successful gNMI Set message.
-This time is customized with the `gnmi_set_cooldown_secs` option in the targe configuration or in a command line argument.
+This time is customized with the `gnmi_set_cooldown_secs` option in the target configuration or in a command line argument.
 
 Similarly, the Target can take some time to show the expected values in a gNMI Get message.
 Some testcases have a retry mechanism, that will repeat the gNMI Get message and comparisons (against an OC model, against an expected JSON text, or both) until it succeeds or times out.
 
 See [here](https://github.com/google/gnxi/blob/master/oc_config_validate/docs/testclasses.md) for more details.
 
+#### Timestamped Logging gNMI messages
+
+With `log_gnmi` option in the command line argument, all gNMI Messages sent and received are logged with a relative timestamp to the beginning of the test.
+
+The gNMI messages logs are in the format `[<relative_time_secs>]gNMI <Operation>(<xpath(s)>) =>|=< <[values]>`. E.g.:
+
+```
+[0.00s]gNMI Subscribe Sample(interfaces/interface[name=*]/state/oper-status) =>
+[5.00s]gNMI Subscribe Sample(interfaces/interface[name=*]/state/oper-status) <= [
+  {
+    "timestamp": 1754947845878668496, ... 
+
+INFO(testbase.py:120):[0.00s]gNMI Set Update(system/clock/config) => {'openconfig-system:timezone-name': 'Europe/Paris'}
+INFO(testbase.py:120):[2.00s]gNMI Get(system/clock/state) => 
+INFO(testbase.py:120):[2.00s]gNMI Get(system/clock/state) <= json_ietf_val: "{\"openconfig-system:timezone-name\":\"Europe/Stockholm\"}"
+```
+
+The messages are logged to the TestCase results and also to STDOUT, as INFO. 
+
+> Because the TestCase results logs are printed to STDOUT upon test failure, the gNMI messages will be seen twice in SDTOUT for failed test.
+
 ## Copyright
 
 Copyright 2022

oc_config_validate/oc_config_validate/target.py

@@ -113,7 +113,6 @@ def gNMIConnect(self):
             self.channel = grpc.insecure_channel(self.address)
         else:
             creds = self._buildCredentials()
-            logging.debug("creds: %s", creds)
             if self.host_tls_override:
                 self.channel = grpc.secure_channel(
                     self.address, creds,

oc_config_validate/oc_config_validate/testbase.py

@@ -32,6 +32,8 @@
 # Switch to enable logging of gNMI messages in the testcase logs.
 LOG_GNMI = False
 
+LOG_TIMESTAMP_PREFIX = "[%.2fs]"
+
 
 def failfast(method):
     """Wrap a test to stop upon failure."""
@@ -100,6 +102,25 @@ class TestCase(unittest.case.TestCase):
     duration_sec = 0
     start_time_sec = 0
 
+    def log_gnmi(self, formatter, *args):
+        """Optionally logs a timestamped message during a test.
+
+        The timestamp is the time since the test started, in seconds.
+
+        It logs also to STDOUT as INFO.
+
+        Args:
+            formatter: The base python string formatter.
+            *args: The formatter parameters. Allows logging messages during
+                test executions.
+        """
+        if LOG_GNMI:
+            timestamp = int(time.time() - self.start_time_sec)
+            if self.result:
+                self.result.log(LOG_TIMESTAMP_PREFIX +
+                                formatter, timestamp, *args)
+            logging.info(LOG_TIMESTAMP_PREFIX + formatter, timestamp, *args)
+
     def phony(self):
         """A phony test method to be used for testing."""
 
@@ -137,20 +158,18 @@ def gNMIGet(self, xpath: str) -> Optional[gnmi_pb2.TypedValue]:
         Returns:
             A single response value, or None if error.
         """
+        self.log_gnmi("gNMI Get(%s) => ", xpath)
         try:
             resp = self.test_target.gNMIGet(xpath)
         except Exception as err:
-            self.log("Get(%s) <= Error: %s", xpath, err)
+            self.log("gNMI Get(%s) <= Error: %s", xpath, err)
             return None
         try:
             resp_val = resp.notification[0].update[0].val
         except IndexError:
-            self.log("Get(%s) <= Bad response: %s", xpath, resp)
+            self.log("gNMI Get(%s) <= Bad response: %s", xpath, resp)
             return None
-        if LOG_GNMI:
-            msg = ("gNMI Get(%s) <= %s", xpath, resp_val)
-            self.log(*msg)
-            logging.info(*msg)
+        self.log_gnmi("gNMI Get(%s) <= %s", xpath, resp_val)
         return resp_val
 
     def gNMIGetAssertJson(self, xpath: str) -> Union[str, bytes]:
@@ -215,14 +234,11 @@ def gNMISetUpdate(self, xpath: str, value: Any) -> bool:
         Returns:
           False if the gNMI Set did not succeed.
         """
-        if LOG_GNMI:
-            msg = ("gNMI Set Update(%s) => %s", xpath, value)
-            self.log(*msg)
-            logging.info(*msg)
+        self.log_gnmi("gNMI Set Update(%s) => %s", xpath, value)
         try:
             self.test_target.gNMISetUpdate(xpath, value)
         except Exception as err:
-            self.log("Set(%s) <= Error: %s", xpath, err)
+            self.log("gNMI Set Update(%s) <= Error: %s", xpath, err)
             return False
         return True
 
@@ -238,14 +254,11 @@ def gNMISetDelete(self, xpath: str) -> bool:
         Returns:
             A single response value, or None if error.
         """
-        if LOG_GNMI:
-            msg = ("gNMI Set Delete(%s) =>", xpath)
-            self.log(*msg)
-            logging.info(*msg)
+        self.log_gnmi("gNMI Set Delete(%s) =>", xpath)
         try:
             self.test_target.gNMISetDelete(xpath)
         except Exception as err:
-            self.log("Set(%s) <= Error: %s", xpath, err)
+            self.log("gNMI Set Delete(%s) <= Error: %s", xpath, err)
             return False
         return True
 
@@ -259,14 +272,11 @@ def gNMISetReplace(self, xpath: str, value: Any) -> bool:
         Returns:
           False if the gNMI Set did not succeed.
         """
-        if LOG_GNMI:
-            msg = ("gNMI Set Replace(%s) => %s", xpath, value)
-            self.log(*msg)
-            logging.info(*msg)
+        self.log("gNMI Set Replace(%s) => %s", xpath, value)
         try:
             self.test_target.gNMISetReplace(xpath, value)
         except Exception as err:
-            self.log("Set(%s) <= Error: %s", xpath, err)
+            self.log("gNMI Set Replace(%s) <= Error: %s", xpath, err)
             return False
         return True
 
@@ -282,16 +292,15 @@ def gNMISubsOnce(self, xpaths: List[str]) -> Optional[
         Returns:
           A list of Notifications received, or None if error.
         """
+        self.log_gnmi("gNMI Subscribe Once(%s) => ", xpaths)
         try:
             resp = self.test_target.gNMISubsOnce(xpaths)
         except Exception as err:
-            self.log("SubscribeOnce(%s) <= Error: %s", xpaths, err)
+            self.log("gNMI Subscribe Once(%s) <= Error: %s", xpaths, err)
             return None
-        if LOG_GNMI:
-            msg = ("gNMI SubscribeOnce(%s) <= %s", xpaths,
-                   schema.notificationsJsonString(resp))
-            self.log(*msg)
-            logging.info(*msg)
+
+        self.log_gnmi("gNMI Subscribe Once(%s) <= %s", xpaths,
+                      schema.notificationsJsonString(resp))
         return resp
 
     def gNMISubsStreamSample(
@@ -311,17 +320,15 @@ def gNMISubsStreamSample(
         Returns:
           A list of Notifications received, or None if error.
         """
+        self.log_gnmi("gNMI Subscribe Sample(%s) =>", xpath)
         try:
             resp = self.test_target.gNMISubsStreamSample(
                 xpath, sample_interval, timeout)
         except Exception as err:
-            self.log("SubscribeStream(%s) <= Error: %s", xpath, err)
+            self.log("gNMI Subscribe Sample(%s) <= Error: %s", xpath, err)
             return None
-        if LOG_GNMI:
-            msg = ("gNMI SubscribeSample(%s) <= %s", xpath,
-                   schema.notificationsJsonString(resp))
-            self.log(*msg)
-            logging.info(*msg)
+        self.log_gnmi("gNMI Subscribe Sample(%s) <= %s", xpath,
+                      schema.notificationsJsonString(resp))
         return resp
 
     def gNMISubsStreamOnChange(
@@ -353,18 +360,15 @@ def gNMISubsStreamOnChange(
             2 Lists of gnmi_pb2.Notification objects received,
               before and after sync_response.
         """
-
+        self.log_gnmi("gNMI Subscribe OnChange(%s) =>\n", xpath)
         try:
             before, after = self.test_target.gNMISubsStreamOnChange(
                 xpath, timeout, sync_response_callback)
         except Exception as err:
-            self.log("SubscribeOnChange(%s) <= Error: %s", xpath, err)
+            self.log("gNMI Subscribe OnChange(%s) <= Error: %s", xpath, err)
             return None, None
-        if LOG_GNMI:
-            msg = ("gNMI SubscribeOnChange(%s) <= %s\n", xpath,
-                   schema.notificationsJsonString(before + after))
-            self.log(*msg)
-            logging.info(*msg)
+        self.log_gnmi("gNMI Subscribe OnChange(%s) <= %s\n", xpath,
+                      schema.notificationsJsonString(before + after))
         return before, after
 
     @classmethod
@@ -492,7 +496,7 @@ def log(self, formatter, *args):
             *args: The formatter parameters. Allows logging messages during
                 test executions.
         """
-        self.log_message += formatter % args + '\n'
+        self.log_message += (formatter % args) + '\n'
 
     def startTest(self, test: TestCase):  # pytype: disable=signature-mismatch
         """Clean the log before every test."""