This post is older than 2 years and might not be relevant anymore
More Info: Consider searching for newer posts

subscribing in Assert tracker v2

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.

Parents
  • 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

  • Hi,

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

    Best regards,

    Didrik

  • 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.

  • 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

  • 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.

  • 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!

  • 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.

Reply
  • 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.

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

  • 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

  • Here is what the modem team said:

    With given information I am not able to comment anything very meaningful. TLS connection is established and UE sends 708 bytes to server. This is acked by the server, but nothing more really. Seems that server is not responding or data is lost somewhere in the path.

    After twenty minutes there are weird TCP transmission to unseen segments. I think the log is not complete and some parts are missing. TCP segment from UE to server jumps from 185 to 3018 which is not possible.

    At this point, I feel like the ticket has gone on long enough that it is time to take a tep back and try to get an overview of where we are. Could you try to sum up the problem you are seeing?

    What are you trying to do, and what is happening?

    What application FW are you suing, which SDK version is it based on, and what modem FW version are you using?

  • Hey Didrik, 

    You are right this issue took a long time. here is the summarize of the problem when CONFIG_MQTT_KEEPALIVE is set for more than 300 sec then the server ( AWS IoT ) doesn't receive any message from the device, even though the device log shows that message is sent successfully. 

    we tried with T-mobile and KPN in NL and both are almost the same except in the T-mobile network the device lost connection after 300 sec when CONFIG_MQTT_KEEPALIVE > 300 sec. but in the KPN network the device doesn't show any error. In both networks, the server doesn't receive anything after 300 sec 

    our project is based on Low power consumption so we need to set CONFIG_MQTT_KEEPALIVE  to a max of AWS limit and that is 1200 sec. but it doesn't work when it is initialized for more than 300 sec.

    we use

    SDK = nrf 1.6.1,

    modem version 1.3.0
    Mqtt server: AWS Iot mqtt 

    LTE-M network: KPN and T-mobile in NL 

    app: asset_tracker_v2

  • one thing I forget to mention is that this problem occurs only when PSM is enabled
    if PSM is disabled, the server receives always message from the device. 

Related