Enhanced logging on WS Server
MODIFY
src/server/ocpp/json/JsonCentralSystemServer.ts
src/server/ocpp/json/JsonCentralSystemServer.ts
@@ -10,6 +10,7 @@ import CentralSystemServer from '../CentralSystemServer';
import ChargingStation from '../../../types/ChargingStation';
import ChargingStationClient from '../../../client/ocpp/ChargingStationClient';
import ChargingStationConfiguration from '../../../types/configuration/ChargingStationConfiguration';
+import Configuration from '../../../utils/Configuration';
import Constants from '../../../utils/Constants';
import JsonRestWSConnection from './JsonRestWSConnection';
import JsonWSConnection from './JsonWSConnection';
@@ -33,9 +34,9 @@ export default class JsonCentralSystemServer extends CentralSystemServer {
public constructor(centralSystemConfig: CentralSystemConfiguration, chargingStationConfig: ChargingStationConfiguration) {
super(centralSystemConfig, chargingStationConfig);
// Start job to clean WS connections
- this.startCleanupWSConnectionsJob();
+ this.checkAndCleanupWSConnections();
// Monitor WS activity
- this.monitorWSConnectionsJob();
+ this.monitorWSConnections();
}
public start(): void {
@@ -193,15 +194,15 @@ export default class JsonCentralSystemServer extends CentralSystemServer {
// Keep it on the ws
ws.wsWrapper = wsWrapper;
// Lock incoming WS messages
- await this.aquireLockForWSMessageRequest(wsWrapper);
+ await this.aquireLockForWSRequest(wsWrapper);
try {
this.runningWSMessages++;
- // Log (do not put the log before the lock or you'll receive a WS Message before which will close the WS connection => Unit Tests fails)
+ // Do not put the log before the lock or it will delay the opening and the set of the lock which will be taken by the incoming WS Messages in // => Unit Tests fails)
await Logging.logInfo({
tenantID: Constants.DEFAULT_TENANT,
action: ServerAction.WS_CONNECTION,
module: MODULE_NAME, method: 'onOpen',
- message: `WS Connection - Incoming: '${wsWrapper.url}'`
+ message: `WS Connection - '${wsWrapper.url}'`
});
// Check Json connection
if (wsWrapper.url.startsWith('/OCPP16')) {
@@ -220,7 +221,7 @@ export default class JsonCentralSystemServer extends CentralSystemServer {
});
}
} catch (error) {
- await Logging.logException(error, ServerAction.WS_CONNECTION_CLOSED, MODULE_NAME, 'onOpen', wsWrapper.tenantID ?? Constants.DEFAULT_TENANT);
+ await Logging.logException(error, ServerAction.WS_CONNECTION, MODULE_NAME, 'onOpen', wsWrapper.tenantID ?? Constants.DEFAULT_TENANT);
await this.closeWebSocket(wsWrapper, WebSocketCloseEventStatusCode.CLOSE_ABNORMAL, `WS Connection - Closed: ${error.message as string}`);
} finally {
this.runningWSMessages--;
@@ -314,13 +315,13 @@ export default class JsonCentralSystemServer extends CentralSystemServer {
}
}
- private async aquireLockForWSMessageRequest(wsWrapper: WSWrapper, ocppMessageType?: OCPPMessageType): Promise<void> {
+ private async aquireLockForWSRequest(wsWrapper: WSWrapper, ocppMessageType?: OCPPMessageType): Promise<void> {
// Only lock requests, not responses
if (ocppMessageType && ocppMessageType !== OCPPMessageType.CALL_MESSAGE) {
return;
}
- // Wait for Init (avoid WS connection with same URL)
- await this.waitForNextWSMessageProcessing(wsWrapper);
+ // Wait for Init (avoid WS connection with same URL), ocppMessageType only provided when a WS Message is received
+ await this.waitForWSLockToRelease(wsWrapper, ocppMessageType ? false : true);
// Lock
this.runningWSRequestsMessages[wsWrapper.url] = true;
}
@@ -339,7 +340,7 @@ export default class JsonCentralSystemServer extends CentralSystemServer {
const [ocppMessageType] = JSON.parse(message);
const wsWrapper = ws.wsWrapper;
// Lock incoming WS messages
- await this.aquireLockForWSMessageRequest(wsWrapper, ocppMessageType);
+ await this.aquireLockForWSRequest(wsWrapper, ocppMessageType);
try {
this.runningWSMessages++;
// OCPP Request?
@@ -366,7 +367,6 @@ export default class JsonCentralSystemServer extends CentralSystemServer {
}
}
-
private async getWSConnectionFromWebSocket(wsWrapper: WSWrapper, closeWSIfNotFound = true): Promise<WSConnection> {
// Return the WS connection
if (wsWrapper.jsonWSConnection) {
@@ -396,16 +396,43 @@ export default class JsonCentralSystemServer extends CentralSystemServer {
});
}
- private async waitForNextWSMessageProcessing(wsWrapper: WSWrapper): Promise<boolean> {
+ private async waitForWSLockToRelease(wsWrapper: WSWrapper, incomingConnection: boolean): Promise<boolean> {
+ let numberOfTrials = 20;
// Wait for init to handle multiple same WS Connection
if (this.runningWSRequestsMessages[wsWrapper.url]) {
+ await Logging.logWarning({
+ tenantID: Constants.DEFAULT_TENANT,
+ action: ServerAction.WS_CONNECTION,
+ module: MODULE_NAME, method: 'waitForWSLockToRelease',
+ message: `WS ${incomingConnection ? 'Connection' : 'Request'} - Lock taken: Wait and try to acquire the lock for '${wsWrapper.url}'...`
+ });
this.waitingWSMessages++;
// eslint-disable-next-line no-constant-condition
while (true) {
// Wait
- await Utils.sleep(500);
- // Initialization has been done
+ await Utils.sleep(250);
+ // Message has been processed
if (!this.runningWSRequestsMessages[wsWrapper.url]) {
+ await Logging.logInfo({
+ tenantID: Constants.DEFAULT_TENANT,
+ action: ServerAction.WS_CONNECTION,
+ module: MODULE_NAME, method: 'waitForWSLockToRelease',
+ message: `WS ${incomingConnection ? 'Connection' : 'Request'} - Lock acquired successfully for '${wsWrapper.url}'`
+ });
+ this.waitingWSMessages--;
+ break;
+ }
+ // Handle remaining trial
+ numberOfTrials--;
+ if (numberOfTrials <= 0) {
+ // Abnormal situation: The lock should not be taken for so long!
+ await Logging.logError({
+ tenantID: Constants.DEFAULT_TENANT,
+ action: ServerAction.WS_CONNECTION,
+ module: MODULE_NAME, method: 'waitForWSLockToRelease',
+ message: `WS ${incomingConnection ? 'Connection' : 'Request'} - Cannot acquire the lock - Lock freed (force) for '${wsWrapper.url}'`
+ });
+ // Free the lock
this.waitingWSMessages--;
break;
}
@@ -475,31 +502,34 @@ export default class JsonCentralSystemServer extends CentralSystemServer {
return this.centralSystemConfig.debug || Utils.isDevelopmentEnv();
}
- private monitorWSConnectionsJob() {
+ private monitorWSConnections() {
+ // eslint-disable-next-line @typescript-eslint/no-misused-promises
+ setInterval(async () => {
+ await Logging.logDebug({
+ tenantID: Constants.DEFAULT_TENANT,
+ action: ServerAction.WS_CONNECTION, module: MODULE_NAME, method: 'monitorWSConnectionsJob',
+ message: `${this.jsonWSConnections.size} WS connections, ${this.jsonRestWSConnections.size} REST connections, ${this.runningWSMessages} Messages, ${Object.keys(this.runningWSRequestsMessages).length} Requests, ${this.waitingWSMessages} queued WS Message(s)`,
+ });
if (this.isDebug()) {
- setInterval(() => {
Logging.logConsoleDebug('=====================================');
Logging.logConsoleDebug(`** ${this.jsonWSConnections.size} JSON Connection(s)`);
Logging.logConsoleDebug(`** ${this.jsonRestWSConnections.size} REST Connection(s)`);
- Logging.logConsoleDebug(`** ${Object.keys(this.runningWSRequestsMessages).length} running WS Messages (Requests)`);
+ Logging.logConsoleDebug(`** ${Object.keys(this.runningWSRequestsMessages).length} running WS Requests`);
Logging.logConsoleDebug(`** ${this.runningWSMessages} running WS Messages (Requests + Responses)`);
Logging.logConsoleDebug(`** ${this.waitingWSMessages} queued WS Message(s)`);
Logging.logConsoleDebug('=====================================');
- }, 30 * 1000);
}
+ }, 30 * 60 * 1000);
}
- private startCleanupWSConnectionsJob() {
- // Check WS connections
+ private checkAndCleanupWSConnections() {
// eslint-disable-next-line @typescript-eslint/no-misused-promises
setInterval(async () => {
- this.isDebug() && Logging.logConsoleDebug('===========================================');
// Check Json connections
await this.checkAndCleanupWebSockets(this.jsonWSConnections, 'Json');
// Check Rest connections
await this.checkAndCleanupWebSockets(this.jsonRestWSConnections, 'Rest');
- this.isDebug() && Logging.logConsoleDebug('===========================================');
- }, 30 * 60 * 1000);
+ }, Configuration.getChargingStationConfig().heartbeatIntervalOCPPJSecs * 1000);
}
private async checkAndCleanupWebSockets(wsConnections: Map<string, WSConnection>, type: 'Json'|'Rest') {
@@ -536,6 +566,8 @@ export default class JsonCentralSystemServer extends CentralSystemServer {
message, detailedMessages: { validConnections, invalidConnections }
});
}
+ } else {
+ this.isDebug() && Logging.logConsoleDebug('No Web Socket connection to ping');
}
}
}

MODIFY
src/storage/mongodb/DatabaseUtils.ts
src/storage/mongodb/DatabaseUtils.ts
@@ -427,7 +427,7 @@ export default class DatabaseUtils {
{
$gte: [
{ $divide: [{ $subtract: [new Date(), '$lastSeen'] }, 1000] },
- Configuration.getChargingStationConfig().heartbeatIntervalOCPPSSecs * 2
+ Configuration.getChargingStationConfig().heartbeatIntervalOCPPJSecs * 2
]
}
]

Enhanced logging on WS Server