NetworkManager removes ip address and route

Message

cmdic · Post by **cmdic** » Tue Nov 12, 2013 7:23 pm

Hi everyone,

I have this weird behaviour of NetworkManager:

Nov 12 19:02:11 localhost dhcpcd[3599]: version 6.1.0 starting
Nov 12 19:02:11 localhost NetworkManager[2049]: <info> dhcpcd started with pid 3599
Nov 12 19:02:11 localhost NetworkManager[2049]: <info> Activation (eth1) Stage 3 of 5 (IP Configure Start) complete.
Nov 12 19:02:11 localhost NetworkManager[2049]: <info> (eth1): DHCPv4 state changed nbi -> preinit
Nov 12 19:02:11 localhost dhcpcd[3599]: eth1: rebinding lease of 192.168.178.21
Nov 12 19:02:16 localhost dhcpcd[3599]: eth1: leased 192.168.178.21 for 864000 seconds
Nov 12 19:02:16 localhost dhcpcd[3599]: eth1: adding host route to 192.168.178.21 via 127.0.0.1
Nov 12 19:02:16 localhost dhcpcd[3599]: eth1: adding route to 192.168.178.0/24
Nov 12 19:02:16 localhost NetworkManager[2049]: <info> (eth1): DHCPv4 state changed preinit -> bound
Nov 12 19:02:16 localhost NetworkManager[2049]: <info>   address 192.168.178.21
Nov 12 19:02:16 localhost NetworkManager[2049]: <info>   prefix 24 (255.255.255.0)
Nov 12 19:02:16 localhost NetworkManager[2049]: <info>   gateway 192.168.178.1
Nov 12 19:02:16 localhost NetworkManager[2049]: <info>   nameserver '192.168.178.1'
Nov 12 19:02:16 localhost NetworkManager[2049]: <info>   domain name 'fritz.box'
Nov 12 19:02:16 localhost NetworkManager[2049]: <info> Activation (eth1) Stage 5 of 5 (IPv4 Configure Commit) scheduled...
Nov 12 19:02:16 localhost NetworkManager[2049]: <info> Activation (eth1) Stage 5 of 5 (IPv4 Commit) started...
Nov 12 19:02:16 localhost dhcpcd[3599]: eth1: removing IP address 192.168.178.21/24
Nov 12 19:02:16 localhost dhcpcd[3599]: eth1: deleting host route to 192.168.178.21 via 127.0.0.1
Nov 12 19:02:16 localhost dhcpcd[3599]: eth1: deleting route to 192.168.178.0/24
Nov 12 19:02:17 localhost NetworkManager[2049]: <info> (eth1): device state change: ip-config -> secondaries (reason 'none') [70 90 0]
Nov 12 19:02:17 localhost NetworkManager[2049]: <info> Activation (eth1) Stage 5 of 5 (IPv4 Commit) complete.
Nov 12 19:02:17 localhost NetworkManager[2049]: <info> (eth1): DHCPv4 state changed bound -> expire
Nov 12 19:02:17 localhost NetworkManager[2049]: <info> (eth1): device state change: secondaries -> activated (reason 'none') [90 100 0]
Nov 12 19:02:17 localhost NetworkManager[2049]: <info> Policy set 'eth1' (eth1) as default for IPv4 routing and DNS.
Nov 12 19:02:17 localhost NetworkManager[2049]: <info> Activation (eth1) successful, device activated.

to be able to go online I have to add the Ip manually via:
ifconfig eth1 192.168.178.21 netmask 255.255.255.0

any suggestions?

dE_logics · Post by **dE_logics** » Thu Nov 14, 2013 8:32 am

What networkmanager clients are you running?

cmdic · Post by **cmdic** » Sun Nov 17, 2013 1:19 pm

Just the gnome-applet nm-applet aka NetworkManager

666threesixes666 · Post by **666threesixes666** » Sun Nov 17, 2013 9:33 pm

as root you must remove any dhcpcd auto start features, or it will conflict with networkmanagers starting of dhcpcd

rc-update del dhcpcd

can you manually connect via nm-applet punching in the ip & dns & other info?

cmdic · Post by **cmdic** » Thu Nov 21, 2013 3:15 pm

Hi,

I haven't tried to put them into nm-applet.

But shall I remove dhcpd from autostart?

It might be possible that I have added dhcpd, while upgrading to systemd.

666threesixes666 · Post by **666threesixes666** » Thu Nov 21, 2013 10:45 pm

yeah remove any auto start of dhcpcd. you'll have to dig around systemctl or what ever systemd uses. if not you should be able to work around it for a bit with manually setting ip addy info in nm-applet by right clicking nm-applet and edit network connections.

id go through the whole gauntlet of testing openrc working with NM... get openrc working, then add complexity to your problem jumping over to systemd. then finally remove all manual ip addresses.

dziadu · Post by **dziadu** » Wed Mar 19, 2014 8:21 am

Hi, I have exactly the same problem, but I also found that problem exists with dhcpcd version higher than 6.0.5. Below are my 6.3.1 and 6.0.5 logs:

6.3.1

Mar 19 08:31:38 hadesnbp023 NetworkManager[17743]: <info> (wlp12s0): supplicant interface state: associating -> associated
Mar 19 08:31:38 hadesnbp023 NetworkManager[17743]: <info> (wlp12s0): supplicant interface state: associated -> completed
Mar 19 08:31:38 hadesnbp023 NetworkManager[17743]: <info> Activation (wlp12s0/wireless) Stage 2 of 5 (Device Configure) successful. Connected to wireless network 'ALICE-WLAN28'.
Mar 19 08:31:38 hadesnbp023 NetworkManager[17743]: <info> Activation (wlp12s0) Stage 3 of 5 (IP Configure Start) scheduled.
Mar 19 08:31:38 hadesnbp023 NetworkManager[17743]: <info> Activation (wlp12s0) Stage 3 of 5 (IP Configure Start) started...
Mar 19 08:31:38 hadesnbp023 NetworkManager[17743]: <info> (wlp12s0): device state change: config -> ip-config (reason 'none') [50 70 0]
Mar 19 08:31:38 hadesnbp023 NetworkManager[17743]: <info> Activation (wlp12s0) Beginning DHCPv4 transaction (timeout in 45 seconds)
Mar 19 08:31:38 hadesnbp023 NetworkManager[17743]: <info> dhcpcd started with pid 18243
Mar 19 08:31:38 hadesnbp023 NetworkManager[17743]: <info> Activation (wlp12s0) Stage 3 of 5 (IP Configure Start) complete.
Mar 19 08:31:38 hadesnbp023 dhcpcd[18243]: version 6.3.1 starting
Mar 19 08:31:38 hadesnbp023 dhcpcd[18243]: all: IPv6 kernel autoconf disabled
Mar 19 08:31:38 hadesnbp023 dhcpcd[18243]: wlp12s0: IPv6 kernel autoconf disabled
Mar 19 08:31:38 hadesnbp023 NetworkManager[17743]: <info> (wlp12s0): DHCPv4 state changed nbi -> preinit
Mar 19 08:31:38 hadesnbp023 dhcpcd[18243]: DUID xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx
Mar 19 08:31:38 hadesnbp023 dhcpcd[18243]: wlp12s0: IAID xx:xx:xx:xx
Mar 19 08:31:38 hadesnbp023 dhcpcd[18243]: wlp12s0: soliciting a DHCP lease
Mar 19 08:31:43 hadesnbp023 dhcpcd[18243]: wlp12s0: offered 192.168.1.17 from 192.168.1.1
Mar 19 08:31:47 hadesnbp023 dhcpcd[18243]: wlp12s0: leased 192.168.1.17 for 604800 seconds
Mar 19 08:31:47 hadesnbp023 dhcpcd[18243]: wlp12s0: adding route to 192.168.1.0/24
Mar 19 08:31:47 hadesnbp023 NetworkManager[17743]: <info> (wlp12s0): DHCPv4 state changed preinit -> bound
Mar 19 08:31:47 hadesnbp023 NetworkManager[17743]: <info> address 192.168.1.17
Mar 19 08:31:47 hadesnbp023 NetworkManager[17743]: <info> prefix 24 (255.255.255.0)
Mar 19 08:31:47 hadesnbp023 NetworkManager[17743]: <info> gateway 192.168.1.1
Mar 19 08:31:47 hadesnbp023 NetworkManager[17743]: <info> nameserver '192.168.1.1'
Mar 19 08:31:47 hadesnbp023 NetworkManager[17743]: <info> domain name 'localdomain'
Mar 19 08:31:47 hadesnbp023 NetworkManager[17743]: <info> Activation (wlp12s0) Stage 5 of 5 (IPv4 Configure Commit) scheduled...
Mar 19 08:31:47 hadesnbp023 NetworkManager[17743]: <info> Activation (wlp12s0) Stage 5 of 5 (IPv4 Commit) started...
Mar 19 08:31:47 hadesnbp023 dhcpcd[18243]: wlp12s0: removing IP address 192.168.1.17/24
Mar 19 08:31:47 hadesnbp023 dhcpcd[18243]: wlp12s0: deleting route to 192.168.1.0/24
Mar 19 08:31:48 hadesnbp023 NetworkManager[17743]: <info> (wlp12s0): device state change: ip-config -> secondaries (reason 'none') [70 90 0]
Mar 19 08:31:48 hadesnbp023 NetworkManager[17743]: <info> Activation (wlp12s0) Stage 5 of 5 (IPv4 Commit) complete.
Mar 19 08:31:48 hadesnbp023 NetworkManager[17743]: <info> (wlp12s0): DHCPv4 state changed bound -> expire
Mar 19 08:31:48 hadesnbp023 NetworkManager[17743]: <info> (wlp12s0): device state change: secondaries -> activated (reason 'none') [90 100 0]
Mar 19 08:31:48 hadesnbp023 NetworkManager[17743]: <info> NetworkManager state is now CONNECTED_GLOBAL
Mar 19 08:31:48 hadesnbp023 NetworkManager[17743]: <info> Policy set 'ALICE-WLAN28' (wlp12s0) as default for IPv4 routing and DNS.
Mar 19 08:31:48 hadesnbp023 NetworkManager[17743]: <info> Writing DNS information to /sbin/resolvconf
Mar 19 08:31:48 hadesnbp023 NetworkManager[17743]: <info> Activation (wlp12s0) successful, device activated.

# ifconfig wlp12s0
wlp12s0: flags=4163<UP,BROADCAST,RUNNING,MULTICAST> mtu 1500
ether xx:xx:xx:xx:xx:xx txqueuelen 1000 (Ethernet)
RX packets 6970 bytes 3599917 (3.4 MiB)
RX errors 0 dropped 0 overruns 0 frame 0
TX packets 12487 bytes 1922030 (1.8 MiB)
TX errors 0 dropped 0 overruns 0 carrier 0 collisions 0

6.0.5

Mar 19 08:53:13 hadesnbp023 NetworkManager[27182]: <info> (wlp12s0): supplicant interface state: associating -> associated
Mar 19 08:53:13 hadesnbp023 NetworkManager[27182]: <info> (wlp12s0): supplicant interface state: associated -> 4-way handshake
Mar 19 08:53:17 hadesnbp023 NetworkManager[27182]: <info> (wlp12s0): supplicant interface state: 4-way handshake -> completed
Mar 19 08:53:17 hadesnbp023 NetworkManager[27182]: <info> Activation (wlp12s0/wireless) Stage 2 of 5 (Device Configure) successful. Connected to wireless network 'ALICE-WLAN28'.
Mar 19 08:53:17 hadesnbp023 NetworkManager[27182]: <info> Activation (wlp12s0) Stage 3 of 5 (IP Configure Start) scheduled.
Mar 19 08:53:17 hadesnbp023 NetworkManager[27182]: <info> Activation (wlp12s0) Stage 3 of 5 (IP Configure Start) started...
Mar 19 08:53:17 hadesnbp023 NetworkManager[27182]: <info> (wlp12s0): device state change: config -> ip-config (reason 'none') [50 70 0]
Mar 19 08:53:17 hadesnbp023 NetworkManager[27182]: <info> Activation (wlp12s0) Beginning DHCPv4 transaction (timeout in 45 seconds)
Mar 19 08:53:17 hadesnbp023 NetworkManager[27182]: <info> dhcpcd started with pid 27262
Mar 19 08:53:17 hadesnbp023 NetworkManager[27182]: <info> Activation (wlp12s0) Stage 3 of 5 (IP Configure Start) complete.
Mar 19 08:53:17 hadesnbp023 dhcpcd[27262]: version 6.0.5 starting
Mar 19 08:53:17 hadesnbp023 NetworkManager[27182]: <info> (wlp12s0): DHCPv4 state changed nbi -> preinit
Mar 19 08:53:17 hadesnbp023 dhcpcd[27262]: wlp12s0: rebinding lease of 192.168.1.17
Mar 19 08:53:21 hadesnbp023 dhcpcd[27262]: wlp12s0: leased 192.168.1.17 for 604800 seconds
Mar 19 08:53:21 hadesnbp023 dhcpcd[27262]: wlp12s0: adding host route to 192.168.1.17 via 127.0.0.1
Mar 19 08:53:21 hadesnbp023 dhcpcd[27262]: wlp12s0: adding route to 192.168.1.0/24
Mar 19 08:53:21 hadesnbp023 NetworkManager[27182]: <info> (wlp12s0): DHCPv4 state changed preinit -> bound
Mar 19 08:53:21 hadesnbp023 NetworkManager[27182]: <info> address 192.168.1.17
Mar 19 08:53:21 hadesnbp023 NetworkManager[27182]: <info> prefix 24 (255.255.255.0)
Mar 19 08:53:21 hadesnbp023 NetworkManager[27182]: <info> gateway 192.168.1.1
Mar 19 08:53:21 hadesnbp023 NetworkManager[27182]: <info> nameserver '192.168.1.1'
Mar 19 08:53:21 hadesnbp023 NetworkManager[27182]: <info> domain name 'localdomain'
Mar 19 08:53:21 hadesnbp023 NetworkManager[27182]: <info> Activation (wlp12s0) Stage 5 of 5 (IPv4 Configure Commit) scheduled...
Mar 19 08:53:21 hadesnbp023 NetworkManager[27182]: <info> Activation (wlp12s0) Stage 5 of 5 (IPv4 Commit) started...
Mar 19 08:53:21 hadesnbp023 dhcpcd[27262]: wlp12s0: removing IP address 192.168.1.17/24
Mar 19 08:53:21 hadesnbp023 dhcpcd[27262]: wlp12s0: removing route to 192.168.1.0/24
Mar 19 08:53:22 hadesnbp023 NetworkManager[27182]: <info> (wlp12s0): device state change: ip-config -> secondaries (reason 'none') [70 90 0]
Mar 19 08:53:22 hadesnbp023 NetworkManager[27182]: <info> Activation (wlp12s0) Stage 5 of 5 (IPv4 Commit) complete.
Mar 19 08:53:22 hadesnbp023 NetworkManager[27182]: <info> (wlp12s0): device state change: secondaries -> activated (reason 'none') [90 100 0]
Mar 19 08:53:23 hadesnbp023 NetworkManager[27182]: <info> NetworkManager state is now CONNECTED_GLOBAL
Mar 19 08:53:23 hadesnbp023 NetworkManager[27182]: <info> Policy set 'ALICE-WLAN28' (wlp12s0) as default for IPv4 routing and DNS.
Mar 19 08:53:23 hadesnbp023 NetworkManager[27182]: <info> Writing DNS information to /sbin/resolvconf
Mar 19 08:53:23 hadesnbp023 NetworkManager[27182]: <info> Activation (wlp12s0) successful, device activated.

# ifconfig wlp12s0
wlp12s0: flags=4163<UP,BROADCAST,RUNNING,MULTICAST> mtu 1500
inet 192.168.1.18 netmask 255.255.255.0 broadcast 192.168.1.255
ether xx:xx:xx:xx:xx:xx txqueuelen 1000 (Ethernet)
RX packets 6935 bytes 3596589 (3.4 MiB)
RX errors 0 dropped 0 overruns 0 frame 0
TX packets 12389 bytes 1911679 (1.8 MiB)
TX errors 0 dropped 0 overruns 0 carrier 0 collisions 0

I don't think that it could be Network Manager problem, since it was many times recompiled since the first time when problem appeared.

I tried to remove duid option from dhcpcd config as suggested here: https://bugs.gentoo.org/show_bug.cgi?id=477356, I also recompiled dhcpcd without ipv6, but no improvements.

Any ideas?

Greetings,
dziadu

UberLord · Post by **UberLord** » Wed Mar 19, 2014 10:58 am

Code: Select all

removing IP address 192.168.1.17/24

That message means that dhcpcd received a kernel message that the ip address had been deleted by something else.
You could try adding the debug directive to /etc/dhcpcd.conf to get more logging if you think it's a dhcpcd failure.

dziadu · Post by **dziadu** » Wed Mar 19, 2014 11:20 am

But the same message appears for 6.0.5's log but IP is assigned anyway. I don't know if the problem is actually related to removing of the address (I posted in this topic because it had the same message and it misled me, but now I see that it could be not related to 'removing' message).

man for the dhcpcd.conf doesn't show any function to run debuging, but there is an 'quite' option, so I think the output we see is the max we can get.

boospy · Post by **boospy** » Sun Mar 30, 2014 12:07 am

Build sys-apps/net-tools with useflag "old-output" and try again.

lkraav · Post by **lkraav** » Sat Apr 05, 2014 10:20 pm

I'm seeing the exact same problem with dhcpcd 6.2.0 and higher. What a mess :/

UberLord · Post by **UberLord** » Sun Apr 06, 2014 5:53 pm

dziadu wrote:But the same message appears for 6.0.5's log but IP is assigned anyway. I don't know if the problem is actually related to removing of the address (I posted in this topic because it had the same message and it misled me, but now I see that it could be not related to 'removing' message).

man for the dhcpcd.conf doesn't show any function to run debuging, but there is an 'quite' option, so I think the output we see is the max we can get.

Hmm, it seems it's just not documented. Fixed here:
http://roy.marples.name/projects/dhcpcd ... 97cd&sbs=1

Now you can find out if dhcpcd is to blame or not. But pay close attention as dhcpcd will spot a 3rd party removing the address and log this and the wording is similar as dhcpcd removing it by itself.
Post the logs here if confused and you think dhcpcd is removing the address still