search

mqttjs / MQTT.js

The MQTT client for Node.js and the browser
Other
8.59k stars 1.42k forks source link

WS connect fails on MacMini+Node 18.x and RaspPiBulleseye+Node18.x but works when Node is downgraded to Node16.x #1551

Closed jsiegenthaler closed 1 year ago

jsiegenthaler commented 1 year ago

A connect or reconnect attempt on a MacMini+Node 18.20.0 fails, and also RaspberryPiBullseye+Node18.20.0. when Node is downgraded to Node 16.x, then mqtt connect works OK

Using Node 18.20.0 on a Windows 10 Home 21H2 PC also works fine, and also on a RaspberryPiBuster also works fine.

Node 18.20.0 log: 2022-11-10T16:21:25.764Z mqttjs connecting to an MQTT broker... 2022-11-10T16:21:25.765Z mqttjs:client MqttClient :: options.protocol wss 2022-11-10T16:21:25.765Z mqttjs:client MqttClient :: options.protocolVersion 4 2022-11-10T16:21:25.765Z mqttjs:client MqttClient :: options.username myusername 2022-11-10T16:21:25.765Z mqttjs:client MqttClient :: options.keepalive 60 2022-11-10T16:21:25.765Z mqttjs:client MqttClient :: options.reconnectPeriod 1000 2022-11-10T16:21:25.765Z mqttjs:client MqttClient :: options.rejectUnauthorized undefined 2022-11-10T16:21:25.765Z mqttjs:client MqttClient :: options.topicAliasMaximum undefined 2022-11-10T16:21:25.766Z mqttjs:client MqttClient :: clientId ljg4yomi-ypkq-y5ad-twir-8lyt9qq32q0d 2022-11-10T16:21:25.766Z mqttjs:client MqttClient :: setting up stream 2022-11-10T16:21:25.768Z mqttjs:client _setupStream :: calling method to clear reconnect 2022-11-10T16:21:25.768Z mqttjs:client _clearReconnect : clearing reconnect timer 2022-11-10T16:21:25.768Z mqttjs:client _setupStream :: using streamBuilder provided to client to create stream 2022-11-10T16:21:25.768Z mqttjs calling streambuilder for wss 2022-11-10T16:21:25.768Z mqttjs:ws streamBuilder 2022-11-10T16:21:25.768Z mqttjs:ws createWebSocket 2022-11-10T16:21:25.768Z mqttjs:ws protocol: MQTT 4 2022-11-10T16:21:25.769Z mqttjs:ws creating new Websocket for url: wss://myendpoint.com:443/mqtt and protocol: mqtt 2022-11-10T16:21:25.771Z mqttjs:client _setupStream :: pipe stream to writable stream 2022-11-10T16:21:25.771Z mqttjs:client _setupStream: sending packet connect 2022-11-10T16:21:25.772Z mqttjs:client sendPacket :: packet: { cmd: 'connect' } 2022-11-10T16:21:25.772Z mqttjs:client sendPacket :: emitting packetsend 2022-11-10T16:21:25.772Z mqttjs:client sendPacket :: writing to stream 2022-11-10T16:21:25.787Z mqttjs:client sendPacket :: writeToStream result true

Then nothing more is logged until the connect times out:

2022-11-10T16:21:35.790Z mqttjs:client !!connectTimeout hit!! Calling _cleanUp with force true 2022-11-10T16:21:35.792Z mqttjs:client _cleanUp :: forced? true 2022-11-10T16:21:35.792Z mqttjs:client _cleanUp :: (ljg4yomi-ypkq-y5ad-twir-8lyt9qq32q0d) :: destroying stream 2022-11-10T16:21:35.807Z mqttjs:client _cleanUp :: client not disconnecting. Clearing and resetting reconnect. 2022-11-10T16:21:35.807Z mqttjs:client _clearReconnect : clearing reconnect timer 2022-11-10T16:21:35.807Z mqttjs:client _setupReconnect :: emit offline state 2022-11-10T16:21:35.807Z mqttjs:client _setupReconnect :: set reconnecting to true 2022-11-10T16:21:35.808Z mqttjs:client _setupReconnect :: setting reconnectTimer for 1000 ms 2022-11-10T16:21:35.811Z mqttjs:client streamErrorHandler :: error WebSocket was closed before the connection was established 2022-11-10T16:21:35.812Z mqttjs:client nop :: Error: WebSocket was closed before the connection was established at WebSocket.terminate (/usr/local/lib/node_modules/homebridge-eosstb/node_modules/ws/lib/websocket.js:433:14) at Duplex.duplex._destroy (/usr/local/lib/node_modules/homebridge-eosstb/node_modules/ws/lib/stream.js:123:32) at _destroy (node:internal/streams/destroy:109:10) at Duplex.destroy (node:internal/streams/destroy:71:5) at MqttClient._cleanUp (/usr/local/lib/node_modules/homebridge-eosstb/node_modules/mqtt/lib/client.js:1160:17) at Timeout._onTimeout (/usr/local/lib/node_modules/homebridge-eosstb/node_modules/mqtt/lib/client.js:518:10) at listOnTimeout (node:internal/timers:564:17) at processTimers (node:internal/timers:507:7) 2022-11-10T16:21:35.814Z mqttjs:client (ljg4yomi-ypkq-y5ad-twir-8lyt9qq32q0d)stream :: on close 2022-11-10T16:21:35.814Z mqttjs:client flushVolatile :: deleting volatile messages from the queue and setting their callbacks as error function 2022-11-10T16:21:35.814Z mqttjs:client stream: emit close to MqttClient 2022-11-10T16:21:35.814Z mqttjs:client close :: connected set to false 2022-11-10T16:21:35.814Z mqttjs:client close :: clearing connackTimer 2022-11-10T16:21:35.814Z mqttjs:client close :: clearing ping timer 2022-11-10T16:21:35.814Z mqttjs:client close :: calling _setupReconnect 2022-11-10T16:21:35.814Z mqttjs:client _setupReconnect :: doing nothing... 2022-11-10T16:21:36.811Z mqttjs:client reconnectTimer :: reconnect triggered!

2022-11-10T16:21:47.840Z mqttjs:client reconnectTimer :: reconnect triggered! 2022-11-10T16:21:47.841Z mqttjs:client _reconnect: emitting reconnect to client 2022-11-10T16:21:47.841Z mqttjs:client _reconnect: calling _setupStream 2022-11-10T16:21:47.841Z mqttjs:client _setupStream :: calling method to clear reconnect 2022-11-10T16:21:47.841Z mqttjs:client _clearReconnect : clearing reconnect timer 2022-11-10T16:21:47.842Z mqttjs:client _setupStream :: using streamBuilder provided to client to create stream 2022-11-10T16:21:47.842Z mqttjs calling streambuilder for wss 2022-11-10T16:21:47.842Z mqttjs:ws streamBuilder 2022-11-10T16:21:47.842Z mqttjs:ws createWebSocket 2022-11-10T16:21:47.842Z mqttjs:ws protocol: MQTT 4 2022-11-10T16:21:47.842Z mqttjs:ws creating new Websocket for url: wss://some.end.point:443/mqtt and protocol: mqtt 2022-11-10T16:21:47.862Z mqttjs:client _setupStream :: pipe stream to writable stream 2022-11-10T16:21:47.862Z mqttjs:client _setupStream: sending packet connect 2022-11-10T16:21:47.865Z mqttjs:client sendPacket :: packet: { cmd: 'connect' } 2022-11-10T16:21:47.865Z mqttjs:client sendPacket :: emitting packetsend 2022-11-10T16:21:47.865Z mqttjs:client sendPacket :: writing to stream 2022-11-10T16:21:47.867Z mqttjs:client sendPacket :: writeToStream result true

On Node 16.x, the behavior shows a successful connection:

2022-11-10T16:28:56.985Z mqttjs connecting to an MQTT broker... 2022-11-10T16:28:56.985Z mqttjs:client MqttClient :: options.protocol wss 2022-11-10T16:28:56.986Z mqttjs:client MqttClient :: options.protocolVersion 4 2022-11-10T16:28:56.986Z mqttjs:client MqttClient :: options.username myusername 2022-11-10T16:28:56.986Z mqttjs:client MqttClient :: options.keepalive 60 2022-11-10T16:28:56.986Z mqttjs:client MqttClient :: options.reconnectPeriod 1000 2022-11-10T16:28:56.986Z mqttjs:client MqttClient :: options.rejectUnauthorized undefined 2022-11-10T16:28:56.987Z mqttjs:client MqttClient :: options.topicAliasMaximum undefined 2022-11-10T16:28:56.987Z mqttjs:client MqttClient :: clientId lx6b4178-ckkz-5hlq-8p76-rxo06u7rg17o 2022-11-10T16:28:56.987Z mqttjs:client MqttClient :: setting up stream 2022-11-10T16:28:56.989Z mqttjs:client _setupStream :: calling method to clear reconnect 2022-11-10T16:28:56.989Z mqttjs:client _clearReconnect : clearing reconnect timer 2022-11-10T16:28:56.989Z mqttjs:client _setupStream :: using streamBuilder provided to client to create stream 2022-11-10T16:28:56.989Z mqttjs calling streambuilder for wss 2022-11-10T16:28:56.989Z mqttjs:ws streamBuilder 2022-11-10T16:28:56.990Z mqttjs:ws createWebSocket 2022-11-10T16:28:56.990Z mqttjs:ws protocol: MQTT 4 2022-11-10T16:28:56.990Z mqttjs:ws creating new Websocket for url: wss://myendpoint.com:443/mqtt and protocol: mqtt 2022-11-10T16:28:56.992Z mqttjs:client _setupStream :: pipe stream to writable stream 2022-11-10T16:28:56.992Z mqttjs:client _setupStream: sending packet connect 2022-11-10T16:28:56.994Z mqttjs:client sendPacket :: packet: { cmd: 'connect' } 2022-11-10T16:28:56.994Z mqttjs:client sendPacket :: emitting packetsend 2022-11-10T16:28:56.994Z mqttjs:client sendPacket :: writing to stream 2022-11-10T16:28:57.011Z mqttjs:client sendPacket :: writeToStream result true

The session continues and mqtt activity occurs without error:

2022-11-10T16:28:57.220Z mqttjs:client writable stream :: parsing buffer 2022-11-10T16:28:57.221Z mqttjs:client parser :: on packet push to packets array. 2022-11-10T16:28:57.221Z mqttjs:client work :: getting next packet in queue 2022-11-10T16:28:57.221Z mqttjs:client work :: packet pulled from queue 2022-11-10T16:28:57.221Z mqttjs:client _handlePacket :: emitting packetreceive 2022-11-10T16:28:57.221Z mqttjs:client _handleConnack 2022-11-10T16:28:57.221Z mqttjs:client _setupPingTimer :: keepalive 60 (seconds) 2022-11-10T16:28:57.223Z mqttjs:client connect :: sending queued packets 2022-11-10T16:28:57.224Z mqttjs:client deliver :: entry undefined 2022-11-10T16:28:57.224Z mqttjs:client _resubscribe

robertsLando commented 1 year ago

Try to reproduce the issue with MQTT v5 and feel free to reopen in case the bug persists