Debugging container failing to start: CreateContainerError

[dominic-p]

I could use a little guidance debugging a Pod that fails to start. I'm trying to run Woodpecker CI jobs on my cluster and the Pod that gets created to run the jobs fails to be created. When I run kubectl describe pod ... I see:

Error: container create failed: chdir: No such file or directory

I set the log level of the runtime to debug with:

[crio.runtime]
default_runtime = "crun"
log_level = "debug"

Then, I watched the logs. Unfortunately, I'm not seeing anything that makes sense to me:

Sep 28 06:43:49.515326 worker-node crio[2084543]: time="2023-09-28 06:43:49.515163502Z" level=debug msg="Setting stage for resource k8s_wp-01hbd89pyaf765becnp3pjecxc-0-clone_wp-01hbd89pyaf765becnp3pjecxc-0-clone_forgejo_22bd0161-b05a-42a2-acef-c8e89646a015_0 from container volume configuration to container device creation" file="resourcestore/resourcestore.go:227" id=67e9307a-b131-46ab-80aa-8ef766864743 name=/runtime.v1.RuntimeService/CreateContainer
Sep 28 06:43:49.515326 worker-node crio[2084543]: time="2023-09-28 06:43:49.515216361Z" level=debug msg="Setting stage for resource k8s_wp-01hbd89pyaf765becnp3pjecxc-0-clone_wp-01hbd89pyaf765becnp3pjecxc-0-clone_forgejo_22bd0161-b05a-42a2-acef-c8e89646a015_0 from container device creation to container storage start" file="resourcestore/resourcestore.go:227" id=67e9307a-b131-46ab-80aa-8ef766864743 name=/runtime.v1.RuntimeService/CreateContainer
Sep 28 06:43:49.515855 worker-node crio[2084543]: time="2023-09-28 06:43:49.515704276Z" level=debug msg="overlay: mount_data=lowerdir=/var/lib/containers/storage/overlay/l/6JP4GDZPMQD6QO7TQSIZVY576H:/var/lib/containers/storage/overlay/l/D4V3HWSFXDDOMOGXEDTM7JYBCH:/var/lib/containers/storage/overlay/l/YT5MDPXROM5FWMBN44QS3ED3Q2:/var/lib/containers/storage/overlay/l/4BHETSMO2YUXXPF2ZHYPPSGGPH,upperdir=/var/lib/containers/storage/overlay/e546d4053317a161121bc2cee43025540ad666c409ec64834ababc65b16b9a9c/diff,workdir=/var/lib/containers/storage/overlay/e546d4053317a161121bc2cee43025540ad666c409ec64834ababc65b16b9a9c/work,nodev,metacopy=on,volatile" file="overlay/overlay.go:1823"
Sep 28 06:43:49.523408 worker-node crio[2084543]: time="2023-09-28 06:43:49.516658957Z" level=debug msg="Mounted container \"a20d18c7410dc3e6edc9564ba3914e25c58a487d501ffc878f54967299c33bb7\" at \"/var/lib/containers/storage/overlay/e546d4053317a161121bc2cee43025540ad666c409ec64834ababc65b16b9a9c/merged\"" file="storage/runtime.go:450"
Sep 28 06:43:49.523408 worker-node crio[2084543]: time="2023-09-28 06:43:49.516726333Z" level=debug msg="Setting stage for resource k8s_wp-01hbd89pyaf765becnp3pjecxc-0-clone_wp-01hbd89pyaf765becnp3pjecxc-0-clone_forgejo_22bd0161-b05a-42a2-acef-c8e89646a015_0 from container storage start to container spec configuration" file="resourcestore/resourcestore.go:227" id=67e9307a-b131-46ab-80aa-8ef766864743 name=/runtime.v1.RuntimeService/CreateContainer
Sep 28 06:43:49.523408 worker-node crio[2084543]: time="2023-09-28 06:43:49.516772550Z" level=debug msg="Applied AppArmor profile crio-default to container a20d18c7410dc3e6edc9564ba3914e25c58a487d501ffc878f54967299c33bb7" file="server/container_create_linux.go:378" id=67e9307a-b131-46ab-80aa-8ef766864743 name=/runtime.v1.RuntimeService/CreateContainer
Sep 28 06:43:49.523408 worker-node crio[2084543]: time="2023-09-28 06:43:49.516835609Z" level=debug msg="Setting container's log_path = /var/log/pods/forgejo_wp-01hbd89pyaf765becnp3pjecxc-0-clone_22bd0161-b05a-42a2-acef-c8e89646a015, sbox.logdir = wp-01hbd89pyaf765becnp3pjecxc-0-clone/0.log, ctr.logfile = /var/log/pods/forgejo_wp-01hbd89pyaf765becnp3pjecxc-0-clone_22bd0161-b05a-42a2-acef-c8e89646a015/wp-01hbd89pyaf765becnp3pjecxc-0-clone/0.log" file="container/container.go:452"
Sep 28 06:43:49.523408 worker-node crio[2084543]: time="2023-09-28 06:43:49.517020665Z" level=debug msg="Setup seccomp from profile field: &SecurityProfile{ProfileType:Unconfined,LocalhostRef:,}" file="seccomp/seccomp.go:188" id=67e9307a-b131-46ab-80aa-8ef766864743 name=/runtime.v1.RuntimeService/CreateContainer
Sep 28 06:43:49.523408 worker-node crio[2084543]: time="2023-09-28 06:43:49.517072703Z" level=debug msg="Setting container's log_path = /var/log/pods/forgejo_wp-01hbd89pyaf765becnp3pjecxc-0-clone_22bd0161-b05a-42a2-acef-c8e89646a015, sbox.logdir = wp-01hbd89pyaf765becnp3pjecxc-0-clone/0.log, ctr.logfile = /var/log/pods/forgejo_wp-01hbd89pyaf765becnp3pjecxc-0-clone_22bd0161-b05a-42a2-acef-c8e89646a015/wp-01hbd89pyaf765becnp3pjecxc-0-clone/0.log" file="container/container.go:452"
Sep 28 06:43:49.523408 worker-node crio[2084543]: time="2023-09-28 06:43:49.517390018Z" level=debug msg="CONTAINER USER: 0" file="server/container_create.go:223" id=67e9307a-b131-46ab-80aa-8ef766864743 name=/runtime.v1.RuntimeService/CreateContainer
Sep 28 06:43:49.523408 worker-node crio[2084543]: time="2023-09-28 06:43:49.518185191Z" level=debug msg="/etc/system-fips does not exist on host, not mounting FIPS mode subscription" file="subscriptions/subscriptions.go:207"
Sep 28 06:43:49.523408 worker-node crio[2084543]: time="2023-09-28 06:43:49.519318266Z" level=debug msg="Setting stage for resource k8s_wp-01hbd89pyaf765becnp3pjecxc-0-clone_wp-01hbd89pyaf765becnp3pjecxc-0-clone_forgejo_22bd0161-b05a-42a2-acef-c8e89646a015_0 from container spec configuration to container runtime creation" file="resourcestore/resourcestore.go:227" id=67e9307a-b131-46ab-80aa-8ef766864743 name=/runtime.v1.RuntimeService/CreateContainer
Sep 28 06:43:49.523408 worker-node crio[2084543]: time="2023-09-28 06:43:49.519432330Z" level=debug msg="running conmon: /usr/bin/conmon" args="[-b /run/containers/storage/overlay-containers/a20d18c7410dc3e6edc9564ba3914e25c58a487d501ffc878f54967299c33bb7/userdata -c a20d18c7410dc3e6edc9564ba3914e25c58a487d501ffc878f54967299c33bb7 --exit-dir /var/run/crio/exits -l /var/log/pods/forgejo_wp-01hbd89pyaf765becnp3pjecxc-0-clone_22bd0161-b05a-42a2-acef-c8e89646a015/wp-01hbd89pyaf765becnp3pjecxc-0-clone/0.log --log-level debug -n k8s_wp-01hbd89pyaf765becnp3pjecxc-0-clone_wp-01hbd89pyaf765becnp3pjecxc-0-clone_forgejo_22bd0161-b05a-42a2-acef-c8e89646a015_0 -P /run/containers/storage/overlay-containers/a20d18c7410dc3e6edc9564ba3914e25c58a487d501ffc878f54967299c33bb7/userdata/conmon-pidfile -p /run/containers/storage/overlay-containers/a20d18c7410dc3e6edc9564ba3914e25c58a487d501ffc878f54967299c33bb7/userdata/pidfile --persist-dir /var/lib/containers/storage/overlay-containers/a20d18c7410dc3e6edc9564ba3914e25c58a487d501ffc878f54967299c33bb7/userdata -r /usr/bin/crun --runtime-arg --root=/run/crun --socket-dir-path /var/run/crio --syslog -u a20d18c7410dc3e6edc9564ba3914e25c58a487d501ffc878f54967299c33bb7 -s]" file="oci/runtime_oci.go:169" id=67e9307a-b131-46ab-80aa-8ef766864743 name=/runtime.v1.RuntimeService/CreateContainer
Sep 28 06:43:49.523408 worker-node crio[2084543]: time="2023-09-28 06:43:49.519983493Z" level=debug msg="Running conmon under slice system.slice and unitName crio-conmon-a20d18c7410dc3e6edc9564ba3914e25c58a487d501ffc878f54967299c33bb7.scope" file="cgmgr/systemd_linux.go:139"
Sep 28 06:43:49.614496 worker-node crio[2084543]: time="2023-09-28 06:43:49.614345672Z" level=debug msg="Received container pid: -1" file="oci/runtime_oci.go:285" id=67e9307a-b131-46ab-80aa-8ef766864743 name=/runtime.v1.RuntimeService/CreateContainer
Sep 28 06:43:49.614590 worker-node crio[2084543]: time="2023-09-28 06:43:49.614495614Z" level=error msg="Container creation error: chdir: No such file or directory\n" file="oci/runtime_oci.go:293" id=67e9307a-b131-46ab-80aa-8ef766864743 name=/runtime.v1.RuntimeService/CreateContainer

For reference here's the YAML for the Pod that's failing:

apiVersion: v1
kind: Pod
metadata:
  creationTimestamp: "2023-09-28T06:40:55Z"
  labels:
    step: wp-01hbd89pyaf765becnp3pjecxc-0-clone
  name: wp-01hbd89pyaf765becnp3pjecxc-0-clone
  namespace: forgejo
  resourceVersion: "3592079"
  uid: 22bd0161-b05a-42a2-acef-c8e89646a015
spec:
  containers:
  - env:
    - name: DRONE_REPO_PRIVATE
      value: "true"
    ...a lot more env variables here
    image: docker.io/woodpeckerci/plugin-git:2.1.1
    imagePullPolicy: IfNotPresent
    name: wp-01hbd89pyaf765becnp3pjecxc-0-clone
    resources: {}
    securityContext:
      privileged: false
    terminationMessagePath: /dev/termination-log
    terminationMessagePolicy: File
    volumeMounts:
    - mountPath: /woodpecker
      name: wp-01hbd89pyaf765becnp3pjecxc-0-default
    - mountPath: /var/run/secrets/kubernetes.io/serviceaccount
      name: kube-api-access-2tfk9
      readOnly: true
    workingDir: /woodpecker/src/git-repo
  dnsPolicy: ClusterFirst
  enableServiceLinks: true
  imagePullSecrets:
  - name: regcred
  nodeName: worker-node
  nodeSelector:
    kubernetes.io/arch: amd64
  preemptionPolicy: PreemptLowerPriority
  priority: 0
  restartPolicy: Never
  schedulerName: default-scheduler
  securityContext: {}
  serviceAccount: default
  serviceAccountName: default
  terminationGracePeriodSeconds: 30
  tolerations:
  - effect: NoExecute
    key: node.kubernetes.io/not-ready
    operator: Exists
    tolerationSeconds: 300
  - effect: NoExecute
    key: node.kubernetes.io/unreachable
    operator: Exists
    tolerationSeconds: 300
  volumes:
  - name: wp-01hbd89pyaf765becnp3pjecxc-0-default
    persistentVolumeClaim:
      claimName: wp-01hbd89pyaf765becnp3pjecxc-0-default
  - name: kube-api-access-2tfk9
    projected:
      defaultMode: 420
      sources:
      - serviceAccountToken:
          expirationSeconds: 3607
          path: token
      - configMap:
          items:
          - key: ca.crt
            path: ca.crt
          name: kube-root-ca.crt
      - downwardAPI:
          items:
          - fieldRef:
              apiVersion: v1
              fieldPath: metadata.namespace
            path: namespace
status:
  conditions:
  - lastProbeTime: null
    lastTransitionTime: "2023-09-28T06:40:55Z"
    status: "True"
    type: Initialized
  - lastProbeTime: null
    lastTransitionTime: "2023-09-28T06:40:55Z"
    message: 'containers with unready status: [wp-01hbd89pyaf765becnp3pjecxc-0-clone]'
    reason: ContainersNotReady
    status: "False"
    type: Ready
  - lastProbeTime: null
    lastTransitionTime: "2023-09-28T06:40:55Z"
    message: 'containers with unready status: [wp-01hbd89pyaf765becnp3pjecxc-0-clone]'
    reason: ContainersNotReady
    status: "False"
    type: ContainersReady
  - lastProbeTime: null
    lastTransitionTime: "2023-09-28T06:40:55Z"
    status: "True"
    type: PodScheduled
  containerStatuses:
  - image: docker.io/woodpeckerci/plugin-git:2.1.1
    imageID: ""
    lastState: {}
    name: wp-01hbd89pyaf765becnp3pjecxc-0-clone
    ready: false
    restartCount: 0
    started: false
    state:
      waiting:
        message: |
          container create failed: chdir: No such file or directory
        reason: CreateContainerError
  hostIP: 192.168.1.1
  phase: Pending
  podIP: 192.168.244.1
  podIPs:
  - ip: 192.168.244.1
  qosClass: BestEffort
  startTime: "2023-09-28T06:40:55Z"

What it comes down is that I don't know which process is trying to change to which dir. If I could figure that out, maybe I could figure out why it's failing.

Any ideas would be appreciated.

[haircommander]

I would first expect the workdir of the image isn't being found--maybe being overridden by the volumes? this is kinda a hunch, but can you try running the container with as few pod spec options as possible and see if that works?

[dominic-p]

Just to follow up on this. It appears that other runtimes (and possibly Podman) create the working dir if doesn't exist. Should CRI-O follow suit? I'm not sure which approach is technically correct (error or just create the working dir), but it would be nice to have consistent behavior in the ecosystem if possible.

[haircommander]

yeah we would accept such a change, do you have any interest in opening a PR?

[dominic-p]

Thanks for the response. Unfortunately, go isn't my language. But, if you can point me at the right file, I can take a stab at it. It should be a fairly straightforward change.

Follow up question: Do you know if this behavior (handling non-existent working dirs) it controlled by CRI-O or the underlying runtime (crun/runC) or both? We were discussing this on the Woodpecker repo, and I wasn't sure.

[haircommander]

I believe it's CRI-O's responsibility (or the image writer)

CRI-O is supposed to be doing this here https://github.com/cri-o/cri-o/blob/main/server/container_create_linux.go#L890. Not sure what's going wrong with your image

[dominic-p]

Thanks for that. I was under the impression that this behavior was by design. Hunting down a bug in a codebase this size might be a bit too much for me for my first go project. :) That said, if I get some free time, I'll give it a whirl.