Unable to run docker logs or docker exec against VCH

[RebeccaYo]

#For bug reports, please include the information below:

VIC version:
1.2.1-13858-c3db65f

Deployment details:
./vic-machine-linux create --compute-resource ordos12.eng.vmware.com --no-tlsverify --no-tls --thumbprint 16:69:E9:DC:27:90:55:23:80:34:DD:2E:60:E7:22:34:86:4B:42:CA --target 10.115.68.198 --user administrator@vsphere.local --name WV-VCH --image-store Unity600-Lun4 --volume-store Unity600-Lun4:default --bridge-network VCH1BridgeNetwork --client-network Testbed --public-network Testbed --management-network PublicNetwork --container-network Testbed:cn1 --dns-server 192.168.10.101 --public-network-ip 192.168.10.100/24 --public-network-gateway 192.168.10.101 --endpoint-cpu 1 --endpoint-memory 2048 --insecure-registry 10.115.68.163:443

Steps to reproduce:
After creating the VCH, execute docker exec or docker logs against any container hosted by VCH. I used docker -H 192.168.10.100:2375 run -i busybox

Actual behavior:
docker: Error response from daemon: Server error from portlayer: unable to wait for process launch status: Post https://10.115.68.198/sdk: context deadline exceeded.

However, the container did get created.

Expected behavior:
For the command docker -H 192.168.10.100:2375 run -i busybox to complete correctly

Logs:
logs.zip

Additional details as necessary:

[sgairo]

@RGRIDER Thanks for the bug report, we'll take a look!

[sgairo]

This could be related to #5819, will investigate further.

[maxisam]

I just run into this one as well. Mine is 1.3

Server Version: v1.3.1-16055-afdab46
Storage Driver: vSphere Integrated Containers v1.3.1-16055-afdab46 Backend Engine

[sgairo]

@maxisam Would you please attach any logs you have?

[sgairo]

Will move into sprint to track follow up.

[maxisam]

I think somehow I bypass this issue and use dch-photon with command line to do general operations without problem. Honestly, VIC is still a long way to go. Hope you guys can fix the issues in UI. It is really confusing.

[mdubya66]

@maxisam can you elaborate on the issues you are seeing in the ui? we are prioritizing now.

[maxisam]

1. I can't create/run a dch-photon container/ or any container requires volume mapping from UI.
2. Every time I try to create a volume from UI, it fails. (I think this one is because it was looking for a storage name default? but I can't find where I can set volume storage name)
3. There should be a way to find what images are on a VCH from UI. Otherwise, how can I restart it?
4. No create/provision button from project repo list.
5. Why UI attach an ID to the name of volume it created? It is super annoying. And then you can see the whole name from UI because it is too long. And I need to use that name for provisioning a container. (And there is no dropdow/typeahead to select either)

Btw, I only use UI for a couple days, but I believe it is still heavily under development. Hope it will be better.

At least the look and feel of the UI is pretty good.

[mdubya66]

Thank you. When you say UI do you mean the Admiral management portal? https://github.com/vmware/admiral @maxisam

The reason I ask is we have several, depending on the user. H5 Plugin on vSphere. OVA installer and the Container Management portal.

[mdubya66]

Given that CDE's are fairly generic I'm putting the portlayer log output in here for tracking purposes

from the above logs.zip in var/log/vic/portlayer.log

Mar  8 2018 22:43:11.573Z INFO  op=290.12: Writing metadata 423789e3-142c-f1f4-43bf-9652bc4551eb/images/02d3847f0b0fb7acd4419040cc53febf91cb112db2451d9b27a245dee5b227c0/imageMetadata/metaData
Mar  8 2018 22:43:12.109Z INFO  op=290.12: Creating image 02d3847f0b0fb7acd4419040cc53febf91cb112db2451d9b27a245dee5b227c0 ([Unity600-Lun4] WV-VCH/VIC/423789e3-142c-f1f4-43bf-9652bc4551eb/images/02d3847f0b0fb7acd4419040cc53febf91cb112db2451d9b27a245dee5b227c0/02d3847f0b0fb7acd4419040cc53febf91cb112db2451d9b27a245dee5b227c0.vmdk)
Mar  8 2018 22:43:12.109Z INFO  op=290.12: Create/attach vmdk [Unity600-Lun4] WV-VCH/VIC/423789e3-142c-f1f4-43bf-9652bc4551eb/images/02d3847f0b0fb7acd4419040cc53febf91cb112db2451d9b27a245dee5b227c0/02d3847f0b0fb7acd4419040cc53febf91cb112db2451d9b27a245dee5b227c0.vmdk from parent [Unity600-Lun4] WV-VCH/VIC/423789e3-142c-f1f4-43bf-9652bc4551eb/images/b033c560078fa8427a78f311ec37bcac1c0d141178e51e036785db6cd1a60d8c/b033c560078fa8427a78f311ec37bcac1c0d141178e51e036785db6cd1a60d8c.vmdk
Mar  8 2018 22:43:12.122Z INFO  op=290.12: No disks match name and persistence: [Unity600-Lun4] WV-VCH/VIC/423789e3-142c-f1f4-43bf-9652bc4551eb/images/02d3847f0b0fb7acd4419040cc53febf91cb112db2451d9b27a245dee5b227c0/02d3847f0b0fb7acd4419040cc53febf91cb112db2451d9b27a245dee5b227c0.vmdk, true
Mar  8 2018 22:43:12.809Z INFO  op=290.12: Attached disk present at /dev/sda
Mar  8 2018 22:43:12.809Z INFO  op=290.12: Mounting /dev/sda to /.filesystem-by-label/dev/sda
Mar  8 2018 22:43:12.843Z INFO  op=290.12: No /.vic.vol.data data directory in volume, mounting filesystem directly
Mar  8 2018 22:43:12.843Z INFO  op=290.12: Mounting /dev/sda to /tmp/mnt454585650
Mar  8 2018 22:43:12.845Z INFO  op=290.12: Unmounting /tmp/mnt454585650
Mar  8 2018 22:43:12.847Z INFO  op=290.12: Unmounting /.filesystem-by-label/dev/sda
Mar  8 2018 22:43:12.850Z INFO  op=290.12: Detaching disk /dev/sda
Mar  8 2018 22:43:14.542Z INFO  Moving [Unity600-Lun4] WV-VCH/kvStores/apiKV.dat-ubiFgfcMAs.tmp to [Unity600-Lun4] WV-VCH/kvStores/apiKV.dat
Mar  8 2018 22:43:14.750Z INFO  set log file name to: [Unity600-Lun4] c1f8a55382750e0403429e21da1a1f71f54fd2145567035d7db5085f4f15c579/tether.debug
Mar  8 2018 22:43:14.750Z INFO  set log file name to: [Unity600-Lun4] c1f8a55382750e0403429e21da1a1f71f54fd2145567035d7db5085f4f15c579/output.log
Mar  8 2018 22:43:15.451Z INFO  Reconfigure: attempting update to c1f8a55382750e0403429e21da1a1f71f54fd2145567035d7db5085f4f15c579 with change version "2018-03-08T22:43:15.274797Z" (poweredOff)
Mar  8 2018 22:43:15.760Z INFO  Reconfigure: committed update to c1f8a55382750e0403429e21da1a1f71f54fd2145567035d7db5085f4f15c579 with change version: 2018-03-08T22:43:15.274797Z
Mar  8 2018 22:43:15.761Z INFO  attach connector:  Connection not found yet for c1f8a55382750e0403429e21da1a1f71f54fd2145567035d7db5085f4f15c579
Mar  8 2018 22:43:15.771Z INFO  Reconfigure: attempting update to c1f8a55382750e0403429e21da1a1f71f54fd2145567035d7db5085f4f15c579 with change version "2018-03-08T22:43:15.673549Z" (poweredOff)
Mar  8 2018 22:43:16.089Z INFO  Reconfigure: committed update to c1f8a55382750e0403429e21da1a1f71f54fd2145567035d7db5085f4f15c579 with change version: 2018-03-08T22:43:15.673549Z
Mar  8 2018 22:44:05.761Z ERROR attach connector: Connection not found error for id:c1f8a55382750e0403429e21da1a1f71f54fd2145567035d7db5085f4f15c579: context deadline exceeded
Mar  8 2018 22:44:05.761Z ERROR attach connector: Connection not found error for id:c1f8a55382750e0403429e21da1a1f71f54fd2145567035d7db5085f4f15c579: context deadline exceeded
Mar  8 2018 22:44:05.761Z ERROR attach connector: Connection not found error for id:c1f8a55382750e0403429e21da1a1f71f54fd2145567035d7db5085f4f15c579: context deadline exceeded
Mar  8 2018 22:44:05.761Z ERROR attach connector: Connection not found error for id:c1f8a55382750e0403429e21da1a1f71f54fd2145567035d7db5085f4f15c579: context deadline exceeded
Mar  8 2018 22:46:16.906Z ERROR Property collector error: Post https://10.115.68.198/sdk: context deadline exceeded
Mar  8 2018 22:46:16.906Z ERROR Unable to wait for extra config property guestinfo.vice..sessions|c1f8a55382750e0403429e21da1a1f71f54fd2145567035d7db5085f4f15c579.started: Post https://10.115.68.198/sdk: context deadline exceeded
Mar  8 2018 22:46:16.906Z ERROR CommitHandler error on handle(d26629727fd15d625dfdec98645832a2) for c1f8a55382750e0403429e21da1a1f71f54fd2145567035d7db5085f4f15c579: &errors.errorString{s:"unable to wait for process launch status: Post https://10.115.68.198/sdk: context deadline exceeded"}```

[mdubya66]

and in the personality.log

Mar  8 2018 22:43:08.785Z INFO  Image ID: sha256:f6e427c148a766d2d6c117d67359a0aa7d133b5bc05830a7ff6e8b64ff6b1d1d
Mar  8 2018 22:43:11.469Z INFO  Path: /tmp/https/registry.hub.docker.com/v2/library/busybox/latest/02d3847f0b0fb7acd4419040cc53febf91cb112db2451d9b27a245dee5b227c0/02d3847f0b0fb7acd4419040cc53febf91cb112db2451d9b27a245dee5b227c0.tar
Mar  8 2018 22:43:13.904Z INFO  Created an image &models.Image{ID:"02d3847f0b0fb7acd4419040cc53febf91cb112db2451d9b27a245dee5b227c0", Metadata:map[string]string{"metaData":"{\"architecture\":\"amd64\",\"config\":{\"Hostname\":\"\",\"Domainname\":\"\",\"User\":\"\",\"AttachStdin\":false,\"AttachStdout\":false,\"AttachStderr\":false,\"Tty\":false,\"OpenStdin\":false,\"StdinOnce\":false,\"Env\":[\"PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin\"],\"Cmd\":[\"sh\"],\"ArgsEscaped\":true,\"Image\":\"sha256:8cae5980d887cc55ba2f978ae99c662007ee06d79881678d57f33f0473fe0736\",\"Volumes\":null,\"WorkingDir\":\"\",\"Entrypoint\":null,\"OnBuild\":null,\"Labels\":null},\"container\":\"8d2c840a1a9b2544fe713c2e24b6757d52328f09bdfc9c2ef6219afbf7ae6b59\",\"container_config\":{\"Hostname\":\"8d2c840a1a9b\",\"Domainname\":\"\",\"User\":\"\",\"AttachStdin\":false,\"AttachStdout\":false,\"AttachStderr\":false,\"Tty\":false,\"OpenStdin\":false,\"StdinOnce\":false,\"Env\":[\"PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin\"],\"Cmd\":[\"/bin/sh\",\"-c\",\"#(nop) \",\"CMD [\\\"sh\\\"]\"],\"ArgsEscaped\":true,\"Image\":\"sha256:8cae5980d887cc55ba2f978ae99c662007ee06d79881678d57f33f0473fe0736\",\"Volumes\":null,\"WorkingDir\":\"\",\"Entrypoint\":null,\"OnBuild\":null,\"Labels\":{}},\"created\":\"2018-02-28T22:14:49.023807051Z\",\"docker_version\":\"17.06.2-ce\",\"id\":\"02d3847f0b0fb7acd4419040cc53febf91cb112db2451d9b27a245dee5b227c0\",\"os\":\"linux\",\"parent\":\"b033c560078fa8427a78f311ec37bcac1c0d141178e51e036785db6cd1a60d8c\",\"throwaway\":true}"}, Parent:"http:///storage/images/423789e3-142c-f1f4-43bf-9652bc4551eb/b033c560078fa8427a78f311ec37bcac1c0d141178e51e036785db6cd1a60d8c", SelfLink:"http:///storage/images/423789e3-142c-f1f4-43bf-9652bc4551eb/02d3847f0b0fb7acd4419040cc53febf91cb112db2451d9b27a245dee5b227c0", Store:"http:///storage/images/423789e3-142c-f1f4-43bf-9652bc4551eb"}
Mar  8 2018 22:43:14.733Z INFO  Container CPU count: 2
Mar  8 2018 22:43:14.734Z INFO  Container memory: 2048 MB
Mar  8 2018 22:43:14.750Z INFO  Specified Volumes : []string(nil)
Mar  8 2018 22:43:14.750Z INFO  anonymous Volumes : []string{}
Mar  8 2018 22:43:14.750Z INFO  Finalized Volume list : []backends.volumeFields{}
Mar  8 2018 22:44:05.762Z ERROR container attach: stdout (c1f8a55382750e0403429e21da1a1f71f54fd2145567035d7db5085f4f15c579): No such interaction connection for container: c1f8a55382750e0403429e21da1a1f71f54fd2145567035d7db5085f4f15c579
Mar  8 2018 22:44:05.762Z ERROR container attach: stderr (c1f8a55382750e0403429e21da1a1f71f54fd2145567035d7db5085f4f15c579): Server error from portlayer: [GET /interaction/{id}/stderr][404] containerGetStderrNotFound 
Mar  8 2018 22:46:16.907Z ERROR Will stop trying again. Operation failed with errors.apiError{error:(*errors.errorString)(0xc4208d0970), statusCode:500}
Mar  8 2018 22:46:16.907Z ERROR Handler for POST /v1.25/containers/c1f8a55382750e0403429e21da1a1f71f54fd2145567035d7db5085f4f15c579/start returned error: Server error from portlayer: unable to wait for process launch status: Post https://10.115.68.198/sdk: context deadline exceeded
Mar  8 2018 22:46:16.908Z ERROR Attach stream has stdinOnce set.  Closing the stdin.
Mar  8 2018 22:46:16.909Z ERROR CloseStdin failed with context canceled
Mar  8 2018 22:46:16.909Z ERROR container attach: stdin (c1f8a55382750e0403429e21da1a1f71f54fd2145567035d7db5085f4f15c579): context canceled
Mar  8 2018 22:46:16.909Z INFO  cleaned up connections to c1f8a55382750e0403429e21da1a1f71f54fd2145567035d7db5085f4f15c579. Checking errors
Mar  8 2018 22:46:16.909Z ERROR container attach error: No such interaction connection for container: c1f8a55382750e0403429e21da1a1f71f54fd2145567035d7db5085f4f15c579
Mar  8 2018 22:46:16.909Z ERROR Will stop trying again. Operation failed with errors.apiError{error:(*errors.errorString)(0xc4208d0600), statusCode:404}
Mar  8 2018 22:46:16.909Z ERROR Handler for POST /v1.25/containers/c1f8a55382750e0403429e21da1a1f71f54fd2145567035d7db5085f4f15c579/attach returned error: No such interaction connection for container: c1f8a55382750e0403429e21da1a1f71f54fd2145567035d7db5085f4f15c579
Mar  8 2018 22:46:16.909Z ERROR Error Hijacking: No such interaction connection for container: c1f8a55382750e0403429e21da1a1f71f54fd2145567035d7db5085f4f15c579
Mar  8 2018 22:57:45.284Z INFO  running product VM discovery
Mar  8 2018 22:57:45.451Z WARN  ignoring product VM Admiral endpoint https://10.115.68.103:8282 since it does not have the VCH added to any project
Mar  8 2018 22:57:45.484Z WARN  ignoring product VM Admiral endpoint https://10.115.68.163:8282 since it does not have the VCH added to any project

[maxisam]

@mdubya66 yes. I am on v1.3.1

[sgairo]

Rebecca was able to resolve the issue.
"After migrating to a different host of the same model (and redeploying the VIC appliance, incidentally), I have a working VCH. I did isolate the issue to the host I was running on. I saw system wide issues on that host which I believe is at the ESXi level."

Error reporting could be improved.

[mdubya66]

OK, Let's close this original issue @maxisam, can you open a new issue describing the failures you are seeing and attach the log files from the failures?