search

Azure / azure-iot-sdk-node

A Node.js SDK for connecting devices to Microsoft Azure IoT services
https://docs.microsoft.com/en-us/azure/iot-hub/
Other
261 stars 227 forks source link

device disconnect after a few days(2 or 3 days) #990

Closed sunhubs closed 3 years ago

sunhubs commented 3 years ago

Context

Description of the issue

I use MQTT over websocket to start a device client, and listen on the disconnect event to do reconnect. The device can receive the message from cloud at the begning. But after a few days the connections seems to be closed because the message is not able to be received(I found after 3days, but the issue may happened a bit earlier as other issue reported). Now I just confirm the disconnect event is not fired, but not sure whether the error event is fired.(I am reproducing the issue and update the result if I catch it) I searched the issue and found there is no solution until close #340, and a case long ago say it has been fixed #12, but in fact it does not! I just want to know the reason and how to avoid such disconnection.

Code sample exhibiting the issue

this.client = Client.fromConnectionString(this.connection_string, MqttWs) this.client.open() this.client.on('disconnect', async () => { // reconnect })

Console log of the issue

Sorry I do not enable such debug currently. I will also try to reproduce and catch it.

sunhubs commented 3 years ago

i got a debug log as below: Jun 15 07:46:13 fake-sg-controller[117582] INFO: use http proxy for all external connections Jun 15 07:46:13 fake-sg-controller[117582] INFO: iot connection information: azure iot hub free-iot.azure-devices.net, device client id test-iot-device-2 2021-06-15T07:46:13.469Z azure-iot-mqtt-base:MqttBase In MQTT base FSM - entered onEnter for disconnect 2021-06-15T07:46:13.471Z azure-iot-common:RetryOperation Operation start time: 1623743173471 - Will stop retrying after: 1623743413471 2021-06-15T07:46:13.471Z azure-iot-device:DeviceClient in newListener, enabling C2D. 2021-06-15T07:46:13.471Z azure-iot-device:DeviceClient enabling C2D 2021-06-15T07:46:13.471Z azure-iot-common:RetryOperation Operation start time: 1623743173471 - Will stop retrying after: 1623743413471 2021-06-15T07:46:13.472Z azure-iot-device-mqtt:Mqtt disconnected -> connecting (disconnected.connect) 2021-06-15T07:46:13.474Z azure-iot-device-mqtt:Mqtt topic publish: devices/test-iot-device-2/messages/events/ 2021-06-15T07:46:13.474Z azure-iot-device-mqtt:Mqtt message topic subscribe: devices/test-iot-device-2/messages/devicebound/# 2021-06-15T07:46:13.474Z azure-iot-common:RetryOperation Operation start time: 1623743173474 - Will stop retrying after: 1623743413474 2021-06-15T07:46:13.494Z azure-iot-mqtt-base:MqttBase disconnected -> connecting (disconnected.connect) 2021-06-15T07:46:13.495Z azure-iot-mqtt-base:MqttBase username: free-iot.azure-devices.net/test-iot-device-2/?api-version=2020-09-30&DeviceClientType=azure-iot-device%2F1.17.3%20(node%20v14.17.0%3B%20CentOS%207.9.2009%3B%20x64) 2021-06-15T07:46:13.495Z azure-iot-mqtt-base:MqttBase uri: wss://free-iot.azure-devices.net:443/$iothub/websocket 2021-06-15T07:46:16.709Z azure-iot-mqtt-base:MqttBase Device is connected 2021-06-15T07:46:16.709Z azure-iot-mqtt-base:MqttBase CONNACK: {"cmd":"connack","retain":false,"qos":0,"dup":false,"length":2,"topic":null,"payload":null,"sessionPresent":true,"returnCode":0} 2021-06-15T07:46:16.710Z azure-iot-mqtt-base:MqttBase connecting -> connected () 2021-06-15T07:46:16.710Z azure-iot-device-mqtt:Mqtt connect 2021-06-15T07:46:16.710Z azure-iot-device-mqtt:Mqtt connecting -> connected () Jun 15 07:46:16 fake-sg-controller[117582] INFO: iot client test-iot-device-2 is connecting to azure IoT. 2021-06-15T07:46:16.710Z azure-iot-device-mqtt:Mqtt subscribe: {"name":"devices/test-iot-device-2/messages/devicebound/#","subscribeInProgress":false,"subscribed":false,"topicMatchRegex":{}} Jun 15 07:46:16 fake-sg-controller[117582] INFO: iot connection set up successfully 2021-06-15T07:46:16.983Z azure-iot-device:DeviceClient enabled C2D 2021-06-15T07:46:16.983Z azure-iot-device:DeviceClient in newListener, successfully enabled C2D 2021-06-15T08:31:13.587Z azure-iot-mqtt-base:MqttBase connected -> reconnecting (connected.updateSharedAccessSignature) 2021-06-15T08:31:13.636Z azure-iot-mqtt-base:MqttBase disconnecting mqtt client 2021-06-15T08:31:13.636Z azure-iot-mqtt-base:MqttBase removing all listeners 2021-06-15T08:31:13.637Z azure-iot-mqtt-base:MqttBase adding null error listener 2021-06-15T08:31:19.068Z azure-iot-mqtt-base:MqttBase mqtt client disconnected - reconnecting 2021-06-15T08:31:19.068Z azure-iot-mqtt-base:MqttBase username: free-iot.azure-devices.net/test-iot-device-2/?api-version=2020-09-30&DeviceClientType=azure-iot-device%2F1.17.3%20(node%20v14.17.0%3B%20CentOS%207.9.2009%3B%20x64) 2021-06-15T08:31:19.069Z azure-iot-mqtt-base:MqttBase uri: wss://free-iot.azure-devices.net:443/$iothub/websocket 2021-06-15T08:31:22.447Z azure-iot-mqtt-base:MqttBase Device is connected 2021-06-15T08:31:22.458Z azure-iot-mqtt-base:MqttBase CONNACK: {"cmd":"connack","retain":false,"qos":0,"dup":false,"length":2,"topic":null,"payload":null,"sessionPresent":true,"returnCode":0} 2021-06-15T08:31:22.458Z azure-iot-mqtt-base:MqttBase mqtt client reconnected successfully 2021-06-15T08:31:22.458Z azure-iot-mqtt-base:MqttBase reconnecting -> connected () 2021-06-15T09:16:13.675Z azure-iot-mqtt-base:MqttBase connected -> reconnecting (connected.updateSharedAccessSignature) 2021-06-15T09:16:13.892Z azure-iot-mqtt-base:MqttBase disconnecting mqtt client 2021-06-15T09:16:13.892Z azure-iot-mqtt-base:MqttBase removing all listeners 2021-06-15T09:16:13.892Z azure-iot-mqtt-base:MqttBase adding null error listener 2021-06-15T09:16:19.160Z azure-iot-mqtt-base:MqttBase mqtt client disconnected - reconnecting 2021-06-15T09:16:19.160Z azure-iot-mqtt-base:MqttBase username: free-iot.azure-devices.net/test-iot-device-2/?api-version=2020-09-30&DeviceClientType=azure-iot-device%2F1.17.3%20(node%20v14.17.0%3B%20CentOS%207.9.2009%3B%20x64) 2021-06-15T09:16:19.161Z azure-iot-mqtt-base:MqttBase uri: wss://free-iot.azure-devices.net:443/$iothub/websocket 2021-06-15T09:16:22.464Z azure-iot-mqtt-base:MqttBase Device is connected 2021-06-15T09:16:22.464Z azure-iot-mqtt-base:MqttBase CONNACK: {"cmd":"connack","retain":false,"qos":0,"dup":false,"length":2,"topic":null,"payload":null,"sessionPresent":true,"returnCode":0} 2021-06-15T09:16:22.464Z azure-iot-mqtt-base:MqttBase mqtt client reconnected successfully 2021-06-15T09:16:22.464Z azure-iot-mqtt-base:MqttBase reconnecting -> connected () 2021-06-15T10:01:13.860Z azure-iot-mqtt-base:MqttBase connected -> reconnecting (connected.updateSharedAccessSignature) 2021-06-15T10:01:13.878Z azure-iot-mqtt-base:MqttBase disconnecting mqtt client 2021-06-15T10:01:13.879Z azure-iot-mqtt-base:MqttBase removing all listeners 2021-06-15T10:01:13.879Z azure-iot-mqtt-base:MqttBase adding null error listener 2021-06-15T10:01:19.140Z azure-iot-mqtt-base:MqttBase mqtt client disconnected - reconnecting 2021-06-15T10:01:19.140Z azure-iot-mqtt-base:MqttBase username: free-iot.azure-devices.net/test-iot-device-2/?api-version=2020-09-30&DeviceClientType=azure-iot-device%2F1.17.3%20(node%20v14.17.0%3B%20CentOS%207.9.2009%3B%20x64) 2021-06-15T10:01:19.140Z azure-iot-mqtt-base:MqttBase uri: wss://free-iot.azure-devices.net:443/$iothub/websocket 2021-06-15T10:01:22.466Z azure-iot-mqtt-base:MqttBase Device is connected 2021-06-15T10:01:22.466Z azure-iot-mqtt-base:MqttBase CONNACK: {"cmd":"connack","retain":false,"qos":0,"dup":false,"length":2,"topic":null,"payload":null,"sessionPresent":true,"returnCode":0} 2021-06-15T10:01:22.466Z azure-iot-mqtt-base:MqttBase mqtt client reconnected successfully 2021-06-15T10:01:22.466Z azure-iot-mqtt-base:MqttBase reconnecting -> connected () 2021-06-15T10:46:14.627Z azure-iot-mqtt-base:MqttBase connected -> reconnecting (connected.updateSharedAccessSignature) 2021-06-15T10:46:14.797Z azure-iot-mqtt-base:MqttBase disconnecting mqtt client 2021-06-15T10:46:14.797Z azure-iot-mqtt-base:MqttBase removing all listeners 2021-06-15T10:46:14.797Z azure-iot-mqtt-base:MqttBase adding null error listener 2021-06-15T10:46:20.210Z azure-iot-mqtt-base:MqttBase mqtt client disconnected - reconnecting 2021-06-15T10:46:20.210Z azure-iot-mqtt-base:MqttBase username: free-iot.azure-devices.net/test-iot-device-2/?api-version=2020-09-30&DeviceClientType=azure-iot-device%2F1.17.3%20(node%20v14.17.0%3B%20CentOS%207.9.2009%3B%20x64) 2021-06-15T10:46:20.210Z azure-iot-mqtt-base:MqttBase uri: wss://free-iot.azure-devices.net:443/$iothub/websocket 2021-06-15T10:46:24.833Z azure-iot-mqtt-base:MqttBase Device is connected 2021-06-15T10:46:24.833Z azure-iot-mqtt-base:MqttBase CONNACK: {"cmd":"connack","retain":false,"qos":0,"dup":false,"length":2,"topic":null,"payload":null,"sessionPresent":true,"returnCode":0} 2021-06-15T10:46:24.833Z azure-iot-mqtt-base:MqttBase mqtt client reconnected successfully 2021-06-15T10:46:24.833Z azure-iot-mqtt-base:MqttBase reconnecting -> connected () 2021-06-15T11:31:14.776Z azure-iot-mqtt-base:MqttBase connected -> reconnecting (connected.updateSharedAccessSignature) 2021-06-15T11:31:14.779Z azure-iot-mqtt-base:MqttBase disconnecting mqtt client 2021-06-15T11:31:14.779Z azure-iot-mqtt-base:MqttBase removing all listeners 2021-06-15T11:31:14.779Z azure-iot-mqtt-base:MqttBase adding null error listener 2021-06-15T11:31:20.032Z azure-iot-mqtt-base:MqttBase mqtt client disconnected - reconnecting 2021-06-15T11:31:20.032Z azure-iot-mqtt-base:MqttBase username: free-iot.azure-devices.net/test-iot-device-2/?api-version=2020-09-30&DeviceClientType=azure-iot-device%2F1.17.3%20(node%20v14.17.0%3B%20CentOS%207.9.2009%3B%20x64) 2021-06-15T11:31:20.032Z azure-iot-mqtt-base:MqttBase uri: wss://free-iot.azure-devices.net:443/$iothub/websocket 2021-06-15T11:31:23.041Z azure-iot-mqtt-base:MqttBase Device is connected 2021-06-15T11:31:23.041Z azure-iot-mqtt-base:MqttBase CONNACK: {"cmd":"connack","retain":false,"qos":0,"dup":false,"length":2,"topic":null,"payload":null,"sessionPresent":true,"returnCode":0} 2021-06-15T11:31:23.041Z azure-iot-mqtt-base:MqttBase mqtt client reconnected successfully 2021-06-15T11:31:23.041Z azure-iot-mqtt-base:MqttBase reconnecting -> connected () 2021-06-15T12:16:14.825Z azure-iot-mqtt-base:MqttBase connected -> reconnecting (connected.updateSharedAccessSignature) 2021-06-15T12:16:14.826Z azure-iot-mqtt-base:MqttBase disconnecting mqtt client 2021-06-15T12:16:14.826Z azure-iot-mqtt-base:MqttBase removing all listeners 2021-06-15T12:16:14.826Z azure-iot-mqtt-base:MqttBase adding null error listener 2021-06-15T12:16:20.080Z azure-iot-mqtt-base:MqttBase mqtt client disconnected - reconnecting 2021-06-15T12:16:20.080Z azure-iot-mqtt-base:MqttBase username: free-iot.azure-devices.net/test-iot-device-2/?api-version=2020-09-30&DeviceClientType=azure-iot-device%2F1.17.3%20(node%20v14.17.0%3B%20CentOS%207.9.2009%3B%20x64) 2021-06-15T12:16:20.080Z azure-iot-mqtt-base:MqttBase uri: wss://free-iot.azure-devices.net:443/$iothub/websocket 2021-06-15T12:16:23.515Z azure-iot-mqtt-base:MqttBase Device is connected 2021-06-15T12:16:23.515Z azure-iot-mqtt-base:MqttBase CONNACK: {"cmd":"connack","retain":false,"qos":0,"dup":false,"length":2,"topic":null,"payload":null,"sessionPresent":true,"returnCode":0} 2021-06-15T12:16:23.515Z azure-iot-mqtt-base:MqttBase mqtt client reconnected successfully 2021-06-15T12:16:23.515Z azure-iot-mqtt-base:MqttBase reconnecting -> connected () 2021-06-15T13:01:14.929Z azure-iot-mqtt-base:MqttBase connected -> reconnecting (connected.updateSharedAccessSignature) 2021-06-15T13:01:14.957Z azure-iot-mqtt-base:MqttBase disconnecting mqtt client 2021-06-15T13:01:14.960Z azure-iot-mqtt-base:MqttBase removing all listeners 2021-06-15T13:01:14.960Z azure-iot-mqtt-base:MqttBase adding null error listener 2021-06-15T13:01:20.213Z azure-iot-mqtt-base:MqttBase mqtt client disconnected - reconnecting 2021-06-15T13:01:20.213Z azure-iot-mqtt-base:MqttBase username: free-iot.azure-devices.net/test-iot-device-2/?api-version=2020-09-30&DeviceClientType=azure-iot-device%2F1.17.3%20(node%20v14.17.0%3B%20CentOS%207.9.2009%3B%20x64) 2021-06-15T13:01:20.213Z azure-iot-mqtt-base:MqttBase uri: wss://free-iot.azure-devices.net:443/$iothub/websocket 2021-06-15T13:01:23.223Z azure-iot-mqtt-base:MqttBase Device is connected 2021-06-15T13:01:23.223Z azure-iot-mqtt-base:MqttBase CONNACK: {"cmd":"connack","retain":false,"qos":0,"dup":false,"length":2,"topic":null,"payload":null,"sessionPresent":true,"returnCode":0} 2021-06-15T13:01:23.223Z azure-iot-mqtt-base:MqttBase mqtt client reconnected successfully 2021-06-15T13:01:23.223Z azure-iot-mqtt-base:MqttBase reconnecting -> connected () 2021-06-15T13:46:15.148Z azure-iot-mqtt-base:MqttBase connected -> reconnecting (connected.updateSharedAccessSignature) 2021-06-15T13:46:15.168Z azure-iot-mqtt-base:MqttBase disconnecting mqtt client 2021-06-15T13:46:15.169Z azure-iot-mqtt-base:MqttBase removing all listeners 2021-06-15T13:46:15.169Z azure-iot-mqtt-base:MqttBase adding null error listener 2021-06-15T13:46:20.494Z azure-iot-mqtt-base:MqttBase mqtt client disconnected - reconnecting 2021-06-15T13:46:20.494Z azure-iot-mqtt-base:MqttBase username: free-iot.azure-devices.net/test-iot-device-2/?api-version=2020-09-30&DeviceClientType=azure-iot-device%2F1.17.3%20(node%20v14.17.0%3B%20CentOS%207.9.2009%3B%20x64) 2021-06-15T13:46:20.494Z azure-iot-mqtt-base:MqttBase uri: wss://free-iot.azure-devices.net:443/$iothub/websocket 2021-06-15T13:46:23.784Z azure-iot-mqtt-base:MqttBase Device is connected 2021-06-15T13:46:23.784Z azure-iot-mqtt-base:MqttBase CONNACK: {"cmd":"connack","retain":false,"qos":0,"dup":false,"length":2,"topic":null,"payload":null,"sessionPresent":true,"returnCode":0} 2021-06-15T13:46:23.784Z azure-iot-mqtt-base:MqttBase mqtt client reconnected successfully 2021-06-15T13:46:23.784Z azure-iot-mqtt-base:MqttBase reconnecting -> connected () 2021-06-15T14:31:15.383Z azure-iot-mqtt-base:MqttBase connected -> reconnecting (connected.updateSharedAccessSignature) 2021-06-15T14:31:15.387Z azure-iot-mqtt-base:MqttBase disconnecting mqtt client 2021-06-15T14:31:15.387Z azure-iot-mqtt-base:MqttBase removing all listeners 2021-06-15T14:31:15.387Z azure-iot-mqtt-base:MqttBase adding null error listener 2021-06-15T14:31:20.828Z azure-iot-mqtt-base:MqttBase mqtt client disconnected - reconnecting 2021-06-15T14:31:20.828Z azure-iot-mqtt-base:MqttBase username: free-iot.azure-devices.net/test-iot-device-2/?api-version=2020-09-30&DeviceClientType=azure-iot-device%2F1.17.3%20(node%20v14.17.0%3B%20CentOS%207.9.2009%3B%20x64) 2021-06-15T14:31:20.828Z azure-iot-mqtt-base:MqttBase uri: wss://free-iot.azure-devices.net:443/$iothub/websocket 2021-06-15T14:31:23.897Z azure-iot-mqtt-base:MqttBase Device is connected 2021-06-15T14:31:23.897Z azure-iot-mqtt-base:MqttBase CONNACK: {"cmd":"connack","retain":false,"qos":0,"dup":false,"length":2,"topic":null,"payload":null,"sessionPresent":true,"returnCode":0} 2021-06-15T14:31:23.897Z azure-iot-mqtt-base:MqttBase mqtt client reconnected successfully 2021-06-15T14:31:23.898Z azure-iot-mqtt-base:MqttBase reconnecting -> connected () 2021-06-15T15:16:15.540Z azure-iot-mqtt-base:MqttBase connected -> reconnecting (connected.updateSharedAccessSignature) 2021-06-15T15:16:15.540Z azure-iot-mqtt-base:MqttBase disconnecting mqtt client 2021-06-15T15:16:15.540Z azure-iot-mqtt-base:MqttBase removing all listeners 2021-06-15T15:16:15.540Z azure-iot-mqtt-base:MqttBase adding null error listener 2021-06-15T15:16:20.802Z azure-iot-mqtt-base:MqttBase mqtt client disconnected - reconnecting 2021-06-15T15:16:20.802Z azure-iot-mqtt-base:MqttBase username: free-iot.azure-devices.net/test-iot-device-2/?api-version=2020-09-30&DeviceClientType=azure-iot-device%2F1.17.3%20(node%20v14.17.0%3B%20CentOS%207.9.2009%3B%20x64) 2021-06-15T15:16:20.802Z azure-iot-mqtt-base:MqttBase uri: wss://free-iot.azure-devices.net:443/$iothub/websocket 2021-06-15T15:16:24.011Z azure-iot-mqtt-base:MqttBase Device is connected 2021-06-15T15:16:24.011Z azure-iot-mqtt-base:MqttBase CONNACK: {"cmd":"connack","retain":false,"qos":0,"dup":false,"length":2,"topic":null,"payload":null,"sessionPresent":true,"returnCode":0} 2021-06-15T15:16:24.011Z azure-iot-mqtt-base:MqttBase mqtt client reconnected successfully 2021-06-15T15:16:24.011Z azure-iot-mqtt-base:MqttBase reconnecting -> connected () 2021-06-15T16:01:15.642Z azure-iot-mqtt-base:MqttBase connected -> reconnecting (connected.updateSharedAccessSignature) 2021-06-15T16:01:15.701Z azure-iot-mqtt-base:MqttBase disconnecting mqtt client 2021-06-15T16:01:15.701Z azure-iot-mqtt-base:MqttBase removing all listeners 2021-06-15T16:01:15.701Z azure-iot-mqtt-base:MqttBase adding null error listener 2021-06-15T16:01:20.953Z azure-iot-mqtt-base:MqttBase mqtt client disconnected - reconnecting 2021-06-15T16:01:20.953Z azure-iot-mqtt-base:MqttBase username: free-iot.azure-devices.net/test-iot-device-2/?api-version=2020-09-30&DeviceClientType=azure-iot-device%2F1.17.3%20(node%20v14.17.0%3B%20CentOS%207.9.2009%3B%20x64) 2021-06-15T16:01:20.953Z azure-iot-mqtt-base:MqttBase uri: wss://free-iot.azure-devices.net:443/$iothub/websocket 2021-06-15T16:01:24.290Z azure-iot-mqtt-base:MqttBase Device is connected 2021-06-15T16:01:24.290Z azure-iot-mqtt-base:MqttBase CONNACK: {"cmd":"connack","retain":false,"qos":0,"dup":false,"length":2,"topic":null,"payload":null,"sessionPresent":true,"returnCode":0} 2021-06-15T16:01:24.290Z azure-iot-mqtt-base:MqttBase mqtt client reconnected successfully 2021-06-15T16:01:24.290Z azure-iot-mqtt-base:MqttBase reconnecting -> connected () 2021-06-15T16:46:15.742Z azure-iot-mqtt-base:MqttBase connected -> reconnecting (connected.updateSharedAccessSignature) 2021-06-15T16:46:15.764Z azure-iot-mqtt-base:MqttBase disconnecting mqtt client 2021-06-15T16:46:15.764Z azure-iot-mqtt-base:MqttBase removing all listeners 2021-06-15T16:46:15.764Z azure-iot-mqtt-base:MqttBase adding null error listener 2021-06-15T16:46:21.004Z azure-iot-mqtt-base:MqttBase mqtt client disconnected - reconnecting 2021-06-15T16:46:21.004Z azure-iot-mqtt-base:MqttBase username: free-iot.azure-devices.net/test-iot-device-2/?api-version=2020-09-30&DeviceClientType=azure-iot-device%2F1.17.3%20(node%20v14.17.0%3B%20CentOS%207.9.2009%3B%20x64) 2021-06-15T16:46:21.004Z azure-iot-mqtt-base:MqttBase uri: wss://free-iot.azure-devices.net:443/$iothub/websocket 2021-06-15T16:46:24.094Z azure-iot-mqtt-base:MqttBase Device is connected 2021-06-15T16:46:24.094Z azure-iot-mqtt-base:MqttBase CONNACK: {"cmd":"connack","retain":false,"qos":0,"dup":false,"length":2,"topic":null,"payload":null,"sessionPresent":true,"returnCode":0} 2021-06-15T16:46:24.094Z azure-iot-mqtt-base:MqttBase mqtt client reconnected successfully 2021-06-15T16:46:24.183Z azure-iot-mqtt-base:MqttBase reconnecting -> connected () 2021-06-15T17:31:15.843Z azure-iot-mqtt-base:MqttBase connected -> reconnecting (connected.updateSharedAccessSignature) 2021-06-15T17:31:15.901Z azure-iot-mqtt-base:MqttBase disconnecting mqtt client 2021-06-15T17:31:15.901Z azure-iot-mqtt-base:MqttBase removing all listeners 2021-06-15T17:31:15.901Z azure-iot-mqtt-base:MqttBase adding null error listener 2021-06-15T17:31:21.159Z azure-iot-mqtt-base:MqttBase mqtt client disconnected - reconnecting 2021-06-15T17:31:21.159Z azure-iot-mqtt-base:MqttBase username: free-iot.azure-devices.net/test-iot-device-2/?api-version=2020-09-30&DeviceClientType=azure-iot-device%2F1.17.3%20(node%20v14.17.0%3B%20CentOS%207.9.2009%3B%20x64) 2021-06-15T17:31:21.159Z azure-iot-mqtt-base:MqttBase uri: wss://free-iot.azure-devices.net:443/$iothub/websocket 2021-06-15T17:31:24.198Z azure-iot-mqtt-base:MqttBase Device is connected 2021-06-15T17:31:24.198Z azure-iot-mqtt-base:MqttBase CONNACK: {"cmd":"connack","retain":false,"qos":0,"dup":false,"length":2,"topic":null,"payload":null,"sessionPresent":true,"returnCode":0} 2021-06-15T17:31:24.198Z azure-iot-mqtt-base:MqttBase mqtt client reconnected successfully 2021-06-15T17:31:24.198Z azure-iot-mqtt-base:MqttBase reconnecting -> connected () 2021-06-15T18:16:15.943Z azure-iot-mqtt-base:MqttBase connected -> reconnecting (connected.updateSharedAccessSignature) 2021-06-15T18:16:15.943Z azure-iot-mqtt-base:MqttBase disconnecting mqtt client 2021-06-15T18:16:15.943Z azure-iot-mqtt-base:MqttBase removing all listeners 2021-06-15T18:16:15.943Z azure-iot-mqtt-base:MqttBase adding null error listener 2021-06-15T18:16:21.191Z azure-iot-mqtt-base:MqttBase mqtt client disconnected - reconnecting 2021-06-15T18:16:21.191Z azure-iot-mqtt-base:MqttBase username: free-iot.azure-devices.net/test-iot-device-2/?api-version=2020-09-30&DeviceClientType=azure-iot-device%2F1.17.3%20(node%20v14.17.0%3B%20CentOS%207.9.2009%3B%20x64) 2021-06-15T18:16:21.191Z azure-iot-mqtt-base:MqttBase uri: wss://free-iot.azure-devices.net:443/$iothub/websocket 2021-06-15T18:16:24.291Z azure-iot-mqtt-base:MqttBase Device is connected 2021-06-15T18:16:24.291Z azure-iot-mqtt-base:MqttBase CONNACK: {"cmd":"connack","retain":false,"qos":0,"dup":false,"length":2,"topic":null,"payload":null,"sessionPresent":true,"returnCode":0} 2021-06-15T18:16:24.291Z azure-iot-mqtt-base:MqttBase mqtt client reconnected successfully 2021-06-15T18:16:24.291Z azure-iot-mqtt-base:MqttBase reconnecting -> connected () 2021-06-15T19:01:16.042Z azure-iot-mqtt-base:MqttBase connected -> reconnecting (connected.updateSharedAccessSignature) 2021-06-15T19:01:16.076Z azure-iot-mqtt-base:MqttBase disconnecting mqtt client 2021-06-15T19:01:16.076Z azure-iot-mqtt-base:MqttBase removing all listeners 2021-06-15T19:01:16.076Z azure-iot-mqtt-base:MqttBase adding null error listener 2021-06-15T19:01:21.319Z azure-iot-mqtt-base:MqttBase mqtt client disconnected - reconnecting 2021-06-15T19:01:21.320Z azure-iot-mqtt-base:MqttBase username: free-iot.azure-devices.net/test-iot-device-2/?api-version=2020-09-30&DeviceClientType=azure-iot-device%2F1.17.3%20(node%20v14.17.0%3B%20CentOS%207.9.2009%3B%20x64) 2021-06-15T19:01:21.320Z azure-iot-mqtt-base:MqttBase uri: wss://free-iot.azure-devices.net:443/$iothub/websocket 2021-06-15T19:01:25.576Z azure-iot-mqtt-base:MqttBase Device is connected 2021-06-15T19:01:25.577Z azure-iot-mqtt-base:MqttBase CONNACK: {"cmd":"connack","retain":false,"qos":0,"dup":false,"length":2,"topic":null,"payload":null,"sessionPresent":true,"returnCode":0} 2021-06-15T19:01:25.577Z azure-iot-mqtt-base:MqttBase mqtt client reconnected successfully 2021-06-15T19:01:25.577Z azure-iot-mqtt-base:MqttBase reconnecting -> connected () 2021-06-15T19:46:16.162Z azure-iot-mqtt-base:MqttBase connected -> reconnecting (connected.updateSharedAccessSignature) 2021-06-15T19:46:16.188Z azure-iot-mqtt-base:MqttBase disconnecting mqtt client 2021-06-15T19:46:16.188Z azure-iot-mqtt-base:MqttBase removing all listeners 2021-06-15T19:46:16.188Z azure-iot-mqtt-base:MqttBase adding null error listener 2021-06-15T19:46:21.441Z azure-iot-mqtt-base:MqttBase mqtt client disconnected - reconnecting 2021-06-15T19:46:21.441Z azure-iot-mqtt-base:MqttBase username: free-iot.azure-devices.net/test-iot-device-2/?api-version=2020-09-30&DeviceClientType=azure-iot-device%2F1.17.3%20(node%20v14.17.0%3B%20CentOS%207.9.2009%3B%20x64) 2021-06-15T19:46:21.441Z azure-iot-mqtt-base:MqttBase uri: wss://free-iot.azure-devices.net:443/$iothub/websocket 2021-06-15T19:46:24.532Z azure-iot-mqtt-base:MqttBase Device is connected 2021-06-15T19:46:24.532Z azure-iot-mqtt-base:MqttBase CONNACK: {"cmd":"connack","retain":false,"qos":0,"dup":false,"length":2,"topic":null,"payload":null,"sessionPresent":true,"returnCode":0} 2021-06-15T19:46:24.532Z azure-iot-mqtt-base:MqttBase mqtt client reconnected successfully 2021-06-15T19:46:24.532Z azure-iot-mqtt-base:MqttBase reconnecting -> connected () 2021-06-15T20:13:25.772Z azure-iot-mqtt-base:MqttBase In base mqtt - close event received from mqtt.js client - no error 2021-06-15T20:13:25.786Z azure-iot-mqtt-base:MqttBase connected -> disconnected (connected.closeEvent) 2021-06-15T20:13:25.786Z azure-iot-mqtt-base:MqttBase In MQTT base FSM - entered onEnter for disconnect 2021-06-15T20:13:25.786Z azure-iot-mqtt-base:MqttBase In mqtt base - no callback for error - emitting 'error': NotConnectedError 2021-06-15T20:13:25.786Z azure-iot-device-mqtt:Mqtt on close 2021-06-15T20:13:25.787Z azure-iot-device-mqtt:Mqtt connected -> disconnecting (connected.disconnect) 2021-06-15T20:13:25.794Z azure-iot-device-mqtt:Mqtt disconnecting -> disconnected (connected.disconnect) 2021-06-15T20:13:25.816Z azure-iot-device:InternalClient transport disconnect event: NotConnectedError: Connection to the server has been closed. Jun 15 20:13:25 fake-sg-controller[117582] ERROR: iot client test-iot-device-2 connection is down. will reconnect 2021-06-15T20:13:26.036Z azure-iot-device:DeviceClient transport disconnect event: NotConnectedError: Connection to the server has been closed. 2021-06-15T20:13:26.037Z azure-iot-common:RetryOperation Operation start time: 1623788006037 - Will stop retrying after: 1623788246037 2021-06-15T20:13:26.037Z azure-iot-device-mqtt:Mqtt disconnected -> connecting (disconnected.connect) 2021-06-15T20:13:26.045Z azure-iot-device-mqtt:Mqtt topic publish: devices/test-iot-device-2/messages/events/ 2021-06-15T20:13:26.057Z azure-iot-device-mqtt:Mqtt message topic subscribe: devices/test-iot-device-2/messages/devicebound/# 2021-06-15T20:13:26.057Z azure-iot-mqtt-base:MqttBase disconnected -> connecting (disconnected.connect) 2021-06-15T20:13:26.057Z azure-iot-mqtt-base:MqttBase username: free-iot.azure-devices.net/test-iot-device-2/?api-version=2020-09-30&DeviceClientType=azure-iot-device%2F1.17.3%20(node%20v14.17.0%3B%20CentOS%207.9.2009%3B%20x64) 2021-06-15T20:13:26.057Z azure-iot-mqtt-base:MqttBase uri: wss://free-iot.azure-devices.net:443/$iothub/websocket 2021-06-15T20:13:29.057Z azure-iot-mqtt-base:MqttBase Device is connected 2021-06-15T20:13:29.057Z azure-iot-mqtt-base:MqttBase CONNACK: {"cmd":"connack","retain":false,"qos":0,"dup":false,"length":2,"topic":null,"payload":null,"sessionPresent":true,"returnCode":0} 2021-06-15T20:13:29.057Z azure-iot-mqtt-base:MqttBase connecting -> connected () 2021-06-15T20:13:29.057Z azure-iot-device-mqtt:Mqtt connect 2021-06-15T20:13:29.057Z azure-iot-device-mqtt:Mqtt connecting -> connected () Jun 15 20:13:29 fake-sg-controller[117582] INFO: iot client test-iot-device-2 is connecting to azure IoT. Jun 15 20:13:29 fake-sg-controller[117582] INFO: iot connection set up successfully 2021-06-15T20:22:29.327Z azure-iot-mqtt-base:MqttBase In base mqtt - close event received from mqtt.js client - no error 2021-06-15T20:22:29.327Z azure-iot-mqtt-base:MqttBase connected -> disconnected (connected.closeEvent) 2021-06-15T20:22:29.327Z azure-iot-mqtt-base:MqttBase In MQTT base FSM - entered onEnter for disconnect 2021-06-15T20:22:29.327Z azure-iot-mqtt-base:MqttBase In mqtt base - no callback for error - emitting 'error': NotConnectedError 2021-06-15T20:22:29.327Z azure-iot-device-mqtt:Mqtt on close 2021-06-15T20:22:29.327Z azure-iot-device-mqtt:Mqtt connected -> disconnecting (connected.disconnect) 2021-06-15T20:22:29.327Z azure-iot-device-mqtt:Mqtt disconnecting -> disconnected (connected.disconnect)

sunhubs commented 3 years ago

As seen above, I can see that: 1, before the client detect a disconnect event, the client do reconnect "connected -> reconnecting" for 16 times, but then " azure-iot-mqtt-base:MqttBase In base mqtt - close event received from mqtt.js client - no error" and the disconnect event was captched by the listener. (the total duration is 45 minutes * 16=12 hours) 2, then the manual reconnect process successed "2021-06-15T20:13:29.057Z azure-iot-device-mqtt:Mqtt connecting -> connected ()" but unfornately another close event received "azure-iot-mqtt-base:MqttBase In base mqtt - close event received from mqtt.js client - no error" but following disconnect event was not captured by the listener, which cut the chance to do manual reconnect.

actually i want to know: 1, what will cause "azure-iot-mqtt-base:MqttBase In base mqtt - close event received from mqtt.js client - no error" ? 2, why the final disconnect was not captured by listener?

anthonyvercolano commented 3 years ago

Mqtt doesn't have a built in way to send error information back in message traffic. The Hub itself is a bit, terse itself with MQTT traffic.

So an abrupt close like that could happen if the device side application has requested an operation in an incorrect manner. The hub will just close on you.

Additionally, sometimes due to high loads on the back end the hub might decide to move the connection to a different "partition" (set of servers). When it does that with MQTT you won't anything other than the close.

As for your second question, do you see an 'error' event at all? Be that as it may, what fix you see back in issue #12 seems to have been changed. (By me perhaps?). We seem to have had some changes in the repo where I can't find when this change actually occurred.

Does this happen enough so that if we (or even you) changed the code to emit a disconnect, does that help?

YoDaMa commented 3 years ago

@sunhubs thanks for your patience. To add onto @anthonyvercolano's comments, it would be helpful to see the debug logs out of MQTT.js. You could do this by adding "mqttjs*" to your DEBUG environment variable.

sunhubs commented 3 years ago

Mqtt doesn't have a built in way to send error information back in message traffic. The Hub itself is a bit, terse itself with MQTT traffic.

So an abrupt close like that could happen if the device side application has requested an operation in an incorrect manner. The hub will just close on you.

Additionally, sometimes due to high loads on the back end the hub might decide to move the connection to a different "partition" (set of servers). When it does that with MQTT you won't anything other than the close.

As for your second question, do you see an 'error' event at all? Be that as it may, what fix you see back in issue #12 seems to have been changed. (By me perhaps?). We seem to have had some changes in the repo where I can't find when this change actually occurred.

Does this happen enough so that if we (or even you) changed the code to emit a disconnect, does that help?

@anthonyvercolano as i said, the first disconnect event was able to be captured, but following disconnect, which lead to a stop is not, I am not sure it is because the disconnect event is not emit, or the event is not captured by the client.

@YoDaMa i will collect the information as soon as possible

YoDaMa commented 3 years ago

@sunhubs great. right now with the logs given it is too opaque for me to make any judgements on the situation.

sunhubs commented 3 years ago

2021-06-24T19:41:04.252Z azure-iot-mqtt-base:MqttBase disconnecting mqtt client 2021-06-24T19:41:04.252Z azure-iot-mqtt-base:MqttBase removing all listeners 2021-06-24T19:41:04.252Z azure-iot-mqtt-base:MqttBase adding null error listener 2021-06-24T19:41:04.252Z mqttjs:client end :: () 2021-06-24T19:41:04.252Z mqttjs:client end :: cb? true 2021-06-24T19:41:04.252Z mqttjs:client _clearReconnect : clearing reconnect timer 2021-06-24T19:41:04.252Z mqttjs:client end :: () :: immediately calling finish 2021-06-24T19:41:04.252Z mqttjs:client end :: () :: finish :: calling _cleanUp with force false 2021-06-24T19:41:04.252Z mqttjs:client _cleanUp :: done callback provided for on stream close 2021-06-24T19:41:04.252Z mqttjs:client _cleanUp :: forced? false 2021-06-24T19:41:04.252Z mqttjs:client _cleanUp :: () :: call _sendPacket with disconnect packet 2021-06-24T19:41:04.252Z mqttjs:client _sendPacket :: () :: start 2021-06-24T19:41:04.252Z mqttjs:client sendPacket :: packet: { cmd: 'disconnect' } 2021-06-24T19:41:04.252Z mqttjs:client sendPacket :: emitting packetsend 2021-06-24T19:41:04.252Z mqttjs:client sendPacket :: writing to stream 2021-06-24T19:41:04.252Z mqttjs:client sendPacket :: writeToStream result true 2021-06-24T19:41:04.252Z mqttjs:client sendPacket :: invoking cb 2021-06-24T19:41:04.252Z mqttjs:client _cleanUp :: clearing pingTimer 2021-06-24T19:41:09.490Z mqttjs:client ()stream :: on close 2021-06-24T19:41:09.490Z mqttjs:client flushVolatile :: deleting volatile messages from the queue and setting their callbacks as error function 2021-06-24T19:41:09.490Z mqttjs:client stream: emit close to MqttClient 2021-06-24T19:41:09.490Z mqttjs:client end :: finish :: calling process.nextTick on closeStores 2021-06-24T19:41:09.490Z mqttjs:client end :: closeStores: closing incoming and outgoing stores 2021-06-24T19:41:09.490Z mqttjs:client end :: closeStores: emitting end 2021-06-24T19:41:09.490Z mqttjs:client end :: closeStores: invoking callback with args 2021-06-24T19:41:09.490Z azure-iot-mqtt-base:MqttBase mqtt client disconnected - reconnecting 2021-06-24T19:41:09.490Z azure-iot-mqtt-base:MqttBase username: .azure-devices.net//?api-version=2020-09-30&DeviceClientType=azure-iot-device%2F1.17.3%20(node%20v16.3.0%3B%20Windows_NT%2010.0.18362%3B%20x64) 2021-06-24T19:41:09.490Z azure-iot-mqtt-base:MqttBase uri: wss://.azure-devices.net:443/$iothub/websocket 2021-06-24T19:41:09.490Z mqttjs connecting to an MQTT broker... 2021-06-24T19:41:09.490Z mqttjs:client MqttClient :: options.protocol wss 2021-06-24T19:41:09.490Z mqttjs:client MqttClient :: options.protocolVersion 4 2021-06-24T19:41:09.490Z mqttjs:client MqttClient :: options.username .azure-devices.net//?api-version=2020-09-30&DeviceClientType=azure-iot-device%2F1.17.3%20(node%20v16.3.0%3B%20Windows_NT%2010.0.18362%3B%20x64) 2021-06-24T19:41:09.490Z mqttjs:client MqttClient :: options.keepalive 180 2021-06-24T19:41:09.490Z mqttjs:client MqttClient :: options.reconnectPeriod 0 2021-06-24T19:41:09.490Z mqttjs:client MqttClient :: options.rejectUnauthorized true 2021-06-24T19:41:09.490Z mqttjs:client MqttClient :: clientId 2021-06-24T19:41:09.490Z mqttjs:client MqttClient :: setting up stream 2021-06-24T19:41:09.490Z mqttjs:client _setupStream :: calling method to clear reconnect 2021-06-24T19:41:09.490Z mqttjs:client _clearReconnect : clearing reconnect timer 2021-06-24T19:41:09.490Z mqttjs:client _setupStream :: using streamBuilder provided to client to create stream 2021-06-24T19:41:09.490Z mqttjs calling streambuilder for wss 2021-06-24T19:41:09.490Z mqttjs:ws streamBuilder 2021-06-24T19:41:09.490Z mqttjs:ws createWebSocket 2021-06-24T19:41:09.490Z mqttjs:ws protocol: MQTT 4 2021-06-24T19:41:09.490Z mqttjs:ws creating new Websocket for url: wss://.azure-devices.net:443/$iothub/websocket and protocol: mqtt 2021-06-24T19:41:09.491Z mqttjs:client _setupStream :: pipe stream to writable stream 2021-06-24T19:41:09.491Z mqttjs:client _setupStream: sending packet connect 2021-06-24T19:41:09.491Z mqttjs:client sendPacket :: packet: { cmd: 'connect' } 2021-06-24T19:41:09.491Z mqttjs:client sendPacket :: emitting packetsend 2021-06-24T19:41:09.491Z mqttjs:client sendPacket :: writing to stream 2021-06-24T19:41:09.491Z mqttjs:client sendPacket :: writeToStream result true 2021-06-24T19:41:12.365Z mqttjs:client writable stream :: parsing buffer 2021-06-24T19:41:12.366Z mqttjs:client parser :: on packet push to packets array. 2021-06-24T19:41:12.366Z mqttjs:client work :: getting next packet in queue 2021-06-24T19:41:12.366Z mqttjs:client work :: packet pulled from queue 2021-06-24T19:41:12.366Z mqttjs:client _handlePacket :: emitting packetreceive 2021-06-24T19:41:12.366Z mqttjs:client _handleConnack 2021-06-24T19:41:12.366Z mqttjs:client _setupPingTimer :: keepalive 180 (seconds) 2021-06-24T19:41:12.366Z mqttjs:client _resubscribe 2021-06-24T19:41:12.366Z mqttjs:client connect :: sending queued packets 2021-06-24T19:41:12.366Z mqttjs:client deliver :: entry undefined 2021-06-24T19:41:12.366Z azure-iot-mqtt-base:MqttBase Device is connected 2021-06-24T19:41:12.366Z azure-iot-mqtt-base:MqttBase CONNACK: {"cmd":"connack","retain":false,"qos":0,"dup":false,"length":2,"topic":null,"payload":null,"sessionPresent":true,"returnCode":0} 2021-06-24T19:41:12.366Z azure-iot-mqtt-base:MqttBase mqtt client reconnected successfully 2021-06-24T19:41:12.366Z azure-iot-mqtt-base:MqttBase reconnecting -> connected () 2021-06-24T19:44:12.368Z mqttjs:client _checkPing :: checking ping... 2021-06-24T19:44:12.368Z mqttjs:client _checkPing :: ping response received. Clearing flag and sending pingreq 2021-06-24T19:44:12.369Z mqttjs:client _sendPacket :: () :: start 2021-06-24T19:44:12.369Z mqttjs:client sendPacket :: packet: { cmd: 'pingreq' } 2021-06-24T19:44:12.369Z mqttjs:client sendPacket :: emitting packetsend 2021-06-24T19:44:12.369Z mqttjs:client sendPacket :: writing to stream 2021-06-24T19:44:12.369Z mqttjs:client sendPacket :: writeToStream result true 2021-06-24T19:44:12.605Z mqttjs:client writable stream :: parsing buffer 2021-06-24T19:44:12.605Z mqttjs:client parser :: on packet push to packets array. 2021-06-24T19:44:12.605Z mqttjs:client work :: getting next packet in queue 2021-06-24T19:44:12.605Z mqttjs:client work :: packet pulled from queue 2021-06-24T19:44:12.605Z mqttjs:client _handlePacket :: emitting packetreceive 2021-06-24T19:47:12.370Z mqttjs:client _checkPing :: checking ping... 2021-06-24T19:47:12.370Z mqttjs:client _checkPing :: ping response received. Clearing flag and sending pingreq 2021-06-24T19:47:12.370Z mqttjs:client _sendPacket :: () :: start 2021-06-24T19:47:12.370Z mqttjs:client sendPacket :: packet: { cmd: 'pingreq' } 2021-06-24T19:47:12.370Z mqttjs:client sendPacket :: emitting packetsend 2021-06-24T19:47:12.370Z mqttjs:client sendPacket :: writing to stream 2021-06-24T19:47:12.370Z mqttjs:client sendPacket :: writeToStream result true 2021-06-24T19:47:12.606Z mqttjs:client writable stream :: parsing buffer 2021-06-24T19:47:12.606Z mqttjs:client parser :: on packet push to packets array. 2021-06-24T19:47:12.606Z mqttjs:client work :: getting next packet in queue 2021-06-24T19:47:12.606Z mqttjs:client work :: packet pulled from queue 2021-06-24T19:47:12.606Z mqttjs:client _handlePacket :: emitting packetreceive 2021-06-24T19:50:12.373Z mqttjs:client _checkPing :: checking ping... 2021-06-24T19:50:12.373Z mqttjs:client _checkPing :: ping response received. Clearing flag and sending pingreq 2021-06-24T19:50:12.373Z mqttjs:client _sendPacket :: () :: start 2021-06-24T19:50:12.373Z mqttjs:client sendPacket :: packet: { cmd: 'pingreq' } 2021-06-24T19:50:12.373Z mqttjs:client sendPacket :: emitting packetsend 2021-06-24T19:50:12.373Z mqttjs:client sendPacket :: writing to stream 2021-06-24T19:50:12.373Z mqttjs:client sendPacket :: writeToStream result true 2021-06-24T19:50:12.608Z mqttjs:client writable stream :: parsing buffer 2021-06-24T19:50:12.608Z mqttjs:client parser :: on packet push to packets array. 2021-06-24T19:50:12.608Z mqttjs:client work :: getting next packet in queue 2021-06-24T19:50:12.608Z mqttjs:client work :: packet pulled from queue 2021-06-24T19:50:12.608Z mqttjs:client _handlePacket :: emitting packetreceive 2021-06-24T19:53:12.375Z mqttjs:client _checkPing :: checking ping... 2021-06-24T19:53:12.375Z mqttjs:client _checkPing :: ping response received. Clearing flag and sending pingreq 2021-06-24T19:53:12.375Z mqttjs:client _sendPacket :: () :: start 2021-06-24T19:53:12.376Z mqttjs:client sendPacket :: packet: { cmd: 'pingreq' } 2021-06-24T19:53:12.376Z mqttjs:client sendPacket :: emitting packetsend 2021-06-24T19:53:12.376Z mqttjs:client sendPacket :: writing to stream 2021-06-24T19:53:12.376Z mqttjs:client sendPacket :: writeToStream result true 2021-06-24T19:53:12.611Z mqttjs:client writable stream :: parsing buffer 2021-06-24T19:53:12.611Z mqttjs:client parser :: on packet push to packets array. 2021-06-24T19:53:12.611Z mqttjs:client work :: getting next packet in queue 2021-06-24T19:53:12.611Z mqttjs:client work :: packet pulled from queue 2021-06-24T19:53:12.611Z mqttjs:client _handlePacket :: emitting packetreceive 2021-06-24T19:56:04.263Z azure-iot-mqtt-base:MqttBase connected -> reconnecting (connected.updateSharedAccessSignature) 2021-06-24T19:56:04.264Z azure-iot-mqtt-base:MqttBase disconnecting mqtt client 2021-06-24T19:56:04.264Z azure-iot-mqtt-base:MqttBase removing all listeners 2021-06-24T19:56:04.264Z azure-iot-mqtt-base:MqttBase adding null error listener 2021-06-24T19:56:04.264Z mqttjs:client end :: () 2021-06-24T19:56:04.264Z mqttjs:client end :: cb? true 2021-06-24T19:56:04.264Z mqttjs:client _clearReconnect : clearing reconnect timer 2021-06-24T19:56:04.264Z mqttjs:client end :: () :: immediately calling finish 2021-06-24T19:56:04.264Z mqttjs:client end :: () :: finish :: calling _cleanUp with force false 2021-06-24T19:56:04.264Z mqttjs:client _cleanUp :: done callback provided for on stream close 2021-06-24T19:56:04.264Z mqttjs:client _cleanUp :: forced? false 2021-06-24T19:56:04.264Z mqttjs:client _cleanUp :: () :: call _sendPacket with disconnect packet 2021-06-24T19:56:04.264Z mqttjs:client _sendPacket :: () :: start 2021-06-24T19:56:04.264Z mqttjs:client sendPacket :: packet: { cmd: 'disconnect' } 2021-06-24T19:56:04.264Z mqttjs:client sendPacket :: emitting packetsend 2021-06-24T19:56:04.264Z mqttjs:client sendPacket :: writing to stream 2021-06-24T19:56:04.264Z mqttjs:client sendPacket :: writeToStream result true 2021-06-24T19:56:04.264Z mqttjs:client sendPacket :: invoking cb 2021-06-24T19:56:04.264Z mqttjs:client _cleanUp :: clearing pingTimer 2021-06-24T19:56:09.504Z mqttjs:client ()stream :: on close 2021-06-24T19:56:09.504Z mqttjs:client flushVolatile :: deleting volatile messages from the queue and setting their callbacks as error function 2021-06-24T19:56:09.504Z mqttjs:client stream: emit close to MqttClient 2021-06-24T19:56:09.504Z mqttjs:client end :: finish :: calling process.nextTick on closeStores 2021-06-24T19:56:09.504Z mqttjs:client end :: closeStores: closing incoming and outgoing stores 2021-06-24T19:56:09.504Z mqttjs:client end :: closeStores: emitting end 2021-06-24T19:56:09.504Z mqttjs:client end :: closeStores: invoking callback with args 2021-06-24T19:56:09.504Z azure-iot-mqtt-base:MqttBase mqtt client disconnected - reconnecting 2021-06-24T19:56:09.504Z azure-iot-mqtt-base:MqttBase username: .azure-devices.net//?api-version=2020-09-30&DeviceClientType=azure-iot-device%2F1.17.3%20(node%20v16.3.0%3B%20Windows_NT%2010.0.18362%3B%20x64) 2021-06-24T19:56:09.504Z azure-iot-mqtt-base:MqttBase uri: wss://.azure-devices.net:443/$iothub/websocket 2021-06-24T19:56:09.504Z mqttjs connecting to an MQTT broker... 2021-06-24T19:56:09.504Z mqttjs:client MqttClient :: options.protocol wss 2021-06-24T19:56:09.504Z mqttjs:client MqttClient :: options.protocolVersion 4 2021-06-24T19:56:09.504Z mqttjs:client MqttClient :: options.username .azure-devices.net//?api-version=2020-09-30&DeviceClientType=azure-iot-device%2F1.17.3%20(node%20v16.3.0%3B%20Windows_NT%2010.0.18362%3B%20x64) 2021-06-24T19:56:09.504Z mqttjs:client MqttClient :: options.keepalive 180 2021-06-24T19:56:09.504Z mqttjs:client MqttClient :: options.reconnectPeriod 0 2021-06-24T19:56:09.504Z mqttjs:client MqttClient :: options.rejectUnauthorized true 2021-06-24T19:56:09.504Z mqttjs:client MqttClient :: clientId 2021-06-24T19:56:09.504Z mqttjs:client MqttClient :: setting up stream 2021-06-24T19:56:09.504Z mqttjs:client _setupStream :: calling method to clear reconnect 2021-06-24T19:56:09.504Z mqttjs:client _clearReconnect : clearing reconnect timer 2021-06-24T19:56:09.504Z mqttjs:client _setupStream :: using streamBuilder provided to client to create stream 2021-06-24T19:56:09.504Z mqttjs calling streambuilder for wss 2021-06-24T19:56:09.504Z mqttjs:ws streamBuilder 2021-06-24T19:56:09.504Z mqttjs:ws createWebSocket 2021-06-24T19:56:09.504Z mqttjs:ws protocol: MQTT 4 2021-06-24T19:56:09.504Z mqttjs:ws creating new Websocket for url: wss://.azure-devices.net:443/$iothub/websocket and protocol: mqtt 2021-06-24T19:56:09.505Z mqttjs:client _setupStream :: pipe stream to writable stream 2021-06-24T19:56:09.505Z mqttjs:client _setupStream: sending packet connect 2021-06-24T19:56:09.505Z mqttjs:client sendPacket :: packet: { cmd: 'connect' } 2021-06-24T19:56:09.505Z mqttjs:client sendPacket :: emitting packetsend 2021-06-24T19:56:09.505Z mqttjs:client sendPacket :: writing to stream 2021-06-24T19:56:09.505Z mqttjs:client sendPacket :: writeToStream result true 2021-06-24T19:56:12.421Z mqttjs:client writable stream :: parsing buffer 2021-06-24T19:56:12.421Z mqttjs:client parser :: on packet push to packets array. 2021-06-24T19:56:12.421Z mqttjs:client work :: getting next packet in queue 2021-06-24T19:56:12.421Z mqttjs:client work :: packet pulled from queue 2021-06-24T19:56:12.421Z mqttjs:client _handlePacket :: emitting packetreceive 2021-06-24T19:56:12.421Z mqttjs:client _handleConnack 2021-06-24T19:56:12.421Z mqttjs:client _setupPingTimer :: keepalive 180 (seconds) 2021-06-24T19:56:12.421Z mqttjs:client _resubscribe 2021-06-24T19:56:12.421Z mqttjs:client connect :: sending queued packets 2021-06-24T19:56:12.421Z mqttjs:client deliver :: entry undefined 2021-06-24T19:56:12.421Z azure-iot-mqtt-base:MqttBase Device is connected 2021-06-24T19:56:12.422Z azure-iot-mqtt-base:MqttBase CONNACK: {"cmd":"connack","retain":false,"qos":0,"dup":false,"length":2,"topic":null,"payload":null,"sessionPresent":true,"returnCode":0} 2021-06-24T19:56:12.422Z azure-iot-mqtt-base:MqttBase mqtt client reconnected successfully 2021-06-24T19:56:12.422Z azure-iot-mqtt-base:MqttBase reconnecting -> connected () 2021-06-24T19:59:12.423Z mqttjs:client _checkPing :: checking ping... 2021-06-24T19:59:12.424Z mqttjs:client _checkPing :: ping response received. Clearing flag and sending pingreq 2021-06-24T19:59:12.424Z mqttjs:client _sendPacket :: () :: start 2021-06-24T19:59:12.424Z mqttjs:client sendPacket :: packet: { cmd: 'pingreq' } 2021-06-24T19:59:12.424Z mqttjs:client sendPacket :: emitting packetsend 2021-06-24T19:59:12.424Z mqttjs:client sendPacket :: writing to stream 2021-06-24T19:59:12.424Z mqttjs:client sendPacket :: writeToStream result true 2021-06-24T19:59:12.662Z mqttjs:client writable stream :: parsing buffer 2021-06-24T19:59:12.662Z mqttjs:client parser :: on packet push to packets array. 2021-06-24T19:59:12.662Z mqttjs:client work :: getting next packet in queue 2021-06-24T19:59:12.662Z mqttjs:client work :: packet pulled from queue 2021-06-24T19:59:12.662Z mqttjs:client _handlePacket :: emitting packetreceive 2021-06-24T20:02:12.426Z mqttjs:client _checkPing :: checking ping... 2021-06-24T20:02:12.426Z mqttjs:client _checkPing :: ping response received. Clearing flag and sending pingreq 2021-06-24T20:02:12.426Z mqttjs:client _sendPacket :: () :: start 2021-06-24T20:02:12.426Z mqttjs:client sendPacket :: packet: { cmd: 'pingreq' } 2021-06-24T20:02:12.426Z mqttjs:client sendPacket :: emitting packetsend 2021-06-24T20:02:12.426Z mqttjs:client sendPacket :: writing to stream 2021-06-24T20:02:12.426Z mqttjs:client sendPacket :: writeToStream result true 2021-06-24T20:02:12.667Z mqttjs:client writable stream :: parsing buffer 2021-06-24T20:02:12.667Z mqttjs:client parser :: on packet push to packets array. 2021-06-24T20:02:12.667Z mqttjs:client work :: getting next packet in queue 2021-06-24T20:02:12.667Z mqttjs:client work :: packet pulled from queue 2021-06-24T20:02:12.667Z mqttjs:client _handlePacket :: emitting packetreceive 2021-06-24T20:05:12.427Z mqttjs:client _checkPing :: checking ping... 2021-06-24T20:05:12.428Z mqttjs:client _checkPing :: ping response received. Clearing flag and sending pingreq 2021-06-24T20:05:12.428Z mqttjs:client _sendPacket :: () :: start 2021-06-24T20:05:12.428Z mqttjs:client sendPacket :: packet: { cmd: 'pingreq' } 2021-06-24T20:05:12.428Z mqttjs:client sendPacket :: emitting packetsend 2021-06-24T20:05:12.428Z mqttjs:client sendPacket :: writing to stream 2021-06-24T20:05:12.428Z mqttjs:client sendPacket :: writeToStream result true 2021-06-24T20:05:12.666Z mqttjs:client writable stream :: parsing buffer 2021-06-24T20:05:12.666Z mqttjs:client parser :: on packet push to packets array. 2021-06-24T20:05:12.666Z mqttjs:client work :: getting next packet in queue 2021-06-24T20:05:12.666Z mqttjs:client work :: packet pulled from queue 2021-06-24T20:05:12.666Z mqttjs:client _handlePacket :: emitting packetreceive 2021-06-24T20:08:12.432Z mqttjs:client _checkPing :: checking ping... 2021-06-24T20:08:12.432Z mqttjs:client _checkPing :: ping response received. Clearing flag and sending pingreq 2021-06-24T20:08:12.432Z mqttjs:client _sendPacket :: () :: start 2021-06-24T20:08:12.432Z mqttjs:client sendPacket :: packet: { cmd: 'pingreq' } 2021-06-24T20:08:12.432Z mqttjs:client sendPacket :: emitting packetsend 2021-06-24T20:08:12.432Z mqttjs:client sendPacket :: writing to stream 2021-06-24T20:08:12.432Z mqttjs:client sendPacket :: writeToStream result true 2021-06-24T20:08:12.673Z mqttjs:client writable stream :: parsing buffer 2021-06-24T20:08:12.673Z mqttjs:client parser :: on packet push to packets array. 2021-06-24T20:08:12.673Z mqttjs:client work :: getting next packet in queue 2021-06-24T20:08:12.673Z mqttjs:client work :: packet pulled from queue 2021-06-24T20:08:12.673Z mqttjs:client _handlePacket :: emitting packetreceive 2021-06-24T20:11:04.275Z azure-iot-mqtt-base:MqttBase connected -> reconnecting (connected.updateSharedAccessSignature) 2021-06-24T20:11:04.275Z azure-iot-mqtt-base:MqttBase disconnecting mqtt client 2021-06-24T20:11:04.275Z azure-iot-mqtt-base:MqttBase removing all listeners 2021-06-24T20:11:04.275Z azure-iot-mqtt-base:MqttBase adding null error listener 2021-06-24T20:11:04.275Z mqttjs:client end :: () 2021-06-24T20:11:04.275Z mqttjs:client end :: cb? true 2021-06-24T20:11:04.275Z mqttjs:client _clearReconnect : clearing reconnect timer 2021-06-24T20:11:04.275Z mqttjs:client end :: () :: immediately calling finish 2021-06-24T20:11:04.275Z mqttjs:client end :: () :: finish :: calling _cleanUp with force false 2021-06-24T20:11:04.275Z mqttjs:client _cleanUp :: done callback provided for on stream close 2021-06-24T20:11:04.275Z mqttjs:client _cleanUp :: forced? false 2021-06-24T20:11:04.275Z mqttjs:client _cleanUp :: () :: call _sendPacket with disconnect packet 2021-06-24T20:11:04.275Z mqttjs:client _sendPacket :: () :: start 2021-06-24T20:11:04.276Z mqttjs:client sendPacket :: packet: { cmd: 'disconnect' } 2021-06-24T20:11:04.276Z mqttjs:client sendPacket :: emitting packetsend 2021-06-24T20:11:04.276Z mqttjs:client sendPacket :: writing to stream 2021-06-24T20:11:04.276Z mqttjs:client sendPacket :: writeToStream result true 2021-06-24T20:11:04.276Z mqttjs:client sendPacket :: invoking cb 2021-06-24T20:11:04.276Z mqttjs:client _cleanUp :: clearing pingTimer 2021-06-24T20:11:09.520Z mqttjs:client ()stream :: on close 2021-06-24T20:11:09.520Z mqttjs:client flushVolatile :: deleting volatile messages from the queue and setting their callbacks as error function 2021-06-24T20:11:09.520Z mqttjs:client stream: emit close to MqttClient 2021-06-24T20:11:09.520Z mqttjs:client end :: finish :: calling process.nextTick on closeStores 2021-06-24T20:11:09.520Z mqttjs:client end :: closeStores: closing incoming and outgoing stores 2021-06-24T20:11:09.520Z mqttjs:client end :: closeStores: emitting end 2021-06-24T20:11:09.520Z mqttjs:client end :: closeStores: invoking callback with args 2021-06-24T20:11:09.520Z azure-iot-mqtt-base:MqttBase mqtt client disconnected - reconnecting 2021-06-24T20:11:09.520Z azure-iot-mqtt-base:MqttBase username: .azure-devices.net//?api-version=2020-09-30&DeviceClientType=azure-iot-device%2F1.17.3%20(node%20v16.3.0%3B%20Windows_NT%2010.0.18362%3B%20x64) 2021-06-24T20:11:09.520Z azure-iot-mqtt-base:MqttBase uri: wss://.azure-devices.net:443/$iothub/websocket 2021-06-24T20:11:09.520Z mqttjs connecting to an MQTT broker... 2021-06-24T20:11:09.520Z mqttjs:client MqttClient :: options.protocol wss 2021-06-24T20:11:09.520Z mqttjs:client MqttClient :: options.protocolVersion 4 2021-06-24T20:11:09.520Z mqttjs:client MqttClient :: options.username .azure-devices.net//?api-version=2020-09-30&DeviceClientType=azure-iot-device%2F1.17.3%20(node%20v16.3.0%3B%20Windows_NT%2010.0.18362%3B%20x64) 2021-06-24T20:11:09.520Z mqttjs:client MqttClient :: options.keepalive 180 2021-06-24T20:11:09.520Z mqttjs:client MqttClient :: options.reconnectPeriod 0 2021-06-24T20:11:09.520Z mqttjs:client MqttClient :: options.rejectUnauthorized true 2021-06-24T20:11:09.520Z mqttjs:client MqttClient :: clientId 2021-06-24T20:11:09.520Z mqttjs:client MqttClient :: setting up stream 2021-06-24T20:11:09.520Z mqttjs:client _setupStream :: calling method to clear reconnect 2021-06-24T20:11:09.520Z mqttjs:client _clearReconnect : clearing reconnect timer 2021-06-24T20:11:09.520Z mqttjs:client _setupStream :: using streamBuilder provided to client to create stream 2021-06-24T20:11:09.520Z mqttjs calling streambuilder for wss 2021-06-24T20:11:09.520Z mqttjs:ws streamBuilder 2021-06-24T20:11:09.520Z mqttjs:ws createWebSocket 2021-06-24T20:11:09.520Z mqttjs:ws protocol: MQTT 4 2021-06-24T20:11:09.520Z mqttjs:ws creating new Websocket for url: wss://.azure-devices.net:443/$iothub/websocket and protocol: mqtt 2021-06-24T20:11:09.529Z mqttjs:client _setupStream :: pipe stream to writable stream 2021-06-24T20:11:09.529Z mqttjs:client _setupStream: sending packet connect 2021-06-24T20:11:09.529Z mqttjs:client sendPacket :: packet: { cmd: 'connect' } 2021-06-24T20:11:09.529Z mqttjs:client sendPacket :: emitting packetsend 2021-06-24T20:11:09.529Z mqttjs:client sendPacket :: writing to stream 2021-06-24T20:11:09.529Z mqttjs:client sendPacket :: writeToStream result true 2021-06-24T20:11:12.438Z mqttjs:client writable stream :: parsing buffer 2021-06-24T20:11:12.438Z mqttjs:client parser :: on packet push to packets array. 2021-06-24T20:11:12.438Z mqttjs:client work :: getting next packet in queue 2021-06-24T20:11:12.438Z mqttjs:client work :: packet pulled from queue 2021-06-24T20:11:12.438Z mqttjs:client _handlePacket :: emitting packetreceive 2021-06-24T20:11:12.438Z mqttjs:client _handleConnack 2021-06-24T20:11:12.438Z mqttjs:client _setupPingTimer :: keepalive 180 (seconds) 2021-06-24T20:11:12.438Z mqttjs:client _resubscribe 2021-06-24T20:11:12.438Z mqttjs:client connect :: sending queued packets 2021-06-24T20:11:12.438Z mqttjs:client deliver :: entry undefined 2021-06-24T20:11:12.438Z azure-iot-mqtt-base:MqttBase Device is connected 2021-06-24T20:11:12.438Z azure-iot-mqtt-base:MqttBase CONNACK: {"cmd":"connack","retain":false,"qos":0,"dup":false,"length":2,"topic":null,"payload":null,"sessionPresent":true,"returnCode":0} 2021-06-24T20:11:12.438Z azure-iot-mqtt-base:MqttBase mqtt client reconnected successfully 2021-06-24T20:11:12.439Z azure-iot-mqtt-base:MqttBase reconnecting -> connected () 2021-06-24T20:14:12.440Z mqttjs:client _checkPing :: checking ping... 2021-06-24T20:14:12.440Z mqttjs:client _checkPing :: ping response received. Clearing flag and sending pingreq 2021-06-24T20:14:12.440Z mqttjs:client _sendPacket :: () :: start 2021-06-24T20:14:12.440Z mqttjs:client sendPacket :: packet: { cmd: 'pingreq' } 2021-06-24T20:14:12.440Z mqttjs:client sendPacket :: emitting packetsend 2021-06-24T20:14:12.440Z mqttjs:client sendPacket :: writing to stream 2021-06-24T20:14:12.440Z mqttjs:client sendPacket :: writeToStream result true 2021-06-24T20:14:12.679Z mqttjs:client writable stream :: parsing buffer 2021-06-24T20:14:12.679Z mqttjs:client parser :: on packet push to packets array. 2021-06-24T20:14:12.679Z mqttjs:client work :: getting next packet in queue 2021-06-24T20:14:12.679Z mqttjs:client work :: packet pulled from queue 2021-06-24T20:14:12.679Z mqttjs:client _handlePacket :: emitting packetreceive 2021-06-24T20:17:12.443Z mqttjs:client _checkPing :: checking ping... 2021-06-24T20:17:12.443Z mqttjs:client _checkPing :: ping response received. Clearing flag and sending pingreq 2021-06-24T20:17:12.443Z mqttjs:client _sendPacket :: () :: start 2021-06-24T20:17:12.443Z mqttjs:client sendPacket :: packet: { cmd: 'pingreq' } 2021-06-24T20:17:12.443Z mqttjs:client sendPacket :: emitting packetsend 2021-06-24T20:17:12.443Z mqttjs:client sendPacket :: writing to stream 2021-06-24T20:17:12.443Z mqttjs:client sendPacket :: writeToStream result true 2021-06-24T20:17:12.697Z mqttjs:client writable stream :: parsing buffer 2021-06-24T20:17:12.698Z mqttjs:client parser :: on packet push to packets array. 2021-06-24T20:17:12.698Z mqttjs:client work :: getting next packet in queue 2021-06-24T20:17:12.698Z mqttjs:client work :: packet pulled from queue 2021-06-24T20:17:12.698Z mqttjs:client _handlePacket :: emitting packetreceive 2021-06-24T20:20:12.447Z mqttjs:client _checkPing :: checking ping... 2021-06-24T20:20:12.447Z mqttjs:client _checkPing :: ping response received. Clearing flag and sending pingreq 2021-06-24T20:20:12.447Z mqttjs:client _sendPacket :: () :: start 2021-06-24T20:20:12.447Z mqttjs:client sendPacket :: packet: { cmd: 'pingreq' } 2021-06-24T20:20:12.447Z mqttjs:client sendPacket :: emitting packetsend 2021-06-24T20:20:12.447Z mqttjs:client sendPacket :: writing to stream 2021-06-24T20:20:12.447Z mqttjs:client sendPacket :: writeToStream result true 2021-06-24T20:20:12.573Z mqttjs:client streamErrorHandler :: error WebSocket is not open: readyState 3 (CLOSED) 2021-06-24T20:20:12.574Z mqttjs:client nop :: Error: WebSocket is not open: readyState 3 (CLOSED) at sendAfterClose (D:\Document\MagicBox\azure\self_test\node_modules\mqtt\node_modules\ws\lib\websocket.js:764:17) at WebSocket.send (D:\Document\MagicBox\azure\self_test\node_modules\mqtt\node_modules\ws\lib\websocket.js:345:7) at Duplex.duplex._write (D:\Document\MagicBox\azure\self_test\node_modules\mqtt\node_modules\ws\lib\stream.js:157:8) at doWrite (node:internal/streams/writable:408:12) at clearBuffer (node:internal/streams/writable:569:7) at Duplex.Writable.uncork (node:internal/streams/writable:348:7) at uncork (D:\Document\MagicBox\azure\self_test\node_modules\mqtt-packet\writeToStream.js:80:10) at processTicksAndRejections (node:internal/process/task_queues:82:21) 2021-06-24T20:20:12.579Z mqttjs:client (****)stream :: on close 2021-06-24T20:20:12.579Z mqttjs:client flushVolatile :: deleting volatile messages from the queue and setting their callbacks as error function 2021-06-24T20:20:12.579Z mqttjs:client stream: emit close to MqttClient 2021-06-24T20:20:12.579Z mqttjs:client close :: connected set to false 2021-06-24T20:20:12.579Z mqttjs:client close :: clearing connackTimer 2021-06-24T20:20:12.579Z mqttjs:client close :: clearing ping timer 2021-06-24T20:20:12.579Z mqttjs:client close :: calling _setupReconnect 2021-06-24T20:20:12.579Z mqttjs:client _setupReconnect :: doing nothing... 2021-06-24T20:20:12.579Z azure-iot-mqtt-base:MqttBase In base mqtt - close event received from mqtt.js client - no error 2021-06-24T20:20:12.581Z azure-iot-mqtt-base:MqttBase connected -> disconnected (connected.closeEvent) 2021-06-24T20:20:12.581Z azure-iot-mqtt-base:MqttBase In MQTT base FSM - entered onEnter for disconnect 2021-06-24T20:20:12.582Z azure-iot-mqtt-base:MqttBase In mqtt base - no callback for error - emitting 'error': NotConnectedError 2021-06-24T20:20:12.583Z azure-iot-device-mqtt:Mqtt on close 2021-06-24T20:20:12.584Z azure-iot-device-mqtt:Mqtt connected -> disconnecting (connected.disconnect) 2021-06-24T20:20:12.584Z azure-iot-device-mqtt:Mqtt disconnecting -> disconnected (connected.disconnect) 2021-06-24T20:20:12.586Z azure-iot-device:InternalClient transport disconnect event: NotConnectedError: Connection to the server has been closed.

the original file is too large, i cut the repeated successful reconnect at the begining and keep one before the final failure reconnect. An exception happens, it may be the root cause.

YoDaMa commented 3 years ago

@sunhubs additionally since this is linked to an internal IcM, you can link the original file if you upload it there.

YoDaMa commented 3 years ago

Additionally, from the logs it looks like there is an error causing the device connection to be suddenly closed. 

2021-06-24T20:20:12.573Z mqttjs:client streamErrorHandler :: error WebSocket is not open: readyState 3 (CLOSED)

Then this is propagated to MQTT.js 

2021-06-24T20:20:12.579Z mqttjs:client ()stream :: on close

Then this is propagated to the MQTT transport in the library. 

          closeEvent: () => {
            this._fsm.transition('disconnected', undefined, new errors.NotConnectedError('Connection to the server has been closed.'));
          }

This transitions the transport's finite state machine directly from connected to disconnected, which only occurs in the event of an error in the connection (for disconnect events, the fsm will transition to disconnecting first). It also does not provide a disconnect callback, since there is no disconnect callback available (the callback would be provided if a call to disconnect was made by the client somehow). 

            // If there is no callback present, the clear implication is that something pretty major occurred,
            // NOT in the context of any particular operation.  There is NO operation that this error can be reported
            // as a result for.  Hence we emit the 'error' event.
            //
            if (callback) {
              callback(err);
            } else {
              if (err) {
                debug('In mqtt base - no callback for error - emitting \'error\': ' + this._errorDescription(err));
                this.emit('error', err);
              }
            }

The implication here is that there will be an error emitted for a connection error, but no callback will be invoked.

We see this bubble up to the device level mqtt transport in your logs.

2021-06-24T20:20:12.583Z azure-iot-device-mqtt:Mqtt on close

And finally makes it to the InternalClient level 

2021-06-24T20:20:12.586Z azure-iot-device:InternalClient transport disconnect event: NotConnectedError: Connection to the server has been closed.

However at this point the error is left to languish. We should look into providing that as an event to the user.

This is the problem piece of code in question:

// From device/core/src/internal_client.ts

    this._disconnectHandler = (err) => {
      debug('transport disconnect event: ' + (err ? err.toString() : 'no error'));
      if (err && this._retryPolicy.shouldRetry(err)) {
        debug('error occurred. client set to attempt retry.');
        /*Codes_SRS_NODE_INTERNAL_CLIENT_16_098: [If the transport emits a `disconnect` event while the client is subscribed to direct methods the retry policy shall be used to reconnect and re-enable the feature using the transport `enableMethods` method.]*/
        if (this._methodsEnabled) {
          this._methodsEnabled = false;
          debug('re-enabling Methods link');
          this._enableMethods((err) => {
            if (err) {
              /*Codes_SRS_NODE_INTERNAL_CLIENT_16_100: [If the retry policy fails to reestablish the direct methods functionality a `disconnect` event shall be emitted with a `results.Disconnected` object.]*/
              this.emit('disconnect', new results.Disconnected(err));
            }
          });
        }

        /*Codes_SRS_NODE_INTERNAL_CLIENT_16_099: [If the transport emits a `disconnect` event while the client is subscribed to desired properties updates the retry policy shall be used to reconnect and re-enable the feature using the transport `enableTwinDesiredPropertiesUpdates` method.]*/
        if (this._twin && this._twin.desiredPropertiesUpdatesEnabled) {
          debug('re-enabling Twin');
          this._twin.enableTwinDesiredPropertiesUpdates((err) => {
            if (err) {
              /*Codes_SRS_NODE_INTERNAL_CLIENT_16_101: [If the retry policy fails to reestablish the twin desired properties updates functionality a `disconnect` event shall be emitted with a `results.Disconnected` object.]*/
              this.emit('disconnect', new results.Disconnected(err));
            }
          });
        }
      } else {
        debug('emitting disconnect');
        this.emit('disconnect', new results.Disconnected(err));
      }
    };
    /*Codes_SRS_NODE_INTERNAL_CLIENT_16_045: [If the transport successfully establishes a connection the `open` method shall subscribe to the `disconnect` event of the transport.]*/
    this._transport.on('disconnect', this._disconnectHandler);
sunhubs commented 3 years ago

@YoDaMa thanks for your update. I acknowleage the reason why the disconnect was not captured. But I still want to have a solution for the client unexpected close/disconnect behavior. So that I do not need to handle the unexpected device disconnect by myself when there is no message from cloud to this device for a long time.

LanceLiMS commented 3 years ago

@YoDaMa Hi Yoseph, please help deploy a fix for our Cx, thanks in advance!

YoDaMa commented 3 years ago

@sunhubs, the logs we're seeing seem confusing right now. It's not clear still. Can you attach the full logs to the ICM? Thanks.

sunhubs commented 3 years ago

sorry, my original log file is not found. I will replay it again, and submit it as soon as possible. Another thing needs your help is that, would you please help confirm why I must initiate a new client to open connection after I close connection. I know it is required in SDK, but it seems not so reasonable.

YoDaMa commented 3 years ago

After the client is called to close the client removes the listeners on the transport, which is destructive. As a result, you need to re-initialize a client.

This is of course different than if your client is disconnect from an error, and you want to reconnect. If the disconnect handler is triggered, then you can simply attempt to reconnect on the same client that you already initialized.

anthonyvercolano commented 3 years ago

Closed due to inactivity.