connection dropping afer one minute

[saimirg]

trafficstars

Hi @mikuso, i need some help. I have a specific charger that is dropping connection after one minute. One the following simple code, the charger disconnects after one minute. However, if I connect the charger using the WS library the charger stays connected and i can communicate two ways.

This is the code used where the charger disconnects.

const server = new RPCServer({
    protocols: ['ocpp1.6'], // server accepts ocpp1.6 subprotocol
    strictMode: true,       // enable strict validation of requests & responses
});

server.auth((accept, reject, handshake) => {
    // accept the incoming client
    accept({
        // anything passed to accept() will be attached as a 'session' property of the client.
        sessionId: 'XYZ123'
    });
});

server.on('client', async (client) => {
    console.log(`${client.session.sessionId} connected!`); // `XYZ123 connected!`

    // create a specific handler for handling BootNotification requests
    client.handle('BootNotification', ({params}) => {
        console.log(`Server got BootNotification from ${client.identity}:`, params);

        // respond to accept the client
        return {
            status: "Accepted",
            interval: 300,
            currentTime: new Date().toISOString()
        };
    });
    
    // create a specific handler for handling Heartbeat requests
    client.handle('Heartbeat', ({params}) => {
        console.log(`Server got Heartbeat from ${client.identity}:`, params);

        // respond with the server's current time.
        return {
            currentTime: new Date().toISOString()
        };
    });
    
    // create a specific handler for handling StatusNotification requests
    client.handle('StatusNotification', ({params}) => {
        console.log(`Server got StatusNotification from ${client.identity}:`, params);
        return {};
    });

    // create a wildcard handler to handle any RPC method
    client.handle(({method, params}) => {
        // This handler will be called if the incoming method cannot be handled elsewhere.
        console.log(`Server got ${method} from ${client.identity}:`, params);

        // throw an RPC error to inform the server that we don't understand the request.
        throw createRPCError("NotImplemented");
    });

    // when clients disconnect, remove them from our Map
    client.once('close', () => {
        // check that we're about to delete the correct client
        console.log(`${client.session.sessionId} disconnected!`);
        console.log(`${client.identity} disconnected!`);

        // if (clients.get(client.identity) === client) {
        //     clients.delete(client.identity);
        // }
    });
});

await server.listen(3000);

Charger does not disconnect when using this code:

const express = require('express');
const http = require('http');
const WebSocket = require('ws');
const bodyParser = require('body-parser');

const app = express();
const server = http.createServer(app);
const wss = new WebSocket.Server({ server });

// Middleware
app.use(bodyParser.json());


// WebSocket handling for OCPP 1.6+
wss.on('connection', (ws) => {
  console.log('New WebSocket connection');

  ws.on('message', (message) => {
    const parsedMessage = JSON.parse(message);
    handleOCPPMessage(parsedMessage, (response) => {
      ws.send(JSON.stringify(response));
    });
  });
});

function handleOCPPMessage(message, callback) {
  const [messageType, messageId, action, payload] = message;

  switch (action) {
    case 'BootNotification':
      handleBootNotification(messageId, payload, callback);
      break;
    case 'StatusNotification':
      handleStatusNotification(messageId, payload, callback);
      break;
    default:
      callback([3, messageId, { error: 'NotImplemented' }]);
  }
}

function handleBootNotification(messageId, payload, callback) {
  console.log('Received BootNotification:', payload);
  const response = {
    status: 'Accepted',
    currentTime: new Date().toISOString(),
    interval: 300
  };
  callback([3, messageId, response]);
}

function handleStatusNotification(messageId, payload, callback) {
  console.log('Received StatusNotification:', payload);
  const response = {};
  callback([3, messageId, response]);
}

const PORT = process.env.PORT || 80;
server.listen(PORT, () => {
  console.log(`OCPP server listening on port ${PORT}`);
});```

[saimirg]

Hi @mikuso, we found out the problem is with Pong response. For some reasons Pong response from the charger is considered malformed and servers throws and error which drops the connection. If we disable ping requests from the server everything works fine but this has an effect on other chargers. We tried asking manufacturer to check the pong response but didnt succeed.

Anything else we can do to fix it ?

[mikuso]

Hi @saimirg

Were you able to recreate this issue using the WS library? What happens when the WS library receives a malformed pong?

One possible solution might be to set the pingIntervalMs option to Infinity when constructing the RPCServer, like so:

const server = new RPCServer({
    protocols: ['ocpp1.6'], // server accepts ocpp1.6 subprotocol
    strictMode: true,       // enable strict validation of requests & responses
    pingIntervalMs: Infinity, // disable pings
});

This should stop the server from sending pings, but disables the keepAlive functionality - so you may end up with lingering connections which get "stuck" if they don't cleanly disconnect.

[saimirg]

Yes, the same behavior happens with WS library when initiating Ping from server side. An error will be thrown and connection would drop when pong is received.

Setting pingIntervalMs: Infinity (we tried null) will work on this particular charger but has an effect on other chargers. It would be great if we could set it on charger level rather then on server.

[mikuso]

Understood. Have you tried using client.reconfigure() to do this on an individual basis?

Something like...

server.on('client', client => {
    if (client.identity === 'badclient') {
        client.reconfigure({ pingIntervalMs: Infinity });
    }
});

[saimirg]

hi @mikuso is there any way we can get more details from WS when a client gets disconnected ? Currently we only get this message: { "code": 1006, "reason": "" }

[mikuso]

WebSocket connections do support status codes for all kinds of disconnects, however the most common one you'll see is probably 1006. Unlike most other codes, this code does not originate from the other peer. This code is simply a stand-in to inform you that the underlying TCP connection has been terminated before the WebSocket could be properly closed.

I guess one point to note about code 1006 is that it doesn't differentiate between any of the reasons why the underlying TCP connection has closed, such as whether the connection was closed from the local or remote side, or the cause for closure.

It shouldn't be possible for you to close the underlying TCP connection locally, as this library doesn't really give you the ability to dig that far into the networking. This leaves us with 2 possible causes that I can think of:

1. The TCP connection was deliberately closed with a FIN packet from the other peer.
2. The TCP connection has been lost due to interference. Something has obstructed the 2-way communication necessary for TCP to work (e.g. if the peer or any of the routers/modems/proxies/firewalls along the way powered-down, crashed or rebooted - leading to a TCP timeout / RST packet)

Is it this detail you're looking for - knowing which of these two it is? If so, I can try digging a little deeper and see if I can find out how you might determine this.

If this isn't what you're looking for, please elaborate.

[mikuso]

Ok, I must amend my previous comment.

It is also possible for the RPCClient or RPCServerClient to call terminate() on the Websocket instance due to a ping timeout. (This is part of the keep-alive logic). This also results in a WebSocket close code of 1006. Unfortunately there is currently no event emitted or other signal that you could use to indicate that this has taken place.

Note: this only occurs if the remote peer is not responding to pings for an extended period of time - so the connection is already presumed to be dead (even if the OS doesn't seem to think so).

Nonetheless, you can disable this behaviour by passing pingIntervalMs: 0 as an option to the RPCClient or RPCServer constructor.

[saimirg]

Is there any way i can log ping-pong messages ? This could help eliminate few reasons. We are interested on the RPCserver side of logging.

[mikuso]

You can log successful ping/pong responses initiated from your side of the connection. However, this does not allow you to monitor unsuccessful ping/pongs (i.e. a ping without a response) nor does it let you monitor pings received from the remote peer.

With this caveat in mind, you can do this as follows:

server.on('client', (client) => {
    client.on('ping', ({rtt}) => {
        console.log(`Ping response received with ${rtt}ms round-trip time`);
    });
});

[mikuso]

If you really absolutely need to log each ping sent from your RPCServer and log the corresponding response, you could take the following monkey-patch approach:

server.on('client', (client) => {
    let pingId = 0;
    const oldPing = client._ws.ping;
    client._ws.ping = () => {
        const pingStr = `#${++pingId}`;
        const res = oldPing.call(client._ws, pingStr);
        console.log(`>>> PING:`, pingStr);
        return res;
    };
    
    client._ws.on('pong', (buf) => {
        console.log(`<<< PONG:`, buf?.toString());
    });
});

As ugly as it is, this is the only way to do this right now, as this behaviour is not really supported.

[KlajdiTolis]

Hi @mikuso We tried to log the ping & pong and this is the error we are getting

[mikuso]

Hi @KlajdiTolis ,

I could probably help you debug this if you can show me the code (- or better yet, a simple example that demonstrates the same error).

[KlajdiTolis]

We am not sure if it is more like a device problem or not , in first pong it is throwing an error and in other one it goes fine . We are trying to make some more test with device and than update you, thank you !

[KlajdiTolis]

Hi @mikuso We're experiencing a issue with one of my chargers. The charger connects and sends the first Ping-Pong, but on the second one, it closes the connection and immediately reconnects after 1-2 seconds. This cycle keeps repeating. We've added some logs to understand the problem.

How can I get more information on why this is happening?

[mikuso]

Refer back to my earlier post regarding close code 1006.

Does the disconnect only happen after ping/pong? If you disable the ping timeout behaviour, does this prevent the disconnect?

Do you have access to the source code of the charger to help debug this on the other side?

[KlajdiTolis]

Ping/pong is not effecting the disconnection

After debugging my server code, I noticed that when I use the following code:

   //++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
    client.handle('Heartbeat', async ({ params }) => {
        console.log(`Device sent Heartbeat: ${client.identity}`, params);
  
        logMessage(client.identity, "Heartbeat", params, client.session.tenantID);

        const response = await heartBeat({ deviceid: client.identity }, { timestamp: new Date() });

        return {
            currentTime: new Date().toISOString()
        };
    });

the charger does not close its connection.

However, when I add the following part of the code, the connection closes:

   //++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
    client.handle('Heartbeat', async ({ params }) => {
        console.log(`Device sent Heartbeat: ${client.identity}`, params);

   if (disconnectTimeouts.has(client.identity)) {
              clearTimeout(disconnectTimeouts.get(client.identity));
              logMessage(client.identity, "Timeout_Cleared", `Charger ${client.identity} timeout cleared.`, client.session.tenantID, "high");
              disconnectTimeouts.delete(client.identity);
          }
  
        logMessage(client.identity, "Heartbeat", params, client.session.tenantID);

        const response = await heartBeat({ deviceid: client.identity }, { timestamp: new Date() });

        return {
            currentTime: new Date().toISOString(),
            message: "Heartbeat processed successfully"
        };
    });

the problem is happening only on a AC Vestel charger

[mikuso]

Sounds like something is going wrong with your code there then. Add a try/catch block around it like this to see if you can avert a failure:

   //++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
    client.handle('Heartbeat', async ({ params }) => {
        console.log(`Device sent Heartbeat: ${client.identity}`, params);

         try {
            if (disconnectTimeouts.has(client.identity)) {
                 clearTimeout(disconnectTimeouts.get(client.identity));
                 logMessage(client.identity, "Timeout_Cleared", `Charger ${client.identity} timeout cleared.`, client.session.tenantID, "high");
                 disconnectTimeouts.delete(client.identity);
             }
         } catch (err) {
            console.log('Caught error:', err.message);
         }
  
        logMessage(client.identity, "Heartbeat", params, client.session.tenantID);

        const response = await heartBeat({ deviceid: client.identity }, { timestamp: new Date() });

        return {
            currentTime: new Date().toISOString()
        };
    });

[KlajdiTolis]

I have tried also you example but I think I found the issue—it was related to the return object.

When I use this code the charger disconnects: return { currentTime: new Date().toISOString(), message: "Heartbeat processed successfully" }; However, if I change it to: return { currentTime: new Date().toISOString() }; (without the message field), the charger works fine.

It's strange because this only happens with this specific charger—the others were working fine.

Thank you for you response @mikuso

[mikuso]

This makes sense, as 'message' is not a valid member of that schema. If the charger performs strict validation, then this is a likely outcome.

Glad you figured it out.