From 768f57bc07232c85b5da068a7c6cc93c2f7826d1 Mon Sep 17 00:00:00 2001
From: anonymous-akorn <66133366+anonymous-akorn@users.noreply.github.com>
Date: Mon, 14 Dec 2020 09:47:11 -0800
Subject: [PATCH] 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.
---
 scripts/gha/desktop_tester.py                 | 30 ++++++++++++-------
 .../src/firebase_test_framework.cc            |  2 +-
 2 files changed, 20 insertions(+), 12 deletions(-)

diff --git a/scripts/gha/desktop_tester.py b/scripts/gha/desktop_tester.py
index ad8003cf04..53d0e959b3 100644
--- a/scripts/gha/desktop_tester.py
+++ b/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)
diff --git a/testing/test_framework/src/firebase_test_framework.cc b/testing/test_framework/src/firebase_test_framework.cc
index d34f0bc2c6..3271be54e5 100644
--- a/testing/test_framework/src/firebase_test_framework.cc
+++ b/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);