Auto-Decode stacktraces (#214)

* Auto-Decode stacktraces

* Fix Gitlab CI

.gitlab-ci.yml

@@ -88,6 +88,10 @@ test2:
       docker tag \
         "${CI_REGISTRY}/ottowinter/esphomeyaml-hassio-${ADDON_ARCH}:${CI_COMMIT_SHA}" \
         "${CI_REGISTRY}/ottowinter/esphomeyaml-hassio-${ADDON_ARCH}:latest"
+    - |
+      docker tag \
+        "${CI_REGISTRY}/ottowinter/esphomeyaml-hassio-${ADDON_ARCH}:${CI_COMMIT_SHA}" \
+        "${CI_REGISTRY}/ottowinter/esphomeyaml-hassio-${ADDON_ARCH}:rc"
     - |
       docker tag \
         "${CI_REGISTRY}/ottowinter/esphomeyaml-hassio-${ADDON_ARCH}:${CI_COMMIT_SHA}" \
@@ -96,9 +100,16 @@ test2:
       docker tag \
         "ottowinter/esphomeyaml-hassio-${ADDON_ARCH}:${version}" \
         "ottowinter/esphomeyaml-hassio-${ADDON_ARCH}:latest"
+    - |
+      docker tag \
+        "ottowinter/esphomeyaml-hassio-${ADDON_ARCH}:${version}" \
+        "ottowinter/esphomeyaml-hassio-${ADDON_ARCH}:rc"
     - docker push "${CI_REGISTRY}/ottowinter/esphomeyaml-hassio-${ADDON_ARCH}:latest"
-    - docker push "ottowinter/esphomeyaml-hassio-${ADDON_ARCH}:${version}"
+    - docker push "${CI_REGISTRY}/ottowinter/esphomeyaml-hassio-${ADDON_ARCH}:rc"
+    - docker push "${CI_REGISTRY}/ottowinter/esphomeyaml-hassio-${ADDON_ARCH}:${version}"
     - docker push "ottowinter/esphomeyaml-hassio-${ADDON_ARCH}:latest"
+    - docker push "ottowinter/esphomeyaml-hassio-${ADDON_ARCH}:rc"
+    - docker push "ottowinter/esphomeyaml-hassio-${ADDON_ARCH}:${version}"
   only:
   - /^v\d+\.\d+\.\d+$/
   except:

esphomeyaml/__main__.py

@@ -7,16 +7,15 @@ import random
 import sys
 from datetime import datetime
 
-from esphomeyaml import const, core, core_config, mqtt, wizard, writer, yaml_util
+from esphomeyaml import const, core, core_config, mqtt, wizard, writer, yaml_util, platformio_api
 from esphomeyaml.config import get_component, iter_components, read_config
 from esphomeyaml.const import CONF_BAUD_RATE, CONF_BUILD_PATH, CONF_DOMAIN, CONF_ESPHOMEYAML, \
     CONF_HOSTNAME, CONF_LOGGER, CONF_MANUAL_IP, CONF_NAME, CONF_STATIC_IP, CONF_USE_CUSTOM_CODE, \
     CONF_WIFI, ESP_PLATFORM_ESP8266
 from esphomeyaml.core import ESPHomeYAMLError
 from esphomeyaml.helpers import AssignmentExpression, Expression, RawStatement, \
-    _EXPRESSIONS, add, \
+    _EXPRESSIONS, add, add_job, color, flush_tasks, indent, statement, relative_path
-    add_job, color, flush_tasks, indent, quote, statement, relative_path
+from esphomeyaml.util import safe_print, run_external_command
-from esphomeyaml.util import safe_print
 
 _LOGGER = logging.getLogger(__name__)
 
@@ -62,34 +61,6 @@ def choose_serial_port(config):
     return result[opt][0]
 
 
-def run_platformio(*cmd, **kwargs):
-    def mock_exit(return_code):
-        raise SystemExit(return_code)
-
-    orig_argv = sys.argv
-    orig_exit = sys.exit  # mock sys.exit
-    full_cmd = u' '.join(quote(x) for x in cmd)
-    _LOGGER.info(u"Running:  %s", full_cmd)
-    try:
-        func = kwargs.get('main')
-        if func is None:
-            import platformio.__main__
-            func = platformio.__main__.main
-        sys.argv = list(cmd)
-        sys.exit = mock_exit
-        return func() or 0
-    except KeyboardInterrupt:
-        return 1
-    except SystemExit as err:
-        return err.args[0]
-    except Exception as err:  # pylint: disable=broad-except
-        _LOGGER.error(u"Running platformio failed: %s", err)
-        _LOGGER.error(u"Please try running %s locally.", full_cmd)
-    finally:
-        sys.argv = orig_argv
-        sys.exit = orig_exit
-
-
 def run_miniterm(config, port, escape=False):
     import serial
     if CONF_LOGGER not in config:
@@ -100,6 +71,7 @@ def run_miniterm(config, port, escape=False):
         _LOGGER.info("UART logging is disabled (baud_rate=0). Not starting UART logs.")
     _LOGGER.info("Starting log output from %s with baud rate %s", port, baud_rate)
 
+    backtrace_state = False
     with serial.Serial(port, baudrate=baud_rate) as ser:
         while True:
             try:
@@ -114,6 +86,9 @@ def run_miniterm(config, port, escape=False):
                 message = message.replace('\033', '\\033')
             safe_print(message)
 
+            backtrace_state = platformio_api.process_stacktrace(
+                config, line, backtrace_state=backtrace_state)
+
 
 def write_cpp(config):
     _LOGGER.info("Generating C++ source...")
@@ -154,11 +129,7 @@ def write_cpp(config):
 
 def compile_program(args, config):
     _LOGGER.info("Compiling app...")
-    build_path = relative_path(config[CONF_ESPHOMEYAML][CONF_BUILD_PATH])
+    return platformio_api.run_compile(config, args.verbose)
-    command = ['platformio', 'run', '-d', build_path]
-    if args.verbose:
-        command.append('-v')
-    return run_platformio(*command)
 
 
 def get_upload_host(config):
@@ -176,10 +147,10 @@ def upload_using_esptool(config, port):
 
     build_path = relative_path(config[CONF_ESPHOMEYAML][CONF_BUILD_PATH])
     path = os.path.join(build_path, '.pioenvs', core.NAME, 'firmware.bin')
+    cmd = ['esptool.py', '--before', 'default_reset', '--after', 'hard_reset',
+           '--chip', 'esp8266', '--port', port, 'write_flash', '0x0', path]
     # pylint: disable=protected-access
-    return run_platformio('esptool.py', '--before', 'default_reset', '--after', 'hard_reset',
+    return run_external_command(esptool._main, *cmd)
-                          '--chip', 'esp8266', '--port', port, 'write_flash', '0x0',
-                          path, main=esptool._main)
 
 
 def upload_program(config, args, port):
@@ -190,11 +161,7 @@ def upload_program(config, args, port):
     if port != 'OTA' and serial_port:
         if core.ESP_PLATFORM == ESP_PLATFORM_ESP8266 and args.use_esptoolpy:
             return upload_using_esptool(config, port)
-        command = ['platformio', 'run', '-d', build_path,
+        return platformio_api.run_upload(config, args.verbose, port)
-                   '-t', 'upload', '--upload-port', port]
-        if args.verbose:
-            command.append('-v')
-        return run_platformio(*command)
 
     if 'ota' not in config:
         _LOGGER.error("No serial port found and OTA not enabled. Can't upload!")
@@ -243,7 +210,7 @@ def clean_mqtt(config, args):
 def setup_log(debug=False):
     log_level = logging.DEBUG if debug else logging.INFO
     logging.basicConfig(level=log_level)
-    fmt = "%(levelname)s [%(name)s] %(message)s"
+    fmt = "%(levelname)s %(message)s"
     colorfmt = "%(log_color)s{}%(reset)s".format(fmt)
     datefmt = '%H:%M:%S'
 

esphomeyaml/dashboard/dashboard.py

@@ -13,7 +13,8 @@ from esphomeyaml.const import CONF_ESPHOMEYAML, CONF_BUILD_PATH
 from esphomeyaml.core import ESPHomeYAMLError
 from esphomeyaml import const, core, __main__
 from esphomeyaml.__main__ import get_serial_ports
-from esphomeyaml.helpers import quote, relative_path
+from esphomeyaml.helpers import relative_path
+from esphomeyaml.util import shlex_quote
 
 try:
     import tornado
@@ -51,7 +52,7 @@ class EsphomeyamlCommandWebSocket(tornado.websocket.WebSocketHandler):
         if self.proc is not None:
             return
         command = self.build_command(message)
-        _LOGGER.debug(u"WebSocket opened for command %s", [quote(x) for x in command])
+        _LOGGER.debug(u"WebSocket opened for command %s", [shlex_quote(x) for x in command])
         self.proc = tornado.process.Subprocess(command,
                                                stdout=tornado.process.Subprocess.STREAM,
                                                stderr=subprocess.STDOUT)

esphomeyaml/helpers.py

@@ -1,10 +1,9 @@
 from __future__ import print_function
 
+from collections import OrderedDict, deque
 import inspect
 import logging
 import os
-import re
-from collections import OrderedDict, deque
 
 from esphomeyaml import core
 from esphomeyaml.const import CONF_AVAILABILITY, CONF_COMMAND_TOPIC, CONF_DISCOVERY, \
@@ -648,22 +647,6 @@ def setup_mqtt_component(obj, config):
                                      availability[CONF_PAYLOAD_NOT_AVAILABLE]))
 
 
-# shlex's quote for Python 2.7
-_find_unsafe = re.compile(r'[^\w@%+=:,./-]').search
-
-
-def quote(s):
-    """Return a shell-escaped version of the string *s*."""
-    if not s:
-        return u"''"
-    if _find_unsafe(s) is None:
-        return s
-
-    # use single quotes, and put single quotes into double quotes
-    # the string $'b is then quoted as '$'"'"'b'
-    return u"'" + s.replace(u"'", u"'\"'\"'") + u"'"
-
-
 def color(the_color, message='', reset=None):
     """Color helper."""
     from colorlog.escape_codes import escape_codes, parse_colors

esphomeyaml/platformio_api.py

@@ -0,0 +1,211 @@
+import json
+import logging
+import re
+import subprocess
+
+from esphomeyaml.const import CONF_BUILD_PATH, CONF_ESPHOMEYAML
+from esphomeyaml.helpers import relative_path
+from esphomeyaml.util import run_external_command
+
+_LOGGER = logging.getLogger(__name__)
+
+
+def run_platformio_cli(*args, **kwargs):
+    import platformio.__main__
+
+    cmd = ['platformio'] + list(args)
+    return run_external_command(platformio.__main__.main,
+                                *cmd, **kwargs)
+
+
+def run_platformio_cli_run(config, verbose, *args, **kwargs):
+    build_path = relative_path(config[CONF_ESPHOMEYAML][CONF_BUILD_PATH])
+    command = ['run', '-d', build_path]
+    if verbose:
+        command += ['-v']
+    command += list(args)
+    return run_platformio_cli(*command, **kwargs)
+
+
+def run_compile(config, verbose):
+    return run_platformio_cli_run(config, verbose)
+
+
+def run_upload(config, verbose, port):
+    return run_platformio_cli_run(config, verbose, '-t', 'upload', '--upload-port', port)
+
+
+def run_idedata(config):
+    args = ['-t', 'idedata']
+    stdout = run_platformio_cli_run(config, False, *args, capture_stdout=True)
+    match = re.search(r'{.*}', stdout)
+    if match is None:
+        return IDEData(None)
+    try:
+        return IDEData(json.loads(match.group()))
+    except ValueError:
+        return IDEData(None)
+
+
+IDE_DATA = None
+
+
+def get_idedata(config):
+    global IDE_DATA
+
+    if IDE_DATA is None:
+        _LOGGER.info("Need to fetch platformio IDE-data, please stand by")
+        IDE_DATA = run_idedata(config)
+    return IDE_DATA
+
+
+# ESP logs stack trace decoder, based on https://github.com/me-no-dev/EspExceptionDecoder
+ESP8266_EXCEPTION_CODES = {
+    0: "Illegal instruction",
+    1: "SYSCALL instruction",
+    2: "InstructionFetchError: Processor internal physical address or data error during "
+       "instruction fetch",
+    3: "LoadStoreError: Processor internal physical address or data error during load or store",
+    4: "Level1Interrupt: Level-1 interrupt as indicated by set level-1 bits in the INTERRUPT "
+       "register",
+    5: "Alloca: MOVSP instruction, if caller's registers are not in the register file",
+    6: "IntegerDivideByZero: QUOS, QUOU, REMS, or REMU divisor operand is zero",
+    7: "reserved",
+    8: "Privileged: Attempt to execute a privileged operation when CRING ? 0",
+    9: "LoadStoreAlignmentCause: Load or store to an unaligned address",
+    10: "reserved",
+    11: "reserved",
+    12: "InstrPIFDataError: PIF data error during instruction fetch",
+    13: "LoadStorePIFDataError: Synchronous PIF data error during LoadStore access",
+    14: "InstrPIFAddrError: PIF address error during instruction fetch",
+    15: "LoadStorePIFAddrError: Synchronous PIF address error during LoadStore access",
+    16: "InstTLBMiss: Error during Instruction TLB refill",
+    17: "InstTLBMultiHit: Multiple instruction TLB entries matched",
+    18: "InstFetchPrivilege: An instruction fetch referenced a virtual address at a ring level "
+        "less than CRING",
+    19: "reserved",
+    20: "InstFetchProhibited: An instruction fetch referenced a page mapped with an attribute "
+        "that does not permit instruction fetch",
+    21: "reserved",
+    22: "reserved",
+    23: "reserved",
+    24: "LoadStoreTLBMiss: Error during TLB refill for a load or store",
+    25: "LoadStoreTLBMultiHit: Multiple TLB entries matched for a load or store",
+    26: "LoadStorePrivilege: A load or store referenced a virtual address at a ring level less "
+        "than ",
+    27: "reserved",
+    28: "LoadProhibited: A load referenced a page mapped with an attribute that does not permit "
+        "loads",
+    29: "StoreProhibited: A store referenced a page mapped with an attribute that does not permit "
+        "stores",
+}
+
+
+def _decode_pc(config, addr):
+    idedata = get_idedata(config)
+    if not idedata.addr2line_path or not idedata.firmware_elf_path:
+        return
+    command = [idedata.addr2line_path, '-pfiaC', '-e', idedata.firmware_elf_path, addr]
+    try:
+        translation = subprocess.check_output(command).strip()
+    except Exception:  # pylint: disable=broad-except
+        return
+
+    if "?? ??:0" in translation:
+        # Nothing useful
+        return
+    translation = translation.replace(' at ??:?', '').replace(':?', '')
+    _LOGGER.warning("Decoded %s", translation)
+
+
+def _parse_register(config, regex, line):
+    match = regex.match(line)
+    if match is not None:
+        _decode_pc(config, match.group(1))
+
+
+STACKTRACE_ESP8266_EXCEPTION_TYPE_RE = re.compile(r'Exception \(([0-9]*)\):')
+STACKTRACE_ESP8266_PC_RE = re.compile(r'epc1=0x(4[0-9a-fA-F]{7})')
+STACKTRACE_ESP8266_EXCVADDR_RE = re.compile(r'excvaddr=0x(4[0-9a-fA-F]{7})')
+STACKTRACE_ESP32_PC_RE = re.compile(r'PC\s*:\s*(?:0x)?(4[0-9a-fA-F]{7})')
+STACKTRACE_ESP32_EXCVADDR_RE = re.compile(r'EXCVADDR\s*:\s*(?:0x)?(4[0-9a-fA-F]{7})')
+STACKTRACE_BAD_ALLOC_RE = re.compile(r'^last failed alloc call: (4[0-9a-fA-F]{7})\((\d+)\)$')
+STACKTRACE_ESP32_BACKTRACE_RE = re.compile(r'Backtrace:(?:\s+0x4[0-9a-fA-F]{7}:0x3[0-9a-fA-F]{7})+')
+STACKTRACE_ESP32_BACKTRACE_PC_RE = re.compile(r'4[0-9a-f]{7}')
+STACKTRACE_ESP8266_BACKTRACE_PC_RE = re.compile(r'4[0-9a-f]{7}')
+
+
+def process_stacktrace(config, line, backtrace_state):
+    line = line.strip()
+    # ESP8266 Exception type
+    match = re.match(STACKTRACE_ESP8266_EXCEPTION_TYPE_RE, line)
+    if match is not None:
+        code = match.group(1)
+        _LOGGER.warning("Exception type: %s", ESP8266_EXCEPTION_CODES.get(code, 'unknown'))
+
+    # ESP8266 PC/EXCVADDR
+    _parse_register(config, STACKTRACE_ESP8266_PC_RE, line)
+    _parse_register(config, STACKTRACE_ESP8266_EXCVADDR_RE, line)
+    # ESP32 PC/EXCVADDR
+    _parse_register(config, STACKTRACE_ESP32_PC_RE, line)
+    _parse_register(config, STACKTRACE_ESP32_EXCVADDR_RE, line)
+
+    # bad alloc
+    match = re.match(STACKTRACE_BAD_ALLOC_RE, line)
+    if match is not None:
+        _LOGGER.warning("Memory allocation of %s bytes failed at %s",
+                        match.group(2), match.group(1))
+        _decode_pc(config, match.group(1))
+
+    # ESP32 single-line backtrace
+    match = re.match(STACKTRACE_ESP32_BACKTRACE_RE, line)
+    if match is not None:
+        _LOGGER.warning("Found stack trace! Trying to decode it")
+        for addr in re.finditer(STACKTRACE_ESP32_BACKTRACE_PC_RE, line):
+            _decode_pc(config, addr.group())
+
+    # ESP8266 multi-line backtrace
+    if '>>>stack>>>' in line:
+        # Start of backtrace
+        backtrace_state = True
+        _LOGGER.warning("Found stack trace! Trying to decode it")
+    elif '<<<stack<<<' in line:
+        # End of backtrace
+        backtrace_state = False
+
+    if backtrace_state:
+        for addr in re.finditer(STACKTRACE_ESP8266_BACKTRACE_PC_RE, line):
+            _decode_pc(config, addr.group())
+
+    return backtrace_state
+
+
+class IDEData(object):
+    def __init__(self, raw):
+        if not isinstance(raw, dict):
+            self.raw = {}
+        else:
+            self.raw = raw
+
+    @property
+    def firmware_elf_path(self):
+        return self.raw.get("prog_path")
+
+    @property
+    def flash_extra_images(self):
+        return [
+            (x['path'], x['offset']) for x in self.raw.get("flash_extra_images", [])
+        ]
+
+    @property
+    def cc_path(self):
+        # For example /Users/<USER>/.platformio/packages/toolchain-xtensa32/bin/xtensa-esp32-elf-gcc
+        return self.raw.get("cc_path")
+
+    @property
+    def addr2line_path(self):
+        cc_path = self.cc_path
+        if cc_path is None:
+            return None
+        # replace gcc at end with addr2line
+        return cc_path[:-3] + 'addr2line'

esphomeyaml/util.py

@@ -1,5 +1,12 @@
 from __future__ import print_function
 
+import io
+import logging
+import re
+import sys
+
+_LOGGER = logging.getLogger(__name__)
+
 
 class Registry(dict):
     def register(self, name):
@@ -30,3 +37,47 @@ def safe_print(message=""):
         print(message.encode('ascii', 'backslashreplace'))
     except UnicodeEncodeError:
         print("Cannot print line because of invalid locale!")
+
+
+def shlex_quote(s):
+    if not s:
+        return u"''"
+    if re.search(r'[^\w@%+=:,./-]', s) is None:
+        return s
+
+    return u"'" + s.replace(u"'", u"'\"'\"'") + u"'"
+
+
+def run_external_command(func, *cmd, **kwargs):
+    def mock_exit(return_code):
+        raise SystemExit(return_code)
+
+    orig_argv = sys.argv
+    orig_exit = sys.exit  # mock sys.exit
+    full_cmd = u' '.join(shlex_quote(x) for x in cmd)
+    _LOGGER.info(u"Running:  %s", full_cmd)
+
+    capture_stdout = kwargs.get('capture_stdout', False)
+    if capture_stdout:
+        sys.stdout = io.BytesIO()
+
+    try:
+        sys.argv = list(cmd)
+        sys.exit = mock_exit
+        return func() or 0
+    except KeyboardInterrupt:
+        return 1
+    except SystemExit as err:
+        return err.args[0]
+    except Exception as err:  # pylint: disable=broad-except
+        _LOGGER.error(u"Running command failed: %s", err)
+        _LOGGER.error(u"Please try running %s locally.", full_cmd)
+    finally:
+        sys.argv = orig_argv
+        sys.exit = orig_exit
+
+        if capture_stdout:
+            # pylint: disable=lost-exception
+            stdout = sys.stdout.getvalue()
+            sys.stdout = sys.__stdout__
+            return stdout