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

@@ -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

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"))

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

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

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)

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)
 

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:
+            # 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')
-            except UnicodeEncodeError:
-                pass
-
         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,