Implement basic logging in firmware

firmware/firmware.ino

@@ -1,15 +1,18 @@
 #include <Arduino.h>
 #include <ArduinoJson.h>
+#include <base64.h>
 #include <ESP8266WiFi.h>
 #include <ESP8266HTTPClient.h>
 #include <EEPROM.h>
 #include <Ticker.h>
+#include <time.h>
 
 const char *WIFI_SSID PROGMEM = "Protospace";
 const char *WIFI_PASS PROGMEM = "yycmakers";
 char wifiMACAddr[20] = "";
 const String SOCKET_URL = String("http://tools-socket.protospace.ca/api/lockout/");
 const String CARD_URL = String("http://tools-auth.protospace.ca/cards/");
+const String INFOLOG_URL = String("http://tools-auth.protospace.ca/infolog/");
 
 Ticker ticker;
 
@@ -27,8 +30,6 @@ typedef struct __attribute__((packed)) cardData {
 	char tail;
 } cardData_t;
 
-#define LOGGING true
-
 #define RELAY_PIN D1
 #define GREEN_BUTTON_PIN D3
 #define RED_BUTTON_PIN D4
@@ -43,9 +44,11 @@ typedef struct __attribute__((packed)) cardData {
 #define LED_PIN_OFF !LED_PIN_ON
 
 #define DELAY_TIME 10
+// times below are multiplied by DELAY_TIME, in ms
 #define LOCK_ARMED_TIMEOUT 1000
 #define COMM_LOCK_IDLE_TIME 50
 #define COMM_CARD_IDLE_TIME 1000
+#define COMM_INFO_IDLE_TIME 3000
 #define LED_ARMED_BLINK_TIME 50
 #define LED_ERROR_BLINK_TIME 50
 
@@ -70,7 +73,7 @@ enum LEDStates
 enum lockStates
 {
 	LOCK_OFF,
-	LOCK_PREARM,
+	LOCK_PREARM, // prevent arming while buttons held
 	LOCK_ARMED,
 	LOCK_ON_PRESSED, // to wait until button is released
 	LOCK_ON,
@@ -82,12 +85,73 @@ enum commStates
 	COMM_IDLE,
 	COMM_LOCK,
 	COMM_CARD,
+	COMM_INFO,
 } commState = COMM_INIT;
 
+#define SERIAL_LOGGING true
+
+#define LOG_SIZE 100
+
+enum eventCodes
+{
+	LOG_BOOT_UP,
+	LOG_INIT_COMPLETE,
+	LOG_WIFI_CONNECTED,
+	LOG_WIFI_DISCONNECTED,
+	LOG_COMM_LOCK_FAIL,
+	LOG_COMM_CARD_FAIL,
+	LOG_COMM_INFO_FAIL,
+	LOG_LOCK_OFF,
+	LOG_LOCK_ARMED,
+	LOG_LOCK_TIMEOUT,
+	LOG_LOCK_ON,
+	LOG_LOCK_CANCEL,
+	LOG_LOCK_ERROR,
+	LOG_CARD_GOOD_READ,
+	LOG_CARD_ACCEPTED,
+	LOG_CARD_DENIED,
+};
+
+typedef struct __attribute__((packed)) logData {
+	uint32_t unixTime;
+	uint8_t eventCode;
+	char data[CARD_DATA_LENGTH];
+} logData_t;
+
+logData_t eventLog[LOG_SIZE];
+uint16_t logPosition = 0;
+
+void logEvent(uint8_t eventCode, const char *data = nullptr, size_t num = 0)
+{
+	logData_t event;
+
+	noInterrupts();
+
+	event.unixTime = time(nullptr);
+	event.eventCode = eventCode;
+	for (uint8_t i = 0; i < CARD_DATA_LENGTH; i++) {
+		if (i >= num) break;
+		event.data[i] = data[i];
+	}
+
+	if (logPosition < LOG_SIZE) {
+		eventLog[logPosition++] = event;
+	}
+
+	interrupts();
+}
+
 void setup()
 {
 	Serial.begin(9600);
-	if (LOGGING) Serial.println("[INFO] Serial started.");
+	if (SERIAL_LOGGING) Serial.println("[INFO] Serial started.");
+
+	struct timeval tv = { .tv_sec = 0, .tv_usec = 0 };
+	struct timezone tz = { .tz_minuteswest = 0, .tz_dsttime = 0 };
+	settimeofday(&tv, &tz);
+
+	if (SERIAL_LOGGING) Serial.println("[INFO] Set system time to 0.");
+	logEvent(LOG_BOOT_UP);
 
 	pinMode(RELAY_PIN, OUTPUT);
 	pinMode(GREEN_BUTTON_PIN, INPUT_PULLUP);
@@ -100,10 +164,12 @@ void setup()
 	byte ar[6];
 	WiFi.macAddress(ar);
 	sprintf(wifiMACAddr, "%02X%02X%02X%02X%02X%02X", ar[0], ar[1], ar[2], ar[3], ar[4], ar[5]);
-	if (LOGGING) Serial.print("[INFO] Wifi MAC Address: ");
+	if (SERIAL_LOGGING) Serial.print("[INFO] Wifi MAC Address: ");
-	if (LOGGING) Serial.println(wifiMACAddr);
+	if (SERIAL_LOGGING) Serial.println(wifiMACAddr);
 
 	ticker.attach_ms(DELAY_TIME, tickerLoop);
+
+	logEvent(LOG_INIT_COMPLETE);
 }
 
 // The stuff in this loop must not be blocked by network delay
@@ -197,15 +263,18 @@ void checkCard()
 			if (tmp == EEPROM_END_MARKER) break;
 		}
 
-		if (LOGGING) Serial.println("[INFO] Good scan from card: " + cardStr);
+		if (SERIAL_LOGGING) Serial.println("[INFO] Good scan from card: " + cardStr);
+		logEvent(LOG_CARD_GOOD_READ, cardStr.c_str(), cardStr.length());
 
 		if (authorizedCards.indexOf(cardStr) >= 0) {
-			if (LOGGING) Serial.println("[INFO] Card is authorized on machine.");
+			if (SERIAL_LOGGING) Serial.println("[INFO] Card is authorized on machine.");
+			logEvent(LOG_CARD_ACCEPTED, cardStr.c_str(), cardStr.length());
 			if (lockState == LOCK_OFF) {
 				lockState = LOCK_PREARM;
 			}
 		} else {
-			if (LOGGING) Serial.println("[INFO] Card not authorized on machine.");
+			if (SERIAL_LOGGING) Serial.println("[INFO] Card not authorized on machine.");
+			logEvent(LOG_CARD_DENIED, cardStr.c_str(), cardStr.length());
 			LEDState = LED_ERROR;
 		}
 	}
@@ -217,7 +286,8 @@ void processWifiState()
 		case WIFI_DISCONNECTED:
 			commState = COMM_INIT;
 
-			if (LOGGING) Serial.println("[INFO] Wifi is disconnected. Attempting to connect...");
+			if (SERIAL_LOGGING) Serial.println("[INFO] Wifi attempting to connect...");
+
 			WiFi.begin(WIFI_SSID, WIFI_PASS);
 
 			wifiState = WIFI_CONNECTING;
@@ -226,21 +296,24 @@ void processWifiState()
 			commState = COMM_INIT;
 
 			if (WiFi.status() == WL_CONNECTED) {
-				if (LOGGING) Serial.println("[INFO] Wifi is connected.");
+				if (SERIAL_LOGGING) Serial.println("[INFO] Wifi is connected.");
+				logEvent(LOG_WIFI_CONNECTED);
 
-				if (LOGGING) Serial.print("[INFO] Wifi IP Address: ");
+				if (SERIAL_LOGGING) Serial.print("[INFO] Wifi IP Address: ");
-				if (LOGGING) Serial.println(WiFi.localIP());
+				if (SERIAL_LOGGING) Serial.println(WiFi.localIP());
 
 				wifiState = WIFI_CONNECTED;
 			}
 			break;
 		case WIFI_CONNECTED:
 			if (WiFi.status() != WL_CONNECTED) {
+				if (SERIAL_LOGGING) Serial.println("[INFO] Wifi disconnected.");
+				logEvent(LOG_WIFI_DISCONNECTED);
 				wifiState = WIFI_DISCONNECTED;
 			}
 			break;
 		default:
-			if (LOGGING) Serial.println("[ERROR] Invalid wifi state.");
+			if (SERIAL_LOGGING) Serial.println("[ERROR] Invalid wifi state.");
 			wifiState = WIFI_DISCONNECTED;
 			break;
 	}
@@ -266,9 +339,12 @@ void processLockState()
 			break;
 		case LOCK_PREARM:
 			if (!greenButton() && !redButton()) {
-				if (LOGGING) Serial.println("[INFO] Arming interlock.");
+				if (SERIAL_LOGGING) Serial.println("[INFO] Arming interlock.");
+				logEvent(LOG_LOCK_ARMED);
 				lockState = LOCK_ARMED;
 			} else {
+				if (SERIAL_LOGGING) Serial.println("[ERROR] Buttons held, aborting.");
+				logEvent(LOG_LOCK_ERROR);
 				lockState = LOCK_OFF;
 				LEDState = LED_ERROR;
 			}
@@ -280,25 +356,29 @@ void processLockState()
 			lockArmedTimeoutCount++;
 
 			if (redButton()) {
-				if (LOGGING) Serial.println("[INFO] Unarming interlock.");
+				if (SERIAL_LOGGING) Serial.println("[INFO] Unarming interlock.");
+				logEvent(LOG_LOCK_CANCEL);
 				lockState = LOCK_OFF;
 			} else if (greenButton()) {
-				if (LOGGING) Serial.println("[INFO] On button pressed.");
+				if (SERIAL_LOGGING) Serial.println("[INFO] On button pressed.");
 				lockState = LOCK_ON_PRESSED;
 			}
 
 			if (lockArmedTimeoutCount > LOCK_ARMED_TIMEOUT) {
-				if (LOGGING) Serial.println("[INFO] Arming timed out, disarming.");
+				if (SERIAL_LOGGING) Serial.println("[INFO] Arming timed out, disarming.");
+				logEvent(LOG_LOCK_TIMEOUT);
 				lockState = LOCK_OFF;
 				LEDState = LED_ERROR;
 			}
 			break;
 		case LOCK_ON_PRESSED:
 			if (redButton()) {
-				if (LOGGING) Serial.println("[ERROR] Off button pressed, aborting.");
+				if (SERIAL_LOGGING) Serial.println("[ERROR] Off button pressed, aborting.");
+				logEvent(LOG_LOCK_ERROR);
 				lockState = LOCK_OFF;
 			} else if (!greenButton()) {
-				if (LOGGING) Serial.println("[INFO] Turning machine on.");
+				if (SERIAL_LOGGING) Serial.println("[INFO] Turning machine on.");
+				logEvent(LOG_LOCK_ON);
 				lockState = LOCK_ON;
 			}
 			break;
@@ -308,12 +388,13 @@ void processLockState()
 			relayOn();
 
 			if (redButton()) {
-				if (LOGGING) Serial.println("[INFO] Off button pressed.");
+				if (SERIAL_LOGGING) Serial.println("[INFO] Off button pressed.");
+				logEvent(LOG_LOCK_OFF);
 				lockState = LOCK_OFF;
 			}
 			break;
 		default:
-			if (LOGGING) Serial.println("[ERROR] Invalid lock state.");
+			if (SERIAL_LOGGING) Serial.println("[ERROR] Invalid lock state.");
 			lockState = LOCK_OFF;
 			break;
 	}
@@ -369,7 +450,7 @@ void processLEDState()
 			}
 			break;
 		default:
-			if (LOGGING) Serial.println("[ERROR] Invalid LED state.");
+			if (SERIAL_LOGGING) Serial.println("[ERROR] Invalid LED state.");
 			LEDState = LED_OFF;
 			break;
 	}
@@ -403,6 +484,23 @@ String deserializeLockJson(String input)
 	return action;
 }
 
+String serializeLog() {
+	size_t logLengthBytes = logPosition * sizeof(logData_t);
+	return base64::encode((uint8_t *) eventLog, logLengthBytes, false);
+}
+
+uint32_t deserializeInfoJson(String input)
+{
+	// Generated with: https://arduinojson.org/assistant/
+	const size_t bufferSize = JSON_OBJECT_SIZE(1) + 50;
+	StaticJsonBuffer<bufferSize> jsonBuffer;
+	JsonObject& root = jsonBuffer.parseObject(input);
+
+	uint32_t unixTime = root["unixTime"];
+
+	return unixTime;
+}
+
 void postState()
 {
 	HTTPClient lockHTTP;
@@ -411,34 +509,39 @@ void postState()
 	lockHTTP.begin(SOCKET_URL + wifiMACAddr);
 	lockHTTP.addHeader("Content-Type", "application/json");
 
-	if (LOGGING) Serial.println("[INFO] Lock state HTTP begin.");
+	if (SERIAL_LOGGING) Serial.println("[INFO] Lock state HTTP begin.");
 
-	if (LOGGING) Serial.print("[INFO] HTTP POST: ");
+	if (SERIAL_LOGGING) Serial.print("[INFO] HTTP POST: ");
 	String postData = serializeLockJson(lockState);
-	if (LOGGING) Serial.println(postData);
+	if (SERIAL_LOGGING) Serial.println(postData);
 	int16_t lockHTTPCode = lockHTTP.POST(postData);
+	String lockHTTPCodeStr = String(lockHTTPCode);
 
 	if (lockHTTPCode > 0) {
-		if (LOGGING) Serial.printf("[INFO] POST success, code: %d\n", lockHTTPCode);
+		if (SERIAL_LOGGING) Serial.printf("[INFO] POST success, code: %d\n", lockHTTPCode);
 
 		if (lockHTTPCode == HTTP_CODE_OK) {
-			if (LOGGING) Serial.print("[INFO] Resource found, parsing response: ");
+			if (SERIAL_LOGGING) Serial.print("[INFO] Resource found, parsing response: ");
 			String lockPayload = lockHTTP.getString();
-			if (LOGGING) Serial.println(lockPayload);
+			if (SERIAL_LOGGING) Serial.println(lockPayload);
 			String action = deserializeLockJson(lockPayload);
 
 			if (action == "arm"  && lockState == LOCK_OFF && LEDState == LED_OFF) {
 				lockState = LOCK_PREARM;
-			} else if (action == "disarm") {
+			} else if (action == "disarm" && lockState != LOCK_ON) {
+				if (SERIAL_LOGGING) Serial.println("[INFO] Unarming interlock.");
+				logEvent(LOG_LOCK_CANCEL);
 				lockState = LOCK_OFF;
 			}
 
-			if (LOGGING) Serial.println("[INFO] action: " + action);
+			if (SERIAL_LOGGING) Serial.println("[INFO] action: " + action);
 		} else {
-			if (LOGGING) Serial.println("[ERROR] Resource not found.");
+			if (SERIAL_LOGGING) Serial.println("[ERROR] Resource not found.");
+			logEvent(LOG_COMM_LOCK_FAIL, lockHTTPCodeStr.c_str(), lockHTTPCodeStr.length());
 		}
 	} else {
-		if (LOGGING) Serial.printf("[ERROR] POST failed, error: %s\n", lockHTTP.errorToString(lockHTTPCode).c_str());
+		if (SERIAL_LOGGING) Serial.printf("[ERROR] POST failed, error: %s\n", lockHTTP.errorToString(lockHTTPCode).c_str());
+		logEvent(LOG_COMM_LOCK_FAIL, lockHTTPCodeStr.c_str(), lockHTTPCodeStr.length());
 	}
 
 	lockHTTP.end();
@@ -452,19 +555,20 @@ void getCards()
 	cardHTTP.begin(CARD_URL + wifiMACAddr + "/");
 	cardHTTP.addHeader("Content-Type", "application/json");
 
-	if (LOGGING) Serial.println("[INFO] Card state HTTP begin.");
+	if (SERIAL_LOGGING) Serial.println("[INFO] Card state HTTP begin.");
 
-	if (LOGGING) Serial.println("[INFO] HTTP GET");
+	if (SERIAL_LOGGING) Serial.println("[INFO] HTTP GET");
 	int16_t cardHTTPCode = cardHTTP.GET();
+	String cardHTTPCodeStr = String(cardHTTPCode);
 
 	if (cardHTTPCode > 0) {
-		if (LOGGING) Serial.printf("[INFO] GET success, code: %d\n", cardHTTPCode);
+		if (SERIAL_LOGGING) Serial.printf("[INFO] GET success, code: %d\n", cardHTTPCode);
 
 		if (cardHTTPCode == HTTP_CODE_OK) {
-			if (LOGGING) Serial.print("[INFO] Resource found, parsing response: ");
+			if (SERIAL_LOGGING) Serial.print("[INFO] Resource found, parsing response: ");
 			String cardPayload = cardHTTP.getString();
 			cardPayload += String(EEPROM_END_MARKER);
-			if (LOGGING) Serial.println(cardPayload);
+			if (SERIAL_LOGGING) Serial.println(cardPayload);
 
 			noInterrupts(); // commit() disables interrupts, but we want an atomic EEPROM buffer write
 			for (int i = 0; i < cardPayload.length(); i++) {
@@ -474,36 +578,85 @@ void getCards()
 			EEPROM.commit();
 			interrupts();
 
-			if (LOGGING) Serial.println("[INFO] Finished getting card data.");
+			if (SERIAL_LOGGING) Serial.println("[INFO] Finished getting card data.");
 		} else {
-			if (LOGGING) Serial.println("[ERROR] Resource not found.");
+			if (SERIAL_LOGGING) Serial.println("[ERROR] Resource not found.");
+			logEvent(LOG_COMM_CARD_FAIL, cardHTTPCodeStr.c_str(), cardHTTPCodeStr.length());
 		}
 	} else {
-		if (LOGGING) Serial.printf("[ERROR] POST failed, error: %s\n", cardHTTP.errorToString(cardHTTPCode).c_str());
+		if (SERIAL_LOGGING) Serial.printf("[ERROR] POST failed, error: %s\n", cardHTTP.errorToString(cardHTTPCode).c_str());
+		logEvent(LOG_COMM_CARD_FAIL, cardHTTPCodeStr.c_str(), cardHTTPCodeStr.length());
 	}
 
 	cardHTTP.end();
 }
 
+void postInfolog()
+{
+	HTTPClient infoHTTP;
+
+	//infoHTTP.begin("https://url", "7a 9c f4 db 40 d3 62 5a 6e 21 bc 5c cc 66 c8 3e a1 45 59 38"); //HTTPS
+	infoHTTP.begin(INFOLOG_URL + wifiMACAddr + "/");
+	infoHTTP.addHeader("Content-Type", "application/json");
+
+	if (SERIAL_LOGGING) Serial.println("[INFO] Info state HTTP begin.");
+
+	if (SERIAL_LOGGING) Serial.print("[INFO] HTTP POST: ");
+	String postData = serializeLog();
+	if (SERIAL_LOGGING) Serial.println(postData);
+	int16_t infoHTTPCode = infoHTTP.POST(postData);
+	String infoHTTPCodeStr = String(infoHTTPCode);
+
+	if (infoHTTPCode > 0) {
+		if (SERIAL_LOGGING) Serial.printf("[INFO] POST success, code: %d\n", infoHTTPCode);
+
+		if (infoHTTPCode == HTTP_CODE_OK) {
+			if (SERIAL_LOGGING) Serial.print("[INFO] Resource found, parsing response: ");
+			String infoPayload = infoHTTP.getString();
+			if (SERIAL_LOGGING) Serial.println(infoPayload);
+			uint32_t unixTime = deserializeInfoJson(infoPayload);
+
+			struct timeval tv = { .tv_sec = unixTime, .tv_usec = 0 };
+			struct timezone tz = { .tz_minuteswest = 0, .tz_dsttime = 0 };
+			settimeofday(&tv, &tz);
+
+			if (SERIAL_LOGGING) Serial.print("[INFO] Set system time to: ");
+			if (SERIAL_LOGGING) Serial.println(unixTime);
+		} else {
+			if (SERIAL_LOGGING) Serial.println("[ERROR] Resource not found.");
+			logEvent(LOG_COMM_INFO_FAIL, infoHTTPCodeStr.c_str(), infoHTTPCodeStr.length());
+		}
+	} else {
+		if (SERIAL_LOGGING) Serial.printf("[ERROR] POST failed, error: %s\n", infoHTTP.errorToString(infoHTTPCode).c_str());
+		logEvent(LOG_COMM_INFO_FAIL, infoHTTPCodeStr.c_str(), infoHTTPCodeStr.length());
+	}
+
+	infoHTTP.end();
+}
+
 void processCommState()
 {
-	static uint16_t commLockIdleCount, commCardIdleCount;
+	static uint16_t commLockIdleCount, commCardIdleCount, commInfoIdleCount;
 
 	switch (commState) {
 		case COMM_INIT:
 			commLockIdleCount = 0;
 			commCardIdleCount = 0;
+			commInfoIdleCount = 0;
 
 			commState = COMM_IDLE;
 			break;
 		case COMM_IDLE:
 			commLockIdleCount++;
 			commCardIdleCount++;
+			commInfoIdleCount++;
 
 			if (commLockIdleCount >= COMM_LOCK_IDLE_TIME) {
 				commState = COMM_LOCK;
 			} else if (commCardIdleCount >= COMM_CARD_IDLE_TIME) {
 				commState = COMM_CARD;
+			} else if (commInfoIdleCount >= COMM_INFO_IDLE_TIME) {
+				commState = COMM_INFO;
 			}
 			break;
 		case COMM_LOCK:
@@ -524,5 +677,14 @@ void processCommState()
 				commState = COMM_IDLE;
 			}
 			break;
+		case COMM_INFO:
+			{
+				postInfolog();
+
+				commInfoIdleCount = 0;
+
+				commState = COMM_IDLE;
+			}
+			break;
 	}
 }