Azure-iot-sdk-c: If module crashes expected redelilivery did not happen - at-least-once semantic is broken

Created on 7 Feb 2020  路  16Comments  路  Source: Azure/azure-iot-sdk-c

If a module consuming message from the hub crashes redelivery of the message did not happen.

This is basically a restart point of https://github.com/Azure/iotedge/issues/2089.
But it is not worth reading through this again - we should start from scratch!

The complete reproduction can be found at https://github.com/alaendle/showcase-edge-transaction.

To explain the issue and the reproduction a little further...

I have a source module sending messages, and a corresponding sink module receiving the messages - both are just newly created C Modules in VSCode with latest templates and SDK's with slightest modifications to create a showcase for this issue.

There is only one route just connecting the two modules

https://github.com/alaendle/showcase-edge-transaction/blob/c082f9939ef4cdb831fc42474690f470e88847d1/deployment.template.json#L92

Unfortunately the event sink crashes on telegram "50" (just to simulate a crash)

https://github.com/alaendle/showcase-edge-transaction/blob/c082f9939ef4cdb831fc42474690f470e88847d1/modules/Sink/main.c#L54-L57

For sure the module recovers and receives the other telegrams - but it never sees telegram "50" again - so it seems to got lost during the crash.

I wonder how this could be the case if QoS=1 is the default.

My expectation would be that telegram "50" gets redelivered - at least after some time; since it should never have been acknowledged.

Or in other words; I wonder if it is possible to write a C module that receives data from the edge with AT-LEAST-ONCE semantic.

Please also note that the C# SDK behaves differently - even if MQTT is used - so if an exception or crash happens during the callback the message gets redelivered.

https://github.com/alaendle/showcase-edge-transaction/blob/428c8c8b352a9e95525ac4d52762df0eeb43b51b/modules/SharpSink/Program.cs#L76-L78

Console Logs

Here it gets really weird - from my point of view; and I think this might lead us to the right direction...

It looks normal for the 'sender' module.

-> 06:30:55 CONNECT | VER: 4 | KEEPALIVE: 240 | FLAGS: 192 | USERNAME: [username]/demo/Source/?api-version=2017-11-08-preview&DeviceClientType=iothubclient%2f1.3.8%20(native%3b%20Linux%3b%20x86_64) | PWD: XXXX | CLEAN: 0
<- 06:30:56 CONNACK | SESSION_PRESENT: false | RETURN_CODE: 0x0
-> 06:30:58 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_LEAST_ONCE | TOPIC_NAME: devices/demo/modules/Source/messages/events/%24.on=output1/ | PACKET_ID: 2 | PAYLOAD_LEN: 1
-> 06:30:58 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_LEAST_ONCE | TOPIC_NAME: devices/demo/modules/Source/messages/events/%24.on=output1/ | PACKET_ID: 3 | PAYLOAD_LEN: 1
-> 06:30:58 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_LEAST_ONCE | TOPIC_NAME: devices/demo/modules/Source/messages/events/%24.on=output1/ | PACKET_ID: 4 | PAYLOAD_LEN: 1
-> 06:30:58 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_LEAST_ONCE | TOPIC_NAME: devices/demo/modules/Source/messages/events/%24.on=output1/ | PACKET_ID: 5 | PAYLOAD_LEN: 1
-> 06:30:58 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_LEAST_ONCE | TOPIC_NAME: devices/demo/modules/Source/messages/events/%24.on=output1/ | PACKET_ID: 6 | PAYLOAD_LEN: 1
-> 06:30:58 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_LEAST_ONCE | TOPIC_NAME: devices/demo/modules/Source/messages/events/%24.on=output1/ | PACKET_ID: 7 | PAYLOAD_LEN: 1
-> 06:30:58 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_LEAST_ONCE | TOPIC_NAME: devices/demo/modules/Source/messages/events/%24.on=output1/ | PACKET_ID: 8 | PAYLOAD_LEN: 1
-> 06:30:59 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_LEAST_ONCE | TOPIC_NAME: devices/demo/modules/Source/messages/events/%24.on=output1/ | PACKET_ID: 9 | PAYLOAD_LEN: 1
<- 06:30:59 PUBACK | PACKET_ID: 2
<- 06:30:59 PUBACK | PACKET_ID: 3
<- 06:30:59 PUBACK | PACKET_ID: 4
<- 06:30:59 PUBACK | PACKET_ID: 5
<- 06:30:59 PUBACK | PACKET_ID: 6
<- 06:30:59 PUBACK | PACKET_ID: 7
...

But the 'sink' log reveals the following

-> 06:30:54 CONNECT | VER: 4 | KEEPALIVE: 240 | FLAGS: 192 | USERNAME: [username]/demo/Sink/?api-version=2017-11-08-preview&DeviceClientType=iothubclient%2f1.3.8%20(native%3b%20Linux%3b%20x86_64) | PWD: XXXX | CLEAN: 0
<- 06:30:54 CONNACK | SESSION_PRESENT: false | RETURN_CODE: 0x0
-> 06:30:54 SUBSCRIBE | PACKET_ID: 2 | TOPIC_NAME: devices/demo/modules/Sink/# | QOS: 0
<- 06:30:55 SUBACK | PACKET_ID: 2 | RETURN_CODE: 0
<- 06:30:59 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/demo/modules/Sink/inputs/input1/%24.cdid=demo&%24.cmid=Source | PAYLOAD_LEN: 1
<- 06:30:59 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/demo/modules/Sink/inputs/input1/%24.cdid=demo&%24.cmid=Source | PAYLOAD_LEN: 1
<- 06:30:59 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/demo/modules/Sink/inputs/input1/%24.cdid=demo&%24.cmid=Source | PAYLOAD_LEN: 1
<- 06:30:59 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/demo/modules/Sink/inputs/input1/%24.cdid=demo&%24.cmid=Source | PAYLOAD_LEN: 1
...

What immediately caught my attention here...

-> 06:30:54 SUBSCRIBE | PACKET_ID: 2 | TOPIC_NAME: devices/demo/modules/Sink/# | QOS: 0
<- 06:30:59 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/demo/modules/Sink/inputs/input1/%24.cdid=demo&%24.cmid=Source | PAYLOAD_LEN: 1

Why does the subscribe specify a maximum QoS of 0 - this would explain the message loss; but I thought QoS=1 is the default? The other question that arises, why is the QoS value of the PUBLISH packet invalid?

bug investigation-required
Source
picture alaendle

Most helpful comment

Hey @alaendle ,
thanks for your patience.
I am puzzled how I managed to go off the tracks on this issue.

I will write the whole scenario here so it is clear:

  1. azure-iot-sdk-c is subscribing for Edge Input queue using QoS 0 (as you pointed by the code search you did);
  2. QoS 0 (AT MOST ONCE) means "fire and forget", so Edge hub would not expect a PUBACK, once it sends the message it dequeues it and considers it delivered;

So, obviously (as a note to myself), the reason why you are not receiving an Edge-to-Device message again after a crash is because azure-iot-sdk-c is subscribing with QoS 0.

Points worth listing:

  1. You mention that azure-iot-sdk-csharp behaves differently, and that's expected because that code subscribes using QoS 1 (AT LEAST ONCE), guaranteeing the sender (Edge) will resend it if it does not receive a PUBACK;

MqttTransportHandler.cs:841: await _channel.WriteAsync(new SubscribePacket(0, new SubscriptionRequest(_receiveEventMessageFilter, _qos))).ConfigureAwait(true);
MqttTransportHandler.cs:833: public override async Task EnableEventReceiveAsync(CancellationToken cancellationToken)
...csharp
InternalClient.cs:1947: private Task EnableEventReceiveAsync(CancellationToken cancellationToken)
InternalClient.cs:1733: public async Task SetInputMessageHandlerAsync(string inputName, MessageHandler messageHandler, object userContext, CancellationToken cancellationToken)
InternalClient.cs:1708: public async Task SetInputMessageHandlerAsync(string inputName, MessageHandler messageHandler, object userContext)
ModuleClient.cs:553: public Task SetInputMessageHandlerAsync(string inputName, MessageHandler messageHandler, object userContext)

MqttTransportHandler.cs:159:
            _qos = settings.PublishToServerQoS;

MqttTransportSettings.cs:27:
        private const QualityOfService DefaultPublishToServerQoS = QualityOfService.AtLeastOnce;

QualityOfService.cs:10
        AtLeastOnce = 1,
  1. azure-iot-sdk-c subscribes to Edge input queue and IoT Hub messages/devicebound with different QoS (0 and 1, respectivelly), so that's why I did not get a repro right away;
  2. Even if azure-iot-sdk-c subscribe to IoT Edge input queue with QoS 1, you would not receive the message again in this scenario if using iothub_device_client.h (the multi-threaded layer on top of iothub_device_client_ll.h) - because in this case the PUBACK would be sent before the callback is invoked to the user app.

So the main ask is if we can change the QoS on the azure-iot-sdk-c subscription for IoT Edge Input messages to QoS 1.
I made such change in this branch, could you validate if it satisfies your request?

Once you confirm, I will consult with my team about merging it.

picture ewertons on 25 Feb 2021
👀1 🚀1 ❤1

All 16 comments

Guess again my assumption was wrong to expect the QoS > 0 on subscriber side.
https://github.com/Azure/azure-iot-sdk-c/blob/b617a8288690df6ef89247647c6adb37b92da880/iothub_client/src/iothubtransport_mqtt_common.c#L1968-L1971
But honestly, is this a good default behaviour? Personally I think most module expect to see their messages at least once; at least the SDK should make that possible.

alaendle picture alaendle on 10 Feb 2020

Sorry for delay here @alaendle. Setting to Qos0 does indeed explain a lot (albeit it the discussions about us PUBACK'ng prior to callback called are still interesting).

I reviewed our MQTT <=> Hub docs here and it's not prescriptive RE QoS level.

@jebrando - do you remember any background about why we made this decision in MQTT? Thanks

jspaith picture jspaith on 15 Feb 2020

@alaendle ,
we are currently investigating this issue. Thanks for all the explanation provided, your level of detail is very good and will help us narrow this root-causing.

We understand you have attempted this scenario quite some time ago, but just in case, would you have the complete logs for the failure instance you described? Not only the excerpts above, but the complete logs up to the crash on the sink application.
Not having the logs will not block the verification on our side, but will help considerably.

ewertons picture ewertons on 13 Jul 2020

@ewertons Thanks for the complements. Since it is easy for me to rerun the reproduction showcase I'm happy to provide the desired log. Hopefully it shows what you have expected - please don't hesitate to contact me if I am able to further contribute to your investigations.

Error: Time:Tue Jul 14 08:37:20 2020 File:/build/azure-c-shared-util-SA7n2E/azure-c-shared-util-0.2.0.0/adapters/socketio_berkeley.c Func:wait_for_connection Line:425 Failure: connect failure 111.
Error: Time:Tue Jul 14 08:37:20 2020 File:/build/azure-c-shared-util-SA7n2E/azure-c-shared-util-0.2.0.0/adapters/socketio_berkeley.c Func:socketio_open Line:827 wait_for_connection failed
Error: Time:Tue Jul 14 08:37:20 2020 File:/build/azure-umqtt-c-GIxo0_/azure-umqtt-c-0.2.0.0/src/mqtt_client.c Func:onOpenComplete Line:454 Error: failure opening connection to endpoint
Error: Time:Tue Jul 14 08:37:20 2020 File:/build/azure-c-shared-util-SA7n2E/azure-c-shared-util-0.2.0.0/adapters/tlsio_openssl.c Func:on_underlying_io_open_complete Line:760 Invalid tlsio_state. Expected state is TLSIO_STATE_OPENING_UNDERLYING_IO.
Error: Time:Tue Jul 14 08:37:20 2020 File:/build/azure-c-shared-util-SA7n2E/azure-c-shared-util-0.2.0.0/adapters/tlsio_openssl.c Func:tlsio_openssl_open Line:1258 Failed opening the underlying I/O.
Error: Time:Tue Jul 14 08:37:20 2020 File:/build/azure-umqtt-c-GIxo0_/azure-umqtt-c-0.2.0.0/src/mqtt_client.c Func:mqtt_client_connect Line:1042 Error: io_open failed
Error: Time:Tue Jul 14 08:37:20 2020 File:/build/azure-iot-sdk-c-nKXWlz/azure-iot-sdk-c-0.2.0.0/iothub_client/src/iothubtransport_mqtt_common.c Func:SendMqttConnectMsg Line:2282 failure connecting to address [host].
Error: Time:Tue Jul 14 08:37:20 2020 File:/build/azure-c-shared-util-SA7n2E/azure-c-shared-util-0.2.0.0/adapters/socketio_berkeley.c Func:wait_for_connection Line:425 Failure: connect failure 111.
Error: Time:Tue Jul 14 08:37:20 2020 File:/build/azure-c-shared-util-SA7n2E/azure-c-shared-util-0.2.0.0/adapters/socketio_berkeley.c Func:socketio_open Line:827 wait_for_connection failed
Error: Time:Tue Jul 14 08:37:20 2020 File:/build/azure-umqtt-c-GIxo0_/azure-umqtt-c-0.2.0.0/src/mqtt_client.c Func:onOpenComplete Line:454 Error: failure opening connection to endpoint
Error: Time:Tue Jul 14 08:37:20 2020 File:/build/azure-c-shared-util-SA7n2E/azure-c-shared-util-0.2.0.0/adapters/tlsio_openssl.c Func:on_underlying_io_open_complete Line:760 Invalid tlsio_state. Expected state is TLSIO_STATE_OPENING_UNDERLYING_IO.
Error: Time:Tue Jul 14 08:37:20 2020 File:/build/azure-c-shared-util-SA7n2E/azure-c-shared-util-0.2.0.0/adapters/tlsio_openssl.c Func:tlsio_openssl_open Line:1258 Failed opening the underlying I/O.
Error: Time:Tue Jul 14 08:37:20 2020 File:/build/azure-umqtt-c-GIxo0_/azure-umqtt-c-0.2.0.0/src/mqtt_client.c Func:mqtt_client_connect Line:1042 Error: io_open failed
Error: Time:Tue Jul 14 08:37:20 2020 File:/build/azure-iot-sdk-c-nKXWlz/azure-iot-sdk-c-0.2.0.0/iothub_client/src/iothubtransport_mqtt_common.c Func:SendMqttConnectMsg Line:2282 failure connecting to address [host].
Error: Time:Tue Jul 14 08:37:21 2020 File:/build/azure-c-shared-util-SA7n2E/azure-c-shared-util-0.2.0.0/adapters/socketio_berkeley.c Func:wait_for_connection Line:425 Failure: connect failure 111.
Error: Time:Tue Jul 14 08:37:21 2020 File:/build/azure-c-shared-util-SA7n2E/azure-c-shared-util-0.2.0.0/adapters/socketio_berkeley.c Func:socketio_open Line:827 wait_for_connection failed
Error: Time:Tue Jul 14 08:37:21 2020 File:/build/azure-umqtt-c-GIxo0_/azure-umqtt-c-0.2.0.0/src/mqtt_client.c Func:onOpenComplete Line:454 Error: failure opening connection to endpoint
Error: Time:Tue Jul 14 08:37:21 2020 File:/build/azure-c-shared-util-SA7n2E/azure-c-shared-util-0.2.0.0/adapters/tlsio_openssl.c Func:on_underlying_io_open_complete Line:760 Invalid tlsio_state. Expected state is TLSIO_STATE_OPENING_UNDERLYING_IO.
Error: Time:Tue Jul 14 08:37:21 2020 File:/build/azure-c-shared-util-SA7n2E/azure-c-shared-util-0.2.0.0/adapters/tlsio_openssl.c Func:tlsio_openssl_open Line:1258 Failed opening the underlying I/O.
Error: Time:Tue Jul 14 08:37:21 2020 File:/build/azure-umqtt-c-GIxo0_/azure-umqtt-c-0.2.0.0/src/mqtt_client.c Func:mqtt_client_connect Line:1042 Error: io_open failed
Error: Time:Tue Jul 14 08:37:21 2020 File:/build/azure-iot-sdk-c-nKXWlz/azure-iot-sdk-c-0.2.0.0/iothub_client/src/iothubtransport_mqtt_common.c Func:SendMqttConnectMsg Line:2282 failure connecting to address [host].
-> 08:37:23 CONNECT | VER: 4 | KEEPALIVE: 240 | FLAGS: 192 | USERNAME: [user]-dev.azure-devices.net/demo/Sink/?api-version=2017-11-08-preview&DeviceClientType=iothubclient%2f1.3.8%20(native%3b%20Linux%3b%20x86_64) | PWD: XXXX | CLEAN: 0
<- 08:37:23 CONNACK | SESSION_PRESENT: false | RETURN_CODE: 0x0
-> 08:37:23 SUBSCRIBE | PACKET_ID: 2 | TOPIC_NAME: devices/demo/modules/Sink/# | QOS: 0
<- 08:37:23 SUBACK | PACKET_ID: 2 | RETURN_CODE: 0
<- 08:37:27 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/demo/modules/Sink/inputs/input1/%24.cdid=demo&%24.cmid=Source | PAYLOAD_LEN: 1
Received Data: [0]
<- 08:37:27 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/demo/modules/Sink/inputs/input1/%24.cdid=demo&%24.cmid=Source | PAYLOAD_LEN: 1
Received Data: [1]
<- 08:37:27 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/demo/modules/Sink/inputs/input1/%24.cdid=demo&%24.cmid=Source | PAYLOAD_LEN: 1
Received Data: [2]
<- 08:37:27 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/demo/modules/Sink/inputs/input1/%24.cdid=demo&%24.cmid=Source | PAYLOAD_LEN: 1
Received Data: [3]
<- 08:37:27 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/demo/modules/Sink/inputs/input1/%24.cdid=demo&%24.cmid=Source | PAYLOAD_LEN: 1
Received Data: [4]
<- 08:37:27 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/demo/modules/Sink/inputs/input1/%24.cdid=demo&%24.cmid=Source | PAYLOAD_LEN: 1
Received Data: [5]
<- 08:37:27 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/demo/modules/Sink/inputs/input1/%24.cdid=demo&%24.cmid=Source | PAYLOAD_LEN: 1
Received Data: [6]
<- 08:37:28 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/demo/modules/Sink/inputs/input1/%24.cdid=demo&%24.cmid=Source | PAYLOAD_LEN: 1
Received Data: [7]
<- 08:37:29 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/demo/modules/Sink/inputs/input1/%24.cdid=demo&%24.cmid=Source | PAYLOAD_LEN: 1
Received Data: [8]
<- 08:37:30 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/demo/modules/Sink/inputs/input1/%24.cdid=demo&%24.cmid=Source | PAYLOAD_LEN: 1
Received Data: [9]
<- 08:37:31 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/demo/modules/Sink/inputs/input1/%24.cdid=demo&%24.cmid=Source | PAYLOAD_LEN: 2
Received Data: [10]
<- 08:37:32 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/demo/modules/Sink/inputs/input1/%24.cdid=demo&%24.cmid=Source | PAYLOAD_LEN: 2
Received Data: [11]
<- 08:37:33 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/demo/modules/Sink/inputs/input1/%24.cdid=demo&%24.cmid=Source | PAYLOAD_LEN: 2
Received Data: [12]
<- 08:37:34 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/demo/modules/Sink/inputs/input1/%24.cdid=demo&%24.cmid=Source | PAYLOAD_LEN: 2
Received Data: [13]
<- 08:37:35 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/demo/modules/Sink/inputs/input1/%24.cdid=demo&%24.cmid=Source | PAYLOAD_LEN: 2
Received Data: [14]
<- 08:37:36 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/demo/modules/Sink/inputs/input1/%24.cdid=demo&%24.cmid=Source | PAYLOAD_LEN: 2
Received Data: [15]
<- 08:37:37 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/demo/modules/Sink/inputs/input1/%24.cdid=demo&%24.cmid=Source | PAYLOAD_LEN: 2
Received Data: [16]
<- 08:37:38 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/demo/modules/Sink/inputs/input1/%24.cdid=demo&%24.cmid=Source | PAYLOAD_LEN: 2
Received Data: [17]
<- 08:37:39 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/demo/modules/Sink/inputs/input1/%24.cdid=demo&%24.cmid=Source | PAYLOAD_LEN: 2
Received Data: [18]
<- 08:37:40 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/demo/modules/Sink/inputs/input1/%24.cdid=demo&%24.cmid=Source | PAYLOAD_LEN: 2
Received Data: [19]
<- 08:37:41 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/demo/modules/Sink/inputs/input1/%24.cdid=demo&%24.cmid=Source | PAYLOAD_LEN: 2
Received Data: [20]
<- 08:37:42 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/demo/modules/Sink/inputs/input1/%24.cdid=demo&%24.cmid=Source | PAYLOAD_LEN: 2
Received Data: [21]
<- 08:37:43 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/demo/modules/Sink/inputs/input1/%24.cdid=demo&%24.cmid=Source | PAYLOAD_LEN: 2
Received Data: [22]
<- 08:37:44 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/demo/modules/Sink/inputs/input1/%24.cdid=demo&%24.cmid=Source | PAYLOAD_LEN: 2
Received Data: [23]
<- 08:37:45 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/demo/modules/Sink/inputs/input1/%24.cdid=demo&%24.cmid=Source | PAYLOAD_LEN: 2
Received Data: [24]
<- 08:37:46 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/demo/modules/Sink/inputs/input1/%24.cdid=demo&%24.cmid=Source | PAYLOAD_LEN: 2
Received Data: [25]
<- 08:37:47 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/demo/modules/Sink/inputs/input1/%24.cdid=demo&%24.cmid=Source | PAYLOAD_LEN: 2
Received Data: [26]
<- 08:37:48 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/demo/modules/Sink/inputs/input1/%24.cdid=demo&%24.cmid=Source | PAYLOAD_LEN: 2
Received Data: [27]
<- 08:37:49 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/demo/modules/Sink/inputs/input1/%24.cdid=demo&%24.cmid=Source | PAYLOAD_LEN: 2
Received Data: [28]
<- 08:37:50 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/demo/modules/Sink/inputs/input1/%24.cdid=demo&%24.cmid=Source | PAYLOAD_LEN: 2
Received Data: [29]
<- 08:37:51 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/demo/modules/Sink/inputs/input1/%24.cdid=demo&%24.cmid=Source | PAYLOAD_LEN: 2
Received Data: [30]
<- 08:37:52 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/demo/modules/Sink/inputs/input1/%24.cdid=demo&%24.cmid=Source | PAYLOAD_LEN: 2
Received Data: [31]
<- 08:37:53 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/demo/modules/Sink/inputs/input1/%24.cdid=demo&%24.cmid=Source | PAYLOAD_LEN: 2
Received Data: [32]
<- 08:37:54 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/demo/modules/Sink/inputs/input1/%24.cdid=demo&%24.cmid=Source | PAYLOAD_LEN: 2
Received Data: [33]
<- 08:37:55 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/demo/modules/Sink/inputs/input1/%24.cdid=demo&%24.cmid=Source | PAYLOAD_LEN: 2
Received Data: [34]
<- 08:37:56 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/demo/modules/Sink/inputs/input1/%24.cdid=demo&%24.cmid=Source | PAYLOAD_LEN: 2
Received Data: [35]
<- 08:37:57 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/demo/modules/Sink/inputs/input1/%24.cdid=demo&%24.cmid=Source | PAYLOAD_LEN: 2
Received Data: [36]
<- 08:37:58 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/demo/modules/Sink/inputs/input1/%24.cdid=demo&%24.cmid=Source | PAYLOAD_LEN: 2
Received Data: [37]
<- 08:37:59 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/demo/modules/Sink/inputs/input1/%24.cdid=demo&%24.cmid=Source | PAYLOAD_LEN: 2
Received Data: [38]
<- 08:38:00 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/demo/modules/Sink/inputs/input1/%24.cdid=demo&%24.cmid=Source | PAYLOAD_LEN: 2
Received Data: [39]
<- 08:38:01 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/demo/modules/Sink/inputs/input1/%24.cdid=demo&%24.cmid=Source | PAYLOAD_LEN: 2
Received Data: [40]
<- 08:38:02 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/demo/modules/Sink/inputs/input1/%24.cdid=demo&%24.cmid=Source | PAYLOAD_LEN: 2
Received Data: [41]
<- 08:38:03 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/demo/modules/Sink/inputs/input1/%24.cdid=demo&%24.cmid=Source | PAYLOAD_LEN: 2
Received Data: [42]
<- 08:38:04 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/demo/modules/Sink/inputs/input1/%24.cdid=demo&%24.cmid=Source | PAYLOAD_LEN: 2
Received Data: [43]
<- 08:38:05 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/demo/modules/Sink/inputs/input1/%24.cdid=demo&%24.cmid=Source | PAYLOAD_LEN: 2
Received Data: [44]
<- 08:38:06 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/demo/modules/Sink/inputs/input1/%24.cdid=demo&%24.cmid=Source | PAYLOAD_LEN: 2
Received Data: [45]
<- 08:38:07 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/demo/modules/Sink/inputs/input1/%24.cdid=demo&%24.cmid=Source | PAYLOAD_LEN: 2
Received Data: [46]
<- 08:38:08 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/demo/modules/Sink/inputs/input1/%24.cdid=demo&%24.cmid=Source | PAYLOAD_LEN: 2
Received Data: [47]
<- 08:38:09 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/demo/modules/Sink/inputs/input1/%24.cdid=demo&%24.cmid=Source | PAYLOAD_LEN: 2
Received Data: [48]
<- 08:38:10 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/demo/modules/Sink/inputs/input1/%24.cdid=demo&%24.cmid=Source | PAYLOAD_LEN: 2
Received Data: [49]
<- 08:38:11 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/demo/modules/Sink/inputs/input1/%24.cdid=demo&%24.cmid=Source | PAYLOAD_LEN: 2
CRASH!

Afterwards the module gets restarted and shows just...

-> 08:38:13 CONNECT | VER: 4 | KEEPALIVE: 240 | FLAGS: 192 | USERNAME: [user]-dev.azure-devices.net/demo/Sink/?api-version=2017-11-08-preview&DeviceClientType=iothubclient%2f1.3.8%20(native%3b%20Linux%3b%20x86_64) | PWD: XXXX | CLEAN: 0
<- 08:38:14 CONNACK | SESSION_PRESENT: true | RETURN_CODE: 0x0
-> 08:38:14 SUBSCRIBE | PACKET_ID: 2 | TOPIC_NAME: devices/demo/modules/Sink/# | QOS: 0
<- 08:38:14 SUBACK | PACKET_ID: 2 | RETURN_CODE: 0
<- 08:38:15 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/demo/modules/Sink/inputs/input1/%24.cdid=demo&%24.cmid=Source | PAYLOAD_LEN: 2
Received Data: [51]
<- 08:38:15 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/demo/modules/Sink/inputs/input1/%24.cdid=demo&%24.cmid=Source | PAYLOAD_LEN: 2
Received Data: [52]
<- 08:38:15 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/demo/modules/Sink/inputs/input1/%24.cdid=demo&%24.cmid=Source | PAYLOAD_LEN: 2
Received Data: [53]
alaendle picture alaendle on 14 Jul 2020

Thanks @alaendle .
The logs are perfect. We are close to getting this issue sorted out.
We will update you briefly.

ewertons picture ewertons on 15 Jul 2020

Hi @alaendle ,
upon verification our assessment is that the initial assumption that the Azure IoT Edge did not received a PUBACK for message 50 seems incorrect.
The code in umqtt (our mqtt client) sends a PUBACK right after the delivery callback is invoked from that layer.
However, as it seems the callback gets queued internally before it gets exposed to the user, so the function returns to umtt and a PUBACK is sent.
https://github.com/Azure/azure-umqtt-c/blob/165f6f52f8b2aec54a28ea5ede41736589726cd0/src/mqtt_client.c#L718
(see lines 704 and 718)

It is not trivial to verify the response because umqtt does not log the PUBACK responses sent to the remote endpoint.

We could argue that since the callback does get invoked with message 50 so you can simulate a crash, there is no actual message loss.

Is that information sufficient to unblock your development?

ewertons picture ewertons on 24 Jul 2020

Hello @ewertons,
I think we are going round in circles :weary: - and I'm sorry to say so, but this aspect was already discussed in January - https://github.com/Azure/iotedge/issues/2089#issuecomment-580770221

Just assume a crash between the PUBACK and the INVOCATION of the callback - and as far as I get it there is no guarantee that this can't happen :smirk:

So I need to contradict, messages can get lost with the current implementation; and since we rely on transactional processing of messages this is not sufficient to unblock our development.

alaendle picture alaendle on 27 Jul 2020

Hi @alaendle,

We do understand your feature request. Ultimately, you want to make sure you received and finished processing the incoming message at the application layer before a PUBACK is sent back to the Azure IoT Hub.

There are two situations where a crash would happen: at the SDK protocol stack level, or within the user application.
The mitigation we have for message loss due to crashes on the SDK is the guarantee that will fix any SDK crashes we or customers have identified, plus all other safeguards we have in place (longhaul runs, automated daily builds, fault-injection tests, fuzzing, etc). Since the SDK protocol stack is common across the numerous device deployments, this code has high coverage and additional issues in this stack will be very unlikely. Customers will more likely run into device application issues as the application is more device specific.

The Azure IoT C SDK has two public surfaces:

iothub_device_client_ll:

Single-threaded, non-thread-safe layer (runs on same thread as user application), which requires the constant and periodic call to IoTHubDeviceClient_LL_DoWork.

iothub_device_client:

Multi-threaded, thread-safe layer (a separate thread is spawn to internally run IoTHubDeviceClient_LL_DoWork).

For the iothub_device_client API, we have implemented a mechanism that detaches the I/O engine from the dispatching of callbacks to the user application. The reason for that was to prevent deadlocks, in case customers would invoke the SDK APIs from within the callback functions (since this layer is thread-safe). The side effect of such protection is that messaging I/O (and PUBACKs) is done before the callbacks to the user are invoked.

Changing this behavior of iothub_device_client would result in extensive and risky code refactoring, which we decided is not advisable given the option offered below.

Recommended action:

To achieve the scenario where a PUBACK is sent by the Azure IoT C SDK back to the Azure IoT Hub after the user application has received the incoming message, developers must use iothub_device_client_ll (or the related iothub_module_client_ll if using modules).

As seen on the callstacks below, the callback to the customer (receive_msg_callback on iothub_ll_c2d_sample) gets invoked sequentially before the PUBACK is sent out by the SDK.

The point where the callback is received by the user application layer.

>   iothub_ll_c2d_sample.exe!receive_msg_callback(IOTHUB_MESSAGE_HANDLE_DATA_TAG * message, void * user_context) Line 60    C
    iothub_ll_c2d_sample.exe!invoke_message_callback(IOTHUB_CLIENT_CORE_LL_HANDLE_DATA_TAG * handleData, MESSAGE_CALLBACK_INFO_TAG * messageData) Line 435  C
    iothub_ll_c2d_sample.exe!IoTHubClientCore_LL_MessageCallback(MESSAGE_CALLBACK_INFO_TAG * messageData, void * ctx) Line 731  C
    iothub_ll_c2d_sample.exe!processIncomingMessageNotification(MQTTTRANSPORT_HANDLE_DATA_TAG * transportData, MQTT_MESSAGE_TAG * msgHandle, const char * topic_resp, IOTHUB_IDENTITY_TYPE_TAG type) Line 1775  C
    iothub_ll_c2d_sample.exe!mqttNotificationCallback(MQTT_MESSAGE_TAG * msgHandle, void * callbackCtx) Line 1821   C
    iothub_ll_c2d_sample.exe!ProcessPublishMessage(MQTT_CLIENT_TAG * mqtt_client, unsigned char * initialPos, unsigned __int64 packetLength, int flags) Line 706    C
    iothub_ll_c2d_sample.exe!recvCompleteCallback(void * context, CONTROL_PACKET_TYPE_TAG packet, int flags, BUFFER_TAG * headerData) Line 812  C
    iothub_ll_c2d_sample.exe!completePacketData(MQTTCODEC_INSTANCE_TAG * codecData) Line 592    C
    iothub_ll_c2d_sample.exe!mqtt_codec_bytesReceived(MQTTCODEC_INSTANCE_TAG * handle, const unsigned char * buffer, unsigned __int64 size) Line 1176   C
    iothub_ll_c2d_sample.exe!onBytesReceived(void * context, const unsigned char * buffer, unsigned __int64 size) Line 473  C
    iothub_ll_c2d_sample.exe!on_underlying_io_bytes_received(void * context, const unsigned char * buffer, unsigned __int64 size) Line 882  C
    iothub_ll_c2d_sample.exe!socketio_dowork(void * socket_io) Line 683 C
    iothub_ll_c2d_sample.exe!xio_dowork(XIO_INSTANCE_TAG * xio) Line 166    C
    iothub_ll_c2d_sample.exe!tlsio_schannel_dowork(void * tls_io) Line 1355 C
    iothub_ll_c2d_sample.exe!xio_dowork(XIO_INSTANCE_TAG * xio) Line 166    C
    iothub_ll_c2d_sample.exe!mqtt_client_dowork(MQTT_CLIENT_TAG * handle) Line 1351 C
    iothub_ll_c2d_sample.exe!IoTHubTransport_MQTT_Common_DoWork(void * handle) Line 3486    C
    iothub_ll_c2d_sample.exe!IoTHubTransportMqtt_DoWork(void * handle) Line 122 C
    iothub_ll_c2d_sample.exe!IoTHubClientCore_LL_DoWork(IOTHUB_CLIENT_CORE_LL_HANDLE_DATA_TAG * iotHubClientHandle) Line 2124   C
    iothub_ll_c2d_sample.exe!IoTHubDeviceClient_LL_DoWork(IOTHUB_CLIENT_CORE_LL_HANDLE_DATA_TAG * iotHubClientHandle) Line 92   C
    iothub_ll_c2d_sample.exe!main() Line 191    C
    [External Code]

The point where the PUBACK is sent back to the Hub:

>   iothub_ll_c2d_sample.exe!ProcessPublishMessage(MQTT_CLIENT_TAG * mqtt_client, unsigned char * initialPos, unsigned __int64 packetLength, int flags) Line 718    C
    iothub_ll_c2d_sample.exe!recvCompleteCallback(void * context, CONTROL_PACKET_TYPE_TAG packet, int flags, BUFFER_TAG * headerData) Line 812  C
    iothub_ll_c2d_sample.exe!completePacketData(MQTTCODEC_INSTANCE_TAG * codecData) Line 592    C
    iothub_ll_c2d_sample.exe!mqtt_codec_bytesReceived(MQTTCODEC_INSTANCE_TAG * handle, const unsigned char * buffer, unsigned __int64 size) Line 1176   C
    iothub_ll_c2d_sample.exe!onBytesReceived(void * context, const unsigned char * buffer, unsigned __int64 size) Line 473  C
    iothub_ll_c2d_sample.exe!on_underlying_io_bytes_received(void * context, const unsigned char * buffer, unsigned __int64 size) Line 882  C
    iothub_ll_c2d_sample.exe!socketio_dowork(void * socket_io) Line 683 C
    iothub_ll_c2d_sample.exe!xio_dowork(XIO_INSTANCE_TAG * xio) Line 166    C
    iothub_ll_c2d_sample.exe!tlsio_schannel_dowork(void * tls_io) Line 1355 C
    iothub_ll_c2d_sample.exe!xio_dowork(XIO_INSTANCE_TAG * xio) Line 166    C
    iothub_ll_c2d_sample.exe!mqtt_client_dowork(MQTT_CLIENT_TAG * handle) Line 1351 C
    iothub_ll_c2d_sample.exe!IoTHubTransport_MQTT_Common_DoWork(void * handle) Line 3486    C
    iothub_ll_c2d_sample.exe!IoTHubTransportMqtt_DoWork(void * handle) Line 122 C
    iothub_ll_c2d_sample.exe!IoTHubClientCore_LL_DoWork(IOTHUB_CLIENT_CORE_LL_HANDLE_DATA_TAG * iotHubClientHandle) Line 2124   C
    iothub_ll_c2d_sample.exe!IoTHubDeviceClient_LL_DoWork(IOTHUB_CLIENT_CORE_LL_HANDLE_DATA_TAG * iotHubClientHandle) Line 92   C
    iothub_ll_c2d_sample.exe!main() Line 191    C
    [External Code]
ewertons picture ewertons on 28 Jan 2021

Hello @ewertons,
thanks for your detailed reply. However I fear I can't follow your intention; if your recommendation is to use the LL API to solve the problem I'm stunned, because my showcase already uses iothub_module_client_ll.h.

https://github.com/alaendle/showcase-edge-transaction/blob/master/modules/Sink/main.c#L7

So I'm not sure how to proceed at this point. If I misunderstood you or if I can contribute, please let me know.

alaendle picture alaendle on 28 Jan 2021

Hey @alaendle , there is indeed some disconnect here. That's quite not the outcome we expected.
I will work to figure it out first thing in the morning.

ewertons picture ewertons on 28 Jan 2021

Hi @alaendle ,
I tried getting a repro of you have described, using the iothub_module_client_ll.h API, but was not too.
If you don't mind, could you run the scenario again on your setup using a change we are making in the C SDK? We added a change to print in the logs when PUBACK is sent back by the C SDK.
That change is in master branch, introduced by this PR today: https://github.com/Azure/azure-iot-sdk-c/pull/1863

Besides that, if you could collect the tcp traffic on the client node (using tcpdump?), that might help identify if the PUBACK is really going out or not (based on packet size, since we won't have a way to decode the traffic).

ewertons picture ewertons on 17 Feb 2021
👀1

Hello @ewertons, thanks, I now build directly against the master branch of this repository. However the log hasn't changed. It still shows a QoS of 0 for subscription and an invalid value for QoS during consumption. All in all the same state as in the initial report (https://github.com/Azure/azure-iot-sdk-c/issues/1422#issue-561479396). For that I'm not providing a tcpdump, because I expect that wouldn't provide useful additional information. Please let me know if I can be of any help.

-> 07:35:56 CONNECT | VER: 4 | KEEPALIVE: 240 | FLAGS: 192 | USERNAME: ioth-bhp-edge-dev.azure-devices.net/bh0vm00001/sink/?api-version=2020-09-30&DeviceClientType=iothubclient%2f1.6.0%20(native%3b%20Linux%3b%20x86_64) | PWD: XXXX | CLEAN: 0
<- 07:35:56 CONNACK | SESSION_PRESENT: true | RETURN_CODE: 0x0
-> 07:35:56 SUBSCRIBE | PACKET_ID: 2 | TOPIC_NAME: devices/bh0vm00001/modules/sink/# | QOS: 0
<- 07:35:57 SUBACK | PACKET_ID: 2 | RETURN_CODE: 0
<- 07:36:52 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/bh0vm00001/modules/sink/inputs/input1/%24.cdid=bh0vm00001&%24.cmid=source | PAYLOAD_LEN: 1
Received Data: [0]
<- 07:36:52 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/bh0vm00001/modules/sink/inputs/input1/%24.cdid=bh0vm00001&%24.cmid=source | PAYLOAD_LEN: 1
Received Data: [1]
<- 07:36:52 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/bh0vm00001/modules/sink/inputs/input1/%24.cdid=bh0vm00001&%24.cmid=source | PAYLOAD_LEN: 1
Received Data: [2]
<- 07:36:52 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/bh0vm00001/modules/sink/inputs/input1/%24.cdid=bh0vm00001&%24.cmid=source | PAYLOAD_LEN: 1
Received Data: [3]
<- 07:36:52 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/bh0vm00001/modules/sink/inputs/input1/%24.cdid=bh0vm00001&%24.cmid=source | PAYLOAD_LEN: 1
Received Data: [4]
<- 07:36:53 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/bh0vm00001/modules/sink/inputs/input1/%24.cdid=bh0vm00001&%24.cmid=source | PAYLOAD_LEN: 1
Received Data: [5]
<- 07:36:54 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/bh0vm00001/modules/sink/inputs/input1/%24.cdid=bh0vm00001&%24.cmid=source | PAYLOAD_LEN: 1
Received Data: [6]
<- 07:36:55 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/bh0vm00001/modules/sink/inputs/input1/%24.cdid=bh0vm00001&%24.cmid=source | PAYLOAD_LEN: 1
Received Data: [7]
<- 07:36:56 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/bh0vm00001/modules/sink/inputs/input1/%24.cdid=bh0vm00001&%24.cmid=source | PAYLOAD_LEN: 1
Received Data: [8]
<- 07:36:57 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/bh0vm00001/modules/sink/inputs/input1/%24.cdid=bh0vm00001&%24.cmid=source | PAYLOAD_LEN: 1
Received Data: [9]
<- 07:36:58 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/bh0vm00001/modules/sink/inputs/input1/%24.cdid=bh0vm00001&%24.cmid=source | PAYLOAD_LEN: 2
Received Data: [10]
<- 07:36:59 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/bh0vm00001/modules/sink/inputs/input1/%24.cdid=bh0vm00001&%24.cmid=source | PAYLOAD_LEN: 2
Received Data: [11]
<- 07:37:00 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/bh0vm00001/modules/sink/inputs/input1/%24.cdid=bh0vm00001&%24.cmid=source | PAYLOAD_LEN: 2
Received Data: [12]
<- 07:37:01 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/bh0vm00001/modules/sink/inputs/input1/%24.cdid=bh0vm00001&%24.cmid=source | PAYLOAD_LEN: 2
Received Data: [13]
<- 07:37:02 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/bh0vm00001/modules/sink/inputs/input1/%24.cdid=bh0vm00001&%24.cmid=source | PAYLOAD_LEN: 2
Received Data: [14]
<- 07:37:03 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/bh0vm00001/modules/sink/inputs/input1/%24.cdid=bh0vm00001&%24.cmid=source | PAYLOAD_LEN: 2
Received Data: [15]
<- 07:37:04 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/bh0vm00001/modules/sink/inputs/input1/%24.cdid=bh0vm00001&%24.cmid=source | PAYLOAD_LEN: 2
Received Data: [16]
<- 07:37:05 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/bh0vm00001/modules/sink/inputs/input1/%24.cdid=bh0vm00001&%24.cmid=source | PAYLOAD_LEN: 2
Received Data: [17]
<- 07:37:06 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/bh0vm00001/modules/sink/inputs/input1/%24.cdid=bh0vm00001&%24.cmid=source | PAYLOAD_LEN: 2
Received Data: [18]
<- 07:37:07 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/bh0vm00001/modules/sink/inputs/input1/%24.cdid=bh0vm00001&%24.cmid=source | PAYLOAD_LEN: 2
Received Data: [19]
<- 07:37:08 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/bh0vm00001/modules/sink/inputs/input1/%24.cdid=bh0vm00001&%24.cmid=source | PAYLOAD_LEN: 2
Received Data: [20]
<- 07:37:09 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/bh0vm00001/modules/sink/inputs/input1/%24.cdid=bh0vm00001&%24.cmid=source | PAYLOAD_LEN: 2
Received Data: [21]
<- 07:37:10 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/bh0vm00001/modules/sink/inputs/input1/%24.cdid=bh0vm00001&%24.cmid=source | PAYLOAD_LEN: 2
Received Data: [22]
<- 07:37:11 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/bh0vm00001/modules/sink/inputs/input1/%24.cdid=bh0vm00001&%24.cmid=source | PAYLOAD_LEN: 2
Received Data: [23]
<- 07:37:12 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/bh0vm00001/modules/sink/inputs/input1/%24.cdid=bh0vm00001&%24.cmid=source | PAYLOAD_LEN: 2
Received Data: [24]
<- 07:37:13 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/bh0vm00001/modules/sink/inputs/input1/%24.cdid=bh0vm00001&%24.cmid=source | PAYLOAD_LEN: 2
Received Data: [25]
<- 07:37:14 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/bh0vm00001/modules/sink/inputs/input1/%24.cdid=bh0vm00001&%24.cmid=source | PAYLOAD_LEN: 2
Received Data: [26]
<- 07:37:15 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/bh0vm00001/modules/sink/inputs/input1/%24.cdid=bh0vm00001&%24.cmid=source | PAYLOAD_LEN: 2
Received Data: [27]
<- 07:37:16 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/bh0vm00001/modules/sink/inputs/input1/%24.cdid=bh0vm00001&%24.cmid=source | PAYLOAD_LEN: 2
Received Data: [28]
<- 07:37:17 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/bh0vm00001/modules/sink/inputs/input1/%24.cdid=bh0vm00001&%24.cmid=source | PAYLOAD_LEN: 2
Received Data: [29]
<- 07:37:18 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/bh0vm00001/modules/sink/inputs/input1/%24.cdid=bh0vm00001&%24.cmid=source | PAYLOAD_LEN: 2
Received Data: [30]
<- 07:37:19 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/bh0vm00001/modules/sink/inputs/input1/%24.cdid=bh0vm00001&%24.cmid=source | PAYLOAD_LEN: 2
Received Data: [31]
<- 07:37:20 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/bh0vm00001/modules/sink/inputs/input1/%24.cdid=bh0vm00001&%24.cmid=source | PAYLOAD_LEN: 2
Received Data: [32]
<- 07:37:21 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/bh0vm00001/modules/sink/inputs/input1/%24.cdid=bh0vm00001&%24.cmid=source | PAYLOAD_LEN: 2
Received Data: [33]
<- 07:37:22 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/bh0vm00001/modules/sink/inputs/input1/%24.cdid=bh0vm00001&%24.cmid=source | PAYLOAD_LEN: 2
Received Data: [34]
<- 07:37:23 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/bh0vm00001/modules/sink/inputs/input1/%24.cdid=bh0vm00001&%24.cmid=source | PAYLOAD_LEN: 2
Received Data: [35]
<- 07:37:24 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/bh0vm00001/modules/sink/inputs/input1/%24.cdid=bh0vm00001&%24.cmid=source | PAYLOAD_LEN: 2
Received Data: [36]
<- 07:37:25 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/bh0vm00001/modules/sink/inputs/input1/%24.cdid=bh0vm00001&%24.cmid=source | PAYLOAD_LEN: 2
Received Data: [37]
<- 07:37:26 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/bh0vm00001/modules/sink/inputs/input1/%24.cdid=bh0vm00001&%24.cmid=source | PAYLOAD_LEN: 2
Received Data: [38]
<- 07:37:27 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/bh0vm00001/modules/sink/inputs/input1/%24.cdid=bh0vm00001&%24.cmid=source | PAYLOAD_LEN: 2
Received Data: [39]
<- 07:37:28 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/bh0vm00001/modules/sink/inputs/input1/%24.cdid=bh0vm00001&%24.cmid=source | PAYLOAD_LEN: 2
Received Data: [40]
<- 07:37:29 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/bh0vm00001/modules/sink/inputs/input1/%24.cdid=bh0vm00001&%24.cmid=source | PAYLOAD_LEN: 2
Received Data: [41]
<- 07:37:30 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/bh0vm00001/modules/sink/inputs/input1/%24.cdid=bh0vm00001&%24.cmid=source | PAYLOAD_LEN: 2
Received Data: [42]
<- 07:37:31 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/bh0vm00001/modules/sink/inputs/input1/%24.cdid=bh0vm00001&%24.cmid=source | PAYLOAD_LEN: 2
Received Data: [43]
<- 07:37:32 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/bh0vm00001/modules/sink/inputs/input1/%24.cdid=bh0vm00001&%24.cmid=source | PAYLOAD_LEN: 2
Received Data: [44]
<- 07:37:33 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/bh0vm00001/modules/sink/inputs/input1/%24.cdid=bh0vm00001&%24.cmid=source | PAYLOAD_LEN: 2
Received Data: [45]
<- 07:37:34 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/bh0vm00001/modules/sink/inputs/input1/%24.cdid=bh0vm00001&%24.cmid=source | PAYLOAD_LEN: 2
Received Data: [46]
<- 07:37:35 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/bh0vm00001/modules/sink/inputs/input1/%24.cdid=bh0vm00001&%24.cmid=source | PAYLOAD_LEN: 2
Received Data: [47]
<- 07:37:36 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/bh0vm00001/modules/sink/inputs/input1/%24.cdid=bh0vm00001&%24.cmid=source | PAYLOAD_LEN: 2
Received Data: [48]
<- 07:37:37 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/bh0vm00001/modules/sink/inputs/input1/%24.cdid=bh0vm00001&%24.cmid=source | PAYLOAD_LEN: 2
Received Data: [49]
<- 07:37:38 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/bh0vm00001/modules/sink/inputs/input1/%24.cdid=bh0vm00001&%24.cmid=source | PAYLOAD_LEN: 2

CRASH!

-> 07:37:53 CONNECT | VER: 4 | KEEPALIVE: 240 | FLAGS: 192 | USERNAME: ioth-bhp-edge-dev.azure-devices.net/bh0vm00001/sink/?api-version=2020-09-30&DeviceClientType=iothubclient%2f1.6.0%20(native%3b%20Linux%3b%20x86_64) | PWD: XXXX | CLEAN: 0
<- 07:37:53 CONNACK | SESSION_PRESENT: true | RETURN_CODE: 0x0
-> 07:37:53 SUBSCRIBE | PACKET_ID: 2 | TOPIC_NAME: devices/bh0vm00001/modules/sink/# | QOS: 0
<- 07:37:53 SUBACK | PACKET_ID: 2 | RETURN_CODE: 0
<- 07:37:54 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/bh0vm00001/modules/sink/inputs/input1/%24.cdid=bh0vm00001&%24.cmid=source | PAYLOAD_LEN: 2
Received Data: [51]
<- 07:37:54 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/bh0vm00001/modules/sink/inputs/input1/%24.cdid=bh0vm00001&%24.cmid=source | PAYLOAD_LEN: 2
Received Data: [52]
<- 07:37:54 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/bh0vm00001/modules/sink/inputs/input1/%24.cdid=bh0vm00001&%24.cmid=source | PAYLOAD_LEN: 2
Received Data: [53]
<- 07:37:54 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/bh0vm00001/modules/sink/inputs/input1/%24.cdid=bh0vm00001&%24.cmid=source | PAYLOAD_LEN: 2
Received Data: [54]
<- 07:37:54 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: QOS_VALUE_INVALID | TOPIC_NAME: devices/bh0vm00001/modules/sink/inputs/input1/%24.cdid=bh0vm00001&%24.cmid=source | PAYLOAD_LEN: 2
Received Data: [55]
...
alaendle picture alaendle on 19 Feb 2021
👍1

Hey @alaendle ,
thanks for your patience.
I am puzzled how I managed to go off the tracks on this issue.

I will write the whole scenario here so it is clear:

  1. azure-iot-sdk-c is subscribing for Edge Input queue using QoS 0 (as you pointed by the code search you did);
  2. QoS 0 (AT MOST ONCE) means "fire and forget", so Edge hub would not expect a PUBACK, once it sends the message it dequeues it and considers it delivered;

So, obviously (as a note to myself), the reason why you are not receiving an Edge-to-Device message again after a crash is because azure-iot-sdk-c is subscribing with QoS 0.

Points worth listing:

  1. You mention that azure-iot-sdk-csharp behaves differently, and that's expected because that code subscribes using QoS 1 (AT LEAST ONCE), guaranteeing the sender (Edge) will resend it if it does not receive a PUBACK;

MqttTransportHandler.cs:841: await _channel.WriteAsync(new SubscribePacket(0, new SubscriptionRequest(_receiveEventMessageFilter, _qos))).ConfigureAwait(true);
MqttTransportHandler.cs:833: public override async Task EnableEventReceiveAsync(CancellationToken cancellationToken)
...csharp
InternalClient.cs:1947: private Task EnableEventReceiveAsync(CancellationToken cancellationToken)
InternalClient.cs:1733: public async Task SetInputMessageHandlerAsync(string inputName, MessageHandler messageHandler, object userContext, CancellationToken cancellationToken)
InternalClient.cs:1708: public async Task SetInputMessageHandlerAsync(string inputName, MessageHandler messageHandler, object userContext)
ModuleClient.cs:553: public Task SetInputMessageHandlerAsync(string inputName, MessageHandler messageHandler, object userContext)

MqttTransportHandler.cs:159:
            _qos = settings.PublishToServerQoS;

MqttTransportSettings.cs:27:
        private const QualityOfService DefaultPublishToServerQoS = QualityOfService.AtLeastOnce;

QualityOfService.cs:10
        AtLeastOnce = 1,
  1. azure-iot-sdk-c subscribes to Edge input queue and IoT Hub messages/devicebound with different QoS (0 and 1, respectivelly), so that's why I did not get a repro right away;
  2. Even if azure-iot-sdk-c subscribe to IoT Edge input queue with QoS 1, you would not receive the message again in this scenario if using iothub_device_client.h (the multi-threaded layer on top of iothub_device_client_ll.h) - because in this case the PUBACK would be sent before the callback is invoked to the user app.

So the main ask is if we can change the QoS on the azure-iot-sdk-c subscription for IoT Edge Input messages to QoS 1.
I made such change in this branch, could you validate if it satisfies your request?

Once you confirm, I will consult with my team about merging it.

ewertons picture ewertons on 25 Feb 2021
👀1 🚀1 ❤1

Hello @ewertons,
thanks for the branch - I can confirm that this change satisfies our request.
Just to proof it - here are the logs:

<- 05:58:32 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE | TOPIC_NAME: devices/laa6bh/modules/sink/inputs/input1/%24.cdid=laa6bh&%24.cmid=source | PACKET_ID: 1 | PAYLOAD_LEN: 2
Received Data: [47]
-> 05:58:32 PUBACK | PACKET_ID: 1
<- 05:58:33 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE | TOPIC_NAME: devices/laa6bh/modules/sink/inputs/input1/%24.cdid=laa6bh&%24.cmid=source | PACKET_ID: 1 | PAYLOAD_LEN: 2
Received Data: [48]
-> 05:58:33 PUBACK | PACKET_ID: 1
<- 05:58:34 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE | TOPIC_NAME: devices/laa6bh/modules/sink/inputs/input1/%24.cdid=laa6bh&%24.cmid=source | PACKET_ID: 1 | PAYLOAD_LEN: 2
Received Data: [49]
-> 05:58:34 PUBACK | PACKET_ID: 1
<- 05:58:35 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE | TOPIC_NAME: devices/laa6bh/modules/sink/inputs/input1/%24.cdid=laa6bh&%24.cmid=source | PACKET_ID: 1 | PAYLOAD_LEN: 2

CRASH!

-> 05:58:48 CONNECT | VER: 4 | KEEPALIVE: 240 | FLAGS: 192 | USERNAME: tci-hub.azure-devices.net/laa6bh/sink/?api-version=2020-09-30&DeviceClientType=iothubclient%2f1.6.0%20(native%3b%20Linux%3b%20x86_64) | PWD: XXXX | CLEAN: 0
<- 05:58:48 CONNACK | SESSION_PRESENT: true | RETURN_CODE: 0x0
-> 05:58:48 SUBSCRIBE | PACKET_ID: 2 | TOPIC_NAME: devices/laa6bh/modules/sink/# | QOS: 1
<- 05:58:48 SUBACK | PACKET_ID: 2 | RETURN_CODE: 1
<- 05:59:06 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE | TOPIC_NAME: devices/laa6bh/modules/sink/inputs/input1/%24.cdid=laa6bh&%24.cmid=source | PACKET_ID: 1 | PAYLOAD_LEN: 2

CRASH!

-> 05:59:29 CONNECT | VER: 4 | KEEPALIVE: 240 | FLAGS: 192 | USERNAME: tci-hub.azure-devices.net/laa6bh/sink/?api-version=2020-09-30&DeviceClientType=iothubclient%2f1.6.0%20(native%3b%20Linux%3b%20x86_64) | PWD: XXXX | CLEAN: 0
<- 05:59:29 CONNACK | SESSION_PRESENT: true | RETURN_CODE: 0x0
-> 05:59:29 SUBSCRIBE | PACKET_ID: 2 | TOPIC_NAME: devices/laa6bh/modules/sink/# | QOS: 1
<- 05:59:29 SUBACK | PACKET_ID: 2 | RETURN_CODE: 1
<- 05:59:38 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE | TOPIC_NAME: devices/laa6bh/modules/sink/inputs/input1/%24.cdid=laa6bh&%24.cmid=source | PACKET_ID: 1 | PAYLOAD_LEN: 2

CRASH!

My demo code crashes on a certain message, so the repetitive crashes here are a good sign! 馃槂

So thank you for your efforts! However, I have a feeling that with the support of transactions, https://github.com/Azure/azure-iot-sdk-c/issues/1647 could soon become relevant - but that's a story for another day!

alaendle picture alaendle on 25 Feb 2021
👍1

Thank you very much, @alaendle !
Once again, I appreciate your patience.
I will update you briefly with the plans for moving forward with this fix.

ewertons picture ewertons on 25 Feb 2021

@alaendle ,
the fix is in master now. You should be able to go.
FYI, as of now we do not have a schedule set for any updates to LTS releases, but the next one should come in July/2021.

ewertons picture ewertons on 26 Feb 2021
❤1
Was this page helpful?
0 / 5 - 0 ratings

Related issues

caobaokun picture caobaokun  路  7Comments
vpetrigo picture vpetrigo  路  5Comments
kskog picture kskog  路  5Comments
duvitech picture duvitech  路  6Comments
thematrix9 picture thematrix9  路  4Comments