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]

I notice the gps coordinate received is wrong as well, points to norway, and Im in south skåne sweden.

So the A-GPS lookup currently doesn't work at all.

[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

Used this page:

https://www.gps-coordinates.net/

Entered 58.51520 and 7.80606 and got position in 

[Johan]

Perhaps I mistaken how this SUPL works... but the coords seemed like something of "good data"

[Martin Lesund]

Hi Johan,

<dbg> agps.supl_logger: Lat: 5851520 Lon: 780606

These are not really coordinates, but coordinates converted into a different format expected by the modem. So that is why you cannot just use the same numbers and plot them on the gps-coordinates page.

The formulas are described here: https://github.com/nrfconnect/sdk-nrfxlib/blob/a6baa0748c486ce71918a97740ae105ba586092e/nrf_modem/include/nrf_socket.h#L1365

---

<dbg> agps.supl_logger: No location data available

This happens because of a bug in currently available SUPL libraries. The current cell ID is encoded incorrectly and the server isn't able to determine the location of the device. Because of this SUPL lib falls back to the MCC based location, which is injected here:

[00:00:15.384,246] <dbg> agps.supl_logger: MCC location info injected, MCC: 240
[00:00:15.394,226] <dbg> agps.supl_logger: Lat: 5851520 Lon: 780606
[00:00:15.403,320] <dbg> agps.supl_logger: Unc semiminor/semimajor: 119/119
[00:00:15.412,994] <dbg> agps.supl_logger: Unc altitude: 127
[00:00:15.421,386] <dbg> agps.supl_logger: Confidence: 100
[00:00:15.429,595] <dbg> agps.supl_logger: Orientation: 0

This will be fixed in the next SUPL library release which should be available shortly.

When you take the new SUPL lib into use, you will get a more accurate location. The only remaining issue is related to the data connectivity which I don't think there's a bug in the library but some bad network configurations. I suspect that you may have an overly long "rrc inactivity timer". (since that has been an issue in one of the networks in SWE before)

Best regards,

Martin L.

[Johan]

All right, seems good. Looking forward to! 
Is there a way to see the coordinate in googlemaps, ie possible to see the real coords also in the debug prints? Is it difficult conversion from modem format to google maps normal decimal format? Good for verification for example..

But then, 
even if network config is strange here, is it really an error, or just that the read ended and that's normal? Just to know, what's the important error code really, and did SUPL finish reading data? Then we are ok right? If someone wants to know if the network ended the connection socket correctly or not, might not be relevant for the supl get a-gps data right? So in practice could handle the read error internally and still return 0 (we are good, supl read correctly to end).

How about that ?

[Martin Lesund]

Hi Johan,

Johan said:

Is there a way to see the coordinate in googlemaps, ie possible to see the real coords also in the debug prints? Is it difficult conversion from modem format to google maps normal decimal format? Good for verification for example.

Not if you are talking about this output:

agps.supl_logger: Lat: 5851520 Lon: 780606

Since that is actually only for the MCC-based assistance location. That will not be printed out when we get the location from the SUPL server. The MCC-based location is constant and points roughly to the middle of Sweden in your case. (Here's that MCC based location converted into location: https://goo.gl/maps/ELB682MiMgkTUQR76) That location is always used when the device is registered to a network in Sweden. With the next SUPL library release, the location will be much more accurate and based on the LTE network cell ID. This location is used to assist GNSS to get the first fix and it doesn't have to be that accurate.

The AGPS sample prints the coordinates when it gets a GPS fix. Those can be copy-pasted to for example to Google Maps. (that means you would need to have the device outside a window to actually acquire the satellites)

You are right that we could return 0 from the library when SUPL data was received correctly but got an error when ending the SUPL session. I think we can probably fix this in a future version.

Best regards,

Martin L.

[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.