Connection keeps triggering onConnectionStatus and onConnected and creating new connections

[TheThing]

• I'm submitting a ...
  [x] bug report
  [ ] feature request
  [ ] question about the decisions made in the repository
  [ ] question about how to use this project

• Summary

For some reason there is a lot of disconnecting and connecting going on when I connect the client to my casparcg 2.2.0 server. It keeps calling onConnected = true before a timeout is immediately triggered and the connection is disposed and a new connection is created, calling onConnected again.

• Other information (e.g. detailed explanation, stacktraces, related issues, suggestions how to fix, links for us to have context, eg. StackOverflow, personal fork, etc.)

For debugging, I added a unique id to CasparCGSocket for every new socket that gets created so I can keep better track of each socket. I also added a logger into _createNewSocket in CasparCG.js for every time a socket gets disposed as well as the id for that socket that's getting disposed, every time CasparCGSocketStatusEvent.STATUS gets listened and whenever _onSocketStatusChange gets called.

In addition I added so whenever the connection is onConnected, it calls info:

connection = new CasparCG({
    host: currentHost,
    port: 5250,
    queueMode: 2,
    autoReconnectInterval: 5000,
    onError: err => {
      logger.error(err, 'CasparCG: Error')
    },
    onConnectionStatus: data => {
      // ...
    },
    onConnected: async connected => {
      logger.info('onConnected status: ' + connected +', checking if playing by sending info request to socket ' + connection._socket.id)
      connection.info('1', '100').then(function() {
        logger.info('info request finished successfully on ' + test)
      })
    },
  })

During opening of the application it "kinda looks normal":

06:09:51.798Z  INFO connection: listening to casparcgsocketconnectioneventstatus on 1000
06:09:51.799Z  INFO connection: disposing 1000
06:09:51.799Z  INFO connection: listening to casparcgsocketconnectioneventstatus on 1001
06:09:51.799Z  INFO connection: disposing 1001
06:09:51.799Z  INFO connection: listening to casparcgsocketconnectioneventstatus on 1002
06:09:51.808Z  INFO connection: _onSocketStatusChange on id 1002
    _val: {
      "connected": true
    }
    --
    socketStatus: {
      "connected": true
    }
06:09:51.809Z  INFO caspar: onConnected status: true, checking if playing by sending info request to socket 1002
06:09:51.818Z  INFO caspar: info request finished successfully on 1002

Then if I leave it running doing absolutely nothing, weird thing starts to happen. IT seems to immediately lose connection, reconnect, then dispose then reconnect again.

06:15:01.621Z  INFO connection: _onSocketStatusChange on id 1002
    _val: {
      "connected": false
    }
    --
    socketStatus: {
      "connected": false
    }
06:15:01.626Z  INFO connection: _onSocketStatusChange on id 1002
    _val: {
      "connected": true
    }
    --
    socketStatus: {
      "connected": true
    }
06:15:01.626Z  INFO caspar: onConnected status: true, checking if playing by sending info request to socket 1002
06:15:01.628Z  INFO connection: _onSocketStatusChange on id 1002
    _val: {
      "connected": false
    }
    --
    socketStatus: {
      "connected": false
    }
06:15:06.626Z  INFO connection: timeout on 1002
06:15:06.627Z  INFO connection: disposing 1002
06:15:06.627Z  INFO connection: listening to casparcgsocketconnectioneventstatus on 1003
06:15:06.630Z  INFO connection: _onSocketStatusChange on id 1003
    _val: {
      "connected": true
    }
    --
    socketStatus: {
      "connected": true
    }
06:15:06.630Z  INFO caspar: onConnected status: true, checking if playing by sending info request to socket 1003
06:15:06.631Z ERROR caspar: CasparCG: Error
    Error: Command error: Failed command
        at /usr/src/app/node_modules/casparcg-connection/dist/CasparCG.js:348:23
        at processTicksAndRejections (internal/process/task_queues.js:97:5)
06:15:06.632Z  INFO caspar: CasparCG: client is up and playing
06:15:06.634Z  INFO caspar: info request finished successfully on 1003

Notice the timestamp, this all happens in the same second, all these events.

Also notice that socket id 1002 06:15:01.626Z INFO caspar: onConnected status: true, checking if playing by sending info request to socket 1002 never finishes and instead I get onError triggered from that.

I have no idea what's going on but it seems that _onSocketStatusChange gets called three times in quick succession leading to the connection being disposed out of nowhere and triggered a new connection being connected every few minutes or so.

Update: In short, _onSocketStatusChange gets called three times on the same socket connection in almost the same millisecond before it disposes that socket connection and creates a brand new one. This seems to happen every 6 - 7 minutes on the dot.

[TheThing]

I think I found the issue, it seems to be an issue with running the software in docker. Running it on the host machine keeps the connection stable.

[TheThing]

I'm wondering if I should re-open this ticket cause the way the onConnection is working and reconnect is very wrong and triggers a lot of error in case there are legitimate connection problems.