RRC mode / Are there debugging options to find out why RRC mode changed to connected

[Hidastelija]

Is there a way to find you the reason for RRC Connect?

I'm using a simple software developed based on NCS AWS IoT sample. I've implemented the SW to test power consumption in different modem idle modes. The SW updates data to AWS periodically and is idle between update periods. For some reason the SW operates differently using different networks and I don't know why.

I had trouble with PSM earlier as I mentioned in this ticket: https://devzone.nordicsemi.com/f/nordic-q-a/80120/asset-tracker-v2-power-consumption-with-thingy-91

Now I know better and I know how to set appropriate PSM parameters that are accepted by network. The thing that I don't understand is why my device constantly transitions between RRC idle and RRC connected randomly when the device is in DNA network. The same RRC mode toggling is not present in Elisa or Telia networks, in those networks the idle modes work as expected.

In DNA network the device very seldom stays in RRC idle for 60 seconds which is the shortest possible active timer value granted by the network. As a result the modem usually won't go to PSM during the 20 minutes that is the keepalive time for AWS IoT MQTT.

If the modem goes to PSM in DNA network, it stays in PSM until the next periodic data update. Thus I'm guessing the RRC toggling is network (not AWS) originated, but I would like to know if there is something that I can do to prevent the toggling.

I've attached a log file with 2min data update interval. In the beginning of the log there are only application writes. After a reboot there are library debug logs with the following flags:

# debugging

CONFIG_LTE_LC_MODEM_SLEEP_NOTIFICATIONS=y

CONFIG_AWS_IOT_LOG_LEVEL_DBG=y

CONFIG_LTE_LINK_CONTROL_LOG_LEVEL_DBG=y

CONFIG_NET_LOG=y

CONFIG_MQTT_LOG_LEVEL_DBG=y

CONFIG_DATE_TIME_THREAD_STACK_SIZE=2048

CONFIG_DATE_TIME_LOG_LEVEL_DBG=y

[Hidastelija]

Fullscreen dna_psm.txt Download

%CESQ: 49,2,13,1
%CESQ: 47,2,8,1
%CESQ: 48,2,13,1
��]��u��U�u���U}}W׵}�����wU]��u]u���u��w}��������]}u��Wu_���U�U���wWWU�u�wUU�u�wUU���wwUU���W�WU�U]W�WU����wUU�u�wUU�u�W_UU�U]U�UU�����]U���UWUU�W�U�UU���U�UU���U�UU���U�UU���UWUU�W�WwUU�U]WUU�WWUwUU�U]UWUU�W�U_UU���UWUU���UWUU��wUWUU���UWUU���U�UU���W_�����W_UU���uWUU���Uw]U��]wu�}�}U��}}�U��]U����u�*** Booting Zephyr OS build v2.7.99-ncs1  ***
Hello: app
%XMODEMSLEEP: 4
%XMODEMSLEEP: 4
%XMODEMSLEEP: 4,0
[00:00:00.206,024] <err> app_module: sizeof(enum): 1
[00:00:00.207,305] <inf> event_manager: e:cloud_module_event CLOUD_EVT_HELLO
[00:00:00.207,397] <inf> cloud_module: Hello: cloud

[00:00:00.213,775] <inf> event_manager: e:app_module_event APP_EVT_HELLO
[00:00:00.213,958] <inf> event_manager: e:app_module_event APP_EVT_CFG_UPDATED
[00:00:00.214,630] <inf> event_manager: e:app_module_event APP_EVT_SHADOW_SEND_REQ
[00:00:00.221,466] <inf> cloud: DATE_TIME_NOT_OBTAINED
[00:00:00.286,987] <inf> cloud_module: Received APP_EVT_HELLO
%CESQ: 47,2,10,1
+CEREG: 2,"0192","001E830A",7
+CSCON: 1
[00:00:01.457,763] <inf> cloud_module: LTE cell changed: Cell ID: 1999626, Tracking area: 402
[00:00:01.457,885] <inf> event_manager: e:cloud_module_event CLOUD_EVT_LTE_DISCONNECTED
[00:00:01.675,781] <inf> cloud_module: RRC mode: Connected
+CEREG: 1,"0192","001E830A",7,,,"11100000","00010011"
%XTIME: ,"22406281028121","01"
%CESQ: 48,2,15,2
[00:00:02.538,208] <inf> cloud_module: PSM parameter update: TAU: 11400, Active time: -1
[00:00:02.538,360] <inf> event_manager: e:cloud_module_event CLOUD_EVT_LTE_CONNECTED
[00:00:02.538,391] <inf> event_manager: e:cloud_module_event COULD_EVT_PSM_REPORT
[00:00:02.538,513] <inf> event_manager: e:app_module_event APP_EVT_SHADOW_SEND_REQ
[00:00:02.538,604] <wrn> cloud_module: Cloud connection establishment in progress
[00:00:02.538,604] <wrn> cloud_module: New connection attempt in 32 seconds if not successful
[00:00:02.538,665] <inf> cloud_module: AWS_IOT_EVT_CONNECTING
[00:00:02.538,726] <inf> event_manager: e:cloud_module_event CLOUD_EVT_CLOUD_CONNECTING
[00:00:02.543,914] <inf> cloud: DATE_TIME_OBTAINED_MODEM
+CEREG: 1,"0192","001E830A",7,,,"00011110","00100111"
[00:00:04.771,697] <inf> cloud_module: AWS_IOT_EVT_CONNECTED
[00:00:04.771,759] <inf> event_manager: e:cloud_module_event CLOUD_EVT_CLOUD_CONNECTED
[00:00:04.772,155] <inf> event_manager: e:app_module_event APP_EVT_SHADOW_SEND_REQ
[00:00:04.777,374] <inf> event_manager: e:mqtt_msg_module_event MQTT_MSG_TO_CLOUD, data size: 399
[00:00:04.960,815] <inf> cloud_module: AWS_IOT_EVT_READY

[00:00:05.084,320] <inf> cloud_module: AWS_IOT_EVT_DATA_RECEIVED
[00:00:05.084,411] <inf> event_manager: e:mqtt_msg_module_event MQTT_MSG_FROM_CLOUD, data size: 265
[00:00:05.085,540] <inf> event_manager: e:app_module_event APP_EVT_CFG_UPDATED
[00:00:05.086,364] <inf> event_manager: e:app_module_event APP_EVT_SHADOW_SEND_REQ
[00:00:05.092,651] <inf> event_manager: e:mqtt_msg_module_event MQTT_MSG_TO_CLOUD, data size: 398
[00:00:05.217,285] <inf> cloud_module: PSM parameter update: TAU: 25200, Active time: 60
[00:00:05.217,407] <inf> event_manager: e:cloud_module_event COULD_EVT_PSM_REPORT
[00:00:05.321,411] <inf> event_manager: e:app_module_event APP_EVT_SHADOW_SEND_REQ
[00:00:05.326,477] <inf> event_manager: e:mqtt_msg_module_event MQTT_MSG_TO_CLOUD, data size: 398
[00:00:05.334,320] <inf> cloud_module: AWS_IOT_EVT_DATA_RECEIVED
[00:00:05.334,503] <inf> event_manager: e:mqtt_msg_module_event MQTT_MSG_FROM_CLOUD, data size: 1296
[00:00:05.339,202] <inf> event_manager: e:app_module_event APP_EVT_CFG_UPDATED
[00:00:05.340,667] <inf> event_manager: e:app_module_event APP_EVT_SHADOW_SEND_REQ
[00:00:05.347,259] <inf> event_manager: e:mqtt_msg_module_event MQTT_MSG_TO_CLOUD, data size: 398
%CESQ: 49,2,10,1
%CESQ: 49,2,15,2
%CESQ: 49,2,10,1
%CESQ: 49,2,15,2
+CSCON: 0
%CESQ: 51,2,20,2
[00:00:20.969,970] <inf> cloud_module: RRC mode: Idle
%CESQ: 50,2,14,2
%CESQ: 51,2,19,2
%CESQ: 50,2,11,1
+CSCON: 1
[00:00:36.058,624] <inf> cloud_module: RRC mode: Connected
%CESQ: 48,2,16,2
+CSCON: 0
[00:00:47.356,658] <inf> cloud_module: RRC mode: Idle
+CSCON: 1
[00:00:52.697,204] <inf> cloud_module: RRC mode: Connected
%CESQ: 49,2,10,1
%CESQ: 49,2,15,2
+CSCON: 0
[00:01:03.997,100] <inf> cloud_module: RRC mode: Idle
+CSCON: 1
[00:01:36.218,353] <inf> cloud_module: RRC mode: Connected
%CESQ: 48,2,10,1
%CESQ: 49,2,15,2
%CESQ: 49,2,20,2
%CESQ: 54,2,14,2
%CESQ: 55,2,19,2
%CESQ: 50,2,19,2
+CSCON: 0
[00:02:00.518,615] <inf> cloud_module: RRC mode: Idle
%CESQ: 48,2,13,1
+CSCON: 1
[00:02:01.819,061] <inf> cloud_module: RRC mode: Connected
[00:02:05.347,900] <inf> event_manager: e:app_module_event APP_EVT_SHADOW_SEND_REQ
[00:02:05.352,844] <inf> event_manager: e:mqtt_msg_module_event MQTT_MSG_TO_CLOUD, data size: 398
%CESQ: 47,2,18,2
��]��u��Uu���U}}�׵}}����wU]��u�u�����]��7�U�UU���]��U�w�_���UUU���WWUU�U]wUU����}U���wwUU��U��WU�U]W�WU�}��UU�u�wUU�uUW_UU�U]U�]U���U�]U���U_UU���UWUU���U�UU���U�UU���U�U����U_UU�W�WwUU�U]WUU�W�UwU���]UWUU�WWUWUU���UWUU���U_UU���UWUU���U�UU��wU�UU���W_�����WWUU���u_UU���w]U�U]wuU}}}]��u}�U��}UW}_�]}*** Booting Zephyr OS build v2.7.99-ncs1  ***
Hello: app
[00:00:00.205,871] <err> app_module: sizeof(enum): 1
[00:00:00.207,153] <inf> event_manager: e:cloud_module_event CLOUD_EVT_HELLO
[00:00:00.207,244] <inf> cloud_module: Hello: cloud

[00:00:00.207,275] <dbg> date_time.date_time_update_thread: Updating date time UTC...
[00:00:00.207,275] <dbg> date_time.date_time_core_current_check: Date time never set
[00:00:00.207,275] <dbg> date_time.date_time_update_thread: Getting time from cellular network
[00:00:00.207,305] <dbg> date_time.date_time_modem_get: Modem has not got time from LTE network, so not using it
[00:00:00.207,305] <dbg> date_time.date_time_update_thread: Getting time from NTP server
[00:00:00.213,623] <inf> event_manager: e:app_module_event APP_EVT_HELLO
[00:00:00.213,806] <inf> event_manager: e:app_module_event APP_EVT_CFG_UPDATED
[00:00:00.214,477] <inf> event_manager: e:app_module_event APP_EVT_SHADOW_SEND_REQ
[00:00:00.214,752] <dbg> lte_lc.init_and_config: System mode (1) and preference (0) are already configured
%XMODEMSLEEP: 4
%XMODEMSLEEP: 4
[00:00:00.326,751] <dbg> date_time.date_time_ntp_get: Not connected to LTE, skipping NTP UTC time update
[00:00:00.326,782] <dbg> date_time.date_time_update_thread: Did not get time from any time source
[00:00:00.326,782] <dbg> date_time.date_time_core_schedule_update: New date time update in: 14400 seconds
[00:00:00.326,782] <inf> cloud: DATE_TIME_NOT_OBTAINED
[00:00:00.335,357] <dbg> lte_lc.at_handler_xmodemsleep: %XMODEMSLEEP notification
[00:00:00.335,479] <dbg> lte_lc_helpers.event_handler_list_dispatch: Dispatching events:
[00:00:00.335,479] <dbg> lte_lc_helpers.event_handler_list_dispatch:  - handler=0x0002DB69
[00:00:00.335,479] <dbg> lte_lc_helpers.event_handler_list_dispatch: Done
[00:00:00.347,320] <dbg> lte_lc.at_handler_xmodemsleep: %XMODEMSLEEP notification
[00:00:00.347,442] <dbg> lte_lc_helpers.event_handler_list_dispatch: Dispatching events:
[00:00:00.347,473] <dbg> lte_lc_helpers.event_handler_list_dispatch:  - handler=0x0002DB69
[00:00:00.347,473] <dbg> lte_lc_helpers.event_handler_list_dispatch:  - handler=0x00024E05
[00:00:00.347,473] <dbg> lte_lc_helpers.event_handler_list_dispatch: Done
%XMODEMSLEEP: 4,0
[00:00:00.503,326] <dbg> lte_lc.at_handler_xmodemsleep: %XMODEMSLEEP notification
[00:00:00.503,479] <dbg> lte_lc_helpers.event_handler_list_dispatch: Dispatching events:
[00:00:00.503,479] <dbg> lte_lc_helpers.event_handler_list_dispatch:  - handler=0x0002DB69
[00:00:00.503,509] <dbg> lte_lc_helpers.event_handler_list_dispatch:  - handler=0x00024E05
[00:00:00.503,509] <dbg> lte_lc_helpers.event_handler_list_dispatch: Done
[00:00:00.504,302] <inf> cloud_module: Received APP_EVT_HELLO
%CESQ: 51,2,10,1
+CEREG: 2,"0192","001E830A",7
[00:00:01.627,746] <dbg> lte_lc.at_handler_cereg: +CEREG notification: +CEREG: 2,"0192","001E830A",7

[00:00:01.627,960] <dbg> lte_lc_helpers.parse_cereg: Network registration status: 2
[00:00:01.627,990] <dbg> lte_lc_helpers.parse_cereg: LTE mode: 7
[00:00:01.628,051] <dbg> lte_lc_helpers.event_handler_list_dispatch: Dispatching events:
[00:00:01.628,051] <dbg> lte_lc_helpers.event_handler_list_dispatch:  - handler=0x0002DB69
[00:00:01.628,540] <dbg> lte_lc_helpers.event_handler_list_dispatch:  - handler=0x00024E05
[00:00:01.628,570] <dbg> lte_lc_helpers.event_handler_list_dispatch: Done
[00:00:01.628,601] <dbg> lte_lc_helpers.event_handler_list_dispatch: Dispatching events:
[00:00:01.628,601] <dbg> lte_lc_helpers.event_handler_list_dispatch:  - handler=0x0002DB69
[00:00:01.628,601] <dbg> lte_lc_helpers.event_handler_list_dispatch:  - handler=0x00024E05
[00:00:01.628,601] <inf> cloud_module: LTE cell changed: Cell ID: 1999626, Tracking area: 402
[00:00:01.628,631] <dbg> lte_lc_helpers.event_handler_list_dispatch: Done
[00:00:01.628,631] <dbg> lte_lc_helpers.event_handler_list_dispatch: Dispatching events:
[00:00:01.628,631] <dbg> lte_lc_helpers.event_handler_list_dispatch:  - handler=0x0002DB69
[00:00:01.628,631] <dbg> lte_lc_helpers.event_handler_list_dispatch:  - handler=0x00024E05
[00+CSCON: 1
:00:01.628,662] <dbg> lte_lc_helpers.event_handler_list_dispatch: Done
[00:00:01.628,723] <inf> event_manager: e:cloud_module_event CLOUD_EVT_LTE_DISCONNECTED
[00:00:01.767,395] <dbg> lte_lc.at_handler_cscon: +CSCON notification
[00:00:01.767,517] <dbg> lte_lc_helpers.event_handler_list_dispatch: Dispatching events:
[00:00:01.767,517] <dbg> lte_lc_helpers.event_handler_list_dispatch:  - handler=0x0002DB69
[00:00:01.767,517] <dbg> lte_lc_helpers.event_handler_list_dispatch:  - handler=0x00024E05
[00:00:01.767,517] <inf> cloud_module: RRC mode: Connected
[00:00:01.767,547] <dbg> lte_lc_helpers.event_handler_list_dispatch: Done
+CEREG: 1,"0192","001E830A",7,,,"11100000","00010011"
%XTIME: ,"22406281229421","01"
[00:00:02.769,805] <dbg> lte_lc.at_handler_cereg: +CEREG notification: +CEREG: 1,"0192","001E830A",7,,,"11100000","0~
[00:00:02.770,080] <dbg> lte_lc_helpers.parse_cereg: Network registration status: 1
[00:00:02.770,111] <dbg> lte_lc_helpers.parse_cereg: LTE mode: 7
[00:00:02.770,172] <dbg> lte_lc_helpers.event_handler_list_dispatch: Dispatching events:
[00:00:02.770,172] <dbg> lte_lc_helpers.event_handler_list_dispatch:  - handler=0x0002DB69
[00:00:02.770,172] <dbg> lte_lc_helpers.event_handler_list_dispatch:  - handler=0x00024E05
[00:00:02.770,202] <dbg> lte_lc_helpers.event_handler_list_dispatch: Done
[00:00:02.771,514] <dbg> lte_lc_helpers.parse_psm: TAU: 11400 sec, active time: -1 sec

[00:00:02.771,514] <dbg> lte_lc.lte_lc_psm_get: TAU: 11400 sec, active time: -1 sec

[00:00:02.771,606] <dbg> lte_lc_helpers.event_handler_list_dispatch: Dispatching events:
[00:00:02.771,606] <dbg> lte_lc_helpers.event_handler_list_dispatch:  - handler=0x0002DB69
[00:00:02.771,636] <dbg> lte_lc_helpers.event_handler_list_dispatch:  - handler=0x00024E05
[00:00:02.771,636] <inf> cloud_module: PSM parameter update: TAU: 11400, Active time: -1
[00:00:02.771,667] <dbg> lte_lc_helpers.event_handler_list_dispatch: Done
[00:00:02.774,719] <dbg> date_time.date_time_core_current_check: Date time never set
[00:00:02.774,749] <dbg> date_time.date_time_at_xtime_handler: Time obtained from cellular network (XTIME notification)
[00:00:02.774,780] <dbg> date_time.date_time_core_store: System time updated: 2022-04-26 18:22:49
[00:00:02.774,810] <inf> cloud: DATE_TIME_OBTAINED_MODEM
[00:00:02.774,841] <inf> event_manager: e:cloud_module_event CLOUD_EVT_LTE_CONNECTED
[00:00:02.774,871] <inf> event_manager: e:cloud_module_event COULD_EVT_PSM_REPORT
%CESQ: 48,2,15,2
[00:00:02.957,946] <inf> event_manager: e:app_module_event APP_EVT_SHADOW_SEND_REQ
[00:00:02.958,068] <wrn> cloud_module: Cloud connection establishment in progress
[00:00:02.958,068] <wrn> cloud_module: New connection attempt in 32 seconds if not successful
[00:00:02.958,129] <inf> cloud_module: AWS_IOT_EVT_CONNECTING
[00:00:02.958,160] <inf> event_manager: e:cloud_module_event CLOUD_EVT_CLOUD_CONNECTING
[00:00:03.072,570] <dbg> aws_iot.broker_init: IPv4 Address found 54.154.240.250
[00:00:03.072,906] <dbg> net_mqtt_sock_tls.mqtt_client_tls_connect: (0x2000e9c8): Created socket 0
[00:00:04.963,256] <dbg> net_mqtt_sock_tls.mqtt_client_tls_connect: (0x2000e9c8): Connect completed
[00:00:04.963,500] <dbg> net_mqtt_enc: Encoding Protocol Description.
                                       4d 51 54 54                                      |MQTT             
[00:00:04.963,531] <dbg> net_mqtt_enc.pack_utf8_str: (0x2000e9c8): >> str_size:00000006 cur:0x20012493, end:0x20012c8e
[00:00:04.963,531] <dbg> net_mqtt_enc.pack_uint16: (0x2000e9c8): >> val:0004 cur:0x20012493, end:0x20012c8e
[00:00:04.963,531] <dbg> net_mqtt_enc.connect_request_encode: (0x2000e9c8): Encoding Protocol Version 04.
[00:00:04.963,531] <dbg> net_mqtt_enc.pack_uint8: (0x2000e9c8): >> val:04 cur:0x20012499, end:0x20012c8e
[00:00:04.963,562] <dbg> net_mqtt_enc.pack_uint8: (0x2000e9c8): >> val:00 cur:0x2001249a, end:0x20012c8e
[00:00:04.963,562] <dbg> net_mqtt_enc.connect_request_encode: (0x2000e9c8): Encoding Keep Alive Time 04b0.
[00:00:04.963,562] <dbg> net_mqtt_enc.pack_uint16: (0x2000e9c8): >> val:04b0 cur:0x2001249b, end:0x20012c8e
[00:00:04.963,562] <dbg> net_mqtt_enc: Encoding Client Id.
                                       33 35 32 36 35 36 31 30  33 37 39 34 32 33 39    |35265610 3794239 
[00:00:04.963,592] <dbg> net_mqtt_enc.pack_utf8_str: (0x2000e9c8): >> str_size:00000011 cur:0x2001249d, end:0x20012c8e
[00:00:04.963,592] <dbg> net_mqtt_enc.pack_uint16: (0x2000e9c8): >> val:000f cur:0x2001249d, end:0x20012c8e
[00:00:04.963,623] <dbg> net_mqtt_enc.mqtt_encode_fixed_header: (0x2000e9c8): << msg type:0x10 length:0x0000001b
[00:00:04.963,623] <dbg> net_mqtt_enc.packet_length_encode: (0x2000e9c8): >> length:0x0000001b cur:(nil), end:(nil)
[00:00:04.963,623] <dbg> net_mqtt_enc.mqtt_encode_fixed_header: (0x2000e9c8): Fixed header length = 02
[00:00:04.963,653] <dbg> net_mqtt_enc.pack_uint8: (0x2000e9c8): >> val:10 cur:0x20012491, end:0x20012c8e
[00:00:04.963,653] <dbg> net_mqtt_enc.packet_length_encode: (0x2000e9c8): >> length:0x0000001b cur:0x20012492, end:0x20012c8e
[00:00:05.167,816] <dbg> net_mqtt_rx.mqtt_handle_packet: (0x2000e9c8): [CID 0x2000f274]: Received MQTT_PKT_TYPE_CONNACK!
--- 7 messages dropped ---
[00:00:05.167,816] <dbg> net_mqtt_dec.unpack_uint8: (0x2000e9c8): >> cur:0x20011c90, end:0x20011c92
[00:00:05.167,816] <dbg> net_mqtt_dec.unpack_uint8: (0x2000e9c8): << val:00
[00:00:05.167,816] <dbg> net_mqtt_dec.unpack_uint8: (0x2000e9c8): >> cur:0x20011c91, end:0x20011c92
[00:00:05.167,846] <dbg> net_mqtt_dec.unpack_uint8: (0x2000e9c8): << val:00
[00:00:05.167,846] <dbg> net_mqtt_dec.connect_ack_decode: (0x2000e9c8): [CID 0x2000f274]: session_present_flag: 0
[00:00:05.167,846] <dbg> net_mqtt_rx.mqtt_handle_packet: (0x2000e9c8): [CID 0x2000f274]: return_code: 0
[00:00:05.167,968] <dbg> net_mqtt.mqtt_subscribe: (0x2000e9c8): [CID 0x2000f274]:[State 0x06]: >> message id 0x0840 topic count 0x0001
[00:00:05.168,182] <dbg> net_mqtt_enc.pack_uint16: (0x2000e9c8): >> val:0840 cur:0x20012493, end:0x20012c8e
[00:00:05.168,212] <dbg> net_mqtt_enc.pack_utf8_str: (0x2000e9c8): >> str_size:0000002e cur:0x20012495, end:0x20012c8e
[00:00:05.168,212] <dbg> net_mqtt_enc.pack_uint16: (0x2000e9c8): >> val:002c cur:0x20012495, end:0x20012c8e
[00:00:05.168,212] <dbg> net_mqtt_enc.pack_uint8: (0x2000e9c8): >> val:01 cur:0x200124c3, end:0x20012c8e
[00:00:05.168,243] <dbg> net_mqtt_enc.mqtt_encode_fixed_header: (0x2000e9c8): << msg type:0x82 length:0x00000031
[00:00:05.168,243] <dbg> net_mqtt_enc.packet_length_encode: (0x2000e9c8): >> length:0x00000031 cur:(nil), end:(nil)
[00:00:05.168,273] <dbg> net_mqtt_enc.mqtt_encode_fixed_header: (0x2000e9c8): Fixed header length = 02
[00:00:05.168,304] <dbg> net_mqtt_enc.pack_uint8: (0x2000e9c8): >> val:82 cur:0x20012491, end:0x20012c8e
[00:00:05.168,304] <dbg> net_mqtt_enc.packet_length_encode: (0x2000e9c8): >> length:0x00000031 cur:0x20012492, end:0x20012c8e
[00:00:05.168,334] <dbg> net_mqtt.client_write: (0x2000e9c8): [0x2000f274]: Transport writing 51 bytes.
[00:00:05.371,032] <dbg> net_mqtt.client_write: (0x2000e9c8): [0x2000f274]: Transport write complete.
[00:00:05.371,063] <dbg> net_mqtt.mqtt_subscribe: (0x2000e9c8): [CID 0x2000f274]:[State 0x06]: << result 0x00000000
[00:00:05.371,185] <dbg> net_mqtt.mqtt_subscribe: (0x2000e9c8): [CID 0x2000f274]:[State 0x06]: >> message id 0x0842 topic count 0x0001
[00:00:05.371,398] <dbg> net_mqtt_enc.pack_uint16: (0x2000e9c8): >> val:0842 cur:0x20012493, end:0x20012c8e
[00:00:05.371,429] <dbg> net_mqtt_enc.pack_utf8_str: (0x2000e9c8): >> str_size:0000002e cur:0x20012495, end:0x20012c8e
[00:00:05.371,429] <dbg> net_mqtt_enc.pack_uint16: (0x2000e9c8): >> val:002c cur:0x20012495, end:0x20012c8e
[00:00:05.371,429] <dbg> net_mqtt_enc.pack_uint8: (0x2000e9c8): >> val:01 cur:0x200124c3, end:0x20012c8e
[00:00:05.371,459] <dbg> net_mqtt_enc.mqtt_encode_fixed_header: (0x2000e9c8): << msg type:0x82 length:0x00000031
[00:00:05.371,459] <dbg> net_mqtt_enc.packet_length_encode: (0x2000e9c8): >> length:0x00000031 cur:(nil), end:(nil)
[00:00:05.371,459] <dbg> net_mqtt_enc.mqtt_encode_fixed_header: (0x2000e9c8): Fixed header length = 02
[00:00:05.371,490] <dbg> net_mqtt_enc.pack_uint8: (0x2000e9c8): >> val:82 cur:0x20012491, end:0x20012c8e
[00:00:05.371,490] <dbg> net_mqtt_enc.packet_length_encode: (0x2000e9c8): >> length:0x00000031 cur:0x20012492, end:0x20012c8e
[00:00:05.371,490] <dbg> net_mqtt.client_write: (0x2000e9c8): [0x2000f274]: Transport writing 51 bytes.
[00:00:05.521,331] <dbg> net_mqtt.client_write: (0x2000e9c8): [0x2000f274]: Transport write complete.
[00:00:05.521,362] <dbg> net_mqtt.mqtt_subscribe: (0x2000e9c8): [CID 0x2000f274]:[State 0x06]: << result 0x00000000
[00:00:05.521,392] <dbg> aws_iot.mqtt_evt_handler: MQTT client connected!
[00:00:05.521,392] <inf> cloud_module: AWS_IOT_EVT_CONNECTED
[00:00:05.521,453] <inf> event_manager: e:cloud_module_event CLOUD_EVT_CLOUD_CONNECTED
[00:00:05.521,545] <dbg> aws_iot.topic_subscribe: Subscribing to application topic: hello
[00:00:05.521,545] <dbg> net_mqtt.mqtt_subscribe: (0x2000e9c8): [CID 0x2000f274]:[State 0x06]: >> message id 0xc2c1 topic count 0x0001
[00:00:05.521,789] <dbg> net_mqtt_enc.pack_uint16: (0x2000e9c8): >> val:c2c1 cur:0x20012493, end:0x20012c8e
[00:00:05.521,789] <dbg> net_mqtt_enc.pack_utf8_str: (0x2000e9c8): >> str_size:00000007 cur:0x20012495, end:0x20012c8e
[00:00:05.521,820] <dbg> net_mqtt_enc.pack_uint16: (0x2000e9c8): >> val:0005 cur:0x20012495, end:0x20012c8e
[00:00:05.521,820] <dbg> net_mqtt_enc.pack_uint8: (0x2000e9c8): >> val:01 cur:0x2001249c, end:0x20012c8e
[00:00:05.521,850] <dbg> net_mqtt_enc.mqtt_encode_fixed_header: (0x2000e9c8): << msg type:0x82 length:0x0000000a
[00:00:05.521,850] <dbg> net_mqtt_enc.packet_length_encode: (0x2000e9c8): >> length:0x0000000a cur:(nil), end:(nil)
[00:00:05.521,850] <dbg> net_mqtt_enc.mqtt_encode_fixed_header: (0x2000e9c8): Fixed header length = 02
[00:00:05.521,850] <dbg> net_mqtt_enc.pack_uint8: (0x2000e9c8): >> val:82 cur:0x20012491, end:0x20012c8e
[00:00:05.521,881] <dbg> net_mqtt_enc.packet_length_encode: (0x2000e9c8): >> length:0x0000000a cur:0x20012492, end:0x20012c8e
[00:00:05.521,881] <dbg> net_mqtt.client_write: (0x2000e9c8): [0x2000f274]: Transport writing 12 bytes.
[00:00:05.521,972] <inf> event_manager: e:app_module_event APP_EVT_SHADOW_SEND_REQ
[00:00:05.714,263] <dbg> net_mqtt_enc.pack_uint16: (0x2000e9c8): >> val:db64 cur:0x20012493, end:0x20012c8e
--- 6 messages dropped ---
[00:00:05.714,263] <dbg> net_mqtt_enc.pack_utf8_str: (0x2000e9c8): >> str_size:00000031 cur:0x20012495, end:0x20012c8e
[00:00:05.714,294] <dbg> net_mqtt_enc.pack_uint16: (0x2000e9c8): >> val:002f cur:0x20012495, end:0x20012c8e
[00:00:05.714,294] <dbg> net_mqtt_enc.pack_uint8: (0x2000e9c8): >> val:01 cur:0x200124c6, end:0x20012c8e
[00:00:05.714,324] <dbg> net_mqtt_enc.pack_utf8_str: (0x2000e9c8): >> str_size:00000031 cur:0x200124c7, end:0x20012c8e
[00:00:05.714,324] <dbg> net_mqtt_enc.pack_uint16: (0x2000e9c8): >> val:002f cur:0x200124c7, end:0x20012c8e
[00:00:05.714,355] <dbg> net_mqtt_enc.pack_uint8: (0x2000e9c8): >> val:01 cur:0x200124f8, end:0x20012c8e
[00:00:05.714,355] <dbg> net_mqtt_enc.pack_utf8_str: (0x2000e9c8): >> str_size:00000031 cur:0x200124f9, end:0x20012c8e
[00:00:05.714,355] <dbg> net_mqtt_enc.pack_uint16: (0x2000e9c8): >> val:002f cur:0x200124f9, end:0x20012c8e
[00:00:05.714,385] <dbg> net_mqtt_enc.pack_uint8: (0x2000e9c8): >> val:01 cur:0x2001252a, end:0x20012c8e
[00:00:05.714,416] <dbg> net_mqtt_enc.mqtt_encode_fixed_header: (0x2000e9c8): << msg type:0x82 length:0x00000098
[00:00:05.714,416] <dbg> net_mqtt_enc.packet_length_encode: (0x2000e9c8): >> length:0x00000098 cur:(nil), end:(nil)
[00:00:05.714,447] <dbg> net_mqtt_enc.mqtt_encode_fixed_header: (0x2000e9c8): Fixed header length = 03
[00:00:05.714,477] <dbg> net_mqtt_enc.pack_uint8: (0x2000e9c8): >> val:82 cur:0x20012490, end:0x20012c8e
[00:00:05.714,508] <dbg> net_mqtt_enc.packet_length_encode: (0x2000e9c8): >> length:0x00000098 cur:0x20012491, end:0x20012c8e
[00:00:05.714,538] <dbg> net_mqtt.client_write: (0x2000e9c8): [0x2000f274]: Transport writing 155 bytes.
[00:00:05.719,024] <inf> event_manager: e:mqtt_msg_module_event MQTT_MSG_TO_CLOUD, data size: 399
[00:00:05.915,191] <dbg> net_mqtt_dec.unpack_uint8: (0x2000e9c8): >> cur:0x20011c8e, end:0x20011c90
--- 3 messages dropped ---
[00:00:05.915,191] <dbg> net_mqtt_dec.unpack_uint8: (0x2000e9c8): << val:90
[00:00:05.915,191] <dbg> net_mqtt_dec.packet_length_decode: (0x2000e9c8): length:0x00000003
[00:00:05.915,283] <dbg> net_mqtt_rx.mqtt_handle_packet: (0x2000e9c8): [CID 0x2000f274]: Received MQTT_PKT_TYPE_SUBACK!
[00:00:05.915,283] <dbg> net_mqtt_dec.unpack_uint16: (0x2000e9c8): >> cur:0x20011c90, end:0x20011c93
[00:00:05.915,283] <dbg> net_mqtt_dec.unpack_uint16: (0x2000e9c8): << val:0840
[00:00:05.915,283] <dbg> net_mqtt_dec.unpack_data: (0x2000e9c8): >> cur:0x20011c92, end:0x20011c93
[00:00:05.915,313] <dbg> net_mqtt_dec.unpack_data: (0x2000e9c8): << bin len:00000001
[00:00:05.915,405] <dbg> net_mqtt.mqtt_publish: (0x2000e9c8): [CID 0x2000f274]:[State 0x06]: >> Topic size 0x0000002a, Data size 0x00000013
[00:00:05.915,649] <dbg> net_mqtt_enc.pack_utf8_str: (0x2000e9c8): >> str_size:0000002c cur:0x20012493, end:0x20012c8e
[00:00:05.915,649] <dbg> net_mqtt_enc.pack_uint16: (0x2000e9c8): >> val:002a cur:0x20012493, end:0x20012c8e
[00:00:05.915,679] <dbg> net_mqtt_enc.pack_uint16: (0x2000e9c8): >> val:f52c cur:0x200124bf, end:0x20012c8e
[00:00:05.915,679] <dbg> net_mqtt_enc.mqtt_encode_fixed_header: (0x2000e9c8): << msg type:0x32 length:0x00000041
[00:00:05.915,710] <dbg> net_mqtt_enc.packet_length_encode: (0x2000e9c8): >> length:0x00000041 cur:(nil), end:(nil)
[00:00:05.915,710] <dbg> net_mqtt_enc.mqtt_encode_fixed_header: (0x2000e9c8): Fixed header length = 02
[00:00:05.915,710] <dbg> net_mqtt_enc.pack_uint8: (0x2000e9c8): >> val:32 cur:0x20012491, end:0x20012c8e
[00:00:05.915,710] <dbg> net_mqtt_enc.packet_length_encode: (0x2000e9c8): >> length:0x00000041 cur:0x20012492, end:0x20012c8e
[00:00:05.915,740] <dbg> net_mqtt.client_write_msg: (0x2000e9c8): [0x2000f274]: Transport writing message.
[00:00:05.916,107] <dbg> aws_iot.aws_iot_send: Publishing to topic: $aws/things/352656103794239/shadow/update
[00:00:05.916,137] <dbg> net_mqtt.mqtt_publish: (0x2000cd50): [CID 0x2000f274]:[State 0x06]: >> Topic size 0x00000029, Data size 0x0000018f
[00:00:06.140,899] <dbg> net_mqtt.client_write_msg: (0x2000e9c8): [0x2000f274]: Transport write complete.
[00:00:06.140,930] <dbg> net_mqtt.mqtt_publish: (0x2000e9c8): [CID 0x2000f274]:[State 0x06]: << result 0x00000000
[00:00:06.140,960] <dbg> aws_iot.mqtt_evt_handler: MQTT_EVT_SUBACK: id = 2112 result = 0
[00:00:06.141,204] <dbg> net_mqtt_enc.pack_utf8_str: (0x2000cd50): >> str_size:0000002b cur:0x20012493, end:0x20012c8e
[00:00:06.141,204] <dbg> net_mqtt_enc.pack_uint16: (0x2000cd50): >> val:0029 cur:0x20012493, end:0x20012c8e
[00:00:06.141,235] <dbg> net_mqtt_enc.mqtt_encode_fixed_header: (0x2000cd50): << msg type:0x30 length:0x000001ba
[00:00:06.141,235] <dbg> net_mqtt_enc.packet_length_encode: (0x2000cd50): >> length:0x000001ba cur:(nil), end:(nil)
[00:00:06.141,235] <dbg> net_mqtt_enc.mqtt_encode_fixed_header: (0x2000cd50): Fixed header length = 03
[00:00:06.141,265] <dbg> net_mqtt_enc.pack_uint8: (0x2000cd50): >> val:30 cur:0x20012490, end:0x20012c8e
[00:00:06.141,265] <dbg> net_mqtt_enc.packet_length_encode: (0x2000cd50): >> length:0x000001ba cur:0x20012491, end:0x20012c8e
[00:00:06.141,265] <dbg> net_mqtt.client_write_msg: (0x2000cd50): [0x2000f274]: Transport writing message.
[00:00:06.266,876] <dbg> net_mqtt_dec.unpack_data: (0x2000e9c8): << bin len:00000001
--- 20 messages dropped ---
[00:00:06.266,876] <dbg> aws_iot.mqtt_evt_handler: MQTT_EVT_SUBACK: id = 49857 result = 0
[00:00:06.266,937] <dbg> net_mqtt.mqtt_input: (0x2000e9c8): state:0x00000006
[00:00:06.266,998] <dbg> net_mqtt_dec.unpack_uint8: (0x2000e9c8): >> cur:0x20011c8e, end:0x20011c90
[00:00:06.267,028] <dbg> net_mqtt_dec.unpack_uint8: (0x2000e9c8): << val:90
[00:00:06.267,028] <dbg> net_mqtt_dec.packet_length_decode: (0x2000e9c8): length:0x00000005
[00:00:06.267,120] <dbg> net_mqtt_rx.mqtt_handle_packet: (0x2000e9c8): [CID 0x2000f274]: Received MQTT_PKT_TYPE_SUBACK!
[00:00:06.267,150] <dbg> net_mqtt_dec.unpack_uint16: (0x2000e9c8): >> cur:0x20011c90, end:0x20011c95
[00:00:06.267,150] <dbg> net_mqtt_dec.unpack_uint16: (0x2000e9c8): << val:db64
[00:00:06.267,181] <dbg> net_mqtt_dec.unpack_data: (0x2000e9c8): >> cur:0x20011c92, end:0x20011c95
[00:00:06.267,181] <dbg> net_mqtt_dec.unpack_data: (0x2000e9c8): << bin len:00000003
[00:00:06.267,211] <dbg> aws_iot.mqtt_evt_handler: MQTT_EVT_SUBACK: id = 56164 result = 0
[00:00:06.267,242] <dbg> aws_iot.aws_iot_send: Publishing to topic: $aws/things/352656103794239/shadow/get
[00:00:06.267,272] <dbg> net_mqtt.mqtt_publish: (0x2000e9c8): [CID 0x2000f274]:[State 0x06]: >> Topic size 0x00000026, Data size 0x00000000
[00:00:06.267,517] <dbg> net_mqtt_enc.pack_utf8_str: (0x2000e9c8): >> str_size:00000028 cur:0x20012493, end:0x20012c8e
[00:00:06.267,547] <dbg> net_mqtt_enc.pack_uint16: (0x2000e9c8): >> val:0026 cur:0x20012493, end:0x20012c8e
[00:00:06.267,578] <dbg> net_mqtt_enc.mqtt_encode_fixed_header: (0x2000e9c8): << msg type:0x30 length:0x00000028
[00:00:06.267,608] <dbg> net_mqtt_enc.packet_length_encode: (0x2000e9c8): >> length:0x00000028 cur:(nil), end:(nil)
[00:00:06.267,608] <dbg> net_mqtt_enc.mqtt_encode_fixed_header: (0x2000e9c8): Fixed header length = 02
[00:00:06.267,639] <dbg> net_mqtt_enc.pack_uint8: (0x2000e9c8): >> val:30 cur:0x20012491, end:0x20012c8e
[00:00:06.267,669] <dbg> net_mqtt_enc.packet_length_encode: (0x2000e9c8): >> length:0x00000028 cur:0x20012492, end:0x20012c8e
[00:00:06.267,669] <dbg> net_mqtt.client_write_msg: (0x2000e9c8): [0x2000f274]: Transport writing message.
[00:00:06.502,990] <dbg> net_mqtt.client_write_msg: (0x2000e9c8): [0x2000f274]: Transport write complete.
[00:00:06.503,021] <dbg> net_mqtt.mqtt_publish: (0x2000e9c8): [CID 0x2000f274]:[State 0x06]: << result 0x00000000
[00:00:06.503,051] <dbg> aws_iot.device_shadow_document_request: Device shadow document requested
[00:00:06.503,051] <inf> cloud_module: AWS_IOT_EVT_READY

[00:00:06.503,112] <dbg> net_mqtt.mqtt_input: (0x2000e9c8): state:0x00000006
[00:00:06.503,173] <dbg> net_mqtt_dec.unpack_uint8: (0x2000e9c8): >> cur:0x20011c8e, end:0x20011c90
[00:00:06.503,173] <dbg> net_mqtt_dec.unpack_uint8: (0x2000e9c8): << val:40
[00:00:06.503,173] <dbg> net_mqtt_dec.packet_length_decode: (0x2000e9c8): length:0x00000002
[00:00:06.503,265] <dbg> net_mqtt_rx.mqtt_handle_packet: (0x2000e9c8): [CID 0x2000f274]: Received MQTT_PKT_TYPE_PUBACK!
[00:00:06.503,265] <dbg> net_mqtt_dec.unpack_uint16: (0x2000e9c8): >> cur:0x20011c90, end:0x20011c92
[00:00:06.503,265] <dbg> net_mqtt_dec.unpack_uint16: (0x2000e9c8): << val:f52c
[00:00:06.503,295] <dbg> aws_iot.mqtt_evt_handler: MQTT_EVT_PUBACK: id = 62764 result = 0
[00:00:06.503,356] <dbg> net_mqtt.mqtt_input: (0x2000e9c8): state:0x00000006
[00:00:06.503,417] <dbg> net_mqtt_dec.unpack_uint8: (0x2000e9c8): >> cur:0x20011c8e, end:0x20011c90
[00:00:06.503,417] <dbg> net_mqtt_dec.unpack_uint8: (0x2000e9c8): << val:30
[00:00:06.503,417] <dbg> net_mqtt_dec.packet_length_decode: (0x2000e9c8): length:0x0000005e
[00:00:06.503,509] <dbg> net_mqtt_rx.mqtt_handle_packet: (0x2000e9c8): [CID 0x2000f274]: Received MQTT_PKT_TYPE_PUBLISH
[00:00:06.503,509] <dbg> net_mqtt_dec.unpack_utf8_str: (0x2000e9c8): >> cur:0x20011c90, end:0x20011cc5
[00:00:06.503,509] <dbg> net_mqtt_dec.unpack_uint16: (0x2000e9c8): >> cur:0x20011c90, end:0x20011cc5
[00:00:06.503,540] <dbg> net_mqtt_dec.unpack_uint16: (0x2000e9c8): << val:0033
[00:00:06.503,540] <dbg> net_mqtt_dec.unpack_utf8_str: (0x2000e9c8): << str_size:00000035
[00:00:06.503,540] <dbg> net_mqtt_rx.mqtt_handle_packet: (0x2000e9c8): PUB QoS:00, message len 00000029, topic len 00000033
[00:00:06.719,726] <dbg> net_mqtt_dec.unpack_uint8: (0x2000e9c8): >> cur:0x20011c8e, end:0x20011c91
--- 3 messages dropped ---
[00:00:06.719,726] <dbg> net_mqtt_dec.unpack_uint8: (0x2000e9c8): << val:32
[00:00:06.719,726] <dbg> net_mqtt_dec.packet_length_decode: (0x2000e9c8): length:0x000004f3
[00:00:06.719,818] <dbg> net_mqtt_rx.mqtt_handle_packet: (0x2000e9c8): [CID 0x2000f274]: Received MQTT_PKT_TYPE_PUBLISH
[00:00:06.719,818] <dbg> net_mqtt_dec.unpack_utf8_str: (0x2000e9c8): >> cur:0x20011c91, end:0x20011cc4
[00:00:06.719,848] <dbg> net_mqtt_dec.unpack_uint16: (0x2000e9c8): >> cur:0x20011c91, end:0x20011cc4
[00:00:06.719,848] <dbg> net_mqtt_dec.unpack_uint16: (0x2000e9c8): << val:002f
[00:00:06.719,848] <dbg> net_mqtt_dec.unpack_utf8_str: (0x2000e9c8): << str_size:00000031
[00:00:06.719,879] <dbg> net_mqtt_dec.unpack_uint16: (0x2000e9c8): >> cur:0x20011cc2, end:0x20011cc4
[00:00:06.719,879] <dbg> net_mqtt_dec.unpack_uint16: (0x2000e9c8): << val:0001
[00:00:06.719,879] <dbg> net_mqtt_rx.mqtt_handle_packet: (0x2000e9c8): PUB QoS:01, message len 000004c0, topic len 0000002f
[00:00:06.719,940] <dbg> aws_iot.mqtt_evt_handler: MQTT_EVT_PUBLISH: id = 1 len = 1216 
[00:00:06.720,153] <dbg> net_mqtt.mqtt_publish_qos1_ack: (0x2000e9c8): [CID 0x2000f274]:[State 0x06]: >> Message id 0x0001
[00:00:06.720,397] <dbg> net_mqtt_enc.pack_uint16: (0x2000e9c8): >> val:0001 cur:0x20012493, end:0x20012c8e
[00:00:06.720,397] <dbg> net_mqtt_enc.mqtt_encode_fixed_header: (0x2000e9c8): << msg type:0x40 length:0x00000002
[00:00:06.720,397] <dbg> net_mqtt_enc.packet_length_encode: (0x2000e9c8): >> length:0x00000002 cur:(nil), end:(nil)
[00:00:06.720,397] <dbg> net_mqtt_enc.mqtt_encode_fixed_header: (0x2000e9c8): Fixed header length = 02
[00:00:06.720,428] <dbg> net_mqtt_enc.pack_uint8: (0x2000e9c8): >> val:40 cur:0x20012491, end:0x20012c8e
[00:00:06.720,458] <dbg> net_mqtt_enc.packet_length_encode: (0x2000e9c8): >> length:0x00000002 cur:0x20012492, end:0x20012c8e
[00:00:06.720,458] <dbg> net_mqtt.client_write: (0x2000e9c8): [0x2000f274]: Transport writing 4 bytes.
[00:00:06.936,614] <dbg> net_mqtt_dec.unpack_uint8: (0x2000e9c8): << val:32
--- 8 messages dropped ---
[00:00:06.936,614] <dbg> net_mqtt_dec.packet_length_decode: (0x2000e9c8): length:0x0000013b
[00:00:06.936,706] <dbg> net_mqtt_rx.mqtt_handle_packet: (0x2000e9c8): [CID 0x2000f274]: Received MQTT_PKT_TYPE_PUBLISH
[00:00:06.936,737] <dbg> net_mqtt_dec.unpack_utf8_str: (0x2000e9c8): >> cur:0x20011c91, end:0x20011cc4
[00:00:06.936,737] <dbg> net_mqtt_dec.unpack_uint16: (0x2000e9c8): >> cur:0x20011c91, end:0x20011cc4
[00:00:06.936,737] <dbg> net_mqtt_dec.unpack_uint16: (0x2000e9c8): << val:002f
[00:00:06.936,737] <dbg> net_mqtt_dec.unpack_utf8_str: (0x2000e9c8): << str_size:00000031
[00:00:06.936,767] <dbg> net_mqtt_dec.unpack_uint16: (0x2000e9c8): >> cur:0x20011cc2, end:0x20011cc4
[00:00:06.936,767] <dbg> net_mqtt_dec.unpack_uint16: (0x2000e9c8): << val:0002
[00:00:06.936,767] <dbg> net_mqtt_rx.mqtt_handle_packet: (0x2000e9c8): PUB QoS:01, message len 00000108, topic len 0000002f
[00:00:06.936,828] <dbg> aws_iot.mqtt_evt_handler: MQTT_EVT_PUBLISH: id = 2 len = 264 
[00:00:06.936,920] <dbg> net_mqtt.mqtt_publish_qos1_ack: (0x2000e9c8): [CID 0x2000f274]:[State 0x06]: >> Message id 0x0002
[00:00:06.937,164] <dbg> net_mqtt_enc.pack_uint16: (0x2000e9c8): >> val:0002 cur:0x20012493, end:0x20012c8e
[00:00:06.937,164] <dbg> net_mqtt_enc.mqtt_encode_fixed_header: (0x2000e9c8): << msg type:0x40 length:0x00000002
[00:00:06.937,194] <dbg> net_mqtt_enc.packet_length_encode: (0x2000e9c8): >> length:0x00000002 cur:(nil), end:(nil)
[00:00:06.937,225] <dbg> net_mqtt_enc.mqtt_encode_fixed_header: (0x2000e9c8): Fixed header length = 02
[00:00:06.937,225] <dbg> net_mqtt_enc.pack_uint8: (0x2000e9c8): >> val:40 cur:0x20012491, end:0x20012c8e
[00:00:06.937,255] <dbg> net_mqtt_enc.packet_length_encode: (0x2000e9c8): >> length:0x00000002 cur:0x20012492, end:0x20012c8e
[00:00:06.937,286] <dbg> net_mqtt.client_write: (0x2000e9c8): [0x2000f274]: Transport writing 4 bytes.
[00:00:06.941,833] <inf> event_manager: e:app_module_event APP_EVT_CFG_UPDATED
[00:00:07.155,364] <dbg> net_mqtt.client_write: (0x2000e9c8): [0x2000f274]: Transport write complete.
[00:00:07.155,395] <dbg> net_mqtt.mqtt_publish_qos1_ack: (0x2000e9c8): [CID 0x2000f274]:[State 0x06]: << result 0x00000000
[00:00:07.155,426] <inf> cloud_module: AWS_IOT_EVT_DATA_RECEIVED
[00:00:07.155,487] <inf> event_manager: e:mqtt_msg_module_event MQTT_MSG_FROM_CLOUD, data size: 265
[00:00:07.156,951] <inf> event_manager: e:app_module_event APP_EVT_SHADOW_SEND_REQ
[00:00:07.157,043] <dbg> lte_lc.lte_lc_psm_param_set: RPTAU set to 00100111
[00:00:07.157,043] <dbg> lte_lc.lte_lc_psm_param_set: RAT set to 00000001
[00:00:07.158,355] <inf> event_manager: e:app_module_event APP_EVT_CFG_UPDATED
[00:00:07.158,996] <dbg> lte_lc.lte_lc_psm_param_set: RPTAU set to 00100111
[00:00:07.158,996] <dbg> lte_lc.lte_lc_psm_param_set: RAT set to 00000001
[00:00:07.163,909] <inf> event_manager: e:mqtt_msg_module_event MQTT_MSG_TO_CLOUD, data size: 398
[00:00:07.165,039] <inf> event_manager: e:app_module_event APP_EVT_SHADOW_SEND_REQ
[00:00:07.273,925] <dbg> aws_iot.aws_iot_send: Publishing to topic: $aws/things/352656103794239/shadow/update
[00:00:07.273,956] <dbg> net_mqtt.mqtt_publish: (0x2000cd50): [CID 0x2000f274]:[State 0x06]: >> Topic size 0x00000029, Data size 0x0000018e
[00:00:07.274,200] <dbg> net_mqtt_enc.pack_utf8_str: (0x2000cd50): >> str_size:0000002b cur:0x20012493, end:0x20012c8e
[00:00:07.274,200] <dbg> net_mqtt_enc.pack_uint16: (0x2000cd50): >> val:0029 cur:0x20012493, end:0x20012c8e
[0+CEREG: 1,"0192","001E830A",7,,,"00011110","00100111"
0:00:07.274,230] <dbg> net_mqtt_enc.mqtt_encode_fixed_header: (0x2000cd50): << msg type:0x30 length:0x000001b9
[00:00:07.274,230] <dbg> net_mqtt_enc.packet_length_encode: (0x2000cd50): >> length:0x000001b9 cur:(nil), end:(nil)
[00:00:07.274,230] <dbg> net_mqtt_enc.mqtt_encode_fixed_header: (0x2000cd50): Fixed header length = 03
[00:00:07.274,261] <dbg> net_mqtt_enc.pack_uint8: (0x2000cd50): >> val:30 cur:0x20012490, end:0x20012c8e
[00:00:07.274,261] <dbg> net_mqtt_enc.packet_length_encode: (0x2000cd50): >> length:0x000001b9 cur:0x20012491, end:0x20012c8e
[00:00:07.274,261] <dbg> net_mqtt.client_write_msg: (0x2000cd50): [0x2000f274]: Transport writing message.
[00:00:07.276,031] <dbg> net_mqtt.client_write_msg: (0x2000cd50): [0x2000f274]: Transport write complete.
[00:00:07.276,062] <dbg> net_mqtt.mqtt_publish: (0x2000cd50): [CID 0x2000f274]:[State 0x06]: << result 0x00000000
[00:00:07.280,395] <inf> event_manager: e:mqtt_msg_module_event MQTT_MSG_TO_CLOUD, data size: 398
[00:00:07.334,686] <dbg> lte_lc.at_handler_cereg: +CEREG notification: +CEREG: 1,"0192","001E830A",7,,,"00011110","0~
[00:00:07.334,960] <dbg> lte_lc_helpers.parse_cereg: Network registration status: 1
[00:00:07.334,960] <dbg> lte_lc_helpers.parse_cereg: LTE mode: 7
[00:00:07.335,876] <dbg> lte_lc_helpers.parse_psm: TAU: 25200 sec, active time: 60 sec

[00:00:07.335,876] <dbg> lte_lc.lte_lc_psm_get: TAU: 25200 sec, active time: 60 sec

[00:00:07.335,876] <dbg> lte_lc_helpers.event_handler_list_dispatch: Dispatching events:
[00:00:07.335,906] <dbg> lte_lc_helpers.event_handler_list_dispatch:  - handler=0x0002DB69
[00:00:07.335,906] <dbg> lte_lc_helpers.event_handler_list_dispatch:  - handler=0x00024E05
[00:00:07.335,906] <inf> cloud_module: PSM parameter update: TAU: 25200, Active time: 60
[00:00:07.335,937] <dbg> lte_lc_helpers.event_handler_list_dispatch: Done
[00:00:07.336,029] <inf> event_manager: e:cloud_module_event COULD_EVT_PSM_REPORT
[00:00:07.537,292] <inf> event_manager: e:app_module_event APP_EVT_SHADOW_SEND_REQ
[00:00:07.537,384] <dbg> aws_iot.aws_iot_send: Publishing to topic: $aws/things/352656103794239/shadow/update
[00:00:07.537,414] <dbg> net_mqtt.mqtt_publish: (0x2000cd50): [CID 0x2000f274]:[State 0x06]: >> Topic size 0x00000029, Data size 0x0000018e
[00:00:07.537,628] <dbg> net_mqtt_enc.pack_utf8_str: (0x2000cd50): >> str_size:0000002b cur:0x20012493, end:0x20012c8e
[00:00:07.537,658] <dbg> net_mqtt_enc.pack_uint16: (0x2000cd50): >> val:0029 cur:0x20012493, end:0x20012c8e
[00:00:07.537,658] <dbg> net_mqtt_enc.mqtt_encode_fixed_header: (0x2000cd50): << msg type:0x30 length:0x000001b9
[00:00:07.537,689] <dbg> net_mqtt_enc.packet_length_encode: (0x2000cd50): >> length:0x000001b9 cur:(nil), end:(nil)
[00:00:07.537,689] <dbg> net_mqtt_enc.mqtt_encode_fixed_header: (0x2000cd50): Fixed header length = 03
[00:00:07.537,689] <dbg> net_mqtt_enc.pack_uint8: (0x2000cd50): >> val:30 cur:0x20012490, end:0x20012c8e
[00:00:07.537,689] <dbg> net_mqtt_enc.packet_length_encode: (0x2000cd50): >> length:0x000001b9 cur:0x20012491, end:0x20012c8e
[00:00:07.537,719] <dbg> net_mqtt.client_write_msg: (0x2000cd50): [0x2000f274]: Transport writing message.
[00:00:07.668,762] <inf> event_manager: e:mqtt_msg_module_event MQTT_MSG_TO_CLOUD, data size: 398
[00:00:07.668,914] <dbg> net_mqtt.client_write_msg: (0x2000cd50): [0x2000f274]: Transport write complete.
[00:00:07.668,945] <dbg> net_mqtt.mqtt_publish: (0x2000cd50): [CID 0x2000f274]:[State 0x06]: << result 0x00000000
[00:00:07.669,006] <dbg> aws_iot.aws_iot_send: Publishing to topic: $aws/things/352656103794239/shadow/update
[00:00:07.669,006] <dbg> net_mqtt.mqtt_publish: (0x2000cd50): [CID 0x2000f274]:[State 0x06]: >> Topic size 0x00000029, Data size 0x0000018e
[00:00:07.669,250] <dbg> net_mqtt_enc.pack_utf8_str: (0x2000cd50): >> str_size:0000002b cur:0x20012493, end:0x20012c8e
[00:00:07.669,250] <dbg> net_mqtt_enc.pack_uint16: (0x2000cd50): >> val:0029 cur:0x20012493, end:0x20012c8e
[00:00:07.669,281] <dbg> net_mqtt_enc.mqtt_encode_fixed_header: (0x2000cd50): << msg type:0x30 length:0x000001b9
[00:00:07.669,281] <dbg> net_mqtt_enc.packet_length_encode: (0x2000cd50): >> length:0x000001b9 cur:(nil), end:(nil)
[00:00:07.669,281] <dbg> net_mqtt_enc.mqtt_encode_fixed_header: (0x2000cd50): Fixed header length = 03
[00:00:07.669,281] <dbg> net_mqtt_enc.pack_uint8: (0x2000cd50): >> val:30 cur:0x20012490, end:0x20012c8e
[00:00:07.669,311] <dbg> net_mqtt_enc.packet_length_encode: (0x2000cd50): >> length:0x000001b9 cur:0x20012491, end:0x20012c8e
[00:00:07.669,311] <dbg> net_mqtt.client_write_msg: (0x2000cd50): [0x2000f274]: Transport writing message.
[00:00:07.821,502] <dbg> net_mqtt.client_write_msg: (0x2000cd50): [0x2000f274]: Transport write complete.
[00:00:07.821,533] <dbg> net_mqtt.mqtt_publish: (0x2000cd50): [CID 0x2000f274]:[State 0x06]: << result 0x00000000
%CESQ: 47,2,10,1
%CESQ: 47,2,15,2
%CESQ: 47,2,10,1
+CSCON: 0
%CESQ: 49,2,15,2
[00:00:23.071,228] <dbg> lte_lc.at_handler_cscon: +CSCON notification
[00:00:23.071,350] <dbg> lte_lc_helpers.event_handler_list_dispatch: Dispatching events:
[00:00:23.071,350] <dbg> lte_lc_helpers.event_handler_list_dispatch:  - handler=0x0002DB69
[00:00:23.071,350] <dbg> lte_lc_helpers.event_handler_list_dispatch:  - handler=0x00024E05
[00:00:23.071,380] <inf> cloud_module: RRC mode: Idle
[00:00:23.071,380] <dbg> lte_lc_helpers.event_handler_list_dispatch: Done
+CSCON: 1
[00:00:39.347,442] <dbg> lte_lc.at_handler_cscon: +CSCON notification
[00:00:39.347,564] <dbg> lte_lc_helpers.event_handler_list_dispatch: Dispatching events:
[00:00:39.347,564] <dbg> lte_lc_helpers.event_handler_list_dispatch:  - handler=0x0002DB69
[00:00:39.347,564] <dbg> lte_lc_helpers.event_handler_list_dispatch:  - handler=0x00024E05
[00:00:39.347,564] <inf> cloud_module: RRC mode: Connected
[00:00:39.347,595] <dbg> lte_lc_helpers.event_handler_list_dispatch: Done
%CESQ: 46,2,10,1
+CSCON: 0
%CESQ: 47,2,15,2
%CESQ: 49,2,10,1
[00:00:57.651,580] <dbg> lte_lc.at_handler_cscon: +CSCON notification
[00:00:57.651,702] <dbg> lte_lc_helpers.event_handler_list_dispatch: Dispatching events:
[00:00:57.651,733] <dbg> lte_lc_helpers.event_handler_list_dispatch:  - handler=0x0002DB69
[00:00:57.651,733] <dbg> lte_lc_helpers.event_handler_list_dispatch:  - handler=0x00024E05
[00:00:57.651,733] <inf> cloud_module: RRC mode: Idle
[00:00:57.651,733] <dbg> lte_lc_helpers.event_handler_list_dispatch: Done
%CESQ: 49,2,16,2
%CESQ: 49,2,11,1
+CSCON: 1
%CESQ: 48,2,16,2
[00:01:04.951,019] <dbg> lte_lc.at_handler_cscon: +CSCON notification
[00:01:04.951,141] <dbg> lte_lc_helpers.event_handler_list_dispatch: Dispatching events:
[00:01:04.951,171] <dbg> lte_lc_helpers.event_handler_list_dispatch:  - handler=0x0002DB69
[00:01:04.951,171] <dbg> lte_lc_helpers.event_handler_list_dispatch:  - handler=0x00024E05
[00:01:04.951,171] <inf> cloud_module: RRC mode: Connected
[00:01:04.951,171] <dbg> lte_lc_helpers.event_handler_list_dispatch: Done
+CSCON: 0
[00:01:16.249,053] <dbg> lte_lc.at_handler_cscon: +CSCON notification
[00:01:16.249,206] <dbg> lte_lc_helpers.event_handler_list_dispatch: Dispatching events:
[00:01:16.249,206] <dbg> lte_lc_helpers.event_handler_list_dispatch:  - handler=0x0002DB69
[00:01:16.249,206] <dbg> lte_lc_helpers.event_handler_list_dispatch:  - handler=0x00024E05
[00:01:16.249,206] <inf> cloud_module: RRC mode: Idle
[00:01:16.249,206] <dbg> lte_lc_helpers.event_handler_list_dispatch: Done
+CSCON: 1
[00:02:05.110,778] <dbg> lte_lc.at_handler_cscon: +CSCON notification
[00:02:05.110,900] <dbg> lte_lc_helpers.event_handler_list_dispatch: Dispatching events:
[00:02:05.110,900] <dbg> lte_lc_helpers.event_handler_list_dispatch:  - handler=0x0002DB69
[00:02:05.110,931] <dbg> lte_lc_helpers.event_handler_list_dispatch:  - handler=0x00024E05
[00:02:05.110,931] <inf> cloud_module: RRC mode: Connected
[00:02:05.110,931] <dbg> lte_lc_helpers.event_handler_list_dispatch: Done
[00:02:07.669,708] <inf> event_manager: e:app_module_event APP_EVT_SHADOW_SEND_REQ
[00:02:07.674,560] <inf> event_manager: e:mqtt_msg_module_event MQTT_MSG_TO_CLOUD, data size: 398
[00:02:07.674,957] <dbg> aws_iot.aws_iot_send: Publishing to topic: $aws/things/352656103794239/shadow/update
[00:02:07.674,957] <dbg> net_mqtt.mqtt_publish: (0x2000cd50): [CID 0x2000f274]:[State 0x06]: >> Topic size 0x00000029, Data size 0x0000018e
[00:02:07.675,201] <dbg> net_mqtt_enc.pack_utf8_str: (0x2000cd50): >> str_size:0000002b cur:0x20012493, end:0x20012c8e
[00:02:07.675,201] <dbg> net_mqtt_enc.pack_uint16: (0x2000cd50): >> val:0029 cur:0x20012493, end:0x20012c8e
[00:02:07.675,231] <dbg> net_mqtt_enc.mqtt_encode_fixed_header: (0x2000cd50): << msg type:0x30 length:0x000001b9
[00:02:07.675,231] <dbg> net_mqtt_enc.packet_length_encode: (0x2000cd50): >> length:0x000001b9 cur:(nil), end:(nil)
[00:02:07.675,231] <dbg> net_mqtt_enc.mqtt_encode_fixed_header: (0x2000cd50): Fixed header length = 03
[00:02:07.675,262] <dbg> net_mqtt_enc.pack_uint8: (0x2000cd50): >> val:30 cur:0x20012490, end:0x20012c8e
[00:02:07.675,262] <dbg> net_mqtt_enc.packet_length_encode: (0x2000cd50): >> length:0x000001b9 cur:0x20012491, end:0x20012c8e
[00:02:07.675,292] <dbg> net_mqtt.client_write_msg: (0x2000cd50): [0x2000f274]: Transport writing message.
[00:02:07.813,201] <dbg> net_mqtt.client_write_msg: (0x2000cd50): [0x2000f274]: Transport write complete.
[00:02:07.813,232] <dbg> net_mqtt.mqtt_publish: (0x2000cd50): [CID 0x2000f274]:[State 0x06]: << result 0x00000000
%CESQ: 50,2,11,1
%CESQ: 49,2,16,2
%CESQ: 49,2,11,1
%CESQ: 49,2,16,2
+CSCON: 0
[00:02:45.414,459] <dbg> lte_lc.at_handler_cscon: +CSCON notification
[00:02:45.414,581] <dbg> lte_lc_helpers.event_handler_list_dispatch: Dispatching events:
[00:02:45.414,611] <dbg> lte_lc_helpers.event_handler_list_dispatch:  - handler=0x0002DB69
[00:02:45.414,611] <dbg> lte_lc_helpers.event_handler_list_dispatch:  - handler=0x00024E05
[00:02:45.414,611] <inf> cloud_module: RRC mode: Idle
[00:02:45.414,611] <dbg> lte_lc_helpers.event_handler_list_dispatch: Done
+CSCON: 1
%CESQ: 48,2,11,1
[00:03:09.112,487] <dbg> lte_lc.at_handler_cscon: +CSCON notification
[00:03:09.112,609] <dbg> lte_lc_helpers.event_handler_list_dispatch: Dispatching events:
[00:03:09.112,609] <dbg> lte_lc_helpers.event_handler_list_dispatch:  - handler=0x0002DB69
[00:03:09.112,609] <dbg> lte_lc_helpers.event_handler_list_dispatch:  - handler=0x00024E05
[00:03:09.112,640] <inf> cloud_module: RRC mode: Connected
[00:03:09.112,640] <dbg> lte_lc_helpers.event_handler_list_dispatch: Done

Minicom log file with .cap extension didn't upload. Chaged the extension to .txt and trying again.

[Charlie]

Hi IIKKA,

Modem trace can help to analyze such kind of communication between device and cell station.

Can you record modem traces with the DNA network and another normal network for your application?

Best regards,

Charlie

[Hidastelija]

Hi Charlie,

This is the first time I've used modem traces, I hope the attached files are ok. Attached is traces from two networks. The traces should have AWS connection at boot, then 4min idle and at 4min a data update.

I am using Circuitdojo nRF9160 Feather HW in my measurements. Using Trace Collector V2 I wasn't able to trace using a board that is not Nordic DK. I took the traces using Trace Collector v1.1.2 and then tried to convert to Wireshark using Trace Collector V2. I couldn't verify the logs as "Convert RAW trace to PCAP" displays this error:

11:39:15.459

Failed conversion to pcap: end of file reached while searching db uid plugin path: C:\Users\ilkka\.nrfconnect-apps\node_modules\pc-nrfconnect-tracecollector-preview\node_modules\@nordicsemiconductor\nrf-monitor-lib-js\Release\win32-ia32\nrfml-insight-source.nrfmlTelia_modem_trace.bin

DNA_modem_trace.bin

If the logs are not good, I can try to trace again using nRF9160DK.

Br,

Ilkka

[Charlie]

Hi IIKKA,

I also failed to convert these two recordings. The reason is that Circuitdojo nRF9160 Feather HW may not support the current tracing configuration since it is not a Nordic Devkits. I am looking forward to seeing your recordings with nRF9160DK.

Best regards,

Charlie

[Hidastelija]

Ok, the logs look better when using nRF9160DK. Now I can convert the logs and open in Wireshark. I've attached again logs from DNA and Telia networks.

Application functionality in the logs:

- log begin

- Reset (using button on DK)

- AWS IoT Connection

- 4min idle

- at 4min data/shadow update to AWS

DNA_modem_trace_nRF91DK.binTelia_modem_trace_nRF91DK.bin

Br,

Ilkka