alta-vr / js-tale

GNU General Public License v3.0
2 stars 10 forks source link

Bot tries to connect to shutdown server, causing unhandled connection errors #12

Open mdingena opened 3 years ago

mdingena commented 3 years ago

Observations

When a server shuts down, js-tale attempts to connect to that server. This issue is similar to #11, which describes js-tale connecting on every server status update.

When the server shuts down, that counts as a status update, and js-tale will connect to the server again. Only this time it will fail because the server is not there anymore.

Here's a dump of my logs.

2021-07-01T01:03:50.803085+00:00 heroku[web.1]: Restarting
2021-07-01T01:03:50.824360+00:00 heroku[web.1]: State changed from up to starting
2021-07-01T01:03:51.979456+00:00 heroku[web.1]: Stopping all processes with SIGTERM

7/1/2021, 1:03:59 AM - [ApiConnection] Setting up https client
7/1/2021, 1:03:59 AM - [ApiConnection] Decoding token
7/1/2021, 1:03:59 AM - [ApiConnection] User ID: 1529569283
7/1/2021, 1:03:59 AM - [ApiConnection] Username: voodoo mod
7/1/2021, 1:04:29 AM - [LiveList] Subscribed to groups delete
7/1/2021, 1:04:31 AM - [LiveList] Subscribed to groups create
7/1/2021, 1:04:32 AM - [Group] Joined (... other servers omitted ...)
7/1/2021, 1:04:32 AM - [Group] Joined 773758417 - pepe
7/1/2021, 1:04:32 AM - [Group] Joined (... other servers omitted ...)
7/1/2021, 1:04:48 AM - [LiveList] Subscribed to (... other servers omitted ...)
7/1/2021, 1:04:49 AM - [LiveList] Subscribed to pepe servers create
7/1/2021, 1:04:49 AM - [LiveList] Subscribed to (... other servers omitted ...)
7/1/2021, 1:04:58 AM - [GroupManager] Accepted all group invites
7/1/2021, 1:04:59 AM - [LiveList] Subscribed to (... other servers omitted ...)
7/1/2021, 1:04:59 AM - [LiveList] Subscribed to pepe servers delete
7/1/2021, 1:04:59 AM - [LiveList] Subscribed to (... other servers omitted ...)
7/1/2021, 1:04:59 AM - [Group] Subscribed to pepe status
7/1/2021, 1:04:59 AM - [LiveList] Subscribed to (... other servers omitted ...)
7/1/2021, 1:04:59 AM - [Server] pepe received status. Online: true. Players: 0
7/1/2021, 1:04:59 AM - [Group] Refreshed server info for pepe (1947466580)
7/1/2021, 1:05:01 AM - [GroupManager] Enabling automatic console for all groups
7/1/2021, 1:05:01 AM - [Group] Enabling (... other servers omitted ...)
7/1/2021, 1:05:01 AM - [Group] Enabling automatic console for pepe
7/1/2021, 1:05:01 AM - [ServerConnection] Creating server connection
7/1/2021, 1:05:01 AM - [ServerConnection] Doing initialize
7/1/2021, 1:05:01 AM - [ServerConnection] Connecting to pepe
7/1/2021, 1:05:01 AM - [Voodoo] Voodoo Server is online
7/1/2021, 1:05:01 AM - [Express] API listening on port 8733
State changed from starting to up
Connecting to 34.212.181.102:7370
Connecting to 34.223.108.179:7394
Connecting to 34.219.192.150:7744
Connecting to 34.223.250.77:7257
Connecting to 44.229.14.94:7671
Resolving connection!
Connection Succeeded, Authenticated as: 1529569283 - voodoo mod
7/1/2021, 1:05:02 AM - [ServerConnection] Subscribing to PlayerJoined
7/1/2021, 1:05:02 AM - [ServerConnection] Subscribing to PlayerLeft
Resolving connection!
Connection Succeeded, Authenticated as: 1529569283 - voodoo mod
7/1/2021, 1:05:02 AM - [ServerConnection] Subscribing to PlayerJoined
7/1/2021, 1:05:02 AM - [ServerConnection] Subscribing to PlayerLeft
Connecting to 52.40.17.250:7161
7/1/2021, 1:05:02 AM - [ServerConnection] Subscribed to PlayerJoined : Success
7/1/2021, 1:05:02 AM - [ServerConnection] Subscribed to PlayerJoined : Success
7/1/2021, 1:05:02 AM - [ServerConnection] Subscribed to PlayerLeft : Success
7/1/2021, 1:05:02 AM - [ServerConnection] Subscribed to PlayerLeft : Success
(... output omitted ...)
7/1/2021, 1:05:02 AM - [Bot] Connected to pepe
(... output omitted ...)
7/1/2021, 1:09:22 AM - [Server] pepe received status. Online: true. Players: 0
7/1/2021, 1:09:22 AM - [ServerConnection] Doing initialize
7/1/2021, 1:09:22 AM - [ServerConnection] Connecting to pepe
Connecting to 52.40.17.250:7161
Resolving connection!
Connection Succeeded, Authenticated as: 1529569283 - voodoo mod
7/1/2021, 1:09:24 AM - [ServerConnection] Connection closed
CloseEvent {
  target: <ref *1> WebSocket {
    _events: [Object: null prototype] {
      open: [Function],
      message: [Function],
      error: [Function],
      close: [Function]
    },
    _eventsCount: 4,
    _maxListeners: undefined,
    _binaryType: 'nodebuffer',
    _closeCode: 1006,
    _closeFrameReceived: false,
    _closeFrameSent: false,
    _closeMessage: '',
    _closeTimer: null,
    _extensions: {},
    _protocol: '',
    _readyState: 3,
    _receiver: Receiver {
      _writableState: [WritableState],
      _events: [Object: null prototype] {},
      _eventsCount: 0,
      _maxListeners: undefined,
      _binaryType: 'nodebuffer',
      _extensions: {},
      _isServer: false,
      _maxPayload: 104857600,
      _bufferedBytes: 0,
      _buffers: [],
      _compressed: false,
      _payloadLength: 161,
      _mask: undefined,
      _fragmented: 0,
      _masked: false,
      _fin: true,
      _opcode: 1,
      _totalPayloadLength: 0,
      _messageLength: 0,
      _fragments: [],
      _state: 0,
      _loop: false,
      [Symbol(kCapture)]: false,
      [Symbol(websocket)]: [Circular *1]
    },
    _sender: Sender {
      _extensions: {},
      _socket: [Socket],
      _firstFragment: true,
      _compress: false,
      _bufferedBytes: 0,
      _deflating: false,
      _queue: []
    },
    _socket: Socket {
      connecting: false,
      _hadError: false,
      _parent: null,
      _host: null,
      _readableState: [ReadableState],
      _events: [Object: null prototype],
      _eventsCount: 2,
      _maxListeners: undefined,
      _writableState: [WritableState],
      allowHalfOpen: false,
      _sockname: null,
      _pendingData: null,
      _pendingEncoding: '',
      server: null,
      _server: null,
      parser: null,
      _httpMessage: null,
      timeout: 0,
      write: [Function: writeAfterFIN],
      [Symbol(async_id_symbol)]: 5030,
      [Symbol(kHandle)]: null,
      [Symbol(kSetNoDelay)]: true,
      [Symbol(lastWriteQueueSize)]: 0,
      [Symbol(timeout)]: null,
      [Symbol(kBuffer)]: null,
      [Symbol(kBufferCb)]: null,
      [Symbol(kBufferGen)]: null,
      [Symbol(kCapture)]: false,
      [Symbol(kBytesRead)]: 294,
      [Symbol(kBytesWritten)]: 434,
      [Symbol(RequestTimeout)]: undefined,
      [Symbol(websocket)]: undefined
    },
    _bufferedAmount: 0,
    _isServer: false,
    _redirects: 0,
    _url: 'ws://52.40.17.250:7161',
    _req: null,
    [Symbol(kCapture)]: false
  },
  type: 'close',
  wasClean: false,
  reason: '',
  code: 1006,
  logger: '[ServerConnection] ',
  timestamp: 1625101764642
}
7/1/2021, 1:09:24 AM - [Server] Console to pepe disconnected.
7/1/2021, 1:09:24 AM - [Voodoo] Removed all players of server 1947466580
7/1/2021, 1:09:24 AM - [Bot] Disconnected from pepe
7/1/2021, 1:09:24 AM - [ServerConnection] Connection closed
CloseEvent {
  target: <ref *1> WebSocket {
    _events: [Object: null prototype] {
      open: [Function],
      message: [Function],
      error: [Function],
      close: [Function]
    },
    _eventsCount: 4,
    _maxListeners: undefined,
    _binaryType: 'nodebuffer',
    _closeCode: 1006,
    _closeFrameReceived: false,
    _closeFrameSent: false,
    _closeMessage: '',
    _closeTimer: null,
    _extensions: {},
    _protocol: '',
    _readyState: 3,
    _receiver: Receiver {
      _writableState: [WritableState],
      _events: [Object: null prototype] {},
      _eventsCount: 0,
      _maxListeners: undefined,
      _binaryType: 'nodebuffer',
      _extensions: {},
      _isServer: false,
      _maxPayload: 104857600,
      _bufferedBytes: 0,
      _buffers: [],
      _compressed: false,
      _payloadLength: 486,
      _mask: undefined,
      _fragmented: 0,
      _masked: false,
      _fin: true,
      _opcode: 1,
      _totalPayloadLength: 0,
      _messageLength: 0,
      _fragments: [],
      _state: 0,
      _loop: false,
      [Symbol(kCapture)]: false,
      [Symbol(websocket)]: [Circular *1]
    },
    _sender: Sender {
      _extensions: {},
      _socket: [Socket],
      _firstFragment: true,
      _compress: false,
      _bufferedBytes: 0,
      _deflating: false,
      _queue: []
    },
    _socket: Socket {
      connecting: false,
      _hadError: false,
      _parent: null,
      _host: null,
      _readableState: [ReadableState],
      _events: [Object: null prototype],
      _eventsCount: 2,
      _maxListeners: undefined,
      _writableState: [WritableState],
      allowHalfOpen: false,
      _sockname: null,
      _pendingData: null,
      _pendingEncoding: '',
      server: null,
      _server: null,
      parser: null,
      _httpMessage: null,
      timeout: 0,
      write: [Function: writeAfterFIN],
      [Symbol(async_id_symbol)]: 2542,
      [Symbol(kHandle)]: null,
      [Symbol(kSetNoDelay)]: true,
      [Symbol(lastWriteQueueSize)]: 0,
      [Symbol(timeout)]: null,
      [Symbol(kBuffer)]: null,
      [Symbol(kBufferCb)]: null,
      [Symbol(kBufferGen)]: null,
      [Symbol(kCapture)]: false,
      [Symbol(kBytesRead)]: 1856,
      [Symbol(kBytesWritten)]: 588,
      [Symbol(RequestTimeout)]: undefined,
      [Symbol(websocket)]: undefined
    },
    _bufferedAmount: 0,
    _isServer: false,
    _redirects: 0,
    _url: 'ws://52.40.17.250:7161',
    _req: null,
    [Symbol(kCapture)]: false
  },
  type: 'close',
  wasClean: false,
  reason: '',
  code: 1006,
  logger: '[ServerConnection] ',
  timestamp: 1625101764655
}
7/1/2021, 1:09:24 AM - [Server] Console to pepe disconnected.
7/1/2021, 1:09:24 AM - [Voodoo] Removed all players of server 1947466580
7/1/2021, 1:09:24 AM - [Bot] Disconnected from pepe
Narmdo commented 3 years ago

Did the status update say the server is offline? I presume not, given it tried to reconnect. Verification on that would be good, as it sounds like it could be an issue on the API side.

mdingena commented 3 years ago

Did the status update say the server is offline? I presume not, given it tried to reconnect.

It tries to connect as a result of #11. The log does mention 7/1/2021, 1:09:22 AM - [Server] pepe received status. Online: true. Players: 0 So it receives a status update which says the server is online, but when it tries to make a new connection (again, that is the bug described in #11) it'll discover that the server is actually offline.

mdingena commented 3 years ago

v2.0.0-rc.4 seems to have resolved #11, but I'm still getting these messages. Perhaps just is just a left-over console.log() that doesn't need to be here? It seems to log the whole CloseEvent and just blows up the server logs, but it doesn't seem to try and reconnect to an offline server anymore?

9/13/2021, 1:17:17 AM - [Server] Elysium received status. Online: true. Players: 0
9/13/2021, 1:17:19 AM - [ServerConnection] Connection closed
CloseEvent {
  target: <ref *1> WebSocket {
    _events: [Object: null prototype] {
      open: [Function],
      message: [Function],
      error: [Function],
      close: [Function]
    },
    _eventsCount: 4,
    _maxListeners: undefined,
    _binaryType: 'nodebuffer',
    _closeCode: 1006,
    _closeFrameReceived: false,
    _closeFrameSent: false,
    _closeMessage: '',
    _closeTimer: null,
    _extensions: {},
    _protocol: '',
    _readyState: 3,
    _receiver: Receiver {
      _writableState: [WritableState],
      _events: [Object: null prototype] {},
      _eventsCount: 0,
      _maxListeners: undefined,
      _binaryType: 'nodebuffer',
      _extensions: {},
      _isServer: false,
      _maxPayload: 104857600,
      _bufferedBytes: 0,
      _buffers: [],
      _compressed: false,
      _payloadLength: 206,
      _mask: undefined,
      _fragmented: 0,
      _masked: false,
      _fin: true,
      _opcode: 1,
      _totalPayloadLength: 0,
      _messageLength: 0,
      _fragments: [],
      _state: 0,
      _loop: false,
      [Symbol(kCapture)]: false,
      [Symbol(websocket)]: [Circular *1]
    },
    _sender: Sender {
      _extensions: {},
      _socket: [Socket],
      _firstFragment: true,
      _compress: false,
      _bufferedBytes: 0,
      _deflating: false,
      _queue: []
    },
    _socket: Socket {
      connecting: false,
      _hadError: false,
      _parent: null,
      _host: null,
      _readableState: [ReadableState],
      _events: [Object: null prototype],
      _eventsCount: 2,
      _maxListeners: undefined,
      _writableState: [WritableState],
      allowHalfOpen: false,
      _sockname: null,
      _pendingData: null,
      _pendingEncoding: '',
      server: null,
      _server: null,
      parser: null,
      _httpMessage: null,
      timeout: 0,
      write: [Function: writeAfterFIN],
      [Symbol(async_id_symbol)]: 32352,
      [Symbol(kHandle)]: null,
      [Symbol(kSetNoDelay)]: true,
      [Symbol(lastWriteQueueSize)]: 0,
      [Symbol(timeout)]: null,
      [Symbol(kBuffer)]: null,
      [Symbol(kBufferCb)]: null,
      [Symbol(kBufferGen)]: null,
      [Symbol(kCapture)]: false,
      [Symbol(kBytesRead)]: 2275,
      [Symbol(kBytesWritten)]: 586,
      [Symbol(RequestTimeout)]: undefined,
      [Symbol(websocket)]: undefined
    },
    _bufferedAmount: 0,
    _isServer: false,
    _redirects: 0,
    _url: 'ws://54.212.4.20:7431',
    _req: null,
    [Symbol(kCapture)]: false
  },
  type: 'close',
  wasClean: false,
  reason: '',
  code: 1006,
  logger: '[ServerConnection] ',
  timestamp: 1631495839057
}
mdingena commented 3 years ago

Does this need to be here?

https://github.com/alta-vr/js-tale/blob/838f561182c907ced610ddf65a13779ed68b95f5/src/Groups/ServerConnection.ts#L152

OfficialExouls commented 2 years ago

Not sure if this will fully fix the issue, but under js-tale/src/groups/server.ts in the elevateState method it calls for online_ping. If this is coming from the group server status subscription then it isn't sent when the server is offline, only last_online is sent having the value of the last time the server was online. last_online should be sent when the server is online as well.