Merge pull request #293 from mullender/fix/auth-precompute-stack-overflow

Fix/auth precompute stack overflow

Author: rednblkx

main/NfcManager.cpp

@@ -68,7 +68,12 @@ void NfcManager::initAuthPrecompute() {
     xQueueSend(m_authCtxFreeQueue, &item, 0);
   }
 
-  BaseType_t ok = xTaskCreateUniversal(authPrecomputeTaskEntry, "hk_auth_precompute", 4096, this, 3, &m_authPrecomputeTaskHandle, 0);
+  // 8192, not 4096: constructing a DDKAuthenticationContext runs mbedTLS P-256
+  // key generation. Measured usage is 4056-4288 bytes and varies with the
+  // random key material, so a 4096-byte stack left as little as 40 bytes of
+  // headroom and intermittently overflowed -- panicking mid-transaction, which
+  // the phone reported as a protocol error.
+  BaseType_t ok = xTaskCreateUniversal(authPrecomputeTaskEntry, "hk_auth_precompute", kAuthPrecomputeStackBytes, this, 3, &m_authPrecomputeTaskHandle, 0);
   if (ok != pdPASS || !m_authPrecomputeTaskHandle) {
     ESP_LOGE(TAG, "Failed to start auth precompute task.");
     m_authPrecomputeTaskHandle = nullptr;
@@ -160,6 +165,23 @@ void NfcManager::authPrecomputeTask() {
     const auto durationMs =
         std::chrono::duration_cast<std::chrono::milliseconds>(stopTime - startTime).count();
 
+
+    // Constructing the context runs mbedTLS P-256 key generation. Report the
+    // headroom straight after: an overflow here reboots the device mid-
+    // transaction, which is indistinguishable from a hang in the logs unless
+    // the reset reason is checked at boot.
+    {
+      const UBaseType_t freeWords = uxTaskGetStackHighWaterMark(nullptr);
+      const unsigned freeBytes = (unsigned)(freeWords * sizeof(StackType_t));
+      if (freeBytes < 768) {
+        ESP_LOGE(TAG, "precompute task stack CRITICALLY LOW: %u bytes free of %u",
+                 freeBytes, (unsigned)kAuthPrecomputeStackBytes);
+      } else {
+        ESP_LOGD(TAG, "precompute task stack headroom: %u bytes free of %u", freeBytes,
+                 (unsigned)kAuthPrecomputeStackBytes);
+      }
+    }
+
     if (!item->ctx) {
       ESP_LOGE(TAG, "Auth precompute: allocation failed.");
       xQueueSend(m_authCtxFreeQueue, &item, 0);
@@ -445,6 +467,21 @@ void NfcManager::handleTagPresence(const std::vector<uint8_t>& uid, const std::a
 
     auto stopTime = std::chrono::high_resolution_clock::now();
     ESP_LOGI(TAG, "Total processing time: %lli ms", std::chrono::duration_cast<std::chrono::milliseconds>(stopTime - startTime).count());
+    // Headroom check. This task runs mbedTLS P-256 operations (ECDH, ECDSA) on
+    // top of the reader's frame buffers, and an overflow here would look
+    // exactly like the observed symptom: a reboot part-way through a
+    // transaction. Reported every time so a downward trend is visible.
+    const UBaseType_t stackFreeWords = uxTaskGetStackHighWaterMark(nullptr);
+    if (stackFreeWords < 512) {
+      ESP_LOGW(TAG, "nfc task stack headroom LOW: %u bytes free",
+               (unsigned)(stackFreeWords * sizeof(StackType_t)));
+    } else {
+      ESP_LOGD(TAG, "nfc task stack headroom: %u bytes free",
+               (unsigned)(stackFreeWords * sizeof(StackType_t)));
+    }
+    ESP_LOGD(TAG, "heap: %u free, %u min-ever", (unsigned)esp_get_free_heap_size(),
+             (unsigned)esp_get_minimum_free_heap_size());
+
 }
 
 /**

main/include/NfcManager.hpp

@@ -95,6 +95,10 @@ class NfcManager {
 
     static const char* TAG;
     AppEventLoop::SubscriptionHandle m_hk_event;
+    // Stack for the hk_auth_precompute task. mbedTLS P-256 key generation was
+    // measured using 4056-4288 bytes, so 4096 was not survivable.
+    static constexpr uint32_t kAuthPrecomputeStackBytes = 8192;
+
     enum PinFunctions {
       SCK,
       MISO,

main/main.cpp

@@ -112,6 +112,36 @@ void setup() {
   if (err != ESP_OK) {
     ESP_LOGE("Main", "Failed to create default event loop: %d", err);
   }
+  // Why did we just boot? Without this a crash-reboot is indistinguishable in
+  // the logs from a hang: the log simply stops and later resumes. The reset
+  // reason separates a software panic from a watchdog timeout from a brownout,
+  // which need entirely different fixes.
+  {
+    const esp_reset_reason_t why = esp_reset_reason();
+    const char *name = "unknown";
+    switch (why) {
+      case ESP_RST_POWERON:  name = "power-on"; break;
+      case ESP_RST_EXT:      name = "external pin"; break;
+      case ESP_RST_SW:       name = "software restart"; break;
+      case ESP_RST_PANIC:    name = "PANIC (exception / assert)"; break;
+      case ESP_RST_INT_WDT:  name = "INTERRUPT WATCHDOG"; break;
+      case ESP_RST_TASK_WDT: name = "TASK WATCHDOG"; break;
+      case ESP_RST_WDT:      name = "other watchdog"; break;
+      case ESP_RST_DEEPSLEEP:name = "deep sleep wake"; break;
+      case ESP_RST_BROWNOUT: name = "BROWNOUT (supply dipped)"; break;
+      case ESP_RST_SDIO:     name = "SDIO"; break;
+      default: break;
+    }
+    const bool unexpected = (why == ESP_RST_PANIC || why == ESP_RST_INT_WDT ||
+                             why == ESP_RST_TASK_WDT || why == ESP_RST_WDT ||
+                             why == ESP_RST_BROWNOUT);
+    if (unexpected) {
+      ESP_LOGE("Boot", "*** UNEXPECTED RESET: %s (reason %d) ***", name, (int)why);
+    } else {
+      ESP_LOGI("Boot", "Reset reason: %s (%d)", name, (int)why);
+    }
+  }
+
   readerDataManager = std::make_unique<ReaderDataManager>();
   configManager = std::make_unique<ConfigManager>();
   configManager->begin();