subscribing in Assert tracker v2

[Mustafa]

Hello,

I'm trying to send messages from the cloud (AWS-IoT ) to the device, so I modified the device so that it subscribes to a new topic and when I send messages from could, it seems that the device doesn't listen frequently to the cloud. sometimes it receives a message, sometimes not. and when I sent multi messages very fast, the device receive all messages after a random delay. 

I tried to check the code if there is any configuration I can use to force the device to listen to Cloud always. but without luck. This behavior is in Active and Passive mode as well. 

My question is: How can the device receive messages instantly from the cloud without delay. 

Thanks in advance.

[Markus Tacker (he/him)]

Hei Mustafa,

this might be due to the device going into PSM, or if you are on NB-IoT the NAT timing out. You can experiment with lowering the MQTT keepalive time (CONFIG_MQTT_KEEPALIVE). However this increases energy consumption.

[Mustafa]

Thank you Markus for your tips. I"m actually using LTE-m.
I've realized that the cloud doesn't receive any message from the device side when I modify CONFIG_MQTT_KEEPALIVE to more than 130 sec. The device behaves normally and logs output confirm that message has been published, but from the cloud-side, no message is received. Any hints for this problem. 

[Markus Tacker (he/him)]

Hei, thanks for the trance. It was in parts corrupted, maybe due to UART issues, but I'll forward it internally for some analysis.

[Markus Tacker (he/him)]

Which modem firmware version are you running?

[Mustafa]

it is version 1.3.0

[Markus Tacker (he/him)]

Thanks!

[Markus Tacker (he/him)]

Unfortunately, the trace was corrupted. This can happen if using a defective USB cable, but also could be cause by an outdated firmware on the onboard Segger chip.

If you use a DK, you can update the firmware on the onboard Segger chip, which should improve the UART performance. You can use a tool called J-Link Configurator to do this. The tool ships with the J-Link software bundle, so there's a good chance that you have already installed it. If not, you can get it here: https://www.segger.com/downloads/jlink/#J-LinkSoftwareAndDocumentationPack

Get v7.52 or newer.

To verify that a trace is not corrupted, you can use the nRF Trace Collector.  It has the option (and instructions how to) both collect traces and view them in Wireshark. If what you see in Wireshark makes sense, that's a good sign.

[Mustafa]

Hey Markus, Thanks for ur answer. I attached the new binary file of the modem trace. Unfortunately, I couldn't find a way to verify the binary file. 
Actually, I tried to use another sim card from T-Mobile in NL and it seems that the Cloud timeout event is triggered every time the application tries to ping Mqtt broker ( AWS ), in my case every 20 min since 

CONFIG_MQTT_KEEPALIVE=1200

App's Log

[00:00:00.254,913] <inf> event_manager: APP_EVT_START
[00:00:00.260,772] <dbg> gps_module.state_set: State: STATE_INIT
[00:00:00.268,341] <dbg> cloud_module.state_set: State: Unknown
[00:00:00.275,085] <dbg> cloud_module.sub_state_set: Sub state: SUB_STATE_CLOUD_DISCONNECTED
///////////////////////////////////////////////////////////////////////////////////////////
[00:00:00.287,445] <wrn> data_module: Device configuration loaded from flash
[00:00:00.295,654] <wrn> data_module: active_mode = 0
[00:00:00.301,818] <wrn> data_module: active_wait_timeout = 300
[00:00:00.308,868] <wrn> data_module: movement_resolution = 60
[00:00:00.315,765] <wrn> data_module: movement_timeout = 3600
[00:00:00.322,601] <wrn> data_module: gps_timeout = 60
[00:00:00.328,887] <wrn> data_module: accelerometer_threshold = 5.000000
///////////////////////////////////////////////////////////////////////////////////////
[00:00:00.336,944] <inf> event_manager: DATA_EVT_CONFIG_INIT
[00:00:00.344,024] <inf> event_manager: MODEM_EVT_INITIALIZED
[00:00:00.351,013] <dbg> gps_module.lna_configure: MAGPIO command: AT%XMAGPIO=1,0,0,1,1,1574,1577
[00:00:00.360,839] <dbg> gps_module.lna_configure: COEX0 command: AT%XCOEX0=1,1,1565,1586
[00:00:00.370,025] <dbg> sensor_module.state_set: State: STATE_INIT
[00:00:00.379,241] <dbg> sensor_module.state_set: State transition STATE_INIT --> STATE_RUNNING
[00:00:00.401,550] <dbg> gps_module.state_set: State transition STATE_INIT --> STATE_RUNNING
[00:00:00.391,143] <dbg> cloud_module.state_set: State transition Unknown --> STATE_LTE_DISCONNECTED
[00:00:00.705,078] <inf> event_manager: MODEM_EVT_LTE_CONNECTING
[00:00:06.509,613] <inf> event_manager: MODEM_EVT_LTE_DISCONNECTED
[00:00:06.517,364] <inf> event_manager: MODEM_EVT_LTE_CELL_UPDATE
[00:00:07.289,825] <inf> event_manager: MODEM_EVT_LTE_CONNECTED
[00:00:07.302,642] <inf> event_manager: MODEM_EVT_LTE_PSM_UPDATE
[00:00:07.310,272] <dbg> cloud_module.state_set: State transition STATE_LTE_DISCONNECTED --> STATE_LTE_CONNECTED
[00:00:07.321,502] <dbg> cloud_module.connect_cloud: Connecting to cloud
[00:00:07.334,686] <wrn> cloud_module: Cloud connection establishment in progress
[00:00:07.343,383] <wrn> cloud_module: New connection attempt in 32 seconds if not successful
[00:00:07.353,240] <dbg> aws_iot_integration.aws_iot_event_handler: AWS_IOT_EVT_CONNECTING
[00:00:07.362,396] <dbg> cloud_module.cloud_wrap_event_handler: CLOUD_WRAP_EVT_CONNECTING
[00:00:07.371,582] <inf> event_manager: CLOUD_EVT_CONNECTING
[00:00:10.293,853] <dbg> aws_iot_integration.aws_iot_event_handler: AWS_IOT_EVT_CONNECTED
[00:00:10.467,620] <dbg> aws_iot_integration.aws_iot_event_handler: AWS_IOT_EVT_READY
[00:00:10.476,409] <dbg> cloud_module.cloud_wrap_event_handler: CLOUD_WRAP_EVT_CONNECTED
[00:00:10.513,031] <inf> event_manager: CLOUD_EVT_CONNECTED
[00:00:10.520,996] <dbg> cloud_module.sub_state_set: Sub state transition SUB_STATE_CLOUD_DISCONNECTED --> SUB_STATE_CLOUD_CONNECTED
[00:00:10.778,289] <inf> event_manager: DATA_EVT_DATE_TIME_OBTAINED
[00:00:10.788,818] <inf> event_manager: APP_EVT_DATA_GET - Requested data types (MOD_DYN, BAT, ENV, NEIGHBOR_CELLS, MOD_STAT)
[00:00:10.801,849] <dbg> sensor_module.environmental_data_get: No external sensors, submitting dummy sensor data
[00:00:10.813,110] <inf> event_manager: SENSOR_EVT_ENVIRONMENTAL_NOT_SUPPORTED
[00:00:10.904,998] <inf> event_manager: MODEM_EVT_MODEM_STATIC_DATA_READY
[00:00:10.995,849] <inf> event_manager: MODEM_EVT_MODEM_DYNAMIC_DATA_READY
[00:00:11.004,425] <dbg> cloud_codec_ringbuffer.cloud_codec_populate_modem_dynamic_buffer: Entry: 1 of 2 in dynamic modem buffer filled
[00:00:11.146,301] <inf> event_manager: MODEM_EVT_BATTERY_DATA_READY
[00:00:11.172,119] <inf> event_manager: MODEM_EVT_NEIGHBOR_CELLS_DATA_READY
[00:00:11.154,266] <dbg> cloud_codec_ringbuffer.cloud_codec_populate_bat_buffer: Entry: 1 of 2 in battery buffer filled
[00:00:11.191,711] <inf> event_manager: DATA_EVT_DATA_READY
[00:00:11.219,055] <inf> event_manager: DATA_EVT_NEIGHBOR_CELLS_DATA_SEND
[00:00:11.294,708] <inf> event_manager: DATA_EVT_DATA_SEND
[00:00:11.302,612] <dbg> cloud_codec.cloud_codec_encode_batch_data: No data to encode, JSON string empty...
[00:00:11.323,852] <dbg> cloud_module.neighbor_cells_data_send: Neighbor cell data sent, data pointer: 0x2001e748
[00:00:11.335,266] <inf> event_manager: CLOUD_EVT_DATA_ACK
[00:00:11.349,334] <dbg> cloud_module.data_send: Data sent, data pointer: 0x2001ec58
[00:00:11.358,123] <inf> event_manager: CLOUD_EVT_DATA_ACK
[00:01:00.343,994] <inf> event_manager: APP_EVT_ACTIVITY_DETECTION_ENABLE
[00:20:11.383,575] <dbg> aws_iot_integration.aws_iot_event_handler: AWS_IOT_EVT_DISCONNECTED
[00:20:11.393,524] <dbg> cloud_module.cloud_wrap_event_handler: CLOUD_WRAP_EVT_DISCONNECTED
[00:20:11.405,303] <inf> event_manager: CLOUD_EVT_DISCONNECTED
[00:20:11.414,367] <dbg> cloud_module.sub_state_set: Sub state transition SUB_STATE_CLOUD_CONNECTED --> SUB_STATE_CLOUD_DISCONNECTED
[00:20:11.427,459] <dbg> cloud_module.connect_check_work_fn: Cloud connection timeout occurred
[00:20:11.437,133] <inf> event_manager: CLOUD_EVT_CONNECTION_TIMEOUT
[00:20:11.444,824] <dbg> cloud_module.connect_cloud: Connecting to cloud
[00:20:11.452,423] <wrn> cloud_module: Cloud connection establishment in progress
[00:20:11.461,090] <wrn> cloud_module: New connection attempt in 32 seconds if not successful
[00:20:11.470,916] <dbg> aws_iot_integration.aws_iot_event_handler: AWS_IOT_EVT_CONNECTING
[00:20:11.480,133] <dbg> cloud_module.cloud_wrap_event_handler: CLOUD_WRAP_EVT_CONNECTING
[00:20:11.492,126] <inf> event_manager: CLOUD_EVT_CONNECTING
[00:20:14.386,016] <dbg> aws_iot_integration.aws_iot_event_handler: AWS_IOT_EVT_CONNECTED
[00:20:14.591,369] <dbg> aws_iot_integration.aws_iot_event_handler: AWS_IOT_EVT_READY
[00:20:14.600,158] <dbg> cloud_module.cloud_wrap_event_handler: CLOUD_WRAP_EVT_CONNECTED
[00:20:14.613,830] <inf> event_manager: CLOUD_EVT_CONNECTED
[00:20:14.623,626] <dbg> cloud_module.sub_state_set: Sub state transition SUB_STATE_CLOUD_DISCONNECTED --> SUB_STATE_CLOUD_CONNECTED
[00:20:14.636,810] <inf> event_manager: DATA_EVT_DATE_TIME_OBTAINED
[00:20:14.644,561] <inf> event_manager: APP_EVT_DATA_GET - Requested data types (MOD_DYN, BAT, ENV, NEIGHBOR_CELLS)
[00:20:14.656,707] <dbg> sensor_module.environmental_data_get: No external sensors, submitting dummy sensor data
[00:20:14.667,999] <inf> event_manager: SENSOR_EVT_ENVIRONMENTAL_NOT_SUPPORTED
[00:20:14.761,810] <inf> event_manager: MODEM_EVT_MODEM_DYNAMIC_DATA_READY
[00:20:14.770,355] <dbg> cloud_codec_ringbuffer.cloud_codec_populate_modem_dynamic_buffer: Entry: 2 of 2 in dynamic modem buffer filled
[00:20:14.847,076] <inf> event_manager: MODEM_EVT_BATTERY_DATA_READY
[00:20:14.874,450] <inf> event_manager: MODEM_EVT_NEIGHBOR_CELLS_DATA_READY
[00:20:14.856,140] <dbg> cloud_codec_ringbuffer.cloud_codec_populate_bat_buffer: Entry: 2 of 2 in battery buffer filled
[00:20:14.895,019] <inf> event_manager: DATA_EVT_DATA_READY
[00:20:14.922,393] <inf> event_manager: DATA_EVT_NEIGHBOR_CELLS_DATA_SEND
[00:20:14.954,986] <inf> event_manager: DATA_EVT_DATA_SEND
[00:20:14.962,921] <dbg> cloud_codec.cloud_codec_encode_batch_data: No data to encode, JSON string empty...
[00:20:14.983,612] <dbg> cloud_module.neighbor_cells_data_send: Neighbor cell data sent, data pointer: 0x2001e748
[00:20:14.995,666] <inf> event_manager: CLOUD_EVT_DATA_ACK
[00:20:15.019,470] <dbg> cloud_module.data_send: Data sent, data pointer: 0x2001e688
[00:20:15.028,228] <inf> event_manager: CLOUD_EVT_DATA_ACK

I've tried the Assert tracker v2 of SDK v1.7.1 and SDK v1.6.1 as well. They both gave the same result. 

The configuration of TAU and active timer is

CONFIG_LTE_PSM_REQ_RPTAU="00100001"        # 1hour

CONFIG_LTE_PSM_REQ_RAT="00000001"             # 2 sec

the values of timers are confirmed by this command 

AT+CEREG?

+CEREG: 5,5,"0106","00277416",7,,,"00000001","00100001"

OK
trace-2021-10-03T15-01-15.377Z.rar