Hi,
I am 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 .
I 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.
A typical log looks as follows:
[00:39:25.021,392] <inf> main: sendto done: seq_num=79, retval=20 [00:39:25.027,618] <inf> modem: Update: %XMONITOR: 5,"","","26202","AF89",9,20,"009E6165",175,6346,52,2 [00:39:25.137,023] <inf> modem: Update: %NBRGRSRP: 175,6346,53,36,6346,52,64,6346,50,498,6346,42 OK [00:39:27.051,574] <inf> modem: Update: +CEREG: 5,"AF65","009F1667",9,,,"11100000","11100000" [00:39:27.160,034] <inf> modem: Update: +CEINFO: 1,1,R,8,1,52,24 [00:39:27.677,368] <inf> modem: Update: +CEINFO: 1,1,C,2,1,52,24 [00:39:27.854,339] <inf> modem: Update: +CGEV: ME PDN DEACT 0 [00:39:27.960,052] <inf> modem: Update: +CNEC_EMM: 10 [00:39:28.065,032] <inf> modem: Update: +CEREG: 2,"AF65","009F1667",9,0,10,"11100000","11100000" [00:39:28.173,797] <inf> modem: Update: +CGEV: NW DETACH [00:39:28.784,698] <inf> modem: Update: %CESQ: 47,2,9,1 [00:39:28.889,923] <inf> modem: Update: +CEINFO: 1,1,I,8,1,47,24 [00:39:28.995,880] <inf> modem: Update: +CEINFO: 1,1,R,8,1,47,24 [00:39:30.182,403] <inf> modem: Update: +CEINFO: 1,1,C,2,1,47,24 [00:39:36.536,407] <inf> modem: Update: +CEINFO: 1,1,R,8,1,47,24 [00:39:36.642,333] <inf> modem: Update: +CEINFO: 1,1,C,2,1,47,24 [00:39:51.770,690] <inf> modem: Update: +CEINFO: 1,1,R,8,1,47,24 [00:39:51.967,987] <inf> modem: Update: +CEINFO: 1,1,C,2,1,47,24 [00:39:52.073,944] <inf> modem: Update: +CGEV: ME PDN ACT 0,0 [00:39:52.179,626] <inf> modem: Update: +CNEC_ESM: 50,0 [00:39:52.284,790] <inf> modem: Update: +CEREG: 5,"AF65","009F1667",9,,,"11100000","11100000" [00:39:52.393,280] <inf> modem: Update: +CGEV: ME PDN DEACT 0 [00:39:52.498,992] <inf> modem: Update: +CEREG: 2,"AF65","009F1667",9,0,0,"11100000","11100000" [00:39:52.607,635] <inf> modem: Update: +CGEV: ME DETACH [00:39:55.004,333] <inf> modem: Update: %CESQ: 54,2,15,2 [00:39:55.028,472] <err> main: sendto error: seq_num=80, retval=-1, errno=51 [00:39:55.109,588] <inf> modem: Update: +CEINFO: 1,1,I,8,1,54,30 [00:39:55.215,545] <inf> modem: Update: +CEREG: 2,"AF89","00ADA666",9,0,0,"11100000","11100000" [00:39:55.324,218] <inf> modem: Update: %XMONITOR: 2 OK [00:39:55.429,473] <inf> modem: Update: OK [00:40:05.156,494] <inf> modem: Update: %CESQ: 47,2,15,2 [00:40:10.276,611] <inf> modem: Update: %CESQ: 47,2,20,2 [00:40:12.836,761] <inf> modem: Update: %CESQ: 57,2,20,2 [00:40:17.956,756] <inf> modem: Update: %CESQ: 52,2,20,2 [00:40:23.076,873] <inf> modem: Update: %CESQ: 52,2,11,1 [00:40:25.044,830] <inf> modem: Update: %XMONITOR: 2 OK [00:40:25.050,201] <err> main: sendto error: seq_num=81, retval=-1, errno=51 [00:40:25.150,115] <inf> modem: Update: %NBRGRSRP: 96,6346,49,498,6346,56,49,6346,51,50,6346,46,245,634 [00:40:28.196,990] <inf> modem: Update: %CESQ: 52,2,16,2 [00:40:34.836,791] <inf> modem: Update: +CEREG: 2,"AF65","009E6367",9,0,0,"11100000","11100000" [00:40:37.308,441] <inf> modem: Update: %CESQ: 52,2,21,3 [00:40:44.988,616] <inf> modem: Update: %CESQ: 52,2,26,3 [00:40:50.108,703] <inf> modem: Update: %CESQ: 57,2,26,3 [00:40:55.058,319] <inf> modem: Update: %XMONITOR: 2 OK [00:40:55.063,568] <err> main: sendto error: seq_num=82, retval=-1, errno=51 [ ... ] [00:46:55.333,923] <err> main: sendto error: seq_num=94, retval=-1, errno=51 [00:46:55.427,612] <inf> modem: Update: OK [00:46:59.092,529] <inf> modem: Update: %CESQ: 67,3,16,2 [00:47:01.652,587] <inf> modem: Update: %CESQ: 61,3,16,2 [00:47:11.892,791] <inf> modem: Update: %CESQ: 55,2,16,2 [00:47:14.452,850] <inf> modem: Update: %CESQ: 55,2,11,1 [00:47:19.572,967] <inf> modem: Update: %CESQ: 55,2,6,0 [00:47:22.221,343] <inf> modem: Update: %CESQ: 55,2,15,2 [00:47:22.326,629] <inf> modem: Update: +CEREG: 2,"AF65","00A0F565",9,0,0,"11100000","11100000" [00:47:25.350,433] <inf> modem: Update: %XMONITOR: 2 OK [00:47:25.361,999] <err> main: sendto error: seq_num=95, retval=-1, errno=51 [00:47:25.455,688] <inf> modem: Update: %NBRGRSRP: 468,6346,58,470,6346,51 OK [00:47:29.813,201] <inf> modem: Update: %CESQ: 55,2,20,2 [00:47:55.370,178] <inf> modem: Update: %XMONITOR: 2 OK [00:47:55.375,579] <err> main: sendto error: seq_num=96, retval=-1, errno=51 [ ... ] [00:54:25.668,304] <err> main: sendto error: seq_num=109, retval=-1, errno=51 [00:54:25.761,962] <inf> modem: Update: %NBRGRSRP: 468,6346,60,310,6346,58 OK [00:54:47.582,702] <inf> modem: Update: %CESQ: 55,2,25,3 [ System reset ] ***** Booting Zephyr OS build v2.0.99-ncs1 ***** [00:00:01.641,601] <inf> main: modem-test 0.5 [00:00:01.648,010] <inf> modem: Connecting to network... [00:00:01.665,740] <inf> modem: Modem firmware: mfw_nrf9160_1.2.0 [00:00:01.672,210] <inf> modem: Supported bands: %XCBAND: (1,2,3,4,5,8,12,13,17,19,20,25,26,28,66) [00:00:01.696,258] <inf> modem: status update: +CEINFO: 1,1,I,0,0,255,127 [00:00:04.728,729] <inf> modem: signal quality update: 53,2,20,2 [00:00:04.734,649] <inf> modem: status update: +CEINFO: 1,1,I,8,1,53,34 [00:00:04.741,180] <inf> modem: status update: +CEREG: 2,"AF65","00A0F565",9,0,0,"11100000","11100000" [00:00:04.741,210] <inf> modem: registration status: 2 [00:00:04.800,170] <inf> modem: status update: +CEINFO: 1,1,R,8,1,53,34 [00:00:05.138,397] <inf> modem: status update: +CEINFO: 1,1,C,2,1,53,34 [00:00:05.625,335] <inf> modem: status update: +CEINFO: 1,1,R,8,1,53,34 [00:00:05.720,489] <inf> modem: status update: +CEINFO: 1,1,C,2,1,53,34 [00:00:06.214,233] <inf> modem: status update: +CGEV: ME PDN ACT 0,0 [00:00:06.220,520] <inf> modem: status update: +CNEC_ESM: 50,0 [00:00:06.226,257] <inf> modem: status update: +CEREG: 5,"AF65","00A0F565",9,,,"11100000","11100000" [00:00:06.226,257] <inf> modem: registration status: 5 [00:00:06.240,203] <inf> modem: Connected [00:00:06.244,445] <inf> modem: Current band: %XCBAND: 20 [00:00:06.250,030] <inf> modem: IMSI: 901280023211437 [00:00:06.250,518] <inf> modem: status update: +CGPADDR: 0,"10.112.128.142" [00:00:06.262,207] <inf> modem: Modem monitor started, tid=0x2002000c [00:00:06.268,493] <inf> main: connected to network [00:00:06.268,524] <inf> main: Session ID: 205407 [00:00:06.269,622] <inf> main: sendto done: seq_num=1, retval=20 [00:00:06.284,942] <inf> modem: Update: %XMONITOR: 5,"","","26202","AF65",9,20,"00A0F565",468,6346,53,3 [00:00:06.394,317] <inf> modem: Update: OK [00:00:06.498,352] <inf> modem: Update: +CEINFO: 1,1,R,8,1,53,34 [00:00:06.728,515] <inf> modem: Update: +CEINFO: 1,1,C,2,1,53,34 [00:00:21.075,164] <inf> modem: Update: +CEINFO: 1,1,I,8,1,53,28 [00:00:21.181,121] <inf> modem: Update: +CEREG: 5,"AF65","009EE267",9,,,"11100000","11100000" [00:00:36.285,949] <inf> main: sendto done: seq_num=2, retval=20
I attach the full log in case that helps. The CNEC_ESM: 50,0 (PDN type IPv4 only allowed) error occurs on every bearer activation and seems to be due to the fact the the NB-IoT network I am connecting to (Vodafone Germany) does not support IPv6 yet. However, it normally does not seem to cause any issues.
Is this issue known? Do you have any suggestions how to debug this further? Will it help if I provide a trace?
Best regards,
Norbert
Full log:
