nrf9160: mqtt_publish blocking - stuck at mutex_lock

[Brett]

Hi,

This appears to be similar to Case 232209 (from 3 years ago).

What:
I am looking to have the 9160 act as a producer - sending ANT and GPS records on a regular basis.  I am batching the data so that the LTE/MQTT doesnt block the GPS receiver. At each record (ANT or GPS) I push that data into a message_queue (default size of 20 each). Once I have 10 records of either ANT or GPS I publish to the broker, simply looping over each record in the queue and sending.

Flow:
52840 ANT -> UART -> 9160 (GPS + ANT Data) -> batch messages =>  MQTT Broker

The flow into the 9160 is working fine, get a consistent stream of messages.

I can send 1 message successfully to the broker, but when I try to send multiple messages in a sequence it will send the first one, but then when I try to send the 2nd message, it gets stuck in net_mqtt.mqtt_publish at mqtt_mutex_lock(client) - as can be seen from the attached logfile/

Tested:
I thought streaming the records as fast as I could might be the reason, so I put a delay after each record of K_MSEC(500),

I am not sure why the first one worked and then I am blocked. 

I have basically cut/paste the code from the mqtt_simple project, but since I am not wanting to subscribe to any topics and only publish to a topic, do I need to consider things like mqtt_live, mqtt_input, poll(&fds, 1, 0).  I realise to keep the session open, I will manage this with mqtt_live and/or mqtt_ping, but if I publish 10 packets, do I need to have anything controlling the session other than just blasting out the records?

Code Snippet:

if (mqtt_connected)
            {
                /* Separate event queue set up for the data, otherwise it was annoying to do 
                * batch processing
                */
                (void)k_poll(send_queue, 2, K_NO_WAIT);
                if (send_queue[PVT_QUEUE].state == K_POLL_STATE_MSGQ_DATA_AVAILABLE) {
                    printk (">>>> PVT_DATA Available\n");
                    while (k_msgq_get(send_queue[PVT_QUEUE].msgq, &pvt_data, K_NO_WAIT) == 0) {
                        print_local_fix_data(pvt_data);
                        //local_fix_data_publish(pvt_data);
                        k_free(pvt_data);
                    }
                }
                
                // ANT Data
                if (send_queue[ANT_QUEUE].state == K_POLL_STATE_MSGQ_DATA_AVAILABLE) {
                    printk ("**** Start: Send ANT_DATA\n");
                    while (k_msgq_get(send_queue[ANT_QUEUE].msgq, &ant_data, K_NO_WAIT) == 0)
                    {
                        print_ant_data( ant_data );
                        publish_ant_data(ant_data);
                        k_free(ant_data);
                        k_sleep( K_MSEC(500) );
                    }
                    printk ("**** Finish: Send ANT_DATA\n");
                }
            }

Log from Console:

Fullscreen nrf9160-20220629.log Download

Establishing LTE link (this may take some time) ...
[00:00:00.278,839] <wrn> date_time: Valid time not currently available
[00:00:00.278,869] <wrn> date_time: date_time_uptime_to_unix_time_ms, error: -61
[00:00:00.336,425] <dbg> lte_lc.lte_lc_system_mode_set: Sending AT command to set system mode: AT%XSYSTEMMODE=1,0,1,0
[00:00:00.338,531] <dbg> lte_lc.init_and_config: System mode (4) and preference (0) configured
[00:00:00.349,517] <dbg> lte_lc.lte_lc_psm_param_set: RPTAU set to 00000011
[00:00:00.349,548] <dbg> lte_lc.lte_lc_psm_param_set: RAT set to 00000011
[00:00:00.354,400] <dbg> lte_lc.lte_lc_system_mode_set: Sending AT command to set system mode: AT%XSYSTEMMODE=1,0,1,0
[00:00:02.849,426] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 2,"3013","082B1A0D",7

[00:00:02.849,670] <dbg> lte_lc_helpers.parse_cereg: Network registration status: 2
[00:00:02.849,700] <dbg> lte_lc_helpers.parse_cereg: LTE mode: 7
[00:00:03.201,660] <dbg> lte_lc.at_handler: +CSCON notification

[00:00:04.331,909] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 1,"3013","082B1A0D",7,,,"00001000","1~
[00:00:04.332,244] <dbg> lte_lc_helpers.parse_cereg: Network registration status: 1
[00:00:04.332,275] <dbg> lte_lc_helpers.parse_cereg: LTE mode: 7
[00:00:04.332,305] <dbg> lte_lc_helpers.parse_psm: TAU: -1 sec, active time: 16 sec

[00:00:04.334,136] <dbg> lte_lc_helpers.parse_psm: TAU: -1 sec, active time: 16 sec

[00:00:04.334,167] <dbg> lte_lc.lte_lc_psm_get: TAU: -1 sec, active time: 16 sec

[00:00:04.371,246] <dbg> mqtt_simple.client_id_get: client_id = nrf-352656106105532
[00:00:04.371,276] <wrn> date_time: Valid time not currently available
[00:00:04.371,276] <wrn> date_time: date_time_uptime_to_unix_time_ms, error: -61
[00:00:04.378,356] <dbg> net_mqtt_sock_tcp.mqtt_client_tcp_connect: (0x20015120): Created socket 1
[00:00:04.378,356] <dbg> net_mqtt_sock_tcp.mqtt_client_tcp_connect: (0x20015120): Connect completed
[00:00:04.498,077] <dbg> net_mqtt_enc: Encoding Protocol Description.
                                       4d 51 54 54                                      |MQTT
[00:00:04.498,107] <dbg> net_mqtt_enc.pack_utf8_str: (0x20015120): >> str_size:00000006 cur:0x20016973, end:0x200169ee
[00:00:04.498,107] <dbg> net_mqtt_enc.pack_uint16: (0x20015120): >> val:0004 cur:0x20016973, end:0x200169ee
[00:00:04.498,107] <dbg> net_mqtt_enc.connect_request_encode: (0x20015120): Encoding Protocol Version 04.
[00:00:04.498,138] <dbg> net_mqtt_enc.pack_uint8: (0x20015120): >> val:04 cur:0x20016979, end:0x200169ee
[00:00:04.498,138] <dbg> net_mqtt_enc.pack_uint8: (0x20015120): >> val:00 cur:0x2001697a, end:0x200input
--- 21 messages dropped ---
[00:00:04.599,456] <dbg> net_mqtt_rx.mqtt_handle_packet: (0x20015120): [CID 0x200152dc]: return_code: 0
[00:00:04.605,682] <inf> mqtt_simple: Subscribing to: s20/60412s len 10
[00:00:04.605,712] <dbg> net_mqtt.mqtt_subscribe: (0x20015120): [CID 0x200152dc]:[State 0x06]: >> message id 0x04d2 topic count 0x0001
[00:00:04.605,773] <dbg> net_mqtt_enc.pack_uint16: (0x20015120): >> val:04d2 cur:0x20016973, end:0x200169ee
[00:00:04.605,804] <dbg> net_mqtt_enc.pack_utf8_str: (0x20015120): >> str_size:0000000c cur:0x20016975, end:0x200169ee
[00:00:04.605,804] <dbg> net_mqtt_enc.pack_uint16: (0x20015120): >> val:000a cur:0x20016975, end:0x200169ee
[00:00:04.605,834] <dbg> net_mqtt_enc.pack_uint8: (0x20015120): >> val:01 cur:0x20016981, end:0x200169ee
[00:00:04.605,865] <dbg> net_mqtt_enc.mqtt_encode_fixed_header: (0x20015120): << msg type:0x82 length:0x0000000f
[00:00:04.605,926] <dbg> net_mqtt_enc.packet_length_encode: (0x20015120): >> length:0x0000000f cur:(nil), end:(nil)
[00:00:04.605,926] <dbg> net_mqtt_enc.mqtt_encode_fixed_header: (0x20015120): Fixed header length = 02
[00:00:04.605,957] <dbg> net_mqtt_enc.pack_uint8: (0x20015120): >> val:82 cur:0x20016971, end:0x200169ee
[00:00:04.606,018] <dbg> net_mqtt_enc.packet_length_encode: (0x20015120): >> length:0x0000000f cur:0x20016972, end:0x200169ee
[00:00:04.606,048] <dbg> net_mqtt.client_write: (0x20015120): [0x200152dc]: Transport writing 17 bytes.
[00:00:04.606,445] <dbg> net_mqtt.client_write: (0x20015120): [0x200152dc]: Transport write complete.
[00:00:04.606,475] <dbg> net_mqtt.mqtt_subscribe: (0x20015120): [CID 0x200152dc]:[State 0x06]: << result 0x00000000
[00:00:04.607,482] <wrn> date_time: Valid time not currently available
[00:00:04.607,513] <wrn> date_time: date_time_uptime_to_unix_time_ms, error: -61
Received an gnss_event NRF_MODEM_GNSS_EVT_BLOCKED
Received an gnss_event NRF_MODEM_GNSS_EVT_UNBLOCKED
[00:00:24.449,218] <dbg> lte_lc.at_handler: +CSCON notification
ant_buffer: FF C7 50 02 00 00
ant_queue: k_msgq_num_used_get: (1)
data_to_send true : time_to_transfer: 0
**** Start: Send ANT_DATA
ANT: FF C7 50 02 00 00 23 00
FF C7 50 02 00 00 23 00
to topic: s20/60412p len: 10
Call to mqtt_publish
[00:Finish Call to mqtt_publish
00:35.611,907] <inf> mqtt_simple: Publishing: {
                                                "e":    199,
                                                                "a":    592,
                                                                                "i":    0,
                                                                                                "t":    35
                                                                                                          }
[00:00:35.616,577] <dbg> net_mqtt.mqtt_publish: (0x20015120): [CID 0x200152dc]:[State 0x06]: >> Topic size 0x0000000a, Data size 0x0000002b
[00:00:35.616,607] <dbg> net_mqtt.mqtt_publish: (0x20015120): Before Lock
[00:00:35.616,607] <dbg> net_mqtt.mqtt_publish: (0x20015120): After Lock
[00:00:35.616,638] <dbg> net_mqtt_enc.pack_utf8_str: (0x20015120): >> str_size:0000000c cur:0x20016973, end:0x200169ee
[00:00:35.616,638] <dbg> net_mqtt_enc.pack_uint16: (0x20015120): >> val:000a cur:0x20016973, end:0x200169ee
[00:00:35.616,668] <dbg> net_mqtt_enc.pack_uint16: (0x20015120): >> val:fc32 cur:0x2001697f, end:0x200169ee
[00:00:35.616,668] <dbg> net_mqtt_enc.mqtt_encode_fixed_header: (0x20015120): << msg type:0x32 length:0x00000039
[00:00:35.616,699] <dbg> net_mqtt_enc.packet_length_encode: (0x20015120): >> length:0x00000039 cur:(nil), end:(nil)
[00:00:35.616,699] <dbg> net_mqtt_enc.mqtt_encode_fixed_header: (0x20015120): Fixed header length = 02
[00:00:35.616,729] <dbg> net_mqtt_enc.pack_uint8: (0x20015120): >> val:32 cur:0x20016971, end:0x200169ee
[00:00:35.616,760] <dbg> net_mqtt_enc.packet_length_encode: (0x20015120): >> length:0x00000039 cur:0x20016972, end:0x200169ee
[00:00:35.616,760] <dbg> net_mqtt.client_write_msg: (0x20015120): [0x200152dc]: Transport writing message.
[00:00:35.617,279] <dbg> net_mqtt.client_write_msg: (0x20015120): [0x200152dc]: Transport write complete.
[00:00:35.617,309] <dbg> net_mqtt.mqtt_publish: (0x20015120): [CID 0x200152dc]:[State 0x06]: << result 0x00000000
[00:00:35.617,309] <dbg> net_mqtt.mqtt_publish: (0x20015120): Before UnLock
[00:00:35.617,340] <dbg> net_mqtt.mqtt_publish: (0x20015120): After UnLock
**** Finish: Send ANT_DATA
Received an gnss_event NRF_MODEM_GNSS_EVT_BLOCKED
[00:00:36.613,677] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 1,"3012","0829550D",7,,,"00001000","1~
[00:00:36.614,013] <dbg> lte_lc_helpers.parse_cereg: Network registration status: 1
[00:00:36.614,044] <dbg> lte_lc_helpers.parse_cereg: LTE mode: 7
[00:00:36.614,074] <dbg> lte_lc_helpers.parse_psm: TAU: -1 sec, active time: 16 sec

[00:00:36.769,927] <dbg> lte_lc.at_handler: +CSCON notification
Received an gnss_event NRF_MODEM_GNSS_EVT_UNBLOCKED
[00:00:48.811,340] <dbg> lte_lc.at_handler: +CSCON notificati+++ Poll result: 2 : 16 : 0
Received an gnss_event NRF_MODEM_GNSS_EVT_BLOCKED
**** Start: Send ANT_DATA
ANT: 98 C8 50 02 00 00 42 00
98 C8 50 02 00 00 42 00
to topic: s20/60412p len: 10
Call to mqtt_publish
[00:01:06.824,279] <inf> mqtt_simple: Publishing: {
                                                        "e":    200,
                                                                        "a":    592,
                                                                                        "i":    0,
                                                                                                        "t":    66
                                                                                                                  }
[00:01:06.828,948] <dbg> net_mqtt.mqtt_publish: (0x20015120): [CID 0x200152dc]:[State 0x06]: >> Topic size 0x0000000a, Data size 0x0000002b
[00:01:06.828,948] <dbg> net_mqtt.mqtt_publish: (0x20015120): Before Lock
Received an gnss_event NRF_MODEM_GNSS_EVT_UNBLOCKED

regards
-brett

[Brett]

I forgot to add, this is running from the v1.6.0 SDK.

I tried 1.7.0 but had issues when loading and booting the code, so went back to 1.6.0.

I tried to go to 2.0.0, but too many breaking changes for now - I will migrate there when I have more time.

[JONATHAN LL]

Hi, We have entered the summer holiday period in Norway so staffing is low, so some delayed response time is expected.
Regards,
Jonathan

[JONATHAN LL]

There are some configuration options to considder, https://github.com/nrfconnect/sdk-nrf/tree/v1.6.0/samples/nrf9160/mqtt_simple#configuration 

Do you have a reconnect defined or a keepalive?

Regards,
Jonathan

[Brett]

Hi Jonathan,

CONFIG_MQTT_KEEPALIVE=1200

reconnect is not defined.

The strange thing is, it sends the first packet fine its only when it sends the 2nd packet that it locks up and this send is basically immediately, as I have 10 packets buffered in a queue to send. 

Is there anything that I need to consider when doing batch processing like this ? Timing or ?
Do I need to consider a different MQTT setting ?

Do I need to consider any ACK packets for MQTT or is all this managed by the underlying protocol stack.  I dont really understand the full implementations of poll, mqtt_live and mqtt_input functions and if I need to manage any of these after I do the send. In this instance the code is a producer only - no subscribe required.

I understand the basics, but not sure if I am missing anything.  Happy to share the code I am using if that helps.  Its a bit ugly at the moment, with all the debug print statements :)

regards
-brett

[Brett]

Fullscreen 7217.prj.txt Download

#
# Copyright (c) 2019 Nordic Semiconductor ASA
#
# SPDX-License-Identifier: LicenseRef-Nordic-5-Clause
#

CONFIG_FPU=y
CONFIG_NRF_MODEM_LIB=y
CONFIG_STDOUT_CONSOLE=y
CONFIG_UART_INTERRUPT_DRIVEN=y
CONFIG_NEWLIB_LIBC=y
CONFIG_NEWLIB_LIBC_FLOAT_PRINTF=y
CONFIG_AT_CMD=y
CONFIG_AT_NOTIF=y

# Disable Modem traces, since we need UART1 ?
CONFIG_NRF_MODEM_LIB_TRACE_ENABLED=n

# To use SUPL client library for assisted GPS, enable the options below
CONFIG_SUPL_CLIENT_LIB=n

# Want LTE and GPS
CONFIG_LTE_LINK_CONTROL=y

CONFIG_LTE_NETWORK_MODE_LTE_M_GPS=y

# Auto-connect should be left off as we want the application to control LTE
CONFIG_LTE_AUTO_INIT_AND_CONNECT=n

CONFIG_LTE_PSM_REQ_RAT="00000001"

# Networking
CONFIG_NETWORKING=y
CONFIG_NET_SOCKETS_OFFLOAD=y
CONFIG_NET_SOCKETS=y
CONFIG_NET_SOCKETS_POSIX_NAMES=y
CONFIG_NET_SOCKETS_SOCKOPT_TLS=y

# Disable native network stack to save some memory
CONFIG_NET_NATIVE=n

# Main thread
CONFIG_HEAP_MEM_POOL_SIZE=2048
CONFIG_MAIN_STACK_SIZE=4096

# Application
CONFIG_GPS_SAMPLE_NMEA_ONLY=n
CONFIG_GPS_SAMPLE_ANTENNA_EXTERNAL=y

# CJSON
CONFIG_CJSON_LIB=y

# Modem information
CONFIG_MODEM_INFO=y

# Date Time library
CONFIG_DATE_TIME=y

# MQTT
CONFIG_MQTT_LIB=y
CONFIG_MQTT_LIB_TLS=n
CONFIG_MQTT_CLEAN_SESSION=y

# Application
#CONFIG_MQTT_PUB_TOPIC="my/publish/topic"
CONFIG_MQTT_PUB_TOPIC="s20/60412p"
CONFIG_MQTT_PUB_POWER_TOPIC="s20/60412p"
CONFIG_MQTT_PUB_GPS_TOPIC="s20/60412g"
#CONFIG_MQTT_SUB_TOPIC="my/subscribe/topic"
CONFIG_MQTT_SUB_TOPIC="s20/60412s"
#CONFIG_MQTT_CLIENT_ID="my-client-id"
CONFIG_MQTT_BROKER_HOSTNAME="220.253.128.250"
CONFIG_MQTT_BROKER_PORT=1883

# AWS IoT library
#CONFIG_AWS_IOT=n
#CONFIG_AWS_IOT_CLIENT_ID_STATIC="nrf9160-mqtt"
#CONFIG_AWS_IOT_BROKER_HOST_NAME="aco9h4lx2fta3-ats.iot.us-west-2.amazonaws.com"
#CONFIG_AWS_IOT_SEC_TAG=16842753
#CONFIG_AWS_IOT_APP_SUBSCRIPTION_LIST_COUNT=2
#CONFIG_AWS_IOT_TOPIC_UPDATE_DELTA_SUBSCRIBE=y
#CONFIG_AWS_IOT_LAST_WILL=y
#CONFIG_AWS_IOT_TOPIC_GET_ACCEPTED_SUBSCRIBE=y
#CONFIG_AWS_IOT_TOPIC_GET_REJECTED_SUBSCRIBE=y

# MQTT - Maximum MQTT keepalive timeout specified by AWS IoT Core
#CONFIG_MQTT_KEEPALIVE=1200
# In Seconds
CONFIG_MQTT_KEEPALIVE=1200

# Date Time library
CONFIG_DATE_TIME=y

#  - got errors from below when added teh simple mqtt
# -- FROM UARTE CODE ---
# Enable the NUS service

#CONFIG_BT_NUS=y

# Enable bonding
#CONFIG_BT_SETTINGS=y
CONFIG_FLASH=y
CONFIG_FLASH_PAGE_LAYOUT=y
CONFIG_FLASH_MAP=y
CONFIG_NVS=y
CONFIG_SETTINGS=y

# Enable DK LED and Buttons library
CONFIG_DK_LIBRARY=y

# This example requires more workqueue stack
CONFIG_SYSTEM_WORKQUEUE_STACK_SIZE=2048

# Config logger
CONFIG_LOG=y
CONFIG_STDOUT_CONSOLE=y
CONFIG_USE_SEGGER_RTT=y
CONFIG_LOG_BACKEND_RTT=y
CONFIG_LOG_BACKEND_UART=y
CONFIG_MQTT_SIMPLE_LOG_LEVEL_DBG=y
CONFIG_LTE_LINK_CONTROL_LOG_LEVEL_DBG=y

CONFIG_ASSERT=y

# New settings now sure why
CONFIG_UART_CONSOLE_LOG_LEVEL_INF=y
### configure the uart between 9160 and 52840
CONFIG_UART_INTERRUPT_DRIVEN=y

# Debug Added 27/06
CONFIG_NET_LOG=y
CONFIG_MQTT_LOG_LEVEL_DBG=y

This is my prj.conf file if it helps