multimedia: Introduce a way to save and show the log messages from the client
Server tests use the multimedia facade framework to call the client
library, such that the existing client library can be reused in server
tests. The implementation is done by RPC. The Autotest logging system
is unable to know the log output from the client. It is hard for debug.
This change introduces a way to save the log by running a tail command
in background. The stdout and stderr are piped to the Autotest logging
system. On every RPC call, the log is processed, meaning showed to
the Autotest log.
BUG=chromium:766631
TEST=Ran a multimedia test cases, with --debug, saw the log, like:
16:54:36 INFO | autoserv| Waiting for calibration image to stabilize...
16:54:47 INFO | autoserv| [client] 14:54:46 INFO | Dispatching method
<bound method DisplayFacadeNative.func_retry of
<autotest_lib.client.cros.multimedia.display_facade_native.DisplayFacadeNative
object at 0x7f5cb558c2d0>> with args ()
16:54:47 INFO | autoserv| [client] 14:54:46 DEBUG| Running 'modetest -c'
16:54:47 INFO | autoserv| [client] 14:54:46 DEBUG| Running 'modetest -p'
16:54:47 INFO | autoserv| [client] 127.0.0.1 - - [26/Sep/2017 14:54:46]
"POST /RPC2 HTTP/1.1" 200 -
16:54:47 INFO | autoserv| RPC 'display.get_external_resolution'((), {})
returns [1920, 1080].
16:54:47 INFO | autoserv| Checking the resolutions of Chameleon and
CrOS...
16:54:47 INFO | autoserv| Resolutions across CrOS and Chameleon match:
1920x1080
16:54:47 INFO | autoserv| Capturing the screen on Chameleon...
16:54:52 INFO | autoserv| Capturing the external screen on CrOS...
Also tested the cases, like DUT reboot, RPC error.
Change-Id: I870052d82cc489acd71b90dc009e470005a0d4ce
Reviewed-on: https://chromium-review.googlesource.com/685310
Commit-Ready: Wai-Hong Tam <waihong@google.com>
Tested-by: Wai-Hong Tam <waihong@google.com>
Reviewed-by: Cheng-Yi Chiang <cychiang@chromium.org>
Reviewed-by: Armando Miraglia <armax@chromium.org>
Reviewed-by: Harpreet Grewal <harpreet@chromium.org>
Reviewed-by: Denis Tosic <dtosic@chromium.org>
(cherry picked from commit 610b49cad27e9904bbc7f2665b7f6e2f4ed6447b)
Reviewed-on: https://chromium-review.googlesource.com/692998
Commit-Queue: Harpreet Grewal <harpreet@chromium.org>
Tested-by: Harpreet Grewal <harpreet@chromium.org>
Trybot-Ready: Harpreet Grewal <harpreet@chromium.org>
diff --git a/server/cros/multimedia/remote_facade_factory.py b/server/cros/multimedia/remote_facade_factory.py
index e8f8517..dd6067f 100644
--- a/server/cros/multimedia/remote_facade_factory.py
+++ b/server/cros/multimedia/remote_facade_factory.py
@@ -11,6 +11,7 @@
import sys
from autotest_lib.client.bin import utils
+from autotest_lib.client.common_lib import logging_manager
from autotest_lib.client.common_lib import error
from autotest_lib.client.common_lib.cros import retry
from autotest_lib.client.cros import constants
@@ -27,6 +28,12 @@
from autotest_lib.server.cros.multimedia import video_facade_adapter
+# Log the client messages in the DEBUG level, with the prefix [client].
+CLIENT_LOG_STREAM = logging_manager.LoggingFile(
+ level=logging.DEBUG,
+ prefix='[client] ')
+
+
class _Method:
"""Class to save the name of the RPC method instead of the real object.
@@ -77,6 +84,7 @@
"""
self._client = host
self._xmlrpc_proxy = None
+ self._log_saving_job = None
self._no_chrome = no_chrome
self._extra_browser_args = extra_browser_args
self.connect()
@@ -100,6 +108,24 @@
@param dargs: The rest of dict-type arguments.
@return: The return value of the RPC method.
"""
+ def process_log():
+ """Process the log from client, i.e. showing the log messages."""
+ if self._log_saving_job:
+ # final_read=True to process all data until the end
+ self._log_saving_job.process_output(
+ stdout=True, final_read=True)
+ self._log_saving_job.process_output(
+ stdout=False, final_read=True)
+
+ def call_rpc_with_log():
+ """Call the RPC with log."""
+ value = getattr(self._xmlrpc_proxy, name)(*args, **dargs)
+ process_log()
+ if type(value) is str and value.startswith('Traceback'):
+ raise Exception('RPC error: %s\n%s' % (name, value))
+ logging.debug('RPC %s returns %s.', rpc, pprint.pformat(value))
+ return value
+
try:
# TODO(ihf): This logs all traffic from server to client. Make
# the spew optional.
@@ -108,11 +134,7 @@
(pprint.pformat(name), pprint.pformat(args),
pprint.pformat(dargs)))
try:
- value = getattr(self._xmlrpc_proxy, name)(*args, **dargs)
- if type(value) is str and value.startswith('Traceback'):
- raise Exception('RPC error: %s\n%s' % (name, value))
- logging.debug('RPC %s returns %s.', rpc, pprint.pformat(value))
- return value
+ return call_rpc_with_log()
except (socket.error,
xmlrpclib.ProtocolError,
httplib.BadStatusLine):
@@ -124,17 +146,36 @@
extra_browser_args=self._extra_browser_args)
# Try again.
logging.warning('Retrying RPC %s.', rpc)
- value = getattr(self._xmlrpc_proxy, name)(*args, **dargs)
- if type(value) is str and value.startswith('Traceback'):
- raise Exception('RPC error: %s\n%s' % (name, value))
- logging.debug('RPC %s returns %s.', rpc, pprint.pformat(value))
- return value
+ return call_rpc_with_log()
except:
+ # Process the log if any. It is helpful for debug.
+ process_log()
logging.error(
'Failed RPC %s with status [%s].', rpc, sys.exc_info()[0])
raise
+ def save_log_bg(self):
+ """Save the log from client in background."""
+ # Run a tail command in background that keeps all the log messages from
+ # client.
+ command = 'tail -n0 -f %s' % constants.MULTIMEDIA_XMLRPC_SERVER_LOG_FILE
+ full_command = '%s "%s"' % (self._client.ssh_command(), command)
+
+ if self._log_saving_job:
+ # Kill and join the previous job, probably due to a DUT reboot.
+ # In this case, a new job will be recreated.
+ logging.info('Kill and join the previous log job.')
+ utils.nuke_subprocess(self._log_saving_job.sp)
+ utils.join_bg_jobs([self._log_saving_job])
+
+ # Create the background job and pipe its stdout and stderr to the
+ # Autotest logging.
+ self._log_saving_job = utils.BgJob(full_command,
+ stdout_tee=CLIENT_LOG_STREAM,
+ stderr_tee=CLIENT_LOG_STREAM)
+
+
def connect(self):
"""Connects the XML-RPC proxy on the client.
@@ -166,6 +207,10 @@
logging.info('Setup the connection to RPC server, with retries...')
connect_with_retries()
+
+ logging.info('Start a job to save the log from the client.')
+ self.save_log_bg()
+
return True
