Improve logging.

Signed-off-by: Jérôme Benoit <jerome.benoit@sap.com>

diff --git a/src/charging-station/AutomaticTransactionGenerator.js b/src/charging-station/AutomaticTransactionGenerator.js
index 5ba078f8874cc7a6fe08341ec06adfd200c6c1ef..e30fafd83dc8163e2c793e600968144fbf54d47f 100644 (file)
--- a/src/charging-station/AutomaticTransactionGenerator.js
+++ b/src/charging-station/AutomaticTransactionGenerator.js
@@ -58,7 +58,6 @@ class AutomaticTransactionGenerator {
       if (start < this._chargingStation._stationInfo.AutomaticTransactionGenerator.probabilityOfStart) {
         skip = 0;
         // Start transaction
-        logger.info(this._basicFormatLog(connectorId) + ' start transaction');
         const startTransaction = performance.timerify(this.startTransaction);
         this._performanceObserver.observe({entryTypes: ['function']});
         const startResponse = await startTransaction(connectorId, this);

diff --git a/src/charging-station/ChargingStation.js b/src/charging-station/ChargingStation.js
index daa9475f44d2907218547049729c76105b50acbe..ebc3509ce97c193dde369d4f9269d5e6a65b705f 100644 (file)
--- a/src/charging-station/ChargingStation.js
+++ b/src/charging-station/ChargingStation.js
@@ -4,7 +4,6 @@ const WebSocket = require('ws');
 const Constants = require('../utils/Constants');
 const Utils = require('../utils/Utils');
 const OCPPError = require('./OcppError');
-const {v4: uuid} = require('uuid');
 const AutomaticTransactionGenerator = require('./AutomaticTransactionGenerator');
 const Statistics = require('../utils/Statistics');
 const fs = require('fs');
@@ -171,7 +170,7 @@ class ChargingStation {
   onOpen() {
     logger.info(`${this._basicFormatLog()} Is connected to server through ${this._url}`);
     if (this._isSocketRestart) {
-      this.basicStartMessageSequence();
+      this._basicStartMessageSequence();
       if (this._messageQueue.length > 0) {
         this._messageQueue.forEach((message) => {
           if (this._wsConnection.readyState === WebSocket.OPEN) {
@@ -182,7 +181,7 @@ class ChargingStation {
     } else {
       // At first start, send BootNotification
       try {
-        this.sendMessage(uuid(), this._bootNotificationMessage, Constants.OCPP_JSON_CALL_MESSAGE, 'BootNotification');
+        this.sendMessage(Utils.generateUUID(), this._bootNotificationMessage, Constants.OCPP_JSON_CALL_MESSAGE, 'BootNotification');
       } catch (error) {
         logger.error(this._basicFormatLog() + ' Send boot notification error: ' + error);
       }
@@ -218,7 +217,7 @@ class ChargingStation {
   }
 
   onPing() {
-    logger.info(this._basicFormatLog() + ' Has received a WS ping (rfc6455) from the server');
+    logger.debug(this._basicFormatLog() + ' Has received a WS ping (rfc6455) from the server');
   }
 
   async onMessage(message) {
@@ -281,6 +280,25 @@ class ChargingStation {
     }
   }
 
+  // eslint-disable-next-line class-methods-use-this
+  async _startHeartbeat(self) {
+    if (self._heartbeatInterval && !self._heartbeatSetInterval) {
+      logger.info(self._basicFormatLog() + ' Heartbeat started every ' + self._heartbeatInterval + 'ms');
+      self._heartbeatSetInterval = setInterval(() => {
+        try {
+          const payload = {
+            currentTime: new Date().toISOString(),
+          };
+          self.sendMessage(Utils.generateUUID(), payload, Constants.OCPP_JSON_CALL_MESSAGE, 'Heartbeat');
+        } catch (error) {
+          logger.error(self._basicFormatLog() + ' Send heartbeat error: ' + error);
+        }
+      }, self._heartbeatInterval);
+    } else {
+      logger.error(self._basicFormatLog() + ' Heartbeat interval undefined, not starting the heartbeat');
+    }
+  }
+
   _reconnect(error) {
     logger.error(this._basicFormatLog() + ' Socket: abnormally closed', error);
     // Stop heartbeat interval
@@ -308,7 +326,7 @@ class ChargingStation {
 
   send(command, messageType = Constants.OCPP_JSON_CALL_MESSAGE) {
     // Send Message
-    return this.sendMessage(uuid(), command, messageType);
+    return this.sendMessage(Utils.generateUUID(), command, messageType);
   }
 
   sendError(messageId, err) {
@@ -318,6 +336,23 @@ class ChargingStation {
     return this.sendMessage(messageId, error, Constants.OCPP_JSON_CALL_ERROR_MESSAGE);
   }
 
+  async sendStatusNotification(connectorId, status, errorCode = 'NoError') {
+    try {
+      const payload = {
+        connectorId,
+        errorCode,
+        status,
+      };
+      await this.sendMessage(Utils.generateUUID(), payload, Constants.OCPP_JSON_CALL_MESSAGE, 'StatusNotification');
+    } catch (error) {
+      logger.error(this._basicFormatLog() + ' Send status error: ' + error);
+    }
+  }
+
+  async sendStatusNotificationWithTimeout(connectorId, status, errorCode = 'NoError', timeout = Constants.STATUS_NOTIFICATION_TIMEOUT) {
+    setTimeout(() => this.sendStatusNotification(connectorId, status, errorCode), timeout);
+  }
+
   sendMessage(messageId, command, messageType = Constants.OCPP_JSON_CALL_RESULT_MESSAGE, commandName = '') {
     // Send a message through wsConnection
     const self = this;
@@ -388,16 +423,7 @@ class ChargingStation {
     });
   }
 
-  handleResponseBootNotification(payload) {
-    if (payload.status === 'Accepted') {
-      this._heartbeatInterval = payload.interval * 1000;
-      this.basicStartMessageSequence();
-    } else {
-      logger.info(this._basicFormatLog() + ' Boot Notification rejected');
-    }
-  }
-
-  async basicStartMessageSequence() {
+  async _basicStartMessageSequence() {
     this._startHeartbeat(this);
     // build connectors
     if (!this._connectors) {
@@ -428,12 +454,12 @@ class ChargingStation {
     for (const connector in this._connectors) {
       if (!this._connectors[connector].transactionStarted) {
         if (this._connectors[connector].bootStatus) {
-          setTimeout(() => this.sendStatusNotification(connector, this._connectors[connector].bootStatus), Constants.STATUS_NOTIFICATION_TIMEOUT);
+          this.sendStatusNotificationWithTimeout(connector, this._connectors[connector].bootStatus);
         } else {
-          setTimeout(() => this.sendStatusNotification(connector, 'Available'), Constants.STATUS_NOTIFICATION_TIMEOUT);
+          this.sendStatusNotificationWithTimeout(connector, 'Available');
         }
       } else {
-        setTimeout(() => this.sendStatusNotification(connector, 'Charging'), Constants.STATUS_NOTIFICATION_TIMEOUT);
+        this.sendStatusNotificationWithTimeout(connector, 'Charging');
       }
     }
 
@@ -446,6 +472,25 @@ class ChargingStation {
     this._statistics.start();
   }
 
+  _resetTransactionOnConnector(connectorID) {
+    this._connectors[connectorID].transactionStarted = false;
+    this._connectors[connectorID].transactionId = null;
+    this._connectors[connectorID].lastConsumptionValue = -1;
+    this._connectors[connectorID].lastSoC = -1;
+    if (this._connectors[connectorID].transactionInterval) {
+      clearInterval(this._connectors[connectorID].transactionInterval);
+    }
+  }
+
+  handleResponseBootNotification(payload) {
+    if (payload.status === 'Accepted') {
+      this._heartbeatInterval = payload.interval * 1000;
+      this._basicStartMessageSequence();
+    } else {
+      logger.info(this._basicFormatLog() + ' Boot Notification rejected');
+    }
+  }
+
   handleResponseStartTransaction(payload, requestPayload) {
     // Reset connector transaction related attributes
     this._connectors[requestPayload.connectorId].transactionStarted = false;
@@ -458,7 +503,7 @@ class ChargingStation {
           this._connectors[connector].transactionId = payload.transactionId;
           this._connectors[connector].lastConsumptionValue = 0;
           this._connectors[connector].lastSoC = 0;
-          logger.info(this._basicFormatLog() + ' Transaction ' + this._connectors[connector].transactionId + ' STARTED on ' + this._stationInfo.name + '#' + requestPayload.connectorId + ' with idTag ' + requestPayload.idTag);
+          logger.info(this._basicFormatLog() + ' Transaction ' + this._connectors[connector].transactionId + ' STARTED on ' + this._stationInfo.name + '#' + requestPayload.connectorId + ' for idTag ' + requestPayload.idTag);
           this.sendStatusNotification(requestPayload.connectorId, 'Charging');
           const configuredMeterValueSampleInterval = this._configuration.configurationKey.find((value) => value.key === 'MeterValueSampleInterval');
           this.startMeterValues(requestPayload.connectorId,
@@ -477,36 +522,16 @@ class ChargingStation {
     }
   }
 
-  async sendStatusNotification(connectorId, status, errorCode = 'NoError') {
-    try {
-      const payload = {
-        connectorId,
-        errorCode,
-        status,
-      };
-      await this.sendMessage(uuid(), payload, Constants.OCPP_JSON_CALL_MESSAGE, 'StatusNotification');
-    } catch (error) {
-      logger.error(this._basicFormatLog() + ' Send status error: ' + error);
-    }
+  handleResponseStatusNotification(payload) {
+    logger.debug(this._basicFormatLog() + ' Status notification response received: %j', payload);
   }
 
-  // eslint-disable-next-line class-methods-use-this
-  async _startHeartbeat(self) {
-    if (self._heartbeatInterval && !self._heartbeatSetInterval) {
-      logger.info(self._basicFormatLog() + ' Heartbeat started every ' + self._heartbeatInterval + 'ms');
-      self._heartbeatSetInterval = setInterval(() => {
-        try {
-          const payload = {
-            currentTime: new Date().toISOString(),
-          };
-          self.sendMessage(uuid(), payload, Constants.OCPP_JSON_CALL_MESSAGE, 'Heartbeat');
-        } catch (error) {
-          logger.error(self._basicFormatLog() + ' Send heartbeat error: ' + error);
-        }
-      }, self._heartbeatInterval);
-    } else {
-      logger.error(self._basicFormatLog() + ' Heartbeat interval undefined, not starting the heartbeat');
-    }
+  handleResponseMeterValues(payload) {
+    logger.debug(this._basicFormatLog() + ' MeterValues response received: %j', payload);
+  }
+
+  handleResponseHeartbeat(payload) {
+    logger.debug(this._basicFormatLog() + ' Heartbeat response received: %j', payload);
   }
 
   async handleRequest(messageId, commandName, commandPayload) {
@@ -553,7 +578,7 @@ class ChargingStation {
       if (this._authorizedTags.find((value) => value === commandPayload.idTag)) {
         // Authorization successful start transaction
         setTimeout(() => this.sendStartTransaction(transactionConnectorID, commandPayload.idTag), Constants.START_TRANSACTION_TIMEOUT);
-        logger.debug(this._basicFormatLog() + ' Transaction remotely STARTED on ' + this._stationInfo.name + '#' + transactionConnectorID + ' with idTag ' + commandPayload.idTag);
+        logger.debug(this._basicFormatLog() + ' Transaction remotely STARTED on ' + this._stationInfo.name + '#' + transactionConnectorID + ' for idTag ' + commandPayload.idTag);
         return Constants.OCPP_RESPONSE_ACCEPTED;
       }
       logger.error(this._basicFormatLog() + ' Remote starting transaction REJECTED with status ' + commandPayload.idTagInfo.status + ', idTag ' + commandPayload.idTag);
@@ -561,7 +586,16 @@ class ChargingStation {
     }
     // No local authorization check required => start transaction
     setTimeout(() => this.sendStartTransaction(transactionConnectorID, commandPayload.idTag), Constants.START_TRANSACTION_TIMEOUT);
-    logger.debug(this._basicFormatLog() + ' Transaction remotely STARTED on ' + this._stationInfo.name + '#' + transactionConnectorID + ' with idTag ' + commandPayload.idTag);
+    logger.debug(this._basicFormatLog() + ' Transaction remotely STARTED on ' + this._stationInfo.name + '#' + transactionConnectorID + ' for idTag ' + commandPayload.idTag);
+    return Constants.OCPP_RESPONSE_ACCEPTED;
+  }
+
+  async handleRemoteStopTransaction(commandPayload) {
+    for (const connector in this._connectors) {
+      if (this._connectors[connector].transactionId === commandPayload.transactionId) {
+        this.sendStopTransaction(commandPayload.transactionId, connector);
+      }
+    }
     return Constants.OCPP_RESPONSE_ACCEPTED;
   }
 
@@ -573,7 +607,7 @@ class ChargingStation {
         meterStart: 0,
         timestamp: new Date().toISOString(),
       };
-      return await this.sendMessage(uuid(), payload, Constants.OCPP_JSON_CALL_MESSAGE, 'StartTransaction');
+      return await this.sendMessage(Utils.generateUUID(), payload, Constants.OCPP_JSON_CALL_MESSAGE, 'StartTransaction');
     } catch (error) {
       logger.error(this._basicFormatLog() + ' Send start transaction error: ' + error);
       this._resetTransactionOnConnector(connectorID);
@@ -588,7 +622,7 @@ class ChargingStation {
         meterStop: 0,
         timestamp: new Date().toISOString(),
       };
-      await this.sendMessage(uuid(), payload, Constants.OCPP_JSON_CALL_MESSAGE, 'StopTransaction');
+      await this.sendMessage(Utils.generateUUID(), payload, Constants.OCPP_JSON_CALL_MESSAGE, 'StopTransaction');
       logger.info(this._basicFormatLog() + ' Transaction ' + this._connectors[connectorID].transactionId + ' STOPPED on ' + this._stationInfo.name + '#' + connectorID);
       this.sendStatusNotification(connectorID, 'Available');
     } catch (error) {
@@ -599,16 +633,6 @@ class ChargingStation {
     }
   }
 
-  _resetTransactionOnConnector(connectorID) {
-    this._connectors[connectorID].transactionStarted = false;
-    this._connectors[connectorID].transactionId = null;
-    this._connectors[connectorID].lastConsumptionValue = -1;
-    this._connectors[connectorID].lastSoC = -1;
-    if (this._connectors[connectorID].transactionInterval) {
-      clearInterval(this._connectors[connectorID].transactionInterval);
-    }
-  }
-
   // eslint-disable-next-line class-methods-use-this
   async sendMeterValues(connectorID, interval, self) {
     try {
@@ -627,7 +651,7 @@ class ChargingStation {
           if (sampledValueLcl.sampledValue[index].value > 100) {
             logger.info(self._basicFormatLog() + ' Meter type: ' +
               (sampledValueLcl.sampledValue[index].measurand ? sampledValueLcl.sampledValue[index].measurand : 'default') +
-              ' value: ' + sampledValueLcl.sampledValue[index].value);
+              ', value: ' + sampledValueLcl.sampledValue[index].value);
           }
         } else {
           // Persist previous value in connector
@@ -645,7 +669,7 @@ class ChargingStation {
           if (sampledValueLcl.sampledValue[index].value > (self._stationInfo.maxPower * 3600 / interval) || sampledValueLcl.sampledValue[index].value < 500) {
             logger.info(self._basicFormatLog() + ' Meter type: ' +
               (sampledValueLcl.sampledValue[index].measurand ? sampledValueLcl.sampledValue[index].measurand : 'default') +
-              ' value: ' + sampledValueLcl.sampledValue[index].value + '/' + (self._stationInfo.maxPower * 3600 / interval));
+              ', value: ' + sampledValueLcl.sampledValue[index].value + '/' + (self._stationInfo.maxPower * 3600 / interval));
           }
         }
       }
@@ -655,7 +679,7 @@ class ChargingStation {
         transactionId: self._connectors[connectorID].transactionId,
         meterValue: [sampledValueLcl],
       };
-      await self.sendMessage(uuid(), payload, Constants.OCPP_JSON_CALL_MESSAGE, 'MeterValues');
+      await self.sendMessage(Utils.generateUUID(), payload, Constants.OCPP_JSON_CALL_MESSAGE, 'MeterValues');
     } catch (error) {
       logger.error(self._basicFormatLog() + ' Send meter values error: ' + error);
     }
@@ -676,15 +700,6 @@ class ChargingStation {
     }, interval);
   }
 
-  async handleRemoteStopTransaction(commandPayload) {
-    for (const connector in this._connectors) {
-      if (this._connectors[connector].transactionId === commandPayload.transactionId) {
-        this.sendStopTransaction(commandPayload.transactionId, connector);
-      }
-    }
-    return Constants.OCPP_RESPONSE_ACCEPTED;
-  }
-
   hasAuthorizedTags() {
     return Array.isArray(this._authorizedTags) && this._authorizedTags.length > 0;
   }

diff --git a/src/utils/Configuration.js b/src/utils/Configuration.js
index 9220127ceaad763eaa85daea562cd6632d1b4033..cba1db2c3f2c9c39bbe7993694ac4b3b93964b18 100644 (file)
--- a/src/utils/Configuration.js
+++ b/src/utils/Configuration.js
@@ -44,6 +44,10 @@ class Configuration {
     return Utils.objectHasOwnProperty(Configuration.getConfig(), 'consoleLog') ? Configuration.getConfig().consoleLog : false;
   }
 
+  static getLogFormat() {
+    return Utils.objectHasOwnProperty(Configuration.getConfig(), 'logFormat') ? Configuration.getConfig().logFormat : 'simple';
+  }
+
   static getLogLevel() {
     return Utils.objectHasOwnProperty(Configuration.getConfig(), 'logLevel') ? Configuration.getConfig().logLevel : 'info';
   }

diff --git a/src/utils/Logger.js b/src/utils/Logger.js
index 0f0fff0ebda47d28c2bdf33d8ba4dfb3d807f71d..1f34b00cb2a6c4f87a78b7ee778f15490559b513 100644 (file)
--- a/src/utils/Logger.js
+++ b/src/utils/Logger.js
@@ -3,8 +3,7 @@ const Winston = require('winston');
 
 const logger = Winston.createLogger({
   level: Configuration.getLogLevel(),
-  format: Winston.format.combine(Winston.format.splat(), Winston.format.json()),
-  defaultMeta: {service: 'user-service'},
+  format: Winston.format.combine(Winston.format.splat(), Winston.format[Configuration.getLogFormat()]()),
   transports: [
     //
     // - Write to all logs with level `info` and below to `combined.log`
@@ -21,7 +20,7 @@ const logger = Winston.createLogger({
 //
 if (Configuration.getConsoleLog()) {
   logger.add(new Winston.transports.Console({
-    format: Winston.format.simple(),
+    format: Winston.format.combine(Winston.format.splat(), Winston.format[Configuration.getLogFormat()]()),
   }));
 }
 

diff --git a/src/utils/Utils.js b/src/utils/Utils.js
index a06d57ead326e3dc052417fe902b54a9036b04fa..5f467feaa6b70035fa75dbd2ce2e7e228c1c93bc 100644 (file)
--- a/src/utils/Utils.js
+++ b/src/utils/Utils.js
@@ -1,7 +1,7 @@
 const {v4: uuid} = require('uuid');
 
 class Utils {
-  static generateGUID() {
+  static generateUUID() {
     return uuid();
   }