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.

[Albrecht Markus Schellenberger]

Mustafa said:

Actually I'm still wondering about the reason to close the TCP connection with server-side. It supposes to keep the connection alive because CONFIG_MQTT_KEEPALIVE = 1200. even I tried to reduce this time but it always closes the connection after 320 seconds ( any value above 320sec causes CLOUD_TIMEOUT event).

Thanks a lot for your feedback, Mustafa! That is a good and interesting observation. I wonder if maybe the NAT rules time-out, making the server not recognise the client anymore? I have to check this with our experts. I’ll be on vacation next week, but I asked my colleague Didrik Rokhaug to watch this ticket.

Regards,

Markus

[Didrik Rokhaug]

Hi,

Could you try to disable PSM, to see if that changes things?

Best regards,

Didrik

[Mustafa]

Hello Didrik, 

What is the best way to disable PSM in the prj.conf ?

Thanks

[Didrik Rokhaug]

When using the asset_tracker_v2, you can set CONFIG_MODEM_AUTO_REQUEST_POWER_SAVING_FEATURES=n.

That should stop the application from requesting PSM.

[Mustafa]

Hey Didrik, I disabled PSM and tried again but it seems that it is the same, no difference. After 300 sec no data was sent to the server-side, even it shows in the logs that data is sent successfully but no data is received by server-side. I attached here the trace file and the log file as well, hoping that you can figure out what the problem is. 

Thanks in advance. 

[00:00:00.223,754] <wrn> cloud_codec: set alarm ---> 1
[00:00:00.257,659] <dbg> cloud_module.state_set: State: STATE_LTE_DISCONNECTED
[00:00:00.267,822] <dbg> cloud_module.sub_state_set: Sub state: SUB_STATE_CLOUD_DISCONNECTED
[00:00:00.287,780] <wrn> data_module: Device configuration loaded from flash
[00:00:00.298,461] <wrn> data_module: active_mode = 0
[00:00:00.306,518] <wrn> data_module: active_wait_timeout = 300
[00:00:00.315,399] <wrn> data_module: movement_resolution = 60
[00:00:00.327,087] <wrn> data_module: movement_timeout = 1000
[00:00:00.335,968] <wrn> data_module: gps_timeout = 60
[00:00:00.344,024] <wrn> data_module: accelerometer_threshold = 5.000000
[00:00:00.359,924] <wrn> app_module: the certificates are found
[00:00:00.367,462] <inf> event_manager: APP_EVT_START
[00:00:00.373,535] <dbg> gps_module.state_set: State: STATE_INIT
[00:00:00.354,766] <dbg> sensor_module.state_set: State: STATE_INIT
[00:00:00.524,230] <inf> event_manager: DATA_EVT_CONFIG_INIT
[00:00:00.530,975] <dbg> gps_module.state_set: State transition STATE_INIT --> STATE_RUNNING
[00:00:00.542,541] <inf> app_module: Device mode: Passive
[00:00:00.548,675] <inf> app_module: Start movement timeout: 1000 seconds interval
[00:00:00.557,098] <inf> app_module: 60 seconds until movement can trigger a new data sample/publication
[00:00:00.567,932] <dbg> sensor_module.state_set: State transition STATE_INIT --> STATE_RUNNING
[00:00:00.697,998] <inf> event_manager: MODEM_EVT_LTE_CONNECTING
[00:00:01.783,447] <inf> event_manager: MODEM_EVT_LTE_DISCONNECTED
[00:00:01.801,055] <inf> event_manager: MODEM_EVT_LTE_CELL_UPDATE
[00:00:02.493,225] <inf> event_manager: MODEM_EVT_LTE_CONNECTED
[00:00:02.500,549] <inf> event_manager: MODEM_EVT_LTE_PSM_UPDATE
[00:00:02.507,995] <dbg> cloud_module.state_set: State transition STATE_LTE_DISCONNECTED --> STATE_LTE_CONNECTED
[00:00:02.519,165] <dbg> cloud_module.connect_cloud: Connecting to cloud
[00:00:02.526,763] <wrn> cloud_module: Cloud connection establishment in progress
[00:00:02.535,369] <wrn> cloud_module: New connection attempt in 32 seconds if not successful
[00:00:02.545,104] <dbg> aws_iot_integration.aws_iot_event_handler: AWS_IOT_EVT_CONNECTING
[00:00:02.554,229] <dbg> cloud_module.cloud_wrap_event_handler: CLOUD_WRAP_EVT_CONNECTING
[00:00:02.563,415] <inf> event_manager: CLOUD_EVT_CONNECTING
[00:00:06.347,198] <dbg> aws_iot_integration.aws_iot_event_handler: AWS_IOT_EVT_CONNECTED
[00:00:06.545,806] <dbg> aws_iot_integration.aws_iot_event_handler: AWS_IOT_EVT_READY
[00:00:06.570,129] <dbg> cloud_module.cloud_wrap_event_handler: CLOUD_WRAP_EVT_CONNECTED
[00:00:06.606,109] <inf> event_manager: CLOUD_EVT_CONNECTED
[00:00:06.613,922] <dbg> cloud_module.sub_state_set: Sub state transition SUB_STATE_CLOUD_DISCONNECTED --> SUB_STATE_CLOUD_CONNECTED
[00:00:06.855,651] <inf> event_manager: DATA_EVT_DATE_TIME_OBTAINED
[00:00:06.863,189] <inf> event_manager: APP_EVT_DATA_GET - Requested data types (MOD_DYN, BAT, ENV, GNSS, MOD_STAT)
[00:00:06.904,235] <inf> event_manager: GPS_EVT_ACTIVE
[00:00:06.910,369] <dbg> gps_module.sub_state_set: Sub state transition SUB_STATE_IDLE --> SUB_STATE_SEARCH
[00:00:06.921,173] <dbg> gps_module.gps_event_handler: GPS_EVT_SEARCH_STARTED
[00:00:06.929,229] <dbg> gps_module.gps_event_handler: GPS_EVT_AGPS_DATA_NEEDED
[00:00:06.937,500] <inf> event_manager: GPS_EVT_AGPS_NEEDED
[00:00:06.944,427] <dbg> sensor_module.environmental_data_get: No external sensors, submitting dummy sensor data
[00:00:06.958,984] <inf> event_manager: SENSOR_EVT_ENVIRONMENTAL_NOT_SUPPORTED
[00:00:06.968,475] <inf> agps: SUPL is initialized
[00:00:07.064,544] <inf> event_manager: MODEM_EVT_MODEM_STATIC_DATA_READY
[00:00:07.147,796] <inf> agps: Starting SUPL session
[00:00:07.216,156] <inf> event_manager: MODEM_EVT_MODEM_DYNAMIC_DATA_READY
[00:00:07.245,758] <dbg> cloud_codec_ringbuffer.cloud_codec_populate_modem_dynamic_buffer: Entry: 1 of 2 in dynamic modem buffer filled
[00:00:07.558,776] <inf> event_manager: MODEM_EVT_BATTERY_DATA_READY
[00:00:07.587,951] <dbg> cloud_codec_ringbuffer.cloud_codec_populate_bat_buffer: Entry: 1 of 2 in battery buffer filled
[00:00:07.892,944] <dbg> gps_module.gps_event_handler: GPS_EVT_OPERATION_BLOCKED
[00:00:09.315,582] <inf> agps: SUPL session finished successfully
[00:00:22.259,094] <dbg> gps_module.gps_event_handler: GPS_EVT_OPERATION_UNBLOCKED
[00:00:35.329,620] <dbg> gps_module.gps_event_handler: GPS_EVT_OPERATION_BLOCKED
[00:01:00.567,718] <inf> event_manager: APP_EVT_ACTIVITY_DETECTION_ENABLE
[00:01:21.968,444] <inf> event_manager: DATA_EVT_DATA_READY
[00:01:22.073,333] <inf> event_manager: DATA_EVT_DATA_SEND
[00:01:22.080,322] <dbg> cloud_codec.cloud_codec_encode_batch_data: No data to encode, JSON string empty...
[00:01:22.184,082] <wrn> cloud_module:  Data sent, data pointer: 0x200201e0
[00:01:22.192,199] <inf> event_manager: CLOUD_EVT_DATA_ACK
[00:01:41.464,813] <dbg> gps_module.gps_event_handler: GPS_EVT_SEARCH_TIMEOUT
[00:01:41.472,900] <inf> event_manager: GPS_EVT_TIMEOUT
[00:01:41.479,156] <inf> event_manager: GPS_EVT_INACTIVE
[00:01:41.485,473] <dbg> gps_module.sub_state_set: Sub state transition SUB_STATE_SEARCH --> SUB_STATE_IDLE
[00:01:41.496,337] <inf> event_manager: DATA_EVT_DATA_READY
[00:01:41.503,387] <dbg> cloud_codec.cloud_codec_encode_data: No data to encode, JSON string empty...
[00:07:35.488,983] <inf> event_manager: UI_EVT_BUTTON_ALARM_DATA_READY
[00:07:35.496,520] <inf> event_manager: UI_EVT_BUTTON_DATA_READY
[00:07:35.503,662] <inf> event_manager: APP_EVT_DATA_GET_ALL
[00:07:35.510,498] <inf> app_module: Device mode: Passive
[00:07:35.516,693] <inf> app_module: Start movement timeout: 1000 seconds interval
[00:07:35.525,207] <inf> app_module: 60 seconds until movement can trigger a new data sample/publication
[00:07:35.535,888] <inf> event_manager: APP_EVT_DATA_GET - Requested data types (MOD_DYN, BAT, ENV, GNSS)
[00:07:35.546,752] <wrn> cloud_codec: set alarm ---> 1
[00:07:35.556,518] <dbg> cloud_codec_ringbuffer.cloud_codec_populate_ui_buffer: Entry: 1 of 2 in UI buffer filled
[00:07:35.570,800] <dbg> cloud_codec_ringbuffer.cloud_codec_populate_ui_buffer: Entry: 2 of 2 in UI buffer filled
[00:07:35.606,475] <inf> event_manager: DATA_EVT_UI_DATA_READY
[00:07:35.613,403] <inf> event_manager: DATA_EVT_UI_DATA_READY
[00:07:35.620,330] <inf> event_manager: GPS_EVT_ACTIVE
[00:07:35.643,585] <dbg> gps_module.sub_state_set: Sub state transition SUB_STATE_IDLE --> SUB_STATE_SEARCH
[00:07:35.654,571] <dbg> sensor_module.environmental_data_get: No external sensors, submitting dummy sensor data
[00:07:35.665,771] <inf> event_manager: SENSOR_EVT_ENVIRONMENTAL_NOT_SUPPORTED
[00:07:35.690,826] <inf> event_manager: DATA_EVT_UI_DATA_SEND
[00:07:35.707,885] <inf> event_manager: UI_EVT_BUTTON_ALARM_DATA_READY
[00:07:35.699,401] <dbg> cloud_module.ui_data_send: UI sent, data pointer: 0x2001fbf8
[00:07:35.716,247] <inf> event_manager: CLOUD_EVT_DATA_ACK
[00:07:35.723,052] <wrn> cloud_codec: set alarm ---> 1
[00:07:35.729,187] <dbg> cloud_codec_ringbuffer.cloud_codec_populate_ui_buffer: Entry: 0 of 2 in UI buffer filled
[00:07:35.830,505] <inf> event_manager: DATA_EVT_UI_DATA_READY
[00:07:35.852,386] <inf> event_manager: DATA_EVT_UI_DATA_SEND
[00:07:35.863,189] <dbg> cloud_module.ui_data_send: UI sent, data pointer: 0x2001fc40
[00:07:35.875,549] <inf> event_manager: CLOUD_EVT_DATA_ACK
[00:07:36.300,201] <inf> event_manager: MODEM_EVT_MODEM_DYNAMIC_DATA_READY
[00:07:36.308,563] <dbg> cloud_codec_ringbuffer.cloud_codec_populate_modem_dynamic_buffer: Entry: 2 of 2 in dynamic modem buffer filled
[00:07:36.407,684] <inf> event_manager: UI_EVT_BUTTON_ALARM_DATA_READY
[00:07:36.425,537] <wrn> cloud_codec: set alarm ---> 0
[00:07:36.469,940] <dbg> cloud_codec_ringbuffer.cloud_codec_populate_ui_buffer: Entry: 1 of 2 in UI buffer filled
[00:07:36.487,152] <inf> event_manager: DATA_EVT_UI_DATA_READY
[00:07:36.508,880] <inf> event_manager: DATA_EVT_UI_DATA_SEND
[00:07:36.517,120] <dbg> cloud_module.ui_data_send: UI sent, data pointer: 0x2001fc00
[00:07:36.528,594] <inf> event_manager: CLOUD_EVT_DATA_ACK
[00:07:36.579,010] <inf> event_manager: MODEM_EVT_BATTERY_DATA_READY
[00:07:36.586,791] <dbg> cloud_codec_ringbuffer.cloud_codec_populate_bat_buffer: Entry: 2 of 2 in battery buffer filled
[00:07:36.639,862] <inf> event_manager: UI_EVT_BUTTON_ALARM_DATA_READY
[00:07:36.647,430] <wrn> cloud_codec: set alarm ---> 1
[00:07:36.653,625] <dbg> cloud_codec_ringbuffer.cloud_codec_populate_ui_buffer: Entry: 2 of 2 in UI buffer filled
[00:07:36.665,008] <inf> event_manager: DATA_EVT_UI_DATA_READY
[00:07:36.684,600] <inf> event_manager: DATA_EVT_UI_DATA_SEND
[00:07:36.700,531] <dbg> cloud_module.ui_data_send: UI sent, data pointer: 0x2001fc00
[00:07:36.709,320] <inf> event_manager: CLOUD_EVT_DATA_ACK
[00:08:05.594,970] <dbg> gps_module.gps_event_handler: GPS_EVT_OPERATION_UNBLOCKED
[00:08:10.650,787] <dbg> gps_module.gps_event_handler: GPS_EVT_OPERATION_BLOCKED
[00:08:29.078,704] <dbg> gps_module.gps_event_handler: GPS_EVT_OPERATION_UNBLOCKED
[00:08:34.143,585] <dbg> gps_module.gps_event_handler: GPS_EVT_OPERATION_BLOCKED
[00:08:35.535,797] <inf> event_manager: APP_EVT_ACTIVITY_DETECTION_ENABLE
[00:08:50.678,161] <inf> event_manager: DATA_EVT_DATA_READY
[00:08:50.711,395] <inf> event_manager: DATA_EVT_DATA_SEND
[00:08:50.718,383] <dbg> cloud_codec.cloud_codec_encode_batch_data: No data to encode, JSON string empty...
[00:08:50.733,062] <wrn> cloud_module:  Data sent, data pointer: 0x2001fd80
[00:08:50.741,271] <inf> event_manager: CLOUD_EVT_DATA_ACK
[00:08:52.627,044] <dbg> gps_module.gps_event_handler: GPS_EVT_OPERATION_UNBLOCKED
[00:08:56.790,222] <dbg> gps_module.gps_event_handler: GPS_EVT_OPERATION_BLOCKED
[00:09:26.429,962] <dbg> gps_module.gps_event_handler: GPS_EVT_SEARCH_TIMEOUT
[00:09:26.438,018] <inf> event_manager: GPS_EVT_TIMEOUT
[00:09:26.444,305] <inf> event_manager: GPS_EVT_INACTIVE
[00:09:26.450,592] <dbg> gps_module.sub_state_set: Sub state transition SUB_STATE_SEARCH --> SUB_STATE_IDLE
[00:09:26.461,761] <inf> event_manager: DATA_EVT_DATA_READY
[00:09:26.468,780] <dbg> cloud_codec.cloud_codec_encode_data: No data to encode, JSON string empty...

trace-2021-10-11T19-45-20.101Z.rar

[Didrik Rokhaug]

There were some problems with the trace, so I was not able to take a proper look at the IP packets.

However, I couldn't see anything that looked wrong in your trace. And in both the trace and the log it looks like the communication with the cloud continued as it should?

Also, when you take a modem trace, it is nice if you restart the device after starting capturing the trace, so that we can see the startup sequence as well.

[Mustafa]

Hey Didrik, thanks for your reply. I did some experiments with two different network operators. I disabled PSM and changed Mqtt_keep alive to 400sec.

In the first operator ( KPN in NL ) the server doesn't receive any data after 300 sec even device shows that data is sent successfully.

The second operator ( T-Mobile in NL): the device gets a timeout after 320sec and then it tries to establish the connection again with the server and every 320sec it gets event Timeout and re-initializes connection with server-side.

Here below are the trace files per operator, hopefully, that you can find the problem. 

KPN 

trace-2021-10-13T21-39-09.599Z KPN.rar

T Mobile

trace-2021-10-13T21-20-33.087Z TMobile.rar

thanks in advance!

[Didrik Rokhaug]

The KPN trace looks better this time, but it doesn't look like it captured the device waking up. The trace ended only  a minute after the SUPL session completed. And the SUPL session ended just a couple of seconds after the last packet sent to the cloud. The whole trace lasts for only a bit less than 2 minutes.

The T Mobile trace on the other hand looks like have captured the issue. But, it looks like the device is still requesting PSM, even though the application doesn't request it. This is probably because the modem has the PSM settings stored. The easiest way to tell the modem not to use PSM is to flash the at_cmd sample, send AT+CPSMS=0 followed by AT+CFUN=0.

[Didrik Rokhaug]

Hi, have you been able to capture traces without PSM yet?

[Mustafa]

Hey Didrik, sorry for my late message. I was actually struggling with GPS timeout that sometimes tracker keeps searching for GPS fix for more than one hour and GPS timeout is already adjusted on 60 sec but that is for another issue. For now, I've tested the devices with/without PSM and I've noticed that without PSM the connection with the server still opens but the device sends an update message per 26 min instead of 60 min since the settings are adjusted to 3600 sec. Here below are the traces files 

trace-2021-10-24T07-58-11.071Z without psm.rar

trace-2021-10-24T14-09-26.958Z with psm.rar