Fix to recnt_test.sh to select line for recovery tests. #791

govint · 2016-12-02T11:46:13Z

Search for specific line in plugin log for recovery test.

kerneltime · 2016-12-02T18:07:54Z

This does not fix the issue https://ci.vmware.run/vmware/docker-volume-vsphere/588

govint · 2016-12-02T18:26:31Z

Ok, the issue is as analysed, I may have added the wrong string to search for. Would be great to have the plugin logs.

On Fri, Dec 2, 2016 at 11:37 PM, Ritesh H Shukla ***@***.***> wrote: This does not fix the issue https://ci.vmware.run/vmware/ docker-volume-vsphere/588 — You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub <#791 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/APHseGBAzWJITl0ONAcQQMNC0i26xBSzks5rEF57gaJpZM4LCeLE> .

kerneltime · 2016-12-02T18:35:45Z

I have attached the logs to the issue from when I ran it manually https://github.com/vmware/docker-volume-vsphere/files/626619/docker-volume-vsphere.txt also https://ci.vmware.run/vmware/docker-volume-vsphere/590

kerneltime · 2016-12-02T18:38:21Z

Relevant bit from https://ci.vmware.run/vmware/docker-volume-vsphere/590 post plugin restart.
Note count is 4 and not the expected value of 5

2016-12-02 18:26:02.31535609 +0000 UTC [INFO] No config file found. Using defaults.
2016-12-02 18:26:02.315397129 +0000 UTC [INFO] Docker VMDK plugin started config="/etc/docker-volume-vsphere.conf" version="VMDK Volume Driver v0.3" port=1019 mock_esx=false log_level=info 
2016-12-02 18:26:02.318377301 +0000 UTC [INFO] Getting volume data from unix:///var/run/docker.sock
2016-12-02 18:28:29.082017235 +0000 UTC [INFO] Discovered 1 volumes in use.
2016-12-02 18:28:29.082073709 +0000 UTC [INFO] Volume name=refCountTestVol count=4 mounted=true device='/dev/disk/by-path/pci-0000:0b:00.0-scsi-0:0:0:0'

govint · 2016-12-05T04:41:07Z

Refcount isn't guaranteed to be at 5, each of the five containers are doing a sleep of one minute after which they exit. Its possible that the first one may have exited by the time the plugin is killed and comes back up.

Overall, this test is very sensitive to how fast the plugin restarts after its killed and there isn't any guarantee that the exact same number of containers are still there when it starts.

govint · 2016-12-05T05:37:00Z

The test itself runs a container to check number of files on the refcount volume, which logs "Unmount...." logs - fixed by searching explicitly for "mounted=true"
Changed container command to sleep for a timeout of 3 minutes (earlier 1) so we should have all five containers running still when the plugin restarts.

msterin · 2016-12-05T06:00:43Z

It is hard to believe that it take more than a minute for the test to complete - I think the issue is different from simple timing. However, this was a quick-and-dirty test (my bad) and it gives us a lot of grief. bandaid does not seem to be working properly. IMO the right way would be to interrogate the plugin for the value (e.g.over a listening unix socket) - screen scraping will keep giving us grief. It is a larger fix, but it will really fix the test.

govint · 2016-12-05T06:15:14Z

This is from the log, from the first mount till the plugin restarts and figures the number of containers using the volume. 2016-12-02 07:20:05.395801635 +0000 UTC [INFO] Mounting volume name=refCountTestVol <----------- first mount 2016-12-02 07:20:08.966202091 +0000 UTC [INFO] Attach complete event="/dev/disk/by-path/pci-0000:0b:00.0-scsi-0:0:0:0": 0x100 == IN_CREATE name=refCountTestVol 2016-12-02 07:20:10.709604134 +0000 UTC [INFO] Mounting volume name=refCountTestVol 2016-12-02 07:20:10.709652346 +0000 UTC [INFO] Already mounted, skipping mount. name=refCountTestVol refcount=2 2016-12-02 07:20:10.971466326 +0000 UTC [INFO] Mounting volume name=refCountTestVol 2016-12-02 07:20:10.971493748 +0000 UTC [INFO] Already mounted, skipping mount. name=refCountTestVol refcount=3 2016-12-02 07:20:11.149668846 +0000 UTC [INFO] Mounting volume name=refCountTestVol 2016-12-02 07:20:11.14969609 +0000 UTC [INFO] Already mounted, skipping mount. name=refCountTestVol refcount=4 2016-12-02 07:20:11.332479343 +0000 UTC [INFO] Mounting volume name=refCountTestVol 2016-12-02 07:20:11.332506087 +0000 UTC [INFO] Already mounted, skipping mount. refcount=5 name=refCountTestVol 2016-12-02 07:20:12.550758257 +0000 UTC [INFO] Mounting volume name=refCountTestVol 2016-12-02 07:20:12.550783947 +0000 UTC [INFO] Already mounted, skipping mount. name=refCountTestVol refcount=6 <---- container started to figure count of files on the test volume 2016-12-02 07:20:12.677462758 +0000 UTC [INFO] Unmounting Volume name=refCountTestVol 2016-12-02 07:20:12.677494154 +0000 UTC [INFO] Still in use, skipping unmount request. name=refCountTestVol refcount=5 2016-12-02 07:20:13.043050206 +0000 UTC [INFO] No config file found. Using defaults. 2016-12-02 07:20:13.043125934 +0000 UTC [INFO] Docker VMDK plugin started log_level=info config="/etc/docker-volume-vsphere.conf" version="VMDK Volume Driver v0.3" port=1019 mock_esx=false 2016-12-02 07:20:13.043168132 +0000 UTC [INFO] Getting volume data from unix:///var/run/docker.sock 2016-12-02 07:22:39.816035959 +0000 UTC [INFO] Discovered 1 volumes in use. <--------------- Plugin completes checking volumes in use (which is beyond the one minute timeout per container) 2016-12-02 07:22:39.816485047 +0000 UTC [INFO] Volume name=refCountTestVol count=4 mounted=true device='/dev/disk/by-path/pci-0000:0b:00.0-scsi-0:0:0:0' @msterin, can you elaborate on the change your proposing.

…

On Mon, Dec 5, 2016 at 11:30 AM, Mark Sterin ***@***.***> wrote: While it's hard to belive that it take more than a minute for the test to complete (I think the issue is different from simple timing)., this was a quick-and-dirty test (my bad) and it gives us a lot of grief. bandaid does not seem to be working properly. IMO the right way would be to interrogate the plugin for the value (e.g.over a listening unix socket) - screen scraping will keep giving us grief. It is a larger fix, but it will really fix the test. — You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub <#791 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/APHseIXK_QAJ8cL_WpfygTiwniDXd3RLks5rE6iMgaJpZM4LCeLE> .

kerneltime · 2016-12-06T12:09:03Z

Were you able to reproduce the issue with docker 1.12.x and did this fix help?

govint · 2016-12-06T12:22:35Z

This issue will happen irrespective of the docker version. Its just looking at the plugin logs to figure if the test works ok.

kerneltime · 2016-12-06T17:06:05Z

Merged but this does not close #790

vmwclabot added the cla-not-required label Dec 2, 2016

Fix to recnt_test.sh to select line for recovery tests.

f6e9c97

govint force-pushed the fix-ref branch from 44fadc5 to f6e9c97 Compare December 5, 2016 05:52

govint mentioned this pull request Dec 6, 2016

Add photon volumes to the plugin #798

Closed

kerneltime merged commit a0ca62c into master Dec 6, 2016

govint mentioned this pull request Dec 7, 2016

Refcount tests are failing against docker 1.12.2 #790

Closed

kerneltime deleted the fix-ref branch December 19, 2016 22:53

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Fix to recnt_test.sh to select line for recovery tests. #791

Fix to recnt_test.sh to select line for recovery tests. #791

govint commented Dec 2, 2016 •

edited by kerneltime

Loading

kerneltime commented Dec 2, 2016

govint commented Dec 2, 2016 via email

kerneltime commented Dec 2, 2016 •

edited

Loading

kerneltime commented Dec 2, 2016 •

edited

Loading

govint commented Dec 5, 2016 •

edited

Loading

govint commented Dec 5, 2016

msterin commented Dec 5, 2016 •

edited

Loading

govint commented Dec 5, 2016 via email

kerneltime commented Dec 6, 2016

govint commented Dec 6, 2016

kerneltime commented Dec 6, 2016 •

edited

Loading

Fix to recnt_test.sh to select line for recovery tests. #791

Fix to recnt_test.sh to select line for recovery tests. #791

Conversation

govint commented Dec 2, 2016 • edited by kerneltime Loading

kerneltime commented Dec 2, 2016

govint commented Dec 2, 2016 via email

kerneltime commented Dec 2, 2016 • edited Loading

kerneltime commented Dec 2, 2016 • edited Loading

govint commented Dec 5, 2016 • edited Loading

govint commented Dec 5, 2016

msterin commented Dec 5, 2016 • edited Loading

govint commented Dec 5, 2016 via email

kerneltime commented Dec 6, 2016

govint commented Dec 6, 2016

kerneltime commented Dec 6, 2016 • edited Loading

govint commented Dec 2, 2016 •

edited by kerneltime

Loading

kerneltime commented Dec 2, 2016 •

edited

Loading

kerneltime commented Dec 2, 2016 •

edited

Loading

govint commented Dec 5, 2016 •

edited

Loading

msterin commented Dec 5, 2016 •

edited

Loading

kerneltime commented Dec 6, 2016 •

edited

Loading