Change integration test log level to "debug"

Currently the logging behaviour for "debug" level logs is set to show them at the end of the integration test, if there were any failures. This results in them not showing up at all, should the integration test prematurely exit to due a crash, failed assertion, or timeout. In practice, this often leads to a lack of relevant logs to understand why a test didn't complete.

To fix this, the overall log level is changed from info to debug. This ensures debug logs are logged immediately, so a prematurely ended test won't prevent them from showing up.

This also includes a small fix to the desktop_tester script to capture logs in the event of a process timeout: previously, result.stdout was used, which doesn't get populated if the process timed out. Instead, we access output from the error. Experimentation revealed that this output will sometimes be test, and sometimes binary: it's unclear what's responsible for this difference (possibly the encoding settings of the environment running the script). Thus we try to decode, and store it as-is if that fails.

Author: anonymous-akorn

scripts/gha/desktop_tester.py

@@ -94,19 +94,27 @@ class Test(object):
   # them as fields so they can be accessed from the main thread.
   def run(self):
     """Executes this testapp."""
-    result = subprocess.run(
-        args=[self.testapp_path],
-        cwd=os.path.dirname(self.testapp_path),  # Testapp checks CWD for config
-        stdout=subprocess.PIPE,
-        stderr=subprocess.STDOUT,
-        text=True,
-        check=False,
-        timeout=300)
+    result = None  # Ensures this var is defined if timeout occurs.
+    try:
+      result = subprocess.run(
+          args=[self.testapp_path],
+          cwd=os.path.dirname(self.testapp_path),  # Testapp uses CWD for config
+          stdout=subprocess.PIPE,
+          stderr=subprocess.STDOUT,
+          text=True,
+          check=False,
+          timeout=300)
+    except subprocess.TimeoutExpired as e:
+      logging.error("Testapp timed out!")
+      # e.output will sometimes be bytes, sometimes string. Decode if needed.
+      try:
+        self.logs = e.output.decode()
+      except AttributeError:  # This will happen if it's already a string.
+        self.logs = e.output
+    if result:
+      self.logs = result.stdout
     logging.info("Finished running %s", self.testapp_path)
 
-    self.logs = result.stdout
-    self.return_code = result.returncode
-
 
 if __name__ == "__main__":
   app.run(main)

testing/test_framework/src/firebase_test_framework.cc

@@ -208,7 +208,7 @@ std::ostream& operator<<(std::ostream& os, const Variant& v) {
 extern "C" int common_main(int argc, char* argv[]) {
   ::testing::InitGoogleTest(&argc, argv);
   firebase_test_framework::FirebaseTest::SetArgs(argc, argv);
-  app_framework::SetLogLevel(app_framework::kInfo);
+  app_framework::SetLogLevel(app_framework::kDebug);
   // Anything below the given log level will be preserved, and printed out in
   // the event of test failure.
   app_framework::SetPreserveFullLog(true);