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:
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:
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
