From 80214640b1f5f31ddbd5fb09caa577b20be73255 Mon Sep 17 00:00:00 2001 From: Otto Winter Date: Sat, 19 Oct 2019 14:04:14 +0200 Subject: [PATCH] Filter some debug lines from PlatformIO in output (#771) * Filter some debug lines from PlatformIO in output * Lint * Strip trailing newline from esp-idf output * Only create global std::string if on esp32 --- esphome/__main__.py | 9 ++--- esphome/config.py | 4 +-- esphome/core.py | 2 ++ esphome/core/log.cpp | 14 +++++++- esphome/core/log.h | 2 ++ esphome/platformio_api.py | 26 +++++++++++++++ esphome/util.py | 69 ++++++++++++++++++++++++++++++++------- 7 files changed, 107 insertions(+), 19 deletions(-) diff --git a/esphome/__main__.py b/esphome/__main__.py index 62c15fda6b..403bf89401 100644 --- a/esphome/__main__.py +++ b/esphome/__main__.py @@ -160,7 +160,7 @@ def compile_program(args, config): from esphome import platformio_api _LOGGER.info("Compiling app...") - return platformio_api.run_compile(config, args.verbose) + return platformio_api.run_compile(config, CORE.verbose) def upload_using_esptool(config, port): @@ -184,7 +184,7 @@ def upload_program(config, args, host): if CORE.is_esp8266: return upload_using_esptool(config, host) - return platformio_api.run_upload(config, args.verbose, host) + return platformio_api.run_upload(config, CORE.verbose, host) from esphome import espota2 @@ -221,6 +221,7 @@ def clean_mqtt(config, args): def setup_log(debug=False, quiet=False): if debug: log_level = logging.DEBUG + CORE.verbose = True elif quiet: log_level = logging.CRITICAL else: @@ -258,7 +259,7 @@ def command_wizard(args): def command_config(args, config): _LOGGER.info("Configuration is valid!") - if not args.verbose: + if not CORE.verbose: config = strip_default_ids(config) safe_print(yaml_util.dump(config)) return 0 @@ -519,7 +520,7 @@ def run_esphome(argv): CORE.config_path = conf_path CORE.dashboard = args.dashboard - config = read_config(args.verbose) + config = read_config() if config is None: return 1 CORE.config = config diff --git a/esphome/config.py b/esphome/config.py index 9141341c61..5906e2fc95 100644 --- a/esphome/config.py +++ b/esphome/config.py @@ -802,7 +802,7 @@ def strip_default_ids(config): return config -def read_config(verbose): +def read_config(): _LOGGER.info("Reading configuration %s...", CORE.config_path) try: res = load_config() @@ -810,7 +810,7 @@ def read_config(verbose): _LOGGER.error(u"Error while reading config: %s", err) return None if res.errors: - if not verbose: + if not CORE.verbose: res = strip_default_ids(res) safe_print(color('bold_red', u"Failed config")) diff --git a/esphome/core.py b/esphome/core.py index b1fd866c76..82ce196cab 100644 --- a/esphome/core.py +++ b/esphome/core.py @@ -507,6 +507,8 @@ class EsphomeCore(object): self.loaded_integrations = set() # A set of component IDs to track what Component subclasses are declared self.component_ids = set() + # Whether ESPHome was started in verbose mode + self.verbose = False def reset(self): self.dashboard = False diff --git a/esphome/core/log.cpp b/esphome/core/log.cpp index 6b6ee05f4e..15d49c0038 100644 --- a/esphome/core/log.cpp +++ b/esphome/core/log.cpp @@ -46,15 +46,27 @@ void HOT esp_log_vprintf_(int level, const char *tag, int line, const __FlashStr } #endif +#ifdef ARDUINO_ARCH_ESP32 int HOT esp_idf_log_vprintf_(const char *format, va_list args) { // NOLINT #ifdef USE_LOGGER auto *log = logger::global_logger; if (log == nullptr) return 0; - log->log_vprintf_(ESPHOME_LOG_LEVEL, "", 0, format, args); + size_t len = strlen(format); + if (format[len - 1] == '\n') { + // Remove trailing newline from format + // Use locally stored + static std::string FORMAT_COPY; + FORMAT_COPY.clear(); + FORMAT_COPY.insert(0, format, len - 1); + format = FORMAT_COPY.c_str(); + } + + log->log_vprintf_(ESPHOME_LOG_LEVEL, "esp-idf", 0, format, args); #endif return 0; } +#endif } // namespace esphome diff --git a/esphome/core/log.h b/esphome/core/log.h index 85f07c0537..361fbe1182 100644 --- a/esphome/core/log.h +++ b/esphome/core/log.h @@ -55,7 +55,9 @@ void esp_log_vprintf_(int level, const char *tag, int line, const char *format, #ifdef USE_STORE_LOG_STR_IN_FLASH void esp_log_vprintf_(int level, const char *tag, int line, const __FlashStringHelper *format, va_list args); #endif +#ifdef ARDUINO_ARCH_ESP32 int esp_idf_log_vprintf_(const char *format, va_list args); // NOLINT +#endif #ifdef USE_STORE_LOG_STR_IN_FLASH #define ESPHOME_LOG_FORMAT(format) F(format) diff --git a/esphome/platformio_api.py b/esphome/platformio_api.py index 348c53af11..29096ba7af 100644 --- a/esphome/platformio_api.py +++ b/esphome/platformio_api.py @@ -39,12 +39,38 @@ def patch_structhash(): command.clean_build_dir = patched_clean_build_dir +IGNORE_LIB_WARNINGS = r'(?:' + '|'.join(['Hash', 'Update']) + r')' +FILTER_PLATFORMIO_LINES = [ + r'Verbose mode can be enabled via `-v, --verbose` option.*', + r'CONFIGURATION: https://docs.platformio.org/.*', + r'PLATFORM: .*', + r'DEBUG: Current.*', + r'PACKAGES: .*', + r'LDF: Library Dependency Finder -> http://bit.ly/configure-pio-ldf.*', + r'LDF Modes: Finder ~ chain, Compatibility ~ soft.*', + r'Looking for ' + IGNORE_LIB_WARNINGS + r' library in registry', + r"Warning! Library `.*'" + IGNORE_LIB_WARNINGS + + r".*` has not been found in PlatformIO Registry.", + r"You can ignore this message, if `.*" + IGNORE_LIB_WARNINGS + r".*` is a built-in library.*", + r'Scanning dependencies...', + r"Found \d+ compatible libraries", + r'Memory Usage -> http://bit.ly/pio-memory-usage', + r'esptool.py v.*', + r"Found: https://platformio.org/lib/show/.*", + r"Using cache: .*", + r'Installing dependencies', +] + + def run_platformio_cli(*args, **kwargs): os.environ["PLATFORMIO_FORCE_COLOR"] = "true" os.environ["PLATFORMIO_BUILD_DIR"] = os.path.abspath(CORE.relative_pioenvs_path()) os.environ["PLATFORMIO_LIBDEPS_DIR"] = os.path.abspath(CORE.relative_piolibdeps_path()) cmd = ['platformio'] + list(args) + if not CORE.verbose: + kwargs['filter_lines'] = FILTER_PLATFORMIO_LINES + if os.environ.get('ESPHOME_USE_SUBPROCESS') is not None: return run_external_process(*cmd, **kwargs) diff --git a/esphome/util.py b/esphome/util.py index 868e5d49e4..098d5e52da 100644 --- a/esphome/util.py +++ b/esphome/util.py @@ -9,7 +9,7 @@ import subprocess import sys from esphome import const -from esphome.py_compat import IS_PY2 +from esphome.py_compat import IS_PY2, decode_text, text_type _LOGGER = logging.getLogger(__name__) @@ -88,24 +88,67 @@ def shlex_quote(s): return u"'" + s.replace(u"'", u"'\"'\"'") + u"'" +ANSI_ESCAPE = re.compile(r'\033[@-_][0-?]*[ -/]*[@-~]') + + class RedirectText(object): - def __init__(self, out): + def __init__(self, out, filter_lines=None): self._out = out + if filter_lines is None: + self._filter_pattern = None + else: + pattern = r'|'.join(r'(?:' + pattern + r')' for pattern in filter_lines) + self._filter_pattern = re.compile(pattern) + self._line_buffer = '' def __getattr__(self, item): return getattr(self._out, item) - def write(self, s): + def _write_color_replace(self, s): from esphome.core import CORE if CORE.dashboard: - try: - s = s.replace('\033', '\\033') - except UnicodeEncodeError: - pass - + # With the dashboard, we must create a little hack to make color output + # work. The shell we create in the dashboard is not a tty, so python removes + # all color codes from the resulting stream. We just convert them to something + # we can easily recognize later here. + s = s.replace('\033', '\\033') self._out.write(s) + def write(self, s): + # s is usually a text_type already (self._out is of type TextIOWrapper) + # However, s is sometimes also a bytes object in python3. Let's make sure it's a + # text_type + # If the conversion fails, we will create an exception, which is okay because we won't + # be able to print it anyway. + text = decode_text(s) + assert isinstance(text, text_type) + + if self._filter_pattern is not None: + self._line_buffer += text + lines = self._line_buffer.splitlines(True) + for line in lines: + if '\n' not in line and '\r' not in line: + # Not a complete line, set line buffer + self._line_buffer = line + break + self._line_buffer = '' + + line_without_ansi = ANSI_ESCAPE.sub('', line) + line_without_end = line_without_ansi.rstrip() + if self._filter_pattern.match(line_without_end) is not None: + # Filter pattern matched, ignore the line + continue + + self._write_color_replace(line) + else: + self._write_color_replace(text) + + # write() returns the number of characters written + # Let's print the number of characters of the original string in order to not confuse + # any caller. + return len(s) + # pylint: disable=no-self-use def isatty(self): return True @@ -120,10 +163,11 @@ def run_external_command(func, *cmd, **kwargs): full_cmd = u' '.join(shlex_quote(x) for x in cmd) _LOGGER.info(u"Running: %s", full_cmd) + filter_lines = kwargs.get('filter_lines') orig_stdout = sys.stdout - sys.stdout = RedirectText(sys.stdout) + sys.stdout = RedirectText(sys.stdout, filter_lines=filter_lines) orig_stderr = sys.stderr - sys.stderr = RedirectText(sys.stderr) + sys.stderr = RedirectText(sys.stderr, filter_lines=filter_lines) capture_stdout = kwargs.get('capture_stdout', False) if capture_stdout: @@ -155,14 +199,15 @@ def run_external_command(func, *cmd, **kwargs): def run_external_process(*cmd, **kwargs): full_cmd = u' '.join(shlex_quote(x) for x in cmd) _LOGGER.info(u"Running: %s", full_cmd) + filter_lines = kwargs.get('filter_lines') capture_stdout = kwargs.get('capture_stdout', False) if capture_stdout: sub_stdout = io.BytesIO() else: - sub_stdout = RedirectText(sys.stdout) + sub_stdout = RedirectText(sys.stdout, filter_lines=filter_lines) - sub_stderr = RedirectText(sys.stderr) + sub_stderr = RedirectText(sys.stderr, filter_lines=filter_lines) try: return subprocess.call(cmd,