search

the-modem-distro / pinephone_modem_sdk

Pinephone Modem SDK: Tools to build your own bootloader, kernel and rootfs
GNU General Public License v3.0
597 stars 65 forks source link

eg25-manager can't set AGPS on the CFW(?) #130

Open SantX27 opened 2 years ago

SantX27 commented 2 years ago

Hi, this is more of question, since I can't prove that this works on my modem with the stock firmware. (Manjaro Unstable has some problems with ADB) So, some time ago, this commits were merged to eg25-manager: https://gitlab.com/mobian1/devices/eg25-manager/-/merge_requests/15 https://gitlab.com/mobian1/devices/eg25-manager/-/merge_requests/27 https://gitlab.com/mobian1/devices/eg25-manager/-/merge_requests/29 Which supposedly, should automagically send the modem the necessary AGPS data. However, I've never seen this automatic procedure work with the community firmware. Here's some debug data collected with journalctl | grep eg25:

lug 07 15:44:11 miria eg25-manager[3148]: Opening config file: /usr/share/eg25-manager/pine64,pinephone-1.2.toml
lug 07 15:44:11 miria eg25-manager[3148]: Starting modem...
lug 07 15:44:12 miria eg25-manager[3148]: Executed power-on/off sequence
lug 07 15:44:12 miria dbus-daemon[3143]: [system] Activating via systemd: service name='org.freedesktop.ModemManager1' unit='dbus-org.freedesktop.ModemManager1.service' requested by ':1.8' (uid=0 pid=3148 comm="/usr/bin/eg25-manager")
lug 07 15:44:12 miria eg25-manager[3148]: taking systemd sleep inhibitor
lug 07 15:44:12 miria eg25-manager[3148]: oFono vanished from D-Bus
lug 07 15:44:12 miria eg25-manager[3148]: inhibitor sleep fd is 20
lug 07 15:44:13 miria eg25-manager[3148]: ModemManager appeared on D-Bus
lug 07 15:44:33 miria eg25-manager[3148]: Response: [RDY]
lug 07 15:44:33 miria eg25-manager[3148]: taking systemd sleep inhibitor (blocking)
lug 07 15:44:33 miria eg25-manager[3148]: inhibitor block fd is 21
lug 07 15:44:33 miria eg25-manager[3148]: Response: [+CPIN: READY]
lug 07 15:44:33 miria eg25-manager[3148]: Executed soft sleep sequence
lug 07 15:44:33 miria eg25-manager[3148]: Response: [+QUSIM: 1]
lug 07 15:44:33 miria eg25-manager[3148]: Executed soft sleep sequence
lug 07 15:44:34 miria eg25-manager[3148]: Response: [+CFUN: 4]
lug 07 15:44:34 miria eg25-manager[3148]: Executed soft sleep sequence
lug 07 15:44:34 miria eg25-manager[3148]: Response: [+QIND: SMS DONE]
lug 07 15:44:34 miria eg25-manager[3148]: Executed soft sleep sequence
lug 07 15:44:35 miria eg25-manager[3148]: Response: [+QIND: PB DONE]
lug 07 15:44:35 miria eg25-manager[3148]: Executed soft sleep sequence
lug 07 15:44:41 miria eg25-manager[3148]: Rescheduling upload since modem isn't online yet, in 30s
lug 07 15:44:45 miria eg25-manager[3148]: ModemManager object `/org/freedesktop/ModemManager1/Modem/0' added
lug 07 15:44:45 miria eg25-manager[3148]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Modem3gpp.ProfileManager' found on object `/org/freedesktop/ModemManager1/Modem/0'
lug 07 15:44:45 miria eg25-manager[3148]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Firmware' found on object `/org/freedesktop/ModemManager1/Modem/0'
lug 07 15:44:45 miria eg25-manager[3148]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Modem3gpp' found on object `/org/freedesktop/ModemManager1/Modem/0'
lug 07 15:44:45 miria eg25-manager[3148]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Time' found on object `/org/freedesktop/ModemManager1/Modem/0'
lug 07 15:44:45 miria eg25-manager[3148]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Voice' found on object `/org/freedesktop/ModemManager1/Modem/0'
lug 07 15:44:45 miria eg25-manager[3148]: ModemManager interface `org.freedesktop.ModemManager1.Modem' found on object `/org/freedesktop/ModemManager1/Modem/0'
lug 07 15:44:45 miria eg25-manager[3148]: Adding new modem `/org/freedesktop/ModemManager1/Modem/0'
lug 07 15:44:45 miria eg25-manager[3148]: Executed soft wake sequence
lug 07 15:44:45 miria eg25-manager[3148]: Successfully sent command: AT+QGMR
lug 07 15:44:45 miria eg25-manager[3148]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Messaging' found on object `/org/freedesktop/ModemManager1/Modem/0'
lug 07 15:44:45 miria eg25-manager[3148]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Modem3gpp.Ussd' found on object `/org/freedesktop/ModemManager1/Modem/0'
lug 07 15:44:45 miria eg25-manager[3148]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Signal' found on object `/org/freedesktop/ModemManager1/Modem/0'
lug 07 15:44:45 miria eg25-manager[3148]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Location' found on object `/org/freedesktop/ModemManager1/Modem/0'
lug 07 15:44:45 miria eg25-manager[3148]: Adding new modem with location capabilities `/org/freedesktop/ModemManager1/Modem/0'
lug 07 15:44:45 miria eg25-manager[3148]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Simple' found on object `/org/freedesktop/ModemManager1/Modem/0'
lug 07 15:44:45 miria eg25-manager[3148]: Response: [0.6.7\r\n\r\nOK]
lug 07 15:44:45 miria eg25-manager[3148]: Successfully sent command: AT+QDAI?
lug 07 15:44:45 miria eg25-manager[3148]: Response: [OK]
lug 07 15:44:45 miria eg25-manager[3148]: Got a different result than expected, changing value...
lug 07 15:44:45 miria eg25-manager[3148]: Expected: [1,1,0,1,0,0,1,1]
lug 07 15:44:45 miria eg25-manager[3148]: Successfully sent command: AT+QDAI=1,1,0,1,0,0,1,1
lug 07 15:44:45 miria eg25-manager[3148]: Response: [OK]
lug 07 15:44:45 miria eg25-manager[3148]: Successfully sent command: AT+QCFG="risignaltype"
lug 07 15:44:45 miria eg25-manager[3148]: Response: [+QCFG: "risignaltype","physical"\r\n\r\nOK]
lug 07 15:44:45 miria eg25-manager[3148]: Successfully sent command: AT+QCFG="ims"
lug 07 15:44:45 miria eg25-manager[3148]: Response: [+QCFG: "ims",1,0\r\n\r\nOK]
lug 07 15:44:45 miria eg25-manager[3148]: Successfully sent command: AT+QCFG="apready"
lug 07 15:44:45 miria eg25-manager[3148]: Response: [+QCFG: "apready",1,0,500\r\n\r\nOK]
lug 07 15:44:45 miria eg25-manager[3148]: Successfully sent command: AT+QCFG="urc/ri/ring"
lug 07 15:44:45 miria eg25-manager[3148]: Response: [+QCFG: "urc/ri/ring","pulse",120,1000,5000,"off",1\r\n\r\nOK]
lug 07 15:44:45 miria eg25-manager[3148]: Successfully sent command: AT+QCFG="urc/ri/smsincoming"
lug 07 15:44:45 miria eg25-manager[3148]: Response: [+QCFG: "urc/ri/smsincoming","pulse",120,1\r\n\r\nOK]
lug 07 15:44:45 miria eg25-manager[3148]: Successfully sent command: AT+QCFG="urc/ri/other"
lug 07 15:44:45 miria eg25-manager[3148]: Response: [+QCFG: "urc/ri/other","off",1,1\r\n\r\nOK]
lug 07 15:44:45 miria eg25-manager[3148]: Successfully sent command: AT+QCFG="urc/delay"
lug 07 15:44:45 miria eg25-manager[3148]: Response: [+QCFG: "urc/delay",0\r\n\r\nOK]
lug 07 15:44:45 miria eg25-manager[3148]: Successfully sent command: AT+QCFG="urc/cache"
lug 07 15:44:45 miria eg25-manager[3148]: Response: [+QCFG: "urc/cache",0\r\n\r\nOK]
lug 07 15:44:45 miria eg25-manager[3148]: Successfully sent command: AT+QCFG="urc/ri/pin"
lug 07 15:44:45 miria eg25-manager[3148]: Response: [+QCFG: "urc/ri/pin",uart_ri\r\n\r\nOK]
lug 07 15:44:45 miria eg25-manager[3148]: Successfully sent command: AT+QURCCFG="urcport"
lug 07 15:44:45 miria eg25-manager[3148]: Response: [+QURCCFG: "urcport","all"\r\n\r\nOK]
lug 07 15:44:45 miria eg25-manager[3148]: Successfully sent command: AT+QSCLK=1
lug 07 15:44:45 miria eg25-manager[3148]: Response: [OK]
lug 07 15:44:45 miria eg25-manager[3148]: Successfully sent command: AT+QGPSXTRA?
lug 07 15:44:45 miria eg25-manager[3148]: Response: [+QGPSXTRA: 1\r\n\r\nOK]
lug 07 15:44:45 miria eg25-manager[3148]: Successfully sent command: AT+QGPSCFG="gnssconfig"
lug 07 15:44:45 miria eg25-manager[3148]: Response: [+QGPSCFG: "gnssconfig",4\r\n\r\nOK]
lug 07 15:44:45 miria eg25-manager[3148]: Successfully sent command: AT+QGPSCFG="odpcontrol"
lug 07 15:44:45 miria eg25-manager[3148]: Response: [+QGPSCFG: "odpcontrol",0\r\n\r\nOK]
lug 07 15:44:45 miria eg25-manager[3148]: Successfully sent command: AT+QGPSCFG="dpoenable"
lug 07 15:44:45 miria eg25-manager[3148]: Response: [+QGPSCFG: "dpoenable",1\r\n\r\nOK]
lug 07 15:44:45 miria eg25-manager[3148]: Successfully sent command: AT+QGPSCFG="gpsnmeatype"
lug 07 15:44:45 miria eg25-manager[3148]: Response: [+QGPSCFG: "gpsnmeatype",31\r\n\r\nOK]
lug 07 15:44:45 miria eg25-manager[3148]: Successfully sent command: AT+QGPSCFG="glonassnmeatype"
lug 07 15:44:46 miria eg25-manager[3148]: Response: [+QGPSCFG: "glonassnmeatype",7\r\n\r\nOK]
lug 07 15:44:46 miria eg25-manager[3148]: Successfully sent command: AT+QGPSCFG="galileonmeatype"
lug 07 15:44:46 miria eg25-manager[3148]: Response: [+QGPSCFG: "galileonmeatype",0\r\n\r\nOK]
lug 07 15:44:46 miria eg25-manager[3148]: Successfully sent command: AT+QGPSCFG="beidounmeatype"
lug 07 15:44:46 miria eg25-manager[3148]: Response: [+QGPSCFG: "beidounmeatype",0\r\n\r\nOK]
lug 07 15:44:46 miria eg25-manager[3148]: Successfully sent command: AT+QGPSCFG="autogps"
lug 07 15:44:46 miria eg25-manager[3148]: Response: [+QGPSCFG: "autogps",0\r\n\r\nOK]
lug 07 15:44:46 miria eg25-manager[3148]: Successfully sent command: AT+QCFG="fast/poweroff"
lug 07 15:44:46 miria eg25-manager[3148]: Response: [OK]
lug 07 15:44:46 miria eg25-manager[3148]: Got a different result than expected, changing value...
lug 07 15:44:46 miria eg25-manager[3148]: Expected: [0]
lug 07 15:44:46 miria eg25-manager[3148]: Successfully sent command: AT+QCFG="fast/poweroff",0
lug 07 15:44:46 miria eg25-manager[3148]: Response: [OK]
lug 07 15:44:46 miria eg25-manager[3148]: Successfully sent command: AT+QCFG="sleepind/level"
lug 07 15:44:46 miria eg25-manager[3148]: Response: [+QCFG: "sleepind/level",0\r\n\r\nOK]
lug 07 15:44:46 miria eg25-manager[3148]: Successfully sent command: AT+QCFG="wakeupin/level"
lug 07 15:44:46 miria eg25-manager[3148]: Response: [+QCFG: "wakeupin/level",0,0\r\n\r\nOK]
lug 07 15:44:46 miria eg25-manager[3148]: Successfully sent command: AT+QCFG="ApRstLevel"
lug 07 15:44:46 miria eg25-manager[3148]: Response: [OK]
lug 07 15:44:46 miria eg25-manager[3148]: Got a different result than expected, changing value...
lug 07 15:44:46 miria eg25-manager[3148]: Expected: [1]
lug 07 15:44:46 miria eg25-manager[3148]: Successfully sent command: AT+QCFG="ApRstLevel",1
lug 07 15:44:46 miria eg25-manager[3148]: Response: [OK]
lug 07 15:44:46 miria eg25-manager[3148]: Successfully sent command: AT+QCFG="ModemRstLevel"
lug 07 15:44:46 miria eg25-manager[3148]: Response: [OK]
lug 07 15:44:46 miria eg25-manager[3148]: Got a different result than expected, changing value...
lug 07 15:44:46 miria eg25-manager[3148]: Expected: [1]
lug 07 15:44:46 miria eg25-manager[3148]: Successfully sent command: AT+QCFG="ModemRstLevel",1
lug 07 15:44:46 miria eg25-manager[3148]: Response: [OK]
lug 07 15:44:46 miria eg25-manager[3148]: Executed soft sleep sequence
lug 07 15:45:11 miria eg25-manager[3148]: GNSS assistance upload started...
lug 07 15:45:11 miria eg25-manager[3148]: GNSS assistance upload step (1/9): fetching assistance data
lug 07 15:45:12 miria eg25-manager[3148]: Fetching GNSS assistance data from https://xtrapath4.izatcloud.net/xtra2.bin was successful
lug 07 15:45:12 miria eg25-manager[3148]: GNSS assistance upload step (2/9): disabling GNSS engine through ModemManager
lug 07 15:45:12 miria eg25-manager[3148]: Unable to disable GNSS engine through ModemManager: GDBus.Error:org.freedesktop.ModemManager1.Error.Core.WrongState: Cannot setup location: device not yet enabled
lug 07 15:45:12 miria eg25-manager[3148]: GNSS assistance upload step (3/9): disabling GNSS engine through AT+QGPS
lug 07 15:45:12 miria eg25-manager[3148]: Executed soft wake sequence
lug 07 15:45:12 miria eg25-manager[3148]: Successfully sent command: AT+QGPS?
lug 07 15:46:33 miria eg25-manager[3148]: Modem is up for 120 seconds and fully ready
lug 07 15:46:33 miria eg25-manager[3148]: dropping systemd sleep block inhibitor

Can somebody confirm this issue? I'm a bit afraid of escalating this to the Mobian guys. Again, sorry if I didn't test more.

k8ieone commented 2 years ago

I have that same exact behavior with 0.6.7 and Manjaro Unstable.

SantX27 commented 2 years ago

I have tested the stock modem firmware and the AGPS procedure works there, getting through all 9 upload steps.

Biktorgj commented 2 years ago

Has anyone tried with 0.6.8? Seems to work for me... If it doesn't, can you post eg25manager log?

SantX27 commented 2 years ago

I have installed 0.6.8 yesterday, here is the log starting from today, when I turned on the phone.

lug 28 10:48:13 miria eg25-manager[2962]: Opening config file: /usr/share/eg25-manager/pine64,pinephone-1.2.toml
lug 28 10:48:13 miria eg25-manager[2962]: Starting modem...
lug 28 10:48:14 miria eg25-manager[2962]: Executed power-on/off sequence
lug 28 10:48:14 miria eg25-manager[2962]: taking systemd sleep inhibitor
lug 28 10:48:14 miria eg25-manager[2962]: oFono vanished from D-Bus
lug 28 10:48:14 miria eg25-manager[2962]: ModemManager appeared on D-Bus
lug 28 10:48:14 miria eg25-manager[2962]: inhibitor sleep fd is 21
lug 28 10:48:34 miria eg25-manager[2962]: Response: [RDY]
lug 28 10:48:34 miria eg25-manager[2962]: taking systemd sleep inhibitor (blocking)
lug 28 10:48:34 miria eg25-manager[2962]: Response: [+CPIN: READY]
lug 28 10:48:34 miria eg25-manager[2962]: Executed soft sleep sequence
lug 28 10:48:34 miria eg25-manager[2962]: inhibitor block fd is 20
lug 28 10:48:34 miria eg25-manager[2962]: Response: [+QUSIM: 1]
lug 28 10:48:34 miria eg25-manager[2962]: Executed soft sleep sequence
lug 28 10:48:35 miria eg25-manager[2962]: Response: [+CFUN: 4]
lug 28 10:48:35 miria eg25-manager[2962]: Executed soft sleep sequence
lug 28 10:48:35 miria eg25-manager[2962]: Response: [+QIND: SMS DONE]
lug 28 10:48:35 miria eg25-manager[2962]: Executed soft sleep sequence
lug 28 10:48:36 miria eg25-manager[2962]: Response: [+QIND: PB DONE]
lug 28 10:48:36 miria eg25-manager[2962]: Executed soft sleep sequence
lug 28 10:48:43 miria eg25-manager[2962]: Rescheduling upload since modem isn't online yet, in 30s
lug 28 10:48:46 miria eg25-manager[2962]: ModemManager object `/org/freedesktop/ModemManager1/Modem/0' added
lug 28 10:48:46 miria eg25-manager[2962]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Modem3gpp.ProfileManager' found on object `/org/freedesktop/ModemManager1/Modem/0'
lug 28 10:48:46 miria eg25-manager[2962]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Firmware' found on object `/org/freedesktop/ModemManager1/Modem/0'
lug 28 10:48:46 miria eg25-manager[2962]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Modem3gpp' found on object `/org/freedesktop/ModemManager1/Modem/0'
lug 28 10:48:46 miria eg25-manager[2962]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Time' found on object `/org/freedesktop/ModemManager1/Modem/0'
lug 28 10:48:46 miria eg25-manager[2962]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Voice' found on object `/org/freedesktop/ModemManager1/Modem/0'
lug 28 10:48:46 miria eg25-manager[2962]: ModemManager interface `org.freedesktop.ModemManager1.Modem' found on object `/org/freedesktop/ModemManager1/Modem/0'
lug 28 10:48:46 miria eg25-manager[2962]: Adding new modem `/org/freedesktop/ModemManager1/Modem/0'
lug 28 10:48:46 miria eg25-manager[2962]: Executed soft wake sequence
lug 28 10:48:46 miria eg25-manager[2962]: Successfully sent command: AT+QGMR
lug 28 10:48:46 miria eg25-manager[2962]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Messaging' found on object `/org/freedesktop/ModemManager1/Modem/0'
lug 28 10:48:46 miria eg25-manager[2962]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Modem3gpp.Ussd' found on object `/org/freedesktop/ModemManager1/Modem/0'
lug 28 10:48:46 miria eg25-manager[2962]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Signal' found on object `/org/freedesktop/ModemManager1/Modem/0'
lug 28 10:48:46 miria eg25-manager[2962]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Location' found on object `/org/freedesktop/ModemManager1/Modem/0'
lug 28 10:48:46 miria eg25-manager[2962]: Adding new modem with location capabilities `/org/freedesktop/ModemManager1/Modem/0'
lug 28 10:48:46 miria eg25-manager[2962]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Simple' found on object `/org/freedesktop/ModemManager1/Modem/0'
lug 28 10:48:46 miria eg25-manager[2962]: Response: [0.6.8\r\n\r\nOK]
lug 28 10:48:46 miria eg25-manager[2962]: Successfully sent command: AT+QDAI?
lug 28 10:48:46 miria eg25-manager[2962]: Response: [OK]
lug 28 10:48:46 miria eg25-manager[2962]: Got a different result than expected, changing value...
lug 28 10:48:46 miria eg25-manager[2962]: Expected: [1,1,0,1,0,0,1,1]
lug 28 10:48:46 miria eg25-manager[2962]: Successfully sent command: AT+QDAI=1,1,0,1,0,0,1,1
lug 28 10:48:46 miria eg25-manager[2962]: Response: [OK]
lug 28 10:48:46 miria eg25-manager[2962]: Successfully sent command: AT+QCFG="risignaltype"
lug 28 10:48:46 miria eg25-manager[2962]: Response: [+QCFG: "risignaltype","physical"\r\n\r\nOK]
lug 28 10:48:46 miria eg25-manager[2962]: Successfully sent command: AT+QCFG="ims"
lug 28 10:48:46 miria eg25-manager[2962]: Response: [+QCFG: "ims",1,0\r\n\r\nOK]
lug 28 10:48:46 miria eg25-manager[2962]: Successfully sent command: AT+QCFG="apready"
lug 28 10:48:46 miria eg25-manager[2962]: Response: [+QCFG: "apready",1,0,500\r\n\r\nOK]
lug 28 10:48:46 miria eg25-manager[2962]: Successfully sent command: AT+QCFG="urc/ri/ring"
lug 28 10:48:46 miria eg25-manager[2962]: Response: [+QCFG: "urc/ri/ring","pulse",120,1000,5000,"off",1\r\n\r\nOK]
lug 28 10:48:46 miria eg25-manager[2962]: Successfully sent command: AT+QCFG="urc/ri/smsincoming"
lug 28 10:48:47 miria eg25-manager[2962]: Response: [+QCFG: "urc/ri/smsincoming","pulse",120,1\r\n\r\nOK]
lug 28 10:48:47 miria eg25-manager[2962]: Successfully sent command: AT+QCFG="urc/ri/other"
lug 28 10:48:47 miria eg25-manager[2962]: Response: [+QCFG: "urc/ri/other","off",1,1\r\n\r\nOK]
lug 28 10:48:47 miria eg25-manager[2962]: Successfully sent command: AT+QCFG="urc/delay"
lug 28 10:48:47 miria eg25-manager[2962]: Response: [+QCFG: "urc/delay",0\r\n\r\nOK]
lug 28 10:48:47 miria eg25-manager[2962]: Successfully sent command: AT+QCFG="urc/cache"
lug 28 10:48:47 miria eg25-manager[2962]: Response: [+QCFG: "urc/cache",0\r\n\r\nOK]
lug 28 10:48:47 miria eg25-manager[2962]: Successfully sent command: AT+QCFG="urc/ri/pin"
lug 28 10:48:47 miria eg25-manager[2962]: Response: [+QCFG: "urc/ri/pin",uart_ri\r\n\r\nOK]
lug 28 10:48:47 miria eg25-manager[2962]: Successfully sent command: AT+QURCCFG="urcport"
lug 28 10:48:47 miria eg25-manager[2962]: Response: [+QURCCFG: "urcport","all"\r\n\r\nOK]
lug 28 10:48:47 miria eg25-manager[2962]: Successfully sent command: AT+QSCLK=1
lug 28 10:48:47 miria eg25-manager[2962]: Response: [OK]
lug 28 10:48:47 miria eg25-manager[2962]: Successfully sent command: AT+QGPSXTRA?
lug 28 10:48:47 miria eg25-manager[2962]: Response: [+QGPSXTRA: 1\r\n\r\nOK]
lug 28 10:48:47 miria eg25-manager[2962]: Successfully sent command: AT+QGPSCFG="gnssconfig"
lug 28 10:48:47 miria eg25-manager[2962]: Response: [+QGPSCFG: "gnssconfig",4\r\n\r\nOK]
lug 28 10:48:47 miria eg25-manager[2962]: Successfully sent command: AT+QGPSCFG="odpcontrol"
lug 28 10:48:47 miria eg25-manager[2962]: Response: [+QGPSCFG: "odpcontrol",0\r\n\r\nOK]
lug 28 10:48:47 miria eg25-manager[2962]: Successfully sent command: AT+QGPSCFG="dpoenable"
lug 28 10:48:47 miria eg25-manager[2962]: Response: [+QGPSCFG: "dpoenable",1\r\n\r\nOK]
lug 28 10:48:47 miria eg25-manager[2962]: Successfully sent command: AT+QGPSCFG="gpsnmeatype"
lug 28 10:48:47 miria eg25-manager[2962]: Response: [+QGPSCFG: "gpsnmeatype",31\r\n\r\nOK]
lug 28 10:48:47 miria eg25-manager[2962]: Successfully sent command: AT+QGPSCFG="glonassnmeatype"
lug 28 10:48:47 miria eg25-manager[2962]: Response: [+QGPSCFG: "glonassnmeatype",7\r\n\r\nOK]
lug 28 10:48:47 miria eg25-manager[2962]: Successfully sent command: AT+QGPSCFG="galileonmeatype"
lug 28 10:48:47 miria eg25-manager[2962]: Response: [+QGPSCFG: "galileonmeatype",0\r\n\r\nOK]
lug 28 10:48:47 miria eg25-manager[2962]: Successfully sent command: AT+QGPSCFG="beidounmeatype"
lug 28 10:48:47 miria eg25-manager[2962]: Response: [+QGPSCFG: "beidounmeatype",0\r\n\r\nOK]
lug 28 10:48:47 miria eg25-manager[2962]: Successfully sent command: AT+QGPSCFG="autogps"
lug 28 10:48:47 miria eg25-manager[2962]: Response: [+QGPSCFG: "autogps",0\r\n\r\nOK]
lug 28 10:48:47 miria eg25-manager[2962]: Successfully sent command: AT+QCFG="fast/poweroff"
lug 28 10:48:47 miria eg25-manager[2962]: Response: [OK]
lug 28 10:48:47 miria eg25-manager[2962]: Got a different result than expected, changing value...
lug 28 10:48:47 miria eg25-manager[2962]: Expected: [0]
lug 28 10:48:47 miria eg25-manager[2962]: Successfully sent command: AT+QCFG="fast/poweroff",0
lug 28 10:48:47 miria eg25-manager[2962]: Response: [OK]
lug 28 10:48:47 miria eg25-manager[2962]: Successfully sent command: AT+QCFG="sleepind/level"
lug 28 10:48:47 miria eg25-manager[2962]: Response: [+QCFG: "sleepind/level",0\r\n\r\nOK]
lug 28 10:48:47 miria eg25-manager[2962]: Successfully sent command: AT+QCFG="wakeupin/level"
lug 28 10:48:47 miria eg25-manager[2962]: Response: [+QCFG: "wakeupin/level",0,0\r\n\r\nOK]
lug 28 10:48:47 miria eg25-manager[2962]: Successfully sent command: AT+QCFG="ApRstLevel"
lug 28 10:48:47 miria eg25-manager[2962]: Response: [OK]
lug 28 10:48:47 miria eg25-manager[2962]: Got a different result than expected, changing value...
lug 28 10:48:47 miria eg25-manager[2962]: Expected: [1]
lug 28 10:48:47 miria eg25-manager[2962]: Successfully sent command: AT+QCFG="ApRstLevel",1
lug 28 10:48:47 miria eg25-manager[2962]: Response: [OK]
lug 28 10:48:47 miria eg25-manager[2962]: Successfully sent command: AT+QCFG="ModemRstLevel"
lug 28 10:48:47 miria eg25-manager[2962]: Response: [OK]
lug 28 10:48:47 miria eg25-manager[2962]: Got a different result than expected, changing value...
lug 28 10:48:47 miria eg25-manager[2962]: Expected: [1]
lug 28 10:48:47 miria eg25-manager[2962]: Successfully sent command: AT+QCFG="ModemRstLevel",1
lug 28 10:48:47 miria eg25-manager[2962]: Response: [OK]
lug 28 10:48:47 miria eg25-manager[2962]: Executed soft sleep sequence
lug 28 10:49:13 miria eg25-manager[2962]: GNSS assistance upload started...
lug 28 10:49:13 miria eg25-manager[2962]: GNSS assistance upload step (1/9): fetching assistance data
lug 28 10:49:13 miria eg25-manager[2962]: Fetching GNSS assistance data from https://xtrapath4.izatcloud.net/xtra2.bin was successful
lug 28 10:49:13 miria eg25-manager[2962]: GNSS assistance upload step (2/9): disabling GNSS engine through ModemManager
lug 28 10:49:13 miria eg25-manager[2962]: GNSS assistance upload step (3/9): disabling GNSS engine through AT+QGPS
lug 28 10:49:13 miria eg25-manager[2962]: Executed soft wake sequence
lug 28 10:49:13 miria eg25-manager[2962]: Successfully sent command: AT+QGPS?
lug 28 10:50:35 miria eg25-manager[2962]: Modem is up for 120 seconds and fully ready
lug 28 10:50:35 miria eg25-manager[2962]: dropping systemd sleep block inhibitor
lug 28 10:58:46 miria eg25-manager[2962]: Response: [+QGPSURC: "xtradataexpire",0,"2022/07/27,02:00:00"]
lug 28 10:58:46 miria eg25-manager[2962]: Executed soft sleep sequence
lug 28 11:08:46 miria eg25-manager[2962]: Response: [+QGPSURC: "xtradataexpire",0,"2022/07/27,02:00:00"]
lug 28 11:08:46 miria eg25-manager[2962]: GNSS assistance data upload already in process (3/9)
lug 28 11:22:44 miria eg25-manager[2962]: Response: [RING]
lug 28 11:22:44 miria eg25-manager[2962]: Executed soft sleep sequence
lug 28 11:22:50 miria eg25-manager[2962]: Response: [RING]
lug 28 11:22:50 miria eg25-manager[2962]: Executed soft sleep sequence
lug 28 11:22:51 miria eg25-manager[2962]: Response: [NO CARRIER]
lug 28 11:22:51 miria eg25-manager[2962]: Executed soft sleep sequence
lug 28 13:02:57 miria eg25-manager[2962]: Response: [RING]
lug 28 13:02:57 miria eg25-manager[2962]: Executed soft sleep sequence
lug 28 13:03:03 miria eg25-manager[2962]: Response: [RING]
lug 28 13:03:03 miria eg25-manager[2962]: Executed soft sleep sequence
lug 28 13:03:09 miria eg25-manager[2962]: Response: [RING]
lug 28 13:03:09 miria eg25-manager[2962]: Executed soft sleep sequence
lug 28 15:58:22 miria eg25-manager[2962]: ModemManager object `/org/freedesktop/ModemManager1/Modem/0' removed
lug 28 15:58:22 miria eg25-manager[2962]: Lost modem, resetting...
lug 28 15:58:26 miria eg25-manager[2962]: Trying to reset modem with USB ID '2-1'
lug 28 15:58:26 miria eg25-manager[2962]: Successfully reset modem's USB connection
lug 28 15:58:40 miria eg25-manager[2962]: ModemManager object `/org/freedesktop/ModemManager1/Modem/2' added
lug 28 15:58:40 miria eg25-manager[2962]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Modem3gpp.ProfileManager' found on object `/org/freedesktop/ModemManager1/Modem/2'
lug 28 15:58:40 miria eg25-manager[2962]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Firmware' found on object `/org/freedesktop/ModemManager1/Modem/2'
lug 28 15:58:40 miria eg25-manager[2962]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Modem3gpp' found on object `/org/freedesktop/ModemManager1/Modem/2'
lug 28 15:58:40 miria eg25-manager[2962]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Time' found on object `/org/freedesktop/ModemManager1/Modem/2'
lug 28 15:58:40 miria eg25-manager[2962]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Voice' found on object `/org/freedesktop/ModemManager1/Modem/2'
lug 28 15:58:40 miria eg25-manager[2962]: ModemManager interface `org.freedesktop.ModemManager1.Modem' found on object `/org/freedesktop/ModemManager1/Modem/2'
lug 28 15:58:40 miria eg25-manager[2962]: Adding new modem `/org/freedesktop/ModemManager1/Modem/2'
lug 28 15:58:40 miria eg25-manager[2962]: Executed soft sleep sequence
lug 28 15:58:40 miria eg25-manager[2962]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Messaging' found on object `/org/freedesktop/ModemManager1/Modem/2'
lug 28 15:58:40 miria eg25-manager[2962]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Modem3gpp.Ussd' found on object `/org/freedesktop/ModemManager1/Modem/2'
lug 28 15:58:40 miria eg25-manager[2962]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Signal' found on object `/org/freedesktop/ModemManager1/Modem/2'
lug 28 15:58:40 miria eg25-manager[2962]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Location' found on object `/org/freedesktop/ModemManager1/Modem/2'
lug 28 15:58:40 miria eg25-manager[2962]: Adding new modem with location capabilities `/org/freedesktop/ModemManager1/Modem/2'
lug 28 15:58:40 miria eg25-manager[2962]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Simple' found on object `/org/freedesktop/ModemManager1/Modem/2'
lug 28 16:08:39 miria eg25-manager[2962]: Response: [+QGPSURC: "xtradataexpire",0,"2022/07/27,02:00:00"]
lug 28 16:08:39 miria eg25-manager[2962]: GNSS assistance data upload already in process (3/9)
lug 28 16:18:39 miria eg25-manager[2962]: Response: [+QGPSURC: "xtradataexpire",0,"2022/07/27,02:00:00"]
lug 28 16:18:39 miria eg25-manager[2962]: GNSS assistance data upload already in process (3/9)
Biktorgj commented 2 years ago

Stupid question, but did you set up the udev rules as recommended in the settings doc?

Does this only happen in Manjaro?

SantX27 commented 2 years ago

I did set it up as described in SETTINGS.md, but it got overwrote by the latest eg25-manager update, so I'm back at the default ruleset. 

cat /usr/lib/udev/rules.d/80-modem-eg25.rules 

ACTION!="add", GOTO="eg25_end"
SUBSYSTEM!="usb", GOTO="eg25_end"
DRIVER!="usb", GOTO="eg25_end"
ENV{DEVTYPE}!="usb_device", GOTO="eg25_end"

# Default attributes values
ATTRS{idVendor}=="2c7c", ATTRS{idProduct}=="0125", ATTR{power/control}="auto"
ATTRS{idVendor}=="2c7c", ATTRS{idProduct}=="0125", ATTR{power/autosuspend_delay_ms}="3000"
ATTRS{idVendor}=="2c7c", ATTRS{idProduct}=="0125", ATTR{power/wakeup}="enabled"
ATTRS{idVendor}=="2c7c", ATTRS{idProduct}=="0125", ATTR{power/persist}="0"

# If running the stock firmware, stop processing here
ATTRS{serial}!="community_fw", GOTO="eg25_end"

# power/control needs to be "on" for the community-maintained firmware
ATTRS{idVendor}=="2c7c", ATTRS{idProduct}=="0125", ATTR{power/control}="on"

# Special trick for the PinePhone Pro: set power/persist to 1 *only* with the community FW
# We can identify the PPP by looking for the string "pinephone-pro" in the device tree "compatible" property
ATTRS{idVendor}=="2c7c", ATTRS{idProduct}=="0125", PROGRAM=="/bin/grep pine64,pinephone-pro /proc/device-tree/compatible", ATTR{power/persist}="1"

LABEL="eg25_end"

As for other distros, I have tried on postmarketOS a while ago and the issue was still there, I'm going to flash an SD with it and see if it happens there as well.

SantX27 commented 2 years ago

I have now tested postmarketOS, enabling logs as described in https://wiki.postmarketos.org/wiki/Modem#Getting_eg25-manager_logs and setting the udev rules as described in SETTINGS.md

The upload works, but not on the first time, I need to restart eg25-manager to make it go through. Maybe eg25-manager never receives the response to AT+QGPS?, stalling the upload process.

I will try restarting eg25-manager on Manjaro, maybe it works there too. 

** Message: 08:32:12.512: Opening config file: /usr/share/eg25-manager/pine64,pinephone-1.2.toml
** Message: 08:32:12.542: Starting modem...
** Message: 08:32:13.642: Executed power-on/off sequence
** Message: 08:32:13.645: ModemManager vanished from D-Bus
** Message: 08:32:13.645: oFono vanished from D-Bus
** Message: 08:32:14.080: ModemManager appeared on D-Bus
** Message: 08:32:15.040: taking systemd sleep inhibitor
** Message: 08:32:15.059: inhibitor sleep fd is 19
** Message: 08:32:35.064: Response: [RDY]
** Message: 08:32:35.065: taking systemd sleep inhibitor (blocking)
** Message: 08:32:35.082: inhibitor block fd is 20
** Message: 08:32:35.103: Response: [+CPIN: READY]
** Message: 08:32:35.103: Executed soft sleep sequence
** Message: 08:32:35.117: Response: [+QUSIM: 1]
** Message: 08:32:35.117: Executed soft sleep sequence
** Message: 08:32:35.446: Response: [+CFUN: 4]
** Message: 08:32:35.447: Executed soft sleep sequence
** Message: 08:32:35.668: Response: [+QIND: SMS DONE]
** Message: 08:32:35.668: Executed soft sleep sequence
** Message: 08:32:36.898: Response: [+QIND: PB DONE]
** Message: 08:32:36.898: Executed soft sleep sequence
** Message: 08:32:42.917: Rescheduling upload since modem isn't online yet, in 30s
** Message: 08:32:46.548: ModemManager object `/org/freedesktop/ModemManager1/Modem/0' added
** Message: 08:32:46.549: ModemManager interface `org.freedesktop.ModemManager1.Modem.Modem3gpp.ProfileManager' found on object `/org/freedesktop/ModemManager1/Modem/0'
** Message: 08:32:46.549: ModemManager interface `org.freedesktop.ModemManager1.Modem.Firmware' found on object `/org/freedesktop/ModemManager1/Modem/0'
** Message: 08:32:46.549: ModemManager interface `org.freedesktop.ModemManager1.Modem.Modem3gpp' found on object `/org/freedesktop/ModemManager1/Modem/0'
** Message: 08:32:46.549: ModemManager interface `org.freedesktop.ModemManager1.Modem.Time' found on object `/org/freedesktop/ModemManager1/Modem/0'
** Message: 08:32:46.549: ModemManager interface `org.freedesktop.ModemManager1.Modem.Voice' found on object `/org/freedesktop/ModemManager1/Modem/0'
** Message: 08:32:46.549: ModemManager interface `org.freedesktop.ModemManager1.Modem' found on object `/org/freedesktop/ModemManager1/Modem/0'
** Message: 08:32:46.549: Adding new modem `/org/freedesktop/ModemManager1/Modem/0'
** Message: 08:32:46.750: Executed soft wake sequence
** Message: 08:32:46.750: Successfully sent command: AT+QGMR
** Message: 08:32:46.750: ModemManager interface `org.freedesktop.ModemManager1.Modem.Messaging' found on object `/org/freedesktop/ModemManager1/Modem/0'
** Message: 08:32:46.750: ModemManager interface `org.freedesktop.ModemManager1.Modem.Modem3gpp.Ussd' found on object `/org/freedesktop/ModemManager1/Modem/0'
** Message: 08:32:46.750: ModemManager interface `org.freedesktop.ModemManager1.Modem.Signal' found on object `/org/freedesktop/ModemManager1/Modem/0'
** Message: 08:32:46.751: ModemManager interface `org.freedesktop.ModemManager1.Modem.Location' found on object `/org/freedesktop/ModemManager1/Modem/0'
** Message: 08:32:46.751: Adding new modem with location capabilities `/org/freedesktop/ModemManager1/Modem/0'
** Message: 08:32:46.751: ModemManager interface `org.freedesktop.ModemManager1.Modem.Simple' found on object `/org/freedesktop/ModemManager1/Modem/0'
** Message: 08:32:46.768: Response: [0.6.8\r\n\r\nOK]
** Message: 08:32:46.768: Successfully sent command: AT+QDAI?
** Message: 08:32:46.786: Response: [OK]
** Message: 08:32:46.786: Got a different result than expected, changing value...
** Message: 08:32:46.786: Expected: [1,1,0,1,0,0,1,1]
Response: [OK]
** Message: 08:32:46.786: Successfully sent command: AT+QDAI=1,1,0,1,0,0,1,1
** Message: 08:32:46.805: Response: [OK]
** Message: 08:32:46.806: Successfully sent command: AT+QCFG="risignaltype"
** Message: 08:32:46.833: Response: [+QCFG: "risignaltype","physical"\r\n\r\nOK]
** Message: 08:32:46.834: Successfully sent command: AT+QCFG="ims"
** Message: 08:32:46.849: Response: [+QCFG: "ims",1,0\r\n\r\nOK]
** Message: 08:32:46.850: Successfully sent command: AT+QCFG="apready"
** Message: 08:32:46.876: Response: [+QCFG: "apready",1,0,500\r\n\r\nOK]
** Message: 08:32:46.877: Successfully sent command: AT+QCFG="urc/ri/ring"
** Message: 08:32:46.905: Response: [+QCFG: "urc/ri/ring","pulse",120,1000,5000,"off",1\r\n\r\nOK]
** Message: 08:32:46.905: Successfully sent command: AT+QCFG="urc/ri/smsincoming"
** Message: 08:32:46.933: Response: [+QCFG: "urc/ri/smsincoming","pulse",120,1\r\n\r\nOK]
** Message: 08:32:46.934: Successfully sent command: AT+QCFG="urc/ri/other"
** Message: 08:32:46.961: Response: [+QCFG: "urc/ri/other","off",1,1\r\n\r\nOK]
** Message: 08:32:46.962: Successfully sent command: AT+QCFG="urc/delay"
** Message: 08:32:46.978: Response: [+QCFG: "urc/delay",0\r\n\r\nOK]
** Message: 08:32:46.978: Successfully sent command: AT+QCFG="urc/cache"
** Message: 08:32:46.995: Response: [+QCFG: "urc/cache",0\r\n\r\nOK]
** Message: 08:32:46.996: Successfully sent command: AT+QCFG="urc/ri/pin"
** Message: 08:32:47.022: Response: [+QCFG: "urc/ri/pin",uart_ri\r\n\r\nOK]
** Message: 08:32:47.023: Successfully sent command: AT+QURCCFG="urcport"
** Message: 08:32:47.050: Response: [+QURCCFG: "urcport","all"\r\n\r\nOK]
** Message: 08:32:47.051: Successfully sent command: AT+QSCLK=1
** Message: 08:32:47.113: Response: [OK]
** Message: 08:32:47.114: Successfully sent command: AT+QGPSXTRA?
** Message: 08:32:47.129: Response: [+QGPSXTRA: 1\r\n\r\nOK]
** Message: 08:32:47.130: Successfully sent command: AT+QGPSCFG="gnssconfig"
** Message: 08:32:47.160: Response: [+QGPSCFG: "gnssconfig",4\r\n\r\nOK]
** Message: 08:32:47.161: Successfully sent command: AT+QGPSCFG="odpcontrol"
** Message: 08:32:47.193: Response: [+QGPSCFG: "odpcontrol",0\r\n\r\nOK]
** Message: 08:32:47.193: Successfully sent command: AT+QGPSCFG="dpoenable"
** Message: 08:32:47.221: Response: [+QGPSCFG: "dpoenable",1\r\n\r\nOK]
** Message: 08:32:47.221: Successfully sent command: AT+QGPSCFG="gpsnmeatype"
** Message: 08:32:47.249: Response: [+QGPSCFG: "gpsnmeatype",31\r\n\r\nOK]
** Message: 08:32:47.249: Successfully sent command: AT+QGPSCFG="glonassnmeatype"
** Message: 08:32:47.277: Response: [+QGPSCFG: "glonassnmeatype",7\r\n\r\nOK]
** Message: 08:32:47.277: Successfully sent command: AT+QGPSCFG="galileonmeatype"
** Message: 08:32:47.305: Response: [+QGPSCFG: "galileonmeatype",0\r\n\r\nOK]
** Message: 08:32:47.305: Successfully sent command: AT+QGPSCFG="beidounmeatype"
** Message: 08:32:47.333: Response: [+QGPSCFG: "beidounmeatype",0\r\n\r\nOK]
** Message: 08:32:47.334: Successfully sent command: AT+QGPSCFG="autogps"
** Message: 08:32:47.350: Response: [+QGPSCFG: "autogps",0\r\n\r\nOK]
** Message: 08:32:47.350: Successfully sent command: AT+QCFG="fast/poweroff"
** Message: 08:32:47.371: Response: [OK]
** Message: 08:32:47.371: Got a different result than expected, changing value...
** Message: 08:32:47.371: Expected: [0]
Response: [OK]
** Message: 08:32:47.371: Successfully sent command: AT+QCFG="fast/poweroff",0
** Message: 08:32:47.391: Response: [OK]
** Message: 08:32:47.392: Successfully sent command: AT+QCFG="sleepind/level"
** Message: 08:32:47.409: Response: [+QCFG: "sleepind/level",0\r\n\r\nOK]
** Message: 08:32:47.409: Successfully sent command: AT+QCFG="wakeupin/level"
** Message: 08:32:47.439: Response: [+QCFG: "wakeupin/level",0,0\r\n\r\nOK]
** Message: 08:32:47.440: Successfully sent command: AT+QCFG="ApRstLevel"
** Message: 08:32:47.461: Response: [OK]
** Message: 08:32:47.461: Got a different result than expected, changing value...
** Message: 08:32:47.461: Expected: [1]
Response: [OK]
** Message: 08:32:47.462: Successfully sent command: AT+QCFG="ApRstLevel",1
** Message: 08:32:47.481: Response: [OK]
** Message: 08:32:47.482: Successfully sent command: AT+QCFG="ModemRstLevel"
** Message: 08:32:47.503: Response: [OK]
** Message: 08:32:47.504: Got a different result than expected, changing value...
** Message: 08:32:47.504: Expected: [1]
Response: [OK]
** Message: 08:32:47.504: Successfully sent command: AT+QCFG="ModemRstLevel",1
** Message: 08:32:47.527: Response: [OK]
** Message: 08:32:47.527: Executed soft sleep sequence
** Message: 08:33:12.925: GNSS assistance upload started...
** Message: 08:33:12.925: GNSS assistance upload step (1/9): fetching assistance data
** Message: 08:33:13.301: Fetching GNSS assistance data from https://xtrapath4.izatcloud.net/xtra2.bin was successful
** Message: 08:33:13.309: GNSS assistance upload step (2/9): disabling GNSS engine through ModemManager
** Message: 08:33:13.324: GNSS assistance upload step (3/9): disabling GNSS engine through AT+QGPS
** Message: 08:33:13.525: Executed soft wake sequence
** Message: 08:33:13.525: Successfully sent command: AT+QGPS?
** Message: 08:34:34.914: Modem is up for 120 seconds and fully ready
** Message: 08:34:34.914: dropping systemd sleep block inhibitor
** Message: 08:41:39.971: Request to quit...
** Message: 08:41:39.974: dropping systemd sleep delay inhibitor
** Message: 08:41:39.975: Powering down the modem...
** Message: 08:41:40.976: Executed power-on/off sequence
** Message: 08:41:40.976: Executed power-off sequence
** Message: 08:41:41.976: Modem down, quitting...
** Message: 08:41:42.074: Opening config file: /usr/share/eg25-manager/pine64,pinephone-1.2.toml
** Message: 08:41:42.083: Starting modem...
** Message: 08:41:43.184: Executed power-on/off sequence
** Message: 08:41:43.190: taking systemd sleep inhibitor
** Message: 08:41:43.191: ModemManager appeared on D-Bus
** Message: 08:41:43.194: oFono vanished from D-Bus
** Message: 08:41:43.202: inhibitor sleep fd is 20
** Message: 08:42:03.369: Response: [RDY]
** Message: 08:42:03.369: taking systemd sleep inhibitor (blocking)
** Message: 08:42:03.388: Response: [+CPIN: READY]
** Message: 08:42:03.388: Executed soft sleep sequence
** Message: 08:42:03.388: inhibitor block fd is 19
** Message: 08:42:03.400: Response: [+QUSIM: 1]
** Message: 08:42:03.400: Executed soft sleep sequence
** Message: 08:42:03.775: Response: [+CFUN: 4]
** Message: 08:42:03.775: Executed soft sleep sequence
** Message: 08:42:04.023: Response: [+QIND: SMS DONE]
** Message: 08:42:04.023: Executed soft sleep sequence
** Message: 08:42:05.216: Response: [+QIND: PB DONE]
** Message: 08:42:05.217: Executed soft sleep sequence
** Message: 08:42:11.920: Rescheduling upload since modem isn't online yet, in 30s
** Message: 08:42:14.417: ModemManager object `/org/freedesktop/ModemManager1/Modem/1' added
** Message: 08:42:14.418: ModemManager interface `org.freedesktop.ModemManager1.Modem.Modem3gpp.ProfileManager' found on object `/org/freedesktop/ModemManager1/Modem/1'
** Message: 08:42:14.418: ModemManager interface `org.freedesktop.ModemManager1.Modem.Firmware' found on object `/org/freedesktop/ModemManager1/Modem/1'
** Message: 08:42:14.418: ModemManager interface `org.freedesktop.ModemManager1.Modem.Modem3gpp' found on object `/org/freedesktop/ModemManager1/Modem/1'
** Message: 08:42:14.418: ModemManager interface `org.freedesktop.ModemManager1.Modem.Time' found on object `/org/freedesktop/ModemManager1/Modem/1'
** Message: 08:42:14.418: ModemManager interface `org.freedesktop.ModemManager1.Modem.Voice' found on object `/org/freedesktop/ModemManager1/Modem/1'
** Message: 08:42:14.418: ModemManager interface `org.freedesktop.ModemManager1.Modem' found on object `/org/freedesktop/ModemManager1/Modem/1'
** Message: 08:42:14.418: Adding new modem `/org/freedesktop/ModemManager1/Modem/1'
** Message: 08:42:14.619: Executed soft wake sequence
** Message: 08:42:14.619: Successfully sent command: AT+QGMR
** Message: 08:42:14.619: ModemManager interface `org.freedesktop.ModemManager1.Modem.Messaging' found on object `/org/freedesktop/ModemManager1/Modem/1'
** Message: 08:42:14.619: ModemManager interface `org.freedesktop.ModemManager1.Modem.Modem3gpp.Ussd' found on object `/org/freedesktop/ModemManager1/Modem/1'
** Message: 08:42:14.619: ModemManager interface `org.freedesktop.ModemManager1.Modem.Signal' found on object `/org/freedesktop/ModemManager1/Modem/1'
** Message: 08:42:14.619: ModemManager interface `org.freedesktop.ModemManager1.Modem.Location' found on object `/org/freedesktop/ModemManager1/Modem/1'
** Message: 08:42:14.619: Adding new modem with location capabilities `/org/freedesktop/ModemManager1/Modem/1'
** Message: 08:42:14.619: ModemManager interface `org.freedesktop.ModemManager1.Modem.Simple' found on object `/org/freedesktop/ModemManager1/Modem/1'
** Message: 08:42:14.638: Response: [0.6.8\r\n\r\nOK]
** Message: 08:42:14.639: Successfully sent command: AT+QDAI?
** Message: 08:42:14.658: Response: [OK]
** Message: 08:42:14.658: Got a different result than expected, changing value...
** Message: 08:42:14.658: Expected: [1,1,0,1,0,0,1,1]
Response: [OK]
** Message: 08:42:14.658: Successfully sent command: AT+QDAI=1,1,0,1,0,0,1,1
** Message: 08:42:14.678: Response: [OK]
** Message: 08:42:14.678: Successfully sent command: AT+QCFG="risignaltype"
** Message: 08:42:14.704: Response: [+QCFG: "risignaltype","physical"\r\n\r\nOK]
** Message: 08:42:14.705: Successfully sent command: AT+QCFG="ims"
** Message: 08:42:14.720: Response: [+QCFG: "ims",1,0\r\n\r\nOK]
** Message: 08:42:14.720: Successfully sent command: AT+QCFG="apready"
** Message: 08:42:14.746: Response: [+QCFG: "apready",1,0,500\r\n\r\nOK]
** Message: 08:42:14.746: Successfully sent command: AT+QCFG="urc/ri/ring"
** Message: 08:42:14.772: Response: [+QCFG: "urc/ri/ring","pulse",120,1000,5000,"off",1\r\n\r\nOK]
** Message: 08:42:14.773: Successfully sent command: AT+QCFG="urc/ri/smsincoming"
** Message: 08:42:14.800: Response: [+QCFG: "urc/ri/smsincoming","pulse",120,1\r\n\r\nOK]
** Message: 08:42:14.800: Successfully sent command: AT+QCFG="urc/ri/other"
** Message: 08:42:14.827: Response: [+QCFG: "urc/ri/other","off",1,1\r\n\r\nOK]
** Message: 08:42:14.828: Successfully sent command: AT+QCFG="urc/delay"
** Message: 08:42:14.843: Response: [+QCFG: "urc/delay",0\r\n\r\nOK]
** Message: 08:42:14.844: Successfully sent command: AT+QCFG="urc/cache"
** Message: 08:42:14.860: Response: [+QCFG: "urc/cache",0\r\n\r\nOK]
** Message: 08:42:14.860: Successfully sent command: AT+QCFG="urc/ri/pin"
** Message: 08:42:14.886: Response: [+QCFG: "urc/ri/pin",uart_ri\r\n\r\nOK]
** Message: 08:42:14.887: Successfully sent command: AT+QURCCFG="urcport"
** Message: 08:42:14.912: Response: [+QURCCFG: "urcport","all"\r\n\r\nOK]
** Message: 08:42:14.913: Successfully sent command: AT+QSCLK=1
** Message: 08:42:15.009: Response: [OK]
** Message: 08:42:15.009: Successfully sent command: AT+QGPSXTRA?
** Message: 08:42:15.025: Response: [+QGPSXTRA: 1\r\n\r\nOK]
** Message: 08:42:15.025: Successfully sent command: AT+QGPSCFG="gnssconfig"
** Message: 08:42:15.056: Response: [+QGPSCFG: "gnssconfig",4\r\n\r\nOK]
** Message: 08:42:15.056: Successfully sent command: AT+QGPSCFG="odpcontrol"
** Message: 08:42:15.085: Response: [+QGPSCFG: "odpcontrol",0\r\n\r\nOK]
** Message: 08:42:15.085: Successfully sent command: AT+QGPSCFG="dpoenable"
** Message: 08:42:15.112: Response: [+QGPSCFG: "dpoenable",1\r\n\r\nOK]
** Message: 08:42:15.112: Successfully sent command: AT+QGPSCFG="gpsnmeatype"
** Message: 08:42:15.138: Response: [+QGPSCFG: "gpsnmeatype",31\r\n\r\nOK]
** Message: 08:42:15.138: Successfully sent command: AT+QGPSCFG="glonassnmeatype"
** Message: 08:42:15.165: Response: [+QGPSCFG: "glonassnmeatype",7\r\n\r\nOK]
** Message: 08:42:15.166: Successfully sent command: AT+QGPSCFG="galileonmeatype"
** Message: 08:42:15.192: Response: [+QGPSCFG: "galileonmeatype",0\r\n\r\nOK]
** Message: 08:42:15.193: Successfully sent command: AT+QGPSCFG="beidounmeatype"
** Message: 08:42:15.219: Response: [+QGPSCFG: "beidounmeatype",0\r\n\r\nOK]
** Message: 08:42:15.220: Successfully sent command: AT+QGPSCFG="autogps"
** Message: 08:42:15.236: Response: [+QGPSCFG: "autogps",0\r\n\r\nOK]
** Message: 08:42:15.236: Successfully sent command: AT+QCFG="fast/poweroff"
** Message: 08:42:15.255: Response: [OK]
** Message: 08:42:15.255: Got a different result than expected, changing value...
** Message: 08:42:15.255: Expected: [0]
Response: [OK]
** Message: 08:42:15.255: Successfully sent command: AT+QCFG="fast/poweroff",0
** Message: 08:42:15.275: Response: [OK]
** Message: 08:42:15.275: Successfully sent command: AT+QCFG="sleepind/level"
** Message: 08:42:15.302: Response: [+QCFG: "sleepind/level",0\r\n\r\nOK]
** Message: 08:42:15.302: Successfully sent command: AT+QCFG="wakeupin/level"
** Message: 08:42:15.331: Response: [+QCFG: "wakeupin/level",0,0\r\n\r\nOK]
** Message: 08:42:15.331: Successfully sent command: AT+QCFG="ApRstLevel"
** Message: 08:42:15.350: Response: [OK]
** Message: 08:42:15.351: Got a different result than expected, changing value...
** Message: 08:42:15.351: Expected: [1]
Response: [OK]
** Message: 08:42:15.351: Successfully sent command: AT+QCFG="ApRstLevel",1
** Message: 08:42:15.371: Response: [OK]
** Message: 08:42:15.371: Successfully sent command: AT+QCFG="ModemRstLevel"
** Message: 08:42:15.391: Response: [OK]
** Message: 08:42:15.391: Got a different result than expected, changing value...
** Message: 08:42:15.391: Expected: [1]
Response: [OK]
** Message: 08:42:15.391: Successfully sent command: AT+QCFG="ModemRstLevel",1
** Message: 08:42:15.413: Response: [OK]
** Message: 08:42:15.413: Executed soft sleep sequence
** Message: 08:42:41.928: GNSS assistance upload started...
** Message: 08:42:41.928: GNSS assistance upload step (1/9): fetching assistance data
** Message: 08:42:42.329: Fetching GNSS assistance data from https://xtrapath4.izatcloud.net/xtra2.bin was successful
** Message: 08:42:42.337: GNSS assistance upload step (2/9): disabling GNSS engine through ModemManager
** Message: 08:42:42.350: GNSS assistance upload step (3/9): disabling GNSS engine through AT+QGPS
** Message: 08:42:42.551: Executed soft wake sequence
** Message: 08:42:42.551: Successfully sent command: AT+QGPS?
** Message: 08:42:42.565: Response: [+QGPS: 0\r\n\r\nOK]
** Message: 08:42:42.565: Executed soft sleep sequence
** Message: 08:42:42.565: GNSS assistance upload step (4/9): initiating upload
** Message: 08:42:42.765: Executed soft wake sequence
** Message: 08:42:42.765: Successfully sent command: AT+QFDEL="RAM:*"
** Message: 08:42:43.180: Response: [OK]
** Message: 08:42:43.181: Executed soft sleep sequence
** Message: 08:42:43.181: Initiate GNSS assistance data upload: "RAM:xtra2.bin",59621,10
** Message: 08:42:43.381: Executed soft wake sequence
** Message: 08:42:43.381: Successfully sent command: AT+QFUPL="RAM:xtra2.bin",59621,10
** Message: 08:42:43.397: Response: [CONNECT]
** Message: 08:42:43.397: Modem ready for GNSS assistance data upload
** Message: 08:42:43.397: GNSS assistance upload step (5/9): uploading assistance data
** Message: 08:42:49.249: Successfully uploaded 59621 bytes to the modem
** Message: 08:42:49.259: Response: [+QFUPL: 59621,ee6\r\n\r\nOK]
** Message: 08:42:49.259: Executed soft sleep sequence
** Message: 08:42:49.259: GNSS assistance upload step (6/9): finishing upload
** Message: 08:42:49.259: Setting GNSS assistance UTC clock to: 0,"2022/08/03,08:42:49"
** Message: 08:42:49.260: Setting GNSS assistance file to: "RAM:xtra2.bin"
** Message: 08:42:49.460: Executed soft wake sequence
** Message: 08:42:49.460: Successfully sent command: AT+QGPSXTRATIME=0,"2022/08/03,08:42:49"
** Message: 08:42:49.478: Response: [OK]
** Message: 08:42:49.478: Successfully sent command: AT+QGPSXTRADATA="RAM:xtra2.bin"
** Message: 08:42:49.494: Response: [OK]
** Message: 08:42:49.494: Executed soft sleep sequence
** Message: 08:42:49.494: GNSS assistance data upload finished
** Message: 08:42:49.495: GNSS assistance upload step (7/9): re-enabling GNSS through ModemManager
** Message: 08:42:49.512: GNSS assistance upload step (8/9): re-enabling GNSS through AT+QGPS
** Message: 08:42:49.512: GNSS assistance upload step (9/9): finished
SantX27 commented 2 years ago

Took a while, but after 4 restarts it did the trick! Posting only the last 2 for the sake of brevity.

ago 03 11:03:43 miria eg25-manager[4526]: Opening config file: /usr/share/eg25-manager/pine64,pinephone-1.2.toml
ago 03 11:03:43 miria eg25-manager[4526]: Starting modem...
ago 03 11:03:44 miria eg25-manager[4526]: Executed power-on/off sequence
ago 03 11:03:44 miria eg25-manager[4526]: taking systemd sleep inhibitor
ago 03 11:03:44 miria eg25-manager[4526]: ModemManager appeared on D-Bus
ago 03 11:03:44 miria eg25-manager[4526]: oFono vanished from D-Bus
ago 03 11:03:44 miria eg25-manager[4526]: inhibitor sleep fd is 21
ago 03 11:04:06 miria eg25-manager[4526]: Response: [RDY]
ago 03 11:04:06 miria eg25-manager[4526]: taking systemd sleep inhibitor (blocking)
ago 03 11:04:06 miria eg25-manager[4526]: inhibitor block fd is 20
ago 03 11:04:06 miria eg25-manager[4526]: Response: [+CPIN: READY]
ago 03 11:04:06 miria eg25-manager[4526]: Executed soft sleep sequence
ago 03 11:04:06 miria eg25-manager[4526]: Response: [+QUSIM: 1]
ago 03 11:04:06 miria eg25-manager[4526]: Executed soft sleep sequence
ago 03 11:04:06 miria eg25-manager[4526]: Response: [+CFUN: 4]
ago 03 11:04:06 miria eg25-manager[4526]: Executed soft sleep sequence
ago 03 11:04:06 miria eg25-manager[4526]: Response: [+QIND: SMS DONE]
ago 03 11:04:06 miria eg25-manager[4526]: Executed soft sleep sequence
ago 03 11:04:07 miria eg25-manager[4526]: Response: [+QIND: PB DONE]
ago 03 11:04:07 miria eg25-manager[4526]: Executed soft sleep sequence
ago 03 11:04:14 miria eg25-manager[4526]: Rescheduling upload since modem isn't online yet, in 30s
ago 03 11:04:16 miria eg25-manager[4526]: ModemManager object `/org/freedesktop/ModemManager1/Modem/1' added
ago 03 11:04:16 miria eg25-manager[4526]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Modem3gpp.ProfileManager' found on object `/org/freedesktop/ModemManager1/Modem/1'
ago 03 11:04:16 miria eg25-manager[4526]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Firmware' found on object `/org/freedesktop/ModemManager1/Modem/1'
ago 03 11:04:16 miria eg25-manager[4526]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Modem3gpp' found on object `/org/freedesktop/ModemManager1/Modem/1'
ago 03 11:04:16 miria eg25-manager[4526]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Time' found on object `/org/freedesktop/ModemManager1/Modem/1'
ago 03 11:04:16 miria eg25-manager[4526]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Voice' found on object `/org/freedesktop/ModemManager1/Modem/1'
ago 03 11:04:16 miria eg25-manager[4526]: ModemManager interface `org.freedesktop.ModemManager1.Modem' found on object `/org/freedesktop/ModemManager1/Modem/1'
ago 03 11:04:16 miria eg25-manager[4526]: Adding new modem `/org/freedesktop/ModemManager1/Modem/1'
ago 03 11:04:17 miria eg25-manager[4526]: Executed soft wake sequence
ago 03 11:04:17 miria eg25-manager[4526]: Successfully sent command: AT+QGMR
ago 03 11:04:17 miria eg25-manager[4526]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Messaging' found on object `/org/freedesktop/ModemManager1/Modem/1'
ago 03 11:04:17 miria eg25-manager[4526]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Modem3gpp.Ussd' found on object `/org/freedesktop/ModemManager1/Modem/1'
ago 03 11:04:17 miria eg25-manager[4526]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Signal' found on object `/org/freedesktop/ModemManager1/Modem/1'
ago 03 11:04:17 miria eg25-manager[4526]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Location' found on object `/org/freedesktop/ModemManager1/Modem/1'
ago 03 11:04:17 miria eg25-manager[4526]: Adding new modem with location capabilities `/org/freedesktop/ModemManager1/Modem/1'
ago 03 11:04:17 miria eg25-manager[4526]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Simple' found on object `/org/freedesktop/ModemManager1/Modem/1'
ago 03 11:04:17 miria eg25-manager[4526]: Response: [0.6.8\r\n\r\nOK]
ago 03 11:04:17 miria eg25-manager[4526]: Successfully sent command: AT+QDAI?
ago 03 11:04:17 miria eg25-manager[4526]: Response: [OK]
ago 03 11:04:17 miria eg25-manager[4526]: Got a different result than expected, changing value...
ago 03 11:04:17 miria eg25-manager[4526]: Expected: [1,1,0,1,0,0,1,1]
ago 03 11:04:17 miria eg25-manager[4526]: Successfully sent command: AT+QDAI=1,1,0,1,0,0,1,1
ago 03 11:04:17 miria eg25-manager[4526]: Response: [OK]
ago 03 11:04:17 miria eg25-manager[4526]: Successfully sent command: AT+QCFG="risignaltype"
ago 03 11:04:17 miria eg25-manager[4526]: Response: [+QCFG: "risignaltype","physical"\r\n\r\nOK]
ago 03 11:04:17 miria eg25-manager[4526]: Successfully sent command: AT+QCFG="ims"
ago 03 11:04:17 miria eg25-manager[4526]: Response: [+QCFG: "ims",1,0\r\n\r\nOK]
ago 03 11:04:17 miria eg25-manager[4526]: Successfully sent command: AT+QCFG="apready"
ago 03 11:04:17 miria eg25-manager[4526]: Response: [+QCFG: "apready",1,0,500\r\n\r\nOK]
ago 03 11:04:17 miria eg25-manager[4526]: Successfully sent command: AT+QCFG="urc/ri/ring"
ago 03 11:04:17 miria eg25-manager[4526]: Response: [+QCFG: "urc/ri/ring","pulse",120,1000,5000,"off",1\r\n\r\nOK]
ago 03 11:04:17 miria eg25-manager[4526]: Successfully sent command: AT+QCFG="urc/ri/smsincoming"
ago 03 11:04:17 miria eg25-manager[4526]: Response: [+QCFG: "urc/ri/smsincoming","pulse",120,1\r\n\r\nOK]
ago 03 11:04:17 miria eg25-manager[4526]: Successfully sent command: AT+QCFG="urc/ri/other"
ago 03 11:04:17 miria eg25-manager[4526]: Response: [+QCFG: "urc/ri/other","off",1,1\r\n\r\nOK]
ago 03 11:04:17 miria eg25-manager[4526]: Successfully sent command: AT+QCFG="urc/delay"
ago 03 11:04:17 miria eg25-manager[4526]: Response: [+QCFG: "urc/delay",0\r\n\r\nOK]
ago 03 11:04:17 miria eg25-manager[4526]: Successfully sent command: AT+QCFG="urc/cache"
ago 03 11:04:17 miria eg25-manager[4526]: Response: [+QCFG: "urc/cache",0\r\n\r\nOK]
ago 03 11:04:17 miria eg25-manager[4526]: Successfully sent command: AT+QCFG="urc/ri/pin"
ago 03 11:04:17 miria eg25-manager[4526]: Response: [+QCFG: "urc/ri/pin",uart_ri\r\n\r\nOK]
ago 03 11:04:17 miria eg25-manager[4526]: Successfully sent command: AT+QURCCFG="urcport"
ago 03 11:04:17 miria eg25-manager[4526]: Response: [+QURCCFG: "urcport","all"\r\n\r\nOK]
ago 03 11:04:17 miria eg25-manager[4526]: Successfully sent command: AT+QSCLK=1
ago 03 11:04:17 miria eg25-manager[4526]: Response: [OK]
ago 03 11:04:17 miria eg25-manager[4526]: Successfully sent command: AT+QGPSXTRA?
ago 03 11:04:17 miria eg25-manager[4526]: Response: [+QGPSXTRA: 1\r\n\r\nOK]
ago 03 11:04:17 miria eg25-manager[4526]: Successfully sent command: AT+QGPSCFG="gnssconfig"
ago 03 11:04:17 miria eg25-manager[4526]: Response: [+QGPSCFG: "gnssconfig",4\r\n\r\nOK]
ago 03 11:04:17 miria eg25-manager[4526]: Successfully sent command: AT+QGPSCFG="odpcontrol"
ago 03 11:04:17 miria eg25-manager[4526]: Response: [+QGPSCFG: "odpcontrol",0\r\n\r\nOK]
ago 03 11:04:17 miria eg25-manager[4526]: Successfully sent command: AT+QGPSCFG="dpoenable"
ago 03 11:04:17 miria eg25-manager[4526]: Response: [+QGPSCFG: "dpoenable",1\r\n\r\nOK]
ago 03 11:04:17 miria eg25-manager[4526]: Successfully sent command: AT+QGPSCFG="gpsnmeatype"
ago 03 11:04:17 miria eg25-manager[4526]: Response: [+QGPSCFG: "gpsnmeatype",31\r\n\r\nOK]
ago 03 11:04:17 miria eg25-manager[4526]: Successfully sent command: AT+QGPSCFG="glonassnmeatype"
ago 03 11:04:17 miria eg25-manager[4526]: Response: [+QGPSCFG: "glonassnmeatype",7\r\n\r\nOK]
ago 03 11:04:17 miria eg25-manager[4526]: Successfully sent command: AT+QGPSCFG="galileonmeatype"
ago 03 11:04:17 miria eg25-manager[4526]: Response: [+QGPSCFG: "galileonmeatype",0\r\n\r\nOK]
ago 03 11:04:17 miria eg25-manager[4526]: Successfully sent command: AT+QGPSCFG="beidounmeatype"
ago 03 11:04:17 miria eg25-manager[4526]: Response: [+QGPSCFG: "beidounmeatype",0\r\n\r\nOK]
ago 03 11:04:17 miria eg25-manager[4526]: Successfully sent command: AT+QGPSCFG="autogps"
ago 03 11:04:17 miria eg25-manager[4526]: Response: [+QGPSCFG: "autogps",0\r\n\r\nOK]
ago 03 11:04:17 miria eg25-manager[4526]: Successfully sent command: AT+QCFG="fast/poweroff"
ago 03 11:04:17 miria eg25-manager[4526]: Response: [OK]
ago 03 11:04:17 miria eg25-manager[4526]: Got a different result than expected, changing value...
ago 03 11:04:17 miria eg25-manager[4526]: Expected: [0]
ago 03 11:04:17 miria eg25-manager[4526]: Successfully sent command: AT+QCFG="fast/poweroff",0
ago 03 11:04:17 miria eg25-manager[4526]: Response: [OK]
ago 03 11:04:17 miria eg25-manager[4526]: Successfully sent command: AT+QCFG="sleepind/level"
ago 03 11:04:17 miria eg25-manager[4526]: Response: [+QCFG: "sleepind/level",0\r\n\r\nOK]
ago 03 11:04:17 miria eg25-manager[4526]: Successfully sent command: AT+QCFG="wakeupin/level"
ago 03 11:04:17 miria eg25-manager[4526]: Response: [+QCFG: "wakeupin/level",0,0\r\n\r\nOK]
ago 03 11:04:17 miria eg25-manager[4526]: Successfully sent command: AT+QCFG="ApRstLevel"
ago 03 11:04:17 miria eg25-manager[4526]: Response: [OK]
ago 03 11:04:17 miria eg25-manager[4526]: Got a different result than expected, changing value...
ago 03 11:04:17 miria eg25-manager[4526]: Expected: [1]
ago 03 11:04:17 miria eg25-manager[4526]: Successfully sent command: AT+QCFG="ApRstLevel",1
ago 03 11:04:17 miria eg25-manager[4526]: Response: [OK]
ago 03 11:04:17 miria eg25-manager[4526]: Successfully sent command: AT+QCFG="ModemRstLevel"
ago 03 11:04:17 miria eg25-manager[4526]: Response: [OK]
ago 03 11:04:17 miria eg25-manager[4526]: Got a different result than expected, changing value...
ago 03 11:04:17 miria eg25-manager[4526]: Expected: [1]
ago 03 11:04:17 miria eg25-manager[4526]: Successfully sent command: AT+QCFG="ModemRstLevel",1
ago 03 11:04:17 miria eg25-manager[4526]: Response: [OK]
ago 03 11:04:17 miria eg25-manager[4526]: Executed soft sleep sequence
ago 03 11:04:44 miria eg25-manager[4526]: GNSS assistance upload started...
ago 03 11:04:44 miria eg25-manager[4526]: GNSS assistance upload step (1/9): fetching assistance data
ago 03 11:04:44 miria eg25-manager[4526]: Fetching GNSS assistance data from https://xtrapath4.izatcloud.net/xtra2.bin was successful
ago 03 11:04:44 miria eg25-manager[4526]: GNSS assistance upload step (2/9): disabling GNSS engine through ModemManager
ago 03 11:04:44 miria eg25-manager[4526]: GNSS assistance upload step (3/9): disabling GNSS engine through AT+QGPS
ago 03 11:04:44 miria eg25-manager[4526]: Executed soft wake sequence
ago 03 11:04:44 miria eg25-manager[4526]: Successfully sent command: AT+QGPS?
ago 03 11:06:06 miria eg25-manager[4526]: Modem is up for 120 seconds and fully ready
ago 03 11:06:06 miria eg25-manager[4526]: dropping systemd sleep block inhibitor
ago 03 11:06:20 miria polkitd[3216]: Operator of unix-process:4660:72810 successfully authenticated as unix-user:manjaro to gain ONE-SHOT authorization for action org.freedesktop.systemd1.manage-units for system-bus-name::1.95 [systemctl restart eg25-manager.service] (owned by unix-user:manjaro)
ago 03 11:06:20 miria eg25-manager[4526]: Request to quit...
ago 03 11:06:20 miria eg25-manager[4526]: dropping systemd sleep delay inhibitor
ago 03 11:06:20 miria eg25-manager[4526]: Powering down the modem...
ago 03 11:06:21 miria eg25-manager[4526]: Executed power-on/off sequence
ago 03 11:06:21 miria eg25-manager[4526]: Executed power-off sequence
ago 03 11:06:22 miria eg25-manager[4526]: Modem down, quitting...
ago 03 11:06:22 miria systemd[1]: eg25-manager.service: Deactivated successfully.
ago 03 11:06:22 miria eg25-manager[4722]: Opening config file: /usr/share/eg25-manager/pine64,pinephone-1.2.toml
ago 03 11:06:22 miria eg25-manager[4722]: Response: ["]
ago 03 11:06:22 miria eg25-manager[4722]: Executed soft sleep sequence
ago 03 11:06:22 miria eg25-manager[4722]: Starting modem...
ago 03 11:06:23 miria eg25-manager[4722]: Executed power-on/off sequence
ago 03 11:06:23 miria eg25-manager[4722]: taking systemd sleep inhibitor
ago 03 11:06:23 miria eg25-manager[4722]: ModemManager appeared on D-Bus
ago 03 11:06:23 miria eg25-manager[4722]: oFono vanished from D-Bus
ago 03 11:06:23 miria eg25-manager[4722]: inhibitor sleep fd is 21
ago 03 11:06:44 miria eg25-manager[4722]: Response: [RDY]
ago 03 11:06:44 miria eg25-manager[4722]: taking systemd sleep inhibitor (blocking)
ago 03 11:06:44 miria eg25-manager[4722]: inhibitor block fd is 20
ago 03 11:06:45 miria eg25-manager[4722]: Response: [+CPIN: READY]
ago 03 11:06:45 miria eg25-manager[4722]: Executed soft sleep sequence
ago 03 11:06:45 miria eg25-manager[4722]: Response: [+QUSIM: 1]
ago 03 11:06:45 miria eg25-manager[4722]: Executed soft sleep sequence
ago 03 11:06:45 miria eg25-manager[4722]: Response: [+CFUN: 4]
ago 03 11:06:45 miria eg25-manager[4722]: Executed soft sleep sequence
ago 03 11:06:45 miria eg25-manager[4722]: Response: [+QIND: SMS DONE]
ago 03 11:06:45 miria eg25-manager[4722]: Executed soft sleep sequence
ago 03 11:06:46 miria eg25-manager[4722]: Response: [+QIND: PB DONE]
ago 03 11:06:46 miria eg25-manager[4722]: Executed soft sleep sequence
ago 03 11:06:53 miria eg25-manager[4722]: Rescheduling upload since modem isn't online yet, in 30s
ago 03 11:06:55 miria eg25-manager[4722]: ModemManager object `/org/freedesktop/ModemManager1/Modem/2' added
ago 03 11:06:55 miria eg25-manager[4722]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Modem3gpp.ProfileManager' found on object `/org/freedesktop/ModemManager1/Modem/2'
ago 03 11:06:55 miria eg25-manager[4722]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Firmware' found on object `/org/freedesktop/ModemManager1/Modem/2'
ago 03 11:06:55 miria eg25-manager[4722]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Modem3gpp' found on object `/org/freedesktop/ModemManager1/Modem/2'
ago 03 11:06:55 miria eg25-manager[4722]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Time' found on object `/org/freedesktop/ModemManager1/Modem/2'
ago 03 11:06:55 miria eg25-manager[4722]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Voice' found on object `/org/freedesktop/ModemManager1/Modem/2'
ago 03 11:06:55 miria eg25-manager[4722]: ModemManager interface `org.freedesktop.ModemManager1.Modem' found on object `/org/freedesktop/ModemManager1/Modem/2'
ago 03 11:06:55 miria eg25-manager[4722]: Adding new modem `/org/freedesktop/ModemManager1/Modem/2'
ago 03 11:06:56 miria eg25-manager[4722]: Executed soft wake sequence
ago 03 11:06:56 miria eg25-manager[4722]: Successfully sent command: AT+QGMR
ago 03 11:06:56 miria eg25-manager[4722]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Messaging' found on object `/org/freedesktop/ModemManager1/Modem/2'
ago 03 11:06:56 miria eg25-manager[4722]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Modem3gpp.Ussd' found on object `/org/freedesktop/ModemManager1/Modem/2'
ago 03 11:06:56 miria eg25-manager[4722]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Signal' found on object `/org/freedesktop/ModemManager1/Modem/2'
ago 03 11:06:56 miria eg25-manager[4722]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Location' found on object `/org/freedesktop/ModemManager1/Modem/2'
ago 03 11:06:56 miria eg25-manager[4722]: Adding new modem with location capabilities `/org/freedesktop/ModemManager1/Modem/2'
ago 03 11:06:56 miria eg25-manager[4722]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Simple' found on object `/org/freedesktop/ModemManager1/Modem/2'
ago 03 11:06:56 miria eg25-manager[4722]: Response: [0.6.8\r\n\r\nOK]
ago 03 11:06:56 miria eg25-manager[4722]: Successfully sent command: AT+QDAI?
ago 03 11:06:56 miria eg25-manager[4722]: Response: [OK]
ago 03 11:06:56 miria eg25-manager[4722]: Got a different result than expected, changing value...
ago 03 11:06:56 miria eg25-manager[4722]: Expected: [1,1,0,1,0,0,1,1]
ago 03 11:06:56 miria eg25-manager[4722]: Successfully sent command: AT+QDAI=1,1,0,1,0,0,1,1
ago 03 11:06:56 miria eg25-manager[4722]: Response: [OK]
ago 03 11:06:56 miria eg25-manager[4722]: Successfully sent command: AT+QCFG="risignaltype"
ago 03 11:06:56 miria eg25-manager[4722]: Response: [+QCFG: "risignaltype","physical"\r\n\r\nOK]
ago 03 11:06:56 miria eg25-manager[4722]: Successfully sent command: AT+QCFG="ims"
ago 03 11:06:56 miria eg25-manager[4722]: Response: [+QCFG: "ims",1,0\r\n\r\nOK]
ago 03 11:06:56 miria eg25-manager[4722]: Successfully sent command: AT+QCFG="apready"
ago 03 11:06:56 miria eg25-manager[4722]: Response: [+QCFG: "apready",1,0,500\r\n\r\nOK]
ago 03 11:06:56 miria eg25-manager[4722]: Successfully sent command: AT+QCFG="urc/ri/ring"
ago 03 11:06:56 miria eg25-manager[4722]: Response: [+QCFG: "urc/ri/ring","pulse",120,1000,5000,"off",1\r\n\r\nOK]
ago 03 11:06:56 miria eg25-manager[4722]: Successfully sent command: AT+QCFG="urc/ri/smsincoming"
ago 03 11:06:56 miria eg25-manager[4722]: Response: [+QCFG: "urc/ri/smsincoming","pulse",120,1\r\n\r\nOK]
ago 03 11:06:56 miria eg25-manager[4722]: Successfully sent command: AT+QCFG="urc/ri/other"
ago 03 11:06:56 miria eg25-manager[4722]: Response: [+QCFG: "urc/ri/other","off",1,1\r\n\r\nOK]
ago 03 11:06:56 miria eg25-manager[4722]: Successfully sent command: AT+QCFG="urc/delay"
ago 03 11:06:56 miria eg25-manager[4722]: Response: [+QCFG: "urc/delay",0\r\n\r\nOK]
ago 03 11:06:56 miria eg25-manager[4722]: Successfully sent command: AT+QCFG="urc/cache"
ago 03 11:06:56 miria eg25-manager[4722]: Response: [+QCFG: "urc/cache",0\r\n\r\nOK]
ago 03 11:06:56 miria eg25-manager[4722]: Successfully sent command: AT+QCFG="urc/ri/pin"
ago 03 11:06:56 miria eg25-manager[4722]: Response: [+QCFG: "urc/ri/pin",uart_ri\r\n\r\nOK]
ago 03 11:06:56 miria eg25-manager[4722]: Successfully sent command: AT+QURCCFG="urcport"
ago 03 11:06:56 miria eg25-manager[4722]: Response: [+QURCCFG: "urcport","all"\r\n\r\nOK]
ago 03 11:06:56 miria eg25-manager[4722]: Successfully sent command: AT+QSCLK=1
ago 03 11:06:56 miria eg25-manager[4722]: Response: [OK]
ago 03 11:06:56 miria eg25-manager[4722]: Successfully sent command: AT+QGPSXTRA?
ago 03 11:06:56 miria eg25-manager[4722]: Response: [+QGPSXTRA: 1\r\n\r\nOK]
ago 03 11:06:56 miria eg25-manager[4722]: Successfully sent command: AT+QGPSCFG="gnssconfig"
ago 03 11:06:56 miria eg25-manager[4722]: Response: [+QGPSCFG: "gnssconfig",4\r\n\r\nOK]
ago 03 11:06:56 miria eg25-manager[4722]: Successfully sent command: AT+QGPSCFG="odpcontrol"
ago 03 11:06:56 miria eg25-manager[4722]: Response: [+QGPSCFG: "odpcontrol",0\r\n\r\nOK]
ago 03 11:06:56 miria eg25-manager[4722]: Successfully sent command: AT+QGPSCFG="dpoenable"
ago 03 11:06:56 miria eg25-manager[4722]: Response: [+QGPSCFG: "dpoenable",1\r\n\r\nOK]
ago 03 11:06:56 miria eg25-manager[4722]: Successfully sent command: AT+QGPSCFG="gpsnmeatype"
ago 03 11:06:56 miria eg25-manager[4722]: Response: [+QGPSCFG: "gpsnmeatype",31\r\n\r\nOK]
ago 03 11:06:56 miria eg25-manager[4722]: Successfully sent command: AT+QGPSCFG="glonassnmeatype"
ago 03 11:06:56 miria eg25-manager[4722]: Response: [+QGPSCFG: "glonassnmeatype",7\r\n\r\nOK]
ago 03 11:06:56 miria eg25-manager[4722]: Successfully sent command: AT+QGPSCFG="galileonmeatype"
ago 03 11:06:56 miria eg25-manager[4722]: Response: [+QGPSCFG: "galileonmeatype",0\r\n\r\nOK]
ago 03 11:06:56 miria eg25-manager[4722]: Successfully sent command: AT+QGPSCFG="beidounmeatype"
ago 03 11:06:56 miria eg25-manager[4722]: Response: [+QGPSCFG: "beidounmeatype",0\r\n\r\nOK]
ago 03 11:06:56 miria eg25-manager[4722]: Successfully sent command: AT+QGPSCFG="autogps"
ago 03 11:06:56 miria eg25-manager[4722]: Response: [+QGPSCFG: "autogps",0\r\n\r\nOK]
ago 03 11:06:56 miria eg25-manager[4722]: Successfully sent command: AT+QCFG="fast/poweroff"
ago 03 11:06:56 miria eg25-manager[4722]: Response: [OK]
ago 03 11:06:56 miria eg25-manager[4722]: Got a different result than expected, changing value...
ago 03 11:06:56 miria eg25-manager[4722]: Expected: [0]
ago 03 11:06:56 miria eg25-manager[4722]: Successfully sent command: AT+QCFG="fast/poweroff",0
ago 03 11:06:56 miria eg25-manager[4722]: Response: [OK]
ago 03 11:06:56 miria eg25-manager[4722]: Successfully sent command: AT+QCFG="sleepind/level"
ago 03 11:06:56 miria eg25-manager[4722]: Response: [+QCFG: "sleepind/level",0\r\n\r\nOK]
ago 03 11:06:56 miria eg25-manager[4722]: Successfully sent command: AT+QCFG="wakeupin/level"
ago 03 11:06:56 miria eg25-manager[4722]: Response: [+QCFG: "wakeupin/level",0,0\r\n\r\nOK]
ago 03 11:06:56 miria eg25-manager[4722]: Successfully sent command: AT+QCFG="ApRstLevel"
ago 03 11:06:56 miria eg25-manager[4722]: Response: [OK]
ago 03 11:06:56 miria eg25-manager[4722]: Got a different result than expected, changing value...
ago 03 11:06:56 miria eg25-manager[4722]: Expected: [1]
ago 03 11:06:56 miria eg25-manager[4722]: Successfully sent command: AT+QCFG="ApRstLevel",1
ago 03 11:06:56 miria eg25-manager[4722]: Response: [OK]
ago 03 11:06:56 miria eg25-manager[4722]: Successfully sent command: AT+QCFG="ModemRstLevel"
ago 03 11:06:56 miria eg25-manager[4722]: Response: [OK]
ago 03 11:06:56 miria eg25-manager[4722]: Got a different result than expected, changing value...
ago 03 11:06:56 miria eg25-manager[4722]: Expected: [1]
ago 03 11:06:56 miria eg25-manager[4722]: Successfully sent command: AT+QCFG="ModemRstLevel",1
ago 03 11:06:56 miria eg25-manager[4722]: Response: [OK]
ago 03 11:06:56 miria eg25-manager[4722]: Executed soft sleep sequence
ago 03 11:07:23 miria eg25-manager[4722]: GNSS assistance upload started...
ago 03 11:07:23 miria eg25-manager[4722]: GNSS assistance upload step (1/9): fetching assistance data
ago 03 11:07:24 miria eg25-manager[4722]: Fetching GNSS assistance data from https://xtrapath4.izatcloud.net/xtra2.bin was successful
ago 03 11:07:24 miria eg25-manager[4722]: GNSS assistance upload step (2/9): disabling GNSS engine through ModemManager
ago 03 11:07:24 miria eg25-manager[4722]: GNSS assistance upload step (3/9): disabling GNSS engine through AT+QGPS
ago 03 11:07:25 miria eg25-manager[4722]: Executed soft wake sequence
ago 03 11:07:25 miria eg25-manager[4722]: Successfully sent command: AT+QGPS?
ago 03 11:07:25 miria eg25-manager[4722]: Response: [+QGPS: 0\r\n\r\nOK]
ago 03 11:07:25 miria eg25-manager[4722]: Executed soft sleep sequence
ago 03 11:07:25 miria eg25-manager[4722]: GNSS assistance upload step (4/9): initiating upload
ago 03 11:07:25 miria eg25-manager[4722]: Executed soft wake sequence
ago 03 11:07:25 miria eg25-manager[4722]: Successfully sent command: AT+QFDEL="RAM:*"
ago 03 11:07:25 miria eg25-manager[4722]: Response: [OK]
ago 03 11:07:25 miria eg25-manager[4722]: Executed soft sleep sequence
ago 03 11:07:25 miria eg25-manager[4722]: Initiate GNSS assistance data upload: "RAM:xtra2.bin",59621,10
ago 03 11:07:25 miria eg25-manager[4722]: Executed soft wake sequence
ago 03 11:07:25 miria eg25-manager[4722]: Successfully sent command: AT+QFUPL="RAM:xtra2.bin",59621,10
ago 03 11:07:25 miria eg25-manager[4722]: Response: [CONNECT]
ago 03 11:07:25 miria eg25-manager[4722]: Modem ready for GNSS assistance data upload
ago 03 11:07:25 miria eg25-manager[4722]: GNSS assistance upload step (5/9): uploading assistance data
ago 03 11:07:31 miria eg25-manager[4722]: Successfully uploaded 59621 bytes to the modem
ago 03 11:07:31 miria eg25-manager[4722]: Response: [+QFUPL: 59621,182d\r\n\r\nOK]
ago 03 11:07:31 miria eg25-manager[4722]: Executed soft sleep sequence
ago 03 11:07:31 miria eg25-manager[4722]: GNSS assistance upload step (6/9): finishing upload
ago 03 11:07:31 miria eg25-manager[4722]: Setting GNSS assistance UTC clock to: 0,"2022/08/03,09:07:31"
ago 03 11:07:31 miria eg25-manager[4722]: Setting GNSS assistance file to: "RAM:xtra2.bin"
ago 03 11:07:31 miria eg25-manager[4722]: Executed soft wake sequence
ago 03 11:07:31 miria eg25-manager[4722]: Successfully sent command: AT+QGPSXTRATIME=0,"2022/08/03,09:07:31"
ago 03 11:07:31 miria eg25-manager[4722]: Response: [OK]
ago 03 11:07:31 miria eg25-manager[4722]: Successfully sent command: AT+QGPSXTRADATA="RAM:xtra2.bin"
ago 03 11:07:31 miria eg25-manager[4722]: Response: [OK]
ago 03 11:07:31 miria eg25-manager[4722]: Executed soft sleep sequence
ago 03 11:07:31 miria eg25-manager[4722]: GNSS assistance data upload finished
ago 03 11:07:31 miria eg25-manager[4722]: GNSS assistance upload step (7/9): re-enabling GNSS through ModemManager
ago 03 11:07:31 miria eg25-manager[4722]: Unable to enable GNSS engine through ModemManager: GDBus.Error:org.freedesktop.DBus.Error.UnknownMethod: Object does not exist at path “/org/freedesktop/ModemManager1/Modem/2”
ago 03 11:07:31 miria eg25-manager[4722]: GNSS assistance upload step (8/9): re-enabling GNSS through AT+QGPS
ago 03 11:07:31 miria eg25-manager[4722]: GNSS assistance upload step (9/9): finished
ago 03 11:07:31 miria eg25-manager[4722]: ModemManager object `/org/freedesktop/ModemManager1/Modem/2' removed
ago 03 11:07:32 miria eg25-manager[4722]: Lost modem, resetting...
ago 03 11:07:35 miria eg25-manager[4722]: Trying to reset modem with USB ID '2-1'
ago 03 11:07:35 miria eg25-manager[4722]: Successfully reset modem's USB connection
ago 03 11:07:50 miria eg25-manager[4722]: ModemManager object `/org/freedesktop/ModemManager1/Modem/4' added
ago 03 11:07:50 miria eg25-manager[4722]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Modem3gpp.ProfileManager' found on object `/org/freedesktop/ModemManager1/Modem/4'
ago 03 11:07:50 miria eg25-manager[4722]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Firmware' found on object `/org/freedesktop/ModemManager1/Modem/4'
ago 03 11:07:50 miria eg25-manager[4722]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Modem3gpp' found on object `/org/freedesktop/ModemManager1/Modem/4'
ago 03 11:07:50 miria eg25-manager[4722]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Time' found on object `/org/freedesktop/ModemManager1/Modem/4'
ago 03 11:07:50 miria eg25-manager[4722]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Voice' found on object `/org/freedesktop/ModemManager1/Modem/4'
ago 03 11:07:50 miria eg25-manager[4722]: ModemManager interface `org.freedesktop.ModemManager1.Modem' found on object `/org/freedesktop/ModemManager1/Modem/4'
ago 03 11:07:50 miria eg25-manager[4722]: Adding new modem `/org/freedesktop/ModemManager1/Modem/4'
ago 03 11:07:50 miria eg25-manager[4722]: Executed soft sleep sequence
ago 03 11:07:50 miria eg25-manager[4722]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Messaging' found on object `/org/freedesktop/ModemManager1/Modem/4'
ago 03 11:07:50 miria eg25-manager[4722]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Modem3gpp.Ussd' found on object `/org/freedesktop/ModemManager1/Modem/4'
ago 03 11:07:50 miria eg25-manager[4722]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Signal' found on object `/org/freedesktop/ModemManager1/Modem/4'
ago 03 11:07:50 miria eg25-manager[4722]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Location' found on object `/org/freedesktop/ModemManager1/Modem/4'
ago 03 11:07:50 miria eg25-manager[4722]: Adding new modem with location capabilities `/org/freedesktop/ModemManager1/Modem/4'
ago 03 11:07:50 miria eg25-manager[4722]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Simple' found on object `/org/freedesktop/ModemManager1/Modem/4'
ago 03 11:08:45 miria eg25-manager[4722]: Modem is up for 120 seconds and fully ready
ago 03 11:08:45 miria eg25-manager[4722]: dropping systemd sleep block inhibitor
stacyharper commented 2 years ago

I relate the same issue on pmos with the vanilla setup from the distro. Got the same udevs and same logs. GNSS assistance upload step stop at (3/9). One time I had the 9/9 but other issues came and I didnt had a fix.

edit: after that breaking point, trying to activate the gps again gives this at issue

$ echo "AT+QGPS=1" | atinout - /dev/EG25.AT -
+CME ERROR: 504

edit2: now ACTIVATING or DEACTIVATING does do anything. And sometime later I had this strange message

(eg25-manager:8585): WARNING **: 20:46:02.756: GNSS assistance data upload already in process (3/9)
stacyharper commented 2 years ago

For it to works I had to do :

~I still got issues with gpsd… Following the previous step I manage one time to see GNSS satelites on cgps. I had to mmcli -m any --location-enable-gps-unmanaged. But now I fail to reproduce it…~

edit: restarting gpsd and gpsd_pinephone solved this last part. If GNSS load correctly then only this is necessary for gpsd clients to works mmcli -m any --location-enable-gps-unmanaged

edit2: I confirm that if I only restart eg25-manager I got the issue and never trigger the following steps after step 3

edit3: I added some debug log on eg25-manager. It looks like it really never receive the response to its AT+QGPS request. ModemManager seems to do something in early stages than cause an issue here

Biktorgj commented 2 years ago

I think we all need to stop hogging the AT interface on the modem, and by all I mean both eg25-manager and the firmware. When the modem starts, we're all sending and waiting for arbitrary commands to an AT interface that's shared by three different programs requesting different things at the same time, and things fail.

I'm currently trying to finish some other (unrelated to this particular issue) piece of code, but once I'm done with that I will have to go through my code and try to minimize all interactions with the AT interface so it's free for whatever ModemManager or eg25-manager need (currently it uses it to sync date and time and get network indication data)

k8ieone commented 1 year ago

Hi everyone, I just want to confirm - this is still happening on 0.7.4.

As far as I can tell, development of eg25-manager has kinda dropped off, which is pretty unfortunate :/

bemoody commented 1 year ago

I tried making the following horrible kludge of a patch to eg25-manager:

--- eg25-manager-0.4.6.orig/src/gnss.c
+++ eg25-manager-0.4.6/src/gnss.c
@@ -16,7 +16,7 @@
 #define BUFFER_SIZE 256
 #define UPLOAD_DELAY_US 25000
 #define UPLOAD_TIMEOUT_S 10
-#define RESCHEDULE_IN_SECS 30
+#define RESCHEDULE_IN_SECS 41

 static void gnss_step(struct EG25Manager *manager);

By delaying the GNSS initialization slightly, this seems to sidestep whatever race condition was happening previously, and it successfully reaches GNSS assistance upload step (9/9): finished.

I still haven't yet gotten a fix (maybe because I don't have a clear view of the sky), but I do now see multiple GPGSV and GLGSV lines in the NMEA output, which I didn't see before.

k8ieone commented 1 year ago

@Biktorgj could this please be included in the next release as a temporary fix?

stacyharper commented 1 year ago

@a13xie This is not up to @Biktorgj to include eg25-manager workaround.

Also, I don't think the RESCHEDULE_IN_SECS is in cause. I tried with 90 and still have the problem. I also tried to implement a timeout behavior in eg25-manager GNSS loading workflow. I then tried to sleep a bit between the ModemManager GNSS disabling, and eg25-manager GPS probing, and still. None of this works.

I think there is a problem in the modem firmware, that is triggered by the chaos from both eg25-manager and ModemManager, initiated by eg25-manager GNSS loading workflow.

add: Here the log with my timeout/restart behavior:

** Message: 09:31:48.853: GNSS assistance upload step timeouts! Restarting...
** Message: 09:31:48.853: GNSS assistance upload step (3/9): disabling GNSS engine through AT+QGPS
** Message: 09:31:48.853: Successfully sent command: AT+QGPS?
** Message: 09:31:58.853: GNSS assistance upload step timeouts! Restarting...
** Message: 09:31:58.853: GNSS assistance upload step (3/9): disabling GNSS engine through AT+QGPS
** Message: 09:31:58.853: Successfully sent command: AT+QGPS?
** Message: 09:32:08.853: GNSS assistance upload step timeouts! Restarting...
** Message: 09:32:08.853: GNSS assistance upload step (3/9): disabling GNSS engine through AT+QGPS
** Message: 09:32:08.853: Successfully sent command: AT+QGPS?
** Message: 09:32:18.851: GNSS assistance upload step timeouts! Restarting...
** Message: 09:32:18.851: GNSS assistance upload step (3/9): disabling GNSS engine through AT+QGPS
** Message: 09:32:18.855: Successfully sent command: AT+QGPS?
** Message: 09:32:28.851: GNSS assistance upload step timeouts! Restarting...
** Message: 09:32:28.851: GNSS assistance upload step (3/9): disabling GNSS engine through AT+QGPS
** Message: 09:32:28.852: Successfully sent command: AT+QGPS?
** Message: 09:32:38.853: GNSS assistance upload step timeouts! Restarting...
** Message: 09:32:38.853: GNSS assistance upload step (3/9): disabling GNSS engine through AT+QGPS
** Message: 09:32:38.853: Successfully sent command: AT+QGPS?
** Message: 09:32:48.850: GNSS assistance upload step timeouts! Restarting...
** Message: 09:32:48.850: GNSS assistance upload step (3/9): disabling GNSS engine through AT+QGPS
** Message: 09:32:48.850: Successfully sent command: AT+QGPS?

As we can see, the firmware now refuse to reply to this task. It probably is stucked in this state.

k8ieone commented 1 year ago

Oh, sorry, I read this as soon as I woke up and I missed the part where you mentioned this was a fix to eg25-manager and not the FW.