agps: SUPL session failed, error: -13

[Johan]

Hi,

We are using 1.5.1 tag and building on the agps-sample called "v1.5.1\nrf\samples\nrf9160\agps\".

We see problems with downloading SUPL-data and also EVT_BLOCKED and stops searching at all.

No apparent reason for it what we can see. Perhaps bugs that were not fixed in 1.5.1 but in later commits? We need help with this.

See log below.

Best

Johan

LOG BELOW

[00:00:00.204,956] <inf> resetinfo: Reset reason = 0x00000001
[00:00:00.213,317] <err> resetinfo: Reboot reason: RESET_REASON_RESET_PIN
[00:00:00.234,619] <dbg> 9160.provision_certificates
[00:00:01.975,952] <inf> agps_sample: A-GPS sample has started
[00:00:01.991,210] <dbg> nrf9160_gps.configure_antenna: MAGPIO set: AT%XMAGPIO=1,0,0,1,1,1574,1577
[00:00:02.002,838] <dbg> nrf9160_gps.open_socket: GPS socket created, fd: 1232491587
[00:00:03.329,071] <inf> modem: ICCID: 89462008001000226627
[00:00:03.337,249] <inf> modem: IMSI: 248030105093729
[00:00:03.344,940] <inf> modem: MFW: mfw_nrf9160_1.3.0
[00:00:03.367,614] <dbg> modem.modem_set_gps_active: Activating GPS...
[00:00:03.431,091] <dbg> nrf9160_gps.gps_priority_set: GPS priority disabled
[00:00:03.448,272] <dbg> nrf9160_gps.start: GPS operational
[00:00:03.456,726] <inf> agps_sample: Periodic GPS search started with interval 0 s, timeout 0 s
[00:00:03.468,139] <inf> agps_sample: GPS_EVT_SEARCH_STARTED
[00:00:03.476,501] <dbg> nrf9160_gps.gps_thread: A-GPS data update needed
[00:00:03.485,839] <inf> agps_sample: GPS_EVT_AGPS_DATA_NEEDED
[00:00:03.494,262] <inf> modem: LTE connecting...
[00:00:03.501,556] <dbg> modem.modem_lte_connect: Activating LTE
[00:00:03.569,091] <wrn> gps_storage: store nrf52 uptime = 11321473 ms
[00:00:11.130,187] <dbg> modem.lte_lc_evt_handler: REG status: 2
[00:00:20.234,680] <dbg> modem.lte_lc_evt_handler: REG status: 5
[00:00:20.243,377] <inf> modem: LTE connected
[00:00:20.250,335] <dbg> agps.init_supl: Using GPS driver to input assistance data
[00:00:20.260,498] <inf> agps: SUPL is initialized
[00:00:20.267,913] <dbg> agps.open_supl_socket: CONFIG_POSIX_MAX_FDS=8
[00:00:20.277,038] <dbg> agps.open_supl_socket: CONFIG_NRF_MODEM_LIB_HEAP_SIZE=2048
[00:00:20.288,757] <dbg> agps.open_supl_socket: ip 173.194.222.192 (c0dec2ad) port 7276
[00:00:20.568,572] <inf> agps: Starting SUPL session
[00:00:20.578,186] <dbg> agps.supl_logger: ULP encoding length: 38
[00:00:20.587,493] <dbg> agps.supl_logger: Bytes sent: 38
[00:00:21.248,138] <dbg> agps.supl_logger: Bytes received: 34, total 34
[00:00:21.257,873] <dbg> agps.supl_logger: ULP ossDecode success, choice 3
[00:00:21.267,425] <dbg> agps.supl_logger: SUPL server responded using version 2.0.4
[00:00:21.277,770] <dbg> agps.supl_logger: SUPL response received
[00:00:21.286,621] <dbg> agps.supl_logger: ULP encoding length: 57
[00:00:21.295,989] <dbg> agps.supl_logger: Bytes sent: 57
[00:00:22.303,161] <dbg> agps.supl_logger: read again
[00:00:22.600,952] <dbg> agps.supl_logger: Bytes received: 708, total 708
[00:00:22.610,961] <dbg> agps.supl_logger: ULP ossDecode more input 4
[00:00:23.620,422] <dbg> agps.supl_logger: read again
[00:00:23.753,448] <dbg> agps.supl_logger: Bytes received: 708, total 1416
[00:00:23.763,458] <dbg> agps.supl_logger: ULP ossDecode more input 4
[00:00:24.772,583] <dbg> agps.supl_logger: read again
[00:00:25.640,686] <dbg> agps.supl_logger: Bytes received: 708, total 2124
[00:00:25.650,665] <dbg> agps.supl_logger: ULP ossDecode more input 4
[00:00:26.659,851] <dbg> agps.supl_logger: read again
[00:00:27.667,388] <dbg> agps.supl_logger: read again
[00:00:28.675,170] <dbg> agps.supl_logger: read again
[00:00:29.682,861] <dbg> agps.supl_logger: read again
[00:00:30.690,643] <dbg> agps.supl_logger: read again
[00:00:31.698,425] <dbg> agps.supl_logger: read again
[00:00:32.706,237] <dbg> agps.supl_logger: Timeout expired
[00:00:32.714,294] <dbg> agps.supl_logger: SUPL error: 3
[00:00:32.722,290] <dbg> agps.supl_logger: ULP encoding length: 34
[00:00:32.731,628] <dbg> agps.supl_logger: Bytes sent: 34
[00:00:32.739,624] <dbg> agps.supl_logger: SUPL session internal resources released
[00:00:32.749,847] <dbg> agps.supl_logger: SUPL session finished
[00:00:32.758,422] <err> agps: SUPL session failed, error: -13
[00:00:32.767,089] <err> agps: SUPL request failed, error: -13
[00:00:32.775,756] <err> agps_sample: Failed to request A-GPS data, error: -13
[00:00:32.785,980] <dbg> nrf9160_gps.print_satellite_stats: Tracking: 0 Using: 0 Unhealthy: 0
[00:00:32.797,088] <dbg> nrf9160_gps.print_satellite_stats: Seconds since last fix 32
[00:00:32.808,319] <dbg> nrf9160_gps.gps_thread: Waiting for time window to operate
[00:00:32.818,542] <inf> agps_sample: GPS_EVT_OPERATION_BLOCKED
[00:00:37.287,292] <dbg> nrf9160_gps.gps_thread: GPS has time window to operate
[00:00:37.297,180] <inf> agps_sample: GPS_EVT_OPERATION_UNBLOCKED
[00:00:37.305,908] <dbg> nrf9160_gps.print_satellite_stats: Tracking: 0 Using: 0 Unhealthy: 0
[00:00:37.317,016] <dbg> nrf9160_gps.print_satellite_stats: Seconds since last fix 37
[00:00:38.287,475] <dbg> nrf9160_gps.print_satellite_stats: Tracking: 0 Using: 0 Unhealthy: 0
[00:00:38.298,614] <dbg> nrf9160_gps.print_satellite_stats: Seconds since last fix 38
[00:00:39.287,536] <dbg> nrf9160_gps.print_satellite_stats: Tracking: 0 Using: 0 Unhealthy: 0
[00:00:39.298,645] <dbg> nrf9160_gps.print_satellite_stats: Seconds since last fix 39
[00:00:40.287,567] <dbg> nrf9160_gps.print_satellite_stats: Tracking: 0 Using: 0 Unhealthy: 0
[00:00:40.298,675] <dbg> nrf9160_gps.print_satellite_stats: Seconds since last fix 40
[00:00:42.383,605] <dbg> nrf9160_gps.gps_thread: Waiting for time window to operate
[00:00:42.393,859] <inf> agps_sample: GPS_EVT_OPERATION_BLOCKED

[Johan]

As suggested by Martin Lesund the blocking and unblocking came from me accidently not going offline from LTE. Cause was I was responding to the error code from the supl session, which was error, and not calling lte disconnect subsequently. 

Now it looks good, no blocking no more. 

I would still enjoy a fix for the supl library to NOT report error. 

Is anybody listening in this thread?

[Johan]

Here's another log with more details for the connect and disconnect of LTE as well if needed.
Hourly A-GPS fetch happened.

[01:00:08.580,505] <dbg> nrf9160_gps.gps_thread: A-GPS data update needed
[01:00:08.589,904] <inf> agps_sample: GPS_EVT_AGPS_DATA_NEEDED
[01:00:08.598,358] <err> modem: modem_lte_connect called
[01:00:08.606,536] <inf> modem: LTE connecting...
[01:00:08.613,830] <dbg> modem.modem_lte_connect: Activating LTE
[01:00:08.622,436] <dbg> at_cmd.at_cmd_write: at_cmd_write 2
[01:00:08.630,676] <dbg> at_cmd.load_cmd_and_write: load_cmd_and_write
[01:00:08.639,801] <dbg> at_cmd.load_cmd_and_write: at_write(AT+CFUN=21)
[01:00:08.649,078] <dbg> at_cmd.at_write: at_write 1
[01:00:08.656,646] <dbg> at_cmd.at_write: Sending command AT+CFUN=21
[01:00:08.665,588] <dbg> net_sock.z_impl_zsock_sendto: z_impl_zsock_sendto
[01:00:08.675,354] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CFUN=21
[01:00:08.712,707] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK

[01:00:08.722,076] <dbg> at_cmd.get_return_code: get_return_code
[01:00:08.730,682] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
[01:00:08.740,997] <dbg> at_cmd.socket_thread_fn: Writing any pending command
[01:00:08.750,701] <dbg> at_cmd.load_cmd_and_write: load_cmd_and_write
[01:00:08.759,857] <dbg> at_cmd.socket_thread_fn: Listening on socket
[01:00:10.019,439] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 32 bytes, +CEREG: 2,"0027","018A0116",7

[01:00:10.031,250] <dbg> at_cmd.get_return_code: get_return_code
[01:00:10.039,886] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 2,"0027","018A0116",7

[01:00:10.051,513] <err> modem: lte_lc_evt_handler called
[01:00:10.059,753] <dbg> modem.lte_lc_evt_handler: REG status: 2
[01:00:10.068,389] <err> modem: lte_lc_evt_handler called
[01:00:10.076,690] <dbg> at_cmd.socket_thread_fn: Writing any pending command
[01:00:10.086,425] <dbg> at_cmd.load_cmd_and_write: load_cmd_and_write
[01:00:10.095,581] <dbg> at_cmd.socket_thread_fn: Listening on socket
[01:00:10.326,538] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 12 bytes, +CSCON: 1

[01:00:10.336,608] <dbg> at_cmd.get_return_code: get_return_code
[01:00:10.345,275] <dbg> lte_lc.at_handler: +CSCON notification
[01:00:10.353,881] <err> modem: lte_lc_evt_handler called
[01:00:10.362,182] <dbg> at_cmd.socket_thread_fn: Writing any pending command
[01:00:10.371,887] <dbg> at_cmd.load_cmd_and_write: load_cmd_and_write
[01:00:10.381,072] <dbg> at_cmd.socket_thread_fn: Listening on socket
[01:00:11.551,971] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 56 bytes, +CEREG: 5,"0027","018A0116",7,,,"11100000","11100000"

[01:00:11.565,887] <dbg> at_cmd.get_return_code: get_return_code
[01:00:11.574,554] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 5,"0027","018A0116",7,,,"11100000","11100000"

[01:00:11.588,348] <dbg> lte_lc.parse_psm_cfg: TAU: -1 sec, active time: -1 sec

[01:00:11.598,449] <err> modem: lte_lc_evt_handler called
[01:00:11.606,719] <dbg> modem.lte_lc_evt_handler: REG status: 5
[01:00:11.615,356] <dbg> at_cmd.socket_thread_fn: Writing any pending command
[01:00:11.625,122] <dbg> at_cmd.load_cmd_and_write: load_cmd_and_write
[01:00:11.634,277] <dbg> at_cmd.socket_thread_fn: Listening on socket
[01:00:11.643,371] <inf> modem: LTE connected
[01:00:11.650,299] <dbg> agps.open_supl_socket: CONFIG_POSIX_MAX_FDS=8
[01:00:11.659,423] <dbg> agps.open_supl_socket: CONFIG_NRF_MODEM_LIB_HEAP_SIZE=2048
[01:00:11.670,928] <dbg> agps.open_supl_socket: ip 173.194.222.192 (c0dec2ad) port 7276
[01:00:11.940,307] <inf> agps: Starting SUPL session
[01:00:11.947,875] <dbg> at_cmd.at_cmd_write: at_cmd_write 2
[01:00:11.956,146] <dbg> at_cmd.load_cmd_and_write: load_cmd_and_write
[01:00:11.965,270] <dbg> at_cmd.load_cmd_and_write: at_write(AT+CIMI)
[01:00:11.974,304] <dbg> at_cmd.at_write: at_write 1
[01:00:11.981,994] <dbg> at_cmd.at_write: Sending command AT+CIMI
[01:00:11.990,722] <dbg> net_sock.z_impl_zsock_sendto: z_impl_zsock_sendto
[01:00:12.000,457] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CIMI
[01:00:12.010,162] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 22 bytes, 248030105093729
OK

[01:00:12.021,148] <dbg> at_cmd.get_return_code: get_return_code
[01:00:12.029,754] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
[01:00:12.040,039] <dbg> at_cmd.socket_thread_fn: Writing any pending command
[01:00:12.049,774] <dbg> at_cmd.load_cmd_and_write: load_cmd_and_write
[01:00:12.058,929] <dbg> at_cmd.socket_thread_fn: Listening on socket
[01:00:12.068,084] <dbg> at_cmd.at_cmd_write: at_cmd_write 2
[01:00:12.076,354] <dbg> at_cmd.load_cmd_and_write: load_cmd_and_write
[01:00:12.085,479] <dbg> at_cmd.load_cmd_and_write: at_write(AT%XMONITOR)
[01:00:12.094,879] <dbg> at_cmd.at_write: at_write 1
[01:00:12.102,447] <dbg> at_cmd.at_write: Sending command AT%XMONITOR
[01:00:12.111,511] <dbg> net_sock.z_impl_zsock_sendto: z_impl_zsock_sendto
[01:00:12.121,337] <dbg> at_cmd.at_cmd_write: Awaiting response for AT%XMONITOR
[01:00:12.131,378] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 117 bytes, %XMONITOR: 5,"TELIA","TELIA","24001","0027",7,20,"018A0116",211,6300,15,27,"","11100000","11100000","01001001"
OK

[01:00:12.150,665] <dbg> at_cmd.get_return_code: get_return_code
[01:00:12.159,301] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
[01:00:12.169,616] <dbg> at_cmd.socket_thread_fn: Writing any pending command
[01:00:12.179,321] <dbg> at_cmd.load_cmd_and_write: load_cmd_and_write
[01:00:12.188,507] <dbg> at_cmd.socket_thread_fn: Listening on socket
[01:00:12.198,059] <dbg> agps.supl_logger: ULP encoding length: 38
[01:00:12.206,909] <dbg> net_sock.z_impl_zsock_sendto: z_impl_zsock_sendto
[01:00:12.217,224] <dbg> agps.supl_logger: Bytes sent: 38
[01:00:12.565,765] <dbg> agps.supl_logger: Bytes received: 34, total 34
[01:00:12.575,439] <dbg> agps.supl_logger: ULP ossDecode success, choice 3
[01:00:12.584,991] <dbg> agps.supl_logger: SUPL server responded using version 2.0.4
[01:00:12.595,367] <dbg> agps.supl_logger: SUPL response received
[01:00:12.604,248] <dbg> agps.supl_logger: ULP encoding length: 57
[01:00:12.613,159] <dbg> net_sock.z_impl_zsock_sendto: z_impl_zsock_sendto
[01:00:12.623,535] <dbg> agps.supl_logger: Bytes sent: 57
[01:00:13.365,997] <dbg> agps.supl_logger: Bytes received: 708, total 708
[01:00:13.375,885] <dbg> agps.supl_logger: ULP ossDecode more input 4
[01:00:14.238,616] <dbg> agps.supl_logger: Bytes received: 708, total 1416
[01:00:14.248,565] <dbg> agps.supl_logger: ULP ossDecode more input 4
[01:00:15.257,324] <dbg> agps.supl_logger: read again
[01:00:16.237,335] <dbg> agps.supl_logger: Bytes received: 1416, total 2832
[01:00:16.247,375] <dbg> agps.supl_logger: ULP ossDecode more input 4
[01:00:16.717,041] <dbg> agps.supl_logger: Bytes received: 167, total 2999
[01:00:16.727,325] <dbg> agps.supl_logger: ULP ossDecode success, choice 5
[01:00:16.740,173] <dbg> agps.supl_logger: No UTC data available
[01:00:16.753,204] <dbg> nrf9160_gps.agps_write: Sent A-GPS data to modem, type: 2
[01:00:16.763,397] <dbg> agps.inject_agps_type: Injected AGPS data, type: 2, size: 72
[01:00:16.778,442] <dbg> nrf9160_gps.agps_write: Sent A-GPS data to modem, type: 2
[01:00:16.788,665] <dbg> agps.inject_agps_type: Injected AGPS data, type: 2, size: 72
[01:00:16.803,100] <dbg> nrf9160_gps.agps_write: Sent A-GPS data to modem, type: 2
[01:00:16.813,293] <dbg> agps.inject_agps_type: Injected AGPS data, type: 2, size: 72
[01:00:16.828,521] <dbg> nrf9160_gps.agps_write: Sent A-GPS data to modem, type: 2
[01:00:16.838,684] <dbg> agps.inject_agps_type: Injected AGPS data, type: 2, size: 72
[01:00:16.853,027] <dbg> nrf9160_gps.agps_write: Sent A-GPS data to modem, type: 2
[01:00:16.863,189] <dbg> agps.inject_agps_type: Injected AGPS data, type: 2, size: 72
[01:00:16.877,990] <dbg> nrf9160_gps.agps_write: Sent A-GPS data to modem, type: 2
[01:00:16.888,183] <dbg> agps.inject_agps_type: Injected AGPS data, type: 2, size: 72
[01:00:16.902,709] <dbg> nrf9160_gps.agps_write: Sent A-GPS data to modem, type: 2
[01:00:16.912,872] <dbg> agps.inject_agps_type: Injected AGPS data, type: 2, size: 72
[01:00:16.927,886] <dbg> nrf9160_gps.agps_write: Sent A-GPS data to modem, type: 2
[01:00:16.938,079] <dbg> agps.inject_agps_type: Injected AGPS data, type: 2, size: 72
[01:00:16.952,545] <dbg> nrf9160_gps.agps_write: Sent A-GPS data to modem, type: 2
[01:00:16.962,738] <dbg> agps.inject_agps_type: Injected AGPS data, type: 2, size: 72
[01:00:16.977,691] <dbg> nrf9160_gps.agps_write: Sent A-GPS data to modem, type: 2
[01:00:16.987,884] <dbg> agps.inject_agps_type: Injected AGPS data, type: 2, size: 72
[01:00:17.001,983] <dbg> nrf9160_gps.agps_write: Sent A-GPS data to modem, type: 2
[01:00:17.012,176] <dbg> agps.inject_agps_type: Injected AGPS data, type: 2, size: 72
[01:00:17.027,374] <dbg> nrf9160_gps.agps_write: Sent A-GPS data to modem, type: 2
[01:00:17.037,536] <dbg> agps.inject_agps_type: Injected AGPS data, type: 2, size: 72
[01:00:17.052,246] <dbg> nrf9160_gps.agps_write: Sent A-GPS data to modem, type: 2
[01:00:17.062,438] <dbg> agps.inject_agps_type: Injected AGPS data, type: 2, size: 72
[01:00:17.077,270] <dbg> nrf9160_gps.agps_write: Sent A-GPS data to modem, type: 2
[01:00:17.087,463] <dbg> agps.inject_agps_type: Injected AGPS data, type: 2, size: 72
[01:00:17.102,203] <dbg> nrf9160_gps.agps_write: Sent A-GPS data to modem, type: 2
[01:00:17.112,365] <dbg> agps.inject_agps_type: Injected AGPS data, type: 2, size: 72
[01:00:17.126,373] <dbg> nrf9160_gps.agps_write: Sent A-GPS data to modem, type: 2
[01:00:17.136,566] <dbg> agps.inject_agps_type: Injected AGPS data, type: 2, size: 72
[01:00:17.151,550] <dbg> nrf9160_gps.agps_write: Sent A-GPS data to modem, type: 2
[01:00:17.161,712] <dbg> agps.inject_agps_type: Injected AGPS data, type: 2, size: 72
[01:00:17.175,659] <dbg> nrf9160_gps.agps_write: Sent A-GPS data to modem, type: 2
[01:00:17.185,821] <dbg> agps.inject_agps_type: Injected AGPS data, type: 2, size: 72
[01:00:17.200,714] <dbg> nrf9160_gps.agps_write: Sent A-GPS data to modem, type: 2
[01:00:17.210,906] <dbg> agps.inject_agps_type: Injected AGPS data, type: 2, size: 72
[01:00:17.225,494] <dbg> nrf9160_gps.agps_write: Sent A-GPS data to modem, type: 2
[01:00:17.235,656] <dbg> agps.inject_agps_type: Injected AGPS data, type: 2, size: 72
[01:00:17.250,915] <dbg> nrf9160_gps.agps_write: Sent A-GPS data to modem, type: 2
[01:00:17.261,108] <dbg> agps.inject_agps_type: Injected AGPS data, type: 2, size: 72
[01:00:17.275,909] <dbg> nrf9160_gps.agps_write: Sent A-GPS data to modem, type: 2
[01:00:17.286,071] <dbg> agps.inject_agps_type: Injected AGPS data, type: 2, size: 72
[01:00:17.301,025] <dbg> nrf9160_gps.agps_write: Sent A-GPS data to modem, type: 2
[01:00:17.311,187] <dbg> agps.inject_agps_type: Injected AGPS data, type: 2, size: 72
[01:00:17.325,897] <dbg> nrf9160_gps.agps_write: Sent A-GPS data to modem, type: 2
[01:00:17.336,059] <dbg> agps.inject_agps_type: Injected AGPS data, type: 2, size: 72
[01:00:17.351,135] <dbg> nrf9160_gps.agps_write: Sent A-GPS data to modem, type: 2
[01:00:17.361,297] <dbg> agps.inject_agps_type: Injected AGPS data, type: 2, size: 72
[01:00:17.376,068] <dbg> nrf9160_gps.agps_write: Sent A-GPS data to modem, type: 2
[01:00:17.386,260] <dbg> agps.inject_agps_type: Injected AGPS data, type: 2, size: 72
[01:00:17.400,939] <dbg> nrf9160_gps.agps_write: Sent A-GPS data to modem, type: 2
[01:00:17.411,102] <dbg> agps.inject_agps_type: Injected AGPS data, type: 2, size: 72
[01:00:17.425,842] <dbg> nrf9160_gps.agps_write: Sent A-GPS data to modem, type: 2
[01:00:17.436,004] <dbg> agps.inject_agps_type: Injected AGPS data, type: 2, size: 72
[01:00:17.450,866] <dbg> nrf9160_gps.agps_write: Sent A-GPS data to modem, type: 2
[01:00:17.461,029] <dbg> agps.inject_agps_type: Injected AGPS data, type: 2, size: 72
[01:00:17.475,830] <dbg> nrf9160_gps.agps_write: Sent A-GPS data to modem, type: 2
[01:00:17.485,992] <dbg> agps.inject_agps_type: Injected AGPS data, type: 2, size: 72
[01:00:17.500,915] <dbg> nrf9160_gps.agps_write: Sent A-GPS data to modem, type: 2
[01:00:17.511,108] <dbg> agps.inject_agps_type: Injected AGPS data, type: 2, size: 72
[01:00:17.523,468] <dbg> nrf9160_gps.agps_write: Sent A-GPS data to modem, type: 3
[01:00:17.533,630] <dbg> agps.inject_agps_type: Injected AGPS data, type: 3, size: 32
[01:00:17.545,837] <dbg> nrf9160_gps.agps_write: Sent A-GPS data to modem, type: 3
[01:00:17.555,999] <dbg> agps.inject_agps_type: Injected AGPS data, type: 3, size: 32
[01:00:17.568,664] <dbg> nrf9160_gps.agps_write: Sent A-GPS data to modem, type: 3
[01:00:17.578,826] <dbg> agps.inject_agps_type: Injected AGPS data, type: 3, size: 32
[01:00:17.591,278] <dbg> nrf9160_gps.agps_write: Sent A-GPS data to modem, type: 3
[01:00:17.601,440] <dbg> agps.inject_agps_type: Injected AGPS data, type: 3, size: 32
[01:00:17.613,769] <dbg> nrf9160_gps.agps_write: Sent A-GPS data to modem, type: 3
[01:00:17.623,931] <dbg> agps.inject_agps_type: Injected AGPS data, type: 3, size: 32
[01:00:17.636,108] <dbg> nrf9160_gps.agps_write: Sent A-GPS data to modem, type: 3
[01:00:17.646,301] <dbg> agps.inject_agps_type: Injected AGPS data, type: 3, size: 32
[01:00:17.658,599] <dbg> nrf9160_gps.agps_write: Sent A-GPS data to modem, type: 3
[01:00:17.668,762] <dbg> agps.inject_agps_type: Injected AGPS data, type: 3, size: 32
[01:00:17.681,304] <dbg> nrf9160_gps.agps_write: Sent A-GPS data to modem, type: 3
[01:00:17.691,528] <dbg> agps.inject_agps_type: Injected AGPS data, type: 3, size: 32
[01:00:17.703,582] <dbg> nrf9160_gps.agps_write: Sent A-GPS data to modem, type: 3
[01:00:17.713,745] <dbg> agps.inject_agps_type: Injected AGPS data, type: 3, size: 32
[01:00:17.725,830] <dbg> nrf9160_gps.agps_write: Sent A-GPS data to modem, type: 3
[01:00:17.736,022] <dbg> agps.inject_agps_type: Injected AGPS data, type: 3, size: 32
[01:00:17.748,626] <dbg> nrf9160_gps.agps_write: Sent A-GPS data to modem, type: 3
[01:00:17.758,789] <dbg> agps.inject_agps_type: Injected AGPS data, type: 3, size: 32
[01:00:17.771,545] <dbg> nrf9160_gps.agps_write: Sent A-GPS data to modem, type: 3
[01:00:17.781,738] <dbg> agps.inject_agps_type: Injected AGPS data, type: 3, size: 32
[01:00:17.794,006] <dbg> nrf9160_gps.agps_write: Sent A-GPS data to modem, type: 3
[01:00:17.804,229] <dbg> agps.inject_agps_type: Injected AGPS data, type: 3, size: 32
[01:00:17.816,131] <dbg> nrf9160_gps.agps_write: Sent A-GPS data to modem, type: 3
[01:00:17.826,354] <dbg> agps.inject_agps_type: Injected AGPS data, type: 3, size: 32
[01:00:17.838,623] <dbg> nrf9160_gps.agps_write: Sent A-GPS data to modem, type: 3
[01:00:17.848,815] <dbg> agps.inject_agps_type: Injected AGPS data, type: 3, size: 32
[01:00:17.861,297] <dbg> nrf9160_gps.agps_write: Sent A-GPS data to modem, type: 3
[01:00:17.871,459] <dbg> agps.inject_agps_type: Injected AGPS data, type: 3, size: 32
[01:00:17.883,575] <dbg> nrf9160_gps.agps_write: Sent A-GPS data to modem, type: 3
[01:00:17.893,768] <dbg> agps.inject_agps_type: Injected AGPS data, type: 3, size: 32
[01:00:17.906,036] <dbg> nrf9160_gps.agps_write: Sent A-GPS data to modem, type: 3
[01:00:17.916,198] <dbg> agps.inject_agps_type: Injected AGPS data, type: 3, size: 32
[01:00:17.928,253] <dbg> nrf9160_gps.agps_write: Sent A-GPS data to modem, type: 3
[01:00:17.938,415] <dbg> agps.inject_agps_type: Injected AGPS data, type: 3, size: 32
[01:00:17.950,744] <dbg> nrf9160_gps.agps_write: Sent A-GPS data to modem, type: 3
[01:00:17.960,906] <dbg> agps.inject_agps_type: Injected AGPS data, type: 3, size: 32
[01:00:17.972,930] <dbg> nrf9160_gps.agps_write: Sent A-GPS data to modem, type: 3
[01:00:17.983,093] <dbg> agps.inject_agps_type: Injected AGPS data, type: 3, size: 32
[01:00:17.995,330] <dbg> nrf9160_gps.agps_write: Sent A-GPS data to modem, type: 3
[01:00:18.005,523] <dbg> agps.inject_agps_type: Injected AGPS data, type: 3, size: 32
[01:00:18.017,883] <dbg> nrf9160_gps.agps_write: Sent A-GPS data to modem, type: 3
[01:00:18.028,076] <dbg> agps.inject_agps_type: Injected AGPS data, type: 3, size: 32
[01:00:18.040,069] <dbg> nrf9160_gps.agps_write: Sent A-GPS data to modem, type: 3
[01:00:18.050,262] <dbg> agps.inject_agps_type: Injected AGPS data, type: 3, size: 32
[01:00:18.062,286] <dbg> nrf9160_gps.agps_write: Sent A-GPS data to modem, type: 3
[01:00:18.072,418] <dbg> agps.inject_agps_type: Injected AGPS data, type: 3, size: 32
[01:00:18.084,442] <dbg> nrf9160_gps.agps_write: Sent A-GPS data to modem, type: 3
[01:00:18.094,635] <dbg> agps.inject_agps_type: Injected AGPS data, type: 3, size: 32
[01:00:18.106,872] <dbg> nrf9160_gps.agps_write: Sent A-GPS data to modem, type: 3
[01:00:18.117,034] <dbg> agps.inject_agps_type: Injected AGPS data, type: 3, size: 32
[01:00:18.129,150] <dbg> nrf9160_gps.agps_write: Sent A-GPS data to modem, type: 3
[01:00:18.139,312] <dbg> agps.inject_agps_type: Injected AGPS data, type: 3, size: 32
[01:00:18.151,580] <dbg> nrf9160_gps.agps_write: Sent A-GPS data to modem, type: 3
[01:00:18.161,712] <dbg> agps.inject_agps_type: Injected AGPS data, type: 3, size: 32
[01:00:18.174,041] <dbg> nrf9160_gps.agps_write: Sent A-GPS data to modem, type: 3
[01:00:18.184,234] <dbg> agps.inject_agps_type: Injected AGPS data, type: 3, size: 32
[01:00:18.196,411] <dbg> nrf9160_gps.agps_write: Sent A-GPS data to modem, type: 3
[01:00:18.206,573] <dbg> agps.inject_agps_type: Injected AGPS data, type: 3, size: 32
[01:00:18.217,010] <dbg> agps.supl_logger: No integrity data available
[01:00:18.226,165] <dbg> agps.supl_logger: No iono data available
[01:00:18.234,832] <dbg> agps.supl_logger: No system time data available
[01:00:18.244,140] <dbg> agps.supl_logger: No location data available
[01:00:18.253,875] <dbg> nrf9160_gps.agps_write: Sent A-GPS data to modem, type: 8
[01:00:18.264,068] <dbg> agps.inject_agps_type: Injected AGPS data, type: 7, size: 16
[01:00:18.274,536] <dbg> agps.supl_logger: MCC location info injected, MCC: 240
[01:00:18.284,545] <dbg> agps.supl_logger: Lat: 5851520 Lon: 780606
[01:00:18.293,548] <dbg> agps.supl_logger: Unc semiminor/semimajor: 119/119
[01:00:18.303,222] <dbg> agps.supl_logger: Unc altitude: 127
[01:00:18.311,614] <dbg> agps.supl_logger: Confidence: 100
[01:00:18.319,793] <dbg> agps.supl_logger: Orientation: 0
[01:00:18.327,941] <dbg> agps.supl_logger: SUPL POS received
[01:00:18.336,303] <dbg> agps.supl_logger: read again
[01:00:18.344,024] <dbg> agps.supl_logger: read error: -1
[01:00:18.352,050] <dbg> agps.supl_logger: SUPL error: 1
[01:00:18.360,076] <dbg> agps.supl_logger: ULP encoding length: 34
[01:00:18.368,957] <dbg> net_sock.z_impl_zsock_sendto: z_impl_zsock_sendto
[01:00:18.378,479] <dbg> agps.supl_logger: Sending SUPL message failed, bytes_sent: -1
[01:00:18.389,007] <dbg> agps.supl_logger: SUPL session internal resources released
[01:00:18.399,261] <dbg> agps.supl_logger: SUPL session finished
[01:00:18.407,867] <err> agps: SUPL session failed, error: -3
[01:00:18.416,503] <err> agps: SUPL request failed, error: -3
[01:00:18.425,109] <err> agps_sample: Failed to request A-GPS data, error: -3
[01:00:18.435,089] <err> modem: modem_lte_disconnect called
[01:00:18.443,542] <inf> modem: LTE disconnecting...
[01:00:18.451,110] <dbg> modem.modem_lte_disconnect: Deactivating LTE
[01:00:18.460,144] <dbg> at_cmd.at_cmd_write: at_cmd_write 2
[01:00:18.468,414] <dbg> at_cmd.load_cmd_and_write: load_cmd_and_write
[01:00:18.477,539] <dbg> at_cmd.load_cmd_and_write: at_write(AT+CFUN=20)
[01:00:18.486,846] <dbg> at_cmd.at_write: at_write 1
[01:00:18.494,415] <dbg> at_cmd.at_write: Sending command AT+CFUN=20
[01:00:18.503,387] <dbg> net_sock.z_impl_zsock_sendto: z_impl_zsock_sendto
[01:00:18.513,092] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CFUN=20
[01:00:18.586,395] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 12 bytes, +CEREG: 0

[01:00:18.596,466] <dbg> at_cmd.get_return_code: get_return_code
[01:00:18.605,102] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 0

[01:00:18.614,868] <err> modem: lte_lc_evt_handler called
[01:00:18.623,107] <dbg> modem.lte_lc_evt_handler: REG status: 0
[01:00:18.631,744] <err> modem: lte_lc_evt_handler called
[01:00:18.640,014] <dbg> at_cmd.socket_thread_fn: Writing any pending command
[01:00:18.649,719] <dbg> at_cmd.load_cmd_and_write: load_cmd_and_write
[01:00:18.658,874] <dbg> at_cmd.socket_thread_fn: Listening on socket
[01:00:19.928,680] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 12 bytes, +CSCON: 0

[01:00:19.938,751] <dbg> at_cmd.get_return_code: get_return_code
[01:00:19.947,357] <dbg> lte_lc.at_handler: +CSCON notification
[01:00:19.955,993] <err> modem: lte_lc_evt_handler called
[01:00:19.964,263] <dbg> at_cmd.socket_thread_fn: Writing any pending command
[01:00:19.973,999] <dbg> at_cmd.load_cmd_and_write: load_cmd_and_write
[01:00:19.983,154] <dbg> at_cmd.socket_thread_fn: Listening on socket
[01:00:20.021,972] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK

[01:00:20.031,372] <dbg> at_cmd.get_return_code: get_return_code
[01:00:20.039,978] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
[01:00:20.050,262] <dbg> at_cmd.socket_thread_fn: Writing any pending command
[01:00:20.059,997] <dbg> at_cmd.load_cmd_and_write: load_cmd_and_write
[01:00:20.069,458] <dbg> at_cmd.socket_thread_fn: Listening on socket
[01:00:20.078,552] <inf> modem: LTE disconnected
[01:00:20.086,608] <inf> agps_sample: Tracking: 2
[01:00:20.094,085] <dbg> agps_sample.print_satellite_stats: Searching for 3611 seconds
[01:00:20.104,583] <dbg> nrf9160_gps.print_satellite_stats: Tracking SV 2: not used, healthy
[01:00:20.116,058] <dbg> nrf9160_gps.print_satellite_stats: Tracking: 1 Using: 0 Unhealthy: 0
[01:00:20.127,166] <dbg> nrf9160_gps.print_satellite_stats: Seconds since last fix 3620
[01:00:20.138,580] <dbg> nrf9160_gps.gps_thread: Waiting for time window to operate
[01:00:20.148,803] <wrn> agps_sample: GPS_EVT_OPERATION_BLOCKED
[01:00:28.062,957] <dbg> nrf9160_gps.gps_thread: GPS has time window to operate
[01:00:28.073,089] <inf> agps_sample: GPS_EVT_OPERATION_UNBLOCKED

[Johan]

All right. I will continue ignoring the return code for now.
It could be good in future to repeat request if it fails for some reason, but I guess that could happen only with bad coverage or network issues.

[Johan]

Martin Lesund

You have another bug in supl library.
If session fails, you don't close the socket.

static int supl_start(const struct gps_agps_request request)
{
int err;
nrf_gnss_agps_data_frame_t req = {
.sv_mask_ephe = request.sv_mask_ephe,
.sv_mask_alm = request.sv_mask_alm,
.data_flags =
(request.utc ?
BIT(NRF_GNSS_AGPS_GPS_UTC_REQUEST) : 0) |
(request.klobuchar ?
BIT(NRF_GNSS_AGPS_KLOBUCHAR_REQUEST) : 0) |
(request.nequick ?
BIT(NRF_GNSS_AGPS_NEQUICK_REQUEST) : 0) |
(request.system_time_tow ?
BIT(NRF_GNSS_AGPS_SYS_TIME_AND_SV_TOW_REQUEST) : 0) |
(request.position ?
BIT(NRF_GNSS_AGPS_POSITION_REQUEST) : 0) |
(request.integrity ?
BIT(NRF_GNSS_AGPS_INTEGRITY_REQUEST) : 0),
};

err = open_supl_socket();
if (err) {
LOG_ERR("Failed to open SUPL socket");
return err;
}

LOG_INF("Starting SUPL session");

err = supl_session(&req);
if (err) {
   LOG_ERR("SUPL session failed, error: %d", err);
   return err;
}

LOG_INF("SUPL session finished successfully");

close_supl_socket();

return err;
}

[Johan]

I got problems when I wanted to open another socket, and it fails for no reason after SUPL has been used.
I'm suspecting this above.
Also it seems it's either dependent on previous socket being closed, or there is a limitation on concurrent sockets open.

[Martin Lesund]

Hi Johan,

Thanks for the feedback.
This has been fixed in nRF Connect Master branch and will be part of the soon to be released ncs v1.6.0.

Best regards,

Martin L.

[Johan]

Good! Thanks Martin.