Cri-o: Error creating pods about pulling images

[afbjorklund]

Description

Have a problem with pulling images, when using the latest cri-o. Some error with progress bars ?

Steps to reproduce the issue:

1. sudo crictl pull k8s.gcr.io/pause:3.1
2. 
   3.

Describe the results you received:

First time (only) gets:
FATA[0002] pulling image failed: rpc error: code = Unknown desc = error creating progress-bar pool: Can't set terminal settings: input/output error
Second time (and on):
FATA[0004] pulling image failed: rpc error: code = Unknown desc = error creating progress-bar pool: Bar pool was started

The actual non-minimized context looks more like this:

  Type     Reason                  Age                  From               Message
  ----     ------                  ----                 ----               -------
  Normal   Scheduled               14m                  default-scheduler  Successfully assigned kube-system/coredns-7748f7f6df-5h62t to box
  Warning  FailedCreatePodSandBox  14m                  kubelet, box       Failed create pod sandbox: rpc error: code = Unknown desc = error creating pod sandbox with name "k8s_coredns-7748f7f6df-5h62t_kube-system_944f653b-53cc-11e9-bc34-a284975d7303_0": error creating progress-bar pool: Can't set terminal settings: input/output error
  Warning  FailedCreatePodSandBox  4m2s (x41 over 14m)  kubelet, box       Failed create pod sandbox: rpc error: code = Unknown desc = error creating pod sandbox with name "k8s_coredns-7748f7f6df-5h62t_kube-system_944f653b-53cc-11e9-bc34-a284975d7303_0": error creating progress-bar pool: Bar pool was started

Describe the results you expected:

It should have worked without errors.

Going to back to a version before the gopkg.in/cheggaaa/pb.v1 update still works OK.

i.e. dfd0faa709b5369f8bb66a11c68cc5cf68fed862^

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

Output of crio --version:

crio version 1.14.0-dev
commit: "7a329fc0a6198e611ad862a67aca3380406dfc83-dirty"

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

VirtualBox

[afbjorklund]

If I understand correctly, the unlockEcho fails to unlock and then it remains lockEcho forever.

https://github.com/kubernetes-sigs/cri-o/blob/master/vendor/gopkg.in/cheggaaa/pb.v1/pb_x.go#L57:L105

        if err := unix.IoctlSetTermios(fd, ioctlWriteTermios, origTermStatePtr); err != nil {
            return fmt.Errorf("Can't set terminal settings: %v", err)
        }

        if origTermStatePtr != nil {
            return shutdownCh, ErrPoolWasStarted
        }

Sadly I still don't know why it failed initially, other than getting an I/O error (for some reason)

[afbjorklund]

Referenced changes:

• https://github.com/kubernetes-sigs/cri-o/commit/dfd0faa709b5369f8bb66a11c68cc5cf68fed862

** https://github.com/containers/image/commit/911d1f5a61eaa1aaca9ef9ae9efa8ef46c0c02cf

* https://github.com/cheggaaa/pb/commit/5f971f1c90c4e7c9e5b7578cb4d114eaee3eb0b0

The old code unlocked before unix.IoctlSetTermios, the new code unlocks _after_ (or never).

[mrunalp]

cc: @vrothberg

[vrothberg]

Hi @afbjorklund, thanks for the great report! The newer versions of containers/image do not use this library anymore. I have a PR open (https://github.com/kubernetes-sigs/cri-o/pull/2195) to update the vendored dependencies from containers/*. Once that's in, the problem will be fixed.

[afbjorklund]

Okay, I will try 9afd50caf052c1bb6909130818744865a6a48a4e out and see if that fixes it

[afbjorklund]

That worked much better, no progress bar etc - but no errors either.

tc@box:~$ sudo crictl rmi k8s.gcr.io/pause:3.0
Deleted: k8s.gcr.io/pause:3.0
tc@box:~$ sudo crictl pull k8s.gcr.io/pause:3.0
Image is up to date for k8s.gcr.io/pause@sha256:0d093c962a6c2dd8bb8727b661e2b5f13e9df884af9945b4cc7088d9350cd3ee
tc@box:~$ crio --version
crio version 1.14.0-dev
commit: "9afd50caf052c1bb6909130818744865a6a48a4e-dirty"
tc@box:~$ 

The 3.1 was now in use (by a pod), so used 3.0 to test with...

[vrothberg]

The upstream e2e tests introduced a regression which should be fixed now. #2195 should be merged today :)

[afbjorklund]

Fixed in 19167358963fe3432c4a9bd0aa2775dafe40422b