Add support to display crash log and function call traceback addresse…

…s, fixes issue ratgdo#2

CHANGELOG.md

@@ -9,6 +9,7 @@ All notable changes to `homekit-ratgdo32` will be documented in this file. This
 ### What's Changed
 
 * Feature: Add user setting to enable/disable parking assist laser, and set duration of assist laser.
+* Feature: Added support to save log on crash (Issue #2)
 * Bugfix: Remove multiple copies of web page content from the firmware binary.
 * Bugfix: Use 64-bit integer to handle milliseconds since last boot.
 * Bugfix: Handle more possible return codes from vehicle distance sensor.

README.md

@@ -8,7 +8,6 @@
 > Firmware for the new DISCO device is under development. The following features, documented in this README, are not currently available in this version
 > and may never be implemented
 > 
-> * Crashlog display and download.
 > * Locking WiFi to specific WiFi access point.
 > * Setting WiFi protocol version.
 > * Setting WiFi transmit power.
@@ -278,7 +277,7 @@ If the OTA firmware update fails the following message will be displayed and you
 
 ### Esptool
 
-[Espressif](https://www.espressif.com) publishes [esptool](https://docs.espressif.com/projects/esptool/en/latest/esp8266/index.html), a command line utility built with python.  Esptool requires that you connect a USB serial cable to the ratgdo device.
+[Espressif](https://www.espressif.com) publishes [esptool](https://docs.espressif.com/projects/esptool/en/latest/esp32/index.html), a command line utility built with python.  Esptool requires that you connect a USB serial cable to the ratgdo device.
 
 > [!NOTE]
 > The ratgdo32 firmware comprises multiple files. It is strongly recommended to use the [online browser-based flash tool](https://ratgdo.github.io/homekit-ratgdo32/flash.html) described above rather than use this command directly
@@ -315,7 +314,7 @@ Resets and reboots the device. This will delete HomeKit pairing.
 ```
 curl -s http://<ip-address>/crashlog
 ```
-Returns details of the last crash including stack trace and the message log leading up to the crash. __Not currently implemented on ratgdo32 boards.__
+Returns details of the last crash including stack trace and the message log leading up to the crash.
 
 ### Clear crash log
 
@@ -412,7 +411,7 @@ has already found a fix.
 
 Great reliability improvements have been made in recent versions of the firmware, but it is possible that things can still go wrong. As noted above you should check that the door protocol is correctly set and if WiFi connection stability is suspected then you select a specific WiFi version.
 
-The footer of the webpage displays useful information that can help project contributors assist with diagnosing a problem. The ESP8266 is a low-memory device so monitoring actual memory usage is first place to start. Whenever you connect to the webpage, the firmware reports memory utilization every second... current available free heap, the lowest value that free heap has reached since last reboot, and the minimum available stack reached since last reboot.
+The footer of the webpage displays useful information that can help project contributors assist with diagnosing a problem. The ratgdo is a low-memory device so monitoring actual memory usage is first place to start. Whenever you connect to the webpage, the firmware reports memory utilization every second... current available free heap, the lowest value that free heap has reached since last reboot, and the minimum available stack reached since last reboot.
 
 In addition the last reboot date and time is reported (calculated by subtracting up-time from current time).
 

lib/ratgdo/log.h

@@ -25,32 +25,28 @@
 
 void print_packet(uint8_t *pkt);
 
-// #define LOG_MSG_BUFFER
-
-#ifdef LOG_MSG_BUFFER
-
 #define CRASH_LOG_MSG_FILE "/crash_log"
 #define REBOOT_LOG_MSG_FILE "/reboot_log"
 
 #if defined(MMU_IRAM_HEAP) || !defined(ESP8266)
 // This can be large, but not too large.  IRAM heap is approx 18KB, we also need
 // space for other data in here, so during development monitor logs and adjust
 // this smaller if necessary.  IRAM malloc's are all done during startup.
-#define LOG_BUFFER_SIZE 2048
+#define LOG_BUFFER_SIZE (1024 * 3)
 #else
 #define LOG_BUFFER_SIZE 1024
 #endif
 #define LINE_BUFFER_SIZE 256
 
-#ifdef ENABLE_CRASH_LOG
-void crashCallback();
-#endif
-
 extern bool syslogEn;
 extern uint16_t syslogPort;
 extern char syslogIP[16];
 extern bool suppressSerialLog;
 
+extern time_t rebootTime;
+extern time_t crashTime;
+extern int16_t crashCount;
+
 typedef struct logBuffer
 {
     uint16_t wrapped;                 // two bytes
@@ -74,30 +70,15 @@ class LOG
     static LOG *getInstance() { return instancePtr; }
 
     void logToBuffer(const char *fmt, ...);
-    void printSavedLog(Print &outDevice = Serial);
+    void printSavedLog(Print &outDevice = Serial, bool fromNVram = false);
     void printMessageLog(Print &outDevice = Serial);
-    void saveMessageLog();
+    void printCrashLog(Print &outDevice = Serial);
+    void saveMessageLog(bool toNVram = false);
 };
 
 extern LOG *ratgdoLogger;
 
 #define RATGDO_PRINTF(message, ...) ratgdoLogger->logToBuffer(PSTR(message), ##__VA_ARGS__)
 
-#define RINFO(tag, message, ...) RATGDO_PRINTF(">>> [%7llu] %s: " message "\n", millis64(), tag, ##__VA_ARGS__)
-#define RERROR(tag, message, ...) RATGDO_PRINTF("!!! [%7llu] %s: " message "\n", millis64(), tag, ##__VA_ARGS__)
-#else // LOG_MSG_BUFFER
-
-#ifndef UNIT_TEST
-
-#define RINFO(tag, message, ...) LOG0(">>> [%7llu] %s: " message "\n", millis64(), tag, ##__VA_ARGS__)
-#define RERROR(tag, message, ...) LOG0("!!! [%7llu] %s: " message "\n", millis64(), tag, ##__VA_ARGS__)
-
-#else // UNIT_TEST
-
-#include <stdio.h>
-#define RINFO(tag, message, ...) printf(">>> %s: " message "\n", tag, ##__VA_ARGS__)
-#define RERROR(tag, message, ...) printf("!!! %s: " message "\n", tag, ##__VA_ARGS__)
-
-#endif // UNIT_TEST
-
-#endif // LOG_MSG_BUFFER
+#define RINFO(tag, message, ...) RATGDO_PRINTF(">>> [%7lu.%03u] %s: " message "\n", (uint32_t)(millis64() / 1000LL), (uint16_t)(millis64() % 1000LL), tag, ##__VA_ARGS__)
+#define RERROR(tag, message, ...) RATGDO_PRINTF("!!! [%7lu.%03u] %s: " message "\n", (uint32_t)(millis64() / 1000LL), (uint16_t)(millis64() % 1000LL), tag, ##__VA_ARGS__)

platformio.ini

@@ -27,17 +27,14 @@ board_build.partitions = partitions.csv
 framework = arduino
 build_flags =
     ${env.build_flags}
-    -Wno-unused-variable
+    -Wall
+    -Wl,--wrap=esp_panic_handler
     -I./src
     -I./lib/ratgdo
     -D CORE_DEBUG_LEVEL=ARDUHAL_LOG_LEVEL_ERROR
     -D SOC_WIFI_SUPPORTED=1
-    -D LOG_MSG_BUFFER
-   ; -D ENABLE_CRASH_LOG
-    -D NTP_CLIENT
     -D USE_NTP_TIMESTAMP
-   ; -D GW_PING_CHECK
-;    -D CRASH_DEBUG
+    ;-D CRASH_DEBUG
 monitor_filters = esp32_exception_decoder
 lib_deps =
    https://github.com/ratgdo/espsoftwareserial.git#autobaud

src/log.cpp

@@ -18,6 +18,8 @@
 
 // Arduino includes
 #include <WiFiUdp.h>
+#include <esp32-hal.h>
+#include <esp_core_dump.h>
 
 // RATGDO project includes
 #include "ratgdo.h"
@@ -42,7 +44,6 @@ void print_packet(uint8_t *pkt)
 void print_packet(uint8_t pkt[SECPLUS2_CODE_LEN]) {}
 #endif // UNIT_TEST
 
-#ifdef LOG_MSG_BUFFER
 // Construct the singleton object for logger access
 LOG *LOG::instancePtr = new LOG();
 LOG *ratgdoLogger = LOG::getInstance();
@@ -54,17 +55,41 @@ char syslogIP[16] = "";
 WiFiUDP syslog;
 bool suppressSerialLog = false;
 
+// There is 8KB of RTC memory that can be set to not initialize on restart.
+// Data saved here will survive a crash and restart, but will not survive a power interruption.
+RTC_NOINIT_ATTR logBuffer rtcRebootLog;
+RTC_NOINIT_ATTR logBuffer rtcCrashLog;
+RTC_NOINIT_ATTR time_t rebootTime;
+RTC_NOINIT_ATTR time_t crashTime;
+RTC_NOINIT_ATTR int16_t crashCount;
+RTC_NOINIT_ATTR char reasonString[64];
+RTC_NOINIT_ATTR char crashVersion[16];
+
+void panic_handler(arduino_panic_info_t *info, void *arg)
+{
+    // crashCount could be negative... indicating that there is a core dump image, but no saved crash log.
+    // But now we are saving a crash log, so need to make sure it is positive.
+    crashCount = (crashCount < 0) ? 1 : crashCount + 1;
+    crashTime = (clockSet) ? time(NULL) : 0;
+    esp_rom_printf("Panic Handler, crash count %d\n", crashCount);
+    memcpy(&rtcCrashLog, ratgdoLogger->msgBuffer, sizeof(rtcCrashLog));
+    strlcpy(reasonString, info->reason, sizeof(reasonString));
+    strlcpy(crashVersion, AUTO_VERSION, sizeof(crashVersion));
+}
+
 // Constructor for LOG class
 LOG::LOG()
 {
     logMutex = xSemaphoreCreateRecursiveMutex();
     msgBuffer = (logBuffer *)malloc(sizeof(logBuffer));
-    // Fill the buffer with space chars... because if we crash and dump buffer before it fills
+    // Zero out the buffer... because if we crash and dump buffer before it fills
     // up, we want blank space not garbage!
-    memset(msgBuffer->buffer, 0x20, sizeof(msgBuffer->buffer));
+    memset(msgBuffer->buffer, 0, sizeof(msgBuffer->buffer));
     msgBuffer->wrapped = 0;
     msgBuffer->head = 0;
     lineBuffer = (char *)malloc(LINE_BUFFER_SIZE);
+
+    set_arduino_panic_handler(panic_handler, NULL);
 }
 
 void LOG::logToBuffer(const char *fmt, ...)
@@ -116,9 +141,9 @@ void LOG::logToBuffer(const char *fmt, ...)
     return;
 }
 
-void LOG::saveMessageLog()
+void LOG::saveMessageLog(bool toNVram)
 {
-    RINFO(TAG, "Save message log buffer to NVRAM");
+    RINFO(TAG, "Save message log buffer%s", toNVram ? "to NVRAM" : "");
     xSemaphoreTakeRecursive(logMutex, portMAX_DELAY);
     // We start by rotating the circular buffer so it is all in order.
     uint16_t first = 0;
@@ -136,19 +161,33 @@ void LOG::saveMessageLog()
     //  reset the index
     msgBuffer->head = 0;
     msgBuffer->wrapped = 0;
-    nvRam->writeBlob(nvram_messageLog, msgBuffer->buffer, sizeof(msgBuffer->buffer));
+    memcpy(&rtcRebootLog, ratgdoLogger->msgBuffer, sizeof(rtcRebootLog));
+    rebootTime = (clockSet) ? time(NULL) : 0;
+    if (toNVram)
+        nvRam->writeBlob(nvram_messageLog, msgBuffer->buffer, sizeof(msgBuffer->buffer));
     xSemaphoreGiveRecursive(logMutex);
 }
 
-void LOG::printSavedLog(Print &outputDev)
+void LOG::printSavedLog(Print &outputDev, bool fromNVram)
 {
-    RINFO(TAG, "Print saved log from NVRAM");
-    char *buf = (char *)malloc(sizeof(msgBuffer->buffer));
-    if (buf)
+    RINFO(TAG, "Print saved log%s", fromNVram ? " from NVRAM" : "");
+    if (fromNVram)
     {
-        nvRam->readBlob(nvram_messageLog, buf, sizeof(msgBuffer->buffer));
-        outputDev.print(buf);
-        free(buf);
+        char *buf = (char *)malloc(sizeof(msgBuffer->buffer));
+        if (buf)
+        {
+            nvRam->readBlob(nvram_messageLog, buf, sizeof(msgBuffer->buffer));
+            outputDev.print(buf);
+            free(buf);
+        }
+    }
+    else if (rebootTime != 0)
+    {
+        outputDev.print(rtcRebootLog.buffer);
+    }
+    else
+    {
+        outputDev.print("\nNo saved log available\n");
     }
 }
 
@@ -161,20 +200,12 @@ extern "C" uint32_t __crc_val;
 void LOG::printMessageLog(Print &outputDev)
 {
     xSemaphoreTakeRecursive(logMutex, portMAX_DELAY);
-#ifdef NTP_CLIENT
     if (enableNTP && clockSet)
     {
         outputDev.printf("Server time: %s\n", timeString());
     }
-#endif
-    outputDev.printf("Server uptime (ms): %llu\n", millis64());
+    outputDev.printf("Server uptime (secs): %lu.%03u\n", (uint32_t)(millis64() / 1000LL), (uint16_t)(millis64() % 1000LL));
     outputDev.printf("Firmware version: %s\n", AUTO_VERSION);
-#ifdef ESP8266
-    outputDev.write("Flash CRC: 0x");
-    outputDev.println(__crc_val, 16);
-    outputDev.write("Flash length: ");
-    outputDev.println(__crc_len);
-#endif
     outputDev.printf("Free heap: %lu\n", free_heap);
     outputDev.printf("Minimum heap: %lu\n\n", min_heap);
     if (msgBuffer)
@@ -186,7 +217,60 @@ void LOG::printMessageLog(Print &outputDev)
             outputDev.write(&msgBuffer->buffer[start], sizeof(msgBuffer->buffer) - start);
         }
         outputDev.print(msgBuffer->buffer); // assumes null terminated
-        // outputDev.write(msgBuffer->buffer, start);
+    }
+    xSemaphoreGiveRecursive(logMutex);
+}
+
+void LOG::printCrashLog(Print &outputDev)
+{
+    xSemaphoreTakeRecursive(logMutex, portMAX_DELAY);
+    if (crashCount > 0)
+    {
+        outputDev.printf("Time of crash: %s\n", timeString(crashTime));
+        outputDev.printf("Crash reason: %s\n", reasonString);
+        outputDev.printf("Firmware version: %s\n\n", crashVersion);
+        // head points to a zero (null terminator of previous log line) which we need to skip.
+        size_t start = (rtcCrashLog.head + 1) % sizeof(rtcCrashLog.buffer);
+        if (rtcCrashLog.wrapped != 0)
+        {
+            outputDev.write(&rtcCrashLog.buffer[start], sizeof(rtcCrashLog.buffer) - start);
+        }
+        outputDev.print(rtcCrashLog.buffer); // assumes null terminated
+    }
+
+    if (esp_core_dump_image_check() == ESP_OK)
+    {
+        esp_core_dump_summary_t *summary = (esp_core_dump_summary_t *)malloc(sizeof(esp_core_dump_summary_t));
+        if (summary)
+        {
+            if (esp_core_dump_get_summary(summary) == ESP_OK)
+            {
+                if (crashCount <= 0)
+                    outputDev.print("No saved crash log available for core dump.");
+
+                outputDev.print("\n\n");
+                outputDev.printf("Crash in task: %s, at address: 0x%08lX\n", summary->exc_task, summary->exc_pc);
+                outputDev.print("Decode backtrace with this Linux command:\n\n");
+                if (crashCount > 0)
+                    outputDev.printf("addr2line -p -f -C -e homekit-ratgdo32-v%s.elf \\\n", crashVersion);
+                else
+                    outputDev.print("addr2line -p -f -C -e firmware.elf \\\n");
+                outputDev.print(" -a ");
+                for (int i = 0; i < summary->exc_bt_info.depth; i++)
+                {
+                    outputDev.printf("0x%08lX ", summary->exc_bt_info.bt[i]);
+                    if (((i + 1) % 6) == 0 && ((i + 1) < summary->exc_bt_info.depth))
+                        outputDev.print("\\\n    ");
+                }
+                outputDev.print("\n\n");
+                outputDev.print("Make sure that the ELF file matches the binary that crashed.\n");
+            }
+        }
+        free(summary);
+    }
+    else
+    {
+        outputDev.print("\n\nNo core dump image available.\n");
     }
     xSemaphoreGiveRecursive(logMutex);
 }
@@ -233,7 +317,7 @@ void logToSyslog(char *message)
     syslog.beginPacket(syslogIP, syslogPort);
     // Use RFC5424 Format
     syslog.printf("<%u>1 ", PRI); // PRI code
-#if defined(NTP_CLIENT) && defined(USE_NTP_TIMESTAMP)
+#if defined(USE_NTP_TIMESTAMP)
     syslog.print((enableNTP && clockSet) ? timeString(0, true) : SYSLOG_NIL);
 #else
     syslog.print(SYSLOG_NIL); // Time - let the syslog server insert time
@@ -253,22 +337,3 @@ void logToSyslog(char *message)
     syslog.print(msg); // message
     syslog.endPacket();
 }
-
-#ifdef ENABLE_CRASH_LOG
-// TODO handle crashdump log
-void crashCallback()
-{
-    if (ratgdoLogger->msgBuffer && ratgdoLogger->logMessageFile)
-    {
-        // ratgdoLogger->logMessageFile.truncate(0);
-        ratgdoLogger->logMessageFile.seek(0, fs::SeekSet);
-        ratgdoLogger->logMessageFile.println();
-        ratgdoLogger->printMessageLog(ratgdoLogger->logMessageFile);
-        ratgdoLogger->logMessageFile.close();
-    }
-    // We may not have enough memory to open the file and save the code
-    // save_rolling_code();
-}
-#endif
-
-#endif // LOG_MSG_BUFFER