Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Docker 25.03 - Updating containers results in IP Error #47441

Closed
edrikk opened this issue Feb 23, 2024 · 11 comments · Fixed by #47474
Closed

Docker 25.03 - Updating containers results in IP Error #47441

edrikk opened this issue Feb 23, 2024 · 11 comments · Fixed by #47474
Assignees
Labels
area/networking kind/bug Bugs are bugs. The cause may or may not be known at triage time so debugging may be needed. version/25.0

Comments

@edrikk
Copy link

edrikk commented Feb 23, 2024

Description

I had incorrectly opened this issue in the CLI tracker. So closing that, and recreating here.
Copy-paste from that ticket.


Hi,

I had been running docker 24.0.X successfully with current setup without issue, however docker 25 started the below. I saw that fixes had gone into version including the 25.0.3 item to resolve MAC address issues.
I have also followed the instructions around recreating all the dockers once on 25.0.3 but my issue remains.

My setup is as follows:

  • I have a macvlan-network setup with IPV4 Subnet - 192.168.40.0/22 and IPV4 Gateway - 192.168.41.1. I have defined IPV4 IP Range - 192.168.42.252/32.
  • I have portainer managing my dockers, with each docker stack defining the related docker's hard coded MAC and IP Address. For example:
version: "2.4"

services:
  librespeed:
    container_name: LibreSpeed
    image: adolfintel/speedtest:latest
    networks:
      macvlan-network:
         ipv4_address: 192.168.41.35
    hostname: speedtest
    domainname: MYFQDN.com
    mac_address: 02:42:c0:a8:29:23
    dns: 192.168.41.1
    restart: unless-stopped
    environment:
      - WEBPORT=80
networks:
  macvlan-network:
    external: true
    name: macvlan-network
  • I also have Watchtower which regularly updates my dockers.

Since upgrading from 24.0.X (and currently on 25.0.3), it appears that the first(? or one of the first) upgrades will be given the .252 address (even thouigh it should get a hardcoded/static IP as defined in the compose/stack). Since this is the only IP Address allowed in my range, the next updated dockers will fail to load with the error message:

Creating /NameOfDocker
Error response from daemon: no available IPv4 address on this network's address pools: macvlan-network (a36........f1).

At this point, I have to manually delete the docker container and delete the docker image of both the docker taking up the "wrongly assigned" IP address, as well as the containers that failed to install, then go into the stack/compose and redeploy them. They will then be given the correct static IP addresses, and all is well.

Until the next set of updates.

Reproduce

Per above.
If watchtower updates a given container after the number of updates passes the number of dynamic IPs that docker is allowed to allocated, this error seems to be hit.
In my case, I have set docker to allocate 1 single IP, but all my containers have static IP addresses defined for them - so the dynamic IP should never be used / cause this issue.

Expected behavior

Dockers should be given the \static MAC and IP address as defined in their docker compose/stack. This was the correct behavior in 24.0.X which has regressed in 25.0.X

docker version

Client: Docker Engine - Community
 Version:           25.0.3
 API version:       1.44
 Go version:        go1.21.6
 Git commit:        4debf41
 Built:             Tue Feb  6 21:14:25 2024
 OS/Arch:           linux/amd64
 Context:           default

Server: Docker Engine - Community
 Engine:
  Version:          25.0.3
  API version:      1.44 (minimum version 1.24)
  Go version:       go1.21.6
  Git commit:       f417435
  Built:            Tue Feb  6 21:14:25 2024
  OS/Arch:          linux/amd64
  Experimental:     false
 containerd:
  Version:          1.6.28
  GitCommit:        ae07eda36dd25f8a1b98dfbf587313b99c0190bb
 runc:
  Version:          1.1.12
  GitCommit:        v1.1.12-0-g51d5e94
 docker-init:
  Version:          0.19.0
  GitCommit:        de40ad0

docker info

Client: Docker Engine - Community
 Version:    25.0.3
 Context:    default
 Debug Mode: false
 Plugins:
  buildx: Docker Buildx (Docker Inc.)
    Version:  v0.12.1
    Path:     /usr/libexec/docker/cli-plugins/docker-buildx
  compose: Docker Compose (Docker Inc.)
    Version:  v2.24.5
    Path:     /usr/libexec/docker/cli-plugins/docker-compose

Server:
 Containers: 16
  Running: 15
  Paused: 0
  Stopped: 1
 Images: 16
 Server Version: 25.0.3
 Storage Driver: overlay2
  Backing Filesystem: extfs
  Supports d_type: true
  Using metacopy: false
  Native Overlay Diff: true
  userxattr: false
 Logging Driver: json-file
 Cgroup Driver: systemd
 Cgroup Version: 2
 Plugins:
  Volume: local
  Network: bridge host ipvlan macvlan null overlay
  Log: awslogs fluentd gcplogs gelf journald json-file local splunk syslog
 Swarm: inactive
 Runtimes: io.containerd.runc.v2 runc
 Default Runtime: runc
 Init Binary: docker-init
 containerd version: ae07eda36dd25f8a1b98dfbf587313b99c0190bb
 runc version: v1.1.12-0-g51d5e94
 init version: de40ad0
 Security Options:
  apparmor
  seccomp
   Profile: builtin
  cgroupns
 Kernel Version: 6.1.0-18-amd64
 Operating System: Debian GNU/Linux 12 (bookworm)
 OSType: linux
 Architecture: x86_64
 CPUs: 4
 Total Memory: 31.06GiB
 Name: GypsyPC
 ID: X76E:4OGO:P4TZ:NJT3:KUZK:BELS:4CQB:SD2N:NNKI:BEBQ:2CL6:TDMV
 Docker Root Dir: /var/lib/docker
 Debug Mode: false
 Experimental: false
 Insecure Registries:
  127.0.0.0/8
 Live Restore Enabled: false

Additional Info

No response

@edrikk edrikk added kind/bug Bugs are bugs. The cause may or may not be known at triage time so debugging may be needed. status/0-triage labels Feb 23, 2024
@edrikk
Copy link
Author

edrikk commented Feb 24, 2024

Hi there,

It happened again, so let me update with state. Over night, 2 containers were updated by WatchTower.
As a reminder, my macvlan-network is defined to have:

IPV4 Subnet - 192.168.40.0/22	
IPV4 Gateway - 192.168.41.1
IPV4 IP Range - 192.168.42.252/32

Portainer updated "CONTAINER_1" first, and it was "successful" (in the sense that it came back up). This container has been defined with stack/compose:

    networks:
      macvlan-network:
         ipv4_address: 192.168.41.45
    hostname: CONTAINER_1
    domainname: FQDN.com
    mac_address: 02:42:c0:a8:29:2d

However, although "successful", it is given IPv4 Address as below when I look within Portainer's "Networks" section:

Container Name	IPv4 Address	IPv6 Address	MacAddress	Actions
CONTAINER_1	192.168.42.252/22	-	02:42:c0:a8:29:2d

The 2nd container updated "CONTAINER_2" failed. Below is the WatchTower log:

time="2024-02-24T04:05:07-05:00" level=info msg="Found new lscr.io/linuxserver/CONTAINER_1:develop image (3e4b72d6d2f8)"
time="2024-02-24T04:05:48-05:00" level=info msg="Found new XXXXXXXXXXXXXX/CONTAINER_2:latest image (a99e85a7cad0)"
time="2024-02-24T04:05:50-05:00" level=info msg="Stopping /CONTAINER_2 (3e7358d6d649) with SIGTERM"
time="2024-02-24T04:05:58-05:00" level=info msg="Stopping /CONTAINER_1 (2856d62f0697) with SIGTERM"
time="2024-02-24T04:06:02-05:00" level=info msg="Creating /CONTAINER_1"
time="2024-02-24T04:06:03-05:00" level=info msg="Creating /CONTAINER_2"
time="2024-02-24T04:06:03-05:00" level=error msg="Error response from daemon: no available IPv4 addresses on this network's address pools: macvlan-network (a36c5938d7d8ca438bfd58adc987c31639a1687738c1e8014dc623f7603604f1)"
time="2024-02-24T04:06:03-05:00" level=info msg="Removing image 6c188dceeb72"
time="2024-02-24T04:06:03-05:00" level=info msg="Session done" Failed=1 Scanned=15 Updated=1 notify=no

Once the image is created for the container (which has failed and is assigned 252 address), stopping and restarting it does not change the address to the static IP that it is supposed to have. I have to delete the image, and rebuild, at which point the static IP IP address is correctly assigned, and then "CONTAINER_2" can also be repulled etc.

@edrikk
Copy link
Author

edrikk commented Feb 24, 2024

containrrr/watchtower#1912

Looks like the same issue that I’m reporting

@thaJeztah
Copy link
Member

cc @akerouanton @robmry

@robmry
Copy link
Contributor

robmry commented Feb 26, 2024

containrrr/watchtower#1912

Looks like the same issue that I’m reporting

Hi @edrikk - yes, it does sound like the same issue, also discussed at #47257 (comment) ...

I was unable to reproduce the problem, for me Watchtower managed to re-create the container with its configured address.

So, as described in that comment - if you're able to enable Docker's debug logging, it would be useful to see the "form data" log lines corresponding to the create/connect POST requests Watchtower is using to re-create the container.

@edrikk
Copy link
Author

edrikk commented Feb 27, 2024

Thanks @robmry for this.

I have captured a log overnight with the failure. Below snippet is the container that got the .252 address. All updates after this one failed with the no ip address error.

I have obfuscated some info (e.g. container names, etc) but if you wish for a fuller log or one that isn't edited, just let me know how to provide privately and I can do so.

The relevant part of compose/stack:

version: "2.4"

services:
  MY_CONTAINER:
    container_name: MY_CONTAINER
    image: lscr.io/linuxserver/MY_CONTAINER:develop
    networks:
      macvlan-network:
         ipv4_address: 192.168.41.46
    hostname: MY_CONTAINER
    domainname: FQDN.com
    mac_address: 02:42:c0:a8:29:28
    dns: 192.168.41.1
    restart: unless-stopped
    ports:
      - "7878:7878"

    volumes:
      - THE VOLUMES
    environment:
      - ENV VARS

networks:
  macvlan-network:
    external: true
    name: macvlan-network

The error log:

Feb 27 04:06:38 MyPC dockerd[760]: time="2024-02-27T04:06:38.529911794-05:00" level=debug msg="Calling GET /v1.25/containers/9955d4ddad013eaf34135aafae041d45c59a82d35b001282f5870cbe0da1ae7a/json"
Feb 27 04:06:38 MyPC dockerd[760]: time="2024-02-27T04:06:38.532232880-05:00" level=debug msg="Calling DELETE /v1.25/containers/9955d4ddad013eaf34135aafae041d45c59a82d35b001282f5870cbe0da1ae7a?force=1"
Feb 27 04:06:38 MyPC dockerd[760]: time="2024-02-27T04:06:38.583808537-05:00" level=debug msg="Calling GET /v1.25/containers/9955d4ddad013eaf34135aafae041d45c59a82d35b001282f5870cbe0da1ae7a/json"
Feb 27 04:06:38 MyPC dockerd[760]: time="2024-02-27T04:06:38.584844279-05:00" level=debug msg="Calling POST /v1.25/containers/1a70950919ad72542b9a7b9dd3b07751ac48e955d6c6a1b8d2792e2bd933a6f3/kill?signal=SIGTERM"
Feb 27 04:06:38 MyPC dockerd[760]: time="2024-02-27T04:06:38.584968468-05:00" level=debug msg="Sending kill signal 15 to container 1a70950919ad72542b9a7b9dd3b07751ac48e955d6c6a1b8d2792e2bd933a6f3"
Feb 27 04:06:38 MyPC dockerd[760]: time="2024-02-27T04:06:38.617577540-05:00" level=debug msg="Calling GET /v1.25/containers/1a70950919ad72542b9a7b9dd3b07751ac48e955d6c6a1b8d2792e2bd933a6f3/json"
Feb 27 04:06:39 MyPC dockerd[760]: time="2024-02-27T04:06:39.619141610-05:00" level=debug msg="Calling GET /v1.25/containers/1a70950919ad72542b9a7b9dd3b07751ac48e955d6c6a1b8d2792e2bd933a6f3/json"
Feb 27 04:06:40 MyPC dockerd[760]: time="2024-02-27T04:06:40.621446019-05:00" level=debug msg="Calling GET /v1.25/containers/1a70950919ad72542b9a7b9dd3b07751ac48e955d6c6a1b8d2792e2bd933a6f3/json"
Feb 27 04:06:41 MyPC dockerd[760]: time="2024-02-27T04:06:41.623585019-05:00" level=debug msg="Calling GET /v1.25/containers/1a70950919ad72542b9a7b9dd3b07751ac48e955d6c6a1b8d2792e2bd933a6f3/json"
Feb 27 04:06:42 MyPC dockerd[760]: time="2024-02-27T04:06:42.625870539-05:00" level=debug msg="Calling GET /v1.25/containers/1a70950919ad72542b9a7b9dd3b07751ac48e955d6c6a1b8d2792e2bd933a6f3/json"
Feb 27 04:06:43 MyPC dockerd[760]: time="2024-02-27T04:06:43.184146078-05:00" level=debug msg=event module=libcontainerd namespace=moby topic=/tasks/exit
Feb 27 04:06:43 MyPC dockerd[760]: time="2024-02-27T04:06:43.194168838-05:00" level=debug msg=event module=libcontainerd namespace=moby topic=/tasks/delete
Feb 27 04:06:43 MyPC dockerd[760]: time="2024-02-27T04:06:43.194195036-05:00" level=info msg="ignoring event" container=1a70950919ad72542b9a7b9dd3b07751ac48e955d6c6a1b8d2792e2bd933a6f3 module=libcontainerd namespace=moby topic=/tasks/delete type="*events.TaskDelete"
Feb 27 04:06:43 MyPC dockerd[760]: time="2024-02-27T04:06:43.203061945-05:00" level=warning msg="ShouldRestart failed, container will not be restarted" container=1a70950919ad72542b9a7b9dd3b07751ac48e955d6c6a1b8d2792e2bd933a6f3 daemonShuttingDown=false error="restart canceled" execDuration=14h14m44.876572573s exitStatus="{0 2024-02-27 09:06:43.183828832 +0000 UTC}" hasBeenManuallyStopped=true restartCount=0
Feb 27 04:06:43 MyPC dockerd[760]: time="2024-02-27T04:06:43.208809081-05:00" level=debug msg="Revoking external connectivity on endpoint MY_CONTAINER (a51065c3e9395a4581a68682c033642bb90d1c67c0de980ad4b4697c3c7eca70)"
Feb 27 04:06:43 MyPC dockerd[760]: time="2024-02-27T04:06:43.277225916-05:00" level=debug msg="a51065c3e9395a4581a68682c033642bb90d1c67c0de980ad4b4697c3c7eca70 (a36c593).deleteSvcRecords(MY_CONTAINER, 192.168.41.46, <nil>, true) updateSvcRecord sid:a51065c3e9395a4581a68682c033642bb90d1c67c0de980ad4b4697c3c7eca70 "
Feb 27 04:06:43 MyPC dockerd[760]: time="2024-02-27T04:06:43.277272126-05:00" level=debug msg="a51065c3e9395a4581a68682c033642bb90d1c67c0de980ad4b4697c3c7eca70 (a36c593).deleteSvcRecords(1a70950919ad, 192.168.41.46, <nil>, false) updateSvcRecord sid:a51065c3e9395a4581a68682c033642bb90d1c67c0de980ad4b4697c3c7eca70 "
Feb 27 04:06:43 MyPC dockerd[760]: time="2024-02-27T04:06:43.298743974-05:00" level=debug msg="Releasing addresses for endpoint MY_CONTAINER's interface on network macvlan-network"
Feb 27 04:06:43 MyPC dockerd[760]: time="2024-02-27T04:06:43.298779513-05:00" level=debug msg="ReleaseAddress(LocalDefault/192.168.40.0/22/192.168.42.252/32, 192.168.41.46)"
Feb 27 04:06:43 MyPC dockerd[760]: time="2024-02-27T04:06:43.298808714-05:00" level=debug msg="Released address Address:192.168.41.46 Sequence:Bits: 1024, Unselected: 1012, Sequence: (0x80000000, 1)->(0x0, 7)->(0x40000000, 1)->(0x17998000, 1)->(0x0, 21)->(0x1, 1)->end Curr:0"
Feb 27 04:06:43 MyPC dockerd[760]: time="2024-02-27T04:06:43.564381595-05:00" level=debug msg="Running health check for container fe936a9ad8737b296cce47e400d79ce8b9f402fcedb58513c83e47dccf709fae ..."
Feb 27 04:06:43 MyPC dockerd[760]: time="2024-02-27T04:06:43.564557843-05:00" level=debug msg="starting exec command 13dcabe497a550ffa56e3a7822ef04628b506baa0671d1361ad33f10186d59a4 in container fe936a9ad8737b296cce47e400d79ce8b9f402fcedb58513c83e47dccf709fae"
Feb 27 04:06:43 MyPC dockerd[760]: time="2024-02-27T04:06:43.565989290-05:00" level=debug msg="attach: stderr: begin"
Feb 27 04:06:43 MyPC dockerd[760]: time="2024-02-27T04:06:43.566088419-05:00" level=debug msg="attach: stdout: begin"
Feb 27 04:06:43 MyPC dockerd[760]: time="2024-02-27T04:06:43.567729312-05:00" level=debug msg=event module=libcontainerd namespace=moby topic=/tasks/exec-added
Feb 27 04:06:43 MyPC dockerd[760]: time="2024-02-27T04:06:43.629625936-05:00" level=debug msg="Calling GET /v1.25/containers/1a70950919ad72542b9a7b9dd3b07751ac48e955d6c6a1b8d2792e2bd933a6f3/json"
Feb 27 04:06:43 MyPC dockerd[760]: time="2024-02-27T04:06:43.630785516-05:00" level=debug msg="Calling DELETE /v1.25/containers/1a70950919ad72542b9a7b9dd3b07751ac48e955d6c6a1b8d2792e2bd933a6f3?force=1"
Feb 27 04:06:43 MyPC dockerd[760]: time="2024-02-27T04:06:43.659555257-05:00" level=debug msg=event module=libcontainerd namespace=moby topic=/tasks/exec-started
Feb 27 04:06:43 MyPC dockerd[760]: time="2024-02-27T04:06:43.663652487-05:00" level=debug msg=event module=libcontainerd namespace=moby topic=/tasks/exit
Feb 27 04:06:43 MyPC dockerd[760]: time="2024-02-27T04:06:43.663753370-05:00" level=debug msg="attach: stdout: end"
Feb 27 04:06:43 MyPC dockerd[760]: time="2024-02-27T04:06:43.663758760-05:00" level=debug msg="attach: stderr: end"
Feb 27 04:06:43 MyPC dockerd[760]: time="2024-02-27T04:06:43.663792344-05:00" level=debug msg="attach done"
Feb 27 04:06:43 MyPC dockerd[760]: time="2024-02-27T04:06:43.663826070-05:00" level=debug msg="Health check for container fe936a9ad8737b296cce47e400d79ce8b9f402fcedb58513c83e47dccf709fae done (exitCode=0)"
Feb 27 04:06:43 MyPC dockerd[760]: time="2024-02-27T04:06:43.664251725-05:00" level=debug msg="Calling GET /v1.25/containers/1a70950919ad72542b9a7b9dd3b07751ac48e955d6c6a1b8d2792e2bd933a6f3/json"
Feb 27 04:06:43 MyPC dockerd[760]: time="2024-02-27T04:06:43.664680431-05:00" level=debug msg="Calling POST /v1.25/containers/create?name=%2FMY_CONTAINER"
Feb 27 04:06:43 MyPC dockerd[760]: time="2024-02-27T04:06:43.665049659-05:00" level=debug msg="form data: {\"AttachStderr\":true,\"AttachStdin\":false,\"AttachStdout\":true,\"Cmd\":null,\"Domainname\":\"FQDN.com\",\"Entrypoint\":null,\"Env\":[\"TZ=MY/TIMEZONE\",\"PUID=1000\",\"PGID=1000\"],\"ExposedPorts\":{\"7878/tcp\":{}},\"HostConfig\":{\"AutoRemove\":false,\"Binds\":[\"/mnt/user/Programs/MY_CONTAINER/config:/config:rw\",\"/mnt/user/Programs/ANOTHER_CONTAINER_PATH/data/:/data:rw\",\"/mnt/user/Programs/ANOTHER_CONTAINER_2_PATH:/something:rw\",\"/mnt/user/Programs/MY_CONTAINER/staging:/data/staging:rw\",\"/mnt/path:/data/lib:rw\",\"/etc/localtime:/etc/localtime:ro\",\"/etc/timezone:/etc/timezone:ro\"],\"BlkioDeviceReadBps\":null,\"BlkioDeviceReadIOps\":null,\"BlkioDeviceWriteBps\":null,\"BlkioDeviceWriteIOps\":null,\"BlkioWeight\":0,\"BlkioWeightDevice\":null,\"CapAdd\":null,\"CapDrop\":null,\"Cgroup\":\"\",\"CgroupParent\":\"\",\"CgroupnsMode\":\"private\",\"ConsoleSize\":[0,0],\"ContainerIDFile\":\"\",\"CpuCount\":0,\"CpuPercent\":0,\"CpuPeriod\":0,\"CpuQuota\":0,\"CpuRealtimePeriod\":0,\"CpuRealtimeRuntime\":0,\"CpuShares\":0,\"CpusetCpus\":\"\",\"CpusetMems\":\"\",\"DeviceCgroupRules\":null,\"DeviceRequests\":null,\"Devices\":null,\"Dns\":[\"192.168.41.1\"],\"DnsOptions\":[],\"DnsSearch\":[],\"ExtraHosts\":[],\"GroupAdd\":null,\"IOMaximumBandwidth\":0,\"IOMaximumIOps\":0,\"IpcMode\":\"private\",\"Isolation\":\"\",\"Links\":null,\"LogConfig\":{\"Config\":{},\"Type\":\"json-file\"},\"MaskedPaths\":[\"/proc/asound\",\"/proc/acpi\",\"/proc/kcore\",\"/proc/keys\",\"/proc/latency_stats\",\"/proc/timer_list\",\"/proc/timer_stats\",\"/proc/sched_debug\",\"/proc/scsi\",\"/sys/firmware\",\"/sys/devices/virtual/powercap\"],\"Memory\":0,\"MemoryReservation\":0,\"MemorySwap\":0,\"MemorySwappiness\":null,\"NanoCpus\":0,\"NetworkMode\":\"a36c5938d7d8ca438bfd58adc987c31639a1687738c1e8014dc623f7603604f1\",\"OomKillDisable\":null,\"OomScoreAdj\":0,\"PidMode\":\"\",\"PidsLimit\":null,\"PortBindings\":{\"7878/tcp\":[{\"HostIp\":\"\",\"HostPort\":\"7878\"}]},\"Privileged\":false,\"PublishAllPorts\":false,\"ReadonlyPaths\":[\"/proc/bus\",\"/proc/fs\",\"/proc/irq\",\"/proc/sys\",\"/proc/sysrq-trigger\"],\"ReadonlyRootfs\":false,\"RestartPolicy\":{\"MaximumRetryCount\":0,\"Name\":\"unless-stopped\"},\"Runtime\":\"runc\",\"SecurityOpt\":null,\"ShmSize\":67108864,\"UTSMode\":\"\",\"Ulimits\":null,\"UsernsMode\":\"\",\"VolumeDriver\":\"\",\"VolumesFrom\":null},\"Hostname\":\"MY_CONTAINER\",\"Image\":\"lscr.io/linuxserver/MY_CONTAINER:develop\",\"Labels\":{\"com.docker.compose.config-hash\":\"52c711ccfaa53863d8dc674b16c213f33e715e41e6a28938535daf111ddc7c27\",\"com.docker.compose.container-number\":\"1\",\"com.docker.compose.depends_on\":\"\",\"com.docker.compose.image\":\"sha256:996494a23282a339eba842da48a65ffe6b85e71d395a01692a1df5aaf337f0b6\",\"com.docker.compose.oneoff\":\"False\",\"com.docker.compose.project\":\"MY_CONTAINER\",\"com.docker.compose.project.config_files\":\"/data/compose/44/docker-compose.yml\",\"com.docker.compose.project.working_dir\":\"/data/compose/44\",\"com.docker.compose.service\":\"MY_CONTAINER\",\"com.docker.compose.version\":\"2.20.2\"},\"MacAddress\":\"02:42:c0:a8:29:28\",\"NetworkingConfig\":{\"EndpointsConfig\":{\"macvlan-network\":{\"Aliases\":[\"MY_CONTAINER\"],\"DriverOpts\":null,\"EndpointID\":\"a51065c3e9395a4581a68682c033642bb90d1c67c0de980ad4b4697c3c7eca70\",\"Gateway\":\"192.168.41.1\",\"GlobalIPv6Address\":\"\",\"GlobalIPv6PrefixLen\":0,\"IPAMConfig\":{\"IPv4Address\":\"192.168.41.46\"},\"IPAddress\":\"192.168.41.46\",\"IPPrefixLen\":22,\"IPv6Gateway\":\"\",\"Links\":null,\"MacAddress\":\"02:42:c0:a8:29:28\",\"NetworkID\":\"a36c5938d7d8ca438bfd58adc987c31639a1687738c1e8014dc623f7603604f1\"}}},\"OnBuild\":null,\"OpenStdin\":false,\"StdinOnce\":false,\"Tty\":false,\"User\":\"\",\"Volumes\":{},\"WorkingDir\":\"\"}"
Feb 27 04:06:43 MyPC dockerd[760]: time="2024-02-27T04:06:43.749697392-05:00" level=debug msg="container mounted via layerStore: /var/lib/docker/overlay2/0f8f205a589c937ab14310db214cb1985bb39050ed47730f176c09c807ba013a/merged" container=a0b3d9705cabd6b9e966652eec89e04d205eec51ea52bbc92ef963094da5bffc
Feb 27 04:06:43 MyPC dockerd[760]: time="2024-02-27T04:06:43.749791441-05:00" level=debug msg="mountpoint already exists, skipping anonymous volume" container=a0b3d9705cabd6b9e966652eec89e04d205eec51ea52bbc92ef963094da5bffc destination=/config
Feb 27 04:06:43 MyPC dockerd[760]: time="2024-02-27T04:06:43.787698789-05:00" level=debug msg="Calling POST /v1.25/networks/macvlan-network/disconnect"
Feb 27 04:06:43 MyPC dockerd[760]: time="2024-02-27T04:06:43.787863028-05:00" level=debug msg="form data: {\"Container\":\"a0b3d9705cabd6b9e966652eec89e04d205eec51ea52bbc92ef963094da5bffc\",\"Force\":true}"
Feb 27 04:06:43 MyPC dockerd[760]: time="2024-02-27T04:06:43.800538381-05:00" level=debug msg="Calling POST /v1.25/networks/macvlan-network/connect"
Feb 27 04:06:43 MyPC dockerd[760]: time="2024-02-27T04:06:43.800767365-05:00" level=debug msg="form data: {\"Container\":\"a0b3d9705cabd6b9e966652eec89e04d205eec51ea52bbc92ef963094da5bffc\",\"EndpointConfig\":{\"Aliases\":[\"MY_CONTAINER\"],\"DriverOpts\":null,\"EndpointID\":\"a51065c3e9395a4581a68682c033642bb90d1c67c0de980ad4b4697c3c7eca70\",\"Gateway\":\"192.168.41.1\",\"GlobalIPv6Address\":\"\",\"GlobalIPv6PrefixLen\":0,\"IPAMConfig\":{\"IPv4Address\":\"192.168.41.46\"},\"IPAddress\":\"192.168.41.46\",\"IPPrefixLen\":22,\"IPv6Gateway\":\"\",\"Links\":null,\"MacAddress\":\"02:42:c0:a8:29:28\",\"NetworkID\":\"a36c5938d7d8ca438bfd58adc987c31639a1687738c1e8014dc623f7603604f1\"}}"
Feb 27 04:06:43 MyPC dockerd[760]: time="2024-02-27T04:06:43.812624850-05:00" level=debug msg="Calling POST /v1.25/containers/a0b3d9705cabd6b9e966652eec89e04d205eec51ea52bbc92ef963094da5bffc/start"
Feb 27 04:06:43 MyPC dockerd[760]: time="2024-02-27T04:06:43.813809096-05:00" level=debug msg="container mounted via layerStore: /var/lib/docker/overlay2/0f8f205a589c937ab14310db214cb1985bb39050ed47730f176c09c807ba013a/merged" container=a0b3d9705cabd6b9e966652eec89e04d205eec51ea52bbc92ef963094da5bffc
Feb 27 04:06:43 MyPC dockerd[760]: time="2024-02-27T04:06:43.814892178-05:00" level=debug msg="Assigning addresses for endpoint MY_CONTAINER's interface on network macvlan-network"
Feb 27 04:06:43 MyPC dockerd[760]: time="2024-02-27T04:06:43.814974515-05:00" level=debug msg="RequestAddress(LocalDefault/192.168.40.0/22/192.168.42.252/32, <nil>, map[])"
Feb 27 04:06:43 MyPC dockerd[760]: time="2024-02-27T04:06:43.817981945-05:00" level=debug msg="Request address PoolID:192.168.40.0/22 Bits: 1024, Unselected: 1012, Sequence: (0x80000000, 1)->(0x0, 7)->(0x40000000, 1)->(0x17998000, 1)->(0x0, 21)->(0x1, 1)->end Curr:0 Serial:false PrefAddress:invalid IP "
Feb 27 04:06:43 MyPC dockerd[760]: time="2024-02-27T04:06:43.818358645-05:00" level=warning msg="macvlan driver does not support port mappings"
Feb 27 04:06:43 MyPC dockerd[760]: time="2024-02-27T04:06:43.818680721-05:00" level=warning msg="macvlan driver does not support port exposures"
Feb 27 04:06:43 MyPC dockerd[760]: time="2024-02-27T04:06:43.826864871-05:00" level=debug msg="Assigning addresses for endpoint MY_CONTAINER's interface on network macvlan-network"
Feb 27 04:06:43 MyPC dockerd[760]: time="2024-02-27T04:06:43.826929766-05:00" level=debug msg="b939bfcea498261a12e3b31b1c2014e79abd9bf5d312d2c2c797d704e032d41f (a36c593).addSvcRecords(MY_CONTAINER, 192.168.42.252, <nil>, true) updateSvcRecord sid:b939bfcea498261a12e3b31b1c2014e79abd9bf5d312d2c2c797d704e032d41f"
Feb 27 04:06:43 MyPC dockerd[760]: time="2024-02-27T04:06:43.827016946-05:00" level=debug msg="b939bfcea498261a12e3b31b1c2014e79abd9bf5d312d2c2c797d704e032d41f (a36c593).addSvcRecords(a0b3d9705cab, 192.168.42.252, <nil>, false) updateSvcRecord sid:b939bfcea498261a12e3b31b1c2014e79abd9bf5d312d2c2c797d704e032d41f"
Feb 27 04:06:43 MyPC dockerd[760]: time="2024-02-27T04:06:43.838122932-05:00" level=debug msg="Macvlan Endpoint Joined with IPv4_Addr: 192.168.42.252, Gateway: 192.168.41.1, MacVlan_Mode: bridge, Parent: enp0s31f6"
Feb 27 04:06:43 MyPC dockerd[760]: time="2024-02-27T04:06:43.846146997-05:00" level=debug msg="b939bfcea498261a12e3b31b1c2014e79abd9bf5d312d2c2c797d704e032d41f (a36c593).addSvcRecords(MY_CONTAINER, 192.168.42.252, <nil>, true) updateSvcRecord sid:b939bfcea498261a12e3b31b1c2014e79abd9bf5d312d2c2c797d704e032d41f"
Feb 27 04:06:43 MyPC dockerd[760]: time="2024-02-27T04:06:43.846249430-05:00" level=debug msg="b939bfcea498261a12e3b31b1c2014e79abd9bf5d312d2c2c797d704e032d41f (a36c593).addSvcRecords(a0b3d9705cab, 192.168.42.252, <nil>, false) updateSvcRecord sid:b939bfcea498261a12e3b31b1c2014e79abd9bf5d312d2c2c797d704e032d41f"
Feb 27 04:06:43 MyPC dockerd[760]: time="2024-02-27T04:06:43.870643941-05:00" level=debug msg="Programming external connectivity on endpoint MY_CONTAINER (b939bfcea498261a12e3b31b1c2014e79abd9bf5d312d2c2c797d704e032d41f)"
Feb 27 04:06:43 MyPC dockerd[760]: time="2024-02-27T04:06:43.871184161-05:00" level=debug msg="EnableService a0b3d9705cabd6b9e966652eec89e04d205eec51ea52bbc92ef963094da5bffc START"
Feb 27 04:06:43 MyPC dockerd[760]: time="2024-02-27T04:06:43.871535354-05:00" level=debug msg="EnableService a0b3d9705cabd6b9e966652eec89e04d205eec51ea52bbc92ef963094da5bffc DONE"
Feb 27 04:06:43 MyPC dockerd[760]: time="2024-02-27T04:06:43.882243812-05:00" level=debug msg="createSpec: cgroupsPath: system.slice:docker:a0b3d9705cabd6b9e966652eec89e04d205eec51ea52bbc92ef963094da5bffc"
Feb 27 04:06:43 MyPC dockerd[760]: time="2024-02-27T04:06:43.890869586-05:00" level=debug msg="bundle dir created" bundle=/var/run/docker/containerd/a0b3d9705cabd6b9e966652eec89e04d205eec51ea52bbc92ef963094da5bffc module=libcontainerd namespace=moby root=/var/lib/docker/overlay2/0f8f205a589c937ab14310db214cb1985bb39050ed47730f176c09c807ba013a/merged

The updates that followed (and failed) show:

Feb 27 04:06:45 MyPC dockerd[760]: time="2024-02-27T04:06:44.991659783-05:00" level=debug msg="Assigning addresses for endpoint pihole's interface on network macvlan-network"
Feb 27 04:06:45 MyPC dockerd[760]: time="2024-02-27T04:06:44.991707973-05:00" level=debug msg="RequestAddress(LocalDefault/192.168.40.0/22/192.168.42.252/32, <nil>, map[])"
Feb 27 04:06:45 MyPC dockerd[760]: time="2024-02-27T04:06:44.991766055-05:00" level=debug msg="Request address PoolID:192.168.40.0/22 Bits: 1024, Unselected: 1011, Sequence: (0x80000000, 1)->(0x0, 7)->(0x40000000, 1)->(0x17998000, 1)->(0x0, 13)->(0x8, 1)->(0x0, 7)->(0x1, 1)->end Curr:765 Serial:false PrefAddress:invalid IP "
Feb 27 04:06:45 MyPC dockerd[760]: time="2024-02-27T04:06:45.023475668-05:00" level=debug msg="FIXME: Got an API for which error does not match any expected type!!!" error="no available IPv4 addresses on this network's address pools: macvlan-network (a36c5938d7d8ca438bfd58adc987c31639a1687738c1e8014dc623f7603604f1)" error_type="*errors.errorString" module=api
Feb 27 04:06:45 MyPC dockerd[760]: time="2024-02-27T04:06:45.023519959-05:00" level=error msg="Handler for POST /v1.25/containers/237096510be09867e539776e29baf203dcfcf52dbe18b073f9d1bcbe55318b20/start returned error: no available IPv4 addresses on this network's address pools: macvlan-network (a36c5938d7d8ca438bfd58adc987c31639a1687738c1e8014dc623f7603604f1)"
Feb 27 04:06:45 MyPC dockerd[760]: time="2024-02-27T04:06:45.023556577-05:00" level=debug msg="FIXME: Got an API for which error does not match any expected type!!!" error="no available IPv4 addresses on this network's address pools: macvlan-network (a36c5938d7d8ca438bfd58adc987c31639a1687738c1e8014dc623f7603604f1)" error_type="*errors.errorString" module=api
Feb 27 04:06:45 MyPC dockerd[760]: time="2024-02-27T04:06:45.024206421-05:00" level=debug msg="Calling DELETE /v1.25/images/sha256:996494a23282a339eba842da48a65ffe6b85e71d395a01692a1df5aaf337f0b6?force=1&noprune=1"

@thaJeztah
Copy link
Member

The Serial:false PrefAddress:invalid IP part looks to be a log produced here;

log.G(context.TODO()).Debugf("Request address PoolID:%v %s Serial:%v PrefAddress:%v ", base, bitmask, serial, prefAddress)

Looking from that code, the Invalid IP is produced if the netip.Addr has a zero-length IP-address? https://cs.opensource.google/go/go/+/refs/tags/go1.22.0:src/net/netip/netip.go;l=751-767

@thaJeztah
Copy link
Member

Perhaps these check should check for prefAddress.IsValid() instead of empty / default / nil value for the type (not sure if that would catch more than the current check though);

if ipr == (netip.Prefix{}) && prefAddress == (netip.Addr{}) {
ordinal, err = bitmask.SetAny(serial)
} else if prefAddress != (netip.Addr{}) {
ordinal = netiputil.HostID(prefAddress, uint(base.Bits()))
err = bitmask.Set(ordinal)

@edrikk
Copy link
Author

edrikk commented Feb 27, 2024

Makes sense. I will note that given that the container should have a static IP (which per the log docker "released" successfully at start of update) even that it's going through the dynamic IP path is odd (to me).

Not knowing the code, I would think that either it shouldn't be even calling for an IP assignment, or upon seeing it has an invalid IP it should assign the static IP, or the empty/null IP should be replaced with the static IP before it even makes it to this check.

But (stating the obvious here 😃 ), assigning 192.168.42.252 is not the correct end result. 😃

@robmry
Copy link
Contributor

robmry commented Feb 27, 2024

Yes, indeed - it shouldn't have got as far as the allocator, because an address was supplied, the one Watchtower found in the old container is what's needed. Once the allocator's involved, it's already doomed.

(Endpoint.assignAddressVersion() should have found that address and skipped ipam.RequestAddress() completely. Edit: oops, misread that, but the 'nil' in RequestAddress(LocalDefault/192.168.40.0/22/192.168.42.252/32, <nil>, map[]) should be the address it picked up above.)

I'm not sure why that's happened, but will take a look... - thank you for the logs!

@robmry
Copy link
Contributor

robmry commented Feb 28, 2024

Just to update on this ...

In the create API request, Watchtower sets HostConfig.NetworkMode to the id of the network, but uses the network's name in the Endpoint config where it supplies the preferred IP address.

In docker 25.x, we deprecated a container-wide setting for the container's MAC address in the latest version of the API. (Watchtower is using an old version of the API.)

For compatibility with old versions of the API, we migrate the container-wide MAC address to endpoint settings - where the updated code expects to find it.

In doing that, when the NetworkMode does not match the name used in EndpointsConfig, we inadvertently create a second version of the endpoint config - only containing that MAC address, stored under the supplied NetworkMode (id in this case).

So, we end up two sets of endpoint config for the same network and later lose the config supplied under the network's name, including the preferred IP address lives.

The backward-compatibility config migration happens early in the request processing, before it's possible to normalise the network name/id/short-id. So, a fix looks a little tricky, I'm still looking in to it.

But - this issue will affect Watchtower updates, when the container has both a configured IP address and a configured MAC address. At the moment, I don't think there's a workaround for that case - it'll need a change in either Watchtower or Docker/moby.

@edrikk
Copy link
Author

edrikk commented Feb 28, 2024

Thank you. Really appreciate the loop back update, and especially one so well explained.
Cheers!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
area/networking kind/bug Bugs are bugs. The cause may or may not be known at triage time so debugging may be needed. version/25.0
Projects
None yet
Development

Successfully merging a pull request may close this issue.

3 participants