Skip to content
This repository has been archived by the owner on Nov 9, 2020. It is now read-only.

Master build failed #768

Closed
kerneltime opened this issue Nov 23, 2016 · 9 comments · Fixed by #792
Closed

Master build failed #768

kerneltime opened this issue Nov 23, 2016 · 9 comments · Fixed by #792
Labels
kind/bug
Milestone
0.10

Comments

@kerneltime
Copy link
Contributor

After @brunotm PR was merged #760 the master build failed https://ci.vmware.run/vmware/docker-volume-vsphere/463

=== RUN   TestSanity
Running tests on  tcp://192.168.31.54:2375 (may take a while)...
Running parallel tests on tcp://192.168.31.54:2375 and tcp://192.168.31.217:2375 (may take a while)...
--- FAIL: TestSanity (628.70s)
	sanity_test.go:195: Successfully connected to tcp://192.168.31.54:2375
	sanity_test.go:195: Successfully connected to tcp://192.168.31.217:2375
	sanity_test.go:200: Creating vol=vol.build463 on client tcp://192.168.31.54:2375.
	sanity_test.go:95: Running cmd=&[touch /mnt/testvol/vol.build463/file_to_touch] with vol=vol.build463 on client tcp://192.168.31.54:2375
	sanity_test.go:95: Running cmd=&[stat /mnt/testvol/vol.build463/file_to_touch] with vol=vol.build463 on client tcp://192.168.31.54:2375
	sanity_test.go:265: Parallel test failed, err: Error response from daemon: create volTestP14: VolumeDriver.Create: Failed to add disk scsi1:0.
FAIL
make[1]: *** [test-vm] Error 1
make: *** [testremote] Error 2

ci.463.txt
@kerneltime kerneltime added this to the 0.10 milestone Nov 23, 2016
@kerneltime
Copy link
Contributor Author

Relevant bits.

11/15/16 01:08:39 5892780 [photon.ga.vsan-[vsanDatastore] dockvols/volTestP04.vmdk] [INFO   ] *** createVMDK: /vmfs/volumes/vsanDatastore/dockvols/volTestP04.vmdk opts = {u'size': u'1gb', u'fstype': u'ext4'}
11/15/16 01:08:45 5892780 [Ubuntu.1404.vsan-[vsanDatastore] dockvols/volTestP14.vmdk] [ERROR  ] Failed to create devFS node for eb5f2a58-fde9-d4b1-8d76-000c29e3609e
11/15/16 01:08:45 5892780 [Ubuntu.1404.vsan-[vsanDatastore] dockvols/volTestP14.vmdk] [INFO   ] executeRequest 'create' completed with ret=None
11/15/16 01:08:47 5892780 [Ubuntu.1404.vsan-[vsanDatastore] dockvols/volTestP14.vmdk] [INFO   ] *** attachVMDK: /vmfs/volumes/vsanDatastore/dockvols/volTestP14.vmdk to Ubuntu.1404.vsan VM uuid = 564dfb57-9a65-0c36-81d0-26cd117aa534
11/15/16 01:08:49 5892780 [Ubuntu.1404.vsan-[vsanDatastore] dockvols/volTestP14.vmdk] [INFO   ] Attaching /vmfs/volumes/vsanDatastore/dockvols/volTestP14.vmdk as independent_persistent
11/15/16 01:08:58 5892780 [Ubuntu.1404.vsan-[vsanDatastore] dockvols/volTestP14.vmdk] [INFO   ] executeRequest 'attach' completed with ret={u'Error': 'Failed to add disk scsi1:0.'}
11/15/16 01:09:01 5892780 [Ubuntu.1404.vsan-[vsanDatastore] dockvols/volTestP14.vmdk] [INFO   ] *** removeVMDK: /vmfs/volumes/vsanDatastore/dockvols/volTestP14.vmdk
11/15/16 01:09:28 5892780 [Ubuntu.1404.vsan-[vsanDatastore] dockvols/volTestP14.vmdk] [INFO   ] executeRequest 'remove' completed with ret=None
11/15/16 01:09:28 5892780 [Ubuntu.1404.vsan-[vsanDatastore] dockvols/volTestP14.vmdk] [INFO   ] executeRequest 'get' completed with ret={u'Error': 'Volume volTestP14 not found (file: /vmfs/volumes/vsanDatastore/dockvols/volTestP14.vmdk)'}
11/15/16 01:09:36 5892780 [photon.ga.vsan-[vsanDatastore] dockvols/volTestP04.vmdk] [INFO   ] executeRequest 'create' completed with ret=None
11/15/16 01:09:36 5892780 [photon.ga.vsan-[vsanDatastore] dockvols/volTestP04.vmdk] [INFO   ] *** attachVMDK: /vmfs/volumes/vsanDatastore/dockvols/volTestP04.vmdk to photon.ga.vsan VM uuid = 564d5ef2-89dc-1cfa-abc6-1289c486759b

@kerneltime
Copy link
Contributor Author

We need to start capturing the hostd log file as part of the build, the snapshot and restore model for CI also implies that we lose all other logs relevant to the failure.

@brunotm
Copy link
Contributor

brunotm commented Nov 23, 2016

@kerneltime
Is the hostd.txt correct? I only see dates between 2016-11-14T06:47:10.420Z and 2016-11-15T04:32:07.085Z.

My main concern with this failure is that all previous builds of that PR were done successfully on top of master, the error in question came from objtool in vmdk_ops.get_vsan_devfs_path (not in the scope of #760) and the output errors weren't being logged until #765.

But from CI history after #760 there isn't any more failures to look at.

@kerneltime
Copy link
Contributor Author

kerneltime commented Nov 23, 2016 •
edited
Loading

@brunotm I will delete the hostd log from here, we snapshot and restore so it does not contain any relevant bits.. I have filed a issue to capture the hostd logs for CI runs.
The devFS node used to be created to format the disk (which should no longer be needed). Will look into it.
We need to know why the test failed, this should not be related #760 and might be another issue lurking that manifested itself.
Apart from devfs failure in the log, the attach failed and that is the reason for the failure.

@brunotm brunotm mentioned this issue Nov 23, 2016
Closed
@brunotm
Copy link
Contributor

brunotm commented Nov 23, 2016 •
edited
Loading

@kerneltime
I reviewed the changes and tested again, but i couldn't reproduce it. - i don't have a vsan testbed at this moment.

Early finding the #770 was the good part.

Thanks.

@brunotm
Copy link
Contributor

brunotm commented Nov 24, 2016

@kerneltime
I have noticed the buid 491 failure with the log below.

While my understanding is that is that the file itself is locked or open by something outside the vmdk_ops service (the busy messages are from failed open() calls on the file) and the ops in parallel tests are being performed on different volumes i don't have the debug log to actually exclude the #760 code change. Even though it seems unlikely that they are the reason for these failures (the locking scope is unchanged)

If there was nothing else that we know of happening during that build, i can open a test PR with debugging loglevel hoping to catch something similar, or we can revert and hold back that change and the #770 until this is sorted out.

What do you think?

11/15/16 01:03:33 5892693 [photon.ga.vsan-[vsanDatastore] dockvols/volTestP01.vmdk] [INFO   ] *** removeVMDK: /vmfs/volumes/vsanDatastore/dockvols/volTestP01.vmdk, coudn't lock volume for removal. Retrying...
11/15/16 01:03:50 5892693 [photon.ga.vsan-[vsanDatastore] dockvols/volTestP01.vmdk] [INFO   ] executeRequest 'remove' completed with ret=None
11/15/16 01:03:51 5892693 [photon.ga.vsan-[vsanDatastore] dockvols/volTestP02.vmdk] [INFO   ] executeRequest 'get' completed with ret={u'Error': 'Volume volTestP02 not found (file: /vmfs/volumes/vsanDatastore/dockvols/volTestP02.vmdk)'}
11/15/16 01:03:51 5892693 [photon.ga.vsan-[vsanDatastore] dockvols/volTestP02.vmdk] [INFO   ] *** createVMDK: /vmfs/volumes/vsanDatastore/dockvols/volTestP02.vmdk opts = {u'size': u'1gb', u'fstype': u'ext4'}
11/15/16 01:03:53 5892693 [Ubuntu.1404.vsan-[vsanDatastore] dockvols/volTestP12.vmdk] [WARNING] Meta file /vmfs/volumes/vsanDatastore/dockvols/volTestP12-c5c4df33013cd893.vmfd busy for save(), retrying...
11/15/16 01:03:54 5892693 [Ubuntu.1404.vsan-[vsanDatastore] dockvols/volTestP12.vmdk] [WARNING] Meta file /vmfs/volumes/vsanDatastore/dockvols/volTestP12-c5c4df33013cd893.vmfd busy for save(), retrying...
11/15/16 01:03:57 5892693 [Ubuntu.1404.vsan-[vsanDatastore] dockvols/volTestP12.vmdk] [WARNING] Meta file /vmfs/volumes/vsanDatastore/dockvols/volTestP12-c5c4df33013cd893.vmfd busy for save(), retrying...
11/15/16 01:03:59 5892693 [Ubuntu.1404.vsan-[vsanDatastore] dockvols/volTestP12.vmdk] [WARNING] Meta file /vmfs/volumes/vsanDatastore/dockvols/volTestP12-c5c4df33013cd893.vmfd busy for save(), retrying...
11/15/16 01:03:59 5892693 [Ubuntu.1404.vsan-[vsanDatastore] dockvols/volTestP12.vmdk] [WARNING] Meta file /vmfs/volumes/vsanDatastore/dockvols/volTestP12-c5c4df33013cd893.vmfd busy for save(), retrying...
11/15/16 01:04:02 5892693 [Ubuntu.1404.vsan-[vsanDatastore] dockvols/volTestP12.vmdk] [WARNING] Meta file /vmfs/volumes/vsanDatastore/dockvols/volTestP12-c5c4df33013cd893.vmfd busy for save(), retrying...
11/15/16 01:04:04 5892693 [Ubuntu.1404.vsan-[vsanDatastore] dockvols/volTestP12.vmdk] [WARNING] Meta file /vmfs/volumes/vsanDatastore/dockvols/volTestP12-c5c4df33013cd893.vmfd busy for save(), retrying...
11/15/16 01:04:04 5892693 [Ubuntu.1404.vsan-[vsanDatastore] dockvols/volTestP12.vmdk] [WARNING] Meta file /vmfs/volumes/vsanDatastore/dockvols/volTestP12-c5c4df33013cd893.vmfd busy for save(), retrying...
11/15/16 01:04:08 5892693 [Ubuntu.1404.vsan-[vsanDatastore] dockvols/volTestP12.vmdk] [WARNING] Meta file /vmfs/volumes/vsanDatastore/dockvols/volTestP12-c5c4df33013cd893.vmfd busy for save(), retrying...
11/15/16 01:04:09 5892693 [Ubuntu.1404.vsan-[vsanDatastore] dockvols/volTestP12.vmdk] [ERROR  ] Failed to save meta-data for /vmfs/volumes/vsanDatastore/dockvols/volTestP12.vmdk
Traceback (most recent call last):
  File "/usr/lib/vmware/vmdkops/Python/kvESX.py", line 300, in save
    with open(meta_file, "w") as fh:
IOError: [Errno 16] Device or resource busy: '/vmfs/volumes/vsanDatastore/dockvols/volTestP12-c5c4df33013cd893.vmfd'
11/15/16 01:04:09 5892693 [Ubuntu.1404.vsan-[vsanDatastore] dockvols/volTestP12.vmdk] [WARNING] Failed to create metadata kv store for /vmfs/volumes/vsanDatastore/dockvols/volTestP12.vmdk
11/15/16 01:04:09 5892693 [Ubuntu.1404.vsan-[vsanDatastore] dockvols/volTestP12.vmdk] [INFO   ] *** removeVMDK: /vmfs/volumes/vsanDatastore/dockvols/volTestP12.vmdk
11/15/16 01:04:09 5892693 [Ubuntu.1404.vsan-[vsanDatastore] dockvols/volTestP12.vmdk] [WARNING] Meta file /vmfs/volumes/vsanDatastore/dockvols/volTestP12-c5c4df33013cd893.vmfd busy for load(), retrying...
11/15/16 01:04:10 5892693 [Ubuntu.1404.vsan-[vsanDatastore] dockvols/volTestP12.vmdk] [WARNING] Meta file /vmfs/volumes/vsanDatastore/dockvols/volTestP12-c5c4df33013cd893.vmfd busy for load(), retrying...
11/15/16 01:04:13 5892693 [Ubuntu.1404.vsan-[vsanDatastore] dockvols/volTestP12.vmdk] [WARNING] Meta file /vmfs/volumes/vsanDatastore/dockvols/volTestP12-c5c4df33013cd893.vmfd busy for load(), retrying...
11/15/16 01:04:14 5892693 [Ubuntu.1404.vsan-[vsanDatastore] dockvols/volTestP12.vmdk] [ERROR  ] Failed to decode meta-data for /vmfs/volumes/vsanDatastore/dockvols/volTestP12.vmdk
Traceback (most recent call last):
  File "/usr/lib/vmware/vmdkops/Python/kvESX.py", line 282, in load
    return json.loads(kv_str)
  File "/build/mts/release/bora-3620759/bora/build/esx/release/vmvisor/sys-boot/lib/python2.7/json/__init__.py", line 338, in loads
  File "/build/mts/release/bora-3620759/bora/build/esx/release/vmvisor/sys-boot/lib/python2.7/json/decoder.py", line 366, in decode
  File "/build/mts/release/bora-3620759/bora/build/esx/release/vmvisor/sys-boot/lib/python2.7/json/decoder.py", line 384, in raw_decode
ValueError: No JSON object could be decoded
11/15/16 01:04:32 5892693 [Ubuntu.1404.vsan-[vsanDatastore] dockvols/volTestP12.vmdk] [INFO   ] executeRequest 'create' completed with ret={u'Error': 'Failed to create metadata kv store for /vmfs/volumes/vsanDatastore/dockvols/volTestP12.vmdk'}
11/15/16 01:04:33 5892693 [Ubuntu.1404.vsan-[vsanDatastore] dockvols/volTestP12.vmdk] [INFO   ] executeRequest 'get' completed with ret={u'Error': 'Volume volTestP12 not found (file: /vmfs/volumes/vsanDatastore/dockvols/volTestP12.vmdk)'}
11/15/16 01:04:33 5892693 [photon.ga.vsan-[vsanDatastore] dockvols/volTestP02.vmdk] [INFO   ] executeRequest 'create' completed with ret=None
11/15/16 01:04:33 5892693 [photon.ga.vsan-[vsanDatastore] dockvols/volTestP02.vmdk] [INFO   ] *** attachVMDK: /vmfs/volumes/vsanDatastore/dockvols/volTestP02.vmdk to photon.ga.vsan VM uuid = 564d5ef2-89dc-1cfa-abc6-1289c486759b
11/15/16 01:04:34 5892693 [photon.ga.vsan-[vsanDatastore] dockvols/volTestP02.vmdk] [INFO   ] Attaching /vmfs/volumes/vsanDatastore/dockvols/volTestP02.vmdk as independent_persistent

@govint
Copy link
Contributor

govint commented Nov 24, 2016

Possibly could spawn an lsof during the retry loop to figure which process has the file open

@brunotm
Copy link
Contributor

brunotm commented Nov 24, 2016 •
edited
Loading

@govint
That's a very good idea. I can put something in vmdk_utils for that. Thanks again!

@brunotm brunotm mentioned this issue Nov 24, 2016
Merged
@brunotm
Copy link
Contributor

brunotm commented Nov 24, 2016

@govint @kerneltime
Below are the relevant parts from #778 build 498. Unfortunately it didn't fail or the behaviour manifested on the vsan part. But it does give an idea.

11/15/16 00:36:47 5886324 [photon.ga.vmfs-[datastore1] dockvols/volTestP02.vmdk] [WARNING] Meta file /vmfs/volumes/datastore1/dockvols/volTestP02-faf6ee7a5f488839.vmfd busy for save(), retrying...
11/15/16 00:36:47 5886324 [photon.ga.vmfs-[datastore1] dockvols/volTestP02.vmdk] [INFO   ] Volume open descriptor: cartel=5891527, name=vmkfstools, type=FILE, fd=14, desc=/vmfs/volumes/575db611-d1ad6cf9-0c74-000c29e3609e/dockvols/volTestP02-flat.vmdk
11/15/16 00:36:47 5886324 [photon.ga.vmfs-[datastore1] dockvols/volTestP02.vmdk] [INFO   ] Volume open descriptor: cartel=5891527, name=vmkfstools, type=FILE, fd=16, desc=/vmfs/volumes/575db611-d1ad6cf9-0c74-000c29e3609e/dockvols/volTestP02-faf6ee7a5f488839.vmfd
11/15/16 00:36:47 5886324 [photon.ga.vmfs-[datastore1] dockvols/volTestP02.vmdk] [INFO   ] Volume open descriptor: cartel=5891526, name=sh, type=FILE, fd=14, desc=/vmfs/volumes/575db611-d1ad6cf9-0c74-000c29e3609e/dockvols/volTestP02-flat.vmdk
11/15/16 00:36:47 5886324 [photon.ga.vmfs-[datastore1] dockvols/volTestP02.vmdk] [INFO   ] Volume open descriptor: cartel=5891526, name=sh, type=FILE, fd=16, desc=/vmfs/volumes/575db611-d1ad6cf9-0c74-000c29e3609e/dockvols/volTestP02-faf6ee7a5f488839.vmfd
11/15/16 00:36:48 5886324 [photon.ga.vmfs-[datastore1] dockvols/volTestP02.vmdk] [WARNING] Meta file /vmfs/volumes/datastore1/dockvols/volTestP02-faf6ee7a5f488839.vmfd busy for save(), retrying...
11/15/16 00:36:48 5886324 [photon.ga.vmfs-[datastore1] dockvols/volTestP02.vmdk] [INFO   ] executeRequest 'create' completed with ret=None


11/15/16 00:36:56 5886324 [photon.ga.vmfs-[datastore1] dockvols/volTestP03.vmdk] [WARNING] Meta file /vmfs/volumes/datastore1/dockvols/volTestP03-fbc99b045c30ef99.vmfd busy for save(), retrying...
11/15/16 00:36:56 5886324 [photon.ga.vmfs-[datastore1] dockvols/volTestP03.vmdk] [INFO   ] Volume open descriptor: cartel=5891577, name=vmkfstools, type=FILE, fd=14, desc=/vmfs/volumes/575db611-d1ad6cf9-0c74-000c29e3609e/dockvols/volTestP03-flat.vmdk
11/15/16 00:36:56 5886324 [photon.ga.vmfs-[datastore1] dockvols/volTestP03.vmdk] [INFO   ] Volume open descriptor: cartel=5891577, name=vmkfstools, type=FILE, fd=16, desc=/vmfs/volumes/575db611-d1ad6cf9-0c74-000c29e3609e/dockvols/volTestP03-fbc99b045c30ef99.vmfd
11/15/16 00:36:56 5886324 [photon.ga.vmfs-[datastore1] dockvols/volTestP03.vmdk] [INFO   ] Volume open descriptor: cartel=5891576, name=sh, type=FILE, fd=14, desc=/vmfs/volumes/575db611-d1ad6cf9-0c74-000c29e3609e/dockvols/volTestP03-flat.vmdk
11/15/16 00:36:56 5886324 [photon.ga.vmfs-[datastore1] dockvols/volTestP03.vmdk] [INFO   ] Volume open descriptor: cartel=5891576, name=sh, type=FILE, fd=16, desc=/vmfs/volumes/575db611-d1ad6cf9-0c74-000c29e3609e/dockvols/volTestP03-fbc99b045c30ef99.vmfd
11/15/16 00:36:57 5886324 [photon.ga.vmfs-[datastore1] dockvols/volTestP03.vmdk] [INFO   ] executeRequest 'create' completed with ret=None


11/15/16 00:37:30 5886324 [Ubuntu.1404.vmfs-[datastore1] dockvols/volTestP17.vmdk] [WARNING] Meta file /vmfs/volumes/datastore1/dockvols/volTestP17-21a9022b8fe11a00.vmfd busy for save(), retrying...
11/15/16 00:37:30 5886324 [Ubuntu.1404.vmfs-[datastore1] dockvols/volTestP17.vmdk] [INFO   ] Volume open descriptor: cartel=5891807, name=vmkfstools, type=FILE, fd=14, desc=/vmfs/volumes/575db611-d1ad6cf9-0c74-000c29e3609e/dockvols/volTestP17-flat.vmdk
11/15/16 00:37:30 5886324 [Ubuntu.1404.vmfs-[datastore1] dockvols/volTestP17.vmdk] [INFO   ] Volume open descriptor: cartel=5891807, name=vmkfstools, type=FILE, fd=17, desc=/vmfs/volumes/575db611-d1ad6cf9-0c74-000c29e3609e/dockvols/volTestP17-21a9022b8fe11a00.vmfd
11/15/16 00:37:30 5886324 [Ubuntu.1404.vmfs-[datastore1] dockvols/volTestP17.vmdk] [INFO   ] Volume open descriptor: cartel=5891806, name=sh, type=FILE, fd=14, desc=/vmfs/volumes/575db611-d1ad6cf9-0c74-000c29e3609e/dockvols/volTestP17-flat.vmdk
11/15/16 00:37:30 5886324 [Ubuntu.1404.vmfs-[datastore1] dockvols/volTestP17.vmdk] [INFO   ] Volume open descriptor: cartel=5891806, name=sh, type=FILE, fd=17, desc=/vmfs/volumes/575db611-d1ad6cf9-0c74-000c29e3609e/dockvols/volTestP17-21a9022b8fe11a00.vmfd
11/15/16 00:37:31 5886324 [Ubuntu.1404.vmfs-[datastore1] dockvols/volTestP17.vmdk] [WARNING] Meta file /vmfs/volumes/datastore1/dockvols/volTestP17-21a9022b8fe11a00.vmfd busy for save(), retrying...
11/15/16 00:37:32 5886324 [Ubuntu.1404.vmfs-[datastore1] dockvols/volTestP17.vmdk] [INFO   ] executeRequest 'create' completed with ret=None

@brunotm brunotm mentioned this issue Dec 3, 2016
Merged
# for free to subscribe to this conversation on GitHub. Already have an account? #.
Assignees
No one assigned
Labels
kind/bug
Projects
None yet
Milestone
0.10
Development

Successfully merging a pull request may close this issue.

Use VirtualDiskManager API in vmdk_ops. brunotm/docker-volume-vsphere
3 participants
@kerneltime @brunotm @govint