Hi all, I'm using podman-remote and I'm trying to exec commands in containers. It seems it fails, but I don't really understand why. I'm on fedora 30 (with last updates), I tried podman 1.6.1 (from RPMs) but also 1.6.2 compiled from scratch: $ podman version Version: 1.6.2 RemoteAPI Version: 1 Go Version: go1.12.10 OS/Arch: linux/amd64 Ultimately, I'd need to exec commands from a golang program, but for now experimenting with command line is fine, but can't make even this work :) here's what I tried: $ varlink call -m unix:/run/podman/io.podman/io.podman.CreateContainer '{"create":{"args":["fedora:30", "/bin/sleep", "10h"]}}' { "container": "c24e28054f89c0a0ac9c5e3690ab0c5ef5a8b859ed51d032ae38cc618a164853" } $ varlink call -m unix:/run/podman/io.podman/io.podman.StartContainer '{"name":"c24e28054f89c0a0ac9c5e3690ab0c5ef5a8b859ed51d032ae38cc618a1 64853"}' { "container": "c24e28054f89c0a0ac9c5e3690ab0c5ef5a8b859ed51d032ae38cc618a164853" } The container IS running now: root 7836 0.0 0.0 77876 1756 ? Ssl 09:11 0:00 /usr/bin/conmon --api-version 1 -s -c c24e28054f89c0a0ac9c5e3690ab0c5ef5a8b859ed51d032ae38cc618a164853 -u c24e28054f89c0a0ac9c5e3690ab0c5ef5a8b859ed51d032ae38cc618a164853 -r /usr/bin/runc -b /var/lib/containers/storage/overlay-containers/c24e28054f89c0a root 7848 0.0 0.0 2320 684 ? Ss 09:11 0:00 \_ /bin/sleep 10h So I do: $ varlink call -m unix:/run/podman/io.podman/io.podman.ExecContainer '{ "opts": { "name": "c24e28054f89c0a0ac9c5e3690ab0c5ef5a8b859ed51d032ae38cc618a164853", "tty": true, "privileged": true, "cmd": ["/bin/date"] } }' Call failed with error: io.podman.ErrorOccurred { "reason": "client must use upgraded connection to exec" } So I downloaded go-varlink-cmd (https://github.com/varlink/go-varlink-cmd) and patched to supporte the upgraded connection (on client side)[1], but doesn't look much better: $ ~/bin/go-varlink-cmd call -upgrade unix:/run/podman/io.podman/io.podman.ExecContainer '{ "opts": { "name": "c24e28054f89c0a0ac9c5e3690ab0c5ef5a8b859ed51d032ae38cc618a164853", "tty": true, "privileged": true, "cmd": ["/bin/date"] } }' recv -> 0 # return value retval -> map[string]interface {}(nil) # what got as answer {} # answer translated to JSON No luck with minimal command line either: $ ~/bin/go-varlink-cmd call -upgrade unix:/run/podman/io.podman/io.podman.ExecContainer '{ "opts": { "name": "c24e28054f89c0a0ac9c5e3690ab0c5ef5a8b859ed51d032ae38cc618a164853", "cmd": ["/bin/date"] } }' recv -> 0 retval -> map[string]interface {}(nil) {} Maybe, just wondering: do I need to set something when I create the container? If so the docs aren't crystal clear :\ I tried to look at logs but can't make much sense. Here's the logs for podman-remote on my system, with log level increased to debug: Oct 28 09:21:09 myhost.lan systemd[1]: Started Podman Remote API Service. Oct 28 09:21:09 myhost.lan audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=io.podman comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Oct 28 09:21:09 myhost.lan podman[8087]: time="2019-10-28T09:21:09+01:00" level=debug msg="Using varlink socket: unix:/run/podman/io.podman" Oct 28 09:21:09 myhost.lan podman[8087]: time="2019-10-28T09:21:09+01:00" level=debug msg="using conmon: \"/usr/bin/conmon\"" Oct 28 09:21:09 myhost.lan podman[8087]: time="2019-10-28T09:21:09+01:00" level=debug msg="Initializing boltdb state at /var/lib/containers/storage/libpod/bolt_state.db" Oct 28 09:21:09 myhost.lan podman[8087]: time="2019-10-28T09:21:09+01:00" level=debug msg="Using graph driver overlay" Oct 28 09:21:09 myhost.lan podman[8087]: time="2019-10-28T09:21:09+01:00" level=debug msg="Using graph root /var/lib/containers/storage" Oct 28 09:21:09 myhost.lan podman[8087]: time="2019-10-28T09:21:09+01:00" level=debug msg="Using run root /var/run/containers/storage" Oct 28 09:21:09 myhost.lan podman[8087]: time="2019-10-28T09:21:09+01:00" level=debug msg="Using static dir /var/lib/containers/storage/libpod" Oct 28 09:21:09 myhost.lan podman[8087]: time="2019-10-28T09:21:09+01:00" level=debug msg="Using tmp dir /var/run/libpod" Oct 28 09:21:09 myhost.lan podman[8087]: time="2019-10-28T09:21:09+01:00" level=debug msg="Using volume path /var/lib/containers/storage/volumes" Oct 28 09:21:09 myhost.lan podman[8087]: time="2019-10-28T09:21:09+01:00" level=debug msg="Set libpod namespace to \"\"" Oct 28 09:21:09 myhost.lan podman[8087]: time="2019-10-28T09:21:09+01:00" level=debug msg="[graphdriver] trying provided driver \"overlay\"" Oct 28 09:21:09 myhost.lan podman[8087]: time="2019-10-28T09:21:09+01:00" level=debug msg="cached value indicated that overlay is supported" Oct 28 09:21:09 myhost.lan podman[8087]: time="2019-10-28T09:21:09+01:00" level=debug msg="cached value indicated that metacopy is being used" Oct 28 09:21:09 myhost.lan podman[8087]: time="2019-10-28T09:21:09+01:00" level=debug msg="cached value indicated that native-diff is not being used" Oct 28 09:21:09 myhost.lan podman[8087]: time="2019-10-28T09:21:09+01:00" level=warning msg="Not using native diff for overlay, this may cause degraded performance for building images: kernel has CONFIG_OVERLAY_FS_REDIRECT_DIR enabled" Oct 28 09:21:09 myhost.lan podman[8087]: time="2019-10-28T09:21:09+01:00" level=debug msg="backingFs=extfs, projectQuotaSupported=false, useNativeDiff=false, usingMetacopy=true" Oct 28 09:21:09 myhost.lan podman[8087]: time="2019-10-28T09:21:09+01:00" level=debug msg="Initializing event backend journald" Oct 28 09:21:09 myhost.lan podman[8087]: time="2019-10-28T09:21:09+01:00" level=debug msg="using runtime \"/usr/bin/runc\"" Oct 28 09:21:09 myhost.lan podman[8087]: time="2019-10-28T09:21:09+01:00" level=warning msg="Error initializing configured OCI runtime crun: no valid executable found for OCI runtime crun: invalid argument" Oct 28 09:21:09 myhost.lan podman[8087]: time="2019-10-28T09:21:09+01:00" level=info msg="Found CNI network podman (type=bridge) at /etc/cni/net.d/87-podman-bridge.conflist" Oct 28 09:21:09 myhost.lan podman[8087]: time="2019-10-28T09:21:09+01:00" level=debug msg="Creating new exec session in container c24e28054f89c0a0ac9c5e3690ab0c5ef5a8b859ed51d032ae38cc618a164853 with session id 6a1ccdea916ee245420320fa3ce02ff68ea066b8b6b7ba1534c014c15054f67c" Oct 28 09:21:09 myhost.lan podman[8087]: time="2019-10-28T09:21:09+01:00" level=error msg="ExecContainer failed to HANG-UP on c24e28054f89c0a0ac9c5e3690ab0c5ef5a8b859ed51d032ae38cc618a164853: write unix /run/podman/io.podman->@: write: broken pipe" Oct 28 09:21:09 myhost.lan podman[8087]: time="2019-10-28T09:21:09+01:00" level=error msg="Exec Container err: write unix /run/podman/io.podman->@: write: broken pipe" Oct 28 09:21:09 myhost.lan podman[8087]: time="2019-10-28T09:21:09+01:00" level=debug msg="/usr/bin/conmon messages will be logged to syslog" Oct 28 09:21:09 myhost.lan podman[8087]: time="2019-10-28T09:21:09+01:00" level=debug msg="running conmon: /usr/bin/conmon" args="[--api-version 1 -s -c c24e28054f89c0a0ac9c5e3690ab0c5ef5a8b859ed51d032ae38cc618a164853 -u 6a1ccdea916ee245420320fa3ce02ff68ea066b8b6b7ba1534c014c15054f67c -r /usr/bin/runc -b /> Oct 28 09:21:09 myhost.lan podman[8087]: time="2019-10-28T09:21:09+01:00" level=debug msg="disabling SD notify" Oct 28 09:21:09 myhost.lan podman[8087]: time="2019-10-28T09:21:09+01:00" level=info msg="Running conmon under slice machine.slice and unitName libpod-conmon- c24e28054f89c0a0ac9c5e3690ab0c5ef5a8b859ed51d032ae38cc618a164853.scop e" Oct 28 09:21:09 myhost.lan podman[8087]: time="2019-10-28T09:21:09+01:00" level=warning msg="Failed to add conmon to systemd sandbox cgroup: Unit libpod-conmon- c24e28054f89c0a0ac9c5e3690ab0c5ef5a8b859ed51d032ae38cc618a164853.scop e already exists." Oct 28 09:21:09 myhost.lan podman[8087]: time="2019-10-28T09:21:09+01:00" level=debug msg="Attaching to container c24e28054f89c0a0ac9c5e3690ab0c5ef5a8b859ed51d032ae38cc618a164853 exec session 6a1ccdea916ee245420320fa3ce02ff68ea066b8b6b7ba1534c014c15054f67c" Oct 28 09:21:09 myhost.lan podman[8087]: time="2019-10-28T09:21:09+01:00" level=debug msg="connecting to socket /var/run/libpod/socket/6a1ccdea916ee245420320fa3ce02ff68ea066b8b6b7ba 1534c014c15054f67c/attach" Oct 28 09:21:09 myhost.lan conmon[8106]: conmon c24e28054f89c0a0ac9c <ninfo>: addr{sun_family=AF_UNIX, sun_path=/tmp/conmon-term.B2039Z} Oct 28 09:21:09 myhost.lan conmon[8106]: conmon c24e28054f89c0a0ac9c <ninfo>: attach sock path: /var/run/libpod/socket/6a1ccdea916ee245420320fa3ce02ff68ea066b8b6b7ba 1534c014c15054f67c/attach Oct 28 09:21:09 myhost.lan conmon[8106]: conmon c24e28054f89c0a0ac9c <ninfo>: addr{sun_family=AF_UNIX, sun_path=/var/run/libpod/socket/6a1ccdea916ee245420320fa3ce02ff68ea06 6b8b6b7ba1534c014c15054f67c/attach} Oct 28 09:21:09 myhost.lan conmon[8106]: conmon c24e28054f89c0a0ac9c <ninfo>: ctl fifo path: /var/lib/containers/storage/overlay- containers/c24e28054f89c0a0ac9c5e3690ab0c5ef5a8b859ed51d032ae38cc618a 164853/userdata/6a1ccdea916ee245420320fa3ce02ff68ea066b8b6b7ba1534c01 4c15054f67c/ctl Oct 28 09:21:09 myhost.lan conmon[8106]: conmon c24e28054f89c0a0ac9c <ninfo>: terminal_ctrl_fd: 18 Oct 28 09:21:09 myhost.lan conmon[8106]: conmon c24e28054f89c0a0ac9c <ndebug>: sending attach message to parent Oct 28 09:21:09 myhost.lan conmon[8106]: conmon c24e28054f89c0a0ac9c <ndebug>: sent attach message to parent Oct 28 09:21:09 myhost.lan conmon[8108]: conmon c24e28054f89c0a0ac9c <ndebug>: exec with attach is waiting for start message from parent Oct 28 09:21:09 myhost.lan podman[8087]: time="2019-10-28T09:21:09+01:00" level=debug msg="Received: 0" Oct 28 09:21:09 myhost.lan conmon[8106]: conmon c24e28054f89c0a0ac9c <ninfo>: Accepted connection 20 Oct 28 09:21:09 myhost.lan conmon[8108]: conmon c24e28054f89c0a0ac9c <ndebug>: exec with attach got start message from parent Oct 28 09:21:09 myhost.lan conmon[8106]: conmon c24e28054f89c0a0ac9c <ninfo>: about to accept from console_socket_fd: 14 Oct 28 09:21:09 myhost.lan conmon[8106]: conmon c24e28054f89c0a0ac9c <ninfo>: about to recvfd from connfd: 21 Oct 28 09:21:09 myhost.lan conmon[8106]: conmon c24e28054f89c0a0ac9c <ninfo>: console = {.name = '/dev/ptmx8 09:21:09 conmon: conmon c24e28054f89c0a0ac9c <ninfo>: about to recvfd from connfd: 21 '; .fd = 14} Oct 28 09:21:09 myhost.lan systemd[2088]: run-runc- c24e28054f89c0a0ac9c5e3690ab0c5ef5a8b859ed51d032ae38cc618a164853- runc.xJTNZd.mount: Succeeded. Oct 28 09:21:09 myhost.lan conmon[8106]: conmon c24e28054f89c0a0ac9c <ndebug>: couldn't find cb for pid 8121 Oct 28 09:21:09 myhost.lan conmon[8106]: conmon c24e28054f89c0a0ac9c <ndebug>: container status and pid were found prior to callback being registered. calling manually Oct 28 09:21:09 myhost.lan conmon[8106]: conmon c24e28054f89c0a0ac9c <ndebug>: container PID: 8121 Oct 28 09:21:09 myhost.lan conmon[8106]: conmon c24e28054f89c0a0ac9c <nwarn>: Failed to open cgroups file: /proc/8121/cgroup Oct 28 09:21:09 myhost.lan conmon[8106]: conmon c24e28054f89c0a0ac9c <nwarn>: Failed to get memory cgroup path. Container may have exited Oct 28 09:21:09 myhost.lan podman[8087]: time="2019-10-28T09:21:09+01:00" level=debug msg="Received: 8121" Oct 28 09:21:09 myhost.lan conmon[8106]: conmon c24e28054f89c0a0ac9c <nwarn>: stdio_input read failed Input/output error Oct 28 09:21:09 myhost.lan conmon[8106]: conmon c24e28054f89c0a0ac9c <nwarn>: Failed to write to socket Oct 28 09:21:09 myhost.lan conmon[8106]: conmon c24e28054f89c0a0ac9c <error>: Unable to send container stderr message to parent Bad file descriptor Oct 28 09:21:09 myhost.lan podman[8087]: 2019-10-28 09:21:09.632987596 +0100 CET m=+0.247438867 container exec c24e28054f89c0a0ac9c5e3690ab0c5ef5a8b859ed51d032ae38cc618a164853 (image=docker.io/library/fedora:30, name=sad_thompson) Oct 28 09:21:09 myhost.lan podman[8087]: time="2019-10-28T09:21:09+01:00" level=debug msg="Successfully started exec session 6a1ccdea916ee245420320fa3ce02ff68ea066b8b6b7ba1534c014c15054f67c in container c24e28054f89c0a0ac9c5e3690ab0c5ef5a8b859ed51d032ae38cc618a164853" Oct 28 09:21:09 myhost.lan podman[8087]: time="2019-10-28T09:21:09+01:00" level=error msg="write unix /run/podman/io.podman->@: write: broken pipe" I'm out of ideas and can't find anything in the docs - apologies if I missed anything, please feel free to send me there Any help or comment would be appreciated. Thanks and bests! -- Francesco Romani Senior SW Eng., Virtualization R&D Red Hat IRC: fromani github: @fromanirh _______________________________________________ Podman mailing list -- podman(a)lists.podman.io To unsubscribe send an email to podman-leave(a)lists.podman.io

On 10/28/19 3:09 PM, Brent Baude wrote: > I'm glad to see that you are going to implement this in a golang > program. That is how you are going to have to do it. I know of no > other way. Hey, thanks for your reply. Does this means it could be a podman bug? bests,

On 10/28/19 3:23 PM, Brent Baude wrote: > On Mon, 2019-10-28 at 15:19 +0100, Francesco Romani wrote: > > On 10/28/19 3:09 PM, Brent Baude wrote: > > > I'm glad to see that you are going to implement this in a > > > golang > > > program. That is how you are going to have to do it. I know > > > of no > > > other way. > > Hey, > > > > > > thanks for your reply. Does this means it could be a podman bug? > > > > > > bests, > > > I don't believe so. I am unaware of how to use the generic varlink > tools to emulate and upgraded connection. OK, thanks. Any other tips about how I can debug this further?

These entries in the podman syslog (actually journal, but still) look suspicious: Oct 28 09:21:09 myhost.lan conmon[8106]: conmon c24e28054f89c0a0ac9c <nwarn>: stdio_input read failed Input/output error Oct 28 09:21:09 myhost.lan conmon[8106]: conmon c24e28054f89c0a0ac9c <nwarn>: Failed to write to socket Oct 28 09:21:09 myhost.lan conmon[8106]: conmon c24e28054f89c0a0ac9c <error>: Unable to send container stderr message to parent Bad file descriptor Oct 28 09:21:09 myhost.lan podman[8087]: 2019-10-28 09:21:09.632987596 +0100 CET m=+0.247438867 container exec c24e28054f89c0a0ac9c5e3690ab0c5ef5a8b859ed51d032ae38cc618a164853 (image=docker.io/library/fedora:30, name=sad_thompson) Oct 28 09:21:09 myhost.lan podman[8087]: time="2019-10-28T09:21:09+01:00" level=debug msg="Successfully started exec session 6a1ccdea916ee245420320fa3ce02ff68ea066b8b6b7ba1534c014c15054f67c in container c24e28054f89c0a0ac9c5e3690ab0c5ef5a8b859ed51d032ae38cc618a164853" Oct 28 09:21:09 myhost.lan podman[8087]: time="2019-10-28T09:21:09+01:00" level=error msg="write unix /run/podman/io.podman->@: write: broken pipe" My wild guess is that the client somehow exits before the podman on the other side of the varlink could reply. Thanks,