diff --git a/scripts/west_commands/run_common.py b/scripts/west_commands/run_common.py index 0d9473944b3..560ac97f3a0 100644 --- a/scripts/west_commands/run_common.py +++ b/scripts/west_commands/run_common.py @@ -6,6 +6,7 @@ ''' import argparse +import logging from os import getcwd, path from subprocess import CalledProcessError import textwrap @@ -25,6 +26,44 @@ from zephyr_ext_common import cached_runner_config # Don't change this, or output from argparse won't match up. INDENT = ' ' * 2 +if log.VERBOSE >= log.VERBOSE_NORMAL: + # Using level 1 allows sub-DEBUG levels of verbosity. The + # west.log module decides whether or not to actually print the + # message. + # + # https://docs.python.org/3.7/library/logging.html#logging-levels. + LOG_LEVEL = 1 +else: + LOG_LEVEL = logging.INFO + + +class WestLogFormatter(logging.Formatter): + + def __init__(self): + super().__init__(fmt='%(message)s') + +class WestLogHandler(logging.Handler): + + def __init__(self, *args, **kwargs): + super().__init__(*args, **kwargs) + self.setFormatter(WestLogFormatter()) + self.setLevel(LOG_LEVEL) + + def emit(self, record): + fmt = self.format(record) + lvl = record.levelno + if lvl > logging.CRITICAL: + log.die(fmt) + elif lvl >= logging.ERROR: + log.err(fmt) + elif lvl >= logging.WARNING: + log.wrn(fmt) + elif lvl >= logging.INFO: + log.inf(fmt) + elif lvl >= logging.DEBUG: + log.dbg(fmt) + else: + log.dbg(fmt, level=log.VERBOSE_EXTREME) def add_parser_common(parser_adder, command): parser = parser_adder.add_parser( @@ -201,9 +240,13 @@ def do_run_common(command, args, runner_args, cached_runner_var): # At this point, the common options above are already parsed in # 'args', and unrecognized arguments are in 'runner_args'. # + # - Set up runner logging to delegate to west. # - Pull the RunnerConfig out of the cache # - Override cached values with applicable command-line options + logger = logging.getLogger('runners') + logger.setLevel(LOG_LEVEL) + logger.addHandler(WestLogHandler()) cfg = cached_runner_config(build_dir, cache) _override_config_from_namespace(cfg, args) diff --git a/scripts/west_commands/runners/core.py b/scripts/west_commands/runners/core.py index f396c4f4ad5..f655a6749ed 100644 --- a/scripts/west_commands/runners/core.py +++ b/scripts/west_commands/runners/core.py @@ -14,19 +14,21 @@ as well as some other helpers for concrete runner classes. import abc import argparse import errno +import logging import os import platform +import shlex import shutil import signal import subprocess -from west import log -from west.util import quote_sh_list +# Turn on to enable just logging the commands that would be run (at +# info rather than debug level), without actually running them. This +# can break runners that are expecting output or if one command +# depends on another, so it's just for debugging. +_DRY_RUN = False -# Turn on to enable just printing the commands that would be run, -# without actually running them. This can break runners that are expecting -# output or if one command depends on another, so it's just for debugging. -JUST_PRINT = False +_logger = logging.getLogger('runners') class _DebugDummyPopen: @@ -313,6 +315,17 @@ class ZephyrBinaryRunner(abc.ABC): 3. Give your runner's name to the Zephyr build system in your board's board.cmake. + Some advice on input and output: + + - If you need to ask the user something (e.g. using input()), do it + in your create() classmethod, not do_run(). That ensures your + __init__() really has everything it needs to call do_run(), and also + avoids calling input() when not instantiating within a command line + application. + + - Use self.logger to log messages using the standard library's + logging API; your logger is named "runner." + For command-line invocation from the Zephyr build system, runners define their own argparse-based interface through the common add_parser() (and runner-specific do_add_parser() it delegates @@ -330,6 +343,10 @@ class ZephyrBinaryRunner(abc.ABC): ``cfg`` is a RunnerConfig instance.''' self.cfg = cfg + '''RunnerConfig for this instance.''' + + self.logger = logging.getLogger('runners.{}'.format(self.name())) + '''logging.Logger for this instance.''' @staticmethod def get_runners(): @@ -465,6 +482,13 @@ class ZephyrBinaryRunner(abc.ABC): server_proc.terminate() server_proc.wait() + def _log_cmd(self, cmd): + escaped = ' '.join(shlex.quote(s) for s in cmd) + if not _DRY_RUN: + self.logger.debug(escaped) + else: + self.logger.info(escaped) + def call(self, cmd): '''Subclass subprocess.call() wrapper. @@ -472,13 +496,9 @@ class ZephyrBinaryRunner(abc.ABC): subprocess and get its return code, rather than using subprocess directly, to keep accurate debug logs. ''' - quoted = quote_sh_list(cmd) - - if JUST_PRINT: - log.inf(quoted) + self._log_cmd(cmd) + if _DRY_RUN: return 0 - - log.dbg(quoted) return subprocess.call(cmd) def check_call(self, cmd): @@ -488,13 +508,9 @@ class ZephyrBinaryRunner(abc.ABC): subprocess and check that it executed correctly, rather than using subprocess directly, to keep accurate debug logs. ''' - quoted = quote_sh_list(cmd) - - if JUST_PRINT: - log.inf(quoted) + self._log_cmd(cmd) + if _DRY_RUN: return - - log.dbg(quoted) try: subprocess.check_call(cmd) except subprocess.CalledProcessError: @@ -507,13 +523,9 @@ class ZephyrBinaryRunner(abc.ABC): subprocess and check that it executed correctly, rather than using subprocess directly, to keep accurate debug logs. ''' - quoted = quote_sh_list(cmd) - - if JUST_PRINT: - log.inf(quoted) + self._log_cmd(cmd) + if _DRY_RUN: return b'' - - log.dbg(quoted) try: return subprocess.check_output(cmd) except subprocess.CalledProcessError: @@ -526,16 +538,14 @@ class ZephyrBinaryRunner(abc.ABC): cflags = 0 preexec = None system = platform.system() - quoted = quote_sh_list(cmd) if system == 'Windows': cflags |= subprocess.CREATE_NEW_PROCESS_GROUP elif system in {'Linux', 'Darwin'}: preexec = os.setsid - if JUST_PRINT: - log.inf(quoted) + self._log_cmd(cmd) + if _DRY_RUN: return _DebugDummyPopen() - log.dbg(quoted) return subprocess.Popen(cmd, creationflags=cflags, preexec_fn=preexec) diff --git a/scripts/west_commands/runners/dfu.py b/scripts/west_commands/runners/dfu.py index 8b172738b5c..f144584f195 100644 --- a/scripts/west_commands/runners/dfu.py +++ b/scripts/west_commands/runners/dfu.py @@ -8,8 +8,6 @@ from collections import namedtuple import sys import time -from west import log - from runners.core import ZephyrBinaryRunner, RunnerCaps, \ BuildConfiguration @@ -36,6 +34,7 @@ class DfuUtilBinaryRunner(ZephyrBinaryRunner): else: self.dfuse = True self.dfuse_config = dfuse_config + self.reset = False @classmethod def name(cls): @@ -80,8 +79,17 @@ class DfuUtilBinaryRunner(ZephyrBinaryRunner): else: dcfg = None - return DfuUtilBinaryRunner(cfg, args.pid, args.alt, args.img, - exe=args.dfu_util, dfuse_config=dcfg) + ret = DfuUtilBinaryRunner(cfg, args.pid, args.alt, args.img, + exe=args.dfu_util, dfuse_config=dcfg) + ret.ensure_device() + return ret + + def ensure_device(self): + if not self.find_device(): + self.reset = True + print('Please reset your board to switch to DFU mode...') + while not self.find_device(): + time.sleep(0.1) def find_device(self): cmd = list(self.cmd) + ['-l'] @@ -91,17 +99,9 @@ class DfuUtilBinaryRunner(ZephyrBinaryRunner): def do_run(self, command, **kwargs): self.require(self.cmd[0]) - reset = False + if not self.find_device(): - reset = True - log.dbg('Device not found, waiting for it', - level=log.VERBOSE_EXTREME) - # Use of print() here is advised. We don't want to lose - # this information in a separate log -- this is - # interactive and requires a terminal. - print('Please reset your board to switch to DFU mode...') - while not self.find_device(): - time.sleep(0.1) + raise RuntimeError('device not found') cmd = list(self.cmd) if self.dfuse: @@ -118,6 +118,6 @@ class DfuUtilBinaryRunner(ZephyrBinaryRunner): # # DfuSe targets do as well, except when 'leave' is given # as an option. - reset = False - if reset: + self.reset = False + if self.reset: print('Now reset your board again to switch back to runtime mode.') diff --git a/scripts/west_commands/runners/esp32.py b/scripts/west_commands/runners/esp32.py index 31bdf89c111..64349a20bfc 100644 --- a/scripts/west_commands/runners/esp32.py +++ b/scripts/west_commands/runners/esp32.py @@ -6,8 +6,6 @@ from os import path -from west import log - from runners.core import ZephyrBinaryRunner, RunnerCaps @@ -95,8 +93,9 @@ class Esp32BinaryRunner(ZephyrBinaryRunner): else: cmd_flash.extend(['0x1000', bin_name]) - log.inf("Converting ELF to BIN") + self.logger.info("Converting ELF to BIN") self.check_call(cmd_convert) - log.inf("Flashing ESP32 on {} ({}bps)".format(self.device, self.baud)) + self.logger.info("Flashing ESP32 on {} ({}bps)". + format(self.device, self.baud)) self.check_call(cmd_flash) diff --git a/scripts/west_commands/runners/intel_s1000.py b/scripts/west_commands/runners/intel_s1000.py index d64c82b7c06..7d824b32ba8 100644 --- a/scripts/west_commands/runners/intel_s1000.py +++ b/scripts/west_commands/runners/intel_s1000.py @@ -7,7 +7,6 @@ from os import path import time import signal -from west import log from runners.core import ZephyrBinaryRunner @@ -84,7 +83,7 @@ class IntelS1000BinaryRunner(ZephyrBinaryRunner): jtag_instr_file = kwargs['ocd-jtag-instr'] gdb_flash_file = kwargs['gdb-flash-file'] - self.print_gdbserver_message(self.gdb_port) + self.log_gdbserver_message(self.gdb_port) server_cmd = [self.xt_ocd_dir, '-c', topology_file, '-I', jtag_instr_file] @@ -122,7 +121,7 @@ class IntelS1000BinaryRunner(ZephyrBinaryRunner): topology_file = kwargs['ocd-topology'] jtag_instr_file = kwargs['ocd-jtag-instr'] - self.print_gdbserver_message(self.gdb_port) + self.log_gdbserver_message(self.gdb_port) server_cmd = [self.xt_ocd_dir, '-c', topology_file, '-I', jtag_instr_file] @@ -152,14 +151,11 @@ class IntelS1000BinaryRunner(ZephyrBinaryRunner): server_proc.terminate() server_proc.wait() - def print_gdbserver_message(self, gdb_port): - log.inf('Intel S1000 GDB server running on port {}'.format(gdb_port)) - def debugserver(self, **kwargs): topology_file = kwargs['ocd-topology'] jtag_instr_file = kwargs['ocd-jtag-instr'] - self.print_gdbserver_message(self.gdb_port) + self.log_gdbserver_message(self.gdb_port) server_cmd = [self.xt_ocd_dir, '-c', topology_file, '-I', jtag_instr_file] @@ -170,3 +166,7 @@ class IntelS1000BinaryRunner(ZephyrBinaryRunner): time.sleep(6) server_proc.terminate() self.check_call(server_cmd) + + def log_gdbserver_message(self, gdb_port): + self.logger.info('Intel S1000 GDB server running on port {}'. + format(gdb_port)) diff --git a/scripts/west_commands/runners/jlink.py b/scripts/west_commands/runners/jlink.py index 995b15884b7..70bef81d7c7 100644 --- a/scripts/west_commands/runners/jlink.py +++ b/scripts/west_commands/runners/jlink.py @@ -7,11 +7,9 @@ import argparse import os import shlex -import shutil import sys import tempfile -from west import log from runners.core import ZephyrBinaryRunner, RunnerCaps, \ BuildConfiguration @@ -105,7 +103,8 @@ class JLinkBinaryRunner(ZephyrBinaryRunner): tui=args.tui, tool_opt=args.tool_opt) def print_gdbserver_message(self): - log.inf('J-Link GDB server running on port {}'.format(self.gdb_port)) + self.logger.info('J-Link GDB server running on port {}'. + format(self.gdb_port)) def do_run(self, command, **kwargs): server_cmd = ([self.gdbserver] + @@ -162,8 +161,8 @@ class JLinkBinaryRunner(ZephyrBinaryRunner): lines.append('g') # Start the CPU lines.append('q') # Close the connection and quit - log.dbg('JLink commander script:') - log.dbg('\n'.join(lines)) + self.logger.debug('JLink commander script:') + self.logger.debug('\n'.join(lines)) # Don't use NamedTemporaryFile: the resulting file can't be # opened again on Windows. @@ -179,5 +178,5 @@ class JLinkBinaryRunner(ZephyrBinaryRunner): '-CommanderScript', fname] + self.tool_opt) - log.inf('Flashing Target Device') + self.logger.info('Flashing Target Device') self.check_call(cmd) diff --git a/scripts/west_commands/runners/nios2.py b/scripts/west_commands/runners/nios2.py index b3a006e9478..c7a377cc583 100644 --- a/scripts/west_commands/runners/nios2.py +++ b/scripts/west_commands/runners/nios2.py @@ -4,7 +4,6 @@ '''Runner for NIOS II, based on quartus-flash.py and GDB.''' -from west import log from runners.core import ZephyrBinaryRunner, NetworkPortHelper @@ -65,7 +64,8 @@ class Nios2BinaryRunner(ZephyrBinaryRunner): self.check_call(cmd) def print_gdbserver_message(self, gdb_port): - log.inf('Nios II GDB server running on port {}'.format(gdb_port)) + self.logger.info('Nios II GDB server running on port {}'. + format(gdb_port)) def debug_debugserver(self, command, **kwargs): # Per comments in the shell script, the NIOSII GDB server diff --git a/scripts/west_commands/runners/nrfjprog.py b/scripts/west_commands/runners/nrfjprog.py index 4d7c468047e..052903e87f6 100644 --- a/scripts/west_commands/runners/nrfjprog.py +++ b/scripts/west_commands/runners/nrfjprog.py @@ -7,8 +7,6 @@ import sys -from west import log - from runners.core import ZephyrBinaryRunner, RunnerCaps @@ -46,8 +44,14 @@ class NrfJprogBinaryRunner(ZephyrBinaryRunner): @classmethod def create(cls, cfg, args): - return NrfJprogBinaryRunner(cfg, args.nrf_family, args.softreset, - args.snr, erase=args.erase) + ret = NrfJprogBinaryRunner(cfg, args.nrf_family, args.softreset, + args.snr, erase=args.erase) + ret.ensure_snr() + return ret + + def ensure_snr(self): + if not self.snr: + self.snr = self.get_board_snr_from_user() def get_board_snr_from_user(self): snrs = self.check_output(['nrfjprog', '--ids']) @@ -63,9 +67,6 @@ class NrfJprogBinaryRunner(ZephyrBinaryRunner): 'is a debugger already connected?') return board_snr - log.dbg("Refusing the temptation to guess a board", - level=log.VERBOSE_EXTREME) - # Use of print() here is advised. We don't want to lose # this information in a separate log -- this is # interactive and requires a terminal. @@ -91,13 +92,13 @@ class NrfJprogBinaryRunner(ZephyrBinaryRunner): commands = [] if self.snr is None: - board_snr = self.get_board_snr_from_user() + raise ValueError("self.snr must not be None") else: board_snr = self.snr.lstrip("0") program_cmd = ['nrfjprog', '--program', self.hex_, '-f', self.family, '--snr', board_snr] - print('Flashing file: {}'.format(self.hex_)) + self.logger.info('Flashing file: {}'.format(self.hex_)) if self.erase: commands.extend([ ['nrfjprog', @@ -129,5 +130,5 @@ class NrfJprogBinaryRunner(ZephyrBinaryRunner): for cmd in commands: self.check_call(cmd) - log.inf('Board with serial number {} flashed successfully.'.format( - board_snr)) + self.logger.info('Board with serial number {} flashed successfully.'. + format(board_snr)) diff --git a/scripts/west_commands/runners/pyocd.py b/scripts/west_commands/runners/pyocd.py index 3c2c0e10fe1..6a167f4a3d7 100644 --- a/scripts/west_commands/runners/pyocd.py +++ b/scripts/west_commands/runners/pyocd.py @@ -6,8 +6,6 @@ import os -from west import log - from runners.core import ZephyrBinaryRunner, RunnerCaps, \ BuildConfiguration @@ -84,19 +82,10 @@ class PyOcdBinaryRunner(ZephyrBinaryRunner): @classmethod def create(cls, cfg, args): - daparg = os.environ.get('PYOCD_DAPARG') - if daparg: - log.wrn('Setting PYOCD_DAPARG in the environment is', - 'deprecated; use the --daparg option instead.') - if args.daparg is None: - log.dbg('Missing --daparg set to {} from environment'.format( - daparg), level=log.VERBOSE_VERY) - args.daparg = daparg - build_conf = BuildConfiguration(cfg.build_dir) flash_addr = cls.get_flash_address(args, build_conf) - return PyOcdBinaryRunner( + ret = PyOcdBinaryRunner( cfg, args.target, pyocd=args.pyocd, flash_addr=flash_addr, flash_opts=args.flash_opt, @@ -104,6 +93,14 @@ class PyOcdBinaryRunner(ZephyrBinaryRunner): board_id=args.board_id, daparg=args.daparg, frequency=args.frequency) + daparg = os.environ.get('PYOCD_DAPARG') + if not ret.daparg_args and daparg: + ret.logger.warning('PYOCD_DAPARG is deprecated; use --daparg') + ret.logger.debug('--daparg={} via PYOCD_DAPARG'.format(daparg)) + ret.daparg_args = ['-da', daparg] + + return ret + def port_args(self): return ['-p', str(self.gdb_port)] @@ -135,11 +132,12 @@ class PyOcdBinaryRunner(ZephyrBinaryRunner): self.flash_extra + [fname]) - log.inf('Flashing Target Device') + self.logger.info('Flashing Target Device') self.check_call(cmd) - def print_gdbserver_message(self): - log.inf('pyOCD GDB server running on port {}'.format(self.gdb_port)) + def log_gdbserver_message(self): + self.logger.info('pyOCD GDB server running on port {}'. + format(self.gdb_port)) def debug_debugserver(self, command, **kwargs): server_cmd = ([self.pyocd] + @@ -151,7 +149,7 @@ class PyOcdBinaryRunner(ZephyrBinaryRunner): self.frequency_args) if command == 'debugserver': - self.print_gdbserver_message() + self.log_gdbserver_message() self.check_call(server_cmd) else: if self.gdb_cmd is None: @@ -168,5 +166,5 @@ class PyOcdBinaryRunner(ZephyrBinaryRunner): '-ex', 'load'] self.require(client_cmd[0]) - self.print_gdbserver_message() + self.log_gdbserver_message() self.run_server_and_client(server_cmd, client_cmd) diff --git a/scripts/west_commands/tests/test_nrfjprog.py b/scripts/west_commands/tests/test_nrfjprog.py index 9238313c0cd..e9177a56445 100644 --- a/scripts/west_commands/tests/test_nrfjprog.py +++ b/scripts/west_commands/tests/test_nrfjprog.py @@ -210,14 +210,15 @@ def test_nrfjprog_init(cc, get_snr, req, test_case, runner_config): runner = NrfJprogBinaryRunner(runner_config, family, softreset, snr, erase=erase) - runner.run('flash') - - assert req.called - assert cc.call_args_list == [call(x) for x in - expected_commands(*test_case)] if snr is None: - get_snr.assert_called_once_with() + with pytest.raises(ValueError) as e: + runner.run('flash') + assert 'snr must not be None' in str(e) else: + runner.run('flash') + assert req.called + assert cc.call_args_list == [call(x) for x in + expected_commands(*test_case)] get_snr.assert_not_called()