ffc-unlock error handling

[Dan Williams]

On Wed, 2025-03-26 at 21:19 +0100, Jan Trejbal wrote:
> Hi,
> I have spent some time on my
> 08:00.0 Wireless controller [0d40]: MEDIATEK Corp. T700 5G Modem [5G
> Solution 5000] (rev 01)
> The reason why it was not working from the start was that in my
> initial setup I had no xxd binary. I did not see any related error
> log in journalctl, neither when I run ModemManager in terminal. Is it
> possible to improve error handling?

Yeah, that seems unhelpful.  Probably due to:

    self->priv->launcher = g_subprocess_launcher_new
(G_SUBPROCESS_FLAGS_STDOUT_SILENCE |
G_SUBPROCESS_FLAGS_STDERR_SILENCE);

in the dispatcher code. We should probably hook the spawned fccunlock
binary's output to MM's log infrastructure so it ends up the same
place.

Would you mind filing an issue at
https://gitlab.freedesktop.org/mobile-broadband/ModemManager/-/issues/new
so we can track it and won't forget?

Thanks!
Dan

> 
> Thank you for your work, this was just a cosmetic issue, but hard to
> find, when you do not know where to look.
> 
> See the fcc-unlock:
> https://github.com/linux-mobile-broadband/ModemManager/blob/main/data/dispatcher-fcc-unlock/14c3#L64
> 
> FCC_UNLOCK_DEBUG_LOG=1 /usr/bin/ModemManager
> ModemManager[31402]: <msg> ModemManager (version 1.23.95-dev-1)
> starting in system bus...
> ModemManager[31402]: <msg> [wwan0mbim0/probe] probe step: start
> ModemManager[31402]: <msg> [wwan0mbim0/probe] probe step: MBIM
> ModemManager[31402]: <msg> [wwan0at0/probe] probe step: start
> ModemManager[31402]: <msg> [wwan0at0/probe] probe step: AT open port
> ModemManager[31402]: <msg> [wwan0at0/probe] probe step: AT
> ModemManager[31402]: <msg> [wwan0at0/probe] probe step: AT close port
> ModemManager[31402]: <msg> [wwan0at0/probe] probe step: done
> ModemManager[31402]: <msg> [wwan0mbim0/mbim] Skipping QMI support
> check in MBIM device
> ModemManager[31402]: <msg> [wwan0mbim0/probe] probe step: done
> ModemManager[31402]: <msg> [base-manager] couldn't check support for
> device '/sys/devices/pci0000:00/0000:00:14.3': not supported by any
> plugin
> ModemManager[31402]: <msg> [device
> /sys/devices/pci0000:00/0000:00:1c.0/0000:08:00.0] creating modem
> with plugin 'mtk' and '3' ports (1cf8:14c3:4d75)
> ModemManager[31402]: <msg> [base-manager] modem for device
> '/sys/devices/pci0000:00/0000:00:1c.0/0000:08:00.0' successfully
> created
> ModemManager[31402]: <msg> [base-manager] running setup for device
> '/sys/devices/pci0000:00/0000:00:1c.0/0000:08:00.0'...
> ModemManager[31402]: <msg> [modem0/wwan0mbim0/mbim] Skipping QMI
> support check in MBIM device
> ModemManager[31402]: <msg> [modem0/wwan0mbim0/mbim] (shared-fibocom)
> MBIM device is AT capable
> ModemManager[31402]: <msg> [modem0] state changed (unknown ->
> disabled)
> ModemManager[31402]: <msg> [modem0] state changed (disabled ->
> enabling)
> ModemManager[31402]: <wrn> [modem0] Cannot power-up: hardware radio
> switch is OFF
> ModemManager[31402]: <wrn> [modem0] Cannot power-up: hardware radio
> switch is OFF
> ModemManager[31402]: <wrn> [modem0] couldn't enable interface:
> 'Invalid transition'
> ModemManager[31402]: <wrn> [modem0] port wwan0at0 timed out 2
> consecutive times
> ModemManager[31402]: <wrn> [modem0] port wwan0at0 timed out 3
> consecutive times
> ModemManager[31402]: <msg> [modem0] state changed (enabling ->
> disabled)
> ModemManager[31402]: <wrn> [modem0] failed enabling modem: Invalid
> transition
> ^CModemManager[31402]: <msg> caught signal, shutting down...
> ModemManager[31402]: <msg> ModemManager is shut down
> 
> Journalctl:
> e 26 17:47:25 cross ModemManager[28745]: <msg> ModemManager (version
> 1.23.95-dev-1) starting in system bus...
> bře 26 17:47:25 cross NetworkManager[1207]: <info>  [1743007645.8846]
> modem-manager: ModemManager now available
> bře 26 17:47:27 cross ModemManager[28745]: <msg> [wwan0mbim0/probe]
> probe step: start
> bře 26 17:47:27 cross ModemManager[28745]: <msg> [wwan0mbim0/probe]
> probe step: MBIM
> bře 26 17:47:27 cross ModemManager[28745]: <msg> [wwan0at0/probe]
> probe step: start
> bře 26 17:47:27 cross ModemManager[28745]: <msg> [wwan0at0/probe]
> probe step: AT open port
> bře 26 17:47:27 cross ModemManager[28745]: <msg> [wwan0at0/probe]
> probe step: AT
> bře 26 17:47:28 cross ModemManager[28745]: <msg> [wwan0at0/probe]
> probe step: AT close port
> bře 26 17:47:28 cross ModemManager[28745]: <msg> [wwan0at0/probe]
> probe step: done
> bře 26 17:47:28 cross ModemManager[28745]: <msg> [wwan0mbim0/mbim]
> Skipping QMI support check in MBIM device
> bře 26 17:47:28 cross ModemManager[28745]: <msg> [wwan0mbim0/probe]
> probe step: done
> bře 26 17:47:29 cross ModemManager[28745]: <msg> [base-manager]
> couldn't check support for device
> '/sys/devices/pci0000:00/0000:00:14.3': not supported by any plugin
> bře 26 17:47:29 cross ModemManager[28745]: <msg> [device
> /sys/devices/pci0000:00/0000:00:1c.0/0000:08:00.0] creating modem
> with plugin 'mtk' and '3' ports (1cf8:14c3:4d75)
> bře 26 17:47:29 cross ModemManager[28745]: <msg> [base-manager] modem
> for device '/sys/devices/pci0000:00/0000:00:1c.0/0000:08:00.0'
> successfully created
> bře 26 17:47:29 cross ModemManager[28745]: <msg> [base-manager]
> running setup for device
> '/sys/devices/pci0000:00/0000:00:1c.0/0000:08:00.0'...
> bře 26 17:47:29 cross ModemManager[28745]: <msg>
> [modem0/wwan0mbim0/mbim] Skipping QMI support check in MBIM device
> bře 26 17:47:29 cross ModemManager[28745]: <msg>
> [modem0/wwan0mbim0/mbim] (shared-fibocom) MBIM device is AT capable
> bře 26 17:47:30 cross ModemManager[28745]: <msg> [modem0] state
> changed (unknown -> disabled)
> bře 26 17:47:30 cross NetworkManager[1207]: <info>  [1743007650.8794]
> manager: (wwan0mbim0): new Broadband device
> (/org/freedesktop/NetworkManager/Devices/5)
> bře 26 17:47:30 cross NetworkManager[1207]: <info>  [1743007650.8795]
> device (wwan0mbim0): state change: unmanaged -> unavailable (reason
> 'managed', managed-type: 'external')
> bře 26 17:47:30 cross NetworkManager[1207]: <info>  [1743007650.8796]
> device (wwan0mbim0): modem state 'enabling'
> bře 26 17:47:30 cross NetworkManager[1207]: <info>  [1743007650.8798]
> device (wwan0mbim0): state change: unavailable -> disconnected
> (reason 'none', managed-type: 'full')
> bře 26 17:47:30 cross ModemManager[28745]: <msg> [modem0] state
> changed (disabled -> enabling)
> bře 26 17:47:30 cross ModemManager[28745]: <wrn> [modem0] Cannot
> power-up: hardware radio switch is OFF
> bře 26 17:47:35 cross ModemManager[28745]: <wrn> [modem0] Cannot
> power-up: hardware radio switch is OFF
> bře 26 17:47:35 cross ModemManager[28745]: <wrn> [modem0] couldn't
> enable interface: 'Invalid transition'
> bře 26 17:47:41 cross ModemManager[28745]: <wrn> [modem0] port
> wwan0at0 timed out 2 consecutive times
> bře 26 17:47:44 cross ModemManager[28745]: <wrn> [modem0] port
> wwan0at0 timed out 3 consecutive times
> bře 26 17:47:44 cross ModemManager[28745]: <msg> [modem0] state
> changed (enabling -> disabled)
> bře 26 17:47:44 cross ModemManager[28745]: <wrn> [modem0] failed
> enabling modem: Invalid transition
> bře 26 17:47:44 cross NetworkManager[1207]: <warn>  [1743007664.8720]
> modem-broadband[wwan0mbim0]: failed to enable modem:
> GDBus.Error:org.freedesktop.ModemManager1.Error.Core.Retry: Retry:
> Invalid transition
> bře 26 17:47:45 cross kernel: mtk_t7xx 0000:08:00.0: Port AT is not
> opened, drop packets
> bře 26 17:47:45 cross kernel: mtk_t7xx 0000:08:00.0: Port AT is not
> opened, drop packets
> bře 26 17:47:45 cross kernel: mtk_t7xx 0000:08:00.0: Port AT is not
> opened, drop packets
> bře 26 17:47:45 cross kernel: mtk_t7xx 0000:08:00.0: Port AT is not
> opened, drop packets
> 
> For the record, I am on manjaro, Gnome.
> 
> Have a nice day,
> Jan Trejbal