search

devplayer0 / docker-net-dhcp

Docker network driver for networking on a host bridge with DHCP-allocated IP addresses
GNU General Public License v3.0
193 stars 55 forks source link

NetworkDriver.CreateEndpoint: Timed out waiting for lease from udhcpc #12

Closed apsoyka closed 2 years ago

apsoyka commented 3 years ago 
<local> - - [10/May/2021 20:48:16] "POST /NetworkDriver.CreateNetwork HTTP/1.1" 200 -
<local> - - [10/May/2021 20:48:28] "POST /NetworkDriver.CreateEndpoint HTTP/1.1" 0 -
400 Bad Request: The browser (or proxy) sent a request that this server could not understand.
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/site-packages/werkzeug/wrappers/json.py", line 119, in get_json
    rv = self.json_module.loads(data)
  File "/usr/local/lib/python3.9/site-packages/flask/json/__init__.py", line 253, in loads
    return _json.loads(s, **kwargs)
  File "/usr/local/lib/python3.9/json/__init__.py", line 359, in loads
    return cls(**kw).decode(s)
  File "/usr/local/lib/python3.9/json/decoder.py", line 337, in decode
    obj, end = self.raw_decode(s, idx=_w(s, 0).end())
  File "/usr/local/lib/python3.9/json/decoder.py", line 355, in raw_decode
    raise JSONDecodeError("Expecting value", s, err.value) from None
json.decoder.JSONDecodeError: Expecting value: line 1 column 1 (char 0)

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.9/site-packages/flask/app.py", line 1949, in full_dispatch_request
    rv = self.dispatch_request()
  File "/usr/local/lib/python3.9/site-packages/flask/app.py", line 1935, in dispatch_request
    return self.view_functions[rule.endpoint](**req.view_args)
  File "/opt/plugin/net_dhcp/network.py", line 134, in create_endpoint
    req = request.get_json(force=True)
  File "/usr/local/lib/python3.9/site-packages/werkzeug/wrappers/json.py", line 128, in get_json
    rv = self.on_json_loading_failed(e)
  File "/usr/local/lib/python3.9/site-packages/flask/wrappers.py", line 27, in on_json_loading_failed
    raise BadRequest()
werkzeug.exceptions.BadRequest: 400 Bad Request: The browser (or proxy) sent a request that this server could not understand.
<local> - - [10/May/2021 20:48:29] "POST /NetworkDriver.CreateEndpoint HTTP/1.1" 500 -
<local> - - [10/May/2021 20:48:40] "POST /NetworkDriver.CreateEndpoint HTTP/1.1" 500 -
<local> - - [10/May/2021 20:48:51] "POST /NetworkDriver.CreateEndpoint HTTP/1.1" 500 -
<local> - - [10/May/2021 20:49:02] "POST /NetworkDriver.CreateEndpoint HTTP/1.1" 500 -
<local> - - [10/May/2021 20:49:18] "POST /NetworkDriver.DeleteNetwork HTTP/1.1" 200 -
2021-05-10 21:23:18,532 [INFO] Creating network "f70003e0ba7478a179b6f00c01c93c65b154a52f8aae192ec2ce7b96d3191d6d" (using bridge "br0")
2021-05-10 21:23:27,415 [INFO] creating veth pair dh-941645c468a3 <=> 941645c468a3-dh
2021-05-10 21:23:27,847 [DEBUG] [udhcp#30075 event] {'type': <EventType.DECONFIG: 'deconfig'>}
2021-05-10 21:23:37,742 [ERROR] Timed out waiting for lease from udhcpc
Traceback (most recent call last):
  File "/opt/plugin/net_dhcp/network.py", line 199, in create_endpoint
    try_addr('v4')
  File "/opt/plugin/net_dhcp/network.py", line 190, in try_addr
    addr = dhcp.finish()
  File "/opt/plugin/net_dhcp/udhcpc.py", line 136, in finish
    self.await_ip()
  File "/opt/plugin/net_dhcp/udhcpc.py", line 124, in await_ip
    raise DHCPClientError(f'Timed out waiting for lease from udhcpc{self._suffix}')
net_dhcp.udhcpc.DHCPClientError: Timed out waiting for lease from udhcpc
AndreaBorgia-Abo commented 3 years ago

@ddsoyka have you found a way to fix this?

apsoyka commented 3 years ago

@AndreaBorgia-Abo Nope, I poked through the code a little bit but I don't know what's wrong.

AndreaBorgia-Abo commented 3 years ago

@devplayer0 any tips for debugging this? I know, rewrite and such... but in the meanwhile... I'd love to understand why this isn't working.

devplayer0 commented 3 years ago

Hey @ddsoyka @AndreaBorgia-Abo! Finally getting back to working on this. I'm not really sure what's going on here to be honest, but hopefully this won't be an issue when I'm done with the rewrite. I'm actually hoping to have it working within the next week or so (see #3)!

I've got DHCP working on startup. Currently the background DHCP client (responsible for maintaining the lease) is not implemented, but that's next on the list. If you want to try it out, replace the image used in all the commands with the latest tag from here. At time of writing this would mean using ghcr.io/devplayer0/docker-net-dhcp:18444a5c-1623100614Z in place of devplayer0/net-dhcp in any Docker commands described in the README. I obviously haven't updated the docs yet, but the setup should be the same.

Tone866 commented 3 years ago

Are you using a VM? I do and have the same issue. Sadly this plugin doesn't work on my pi and I doesn't have a other physical Linux machine.. This is my issue on my pi:

pi@raspberrypi:~ $ sudo docker plugin install devplayer0/net-dhcp
Plugin "devplayer0/net-dhcp" is requesting the following privileges:
 - network: [host]
 - host pid namespace: [true]
 - mount: [/var/run/docker.sock]
 - capabilities: [CAP_NET_ADMIN CAP_SYS_ADMIN CAP_SYS_PTRACE CAP_SYS_RESOURCE]
Do you grant the above permissions? [y/N] y
latest: Pulling from devplayer0/net-dhcp
f20d1e188e68: Download complete
Digest: sha256:fe6055ff762181da6a358dad689c6a8cfd5fa3687a3a1da9c4cec894eea6f41a
Status: Downloaded newer image for devplayer0/net-dhcp:latest
Error response from daemon: dial unix /run/docker/plugins/41b2fc8f173d4801db15165b8e6d3ff2da5791e8257f0c46958f69a7d36b60d6/net-dhcp.sock: connect: no such file or director

Anyway.. I traced the dhcp traffic on my router and VM. The discover just works. Then the router sends an offer but the VM doesn't receive it. So I think it's maybe a problem of the VM network driver on the host machine (I'm using Win10 with Virtual Box). It seems it didn't forward the packet (maybe because the Mac isn't learned?).

devplayer0 commented 3 years ago

@Tone866 Your problem here is that the plugin is currently only available for amd64 machines. Given the popularity of ARM-based systems these days, I'll be looking into getting images built for other platforms with the new Go edition. Until then I'm afraid there's not much you can do :(

Tone866 commented 3 years ago

@devplayer0 Thats sad :( Because I wanted the use it on a Pi and didn't find an alternative for this plugin. But my VM is amd64 so this should work.

devplayer0 commented 3 years ago

@Tone866 I've opened #13 to track the lack of non-amd64 support.

AndreaBorgia-Abo commented 3 years ago

@Tone866 Debian host, AMD64 native, no VM.

Tone866 commented 3 years ago

@AndreaBorgia-Abo ok thanks! Could you trace with tcpdump -i eth0 -n port 67 and port 68 while you start the container? In best case on the host and the router. It would be interesting to me if you also not receiving an offer.

devplayer0 commented 3 years ago

The Go rewrite is now complete :smile: Increasing the log verbosity (see README) may help with detecting some problems.

Tone866 commented 3 years ago

Nothing changed for me, the VM do not receive the offer, but the router sends it. Maybe you should set the broadcast flag in the discover.

time="2021-06-11T16:49:26Z" level=error msg="Error while processing request" error="failed to get initial IP address via DHCP: context deadline exceeded"
devplayer0 commented 3 years ago

@Tone866 Can you check your iptables configuration? Perhaps you are experiencing the same issue as @blop in #14.

Tone866 commented 3 years ago

@devplayer0 no sadly not, same issue, no offer at the VM

root@ubuntu-vm:~# sysctl -w net.bridge.bridge-nf-call-iptables=0
net.bridge.bridge-nf-call-iptables = 0
root@ubuntu-vm:~# docker run --rm -ti --network my-dhcp-net alpine
docker: Error response from daemon: failed to create endpoint jolly_shaw on network my-dhcp-net: NetworkDriver.CreateEndpoint: failed to get initial IP address via DHCP: context deadline exceeded.
devplayer0 commented 3 years ago

What's in your iptables? There's something strange going on here. Does the offer make it as far as the host (as in the machine running Docker)? You can set LOG_LEVEL on the plugin and read the logs (check the README) to see if there's an issue with udhcpc not running correctly too.

Tone866 commented 3 years ago

iptables:

# ip a
1: lo: <LOOPBACK,UP,LOWER_UP> mtu 65536 qdisc noqueue state UNKNOWN group default qlen 1000
    link/loopback 00:00:00:00:00:00 brd 00:00:00:00:00:00
    inet 127.0.0.1/8 scope host lo
       valid_lft forever preferred_lft forever
    inet6 ::1/128 scope host 
       valid_lft forever preferred_lft forever
2: enp0s3: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc fq_codel master my-bridge state UP group default qlen 1000
    link/ether 08:00:27:86:99:ce brd ff:ff:ff:ff:ff:ff
5: docker0: <NO-CARRIER,BROADCAST,MULTICAST,UP> mtu 1500 qdisc noqueue state DOWN group default 
    link/ether 02:42:3a:10:89:20 brd ff:ff:ff:ff:ff:ff
    inet 172.17.0.1/16 brd 172.17.255.255 scope global docker0
       valid_lft forever preferred_lft forever
6: my-bridge: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc noqueue state UP group default qlen 1000
    link/ether 08:00:27:86:99:ce brd ff:ff:ff:ff:ff:ff
    inet 192.168.10.126/24 brd 192.168.10.255 scope global dynamic my-bridge
       valid_lft 862490sec preferred_lft 862490sec
    inet6 fe80::74d3:32ff:fe31:39da/64 scope link 
       valid_lft forever preferred_lft forever

# iptables -L -n
Chain INPUT (policy ACCEPT)
target     prot opt source               destination         

Chain FORWARD (policy ACCEPT)
target     prot opt source               destination         
DOCKER-USER  all  --  0.0.0.0/0            0.0.0.0/0           
DOCKER-ISOLATION-STAGE-1  all  --  0.0.0.0/0            0.0.0.0/0           
ACCEPT     all  --  0.0.0.0/0            0.0.0.0/0            ctstate RELATED,ESTABLISHED
DOCKER     all  --  0.0.0.0/0            0.0.0.0/0           
ACCEPT     all  --  0.0.0.0/0            0.0.0.0/0           
ACCEPT     all  --  0.0.0.0/0            0.0.0.0/0           

Chain OUTPUT (policy ACCEPT)
target     prot opt source               destination         

Chain DOCKER (1 references)
target     prot opt source               destination         

Chain DOCKER-ISOLATION-STAGE-1 (1 references)
target     prot opt source               destination         
DOCKER-ISOLATION-STAGE-2  all  --  0.0.0.0/0            0.0.0.0/0           
RETURN     all  --  0.0.0.0/0            0.0.0.0/0           

Chain DOCKER-ISOLATION-STAGE-2 (1 references)
target     prot opt source               destination         
DROP       all  --  0.0.0.0/0            0.0.0.0/0           
RETURN     all  --  0.0.0.0/0            0.0.0.0/0           

Chain DOCKER-USER (1 references)
target     prot opt source               destination         
RETURN     all  --  0.0.0.0/0            0.0.0.0/0

Log:

time="2021-06-13T12:55:54Z" level=debug msg="CreateEndpoint options" options="map[com.docker.network.endpoint.exposedports:[] com.docker.network.portmap:[]]"
time="2021-06-13T12:55:54Z" level=trace msg="new udhcpc client" cmd="/sbin/udhcpc -f -i 8484b43d09eb-dh -s /usr/lib/net-dhcp/udhcpc-handler -q -V docker-net-dhcp"
time="2021-06-13T12:55:54Z" level=debug msg="udhcpc: started, v1.32.1"
time="2021-06-13T12:55:54Z" level=trace msg="udhcpc handler line" line="{\"Type\":\"deconfig\",\"Data\":{\"IP\":\"\",\"Gateway\":\"\",\"Domain\":\"\"}}"
time="2021-06-13T12:55:54Z" level=debug msg="udhcpc: sending discover"
time="2021-06-13T12:55:57Z" level=debug msg="udhcpc: sending discover"
time="2021-06-13T12:56:00Z" level=debug msg="udhcpc: sending discover"
time="2021-06-13T12:56:03Z" level=debug msg="udhcpc: sending discover"
time="2021-06-13T12:56:04Z" level=error msg="Error while processing request" error="failed to get initial IP address via DHCP: context deadline exceeded"
time="2021-06-13T12:56:04Z" level=trace msg="POST /NetworkDriver.CreateEndpoint" resSize=79 status=500

I tried the the new version on my pi and had the same behaviour. The discover was send, but after that nothing. Sadly this time I couldn't trace on my router.

AndreaBorgia-Abo commented 3 years ago

Running without IPV6, with the "sysctl -w net.bridge.bridge-nf-call-iptables=0" command and a longer timeout the plugin works.

When started with IPV6 enabled, the router will receive and reply with an IPV4 lease but it will timeout on the IPV6 one.

time="2021-06-17T21:21:20Z" level=debug msg="udhcpc: sending discover"
time="2021-06-17T21:21:20Z" level=debug msg="udhcpc: sending select for 192.168.2.96"
time="2021-06-17T21:21:20Z" level=debug msg="udhcpc: lease of 192.168.2.96 obtained, lease time 86400"
time="2021-06-17T21:21:20Z" level=trace msg="udhcpc handler line" line="{\"Type\":\"bound\",\"Data\":{\"IP\":\"192.168.2.96/24\",\"Gateway\":\"192.168.2.1\",\"Domain\":\"chateaulan\"}}"
time="2021-06-17T21:21:20Z" level=trace msg="new udhcpc client" cmd="/usr/bin/udhcpc6 -f -i 157863ca8014-dh -s /usr/lib/net-dhcp/udhcpc-handler -q"
time="2021-06-17T21:21:20Z" level=debug msg="udhcpc6: started, v1.32.1"
time="2021-06-17T21:21:20Z" level=trace msg="udhcpc handler line" line="{\"Type\":\"deconfig\",\"Data\":{\"IP\":\"\",\"Gateway\":\"\",\"Domain\":\"\"}}"
time="2021-06-17T21:21:20Z" level=debug msg="udhcpc6: sending discover"
time="2021-06-17T21:21:24Z" level=debug msg="udhcpc6: sending discover"
time="2021-06-17T21:21:27Z" level=debug msg="udhcpc6: sending discover"
time="2021-06-17T21:21:30Z" level=trace msg="udhcpc handler line" line="{\"Type\":\"leasefail\",\"Data\":{\"IP\":\"\",\"Gateway\":\"\",\"Domain\":\"\"}}"
time="2021-06-17T21:21:41Z" level=error msg="Error while processing request" error="failed to get initial IPv6 address via DHCPv6: context canceled"
time="2021-06-17T21:21:41Z" level=trace msg="POST /NetworkDriver.CreateEndpoint" resSize=74 status=500

Since it helped with IPV4, I added this command: sysctl -w net.bridge.bridge-nf-call-ip6tables=0

After noting down the MAC from the IPV4 DHCP request, I ran Wireshark capturing IPV6 only and later applied a visualization filter to show only the container traffic: apparently DHCPv6 requests are sent but no replies are received.

Fun fact: according to my OpenWRT router, requests are always answered:

Thu Jun 17 21:21:20 2021 daemon.info dnsmasq-dhcp[21675]: DHCPDISCOVER(br-casa) 7a:17:68:d6:a2:0c
Thu Jun 17 21:21:20 2021 daemon.info dnsmasq-dhcp[21675]: DHCPOFFER(br-casa) 192.168.2.96 7a:17:68:d6:a2:0c
Thu Jun 17 21:21:20 2021 daemon.info dnsmasq-dhcp[21675]: DHCPDISCOVER(br-casa) 7a:17:68:d6:a2:0c
Thu Jun 17 21:21:20 2021 daemon.info dnsmasq-dhcp[21675]: DHCPOFFER(br-casa) 192.168.2.96 7a:17:68:d6:a2:0c
Thu Jun 17 21:21:20 2021 daemon.info dnsmasq-dhcp[21675]: DHCPREQUEST(br-casa) 192.168.2.96 7a:17:68:d6:a2:0c
Thu Jun 17 21:21:20 2021 daemon.info dnsmasq-dhcp[21675]: DHCPACK(br-casa) 192.168.2.96 7a:17:68:d6:a2:0c
Thu Jun 17 21:21:20 2021 daemon.debug odhcpd[29058]: Received 54 Bytes from fe80::7817:68ff:fed6:a20c%casa@br-casa
Thu Jun 17 21:21:20 2021 daemon.debug odhcpd[29058]: Got a DHCPv6-request on casa
Thu Jun 17 21:21:20 2021 daemon.info odhcpd[29058]: DHCPV6 SOLICIT IA_NA from 000300017a1768d6a20c on casa: ok SOMEPREFIX::f37/128 OTHERPREFIX::f37/128
Thu Jun 17 21:21:20 2021 daemon.debug odhcpd[29058]: Sending a DHCPv6-reply on casa
Thu Jun 17 21:21:20 2021 daemon.debug odhcpd[29058]: Sent 132 bytes to fe80::7817:68ff:fed6:a20c%casa@br-casa
devplayer0 commented 3 years ago

iptables:

# ip a
1: lo: <LOOPBACK,UP,LOWER_UP> mtu 65536 qdisc noqueue state UNKNOWN group default qlen 1000
    link/loopback 00:00:00:00:00:00 brd 00:00:00:00:00:00
    inet 127.0.0.1/8 scope host lo
       valid_lft forever preferred_lft forever
    inet6 ::1/128 scope host 
       valid_lft forever preferred_lft forever
2: enp0s3: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc fq_codel master my-bridge state UP group default qlen 1000
    link/ether 08:00:27:86:99:ce brd ff:ff:ff:ff:ff:ff
5: docker0: <NO-CARRIER,BROADCAST,MULTICAST,UP> mtu 1500 qdisc noqueue state DOWN group default 
    link/ether 02:42:3a:10:89:20 brd ff:ff:ff:ff:ff:ff
    inet 172.17.0.1/16 brd 172.17.255.255 scope global docker0
       valid_lft forever preferred_lft forever
6: my-bridge: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc noqueue state UP group default qlen 1000
    link/ether 08:00:27:86:99:ce brd ff:ff:ff:ff:ff:ff
    inet 192.168.10.126/24 brd 192.168.10.255 scope global dynamic my-bridge
       valid_lft 862490sec preferred_lft 862490sec
    inet6 fe80::74d3:32ff:fe31:39da/64 scope link 
       valid_lft forever preferred_lft forever

# iptables -L -n
Chain INPUT (policy ACCEPT)
target     prot opt source               destination         

Chain FORWARD (policy ACCEPT)
target     prot opt source               destination         
DOCKER-USER  all  --  0.0.0.0/0            0.0.0.0/0           
DOCKER-ISOLATION-STAGE-1  all  --  0.0.0.0/0            0.0.0.0/0           
ACCEPT     all  --  0.0.0.0/0            0.0.0.0/0            ctstate RELATED,ESTABLISHED
DOCKER     all  --  0.0.0.0/0            0.0.0.0/0           
ACCEPT     all  --  0.0.0.0/0            0.0.0.0/0           
ACCEPT     all  --  0.0.0.0/0            0.0.0.0/0           

Chain OUTPUT (policy ACCEPT)
target     prot opt source               destination         

Chain DOCKER (1 references)
target     prot opt source               destination         

Chain DOCKER-ISOLATION-STAGE-1 (1 references)
target     prot opt source               destination         
DOCKER-ISOLATION-STAGE-2  all  --  0.0.0.0/0            0.0.0.0/0           
RETURN     all  --  0.0.0.0/0            0.0.0.0/0           

Chain DOCKER-ISOLATION-STAGE-2 (1 references)
target     prot opt source               destination         
DROP       all  --  0.0.0.0/0            0.0.0.0/0           
RETURN     all  --  0.0.0.0/0            0.0.0.0/0           

Chain DOCKER-USER (1 references)
target     prot opt source               destination         
RETURN     all  --  0.0.0.0/0            0.0.0.0/0

Log:

time="2021-06-13T12:55:54Z" level=debug msg="CreateEndpoint options" options="map[com.docker.network.endpoint.exposedports:[] com.docker.network.portmap:[]]"
time="2021-06-13T12:55:54Z" level=trace msg="new udhcpc client" cmd="/sbin/udhcpc -f -i 8484b43d09eb-dh -s /usr/lib/net-dhcp/udhcpc-handler -q -V docker-net-dhcp"
time="2021-06-13T12:55:54Z" level=debug msg="udhcpc: started, v1.32.1"
time="2021-06-13T12:55:54Z" level=trace msg="udhcpc handler line" line="{\"Type\":\"deconfig\",\"Data\":{\"IP\":\"\",\"Gateway\":\"\",\"Domain\":\"\"}}"
time="2021-06-13T12:55:54Z" level=debug msg="udhcpc: sending discover"
time="2021-06-13T12:55:57Z" level=debug msg="udhcpc: sending discover"
time="2021-06-13T12:56:00Z" level=debug msg="udhcpc: sending discover"
time="2021-06-13T12:56:03Z" level=debug msg="udhcpc: sending discover"
time="2021-06-13T12:56:04Z" level=error msg="Error while processing request" error="failed to get initial IP address via DHCP: context deadline exceeded"
time="2021-06-13T12:56:04Z" level=trace msg="POST /NetworkDriver.CreateEndpoint" resSize=79 status=500

I tried the the new version on my pi and had the same behaviour. The discover was send, but after that nothing. Sadly this time I couldn't trace on my router.

This is strange indeed. Which DHCP client did you use on the host to successfully get an IP? Is it possible the timeout was more lenient in that case?

devplayer0 commented 3 years ago

Running without IPV6, with the "sysctl -w net.bridge.bridge-nf-call-iptables=0" command and a longer timeout the plugin works.

When started with IPV6 enabled, the router will receive and reply with an IPV4 lease but it will timeout on the IPV6 one.

time="2021-06-17T21:21:20Z" level=debug msg="udhcpc: sending discover"
time="2021-06-17T21:21:20Z" level=debug msg="udhcpc: sending select for 192.168.2.96"
time="2021-06-17T21:21:20Z" level=debug msg="udhcpc: lease of 192.168.2.96 obtained, lease time 86400"
time="2021-06-17T21:21:20Z" level=trace msg="udhcpc handler line" line="{\"Type\":\"bound\",\"Data\":{\"IP\":\"192.168.2.96/24\",\"Gateway\":\"192.168.2.1\",\"Domain\":\"chateaulan\"}}"
time="2021-06-17T21:21:20Z" level=trace msg="new udhcpc client" cmd="/usr/bin/udhcpc6 -f -i 157863ca8014-dh -s /usr/lib/net-dhcp/udhcpc-handler -q"
time="2021-06-17T21:21:20Z" level=debug msg="udhcpc6: started, v1.32.1"
time="2021-06-17T21:21:20Z" level=trace msg="udhcpc handler line" line="{\"Type\":\"deconfig\",\"Data\":{\"IP\":\"\",\"Gateway\":\"\",\"Domain\":\"\"}}"
time="2021-06-17T21:21:20Z" level=debug msg="udhcpc6: sending discover"
time="2021-06-17T21:21:24Z" level=debug msg="udhcpc6: sending discover"
time="2021-06-17T21:21:27Z" level=debug msg="udhcpc6: sending discover"
time="2021-06-17T21:21:30Z" level=trace msg="udhcpc handler line" line="{\"Type\":\"leasefail\",\"Data\":{\"IP\":\"\",\"Gateway\":\"\",\"Domain\":\"\"}}"
time="2021-06-17T21:21:41Z" level=error msg="Error while processing request" error="failed to get initial IPv6 address via DHCPv6: context canceled"
time="2021-06-17T21:21:41Z" level=trace msg="POST /NetworkDriver.CreateEndpoint" resSize=74 status=500

Since it helped with IPV4, I added this command: sysctl -w net.bridge.bridge-nf-call-ip6tables=0

After noting down the MAC from the IPV4 DHCP request, I ran Wireshark capturing IPV6 only and later applied a visualization filter to show only the container traffic: apparently DHCPv6 requests are sent but no replies are received.

Fun fact: according to my OpenWRT router, requests are always answered:

Thu Jun 17 21:21:20 2021 daemon.info dnsmasq-dhcp[21675]: DHCPDISCOVER(br-casa) 7a:17:68:d6:a2:0c
Thu Jun 17 21:21:20 2021 daemon.info dnsmasq-dhcp[21675]: DHCPOFFER(br-casa) 192.168.2.96 7a:17:68:d6:a2:0c
Thu Jun 17 21:21:20 2021 daemon.info dnsmasq-dhcp[21675]: DHCPDISCOVER(br-casa) 7a:17:68:d6:a2:0c
Thu Jun 17 21:21:20 2021 daemon.info dnsmasq-dhcp[21675]: DHCPOFFER(br-casa) 192.168.2.96 7a:17:68:d6:a2:0c
Thu Jun 17 21:21:20 2021 daemon.info dnsmasq-dhcp[21675]: DHCPREQUEST(br-casa) 192.168.2.96 7a:17:68:d6:a2:0c
Thu Jun 17 21:21:20 2021 daemon.info dnsmasq-dhcp[21675]: DHCPACK(br-casa) 192.168.2.96 7a:17:68:d6:a2:0c
Thu Jun 17 21:21:20 2021 daemon.debug odhcpd[29058]: Received 54 Bytes from fe80::7817:68ff:fed6:a20c%casa@br-casa
Thu Jun 17 21:21:20 2021 daemon.debug odhcpd[29058]: Got a DHCPv6-request on casa
Thu Jun 17 21:21:20 2021 daemon.info odhcpd[29058]: DHCPV6 SOLICIT IA_NA from 000300017a1768d6a20c on casa: ok SOMEPREFIX::f37/128 OTHERPREFIX::f37/128
Thu Jun 17 21:21:20 2021 daemon.debug odhcpd[29058]: Sending a DHCPv6-reply on casa
Thu Jun 17 21:21:20 2021 daemon.debug odhcpd[29058]: Sent 132 bytes to fe80::7817:68ff:fed6:a20c%casa@br-casa

Nice that IPv4 works at least. IPv6 support may not be 100% there since my test setup is fairly basic and I'm not using it myself. What interface are you capturing traffic on? Maybe the DHCPv6 replies are being dropped across your network card before they get to the bridge?

AndreaBorgia-Abo commented 3 years ago

@devplayer0 Honestly I don't remember but I did see the outgoing requests. If you wish to test using IPV6, you can get a tunnel for free from he.net

Tone866 commented 3 years ago

iptables:

# ip a
1: lo: <LOOPBACK,UP,LOWER_UP> mtu 65536 qdisc noqueue state UNKNOWN group default qlen 1000
    link/loopback 00:00:00:00:00:00 brd 00:00:00:00:00:00
    inet 127.0.0.1/8 scope host lo
       valid_lft forever preferred_lft forever
    inet6 ::1/128 scope host 
       valid_lft forever preferred_lft forever
2: enp0s3: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc fq_codel master my-bridge state UP group default qlen 1000
    link/ether 08:00:27:86:99:ce brd ff:ff:ff:ff:ff:ff
5: docker0: <NO-CARRIER,BROADCAST,MULTICAST,UP> mtu 1500 qdisc noqueue state DOWN group default 
    link/ether 02:42:3a:10:89:20 brd ff:ff:ff:ff:ff:ff
    inet 172.17.0.1/16 brd 172.17.255.255 scope global docker0
       valid_lft forever preferred_lft forever
6: my-bridge: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc noqueue state UP group default qlen 1000
    link/ether 08:00:27:86:99:ce brd ff:ff:ff:ff:ff:ff
    inet 192.168.10.126/24 brd 192.168.10.255 scope global dynamic my-bridge
       valid_lft 862490sec preferred_lft 862490sec
    inet6 fe80::74d3:32ff:fe31:39da/64 scope link 
       valid_lft forever preferred_lft forever

# iptables -L -n
Chain INPUT (policy ACCEPT)
target     prot opt source               destination         

Chain FORWARD (policy ACCEPT)
target     prot opt source               destination         
DOCKER-USER  all  --  0.0.0.0/0            0.0.0.0/0           
DOCKER-ISOLATION-STAGE-1  all  --  0.0.0.0/0            0.0.0.0/0           
ACCEPT     all  --  0.0.0.0/0            0.0.0.0/0            ctstate RELATED,ESTABLISHED
DOCKER     all  --  0.0.0.0/0            0.0.0.0/0           
ACCEPT     all  --  0.0.0.0/0            0.0.0.0/0           
ACCEPT     all  --  0.0.0.0/0            0.0.0.0/0           

Chain OUTPUT (policy ACCEPT)
target     prot opt source               destination         

Chain DOCKER (1 references)
target     prot opt source               destination         

Chain DOCKER-ISOLATION-STAGE-1 (1 references)
target     prot opt source               destination         
DOCKER-ISOLATION-STAGE-2  all  --  0.0.0.0/0            0.0.0.0/0           
RETURN     all  --  0.0.0.0/0            0.0.0.0/0           

Chain DOCKER-ISOLATION-STAGE-2 (1 references)
target     prot opt source               destination         
DROP       all  --  0.0.0.0/0            0.0.0.0/0           
RETURN     all  --  0.0.0.0/0            0.0.0.0/0           

Chain DOCKER-USER (1 references)
target     prot opt source               destination         
RETURN     all  --  0.0.0.0/0            0.0.0.0/0

Log:

time="2021-06-13T12:55:54Z" level=debug msg="CreateEndpoint options" options="map[com.docker.network.endpoint.exposedports:[] com.docker.network.portmap:[]]"
time="2021-06-13T12:55:54Z" level=trace msg="new udhcpc client" cmd="/sbin/udhcpc -f -i 8484b43d09eb-dh -s /usr/lib/net-dhcp/udhcpc-handler -q -V docker-net-dhcp"
time="2021-06-13T12:55:54Z" level=debug msg="udhcpc: started, v1.32.1"
time="2021-06-13T12:55:54Z" level=trace msg="udhcpc handler line" line="{\"Type\":\"deconfig\",\"Data\":{\"IP\":\"\",\"Gateway\":\"\",\"Domain\":\"\"}}"
time="2021-06-13T12:55:54Z" level=debug msg="udhcpc: sending discover"
time="2021-06-13T12:55:57Z" level=debug msg="udhcpc: sending discover"
time="2021-06-13T12:56:00Z" level=debug msg="udhcpc: sending discover"
time="2021-06-13T12:56:03Z" level=debug msg="udhcpc: sending discover"
time="2021-06-13T12:56:04Z" level=error msg="Error while processing request" error="failed to get initial IP address via DHCP: context deadline exceeded"
time="2021-06-13T12:56:04Z" level=trace msg="POST /NetworkDriver.CreateEndpoint" resSize=79 status=500

I tried the the new version on my pi and had the same behaviour. The discover was send, but after that nothing. Sadly this time I couldn't trace on my router.

This is strange indeed. Which DHCP client did you use on the host to successfully get an IP? Is it possible the timeout was more lenient in that case?

I‘m using dhclient. The timeout shouldn‘t be a problem. My router answers fast and I never had issues with that.

AndreaBorgia-Abo commented 3 years ago

@devplayer0 any news on the IPV6 front?

apsoyka commented 2 years ago

I am no longer experiencing this problem when using version 0.1.4 of this plugin (after the Go rewrite); therefore I'm going to close this issue.

AndreaBorgia-Abo commented 2 years ago

It still does not work for IPV6, though