TechQA.

Why Docker container is silently removed on start

652 views Asked by At

I am trying to run Integration test written in Java using testcontainers library.

  • OS: macOS Catalina 10.15.6
  • Docker Engine: 19.03.13
  • Docker Desktop: 2.4.0.0
  • Testcontainers version: 1.14.3
  • Java: 8

This library runs Ryuk Docker container responsible for Docker resources cleanup after test execution. Basically, library creates Ryuk container and then starts it. However, when the library tries to start Ryuk, it is silently removed. This issue appeared after last Docker Desktop upgrade. Seems like Docker itself rejects this container for some reason, because there was no API call to kill it according to the logs. Could you please help me with this problem?

Docker container inspect output:

[
    {
        "Id": "81ff589cf8993fa7d20bbab0f3817d2ef9eeeb81994ee1c9bddcb0d947605084",
        "Created": "2020-10-08T13:57:32.805356662Z",
        "Path": "/app",
        "Args": [],
        "State": {
            "Status": "created",
            "Running": false,
            "Paused": false,
            "Restarting": false,
            "OOMKilled": false,
            "Dead": false,
            "Pid": 0,
            "ExitCode": 0,
            "Error": "",
            "StartedAt": "0001-01-01T00:00:00Z",
            "FinishedAt": "0001-01-01T00:00:00Z"
        },
        "Image": "sha256:344c0229fe447209d01c388035dfe01ca38f5289d99c7e14febbcb9a0b128775",
        "ResolvConfPath": "",
        "HostnamePath": "",
        "HostsPath": "",
        "LogPath": "",
        "Name": "/testcontainers-ryuk-4b282143-1305-44c2-9fc2-2bd323a2bd67",
        "RestartCount": 0,
        "Driver": "overlay2",
        "Platform": "linux",
        "MountLabel": "",
        "ProcessLabel": "",
        "AppArmorProfile": "",
        "HostConfig": {
            "Binds": [
                "/host_mnt/Users/rastiehaiev/Library/Containers/com.docker.docker/Data/docker.sock:/var/run/docker.sock:rw"
            ],
            "ContainerIDFile": "",
            "LogConfig": {
                "Type": "json-file",
                "Config": {}
            },
            "NetworkMode": "default",
            "PortBindings": null,
            "RestartPolicy": {
                "Name": "",
                "MaximumRetryCount": 0
            },
            "AutoRemove": true,
            "VolumeDriver": "",
            "IpcMode": "private",
            "Cgroup": "",
            "OomScoreAdj": 0,
            "PidMode": "",
            "Privileged": false,
            "PublishAllPorts": true,
            "ReadonlyRootfs": false,
            "UTSMode": "",
            "UsernsMode": "",
            "ShmSize": 67108864,
            "Runtime": "runc",
            "ConsoleSize": [
                0,
                0
            ],
            "Isolation": "",
            "CpuShares": 0,
            "Memory": 0,
            "NanoCpus": 0,
            "CgroupParent": "",
            "BlkioWeight": 0,
            "CpuPeriod": 0,
            "CpuQuota": 0,
            "CpuRealtimePeriod": 0,
            "CpuRealtimeRuntime": 0,
            "CpusetCpus": "",
            "CpusetMems": "",
            "Devices": null,
            "KernelMemory": 0,
            "KernelMemoryTCP": 0,
            "MemoryReservation": 0,
            "MemorySwap": 0,
            "OomKillDisable": false,
            "PidsLimit": null,
            "Ulimits": null,
            "CpuCount": 0,
            "CpuPercent": 0,
            "IOMaximumIOps": 0,
            "IOMaximumBandwidth": 0,
            "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"
            ],
            "ReadonlyPaths": [
                "/proc/bus",
                "/proc/fs",
                "/proc/irq",
                "/proc/sys",
                "/proc/sysrq-trigger"
            ]
        },
        "GraphDriver": {
            "Data": {
                "LowerDir": "/var/lib/docker/overlay2/2e9bdf84768ed5272c48f93a70c09341f789631edaf7b94f19a2117d767b2399-init/diff:/var/lib/docker/overlay2/3b560fdd2209c4a289be85aedb65399b08da026f21672efeb0951196d3748c77/diff:/var/lib/docker/overlay2/ac331eaaf59d9d135c1442f285cc4553658851fec751c492890efb693885375f/diff:/var/lib/docker/overlay2/9170a14e2be39e10fe11b9411e37a4672bed6b14c295a8ad4b8fbb7c9705935b/diff",
                "MergedDir": "/var/lib/docker/overlay2/2e9bdf84768ed5272c48f93a70c09341f789631edaf7b94f19a2117d767b2399/merged",
                "UpperDir": "/var/lib/docker/overlay2/2e9bdf84768ed5272c48f93a70c09341f789631edaf7b94f19a2117d767b2399/diff",
                "WorkDir": "/var/lib/docker/overlay2/2e9bdf84768ed5272c48f93a70c09341f789631edaf7b94f19a2117d767b2399/work"
            },
            "Name": "overlay2"
        },
        "Mounts": [
            {
                "Type": "bind",
                "Source": "/host_mnt/Users/rastiehaiev/Library/Containers/com.docker.docker/Data/docker.sock",
                "Destination": "/var/run/docker.sock",
                "Mode": "rw",
                "RW": true,
                "Propagation": "rprivate"
            }
        ],
        "Config": {
            "Hostname": "81ff589cf899",
            "Domainname": "",
            "User": "",
            "AttachStdin": false,
            "AttachStdout": false,
            "AttachStderr": false,
            "ExposedPorts": {
                "8080/tcp": {}
            },
            "Tty": false,
            "OpenStdin": false,
            "StdinOnce": false,
            "Env": [
                "PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin"
            ],
            "Cmd": [
                "/app"
            ],
            "Image": "testcontainersofficial/ryuk:0.3.0",
            "Volumes": null,
            "WorkingDir": "",
            "Entrypoint": null,
            "OnBuild": null,
            "Labels": {
                "desktop.docker.io/binds/0/Source": "//var/run/docker.sock",
                "desktop.docker.io/binds/0/SourceKind": "hostFile",
                "desktop.docker.io/binds/0/Target": "/var/run/docker.sock",
                "org.testcontainers": "true"
            }
        },
        "NetworkSettings": {
            "Bridge": "",
            "SandboxID": "",
            "HairpinMode": false,
            "LinkLocalIPv6Address": "",
            "LinkLocalIPv6PrefixLen": 0,
            "Ports": {},
            "SandboxKey": "",
            "SecondaryIPAddresses": null,
            "SecondaryIPv6Addresses": null,
            "EndpointID": "",
            "Gateway": "",
            "GlobalIPv6Address": "",
            "GlobalIPv6PrefixLen": 0,
            "IPAddress": "",
            "IPPrefixLen": 0,
            "IPv6Gateway": "",
            "MacAddress": "",
            "Networks": {
                "bridge": {
                    "IPAMConfig": null,
                    "Links": null,
                    "Aliases": null,
                    "NetworkID": "",
                    "EndpointID": "",
                    "Gateway": "",
                    "IPAddress": "",
                    "IPPrefixLen": 0,
                    "IPv6Gateway": "",
                    "GlobalIPv6Address": "",
                    "GlobalIPv6PrefixLen": 0,
                    "MacAddress": "",
                    "DriverOpts": null
                }
            }
        }
    }
]

Docker system logs:

2020-10-08T14:16:40Z dockerd time="2020-10-08T14:16:40.806579359Z" level=debug msg="Calling GET /images/json?filter=testcontainersofficial%2Fryuk%3A0.3.0"
2020-10-08T14:16:41Z dockerd time="2020-10-08T14:16:41.184803499Z" level=debug msg="Calling POST /containers/create?name=testcontainers-ryuk-c2b76bfe-5e08-42df-836b-291c0aa4e898"
2020-10-08T14:16:41Z dockerd time="2020-10-08T14:16:41.185381040Z" level=debug msg="form data: {\"AttachStderr\":false,\"AttachStdin\":false,\"AttachStdout\":false,\"Cmd\":null,\"Domainname\":\"\",\"Entrypoint\":null,\"En
v\":null,\"ExposedPorts\":{\"8080/tcp\":{}},\"HostConfig\":{\"AutoRemove\":true,\"Binds\":[\"/host_mnt/Users/rastiehaiev/Library/Containers/com.docker.docker/Data/docker.sock:/var/run/docker.sock:rw\"],\"BlkioDeviceReadBp
s\":null,\"BlkioDeviceReadIOps\":null,\"BlkioDeviceWriteBps\":null,\"BlkioDeviceWriteIOps\":null,\"BlkioWeight\":0,\"BlkioWeightDevice\":null,\"CapAdd\":null,\"CapDrop\":null,\"Capabilities\":null,\"Cgroup\":\"\",\"Cgroup
Parent\":\"\",\"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\":null,\"DnsOptions\":null,\"DnsSearch\":null,\"ExtraHosts\":null,\"GroupAdd\":null,\"I
2020-10-08T14:16:41Z dockerd time="2020-10-08T14:16:41.203874397Z" level=debug msg="container mounted via layerStore: &{/var/lib/docker/overlay2/29307b0b1c8ab639ae287dd9c0bff4b550acab017dcac6bc1032f18783df72b7/merged 0x3d
7bfa0 0x3d7bfa0}"
2020-10-08T14:16:42Z dockerd time="2020-10-08T14:16:42.561989090Z" level=debug msg="Calling GET /system/df"
2020-10-08T14:16:42Z dockerd time="2020-10-08T14:16:42.563161207Z" level=debug msg="Calling GET /system/df"
2020-10-08T14:16:42Z dockerd time="2020-10-08T14:16:42.563279476Z" level=debug msg="FIXME: Got an API for which error does not match any expected type!!!: a disk usage operation is already running" error_type="*errors.err
orString" module=api
2020-10-08T14:16:42Z dockerd time="2020-10-08T14:16:42.563297884Z" level=error msg="Handler for GET /system/df returned error: a disk usage operation is already running"
2020-10-08T14:16:42Z dockerd time="2020-10-08T14:16:42.563313704Z" level=debug msg="FIXME: Got an API for which error does not match any expected type!!!: a disk usage operation is already running" error_type="*errors.err
orString" module=api
2020-10-08T14:16:42Z dockerd time="2020-10-08T14:16:42.577472479Z" level=debug msg=VolumeStore.Find ByType=service.andCombinator ByValue="[[local] 0x1645e10]"
2020-10-08T14:17:39Z dockerd time="2020-10-08T14:17:39.671947023Z" level=debug msg="Calling GET /v1.40/containers/json?all=1"
2020-10-08T14:17:48Z dockerd time="2020-10-08T14:17:48.043005587Z" level=debug msg="Calling GET /v1.40/containers/148a8fa42878/json"
2020-10-08T14:17:48Z dockerd time="2020-10-08T14:17:48.047243534Z" level=debug msg="begin logs" container=148a8fa428782b45e7b36517c80754571e2c3be8ca70e2fce82da4aa1a94a7bd method="(*Daemon).ContainerLogs" module=daemon
2020-10-08T14:17:48Z dockerd time="2020-10-08T14:17:48.047349685Z" level=debug msg="end logs (<nil>)" container=148a8fa428782b45e7b36517c80754571e2c3be8ca70e2fce82da4aa1a94a7bd method="(*Daemon).ContainerLogs" module=daem
on
2020-10-08T14:17:51Z dockerd time="2020-10-08T14:17:51.311935105Z" level=debug msg="Calling GET /v1.40/containers/148a8fa42878/json"
2020-10-08T14:18:26Z dockerd time="2020-10-08T14:18:26.969481521Z" level=debug msg="Calling POST /containers/148a8fa428782b45e7b36517c80754571e2c3be8ca70e2fce82da4aa1a94a7bd/start"
2020-10-08T14:18:26Z dockerd time="2020-10-08T14:18:26.969628004Z" level=debug msg="form data: null"
2020-10-08T14:18:26Z dockerd time="2020-10-08T14:18:26.971413387Z" level=debug msg="container mounted via layerStore: &{/var/lib/docker/overlay2/29307b0b1c8ab639ae287dd9c0bff4b550acab017dcac6bc1032f18783df72b7/merged 0x3d7bfa0 0x3d7bfa0}"
2020-10-08T14:18:26Z dockerd time="2020-10-08T14:18:26.972286209Z" level=debug msg="Assigning addresses for endpoint testcontainers-ryuk-c2b76bfe-5e08-42df-836b-291c0aa4e898's interface on network bridge"
2020-10-08T14:18:26Z dockerd time="2020-10-08T14:18:26.972347128Z" level=debug msg="RequestAddress(LocalDefault/172.17.0.0/16, <nil>, map[])"
2020-10-08T14:18:26Z dockerd time="2020-10-08T14:18:26.972393433Z" level=debug msg="Request address PoolID:172.17.0.0/16 App: ipam/default/data, ID: LocalDefault/172.17.0.0/16, DBIndex: 0x0, Bits: 65536, Unselected: 65533, Sequence: (0xc0000000, 1)->(0x0, 2046)->(0x1, 1)->end Curr:3 Serial:false PrefAddress:<nil> "
2020-10-08T14:18:26Z dockerd time="2020-10-08T14:18:26.985619161Z" level=debug msg="Assigning addresses for endpoint testcontainers-ryuk-c2b76bfe-5e08-42df-836b-291c0aa4e898's interface on network bridge"
2020-10-08T14:18:26Z dockerd time="2020-10-08T14:18:26.992776451Z" level=debug msg="Programming external connectivity on endpoint testcontainers-ryuk-c2b76bfe-5e08-42df-836b-291c0aa4e898 (744cfc348c7ebb7f4f37ff1d15a810cf925118eb18b813e4b079a8628b52e2ac)"
2020-10-08T14:18:26Z dockerd time="2020-10-08T14:18:26.993013144Z" level=debug msg="/sbin/iptables, [--wait -t nat -C DOCKER -p tcp -d 0/0 --dport 32772 -j DNAT --to-destination 172.17.0.2:8080 ! -i docker0]"
2020-10-08T14:18:26Z dockerd time="2020-10-08T14:18:26.997955746Z" level=debug msg="/sbin/iptables, [--wait -t nat -A DOCKER -p tcp -d 0/0 --dport 32772 -j DNAT --to-destination 172.17.0.2:8080 ! -i docker0]"
2020-10-08T14:18:27Z dockerd time="2020-10-08T14:18:27.003525652Z" level=debug msg="/sbin/iptables, [--wait -t filter -C DOCKER ! -i docker0 -o docker0 -p tcp -d 172.17.0.2 --dport 8080 -j ACCEPT]"
2020-10-08T14:18:27Z dockerd time="2020-10-08T14:18:27.008125887Z" level=debug msg="/sbin/iptables, [--wait -t filter -A DOCKER ! -i docker0 -o docker0 -p tcp -d 172.17.0.2 --dport 8080 -j ACCEPT]"
2020-10-08T14:18:27Z dockerd time="2020-10-08T14:18:27.011248735Z" level=debug msg="/sbin/iptables, [--wait -t nat -C POSTROUTING -p tcp -s 172.17.0.2 -d 172.17.0.2 --dport 8080 -j MASQUERADE]"
2020-10-08T14:18:27Z dockerd time="2020-10-08T14:18:27.014453984Z" level=debug msg="/sbin/iptables, [--wait -t nat -A POSTROUTING -p tcp -s 172.17.0.2 -d 172.17.0.2 --dport 8080 -j MASQUERADE]"
2020-10-08T14:18:27Z dockerd time="2020-10-08T14:18:27.026974404Z" level=debug msg="EnableService 148a8fa428782b45e7b36517c80754571e2c3be8ca70e2fce82da4aa1a94a7bd START"
2020-10-08T14:18:27Z dockerd time="2020-10-08T14:18:27.027030926Z" level=debug msg="EnableService 148a8fa428782b45e7b36517c80754571e2c3be8ca70e2fce82da4aa1a94a7bd DONE"
2020-10-08T14:18:27Z dockerd time="2020-10-08T14:18:27.035386163Z" level=debug msg="bundle dir created" bundle=/var/run/docker/containerd/148a8fa428782b45e7b36517c80754571e2c3be8ca70e2fce82da4aa1a94a7bd module=libcontainerd namespace=moby root=/var/lib/docker/overlay2/29307b0b1c8ab639ae287dd9c0bff4b550acab017dcac6bc1032f18783df72b7/merged
2020-10-08T14:18:27Z dockerd time="2020-10-08T14:18:27.280445659Z" level=debug msg="sandbox set key processing took 100.216398ms for container 148a8fa428782b45e7b36517c80754571e2c3be8ca70e2fce82da4aa1a94a7bd"
2020-10-08T14:18:27Z dockerd time="2020-10-08T14:18:27.328718866Z" level=debug msg=event module=libcontainerd namespace=moby topic=/tasks/create
2020-10-08T14:18:27Z dockerd time="2020-10-08T14:18:27.346374052Z" level=debug msg=event module=libcontainerd namespace=moby topic=/tasks/start
2020-10-08T14:18:27Z dockerd time="2020-10-08T14:18:27.361502145Z" level=debug msg="Calling GET /containers/148a8fa428782b45e7b36517c80754571e2c3be8ca70e2fce82da4aa1a94a7bd/json"
2020-10-08T14:18:27Z dockerd time="2020-10-08T14:18:27.382404528Z" level=debug msg="Calling GET /containers/148a8fa428782b45e7b36517c80754571e2c3be8ca70e2fce82da4aa1a94a7bd/logs?stdout=true&stderr=true&follow=true&since=0"
2020-10-08T14:18:27Z dockerd time="2020-10-08T14:18:27.382552355Z" level=debug msg="begin logs" container=148a8fa428782b45e7b36517c80754571e2c3be8ca70e2fce82da4aa1a94a7bd method="(*Daemon).ContainerLogs" module=daemon
2020-10-08T14:18:27Z dockerd time="2020-10-08T14:18:27.479073054Z" level=debug msg=event module=libcontainerd namespace=moby topic=/tasks/exit
2020-10-08T14:18:27Z dockerd time="2020-10-08T14:18:27.546231426Z" level=debug msg=event module=libcontainerd namespace=moby topic=/tasks/delete
2020-10-08T14:18:27Z dockerd time="2020-10-08T14:18:27.546316079Z" level=info msg="ignoring event" module=libcontainerd namespace=moby topic=/tasks/delete type="*events.TaskDelete"
2020-10-08T14:18:27Z dockerd time="2020-10-08T14:18:27.548362903Z" level=debug msg="Revoking external connectivity on endpoint testcontainers-ryuk-c2b76bfe-5e08-42df-836b-291c0aa4e898 (744cfc348c7ebb7f4f37ff1d15a810cf925118eb18b813e4b079a8628b52e2ac)"
2020-10-08T14:18:27Z dockerd time="2020-10-08T14:18:27.553270608Z" level=debug msg="end logs (<nil>)" container=148a8fa428782b45e7b36517c80754571e2c3be8ca70e2fce82da4aa1a94a7bd method="(*Daemon).ContainerLogs" module=daemon
2020-10-08T14:18:27Z dockerd time="2020-10-08T14:18:27.561062325Z" level=debug msg="/sbin/iptables, [--wait -t nat -C DOCKER -p tcp -d 0/0 --dport 32772 -j DNAT --to-destination 172.17.0.2:8080 ! -i docker0]"
2020-10-08T14:18:27Z dockerd time="2020-10-08T14:18:27.565495319Z" level=debug msg="/sbin/iptables, [--wait -t nat -D DOCKER -p tcp -d 0/0 --dport 32772 -j DNAT --to-destination 172.17.0.2:8080 ! -i docker0]"
2020-10-08T14:18:27Z dockerd time="2020-10-08T14:18:27.569612079Z" level=debug msg="/sbin/iptables, [--wait -t filter -C DOCKER ! -i docker0 -o docker0 -p tcp -d 172.17.0.2 --dport 8080 -j ACCEPT]"
2020-10-08T14:18:27Z dockerd time="2020-10-08T14:18:27.571538278Z" level=debug msg="/sbin/iptables, [--wait -t filter -D DOCKER ! -i docker0 -o docker0 -p tcp -d 172.17.0.2 --dport 8080 -j ACCEPT]"
2020-10-08T14:18:27Z dockerd time="2020-10-08T14:18:27.573748296Z" level=debug msg="/sbin/iptables, [--wait -t nat -C POSTROUTING -p tcp -s 172.17.0.2 -d 172.17.0.2 --dport 8080 -j MASQUERADE]"
2020-10-08T14:18:27Z dockerd time="2020-10-08T14:18:27.576092480Z" level=debug msg="/sbin/iptables, [--wait -t nat -D POSTROUTING -p tcp -s 172.17.0.2 -d 172.17.0.2 --dport 8080 -j MASQUERADE]"
2020-10-08T14:18:27Z dockerd time="2020-10-08T14:18:27.580308290Z" level=debug msg="DeleteConntrackEntries purged ipv4:0, ipv6:0"
2020-10-08T14:18:27Z dockerd time="2020-10-08T14:18:27.637531876Z" level=debug msg="Releasing addresses for endpoint testcontainers-ryuk-c2b76bfe-5e08-42df-836b-291c0aa4e898's interface on network bridge"
2020-10-08T14:18:27Z dockerd time="2020-10-08T14:18:27.637597509Z" level=debug msg="ReleaseAddress(LocalDefault/172.17.0.0/16, 172.17.0.2)"
2020-10-08T14:18:27Z dockerd time="2020-10-08T14:18:27.637656795Z" level=debug msg="Released address PoolID:LocalDefault/172.17.0.0/16, Address:172.17.0.2 Sequence:App: ipam/default/data, ID: LocalDefault/172.17.0.0/16, DBIndex: 0x0, Bits: 65536, Unselected: 65532, Sequence: (0xe0000000, 1)->(0x0, 2046)->(0x1, 1)->end Curr:3"
2020-10-08T14:18:28Z dockerd time="2020-10-08T14:18:28.348463529Z" level=debug msg="Calling GET /system/df"
2020-10-08T14:18:28Z dockerd time="2020-10-08T14:18:28.349304690Z" level=debug msg="Calling GET /system/df"
2020-10-08T14:18:28Z dockerd time="2020-10-08T14:18:28.349587379Z" level=debug msg="FIXME: Got an API for which error does not match any expected type!!!: a disk usage operation is already running" error_type="*errors.errorString" module=api
2020-10-08T14:18:28Z dockerd time="2020-10-08T14:18:28.349765737Z" level=error msg="Handler for GET /system/df returned error: a disk usage operation is already running"
2020-10-08T14:18:28Z dockerd time="2020-10-08T14:18:28.349801648Z" level=debug msg="FIXME: Got an API for which error does not match any expected type!!!: a disk usage operation is already running" error_type="*errors.errorString" module=api
2020-10-08T14:18:28Z dockerd time="2020-10-08T14:18:28.359533134Z" level=debug msg=VolumeStore.Find ByType=service.andCombinator ByValue="[[local] 0x1645e10]"
docker junit testcontainers
Original Q&A
1

There are 1 answers

0
PeterM On

It's a known issue #3166, just like Vitaly Chura said, and it was fixed in version 1.15.0-rc2.

Related Questions in DOCKER

Related Questions in JUNIT

Related Questions in TESTCONTAINERS

Popular Questions

Popular Tags

javascript python java c# php android html jquery c++ css ios sql mysql r reactjs node.js arrays c asp.net json python-3.x ruby-on-rails .net sql-server swift django angular objective-c pandas excel

Trending Questions