[APIv2] Container log not provided #7196

psakar · 2020-08-03T15:50:18Z

Is this a BUG REPORT or FEATURE REQUEST? (leave only one on its own line)

/kind bug

Description

Container log not provided
Steps to reproduce the issue:

Docker

CLI
docker create --interactive --tty --name busybox docker.io/library/busybox:latest sh -c "echo Hello"
docker start busybox
docker logs busybox
docker inspect busybox > /tmp/test-busybox-docker.txt
docker rm busybox

REST
curl --unix-socket /var/run/docker.sock -X POST -H "Content-Type: application/json" 'http://127.0.0.1:8880/containers/create?name=busybox' --data '{"name":"busybox2","Image":"docker.io/library/busybox:latest", "Tty":true, "Cmd":["sh", "-c", "echo Hello"]}'
curl --unix-socket /var/run/docker.sock -X POST -H "Content-Type: application/json" 'http://127.0.0.1:8880/containers/busybox/start'
curl --unix-socket /var/run/docker.sock --output - -H "Content-Type: application/json" "http://127.0.0.1:8880/containers/busybox/logs?stdout=true&stderr=true"
docker logs busybox
docker inspect busybox > /tmp/test-busybox-docker-api.txt
curl --unix-socket /var/run/docker.sock -X DELETE -H "Content-Type: application/json" 'http://127.0.0.1:8880/containers/busybox'

Podman

podman --log-level=debug system service -t 0 tcp:localhost:8880 2>&1>/tmp/podman-rest.log &

CLI
podman create --interactive --tty --name busybox docker.io/library/busybox:latest sh -c "echo Hello"
podman start busybox
podman logs busybox
podman inspect busybox > /tmp/test-busybox-podman.txt
podman rm busybox

REST
curl -X POST -H "Content-Type: application/json" 'http://127.0.0.1:8880/containers/create?name=busybox' --data '{"name":"busybox2","Image":"docker.io/library/busybox:latest", "Tty":true, "Cmd":["sh", "-c", "echo Hello"]}'
curl -X POST -H "Content-Type: application/json" 'http://127.0.0.1:8880/containers/busybox/start'
curl --output - -H "Content-Type: application/json" "http://127.0.0.1:8880/containers/busybox/logs?stdout=true&stderr=true"
podman logs busybox
podman inspect busybox > /tmp/test-busybox-podman-api.txt
curl -X DELETE -H "Content-Type: application/json" 'http://127.0.0.1:8880/containers/busybox'

Describe the results you received:

curl --unix-socket /var/run/docker.sock --output - -H "Content-Type: application/json" "http://127.0.0.1:8880/containers/busybox/logs?stdout=true&stderr=true"

returns Hello

curl --output - -H "Content-Type: application/json" "http://127.0.0.1:8880/containers/busybox/logs?stdout=true&stderr=true"

returns nothing

podman logs busybox

returns Hello

Describe the results you expected:

All three commands above should return Hello

Additional information you deem important (e.g. issue happens only occasionally):

Output of podman version:

Version:      2.0.3
API Version:  1
Go Version:   go1.13.11
Built:        Thu Jan  1 01:00:00 1970
OS/Arch:      linux/amd64

Output of podman info --debug:

host:
  arch: amd64
  buildahVersion: 1.15.0
  cgroupVersion: v2
  conmon:
    package: conmon-2.0.19-1.fc31.x86_64
    path: /usr/libexec/crio/conmon
    version: 'conmon version 2.0.19, commit: ed806cf10f2791e13a8cb3ca3552cd1e9fa996e4'
  cpus: 8
  distribution:
    distribution: fedora
    version: "31"
  eventLogger: file
  hostname: localhost.localdomain
  idMappings:
    gidmap:
    - container_id: 0
      host_id: 21528
      size: 1
    - container_id: 1
      host_id: 100000
      size: 65536
    uidmap:
    - container_id: 0
      host_id: 21528
      size: 1
    - container_id: 1
      host_id: 100000
      size: 65536
  kernel: 5.7.9-100.fc31.x86_64
  linkmode: dynamic
  memFree: 4429897728
  memTotal: 16381521920
  ociRuntime:
    name: crun
    package: crun-0.14.1-1.fc31.x86_64
    path: /usr/bin/crun
    version: |-
      crun version 0.14.1
      commit: 598ea5e192ca12d4f6378217d3ab1415efeddefa
      spec: 1.0.0
      +SYSTEMD +SELINUX +APPARMOR +CAP +SECCOMP +EBPF +YAJL
  os: linux
  remoteSocket:
    path: /run/user/21528/podman/podman.sock
  rootless: true
  slirp4netns:
    executable: /bin/slirp4netns
    package: slirp4netns-1.1.4-1.fc31.x86_64
    version: |-
      slirp4netns version 1.1.4
      commit: b66ffa8e262507e37fca689822d23430f3357fe8
      libslirp: 4.1.0
      SLIRP_CONFIG_VERSION_MAX: 1
  swapFree: 8252289024
  swapTotal: 8252289024
  uptime: 7h 51m 24.75s (Approximately 0.29 days)
registries:
  search:
  - registry.fedoraproject.org
  - registry.access.redhat.com
  - registry.centos.org
  - docker.io
store:
  configFile: /home/psakar/.config/containers/storage.conf
  containerStore:
    number: 4
    paused: 0
    running: 0
    stopped: 4
  graphDriverName: vfs
  graphOptions: {}
  graphRoot: /home/psakar/.local/share/containers/storage
  graphStatus: {}
  imageStore:
    number: 65
  runRoot: /run/user/21528/run
  volumePath: /home/psakar/.local/share/containers/storage/volumes
version:
  APIVersion: 1
  Built: 0
  BuiltTime: Thu Jan  1 01:00:00 1970
  GitCommit: ""
  GoVersion: go1.13.11
  OsArch: linux/amd64
  Version: 2.0.3

Package info (e.g. output of rpm -q podman or apt list podman):

podman-2.0.3-1.fc31.x86_64

Additional environment details (AWS, VirtualBox, physical, etc.):
physical

The text was updated successfully, but these errors were encountered:

rhatdan · 2020-08-04T13:03:13Z

@ashley-cui PTAL

zhangguanzhang · 2020-08-04T16:17:08Z

https://github.com/containers/podman/blob/master/pkg/api/handlers/compat/containers_logs.go#L139
problem is in this line, but I cannot find why, if I enabled time, It will be this:

root@develop:~# curl -o - "http://127.0.0.1:8080/containers/busybox/logs?stdout=true&stderr=true&timestamps=true" 
root@develop:~# 4:30+08:00 Hello

psakar · 2020-08-04T16:52:45Z

timestamps does not make any difference in my case, output is empty ( no matter whether rootless or rootfull )

zhangguanzhang · 2020-08-05T06:55:33Z

I found the reason,

[root@sz-test ~]# podman run --rm  alpine echo 1 | cat -A
1$
[root@sz-test ~]# podman run --rm --tty alpine echo 1 | cat -A
1^M$
    [root@sz-test ~]#

build with -gcflags 'all=-trimpath=/root/zgz/podman -N -l' and use dlv to debug it

[root@sz-test ~]# dlv exec ./bin/podman -- run --tty  docker.io/zhangguanzhang/alpine sh -c 'echo hello'
Type 'help' for list of commands.
(dlv) b main.main
Breakpoint 1 set at 0x1ed0a8b for main.main() cmd/podman/main.go:26
(dlv) b libpod/container_api.go:132
Breakpoint 2 set at 0x19da4f0 for github.com/containers/podman/v2/libpod.(*Container).StartAndAttach() libpod/container_api.go:132
(dlv) b libpod/oci_conmon_linux.go:377
Breakpoint 3 set at 0x1a7a9e4 for github.com/containers/podman/v2/libpod.(*ConmonOCIRuntime).StartContainer() libpod/oci_conmon_linux.go:377
(dlv) c
> main.main() cmd/podman/main.go:26 (hits goroutine(1):1 total:1) (PC: 0x1ed0a8b)
    21:		"github.com/containers/storage/pkg/reexec"
    22:		"github.com/sirupsen/logrus"
    23:		"github.com/spf13/cobra"
    24:	)
    25:	
=>  26:	func main() {
    27:		if reexec.Init() {
    28:			// We were invoked with a different argv[0] indicating that we
    29:			// had a specific job to do as a subprocess, and it's done.
    30:			return
    31:		}
(dlv) c
> github.com/containers/podman/v2/libpod.(*Container).StartAndAttach() libpod/container_api.go:132 (hits goroutine(1):1 total:1) (PC: 0x19da4f0)
   127:		}
   128:		attachChan := make(chan error)
   129:	
   130:		// We need to ensure that we don't return until start() fired in attach.
   131:		// Use a channel to sync
=> 132:		startedChan := make(chan bool)
   133:	
   134:		// Attach to the container before starting it
   135:		go func() {
   136:			if err := c.attach(streams, keys, resize, true, startedChan); err != nil {
   137:				attachChan <- err
(dlv) c
> github.com/containers/podman/v2/libpod.(*ConmonOCIRuntime).StartContainer() libpod/oci_conmon_linux.go:377 (hits goroutine(82):1 total:1) (PC: 0x1a7abbc)
   372:			}
   373:		}
   374:		if path, ok := os.LookupEnv("PATH"); ok {
   375:			env = append(env, fmt.Sprintf("PATH=%s", path))
   376:		}
=> 377:		if err := utils.ExecCmdWithStdStreams(os.Stdin, os.Stdout, os.Stderr, env, r.path, "start", ctr.ID()); err != nil {
   378:			return err
   379:		}
   380:	
   381:		ctr.state.StartedTime = time.Now()
   382:	
(dlv) s
> github.com/containers/podman/v2/libpod.(*Container).ID() libpod/container.go:287 (PC: 0x19d17f0)
   282:	
   283:		return returnSpec, nil
   284:	}
   285:	
   286:	// ID returns the container's ID
=> 287:	func (c *Container) ID() string {
   288:		return c.config.ID
   289:	}
   290:	
   291:	// Name returns the container's name
   292:	func (c *Container) Name() string {
(dlv) s
> github.com/containers/podman/v2/libpod.(*Container).ID() libpod/container.go:288 (PC: 0x19d17f8)
   283:		return returnSpec, nil
   284:	}
   285:	
   286:	// ID returns the container's ID
   287:	func (c *Container) ID() string {
=> 288:		return c.config.ID
   289:	}
   290:	
   291:	// Name returns the container's name
   292:	func (c *Container) Name() string {
   293:		return c.config.Name
(dlv) so
> github.com/containers/podman/v2/libpod.(*ConmonOCIRuntime).StartContainer() libpod/oci_conmon_linux.go:377 (PC: 0x1a7abcd)
Values returned:
	~r0: "62189eb5a343e7d14e90df0f5a6d03a00fae3120fccc097ac4a5f3d47cbb9689"

   372:			}
   373:		}
   374:		if path, ok := os.LookupEnv("PATH"); ok {
   375:			env = append(env, fmt.Sprintf("PATH=%s", path))
   376:		}
=> 377:		if err := utils.ExecCmdWithStdStreams(os.Stdin, os.Stdout, os.Stderr, env, r.path, "start", ctr.ID()); err != nil {
   378:			return err
   379:		}
   380:	
   381:		ctr.state.StartedTime = time.Now()
   382:

now get the container's ID, open another terminal. and run this

[root@sz-test podman]# cd /var/lib/containers/storage/overlay-containers/
[root@sz-test overlay-containers]# ll 62189eb5a343e7d14e90df0f5a6d03a00fae3120fccc097ac4a5f3d47cbb9689
total 0
drwx------ 4 root root 106 Aug  5 13:33 userdata
[root@sz-test overlay-containers]# ll 62189eb5a343e7d14e90df0f5a6d03a00fae3120fccc097ac4a5f3d47cbb9689/
total 0
drwx------ 4 root root 106 Aug  5 13:33 userdata
[root@sz-test overlay-containers]# ll 62189eb5a343e7d14e90df0f5a6d03a00fae3120fccc097ac4a5f3d47cbb9689/userdata/
total 12
drwxr-xr-x 2 root root    6 Aug  5 13:33 artifacts
srwx------ 1 root root    0 Aug  5 13:33 attach
-rw-r--r-- 1 root root 9315 Aug  5 13:33 config.json
prw-r--r-- 1 root root    0 Aug  5 13:33 ctl
-rw------- 1 root root    0 Aug  5 13:33 ctr.log
drwxrwxrwt 2 root root   40 Aug  5 13:33 shm
prw-r--r-- 1 root root    0 Aug  5 13:33 winsz
[root@sz-test overlay-containers]# ll 62189eb5a343e7d14e90df0f5a6d03a00fae3120fccc097ac4a5f3d47cbb9689/userdata/ctr.log 
-rw------- 1 root root 0 Aug  5 13:33 62189eb5a343e7d14e90df0f5a6d03a00fae3120fccc097ac4a5f3d47cbb9689/userdata/ctr.log
[root@sz-test overlay-containers]# cat 62189eb5a343e7d14e90df0f5a6d03a00fae3120fccc097ac4a5f3d47cbb9689/userdata/ctr.log
[root@sz-test overlay-containers]# runc start 62189eb5a343e7d14e90df0f5a6d03a00fae3120fccc097ac4a5f3d47cbb9689
[root@sz-test overlay-containers]# cat 62189eb5a343e7d14e90df0f5a6d03a00fae3120fccc097ac4a5f3d47cbb9689/userdata/ctr.log
2020-08-05T13:34:22.891045849+08:00 stdout F hello
[root@sz-test overlay-containers]# cat -A 62189eb5a343e7d14e90df0f5a6d03a00fae3120fccc097ac4a5f3d47cbb9689/userdata/ctr.log
2020-08-05T13:34:22.891045849+08:00 stdout F hello^M$

You can see that there is a problem with the log-writing logic.

and I update runc, it still exsit. and I can't find where the code was written to the log file

[root@sz-test overlay-containers]# rpm -qa | grep runc
runc-1.0.0-64.rc9.module_el8.1.0+298+41f9343a.x86_64
[root@sz-test overlay-containers]# yum install -y runc
CentOS-8 - AppStream                                                                                                                                                                                        548 kB/s | 4.3 kB     00:00    
CentOS-8 - Base                                                                                                                                                                                             647 kB/s | 3.9 kB     00:00    
CentOS-8 - Extras                                                                                                                                                                                           214 kB/s | 1.5 kB     00:00    
Extra Packages for Enterprise Linux 8 - x86_64                                                                                                                                                              725 kB/s | 4.7 kB     00:00    
Copr repo for container-selinux owned by rhcontainerbot                                                                                                                                                     1.0 kB/s | 3.3 kB     00:03    
Stable Releases of Upstream github.com/containers packages (CentOS_8)                                                                                                                                       1.8 kB/s | 1.7 kB     00:00    
Package runc-1.0.0-64.rc9.module_el8.1.0+298+41f9343a.x86_64 is already installed.
Dependencies resolved.
============================================================================================================================================================================================================================================
 Package                                    Architecture                                 Version                                                               Repository                                                              Size
============================================================================================================================================================================================================================================
Upgrading:
 runc                                       x86_64                                       2:1.0.0-145.rc91.git24a3cf8.el8                                       devel_kubic_libcontainers_stable                                       5.8 M

@QiWang19 @mheon @giuseppe PTAL

psakar · 2020-08-05T07:17:30Z

Leaving aside other issues this line is probably wrong https://github.com/containers/podman/blob/master/pkg/api/handlers/compat/containers_logs.go#L88
I think options.Timestamps for log reading should be always true (given the log has fixed format) ?

zhangguanzhang · 2020-08-05T07:31:02Z

The source of the error is not here, and the log source returned by the API is also read from the container log file

psakar · 2020-08-05T09:32:28Z

@zhangguanzhang One more question - according to docker api doc https://docs.docker.com/engine/api/v1.40/#operation/ContainerAttach

when the TTY setting is enabled in POST /containers/create, the stream is not multiplexed. The data exchanged over the hijacked connection is simply the raw data from the process PTY and client's stdin

Given that should be the output header written always ? https://github.com/containers/podman/blob/master/pkg/api/handlers/compat/containers_logs.go#L141

zhangguanzhang · 2020-08-05T09:38:41Z

problem is not in the api handler,you could see this

root@develop:~# curl -o - "http://127.0.0.1:8080/containers/busybox/logs?stdout=true&stderr=true&timestamps=true" 
root@develop:~# 4:30+08:00 Hello

and this

[root@sz-test ~]# podman run --rm  alpine echo 1 | cat -A
1$
[root@sz-test ~]# podman run --rm --tty alpine echo 1 | cat -A
1^M$
    [root@sz-test ~]#

enabled --tty on causes some invisible characters and ^M

psakar · 2020-08-05T09:48:35Z

Are you sure ? I think that in case tty is enabled then the downloaded log should not contain the output header - those "invisible characters" as you call them

mheon · 2020-08-05T12:52:56Z

The logs are written by Conmon - https://github.com/containers/conmon/

ashley-cui · 2020-09-02T21:33:34Z

@zhangguanzhang looks like you were right on this issue, seems to be libpod not reading log lines correctly. Thanks for pointing it out, but it's strange since it affects the remote api but not the cli in outputting the log. if you have any ideas, let me know

zhangguanzhang · 2020-09-03T14:47:47Z

@zhangguanzhang looks like you were right on this issue, seems to be libpod not reading log lines correctly. Thanks for pointing it out, but it's strange since it affects the remote api but not the cli in outputting the log. if you have any ideas, let me know

Up to now, I have not found any clues about the occurrence of the problem

openshift-ci-robot added the kind/bug Categorizes issue or PR as related to a bug. label Aug 3, 2020

mheon added the HTTP API Bug is in RESTful API label Aug 3, 2020

psakar mentioned this issue Aug 3, 2020

Podman support testcontainers/testcontainers-java#2088

Closed

rhatdan assigned ashley-cui Aug 4, 2020

zhangguanzhang mentioned this issue Aug 5, 2020

There will be extra characters when podman run with --tty containers/conmon#195

Closed

ashley-cui mentioned this issue Sep 1, 2020

Fix remote api logs #7522

Closed

ashley-cui mentioned this issue Sep 16, 2020

Fix remote logs #7660

Merged

openshift-merge-robot closed this as completed in #7660 Sep 18, 2020

zhangguanzhang mentioned this issue Oct 7, 2020

podman run -t issues CRLF, making for confusing 'podman logs' output #7942

Closed

github-actions bot added the locked - please file new issue/PR Assist humans wanting to comment on an old issue or PR with locked comments. label Sep 22, 2023

github-actions bot locked as resolved and limited conversation to collaborators Sep 22, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[APIv2] Container log not provided #7196

[APIv2] Container log not provided #7196

psakar commented Aug 3, 2020

rhatdan commented Aug 4, 2020

zhangguanzhang commented Aug 4, 2020

psakar commented Aug 4, 2020

zhangguanzhang commented Aug 5, 2020

psakar commented Aug 5, 2020

zhangguanzhang commented Aug 5, 2020

psakar commented Aug 5, 2020

zhangguanzhang commented Aug 5, 2020 •

edited

Loading

psakar commented Aug 5, 2020 •

edited

Loading

mheon commented Aug 5, 2020

ashley-cui commented Sep 2, 2020

zhangguanzhang commented Sep 3, 2020

[APIv2] Container log not provided #7196

[APIv2] Container log not provided #7196

Comments

psakar commented Aug 3, 2020

rhatdan commented Aug 4, 2020

zhangguanzhang commented Aug 4, 2020

psakar commented Aug 4, 2020

zhangguanzhang commented Aug 5, 2020

psakar commented Aug 5, 2020

zhangguanzhang commented Aug 5, 2020

psakar commented Aug 5, 2020

zhangguanzhang commented Aug 5, 2020 • edited Loading

psakar commented Aug 5, 2020 • edited Loading

mheon commented Aug 5, 2020

ashley-cui commented Sep 2, 2020

zhangguanzhang commented Sep 3, 2020

zhangguanzhang commented Aug 5, 2020 •

edited

Loading

psakar commented Aug 5, 2020 •

edited

Loading