Note: This is related to the following issues:
- https://devzone.nordicsemi.com/f/nordic-q-a/63255/nrf9160-getting-stuck-after-cell-change
------------------------------------------------
Hi,
we are running into issues where the nRF9160 (in NB-IoT mode) does not seem to handle cell changes reliably. I am using modem firmware mfw_nrf9160_1.2.0 .
We made a simplified test firmware to debug the issue. The test firmware enables several unsolicited notifications from the modem and prints them to the log. It then sends a UDP packet every 30s to a server which logs them. It also calls AT%XMONITOR and AT%NBRGRSRP in hope to get additional information. The AT commands at startup are as follows:
AT%XSYSTEMMODE=0,1,0,2 // Set modem to NB-IoT mode
AT+CGMR // Query modem firmware
AT%XCBAND=? // Query supported bands
AT+CMEE=1 // Subscribe to mobile termination error
AT+CEREG=5 // Subscribe to network registration status
AT+CGEREP=1 // Subscribe to packet domain events
AT+CNEC=24 // Subscribe to network error codes
AT%CESQ=1 // Subscribe to signal quality
AT+CEINFO=1 // Subscribe to Coverage Enhancement notifications
AT%XBANDLOCK=2,"10000000000000000000" // Run-time lock to band 20
AT+CFUN=1 // Enable modem
// *** after connect ***
AT%XCBAND // Query current band
AT+CIMI // Query IMSI
AT+CGPADDR // Query IP address
After a while, sendto starts to fail with errno=ENETUNREACH. The logs show that this is because there is no longer a packet domain connection. The problem can be provoked by driving the system around in a car (more cell changes), but also happens after a few days if the system is stationary. It does seem to fix itself eventually, but may take many hours to do so. However, if I reset the system, it instantly connects again.
The log file looks as follows:
[34:19:46.436,828] <inf> main: sendto done: seq_num=4118, retval=20
[34:19:46.443,481] <inf> modem: Update: %XMONITOR: 5,"","","26202","AF67",9,20,"00AD1665",259,6346,42,3
[34:19:46.552,978] <inf> modem: Update: OK
[34:19:46.657,073] <inf> modem: Update: +CEINFO: 1,1,R,8,1,42,31
[34:19:46.763,122] <inf> modem: Update: +CEINFO: 1,1,C,2,1,42,31
[34:19:56.982,971] <inf> modem: Update: %CESQ: 42,2,17,2
[34:19:57.088,317] <inf> modem: Update: +CEINFO: 1,1,I,8,1,42,27
[34:20:15.881,408] <inf> modem: Update: %CESQ: 42,2,22,3
[34:20:16.453,002] <inf> main: sendto done: seq_num=4119, retval=20
[34:20:16.459,503] <inf> modem: Update: %XMONITOR: 5,"","","26202","AF67",9,20,"00AD1665",259,6346,42,3
[34:20:16.569,000] <inf> modem: Update: %NBRGRSRP: 259,6346,50,290,6346,47,260,6346,41 OK
[34:20:16.677,368] <inf> modem: Update: +CEINFO: 1,1,R,8,1,42,33
[34:20:16.970,581] <inf> modem: Update: +CEINFO: 1,1,C,2,1,42,33
[34:20:22.263,122] <inf> modem: Update: +CEINFO: 1,1,I,8,1,42,31
[34:20:38.921,539] <inf> modem: Update: %CESQ: 42,2,14,2
[34:20:46.469,024] <inf> main: sendto done: seq_num=4120, retval=20
[34:20:46.475,524] <inf> modem: Update: %XMONITOR: 5,"","","26202","AF67",9,20,"00AD1665",259,6346,42,2
[34:20:46.585,052] <inf> modem: Update: %NBRGRSRP: 259,6346,42,290,6346,46,260,6346,40,299,6346,39 OK
[34:20:49.161,621] <inf> modem: Update: %CESQ: 42,2,19,2
[34:20:50.185,485] <inf> modem: Update: +CEREG: 5,"AF66","009DE067",9,,,"00100001","10111110"
[34:20:50.294,097] <inf> modem: Update: +CEINFO: 1,1,R,8,1,42,30
[34:20:50.731,109] <inf> modem: Update: +CEINFO: 1,1,C,2,1,42,30
ESM = Session Management
EMM = Mobility Management
[34:20:50.837,127] <inf> modem: Update: +CGEV: ME PDN DEACT 0 -> The UE has deactivated a default bearer
[34:20:50.942,901] <inf> modem: Update: +CNEC_EMM: 10 -> Implicitly detached
[34:20:51.048,004] <inf> modem: Update: +CEREG: 2,"AF66","009DE067",9,0,10,"11100000","11100000"
[34:20:51.156,860] <inf> modem: Update: +CGEV: NW DETACH -> Network detach
[34:20:51.262,207] <inf> modem: Update: +CEINFO: 1,1,I,8,1,42,32
[34:20:51.368,255] <inf> modem: Update: +CEINFO: 1,1,R,8,1,42,32
[34:20:51.476,104] <inf> modem: Update: +CEINFO: 1,1,C,2,1,42,32
[34:20:51.644,531] <inf> modem: Update: +CNEC_ESM: 29,0 -> User authentication failed
[34:20:51.749,786] <inf> modem: Update: +CNEC_EMM: 19 -> ESM failure
[34:20:51.854,888] <inf> modem: Update: +CEREG: 2,"AF66","009DE067",9,0,19,"11100000","11100000"
[34:20:51.963,745] <inf> modem: Update: +CEINFO: 1,1,I,8,1,42,32
[34:21:16.484,802] <inf> modem: Update: %XMONITOR: 2 OK
[34:21:16.490,142] <err> main: sendto error: seq_num=4121, retval=-1, errno=51
[34:21:16.590,270] <inf> modem: Update: %NBRGRSRP: 290,6346,48,259,6346,48,299,6346,40,260,6346,38 OK
[34:21:22.662,109] <inf> modem: Update: %CESQ: 42,2,24,3
[34:21:46.513,061] <inf> modem: Update: %XMONITOR: 2 OK
[34:21:46.524,780] <err> main: sendto error: seq_num=4122, retval=-1, errno=51
[34:21:46.618,438] <inf> modem: Update: %NBRGRSRP: 290,6346,47,259,6346,43,260,6346,39,299,6346,39 OK
[34:22:16.541,595] <inf> modem: Update: %XMONITOR: 2 OK
[34:22:16.553,314] <err> main: sendto error: seq_num=4123, retval=-1, errno=51
[34:22:16.647,003] <inf> modem: Update: %NBRGRSRP: 290,6346,47,259,6346,43,299,6346,41,260,6346,40 OK
[34:22:46.561,767] <inf> modem: Update: %XMONITOR: 2 OK
[34:22:46.567,352] <err> main: sendto error: seq_num=4124, retval=-1, errno=51
[34:22:46.667,144] <inf> modem: Update: %NBRGRSRP: 290,6346,48,259,6346,43,260,6346,41,299,6346,34 OK
[34:22:54.822,601] <inf> modem: Update: %CESQ: 42,2,19,2
[34:23:15.302,703] <inf> modem: Update: %CESQ: 42,2,24,3
[34:23:16.584,045] <inf> modem: Update: %XMONITOR: 2 OK
[34:23:16.595,764] <err> main: sendto error: seq_num=4125, retval=-1, errno=51
[34:23:16.689,453] <inf> modem: Update: %NBRGRSRP: 290,6346,49,259,6346,47,260,6346,40,299,6346,40 OK
[34:23:46.612,579] <inf> modem: Update: %XMONITOR: 2 OK
[34:23:46.624,298] <err> main: sendto error: seq_num=4126, retval=-1, errno=51
[34:23:46.717,987] <inf> modem: Update: %NBRGRSRP: 290,6346,47,259,6346,40,260,6346,40,299,6346,34 OK
[34:24:06.502,960] <inf> modem: Update: %CESQ: 42,2,18,2
[34:24:11.622,985] <inf> modem: Update: %CESQ: 42,2,24,3
[34:24:16.632,690] <inf> modem: Update: %XMONITOR: 2 OK
[34:24:16.638,122] <err> main: sendto error: seq_num=4127, retval=-1, errno=51
[34:24:16.738,037] <inf> modem: Update: %NBRGRSRP: 290,6346,48,259,6346,43,299,6346,41,260,6346,40,41,6
[34:24:46.654,815] <inf> modem: Update: %XMONITOR: 2 OK
[34:24:46.666,473] <err> main: sendto error: seq_num=4128, retval=-1, errno=51
[34:24:46.760,162] <inf> modem: Update: %NBRGRSRP: 290,6346,48,259,6346,42,260,6346,41,299,6346,38,39,6
[34:25:16.683,258] <inf> modem: Update: %XMONITOR: 2 OK
[34:25:16.694,946] <err> main: sendto error: seq_num=4129, retval=-1, errno=51
[34:25:16.788,635] <inf> modem: Update: %NBRGRSRP: 290,6346,47,259,6346,42,260,6346,41,299,6346,40,39,6
[34:25:46.711,761] <inf> modem: Update: %XMONITOR: 2 OK
[34:25:46.723,480] <err> main: sendto error: seq_num=4130, retval=-1, errno=51
[34:25:46.817,169] <inf> modem: Update: %NBRGRSRP: 290,6346,47,260,6346,39,259,6346,37,299,6346,36,39,6
[34:26:01.703,582] <inf> modem: Update: %CESQ: 42,2,19,2
[34:26:04.263,610] <inf> modem: Update: %CESQ: 42,2,24,3
[34:26:16.731,933] <inf> modem: Update: %XMONITOR: 2 OK
[34:26:16.737,487] <err> main: sendto error: seq_num=4131, retval=-1, errno=51
[34:26:16.837,310] <inf> modem: Update: %NBRGRSRP: 290,6346,47,259,6346,41,260,6346,41,299,6346,37,39,6
[34:26:46.754,180] <inf> modem: Update: %XMONITOR: 2 OK
[34:26:46.765,899] <err> main: sendto error: seq_num=4132, retval=-1, errno=51
[34:26:46.859,588] <inf> modem: Update: %NBRGRSRP: 290,6346,48,259,6346,43,299,6346,42,260,6346,41,39,6
[34:27:16.782,714] <inf> modem: Update: %XMONITOR: 2 OK
[34:27:16.794,403] <err> main: sendto error: seq_num=4133, retval=-1, errno=51
[34:27:16.888,092] <inf> modem: Update: %NBRGRSRP: 290,6346,47,259,6346,46,260,6346,40,299,6346,38 OK
[34:27:46.811,218] <inf> modem: Update: %XMONITOR: 2 OK
[34:27:46.822,937] <err> main: sendto error: seq_num=4134, retval=-1, errno=51
[34:27:46.916,625] <inf> modem: Update: %NBRGRSRP: 290,6346,47,259,6346,43,260,6346,42,299,6346,39,258,
[34:28:16.831,512] <err> main: sendto error: seq_num=4135, retval=-1, errno=51
[34:28:16.831,604] <inf> modem: Update: %XMONITOR: 2 OK
[34:28:16.944,152] <inf> modem: Update: %NBRGRSRP: 290,6346,47,259,6346,45,260,6346,41,299,6346,38,258,
[34:28:46.853,332] <inf> modem: Update: %XMONITOR: 2 OK
[34:28:46.864,990] <err> main: sendto error: seq_num=4136, retval=-1, errno=51
[34:28:46.958,679] <inf> modem: Update: %NBRGRSRP: 290,6346,46,259,6346,41,299,6346,38,260,6346,36,258,
[34:29:16.881,805] <inf> modem: Update: %XMONITOR: 2 OK
[34:29:16.893,524] <err> main: sendto error: seq_num=4137, retval=-1, errno=51
[34:29:16.987,182] <inf> modem: Update: %NBRGRSRP: 290,6346,47,259,6346,45,260,6346,41,299,6346,35,258,
[34:29:46.902,008] <inf> modem: Update: %XMONITOR: 2 OK
[34:29:46.907,562] <err> main: sendto error: seq_num=4138, retval=-1, errno=51
[34:29:47.007,354] <inf> modem: Update: %NBRGRSRP: 290,6346,47,259,6346,44,260,6346,38,299,6346,36,258,
[34:30:12.584,930] <inf> modem: Update: %CESQ: 42,2,19,2
[34:30:16.924,224] <inf> modem: Update: %XMONITOR: 2 OK
[34:30:16.935,943] <err> main: sendto error: seq_num=4139, retval=-1, errno=51
[34:30:17.029,632] <inf> modem: Update: %NBRGRSRP: 290,6346,47,259,6346,54,299,6346,43,258,6346,41,260,
[34:30:17.704,956] <inf> modem: Update: %CESQ: 47,2,19,2
[34:30:23.404,876] <inf> modem: Update: +CEREG: 2,"AF67","00AD1665",9,0,19,"11100000","11100000"
[34:30:23.513,763] <inf> modem: Update: +CEINFO: 1,1,R,8,1,47,33
[34:30:23.815,826] <inf> modem: Update: +CEINFO: 1,1,C,2,1,47,33
[34:30:24.329,681] <inf> modem: Update: +CEINFO: 1,1,R,8,1,47,33
[34:30:24.435,699] <inf> modem: Update: +CEINFO: 1,1,C,2,1,47,33
[34:30:24.851,501] <inf> modem: Update: +CGEV: ME PDN ACT 0,0 -> The ME has activated a default bearer. Reason 0: Only IPv4 allowed
[34:30:24.957,275] <inf> modem: Update: +CNEC_ESM: 50,0 -> PDN type IPv4 only allowed
[34:30:25.062,530] <inf> modem: Update: +CEREG: 5,"AF67","00AD1665",9,,,"00100001","10111110"
[34:30:35.226,379] <inf> modem: Update: +CEINFO: 1,1,I,8,1,47,31
[34:30:37.964,721] <inf> modem: Update: %CESQ: 47,2,24,3
[34:30:46.953,033] <inf> main: sendto done: seq_num=4140, retval=20
In this case, we observe the following Error messages:
- +CNEC_ESM: 29,0 -> User authentication failed
- +CNEC_EMM: 19 -> ESM failure
- +CNEC_ESM: 50,0 -> PDN type IPv4 only allowed
The full logfile is attached here: