yamux: keepalive failed: i/o deadline reached

[devimc]

Description of problem

Run a container with -ti and pause it for 45 seconds

Terminal 1

$ docker run --name foo -ti centos bash

Terminal 2

$ docker pause foo
$ sleep 45
$ docker unpause foo

Terminal 1 gets stuck after 45 second and next message is logged in the journal

[ERR] yamux: keepalive failed: i/o deadline reached

[grahamwhaley]

Ah, I think I have seen this recently, but not had time to track down why... currently, if you 'ignore' a container, it will stop responding and then die... good find! +1 for I think this is a real current issue!
Hmm, so we could add a test for this to the CI - but that would push out CI feedback loop time another 10 minutes.... so, maybe we won't ... but, if we ever get a 'long soak test' QA CI, that maybe runs on the master branch merges (rather than PRs), then we should add it there.

[grahamwhaley]

I've added a P1 label as well...

[sboeuf]

Dumb question, can we simply disable this timeout ?

[devimc]

@sboeuf ehmm, which timeout? is there a timeout in yamux?

[sboeuf]

Take a look at this test on the yamux repo: https://github.com/hashicorp/yamux/blob/master/session_test.go#L797-L838

[grahamwhaley]

yep, probably maybe we need to set the EnableKeepAlive? https://github.com/hashicorp/yamux/blob/d1caa6c97c9fc1cc9e83bbe34d0603f9ff0ce8bd/mux.go#L16

[sboeuf]

Yes we need to make sure we understand the potential cases but a smart usage of those three flags: https://github.com/hashicorp/yamux/blob/d1caa6c97c9fc1cc9e83bbe34d0603f9ff0ce8bd/mux.go#L16-L27 should do the trick ;)

[WeiZhang555]

Interesting find 👍

[egernst]

@WeiZhang555 @devimc -- since this is marked P1... seems we should probably do this with priority. Any takers?

[jingxiaolu]

This is interesting...
I checked code, currently in agent/channel.go, if we use serialChannel, config=nil when calling yamux.Server():

agent/channel.go

Line 149 in ea0e6ae

session, err := yamux.Server(c.serialConn, nil)

So yamux will use default config, which already EnableKeepAlive:

agent/vendor/github.com/hashicorp/yamux/mux.go

Lines 38 to 47 in ea0e6ae

	func DefaultConfig() *Config {
	return &Config{
	AcceptBacklog: 256,
	EnableKeepAlive: true,
	KeepAliveInterval: 30 * time.Second,
	ConnectionWriteTimeout: 10 * time.Second,
	MaxStreamWindowSize: initialStreamWindow,
	LogOutput: os.Stderr,
	}
	}

[jingxiaolu]

Seems this is because we should update the vendor package agent in shim now.

Now in shim, when it calls NewAgentClient(), in current vendor it's agentDialer(), it will not create a yamux client func agentDialer(addr *url.URL) dialer {:
https://github.com/kata-containers/shim/blob/2457ccc107ac46d7105254c089b240523b1701c4/vendor/github.com/kata-containers/agent/protocols/client/client.go#L115-L129

While in current agent's protocol, it will return a yamux client...

agent/protocols/client/client.go

Lines 122 to 150 in ea0e6ae

	func agentDialer(addr *url.URL, enableYamux bool) dialer {
	var d dialer
	switch addr.Scheme {
	case vsockSocketScheme:
	d = vsockDialer
	case unixSocketScheme:
	fallthrough
	default:
	d = unixDialer
	}
	if !enableYamux {
	return d
	}
	// yamux dialer
	return func(sock string, timeout time.Duration) (net.Conn, error) {
	conn, err := d(sock, timeout)
	if err != nil {
	return nil, err
	}
	defer func() {
	if err != nil {
	conn.Close()
	}
	}()
	var session *yamux.Session
	session, err = yamux.Client(conn, nil)

I might give it a try on Monday...

[jingxiaolu]

Sorry the yamux client here is kata proxy but not kata shim, so shim may not necessary to upgrade the vendor agent.

In my TE, I can't reproduce the same phenomenon by leaving it for long time.
I can reproduce it with:

1. run a new container with kata-runtime;
2. send signal 19 SIGSTOP to proxy;
3. wait for more than 30 seconds;
4. send signal 18 SIGCONT to proxy;
5. check journal log, get the same error print

[devimc]

@jingxiaolu thanks for debugging it, let me try to find another way to reproduce it

[devimc]

Hi I found an easy way to reproduce it

Terminal 1

$ docker run --name foo -ti centos bash

Terminal 2

$ docker pause foo
$ sleep 600
$ docker unpause foo

Terminal 1 gets stuck

[devimc]

actually 45 seconds is enough to reproduce this issue.
updating issue

[jshachm]

docker pause finally also sends SIGSTOP to container process(here in kata is shim represents).
So we find a actual docker cli option to reproduce it.

Good job for both of you~~~
@jingxiaolu @devimc

[devimc]

please take a look kata-containers/proxy#71

[jshachm]

Making a mistake. Nowadays, we just support kata-runtime pause cli just pause hypervisor(vm) using qmp cmd. Not like what runc does, change cgroup freezer for all container process.

[devimc]

see kata-containers/proxy#70