directfs startup issue

[sigcafe]

Description

When using directfs (starting from the june build) I am unable to start containers,

docker run --rm --runtime=runsc-debug hello-world
docker: Error response from daemon: OCI runtime start failed: starting container: setting up network: creating interfaces from net namespace "/proc/500457/ns/net": creating links and routes: broken pipe: unknown.

When disabling directfs using --directfs=false or using runsc from the may build, the container starts.

 docker run --rm --runtime=runsc hello-world

Hello from Docker!
This message shows that your installation appears to be working correctly.

Steps to reproduce

No response

runsc version

runsc version release-20230904.0
spec: 1.1.0-rc.1

docker version (if using docker)

Client:
 Version:           24.0.5
 API version:       1.43
 Go version:        go1.20.6
 Git commit:        ced0996600
 Built:             Wed Jul 26 21:44:58 2023
 OS/Arch:           linux/amd64
 Context:           default

Server:
 Engine:
  Version:          24.0.5
  API version:      1.43 (minimum version 1.12)
  Go version:       go1.20.6
  Git commit:       a61e2b4c9c
  Built:            Wed Jul 26 21:44:58 2023
  OS/Arch:          linux/amd64
  Experimental:     false
 containerd:
  Version:          v1.7.2
  GitCommit:        0cae528dd6cb557f7201036e9f43420650207b58.m
 runc:
  Version:          1.1.9
  GitCommit:
 docker-init:
  Version:          0.19.0
  GitCommit:        de40ad0

uname

Linux lolo 6.4.12-arch1-1 #1 SMP PREEMPT_DYNAMIC Thu, 24 Aug 2023 00:38:14 +0000 x86_64 GNU/Linux

kubectl (if using Kubernetes)

No response

repo state (if built from source)

No response

runsc debug logs (if available)

I0909 09:29:08.389751  500446 main.go:188] ***************************
I0909 09:29:08.389812  500446 main.go:189] Args: [/usr/bin/runsc --debug-log=/tmp/runsc/ --debug --strace --root /var/run/docker/runtime-runc/moby --log /run/containerd/io.containerd.runtime.v2.task/moby/1f349680ce14edbbfd0aecff780c2b1cf92bb53a1e8b0429730d423e330826ea/log.json --log-format json --systemd-cgroup create --bundle /run/containerd/io.containerd.runtime.v2.task/moby/1f349680ce14edbbfd0aecff780c2b1cf92bb53a1e8b0429730d423e330826ea --pid-file /run/containerd/io.containerd.runtime.v2.task/moby/1f349680ce14edbbfd0aecff780c2b1cf92bb53a1e8b0429730d423e330826ea/init.pid 1f349680ce14edbbfd0aecff780c2b1cf92bb53a1e8b0429730d423e330826ea]
I0909 09:29:08.389851  500446 main.go:190] Version release-20230904.0
I0909 09:29:08.389865  500446 main.go:191] GOOS: linux
I0909 09:29:08.389878  500446 main.go:192] GOARCH: amd64
I0909 09:29:08.389896  500446 main.go:193] PID: 500446
I0909 09:29:08.389910  500446 main.go:194] UID: 0, GID: 0
I0909 09:29:08.389923  500446 main.go:195] Configuration:
I0909 09:29:08.389936  500446 main.go:196]              RootDir: /var/run/docker/runtime-runc/moby
I0909 09:29:08.389953  500446 main.go:197]              Platform: systrap
I0909 09:29:08.389966  500446 main.go:198]              FileAccess: exclusive
I0909 09:29:08.389982  500446 main.go:199]              Directfs: true
I0909 09:29:08.389995  500446 main.go:200]              Overlay: root:self
I0909 09:29:08.390010  500446 main.go:201]              Network: sandbox, logging: false
I0909 09:29:08.390025  500446 main.go:202]              Strace: true, max size: 1024, syscalls:
I0909 09:29:08.390039  500446 main.go:203]              IOURING: false
I0909 09:29:08.390056  500446 main.go:204]              Debug: true
I0909 09:29:08.390068  500446 main.go:205]              Systemd: true
I0909 09:29:08.390081  500446 main.go:206] ***************************
D0909 09:29:08.391983  500446 specutils.go:85] Spec:
{
  "ociVersion": "1.1.0-rc.2",
  "process": {
    "user": {
      "uid": 0,
      "gid": 0,
      "additionalGids": [
        0
      ]
    },
    "args": [
      "/hello"
    ],
    "env": [
      "PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin",
      "HOSTNAME=1f349680ce14"
    ],
    "cwd": "/",
    "noNewPrivileges": true,
    "oomScoreAdj": 0
  },
  "root": {
    "path": "/var/lib/docker/165536.165536/overlay2/f121f7d43bbb01d931b7656798f1c2969a263a9dc6e5c063544b1f37d28b3be2/merged"
  },
  "hostname": "1f349680ce14",
  "mounts": [
    {
      "destination": "/proc",
      "type": "proc",
      "source": "/run/containerd/io.containerd.runtime.v2.task/moby/1f349680ce14edbbfd0aecff780c2b1cf92bb53a1e8b0429730d423e330826ea/proc",
      "options": [
        "nosuid",
        "noexec",
        "nodev"
      ]
    },
    {
      "destination": "/dev",
      "type": "tmpfs",
      "source": "/run/containerd/io.containerd.runtime.v2.task/moby/1f349680ce14edbbfd0aecff780c2b1cf92bb53a1e8b0429730d423e330826ea/tmpfs",
      "options": [
        "nosuid",
        "strictatime",
        "mode=755",
        "size=65536k"
      ]
    },
    {
      "destination": "/dev/pts",
      "type": "devpts",
      "source": "/run/containerd/io.containerd.runtime.v2.task/moby/1f349680ce14edbbfd0aecff780c2b1cf92bb53a1e8b0429730d423e330826ea/devpts",
      "options": [
        "nosuid",
        "noexec",
        "newinstance",
        "ptmxmode=0666",
        "mode=0620",
        "gid=5"
      ]
    },
    {
      "destination": "/sys",
      "type": "sysfs",
      "source": "/run/containerd/io.containerd.runtime.v2.task/moby/1f349680ce14edbbfd0aecff780c2b1cf92bb53a1e8b0429730d423e330826ea/sysfs",
      "options": [
        "nosuid",
        "noexec",
        "nodev",
        "ro"
      ]
    },
    {
      "destination": "/sys/fs/cgroup",
      "type": "cgroup",
      "source": "/run/containerd/io.containerd.runtime.v2.task/moby/1f349680ce14edbbfd0aecff780c2b1cf92bb53a1e8b0429730d423e330826ea/cgroup",
      "options": [
        "nosuid",
        "noexec",
        "nodev"
      ]
    },
    {
      "destination": "/dev/mqueue",
      "type": "mqueue",
      "source": "/run/containerd/io.containerd.runtime.v2.task/moby/1f349680ce14edbbfd0aecff780c2b1cf92bb53a1e8b0429730d423e330826ea/mqueue",
      "options": [
        "nosuid",
        "noexec",
        "nodev"
      ]
    },
    {
      "destination": "/dev/shm",
      "type": "tmpfs",
      "source": "/run/containerd/io.containerd.runtime.v2.task/moby/1f349680ce14edbbfd0aecff780c2b1cf92bb53a1e8b0429730d423e330826ea/shm",
      "options": [
        "nosuid",
        "noexec",
        "nodev",
        "mode=1777",
        "size=67108864"
      ]
    },
    {
      "destination": "/etc/resolv.conf",
      "type": "bind",
      "source": "/var/lib/docker/165536.165536/containers/1f349680ce14edbbfd0aecff780c2b1cf92bb53a1e8b0429730d423e330826ea/resolv.conf",
      "options": [
        "rbind",
        "rprivate"
      ]
    },
    {
      "destination": "/etc/hostname",
      "type": "bind",
      "source": "/var/lib/docker/165536.165536/containers/1f349680ce14edbbfd0aecff780c2b1cf92bb53a1e8b0429730d423e330826ea/hostname",
      "options": [
        "rbind",
        "rprivate"
      ]
    },
    {
      "destination": "/etc/hosts",
      "type": "bind",
      "source": "/var/lib/docker/165536.165536/containers/1f349680ce14edbbfd0aecff780c2b1cf92bb53a1e8b0429730d423e330826ea/hosts",
      "options": [
        "rbind",
        "rprivate"
      ]
    }
  ],
  "hooks": {
    "prestart": [
      {
        "path": "/proc/499159/exe",
        "args": [
          "libnetwork-setkey",
          "-exec-root=/var/run/docker",
          "1f349680ce14edbbfd0aecff780c2b1cf92bb53a1e8b0429730d423e330826ea",
          "9d43fb96b2fe"
        ]
      }
    ]
  },
  "linux": {
    "uidMappings": [
      {
        "containerID": 0,
        "hostID": 165536,
        "size": 65536
      }
    ],
    "gidMappings": [
      {
        "containerID": 0,
        "hostID": 165536,
        "size": 65536
      }
    ],
    "sysctl": {
      "net.ipv4.ip_unprivileged_port_start": "0"
    },
    "resources": {
      "blockIO": {}
    },
    "cgroupsPath": "system.slice:docker:1f349680ce14edbbfd0aecff780c2b1cf92bb53a1e8b0429730d423e330826ea",
    "namespaces": [
      {
        "type": "mount"
      },
      {
        "type": "network"
      },
      {
        "type": "uts"
      },
      {
        "type": "pid"
      },
      {
        "type": "ipc"
      },
      {
        "type": "user"
      },
      {
        "type": "cgroup"
      }
    ]
  }
}
D0909 09:29:08.392052  500446 container.go:196] Create container, cid: 1f349680ce14edbbfd0aecff780c2b1cf92bb53a1e8b0429730d423e330826ea, rootDir: "/var/run/docker/runtime-runc/moby"
D0909 09:29:08.392186  500446 container.go:258] Creating new sandbox for container, cid: 1f349680ce14edbbfd0aecff780c2b1cf92bb53a1e8b0429730d423e330826ea
D0909 09:29:08.396107  500446 cgroup.go:410] New cgroup for pid: self, *cgroup.cgroupSystemd: &{cgroupV2:{Mountpoint:/sys/fs/cgroup Path:/system.slice/docker-1f349680ce14edbbfd0aecff780c2b1cf92bb53a1e8b0429730d423e330826ea.scope Controllers:[cpuset cpu io memory hugetlb pids rdma misc] Own:[]} Name:1f349680ce14edbbfd0aecff780c2b1cf92bb53a1e8b0429730d423e330826ea Parent:system.slice ScopePrefix:docker properties:[] dbusConn:0xc0003aa000}
D0909 09:29:08.396180  500446 systemd.go:98] Installing systemd cgroup resource controller under system.slice
D0909 09:29:08.396393  500446 container.go:950] Created overlay filestore file at "/var/lib/docker/165536.165536/overlay2/f121f7d43bbb01d931b7656798f1c2969a263a9dc6e5c063544b1f37d28b3be2/merged/.gvisor.overlay.img.1f349680ce14edbbfd0aecff780c2b1cf92bb53a1e8b0429730d423e330826ea" for mount source "/var/lib/docker/165536.165536/overlay2/f121f7d43bbb01d931b7656798f1c2969a263a9dc6e5c063544b1f37d28b3be2/merged"
D0909 09:29:08.396472  500446 systemd.go:154] Joining systemd cgroup docker-1f349680ce14edbbfd0aecff780c2b1cf92bb53a1e8b0429730d423e330826ea.scope
I0909 09:29:08.452481  500446 namespace.go:202] Mapping host uid 165536 to container uid 0 (size=65536)
I0909 09:29:08.452520  500446 namespace.go:210] Mapping host gid 165536 to container gid 0 (size=65536)
D0909 09:29:08.452537  500446 donation.go:31] Donating FD 3: "/run/containerd/io.containerd.runtime.v2.task/moby/1f349680ce14edbbfd0aecff780c2b1cf92bb53a1e8b0429730d423e330826ea/log.json"
D0909 09:29:08.452576  500446 donation.go:31] Donating FD 4: "/tmp/runsc/runsc.log.20230909-092908.452130.gofer.txt"
D0909 09:29:08.452587  500446 donation.go:31] Donating FD 5: "/run/containerd/io.containerd.runtime.v2.task/moby/1f349680ce14edbbfd0aecff780c2b1cf92bb53a1e8b0429730d423e330826ea/config.json"
D0909 09:29:08.452611  500446 donation.go:31] Donating FD 6: "|1"
D0909 09:29:08.452619  500446 donation.go:31] Donating FD 7: "gofer IO FD"
D0909 09:29:08.452629  500446 donation.go:31] Donating FD 8: "gofer IO FD"
D0909 09:29:08.452638  500446 donation.go:31] Donating FD 9: "gofer IO FD"
D0909 09:29:08.452647  500446 donation.go:31] Donating FD 10: "gofer IO FD"
D0909 09:29:08.452657  500446 container.go:1207] Starting gofer: /proc/self/exe [runsc-gofer --strace=true --systemd-cgroup=true --root=/var/run/docker/runtime-runc/moby --debug=true --log=/run/containerd/io.containerd.runtime.v2.task/moby/1f349680ce14edbbfd0aecff780c2b1cf92bb53a1e8b0429730d423e330826ea/log.json --log-format=json --debug-log=/tmp/runsc/ --log-fd=3 --debug-log-fd=4 gofer --bundle /run/containerd/io.containerd.runtime.v2.task/moby/1f349680ce14edbbfd0aecff780c2b1cf92bb53a1e8b0429730d423e330826ea --overlay-mediums=2,0,0,0 --spec-fd=5 --mounts-fd=6 --io-fds=7 --io-fds=8 --io-fds=9 --io-fds=10]
I0909 09:29:08.456246  500446 container.go:1211] Gofer started, PID: 500452
D0909 09:29:08.456686  500446 sandbox.go:84] Attempting to create socket file "/var/run/docker/runtime-runc/moby/runsc-1f349680ce14edbbfd0aecff780c2b1cf92bb53a1e8b0429730d423e330826ea.sock"
D0909 09:29:08.456732  500446 sandbox.go:84] Attempting to create socket file "/var/run/runsc-1f349680ce14edbbfd0aecff780c2b1cf92bb53a1e8b0429730d423e330826ea.sock"
D0909 09:29:08.456795  500446 sandbox.go:87] Using socket file "/var/run/runsc-1f349680ce14edbbfd0aecff780c2b1cf92bb53a1e8b0429730d423e330826ea.sock"
I0909 09:29:08.456808  500446 sandbox.go:751] Control socket: ""
I0909 09:29:08.456894  500446 sandbox.go:787] Sandbox will be started in new mount, IPC and UTS namespaces
I0909 09:29:08.456913  500446 sandbox.go:797] Sandbox will be started in the current PID namespace
I0909 09:29:08.456929  500446 sandbox.go:808] Sandbox will be started in the container's network namespace: {Type:network Path:}
I0909 09:29:08.457002  500446 sandbox.go:830] Sandbox will be started in container's user namespace: {Type:user Path:}
I0909 09:29:08.457027  500446 namespace.go:202] Mapping host uid 165536 to container uid 0 (size=65536)
I0909 09:29:08.457039  500446 namespace.go:210] Mapping host gid 165536 to container gid 0 (size=65536)
I0909 09:29:08.457168  500446 sandbox.go:860] Sandbox will be started in minimal chroot
D0909 09:29:08.457207  500446 sandbox.go:1459] Changing "/dev/stdin" ownership to 0/0
D0909 09:29:08.457229  500446 sandbox.go:1459] Changing "/dev/stdout" ownership to 0/0
D0909 09:29:08.457242  500446 sandbox.go:1459] Changing "/dev/stderr" ownership to 0/0
D0909 09:29:08.457476  500446 donation.go:31] Donating FD 3: "/run/containerd/io.containerd.runtime.v2.task/moby/1f349680ce14edbbfd0aecff780c2b1cf92bb53a1e8b0429730d423e330826ea/log.json"
D0909 09:29:08.457494  500446 donation.go:31] Donating FD 4: "/tmp/runsc/runsc.log.20230909-092908.456419.boot.txt"
D0909 09:29:08.457505  500446 donation.go:31] Donating FD 5: "sandbox IO FD"
D0909 09:29:08.457515  500446 donation.go:31] Donating FD 6: "sandbox IO FD"
D0909 09:29:08.457524  500446 donation.go:31] Donating FD 7: "sandbox IO FD"
D0909 09:29:08.457534  500446 donation.go:31] Donating FD 8: "sandbox IO FD"
D0909 09:29:08.457543  500446 donation.go:31] Donating FD 9: "/var/lib/docker/165536.165536/overlay2/f121f7d43bbb01d931b7656798f1c2969a263a9dc6e5c063544b1f37d28b3be2/merged/.gvisor.overlay.img.1f349680ce14edbbfd0aecff780c2b1cf92bb53a1e8b0429730d423e330826ea"
D0909 09:29:08.457567  500446 donation.go:31] Donating FD 10: "|0"
D0909 09:29:08.457576  500446 donation.go:31] Donating FD 11: "|1"
D0909 09:29:08.457591  500446 donation.go:31] Donating FD 12: "control_server_socket"
D0909 09:29:08.457601  500446 donation.go:31] Donating FD 13: "/run/containerd/io.containerd.runtime.v2.task/moby/1f349680ce14edbbfd0aecff780c2b1cf92bb53a1e8b0429730d423e330826ea/config.json"
D0909 09:29:08.457618  500446 donation.go:31] Donating FD 14: "/dev/stdin"
D0909 09:29:08.457628  500446 donation.go:31] Donating FD 15: "/dev/stdout"
D0909 09:29:08.457637  500446 donation.go:31] Donating FD 16: "/dev/stderr"
D0909 09:29:08.457647  500446 sandbox.go:1045] Starting sandbox: /proc/self/exe [runsc-sandbox --debug=true --log=/run/containerd/io.containerd.runtime.v2.task/moby/1f349680ce14edbbfd0aecff780c2b1cf92bb53a1e8b0429730d423e330826ea/log.json --log-format=json --debug-log=/tmp/runsc/ --strace=true --systemd-cgroup=true --root=/var/run/docker/runtime-runc/moby --log-fd=3 --debug-log-fd=4 boot --bundle=/run/containerd/io.containerd.runtime.v2.task/moby/1f349680ce14edbbfd0aecff780c2b1cf92bb53a1e8b0429730d423e330826ea --overlay-mediums=2,0,0,0 --apply-caps=true --setup-root --total-host-memory 14609473536 --cpu-num 8 --total-memory 14609473536 --io-fds=5 --io-fds=6 --io-fds=7 --io-fds=8 --overlay-filestore-fds=9 --mounts-fd=10 --start-sync-fd=11 --controller-fd=12 --spec-fd=13 --stdio-fds=14 --stdio-fds=15 --stdio-fds=16 1f349680ce14edbbfd0aecff780c2b1cf92bb53a1e8b0429730d423e330826ea]
D0909 09:29:08.457695  500446 sandbox.go:1046] SysProcAttr: &{Chroot: Credential:0xc00033d410 Ptrace:false Setsid:true Setpgid:false Setctty:false Noctty:false Ctty:0 Foreground:false Pgid:0 Pdeathsig:signal 0 Cloneflags:0 Unshareflags:0 UidMappings:[{ContainerID:0 HostID:165536 Size:65536}] GidMappings:[{ContainerID:0 HostID:165536 Size:65536}] GidMappingsEnableSetgroups:false AmbientCaps:[] UseCgroupFD:false CgroupFD:0}
I0909 09:29:08.460947  500446 sandbox.go:1074] Sandbox started, PID: 500457
D0909 09:29:08.630452  500446 cgroup_v2.go:174] Deleting cgroup "/sys/fs/cgroup/system.slice/docker-1f349680ce14edbbfd0aecff780c2b1cf92bb53a1e8b0429730d423e330826ea.scope"
D0909 09:29:08.630557  500446 container.go:988] Save container, cid: 1f349680ce14edbbfd0aecff780c2b1cf92bb53a1e8b0429730d423e330826ea
D0909 09:29:08.633091  500446 hook.go:63] Executing hook {Path:/proc/499159/exe Args:[libnetwork-setkey -exec-root=/var/run/docker 1f349680ce14edbbfd0aecff780c2b1cf92bb53a1e8b0429730d423e330826ea 9d43fb96b2fe] Env:[] Timeout:<nil>}, state: {Version:1.1.0-rc.1 ID:1f349680ce14edbbfd0aecff780c2b1cf92bb53a1e8b0429730d423e330826ea Status:created Pid:500457 Bundle:/run/containerd/io.containerd.runtime.v2.task/moby/1f349680ce14edbbfd0aecff780c2b1cf92bb53a1e8b0429730d423e330826ea Annotations:map[]}
D0909 09:29:08.762430  500446 hook.go:118] Execute hook "/proc/499159/exe" success!
I0909 09:29:08.762694  500446 main.go:223] Exiting with status: 0

[ayushr2]

Strange that the hello-world container won't start up. It seems that the start command is failing. Could you upload the logs from that command? The resultant log file will have the start suffix in it. I think the above mentioned logs are from the create command, which was successful.

[ayushr2]

Note to self: It might be because of the custom uidMappings and gidMappings set in the container spec.

[sigcafe]

added the latest logfile

runsc.log.20230909-162304.911145.start.txt

[EtiennePerot]

A "broken pipe" error in urpc indicates that the runsc start command failed to communicate with the runsc boot process, for example if the runsc boot process crashed while handling the request to start the container. Can you upload the *.boot.log log? (Or simply upload every log you have.)

[sigcafe]

these are the logs I have,

just to clarify

• all other containers fail to startup.
• userns-remap and no-new-privileges are enabled
• userland-proxy is disabled
• storage-driver is overlay2

runsc.log.20230910-092119.273955.create.txt
runsc.log.20230910-092119.343513.gofer.txt
runsc.log.20230910-092119.349445.boot.txt
runsc.log.20230910-092119.749576.start.txt
runsc.log.20230910-092119.850217.kill.txt

[sigcafe]

looks like userns-remap is causing trouble

$ docker run --userns=host --rm --runtime=runsc-debug hello-world

Hello from Docker!

[ayushr2]

Thanks for the report, we understand the issue. We are working on a resolution.