Bug 1128286 - Docker networking fails for first minute
Summary: Docker networking fails for first minute
Keywords:
Status: CLOSED EOL
Alias: None
Product: Fedora
Classification: Fedora
Component: NetworkManager
Version: 20
Hardware: x86_64
OS: Linux
unspecified
unspecified
Target Milestone: ---
Assignee: Dan Williams
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2014-08-08 19:35 UTC by Aric
Modified: 2015-06-29 21:59 UTC (History)
5 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2015-06-29 21:59:23 UTC


Attachments (Terms of Use)

Description Aric 2014-08-08 19:35:08 UTC
Description of problem:

When using network manager to Manage my bridge (called Docker0) docker containers do not have networking for the first minute after they are created.

Disabling network manager and switching to sysconfig/network-scripts solved the issue.

Version-Release number of selected component (if applicable):

NetworkManager-0.9.9.0-43.git20131003.fc20.x86_64

How reproducible:
 
For me personally, allways.

Steps to Reproduce:
1.  Settings -> Network ->  + Create Bridge (Named Docker 0) -> Bridge Tab, add Ethernet -> add mac address -> save  
Settings -> Network -> Wired toggle -> Off -> Bridge toggle -> On

$ nmcli con up "bridge0 slave 1"

Networking works. (kvm etc is happy)

2. $ sudo yum install docker-io

3. $ sudo docker run -i -t ubuntu:latest ping google.com
PING 192.168.0.106 (192.168.0.106) 56(84) bytes of data.
From 192.168.0.6 icmp_seq=1 Destination Host Unreachable

Wait ~1 minute

root@2ed081d6465f:/# ping 192.168.0.106
PING 192.168.0.106 (192.168.0.106) 56(84) bytes of data.
64 bytes from 192.168.0.106: icmp_seq=1 ttl=64 time=0.243 ms
64 bytes from 192.168.0.106: icmp_seq=2 ttl=64 time=0.107 ms


Actual results:

Networking does not come up right away as expected. 


Expected results:

With sysconfig/network-scripts networking comes up right away.


Additional info:

Comment 1 Jirka Klimes 2014-08-28 11:41:07 UTC
Can you attach NetworkManagers logs so that we could see what happens?
Either /var/log/messages or via journal: journalctl -u NetworkManager

Comment 2 Aric 2014-09-08 15:04:38 UTC
Hi Jirka Klimes

I included the Kernel and Docker logs along with network managers. It's more obvious to me what's happening with those for context, hopefully the same goes for you.  Not sure what the deal is with The veth9ce9 device that Networkmanager tries to connect with, but the kernel creates the interface vethe127 which eventually works inside the container. 

$ relevant ip a bits:

2: enp0s25: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc pfifo_fast master docker0 state UP group default qlen 1000
    link/ether 28:d2:44:71:9f:30 brd ff:ff:ff:ff:ff:ff
    inet6 fe80::2ad2:44ff:fe71:9f30/64 scope link
       valid_lft forever preferred_lft forever

5: docker0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc noqueue state UP group default
    link/ether 28:d2:44:71:9f:30 brd ff:ff:ff:ff:ff:ff
    inet 192.168.0.106/24 brd 192.168.0.255 scope global dynamic docker0
       valid_lft 85053sec preferred_lft 85053sec
    inet6 fe80::864:51ff:fe9b:1039/64 scope link
       valid_lft forever preferred_lft forever

21: vethe127: <BROADCAST,UP,LOWER_UP> mtu 1500 qdisc pfifo_fast master docker0 state UP group default qlen 1000
    link/ether 32:79:69:7d:35:f4 brd ff:ff:ff:ff:ff:ff
    inet6 fe80::3079:69ff:fe7d:35f4/64 scope link
       valid_lft forever preferred_lft forever


Here is a gist of the log below. You may find it more readable.
https://gist.github.com/Aricg/4ed35ad3fde0e44a89ca


###### LOGS 
###### STARTING THE CONTAINER:
Sep 08 10:44:03 hyperion.local docker[13188]: 2014/09/08 10:44:03 POST /v1.13/containers/create
Sep 08 10:44:03 hyperion.local docker[13188]: [87d65874] +job create()
Sep 08 10:44:03 hyperion.local kernel: device-mapper: thin: Creation of new snapshot 44 of device 30 failed.
Sep 08 10:44:03 hyperion.local kernel: EXT4-fs (dm-6): mounted filesystem with ordered data mode. Opts: discard
Sep 08 10:44:03 hyperion.local kernel: SELinux: initialized (dev dm-6, type ext4), uses xattr
Sep 08 10:44:03 hyperion.local kernel: device-mapper: thin: Creation of new snapshot 46 of device 45 failed.
Sep 08 10:44:03 hyperion.local docker[13188]: [87d65874] -job create() = OK (0)
Sep 08 10:44:03 hyperion.local docker[13188]: 2014/09/08 10:44:03 POST /v1.13/containers/c0ff44ef206cdd617fdfe394fab4ef63b26dc4d89163dd93395073114361083b/attach?stderr=1&stdin=1&stdout=1&stream=1
Sep 08 10:44:03 hyperion.local docker[13188]: [87d65874] +job container_inspect(c0ff44ef206cdd617fdfe394fab4ef63b26dc4d89163dd93395073114361083b)
Sep 08 10:44:03 hyperion.local docker[13188]: [87d65874] -job container_inspect(c0ff44ef206cdd617fdfe394fab4ef63b26dc4d89163dd93395073114361083b) = OK (0)
Sep 08 10:44:03 hyperion.local docker[13188]: [87d65874] +job attach(c0ff44ef206cdd617fdfe394fab4ef63b26dc4d89163dd93395073114361083b)
Sep 08 10:44:03 hyperion.local docker[13188]: 2014/09/08 10:44:03 POST /v1.13/containers/c0ff44ef206cdd617fdfe394fab4ef63b26dc4d89163dd93395073114361083b/start
Sep 08 10:44:03 hyperion.local docker[13188]: [87d65874] +job start(c0ff44ef206cdd617fdfe394fab4ef63b26dc4d89163dd93395073114361083b)
Sep 08 10:44:03 hyperion.local kernel: EXT4-fs (dm-6): mounted filesystem with ordered data mode. Opts: discard
Sep 08 10:44:03 hyperion.local kernel: SELinux: initialized (dev dm-6, type ext4), uses mountpoint labeling
Sep 08 10:44:03 hyperion.local docker[13188]: [87d65874] +job allocate_interface(c0ff44ef206cdd617fdfe394fab4ef63b26dc4d89163dd93395073114361083b)
Sep 08 10:44:03 hyperion.local docker[13188]: [87d65874] -job allocate_interface(c0ff44ef206cdd617fdfe394fab4ef63b26dc4d89163dd93395073114361083b) = OK (0)
Sep 08 10:44:03 hyperion.local kernel: SELinux: initialized (dev mqueue, type mqueue), uses transition SIDs
Sep 08 10:44:03 hyperion.local kernel: SELinux: initialized (dev proc, type proc), uses genfs_contexts
Sep 08 10:44:03 hyperion.local systemd[1]: Starting docker container c0ff44ef206cdd617fdfe394fab4ef63b26dc4d89163dd93395073114361083b.
-- Subject: Unit docker-c0ff44ef206cdd617fdfe394fab4ef63b26dc4d89163dd93395073114361083b.scope has begun with start-up
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
-- 
-- Unit docker-c0ff44ef206cdd617fdfe394fab4ef63b26dc4d89163dd93395073114361083b.scope has begun starting up.
Sep 08 10:44:03 hyperion.local systemd[1]: Started docker container c0ff44ef206cdd617fdfe394fab4ef63b26dc4d89163dd93395073114361083b.
-- Subject: Unit docker-c0ff44ef206cdd617fdfe394fab4ef63b26dc4d89163dd93395073114361083b.scope has finished start-up
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
-- 
-- Unit docker-c0ff44ef206cdd617fdfe394fab4ef63b26dc4d89163dd93395073114361083b.scope has finished starting up.
-- 
-- The start-up result is done.
Sep 08 10:44:03 hyperion.local kernel: netlink: 1 bytes leftover after parsing attributes in process `docker'.
Sep 08 10:44:03 hyperion.local kernel: device vethe127 entered promiscuous mode
Sep 08 10:44:03 hyperion.local kernel: IPv6: ADDRCONF(NETDEV_UP): vethe127: link is not ready
Sep 08 10:44:03 hyperion.local avahi-daemon[968]: Withdrawing workstation service for veth9ce9.
Sep 08 10:44:03 hyperion.local NetworkManager[12253]: <info> (veth9ce9): carrier is OFF
Sep 08 10:44:03 hyperion.local NetworkManager[12253]: <info> (veth9ce9): new Veth device (driver: 'unknown' ifindex: 20)
Sep 08 10:44:03 hyperion.local NetworkManager[12253]: <info> (veth9ce9): exported as /org/freedesktop/NetworkManager/Devices/10
Sep 08 10:44:03 hyperion.local NetworkManager[12253]: <info> (veth9ce9): Generating connection from current device status.
Sep 08 10:44:03 hyperion.local NetworkManager[12253]: <info> (veth9ce9): Using generated connection: 'veth9ce9'
Sep 08 10:44:03 hyperion.local NetworkManager[12253]: <info> (veth9ce9): device state change: unmanaged -> unavailable (reason 'connection-assumed') [10 20 41]
Sep 08 10:44:03 hyperion.local NetworkManager[12253]: <info> (veth9ce9): bringing up device.
Sep 08 10:44:03 hyperion.local NetworkManager[12253]: <error> [1410187443.889330] [platform/nm-linux-platform.c:1596] link_change(): Netlink error: No such device
Sep 08 10:44:03 hyperion.local NetworkManager[12253]: <info> Added default wired connection 'Wired connection 1' for /virtual/device/placeholder/4
Sep 08 10:44:03 hyperion.local kernel: IPv6: ADDRCONF(NETDEV_CHANGE): vethe127: link becomes ready
Sep 08 10:44:03 hyperion.local kernel: docker0: port 2(vethe127) entered listening state
Sep 08 10:44:03 hyperion.local kernel: docker0: port 2(vethe127) entered listening state
Sep 08 10:44:03 hyperion.local NetworkManager[12253]: <info> (vethe127): carrier is OFF
Sep 08 10:44:03 hyperion.local NetworkManager[12253]: <info> (vethe127): new Veth device (driver: 'unknown' ifindex: 21)
Sep 08 10:44:03 hyperion.local NetworkManager[12253]: <info> (vethe127): exported as /org/freedesktop/NetworkManager/Devices/11
Sep 08 10:44:03 hyperion.local NetworkManager[12253]: <info> (vethe127): Generating connection from current device status.
Sep 08 10:44:03 hyperion.local NetworkManager[12253]: <info> (vethe127): Using generated connection: 'vethe127'
Sep 08 10:44:03 hyperion.local NetworkManager[12253]: <info> (vethe127): device state change: unmanaged -> unavailable (reason 'connection-assumed') [10 20 41]
Sep 08 10:44:03 hyperion.local NetworkManager[12253]: <info> Added default wired connection 'Wired connection 2' for /virtual/device/placeholder/5
Sep 08 10:44:03 hyperion.local NetworkManager[12253]: <info> (vethe127): link connected
Sep 08 10:44:03 hyperion.local NetworkManager[12253]: <warn> (veth9ce9): failed to get device's ifindex
Sep 08 10:44:03 hyperion.local kernel: SELinux: initialized (dev sysfs, type sysfs), uses genfs_contexts
Sep 08 10:44:03 hyperion.local kernel: SELinux: initialized (dev tmpfs, type tmpfs), uses mountpoint labeling
Sep 08 10:44:03 hyperion.local kernel: SELinux: initialized (dev tmpfs, type tmpfs), uses mountpoint labeling
Sep 08 10:44:03 hyperion.local kernel: SELinux: initialized (dev devpts, type devpts), uses mountpoint labeling
Sep 08 10:44:03 hyperion.local NetworkManager[12253]: <info> (veth9ce9): device state change: unavailable -> unmanaged (reason 'removed') [20 10 36]
Sep 08 10:44:03 hyperion.local NetworkManager[12253]: <info> (vethe127): device state change: unavailable -> disconnected (reason 'carrier-changed') [20 30 40]
Sep 08 10:44:03 hyperion.local NetworkManager[12253]: <info> Auto-activating connection 'Wired connection 2'.
Sep 08 10:44:03 hyperion.local NetworkManager[12253]: <info> Activation (vethe127) starting connection 'Wired connection 2'
Sep 08 10:44:03 hyperion.local NetworkManager[12253]: <info> (vethe127): device state change: disconnected -> prepare (reason 'none') [30 40 0]
Sep 08 10:44:03 hyperion.local NetworkManager[12253]: <info> Activation (vethe127) Stage 1 of 5 (Device Prepare) scheduled...
Sep 08 10:44:03 hyperion.local NetworkManager[12253]: <info> Activation (vethe127) Stage 1 of 5 (Device Prepare) started...
Sep 08 10:44:03 hyperion.local NetworkManager[12253]: <info> Activation (vethe127) Stage 2 of 5 (Device Configure) scheduled...
Sep 08 10:44:03 hyperion.local NetworkManager[12253]: <info> Activation (vethe127) Stage 1 of 5 (Device Prepare) complete.
Sep 08 10:44:03 hyperion.local NetworkManager[12253]: <info> Activation (vethe127) Stage 2 of 5 (Device Configure) starting...
Sep 08 10:44:03 hyperion.local NetworkManager[12253]: <info> (vethe127): device state change: prepare -> config (reason 'none') [40 50 0]
Sep 08 10:44:03 hyperion.local NetworkManager[12253]: <info> Activation (vethe127) Stage 2 of 5 (Device Configure) successful.
Sep 08 10:44:03 hyperion.local NetworkManager[12253]: <info> Activation (vethe127) Stage 3 of 5 (IP Configure Start) scheduled.
Sep 08 10:44:03 hyperion.local NetworkManager[12253]: <info> Activation (vethe127) Stage 2 of 5 (Device Configure) complete.
Sep 08 10:44:03 hyperion.local NetworkManager[12253]: <info> Activation (vethe127) Stage 3 of 5 (IP Configure Start) started...
Sep 08 10:44:03 hyperion.local NetworkManager[12253]: <info> (vethe127): device state change: config -> ip-config (reason 'none') [50 70 0]
Sep 08 10:44:03 hyperion.local NetworkManager[12253]: <info> Activation (vethe127) Beginning DHCPv4 transaction (timeout in 45 seconds)
Sep 08 10:44:03 hyperion.local NetworkManager[12253]: <info> dhclient started with pid 13441
Sep 08 10:44:03 hyperion.local NetworkManager[12253]: nm_utils_get_ip_config_method: assertion 's_ip6 != NULL' failed
Sep 08 10:44:03 hyperion.local NetworkManager[12253]: <info> Activation (vethe127) Stage 3 of 5 (IP Configure Start) complete.
Sep 08 10:44:03 hyperion.local docker[13188]: [87d65874] -job start(c0ff44ef206cdd617fdfe394fab4ef63b26dc4d89163dd93395073114361083b) = OK (0)
Sep 08 10:44:03 hyperion.local docker[13188]: 2014/09/08 10:44:03 POST /v1.13/containers/c0ff44ef206cdd617fdfe394fab4ef63b26dc4d89163dd93395073114361083b/resize?h=22&w=88
Sep 08 10:44:03 hyperion.local docker[13188]: [87d65874] +job resize(c0ff44ef206cdd617fdfe394fab4ef63b26dc4d89163dd93395073114361083b, 22, 88)
Sep 08 10:44:03 hyperion.local docker[13188]: [87d65874] -job resize(c0ff44ef206cdd617fdfe394fab4ef63b26dc4d89163dd93395073114361083b, 22, 88) = OK (0)
Sep 08 10:44:03 hyperion.local dhclient[13441]: Internet Systems Consortium DHCP Client 4.2.7
Sep 08 10:44:03 hyperion.local dhclient[13441]: Copyright 2004-2014 Internet Systems Consortium.
Sep 08 10:44:03 hyperion.local dhclient[13441]: All rights reserved.
Sep 08 10:44:03 hyperion.local dhclient[13441]: For info, please visit https://www.isc.org/software/dhcp/
Sep 08 10:44:03 hyperion.local dhclient[13441]: 
Sep 08 10:44:03 hyperion.local NetworkManager[12253]: Internet Systems Consortium DHCP Client 4.2.7
Sep 08 10:44:03 hyperion.local NetworkManager[12253]: Copyright 2004-2014 Internet Systems Consortium.
Sep 08 10:44:03 hyperion.local NetworkManager[12253]: All rights reserved.
Sep 08 10:44:03 hyperion.local NetworkManager[12253]: For info, please visit https://www.isc.org/software/dhcp/
Sep 08 10:44:03 hyperion.local NetworkManager[12253]: <info> (vethe127): DHCPv4 state changed nbi -> preinit
Sep 08 10:44:03 hyperion.local dhclient[13441]: Listening on LPF/vethe127/32:79:69:7d:35:f4
Sep 08 10:44:03 hyperion.local dhclient[13441]: Sending on   LPF/vethe127/32:79:69:7d:35:f4
Sep 08 10:44:03 hyperion.local dhclient[13441]: Sending on   Socket/fallback
Sep 08 10:44:03 hyperion.local dhclient[13441]: DHCPDISCOVER on vethe127 to 255.255.255.255 port 67 interval 3 (xid=0x6644bb94)
Sep 08 10:44:03 hyperion.local NetworkManager[12253]: Listening on LPF/vethe127/32:79:69:7d:35:f4
Sep 08 10:44:03 hyperion.local NetworkManager[12253]: Sending on   LPF/vethe127/32:79:69:7d:35:f4
Sep 08 10:44:03 hyperion.local NetworkManager[12253]: Sending on   Socket/fallback
Sep 08 10:44:03 hyperion.local NetworkManager[12253]: DHCPDISCOVER on vethe127 to 255.255.255.255 port 67 interval 3 (xid=0x6644bb94)
Sep 08 10:44:05 hyperion.local NetworkManager[12253]: nm_utils_get_ip_config_method: assertion 's_ip6 != NULL' failed
Sep 08 10:44:05 hyperion.local gnome-session[1523]: [4732:332] 0x2e7fc76105a0: C->F: ["comment","BC Request StatEvent: 14"]
Sep 08 10:44:06 hyperion.local dhclient[13441]: DHCPDISCOVER on vethe127 to 255.255.255.255 port 67 interval 8 (xid=0x6644bb94)
Sep 08 10:44:06 hyperion.local NetworkManager[12253]: DHCPDISCOVER on vethe127 to 255.255.255.255 port 67 interval 8 (xid=0x6644bb94)
Sep 08 10:44:14 hyperion.local dhclient[13441]: DHCPDISCOVER on vethe127 to 255.255.255.255 port 67 interval 12 (xid=0x6644bb94)
Sep 08 10:44:14 hyperion.local NetworkManager[12253]: DHCPDISCOVER on vethe127 to 255.255.255.255 port 67 interval 12 (xid=0x6644bb94)
Sep 08 10:44:18 hyperion.local kernel: docker0: port 2(vethe127) entered learning state
Sep 08 10:44:26 hyperion.local dhclient[13441]: DHCPDISCOVER on vethe127 to 255.255.255.255 port 67 interval 11 (xid=0x6644bb94)
Sep 08 10:44:26 hyperion.local NetworkManager[12253]: DHCPDISCOVER on vethe127 to 255.255.255.255 port 67 interval 11 (xid=0x6644bb94)
Sep 08 10:44:33 hyperion.local kernel: docker0: topology change detected, propagating
Sep 08 10:44:33 hyperion.local kernel: docker0: port 2(vethe127) entered forwarding state
Sep 08 10:44:37 hyperion.local dhclient[13441]: DHCPDISCOVER on vethe127 to 255.255.255.255 port 67 interval 10 (xid=0x6644bb94)
Sep 08 10:44:37 hyperion.local NetworkManager[12253]: DHCPDISCOVER on vethe127 to 255.255.255.255 port 67 interval 10 (xid=0x6644bb94)
Sep 08 10:44:47 hyperion.local dhclient[13441]: DHCPDISCOVER on vethe127 to 255.255.255.255 port 67 interval 12 (xid=0x6644bb94)
Sep 08 10:44:47 hyperion.local NetworkManager[12253]: DHCPDISCOVER on vethe127 to 255.255.255.255 port 67 interval 12 (xid=0x6644bb94)
Sep 08 10:44:49 hyperion.local NetworkManager[12253]: <warn> (vethe127): DHCPv4 request timed out.
Sep 08 10:44:49 hyperion.local NetworkManager[12253]: <info> (vethe127): canceled DHCP transaction, DHCP client pid 13441
Sep 08 10:44:49 hyperion.local NetworkManager[12253]: <info> Activation (vethe127) Stage 4 of 5 (IPv4 Configure Timeout) scheduled...
Sep 08 10:44:49 hyperion.local NetworkManager[12253]: <info> Activation (vethe127) Stage 4 of 5 (IPv4 Configure Timeout) started...
############################################
###Networking for container starts working. ~40 seconds later) 
############################################
Sep 08 10:44:49 hyperion.local NetworkManager[12253]: <info> Activation (vethe127) Stage 4 of 5 (IPv4 Configure Timeout) complete.

Comment 3 Aric 2014-09-08 15:10:49 UTC
Sorry this line I added is unclear

###Networking for container starts working. ~40 seconds later) 

I mean that from the top of the log its been 40 seconds, the networking works as soon as I receive the last log message 

Sep 08 10:44:49 hyperion.local NetworkManager[12253]: <info> Activation (vethe127) Stage 4 of 5 (IPv4 Configure Timeout) complete.

Comment 4 Fedora End Of Life 2015-05-29 12:35:26 UTC
This message is a reminder that Fedora 20 is nearing its end of life.
Approximately 4 (four) weeks from now Fedora will stop maintaining
and issuing updates for Fedora 20. It is Fedora's policy to close all
bug reports from releases that are no longer maintained. At that time
this bug will be closed as EOL if it remains open with a Fedora  'version'
of '20'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, simply change the 'version' 
to a later Fedora version.

Thank you for reporting this issue and we are sorry that we were not 
able to fix it before Fedora 20 is end of life. If you would still like 
to see this bug fixed and are able to reproduce it against a later version 
of Fedora, you are encouraged  change the 'version' to a later Fedora 
version prior this bug is closed as described in the policy above.

Although we aim to fix as many bugs as possible during every release's 
lifetime, sometimes those efforts are overtaken by events. Often a 
more recent Fedora release includes newer upstream software that fixes 
bugs or makes them obsolete.

Comment 5 Fedora End Of Life 2015-06-29 21:59:23 UTC
Fedora 20 changed to end-of-life (EOL) status on 2015-06-23. Fedora 20 is
no longer maintained, which means that it will not receive any further
security or bug fix updates. As a result we are closing this bug.

If you can reproduce this bug against a currently maintained version of
Fedora please feel free to reopen this bug against that version. If you
are unable to reopen this bug, please file a new report against the
current release. If you experience problems, please add a comment to this
bug.

Thank you for reporting this bug and we are sorry it could not be fixed.


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