Bug 689291
| Summary: | <error> activation_source_schedule(): activation stage already scheduled | ||||||
|---|---|---|---|---|---|---|---|
| Product: | [Fedora] Fedora | Reporter: | Steven Haigh <netwiz> | ||||
| Component: | NetworkManager | Assignee: | Dan Williams <dcbw> | ||||
| Status: | CLOSED ERRATA | QA Contact: | Fedora Extras Quality Assurance <extras-qa> | ||||
| Severity: | high | Docs Contact: | |||||
| Priority: | unspecified | ||||||
| Version: | 15 | CC: | awilliam, dcbw, jlaska, sthirugn, tflink | ||||
| Target Milestone: | --- | ||||||
| Target Release: | --- | ||||||
| Hardware: | x86_64 | ||||||
| OS: | Unspecified | ||||||
| Whiteboard: | AcceptedNTH | ||||||
| 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 15:32:31 UTC | Type: | --- | ||||
| Regression: | --- | Mount Type: | --- | ||||
| Documentation: | --- | CRM: | |||||
| Verified Versions: | Category: | --- | |||||
| oVirt Team: | --- | RHEL 7.3 requirements from Atomic Host: | |||||
| Cloudforms Team: | --- | Target Upstream Version: | |||||
| Embargoed: | |||||||
| Bug Depends On: | |||||||
| Bug Blocks: | 617261, 657619 | ||||||
| Attachments: |
|
||||||
|
Description
Steven Haigh
2011-03-20 22:06:23 UTC
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 Created attachment 486520 [details]
dmesg output.
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? 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. 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. 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.
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. 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. 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.
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? 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. Fixed upstream as: 801beb4b4d5204a9930d3ff04d9b035bf9949bd0 (master) a5fe769a30b60ac9014c3f81923079fde070ca37 (0.8.x) and should be in next F15 build. 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! RC compose is scheduled for Thursday. 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 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). 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 This does seem to be fixed in NetworkManager-0.8.998-2.git20110406.fc15.x86_64 (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. 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. dropping commonbugs keyword as this is fixed. 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 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 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 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 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. 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. |