`ExecStartAndAttach` - noise in logs by incorrect goroutine handling after exec completion

[lpcalisi]

Issue Description

When using the ExecStartAndAttach function to run an interactive exec session, the following errors appear in the terminal after the exec process finishes:

ERRO[0002] Failed to write input to service: write unix ->/var/folders/t1/2v3660rx2p314346d7qxxngs84bccr/T/podman/podman-machine-default-api.sock: use of closed network connection
WARN[0002] Failed to close STDIN for writing: close unix ->/var/folders/t1/2v3660rx2p314346d7qxxngs84bccr/T/podman/podman-machine-default-api.sock: use of closed network connection

It seems that the goroutine responsible for copying STDIN to the socket is not correctly terminated when the exec session ends, resulting in attempts to write to a closed socket.

cc @mesaglio

Steps to reproduce the issue

Steps to reproduce the issue

I've created a small proof-of-concept (PoC) program in Go using podman/bindings to reproduce the issue:

package main

import (
	"bufio"
	"context"
	"fmt"
	"io"
	"log"
	"os"
	"time"

	"github.com/containers/podman/v5/pkg/api/handlers"
	"github.com/containers/podman/v5/pkg/bindings"
	"github.com/containers/podman/v5/pkg/bindings/containers"
	"github.com/containers/podman/v5/pkg/specgen"
	dockerContainer "github.com/docker/docker/api/types/container"
)

func main() {
	conn, _ := bindings.NewConnection(context.Background(), "")
	fmt.Println("[+] first exec interactive...")
	execInteractive(conn)
	fmt.Println("[+] exec finished")
	fmt.Println("[+] press any key now and see error...")
	time.Sleep(5 * time.Second)
}

func execInteractive(ctx context.Context) error {
	spec := specgen.NewSpecGenerator("alpine", false)
	spec.Command = []string{"/bin/sh", "-c", "while true; do sleep 5; done"}
	create, err := containers.CreateWithSpec(ctx, spec, nil)
	if err != nil {
		log.Println(err.Error())
	}
	err = containers.Start(ctx, create.ID, nil)
	if err != nil {
		log.Println(err.Error())
	}

	dockerExecOpts := dockerContainer.ExecOptions{
		Cmd:          []string{"/bin/sh"},
		AttachStderr: true,
		AttachStdout: true,
		AttachStdin:  true,
		Tty:          true,
	}

	execConfig := &handlers.ExecCreateConfig{dockerExecOpts}
	execId, err := containers.ExecCreate(ctx, create.ID, execConfig)
	if err != nil {
		return err
	}

	var stdout io.Writer = os.Stdout
	var stderr io.Writer = os.Stdout
	input := bufio.NewReader(os.Stdin)

	attachOptions := new(containers.ExecStartAndAttachOptions)
	attachOptions.WithAttachError(true).WithAttachInput(true).WithAttachOutput(true).WithErrorStream(stderr).WithOutputStream(stdout).WithInputStream(*input)
	err = containers.ExecStartAndAttach(ctx, execId, attachOptions)
	if err != nil {
		return err
	}

	_, err = containers.Remove(ctx, create.ID, nil)
	if err != nil {
		return err
	}
	return nil
}

go.mod

go 1.23.3

require (
        github.com/containers/podman/v5 v5.4.0
        github.com/docker/docker v27.5.1+incompatible
)

Describe the results you received

When exec finishes, socket was close and if you press any key on stdin fails.

➜  poc ./main
[+] first exec interactive...
/ # exit 0
[+] exec finished
[+] press any key now and see error...

ERRO[0004] Failed to write input to service: write unix ->/var/folders/t1/2v3660rx2p314346d7qxxngs84bccr/T/podman/podman-machine-default-api.sock: use of closed network connection
WARN[0004] Failed to close STDIN for writing: close unix ->/var/folders/t1/2v3660rx2p314346d7qxxngs84bccr/T/podman/podman-machine-default-api.sock: use of closed network connection

Expected results

➜ poc ./main
[+] first exec interactive...
/ # exit 0
[+] exec finished
[+] press any key now and see error...

➜ poc

podman info output

`
Client:
  APIVersion: 5.4.0
  BuildOrigin: brew
  Built: 1739290083
  BuiltTime: Tue Feb 11 13:08:03 2025
  GitCommit: ""
  GoVersion: go1.23.6
  Os: darwin
  OsArch: darwin/arm64
  Version: 5.4.0
host:
  arch: arm64
  buildahVersion: 1.39.0
  cgroupControllers:
  - cpuset
  - cpu
  - io
  - memory
  - pids
  - rdma
  - misc
  cgroupManager: systemd
  cgroupVersion: v2
  conmon:
    package: conmon-2.1.12-3.fc41.aarch64
    path: /usr/bin/conmon
    version: 'conmon version 2.1.12, commit: '
  cpuUtilization:
    idlePercent: 99.73
    systemPercent: 0.18
    userPercent: 0.1
  cpus: 4
  databaseBackend: sqlite
  distribution:
    distribution: fedora
    variant: coreos
    version: "41"
  eventLogger: journald
  freeLocks: 2035
  hostname: localhost.localdomain
  idMappings:
    gidmap: null
    uidmap: null
  kernel: 6.12.9-200.fc41.aarch64
  linkmode: dynamic
  logDriver: journald
  memFree: 1462202368
  memTotal: 2042535936
  networkBackend: netavark
  networkBackendInfo:
    backend: netavark
    dns:
      package: aardvark-dns-1.13.1-1.fc41.aarch64
      path: /usr/libexec/podman/aardvark-dns
      version: aardvark-dns 1.13.1
    package: netavark-1.13.1-1.fc41.aarch64
    path: /usr/libexec/podman/netavark
    version: netavark 1.13.1
  ociRuntime:
    name: crun
    package: crun-1.19.1-1.fc41.aarch64
    path: /usr/bin/crun
    version: |-
      crun version 1.19.1
      commit: 3e32a70c93f5aa5fea69b50256cca7fd4aa23c80
      rundir: /run/crun
      spec: 1.0.0
      +SYSTEMD +SELINUX +APPARMOR +CAP +SECCOMP +EBPF +CRIU +LIBKRUN +WASM:wasmedge +YAJL
  os: linux
  pasta:
    executable: /usr/bin/pasta
    package: passt-0^20241211.g09478d5-1.fc41.aarch64
    version: |
      pasta 0^20241211.g09478d5-1.fc41.aarch64-pasta
      Copyright Red Hat
      GNU General Public License, version 2 or later
        <https://www.gnu.org/licenses/old-licenses/gpl-2.0.html>
      This is free software: you are free to change and redistribute it.
      There is NO WARRANTY, to the extent permitted by law.
  remoteSocket:
    exists: true
    path: unix:///run/podman/podman.sock
  rootlessNetworkCmd: pasta
  security:
    apparmorEnabled: false
    capabilities: CAP_CHOWN,CAP_DAC_OVERRIDE,CAP_FOWNER,CAP_FSETID,CAP_KILL,CAP_NET_BIND_SERVICE,CAP_SETFCAP,CAP_SETGID,CAP_SETPCAP,CAP_SETUID,CAP_SYS_CHROOT
    rootless: false
    seccompEnabled: true
    seccompProfilePath: /usr/share/containers/seccomp.json
    selinuxEnabled: true
  serviceIsRemote: true
  slirp4netns:
    executable: /usr/bin/slirp4netns
    package: slirp4netns-1.3.1-1.fc41.aarch64
    version: |-
      slirp4netns version 1.3.1
      commit: e5e368c4f5db6ae75c2fce786e31eef9da6bf236
      libslirp: 4.8.0
      SLIRP_CONFIG_VERSION_MAX: 5
      libseccomp: 2.5.5
  swapFree: 0
  swapTotal: 0
  uptime: 1h 10m 22.00s (Approximately 0.04 days)
  variant: v8
plugins:
  authorization: null
  log:
  - k8s-file
  - none
  - passthrough
  - journald
  network:
  - bridge
  - macvlan
  - ipvlan
  volume:
  - local
registries:
  search:
  - docker.io
store:
  configFile: /usr/share/containers/storage.conf
  containerStore:
    number: 13
    paused: 0
    running: 13
    stopped: 0
  graphDriverName: overlay
  graphOptions:
    overlay.additionalImageStores:
    - /usr/lib/containers/storage
    overlay.imagestore: /usr/lib/containers/storage
    overlay.mountopt: nodev,metacopy=on
  graphRoot: /var/lib/containers/storage
  graphRootAllocated: 106415992832
  graphRootUsed: 4260315136
  graphStatus:
    Backing Filesystem: xfs
    Native Overlay Diff: "false"
    Supports d_type: "true"
    Supports shifting: "true"
    Supports volatile: "true"
    Using metacopy: "true"
  imageCopyTmpDir: /var/tmp
  imageStore:
    number: 1
  runRoot: /run/containers/storage
  transientStore: false
  volumePath: /var/lib/containers/storage/volumes
version:
  APIVersion: 5.4.0
  BuildOrigin: Fedora Project
  Built: 1739232000
  BuiltTime: Mon Feb 10 21:00:00 2025
  GitCommit: ""
  GoVersion: go1.23.5
  Os: linux
  OsArch: linux/arm64
  Version: 5.4.0
`

Podman in a container

No

Privileged Or Rootless

Privileged

Upstream Latest Release

Yes

Additional environment details

The error is using podman bindings.

Root Cause Analysis

The issue seems to stem from this code in the ExecStartAndAttach implementation:

if options.GetAttachInput() {
    go func() {
        logrus.Debugf("Copying STDIN to socket")
        _, err := detach.Copy(socket, options.InputStream, []byte{})
        if err != nil {
            logrus.Errorf("Failed to write input to service: %v", err)
        }

        if closeWrite, ok := socket.(CloseWriter); ok {
            logrus.Debugf("Closing STDIN")
            if err := closeWrite.CloseWrite(); err != nil {
                logrus.Warnf("Failed to close STDIN for writing: %v", err)
            }
        }
    }()
}

Additional information

No response

[Luap99]

There is no way to cancel the goroutine, as there is no way to cancel the copy operation. The only way is to close stdin or well as in this case when the exec connection ends and we get an write error.
I guess catching this error and ignoring it might be the best we can do. But the problem there is that goroutine stays leaked forever until the stdin is closed or we get same data to trigger the write on closed error which is really not good.

Also see the comment for Attach() which does the same thing

// NOTE: When stdin is provided, this function currently leaks a goroutine reading from that stream
// even if the ctx is cancelled. The goroutine will only exit if the input stream is closed. For example,
// if stdin is `os.Stdin` attached to a tty, the goroutine will consume a chunk of user input from the
// terminal even after the container has exited. In this scenario the os.Stdin stream will not be expected
// to be closed.

[lpcalisi]

What do you think about something like this?

This approach avoids showing error messages when the socket is closed but still logs other errors. However, I’m not sure if hiding these errors might cause more confusion or hide relevant information.

	if options.GetAttachInput() {
		go func() {
			logrus.Debugf("Copying STDIN to socket")
			_, err := detach.Copy(socket, options.InputStream, []byte{})
			// if err != nil && {
			if err != nil && !errors.Is(err, net.ErrClosed) {
				logrus.Errorf("Failed to write input to service: %v", err)
			}

                        /*
                        if closeWrite, ok := socket.(CloseWriter); ok {
                          	logrus.Debugf("Closing STDIN")
                          	if err := closeWrite.CloseWrite(); err != nil {
                          		logrus.Warnf("Failed to close STDIN for writing: %v", err)
                          	}
                        }
                        */

			if err == nil {
				if closeWrite, ok := socket.(CloseWriter); ok {
					logrus.Debugf("Closing STDIN")
					if err := closeWrite.CloseWrite(); err != nil {
						logrus.Warnf("Failed to close STDIN for writing: %v", err)
					}
				}
			}
		}()
	}

This change only aims to reduce the noise in the logs, while the goroutines will still leak, which remains the root issue.

[Luap99]

I think that is fine, we should do the same change for the normal attach as well then. And then copy the comment about the stdin problem from Attach() to ExecStartAndAttach() then we can at least say it is documented to leak the goroutine.

[lpcalisi]

@Luap99 here is the change: #25345

Do you think it makes sense to add the No New Tests label? I'm trying to add a new test under pkg/bindings/test, but the only way to test it would be by checking that stdout does not print log errors 😢

[Luap99]

you can use something like this in the test setup

logBuffer := bytes.Buffer{}
logrus.SetOutput(&logBuffer)
logrus.SetLevel(logrus.InfoLevel)

Then in the test check that the buffer is empty, not sure if it is worth it. I would be fine to add No New Tests for this change

[lpcalisi]

I think it doesn't make sense, please could you add the label?