nrf9160 nRF cloud doesn't pair, stuck at CLOUD_EVT_PAIR_REQUEST

[samo4]

Hello,

I have a Thingy91 which was previously successfuly paired to nrf cloud. I deleted the device from nrf cloud and provisioned new certificates from nrf cloud (and uploaded to device). Now the device won't pair.. no error. See part of the log below.

[0m<dbg> nrf_cloud.api_event_handler: NRF_CLOUD_EVT_USER_ASSOCIATION_REQUEST

[0m<inf> asset_tracker: CLOUD_EVT_PAIR_REQUEST

[0m<inf> asset_tracker: Add device to cloud account.

[0m<inf> asset_tracker: Waiting for cloud association...

[0m<dbg> nrf_cloud_transport.nct_mqtt_evt_handler: MQTT_EVT_PUBACK: id = 1 result = 0

I also tried provisioning certificates with my custom prefix (and changing the NRF_CLOUD_CLIENT_ID_PREFIX), but the result is the same.

I'm currently using LTE-M, but I believe the original pairing was done with NbIOT. That being said.. I'm wondering how is NRFCloud able to support NBIOT (UDP?).

[Albrecht Markus Schellenberger]

Hello,

could you provide me with a full application log? I might have to cross-check this with our nRF Cloud team.

Thanks and regards,

Markus

[samo4]

Here's the complete log for the version when I use custom prefix:

*** Booting Zephyr OS build v2.4.99-ncs2  ***

[00:00:00.237,243] <inf> asset_tracker: Asset tracker started... v1.5a
[00:00:00.244,812] <dbg> nrf_cloud_transport.nct_client_id_get: client_id = shd-352656101110727
[00:00:00.245,330] <dbg> nrf_cloud_transport.nct_topics_populate: shadow_base_topic: $aws/things/shd-352656101110727/shadow
[00:00:00.245,941] <dbg> nrf_cloud_transport.nct_topics_populate: accepted_topic: shd-352656101110727/shadow/get/accepted
[00:00:00.246,520] <dbg> nrf_cloud_transport.nct_topics_populate: rejected_topic: $aws/things/shd-352656101110727/shadow/get/rejected
[00:00:00.247,161] <dbg> nrf_cloud_transport.nct_topics_populate: update_delta_topic: $aws/things/shd-352656101110727/shadow/update/delta
[00:00:00.247,802] <dbg> nrf_cloud_transport.nct_topics_populate: update_topic: $aws/things/shd-352656101110727/shadow/update
[00:00:00.248,413] <dbg> nrf_cloud_transport.nct_topics_populate: shadow_get_topic: $aws/things/sh[00:00:19.974,334] <inf> nrf_cloud_transport: Using socket send timeout of 60 seconds
[00:00:19.974,853] <dbg> nrf_cloud.nrf_cloud_run: Cloud connection request sent.
[00:00:20.546,417] <dbg> nrf_cloud_transport.nct_mqtt_evt_handler: MQTT_EVT_CONNACK: result 0
[00:00:20.546,905] <dbg> nrf_cloud.nfsm_set_current_state_and_notify: state: 2
[00:00:20.547,363] <dbg> nrf_cloud.api_event_handler: NRF_CLOUD_EVT_TRANSPORT_CONNECTED
[00:00:20.547,821] <inf> asset_tracker: CLOUD_EVT_CONNECTED
[00:00:20.548,217] <inf> asset_tracker: Persistent Sessions = 0
[00:00:20.548,614] <dbg> nrf_cloud_transport.nct_cc_connect: nct_cc_connect
[00:00:20.550,079] <dbg> nrf_cloud.nfsm_set_current_state_and_notify: state: 3
[00:00:21.123,413] <dbg> nrf_cloud_transport.nct_mqtt_evt_handler: MQTT_EVT_SUBACK: id = 1234 result = 0
[00:00:21.123,992] <dbg> nrf_cloud.nfsm_set_current_state_and_notify: state: 4
[00:00:21.124,450] <dbg> nrf_cloud_transport.nct_cc_send: mqtt_publish: id = 5678 opcode = 0 len = 0
[00:00:21.126,007] <dbg> nrf_cloud.nfsm_set_current_state_and_notify: state: 5
[00:00:21.646,423] <dbg> nrf_cloud_transport.nct_mqtt_evt_handler: MQTT_EVT_PUBACK: id = 5678 result = 0
[00:00:21.646,972] <dbg> nrf_cloud.nfsm_set_current_state_and_notify: state: 5
[00:00:21.891,510] <dbg> nrf_cloud_transport.nct_mqtt_evt_handler: MQTT_EVT_PUBLISH: id = 37916 len = 50
[00:00:21.894,165] <dbg> nrf_cloud_transport.nct_cc_send: mqtt_publish: id = 1 opcode = 1 len = 168
[00:00:21.896,392] <dbg> nrf_cloud.nfsm_set_current_state_and_notify: state: 6
[00:00:21.896,850] <dbg> nrf_cloud.api_event_handler: NRF_CLOUD_EVT_USER_ASSOCIATION_REQUEST
[00:00:21.897,338] <inf> asset_tracker: CLOUD_EVT_PAIR_REQUEST
[00:00:21.897,705] <inf> asset_tracker: Add device to cloud account.
[00:00:21.898,101] <inf> asset_tracker: Waiting for cloud association...
[00:00:22.830,444] <dbg> nrf_cloud_transport.nct_mqtt_evt_handler: MQTT_EVT_PUBACK: id = 1 result = 0
[00:00:29.303,680] <dbg> lte_lc.at_handler: +CSCON notification
[00:00:29.304,199] <inf> asset_tracker: RRC mode: Idle
[00:02:22.373,748] <dbg> lte_lc.at_handler: +CSCON notification
[00:02:22.374,267] <inf> asset_tracker: RRC mode: Connected

Here's later log:

[00:05:21.898,559] <inf> asset_tracker: Disconnecting from cloud...
[00:05:21.898,956] <dbg> nrf_cloud_transport.nct_disconnect: nct_disconnect
[00:05:21.907,653] <dbg> nrf_cloud_transport.nct_mqtt_evt_handler: MQTT_EVT_DISCONNECT: result = 0
[00:05:21.908,172] <dbg> nrf_cloud.nfsm_set_current_state_and_notify: state: 1
[00:05:21.908,630] <dbg> nrf_cloud.api_event_handler: NRF_CLOUD_EVT_TRANSPORT_DISCONNECTED
[00:05:21.909,118] <inf> asset_tracker: CLOUD_EVT_DISCONNECTED: 0
[00:05:21.909,515] <inf> asset_tracker: Attempting reconnect in 10 seconds...
[00:05:21.910,095] <dbg> nrf_cloud.nrf_cloud_run: Socket error: POLLNVAL
[00:05:21.910,522] <dbg> nrf_cloud.nrf_cloud_run: The cloud socket was unexpectedly closed.
[00:05:22.216,918] <dbg> lte_lc.at_handler: +CSCON notification
[00:05:22.217,437] <inf> asset_tracker: RRC mode: Connected
[00:05:28.225,555] <dbg> lte_lc.at_handler: +CSCON notification
[00:05:28.226,074] <inf> asset_tracker: RRC mode: Idle
[00:05:28.577,880] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 1,"2775","0003F321",9,,,"11100000","11100000"

[00:05:28.578,735] <dbg> lte_lc.parse_psm_cfg: TAU: -1 sec, active time: -1 sec

[00:05:28.579,315] <inf> asset_tracker: cell changed ID: 258849, area: 10101
[00:05:31.910,034] <inf> asset_tracker: Connecting to cloud, attempt 1 of 8
[00:05:31.910,522] <inf> asset_tracker: Cloud connection request sent.
[00:05:31.910,919] <inf> asset_tracker: Connection response timeout is set to 30 seconds.
[00:05:31.911,437] <dbg> nrf_cloud.api_event_handler: NRF_CLOUD_EVT_TRANSPORT_CONNECTING
[00:05:31.911,926] <inf> asset_tracker: CLOUD_EVT_CONNECTING
[00:05:32.507,720] <dbg> lte_lc.at_handler: +CSCON notification
[00:05:32.508,239] <inf> asset_tracker: RRC mode: Connected
[00:05:32.956,329] <dbg> nrf_cloud_transport.nct_connect: IPv4 address: 52.71.225.111
[00:05:50.885,803] <inf> nrf_cloud_transport: Using socket send timeout of 60 seconds
[00:05:50.886,291] <dbg> nrf_cloud.nrf_cloud_run: Cloud connection request sent.
[00:05:51.419,830] <dbg> nrf_cloud_transport.nct_mqtt_evt_handler: MQTT_EVT_CONNACK: result 0
[00:05:51.420,349] <dbg> nrf_cloud.nfsm_set_current_state_and_notify: state: 2
[00:05:51.420,806] <dbg> nrf_cloud.api_event_handler: NRF_CLOUD_EVT_TRANSPORT_CONNECTED
[00:05:51.421,264] <inf> asset_tracker: CLOUD_EVT_CONNECTED
[00:05:51.421,630] <inf> asset_tracker: Persistent Sessions = 0
[00:05:51.422,058] <dbg> nrf_cloud_transport.nct_cc_connect: nct_cc_connect
[00:05:51.423,522] <dbg> nrf_cloud.nfsm_set_current_state_and_notify: state: 3
[00:05:52.059,844] <dbg> nrf_cloud_transport.nct_mqtt_evt_handler: MQTT_EVT_SUBACK: id = 1234 result = 0
[00:05:52.060,424] <dbg> nrf_cloud.nfsm_set_current_state_and_notify: state: 4
[00:05:52.060,882] <dbg> nrf_cloud_transport.nct_cc_send: mqtt_publish: id = 5678 opcode = 0 len = 0
[00:05:52.062,408] <dbg> nrf_cloud.nfsm_set_current_state_and_notify: state: 5
[00:05:52.607,849] <dbg> nrf_cloud_transport.nct_mqtt_evt_handler: MQTT_EVT_PUBACK: id = 5678 result = 0
[00:05:52.608,428] <dbg> nrf_cloud.nfsm_set_current_state_and_notify: state: 5
[00:05:52.827,850] <dbg> nrf_cloud_transport.nct_mqtt_evt_handler: MQTT_EVT_PUBLISH: id = 37916 len = 50
[00:05:52.830,505] <dbg> nrf_cloud_transport.nct_cc_send: mqtt_publish: id = 1 opcode = 1 len = 168
[00:05:52.832,702] <dbg> nrf_cloud.nfsm_set_current_state_and_notify: state: 6
[00:05:52.833,160] <dbg> nrf_cloud.api_event_handler: NRF_CLOUD_EVT_USER_ASSOCIATION_REQUEST
[00:05:52.833,648] <inf> asset_tracker: CLOUD_EVT_PAIR_REQUEST
[00:05:52.834,014] <inf> asset_tracker: Add device to cloud account.
[00:05:52.834,411] <inf> asset_tracker: Waiting for cloud association...
[00:05:53.761,901] <dbg> nrf_cloud_transport.nct_mqtt_evt_handler: MQTT_EVT_PUBACK: id = 1 result = 0
[00:05:59.922,729] <dbg> lte_lc.at_handler: +CSCON notification
[00:05:59.923,248] <inf> asset_tracker: RRC mode: Idle
[00:06:00.181,274] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 1,"2775","00075E21",9,,,"11100000","11100000"

[00:06:00.182,128] <dbg> lte_lc.parse_psm_cfg: TAU: -1 sec, active time: -1 sec

[00:06:00.182,708] <inf> asset_tracker: cell changed ID: 482849, area: 10101