Sporadic resize tty warnings when running containers with podman 3.0 #9172

afbjorklund · 2021-01-31T18:34:44Z

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

/kind bug

Description

Sporadic error output, when running containers.

Steps to reproduce the issue:

podman-remote run -it busybox true

Describe the results you received:

WARN[0000] failed to resize TTY: <nil>

Describe the results you expected:

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

Only happens occasionally. Seems to be a race between running and resizing ?

Didn't see this with podman2.

Note that the original error is wrong, due to dumping the wrong error variable.

 			if resizeErr != nil {
-				logrus.Warnf("failed to resize TTY: %v", err)
+				logrus.Warnf("failed to resize TTY: %v", resizeErr)
 			}

The real error is:

WARN[0000] failed to resize TTY: container "909607af8e848d82382b7d9a08e53d28c326d16e0229d62bdb9b3cfe5d7fb188" in wrong state "created"

Output of podman version:

3.0.0-rc2

Output of podman info --debug:

(paste your output here)

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

(paste your output here)

Have you tested with the latest version of Podman and have you checked the Podman Troubleshooting Guide?

Yes

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

Ubuntu

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

afbjorklund · 2021-01-31T18:49:41Z

Happy path:

INFO[0002] APIHandler(f57fd346-dae1-4f09-821b-bc21d57202f6) -- POST /v2.0.0/libpod/containers/121b5f7292580358a59596d308e0840c2ad05bd5b03e754bfbde8b3810683385/start?detachkeys=ctrl-p%2Cctrl-q BEGIN 
DEBU[0002] APIHandler(f57fd346-dae1-4f09-821b-bc21d57202f6) -- Header: User-Agent=[Go-http-client/1.1] 
DEBU[0002] APIHandler(f57fd346-dae1-4f09-821b-bc21d57202f6) -- Header: Content-Length=[0] 
DEBU[0002] APIHandler(f57fd346-dae1-4f09-821b-bc21d57202f6) -- Header: Accept-Encoding=[gzip] 
INFO[0002] APIHandler(786b3aec-5570-4a43-b819-ca4ebf7b7971) -- POST /v2.0.0/libpod/containers/121b5f7292580358a59596d308e0840c2ad05bd5b03e754bfbde8b3810683385/resize?h=169&w=36 BEGIN 
DEBU[0002] APIHandler(786b3aec-5570-4a43-b819-ca4ebf7b7971) -- Header: User-Agent=[Go-http-client/1.1] 
DEBU[0002] APIHandler(786b3aec-5570-4a43-b819-ca4ebf7b7971) -- Header: Content-Length=[0] 
INFO[0002] the detach keys parameter is not supported on start container 
DEBU[0002] APIHandler(786b3aec-5570-4a43-b819-ca4ebf7b7971) -- Header: Accept-Encoding=[gzip] 
DEBU[0002] Created root filesystem for container 121b5f7292580358a59596d308e0840c2ad05bd5b03e754bfbde8b3810683385 at /home/anders/.local/share/containers/storage/overlay/a869d5628c90b36bc8e0f708bb8cd410776a6e760141ea5de82cd769293c2bea/merged 
DEBU[0002] Workdir "/" resolved to host path "/home/anders/.local/share/containers/storage/overlay/a869d5628c90b36bc8e0f708bb8cd410776a6e760141ea5de82cd769293c2bea/merged" 
DEBU[0002] Starting container 121b5f7292580358a59596d308e0840c2ad05bd5b03e754bfbde8b3810683385 with command [true] 
DEBU[0002] Started container 121b5f7292580358a59596d308e0840c2ad05bd5b03e754bfbde8b3810683385 
DEBU[0002] APIHandler(f57fd346-dae1-4f09-821b-bc21d57202f6) -- POST /v2.0.0/libpod/containers/121b5f7292580358a59596d308e0840c2ad05bd5b03e754bfbde8b3810683385/start?detachkeys=ctrl-p%2Cctrl-q END 
DEBU[0002] IdleTracker 0xc0000120c0:idle 4m+1h/5t connection(s) 
INFO[0002] Resizing TTY of container 121b5f7292580358a59596d308e0840c2ad05bd5b03e754bfbde8b3810683385 
DEBU[0002] Received a resize event for container 121b5f7292580358a59596d308e0840c2ad05bd5b03e754bfbde8b3810683385: {Width:36 Height:169} 
DEBU[0002] APIHandler(786b3aec-5570-4a43-b819-ca4ebf7b7971) -- POST /v2.0.0/libpod/containers/121b5f7292580358a59596d308e0840c2ad05bd5b03e754bfbde8b3810683385/resize?h=169&w=36 END

Sad path:

INFO[0007] APIHandler(dd161c8e-b71e-49ea-96ee-acd92b515359) -- POST /v2.0.0/libpod/containers/7e2fe699bc907a0a9545de1873bd7670202718c8d9b86b4afe60510818985150/start?detachkeys=ctrl-p%2Cctrl-q BEGIN 
INFO[0007] APIHandler(ab5d15b7-bf16-47bf-b1c8-499030be8b0f) -- POST /v2.0.0/libpod/containers/7e2fe699bc907a0a9545de1873bd7670202718c8d9b86b4afe60510818985150/resize?h=169&w=36 BEGIN 
DEBU[0007] APIHandler(dd161c8e-b71e-49ea-96ee-acd92b515359) -- Header: User-Agent=[Go-http-client/1.1] 
DEBU[0007] APIHandler(ab5d15b7-bf16-47bf-b1c8-499030be8b0f) -- Header: User-Agent=[Go-http-client/1.1] 
DEBU[0007] APIHandler(dd161c8e-b71e-49ea-96ee-acd92b515359) -- Header: Content-Length=[0] 
DEBU[0007] APIHandler(ab5d15b7-bf16-47bf-b1c8-499030be8b0f) -- Header: Content-Length=[0] 
DEBU[0007] APIHandler(dd161c8e-b71e-49ea-96ee-acd92b515359) -- Header: Accept-Encoding=[gzip] 
DEBU[0007] APIHandler(ab5d15b7-bf16-47bf-b1c8-499030be8b0f) -- Header: Accept-Encoding=[gzip] 
INFO[0007] the detach keys parameter is not supported on start container 
INFO[0007] Request Failed(Conflict): container "7e2fe699bc907a0a9545de1873bd7670202718c8d9b86b4afe60510818985150" in wrong state "created" 
DEBU[0007] APIHandler(ab5d15b7-bf16-47bf-b1c8-499030be8b0f) -- POST /v2.0.0/libpod/containers/7e2fe699bc907a0a9545de1873bd7670202718c8d9b86b4afe60510818985150/resize?h=169&w=36 END 
DEBU[0007] IdleTracker 0xc000010270:idle 4m+1h/10t connection(s) 
DEBU[0007] Created root filesystem for container 7e2fe699bc907a0a9545de1873bd7670202718c8d9b86b4afe60510818985150 at /home/anders/.local/share/containers/storage/overlay/a7cb615f3c205afd1cff580fb9352f6285d38a574fead7092d2b4a4f10a8b683/merged 
DEBU[0007] Workdir "/" resolved to host path "/home/anders/.local/share/containers/storage/overlay/a7cb615f3c205afd1cff580fb9352f6285d38a574fead7092d2b4a4f10a8b683/merged" 
DEBU[0007] Starting container 7e2fe699bc907a0a9545de1873bd7670202718c8d9b86b4afe60510818985150 with command [true] 
DEBU[0007] Started container 7e2fe699bc907a0a9545de1873bd7670202718c8d9b86b4afe60510818985150 
DEBU[0007] APIHandler(dd161c8e-b71e-49ea-96ee-acd92b515359) -- POST /v2.0.0/libpod/containers/7e2fe699bc907a0a9545de1873bd7670202718c8d9b86b4afe60510818985150/start?detachkeys=ctrl-p%2Cctrl-q END

vrothberg · 2021-02-03T13:40:38Z

Opened #9217 to address the warning, thanks @afbjorklund !

afbjorklund · 2021-02-03T16:59:29Z

No worries, hope that you can get it fixed before the release.

$ podman3-remote run --rm -it busybox true
$ podman3-remote run --rm -it busybox true
$ podman3-remote run --rm -it busybox true
WARN[0000] failed to resize TTY: <nil>                  
$ podman3-remote run --rm -it busybox true
$ podman3-remote run --rm -it busybox true
WARN[0000] failed to resize TTY: <nil>                  
$ podman3-remote run --rm -it busybox true
$ podman3-remote run --rm -it busybox true
$ podman3-remote run --rm -it busybox true
$ podman3-remote run --rm -it busybox true

afbjorklund · 2021-02-03T17:13:18Z

I think @vrothberg accidentally said the magic word (as in: does not fix)

/reopen

openshift-ci-robot · 2021-02-03T17:14:20Z

@afbjorklund: Reopened this issue.

In response to this:

I think @vrothberg accidentally said the magic word (as in: does not fix)

/reopen

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository.

rhatdan · 2021-02-04T20:01:30Z

@afbjorklund Could you try again against the main branch? To see if we get more info.

The resize warning logged the wrong error. While this does not fix containers#9172, it may very well be helpful finding its root cause. [NO TESTS NEEDED] Signed-off-by: Valentin Rothberg <[email protected]>

afbjorklund · 2021-02-05T06:38:33Z

Yes, now the error looks much "better" now on podman master (b1bd126):

$ ./bin/podman-remote run --rm -it busybox true
WARN[0000] failed to resize TTY: container "a1e1c4631e8a113221559ca0e851c210c2a36724f7ca2fe087d5f866701f09fe" in wrong state "created" 
$ ./bin/podman-remote run --rm -it busybox true
$ ./bin/podman-remote run --rm -it busybox true
$ ./bin/podman-remote run --rm -it busybox true
WARN[0000] failed to resize TTY: container "e5df1faf8c5e6e52ac49a2a52a582c9e803e5ccc98961c601a320b3875d7ca29" in wrong state "created" 
$ ./bin/podman-remote run --rm -it busybox true
WARN[0000] failed to resize TTY: container "dcc7b50dc95cd9f6f1daf462fb7f432312a1f431e644d41e76b902ce41a481db" in wrong state "created" 
$ ./bin/podman-remote run --rm -it busybox true
WARN[0000] failed to resize TTY: container "4ab79eb9dddaa8573f48da894e061fbc66ff994b70879aaf60b2ae5dea062c38" in wrong state "created" 
$ ./bin/podman-remote run --rm -it busybox true
WARN[0000] failed to resize TTY: container "f763a9d4d8a5de8a23e757992222b667823316acd169f081681efdc5e87db3ee" in wrong state "created" 
$ ./bin/podman-remote run --rm -it busybox true
WARN[0000] failed to resize TTY: container "33037fe9106776da9225fb523eee71d3578976fd2128fda029789f97c9fed8a4" in wrong state "created" 
$ ./bin/podman-remote run --rm -it busybox true
$ ./bin/podman-remote run --rm -it busybox true

Just running towards a local server, so shouldn't be about network issues.

./bin/podman system service --timeout=0

vrothberg · 2021-02-05T09:45:31Z

Thanks for checking, @afbjorklund!

This smells like a race in the remote client. Resizing a "stopped" container won't work :)

afbjorklund · 2021-02-05T10:14:11Z

Reliving old Docker bugs... It used to ignore WINCH signals, had to run resize in shell

pineman · 2021-02-28T13:40:03Z

Also experiencing this almost 100% of the times, not always.
WARN[0000] failed to resize TTY: container "7009d9ec2c6202ad63b5118b8362df149e3943e1963f3257ef904da22d929863" in wrong state "created"

podman version 3.0.1
on macos and podman running in a VM

vrothberg · 2021-03-01T07:08:15Z

@jwhonce @mheon PTAL

rhatdan · 2021-03-01T17:48:19Z

Should we just drop this down in lever from WARN, if the user can not do something about it, and we don't feel that it is an error, then we should not Warn the user.

afbjorklund · 2021-03-01T18:40:45Z

I'm not sure it has any major user impact, but there is a race somewhere in the startup.

$ podman-remote run -it fedora stty size
140 42
$ podman-remote run -it fedora stty size
140 42
$ podman-remote run -it fedora stty size
140 42
$ podman-remote run -it fedora stty size
WARN[0000] failed to resize TTY: container "92a332cce3ac39307e6fd74cc6f26fadaa6ee63d211967c542e04e0b343909cb" in wrong state "created" 
0 0
$ podman-remote run -it fedora stty size
140 42
$ podman-remote run -it fedora stty size
140 42
$ podman-remote run -it fedora stty size
140 42

mheon · 2021-03-01T20:05:53Z

Yes - this is a real bug. If the warning fires, we have a bad TTY size set.

oblutak · 2021-03-18T18:37:23Z

Not directly related to the sporadic error reported here, but I am new to container and first time using podman client and people seems to know a lot on tty related things in this discurrion. To me, it looks like row/columns is inverted on the podman client. i.e. using podman client, in the container, stty size reports 364 17, but if I ssh to the remote host and use the local podman, stty size reports 17 364.

which might explains the weird line wrapping I am seeing on first try of podman client.

mheon · 2021-03-18T19:02:57Z

Can you open a separate issue for that? It sounds properly strange.

oblutak · 2021-03-18T19:31:35Z

Ok. Opened #9756

afbjorklund · 2021-03-19T07:04:12Z

I didn't even look at the numbers, to see that they were actually flipped :-D

* size print the number of rows and columns according to the kernel

Just compared them with 0 0

rhatdan · 2021-03-23T19:02:16Z

Did someone open a PR to fix this?

afbjorklund · 2021-03-23T20:56:57Z

It seems to still be there with v3.1.0-rc2, like 33% of the time or so.

github-actions · 2021-04-23T00:07:15Z

A friendly reminder that this issue had no activity for 30 days.

rhatdan · 2021-04-23T11:52:11Z

@afbjorklund Could you check if we still have this issue?

rhatdan · 2021-04-23T11:58:28Z

The WARNING no longer shows up, but the issue still happens sporatically.

for i in {1..100}; do podman-remote run -it fedora stty size; done
24 80
24 80
24 80
24 80
24 80
24 80
24 80
24 80
24 80
24 80
24 80
24 80
24 80
24 80
24 80
24 80
24 80
0 0
24 80
24 80
...

github-actions · 2021-05-24T00:05:10Z

A friendly reminder that this issue had no activity for 30 days.

rhatdan · 2021-05-24T13:41:41Z

I just ran over 300 tests and can not get this to happen with current main branch so I am going to close.

openshift-ci-robot added the kind/bug Categorizes issue or PR as related to a bug. label Jan 31, 2021

afbjorklund changed the title ~~Sporadic warnings when running containers with podman 3.0~~ Sporadic resize tty warnings when running containers with podman 3.0 Jan 31, 2021

vrothberg mentioned this issue Feb 3, 2021

bindings: attach: warn correct error #9217

Merged

edsantiago assigned jwhonce Feb 3, 2021

openshift-merge-robot closed this as completed in bc149a4 Feb 3, 2021

openshift-ci-robot reopened this Feb 3, 2021

afbjorklund mentioned this issue Mar 22, 2021

podman resizes content wrongly in terminal #9780

Closed

github-actions bot added the stale-issue label Apr 23, 2021

rhatdan removed the stale-issue label Apr 23, 2021

github-actions bot added the stale-issue label May 24, 2021

rhatdan closed this as completed May 24, 2021

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 21, 2023

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

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Sporadic resize tty warnings when running containers with podman 3.0 #9172

Sporadic resize tty warnings when running containers with podman 3.0 #9172

afbjorklund commented Jan 31, 2021 •

edited

Loading

afbjorklund commented Jan 31, 2021

vrothberg commented Feb 3, 2021

afbjorklund commented Feb 3, 2021

afbjorklund commented Feb 3, 2021

openshift-ci-robot commented Feb 3, 2021

rhatdan commented Feb 4, 2021

afbjorklund commented Feb 5, 2021

vrothberg commented Feb 5, 2021

afbjorklund commented Feb 5, 2021

pineman commented Feb 28, 2021 •

edited

Loading

vrothberg commented Mar 1, 2021

rhatdan commented Mar 1, 2021

afbjorklund commented Mar 1, 2021

mheon commented Mar 1, 2021

oblutak commented Mar 18, 2021

mheon commented Mar 18, 2021

oblutak commented Mar 18, 2021

afbjorklund commented Mar 19, 2021

rhatdan commented Mar 23, 2021

afbjorklund commented Mar 23, 2021

github-actions bot commented Apr 23, 2021

rhatdan commented Apr 23, 2021

rhatdan commented Apr 23, 2021

github-actions bot commented May 24, 2021

rhatdan commented May 24, 2021

Sporadic resize tty warnings when running containers with podman 3.0 #9172

Sporadic resize tty warnings when running containers with podman 3.0 #9172

Comments

afbjorklund commented Jan 31, 2021 • edited Loading

afbjorklund commented Jan 31, 2021

vrothberg commented Feb 3, 2021

afbjorklund commented Feb 3, 2021

afbjorklund commented Feb 3, 2021

openshift-ci-robot commented Feb 3, 2021

rhatdan commented Feb 4, 2021

afbjorklund commented Feb 5, 2021

vrothberg commented Feb 5, 2021

afbjorklund commented Feb 5, 2021

pineman commented Feb 28, 2021 • edited Loading

vrothberg commented Mar 1, 2021

rhatdan commented Mar 1, 2021

afbjorklund commented Mar 1, 2021

mheon commented Mar 1, 2021

oblutak commented Mar 18, 2021

mheon commented Mar 18, 2021

oblutak commented Mar 18, 2021

afbjorklund commented Mar 19, 2021

rhatdan commented Mar 23, 2021

afbjorklund commented Mar 23, 2021

github-actions bot commented Apr 23, 2021

rhatdan commented Apr 23, 2021

rhatdan commented Apr 23, 2021

github-actions bot commented May 24, 2021

rhatdan commented May 24, 2021

afbjorklund commented Jan 31, 2021 •

edited

Loading

pineman commented Feb 28, 2021 •

edited

Loading