MQTT messages received multiple times on QoS 1 subscription

[JWizard]

I am using the SLM app from the 1.9.1 SDK.

I connect to my MQTT broker using TLS offloaded on the modem.

I subscribe to a topic using QoS = 1

Then if a message is published to the same topic using QoS = 1 then the nrf9160 reports the message received over and over again every few seconds.

If I instead subscribe to the topic using QoS = 0 then I will only get the messages (published at QoS = 1) one time.

Is this the intended behavior? I feel unsure that I am actually operating under QoS = 1 conditions when the subscription is set to QoS = 0.

[Øyvind]

Hello, 

Sorry for the late response. I will have a look at your issue today. Please note that due to Easter holidays in our R&D department, there might be some more delay to get an answer.  We're sorry for the inconvenience. 

Kind regards,
Øyvind

[Øyvind]

Hello, 

I tested with 
#XMQTTCON: 1,"287290_client","test.mosquitto.org",1883
AT#XMQTTSUB="nordic/test",1

Then publishing to nordic/test from my mosquitto client with QoS 1. I received only one notification in the SLM. 

Have not been able to test using TLS yet. Can you confirm if you see the same issue with e.g. similar setup as I did?

Kind regards,
Øyvind

[Øyvind]

I was finally able to test this scenario connecting to AWS IoT, and yes, you are correct. 

2022-04-11T12:25:08.800Z DEBUG modem >> AT#XMQTTSUB="nordic/test/",1
2022-04-11T12:25:08.816Z DEBUG modem << OK
2022-04-11T12:25:09.363Z DEBUG modem << #XMQTTEVT: 7,0
2022-04-11T12:25:49.691Z DEBUG modem << #XMQTTMSG: 12,45
2022-04-11T12:25:49.703Z DEBUG modem << nordic/test/
2022-04-11T12:25:49.705Z DEBUG modem << {
2022-04-11T12:25:49.706Z DEBUG modem <<   "message": "Hello from AWS IoT console"
2022-04-11T12:25:49.708Z DEBUG modem << }
2022-04-11T12:25:49.710Z DEBUG modem << #XMQTTEVT: 2,0
2022-04-11T12:25:50.130Z DEBUG modem << %CESQ: 55,2,17,2
2022-04-11T12:25:53.932Z DEBUG modem << %CESQ: 54,2,12,1
2022-04-11T12:26:09.565Z DEBUG modem << #XMQTTEVT: 9,0
2022-04-11T12:26:19.791Z DEBUG modem << #XMQTTMSG: 12,45
2022-04-11T12:26:19.803Z DEBUG modem << nordic/test/
2022-04-11T12:26:19.804Z DEBUG modem << {
2022-04-11T12:26:19.806Z DEBUG modem <<   "message": "Hello from AWS IoT console"
2022-04-11T12:26:19.806Z DEBUG modem << }
2022-04-11T12:26:19.807Z DEBUG modem << #XMQTTEVT: 2,0
2022-04-11T12:26:25.229Z DEBUG modem << %CESQ: 57,2,17,2
2022-04-11T12:26:32.909Z DEBUG modem << %CESQ: 54,2,12,1
2022-04-11T12:26:49.846Z DEBUG modem << #XMQTTMSG: 12,45
2022-04-11T12:26:49.858Z DEBUG modem << nordic/test/
2022-04-11T12:26:49.860Z DEBUG modem << {
2022-04-11T12:26:49.861Z DEBUG modem <<   "message": "Hello from AWS IoT console"
2022-04-11T12:26:49.862Z DEBUG modem << }
2022-04-11T12:26:49.863Z DEBUG modem << #XMQTTEVT: 2,0
2022-04-11T12:27:09.574Z DEBUG modem << #XMQTTEVT: 9,0
2022-04-11T12:27:21.544Z DEBUG modem << %CESQ: 57,2,17,2
2022-04-11T12:27:29.863Z DEBUG modem << %CESQ: 57,2,12,1
2022-04-11T12:27:36.559Z DEBUG modem << #XMQTTMSG: 12,45
2022-04-11T12:27:36.574Z DEBUG modem << nordic/test/
2022-04-11T12:27:36.576Z DEBUG modem << {
2022-04-11T12:27:36.576Z DEBUG modem <<   "message": "Hello from AWS IoT console"
2022-04-11T12:27:36.577Z DEBUG modem << }
2022-04-11T12:27:36.578Z DEBUG modem << #XMQTTEVT: 2,0
2022-04-11T12:28:09.474Z DEBUG modem << #XMQTTEVT: 9,0
2022-04-11T12:28:23.620Z DEBUG modem << %CESQ: 57,2,17,2
2022-04-11T12:29:08.943Z DEBUG modem << %CESQ: 56,2,12,1
2022-04-11T12:29:09.384Z DEBUG modem << #XMQTTEVT: 9,0
2022-04-11T12:29:11.411Z DEBUG modem << %CESQ: 56,2,17,2
2022-04-11T12:29:32.404Z DEBUG modem << #XMQTTMSG: 12,45
2022-04-11T12:29:32.416Z DEBUG modem << nordic/test/
2022-04-11T12:29:32.418Z DEBUG modem << {
2022-04-11T12:29:32.419Z DEBUG modem <<   "message": "Hello from AWS IoT console"
2022-04-11T12:29:32.420Z DEBUG modem << }
2022-04-11T12:29:32.421Z DEBUG modem << #XMQTTEVT: 2,0
2022-04-11T12:30:03.468Z DEBUG modem << %CESQ: 56,2,12,1
2022-04-11T12:30:09.490Z DEBUG modem << #XMQTTEVT: 9,0
2022-04-11T12:30:14.403Z DEBUG modem << %CESQ: 56,2,17,2
2022-04-11T12:30:57.871Z DEBUG modem << %CESQ: 56,2,12,1
2022-04-11T12:31:09.570Z DEBUG modem << #XMQTTEVT: 9,0
2022-04-11T12:31:45.874Z DEBUG modem << %CESQ: 56,2,17,2
2022-04-11T12:31:52.911Z DEBUG modem << %CESQ: 56,2,12,1
2022-04-11T12:32:09.548Z DEBUG modem << #XMQTTEVT: 9,0
2022-04-11T12:32:24.270Z DEBUG modem << %CESQ: 56,2,17,2
2022-04-11T12:32:40.907Z DEBUG modem << %CESQ: 55,2,12,1
2022-04-11T12:33:09.451Z DEBUG modem << #XMQTTEVT: 9,0
2022-04-11T12:34:09.181Z DEBUG modem << %CESQ: 53,2,7,1
2022-04-11T12:34:09.304Z DEBUG modem << #XMQTTEVT: 9,0
2022-04-11T12:34:13.235Z DEBUG modem << %CESQ: 54,2,12,1
2022-04-11T12:34:39.605Z DEBUG modem << #XMQTTMSG: 12,45
2022-04-11T12:34:39.617Z DEBUG modem << nordic/test/
2022-04-11T12:34:39.619Z DEBUG modem << {
2022-04-11T12:34:39.630Z DEBUG modem <<   "message": "Hello from AWS IoT console"
2022-04-11T12:34:39.631Z DEBUG modem << }
2022-04-11T12:34:39.633Z DEBUG modem << #XMQTTEVT: 2,0

Will investigate to verify behavior.

Kind regards,
Øyvind

[JWizard]

Hi Oyvind,

Thanks for looking into it. I just tested with the public, non-encrypted test.mosquitto.org and I also saw only one message received with QoS=1 in that scenario.

[Øyvind]

Hello, 

A small update on this case. Looking at Steve's Internet Guide on Understanding MQTT QoS Levels, the QoS 1 message will continue to be resent at regular intervals, until the sender receives an acknowledgement.

The MQTT API in Zephyr has the following API

/**
 * @brief API used by client to send acknowledgment on receiving QoS1 publish
 *        message. Should be called on reception of @ref MQTT_EVT_PUBLISH with
 *        QoS level @ref MQTT_QOS_1_AT_LEAST_ONCE.
 *
 * @param[in] client Client instance for which the procedure is requested.
 *                   Shall not be NULL.
 * @param[in] param Identifies message being acknowledged.
 *
 * @return 0 or a negative error code (errno.h) indicating reason of failure.
 */
int mqtt_publish_qos1_ack(struct mqtt_client *client,
			  const struct mqtt_puback_param *param);

The Serial LTE Modem does not use this, however, the Simple MQTT sample does use the following in the mqtt_evt_handler (nrf\samples\nrf9160\mqtt_simple\src\main.c)

if (p->message.topic.qos == MQTT_QOS_1_AT_LEAST_ONCE) {
			const struct mqtt_puback_param ack = {
				.message_id = p->message_id
			};

			/* Send acknowledgment. */
			mqtt_publish_qos1_ack(&client, &ack);
}

[Øyvind]

Hello, have confirmed that this was a bug. A bug fix has been registered https://github.com/nrfconnect/sdk-nrf/pull/7363 

Kind regards,
Øyvind

[Øyvind]

In order to fix the issue in the nRF Connect SDK tag 1.9.1 - please add the following to the beginning of handle_mqtt_publish_evt() in nrf\applications\serial_lte_modem\src\mqtt_c\slm_at_mqtt.c

const struct mqtt_publish_param *p = &evt->param.publish;
LOG_INF("MQTT PUBLISH result=%d len=%d",
		evt->result, p->message.payload.len);
	
ret = publish_get_payload(c, evt->param.publish.message.payload.len);
if (ret < 0) {
	return ret;
}

if (p->message.topic.qos == MQTT_QOS_1_AT_LEAST_ONCE) {
	const struct mqtt_puback_param ack = {
	.message_id = p->message_id
	};
	/* Send acknowledgment. */
	mqtt_publish_qos1_ack(&client, &ack);
}