Refactor the server_job code to use the base_job implementation of
record.

The two main features that the server job code added on top of the
basic job record were the ability to inject client job records into
the server job record, and the ability to inject console/vlm warnings
into the record.

The Autotest injection was implemented by adding a parse classmethod
to the status_log_entry class that does the inverse of the render
method, so that the Autotest class can construct status_log_entries
from the raw text status logs it gets from the client. The server then
re-records the messages, rather than using a low-level method to
bypass the old job.record rendering.

The warning injection was implemented by using the record_hook; to
make it work better it was moved to be called before the entry is
logged, not after.  This required a slightly more involved hook, as it
was useful to be able to call job.record directly from the hook and so
the hook was wrapped in a callable class that prevents recursion.

Signed-off-by: John Admanski <jadmanski@google.com>


git-svn-id: http://test.kernel.org/svn/autotest/trunk@4605 592f7852-d20e-0410-864c-8624ca9c26a4
diff --git a/server/server_job.py b/server/server_job.py
index 40489e4..567fb5a 100644
--- a/server/server_job.py
+++ b/server/server_job.py
@@ -48,6 +48,70 @@
     _get_site_job_data_dummy)
 
 
+class status_indenter(base_job.status_indenter):
+    """Provide a simple integer-backed status indenter."""
+    def __init__(self):
+        self._indent = 0
+
+
+    @property
+    def indent(self):
+        return self._indent
+
+
+    def increment(self):
+        self._indent += 1
+
+
+    def decrement(self):
+        self._indent -= 1
+
+
+class server_job_record_hook(object):
+    """The job.record hook for server job. Used to inject WARN messages from
+    the console or vlm whenever new logs are written, and to echo any logs
+    to INFO level logging. Implemented as a class so that it can use state to
+    block recursive calls, so that the hook can call job.record itself to
+    log WARN messages.
+
+    Depends on job._read_warnings and job._logger.
+    """
+    def __init__(self, job):
+        self._job = job
+        self._being_called = False
+
+
+    def __call__(self, entry):
+        """A wrapper around the 'real' record hook, the _hook method, which
+        prevents recursion. This isn't making any effort to be threadsafe,
+        the intent is to outright block infinite recursion via a
+        job.record->_hook->job.record->_hook->job.record... chain."""
+        if self._being_called:
+            return
+        self._being_called = True
+        try:
+            self._hook(self._job, entry)
+        finally:
+            self._being_called = False
+
+
+    @staticmethod
+    def _hook(job, entry):
+        """The core hook, which can safely call job.record."""
+        entries = []
+        # poll all our warning loggers for new warnings
+        for timestamp, msg in job._read_warnings():
+            warning_entry = base_job.status_log_entry(
+                'WARN', None, None, msg, {}, timestamp=timestamp)
+            entries.append(warning_entry)
+            job.record_entry(warning_entry)
+        # echo rendered versions of all the status logs to info
+        entries.append(entry)
+        for entry in entries:
+            rendered_entry = job._logger.render_entry(entry)
+            logging.info(rendered_entry)
+
+
 class base_server_job(base_job.base_job):
     """The server-side concrete implementation of base_job.
 
@@ -152,6 +216,11 @@
         self.bootloader = None
         self.harness = None
 
+        # set up the status logger
+        self._logger = base_job.status_logger(
+            self, status_indenter(), 'status.log', 'status.log',
+            record_hook=server_job_record_hook(self))
+
 
     @classmethod
     def _find_base_directories(cls):
@@ -177,6 +246,11 @@
             return None
 
 
+    def _get_status_logger(self):
+        """Return a reference to the status logger."""
+        return self._logger
+
+
     @staticmethod
     def _load_control_file(path):
         f = open(path)
@@ -622,55 +696,6 @@
             self.sysinfo.boot_loggables.add(loggable)
 
 
-    def record(self, status_code, subdir, operation, status='',
-               optional_fields=None):
-        """
-        Record job-level status
-
-        The intent is to make this file both machine parseable and
-        human readable. That involves a little more complexity, but
-        really isn't all that bad ;-)
-
-        Format is <status code>\t<subdir>\t<operation>\t<status>
-
-        status code: see common_lib.log.is_valid_status()
-                     for valid status definition
-
-        subdir: MUST be a relevant subdirectory in the results,
-        or None, which will be represented as '----'
-
-        operation: description of what you ran (e.g. "dbench", or
-                                        "mkfs -t foobar /dev/sda9")
-
-        status: error message or "completed sucessfully"
-
-        ------------------------------------------------------------
-
-        Initial tabs indicate indent levels for grouping, and is
-        governed by self._record_prefix
-
-        multiline messages have secondary lines prefaced by a double
-        space ('  ')
-
-        Executing this method will trigger the logging of all new
-        warnings to date from the various console loggers.
-        """
-        # poll all our warning loggers for new warnings
-        warnings = self._read_warnings()
-        old_record_prefix = self._record_prefix
-        try:
-            if status_code.startswith("END "):
-                self._record_prefix += "\t"
-            for timestamp, msg in warnings:
-                self._record("WARN", None, None, msg, timestamp)
-        finally:
-            self._record_prefix = old_record_prefix
-
-        # write out the actual status log line
-        self._record(status_code, subdir, operation, status,
-                      optional_fields=optional_fields)
-
-
     def _read_warnings(self):
         """Poll all the warning loggers and extract any new warnings that have
         been logged. If the warnings belong to a category that is currently
@@ -860,74 +885,6 @@
             return []
 
 
-    def _render_record(self, status_code, subdir, operation, status='',
-                       epoch_time=None, record_prefix=None,
-                       optional_fields=None):
-        """
-        Internal Function to generate a record to be written into a
-        status log. For use by server_job.* classes only.
-        """
-        if subdir:
-            if re.match(r'[\n\t]', subdir):
-                raise ValueError('Invalid character in subdir string')
-            substr = subdir
-        else:
-            substr = '----'
-
-        if not log.is_valid_status(status_code):
-            raise ValueError('Invalid status code supplied: %s' % status_code)
-        if not operation:
-            operation = '----'
-        if re.match(r'[\n\t]', operation):
-            raise ValueError('Invalid character in operation string')
-        operation = operation.rstrip()
-        status = status.rstrip()
-        status = re.sub(r"\t", "  ", status)
-        # Ensure any continuation lines are marked so we can
-        # detect them in the status file to ensure it is parsable.
-        status = re.sub(r"\n", "\n" + self._record_prefix + "  ", status)
-
-        if not optional_fields:
-            optional_fields = {}
-
-        # Generate timestamps for inclusion in the logs
-        if epoch_time is None:
-            epoch_time = int(time.time())
-        local_time = time.localtime(epoch_time)
-        optional_fields["timestamp"] = str(epoch_time)
-        optional_fields["localtime"] = time.strftime("%b %d %H:%M:%S",
-                                                     local_time)
-
-        fields = [status_code, substr, operation]
-        fields += ["%s=%s" % x for x in optional_fields.iteritems()]
-        fields.append(status)
-
-        if record_prefix is None:
-            record_prefix = self._record_prefix
-
-        msg = '\t'.join(str(x) for x in fields)
-        return record_prefix + msg + '\n'
-
-
-    def _record_prerendered(self, msg):
-        """
-        Record a pre-rendered msg into the status logs. The only
-        change this makes to the message is to add on the local
-        indentation. Should not be called outside of server_job.*
-        classes. Unlike _record, this does not write the message
-        to standard output.
-        """
-        lines = []
-        status_file = self.get_status_log_path()
-        status_log = open(status_file, 'a')
-        for line in msg.splitlines():
-            line = self._record_prefix + line + '\n'
-            lines.append(line)
-            status_log.write(line)
-        status_log.close()
-        self.__parse_status(lines)
-
-
     def _fill_server_control_namespace(self, namespace, protect=True):
         """
         Prepare a namespace to be used when executing server control files.
@@ -1045,27 +1002,6 @@
         execfile(code_file, namespace, namespace)
 
 
-    def _record(self, status_code, subdir, operation, status='',
-                 epoch_time=None, optional_fields=None):
-        """
-        Actual function for recording a single line into the status
-        logs. Should never be called directly, only by job.record as
-        this would bypass the console monitor logging.
-        """
-
-        msg = self._render_record(status_code, subdir, operation, status,
-                                  epoch_time, optional_fields=optional_fields)
-
-        status_file = self.get_status_log_path()
-        sys.stdout.write(msg)
-        if status_file:
-            open(status_file, "a").write(msg)
-        if subdir:
-            sub_status_file = self.get_status_log_path(subdir)
-            open(sub_status_file, "a").write(msg)
-        self.__parse_status(msg.splitlines())
-
-
     def __parse_status(self, new_lines):
         if not self._using_parser:
             return