Azure-iot-sdk-c: No reconnection after network disconnection
Hi,
I'm facing the some problems with the connection to the IoTHub after connection lose.
Setup
I'm running the last version of the SDK 2017-10-09 on Ubuntu 16.04.
Ubuntu is running on a VM on a Windows 10.
Description
I'm running a simple client that send every 5 seconds a message on the IoTHub.
The transport protocol used is MQTT.
Case 1 (working)
When the device is disconnected "locally" (see schema below) the SDK handles the reconnection properly after some time when the connection is back. The messages are correctly enqueued and are sent as soon as the connection is back.
|device|---------|Ubuntu(VM)|----X----|Windows|---------|Internet|---------|IoTHub|
Case 2 (not working)
When the device is disconnected from windows (we cut the connection), The socket in the SDK receive a signal 13 (SIGPIPE) and the connection is not recovered.
|device|---------|Ubuntu(VM)|---------|Windows|----X----|Internet|---------|IoTHub|
In fact, we observed the same behavior on a real device, when the internet connection is lost by a switch.
|device|---------|switch|----X----|Internet|---------|IoTHub|
Logs
Case 1 (working)
see https://gist.github.com/alexmrtn/749448cb1ef0d2fff6af8e030200f002
Case 2 (not working)
[13:25:57.738][INFO ]{iothubAgentExample_send.c:134} A message will be sent in 5 seconds
[13:25:57.738][ERROR]{socketio_berkeley.c:242} Socket received signal 13.
[13:25:57.739][ERROR]{wsio.c:448} on_underlying_ws_error called with error code 3
[13:25:57.741][ERROR]{socketio_berkeley.c:814} Failure: sending socket failed. errno=107 (Transport endpoint is not connected).
[13:25:57.741][ERROR]{http_proxy_io.c:851} Underlying xio_send failed.
[13:25:57.741][ERROR]{tlsio_openssl.c:585} Error in xio_send.
[13:25:57.741][ERROR]{tlsio_openssl.c:1314} Error in write_outgoing_bytes.
[13:25:57.741][ERROR]{uws_client.c:1778} Could not send bytes through the underlying IO
[13:25:57.741][ERROR]{wsio.c:611} Failed removing pending IO from linked list.
[13:25:57.741][ERROR]{mqtt_client.c:332} 615: Failure sending control packet data
[13:25:57.741][ERROR]{mqtt_client.c:1030} Error: mqtt_client_publish send failed
[13:25:57.741][ERROR]{iothubtransport_mqtt_common.c:7:} Failed attempting to publish mqtt message
[13:25:57.741][INFO ]{iothubAgentExample_send.c:66} Send confirmation callback: messageId [00005], err=1
Related issues
It seems that issues https://github.com/Azure/azure-iot-sdk-c/issues/212 and https://github.com/Azure/azure-c-shared-utility/issues/105 are related to this one. To be confirmed.
alexmrtn
All 16 comments
Hi,
As suggested, I reproduced the same experiment using the master branch.
The good new is that we don't get the signal 13 anymore. But the reconnection is still blocked because of a TLS error.
log of the disconnection
[08:15:39.498][DEBUG]{iothubAgent_sendMessage.c:167} Sending message [00005]...
[08:15:39.498][INFO ]{iothubAgent_sendMessage.c:145} Message [00005] put in the outgoing queue
[08:15:39.498][INFO ]{iothubAgentExample_send.c:141} iothubAgent_send (messageId: 00005) returned 0
[08:15:39.498][INFO ]{iothubAgentExample_send.c:134} A message will be sent in 5 seconds
[08:15:43.890][ERROR]{socketio_berkeley.c:931} Socketio_Failure: Receiving data from endpoint: errno=104.
[08:15:43.890][ERROR]{wsio.c:448} on_underlying_ws_error called with error code 3
[08:15:43.895][ERROR]{socketio_berkeley.c:697} Failure: connect failure 113.
[08:15:43.896][ERROR]{http_proxy_io.c:271} Underlying IO open failed
[08:15:43.896][ERROR]{wsio.c:150} wsio_close when not open.
[08:15:43.901][ERROR]{tlsio_openssl.c:688} Invalid tlsio_state. Expected state is TLSIO_STATE_OPENING_UNDERLYING_IO.
[08:15:43.901][ERROR]{http_proxy_io.c:740} Cannot open the underlying IO.
[08:15:43.901][ERROR]{tlsio_openssl.c:1202} Failed opening the underlying I/O.
[08:15:43.901][ERROR]{uws_client.c:1472} Opening the underlying IO failed
[08:15:43.901][ERROR]{wsio.c:513} Opening the uws instance failed.
[08:15:43.901][ERROR]{mqtt_client.c:971} Error: io_open failed
[08:15:43.901][ERROR]{iothubtransport_mqtt_common.c:1:} failure connecting to address ####.
[08:15:44.004][ERROR]{socketio_berkeley.c:697} Failure: connect failure 113.
[08:15:44.004][ERROR]{http_proxy_io.c:271} Underlying IO open failed
[08:15:44.004][ERROR]{wsio.c:150} wsio_close when not open.
[08:15:44.007][ERROR]{tlsio_openssl.c:688} Invalid tlsio_state. Expected state is TLSIO_STATE_OPENING_UNDERLYING_IO.
[08:15:44.007][ERROR]{http_proxy_io.c:740} Cannot open the underlying IO.
[08:15:44.007][ERROR]{tlsio_openssl.c:1202} Failed opening the underlying I/O.
[08:15:44.007][ERROR]{uws_client.c:1472} Opening the underlying IO failed
[08:15:44.007][ERROR]{wsio.c:513} Opening the uws instance failed.
[08:15:44.007][ERROR]{mqtt_client.c:971} Error: io_open failed
[08:15:44.007][ERROR]{iothubtransport_mqtt_common.c:1:} failure connecting to address ####.
log when trying the reconnection
[08:16:44.518][INFO ]{iothubAgent_sendMessage.c:145} Message [00018] put in the outgoing queue
[08:16:44.518][INFO ]{iothubAgentExample_send.c:141} iothubAgent_send (messageId: 00018) returned 0
[08:16:44.518][INFO ]{iothubAgentExample_send.c:134} A message will be sent in 5 seconds
[08:16:46.044][INFO ]{tlsio_openssl.c:617} error:1408F10B:SSL routines:SSL3_GET_RECORD:wrong version number
[08:16:46.044][ERROR]{wsio.c:150} wsio_close when not open.
Some more information:
I traced the network packets in order to observe what happen during the disconnection for both cases describe above. Here what I found.
Case 1 (working)
267 50.018531833 205.167.7.126 10.0.2.15 TCP 60 80 → 45286 [ACK] Seq=741 Ack=2047 Win=65535 Len=0
268 50.142907624 205.167.7.126 10.0.2.15 TCP 128 80 → 45286 [PSH, ACK] Seq=741 Ack=2047 Win=65535 Len=74
269 50.142920681 10.0.2.15 205.167.7.126 TCP 54 45286 → 80 [ACK] Seq=2047 Ack=815 Win=45440 Len=0
270 55.017697207 10.0.2.15 205.167.7.126 TCP 240 45286 → 80 [PSH, ACK] Seq=2047 Ack=815 Win=45440 Len=186
271 55.018311994 205.167.7.126 10.0.2.15 TCP 60 80 → 45286 [ACK] Seq=815 Ack=2233 Win=65535 Len=0
272 55.137525865 205.167.7.126 10.0.2.15 TCP 128 80 → 45286 [PSH, ACK] Seq=815 Ack=2233 Win=65535 Len=74
273 55.137555180 10.0.2.15 205.167.7.126 TCP 54 45286 → 80 [ACK] Seq=2233 Ack=889 Win=45440 Len=0
371 90.039107032 10.0.2.15 205.167.7.126 TCP 1356 45286 → 80 [PSH, ACK] Seq=2233 Ack=889 Win=45440 Len=1302
372 90.039502170 205.167.7.126 10.0.2.15 TCP 60 80 → 45286 [ACK] Seq=889 Ack=3535 Win=65535 Len=0
374 90.144125420 205.167.7.126 10.0.2.15 TCP 128 80 → 45286 [PSH, ACK] Seq=889 Ack=3535 Win=65535 Len=74
375 90.144135657 10.0.2.15 205.167.7.126 TCP 54 45286 → 80 [ACK] Seq=3535 Ack=963 Win=45440 Len=0
376 90.163543094 205.167.7.126 10.0.2.15 TCP 128 80 → 45286 [PSH, ACK] Seq=963 Ack=3535 Win=65535 Len=74
377 90.163559021 10.0.2.15 205.167.7.126 TCP 54 45286 → 80 [ACK] Seq=3535 Ack=1037 Win=45440 Len=0
378 90.185305236 205.167.7.126 10.0.2.15 TCP 128 80 → 45286 [PSH, ACK] Seq=1037 Ack=3535 Win=65535 Len=74
379 90.185319956 10.0.2.15 205.167.7.126 TCP 54 45286 → 80 [ACK] Seq=3535 Ack=1111 Win=45440 Len=0
381 90.206419756 205.167.7.126 10.0.2.15 TCP 128 80 → 45286 [PSH, ACK] Seq=1111 Ack=3535 Win=65535 Len=74
382 90.206431647 10.0.2.15 205.167.7.126 TCP 54 45286 → 80 [ACK] Seq=3535 Ack=1185 Win=45440 Len=0
The disconnection happens at packet 273, when the connection is back we see that the messaging process continue normally at packet 371 and after.
Case 2 (not working)
630 341.781848214 205.167.7.126 10.0.2.15 TCP 60 80 → 45184 [ACK] Seq=4737 Ack=12277 Win=65535 Len=0
631 343.648189411 10.0.2.15 205.167.7.126 TCP 240 45184 → 80 [PSH, ACK] Seq=12277 Ack=4737 Win=45440 Len=186
632 343.648457855 205.167.7.126 10.0.2.15 TCP 60 80 → 45184 [ACK] Seq=4737 Ack=12463 Win=65535 Len=0
633 348.649561971 10.0.2.15 205.167.7.126 TCP 240 45184 → 80 [PSH, ACK] Seq=12463 Ack=4737 Win=45440 Len=186
634 348.649846226 205.167.7.126 10.0.2.15 TCP 60 80 → 45184 [ACK] Seq=4737 Ack=12649 Win=65535 Len=0
652 352.861817949 205.167.7.126 10.0.2.15 TCP 60 80 → 45184 [RST, ACK] Seq=4737 Ack=12649 Win=65535 Len=0
The disconnection happens at packet 634, but in this case we get a RESET TCP (packet 652) that kills the connection. The connection is never back on after that.
Reproducing the bug
In order to reproduce this behavior, I used the tcpkill tool that provide a way to force TCP RST as we had in the case 2.
With this tool we was able to reproduce this error. However we still have the error:1408F10B:SSL routines:SSL3_GET_RECORD:wrong version numbermentioned in the previous post.
The fact that we run the client in a VM seems not to be related to this problem. I'm currently unable to test this behavior on a non hosted Linux but I'll post the result if I can.
alexmrtn
on 18 Oct 2017
After some investigation, the SLL problem seems to be present only if we connect a device through a proxy. I was able to test and validate the similar behavior on a raspberry pi. The reconnection works well if we are directly connected to the iotHub, but not behind a simple proxy server.
alexmrtn
on 23 Oct 2017
Hi @alexmrtn ,
what kind of authentication are you using? SAS, or x509?
We had several issues fixed recently. Would it be possible for you to verify the failing scenario above using the latest SDK code from master branch?
ewertons
on 29 Nov 2017
Hi @ewertons,
We use SAS authentication method. As today on the master branch of the SDK this problem is still present.
alexmrtn
on 30 Nov 2017
Thanks for confirming, @alexmrtn .
We will verify this issue and report back with the fix soon.
ewertons
on 30 Nov 2017
Hi @ewertons,
Did you find something new related to this issue?
I did few tests and it seems to be present only when using the MQTT/Websockeet transport protocol. On AMQP/Websocket it works fine.
The error:1408F10B:SSL routines:SSL3_GET_RECORD:wrong version number seems to come from an error when doing the TLS handshake (the second one when it tries to reconnect to the iothub).
I'm continuing to investigate this, looking inside the iothub_client/src/iothubtransport_mqtt_common.c file as it only happens using this protocol.
alexmrtn
on 17 Jan 2018
@alexmrtn - We fixed some issues related to MQTT over websockets and are part of our latest release. Did this happen again on your end with the latest release?
tameraw
on 18 Jan 2018
Hi @tameraw , unfortunately this problem is still there on the 2018-01-12 release.
alexmrtn
on 19 Jan 2018
Release: 2018-02-09
Operating System: macOS 10.12.3 (also reproducible on Ubuntu 16.04 LTS)
Protocol: MQTT_WebSocket_Protocol
Source: devicemethod_simplesample under serializer samples(with minor changes for websockets and Cntlm IP/port).
I am able to consistently and quickly reproduce this error(SSL routines:SSL3_GET_RECORD:wrong version number) when running serializer sample devicemethod_simplesample behind a Cntlm(1). Cntlm is used only as a simple proxy server as suggested by original poster. Setup below.
|device|---X---|Cntlm|-----|Internet|
Steps to reproduce
- Setup and start Cntlm to listen on localhost/local port. There is no need of any secondary HTTP proxy. Setup Cntlm to pass through all addresses. This is done by giving
*underNoProxylist in _cntlm.conf_ which mostly resides in _/etc/cntlm.conf_. - Modify devicemethod_simplesample.c(2) to connect to Cntlm provided localhost / local port using
MQTT_WebSocket_ProtocolandOPTION_HTTP_PROXYoptions. Start devicemethod_simplesample. - Restart Cntlm and wait to see the error.
kiranpradeep
on 23 Feb 2018
This exists in 1.0.0-pre-release-1.0.8 release also. This issue is consistently reproducible with minimal setup effort on both macOS and Ubuntu. I am fully available for any query regarding reproducing this issue. Please let me know.
kiranpradeep
on 13 Mar 2018
Hi @kiranpradeep,
You're right. I was able to reproduce this error with cntlm too. In fact I didn't break the connection, I simply restarted the proxy server and saw the message:
Info: error:1408F10B:SSL routines:SSL3_GET_RECORD:wrong version number
I'll look into this further.
_Mark Radbourne MSFT_
markrad
on 19 Mar 2018
First thanks to everyone for repro steps & my apologies that this has lingered so long.
;tl-dr. We have a provisional fix, look for it sometime next week. It will make the 3/30 release.
Because I'm guessing the audience here is geeks and wants the details...
MQTT_WS on reconnection is not properly blasting the tlsio_* layer and there's cached gunk lying around that we pass to openssl, schannel (this repros on Windows). AMQP_WS in fact does clean up after itself which is why this bug doesn't repro on it.
I've put in a proof of concept in MQTT where its much more aggressive cleaning up its lower layer. It's working very well in smoke tests; I've killed proxy ~10 times across varying lengths of timeouts and MQTT_WS always returns. On both Windows 10 and Ubuntu 16.04.
Even though this is like a 2 liner and even though we have auto-fault injection tests that run on the gate (for non-proxies) which in theory would catch regressions, changes like this are going to get additional human review of change itself. We're also going to see if other places have this class of bug. So sometime next week is our timeline.
https://github.com/Azure/azure-iot-sdk-c/compare/mqtt-ws-proxy has wave 1 of the fix; it's not the final (there's false positive error messages and it may make sense to break this function up instead of the if checks).
jspaith
on 23 Mar 2018
Thanks for keeping us in touch. It will be awesome if it makes the 3/30 release!
alexmrtn
on 26 Mar 2018
We have submitted the fix. https://github.com/Azure/azure-iot-sdk-c/commit/f0ad9e3c63dcff3276473be17e6026d4c47e625c
This will make the 3/30 release (which we held explicitly so it would).
jspaith
on 31 Mar 2018
@alexmrtn thank you for your contribution to our open-sourced project! Please help us improve by filling out this 2-minute customer satisfaction survey.
tameraw
on 24 Apr 2018
Related issues
chinnaece
·
5Comments
geebinge
·
4Comments
duvitech
·
6Comments
zvrba
·
5Comments
kenyelima
·
3Comments