[bug] 'connect' event never triggered when lot of publish are done before connect

[robertsLando]

I'm expecting a strange behaviour when connecting to a broker using wss protocol, the client never emits the 'connect' event but packets are published anyway to the broker. The broker on it's side correctly authenticate the client and receives all client messages. I connect using

var options = {
clean: true,
rejectUnauthorized:true,
clientId: 'mqtt_01',
username: xxx,
password: xxx,
incomingStore: <nedb store>,
outgoingStore: <nedb store>,
will: "...",
reconnectPeriod: 3000
}
var client = mqtt.connect('wss://my.broker.url:443', options)

I'm using Aedes as broker

AB#8680452

[robertsLando]

@YoDaMa This only occurs when using store. In my case I'm using https://github.com/behrad/mqtt-nedb-store

[robertsLando]

By deleting the store folder everything seems working, I have no idea why it wasn't before.

[YoDaMa]

@robertsLando apologies for the delay. Sounds like it's not a bug, sort of? Can you give a bit more clarity for me.

Did you have to stop using store in order for things to work again? What's it mean to delete the store folder?

[robertsLando]

@YoDaMa Sincerly I have no idea, I have tried everything then I tried to remove the code that generates the store and it was working, so I removed the store folder (the folder where the incoming/outgoing db was stored) and put back the code and it was working, no error on the console, also I tried to enable mqtt debug and I wasn't able to find where it was stucked.

I think there is a bug somewhere but unfortunally I can't provide you more info about this, the strange thing is that is was publishing messages correctly, only the connect event wasn't fired

[robertsLando]

I reopen this as it's still happening to me. There is a really strange bug here and is not related to the protocol used or the persistent store used. What I have found is that sometimes the connect event never triggers and after some time I get this error:

1|gateway  | MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 close listeners added to [MqttClient]. Use emitter.setMaxListeners() to increase limit
1|gateway  |     at _addListener (events.js:390:17)
1|gateway  |     at MqttClient.addListener (events.js:406:10)
1|gateway  |     at MqttClient.once (events.js:437:8)
1|gateway  |     at startStreamProcess (/snapshot/app/node_modules/mqtt/lib/client.js:1496:10)
1|gateway  |     at Readable.<anonymous> (/snapshot/app/node_modules/mqtt/lib/client.js:1566:9)
1|gateway  |     at Readable.emit (events.js:315:20)
1|gateway  |     at endReadableNT (/snapshot/app/node_modules/mqtt/node_modules/readable-stream/lib/_stream_readable.js:1010:12)
1|gateway  |     at processTicksAndRejections (internal/process/task_queues.js:84:21)

I have no clue what's going on here but the strange thing is that even if connected event isn't triggered the client is anyway able to publish messages without any problem, but weird things happen in this situation. The connect event could be triggered after some minutes or never triggered at all

@YoDaMa @mcollina any ideas?

[Atrix1987]

@robertsLando check where you are adding the mqttClient.on listeners? The EventEmitter limit is not specific to Mqtt but specific to NodeJS. What we observed was, we were adding message listeners in on connect and when connect was fired multiple times this exception was logged

[robertsLando]

@Atrix1987 I have tried to debug this many times without success, I'm quite sure there is a bug somewhere, the listeners warning is just an alert, what's strange is that client is publishing without triggerig the "connect" event, when this happens it's the client that keeps adding "once" listeners on "close" event for some reason I don't know. In my previous comment I show when this happens

[robertsLando]

@YoDaMa Ping

[YoDaMa]

@robertsLando can you give me a way to repro what you're seeing using a local aedes server and mqtt.js code snippet? Seems like it could be a memory leak but without the logs I'm flying blind.

[robertsLando]

@YoDaMa Here are the logs:

mqttjs connecting to an MQTT broker... +0ms
  mqttjs:client MqttClient :: options.protocol mqtt +0ms
  mqttjs:client MqttClient :: options.protocolVersion 4 +1ms
  mqttjs:client MqttClient :: options.username clientName +9ms
  mqttjs:client MqttClient :: options.keepalive 60 +0ms
  mqttjs:client MqttClient :: options.reconnectPeriod 3000 +1ms
  mqttjs:client MqttClient :: options.rejectUnauthorized true +1ms
  mqttjs:client MqttClient :: clientId MQTT_GATEWAY-clientName03 +1ms
  mqttjs:client MqttClient :: setting up stream +1ms
  mqttjs:client _setupStream :: calling method to clear reconnect +3ms
  mqttjs:client _clearReconnect : clearing reconnect timer +0ms
  mqttjs:client _setupStream :: using streamBuilder provided to client to create stream +0ms
  mqttjs calling streambuilder for mqtt +56ms
  mqttjs:tcp port 1883 and host 10.9.1.33 +0ms
  mqttjs:client _setupStream :: pipe stream to writable stream +7ms
  mqttjs:client _setupStream: sending packet `connect` +3ms
  mqttjs:client sendPacket :: packet: { cmd: 'connect' } +2ms
  mqttjs:client sendPacket :: emitting `packetsend` +12ms
  mqttjs:client sendPacket :: writing to stream +1ms
  mqttjs:client sendPacket :: writeToStream result true +230ms
  mqttjs:client publish :: message `{"value":true,"time":1604389010271}` to topic `prefix/_CLIENTS/MQTT_GATEWAY-clientName03/$devices/cqs/status` +32ms
  mqttjs:client publish :: qos 1 +1ms
  mqttjs:client MqttClient:publish: packet cmd: publish +1ms
  mqttjs:client _sendPacket :: (MQTT_GATEWAY-clientName03) ::  start +0ms
  mqttjs:client _sendPacket :: client not connected. Storing packet offline. +0ms
  mqttjs:client _storePacket :: packet: { cmd: 'publish', topic: 'prefix/_CLIENTS/MQTT_GATEWAY-clientName03/$devices/cqs/status', payload: '{"value":true,"time":1604389010271}', qos: 1, retain: true, messageId: 53287, dup: false } +0ms

**** a tons of publish here like that that are stored in queue like this one ****

Then I get this:

 mqttjs:client writable stream :: parsing buffer +108ms
    mqttjs:client parser :: on packet push to packets array. +3ms
    mqttjs:client work :: getting next packet in queue +1ms
    mqttjs:client work :: packet pulled from queue +1ms
    mqttjs:client _handlePacket :: emitting packetreceive +0ms
    mqttjs:client _handleConnack +0ms
    mqttjs:client _setupPingTimer :: keepalive 60 (seconds) +1ms
    mqttjs:client _resubscribe +1ms

***** Starting from now mqtt client starts to empty publish queue and packets are sent but connect event isn't never received, also seems client isn't able to empty the offline queue and so the packets could have a delay of some minutes ***** 

    mqttjs:client _sendPacket :: (MQTT_GATEWAY-clientName03) ::  start +3ms
    mqttjs:client storeAndSend :: store packet with cmd publish to outgoingStore +1ms
    mqttjs:client nop :: undefined +1ms
    mqttjs:client sendPacket :: packet: {
   mqttjs:client   cmd: 'publish',
    mqttjs:client   topic: 'prefix/_CLIENTS/MQTT_GATEWAY-clientName03/$devices/cqs/status',
    mqttjs:client   payload: '{"value":true,"time":1604389010271}',
    mqttjs:client   qos: 1,
    mqttjs:client   retain: true,
    mqttjs:client   messageId: 53287,
    mqttjs:client   dup: false
    mqttjs:client } +0ms
    mqttjs:client sendPacket :: emitting `packetsend` +1ms
    mqttjs:client sendPacket :: writing to stream +1ms
    mqttjs:client sendPacket :: writeToStream result true +0ms
    mqttjs:client _sendPacket :: (MQTT_GATEWAY-clientName03) ::  end +1ms
   mqttjs:client publish :: message `{"value":0,"time":"2020-11-03T07:36:50.617Z"}` to topic `prefix/clientName/cqstest/enable/edits/command` +6ms
    mqttjs:client publish :: qos 1 +1ms
    mqttjs:client _storeProcessing enabled +0ms
    mqttjs:client _storePacket :: packet: { cmd: 'publish', topic: 'prefix/clientName/cqstest/enable/edits/command', payload: '{"value":0,"time":"2020-11-03T07:36:50.617Z"}', qos: 1, retain: true, messageId: 53302, dup: false } +0ms
    mqttjs:client _storePacket :: cb? false +1ms
    mqttjs:client nop :: undefined +0ms
    mqttjs:client publish :: message `{"value":1,"time":"2020-11-03T07:36:50.619Z"}` to topic `prefix/clientName/cqstest/config/unitid` +1ms

Also note that connected is true at this point, but the event is still never sent and that error maxeventlisteners is triggered after some time periodically

[robertsLando]

@YoDaMa News on this?

[YoDaMa]

@robertsLando not yet there has been an election and that has been involving my whole brain

[robertsLando]

@YoDaMa no worries, LMK :)