IPv4 problem with latest head version

[<colin helliwell ln-systems com>]

Apologies for the vague subject, but I'm not too sure how to be more
specific.
I've been successfully using NM (fetched ~17 July), in conjunction with
ModemManager and a GSM modem. I just happen to have fetched a newer version
from the github master head, and something is awry with the PPP ip4
operation.
The connection (auto-started) is firing up, and ppp connects and get IP
address etc. However whilst ppp0 appears in 'ifconfig', the IP address isn't
shown. Also there are no routes added for it. It is being added to
/etc/resolv.conf
Ipv6 is set to 'ignore' on both connections.

Tail end of the log is as follows. Note that the eth connection is also
coming up at the same time (it seems to get delayed until the
[autostart-ing] GSM connection is also ready to go? i.e. once MM has got it
going and the modem has registered on the network)

I wonder if the "nm_ip4_config_add_address: assertion
'NM_IP4_CONFIG_GET_PRIVATE (self)->ifindex > 0' failed" is relevant?
But let me know if any other config info needed.

Jul 27 13:52:43 wg2 daemon.notice pppd[934]: local  IP address 10.65.128.127
Jul 27 13:52:43 wg2 daemon.notice pppd[934]: remote IP address 10.65.128.127
Jul 27 13:52:43 wg2 daemon.notice pppd[934]: primary   DNS address
82.132.254.2
Jul 27 13:52:43 wg2 daemon.notice pppd[934]: secondary DNS address
82.132.254.3
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.6871] default-route: resync: schedule on idle
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.6874] device[0x19906f8] (ppp0): queued IP4 config change
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.6887] platform: signal: link changed: 3: ppp0
<NOARP,UP,LOWER_UP;pointopoint,multicast,noarp,up,running,lowerup> mtu 1500
arp 512 unknown? init driver unknown rx:5,68 tx:7,135
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.6926] device[0x19906f8] (ppp0): queued link change for ifindex 3
Jul 27 13:52:43 wg2 auth.notice dbus[799]: [system] Rejected send message, 0
matched rules; type="method_return", sender=":1.1" (uid=0 pid=825
comm="/usr/sbin/NetworkManager --no-daemon ") interface="(unset)"
member="(unset)" error name="(unset)" requested_reply="0"
Jul 27 13:52:43 wg2 daemon.info NetworkManager[825]: <info>
[1501159963.6992] ppp-manager: (IPv4 Config Get) reply received.
Jul 27 13:52:43 wg2 daemon.err NetworkManager[825]:
nm_ip4_config_add_address: assertion 'NM_IP4_CONFIG_GET_PRIVATE
(self)->ifindex > 0' failed
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7009] device[0x19d23c8] (ttyMux1): ip-ifname: set ifname 'ppp0',
ifindex 3
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7013] manager: (ppp0): removing device (allow_unmanage 0,
managed 0)
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7017] device[0x19906f8] (ppp0): ip4-config: update (commit=0,
routes-full-sync=0, new-config=(nil))
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7019] device[0x19906f8] (ppp0): ip4-config: clear IP4Config
instance (/org/freedesktop/NetworkManager/IP4Config/4)
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7024] dns-mgr: (device_ip4_config_changed): queueing DNS updates
(1)
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7027] dns-mgr: (device_ip4_config_changed): DNS configuration
did not change
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7029] dns-mgr: (device_ip4_config_changed): no DNS changes to
commit (0)
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7052] device[0x19906f8] (ppp0): ip6-config: update (commit=0,
routes-full-sync=0, new-config=(nil))
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7055] device[0x19906f8] (ppp0): ip6-config: clear IP6Config
instance (/org/freedesktop/NetworkManager/IP6Config/4)
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7060] dns-mgr: (device_ip6_config_changed): queueing DNS updates
(1)
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7063] dns-mgr: (device_ip6_config_changed): DNS configuration
did not change
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7065] dns-mgr: (device_ip6_config_changed): no DNS changes to
commit (0)
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7135] device[0x19906f8] (ppp0): disposing
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7139] device[0x19906f8] (ppp0): clearing queued IP4 config
change
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7141] device[0x19906f8] (ppp0): ip4-config: update (commit=1,
routes-full-sync=1, new-config=(nil))
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7144] device[0x19906f8] (ppp0): ip6-config: update (commit=1,
routes-full-sync=1, new-config=(nil))
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7148] device[0x19906f8] (ppp0): finalize(): NMDeviceGeneric
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7153] platform-linux: sysctl: failed to open
'/proc/sys/net/ipv6/conf/ppp0/disable_ipv6': (2) No such file or directory
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7162] device[0x19d23c8] (ttyMux1): ip4-config: update (commit=1,
routes-full-sync=1, new-config=0x19ac640)
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7166] platform: address: deleting IPv4 address 10.65.128.127/32,
ifindex 3 dev ppp0
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7176] platform: signal: address 4 removed: 10.65.128.127/32 lft
forever pref forever lifetime 30-0[4294967295,4294967295] dev 3 flags
permanent src kernel
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7181] device[0x19d23c8] (ttyMux1): queued IP4 config change
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7189] platform-linux: do-delete-ip4-address[3:
10.65.128.127/32]: success
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7193] route-mgr4:   3: sync 0 IPv4 routes
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7257] device[0x19d23c8] (ttyMux1): ip4-config: set IP4Config
instance (/org/freedesktop/NetworkManager/IP4Config/5)
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7261] default-route: entry[1/dev:0x19d23c8:ttyMux1:-has:+sync]:
record:add    0.0.0.0/0 via 0.0.0.0 dev 3 metric 4294967295 mss 0 rt-src
unknown (4294967295)
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7263] default-route: resync: cancelled (281)
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7266] default-route: entry[0/dev:0x19963e0:eth0:+has:+sync]:
sync:re-add 0.0.0.0/0 via 192.168.10.254 dev 2 metric 100 mss 0 rt-src user
(100 -> 100)
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7269] platform: route: adding or updating IPv4 route: 0.0.0.0/0
via 192.168.10.254 dev 2 metric 100 mss 0 rt-src user
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7273] platform-linux: do-add-ip4-route[2: 0.0.0.0/0 100]:
success
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7281] dns-mgr: (device_ip4_config_changed): queueing DNS updates
(1)
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7283] dns-mgr: (device_ip4_config_changed): DNS configuration
did not change
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7286] dns-mgr: (device_ip4_config_changed): no DNS changes to
commit (0)
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7288] device[0x19d23c8] (ttyMux1): activation-stage: schedule
activate_stage5_ip4_config_result,2 (id 283)
Jul 27 13:52:43 wg2 auth.notice dbus[799]: [system] Rejected send message, 0
matched rules; type="method_return", sender=":1.1" (uid=0 pid=825
comm="/usr/sbin/NetworkManager --no-daemon ") interface="(unset)"
member="(unset)" error name="(unset)" requested_reply="0"
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7376] device[0x19d23c8] (ttyMux1): activation-stage: invoke
activate_stage5_ip4_config_result,2 (id 283)
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7387] device[0x19d23c8] (ttyMux1): ip4-config: update (commit=1,
routes-full-sync=0, new-config=0x19e0860)
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7392] route-mgr4:   3: sync 0 IPv4 routes
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7395] default-route: entry[1/dev:0x19d23c8:ttyMux1:-has:+sync]:
record:resync 0.0.0.0/0 via 0.0.0.0 dev 3 metric 4294967295 mss 0 rt-src
unknown (4294967295)
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7399] default-route: entry[0/dev:0x19963e0:eth0:+has:+sync]:
sync:re-add 0.0.0.0/0 via 192.168.10.254 dev 2 metric 100 mss 0 rt-src user
(100 -> 100)
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7401] platform: route: adding or updating IPv4 route: 0.0.0.0/0
via 192.168.10.254 dev 2 metric 100 mss 0 rt-src user
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7405] platform-linux: do-add-ip4-route[2: 0.0.0.0/0 100]:
success
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7408] device[0x19d23c8] (ttyMux1): ip4-config: default route
changed
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7411] dns-mgr: (device_ip4_config_changed): queueing DNS updates
(1)
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7413] dns-mgr: (device_ip4_config_changed): DNS configuration
did not change
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7415] dns-mgr: (device_ip4_config_changed): no DNS changes to
commit (0)
Jul 27 13:52:43 wg2 daemon.info NetworkManager[825]: <info>
[1501159963.7418] device (ttyMux1): state change: ip-config -> ip-check
(reason 'none', internal state 'managed')
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7444] firewall: [0x19db8f0,change*:"ppp0"]: firewall zone change
ppp0:default (not running, simulate success)
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7455] device[0x19d23c8] (ttyMux1): activation-stage: complete
activate_stage5_ip4_config_result,2 (id 283)
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7488] device[0x19d23c8] (ttyMux1): ip4-config: update (commit=0,
routes-full-sync=0, new-config=0x19e0aa0)
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7494] device[0x19d23c8] (ttyMux1): ip4-config: update IP4Config
instance (/org/freedesktop/NetworkManager/IP4Config/5)
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7498] default-route: entry[1/dev:0x19d23c8:ttyMux1:-has:+sync]:
record:remove 0.0.0.0/0 via 0.0.0.0 dev 3 metric 4294967295 mss 0 rt-src
unknown (4294967295)
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7501] default-route: entry[0/dev:0x19963e0:eth0:+has:+sync]:
sync:re-add 0.0.0.0/0 via 192.168.10.254 dev 2 metric 100 mss 0 rt-src user
(100 -> 100)
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7503] platform: route: adding or updating IPv4 route: 0.0.0.0/0
via 192.168.10.254 dev 2 metric 100 mss 0 rt-src user
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7508] platform-linux: do-add-ip4-route[2: 0.0.0.0/0 100]:
success
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7511] dns-mgr: (device_ip4_config_changed): queueing DNS updates
(1)
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7513] dns-mgr: (device_ip4_config_changed): DNS configuration
did not change
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7515] dns-mgr: (device_ip4_config_changed): no DNS changes to
commit (0)
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7538] firewall: [0x19db8f0,change*:"ppp0"]: complete: fake
success
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7542] dispatcher: (5) (ttyMux1) dispatching action 'pre-up'
(with callback)
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7544] dispatcher: (5) simulate request; no scripts in
/etc/NetworkManager/dispatcher.d/pre-up.d
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7580] device[0x19d23c8] (ttyMux1): add_pending_action (2):
'queued-state-change-secondaries'
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7583] device[0x19d23c8] (ttyMux1): queue-state[secondaries,
reason:none, id:291]: queue state change
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7586] device[0x19d23c8] (ttyMux1): queue-state[secondaries,
reason:none, id:291]: change state
Jul 27 13:52:43 wg2 daemon.info NetworkManager[825]: <info>
[1501159963.7588] device (ttyMux1): state change: ip-check -> secondaries
(reason 'none', internal state 'managed')
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7611] device[0x19d23c8] (ttyMux1): add_pending_action (3):
'queued-state-change-activated'
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7614] device[0x19d23c8] (ttyMux1): queue-state[activated,
reason:none, id:294]: queue state change
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7618] device[0x19d23c8] (ttyMux1): device entered SECONDARIES
state
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7620] device[0x19d23c8] (ttyMux1): remove_pending_action (2):
'queued-state-change-secondaries'
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7657] device[0x19d23c8] (ttyMux1): queue-state[activated,
reason:none, id:294]: change state
Jul 27 13:52:43 wg2 daemon.info NetworkManager[825]: <info>
[1501159963.7659] device (ttyMux1): state change: secondaries -> activated
(reason 'none', internal state 'managed')
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7683] active-connection[0x19b19a0]: set state activated (was
activating)
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7703] active-connection[0x19b19a0]: check-master-ready: not
signalling (state activated, no master)
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7858] device[0x19d23c8] (ttyMux1): remove_pending_action (1):
'activation-0x19b19a0'
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7890] dns-mgr: (device_state_changed): queueing DNS updates (1)
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7893] dns-mgr: (update_routing_and_dns): queueing DNS updates
(2)
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7897] dns-mgr: (update_routing_and_dns): DNS configuration
changed
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7899] dns-mgr: (update_routing_and_dns): no DNS changes to
commit (1)
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7901] dns-mgr: (device_state_changed): DNS configuration changed
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7903] dns-mgr: (device_state_changed): committing DNS changes
(0)
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7905] dns-mgr: update-dns: updating resolv.conf
Jul 27 13:52:43 wg2 daemon.info NetworkManager[825]: <info>
[1501159963.7925] device (ttyMux1): Activation: successful, device
activated.
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7928] device[0x19d23c8] (ttyMux1): set metered value 3
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.7932] dispatcher: (6) (ttyMux1) dispatching action 'up'
Jul 27 13:52:43 wg2 daemon.notice dbus[799]: [system] Activating service
name='org.freedesktop.nm_dispatcher' (using servicehelper)
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.8017] pacrunner: call[0x19bc0c0]: send: new config
({'Interface': <'ppp0'>, 'Method': <'direct'>, 'BrowserOnly': <false>},)
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.8054] device[0x19d23c8] (ttyMux1): remove_pending_action (0):
'queued-state-change-activated'
Jul 27 13:52:43 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159963.8145] pacrunner: call[0x19bc0c0]: sending failed:
GDBus.Error:org.freedesktop.DBus.Error.NameHasNoOwner: Name "org.pacrunner"
does not exist
Jul 27 13:52:43 wg2 daemon.notice dbus[799]: [system] Successfully activated
service 'org.freedesktop.nm_dispatcher'
Jul 27 13:52:43 wg2 daemon.info nm-dispatcher: req:1 'up' [ppp0]: new
request (1 scripts)
Jul 27 13:52:43 wg2 daemon.debug nm-dispatcher: req:1 'up' [ppp0]:
environment: IP4_NUM_ROUTES=0
Jul 27 13:52:43 wg2 daemon.debug nm-dispatcher: req:1 'up' [ppp0]:
environment: IP4_NAMESERVERS=82.132.254.2 82.132.254.3
Jul 27 13:52:43 wg2 daemon.debug nm-dispatcher: req:1 'up' [ppp0]:
environment: IP4_GATEWAY=0.0.0.0
Jul 27 13:52:43 wg2 daemon.debug nm-dispatcher: req:1 'up' [ppp0]:
environment: DEVICE_IP_IFACE=ppp0
Jul 27 13:52:43 wg2 daemon.debug nm-dispatcher: req:1 'up' [ppp0]:
environment: DEVICE_IFACE=ttyMux1
Jul 27 13:52:43 wg2 daemon.debug nm-dispatcher: req:1 'up' [ppp0]:
environment: CONNECTION_ID=GSM
Jul 27 13:52:43 wg2 daemon.debug nm-dispatcher: req:1 'up' [ppp0]:
environment: CONNECTION_UUID=4259ac07-9d07-45f6-3f08-37d69ba7a537
Jul 27 13:52:43 wg2 daemon.debug nm-dispatcher: req:1 'up' [ppp0]:
environment: CONNECTION_FILENAME=/etc/NetworkManager/system-connections/GSM
Jul 27 13:52:43 wg2 daemon.debug nm-dispatcher: req:1 'up' [ppp0]:
environment: CONNECTION_DBUS_PATH=/org/freedesktop/NetworkManager/Settings/2
Jul 27 13:52:43 wg2 daemon.info nm-dispatcher: req:1 'up' [ppp0]: start
running ordered scripts...
Jul 27 13:52:43 wg2 daemon.debug nm-dispatcher: req:1 'up' [ppp0],
"/etc/NetworkManager/dispatcher.d/ppp-vnstat": run script
Jul 27 13:52:44 wg2 daemon.debug nm-dispatcher: req:1 'up' [ppp0],
"/etc/NetworkManager/dispatcher.d/ppp-vnstat": complete
Jul 27 13:52:44 wg2 daemon.debug nm-dispatcher: req:1 'up' [ppp0]: completed
(1 scripts)
Jul 27 13:52:44 wg2 daemon.debug NetworkManager[825]: <debug>
[1501159964.1166] dispatcher: (6) ppp-vnstat succeeded