audio/cmd_utils - Log subproess's output
We should log subprocess's output (stdout, stdin).
It is important for debugging.
TEST=Run the audiovideo_CRASFormatConversion test
BUG=None
Change-Id: Ia328a7703c356d0995603f69313d6bfef9a16f7f
Reviewed-on: https://chromium-review.googlesource.com/179761
Reviewed-by: Hsinyu Chao <hychao@chromium.org>
Commit-Queue: Owen Lin <owenlin@chromium.org>
Tested-by: Owen Lin <owenlin@chromium.org>
diff --git a/client/cros/audio/cmd_utils.py b/client/cros/audio/cmd_utils.py
index 3b8ec27..b739b68 100644
--- a/client/cros/audio/cmd_utils.py
+++ b/client/cros/audio/cmd_utils.py
@@ -3,12 +3,112 @@
# Use of this source code is governed by a BSD-style license that can be
# found in the LICENSE file.
+import atexit
+import itertools
import logging
+import os
import pipes
+import select
import subprocess
import threading
+from autotest_lib.client.common_lib.utils import TEE_TO_LOGS
+
_popen_lock = threading.Lock()
+_logging_service = None
+_command_serial_number = itertools.count(1)
+
+_LOG_BUFSIZE = 4096
+_PIPE_CLOSED = -1
+
+class _LoggerProxy(object):
+
+ def __init__(self, logger):
+ self._logger = logger
+
+ def fileno(self):
+ return self._logger._pipe[1]
+
+ def __del__(self):
+ self._logger.close()
+
+
+class _PipeLogger(object):
+
+ def __init__(self, level, prefix):
+ self._pipe = list(os.pipe())
+ self._level = level
+ self._prefix = prefix
+
+ def close(self):
+ if self._pipe[1] != _PIPE_CLOSED:
+ os.close(self._pipe[1])
+ self._pipe[1] = _PIPE_CLOSED
+
+
+class _LoggingService(object):
+
+ def __init__(self):
+ # Python's list is thread safe
+ self._loggers = []
+
+ # Change tuple to list so that we can change the value when
+ # closing the pipe.
+ self._pipe = list(os.pipe())
+ self._thread = threading.Thread(target=self._service_run)
+ self._thread.daemon = True
+ self._thread.start()
+
+
+ def _service_run(self):
+ terminate_loop = False
+ while not terminate_loop:
+ rlist = [l._pipe[0] for l in self._loggers]
+ rlist.append(self._pipe[0])
+ for r in select.select(rlist, [], [])[0]:
+ data = os.read(r, _LOG_BUFSIZE)
+ if r != self._pipe[0]:
+ self._output_logger_message(r, data)
+ elif len(data) == 0:
+ terminate_loop = True
+ # Release resources.
+ os.close(self._pipe[0])
+ for logger in self._loggers:
+ os.close(logger._pipe[0])
+
+
+ def _output_logger_message(self, r, data):
+ logger = next(l for l in self._loggers if l._pipe[0] == r)
+
+ if len(data) == 0:
+ os.close(logger._pipe[0])
+ self._loggers.remove(logger)
+ return
+
+ for line in data.split('\n'):
+ logging.log(logger._level, '%s%s', logger._prefix, line)
+
+
+ def create_logger(self, level=logging.DEBUG, prefix=''):
+ logger = _PipeLogger(level=level, prefix=prefix)
+ self._loggers.append(logger)
+ os.write(self._pipe[1], '\0')
+ return _LoggerProxy(logger)
+
+
+ def shutdown(self):
+ if self._pipe[1] != _PIPE_CLOSED:
+ os.close(self._pipe[1])
+ self._pipe[1] = _PIPE_CLOSED
+ self._thread.join()
+
+
+def create_logger(level=logging.DEBUG, prefix=''):
+ global _logging_service
+ if _logging_service is None:
+ _logging_service = _LoggingService()
+ atexit.register(_logging_service.shutdown)
+ return _logging_service.create_logger(level=level, prefix=prefix)
def kill_or_log_returncode(*popens):
@@ -44,7 +144,7 @@
raise RuntimeError(error_message)
-def execute(args, stdin=None, stdout=None):
+def execute(args, stdin=None, stdout=TEE_TO_LOGS, stderr=TEE_TO_LOGS):
'''Executes a child command and wait for it.
Returns the output from standard output if 'stdout' is subprocess.PIPE.
@@ -54,22 +154,31 @@
@param stdin: the executed program's standard input
@param stdout: the executed program's stdandrd output
'''
- ps = popen(args, stdin=stdin, stdout=stdout)
+ ps = popen(args, stdin=stdin, stdout=stdout, stderr=stderr)
out = ps.communicate()[0] if stdout == subprocess.PIPE else None
wait_and_check_returncode(ps)
return out
-def popen(*args, **kargs):
+def popen(args, stdin=None, stdout=TEE_TO_LOGS, stderr=TEE_TO_LOGS):
'''Returns a Popen object just as subprocess.Popen does but with the
executed command stored in Popen.command.
'''
+ command_id = _command_serial_number.next()
+ prefix = '[%04d] ' % command_id
+
+ if stdout is TEE_TO_LOGS:
+ stdout = create_logger(level=logging.DEBUG, prefix=prefix)
+ if stderr is TEE_TO_LOGS:
+ stderr = create_logger(level=logging.ERROR, prefix=prefix)
+
+ command = ' '.join(pipes.quote(x) for x in args)
+ logging.info('%sRunning: %s', prefix, command)
+
# The lock is required for http://crbug.com/323843.
- the_args = args[0] if len(args) > 0 else kargs['args']
- command = ' '.join(pipes.quote(x) for x in the_args)
- logging.info('Running: %s', command)
with _popen_lock:
- ps = subprocess.Popen(*args, **kargs)
+ ps = subprocess.Popen(args, stdin=stdin, stdout=stdout, stderr=stderr)
+ logging.info('%spid is %d', prefix, ps.pid)
+ ps.command_id = command_id
ps.command = command
- logging.info('pid: %d', ps.pid)
return ps