MQTT Direct Method execution timeout

[c-larsen]

We are using the 2016-12-06 release of the C SDK on a linux device and are experiencing that the server looses MQTT connection to the device after 10 direct method executions. When connection is lost, the C2D method execution times out for 6 method executions until device connection is automatically reestablished. Once connection is reestablished, we are again able to do 10 successful direct method executions until the device disconnects.

Looking at the output on the device it is clear that the requested method is actually invoked on the device when MQTT connection looks like it is lost from the server side. However the replies being sent from the device never reaches the server and hence it times out waiting for the device to reply.

Below is a log output from the device. When we get the TOPIC_NAME: $iothub/methods/res/200/?$rid=4 output, the server requesting the method execution never receives a reply from the device. When rid is again incremented, a reply is received. Looks like the the problem is a hex/decimal mismatch problem between server/device for the $rid value?

I tried changing the following in iothubtransport_mqtt_common.c:

line 604: *request_id = (uint16_t)strtol(request_id_value+request_id_length, NULL, 16);
...
line 844: STRING_HANDLE msg_topic = STRING_construct_sprintf("$iothub/methods/res/%d/?$rid=%x", status_code, request_id);

This looks like it solves the problem, however there might be other problems related to this issue that I have not yet discovered.

-> 19:02:16 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE | TOPIC_NAME: $iothub/methods/res/200/?$rid=45 | PAYLOAD_LEN: 44
<- 19:02:17 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE = 0x00 | TOPIC_NAME: $iothub/methods/POST/WhatIsPlaying/?$rid=46 | PAYLOAD_LE
N: 2
-> 19:02:17 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE | TOPIC_NAME: $iothub/methods/res/200/?$rid=46 | PAYLOAD_LEN: 44
<- 19:02:18 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE = 0x00 | TOPIC_NAME: $iothub/methods/POST/WhatIsPlaying/?$rid=47 | PAYLOAD_LE
N: 2
-> 19:02:18 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE | TOPIC_NAME: $iothub/methods/res/200/?$rid=47 | PAYLOAD_LEN: 44
<- 19:02:19 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE = 0x00 | TOPIC_NAME: $iothub/methods/POST/WhatIsPlaying/?$rid=48 | PAYLOAD_LE
N: 2
-> 19:02:19 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE | TOPIC_NAME: $iothub/methods/res/200/?$rid=48 | PAYLOAD_LEN: 44
<- 19:02:20 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE = 0x00 | TOPIC_NAME: $iothub/methods/POST/WhatIsPlaying/?$rid=49 | PAYLOAD_LE
N: 2
-> 19:02:20 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE | TOPIC_NAME: $iothub/methods/res/200/?$rid=49 | PAYLOAD_LEN: 44
<- 19:02:21 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE = 0x00 | TOPIC_NAME: $iothub/methods/POST/WhatIsPlaying/?$rid=4a | PAYLOAD_LE
N: 2
-> 19:02:21 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE | TOPIC_NAME: $iothub/methods/res/200/?$rid=4 | PAYLOAD_LEN: 44
<- 19:02:22 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE = 0x00 | TOPIC_NAME: $iothub/methods/POST/WhatIsPlaying/?$rid=4b | PAYLOAD_LE
N: 2
-> 19:02:22 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE | TOPIC_NAME: $iothub/methods/res/200/?$rid=4 | PAYLOAD_LEN: 44
<- 19:02:27 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE = 0x00 | TOPIC_NAME: $iothub/methods/POST/WhatIsPlaying/?$rid=4c | PAYLOAD_LE
N: 2
-> 19:02:27 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE | TOPIC_NAME: $iothub/methods/res/200/?$rid=4 | PAYLOAD_LEN: 44
<- 19:02:29 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE = 0x00 | TOPIC_NAME: $iothub/methods/POST/WhatIsPlaying/?$rid=4d | PAYLOAD_LE
N: 2
-> 19:02:29 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE | TOPIC_NAME: $iothub/methods/res/200/?$rid=4 | PAYLOAD_LEN: 44
<- 19:02:31 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE = 0x00 | TOPIC_NAME: $iothub/methods/POST/WhatIsPlaying/?$rid=4e | PAYLOAD_LE
N: 2
-> 19:02:31 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE | TOPIC_NAME: $iothub/methods/res/200/?$rid=4 | PAYLOAD_LEN: 44
<- 19:02:36 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE = 0x00 | TOPIC_NAME: $iothub/methods/POST/WhatIsPlaying/?$rid=4f | PAYLOAD_LE
N: 2
-> 19:02:36 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE | TOPIC_NAME: $iothub/methods/res/200/?$rid=4 | PAYLOAD_LEN: 44
<- 19:02:40 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE = 0x00 | TOPIC_NAME: $iothub/methods/POST/WhatIsPlaying/?$rid=50 | PAYLOAD_LE
N: 2
-> 19:02:40 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE | TOPIC_NAME: $iothub/methods/res/200/?$rid=50 | PAYLOAD_LEN: 44
<- 19:16:23 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE = 0x00 | TOPIC_NAME: $iothub/methods/POST/WhatIsPlaying/?$rid=51 | PAYLOAD_LE
N: 2
-> 19:16:23 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE | TOPIC_NAME: $iothub/methods/res/200/?$rid=51 | PAYLOAD_LEN: 44
<- 19:16:27 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE = 0x00 | TOPIC_NAME: $iothub/methods/POST/WhatIsPlaying/?$rid=52 | PAYLOAD_LE
N: 2
-> 19:16:27 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE | TOPIC_NAME: $iothub/methods/res/200/?$rid=52 | PAYLOAD_LEN: 44
<- 19:16:29 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE = 0x00 | TOPIC_NAME: $iothub/methods/POST/WhatIsPlaying/?$rid=53 | PAYLOAD_LE
N: 2

[damonbarry]

This is fixed, commit f48df95 is in develop.