SERVER-35472 Avoid falling back to stderr in resmoke.py.

Instead a special return code of 75 is used to indicate that the log
output would otherwise be incomplete.

2 files changed, 63 insertions, 41 deletions

diff --git a/buildscripts/resmokelib/logging/buildlogger.py b/buildscripts/resmokelib/logging/buildlogger.py
index 5fa52c85c69..2e48101d517 100644
--- a/buildscripts/resmokelib/logging/buildlogger.py
+++ b/buildscripts/resmokelib/logging/buildlogger.py
@@ -4,6 +4,7 @@ from __future__ import absolute_import
 
 import functools
 import json
+import threading
 
 import requests
 
@@ -23,6 +24,20 @@ _SEND_AFTER_SECS = 10
 # Initialized by resmokelib.logging.loggers.configure_loggers()
 BUILDLOGGER_FALLBACK = None
 
+_INCOMPLETE_LOG_OUTPUT = threading.Event()
+
+
+def is_log_output_incomplete():  # noqa: D205,D400
+    """Return true if we failed to write all of the log output to the buildlogger server, and return
+    false otherwise.
+    """
+    return _INCOMPLETE_LOG_OUTPUT.is_set()
+
+
+def set_log_output_incomplete():
+    """Indicate that we failed to write all of the log output to the buildlogger server."""
+    _INCOMPLETE_LOG_OUTPUT.set()
+
 
 def _log_on_error(func):
     """Provide decorator that causes exceptions to be logged by the "buildlogger" Logger instance.
@@ -35,6 +50,10 @@ def _log_on_error(func):
         """Provide wrapper function."""
         try:
             return func(*args, **kwargs)
+        except requests.HTTPError as err:
+            BUILDLOGGER_FALLBACK.error("Encountered an HTTP error: %s", err)
+        except requests.RequestException as err:
+            BUILDLOGGER_FALLBACK.error("Encountered a network error: %s", err)
         except:  # pylint: disable=bare-except
             BUILDLOGGER_FALLBACK.exception("Encountered an error.")
         return None
@@ -155,11 +174,12 @@ class _BaseBuildloggerHandler(handlers.BufferedHandler):
                         new_max_size)
                     self.max_size = new_max_size
                     return self._append_logs(log_lines_chunk)
-            BUILDLOGGER_FALLBACK.exception("Encountered an error.")
-            return 0
+            BUILDLOGGER_FALLBACK.error("Encountered an HTTP error: %s", err)
+        except requests.RequestException as err:
+            BUILDLOGGER_FALLBACK.error("Encountered a network error: %s", err)
         except:  # pylint: disable=bare-except
             BUILDLOGGER_FALLBACK.exception("Encountered an error.")
-            return 0
+        return 0
 
     def _flush_buffer_with_lock(self, buf, close_called):
         """Ensure all logging output has been flushed to the buildlogger server.
@@ -175,14 +195,17 @@ class _BaseBuildloggerHandler(handlers.BufferedHandler):
         if nb_sent:
             self.retry_buffer = self.retry_buffer[nb_sent:]
         if close_called and self.retry_buffer:
-            # Request to the buildlogger server returned an error, so use the fallback logger to
-            # avoid losing the log messages entirely.
-            for (_, message) in self.retry_buffer:
-                # TODO: construct an LogRecord instance equivalent to the one passed to the
-                #       process_record() method if we ever decide to log the time when the
-                #       LogRecord was created, e.g. using %(asctime)s in
-                #       _fallback_buildlogger_handler().
-                BUILDLOGGER_FALLBACK.info(message)
+            # The request to the logkeeper returned an error. We discard the log output rather than
+            # writing the messages to the fallback logkeeper to avoid putting additional pressure on
+            # the Evergreen database.
+            BUILDLOGGER_FALLBACK.warning(
+                "Failed to flush all log output (%d messages) to logkeeper.", len(
+                    self.retry_buffer))
+
+            # We set a flag to indicate that we failed to flush all log output to logkeeper so
+            # resmoke.py can exit with a special return code.
+            set_log_output_incomplete()
+
             self.retry_buffer = []
 
 
diff --git a/buildscripts/resmokelib/logging/loggers.py b/buildscripts/resmokelib/logging/loggers.py
index d319928eb5f..deb3f6c38a2 100644
--- a/buildscripts/resmokelib/logging/loggers.py
+++ b/buildscripts/resmokelib/logging/loggers.py
@@ -7,6 +7,7 @@ import sys
 
 from . import buildlogger
 from . import formatters
+from .. import errors
 
 _DEFAULT_FORMAT = "[%(name)s] %(message)s"
 
@@ -174,15 +175,18 @@ class JobLogger(BaseLogger):
         BaseLogger.__init__(self, name, parent=parent)
         self.job_num = job_num
         self.fixture_root_logger = fixture_root_logger
-        # create build_id if it should
         if self.build_logger_server:
+            # If we're configured to log messages to the buildlogger server, then request a new
+            # build_id for this job.
             self.build_id = self.build_logger_server.new_build_id("job%d" % job_num)
-            if self.build_id:
-                url = self.build_logger_server.get_build_log_url(self.build_id)
-                parent.info("Writing output of job #%d to %s.", job_num, url)
-            else:
-                parent.info("Encountered an error configuring buildlogger for job #%d, falling"
-                            " back to stderr.", job_num)
+            if not self.build_id:
+                buildlogger.set_log_output_incomplete()
+                raise errors.LoggerRuntimeConfigError(
+                    "Encountered an error configuring buildlogger for job #{:d}: Failed to get a"
+                    " new build_id".format(job_num))
+
+            url = self.build_logger_server.get_build_log_url(self.build_id)
+            parent.info("Writing output of job #%d to %s.", job_num, url)
         else:
             self.build_id = None
 
@@ -193,14 +197,19 @@ class JobLogger(BaseLogger):
     def new_test_logger(self, test_shortname, test_basename, command, parent):
         """Create a new test logger that will be a child of the given parent."""
         if self.build_id:
+            # If we're configured to log messages to the buildlogger server, then request a new
+            # test_id for this test.
             test_id = self.build_logger_server.new_test_id(self.build_id, test_basename, command)
-            if test_id:
-                url = self.build_logger_server.get_test_log_url(self.build_id, test_id)
-                self.info("Writing output of %s to %s.", test_shortname, url)
-                return TestLogger(test_shortname, parent, self.build_id, test_id, url)
-            else:
-                self.info("Encountered an error configuring buildlogger for test %s, falling"
-                          " back to stderr.", test_shortname)
+            if not test_id:
+                buildlogger.set_log_output_incomplete()
+                raise errors.LoggerRuntimeConfigError(
+                    "Encountered an error configuring buildlogger for test {}: Failed to get a new"
+                    " test_id".format(test_basename))
+
+            url = self.build_logger_server.get_test_log_url(self.build_id, test_id)
+            self.info("Writing output of %s to %s.", test_basename, url)
+            return TestLogger(test_shortname, parent, self.build_id, test_id, url)
+
         return TestLogger(test_shortname, parent)
 
 
@@ -226,14 +235,9 @@ class TestLogger(BaseLogger):
         logger_info = self.logging_config[TESTS_LOGGER_NAME]
         handler_info = _get_buildlogger_handler_info(logger_info)
         if handler_info is not None:
-            if build_id and test_id:
-                handler = self.build_logger_server.get_test_handler(build_id, test_id, handler_info)
-                handler.setFormatter(self.get_formatter(logger_info))
-                self.addHandler(handler)
-            else:
-                # The build_id or test_id could not be obtained from the build logger server, so
-                # we're falling back to stderr.
-                self.addHandler(_fallback_buildlogger_handler())
+            handler = self.build_logger_server.get_test_handler(build_id, test_id, handler_info)
+            handler.setFormatter(self.get_formatter(logger_info))
+            self.addHandler(handler)
 
     def new_test_thread_logger(self, test_kind, thread_id):
         """Create a new child test thread logger."""
@@ -272,14 +276,9 @@ class FixtureLogger(BaseLogger):
         logger_info = self.logging_config[FIXTURE_LOGGER_NAME]
         handler_info = _get_buildlogger_handler_info(logger_info)
         if handler_info is not None:
-            if build_id:
-                handler = self.build_logger_server.get_global_handler(build_id, handler_info)
-                handler.setFormatter(self.get_formatter(logger_info))
-                self.addHandler(handler)
-            else:
-                # The build_id could not be obtained from the build logger server, so we're
-                # falling back to stderr.
-                self.addHandler(_fallback_buildlogger_handler())
+            handler = self.build_logger_server.get_global_handler(build_id, handler_info)
+            handler.setFormatter(self.get_formatter(logger_info))
+            self.addHandler(handler)
 
     def new_fixture_node_logger(self, node_name):
         """Create a new child FixtureNodeLogger."""