Bug 689291 - <error> activation_source_schedule(): activation stage already scheduled
<error> activation_source_schedule(): activation stage already scheduled
Status: CLOSED ERRATA
Product: Fedora
Classification: Fedora
Component: NetworkManager (Show other bugs)
15
x86_64 Unspecified
unspecified Severity high
: ---
: ---
Assigned To: Dan Williams
Fedora Extras Quality Assurance
AcceptedNTH
:
Depends On:
Blocks: F15Blocker/F15FinalBlocker F15Beta-accepted/F15BetaFreezeExcept
  Show dependency treegraph
 
Reported: 2011-03-20 18:06 EDT by Steven Haigh
Modified: 2015-06-02 10:59 EDT (History)
5 users (show)

See Also:
Fixed In Version: NetworkManager-0.8.4-1.fc14
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2011-04-11 11:32:31 EDT
Type: ---
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:


Attachments (Terms of Use)
dmesg output. (81.74 KB, text/plain)
2011-03-20 18:30 EDT, Steven Haigh
no flags Details

  None (edit)
Description Steven Haigh 2011-03-20 18:06:23 EDT
Description of problem:
NetworkManager flaps my ethernet connection and repeatedly issues and gets DHCP config from the network.

Version-Release number of selected component (if applicable):
NetworkManager-0.8.2-8.git20101117.fc15.x86_64

How reproducible:
Every boot.

Steps to Reproduce:
1. Start F15 system
2. Log in as a user
3. allow NetworkManager to connect.
  
Actual results:
System gets an IP address, then releases it, starts again from scratch.

Expected results:
System is configured for both ipv4 and ipv6 addresses.

Additional info:
Pastes of logs to follow.
Comment 1 Steven Haigh 2011-03-20 18:10:00 EDT
From /var/log/messages:
Mar 21 08:53:15 wopr NetworkManager[1027]: <info> Activation (em1) starting connection 'System em1'
Mar 21 08:53:15 wopr NetworkManager[1027]: <info> (em1): device state change: 3 -> 4 (reason 0)
Mar 21 08:53:15 wopr NetworkManager[1027]: <info> Activation (em1) Stage 1 of 5 (Device Prepare) scheduled...
Mar 21 08:53:15 wopr NetworkManager[1027]: <info> Activation (em1) Stage 1 of 5 (Device Prepare) started...
Mar 21 08:53:15 wopr NetworkManager[1027]: <info> Activation (em1) Stage 2 of 5 (Device Configure) scheduled...
Mar 21 08:53:15 wopr NetworkManager[1027]: <info> Activation (em1) Stage 1 of 5 (Device Prepare) complete.
Mar 21 08:53:15 wopr NetworkManager[1027]: <info> Activation (em1) Stage 2 of 5 (Device Configure) starting...
Mar 21 08:53:15 wopr NetworkManager[1027]: <info> (em1): device state change: 4 -> 5 (reason 0)
Mar 21 08:53:15 wopr NetworkManager[1027]: <info> Activation (em1) Stage 2 of 5 (Device Configure) successful.
Mar 21 08:53:15 wopr NetworkManager[1027]: <info> Activation (em1) Stage 3 of 5 (IP Configure Start) scheduled.
Mar 21 08:53:15 wopr NetworkManager[1027]: <info> Activation (em1) Stage 2 of 5 (Device Configure) complete.
Mar 21 08:53:15 wopr NetworkManager[1027]: <info> Activation (em1) Stage 3 of 5 (IP Configure Start) started...
Mar 21 08:53:15 wopr NetworkManager[1027]: <info> (em1): device state change: 5 -> 7 (reason 0)
Mar 21 08:53:15 wopr NetworkManager[1027]: <info> Activation (em1) Beginning DHCPv4 transaction (timeout in 45 seconds)
Mar 21 08:53:15 wopr NetworkManager[1027]: <info> dhclient started with pid 2546
Mar 21 08:53:15 wopr NetworkManager[1027]: <info> Activation (em1) Beginning IP6 addrconf.
Mar 21 08:53:15 wopr NetworkManager[1027]: <info> Activation (em1) Stage 3 of 5 (IP Configure Start) complete.
Mar 21 08:53:15 wopr dhclient[2546]: Internet Systems Consortium DHCP Client 4.2.1
Mar 21 08:53:15 wopr dhclient[2546]: Copyright 2004-2011 Internet Systems Consortium.
Mar 21 08:53:15 wopr dhclient[2546]: All rights reserved.
Mar 21 08:53:15 wopr dhclient[2546]: For info, please visit https://www.isc.org/software/dhcp/
Mar 21 08:53:15 wopr dhclient[2546]: 
Mar 21 08:53:15 wopr NetworkManager[1027]: <info> (em1): DHCPv4 state changed nbi -> preinit
Mar 21 08:53:15 wopr dhclient[2546]: Listening on LPF/em1/bc:ae:c5:12:73:7e
Mar 21 08:53:15 wopr dhclient[2546]: Sending on   LPF/em1/bc:ae:c5:12:73:7e
Mar 21 08:53:15 wopr dhclient[2546]: Sending on   Socket/fallback
Mar 21 08:53:16 wopr dhclient[2546]: DHCPREQUEST on em1 to 255.255.255.255 port 67
Mar 21 08:53:16 wopr dhclient[2546]: DHCPACK from 203.56.246.94
Mar 21 08:53:16 wopr dhclient[2546]: bound to 203.56.246.83 -- renewal in 9008 seconds.
Mar 21 08:53:16 wopr NetworkManager[1027]: <info> (em1): DHCPv4 state changed preinit -> reboot
Mar 21 08:53:16 wopr NetworkManager[1027]: <info> Activation (em1) Stage 4 of 5 (IP4 Configure Get) scheduled...
Mar 21 08:53:16 wopr NetworkManager[1027]: <info> Activation (em1) Stage 4 of 5 (IP4 Configure Get) started...
Mar 21 08:53:16 wopr NetworkManager[1027]: <info>   address 203.56.246.83
Mar 21 08:53:16 wopr NetworkManager[1027]: <info>   prefix 28 (255.255.255.240)
Mar 21 08:53:16 wopr NetworkManager[1027]: <info>   gateway 203.56.246.94
Mar 21 08:53:16 wopr NetworkManager[1027]: <info>   nameserver '203.56.246.94'
Mar 21 08:53:16 wopr NetworkManager[1027]: <info>   domain name 'crc.id.au'
Mar 21 08:53:16 wopr NetworkManager[1027]: <info> Activation (em1) Stage 4 of 5 (IP4 Configure Get) complete.
Mar 21 08:53:18 wopr NetworkManager[1027]: <info> Activation (em1) Stage 4 of 5 (IP6 Configure Get) scheduled...
Mar 21 08:53:18 wopr NetworkManager[1027]: <info> Activation (em1) Stage 4 of 5 (IP6 Configure Get) started...
Mar 21 08:53:18 wopr NetworkManager[1027]: <info> Activation (em1) Stage 5 of 5 (IP Configure Commit) scheduled...
Mar 21 08:53:18 wopr NetworkManager[1027]: <info> Activation (em1) Stage 4 of 5 (IP6 Configure Get) complete.
Mar 21 08:53:18 wopr NetworkManager[1027]: <info> Activation (em1) Stage 5 of 5 (IP Configure Commit) started...
Mar 21 08:53:20 wopr NetworkManager[1027]: <info> (em1): device state change: 7 -> 8 (reason 0)
Mar 21 08:53:20 wopr NetworkManager[1027]: <info> Policy set 'System em1' (em1) as default for IPv4 routing and DNS.
Mar 21 08:53:20 wopr NetworkManager[1027]: <info> Policy set 'System em1' (em1) as default for IPv6 routing and DNS.
Mar 21 08:53:20 wopr NetworkManager[1027]: <info> Updating /etc/hosts with new system hostname
Mar 21 08:53:20 wopr NetworkManager[1027]: <info> Activation (em1) successful, device activated.
Mar 21 08:53:20 wopr NetworkManager[1027]: <info> Activation (em1) Stage 5 of 5 (IP Configure Commit) complete.
Mar 21 08:53:25 wopr NetworkManager[1027]: <info> (em1): device state change: 8 -> 9 (reason 5)
Mar 21 08:53:25 wopr NetworkManager[1027]: <warn> Activation (em1) failed.
Mar 21 08:53:25 wopr NetworkManager[1027]: <info> Activation (em1) Stage 4 of 5 (IP6 Configure Get) scheduled...
Mar 21 08:53:25 wopr NetworkManager[1027]: <error> [1300658005.596414] [nm-device.c:628] activation_source_schedule(): activation stage already scheduled
Mar 21 08:53:25 wopr NetworkManager[1027]: <info> Activation (em1) Stage 4 of 5 (IP6 Configure Get) scheduled...
Mar 21 08:53:25 wopr NetworkManager[1027]: <error> [1300658005.596616] [nm-device.c:628] activation_source_schedule(): activation stage already scheduled
Mar 21 08:53:25 wopr NetworkManager[1027]: <info> Activation (em1) Stage 4 of 5 (IP6 Configure Get) scheduled...
Mar 21 08:53:25 wopr NetworkManager[1027]: <error> [1300658005.596660] [nm-device.c:628] activation_source_schedule(): activation stage already scheduled
Mar 21 08:53:25 wopr NetworkManager[1027]: <info> Activation (em1) Stage 4 of 5 (IP6 Configure Get) scheduled... 
***** repeated hundreds of times *****
Mar 21 08:53:25 wopr NetworkManager[1027]: <info> (em1): device state change: 9 -> 3 (reason 0)
Mar 21 08:53:25 wopr NetworkManager[1027]: <info> (em1): deactivating device (reason: 0).
Mar 21 08:53:26 wopr NetworkManager[1027]: <info> (em1): canceled DHCP transaction, DHCP client pid 2546
Comment 2 Steven Haigh 2011-03-20 18:30:51 EDT
Created attachment 486520 [details]
dmesg output.
Comment 3 Adam Williamson 2011-03-25 14:00:50 EDT
Discussed at the 2011-03-25 blocker review meeting, we agreed we need more data on this to determine blocker status.

The big NetworkManager 0.9 dump just landed:

https://admin.fedoraproject.org/updates/libsocialweb-0.25.11-3.fc15,kdebase-runtime-4.6.1-3.fc15,epiphany-2.91.92-2.fc15,evolution-2.91.92-2.fc15,control-center-2.91.92-3.fc15,kde-plasma-networkmanagement-0.9-0.43.20110323.fc15,kdebase-workspace-4.6.1-5.fc15,empathy-2.91.92-1.fc15,geoclue-0.12.0-7.fc15,krb5-auth-dialog-2.91.91-3.fc15,gnome-shell-2.91.92-3.fc15,NetworkManager-openvpn-0.8.995-1.fc15,NetworkManager-vpnc-0.8.996-2.fc15,NetworkManager-0.8.997-4.git20110325.fc15

can you test with that? Thanks. Also, I'm guessing this is related to the IPv6 configuration - it doesn't happen in a pure IPv4 setup?
Comment 4 Steven Haigh 2011-03-25 22:21:24 EDT
This still occurs with the following:

# rpm -qa | grep Network
NetworkManager-0.8.997-4.git20110325.fc15.x86_64
NetworkManager-gnome-0.8.997-4.git20110325.fc15.x86_64
NetworkManager-glib-0.8.997-4.git20110325.fc15.x86_64

Stopping NetworkManager and running 'dhclient em1' is a workaround, however in the default state this breaks both ipv6 and ipv4 networking.

It seems that stopping radvd announcements from my router causes stable network connectivity. Any resuming of radvd announcements will put Network Manager into the same endless loop.
Comment 5 Tim Flink 2011-04-01 13:25:33 EDT
Discussed at the 2011-04-01 blocker review meeting. We still need more information before deciding on blocker status.

What router model/firmware is being used?
Does this affect any router running radvd?

We would also like to see someone else reproduce this.
Comment 6 Steven Haigh 2011-04-01 22:26:17 EDT
The router is a Fedora 14 system using the radvd package.

The config on the router in /etc/radvd.conf is:
interface eth1.203 {
        AdvHomeAgentFlag off;
        AdvSendAdvert on;
        #AdvManagedFlag on;
        #AdvOtherConfigFlag on;

        prefix 2002:cb38:f71b:1::/64 {
                AdvOnLink on;
                AdvAutonomous on;
                AdvRouterAddr off;
        };

        RDNSS 2002:cb38:f71b:1::1 {
                AdvRDNSSPreference 8;
                AdvRDNSSOpen on;
                AdvRDNSSLifetime infinity;
        };
};

I believe this to be pretty much stock standard for using radvd in linux.
Comment 7 Steven Haigh 2011-04-01 22:27:26 EDT
It might also be worth mentioning that NO configuration is done on the F15 Beta TC1 system. The failure has to do with NetworkManager and the IPv6 autoconfiguration. The provided config above runs on the machine acting as a router.
Comment 8 Dan Williams 2011-04-02 10:20:55 EDT
There was a bug until a few days ago that might caused the default DHCP connections not to be created for wired devices, but that's fixed in the latest testing updates.

What we're going to need here is more debugging.  Can you do the following for me?

1) service NetworkManager stop
2) NetworkManager --no-daemon --log-level=debug --log-domains=CORE,HW,IPV6,IPV4,ETHER

and lets see what we get when the problem reproduces itself.  That's a lot of spew, but if you can get that and paste it in we can see what's going one.

My best guess is that your RDNSS or DNSSL information has expired, which means we can no longer continue to use the IPv6 configuration given to us by the router.  Or there's a bug in the RDNSS/DNSSL management.  But the debugging output will tell us that.  I can try to test out your IPv6 config next week.  The 'infinity' part there is interesting, and may not be handled correctly, it'll be interesting to see what the kernel sends us as nd_opt_rdnss_lifetime when infinity is used on the router.
Comment 9 Steven Haigh 2011-04-02 11:15:59 EDT
I think its safe to say this is the problem:

NetworkManager[2189]: <info> Activation (em1) Stage 4 of 5 (IP6 Configure Get) scheduled...
NetworkManager[2189]: <debug> [1301756659.988179] [nm-ip6-manager.c:266] rdnss_expired(): (em1): IPv6 RDNSS information expired
NetworkManager[2189]: <info> Activation (em1) Stage 4 of 5 (IP6 Configure Get) scheduled...
NetworkManager[2189]: <debug> [1301756659.988276] [nm-ip6-manager.c:266] rdnss_expired(): (em1): IPv6 RDNSS information expired
NetworkManager[2189]: <info> Activation (em1) Stage 4 of 5 (IP6 Configure Get) scheduled...
NetworkManager[2189]: <debug> [1301756659.988354] [nm-ip6-manager.c:266] rdnss_expired(): (em1): IPv6 RDNSS information expired
NetworkManager[2189]: <info> Activation (em1) Stage 4 of 5 (IP6 Configure Get) scheduled...
NetworkManager[2189]: <debug> [1301756660.9644] [nm-device-ethernet.c:674] _set_hw_addr(): (em1): no MAC address change needed
NetworkManager[2189]: <debug> [1301756660.9691] [nm-system.c:1362] flush_routes(): (em1): flushing routes ifindex 2 family UNSPEC (0)

Interestingly, changing the following in /etc/radvd.conf on the Fedora 14 router fixed the issue.
                #AdvRDNSSLifetime infinity;
                AdvRDNSSLifetime 3600;

It seems that NetworkManager bails when it gets a lifetime of infinity.
Comment 10 Steven Haigh 2011-04-04 11:53:38 EDT
Dan,

Having not found any info on if this is a common setup to have, would this likely affect many people with other IPv6 devices?

At the moment, I've taken it off an F15Beta Blocker - as it seems to *only* trigger when AdvRDNSSLifetime == infinity. I would guess that NetworkManager is confusing infinite with expired - hence the bug.

Your thoughts on this?
Comment 11 Adam Williamson 2011-04-05 00:44:36 EDT
Dan and I concur with Steven's analysis that this is not likely to be a very common configuration, and we think it's not a Beta blocker. I'd like to propose it as Beta NTH and Final blocker for re-evaluation on Friday.
Comment 12 Dan Williams 2011-04-05 11:05:33 EDT
Fixed upstream as:

801beb4b4d5204a9930d3ff04d9b035bf9949bd0 (master)
a5fe769a30b60ac9014c3f81923079fde070ca37 (0.8.x)

and should be in next F15 build.
Comment 13 Adam Williamson 2011-04-05 11:38:36 EDT
Dan, if we want to get this into Beta, it'd be best to do an F15 build quickly and submit it as an update, so we have time to take it into the RC compose. thanks!
Comment 14 Adam Williamson 2011-04-05 11:38:48 EDT
RC compose is scheduled for Thursday.
Comment 15 Fedora Update System 2011-04-06 15:07:07 EDT
NetworkManager-0.8.998-2.git20110406.fc15 has been submitted as an update for Fedora 15.
https://admin.fedoraproject.org/updates/NetworkManager-0.8.998-2.git20110406.fc15
Comment 16 Fedora Update System 2011-04-06 22:19:42 EDT
Package NetworkManager-0.8.998-2.git20110406.fc15:
* should fix your issue,
* was pushed to the Fedora 15 testing repository,
* should be available at your local mirror within two days.
Update it with:
# su -c 'yum update --enablerepo=updates-testing NetworkManager-0.8.998-2.git20110406.fc15'
as soon as you are able to, then reboot.
Please go to the following url:
https://admin.fedoraproject.org/updates/NetworkManager-0.8.998-2.git20110406.fc15
then log in and leave karma (feedback).
Comment 17 James Laska 2011-04-08 15:12:18 EDT
Discussed during the 2011-04-08 blocker review meeting [1].  AcceptedNTH for Beta. Proposed fix already included in RC1

[1] http://meetbot.fedoraproject.org/fedora-bugzappers/2011-04-08/f-15-beta-blocker-review.2011-04-08-17.00.html
Comment 18 Steven Haigh 2011-04-10 19:01:58 EDT
This does seem to be fixed in NetworkManager-0.8.998-2.git20110406.fc15.x86_64
Comment 19 James Laska 2011-04-11 10:08:45 EDT
(In reply to comment #18)
> This does seem to be fixed in NetworkManager-0.8.998-2.git20110406.fc15.x86_64

Thanks for the feedback.  Moving to VERIFIED based on your input.
Comment 20 Fedora Update System 2011-04-11 11:32:21 EDT
NetworkManager-0.8.998-2.git20110406.fc15 has been pushed to the Fedora 15 stable repository.  If problems still persist, please make note of it in this bug report.
Comment 21 Adam Williamson 2011-04-14 21:02:39 EDT
dropping commonbugs keyword as this is fixed.
Comment 22 Fedora Update System 2011-04-15 17:43:35 EDT
NetworkManager-0.8.3.999-2.git20110414.fc14 has been submitted as an update for Fedora 14.
https://admin.fedoraproject.org/updates/NetworkManager-0.8.3.999-2.git20110414.fc14
Comment 23 Fedora Update System 2011-04-15 17:44:24 EDT
NetworkManager-0.8.3.999-2.git20110414.fc13 has been submitted as an update for Fedora 13.
https://admin.fedoraproject.org/updates/NetworkManager-0.8.3.999-2.git20110414.fc13
Comment 24 Fedora Update System 2011-04-20 18:43:27 EDT
NetworkManager-0.8.4-1.fc14 has been submitted as an update for Fedora 14.
https://admin.fedoraproject.org/updates/NetworkManager-0.8.4-1.fc14
Comment 25 Fedora Update System 2011-04-20 18:44:54 EDT
NetworkManager-0.8.4-1.fc13 has been submitted as an update for Fedora 13.
https://admin.fedoraproject.org/updates/NetworkManager-0.8.4-1.fc13
Comment 26 Fedora Update System 2011-04-27 22:03:49 EDT
NetworkManager-0.8.4-1.fc14 has been pushed to the Fedora 14 stable repository.  If problems still persist, please make note of it in this bug report.
Comment 27 Fedora Update System 2011-05-26 17:53:00 EDT
NetworkManager-0.8.4-1.fc13 has been pushed to the Fedora 13 stable repository.  If problems still persist, please make note of it in this bug report.

Note You need to log in before you can comment on or make changes to this bug.