Fuchsia: Get kernel logs over SSH and and symbolize their stack traces.

Serial kernel logging is a deprecated feature of Zircon and should not
be used anymore. This uses a long-running SSH invocation of "dlog"
to pull the logs over the wire. It works equally well on QEMU and on
devices.

Created a stream multiplexer using "poll" to merge the kernel log and
application log into a single stream, which is passed to the symbolizing
filter.

Modified the symbolizer regex rules to allow kernel log timestamps.
Kernel log timestamps can be omitted from the output, but they seem
to be helpful at visually distinguishing kernel output from app output.


Bug: 838671
Change-Id: Icd45f902a49983b4e4ee262de474d69fbef56860
Reviewed-on: https://chromium-review.googlesource.com/1038423
Commit-Queue: Kevin Marshall <kmarshall@chromium.org>
Reviewed-by: Fabrice de Gans-Riberi <fdegans@chromium.org>
Cr-Commit-Position: refs/heads/master@{#556170}

build/fuchsia/common_args.py

@@ -40,8 +40,7 @@ def AddCommonArgs(arg_parser):
   common_args.add_argument('--ssh-config', '-F',
                            help='The path to the SSH configuration used for '
                                 'connecting to the target device.')
-  common_args.add_argument('--no-system-logs', default=False,
-                           action='store_true',
+  common_args.add_argument('--include-system-logs', default=True, type=bool,
                            help='Do not show system log data.')
   common_args.add_argument('--verbose', '-v', default=False,
                            action='store_true',
@@ -70,8 +69,7 @@ def GetDeploymentTargetForArgs(args):
   command line arguments."""
 
   if not args.device:
-    return QemuTarget(args.output_directory, args.target_cpu,
-                      not args.no_system_logs)
+    return QemuTarget(args.output_directory, args.target_cpu)
   else:
     return DeviceTarget(args.output_directory, args.target_cpu,
                         args.host, args.port, args.ssh_config)

build/fuchsia/exe_runner.py

@@ -25,8 +25,9 @@ def main():
 
   with GetDeploymentTargetForArgs(args) as target:
     target.Start()
-    return RunPackage(args.output_directory, target, args.package,
-                      args.package_name, args.child_args, args.package_manifest)
+    return RunPackage(
+        args.output_directory, target, args.package, args.package_name,
+        args.child_args, args.include_system_logs, args.package_manifest)
 
 
 if __name__ == '__main__':

build/fuchsia/qemu_target.py

@@ -33,17 +33,15 @@ def _GetAvailableTcpPort():
 
 
 class QemuTarget(target.Target):
-  def __init__(self, output_dir, target_cpu, system_logs,
+  def __init__(self, output_dir, target_cpu,
                ram_size_mb=2048):
     """output_dir: The directory which will contain the files that are
                    generated to support the QEMU deployment.
     target_cpu: The emulated target CPU architecture.
-                Can be 'x64' or 'arm64'.
-    system_logs: If true, emit system log data."""
+                Can be 'x64' or 'arm64'."""
     super(QemuTarget, self).__init__(output_dir, target_cpu)
     self._qemu_process = None
     self._ram_size_mb = ram_size_mb
-    self._system_logs = system_logs
 
   def __enter__(self):
     return self
@@ -63,10 +61,6 @@ class QemuTarget(target.Target):
     # noisy ANSI spew from the user's terminal emulator.
     kernel_args.append('TERM=dumb')
 
-    # Enable logging to the serial port.
-    # TODO(sergeyu): Use loglistener instead of serial port to get zircon logs.
-    kernel_args.append('kernel.serial=legacy')
-
     qemu_command = [qemu_path,
         '-m', str(self._ram_size_mb),
         '-nographic',
@@ -139,12 +133,9 @@ class QemuTarget(target.Target):
     logging.debug('Launching QEMU.')
     logging.debug(' '.join(qemu_command))
 
-    stdio_flags = {'stdin': open(os.devnull)}
-    if not self._system_logs:
-      # Output the Fuchsia debug log.
-      stdio_flags['stdout'] = open(os.devnull)
-      stdio_flags['stderr'] = open(os.devnull)
-
+    stdio_flags = {'stdin': open(os.devnull),
+                   'stdout': open(os.devnull),
+                   'stderr': open(os.devnull)}
     self._qemu_process = subprocess.Popen(qemu_command, **stdio_flags)
     self._WaitUntilReady();
 

build/fuchsia/run_package.py

@@ -8,11 +8,14 @@ executable on a Target."""
 import common
 import json
 import logging
+import multiprocessing
 import os
 import shutil
 import subprocess
 import tempfile
+import threading
 import uuid
+import select
 
 from symbolizer import FilterStream
 
@@ -20,8 +23,65 @@ FAR = os.path.join(common.SDK_ROOT, 'tools', 'far')
 PM = os.path.join(common.SDK_ROOT, 'tools', 'pm')
 
 
+def _AttachKernelLogReader(target):
+  """Attaches a kernel log reader as a long-running SSH task."""
+
+  logging.info('Attaching kernel logger.')
+  return target.RunCommandPiped(['dlog', '-f'], stdin=open(os.devnull, 'r'),
+                                stdout=subprocess.PIPE)
+
+
+def _ReadMergedLines(streams):
+  """Creates a generator which merges the buffered line output from |streams|.
+  The generator is terminated when the primary (first in sequence) stream
+  signals EOF. Absolute output ordering is not guaranteed."""
+
+  assert len(streams) > 0
+  poll = select.poll()
+  streams_by_fd = {}
+  primary_fd = streams[0].fileno()
+  for s in streams:
+    poll.register(s.fileno(), select.POLLIN)
+    streams_by_fd[s.fileno()] = s
+
+  try:
+    while primary_fd != None:
+      events = poll.poll(1)
+      for fileno, event in events:
+        if event & select.POLLIN:
+          yield streams_by_fd[fileno].readline()
+
+        elif event & select.POLLHUP:
+          poll.unregister(fileno)
+          del streams_by_fd[fileno]
+
+          if fileno == primary_fd:
+            primary_fd = None
+  finally:
+    for fd_to_cleanup, _ in streams_by_fd.iteritems():
+      poll.unregister(fd_to_cleanup)
+
+
+def DrainStreamToStdout(stream, quit_event):
+  """Outputs the contents of |stream| until |quit_event| is set."""
+
+  poll = select.poll()
+  poll.register(stream.fileno(), select.POLLIN)
+  try:
+    while not quit_event.is_set():
+      events = poll.poll(1)
+      for fileno, event in events:
+        if event & select.POLLIN:
+          print stream.readline().rstrip()
+        elif event & select.POLLHUP:
+          break
+
+  finally:
+    poll.unregister(stream.fileno())
+
+
 def RunPackage(output_dir, target, package_path, package_name, run_args,
-               symbolizer_config=None):
+               system_logging, symbolizer_config=None):
   """Copies the Fuchsia package at |package_path| to the target,
   executes it with |run_args|, and symbolizes its output.
 
@@ -30,6 +90,7 @@ def RunPackage(output_dir, target, package_path, package_name, run_args,
   package_path: The path to the .far package file.
   package_name: The name of app specified by package metadata.
   run_args: The arguments which will be passed to the Fuchsia process.
+  system_logging: If true, connects a system log reader to the target.
   symbolizer_config: A newline delimited list of source files contained
                      in the package. Omitting this parameter will disable
                      symbolization.
@@ -37,11 +98,25 @@ def RunPackage(output_dir, target, package_path, package_name, run_args,
   Returns the exit code of the remote package process."""
 
 
-  logging.info('Copying package to target.')
-  install_path = os.path.join('/data', os.path.basename(package_path))
-  target.PutFile(package_path, install_path)
-
+  system_logger = _AttachKernelLogReader(target) if system_logging else None
+  package_copied = False
+  log_output_thread = None
   try:
+    log_output_thread = None
+    if system_logger:
+      # Spin up a thread to asynchronously dump the system log to stdout
+      # for easier diagnoses of early, pre-execution failures.
+      log_output_quit_event = multiprocessing.Event()
+      log_output_thread = threading.Thread(
+          target=lambda: DrainStreamToStdout(system_logger.stdout,
+                                             log_output_quit_event))
+      log_output_thread.start()
+
+    logging.info('Copying package to target.')
+    install_path = os.path.join('/data', os.path.basename(package_path))
+    target.PutFile(package_path, install_path)
+    package_copied = True
+
     logging.info('Installing package.')
     p = target.RunCommandPiped(['pm', 'install', install_path],
                                stderr=subprocess.PIPE)
@@ -51,7 +126,11 @@ def RunPackage(output_dir, target, package_path, package_name, run_args,
     if p.returncode != 0:
       # Don't error out if the package already exists on the device.
       if len(output) != 1 or 'ErrAlreadyExists' not in output[0]:
-        raise Exception('Error when installing package: %s' % '\n'.join(output))
+        raise Exception('Error while installing: %s' % '\n'.join(output))
+
+    if log_output_thread:
+      log_output_quit_event.set()
+      log_output_thread.join()
 
     logging.info('Running application.')
     command = ['run', package_name] + run_args
@@ -60,16 +139,21 @@ def RunPackage(output_dir, target, package_path, package_name, run_args,
                                      stdout=subprocess.PIPE,
                                      stderr=subprocess.STDOUT)
 
+    if system_logger:
+      task_output = _ReadMergedLines([process.stdout, system_logger.stdout])
+    else:
+      task_output = process.stdout
+
     if symbolizer_config:
       # Decorate the process output stream with the symbolizer.
-      output = FilterStream(process.stdout, package_name,
-                            symbolizer_config, output_dir)
+      output = FilterStream(task_output, package_name, symbolizer_config,
+                            output_dir)
     else:
       logging.warn('Symbolization is DISABLED.')
       output = process.stdout
 
     for next_line in output:
-      print next_line.strip()
+      print next_line.rstrip()
 
     process.wait()
     if process.returncode == 0:
@@ -81,8 +165,13 @@ def RunPackage(output_dir, target, package_path, package_name, run_args,
                       process.returncode)
 
   finally:
-    logging.info('Removing package source from device.')
-    target.RunCommand(['rm', install_path])
+    if system_logger:
+      print 'Terminating kernel log reader.'
+      system_logger.kill()
+
+    if package_copied:
+      logging.info('Removing package source from device.')
+      target.RunCommand(['rm', install_path])
 
 
   return process.returncode

build/fuchsia/symbolizer.py

@@ -8,7 +8,7 @@ import re
 import subprocess
 
 # Matches the coarse syntax of a backtrace entry.
-_BACKTRACE_PREFIX_RE = re.compile(r'bt#(?P<frame_id>\d+): ')
+_BACKTRACE_PREFIX_RE = re.compile(r'(\[[0-9.]+\] )?bt#(?P<frame_id>\d+): ')
 
 # Matches the specific fields of a backtrace entry.
 # Back-trace line matcher/parser assumes that 'pc' is always present, and

build/fuchsia/test_runner.py

@@ -98,9 +98,9 @@ def main():
     if args.enable_test_server:
       test_server = SetupTestServer(target, test_concurrency)
 
-    returncode = RunPackage(args.output_directory, target, args.package,
-                            args.package_name, child_args,
-                            args.package_manifest)
+    returncode = RunPackage(
+        args.output_directory, target, args.package, args.package_name,
+        child_args, args.include_system_logs, args.package_manifest)
 
     if forwarder:
       forwarder.terminate()