snapshot

sketches/doorbell/doorbell.ino

@@ -39,6 +39,9 @@ Arduino_DataBus *bus = new Arduino_HWSPI(15, 14, 7, 6, -1);
 Arduino_GFX *gfx = new Arduino_ST7789(bus, 21, 1, true, 172, 320, 34, 0, 34, 0);
 
 enum State { STATE_SILENT, STATE_ALERT };
+enum LogLevel { LOG_DEBUG, LOG_INFO, LOG_WARN, LOG_ERROR, LOG_FATAL };
+
+const LogLevel CURRENT_LOG_LEVEL = LOG_DEBUG;
 
 State currentState = STATE_SILENT;
 State lastPublishedState = STATE_SILENT;
@@ -48,6 +51,7 @@ unsigned long lastSilencePoll = 0;
 unsigned long nextPollTime = 0;
 unsigned long blinkStartTime = 0;
 bool blinkPhase = false;
+bool backlightState = false;  // Explicit tracking
 
 String lastCommandId = "";
 String lastSilenceId = "";
@@ -56,24 +60,81 @@ String alertMessage = "";
 
 unsigned long long epochOffsetMs = 0;
 
+// ============== PROFESSIONAL LOGGING ==============
+
+void logMessage(LogLevel level, const char* component, const char* message) {
+  if (level < CURRENT_LOG_LEVEL) return;
+
+  const char* levelStr;
+  switch (level) {
+    case LOG_DEBUG: levelStr = "DEBUG"; break;
+    case LOG_INFO:  levelStr = "INFO "; break;
+    case LOG_WARN:  levelStr = "WARN "; break;
+    case LOG_ERROR: levelStr = "ERROR"; break;
+    case LOG_FATAL: levelStr = "FATAL"; break;
+    default:        levelStr = "?????"; break;
+  }
+
+  char timestamp[32];
+  formatIsoTimestamp(timestamp, sizeof(timestamp));
+
+  Serial.print(timestamp);
+  Serial.print(" [");
+  Serial.print(levelStr);
+  Serial.print("] ");
+  Serial.print(component);
+  Serial.print(": ");
+  Serial.println(message);
+}
+
+void logValue(LogLevel level, const char* component, const char* name, long long value) {
+  if (level < CURRENT_LOG_LEVEL) return;
+  char buf[128];
+  snprintf(buf, sizeof(buf), "%s=%lld", name, value);
+  logMessage(level, component, buf);
+}
+
+void logString(LogLevel level, const char* component, const char* name, const String& value) {
+  if (level < CURRENT_LOG_LEVEL) return;
+  char buf[256];
+  snprintf(buf, sizeof(buf), "%s=[%s]", name, value.c_str());
+  logMessage(level, component, buf);
+}
+
+void formatIsoTimestamp(char* buf, size_t len) {
+  unsigned long long epochMs = getEpochMs();
+  time_t seconds = epochMs / 1000;
+  unsigned int ms = epochMs % 1000;
+
+  struct tm* tm = gmtime(&seconds);
+  snprintf(buf, len, "%04d-%02d-%02dT%02d:%02d:%02d.%03dZ",
+    tm->tm_year + 1900, tm->tm_mon + 1, tm->tm_mday,
+    tm->tm_hour, tm->tm_min, tm->tm_sec, ms);
+}
+
+// ============== SETUP ==============
+
 void setup() {
   Serial.begin(115200);
   delay(3000);
-  Serial.println("\n=== KLUBHAUS DOORBELL v3.6.1 ===");
+
-  Serial.println("Fix: restored missing loop() function");
+  logMessage(LOG_INFO, "MAIN", "=== KLUBHAUS DOORBELL v3.7 ===");
+  logMessage(LOG_INFO, "MAIN", "Features: structured logging, epoch timestamps, backlight fix");
 
   pinMode(BACKLIGHT_PIN, OUTPUT);
-  digitalWrite(BACKLIGHT_PIN, LOW);
+  setBacklight(false);  // Start OFF
   pinMode(BUTTON_PIN, INPUT_PULLUP);
 
   gfx->begin();
-  digitalWrite(BACKLIGHT_PIN, HIGH);
+  setBacklight(true);  // ON for test
   testDisplay();
   delay(300);
 
   transitionTo(STATE_SILENT);
 
+  logMessage(LOG_INFO, "WIFI", "Connecting...");
   WiFi.begin(ssid, password);
+
   int timeout = 0;
   while (WiFi.status() != WL_CONNECTED && timeout < 40) {
     delay(500);
@@ -82,51 +143,65 @@ void setup() {
   }
 
   if (WiFi.status() != WL_CONNECTED) {
-    Serial.println("\nWiFi FAILED");
+    Serial.println();
+    logMessage(LOG_FATAL, "WIFI", "Connection failed");
     showFatalError("OFFLINE");
-  } else {
+    return;
-    Serial.println("\nWiFi OK: " + WiFi.localIP().toString());
-    initEpochTime();
-    publishStatus();
   }
 
-  Serial.println("=== READY ===");
+  Serial.println();
+  char ipBuf[64];
+  snprintf(ipBuf, sizeof(ipBuf), "Connected: %s", WiFi.localIP().toString().c_str());
+  logMessage(LOG_INFO, "WIFI", ipBuf);
+
+  initEpochTime();
+  publishStatus();
+
+  logMessage(LOG_INFO, "MAIN", "=== READY ===");
+}
+
+// ============== BACKLIGHT CONTROL ==============
+
+void setBacklight(bool on) {
+  digitalWrite(BACKLIGHT_PIN, on ? HIGH : LOW);
+  if (backlightState != on) {
+    backlightState = on;
+    logValue(LOG_DEBUG, "BACKLIGHT", "state", on ? 1 : 0);
+  }
 }
 
 // ============== EPOCH TIME ==============
 
 void initEpochTime() {
+  logMessage(LOG_INFO, "TIME", "Initializing NTP...");
   configTime(0, 0, "pool.ntp.org", "time.nist.gov");
 
-  Serial.print("Syncing NTP...");
   time_t now = 0;
   int retries = 0;
   while (now < 1000000000 && retries < 30) {
     delay(500);
     now = time(nullptr);
-    Serial.print(".");
     retries++;
   }
 
   if (now > 1000000000) {
     epochOffsetMs = (now * 1000ULL) - millis();
-    Serial.println(" OK");
+    logValue(LOG_INFO, "TIME", "epochOffsetMs", (long long)epochOffsetMs);
-    Serial.print("Epoch offset: ");
+    char ts[32];
-    Serial.println((unsigned long)epochOffsetMs);
+    formatIsoTimestamp(ts, sizeof(ts));
+    logString(LOG_INFO, "TIME", "syncedAt", ts);
   } else {
-    Serial.println(" FAILED — using boot-relative time");
+    logMessage(LOG_WARN, "TIME", "NTP sync failed — using boot-relative timestamps");
     epochOffsetMs = 0;
   }
 }
 
 unsigned long long getEpochMs() {
-  if (epochOffsetMs == 0) {
+  if (epochOffsetMs == 0) return millis();
-    return millis();
-  }
   return epochOffsetMs + millis();
 }
 
-// ============== MAIN LOOP (RESTORED) ==============
+// ============== MAIN LOOP ==============
 
 void loop() {
   unsigned long now = millis();
@@ -157,7 +232,7 @@ void loop() {
       }
       updateBlink(now);
       if (now - blinkStartTime >= BLINK_DURATION) {
-        Serial.println("ALERT TIMEOUT");
+        logMessage(LOG_INFO, "STATE", "Alert timeout — transitioning to SILENT");
         transitionTo(STATE_SILENT);
       }
       break;
@@ -170,10 +245,12 @@ void loop() {
 
 void publishStatus() {
   if (WiFi.status() != WL_CONNECTED) {
-    Serial.println("Status: skip (no WiFi)");
+    logMessage(LOG_WARN, "HTTP", "Status publish skipped — no WiFi");
     return;
   }
 
+  logMessage(LOG_DEBUG, "HTTP", "POST /STATUS_klubhaus_topic");
+
   HTTPClient http;
   http.begin(STATUS_POST_URL);
   http.addHeader("Content-Type", "text/plain");
@@ -186,10 +263,13 @@ void publishStatus() {
   String payload;
   serializeJson(doc, payload);
 
+  unsigned long reqStart = millis();
   int code = http.POST(payload);
-  Serial.print("Status: ");
+  unsigned long duration = millis() - reqStart;
-  Serial.print(payload);
+
-  Serial.println(String(" (") + code + ")");
+  char logBuf[512];
+  snprintf(logBuf, sizeof(logBuf), "status=%d duration=%lums payload=%s", code, duration, payload.c_str());
+  logString(LOG_INFO, "HTTP", "response", logBuf);
 
   http.end();
   lastPublishedState = currentState;
@@ -198,10 +278,7 @@ void publishStatus() {
 void transitionTo(State newState) {
   if (newState == currentState) return;
 
-  Serial.print("STATE: ");
+  logMessage(LOG_INFO, "STATE", newState == STATE_SILENT ? "SILENT <- ALERT" : "ALERT <- SILENT");
-  Serial.print(currentState == STATE_SILENT ? "SILENT" : "ALERT");
-  Serial.print(" -> ");
-  Serial.println(newState == STATE_SILENT ? "SILENT" : "ALERT");
 
   currentState = newState;
 
@@ -209,11 +286,11 @@ void transitionTo(State newState) {
     case STATE_SILENT:
       alertMessage = "";
       gfx->fillScreen(COLOR_BLACK);
-      digitalWrite(BACKLIGHT_PIN, LOW);
+      setBacklight(false);  // EXPLICIT OFF
       break;
 
     case STATE_ALERT:
-      digitalWrite(BACKLIGHT_PIN, HIGH);
+      setBacklight(true);   // EXPLICIT ON
       blinkStartTime = millis();
       blinkPhase = false;
       drawAlertScreen(ALERT_BG_1, ALERT_TEXT_1);
@@ -226,50 +303,66 @@ void transitionTo(State newState) {
 // ============== TOPIC POLLING ==============
 
 void checkCommandTopic() {
-  Serial.println("Poll COMMAND...");
+  logMessage(LOG_DEBUG, "HTTP", "GET /ALERT_klubhaus_topic/json");
-  String response = fetchNtfyJson(COMMAND_POLL_URL);
+
-  if (response.length() == 0) return;
+  unsigned long reqStart = millis();
+  String response = fetchNtfyJson(COMMAND_POLL_URL, "COMMAND");
+  unsigned long duration = millis() - reqStart;
+
+  if (response.length() == 0) {
+    logMessage(LOG_DEBUG, "HTTP", "No new messages (204 or empty)");
+    return;
+  }
 
   StaticJsonDocument<512> doc;
   DeserializationError error = deserializeJson(doc, response);
   if (error) {
-    Serial.print("  JSON error: ");
+    char errBuf[128];
-    Serial.println(error.c_str());
+    snprintf(errBuf, sizeof(errBuf), "JSON parse failed: %s", error.c_str());
+    logMessage(LOG_ERROR, "JSON", errBuf);
     return;
   }
 
   String id = doc["id"] | "";
   String message = doc["message"] | "";
+  long long serverTime = doc["time"] | 0;
 
   message.trim();
+
+  char logBuf[512];
+  snprintf(logBuf, sizeof(logBuf), "duration=%lums id=[%s] message=[%s] serverTime=%lld", 
+    duration, id.c_str(), message.c_str(), serverTime);
+  logString(LOG_INFO, "COMMAND", "received", logBuf);
+
   if (message.length() == 0) {
-    Serial.println("  Empty message, skip");
+    logMessage(LOG_DEBUG, "COMMAND", "Empty message — discarded");
     return;
   }
 
   if (id == lastCommandId && id.length() > 0) {
-    Serial.println("  Same ID, skip");
+    logMessage(LOG_DEBUG, "COMMAND", "Duplicate ID — discarded");
     return;
   }
   lastCommandId = id;
 
-  Serial.print("  NEW: [");
-  Serial.print(message);
-  Serial.println("]");
-
   if (message.equalsIgnoreCase("SILENCE")) {
-    Serial.println("  -> SILENCE command");
+    logMessage(LOG_INFO, "COMMAND", "SILENCE command — acknowledging");
     transitionTo(STATE_SILENT);
     flashConfirm("SILENCE", COLOR_MINT, COLOR_BLACK);
   } else {
-    Serial.println("  -> ALERT trigger");
+    logString(LOG_INFO, "COMMAND", "ALERT trigger", message);
     alertMessage = message;
     transitionTo(STATE_ALERT);
   }
 }
 
 void checkSilenceTopic() {
-  String response = fetchNtfyJson(SILENCE_POLL_URL);
+  logMessage(LOG_DEBUG, "HTTP", "GET /SILENCE_klubhaus_topic/json");
+
+  unsigned long reqStart = millis();
+  String response = fetchNtfyJson(SILENCE_POLL_URL, "SILENCE");
+  unsigned long duration = millis() - reqStart;
+
   if (response.length() == 0) return;
 
   StaticJsonDocument<512> doc;
@@ -280,23 +373,24 @@ void checkSilenceTopic() {
   String message = doc["message"] | "";
 
   message.trim();
-  if (message.length() == 0) return;
 
+  char logBuf[512];
+  snprintf(logBuf, sizeof(logBuf), "duration=%lums id=[%s] message=[%s]", 
+    duration, id.c_str(), message.c_str());
+  logString(LOG_INFO, "SILENCE", "received", logBuf);
+
+  if (message.length() == 0) return;
   if (id == lastSilenceId && id.length() > 0) return;
   lastSilenceId = id;
 
-  Serial.print("Silence topic: [");
-  Serial.print(message);
-  Serial.println("]");
-
   if (currentState == STATE_ALERT) {
-    Serial.println("  -> Force silence");
+    logMessage(LOG_INFO, "SILENCE", "Force silence — acknowledging");
     transitionTo(STATE_SILENT);
     flashConfirm("SILENCED", COLOR_MINT, COLOR_BLACK);
   }
 }
 
-String fetchNtfyJson(const char* url) {
+String fetchNtfyJson(const char* url, const char* topicName) {
   HTTPClient http;
   http.begin(url);
   http.setTimeout(8000);
@@ -304,22 +398,31 @@ String fetchNtfyJson(const char* url) {
   int code = http.GET();
 
   if (code == 204) {
+    logMessage(LOG_DEBUG, "HTTP", "204 No Content");
     http.end();
     return "";
   }
 
-  if (code == 429 || code == 500 || code == 502 || code == 503) {
+  if (code == 429) {
-    Serial.print("  HTTP error ");
+    logMessage(LOG_WARN, "HTTP", "429 Rate Limited — backing off 60s");
-    Serial.print(code);
+    nextPollTime = millis() + ERROR_BACKOFF;
-    Serial.println(" — backing off 60s");
+    http.end();
+    return "";
+  }
+
+  if (code >= 500) {
+    char errBuf[64];
+    snprintf(errBuf, sizeof(errBuf), "%d Server Error — backing off 60s", code);
+    logMessage(LOG_ERROR, "HTTP", errBuf);
     nextPollTime = millis() + ERROR_BACKOFF;
     http.end();
     return "";
   }
 
   if (code != 200) {
-    Serial.print("  HTTP error: ");
+    char errBuf[64];
-    Serial.println(code);
+    snprintf(errBuf, sizeof(errBuf), "Unexpected status %d", code);
+    logMessage(LOG_ERROR, "HTTP", errBuf);
     http.end();
     return "";
   }
@@ -327,6 +430,7 @@ String fetchNtfyJson(const char* url) {
   String payload = http.getString();
   http.end();
 
+  // ntfy JSON streaming: take first line only
   int newline = payload.indexOf('\n');
   if (newline > 0) payload = payload.substring(0, newline);
 
@@ -336,12 +440,15 @@ String fetchNtfyJson(const char* url) {
 // ============== VISUALS ==============
 
 void flashConfirm(const char* text, uint16_t bgColor, uint16_t textColor) {
-  digitalWrite(BACKLIGHT_PIN, HIGH);
+  logString(LOG_DEBUG, "DISPLAY", "flashConfirm", text);
+  setBacklight(true);
   gfx->fillScreen(bgColor);
   drawCenteredText(text, 3, textColor, bgColor, 70);
   delay(500);
   gfx->fillScreen(COLOR_BLACK);
-  digitalWrite(BACKLIGHT_PIN, LOW);
+  if (currentState == STATE_SILENT) {
+    setBacklight(false);
+  }
 }
 
 void drawAlertScreen(uint16_t bgColor, uint16_t textColor) {
@@ -385,11 +492,12 @@ void drawCenteredText(const char* text, int textSize, uint16_t textColor, uint16
 }
 
 void showFatalError(const char* text) {
-  digitalWrite(BACKLIGHT_PIN, HIGH);
+  logString(LOG_FATAL, "DISPLAY", "fatalError", text);
+  setBacklight(true);
   gfx->fillScreen(COLOR_BLACK);
   drawCenteredText(text, 3, COLOR_FUCHSIA, COLOR_BLACK, 70);
   delay(3000);
-  digitalWrite(BACKLIGHT_PIN, LOW);
+  setBacklight(false);
 }
 
 // ============== BUTTON ==============
@@ -398,20 +506,20 @@ void handleButton() {
   bool pressed = (digitalRead(BUTTON_PIN) == LOW);
 
   if (pressed && !lastButtonState) {
-    Serial.println("BUTTON PRESSED");
+    logMessage(LOG_INFO, "BUTTON", "PRESSED");
-    digitalWrite(BACKLIGHT_PIN, HIGH);
+    setBacklight(true);
     gfx->fillScreen(COLOR_COCAINE);
     drawCenteredText("TEST MODE", 2, COLOR_BLACK, COLOR_COCAINE, 70);
   }
   else if (!pressed && lastButtonState) {
-    Serial.println("BUTTON RELEASED");
+    logMessage(LOG_INFO, "BUTTON", "RELEASED");
     if (currentState == STATE_ALERT) {
-      Serial.println("  -> Reset to SILENT");
+      logMessage(LOG_INFO, "BUTTON", "Action: reset to SILENT");
       transitionTo(STATE_SILENT);
       flashConfirm("SILENCED", COLOR_MINT, COLOR_BLACK);
     } else {
       gfx->fillScreen(COLOR_BLACK);
-      digitalWrite(BACKLIGHT_PIN, LOW);
+      setBacklight(false);
     }
   }
   lastButtonState = pressed;
@@ -433,7 +541,9 @@ void updateBlink(unsigned long now) {
 // ============== TEST ==============
 
 void testDisplay() {
+  logMessage(LOG_DEBUG, "DISPLAY", "Running color test...");
   uint16_t colors[] = {COLOR_TEAL, COLOR_FUCHSIA, COLOR_COCAINE, COLOR_MINT, COLOR_BLACK};
+  const char* names[] = {"TEAL", "FUCHSIA", "COCAINE", "MINT", "BLACK"};
   for (int i = 0; i < 5; i++) {
     gfx->fillScreen(colors[i]);
     delay(100);