"connections-read" signal not emitted reliably?

[Aleksander Morgado <aleksander aleksander es>]

Hey,

Using NM 0.9.8.8 and seeing an issue with the "connections-read"
callback in NMClient.RemoteSettings; basically, the callback isn't
being fired. This only seems to happen if NM is started and right away
(after NM is in the bus) a program creates a NMClient.RemoteSettings
and connects to the signal. Any idea?

Log below shows the issue. There's a "Modem" systemd service which has
both NM and MM as dependencies; so it will be started when these both
have started. The "Modem" service will just run a python script, and
the first thing the python script does is creating a
NMClient.RemoteSettings object and connecting to the
"connections-read" signal. The code is really the same as the one in
the "examples/python/gi/list-connections.py" example.

Jun 24 08:34:38 K5435 systemd[1]: Starting Modem Manager...
Jun 24 08:34:38 K5435 systemd[1]: Starting Network Manager...
Jun 24 08:34:38 K5435 ModemManager[428]: <info>  ModemManager (version
1.2.0) starting...
Jun 24 08:34:38 K5435 NetworkManager[432]: <info> NetworkManager
(version 0.9.8.8) is starting...
Jun 24 08:34:38 K5435 NetworkManager[432]: <info> Read config file
/etc/NetworkManager/NetworkManager.conf
Jun 24 08:34:38 K5435 NetworkManager[432]: <info> WEXT support is enabled
Jun 24 08:34:39 K5435 NetworkManager[432]: <info> Loaded plugin
ifcfg-suse: (C) 2008 Novell, Inc.  To report bugs please use the
NetworkManager mailing list.
Jun 24 08:34:39 K5435 NetworkManager[432]: <info> Loaded plugin
keyfile: (c) 2007 - 2010 Red Hat, Inc.  To report bugs please use the
NetworkManager mailing list.
Jun 24 08:34:39 K5435 NetworkManager[432]: keyfile: parsing verizon ...
Jun 24 08:34:39 K5435 NetworkManager[432]: keyfile:     read
connection 'verizon'
Jun 24 08:34:39 K5435 ModemManager[428]: <warn>  (ttyUSB0): port
attributes not fully set
Jun 24 08:34:39 K5435 ModemManager[428]: <warn>  (ttyUSB1): port
attributes not fully set
Jun 24 08:34:39 K5435 ModemManager[428]: <warn>  (ttyUSB2): port
attributes not fully set
Jun 24 08:34:39 K5435 NetworkManager[432]: <info> monitoring kernel
firmware directory '/lib/firmware'.
Jun 24 08:34:39 K5435 systemd[1]: Started Modem Manager.
Jun 24 08:34:39 K5435 systemd[1]: Started Network Manager.
Jun 24 08:34:39 K5435 systemd[1]: Starting Modem service...
Jun 24 08:34:39 K5435 systemd[1]: Started Modem service.
Jun 24 08:34:39 K5435 NetworkManager[432]: <info> WiFi enabled by
radio killswitch; enabled by state file
Jun 24 08:34:39 K5435 NetworkManager[432]: <info> WWAN enabled by
radio killswitch; enabled by state file
Jun 24 08:34:39 K5435 NetworkManager[432]: <info> WiMAX enabled by
radio killswitch; enabled by state file
Jun 24 08:34:39 K5435 NetworkManager[432]: <info> Networking is
enabled by state file
Jun 24 08:34:39 K5435 ModemManager[428]: <warn>  (ttyUSB3): port
attributes not fully set
Jun 24 08:34:39 K5435 NetworkManager[432]: <warn> failed to allocate
link cache: (-12) Object not found
Jun 24 08:34:39 K5435 NetworkManager[432]: <info> (enp2s0): carrier is OFF
Jun 24 08:34:39 K5435 NetworkManager[432]: <info> (enp2s0): new
Ethernet device (driver: 'r8169' ifindex: 2)
Jun 24 08:34:39 K5435 NetworkManager[432]: <info> (enp2s0): exported
as /org/freedesktop/NetworkManager/Devices/0
Jun 24 08:34:39 K5435 NetworkManager[432]: <info> (enp2s0): device
state change: unmanaged -> unavailable (reason 'managed') [10 20 2]
Jun 24 08:34:39 K5435 NetworkManager[432]: <info> (enp2s0): bringing up device.
Jun 24 08:34:39 K5435 NetworkManager[432]: <info> (enp2s0): preparing device.
Jun 24 08:34:39 K5435 NetworkManager[432]: <info> (enp2s0):
deactivating device (reason 'managed') [2]
Jun 24 08:34:39 K5435 NetworkManager[432]: <info> Added default wired
connection 'Wired connection 1' for
/sys/devices/pci0000:00/0000:00:1c.5/0000:02:00.0/net/enp2s0
Jun 24 08:34:39 K5435 NetworkManager[432]: <warn>
/sys/devices/virtual/net/lo: couldn't determine device driver;
ignoring...
Jun 24 08:34:39 K5435 NetworkManager[432]: <warn>
/sys/devices/virtual/net/lo: couldn't determine device driver;
ignoring...
Jun 24 08:34:39 K5435 NetworkManager[432]: <warn> Couldn't get managed
objects: GDBus.Error:org.freedesktop.DBus.Error.ServiceUnknown: The
name org.bluez was not provided by any .service files
Jun 24 08:34:39 K5435 NetworkManager[432]: <info> ModemManager
available in the bus
Jun 24 08:34:39 K5435 modem[476]: ['verizon']
Jun 24 08:34:39 K5435 modem[476]: 1
Jun 24 08:34:39 K5435 modem[476]: 2014-06-24 08:34:39 [profile
verizon] setting up NM client...
Jun 24 08:34:39 K5435 modem[476]: 2014-06-24 08:34:39 [profile
verizon] setting up MM client...
Jun 24 08:34:39 K5435 modem[476]: 2014-06-24 08:34:39 [profile
verizon] NM service is running... reading connection list

.... we connect to the signal and wait for the callback to be
called.... but never happens.

Jun 24 08:34:41 K5435 ModemManager[428]: <warn>  Couldn't find support
for device at '/sys/devices/pci0000:00/0000:00:1c.5/0000:02:00.0': not
supported by any plugin
Jun 24 08:34:55 K5435 ModemManager[428]: <info>  Creating modem with
plugin 'Generic' and '1' ports
Jun 24 08:34:55 K5435 ModemManager[428]: <warn>  Could not grab port
(tty/ttyUSB4): 'Cannot add port 'tty/ttyUSB4', unhandled serial type'
Jun 24 08:34:55 K5435 ModemManager[428]: <warn>  Couldn't create modem
for device at '/sys/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.2':
Failed to find primary AT port
Jun 24 08:35:08 K5435 ModemManager[428]: <info>  Creating modem with
plugin 'Novatel' and '4' ports
Jun 24 08:35:08 K5435 ModemManager[428]: <warn>  Could not grab port
(tty/ttyUSB3): 'Cannot add port 'tty/ttyUSB3', unhandled serial type'
Jun 24 08:35:08 K5435 ModemManager[428]: <warn>  (ttyUSB0): port
attributes not fully set
Jun 24 08:35:08 K5435 ModemManager[428]: <info>  Modem for device at
'/sys/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.1' successfully
created
Jun 24 08:35:08 K5435 ModemManager[428]: <warn>  couldn't load current
allowed/preferred modes: 'Loading allowed modes not supported in
CDMA-only modems'
Jun 24 08:35:08 K5435 ModemManager[428]: <info>  Modem: state changed
(unknown -> disabled)
Jun 24 08:35:08 K5435 NetworkManager[432]: <warn> (ttyUSB0): failed to
look up interface index
Jun 24 08:35:08 K5435 NetworkManager[432]: <info> (ttyUSB0): new
Broadband device (driver: 'option1' ifindex: 0)
Jun 24 08:35:08 K5435 NetworkManager[432]: <info> (ttyUSB0): exported
as /org/freedesktop/NetworkManager/Devices/1
Jun 24 08:35:08 K5435 NetworkManager[432]: <info> (ttyUSB0): device
state change: unmanaged -> unavailable (reason 'managed') [10 20 2]
Jun 24 08:35:08 K5435 NetworkManager[432]: <info> (ttyUSB0):
deactivating device (reason 'managed') [2]
Jun 24 08:35:08 K5435 NetworkManager[432]: <info> (ttyUSB0): device
state change: unavailable -> disconnected (reason 'none') [20 30 0]
Jun 24 10:24:12 K5435 systemd[1]: Stopping Modem service...
Jun 24 10:24:12 K5435 modem[476]: 2014-06-24 10:24:12 [profile
verizon] signal caught
Jun 24 10:24:12 K5435 modem[476]: 2014-06-24 10:24:12 [profile
verizon] exiting...




-- 
Aleksander
https://aleksander.es