From 156fbafd58fe00bf025a67649f4408bceab41a85 Mon Sep 17 00:00:00 2001
From: Zoe Pfister <zoe.pfister@uibk.ac.at>
Date: Wed, 2 Nov 2022 15:14:06 +0100
Subject: [PATCH] WIP: Refactor logging facility. Now logs to SD card. Requires
 using explicit esp logging facility because arduino overwrites the Macros in
 the backend

---
 host/esp-t-sim7000g/platformio.ini |   1 +
 host/esp-t-sim7000g/src/main.cpp   | 157 +++++++++++++++++++----------
 2 files changed, 106 insertions(+), 52 deletions(-)

diff --git a/host/esp-t-sim7000g/platformio.ini b/host/esp-t-sim7000g/platformio.ini
index e73dc1b..1e0fb84 100644
--- a/host/esp-t-sim7000g/platformio.ini
+++ b/host/esp-t-sim7000g/platformio.ini
@@ -16,6 +16,7 @@ monitor_speed = 115200
 monitor_port = /dev/ttyACM0
 upload_port = /dev/ttyACM0
 build_flags =
+    -I include
     -DCORE_DEBUG_LEVEL=5
     -std=gnu++17
 build_unflags = -std=gnu++11
diff --git a/host/esp-t-sim7000g/src/main.cpp b/host/esp-t-sim7000g/src/main.cpp
index 2a3fb77..542d10a 100644
--- a/host/esp-t-sim7000g/src/main.cpp
+++ b/host/esp-t-sim7000g/src/main.cpp
@@ -74,6 +74,37 @@ void on_data_sent(const uint8_t *mac_addr, esp_now_send_status_t status)
 	// go to sleep
 }
 
+static char log_print_buffer[512];
+
+int vprintf_into_sd(const char *szFormat, va_list args)
+{
+	String logstring = "[" + rtc.getDateTime() + "] ";
+	logstring += szFormat;
+	// write evaluated format string into buffer
+	int ret = vsnprintf(log_print_buffer, sizeof(log_print_buffer), logstring.c_str(), args);
+
+	// output is now in buffer. write to file.
+	if (ret >= 0) {
+		if (!SD.exists("/log.txt")) {
+			File writeLog = SD.open("/log.txt", FILE_WRITE);
+			if (!writeLog)
+				Serial.println("Couldn't open spiffs_log.txt");
+			delay(50);
+			writeLog.close();
+		}
+
+		File logFile = SD.open("/log.txt", FILE_APPEND);
+
+		// debug output
+		vprintf(logstring.c_str(), args);
+		logFile.write((uint8_t *)log_print_buffer, (size_t)ret);
+		// to be safe in case of crashes: flush the output
+		logFile.flush();
+		logFile.close();
+	}
+	return ret;
+}
+
 String getMacAddressAsString(const uint8_t *mac);
 DynamicJsonDocument parseReceivedJsonData(char *data);
 void saveStringToSDCard(const std::string &dataString);
@@ -83,11 +114,11 @@ void setupSDCard();
 void syncUTCTimeToRTC();
 void on_data_recv(const uint8_t *mac, const uint8_t *incomingData, int len)
 {
-	ESP_LOGD(TAG_ESPNOW.c_str(), "Message recieved");
+	esp_log_write(ESP_LOG_INFO, TAG_ESPNOW.c_str(), "Message recieved\n");
 	// copy received data to a char array
 	char data[len];
 	memcpy(data, incomingData, len);
-	ESP_LOGD(TAG_ESPNOW.c_str(), "Raw received Data: %s", data);
+	esp_log_write(ESP_LOG_DEBUG, TAG_ESPNOW.c_str(), "Raw received Data: %s\n", data);
 
 	DynamicJsonDocument doc = parseReceivedJsonData(data);
 
@@ -105,7 +136,7 @@ void on_data_recv(const uint8_t *mac, const uint8_t *incomingData, int len)
 
 	String lineData = documentToLineProtocolString(doc);
 
-	ESP_LOGD(TAG_ESPNOW.c_str(), "Line protocol data: %s", lineData.c_str());
+	esp_log_write(ESP_LOG_DEBUG, TAG_ESPNOW.c_str(), "Line protocol data: %s\n", lineData.c_str());
 
 	xSemaphoreTake(xMutex, portMAX_DELAY);
 	queue.push(lineData);
@@ -139,7 +170,7 @@ void saveStringToSDCard(const std::string &dataString)
 	}
 	// if the file isn't open, pop up an error:
 	else {
-		ESP_LOGE(TAG.c_str(), "error opening datalog.txt");
+		esp_log_write(ESP_LOG_ERROR, TAG.c_str(), "error opening datalog.txt\n");
 		// TODO: Error handling
 	}
 }
@@ -148,7 +179,7 @@ DynamicJsonDocument parseReceivedJsonData(char *data)
 	DynamicJsonDocument doc(250);
 	auto error = deserializeJson(doc, data);
 	if (error) {
-		ESP_LOGE(TAG_ESPNOW.c_str(), "Error while parsing json: %s", error.f_str());
+		esp_log_write(ESP_LOG_ERROR, TAG_ESPNOW.c_str(), "Error while parsing json: %s\n", error.f_str());
 		// TODO error handling
 	}
 	return doc;
@@ -159,25 +190,25 @@ String getMacAddressAsString(const uint8_t *mac)
 	for (int i = 0; i < 6; i++) {
 		macAddress += String(mac[i], HEX);
 	}
-	ESP_LOGD(TAG_ESPNOW.c_str(), "MAC: %s", macAddress.c_str());
+	esp_log_write(ESP_LOG_DEBUG, TAG_ESPNOW.c_str(), "MAC: %s\n", macAddress.c_str());
 	return macAddress;
 }
 
 [[noreturn]] void ESPNOWReceiveTask(void *parameter)
 {
-	ESP_LOGD(TAG_ESPNOW.c_str(), "ESPNOWReceiveTask started on core %d", xPortGetCoreID());
+	esp_log_write(ESP_LOG_DEBUG, TAG_ESPNOW.c_str(), "ESPNOWReceiveTask started on core %d\n", xPortGetCoreID());
 
 	WiFi.mode(WIFI_STA);
 
-	ESP_LOGD(TAG_ESPNOW.c_str(), "Initialising ESPNow...");
+	esp_log_write(ESP_LOG_DEBUG, TAG_ESPNOW.c_str(), "Initialising ESPNow...\n");
 
 	if (esp_now_init() != ESP_OK) {
 		// initialization failed
-		ESP_LOGE(TAG_ESPNOW.c_str(), "Initialising ESPNow FAILED");
+		esp_log_write(ESP_LOG_ERROR, TAG_ESPNOW.c_str(), "Initialising ESPNow FAILED\n");
 		exit(ESP_FAIL);
 	}
 
-	ESP_LOGD(TAG_ESPNOW.c_str(), "Initialising ESPNow SUCCESS");
+	esp_log_write(ESP_LOG_DEBUG, TAG_ESPNOW.c_str(), "Initialising ESPNow SUCCESS\n");
 
 	esp_now_register_recv_cb(on_data_recv);
 
@@ -215,13 +246,15 @@ void setup()
 	// Set console baud rate
 	Serial.begin(115200);
 	delay(10);
+	setupSDCard();
 
-	ESP_LOGD(TAG.c_str(), "%s", WiFi.macAddress());
+	//	https://stackoverflow.com/questions/60442350/arduinos-esp-log-set-vprintf-does-not-work-on-esp32
+	esp_log_set_vprintf(&vprintf_into_sd);
+	esp_log_level_set("*", ESP_LOG_VERBOSE);
+	esp_log_write(ESP_LOG_DEBUG, TAG.c_str(), "%s", WiFi.macAddress().c_str());
 
 	turnOffLEDs();
 
-	setupSDCard();
-
 	xMutex = xSemaphoreCreateMutex();
 
 	delay(1000);
@@ -240,33 +273,34 @@ void setup()
 
 	// Restart takes quite some time
 	// To skip it, call init() instead of restart()
-	ESP_LOGD(TAG_GSM.c_str(), "Initializing modem...");
+	esp_log_write(ESP_LOG_DEBUG, TAG_GSM.c_str(), "Initializing modem...\n");
 	if (!modem.restart()) {
-		ESP_LOGW(TAG_GSM.c_str(), "Failed to restart modem, attempting to continue without restarting");
+		esp_log_write(ESP_LOG_WARN, TAG_GSM.c_str(),
+		              "Failed to restart modem, attempting to continue without restarting\n");
 	}
 
 	syncUTCTimeToRTC();
 }
 void syncUTCTimeToRTC()
 {
-	ESP_LOGD(TAG_GSM.c_str(), "NTP Server Syncing...");
+	esp_log_write(ESP_LOG_DEBUG, TAG_GSM.c_str(), "NTP Server Syncing...\n");
 	modem.NTPServerSync("pool.ntp.org", 0);
 	auto gsmDateTimeString = modem.getGSMDateTime(DATE_FULL);
-	ESP_LOGD(TAG_GSM.c_str(), "GSM DateTime: %s", gsmDateTimeString.c_str());
+	esp_log_write(ESP_LOG_DEBUG, TAG_GSM.c_str(), "GSM DateTime: %s\n", gsmDateTimeString.c_str());
 	time_t time = timeToUnixEpochSeconds(gsmDateTimeString.c_str());
 	rtc.setTime(time);
-	ESP_LOGI(TAG_GSM.c_str(), "Time set to EPOCH: %s", String(rtc.getEpoch()));
+	esp_log_write(ESP_LOG_INFO, TAG_GSM.c_str(), "Time set to EPOCH: %s\n", String(rtc.getEpoch()).c_str());
 }
 void setupSDCard()
 {
 	SPI.begin(SD_SCLK, SD_MISO, SD_MOSI, SD_CS);
 	if (!SD.begin(SD_CS)) {
-		ESP_LOGE(TAG.c_str(), "Card MOUNT FAIL");
+		esp_log_write(ESP_LOG_ERROR, TAG.c_str(), "Card MOUNT FAIL\n");
 		// TODO: Error handling
 	} else {
 		uint32_t cardSize = SD.cardSize() / (1024 * 1024);
 		String sdcardSizeString = "SDCard Size: " + String(cardSize) + "MB";
-		ESP_LOGD(TAG.c_str(), "%s", sdcardSizeString.c_str());
+		esp_log_write(ESP_LOG_DEBUG, TAG.c_str(), "%s\n", sdcardSizeString.c_str());
 	}
 }
 
@@ -282,23 +316,48 @@ void turnOffLEDs()
 	digitalWrite(PWR_PIN, LOW);
 }
 
+const String INFLUXDB_TOKEN =
+    "dUh2gbVLv7e3egqocxriDsJQNUacA9qZ5YXsYtdnVAglnHgy4nx-jDVO7nGlSF34BosfnuwnUDaviC7dQeC5RQ==";
+
+struct RequestInformation {
+	String method;
+	String host;
+	String path;
+	String body;
+};
+
+String buildRequest(const RequestInformation &requestInformation)
+{
+	String request = "";
+	request += requestInformation.method + " " + requestInformation.path + " HTTP/1.1\r\n";
+	request += "Host: " + requestInformation.host + "\r\n";
+	request += "Authorization: Token " + INFLUXDB_TOKEN + "\r\n";
+	request += "User-Agent: ESP32\r\n";
+	request += "Content-Type: text/plain\r\n";
+	request += "Content-Length: " + String(requestInformation.body.length()) + "\r\n";
+	request += "\r\n";
+	request += requestInformation.body;
+	return request;
+}
+
 void loop()
 {
 
 	// Restart takes quite some time
 	// To skip it, call init() instead of restart()
-	ESP_LOGD(TAG.c_str(), "Initializing modem...");
+	esp_log_write(ESP_LOG_DEBUG, TAG.c_str(), "Initializing modem...\n");
 	if (!modem.init()) {
-		ESP_LOGD(TAG.c_str(), "Failed to restart modem, attempting to continue without restarting");
+		esp_log_write(ESP_LOG_DEBUG, TAG.c_str(),
+		              "Failed to restart modem, attempting to continue without restarting\n");
 	}
 
 	String name = modem.getModemName();
 	delay(500);
-	ESP_LOGD(TAG.c_str(), "Modem Name %s", name);
+	esp_log_write(ESP_LOG_DEBUG, TAG.c_str(), "Modem Name %s\n", name.c_str());
 
 	String modemInfo = modem.getModemInfo();
 	delay(500);
-	ESP_LOGD(TAG.c_str(), "Modem Info: %s", modemInfo);
+	esp_log_write(ESP_LOG_DEBUG, TAG.c_str(), "Modem Info: %s\n", modemInfo.c_str());
 
 	// Set SIM7000G GPIO4 LOW ,turn off GPS power
 	// CMD:AT+SGPIO=0,4,1,0
@@ -360,64 +419,58 @@ void loop()
 
 	//	modem.disableGPS();
 	delay(200);
-	ESP_LOGD(TAG.c_str(), "%s", String(modem.getSignalQuality()));
+	esp_log_write(ESP_LOG_DEBUG, TAG.c_str(), "%s\n", String(modem.getSignalQuality()).c_str());
 	delay(200);
-	ESP_LOGD(TAG.c_str(), "Trying to connect to network");
+	esp_log_write(ESP_LOG_DEBUG, TAG.c_str(), "Trying to connect to network\n");
 	modem.gprsConnect(apn, gprsUser, gprsPass);
 	delay(200);
 	syncUTCTimeToRTC();
 
-	ESP_LOGD(TAG.c_str(), "Waiting for network...");
+	esp_log_write(ESP_LOG_DEBUG, TAG.c_str(), "Waiting for network...\n");
 	if (!modem.isNetworkConnected()) {
-		ESP_LOGD(TAG.c_str(), "Network not connected");
+		esp_log_write(ESP_LOG_DEBUG, TAG.c_str(), "Network not connected\n");
 		return;
 	} else {
-		ESP_LOGD(TAG.c_str(), "Network connected");
+		esp_log_write(ESP_LOG_DEBUG, TAG.c_str(), "Network connected\n");
 		delay(200);
 
 		// quality
-		ESP_LOGD(TAG.c_str(), "%s", String(modem.getSignalQuality()));
+		esp_log_write(ESP_LOG_DEBUG, TAG.c_str(), "%s\n", String(modem.getSignalQuality()).c_str());
 		// make a http post request
 		String url = "influxdb.qe-forte.uibk.ac.at";
 		String path = "/api/v2/write?org=QE&bucket=esp32test&precision=s";
 		Serial.print("Connecting to ");
-		ESP_LOGD(TAG.c_str(), "%s", url);
+		esp_log_write(ESP_LOG_DEBUG, TAG.c_str(), "%s\n", url.c_str());
 		// Use WiFiClient class to create TCP connections
 
 		while (!queue.empty()) {
 
-			TinyGsmClient client{modem};
-			const int httpPort = 80;
-			if (!client.connect(url.c_str(), httpPort)) {
-				ESP_LOGD(TAG.c_str(), "connection failed");
-				return;
-			}
-
 			xSemaphoreTake(xMutex, portMAX_DELAY);
 			String lineData = queue.front();
 			queue.pop();
 			xSemaphoreGive(xMutex);
 
+			RequestInformation requestInformation{.method = "POST", .host = url, .path = path, .body = lineData};
+
 			//"sensorName":"DRS26","timestamp":1666872216,"protocol":"I2C","value":0,"channel":0,"measurementType":"CIRCUMFERENCE_INCREMENT"
 
-			String token = "dUh2gbVLv7e3egqocxriDsJQNUacA9qZ5YXsYtdnVAglnHgy4nx-jDVO7nGlSF34BosfnuwnUDaviC7dQeC5RQ==";
-			// get request
-			client.println("POST " + path + " HTTP/1.1");
-			client.println("Host: " + url);
-			// authorization
-			client.println("Authorization: Token " + token);
-			// line data
-			client.println("Content-Type: text/plain");
-			// data length
-			client.println("Content-Length: " + String(lineData.length()));
-			client.println();
-			client.println(lineData);
+			String request = buildRequest(requestInformation);
+			esp_log_write(ESP_LOG_VERBOSE, TAG.c_str(), "request: %s\n", request.c_str());
+
+			TinyGsmClient client{modem};
+			const int httpPort = 80;
+			if (!client.connect(url.c_str(), httpPort)) {
+				esp_log_write(ESP_LOG_DEBUG, TAG.c_str(), "connection failed\n");
+				return;
+			}
+
+			client.print(request);
 
 			// print response
 			while (client.connected()) {
 				String line = client.readStringUntil('\n');
 				if (line == "\r") {
-					ESP_LOGD(TAG.c_str(), "headers received");
+					esp_log_write(ESP_LOG_DEBUG, TAG.c_str(), "headers received\n");
 					break;
 				}
 			}
@@ -435,7 +488,7 @@ void loop()
 	//		DBG("+CPOWD=1");
 	//	}
 	//	modem.poweroff();
-	ESP_LOGD(TAG.c_str(), "Poweroff.");
+	esp_log_write(ESP_LOG_DEBUG, TAG.c_str(), "Poweroff.");
 #endif
 
 	delay(1000);
-- 
GitLab