Endless loop in modem configuration #5849

fdizazzo · 2025-06-11T10:42:28Z

fdizazzo
Jun 11, 2025

Hi everyone! :)

I got a weird issue with a modem on a RaspberryPi running Kura 5.6.0: sometimes when starting up, network configuration gets stuck endlessly rollbacking my network configuration.

Log repeats as follows (debug only enabled on org.eclipse.kura.nm)

2025-06-06T20:02:53,226` [DBus Worker Thread-1] DEBUG o.e.k.n.ModemManagerDbusWrapper - Modem location setup [MM_MODEM_LOCATION_SOURCE_GPS_RAW, MM_MODEM_LOCATION_SOURCE_GPS_NMEA] for modem /org/freedesktop/ModemManager1/Modem/0
2025-06-06T20:02:53,228 [DBus Worker Thread-1] DEBUG o.e.k.n.NMDbusConnector - Network configuration enforcement set to true (Expected: true)
2025-06-06T20:02:55,978 [DBus Worker Thread-4] DEBUG o.e.k.n.s.h.NMConfigurationEnforcementHandler - Device state change detected: NM_DEVICE_STATE_PREPARE -> NM_DEVICE_STATE_CONFIG (reason: NM_DEVICE_STATE_REASON_NONE), for device /org/freedesktop/NetworkManager/Devices/4
2025-06-06T20:02:55,979 [DBus Worker Thread-4] INFO  o.e.k.n.s.h.NMConfigurationEnforcementHandler - Network change detected on interface /org/freedesktop/NetworkManager/Devices/4. Roll-back to cached configuration
2025-06-06T20:02:55,978 [DBus Worker Thread-3] DEBUG o.e.k.n.s.h.NMModemResetHandler - Modem state change detected: NM_DEVICE_STATE_PREPARE -> NM_DEVICE_STATE_CONFIG, for device /org/freedesktop/NetworkManager/Devices/4
2025-06-06T20:02:55,980 [DBus Worker Thread-2] DEBUG o.e.k.n.s.h.NMModemResetHandler - Modem state change detected: NM_DEVICE_STATE_CONFIG -> NM_DEVICE_STATE_IP_CONFIG, for device /org/freedesktop/NetworkManager/Devices/4
2025-06-06T20:02:55,981 [DBus Worker Thread-2] DEBUG o.e.k.n.s.h.NMConfigurationEnforcementHandler - Device state change detected: NM_DEVICE_STATE_CONFIG -> NM_DEVICE_STATE_IP_CONFIG (reason: NM_DEVICE_STATE_REASON_NONE), for device /org/freedesktop/NetworkManager/Devices/4
2025-06-06T20:02:55,984 [DBus Worker Thread-3] DEBUG o.e.k.n.s.h.NMModemResetHandler - Modem state change detected: NM_DEVICE_STATE_IP_CONFIG -> NM_DEVICE_STATE_IP_CHECK, for device /org/freedesktop/NetworkManager/Devices/4
2025-06-06T20:02:55,985 [DBus Worker Thread-3] DEBUG o.e.k.n.s.h.NMConfigurationEnforcementHandler - Device state change detected: NM_DEVICE_STATE_IP_CONFIG -> NM_DEVICE_STATE_IP_CHECK (reason: NM_DEVICE_STATE_REASON_NONE), for device /org/freedesktop/NetworkManager/Devices/4
2025-06-06T20:02:55,987 [DBus Worker Thread-4] DEBUG o.e.k.n.NetworkManagerDbusWrapper - Found DBus path /org/freedesktop/ModemManager1/Modem/0 for modem device /org/freedesktop/NetworkManager/Devices/4
2025-06-06T20:02:55,989 [DBus Worker Thread-2] DEBUG o.e.k.n.s.h.NMConfigurationEnforcementHandler - Device state change detected: NM_DEVICE_STATE_IP_CHECK -> NM_DEVICE_STATE_SECONDARIES (reason: NM_DEVICE_STATE_REASON_NONE), for device /org/freedesktop/NetworkManager/Devices/4
2025-06-06T20:02:55,990 [DBus Worker Thread-3] DEBUG o.e.k.n.s.h.NMModemResetHandler - Modem state change detected: NM_DEVICE_STATE_SECONDARIES -> NM_DEVICE_STATE_ACTIVATED, for device /org/freedesktop/NetworkManager/Devices/4
2025-06-06T20:02:55,990 [DBus Worker Thread-2] DEBUG o.e.k.n.s.h.NMConfigurationEnforcementHandler - Device state change detected: NM_DEVICE_STATE_SECONDARIES -> NM_DEVICE_STATE_ACTIVATED (reason: NM_DEVICE_STATE_REASON_NONE), for device /org/freedesktop/NetworkManager/Devices/4
2025-06-06T20:02:55,989 [DBus Worker Thread-1] DEBUG o.e.k.n.s.h.NMModemResetHandler - Modem state change detected: NM_DEVICE_STATE_IP_CHECK -> NM_DEVICE_STATE_SECONDARIES, for device /org/freedesktop/NetworkManager/Devices/4
2025-06-06T20:02:55,992 [DBus Worker Thread-4] DEBUG o.e.k.n.NMDbusConnector - Network configuration enforcement set to false (Expected: false)
2025-06-06T20:02:55,992 [DBus Worker Thread-4] DEBUG o.e.k.n.s.h.NMModemResetHandler - ModemStateHandler disarmed for /org/freedesktop/NetworkManager/Devices/4
2025-06-06T20:02:56,024 [DBus Worker Thread-4] DEBUG o.e.k.n.NetworkManagerDbusWrapper - Found DBus path /org/freedesktop/ModemManager1/Modem/0 for modem device /org/freedesktop/NetworkManager/Devices/4
2025-06-06T20:02:56,031 [DBus Worker Thread-4] INFO  o.e.k.n.NMDbusConnector - Settings iface "1-1.2":NM_DEVICE_TYPE_MODEM
2025-06-06T20:03:01,138 [DBus Worker Thread-4] WARN  o.e.k.n.s.h.DeviceStateLock - Timeout elapsed. Exiting anyway
2025-06-06T20:03:01,169 [DBus Worker Thread-4] DEBUG o.e.k.n.NetworkManagerDbusWrapper - Found DBus path /org/freedesktop/ModemManager1/Modem/0 for modem device /org/freedesktop/NetworkManager/Devices/4
2025-06-06T20:03:01,170 [DBus Worker Thread-4] DEBUG o.e.k.n.s.h.NMModemResetHandler - ModemStateHandler armed for /org/freedesktop/NetworkManager/Devices/4
2025-06-06T20:03:01,180 [DBus Worker Thread-4] DEBUG o.e.k.n.NetworkManagerDbusWrapper - Found DBus path /org/freedesktop/ModemManager1/Modem/0 for modem device /org/freedesktop/NetworkManager/Devices/4
2025-06-06T20:03:01,191 [DBus Worker Thread-4] DEBUG o.e.k.n.ModemManagerDbusWrapper - Modem location setup [MM_MODEM_LOCATION_SOURCE_GPS_RAW, MM_MODEM_LOCATION_SOURCE_GPS_NMEA] for modem /org/freedesktop/ModemManager1/Modem/0
2025-06-06T20:03:01,193 [DBus Worker Thread-4] DEBUG o.e.k.n.NMDbusConnector - Network configuration enforcement set to true (Expected: true)

If i got this right, only NMConfigurationEnforcementHandler is firing, not NMModemResetHandler.
Looking at the code for NMConfigurationEnforcementHandler we have:

kura/kura/org.eclipse.kura.nm/src/main/java/org/eclipse/kura/nm/signal/handlers/NMConfigurationEnforcementHandler.java

Lines 45 to 59 in 2673f47

    
           boolean deviceDisconnectedBecauseOfConfigurationEvent = oldState != NMDeviceState.NM_DEVICE_STATE_FAILED 
        
                   && oldState != NMDeviceState.NM_DEVICE_STATE_UNAVAILABLE 
        
                   && newState == NMDeviceState.NM_DEVICE_STATE_DISCONNECTED; 
        
           boolean deviceIsConnectingToANewNetwork = newState == NMDeviceState.NM_DEVICE_STATE_CONFIG; 
        
           if (deviceIsConnectingToANewNetwork || deviceDisconnectedBecauseOfConfigurationEvent) { 
        
               try { 
        
                   logger.info("Network change detected on interface {}. Roll-back to cached configuration", s.getPath()); 
        
                   String deviceId = this.nm.getInterfaceIdByDBusPath(s.getPath()); 
        
                   this.nm.apply(deviceId); 
        
               } catch (DBusException e) { 
        
                   logger.error("Failed to handle network configuration change event for device: {}. Caused by:", 
        
                           s.getPath(), e); 
        
               } 
        
           }

Maybe additional states should be added at line 48 for connections requiring additional steps?

Edit for completeness sake: NetworkManager is 1.42.4, Modem manager 1.20.4. Modem connection is LTE running through a private APN.

mattdibi · 2025-06-11T12:18:39Z

mattdibi
Jun 11, 2025
Collaborator

Hi there @fdizazzo thanks for reaching out.

This doesn't look good 🤔

So... as a refresher IIRC the modem logic goes like this:

NMConfigurationEnforcementHandler are suspended
Configuration is applied to NM
Kura waits for the device to connect, if not it returns anyway
Once configuration is applied it sets up the NMConfigurationEnforcementHandler to check that the configuration is not tampered with, if so it reapplies it.

The thing here is that... NMConfigurationEnforcementHandler should fire only if when NM fires a particular event (like you noted above). What's going on here? I think there's only two possible causes:

The modem disconnects and thus the event is fired (which would mean further investigation on the MM/modem side is needed)
The modem is still trying to connect when Kura reinstates the NMConfigurationEnforcementHandler and the modem connecting fires the configuration roll-back (which would be bad)

I think you can:

Monitor the events being fired on the DBus to understand what's going on with the modem connection and understand if the Kura behaviour is legitimate (disconnection) or not (connection)[1]
See if the latest version of Kura develop handles this behaviour correctly (we recently reworked that in feat(nm): Modem autoreconnection #5762)

[1] Example command for monitoring dbus signals

dbus-monitor --system "type='signal',interface='org.freedesktop.NetworkManager.Device'"

0 replies

fdizazzo · 2025-06-11T13:27:12Z

fdizazzo
Jun 11, 2025
Author

Hi and thanks for the quick response :)

Here's how the loop runs on dbus:

signal time=1749644301.559383 sender=:1.8 -> destination=(null destination) serial=1095 path=/org/freedesktop/NetworkManager/Devices/4; interface=org.freedesktop.NetworkManager.Device; member=StateChanged
   uint32 40
   uint32 30
   uint32 0
signal time=1749644301.560503 sender=:1.8 -> destination=(null destination) serial=1103 path=/org/freedesktop/NetworkManager/Devices/4; interface=org.freedesktop.NetworkManager.Device; member=StateChanged
   uint32 60
   uint32 40
   uint32 0
signal time=1749644301.562138 sender=:1.8 -> destination=(null destination) serial=1110 path=/org/freedesktop/NetworkManager/Devices/4; interface=org.freedesktop.NetworkManager.Device; member=StateChanged
   uint32 40
   uint32 60
   uint32 0
signal time=1749644308.570684 sender=:1.8 -> destination=(null destination) serial=1134 path=/org/freedesktop/NetworkManager/Devices/4; interface=org.freedesktop.NetworkManager.Device; member=StateChanged
   uint32 50
   uint32 40
   uint32 0
signal time=1749644308.572883 sender=:1.8 -> destination=(null destination) serial=1138 path=/org/freedesktop/NetworkManager/Devices/4; interface=org.freedesktop.NetworkManager.Device; member=StateChanged
   uint32 70
   uint32 50
   uint32 0
signal time=1749644308.582645 sender=:1.8 -> destination=(null destination) serial=1147 path=/org/freedesktop/NetworkManager/Devices/4; interface=org.freedesktop.NetworkManager.Device; member=StateChanged
   uint32 80
   uint32 70
   uint32 0
signal time=1749644308.595423 sender=:1.8 -> destination=(null destination) serial=1157 path=/org/freedesktop/NetworkManager/Devices/4; interface=org.freedesktop.NetworkManager.Device; member=StateChanged
   uint32 90
   uint32 80
   uint32 0
signal time=1749644308.595908 sender=:1.8 -> destination=(null destination) serial=1160 path=/org/freedesktop/NetworkManager/Devices/4; interface=org.freedesktop.NetworkManager.Device; member=StateChanged
   uint32 100
   uint32 90
   uint32 0
signal time=1749644308.801686 sender=:1.8 -> destination=(null destination) serial=1201 path=/org/freedesktop/NetworkManager/Devices/4; interface=org.freedesktop.NetworkManager.Device; member=StateChanged
   uint32 110
   uint32 100
   uint32 60
signal time=1749644309.554920 sender=:1.8 -> destination=(null destination) serial=1236 path=/org/freedesktop/NetworkManager/Devices/4; interface=org.freedesktop.NetworkManager.Device; member=StateChanged
   uint32 30
   uint32 110
   uint32 60
signal time=1749644309.558842 sender=:1.8 -> destination=(null destination) serial=1252 path=/org/freedesktop/NetworkManager/Devices/4; interface=org.freedesktop.NetworkManager.Device; member=StateChanged
   uint32 40
   uint32 30
   uint32 0

with those two not appearing in kura logs

signal time=1749644308.801686 sender=:1.8 -> destination=(null destination) serial=1201 path=/org/freedesktop/NetworkManager/Devices/4; interface=org.freedesktop.NetworkManager.Device; member=StateChanged
   uint32 110
   uint32 100
   uint32 60
signal time=1749644309.554920 sender=:1.8 -> destination=(null destination) serial=1236 path=/org/freedesktop/NetworkManager/Devices/4; interface=org.freedesktop.NetworkManager.Device; member=StateChanged
   uint32 30
   uint32 110
   uint32 60

Looks like there's a disconnection due to a new connection request.
I've tried stopping Kura and the connection remained stable until i started it again, with the same behaviour.

0 replies

fdizazzo · 2025-06-11T14:13:10Z

fdizazzo
Jun 11, 2025
Author

Also, not sure if relevant,
a "good" boot logs like this

2025-06-11T15:49:38,574 [Start Level: Equinox Container: e6d94e0e-7d76-4fee-a02e-96cdc077aa7d] DEBUG o.e.k.n.NetworkManagerDbusWrapper - Found DBus path /org/freedesktop/ModemManager1/Modem/0 for modem device /org/freedesktop/NetworkManager/Devices/4
2025-06-11T15:49:38,586 [Start Level: Equinox Container: e6d94e0e-7d76-4fee-a02e-96cdc077aa7d] INFO  o.e.k.n.NMDbusConnector - Settings iface "1-1.2":NM_DEVICE_TYPE_MODEM
2025-06-11T15:49:39,397 [DBus Worker Thread-2] DEBUG o.e.k.n.s.h.NMDeviceStateChangeHandler - Notify waiting thread
2025-06-11T15:49:39,460 [Start Level: Equinox Container: e6d94e0e-7d76-4fee-a02e-96cdc077aa7d] DEBUG o.e.k.n.NetworkManagerDbusWrapper - Found DBus path /org/freedesktop/ModemManager1/Modem/0 for modem device /org/freedesktop/NetworkManager/Devices/4
2025-06-11T15:49:39,475 [Start Level: Equinox Container: e6d94e0e-7d76-4fee-a02e-96cdc077aa7d] DEBUG o.e.k.n.s.h.NMModemResetHandler - ModemStateHandler armed for /org/freedesktop/NetworkManager/Devices/4
2025-06-11T15:49:39,503 [Start Level: Equinox Container: e6d94e0e-7d76-4fee-a02e-96cdc077aa7d] DEBUG o.e.k.n.NetworkManagerDbusWrapper - Found DBus path /org/freedesktop/ModemManager1/Modem/0 for modem device /org/freedesktop/NetworkManager/Devices/4
2025-06-11T15:49:39,536 [Start Level: Equinox Container: e6d94e0e-7d76-4fee-a02e-96cdc077aa7d] DEBUG o.e.k.n.ModemManagerDbusWrapper - Modem location setup [MM_MODEM_LOCATION_SOURCE_3GPP_LAC_CI] for modem /org/freedesktop/ModemManager1/Modem/0
2025-06-11T15:49:39,779 [Start Level: Equinox Container: e6d94e0e-7d76-4fee-a02e-96cdc077aa7d] DEBUG o.e.k.n.NMDbusConnector - Network configuration enforcement set to true (Expected: true)
2025-06-11T15:49:39,866 [Start Level: Equinox Container: e6d94e0e-7d76-4fee-a02e-96cdc077aa7d] DEBUG o.e.k.n.NetworkManagerDbusWrapper - Found DBus path /org/freedesktop/ModemManager1/Modem/0 for modem device /org/freedesktop/NetworkManager/Devices/4
2025-06-11T15:49:41,012 [Start Level: Equinox Container: e6d94e0e-7d76-4fee-a02e-96cdc077aa7d] INFO  o.e.k.n.c.NMConfigurationServiceImpl - Update NetworkConfigurationService... Done.
2025-06-11T15:49:41,012 [DnsMonitorServiceImpl] DEBUG o.e.k.n.c.m.DnsServerMonitor - DnsMonitor task start
2025-06-11T15:49:41,013 [Start Level: Equinox Container: e6d94e0e-7d76-4fee-a02e-96cdc077aa7d] INFO  o.e.k.n.c.NMConfigurationServiceImpl - Activate NetworkConfigurationService... Done.
2025-06-11T15:49:41,014 [Start Level: Equinox Container: e6d94e0e-7d76-4fee-a02e-96cdc077aa7d] INFO  o.e.k.c.c.ConfigurationServiceImpl - Registering SelfConfiguringComponent - org.eclipse.kura.net.admin.NetworkConfigurationService....
2025-06-11T15:49:41,015 [Start Level: Equinox Container: e6d94e0e-7d76-4fee-a02e-96cdc077aa7d] INFO  o.e.k.c.c.ConfigurationServiceImpl - Registering SelfConfiguringComponent - org.eclipse.kura.net.admin.NetworkConfigurationService....Done
2025-06-11T15:49:41,021 [Start Level: Equinox Container: e6d94e0e-7d76-4fee-a02e-96cdc077aa7d] INFO  o.e.k.n.s.NMStatusServiceImpl - Activate NMStatusService...
2025-06-11T15:49:41,021 [Start Level: Equinox Container: e6d94e0e-7d76-4fee-a02e-96cdc077aa7d] INFO  o.e.k.n.s.NMStatusServiceImpl - Activate NMStatusService... Done.

leading to a stable connection, while a bad one is

2025-06-11T14:17:41,120 [Start Level: Equinox Container: 747ea6f0-6ca6-41ca-85b5-c8fa8fa272c2] INFO  o.e.k.n.NMDbusConnector - Settings iface "1-1.2":NM_DEVICE_TYPE_MODEM
2025-06-11T14:17:41,388 [AbstractNtpClockSyncProvider:schedule] INFO  o.e.k.l.c.AbstractNtpClockSyncProvider - Try to sync clock (22)
2025-06-11T14:17:41,389 [AbstractNtpClockSyncProvider:schedule] WARN  o.e.k.l.c.JavaNtpClockSyncProvider - Error while synchronizing System Clock with NTP host [redacted :)]. Please verify network connectivity ...
2025-06-11T14:17:42,388 [AbstractNtpClockSyncProvider:schedule] INFO  o.e.k.l.c.AbstractNtpClockSyncProvider - Try to sync clock (23)
2025-06-11T14:17:42,389 [AbstractNtpClockSyncProvider:schedule] WARN  o.e.k.l.c.JavaNtpClockSyncProvider - Error while synchronizing System Clock with NTP host [redacted :)]. Please verify network connectivity ...
2025-06-11T14:17:43,388 [AbstractNtpClockSyncProvider:schedule] INFO  o.e.k.l.c.AbstractNtpClockSyncProvider - Try to sync clock (24)
2025-06-11T14:17:43,389 [AbstractNtpClockSyncProvider:schedule] WARN  o.e.k.l.c.JavaNtpClockSyncProvider - Error while synchronizing System Clock with NTP host [redacted :)]. Please verify network connectivity ...
2025-06-11T14:17:44,388 [AbstractNtpClockSyncProvider:schedule] INFO  o.e.k.l.c.AbstractNtpClockSyncProvider - Try to sync clock (25)
2025-06-11T14:17:44,390 [AbstractNtpClockSyncProvider:schedule] WARN  o.e.k.l.c.JavaNtpClockSyncProvider - Error while synchronizing System Clock with NTP host [redacted :)]. Please verify network connectivity ...
2025-06-11T14:17:45,388 [AbstractNtpClockSyncProvider:schedule] INFO  o.e.k.l.c.AbstractNtpClockSyncProvider - Try to sync clock (26)
2025-06-11T14:17:45,389 [AbstractNtpClockSyncProvider:schedule] WARN  o.e.k.l.c.JavaNtpClockSyncProvider - Error while synchronizing System Clock with NTP host [redacted :)]. Please verify network connectivity ...
2025-06-11T14:17:46,244 [Start Level: Equinox Container: 747ea6f0-6ca6-41ca-85b5-c8fa8fa272c2] WARN  o.e.k.n.s.h.DeviceStateLock - Timeout elapsed. Exiting anyway
2025-06-11T14:17:46,273 [Start Level: Equinox Container: 747ea6f0-6ca6-41ca-85b5-c8fa8fa272c2] DEBUG o.e.k.n.NetworkManagerDbusWrapper - Found DBus path /org/freedesktop/ModemManager1/Modem/0 for modem device /org/freedesktop/NetworkManager/Devices/4
2025-06-11T14:17:46,284 [Start Level: Equinox Container: 747ea6f0-6ca6-41ca-85b5-c8fa8fa272c2] DEBUG o.e.k.n.s.h.NMModemResetHandler - ModemStateHandler armed for /org/freedesktop/NetworkManager/Devices/4
2025-06-11T14:17:46,295 [Start Level: Equinox Container: 747ea6f0-6ca6-41ca-85b5-c8fa8fa272c2] DEBUG o.e.k.n.NetworkManagerDbusWrapper - Found DBus path /org/freedesktop/ModemManager1/Modem/0 for modem device /org/freedesktop/NetworkManager/Devices/4
2025-06-11T14:17:46,311 [Start Level: Equinox Container: 747ea6f0-6ca6-41ca-85b5-c8fa8fa272c2] DEBUG o.e.k.n.ModemManagerDbusWrapper - Modem location setup [MM_MODEM_LOCATION_SOURCE_3GPP_LAC_CI] for modem /org/freedesktop/ModemManager1/Modem/0
2025-06-11T14:17:46,389 [AbstractNtpClockSyncProvider:schedule] INFO  o.e.k.l.c.AbstractNtpClockSyncProvider - Try to sync clock (27)
2025-06-11T14:17:46,390 [AbstractNtpClockSyncProvider:schedule] WARN  o.e.k.l.c.JavaNtpClockSyncProvider - Error while synchronizing System Clock with NTP host [redacted :)]. Please verify network connectivity ...
2025-06-11T14:17:46,508 [Start Level: Equinox Container: 747ea6f0-6ca6-41ca-85b5-c8fa8fa272c2] DEBUG o.e.k.n.NMDbusConnector - Network configuration enforcement set to true (Expected: true)
2025-06-11T14:17:46,641 [Start Level: Equinox Container: 747ea6f0-6ca6-41ca-85b5-c8fa8fa272c2] DEBUG o.e.k.n.NetworkManagerDbusWrapper - Found DBus path /org/freedesktop/ModemManager1/Modem/0 for modem device /org/freedesktop/NetworkManager/Devices/4
2025-06-11T14:17:47,388 [AbstractNtpClockSyncProvider:schedule] INFO  o.e.k.l.c.AbstractNtpClockSyncProvider - Try to sync clock (28)
2025-06-11T14:17:47,389 [AbstractNtpClockSyncProvider:schedule] WARN  o.e.k.l.c.JavaNtpClockSyncProvider - Error while synchronizing System Clock with NTP host [redacted :)]. Please verify network connectivity ...
2025-06-11T14:17:47,672 [Start Level: Equinox Container: 747ea6f0-6ca6-41ca-85b5-c8fa8fa272c2] INFO  o.e.k.n.c.NMConfigurationServiceImpl - Update NetworkConfigurationService... Done.
2025-06-11T14:17:47,672 [DnsMonitorServiceImpl] DEBUG o.e.k.n.c.m.DnsServerMonitor - DnsMonitor task start
2025-06-11T14:17:47,673 [Start Level: Equinox Container: 747ea6f0-6ca6-41ca-85b5-c8fa8fa272c2] INFO  o.e.k.n.c.NMConfigurationServiceImpl - Activate NetworkConfigurationService... Done.
2025-06-11T14:17:47,676 [Start Level: Equinox Container: 747ea6f0-6ca6-41ca-85b5-c8fa8fa272c2] INFO  o.e.k.c.c.ConfigurationServiceImpl - Registering SelfConfiguringComponent - org.eclipse.kura.net.admin.NetworkConfigurationService....
2025-06-11T14:17:47,676 [Start Level: Equinox Container: 747ea6f0-6ca6-41ca-85b5-c8fa8fa272c2] INFO  o.e.k.c.c.ConfigurationServiceImpl - Registering SelfConfiguringComponent - org.eclipse.kura.net.admin.NetworkConfigurationService....Done
2025-06-11T14:17:47,683 [Start Level: Equinox Container: 747ea6f0-6ca6-41ca-85b5-c8fa8fa272c2] INFO  o.e.k.n.s.NMStatusServiceImpl - Activate NMStatusService...
2025-06-11T14:17:47,683 [Start Level: Equinox Container: 747ea6f0-6ca6-41ca-85b5-c8fa8fa272c2] INFO  o.e.k.n.s.NMStatusServiceImpl - Activate NMStatusService... Done.
[...unrelated logs...]
2025-06-11T14:17:57,754 [DBus Worker Thread-4] DEBUG o.e.k.n.s.h.NMModemResetHandler - Modem state change detected: NM_DEVICE_STATE_PREPARE -> NM_DEVICE_STATE_CONFIG, for device /org/freedesktop/NetworkManager/Devices/4
2025-06-11T14:17:57,758 [DBus Worker Thread-4] DEBUG o.e.k.n.s.h.NMConfigurationEnforcementHandler - Device state change detected: NM_DEVICE_STATE_PREPARE -> NM_DEVICE_STATE_CONFIG (reason: NM_DEVICE_STATE_REASON_NONE), for device /org/freedesktop/NetworkManager/Devices/4
2025-06-11T14:17:57,760 [DBus Worker Thread-3] DEBUG o.e.k.n.s.h.NMModemResetHandler - Modem state change detected: NM_DEVICE_STATE_IP_CONFIG -> NM_DEVICE_STATE_IP_CHECK, for device /org/freedesktop/NetworkManager/Devices/4
2025-06-11T14:17:57,761 [DBus Worker Thread-4] INFO  o.e.k.n.s.h.NMConfigurationEnforcementHandler - Network change detected on interface /org/freedesktop/NetworkManager/Devices/4. Roll-back to cached configuration
2025-06-11T14:17:57,761 [DBus Worker Thread-3] DEBUG o.e.k.n.s.h.NMConfigurationEnforcementHandler - Device state change detected: NM_DEVICE_STATE_IP_CONFIG -> NM_DEVICE_STATE_IP_CHECK (reason: NM_DEVICE_STATE_REASON_NONE), for device /org/freedesktop/NetworkManager/Devices/4
2025-06-11T14:17:57,760 [DBus Worker Thread-2] DEBUG o.e.k.n.s.h.NMConfigurationEnforcementHandler - Device state change detected: NM_DEVICE_STATE_CONFIG -> NM_DEVICE_STATE_IP_CONFIG (reason: NM_DEVICE_STATE_REASON_NONE), for device /org/freedesktop/NetworkManager/Devices/4
2025-06-11T14:17:57,761 [DBus Worker Thread-1] DEBUG o.e.k.n.s.h.NMModemResetHandler - Modem state change detected: NM_DEVICE_STATE_CONFIG -> NM_DEVICE_STATE_IP_CONFIG, for device /org/freedesktop/NetworkManager/Devices/4
2025-06-11T14:17:57,779 [DBus Worker Thread-4] DEBUG o.e.k.n.NetworkManagerDbusWrapper - Found DBus path /org/freedesktop/ModemManager1/Modem/0 for modem device /org/freedesktop/NetworkManager/Devices/4

Looking like if the initialization exceed the expected 5 seconds, when it finally works it get rolled back as unexpected behaviour.

4 replies

mattdibi Jun 11, 2025
Collaborator

🤔 Let's try something silly: what happens if you increase the timeout for the DeviceStateLock here?

fdizazzo Jun 11, 2025
Author

Due to the seemingly random nature of the issue I went event sillier with this.latch.await(1, TimeUnit.MILLISECONDS); and it happens 100% of the time.
Now testing 30 seconds and it looks fine, but I'm taking some more time to be sure I'm not just being lucky :)

mattdibi Jun 12, 2025
Collaborator

Ok, this seals the deal for me: this is a bug in the configuration enforcement logic that puts Kura in a meta-stable state. Unfortunately this seems to be time/HW dependent (and maybe even related to the APN) thus we didn't find it during our QAs.

I'm moving this to the Issue queue and will tag it as bug. I'll talk to the rest of the team and understand how we want to handle it.

mattdibi Jun 12, 2025
Collaborator

The current plan is to fix the bug in Kura 6.0.0 and backport it to the maintenance branch of 5.6. There's currently no plan for a 5.6.1 release though.

@fdizazzo can you share additional information about the modem and the APN setup? Brand, FW version etc. whatever helps in reproducing the issue?

fdizazzo · 2025-06-12T09:21:02Z

fdizazzo
Jun 12, 2025
Author

I'm using this modem on a Raspberry4, connected on a usb3 port.
Details from mmcli as follows:

 -----------------------------------
  Hardware |            manufacturer: QUALCOMM INCORPORATED
           |                   model: SIMCOM_SIM7600E-H
           |       firmware revision: LE20B04SIM7600M22
           |          carrier config: ROW_Gen_VoLTE
           | carrier config revision: 05010822
           |            h/w revision: 10000
           |               supported: gsm-umts, lte
           |                 current: gsm-umts, lte
           |            equipment id: [redacted :)]
  -----------------------------------
  System   |                  device: /sys/devices/platform/scb/fd500000.pcie/pci0000:00/0000:00:00.0/0000:01:00.0/usb1/1-1/1-1.2
           |                 drivers: option, qmi_wwan
           |                  plugin: simtech
           |            primary port: cdc-wdm0
           |                   ports: cdc-wdm0 (qmi), ttyUSB0 (ignored), ttyUSB1(gps),
           |                          ttyUSB2 (at), ttyUSB3 (at), ttyUSB4 (audio), wwan0 (net)
  -----------------------------------

NetworkManager is 1.42.4, Modem manager 1.20.4, OS is

Operating System: Debian GNU/Linux 12 (bookworm)
          Kernel: Linux 6.6.51+rpt-rpi-v8
    Architecture: arm64

The issue is probably caused by the APN authentication and routing, taking 15 to 20 seconds when tested after a >1 hour power off, while being well under 5 seconds on a reboot or service restart.

1 reply

mattdibi Jun 12, 2025
Collaborator

Thanks 🙏

pierantoniomerlino · 2025-06-19T07:59:59Z

pierantoniomerlino
Jun 19, 2025
Collaborator

Addressed in #5858

0 replies

pierantoniomerlino · 2025-07-04T08:03:17Z

pierantoniomerlino
Jul 4, 2025
Collaborator

Hi @mattdibi @fdizazzo!

The #5858 is completed and merged. So, if you have time, please test the fix on your environment. Any feedback is welcome.

0 replies

Endless loop in modem configuration #5849

Uh oh!

Uh oh!

fdizazzo Jun 11, 2025

Replies: 6 comments · 5 replies

Uh oh!

Uh oh!

mattdibi Jun 11, 2025 Collaborator

Uh oh!

fdizazzo Jun 11, 2025 Author

Uh oh!

fdizazzo Jun 11, 2025 Author

Uh oh!

mattdibi Jun 11, 2025 Collaborator

Uh oh!

fdizazzo Jun 11, 2025 Author

Uh oh!

Uh oh!

mattdibi Jun 12, 2025 Collaborator

Uh oh!

mattdibi Jun 12, 2025 Collaborator

Uh oh!

fdizazzo Jun 12, 2025 Author

Uh oh!

mattdibi Jun 12, 2025 Collaborator

Uh oh!

pierantoniomerlino Jun 19, 2025 Collaborator

Uh oh!

pierantoniomerlino Jul 4, 2025 Collaborator

fdizazzo
Jun 11, 2025

Replies: 6 comments 5 replies

mattdibi
Jun 11, 2025
Collaborator

fdizazzo
Jun 11, 2025
Author

fdizazzo
Jun 11, 2025
Author

mattdibi Jun 11, 2025
Collaborator

fdizazzo Jun 11, 2025
Author

mattdibi Jun 12, 2025
Collaborator

mattdibi Jun 12, 2025
Collaborator

fdizazzo
Jun 12, 2025
Author

mattdibi Jun 12, 2025
Collaborator

pierantoniomerlino
Jun 19, 2025
Collaborator

pierantoniomerlino
Jul 4, 2025
Collaborator