Cleaner, more elegant logging (#24)

Restructured logging procedures

- updated logging levels per message type (more in the future)
- cleaned up redundancies
- increased performances
- messages only printed during change of state (once)

* - added WiFi Firmware version check and update message
- tested on MKR1000 and MKR1010
NOTE: WiFINina wrongly reports "1.2.0" when WiFi.firmwareVersion() is invoked, although version "1.2.1" is set in the source files

Author: ubidefeo

Diff for: src/ArduinoIoTCloud.cpp

@@ -304,9 +304,9 @@ void ArduinoIoTCloudClass::connectionCheck() {
 
     if (connection->getStatus() != CONNECTION_STATE_CONNECTED) {
       if(iotStatus == IOT_STATUS_CLOUD_CONNECTED){
-        iotStatus = IOT_STATUS_CLOUD_DISCONNECTED;
+        setIoTConnectionState(IOT_STATUS_CLOUD_DISCONNECTED);
       }else{
-        iotStatus = IOT_STATUS_CLOUD_CONNECTING;  
+        //setIoTConnectionState(IOT_STATUS_CLOUD_CONNECTING);
       }
       return;
     }
@@ -317,61 +317,79 @@ void ArduinoIoTCloudClass::connectionCheck() {
 
   switch (iotStatus) {
     case IOT_STATUS_IDLE:
+    {
+      int connectionAttempt;
       if(connection == NULL){
-        if(!begin(*_net, _brokerAddress)){
-          debugMessage("Error Starting Arduino Cloud\nTrying again in a few seconds", 0);
-          iotStatus = IOT_STATUS_CLOUD_ERROR;
-          return;
-        }
+        connectionAttempt = begin(*_net, _brokerAddress);
       }else{
-        if (!begin(connection, _brokerAddress)) {
-          debugMessage("Error Starting Arduino Cloud\nTrying again in a few seconds", 0);
-          iotStatus = IOT_STATUS_CLOUD_ERROR;
-          return;
-        }
+        connectionAttempt = begin(connection, _brokerAddress);
       }
-      
-      iotStatus = IOT_STATUS_CLOUD_CONNECTING;
+      if(!connectionAttempt){
+        debugMessage("Error Starting Arduino Cloud\nTrying again in a few seconds", 0);
+        setIoTConnectionState(IOT_STATUS_CLOUD_ERROR);
+        return;
+      }
+      setIoTConnectionState(IOT_STATUS_CLOUD_CONNECTING);
       break;
+    } 
+      
     case IOT_STATUS_CLOUD_ERROR:
       debugMessage("Cloud Error. Retrying...", 0);
-      iotStatus = IOT_STATUS_CLOUD_RECONNECTING;
+      setIoTConnectionState(IOT_STATUS_CLOUD_RECONNECTING);
       break;
     case IOT_STATUS_CLOUD_CONNECTED:
-      debugMessage("connected to Arduino IoT Cloud", 3);
+      debugMessage(".", 4, false, true);
       break;
     case IOT_STATUS_CLOUD_DISCONNECTED:
-      debugMessage("disconnected from Arduino IoT Cloud", 0);
-      iotStatus = IOT_STATUS_CLOUD_RECONNECTING;
+      setIoTConnectionState(IOT_STATUS_CLOUD_RECONNECTING);
       break;
     case IOT_STATUS_CLOUD_RECONNECTING:
-      debugMessage("IoT Cloud reconnecting...", 1);
-      //wifiClient.stop();
       int arduinoIoTReconnectionAttempt;
       arduinoIoTReconnectionAttempt = reconnect(*_net);
       *msgBuffer = 0;
       sprintf(msgBuffer, "ArduinoCloud.reconnect(): %d", arduinoIoTReconnectionAttempt);
-      debugMessage(msgBuffer, 1);
+      debugMessage(msgBuffer, 2);
       if (arduinoIoTReconnectionAttempt == 1) {
-        iotStatus = IOT_STATUS_CLOUD_CONNECTED;
+        setIoTConnectionState(IOT_STATUS_CLOUD_CONNECTED);
         CloudSerial.begin(9600);
         CloudSerial.println("Hello from Cloud Serial!");
       }
       break;
     case IOT_STATUS_CLOUD_CONNECTING:
-      debugMessage("IoT Cloud connecting...", 1);
+      
       int arduinoIoTConnectionAttempt;
       arduinoIoTConnectionAttempt = connect();
       *msgBuffer = 0;
       sprintf(msgBuffer, "ArduinoCloud.connect(): %d", arduinoIoTConnectionAttempt);
-      debugMessage(msgBuffer, 2);
+      debugMessage(msgBuffer, 4);
       if (arduinoIoTConnectionAttempt == 1) {
-        iotStatus = IOT_STATUS_CLOUD_CONNECTED;
+        setIoTConnectionState(IOT_STATUS_CLOUD_CONNECTED);
         CloudSerial.begin(9600);
         CloudSerial.println("Hello from Cloud Serial!");
       }
       break;
   }
 }
 
+void ArduinoIoTCloudClass::setIoTConnectionState(ArduinoIoTConnectionStatus _newState){
+  switch(_newState){
+    case IOT_STATUS_CLOUD_ERROR:
+      debugMessage("Arduino, we have a problem.", 0);
+      break;
+    case IOT_STATUS_CLOUD_CONNECTING:
+      debugMessage("Connecting to Arduino IoT Cloud...", 0);
+      break;
+    case IOT_STATUS_CLOUD_RECONNECTING:
+      debugMessage("Reconnecting to Arduino IoT Cloud...", 0);
+      break;
+    case IOT_STATUS_CLOUD_CONNECTED:
+      debugMessage("Connected to Arduino IoT Cloud", 0);
+      break;
+    case IOT_STATUS_CLOUD_DISCONNECTED:
+      debugMessage("Disconnected from Arduino IoT Cloud", 0);
+      break;
+  }
+  iotStatus = _newState;
+}
+
 ArduinoIoTCloudClass ArduinoCloud;

Diff for: src/ArduinoIoTCloud.h

@@ -121,7 +121,7 @@ class ArduinoIoTCloudClass {
   bool mqttReconnect(int const maxRetries, int const timeout);
 
   ArduinoIoTConnectionStatus getIoTStatus() { return iotStatus; }
-
+  void setIoTConnectionState(ArduinoIoTConnectionStatus _newState);
 private:
   ArduinoIoTConnectionStatus iotStatus = IOT_STATUS_IDLE;
   ConnectionManager *connection;

Diff for: src/ConnectionManager.h

@@ -25,7 +25,6 @@
 #include <Client.h>
 
 enum NetworkConnectionState {
-  CONNECTION_STATE_IDLE,
   CONNECTION_STATE_INIT,
   CONNECTION_STATE_CONNECTING,
   CONNECTION_STATE_CONNECTED,
@@ -46,7 +45,7 @@ class ConnectionManager {
 
 protected:
   unsigned long lastValidTimestamp = 0;
-  NetworkConnectionState netConnectionState = CONNECTION_STATE_IDLE;
+  NetworkConnectionState netConnectionState = CONNECTION_STATE_INIT;
 
 };
 
@@ -57,6 +56,7 @@ class ConnectionManager {
 #define NETWORK_HARDWARE_ERROR WL_NO_SHIELD
 #define NETWORK_IDLE_STATUS WL_IDLE_STATUS
 #define NETWORK_CONNECTED WL_CONNECTED
+#define WIFI_FIRMWARE_VERSION_REQUIRED WIFI_FIRMWARE_REQUIRED
 #endif
 
 #ifdef ARDUINO_SAMD_MKRWIFI1010
@@ -65,6 +65,7 @@ class ConnectionManager {
 #define NETWORK_HARDWARE_ERROR WL_NO_MODULE
 #define NETWORK_IDLE_STATUS WL_IDLE_STATUS
 #define NETWORK_CONNECTED WL_CONNECTED
+#define WIFI_FIRMWARE_VERSION_REQUIRED WIFI_FIRMWARE_LATEST_VERSION
 #endif
 
 #ifdef ARDUINO_SAMD_MKRGSM1400
@@ -76,12 +77,18 @@ class ConnectionManager {
 #endif
 
 static int debugMessageLevel = ARDUINO_CLOUD_DEBUG_LEVEL;
-inline void debugMessage(char *_msg, uint8_t _debugLevel) {
+inline void debugMessage(char *_msg, uint8_t _debugLevel, bool _timestamp = true, bool _newline = true) {
   if (_debugLevel <= debugMessageLevel) {
     char prepend[20];
     sprintf(prepend, "\n[ %d ] ", millis());
-    Serial.print(prepend);
-    Serial.println(_msg);
+    if(_timestamp)
+      Serial.print(prepend);
+    if(_newline){
+      Serial.println(_msg);
+    }else{
+      Serial.print(_msg);
+    }
+    
   }
 }
 

Diff for: src/WiFiConnectionManager.h

@@ -31,17 +31,20 @@ class WiFiConnectionManager : public ConnectionManager {
 
   void changeConnectionState(NetworkConnectionState _newState);
 
-  const int CHECK_INTERVAL_IDLE = 100;
   const int CHECK_INTERVAL_INIT = 100;
   const int CHECK_INTERVAL_CONNECTING = 500;
-  const int CHECK_INTERVAL_GETTIME = 1000;
+  const int CHECK_INTERVAL_GETTIME = 100;
   const int CHECK_INTERVAL_CONNECTED = 10000;
   const int CHECK_INTERVAL_RETRYING = 5000;
   const int CHECK_INTERVAL_DISCONNECTED = 1000;
   const int CHECK_INTERVAL_ERROR = 500;
 
+  const int MAX_GETTIME_RETRY = 30;
+
   const char *ssid, *pass;
   unsigned long lastConnectionTickTime, lastNetworkStep;
+  unsigned long getTimeRetries;
+
   WiFiClient wifiClient;
   int connectionTickTimeInterval;
 };
@@ -51,7 +54,8 @@ static const unsigned long NETWORK_CONNECTION_INTERVAL = 30000;
 WiFiConnectionManager::WiFiConnectionManager(const char *ssid, const char *pass) :
   ssid(ssid), pass(pass),
   lastConnectionTickTime(millis()),
-  connectionTickTimeInterval(CHECK_INTERVAL_IDLE) {
+  connectionTickTimeInterval(CHECK_INTERVAL_INIT),
+  getTimeRetries(MAX_GETTIME_RETRY) {
 }
 
 unsigned long WiFiConnectionManager::getTime() {
@@ -62,28 +66,39 @@ void WiFiConnectionManager::init() {
 }
 
 void WiFiConnectionManager::changeConnectionState(NetworkConnectionState _newState) {
-  netConnectionState = _newState;
-  int newInterval = CHECK_INTERVAL_IDLE;
+  char msgBuffer[120];
+  int newInterval = CHECK_INTERVAL_INIT;
   switch (_newState) {
     case CONNECTION_STATE_INIT:
       newInterval = CHECK_INTERVAL_INIT;
       break;
     case CONNECTION_STATE_CONNECTING:
+      *msgBuffer = 0;
+      sprintf(msgBuffer, "Connecting to \"%s\"", ssid);
+      debugMessage(msgBuffer, 2);
       newInterval = CHECK_INTERVAL_CONNECTING;
       break;
     case CONNECTION_STATE_GETTIME:
       newInterval = CHECK_INTERVAL_GETTIME;
+      debugMessage("Acquiring Time from Network", 3);
       break;
     case CONNECTION_STATE_CONNECTED:
       newInterval = CHECK_INTERVAL_CONNECTED;
       break;
     case CONNECTION_STATE_DISCONNECTED:
+      *msgBuffer = 0;
+      sprintf(msgBuffer, "WiFi.status(): %d", WiFi.status());
+      debugMessage(msgBuffer, 4);
+      *msgBuffer = 0;
+      sprintf(msgBuffer, "Connection to \"%s\" lost.", ssid);
+      debugMessage(msgBuffer, 0);
+      debugMessage("Attempting reconnection", 0);
       newInterval = CHECK_INTERVAL_DISCONNECTED;
-      
       break;
   }
   connectionTickTimeInterval = newInterval;
   lastConnectionTickTime = millis();
+  netConnectionState = _newState;
 }
 
 void WiFiConnectionManager::check() {
@@ -92,9 +107,6 @@ void WiFiConnectionManager::check() {
   int networkStatus = 0;
   if (now - lastConnectionTickTime > connectionTickTimeInterval) {
     switch (netConnectionState) {
-      case CONNECTION_STATE_IDLE:
-        changeConnectionState(CONNECTION_STATE_INIT);
-        break;
       case CONNECTION_STATE_INIT:
         networkStatus = WiFi.status();
         *msgBuffer = 0;
@@ -108,19 +120,21 @@ void WiFiConnectionManager::check() {
           return;
         }
         *msgBuffer = 0;
-        sprintf(msgBuffer, "WiFi Firmware v. %s", WiFi.firmwareVersion());
+        sprintf(msgBuffer, "Current WiFi Firmware: %s", WiFi.firmwareVersion());
         debugMessage(msgBuffer, 0);
+        if(strcmp(WiFi.firmwareVersion(), WIFI_FIRMWARE_VERSION_REQUIRED) != 0){
+          *msgBuffer = 0;
+          sprintf(msgBuffer, "Latest WiFi Firmware: %s", WIFI_FIRMWARE_VERSION_REQUIRED);
+          debugMessage(msgBuffer, 0);
+          debugMessage("Please update to latest version for optimal performance.", 0);
+        }
         changeConnectionState(CONNECTION_STATE_CONNECTING);
         break;
       case CONNECTION_STATE_CONNECTING:
-        *msgBuffer = 0;
-        sprintf(msgBuffer, "Connecting to \"%s\"", ssid);
-        debugMessage(msgBuffer, 2);
-
         networkStatus = WiFi.begin(ssid, pass);
         *msgBuffer = 0;
         sprintf(msgBuffer, "WiFi.status(): %d", networkStatus);
-        debugMessage(msgBuffer, 2);
+        debugMessage(msgBuffer, 4);
         if (networkStatus != NETWORK_CONNECTED) {
           *msgBuffer = 0;
           sprintf(msgBuffer, "Connection to \"%s\" failed", ssid);
@@ -136,46 +150,47 @@ void WiFiConnectionManager::check() {
           sprintf(msgBuffer, "Connected to \"%s\"", ssid);
           debugMessage(msgBuffer, 2);
           changeConnectionState(CONNECTION_STATE_GETTIME);
+          getTimeRetries = MAX_GETTIME_RETRY;
           return;
         }
         break;
       case CONNECTION_STATE_GETTIME:
-        debugMessage("Acquiring Time from Network", 3);
+        
         unsigned long networkTime;
         networkTime = WiFi.getTime();
-        *msgBuffer = 0;
-        sprintf(msgBuffer, "Network Time: %u", networkTime);
-        debugMessage(msgBuffer, 3);
+        
+        debugMessage(".", 3, false, false);
         if(networkTime > lastValidTimestamp){
           lastValidTimestamp = networkTime;
+          *msgBuffer = 0;
+          sprintf(msgBuffer, "Network Time: %u", networkTime);
+          debugMessage(msgBuffer, 3);
           changeConnectionState(CONNECTION_STATE_CONNECTED);
-        }
+        } else if (WiFi.status() != WL_CONNECTED) {
+           changeConnectionState(CONNECTION_STATE_DISCONNECTED);
+        } else if (!getTimeRetries--) {
+           changeConnectionState(CONNECTION_STATE_DISCONNECTED);
+        } 
         break;
       case CONNECTION_STATE_CONNECTED:
         // keep testing connection
         networkStatus = WiFi.status();
         *msgBuffer = 0;
         sprintf(msgBuffer, "WiFi.status(): %d", networkStatus);
-        debugMessage(msgBuffer, 2);
+        debugMessage(msgBuffer, 4);
         if (networkStatus != WL_CONNECTED) {
           changeConnectionState(CONNECTION_STATE_DISCONNECTED);
           return;
         }
         *msgBuffer = 0;
         sprintf(msgBuffer, "Connected to \"%s\"", ssid);
-        debugMessage(msgBuffer, 2);
+        debugMessage(msgBuffer, 4);
         break;
       case CONNECTION_STATE_DISCONNECTED:
         //WiFi.disconnect();
         WiFi.end();
 
-        *msgBuffer = 0;
-        sprintf(msgBuffer, "DISC | WiFi.status(): %d", WiFi.status());
-        debugMessage(msgBuffer, 1);
-        *msgBuffer = 0;
-        sprintf(msgBuffer, "Connection to \"%s\" lost.", ssid);
-        debugMessage(msgBuffer, 0);
-        debugMessage("Attempting reconnection", 1);
+        
         changeConnectionState(CONNECTION_STATE_CONNECTING);
         //wifiClient.stop();
         break;