docker run ubuntu /bin/cat /bin/hostname hangs the client

[mhagen-vmware]

On VC6.0, if you try to cat and log a binary file on VC it hangs the client hard (ctrl-c does not exit) at the docker run command. This work on vanilla docker and it works on ESX.

This is in relation to test 1-08-Docker-Logs: Docker binary logs

container-logs.zip

from docker-personality:

time="2017-05-16T14:37:43Z" level=error msg="Handler for POST /v1.23/containers/5e8fb62366a46c7d868a4da3c53bc939cb3572aafe333467566b84ffadb52024/kill returned error: Cannot kill container 5e8fb62366a46c7d868a4da3c53bc939cb3572aafe333467566b84ffadb52024: 5e8fb62366a46c7d868a4da3c53bc939cb3572aafe333467566b84ffadb52024 is not running" 

[jzt]

Everything from the container side of things seems normal. The command ran, nothing crazy happened and it shut down normally. No errors that I could find in tether.log or vmware.log, and output.log looked normal.

I did find this: docker personality:

time="2017-05-16T14:37:03Z" level=debug msg="Calling GET /v1.23/events?filters=%7B%22container%22%3A%7B%225e8fb62366a46c7d868a4da3c53bc939cb3572aafe333467566b84ffadb52024%22%3Atrue%7D%2C%22type%22%3A%7B%22container%22%3Atrue%7D%7D" 
time="2017-05-16T14:37:03Z" level=debug msg="Calling POST /v1.23/containers/5e8fb62366a46c7d868a4da3c53bc939cb3572aafe333467566b84ffadb52024/start" 
time=2017-05-16T14:37:03.207135290Z level=debug msg=[BEGIN] [github.com/vmware/vic/lib/apiservers/engine/backends.(*Container).ContainerStart:542] 5e8fb62366a46c7d868a4da3c53bc939cb3572aafe333467566b84ffadb52024 
time=2017-05-16T14:37:03.207142715Z level=debug msg=[BEGIN] [github.com/vmware/vic/lib/apiservers/engine/backends.Retry:160] 
time="2017-05-16T14:37:03Z" level=debug msg="mapPorts for \"5e8fb62366a46c7d868a4da3c53bc939cb3572aafe333467566b84ffadb52024\": map[]" 
time="2017-05-16T14:37:17Z" level=debug msg="* stdout attach end Tue May 16 14:37:17 UTC 2017" 
time="2017-05-16T14:37:17Z" level=info msg="container attach: stdout (5e8fb62366a46c7d868a4da3c53bc939cb3572aafe333467566b84ffadb52024) done: %!s(MISSING)" 
time="2017-05-16T14:37:17Z" level=error msg="container attach: stderr (5e8fb62366a46c7d868a4da3c53bc939cb3572aafe333467566b84ffadb52024): Server error from portlayer: net/http: request canceled" 
time="2017-05-16T14:37:17Z" level=info msg="returning from stdin as context canceled somewhere else" 
time="2017-05-16T14:37:17Z" level=info msg="cleaned up connections to 5e8fb62366a46c7d868a4da3c53bc939cb3572aafe333467566b84ffadb52024. Checking errors" 
time="2017-05-16T14:37:17Z" level=info msg="No error found. Returning nil..." 
time="2017-05-16T14:37:17Z" level=debug msg="Will not try again. Operation succeeded" 

And this in the portlayer log (not sure ssh session for stderr was ever successfully found) :

time="2017-05-16T14:37:03Z" level=debug msg="Attempting to get ssh session for container 5e8fb62366a46c7d868a4da3c53bc939cb3572aafe333467566b84ffadb52024 stderr" 
time=2017-05-16T14:37:03.180629843Z level=debug msg=[BEGIN] [github.com/vmware/vic/lib/portlayer/attach.(*Server).Get:90] 5e8fb62366a46c7d868a4da3c53bc939cb3572aafe333467566b84ffadb52024 
time=2017-05-16T14:37:03.180633974Z level=debug msg=[BEGIN] [github.com/vmware/vic/lib/portlayer/attach.(*Connector).Get:80] 5e8fb62366a46c7d868a4da3c53bc939cb3572aafe333467566b84ffadb52024 
time="2017-05-16T14:37:03Z" level=info msg="attach connector:  Connection not found yet for 5e8fb62366a46c7d868a4da3c53bc939cb3572aafe333467566b84ffadb52024" 
time=2017-05-16T14:37:03.180711822Z level=debug msg=[BEGIN] [github.com/vmware/vic/lib/apiservers/portlayer/restapi/handlers.(*InteractionHandlersImpl).ContainerGetStdoutHandler:268] 5e8fb62366a46c7d868a4da3c53bc939cb3572aafe333467566b84ffadb52024 
time="2017-05-16T14:37:03Z" level=debug msg="Attempting to get ssh session for container 5e8fb62366a46c7d868a4da3c53bc939cb3572aafe333467566b84ffadb52024 stdout with deadline Tue May 16 14:37:33 UTC 2017" 
time=2017-05-16T14:37:03.180740619Z level=debug msg=[BEGIN] [github.com/vmware/vic/lib/portlayer/attach.(*Server).Get:90] 5e8fb62366a46c7d868a4da3c53bc939cb3572aafe333467566b84ffadb52024 
time=2017-05-16T14:37:03.180744101Z level=debug msg=[BEGIN] [github.com/vmware/vic/lib/portlayer/attach.(*Connector).Get:80] 5e8fb62366a46c7d868a4da3c53bc939cb3572aafe333467566b84ffadb52024 
time="2017-05-16T14:37:03Z" level=info msg="attach connector:  Connection not found yet for 5e8fb62366a46c7d868a4da3c53bc939cb3572aafe333467566b84ffadb52024" 
time=2017-05-16T14:37:03.210933332Z level=debug msg=[BEGIN] [github.com/vmware/vic/lib/apiservers/portlayer/restapi/handlers.(*ContainersHandlersImpl).GetHandler:212] 5e8fb62366a46c7d868a4da3c53bc939cb3572aafe333467566b84ffadb52024 
time=2017-05-16T14:37:03.210952175Z level=debug msg=[BEGIN] [github.com/vmware/vic/lib/portlayer/exec.(*Container).Refresh:272] 5e8fb62366a46c7d868a4da3c53bc939cb3572aafe333467566b84ffadb52024 
time=2017-05-16T14:37:03.210958303Z level=debug msg=[BEGIN] [github.com/vmware/vic/lib/portlayer/exec.(*containerBase).updates:98] 5e8fb62366a46c7d868a4da3c53bc939cb3572aafe333467566b84ffadb52024 
time="2017-05-16T14:37:03Z" level=debug msg="get vm properties [config runtime] of vm VirtualMachine:vm-74690" 
time="2017-05-16T14:37:03Z" level=debug msg="properties: [config runtime summary.runtime.connectionState]" 
time=2017-05-16T14:37:03.219872386Z level=debug msg=[ END ] [github.com/vmware/vic/lib/portlayer/exec.(*containerBase).updates:98] [8.912092ms] 5e8fb62366a46c7d868a4da3c53bc939cb3572aafe333467566b84ffadb52024 
time=2017-05-16T14:37:03.219880522Z level=debug msg=[ END ] [github.com/vmware/vic/lib/portlayer/exec.(*Container).Refresh:272] [8.928229ms] 5e8fb62366a46c7d868a4da3c53bc939cb3572aafe333467566b84ffadb52024 
time=2017-05-16T14:37:03.220123408Z level=debug msg=[ END ] [github.com/vmware/vic/lib/apiservers/portlayer/restapi/handlers.(*ContainersHandlersImpl).GetHandler:212] [9.191062ms] 5e8fb62366a46c7d868a4da3c53bc939cb3572aafe333467566b84ffadb52024 

@hickeng any insights?

[jzt]

I was able to repro on blinky using the 1.1.0 release build. I checked out the v1.1.0 tag and added some logging statements to try to zero-in on the issue, and suddenly it won't repro.

[mhagen-vmware]

I was unable to repro this again today. But I did notice that when you run: docker -H xxx run ubuntu /bin/cat /bin/hostname >/tmp/hostname

It can take quite a long time to run, and during that period it ignores all ctrl-c ctrl-z commands. So this might be a case of the command taking even longer than normal to complete (like minutes/hours) due to a slow environment... in that case we will hang the client terminal, but it will eventually return once the command finally completes.

[jzt]

@mhagen-vmware normal docker will ignore ^C/^Z if you don't specify -it options when running the container. Just tested and verified that ^C and ^Z both work if you use run -it.

[mhagen-vmware]

@jzt See the last comment on May 17

[emlin]

Did some test and investigation on blinky, as @jzt ever reproduce it. Here is what I found:

The docker binary logs command mentioned in this issue does not take long time. It doesn't feels like docker client hung there. But I tried another command docker -H 10.17.109.115:2376 --tls run ubuntu /bin/cat /bin/* > /tmp/bin, which does take long time than vanilla docker. The slow includes two parts, one is to create container VM, and the other is the logs output. So in one word, if the container command is executed does take long time, and no any error message output. User is still able to tell if the command is running by checking the command output. That's not a true hung there.

For the Ctrl+C and Ctrl+Z, I tried it in vanilla docker, it's same. Although vanilla docker can usually finish the command very fast, it does not stop if I issue Ctrl+C/Z.

And this hot key works well if we have -it for docker run as @jzt mentioned.

Basically, I agree that the docker logs performance is one issue, especially while there are large amount of data output. But it should not be a blocker for 1.2 release. @mdubya66

[mdubya66]

removing the bug from this. it should be looked at for performance enhancements.

On the latest build 14308,

real    0m35.197s
user    0m0.021s
sys 0m0.018s