Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[Bug]: Error: Keepalive timeout, js engine: hermes - React Native #1853

Closed
abdelhameedhamdy opened this issue Apr 27, 2024 · 28 comments
Closed
Labels

Comments

@abdelhameedhamdy
Copy link
Contributor

abdelhameedhamdy commented Apr 27, 2024

MQTTjs Version

5.5.3

Broker

flespi

Environment

NodeJS

Description

In React Native (Expo) , after some random time (few minutes), the following error appears
Error: Keepalive timeout, js engine: hermes
image

mqttOptions params :

{
keepalive: 60 * 5,
  reschedulePings: true,
  protocolId: "MQTT",
  protocolVersion: 5,
  reconnectPeriod: 1000,
  connectTimeout: 30 * 1000,
  clean: false,
  properties: {
    sessionExpiryInterval: 3600 * 24 * 7,
  },
  timerVariant: "native"
}

Minimal Reproduction

Connecting to Flespi broker sample:
https://flespi.com/mqtt-broker#client

const mqttOptions = {
  username:
    "FlespiToken xxxx,
  port: 443,
  keepalive: 60 * 5,
  reschedulePings: true,
  protocolId: "MQTT",
  protocolVersion: 5,
  reconnectPeriod: 1000,
  connectTimeout: 30 * 1000,
  clean: false,
  clientId: 'testClient',
  properties: {
    sessionExpiryInterval: 3600 * 24 * 7,
  },
  timerVariant: "native",
}

const client = connect("mqtts://mqtt.flespi.io", mqttOptions);

Debug logs

ERROR Error: Keepalive timeout, js engine: hermes

@robertsLando
Copy link
Member

robertsLando commented Apr 29, 2024

@abdelhameedhamdy I need debug logs, seems that happens because the broker doesn't respond to a ping in the keepliave timeout you specified on settings (5 minutes). Try to use a lower keepalive like 10 seconds and enable logs and attach them here

@abdelhameedhamdy
Copy link
Contributor Author

@abdelhameedhamdy I need debug logs, seems that happens because the broker doesn't respond to a ping in the keepliave timeout you specified on settings (5 minutes). Try to use a lower keepalive like 10 seconds and enable logs and attach them here

keepalive set to 10 sec, and logs as following :

 DEBUG  mqtt-packet:parser _parsePayload: payload '{"_bufs": [[Object]], "_events": {}, "_eventsCount": 0, "_maxListeners": undefined, "_readableState": {"awaitDrainWriters": null, "buffer": {"head": null, "length": 0, "tail": null}, "decoder": null, "defaultEncoding": "utf8", "encoding": null, "errored": null, "flowing": null, "highWaterMark": 16384, "length": 0, "pipes": [], "state": 6192, Symbol(kPaused): null}, "_writableState": {"afterWriteTickInfo": null, "allBuffers": true, "allNoop": true, "autoDestroy": true, "bufferProcessing": false, "buffered": [], "bufferedIndex": 0, "closeEmitted": false, "closed": false, "constructed": true, "corked": 0, "decodeStrings": true, "defaultEncoding": "utf8", "destroyed": false, "emitClose": true, "ended": false, "ending": false, "errorEmitted": false, "errored": null, "finalCalled": false, "finished": false, "highWaterMark": 16384, "length": 0, "needDrain": false, "objectMode": false, "onwrite": [Function bound onwrite], "pendingcb": 0, "prefinished": false, "sync": true, "writecb": null, "writelen": 0, "writing": false, Symbol(kOnFinished): []}, "allowHalfOpen": true, "length": 5}' +1ms
 DEBUG  mqtt-packet:parser _parseSuback +1ms
 DEBUG  mqtt-packet:parser _parseNum: result: 18333 +0ms
 DEBUG  mqtt-packet:parser _parseMessageId: packet.messageId 18333 +0ms
 DEBUG  mqtt-packet:parser _parseProperties +0ms
 DEBUG  mqtt-packet:parser _parseVarByteNum +0ms
 DEBUG  mqtt-packet:parser _parseVarByteNum: result: '0' +0ms
 DEBUG  mqtt-packet:parser _parsePayload complete result: true +0ms
 DEBUG  mqtt-packet:parser parse: state complete. _stateCounter is now: 3 +0ms
 DEBUG  mqtt-packet:parser parse: packet.length: 5, buffer list length: 5 +0ms
 DEBUG  mqtt-packet:parser _newPacket +0ms
 DEBUG  mqtt-packet:parser _newPacket: parser emit packet: packet.cmd: suback, packet.payload: null, packet.length: 5 +0ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +4ms
 DEBUG  mqtt-packet:parser _newPacket: new packet +1ms
 DEBUG  mqtt-packet:parser parse: state complete. _stateCounter is now: 4 +0ms
 DEBUG  mqtt-packet:parser parse: packet.length: -1, buffer list length: 0 +0ms
 DEBUG  mqtt-packet:parser parse: exited while loop. packet: -1, buffer list length: 0 +0ms
 DEBUG  mqttjs:client work :: getting next packet in queue +0ms
 DEBUG  mqttjs:client work :: packet pulled from queue +0ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +0ms
 DEBUG  mqttjs:client _handleAck :: packet type +0ms suback
 DEBUG  mqttjs:client noop :: +0ms null
 DEBUG  mqttjs:client _checkPing :: checking ping... +10s
 DEBUG  mqttjs:client _checkPing :: ping response received. Clearing flag and sending `pingreq` +2ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +0ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +0ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +1ms
 DEBUG  mqttjs:client _writePacket :: writing to stream +0ms
 DEBUG  mqtt-packet:writeToStream generate called +9s
 DEBUG  mqtt-packet:writeToStream generate: packet.cmd: pingreq +0ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result false +6ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +1ms
 DEBUG  mqttjs:client noop :: +1ms undefined
 DEBUG  mqttjs:client _checkPing :: checking ping... +10s
 DEBUG  mqttjs:client _checkPing :: ping response received. Clearing flag and sending `pingreq` +2ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +0ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +1ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +4ms
 LOG  packet {"cmd": "pingreq"}
 DEBUG  mqttjs:client _writePacket :: writing to stream +2ms
 DEBUG  mqtt-packet:writeToStream generate called +2s
 DEBUG  mqtt-packet:writeToStream generate: packet.cmd: pingreq +1ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +4ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +1ms
 DEBUG  mqttjs:client noop :: +1ms undefined
 DEBUG  mqttjs:client writable stream :: parsing buffer +123ms
 DEBUG  mqtt-packet:parser parse: current state: _parseHeader +10s
 DEBUG  mqtt-packet:parser _parseHeader: packet: '{"cmd": "pingresp", "dup": false, "length": -1, "payload": null, "qos": 0, "retain": false, "topic": null}' +1ms
 DEBUG  mqtt-packet:parser parse: state complete. _stateCounter is now: 1 +3ms
 DEBUG  mqtt-packet:parser parse: packet.length: -1, buffer list length: 1 +3ms
 DEBUG  mqtt-packet:parser _parseVarByteNum +1ms
 DEBUG  mqtt-packet:parser _parseVarByteNum: result: '{"bytes": 1, "value": 0}' +1ms
 DEBUG  mqtt-packet:parser _parseLength 0 +3ms
 DEBUG  mqtt-packet:parser parse: state complete. _stateCounter is now: 2 +1ms
 DEBUG  mqtt-packet:parser parse: packet.length: 0, buffer list length: 0 +1ms
 DEBUG  mqtt-packet:parser _parsePayload: payload '{"_bufs": [], "_events": {}, "_eventsCount": 0, "_maxListeners": undefined, "_readableState": {"awaitDrainWriters": null, "buffer": {"head": null, "length": 0, "tail": null}, "decoder": null, "defaultEncoding": "utf8", "encoding": null, "errored": null, "flowing": null, "highWaterMark": 16384, "length": 0, "pipes": [], "state": 6192, Symbol(kPaused): null}, "_writableState": {"afterWriteTickInfo": null, "allBuffers": true, "allNoop": true, "autoDestroy": true, "bufferProcessing": false, "buffered": [], "bufferedIndex": 0, "closeEmitted": false, "closed": false, "constructed": true, "corked": 0, "decodeStrings": true, "defaultEncoding": "utf8", "destroyed": false, "emitClose": true, "ended": false, "ending": false, "errorEmitted": false, "errored": null, "finalCalled": false, "finished": false, "highWaterMark": 16384, "length": 0, "needDrain": false, "objectMode": false, "onwrite": [Function bound onwrite], "pendingcb": 0, "prefinished": false, "sync": true, "writecb": null, "writelen": 0, "writing": false, Symbol(kOnFinished): []}, "allowHalfOpen": true, "length": 0}' +3ms
 DEBUG  mqtt-packet:parser _parsePayload complete result: true +13ms
 DEBUG  mqtt-packet:parser parse: state complete. _stateCounter is now: 3 +1ms
 DEBUG  mqtt-packet:parser parse: packet.length: 0, buffer list length: 0 +1ms
 DEBUG  mqtt-packet:parser _newPacket +1ms
 DEBUG  mqtt-packet:parser _newPacket: parser emit packet: packet.cmd: pingresp, packet.payload: null, packet.length: 0 +0ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +35ms
 DEBUG  mqtt-packet:parser _newPacket: new packet +1ms
 DEBUG  mqtt-packet:parser parse: state complete. _stateCounter is now: 4 +0ms
 DEBUG  mqtt-packet:parser parse: packet.length: -1, buffer list length: 0 +2ms
 DEBUG  mqtt-packet:parser parse: exited while loop. packet: -1, buffer list length: 0 +1ms
 DEBUG  mqttjs:client work :: getting next packet in queue +4ms
 DEBUG  mqttjs:client work :: packet pulled from queue +0ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +1ms
 DEBUG  mqttjs:client _checkPing :: checking ping... +10s
 ERROR  Error: Keepalive timeout, js engine: hermes
 DEBUG  mqttjs:client _checkPing :: checking ping... +10s
 DEBUG  mqttjs:client _checkPing :: ping response received. Clearing flag and sending `pingreq` +2ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +1ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +1ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +5ms
 LOG  packet {"cmd": "pingreq"}
 DEBUG  mqttjs:client _writePacket :: writing to stream +3ms
 DEBUG  mqtt-packet:writeToStream generate called +10s
 DEBUG  mqtt-packet:writeToStream generate: packet.cmd: pingreq +1ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +3ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +4ms
 DEBUG  mqttjs:client noop :: +0ms undefined
 DEBUG  mqttjs:client writable stream :: parsing buffer +116ms
 DEBUG  mqtt-packet:parser parse: current state: _parseHeader +10s
 DEBUG  mqtt-packet:parser _parseHeader: packet: '{"cmd": "pingresp", "dup": false, "length": -1, "payload": null, "qos": 0, "retain": false, "topic": null}' +1ms
 DEBUG  mqtt-packet:parser parse: state complete. _stateCounter is now: 1 +3ms
 DEBUG  mqtt-packet:parser parse: packet.length: -1, buffer list length: 1 +3ms
 DEBUG  mqtt-packet:parser _parseVarByteNum +0ms
 DEBUG  mqtt-packet:parser _parseVarByteNum: result: '{"bytes": 1, "value": 0}' +1ms
 DEBUG  mqtt-packet:parser _parseLength 0 +3ms
 DEBUG  mqtt-packet:parser parse: state complete. _stateCounter is now: 2 +1ms
 DEBUG  mqtt-packet:parser parse: packet.length: 0, buffer list length: 0 +1ms
 DEBUG  mqtt-packet:parser _parsePayload: payload '{"_bufs": [], "_events": {}, "_eventsCount": 0, "_maxListeners": undefined, "_readableState": {"awaitDrainWriters": null, "buffer": {"head": null, "length": 0, "tail": null}, "decoder": null, "defaultEncoding": "utf8", "encoding": null, "errored": null, "flowing": null, "highWaterMark": 16384, "length": 0, "pipes": [], "state": 6192, Symbol(kPaused): null}, "_writableState": {"afterWriteTickInfo": null, "allBuffers": true, "allNoop": true, "autoDestroy": true, "bufferProcessing": false, "buffered": [], "bufferedIndex": 0, "closeEmitted": false, "closed": false, "constructed": true, "corked": 0, "decodeStrings": true, "defaultEncoding": "utf8", "destroyed": false, "emitClose": true, "ended": false, "ending": false, "errorEmitted": false, "errored": null, "finalCalled": false, "finished": false, "highWaterMark": 16384, "length": 0, "needDrain": false, "objectMode": false, "onwrite": [Function bound onwrite], "pendingcb": 0, "prefinished": false, "sync": true, "writecb": null, "writelen": 0, "writing": false, Symbol(kOnFinished): []}, "allowHalfOpen": true, "length": 0}' +0ms
 DEBUG  mqtt-packet:parser _parsePayload complete result: true +9ms
 DEBUG  mqtt-packet:parser parse: state complete. _stateCounter is now: 3 +1ms
 DEBUG  mqtt-packet:parser parse: packet.length: 0, buffer list length: 0 +1ms
 DEBUG  mqtt-packet:parser _newPacket +0ms
 DEBUG  mqtt-packet:parser _newPacket: parser emit packet: packet.cmd: pingresp, packet.payload: null, packet.length: 0 +1ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +26ms
 DEBUG  mqtt-packet:parser _newPacket: new packet +1ms
 DEBUG  mqtt-packet:parser parse: state complete. _stateCounter is now: 4 +0ms
 DEBUG  mqtt-packet:parser parse: packet.length: -1, buffer list length: 0 +0ms
 DEBUG  mqtt-packet:parser parse: exited while loop. packet: -1, buffer list length: 0 +1ms
 DEBUG  mqttjs:client work :: getting next packet in queue +2ms
 DEBUG  mqttjs:client work :: packet pulled from queue +0ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +2ms
 DEBUG  mqttjs:client _checkPing :: checking ping... +10s
 DEBUG  mqttjs:client _checkPing :: ping response received. Clearing flag and sending `pingreq` +1ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +1ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +0ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +2ms
 LOG  packet {"cmd": "pingreq"}
 DEBUG  mqttjs:client _writePacket :: writing to stream +7ms
 DEBUG  mqtt-packet:writeToStream generate called +10s
 DEBUG  mqtt-packet:writeToStream generate: packet.cmd: pingreq +0ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +2ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +1ms
 DEBUG  mqttjs:client noop :: +0ms undefined
 DEBUG  mqttjs:client writable stream :: parsing buffer +101ms
 DEBUG  mqtt-packet:parser parse: current state: _parseHeader +10s
 DEBUG  mqtt-packet:parser _parseHeader: packet: '{"cmd": "pingresp", "dup": false, "length": -1, "payload": null, "qos": 0, "retain": false, "topic": null}' +0ms
 DEBUG  mqtt-packet:parser parse: state complete. _stateCounter is now: 1 +1ms
 DEBUG  mqtt-packet:parser parse: packet.length: -1, buffer list length: 1 +8ms
 DEBUG  mqtt-packet:parser _parseVarByteNum +1ms
 DEBUG  mqtt-packet:parser _parseVarByteNum: result: '{"bytes": 1, "value": 0}' +0ms
 DEBUG  mqtt-packet:parser _parseLength 0 +0ms
 DEBUG  mqtt-packet:parser parse: state complete. _stateCounter is now: 2 +0ms
 DEBUG  mqtt-packet:parser parse: packet.length: 0, buffer list length: 0 +1ms
 DEBUG  mqtt-packet:parser _parsePayload: payload '{"_bufs": [], "_events": {}, "_eventsCount": 0, "_maxListeners": undefined, "_readableState": {"awaitDrainWriters": null, "buffer": {"head": null, "length": 0, "tail": null}, "decoder": null, "defaultEncoding": "utf8", "encoding": null, "errored": null, "flowing": null, "highWaterMark": 16384, "length": 0, "pipes": [], "state": 6192, Symbol(kPaused): null}, "_writableState": {"afterWriteTickInfo": null, "allBuffers": true, "allNoop": true, "autoDestroy": true, "bufferProcessing": false, "buffered": [], "bufferedIndex": 0, "closeEmitted": false, "closed": false, "constructed": true, "corked": 0, "decodeStrings": true, "defaultEncoding": "utf8", "destroyed": false, "emitClose": true, "ended": false, "ending": false, "errorEmitted": false, "errored": null, "finalCalled": false, "finished": false, "highWaterMark": 16384, "length": 0, "needDrain": false, "objectMode": false, "onwrite": [Function bound onwrite], "pendingcb": 0, "prefinished": false, "sync": true, "writecb": null, "writelen": 0, "writing": false, Symbol(kOnFinished): []}, "allowHalfOpen": true, "length": 0}' +0ms
 DEBUG  mqtt-packet:parser _parsePayload complete result: true +2ms
 DEBUG  mqtt-packet:parser parse: state complete. _stateCounter is now: 3 +0ms
 DEBUG  mqtt-packet:parser parse: packet.length: 0, buffer list length: 0 +0ms
 DEBUG  mqtt-packet:parser _newPacket +0ms
 DEBUG  mqtt-packet:parser _newPacket: parser emit packet: packet.cmd: pingresp, packet.payload: null, packet.length: 0 +0ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +14ms
 DEBUG  mqtt-packet:parser _newPacket: new packet +2ms
 DEBUG  mqtt-packet:parser parse: state complete. _stateCounter is now: 4 +0ms
 DEBUG  mqtt-packet:parser parse: packet.length: -1, buffer list length: 0 +0ms
 DEBUG  mqtt-packet:parser parse: exited while loop. packet: -1, buffer list length: 0 +0ms
 DEBUG  mqttjs:client work :: getting next packet in queue +2ms
 DEBUG  mqttjs:client work :: packet pulled from queue +0ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +1ms
 DEBUG  mqttjs:client _checkPing :: checking ping... +10s
 DEBUG  mqttjs:client _checkPing :: ping response received. Clearing flag and sending `pingreq` +1ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +1ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +1ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +1ms
 LOG  packet {"cmd": "pingreq"}
 DEBUG  mqttjs:client _writePacket :: writing to stream +3ms
 DEBUG  mqtt-packet:writeToStream generate called +10s
 DEBUG  mqtt-packet:writeToStream generate: packet.cmd: pingreq +0ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +1ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +0ms
 DEBUG  mqttjs:client noop :: +1ms undefined
 DEBUG  mqttjs:client writable stream :: parsing buffer +102ms
 DEBUG  mqtt-packet:parser parse: current state: _parseHeader +10s
 DEBUG  mqtt-packet:parser _parseHeader: packet: '{"cmd": "pingresp", "dup": false, "length": -1, "payload": null, "qos": 0, "retain": false, "topic": null}' +2ms
 DEBUG  mqtt-packet:parser parse: state complete. _stateCounter is now: 1 +3ms
 DEBUG  mqtt-packet:parser parse: packet.length: -1, buffer list length: 1 +0ms
 DEBUG  mqtt-packet:parser _parseVarByteNum +1ms
 DEBUG  mqtt-packet:parser _parseVarByteNum: result: '{"bytes": 1, "value": 0}' +0ms
 DEBUG  mqtt-packet:parser _parseLength 0 +2ms
 DEBUG  mqtt-packet:parser parse: state complete. _stateCounter is now: 2 +1ms
 DEBUG  mqtt-packet:parser parse: packet.length: 0, buffer list length: 0 +1ms
 DEBUG  mqtt-packet:parser _parsePayload: payload '{"_bufs": [], "_events": {}, "_eventsCount": 0, "_maxListeners": undefined, "_readableState": {"awaitDrainWriters": null, "buffer": {"head": null, "length": 0, "tail": null}, "decoder": null, "defaultEncoding": "utf8", "encoding": null, "errored": null, "flowing": null, "highWaterMark": 16384, "length": 0, "pipes": [], "state": 6192, Symbol(kPaused): null}, "_writableState": {"afterWriteTickInfo": null, "allBuffers": true, "allNoop": true, "autoDestroy": true, "bufferProcessing": false, "buffered": [], "bufferedIndex": 0, "closeEmitted": false, "closed": false, "constructed": true, "corked": 0, "decodeStrings": true, "defaultEncoding": "utf8", "destroyed": false, "emitClose": true, "ended": false, "ending": false, "errorEmitted": false, "errored": null, "finalCalled": false, "finished": false, "highWaterMark": 16384, "length": 0, "needDrain": false, "objectMode": false, "onwrite": [Function bound onwrite], "pendingcb": 0, "prefinished": false, "sync": true, "writecb": null, "writelen": 0, "writing": false, Symbol(kOnFinished): []}, "allowHalfOpen": true, "length": 0}' +0ms
 DEBUG  mqtt-packet:parser _parsePayload complete result: true +5ms
 DEBUG  mqtt-packet:parser parse: state complete. _stateCounter is now: 3 +1ms
 DEBUG  mqtt-packet:parser parse: packet.length: 0, buffer list length: 0 +1ms
 DEBUG  mqtt-packet:parser _newPacket +0ms
 DEBUG  mqtt-packet:parser _newPacket: parser emit packet: packet.cmd: pingresp, packet.payload: null, packet.length: 0 +0ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +19ms
 DEBUG  mqtt-packet:parser _newPacket: new packet +1ms
 DEBUG  mqtt-packet:parser parse: state complete. _stateCounter is now: 4 +0ms
 DEBUG  mqtt-packet:parser parse: packet.length: -1, buffer list length: 0 +1ms
 DEBUG  mqtt-packet:parser parse: exited while loop. packet: -1, buffer list length: 0 +0ms
 DEBUG  mqttjs:client work :: getting next packet in queue +2ms
 DEBUG  mqttjs:client work :: packet pulled from queue +0ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +0ms
 ERROR  Error: Keepalive timeout, js engine: hermes

appeared in the log

@robertsLando
Copy link
Member

robertsLando commented Apr 29, 2024

@abdelhameedhamdy Could yuou also try using 5.3.4? Is your log truncated? I don't see the cleanup part after the keepalive timeout error

@abdelhameedhamdy
Copy link
Contributor Author

abdelhameedhamdy commented Apr 29, 2024

@abdelhameedhamdy Could yuou also try using 5.3.4? Is your log truncated? I don't see the cleanup part after the keepalive timeout error

Here it's
image

Just extracted a sample of repeated pattern.

If switching to 5.3.4, RN App won't run, as it needs the last fixes like buffer packages and other url blob issues appears in 5.3.4, in addition to timerVariant: "native" is not available in it.

@robertsLando
Copy link
Member

Sorry I meant 5.5.4

@robertsLando
Copy link
Member

robertsLando commented Apr 29, 2024

Your logs makes no sense to me as that error is emitted right before closing the client and I see no mention to the cleanUp

MQTT.js/src/lib/client.ts

Lines 2128 to 2130 in 6f3109a

this.emit('error', new Error('Keepalive timeout'))
this.log('_checkPing :: calling _cleanUp with force true')
this._cleanUp(true)

@abdelhameedhamdy
Copy link
Contributor Author

Sorry I meant 5.5.4

Already on last release 5.5.4, and the log was based on it as well.

@robertsLando
Copy link
Member

@abdelhameedhamdy Do you have an client.on('error' listener?

@abdelhameedhamdy
Copy link
Contributor Author

@abdelhameedhamdy Do you have an client.on('error' listener?

Yes, I have one, and this error is not caught in it when it comes, I was trying to handle it.

@abdelhameedhamdy
Copy link
Contributor Author

Your logs makes no sense to me as that error is emitted right before closing the client and I see no mention to the cleanUp

MQTT.js/src/lib/client.ts

Lines 2128 to 2130 in 6f3109a

this.emit('error', new Error('Keepalive timeout'))
this.log('_checkPing :: calling _cleanUp with force true')
this._cleanUp(true)

Another log sample screenshot from terminal
image

@abdelhameedhamdy
Copy link
Contributor Author

And this another log with keepalive set to 5 min

DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +1ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "puback", "messageId": 1, "reasonCode": 0}' +1ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +0ms
 LOG  packet {"cmd": "puback", "messageId": 1, "reasonCode": 0}
 DEBUG  mqttjs:client _writePacket :: writing to stream +0ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +0ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +0ms
 DEBUG  mqttjs:client writable stream :: parsing buffer +1ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +1ms
 DEBUG  mqttjs:client work :: getting next packet in queue +0ms
 DEBUG  mqttjs:client work :: packet pulled from queue +0ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +0ms
 DEBUG  mqttjs:client _handleAck :: packet type +0ms suback
 DEBUG  mqttjs:client noop :: +0ms null
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +3m
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +1ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +1ms
 LOG  packet {"cmd": "pingreq"}
 DEBUG  mqttjs:client _writePacket :: writing to stream +1ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +0ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +0ms
 DEBUG  mqttjs:client noop :: +1ms undefined
 DEBUG  mqttjs:client writable stream :: parsing buffer +127ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +2ms
 DEBUG  mqttjs:client work :: getting next packet in queue +1ms
 DEBUG  mqttjs:client work :: packet pulled from queue +0ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +2ms
 DEBUG  mqttjs:client _checkPing :: checking ping... +5m
 DEBUG  mqttjs:client _checkPing :: ping response received. Clearing flag and sending `pingreq` +2ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +2ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +1ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +2ms
 DEBUG  mqttjs:client _writePacket :: writing to stream +1ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result false +4ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +1ms
 DEBUG  mqttjs:client noop :: +1ms undefined
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +3m
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +2ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +2ms
 LOG  packet {"cmd": "pingreq"}
 DEBUG  mqttjs:client _writePacket :: writing to stream +3ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +1ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +0ms
 DEBUG  mqttjs:client noop :: +0ms undefined
 DEBUG  mqttjs:client writable stream :: parsing buffer +101ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +1ms
 DEBUG  mqttjs:client work :: getting next packet in queue +1ms
 DEBUG  mqttjs:client work :: packet pulled from queue +0ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +1ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +3m
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +2ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +1ms
 LOG  packet {"cmd": "pingreq"}
 DEBUG  mqttjs:client _writePacket :: writing to stream +5ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +1ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +2ms
 DEBUG  mqttjs:client noop :: +1ms undefined
 DEBUG  mqttjs:client writable stream :: parsing buffer +107ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +2ms
 DEBUG  mqttjs:client work :: getting next packet in queue +0ms
 DEBUG  mqttjs:client work :: packet pulled from queue +1ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +1ms
 DEBUG  mqttjs:client _checkPing :: checking ping... +5m
 ERROR  Error: Keepalive timeout, js engine: hermes
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +3m
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +1ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +1ms
 LOG  packet {"cmd": "pingreq"}
 DEBUG  mqttjs:client _writePacket :: writing to stream +1ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +0ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +1ms
 DEBUG  mqttjs:client noop :: +0ms undefined
 DEBUG  mqttjs:client writable stream :: parsing buffer +110ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +1ms
 DEBUG  mqttjs:client work :: getting next packet in queue +0ms
 DEBUG  mqttjs:client work :: packet pulled from queue +1ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +0ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +3m
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +1ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +3ms
 LOG  packet {"cmd": "pingreq"}
 DEBUG  mqttjs:client _writePacket :: writing to stream +4ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +1ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +2ms
 DEBUG  mqttjs:client noop :: +0ms undefined
 DEBUG  mqttjs:client writable stream :: parsing buffer +108ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +1ms
 DEBUG  mqttjs:client work :: getting next packet in queue +1ms
 DEBUG  mqttjs:client work :: packet pulled from queue +2ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +1ms

with the ERROR Error: Keepalive timeout, js engine: hermes message.

@robertsLando
Copy link
Member

Try with the coming version 5.5.5

@abdelhameedhamdy
Copy link
Contributor Author

abdelhameedhamdy commented Apr 30, 2024

Try with the coming version 5.5.5

Tested with 5.5.5, and same error appears, logs

 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +2ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "puback", "messageId": 1, "reasonCode": 0}' +1ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +0ms
 LOG  packet {"cmd": "puback", "messageId": 1, "reasonCode": 0}
 DEBUG  mqttjs:client _writePacket :: writing to stream +0ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +0ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +0ms
 DEBUG  mqttjs:client _checkPing :: checking ping... +10s
 DEBUG  mqttjs:client _checkPing :: ping response received in time +1ms
 DEBUG  mqttjs:client _sendPing :: sending pingreq +0ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +1ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +0ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +1ms
 DEBUG  mqttjs:client _writePacket :: writing to stream +0ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result false +3ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +1ms
 DEBUG  mqttjs:client noop :: +0ms undefined
 DEBUG  mqttjs:client _checkPing :: checking ping... +10s
 DEBUG  mqttjs:client _checkPing :: ping response received in time +1ms
 DEBUG  mqttjs:client _sendPing :: sending pingreq +1ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +1ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +1ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +3ms
 LOG  packet {"cmd": "pingreq"}
 DEBUG  mqttjs:client _writePacket :: writing to stream +1ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +1ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +0ms
 DEBUG  mqttjs:client noop :: +2ms undefined
 DEBUG  mqttjs:client writable stream :: parsing buffer +623ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +2ms
 DEBUG  mqttjs:client work :: getting next packet in queue +1ms
 DEBUG  mqttjs:client work :: packet pulled from queue +0ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +3ms
 DEBUG  mqttjs:client _checkPing :: checking ping... +10s
 ERROR  Error: Keepalive timeout, js engine: hermes
 DEBUG  mqttjs:client _checkPing :: checking ping... +9s
 DEBUG  mqttjs:client _checkPing :: ping response received in time +1ms
 DEBUG  mqttjs:client _sendPing :: sending pingreq +0ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +1ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +0ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +1ms
 LOG  packet {"cmd": "pingreq"}
 DEBUG  mqttjs:client _writePacket :: writing to stream +1ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +0ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +0ms
 DEBUG  mqttjs:client noop :: +1ms undefined
 DEBUG  mqttjs:client writable stream :: parsing buffer +140ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +2ms
 DEBUG  mqttjs:client work :: getting next packet in queue +1ms
 DEBUG  mqttjs:client work :: packet pulled from queue +0ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +2ms
 DEBUG  mqttjs:client _checkPing :: checking ping... +10s
 DEBUG  mqttjs:client _checkPing :: ping response received in time +1ms
 DEBUG  mqttjs:client _sendPing :: sending pingreq +0ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +1ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +0ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +1ms
 LOG  packet {"cmd": "pingreq"}
 DEBUG  mqttjs:client _writePacket :: writing to stream +3ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +0ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +0ms
 DEBUG  mqttjs:client noop :: +1ms undefined
 DEBUG  mqttjs:client writable stream :: parsing buffer +115ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +1ms
 DEBUG  mqttjs:client work :: getting next packet in queue +1ms
 DEBUG  mqttjs:client work :: packet pulled from queue +1ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +0ms
 DEBUG  mqttjs:client _checkPing :: checking ping... +10s
 DEBUG  mqttjs:client _checkPing :: ping response received in time +1ms
 DEBUG  mqttjs:client _sendPing :: sending pingreq +1ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +1ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +1ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +1ms
 LOG  packet {"cmd": "pingreq"}
 DEBUG  mqttjs:client _writePacket :: writing to stream +3ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +0ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +1ms
 DEBUG  mqttjs:client noop :: +1ms undefined
 DEBUG  mqttjs:client writable stream :: parsing buffer +118ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +1ms
 DEBUG  mqttjs:client work :: getting next packet in queue +1ms
 DEBUG  mqttjs:client work :: packet pulled from queue +0ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +1ms
 DEBUG  mqttjs:client _checkPing :: checking ping... +10s
 DEBUG  mqttjs:client _checkPing :: ping response received in time +1ms
 DEBUG  mqttjs:client _sendPing :: sending pingreq +1ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +1ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +1ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +4ms
 LOG  packet {"cmd": "pingreq"}
 DEBUG  mqttjs:client _writePacket :: writing to stream +1ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +0ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +1ms
 DEBUG  mqttjs:client noop :: +3ms undefined
 DEBUG  mqttjs:client writable stream :: parsing buffer +99ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +1ms
 DEBUG  mqttjs:client work :: getting next packet in queue +1ms
 DEBUG  mqttjs:client work :: packet pulled from queue +1ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +0ms
 DEBUG  mqttjs:client _checkPing :: checking ping... +10s
 DEBUG  mqttjs:client _checkPing :: ping response received in time +2ms
 DEBUG  mqttjs:client _sendPing :: sending pingreq +0ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +1ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +1ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +3ms
 LOG  packet {"cmd": "pingreq"}
 DEBUG  mqttjs:client _writePacket :: writing to stream +2ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +0ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +1ms
 DEBUG  mqttjs:client noop :: +2ms undefined
 DEBUG  mqttjs:client writable stream :: parsing buffer +107ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +2ms
 DEBUG  mqttjs:client work :: getting next packet in queue +0ms
 DEBUG  mqttjs:client work :: packet pulled from queue +1ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +1ms
 DEBUG  mqttjs:client _checkPing :: checking ping... +10s
 DEBUG  mqttjs:client _checkPing :: ping response received in time +2ms
 DEBUG  mqttjs:client _sendPing :: sending pingreq +1ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +0ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +2ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +2ms
 LOG  packet {"cmd": "pingreq"}
 DEBUG  mqttjs:client _writePacket :: writing to stream +1ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +1ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +0ms
 DEBUG  mqttjs:client noop :: +1ms undefined
 DEBUG  mqttjs:client writable stream :: parsing buffer +107ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +1ms
 DEBUG  mqttjs:client work :: getting next packet in queue +1ms
 DEBUG  mqttjs:client work :: packet pulled from queue +0ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +1ms
 DEBUG  mqttjs:client _checkPing :: checking ping... +10s
 DEBUG  mqttjs:client _checkPing :: ping response received in time +2ms
 DEBUG  mqttjs:client _sendPing :: sending pingreq +1ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +1ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +1ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +3ms
 LOG  packet {"cmd": "pingreq"}
 DEBUG  mqttjs:client _writePacket :: writing to stream +1ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +1ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +0ms
 DEBUG  mqttjs:client noop :: +1ms undefined
 DEBUG  mqttjs:client writable stream :: parsing buffer +102ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +1ms
 DEBUG  mqttjs:client work :: getting next packet in queue +0ms
 DEBUG  mqttjs:client work :: packet pulled from queue +1ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +0ms
 DEBUG  mqttjs:client _checkPing :: checking ping... +10s
 DEBUG  mqttjs:client _checkPing :: ping response received in time +2ms
 DEBUG  mqttjs:client _sendPing :: sending pingreq +0ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +1ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +1ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +3ms
 LOG  packet {"cmd": "pingreq"}
 DEBUG  mqttjs:client _writePacket :: writing to stream +1ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +1ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +0ms
 DEBUG  mqttjs:client noop :: +1ms undefined
 DEBUG  mqttjs:client writable stream :: parsing buffer +127ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +2ms
 DEBUG  mqttjs:client work :: getting next packet in queue +0ms
 DEBUG  mqttjs:client work :: packet pulled from queue +2ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +1ms
 DEBUG  mqttjs:client _checkPing :: checking ping... +10s
 DEBUG  mqttjs:client _checkPing :: ping response received in time +1ms
 DEBUG  mqttjs:client _sendPing :: sending pingreq +1ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +1ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +1ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +3ms
 LOG  packet {"cmd": "pingreq"}
 DEBUG  mqttjs:client _writePacket :: writing to stream +1ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +1ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +0ms
 DEBUG  mqttjs:client noop :: +2ms undefined
 DEBUG  mqttjs:client writable stream :: parsing buffer +497ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +1ms
 DEBUG  mqttjs:client work :: getting next packet in queue +1ms
 DEBUG  mqttjs:client work :: packet pulled from queue +1ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +2ms
 DEBUG  mqttjs:client _checkPing :: checking ping... +10s
 DEBUG  mqttjs:client _checkPing :: ping response received in time +2ms
 DEBUG  mqttjs:client _sendPing :: sending pingreq +1ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +0ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +1ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +4ms
 LOG  packet {"cmd": "pingreq"}
 DEBUG  mqttjs:client _writePacket :: writing to stream +1ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +2ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +2ms
 DEBUG  mqttjs:client noop :: +1ms undefined
 DEBUG  mqttjs:client writable stream :: parsing buffer +103ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +1ms
 DEBUG  mqttjs:client work :: getting next packet in queue +1ms
 DEBUG  mqttjs:client work :: packet pulled from queue +1ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +0ms
 DEBUG  mqttjs:client _checkPing :: checking ping... +10s
 DEBUG  mqttjs:client _checkPing :: ping response received in time +1ms
 DEBUG  mqttjs:client _sendPing :: sending pingreq +1ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +0ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +2ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +4ms
 LOG  packet {"cmd": "pingreq"}
 DEBUG  mqttjs:client _writePacket :: writing to stream +1ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +0ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +4ms
 DEBUG  mqttjs:client noop :: +0ms undefined
 DEBUG  mqttjs:client writable stream :: parsing buffer +105ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +1ms
 DEBUG  mqttjs:client work :: getting next packet in queue +1ms
 DEBUG  mqttjs:client work :: packet pulled from queue +1ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +0ms
 DEBUG  mqttjs:client _checkPing :: checking ping... +10s
 DEBUG  mqttjs:client _checkPing :: ping response received in time +2ms
 DEBUG  mqttjs:client _sendPing :: sending pingreq +0ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +1ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +1ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +4ms
 LOG  packet {"cmd": "pingreq"}
 DEBUG  mqttjs:client _writePacket :: writing to stream +3ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +3ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +1ms
 DEBUG  mqttjs:client noop :: +0ms undefined
 DEBUG  mqttjs:client writable stream :: parsing buffer +124ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +2ms
 DEBUG  mqttjs:client work :: getting next packet in queue +0ms
 DEBUG  mqttjs:client work :: packet pulled from queue +2ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +1ms
 DEBUG  mqttjs:client _checkPing :: checking ping... +10s
 DEBUG  mqttjs:client _checkPing :: ping response received in time +1ms
 DEBUG  mqttjs:client _sendPing :: sending pingreq +1ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +1ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +1ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +3ms
 LOG  packet {"cmd": "pingreq"}
 DEBUG  mqttjs:client _writePacket :: writing to stream +1ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +1ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +0ms
 DEBUG  mqttjs:client noop :: +2ms undefined
 DEBUG  mqttjs:client writable stream :: parsing buffer +1s
 DEBUG  mqttjs:client parser :: on packet push to packets array. +2ms
 DEBUG  mqttjs:client work :: getting next packet in queue +0ms
 DEBUG  mqttjs:client work :: packet pulled from queue +3ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +0ms

wondering, why it's uncaught in client.on('error') !

@abdelhameedhamdy
Copy link
Contributor Author

Another log, with same error repeated.

 DEBUG  mqttjs:ws WebSocket onOpen +536ms
 DEBUG  mqttjs:client writable stream :: parsing buffer +4s
 DEBUG  mqttjs:client parser :: on packet push to packets array. +0ms
 DEBUG  mqttjs:client work :: getting next packet in queue +0ms
 DEBUG  mqttjs:client work :: packet pulled from queue +0ms
 DEBUG  mqttjs:client _reschedulePing :: rescheduling ping +1ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +0ms
 DEBUG  mqttjs:ws WebSocket onError +230ms {"isTrusted": false, "message": null}
 DEBUG  mqttjs:ws WebSocket onClose +0ms {"code": 1006, "isTrusted": false, "reason": null}
 DEBUG  mqttjs:client streamErrorHandler :: error +188ms WebSocket error
 DEBUG  mqttjs:client noop :: +1ms [Error: WebSocket error]
 DEBUG  mqttjs:client (mobile-app)stream :: on close +0ms
 DEBUG  mqttjs:client _flushVolatile :: deleting volatile messages from the queue and setting their callbacks as error function +0ms
 DEBUG  mqttjs:client stream: emit close to MqttClient +0ms
 DEBUG  mqttjs:client writable stream :: parsing buffer +2s
 DEBUG  mqttjs:client parser :: on packet push to packets array. +1ms
 DEBUG  mqttjs:client work :: getting next packet in queue +0ms
 DEBUG  mqttjs:client work :: packet pulled from queue +0ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +0ms
 DEBUG  mqttjs:client _handleConnack +0ms
 DEBUG  mqttjs:client _setupPingTimer :: keepalive 10 (seconds) +12ms
 DEBUG  mqttjs:client connect :: sending queued packets +5ms
 DEBUG  mqttjs:client deliver :: entry 'undefined' +0ms
 DEBUG  mqttjs:client _resubscribe +0ms
 DEBUG  mqttjs:client subscribe: array topic flespi/message/gw/devices/000000 +0ms
 DEBUG  mqttjs:client subscribe: pushing topic `flespi/message/gw/devices/000000` and qos `1` to subs list +0ms
 DEBUG  mqttjs:client subscribe: array topic test/topic +0ms
 DEBUG  mqttjs:client subscribe: pushing topic `test/topic` and qos `1` to subs list +0ms
 DEBUG  mqttjs:client subscribe :: resubscribe true +1ms
 DEBUG  mqttjs:client subscribe :: call _sendPacket +0ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +0ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "subscribe", "messageId": 22847, "subscriptions": [{"nl": false, "properties": undefined, "qos": 1, "rap": false, "rh": 0, "topic": "flespi/message/gw/devices/000000"}, {"nl": false, "properties": undefined, "qos": 1, "rap": false, "rh": 0, "topic": "test/topic"}]}' +0ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +0ms
 DEBUG  mqttjs:client _writePacket :: writing to stream +1ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +0ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +0ms
 DEBUG  mqttjs:client noop :: +0ms undefined
 DEBUG  mqttjs:client subscribe: array topic flespi/state/gw/devices/000000/telemetry/position +65ms
 DEBUG  mqttjs:client subscribe: pushing topic `flespi/state/gw/devices/000000/telemetry/position` and qos `0` to subs list +0ms
 DEBUG  mqttjs:client subscribe: array topic flespi/state/gw/devices/000000/telemetry/status +0ms
 DEBUG  mqttjs:client subscribe: pushing topic `flespi/state/gw/devices/000000/telemetry/status` and qos `0` to subs list +1ms
 DEBUG  mqttjs:client subscribe: array topic flespi/state/gw/devices/000000/telemetry/timestamp +0ms
 DEBUG  mqttjs:client subscribe: pushing topic `flespi/state/gw/devices/000000/telemetry/timestamp` and qos `0` to subs list +0ms
 DEBUG  mqttjs:client subscribe :: resubscribe true +0ms
 DEBUG  mqttjs:client subscribe :: call _sendPacket +0ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +0ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "subscribe", "messageId": 22848, "subscriptions": [{"nl": false, "properties": undefined, "qos": 0, "rap": false, "rh": 0, "topic": "flespi/state/gw/devices/000000/telemetry/position"}, {"nl": false, "properties": undefined, "qos": 0, "rap": false, "rh": 0, "topic": "flespi/state/gw/devices/000000/telemetry/status"}, {"nl": false, "properties": undefined, "qos": 0, "rap": false, "rh": 0, "topic": "flespi/state/gw/devices/000000/telemetry/timestamp"}]}' +0ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +1ms
 DEBUG  mqttjs:client _writePacket :: writing to stream +0ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result false +0ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +0ms
 DEBUG  mqttjs:client noop :: +1ms undefined
 DEBUG  mqttjs:client writable stream :: parsing buffer +103ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +0ms
 DEBUG  mqttjs:client work :: getting next packet in queue +0ms
 DEBUG  mqttjs:client work :: packet pulled from queue +1ms
 DEBUG  mqttjs:client _reschedulePing :: rescheduling ping +0ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +0ms
 DEBUG  mqttjs:client handlePublish: packet '{"cmd": "publish", "dup": false, "length": 863, "messageId": 1, "payload": {"data": [Array], "type": "Buffer"}, "properties": {"userProperties": {"cid": "1768230", "timestamp": "1702594243.638359", "token_id": "59212603"}}, "qos": 1, "retain": true, "topic": "test/topic"}' +0ms
 DEBUG  mqttjs:client handlePublish: qos 1 +12ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +5ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "puback", "messageId": 1, "reasonCode": 0}' +1ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +0ms
 DEBUG  mqttjs:client _writePacket :: writing to stream +0ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +0ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +1ms
 DEBUG  mqttjs:client writable stream :: parsing buffer +2ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +1ms
 DEBUG  mqttjs:client work :: getting next packet in queue +0ms
 DEBUG  mqttjs:client work :: packet pulled from queue +0ms
 DEBUG  mqttjs:client _reschedulePing :: rescheduling ping +0ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +0ms
 DEBUG  mqttjs:client _handleAck :: packet type +0ms suback
 DEBUG  mqttjs:client noop :: +0ms null
 DEBUG  mqttjs:client writable stream :: parsing buffer +2ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +1ms
 DEBUG  mqttjs:client work :: getting next packet in queue +0ms
 DEBUG  mqttjs:client work :: packet pulled from queue +0ms
 DEBUG  mqttjs:client _reschedulePing :: rescheduling ping +0ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +0ms
 DEBUG  mqttjs:client handlePublish: packet '{"cmd": "publish", "dup": false, "length": 209, "payload": {"data": [Array], "type": "Buffer"}, "properties": {"messageExpiryInterval": 31968000, "userProperties": {"cid": "1768230", "timestamp": "1714480255"}}, "qos": 0, "retain": true, "topic": "flespi/state/gw/devices/000000/telemetry/position"}' +0ms
 DEBUG  mqttjs:client handlePublish: qos 0 +6ms
 DEBUG  mqttjs:client writable stream :: parsing buffer +66ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +1ms
 DEBUG  mqttjs:client work :: getting next packet in queue +0ms
 DEBUG  mqttjs:client work :: packet pulled from queue +0ms
 DEBUG  mqttjs:client _reschedulePing :: rescheduling ping +0ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +0ms
 DEBUG  mqttjs:client handlePublish: packet '{"cmd": "publish", "dup": false, "length": 123, "payload": {"data": [Array], "type": "Buffer"}, "properties": {"messageExpiryInterval": 31968000, "userProperties": {"cid": "1768230", "timestamp": "1714480255"}}, "qos": 0, "retain": true, "topic": "flespi/state/gw/devices/000000/telemetry/status"}' +0ms
 DEBUG  mqttjs:client handlePublish: qos 0 +1ms
 DEBUG  mqttjs:client writable stream :: parsing buffer +8ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +1ms
 DEBUG  mqttjs:client work :: getting next packet in queue +0ms
 DEBUG  mqttjs:client work :: packet pulled from queue +1ms
 DEBUG  mqttjs:client _reschedulePing :: rescheduling ping +0ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +0ms
 DEBUG  mqttjs:client handlePublish: packet '{"cmd": "publish", "dup": false, "length": 108, "payload": {"data": [Array], "type": "Buffer"}, "properties": {"messageExpiryInterval": 31968000, "userProperties": {"cid": "1768230", "timestamp": "1714480255"}}, "qos": 0, "retain": true, "topic": "flespi/state/gw/devices/000000/telemetry/timestamp"}' +0ms
 DEBUG  mqttjs:client handlePublish: qos 0 +1ms
 DEBUG  mqttjs:client writable stream :: parsing buffer +1ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +0ms
 DEBUG  mqttjs:client work :: getting next packet in queue +1ms
 DEBUG  mqttjs:client work :: packet pulled from queue +0ms
 DEBUG  mqttjs:client _reschedulePing :: rescheduling ping +0ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +0ms
 DEBUG  mqttjs:client _handleAck :: packet type +0ms suback
 DEBUG  mqttjs:client noop :: +0ms null
 DEBUG  mqttjs:client _checkPing :: checking ping... +10s
 ERROR  Error: Keepalive timeout, js engine: hermes
 DEBUG  mqttjs:client _checkPing :: checking ping... +10s
 DEBUG  mqttjs:client _checkPing :: ping response received in time +2ms
 DEBUG  mqttjs:client _sendPing :: sending pingreq +0ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +1ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +2ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +3ms
 DEBUG  mqttjs:client _writePacket :: writing to stream +1ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result false +1ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +0ms
 DEBUG  mqttjs:client noop :: +3ms undefined
 DEBUG  mqttjs:client _checkPing :: checking ping... +10s
 DEBUG  mqttjs:client _checkPing :: ping response received in time +1ms
 DEBUG  mqttjs:client _sendPing :: sending pingreq +1ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +1ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +1ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +4ms
 DEBUG  mqttjs:client _writePacket :: writing to stream +0ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +1ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +0ms
 DEBUG  mqttjs:client noop :: +2ms undefined
 DEBUG  mqttjs:client writable stream :: parsing buffer +97ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +0ms
 DEBUG  mqttjs:client work :: getting next packet in queue +1ms
 DEBUG  mqttjs:client work :: packet pulled from queue +0ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +0ms
 DEBUG  mqttjs:client _checkPing :: checking ping... +10s
 ERROR  Error: Keepalive timeout, js engine: hermes
 DEBUG  mqttjs:client _checkPing :: checking ping... +10s
 DEBUG  mqttjs:client _checkPing :: ping response received in time +0ms
 DEBUG  mqttjs:client _sendPing :: sending pingreq +1ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +0ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +0ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +0ms
 DEBUG  mqttjs:client _writePacket :: writing to stream +1ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +0ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +0ms
 DEBUG  mqttjs:client noop :: +0ms undefined
 DEBUG  mqttjs:client writable stream :: parsing buffer +114ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +1ms
 DEBUG  mqttjs:client work :: getting next packet in queue +0ms
 DEBUG  mqttjs:client work :: packet pulled from queue +1ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +0ms
 DEBUG  mqttjs:client _checkPing :: checking ping... +10s
 DEBUG  mqttjs:client _checkPing :: ping response received in time +2ms
 DEBUG  mqttjs:client _sendPing :: sending pingreq +1ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +0ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +2ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +3ms
 DEBUG  mqttjs:client _writePacket :: writing to stream +1ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +0ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +1ms
 DEBUG  mqttjs:client noop :: +0ms undefined
 DEBUG  mqttjs:client writable stream :: parsing buffer +95ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +1ms
 DEBUG  mqttjs:client work :: getting next packet in queue +0ms
 DEBUG  mqttjs:client work :: packet pulled from queue +1ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +0ms

@robertsLando
Copy link
Member

@abdelhameedhamdy

 DEBUG  mqttjs:client _checkPing :: checking ping... +10s
 ERROR  Error: Keepalive timeout, js engine: hermes
 DEBUG  mqttjs:client _checkPing :: checking ping... +10s

Seems your keepalive is 10s not 5 minutes, could you attach full logs from startup?

@abdelhameedhamdy
Copy link
Contributor Author

@abdelhameedhamdy

 DEBUG  mqttjs:client _checkPing :: checking ping... +10s
 ERROR  Error: Keepalive timeout, js engine: hermes
 DEBUG  mqttjs:client _checkPing :: checking ping... +10s

Seems your keepalive is 10s not 5 minutes, could you attach full logs from startup?

Yes, it is set to 10 sec not 5, the last log is a full one from starting a connection with mqtt

@abdelhameedhamdy
Copy link
Contributor Author

My case scenario, mobile app opens a connection to mqtt, then when app bacgrounded, it reconnects again with the same mqtt options mentioned before, (keealive set to 10 sec), then the keepalive timeout appears, attached extra logs for the whole case:

 DEBUG  mqttjs:client parser :: on packet push to packets array. +7ms
 DEBUG  mqttjs:client work :: getting next packet in queue +0ms
 DEBUG  mqttjs:client work :: packet pulled from queue +0ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +1ms
 DEBUG  mqttjs:client _handleConnack +0ms
 DEBUG  mqttjs:client _setupPingTimer :: keepalive 10 (seconds) +16ms
 DEBUG  mqttjs:client connect :: sending queued packets +164ms
 DEBUG  mqttjs:client deliver :: entry 'undefined' +0ms
 DEBUG  mqttjs:client _resubscribe +1ms
 DEBUG  mqttjs:client subscribe: array topic flespi/message/gw/devices/0000 +1ms
 DEBUG  mqttjs:client subscribe: pushing topic `flespi/message/gw/devices/0000` and qos `1` to subs list +1ms
 DEBUG  mqttjs:client subscribe: array topic test/topic +0ms
 DEBUG  mqttjs:client subscribe: pushing topic `test/topic` and qos `1` to subs list +0ms
 DEBUG  mqttjs:client subscribe :: resubscribe true +1ms
 DEBUG  mqttjs:client subscribe :: call _sendPacket +0ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +1ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "subscribe", "messageId": 12623, "subscriptions": [{"nl": false, "properties": undefined, "qos": 1, "rap": false, "rh": 0, "topic": "flespi/message/gw/devices/0000"}, {"nl": false, "properties": undefined, "qos": 1, "rap": false, "rh": 0, "topic": "test/topic"}]}' +0ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +1ms
 DEBUG  mqttjs:client _writePacket :: writing to stream +0ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +2ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +1ms
 DEBUG  mqttjs:client noop :: +0ms undefined
 DEBUG  mqttjs:client subscribe: array topic flespi/state/gw/devices/0000/telemetry/position +122ms
 DEBUG  mqttjs:client subscribe: pushing topic `flespi/state/gw/devices/0000/telemetry/position` and qos `0` to subs list +0ms
 DEBUG  mqttjs:client subscribe: array topic flespi/state/gw/devices/0000/telemetry/status +0ms
 DEBUG  mqttjs:client subscribe: pushing topic `flespi/state/gw/devices/0000/telemetry/status` and qos `0` to subs list +0ms
 DEBUG  mqttjs:client subscribe: array topic flespi/state/gw/devices/0000/telemetry/timestamp +0ms
 DEBUG  mqttjs:client subscribe: pushing topic `flespi/state/gw/devices/0000/telemetry/timestamp` and qos `0` to subs list +0ms
 DEBUG  mqttjs:client subscribe :: resubscribe true +0ms
 DEBUG  mqttjs:client subscribe :: call _sendPacket +0ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +0ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "subscribe", "messageId": 12624, "subscriptions": [{"nl": false, "properties": undefined, "qos": 0, "rap": false, "rh": 0, "topic": "flespi/state/gw/devices/0000/telemetry/position"}, {"nl": false, "properties": undefined, "qos": 0, "rap": false, "rh": 0, "topic": "flespi/state/gw/devices/0000/telemetry/status"}, {"nl": false, "properties": undefined, "qos": 0, "rap": false, "rh": 0, "topic": "flespi/state/gw/devices/0000/telemetry/timestamp"}]}' +1ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +1ms
 DEBUG  mqttjs:client _writePacket :: writing to stream +0ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result false +0ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +0ms
 DEBUG  mqttjs:client noop :: +0ms undefined
 DEBUG  mqttjs:client writable stream :: parsing buffer +128ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +2ms
 DEBUG  mqttjs:client work :: getting next packet in queue +1ms
 DEBUG  mqttjs:client work :: packet pulled from queue +0ms
 DEBUG  mqttjs:client _reschedulePing :: rescheduling ping +0ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +4ms
 DEBUG  mqttjs:client _handleAck :: packet type +1ms suback
 DEBUG  mqttjs:client noop :: +0ms null
 DEBUG  mqttjs:client writable stream :: parsing buffer +2ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +0ms
 DEBUG  mqttjs:client work :: getting next packet in queue +0ms
 DEBUG  mqttjs:client work :: packet pulled from queue +0ms
 DEBUG  mqttjs:client _reschedulePing :: rescheduling ping +0ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +0ms
 DEBUG  mqttjs:client _handleAck :: packet type +0ms suback
 DEBUG  mqttjs:client noop :: +0ms null
 DEBUG  mqttjs:client writable stream :: parsing buffer +2s
 DEBUG  mqttjs:client parser :: on packet push to packets array. +4ms
 DEBUG  mqttjs:client work :: getting next packet in queue +2ms
 DEBUG  mqttjs:client work :: packet pulled from queue +2ms
 DEBUG  mqttjs:client _reschedulePing :: rescheduling ping +1ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +1ms
 DEBUG  mqttjs:client handlePublish: packet '{"cmd": "publish", "dup": false, "length": 863, "messageId": 1, "payload": {"data": [Array], "type": "Buffer"}, "properties": {"userProperties": {"cid": "1768230", "timestamp": "1702594243.638359", "token_id": "59212603"}}, "qos": 1, "retain": true, "topic": "test/topic"}' +4ms
 DEBUG  mqttjs:client handlePublish: qos 1 +30ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +4ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "puback", "messageId": 1, "reasonCode": 0}' +0ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +0ms
 DEBUG  mqttjs:client _writePacket :: writing to stream +0ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +4ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +0ms
 DEBUG  mqttjs:client _checkPing :: checking ping... +10s
 DEBUG  mqttjs:client _checkPing :: ping response received in time +2ms
 DEBUG  mqttjs:client _sendPing :: sending pingreq +2ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +0ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +1ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +2ms
 DEBUG  mqttjs:client _writePacket :: writing to stream +2ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +1ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +3ms
 DEBUG  mqttjs:client noop :: +2ms undefined
 DEBUG  mqttjs:client writable stream :: parsing buffer +157ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +1ms
 DEBUG  mqttjs:client work :: getting next packet in queue +0ms
 DEBUG  mqttjs:client work :: packet pulled from queue +1ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +0ms
 DEBUG  mqttjs:client _checkPing :: checking ping... +10s
 DEBUG  mqttjs:client _checkPing :: ping response received in time +1ms
 DEBUG  mqttjs:client _sendPing :: sending pingreq +1ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +0ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +1ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +4ms
 DEBUG  mqttjs:client _writePacket :: writing to stream +1ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +0ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +3ms
 DEBUG  mqttjs:client noop :: +1ms undefined
 DEBUG  mqttjs:client writable stream :: parsing buffer +98ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +1ms
 DEBUG  mqttjs:client work :: getting next packet in queue +1ms
 DEBUG  mqttjs:client work :: packet pulled from queue +0ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +0ms
 DEBUG  mqttjs:client _checkPing :: checking ping... +10s
 DEBUG  mqttjs:client _checkPing :: ping response received in time +2ms
 DEBUG  mqttjs:client _sendPing :: sending pingreq +0ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +1ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +1ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +5ms
 DEBUG  mqttjs:client _writePacket :: writing to stream +0ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +5ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +2ms
 DEBUG  mqttjs:client noop :: +0ms undefined
 DEBUG  mqttjs:client writable stream :: parsing buffer +98ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +1ms
 DEBUG  mqttjs:client work :: getting next packet in queue +0ms
 DEBUG  mqttjs:client work :: packet pulled from queue +1ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +0ms
 DEBUG  mqttjs:client _checkPing :: checking ping... +10s
 DEBUG  mqttjs:client _checkPing :: ping response received in time +1ms
 DEBUG  mqttjs:client _sendPing :: sending pingreq +1ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +0ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +1ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +4ms
 DEBUG  mqttjs:client _writePacket :: writing to stream +1ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +1ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +2ms
 DEBUG  mqttjs:client noop :: +0ms undefined
 DEBUG  mqttjs:client writable stream :: parsing buffer +113ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +2ms
 DEBUG  mqttjs:client work :: getting next packet in queue +0ms
 DEBUG  mqttjs:client work :: packet pulled from queue +1ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +1ms
 DEBUG  mqttjs:client _checkPing :: checking ping... +10s
 DEBUG  mqttjs:client _checkPing :: ping response received in time +2ms
 DEBUG  mqttjs:client _sendPing :: sending pingreq +1ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +1ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +1ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +4ms
 DEBUG  mqttjs:client _writePacket :: writing to stream +1ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +0ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +5ms
 DEBUG  mqttjs:client noop :: +2ms undefined
 DEBUG  mqttjs:client writable stream :: parsing buffer +109ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +1ms
 DEBUG  mqttjs:client work :: getting next packet in queue +1ms
 DEBUG  mqttjs:client work :: packet pulled from queue +0ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +0ms
 DEBUG  mqttjs:client _checkPing :: checking ping... +10s
 DEBUG  mqttjs:client _checkPing :: ping response received in time +1ms
 DEBUG  mqttjs:client _sendPing :: sending pingreq +1ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +1ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +1ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +4ms
 DEBUG  mqttjs:client _writePacket :: writing to stream +1ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +1ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +5ms
 DEBUG  mqttjs:client noop :: +1ms undefined
 DEBUG  mqttjs:client writable stream :: parsing buffer +424ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +1ms
 DEBUG  mqttjs:client work :: getting next packet in queue +1ms
 DEBUG  mqttjs:client work :: packet pulled from queue +0ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +0ms
 DEBUG  mqttjs:client _checkPing :: checking ping... +10s
 DEBUG  mqttjs:client _checkPing :: ping response received in time +2ms
 DEBUG  mqttjs:client _sendPing :: sending pingreq +1ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +1ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +1ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +4ms
 DEBUG  mqttjs:client _writePacket :: writing to stream +1ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +1ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +2ms
 DEBUG  mqttjs:client noop :: +1ms undefined
 DEBUG  mqttjs:client writable stream :: parsing buffer +103ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +1ms
 DEBUG  mqttjs:client work :: getting next packet in queue +0ms
 DEBUG  mqttjs:client work :: packet pulled from queue +1ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +0ms
 DEBUG  mqttjs:client _checkPing :: checking ping... +10s
 DEBUG  mqttjs:client _checkPing :: ping response received in time +2ms
 DEBUG  mqttjs:client _sendPing :: sending pingreq +0ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +1ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +2ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +3ms
 DEBUG  mqttjs:client _writePacket :: writing to stream +0ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +1ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +1ms
 DEBUG  mqttjs:client noop :: +2ms undefined
 DEBUG  mqttjs:client writable stream :: parsing buffer +134ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +1ms
 DEBUG  mqttjs:client work :: getting next packet in queue +1ms
 DEBUG  mqttjs:client work :: packet pulled from queue +0ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +0ms
 DEBUG  mqttjs:client _checkPing :: checking ping... +10s
 DEBUG  mqttjs:client _checkPing :: ping response received in time +2ms
 DEBUG  mqttjs:client _sendPing :: sending pingreq +1ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +0ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +1ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +5ms
 DEBUG  mqttjs:client _writePacket :: writing to stream +0ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +2ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +1ms
 DEBUG  mqttjs:client noop :: +1ms undefined
 DEBUG  mqttjs:client writable stream :: parsing buffer +127ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +1ms
 DEBUG  mqttjs:client work :: getting next packet in queue +1ms
 DEBUG  mqttjs:client work :: packet pulled from queue +0ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +1ms
 DEBUG  mqttjs:client _checkPing :: checking ping... +10s
 DEBUG  mqttjs:client _checkPing :: ping response received in time +1ms
 DEBUG  mqttjs:client _sendPing :: sending pingreq +1ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +0ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +1ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +4ms
 DEBUG  mqttjs:client _writePacket :: writing to stream +1ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +5ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +1ms
 DEBUG  mqttjs:client noop :: +1ms undefined
 DEBUG  mqttjs:client writable stream :: parsing buffer +112ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +1ms
 DEBUG  mqttjs:client work :: getting next packet in queue +1ms
 DEBUG  mqttjs:client work :: packet pulled from queue +0ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +2ms
 DEBUG  mqttjs:client _checkPing :: checking ping... +10s
 DEBUG  mqttjs:client _checkPing :: ping response received in time +2ms
 DEBUG  mqttjs:client _sendPing :: sending pingreq +0ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +1ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +1ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +3ms
 DEBUG  mqttjs:client _writePacket :: writing to stream +1ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +0ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +1ms
 DEBUG  mqttjs:client noop :: +1ms undefined
 DEBUG  mqttjs:client writable stream :: parsing buffer +106ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +1ms
 DEBUG  mqttjs:client work :: getting next packet in queue +0ms
 DEBUG  mqttjs:client work :: packet pulled from queue +1ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +0ms
 DEBUG  mqttjs:client _checkPing :: checking ping... +10s
 DEBUG  mqttjs:client _checkPing :: ping response received in time +2ms
 DEBUG  mqttjs:client _sendPing :: sending pingreq +1ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +0ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +2ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +3ms
 DEBUG  mqttjs:client _writePacket :: writing to stream +0ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +1ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +1ms
 DEBUG  mqttjs:client noop :: +1ms undefined
 DEBUG  mqttjs:client writable stream :: parsing buffer +102ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +2ms
 DEBUG  mqttjs:client work :: getting next packet in queue +0ms
 DEBUG  mqttjs:client work :: packet pulled from queue +1ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +1ms
 DEBUG  mqttjs:client _checkPing :: checking ping... +10s
 DEBUG  mqttjs:client _checkPing :: ping response received in time +1ms
 DEBUG  mqttjs:client _sendPing :: sending pingreq +1ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +1ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +3ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +1ms
 DEBUG  mqttjs:client _writePacket :: writing to stream +0ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +1ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +0ms
 DEBUG  mqttjs:client noop :: +0ms undefined
 DEBUG  mqttjs:client writable stream :: parsing buffer +102ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +1ms
 DEBUG  mqttjs:client work :: getting next packet in queue +0ms
 DEBUG  mqttjs:client work :: packet pulled from queue +0ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +1ms
 DEBUG  mqttjs:client _checkPing :: checking ping... +10s
 DEBUG  mqttjs:client _checkPing :: ping response received in time +1ms
 DEBUG  mqttjs:client _sendPing :: sending pingreq +1ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +1ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +1ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +3ms
 DEBUG  mqttjs:client _writePacket :: writing to stream +0ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +1ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +0ms
 DEBUG  mqttjs:client noop :: +1ms undefined
 DEBUG  mqttjs:client writable stream :: parsing buffer +114ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +1ms
 DEBUG  mqttjs:client work :: getting next packet in queue +1ms
 DEBUG  mqttjs:client work :: packet pulled from queue +1ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +2ms
 DEBUG  mqttjs:client _checkPing :: checking ping... +10s
 DEBUG  mqttjs:client _checkPing :: ping response received in time +1ms
 DEBUG  mqttjs:client _sendPing :: sending pingreq +1ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +0ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +0ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +1ms
 DEBUG  mqttjs:client _writePacket :: writing to stream +1ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +0ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +0ms
 DEBUG  mqttjs:client noop :: +4ms undefined
 DEBUG  mqttjs:client writable stream :: parsing buffer +106ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +2ms
 DEBUG  mqttjs:client work :: getting next packet in queue +1ms
 DEBUG  mqttjs:client work :: packet pulled from queue +0ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +0ms
 DEBUG  mqttjs:client _checkPing :: checking ping... +10s
 DEBUG  mqttjs:client _checkPing :: ping response received in time +1ms
 DEBUG  mqttjs:client _sendPing :: sending pingreq +1ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +1ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +1ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +3ms
 DEBUG  mqttjs:client _writePacket :: writing to stream +0ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +1ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +0ms
 DEBUG  mqttjs:client noop :: +0ms undefined
 DEBUG  mqttjs:client writable stream :: parsing buffer +118ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +1ms
 DEBUG  mqttjs:client work :: getting next packet in queue +0ms
 DEBUG  mqttjs:client work :: packet pulled from queue +0ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +1ms
 DEBUG  mqttjs:client _checkPing :: checking ping... +10s
 DEBUG  mqttjs:client _checkPing :: ping response received in time +1ms
 DEBUG  mqttjs:client _sendPing :: sending pingreq +2ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +0ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +2ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +2ms
 DEBUG  mqttjs:client _writePacket :: writing to stream +1ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +5ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +1ms
 DEBUG  mqttjs:client noop :: +0ms undefined
 DEBUG  mqttjs:client writable stream :: parsing buffer +114ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +1ms
 DEBUG  mqttjs:client work :: getting next packet in queue +1ms
 DEBUG  mqttjs:client work :: packet pulled from queue +0ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +1ms
 DEBUG  mqttjs:client _checkPing :: checking ping... +10s
 DEBUG  mqttjs:client _checkPing :: ping response received in time +1ms
 DEBUG  mqttjs:client _sendPing :: sending pingreq +1ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +1ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +1ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +4ms
 DEBUG  mqttjs:client _writePacket :: writing to stream +1ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +1ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +2ms
 DEBUG  mqttjs:client noop :: +1ms undefined
 DEBUG  mqttjs:client writable stream :: parsing buffer +122ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +1ms
 DEBUG  mqttjs:client work :: getting next packet in queue +1ms
 DEBUG  mqttjs:client work :: packet pulled from queue +0ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +1ms
 DEBUG  mqttjs:client _checkPing :: checking ping... +10s
 DEBUG  mqttjs:client _checkPing :: ping response received in time +2ms
 DEBUG  mqttjs:client _sendPing :: sending pingreq +1ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +0ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +1ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +8ms
 DEBUG  mqttjs:client _writePacket :: writing to stream +1ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +0ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +1ms
 DEBUG  mqttjs:client noop :: +0ms undefined
 DEBUG  mqttjs:client writable stream :: parsing buffer +101ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +1ms
 DEBUG  mqttjs:client work :: getting next packet in queue +1ms
 DEBUG  mqttjs:client work :: packet pulled from queue +0ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +0ms
 DEBUG  mqttjs:client _checkPing :: checking ping... +10s
 DEBUG  mqttjs:client _checkPing :: ping response received in time +2ms
 DEBUG  mqttjs:client _sendPing :: sending pingreq +1ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +0ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +1ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +4ms
 DEBUG  mqttjs:client _writePacket :: writing to stream +1ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +1ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +4ms
 DEBUG  mqttjs:client noop :: +1ms undefined
 DEBUG  mqttjs:client writable stream :: parsing buffer +122ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +1ms
 DEBUG  mqttjs:client work :: getting next packet in queue +1ms
 DEBUG  mqttjs:client work :: packet pulled from queue +2ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +0ms
 DEBUG  mqttjs:client _checkPing :: checking ping... +10s
 DEBUG  mqttjs:client _checkPing :: ping response received in time +1ms
 DEBUG  mqttjs:client _sendPing :: sending pingreq +1ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +1ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +1ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +3ms
 DEBUG  mqttjs:client _writePacket :: writing to stream +0ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +1ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +1ms
 DEBUG  mqttjs:client noop :: +0ms undefined
 DEBUG  mqttjs:client writable stream :: parsing buffer +114ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +1ms
 DEBUG  mqttjs:client work :: getting next packet in queue +0ms
 DEBUG  mqttjs:client work :: packet pulled from queue +1ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +0ms
 DEBUG  mqttjs:client _checkPing :: checking ping... +10s
 DEBUG  mqttjs:client _checkPing :: ping response received in time +2ms
 DEBUG  mqttjs:client _sendPing :: sending pingreq +0ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +1ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +1ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +4ms
 DEBUG  mqttjs:client _writePacket :: writing to stream +0ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +1ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +0ms
 DEBUG  mqttjs:client noop :: +0ms undefined
 DEBUG  mqttjs:client writable stream :: parsing buffer +101ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +2ms
 DEBUG  mqttjs:client work :: getting next packet in queue +0ms
 DEBUG  mqttjs:client work :: packet pulled from queue +0ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +1ms
 DEBUG  mqttjs:client _checkPing :: checking ping... +10s
 DEBUG  mqttjs:client _checkPing :: ping response received in time +1ms
 DEBUG  mqttjs:client _sendPing :: sending pingreq +1ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +1ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +1ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +4ms
 DEBUG  mqttjs:client _writePacket :: writing to stream +1ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +1ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +2ms
 DEBUG  mqttjs:client noop :: +1ms undefined
 DEBUG  mqttjs:client writable stream :: parsing buffer +416ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +2ms
 DEBUG  mqttjs:client work :: getting next packet in queue +0ms
 DEBUG  mqttjs:client work :: packet pulled from queue +0ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +1ms
 DEBUG  mqttjs:client _checkPing :: checking ping... +10s
 DEBUG  mqttjs:client _checkPing :: ping response received in time +1ms
 DEBUG  mqttjs:client _sendPing :: sending pingreq +1ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +1ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +1ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +4ms
 DEBUG  mqttjs:client _writePacket :: writing to stream +0ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +1ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +1ms
 DEBUG  mqttjs:client noop :: +3ms undefined
 DEBUG  mqttjs:client writable stream :: parsing buffer +120ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +2ms
 DEBUG  mqttjs:client work :: getting next packet in queue +1ms
 DEBUG  mqttjs:client work :: packet pulled from queue +1ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +2ms
 DEBUG  mqttjs connecting to an MQTT broker... +4m
 DEBUG  mqttjs:client MqttClient :: version: +0ms 5.5.5
 DEBUG  mqttjs:client MqttClient :: environment +1ms browser
 DEBUG  mqttjs:client MqttClient :: options.protocol +0ms wss
 DEBUG  mqttjs:client MqttClient :: options.protocolVersion +1ms 5
 DEBUG  mqttjs:client MqttClient :: options.username +0ms FlespiToken WH9hV9TxKKso8HziAbJ9uQOn6ZFU7uPSZOZIMG6mgozeUWmkXUhiAVvwJZfEhUm5
 DEBUG  mqttjs:client MqttClient :: options.keepalive +1ms 10
 DEBUG  mqttjs:client MqttClient :: options.reconnectPeriod +1ms 1000
 DEBUG  mqttjs:client MqttClient :: options.rejectUnauthorized +0ms undefined
 DEBUG  mqttjs:client MqttClient :: options.properties.topicAliasMaximum +1ms undefined
 DEBUG  mqttjs:client MqttClient :: clientId +0ms mobile-app
 DEBUG  mqttjs:client MqttClient :: setting up stream +0ms
 DEBUG  mqttjs:client connect :: calling method to clear reconnect +1ms
 DEBUG  mqttjs:client _clearReconnect : clearing reconnect timer +0ms
 DEBUG  mqttjs:client connect :: using streamBuilder provided to client to create stream +0ms
 DEBUG  mqttjs calling streambuilder for +8ms wss
 DEBUG  mqttjs:ws browserStreamBuilder +4m
 DEBUG  mqttjs:client connect :: pipe stream to writable stream +4ms
 DEBUG  mqttjs:client connect: sending packet `connect` +0ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"clean": false, "clientId": "mobile-app", "cmd": "connect", "keepalive": 10, "password": undefined, "properties": {"sessionExpiryInterval": 604800}, "protocolId": "MQTT", "protocolVersion": 5, "username": "FlespiToken WH9hV9TxKKso8HziAbJ9uQOn6ZFU7uPSZOZIMG6mgozeUWmkXUhiAVvwJZfEhUm5"}' +0ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +2ms
 DEBUG  mqttjs:client _writePacket :: writing to stream +0ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +1ms
 DEBUG  mqttjs:ws WebSocket onOpen +1s
 DEBUG  mqttjs:client writable stream :: parsing buffer +7s
 DEBUG  mqttjs:client parser :: on packet push to packets array. +1ms
 DEBUG  mqttjs:client work :: getting next packet in queue +1ms
 DEBUG  mqttjs:client work :: packet pulled from queue +0ms
 DEBUG  mqttjs:client _reschedulePing :: rescheduling ping +0ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +0ms
 DEBUG  mqttjs:ws WebSocket onError +119ms {"isTrusted": false, "message": null}
 DEBUG  mqttjs:ws WebSocket onClose +3ms {"code": 1006, "isTrusted": false, "reason": null}
 DEBUG  mqttjs:client streamErrorHandler :: error +11ms WebSocket error
 DEBUG  mqttjs:client noop :: +0ms [Error: WebSocket error]
 DEBUG  mqttjs:client (mobile-app)stream :: on close +8ms
 DEBUG  mqttjs:client _flushVolatile :: deleting volatile messages from the queue and setting their callbacks as error function +0ms
 DEBUG  mqttjs:client stream: emit close to MqttClient +0ms
 DEBUG  mqttjs:client writable stream :: parsing buffer +2s
 DEBUG  mqttjs:client parser :: on packet push to packets array. +2ms
 DEBUG  mqttjs:client work :: getting next packet in queue +1ms
 DEBUG  mqttjs:client work :: packet pulled from queue +1ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +0ms
 DEBUG  mqttjs:client _handleConnack +0ms
 DEBUG  mqttjs:client _setupPingTimer :: keepalive 10 (seconds) +17ms
 DEBUG  mqttjs:client connect :: sending queued packets +10ms
 DEBUG  mqttjs:client deliver :: entry 'undefined' +0ms
 DEBUG  mqttjs:client _resubscribe +0ms
 DEBUG  mqttjs:client subscribe: array topic flespi/message/gw/devices/0000 +2ms
 DEBUG  mqttjs:client subscribe: pushing topic `flespi/message/gw/devices/test` and qos `1` to subs list +0ms
 DEBUG  mqttjs:client subscribe: array topic test/topic +0ms
 DEBUG  mqttjs:client subscribe: pushing topic `test/topic` and qos `1` to subs list +0ms
 DEBUG  mqttjs:client subscribe :: resubscribe true +1ms
 DEBUG  mqttjs:client subscribe :: call _sendPacket +0ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +0ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "subscribe", "messageId": 56220, "subscriptions": [{"nl": false, "properties": undefined, "qos": 1, "rap": false, "rh": 0, "topic": "flespi/message/gw/devices/0000"}, {"nl": false, "properties": undefined, "qos": 1, "rap": false, "rh": 0, "topic": "test/topic"}]}' +0ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +3ms
 DEBUG  mqttjs:client _writePacket :: writing to stream +0ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +0ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +1ms
 DEBUG  mqttjs:client noop :: +0ms undefined
 DEBUG  mqttjs:client writable stream :: parsing buffer +113ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +0ms
 DEBUG  mqttjs:client work :: getting next packet in queue +1ms
 DEBUG  mqttjs:client work :: packet pulled from queue +0ms
 DEBUG  mqttjs:client _reschedulePing :: rescheduling ping +0ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +1ms
 DEBUG  mqttjs:client _handleAck :: packet type +0ms suback
 DEBUG  mqttjs:client noop :: +0ms null
 DEBUG  mqttjs:client writable stream :: parsing buffer +2s
 DEBUG  mqttjs:client parser :: on packet push to packets array. +3ms
 DEBUG  mqttjs:client work :: getting next packet in queue +2ms
 DEBUG  mqttjs:client work :: packet pulled from queue +1ms
 DEBUG  mqttjs:client _reschedulePing :: rescheduling ping +0ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +1ms
 DEBUG  mqttjs:client handlePublish: packet '{"cmd": "publish", "dup": false, "length": 863, "messageId": 1, "payload": {"data": [Array], "type": "Buffer"}, "properties": {"userProperties": {"cid": "1768230", "timestamp": "1702594243.638359", "token_id": "59212603"}}, "qos": 1, "retain": true, "topic": "test/topic"}' +0ms
 DEBUG  mqttjs:client handlePublish: qos 1 +40ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +2ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "puback", "messageId": 1, "reasonCode": 0}' +0ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +0ms
 LOG  packet {"cmd": "puback", "messageId": 1, "reasonCode": 0}
 DEBUG  mqttjs:client _writePacket :: writing to stream +0ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +0ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +1ms
 DEBUG  mqttjs:client _checkPing :: checking ping... +10s
 DEBUG  mqttjs:client _checkPing :: ping response received in time +0ms
 DEBUG  mqttjs:client _sendPing :: sending pingreq +1ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +0ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +0ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +1ms
 DEBUG  mqttjs:client _writePacket :: writing to stream +0ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result false +2ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +2ms
 DEBUG  mqttjs:client noop :: +0ms undefined
 DEBUG  mqttjs:client _checkPing :: checking ping... +10s
 DEBUG  mqttjs:client _checkPing :: ping response received in time +1ms
 DEBUG  mqttjs:client _sendPing :: sending pingreq +1ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +0ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +1ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +5ms
 LOG  packet {"cmd": "pingreq"}
 DEBUG  mqttjs:client _writePacket :: writing to stream +3ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +1ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +0ms
 DEBUG  mqttjs:client noop :: +1ms undefined
 DEBUG  mqttjs:client writable stream :: parsing buffer +107ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +2ms
 DEBUG  mqttjs:client work :: getting next packet in queue +1ms
 DEBUG  mqttjs:client work :: packet pulled from queue +0ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +2ms
 DEBUG  mqttjs:client _checkPing :: checking ping... +10s
 ERROR  Error: Keepalive timeout, js engine: hermes
 DEBUG  mqttjs:client _checkPing :: checking ping... +10s
 DEBUG  mqttjs:client _checkPing :: ping response received in time +1ms
 DEBUG  mqttjs:client _sendPing :: sending pingreq +0ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +0ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +1ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +1ms
 LOG  packet {"cmd": "pingreq"}
 DEBUG  mqttjs:client _writePacket :: writing to stream +0ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +1ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +0ms
 DEBUG  mqttjs:client noop :: +0ms undefined
 DEBUG  mqttjs:client writable stream :: parsing buffer +131ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +1ms
 DEBUG  mqttjs:client work :: getting next packet in queue +0ms
 DEBUG  mqttjs:client work :: packet pulled from queue +0ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +0ms
 DEBUG  mqttjs:client _checkPing :: checking ping... +10s
 DEBUG  mqttjs:client _checkPing :: ping response received in time +1ms
 DEBUG  mqttjs:client _sendPing :: sending pingreq +1ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +0ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +1ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +4ms
 LOG  packet {"cmd": "pingreq"}
 DEBUG  mqttjs:client _writePacket :: writing to stream +4ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +1ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +1ms
 DEBUG  mqttjs:client noop :: +1ms undefined
 DEBUG  mqttjs:client writable stream :: parsing buffer +100ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +1ms
 DEBUG  mqttjs:client work :: getting next packet in queue +1ms
 DEBUG  mqttjs:client work :: packet pulled from queue +0ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +0ms
 DEBUG  mqttjs:client _checkPing :: checking ping... +10s
 DEBUG  mqttjs:client _checkPing :: ping response received in time +1ms
 DEBUG  mqttjs:client _sendPing :: sending pingreq +1ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +1ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +1ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +4ms
 LOG  packet {"cmd": "pingreq"}
 DEBUG  mqttjs:client _writePacket :: writing to stream +2ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +3ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +1ms
 DEBUG  mqttjs:client noop :: +1ms undefined
 DEBUG  mqttjs:client writable stream :: parsing buffer +107ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +2ms
 DEBUG  mqttjs:client work :: getting next packet in queue +1ms
 DEBUG  mqttjs:client work :: packet pulled from queue +0ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +2ms
 DEBUG  mqttjs:client _checkPing :: checking ping... +10s
 DEBUG  mqttjs:client _checkPing :: ping response received in time +1ms
 DEBUG  mqttjs:client _sendPing :: sending pingreq +1ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +0ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +2ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +3ms
 LOG  packet {"cmd": "pingreq"}
 DEBUG  mqttjs:client _writePacket :: writing to stream +2ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +5ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +1ms
 DEBUG  mqttjs:client noop :: +2ms undefined
 DEBUG  mqttjs:client writable stream :: parsing buffer +112ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +1ms
 DEBUG  mqttjs:client work :: getting next packet in queue +1ms
 DEBUG  mqttjs:client work :: packet pulled from queue +2ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +1ms
 DEBUG  mqttjs:client _checkPing :: checking ping... +10s
 DEBUG  mqttjs:client _checkPing :: ping response received in time +2ms
 DEBUG  mqttjs:client _sendPing :: sending pingreq +0ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +1ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +1ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +4ms
 LOG  packet {"cmd": "pingreq"}
 DEBUG  mqttjs:client _writePacket :: writing to stream +3ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +2ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +1ms
 DEBUG  mqttjs:client noop :: +0ms undefined
 DEBUG  mqttjs:client writable stream :: parsing buffer +101ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +1ms
 DEBUG  mqttjs:client work :: getting next packet in queue +1ms
 DEBUG  mqttjs:client work :: packet pulled from queue +0ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +3ms

@abdelhameedhamdy
Copy link
Contributor Author

Logs, after app came to foreground, with keepalive timeouts,

DEBUG  mqttjs connecting to an MQTT broker... +8m
 DEBUG  mqttjs:client MqttClient :: version: +0ms 5.5.5
 DEBUG  mqttjs:client MqttClient :: environment +1ms browser
 DEBUG  mqttjs:client MqttClient :: options.protocol +0ms wss
 DEBUG  mqttjs:client MqttClient :: options.protocolVersion +0ms 5
 DEBUG  mqttjs:client MqttClient :: options.username +0ms FlespiToken xxxxx
 DEBUG  mqttjs:client MqttClient :: options.keepalive +0ms 10
 DEBUG  mqttjs:client MqttClient :: options.reconnectPeriod +0ms 1000
 DEBUG  mqttjs:client MqttClient :: options.rejectUnauthorized +0ms undefined
 DEBUG  mqttjs:client MqttClient :: options.properties.topicAliasMaximum +0ms undefined
 DEBUG  mqttjs:client MqttClient :: clientId +1ms mobile-app
 DEBUG  mqttjs:client MqttClient :: setting up stream +0ms
 DEBUG  mqttjs:client connect :: calling method to clear reconnect +1ms
 DEBUG  mqttjs:client _clearReconnect : clearing reconnect timer +0ms
 DEBUG  mqttjs:client connect :: using streamBuilder provided to client to create stream +0ms
 DEBUG  mqttjs calling streambuilder for +3ms wss
 DEBUG  mqttjs:ws browserStreamBuilder +8m
 DEBUG  mqttjs:client connect :: pipe stream to writable stream +0ms
 DEBUG  mqttjs:client connect: sending packet `connect` +0ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"clean": false, "clientId": "mobile-app", "cmd": "connect", "keepalive": 10, "password": undefined, "properties": {"sessionExpiryInterval": 604800}, "protocolId": "MQTT", "protocolVersion": 5, "username": "FlespiToken xxxxx"}' +0ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +1ms
 DEBUG  mqttjs:client _writePacket :: writing to stream +0ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +2ms
 WARN  Mapbox warning {texposqlitenext}[ParseStyle]: source must have tiles {"level": "warning", "message": "{texposqlitenext}[ParseStyle]: source must have tiles", "tag": "Mbgl"}
 DEBUG  mqttjs:client _checkPing :: checking ping... +10s
 DEBUG  mqttjs:client _checkPing :: ping response received in time +1ms
 DEBUG  mqttjs:client _sendPing :: sending pingreq +0ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +0ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +0ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +0ms
 DEBUG  mqttjs:client _writePacket :: writing to stream +0ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +0ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +0ms
 DEBUG  mqttjs:client noop :: +1ms undefined
 DEBUG  mqttjs:client writable stream :: parsing buffer +90ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +1ms
 DEBUG  mqttjs:client work :: getting next packet in queue +0ms
 DEBUG  mqttjs:client work :: packet pulled from queue +0ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +0ms
 DEBUG  mqttjs:ws WebSocket onOpen +3s
 DEBUG  mqttjs:client writable stream :: parsing buffer +919ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +1ms
 DEBUG  mqttjs:client work :: getting next packet in queue +0ms
 DEBUG  mqttjs:client work :: packet pulled from queue +0ms
 DEBUG  mqttjs:client _reschedulePing :: rescheduling ping +1ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +0ms
 DEBUG  mqttjs:ws WebSocket onError +115ms {"isTrusted": false, "message": null}
 DEBUG  mqttjs:ws WebSocket onClose +2ms {"code": 1006, "isTrusted": false, "reason": null}
 DEBUG  mqttjs:client streamErrorHandler :: error +6ms WebSocket error
 DEBUG  mqttjs:client noop :: +1ms [Error: WebSocket error]
 DEBUG  mqttjs:client (mobile-app)stream :: on close +0ms
 DEBUG  mqttjs:client _flushVolatile :: deleting volatile messages from the queue and setting their callbacks as error function +0ms
 DEBUG  mqttjs:client stream: emit close to MqttClient +0ms
 DEBUG  mqttjs:client writable stream :: parsing buffer +4s
 DEBUG  mqttjs:client parser :: on packet push to packets array. +2ms
 DEBUG  mqttjs:client work :: getting next packet in queue +1ms
 DEBUG  mqttjs:client work :: packet pulled from queue +0ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +0ms
 DEBUG  mqttjs:client _handleConnack +3ms
 DEBUG  mqttjs:client _setupPingTimer :: keepalive 10 (seconds) +11ms
 DEBUG  mqttjs:client connect :: sending queued packets +5ms
 DEBUG  mqttjs:client deliver :: entry 'undefined' +0ms
 DEBUG  mqttjs:client _resubscribe +1ms
 DEBUG  mqttjs:client subscribe: array topic flespi/message/gw/devices/00000 +0ms
 DEBUG  mqttjs:client subscribe: pushing topic `flespi/message/gw/devices/00000` and qos `1` to subs list +0ms
 DEBUG  mqttjs:client subscribe: array topic /topic +1ms
 DEBUG  mqttjs:client subscribe: pushing topic `/topic` and qos `1` to subs list +0ms
 DEBUG  mqttjs:client subscribe :: resubscribe true +0ms
 DEBUG  mqttjs:client subscribe :: call _sendPacket +0ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +0ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "subscribe", "messageId": 20340, "subscriptions": [{"nl": false, "properties": undefined, "qos": 1, "rap": false, "rh": 0, "topic": "flespi/message/gw/devices/00000"}, {"nl": false, "properties": undefined, "qos": 1, "rap": false, "rh": 0, "topic": "test/topic"}]}' +0ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +1ms
 DEBUG  mqttjs:client _writePacket :: writing to stream +0ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +0ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +0ms
 DEBUG  mqttjs:client noop :: +0ms undefined
 DEBUG  mqttjs:client subscribe: array topic flespi/state/gw/devices/00000/telemetry/position +45ms
 DEBUG  mqttjs:client subscribe: pushing topic `flespi/state/gw/devices/00000/telemetry/position` and qos `0` to subs list +0ms
 DEBUG  mqttjs:client subscribe: array topic flespi/state/gw/devices/00000/telemetry/config.engine.ignition.status +0ms
 DEBUG  mqttjs:client subscribe: pushing topic `flespi/state/gw/devices/00000/telemetry/config.engine.ignition.status` and qos `0` to subs list +0ms
 DEBUG  mqttjs:client subscribe: array topic flespi/state/gw/devices/00000/telemetry/timestamp +0ms
 DEBUG  mqttjs:client subscribe: pushing topic `flespi/state/gw/devices/00000/telemetry/timestamp` and qos `0` to subs list +0ms
 DEBUG  mqttjs:client subscribe :: resubscribe true +1ms
 DEBUG  mqttjs:client subscribe :: call _sendPacket +0ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +0ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "subscribe", "messageId": 20341, "subscriptions": [{"nl": false, "properties": undefined, "qos": 0, "rap": false, "rh": 0, "topic": "flespi/state/gw/devices/00000/telemetry/position"}, {"nl": false, "properties": undefined, "qos": 0, "rap": false, "rh": 0, "topic": "flespi/state/gw/devices/00000/telemetry/config.engine.ignition.status"}, {"nl": false, "properties": undefined, "qos": 0, "rap": false, "rh": 0, "topic": "flespi/state/gw/devices/00000/telemetry/timestamp"}]}' +0ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +0ms
 DEBUG  mqttjs:client _writePacket :: writing to stream +0ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result false +1ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +2ms
 DEBUG  mqttjs:client noop :: +0ms undefined
 DEBUG  mqttjs:client writable stream :: parsing buffer +633ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +0ms
 DEBUG  mqttjs:client work :: getting next packet in queue +1ms
 DEBUG  mqttjs:client work :: packet pulled from queue +0ms
 DEBUG  mqttjs:client _reschedulePing :: rescheduling ping +0ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +1ms
 DEBUG  mqttjs:client _handleAck :: packet type +0ms suback
 DEBUG  mqttjs:client noop :: +0ms null
 DEBUG  mqttjs:client writable stream :: parsing buffer +3ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +1ms
 DEBUG  mqttjs:client work :: getting next packet in queue +0ms
 DEBUG  mqttjs:client work :: packet pulled from queue +0ms
 DEBUG  mqttjs:client _reschedulePing :: rescheduling ping +0ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +1ms
 DEBUG  mqttjs:client _handleAck :: packet type +0ms suback
 DEBUG  mqttjs:client noop :: +0ms null
 DEBUG  mqttjs:client writable stream :: parsing buffer +1s
 DEBUG  mqttjs:client parser :: on packet push to packets array. +1ms
 DEBUG  mqttjs:client work :: getting next packet in queue +1ms
 DEBUG  mqttjs:client work :: packet pulled from queue +0ms
 DEBUG  mqttjs:client _reschedulePing :: rescheduling ping +0ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +1ms
 DEBUG  mqttjs:client handlePublish: packet '{"cmd": "publish", "dup": false, "length": 863, "messageId": 1, "payload": {"data": [Array], "type": "Buffer"}, "properties": {"userProperties": {"cid": "1768230", "timestamp": "1702594243.638359", "token_id": "59212603"}}, "qos": 1, "retain": true, "topic": "test/topic"}' +0ms
 DEBUG  mqttjs:client handlePublish: qos 1 +18ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +2ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "puback", "messageId": 1, "reasonCode": 0}' +0ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +0ms
 DEBUG  mqttjs:client _writePacket :: writing to stream +0ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +0ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +1ms
 DEBUG  mqttjs:client _checkPing :: checking ping... +10s
 DEBUG  mqttjs:client _checkPing :: ping response received in time +0ms
 DEBUG  mqttjs:client _sendPing :: sending pingreq +1ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +0ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +0ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +1ms
 DEBUG  mqttjs:client _writePacket :: writing to stream +0ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result false +1ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +0ms
 DEBUG  mqttjs:client noop :: +1ms undefined
 DEBUG  mqttjs:client _checkPing :: checking ping... +10s
 DEBUG  mqttjs:client _checkPing :: ping response received in time +1ms
 DEBUG  mqttjs:client _sendPing :: sending pingreq +1ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +0ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +2ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +3ms
 DEBUG  mqttjs:client _writePacket :: writing to stream +1ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +0ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +1ms
 DEBUG  mqttjs:client noop :: +0ms undefined
 DEBUG  mqttjs:client writable stream :: parsing buffer +744ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +0ms
 DEBUG  mqttjs:client work :: getting next packet in queue +1ms
 DEBUG  mqttjs:client work :: packet pulled from queue +0ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +0ms
 DEBUG  mqttjs:client _checkPing :: checking ping... +10s
 ERROR  Error: Keepalive timeout, js engine: hermes
 DEBUG  mqttjs:client _checkPing :: checking ping... +9s
 DEBUG  mqttjs:client _checkPing :: ping response received in time +0ms
 DEBUG  mqttjs:client _sendPing :: sending pingreq +0ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +1ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +0ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +0ms
 DEBUG  mqttjs:client _writePacket :: writing to stream +1ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +0ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +0ms
 DEBUG  mqttjs:client noop :: +0ms undefined
 DEBUG  mqttjs:client writable stream :: parsing buffer +752ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +1ms
 DEBUG  mqttjs:client work :: getting next packet in queue +1ms
 DEBUG  mqttjs:client work :: packet pulled from queue +2ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +1ms
 DEBUG  mqttjs:client _checkPing :: checking ping... +9s
 DEBUG  mqttjs:client _checkPing :: ping response received in time +1ms
 DEBUG  mqttjs:client _sendPing :: sending pingreq +1ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +1ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +3ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +2ms
 DEBUG  mqttjs:client _writePacket :: writing to stream +0ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +1ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +1ms
 DEBUG  mqttjs:client noop :: +1ms undefined
 DEBUG  mqttjs:client writable stream :: parsing buffer +746ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +2ms
 DEBUG  mqttjs:client work :: getting next packet in queue +2ms
 DEBUG  mqttjs:client work :: packet pulled from queue +1ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +0ms
 DEBUG  mqttjs:client _checkPing :: checking ping... +9s
 DEBUG  mqttjs:client _checkPing :: ping response received in time +2ms
 DEBUG  mqttjs:client _sendPing :: sending pingreq +0ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +1ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +3ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +3ms
 DEBUG  mqttjs:client _writePacket :: writing to stream +1ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +1ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +2ms
 DEBUG  mqttjs:client noop :: +0ms undefined
 DEBUG  mqttjs:client writable stream :: parsing buffer +103ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +1ms
 DEBUG  mqttjs:client work :: getting next packet in queue +0ms
 DEBUG  mqttjs:client work :: packet pulled from queue +1ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +0ms
 DEBUG  mqttjs:client _checkPing :: checking ping... +10s
 DEBUG  mqttjs:client _checkPing :: ping response received in time +2ms
 DEBUG  mqttjs:client _sendPing :: sending pingreq +1ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +0ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +4ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +1ms
 DEBUG  mqttjs:client _writePacket :: writing to stream +2ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +1ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +1ms
 DEBUG  mqttjs:client noop :: +0ms undefined
 DEBUG  mqttjs:client writable stream :: parsing buffer +98ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +0ms
 DEBUG  mqttjs:client work :: getting next packet in queue +0ms
 DEBUG  mqttjs:client work :: packet pulled from queue +1ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +0ms
 DEBUG  mqttjs:client _checkPing :: checking ping... +10s
 DEBUG  mqttjs:client _checkPing :: ping response received in time +1ms
 DEBUG  mqttjs:client _sendPing :: sending pingreq +1ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +1ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +1ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +4ms
 DEBUG  mqttjs:client _writePacket :: writing to stream +1ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +0ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +1ms
 DEBUG  mqttjs:client noop :: +1ms undefined
 DEBUG  mqttjs:client writable stream :: parsing buffer +97ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +0ms
 DEBUG  mqttjs:client work :: getting next packet in queue +1ms
 DEBUG  mqttjs:client work :: packet pulled from queue +0ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +0ms
 DEBUG  mqttjs:client _checkPing :: checking ping... +10s
 DEBUG  mqttjs:client _checkPing :: ping response received in time +2ms
 DEBUG  mqttjs:client _sendPing :: sending pingreq +0ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +1ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +3ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +2ms
 DEBUG  mqttjs:client _writePacket :: writing to stream +1ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +1ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +1ms
 DEBUG  mqttjs:client noop :: +0ms undefined
 DEBUG  mqttjs:client writable stream :: parsing buffer +98ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +1ms
 DEBUG  mqttjs:client work :: getting next packet in queue +0ms
 DEBUG  mqttjs:client work :: packet pulled from queue +1ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +0ms
 DEBUG  mqttjs:client _checkPing :: checking ping... +10s
 DEBUG  mqttjs:client _checkPing :: ping response received in time +2ms
 DEBUG  mqttjs:client _sendPing :: sending pingreq +0ms
 DEBUG  mqttjs:client _sendPacket :: (mobile-app) ::  start +1ms
 DEBUG  mqttjs:client _writePacket :: packet: '{"cmd": "pingreq"}' +3ms
 DEBUG  mqttjs:client _writePacket :: emitting `packetsend` +2ms
 DEBUG  mqttjs:client _writePacket :: writing to stream +1ms
 DEBUG  mqttjs:client _writePacket :: writeToStream result true +1ms
 DEBUG  mqttjs:client _writePacket :: invoking cb +0ms
 DEBUG  mqttjs:client noop :: +1ms undefined
 DEBUG  mqttjs:client writable stream :: parsing buffer +715ms
 DEBUG  mqttjs:client parser :: on packet push to packets array. +2ms
 DEBUG  mqttjs:client work :: getting next packet in queue +0ms
 DEBUG  mqttjs:client work :: packet pulled from queue +3ms
 DEBUG  mqttjs:client _handlePacket :: emitting packetreceive +0ms

@robertsLando
Copy link
Member

robertsLando commented Apr 30, 2024

As I said above everything seems correct from mqtt side, the keepalive timeout error is triggered because no packet is received in the keepalive time, the only very strange thing is that the keepalive timeout doesn't trigger the close of client. You should debug this on your side if possible by putting breakpoints on mqttjs code and see where it breaks. Expecially in this line:

MQTT.js/src/lib/client.ts

Lines 2136 to 2137 in 0c72b5a

this.log('_checkPing :: calling _cleanUp with force true')
this._cleanUp(true)

The error here is it is not calling cleanUp

@robertsLando
Copy link
Member

Could you show me the code you have in client.on('error' ) listener?

@abdelhameedhamdy
Copy link
Contributor Author

abdelhameedhamdy commented Apr 30, 2024

Could you show me the code you have in client.on('error' ) listener?

const client = connect("mqtts://mqtt.flespi.io", mqttOptions);
client.on("error", (error) => {
        console.log(error);
      })

@robertsLando
Copy link
Member

My feel is that you do something there that stops the event loop and that's the reason why the cleanUp isn't called

@abdelhameedhamdy
Copy link
Contributor Author

My feel is that you do something there that stops the event loop and that's the reason why the cleanUp isn't called

So, because of the _cleanUp() is not called, the keepalive timeout error is uncaught !

@robertsLando
Copy link
Member

So, because of the _cleanUp() is not called, the keepalive timeout error is uncaught !

Nope, I didn't meant that. The keepalive timeout is uncaught because you may be doing something strange in the error listener...

@abdelhameedhamdy
Copy link
Contributor Author

Ok, I think I caught it, when re-connecting with the same clientid which is intended, I was not ending the connection manually as I was counting on that the connection will be auto-closed and connect, now I enforce the client to end before reconnecting, and no error appears now.
Though, I am not sure why this error is uncaught even if _cleanUp() is not called.

@abdelhameedhamdy
Copy link
Contributor Author

Thank you @robertsLando, the connection is stable now.

@robertsLando
Copy link
Member

I'm not sure I got what you meant here but generally the client should handle it's connection/reconnection itself without the need you manually end it or else but glad you fixed it

@abdelhameedhamdy
Copy link
Contributor Author

abdelhameedhamdy commented Apr 30, 2024

I'm not sure I got what you meant here but generally the client should handle it's connection/reconnection itself without the need you manually end it or else but glad you fixed it

It is two clients with same connection params, one for foreground and the the other for background mode, so they shares the same clientid when connecting (i.e. only one client at a time, not at the same time), and each one force the other to close automatically when trying to connect.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests

2 participants