{"action":"created","issue":{"url":"https://api.github.com/repos/Azure/azure-iot-sdk-node/issues/189","repository_url":"https://api.github.com/repos/Azure/azure-iot-sdk-node","labels_url":"https://api.github.com/repos/Azure/azure-iot-sdk-node/issues/189/labels{/name}","comments_url":"https://api.github.com/repos/Azure/azure-iot-sdk-node/issues/189/comments","events_url":"https://api.github.com/repos/Azure/azure-iot-sdk-node/issues/189/events","html_url":"https://github.com/Azure/azure-iot-sdk-node/issues/189","id":285656396,"number":189,"title":"MQTT state machine doesn't detect disconnect","user":{"login":"sgacond","id":9912606,"avatar_url":"https://avatars0.githubusercontent.com/u/9912606?v=4","gravatar_id":"","url":"https://api.github.com/users/sgacond","html_url":"https://github.com/sgacond","followers_url":"https://api.github.com/users/sgacond/followers","following_url":"https://api.github.com/users/sgacond/following{/other_user}","gists_url":"https://api.github.com/users/sgacond/gists{/gist_id}","starred_url":"https://api.github.com/users/sgacond/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/sgacond/subscriptions","organizations_url":"https://api.github.com/users/sgacond/orgs","repos_url":"https://api.github.com/users/sgacond/repos","events_url":"https://api.github.com/users/sgacond/events{/privacy}","received_events_url":"https://api.github.com/users/sgacond/received_events","type":"User","site_admin":false},"labels":[{"id":512640578,"url":"https://api.github.com/repos/Azure/azure-iot-sdk-node/labels/investigation-required","name":"investigation-required","color":"649ec1","default":false}],"state":"open","locked":false,"assignee":{"login":"pierreca","id":4979572,"avatar_url":"https://avatars2.githubusercontent.com/u/4979572?v=4","gravatar_id":"","url":"https://api.github.com/users/pierreca","html_url":"https://github.com/pierreca","followers_url":"https://api.github.com/users/pierreca/followers","following_url":"https://api.github.com/users/pierreca/following{/other_user}","gists_url":"https://api.github.com/users/pierreca/gists{/gist_id}","starred_url":"https://api.github.com/users/pierreca/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/pierreca/subscriptions","organizations_url":"https://api.github.com/users/pierreca/orgs","repos_url":"https://api.github.com/users/pierreca/repos","events_url":"https://api.github.com/users/pierreca/events{/privacy}","received_events_url":"https://api.github.com/users/pierreca/received_events","type":"User","site_admin":false},"assignees":[{"login":"pierreca","id":4979572,"avatar_url":"https://avatars2.githubusercontent.com/u/4979572?v=4","gravatar_id":"","url":"https://api.github.com/users/pierreca","html_url":"https://github.com/pierreca","followers_url":"https://api.github.com/users/pierreca/followers","following_url":"https://api.github.com/users/pierreca/following{/other_user}","gists_url":"https://api.github.com/users/pierreca/gists{/gist_id}","starred_url":"https://api.github.com/users/pierreca/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/pierreca/subscriptions","organizations_url":"https://api.github.com/users/pierreca/orgs","repos_url":"https://api.github.com/users/pierreca/repos","events_url":"https://api.github.com/users/pierreca/events{/privacy}","received_events_url":"https://api.github.com/users/pierreca/received_events","type":"User","site_admin":false}],"milestone":null,"comments":4,"created_at":"2018-01-03T11:06:23Z","updated_at":"2018-02-03T14:53:11Z","closed_at":null,"author_association":"NONE","body":"# Context\r\n- **OS and version used:** Raspbian Jessie, Linux 4.9.40-v7+, armv7l\r\n- **Node.js version:** v9.3.0\r\n- **npm version:** v5.5.1\r\n- **list of installed packages:** \r\n```\r\n├── azure-iot-common@1.3.0\r\n├── azure-iot-device@1.3.0\r\n├── azure-iot-device-mqtt@1.3.0\r\n└── bluebird@3.5.1\r\n```\r\n\r\n# Description of the issue:\r\nWe used to have strange behaviour on some devices out in the field. \r\nThe logs looked like the transmission timer suddenly stopped to transmit, but there was no exception or error callback. Devices with weaker and more unstable internet connection did it more often then others (some once a month, some once a week).\r\nA simple restart of the whole app solved the issue for a while.\r\n\r\nWe found out, that losing the network connection and reconnecting it in on the raspbian device caused the iot-sdk to stop doing anything. Every method call (even \"disconnect\") went to neverland. No callback, no error. The network interface was not disconnected, just the cable. On my development machine (mac os), the behaviour was different: after a timeout time, the error callback arrived and the next \"sendEvent\" tried to reconnect.\r\n\r\nThe retry policy is set to NoRetry().\r\n\r\n# Investigation\r\n\r\nUnfortunately our devices don't have any display port and remote debugging while unplugging the network connection is a bit a challange. But using a second network adapter and a local connection without gateway address enabled that.\r\n\r\nUnlike on my dev mac, the underlying socket under the MQTT lib was never closed on raspbian (\"end-of-stream\" was never fired). So the state machine of \"MqttBase\" didn't catch the \"close\"-event ([transport/mqtt/src/mqtt_base.ts:77](https://github.com/Azure/azure-iot-sdk-node/blob/55dd09dd2ba0d1bc331f9b4755d9c8a37399da99/common/transport/mqtt/src/mqtt_base.ts#L77)) of _mqttClient and stayed in connected state.\r\n\r\n## Ugly workaround\r\n\r\nAs a workaround I introduced a timeout on the send event (bluebird: prmoisified and timeout(...)), and shifted state manually when it got hit.\r\n\r\n# Code sample exhibiting the issue:\r\n```javascript\r\nconst Message = require('azure-iot-device').Message,\r\n      Client = require('azure-iot-device').Client,\r\n      SharedAccessKeyAuthenticationProvider = require('azure-iot-device').SharedAccessKeyAuthenticationProvider,\r\n      Mqtt = require('azure-iot-device-mqtt').Mqtt,\r\n      NoRetry = require('azure-iot-common').NoRetry,\r\n      Promise = require('bluebird');\r\n\r\nlet data = '{...}';\r\n\r\nlet authProvider = new SharedAccessKeyAuthenticationProvider({ \r\n    host: '...',\r\n    deviceId: '...',\r\n    sharedAccessKey: '...'\r\n});\r\n\r\nlet client = Client.fromAuthenticationProvider(authProvider, Mqtt);\r\n\r\nclient.setRetryPolicy(new NoRetry());\r\nclient.open((err, result) => {\r\n\r\n    if(err)\r\n        console.log('client open error: %s', err);\r\n\r\n        client.on('error', err => {\r\n        console.log('client on error called.');\r\n    });\r\n\r\n    client.on('disconnect', () => {\r\n        console.log('client on disconnect called.');\r\n    });\r\n\r\n    sendMessage();\r\n\r\n    setInterval(() => {\r\n        sendMessage();\r\n    }, 10000);\r\n\r\n});\r\n\r\nlet i = 0;\r\n\r\nfunction sendMessage() {\r\n    let sendAsync = Promise.promisify(client.sendEvent, { context: client });\r\n    let message = new Message(data);\r\n    let messageI = ++i;\r\n    console.log('SEND: ', messageI);\r\n    sendAsync(message).then(result => {\r\n        console.log('CB: ', messageI);\r\n    }, err => {\r\n        console.log('CB with err: ', messageI);\r\n        console.error(err);\r\n    }).timeout(5000)\r\n    .catch(Promise.TimeoutError, err => {\r\n        console.log('TIMEOUT', messageI);\r\n        console.log('TRANSPORT STATE: ', client._transport._fsm.state);\r\n        console.log('TRANSPORT MQTT STATE: ', client._transport._mqtt._fsm.state);\r\n\r\n        // WORKAROUND\r\n        //   On raspbian, the socket is never closed. 'close' is never called.\r\n        //   Hit the state machine manually to avoid staying 'connected' forever.\r\n        if(client._transport._mqtt._fsm.state == 'connected')\r\n            client._transport._mqtt._fsm.handle('closeEvent');\r\n    });\r\n}\r\n```\r\n\r\n# Console log of the issue:\r\n_(without workaround timeout)_\r\n```\r\nDebugger listening on ws://0.0.0.0:9229/b10ed993-32e0-410a-8766-4ec2e6ae76ac\r\nFor help see https://nodejs.org/en/docs/inspector\r\nDebugger attached.\r\n  azure-iot-device-mqtt:Mqtt disconnected -> connecting (disconnected.connect) +0ms\r\n  azure-iot-device-mqtt:Mqtt topic publish: devices/dev-slm-client/messages/events/ +1ms\r\n  azure-iot-device-mqtt:Mqtt topic subscribe: devices/dev-slm-client/messages/devicebound/# +1ms\r\n  azure-iot-mqtt-base:MqttBase disconnected -> connecting (disconnected.connect) +0ms\r\n  azure-iot-mqtt-base:MqttBase username: <...>.azure-devices.net/dev-slm-client/DeviceClientType=azure-iot-device%2F1.3.0&api-version=2017-06-30 +0ms\r\n  azure-iot-mqtt-base:MqttBase uri:      mqtts://<...>.azure-devices.net +1ms\r\n(node:4307) [INSPECTOR_ASYNC_STACK_TRACES_NOT_AVAILABLE] Warning: Warning: Async stack traces in debugger are not available on 32bit platforms. The feature is disabled.\r\n  azure-iot-mqtt-base:MqttBase Device is connected +409ms\r\n  azure-iot-mqtt-base:MqttBase CONNACK: {\"cmd\":\"connack\",\"retain\":false,\"qos\":0,\"dup\":false,\"length\":2,\"topic\":null,\"payload\":null,\"sessionPresent\":true,\"returnCode\":0} +0ms\r\n  azure-iot-mqtt-base:MqttBase connecting -> connected () +1ms\r\n  azure-iot-device-mqtt:Mqtt connect +412ms\r\n  azure-iot-device-mqtt:Mqtt connecting -> connected () +0ms\r\nSEND:  1\r\n  azure-iot-device-mqtt:Mqtt sendEvent {\"data\":...}\",\"properties\":{\"propertyList\":[]},\"messageId\":\"\",\"to\":\"\",\"lockToken\":\"\",\"correlationId\":\"\",\"userId\":\"\"} +3ms\r\n  azure-iot-device-mqtt:Mqtt PUBACK: {\"transportObj\":{\"cmd\":\"publish\",\"topic\":\"devices/dev-slm-client/messages/events/\",\"payload\":\"{...}\",\"qos\":1,\"retain\":false,\"messageId\":37302,\"dup\":false}} +8s\r\nCB:  1\r\n======> NETWORK CABLE UNPLUGGED HERE <========\r\nSEND:  2\r\n  azure-iot-device-mqtt:Mqtt sendEvent {\"data\":...}\",\"properties\":{\"propertyList\":[]},\"messageId\":\"\",\"to\":\"\",\"lockToken\":\"\",\"correlationId\":\"\",\"userId\":\"\"} +10s\r\nSEND:  3\r\n  azure-iot-device-mqtt:Mqtt sendEvent {\"data\":...}\",\"properties\":{\"propertyList\":[]},\"messageId\":\"\",\"to\":\"\",\"lockToken\":\"\",\"correlationId\":\"\",\"userId\":\"\"} +1m\r\nSEND:  4\r\n  azure-iot-device-mqtt:Mqtt sendEvent {\"data\":...}\",\"properties\":{\"propertyList\":[]},\"messageId\":\"\",\"to\":\"\",\"lockToken\":\"\",\"correlationId\":\"\",\"userId\":\"\"} +1m\r\nSEND:  5\r\n  azure-iot-device-mqtt:Mqtt sendEvent {\"data\":...}\",\"properties\":{\"propertyList\":[]},\"messageId\":\"\",\"to\":\"\",\"lockToken\":\"\",\"correlationId\":\"\",\"userId\":\"\"} +1m\r\n```\r\n\r\n# Final thoughts\r\n\r\nCould be the same or related to #175, but i'm not completly shure.\r\nCould also be the case when using AMQP. I switched to AMQP and back early when investigating with same results.\r\n... and could also be a problem of the underlying libs (mqtt, end-of-stream, node itself), but maybe it can be caught on api-level."},"comment":{"url":"https://api.github.com/repos/Azure/azure-iot-sdk-node/issues/comments/362817557","html_url":"https://github.com/Azure/azure-iot-sdk-node/issues/189#issuecomment-362817557","issue_url":"https://api.github.com/repos/Azure/azure-iot-sdk-node/issues/189","id":362817557,"user":{"login":"sgacond","id":9912606,"avatar_url":"https://avatars0.githubusercontent.com/u/9912606?v=4","gravatar_id":"","url":"https://api.github.com/users/sgacond","html_url":"https://github.com/sgacond","followers_url":"https://api.github.com/users/sgacond/followers","following_url":"https://api.github.com/users/sgacond/following{/other_user}","gists_url":"https://api.github.com/users/sgacond/gists{/gist_id}","starred_url":"https://api.github.com/users/sgacond/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/sgacond/subscriptions","organizations_url":"https://api.github.com/users/sgacond/orgs","repos_url":"https://api.github.com/users/sgacond/repos","events_url":"https://api.github.com/users/sgacond/events{/privacy}","received_events_url":"https://api.github.com/users/sgacond/received_events","type":"User","site_admin":false},"created_at":"2018-02-03T14:53:11Z","updated_at":"2018-02-03T14:53:11Z","author_association":"NONE","body":"Hi @pierreca \r\nFirst of all, sorry for the long delay!\r\nI did run some more tests but was not able to reproduce the issue anymore. As you wrote above, after twice the timeout time (6 mins), the socket is reset correctly. I did longer running tests in the past and had the behaviour of not resetting, but I don't get it reproduced anymore.\r\nOk to close for me... I'll write again, when i'm able to reproduce again.\r\nThank you very much!"}}
{"actor":{"display_login":"sgacond"}}