File system for created volume is N/A #1615

ashahi1 · 2017-07-21T01:11:13Z

Steps:

Verified that there are no volumes.
Ran a container by passing -v option - Command throws an error docker: Error response from daemon: create Vol22@sharedVmfs-0: Post http://%2Frun%2Fdocker%2Fplugins%2Fa2341bfd26d15ba333e64eb30eb53e8174d87716ed1168313e9fecc779f7b759%2Fvsphere.sock/VolumeDriver.Create: http: ContentLength=42 with Body length 0.
Admin cli and docker cli lists the volume
File system for volume is listed as N/A on admin cli

Steps and their output are as follows:

Verified that there are no volumes

root@sc-rdops-vm02-dhcp-52-237:~# docker volume ls
DRIVER              VOLUME NAME
root@sc-rdops-vm02-dhcp-52-237:~#

Ran a container by passing -v option and specifying volume name as - Vol22@sharedVmfs-0

root@sc-rdops-vm02-dhcp-52-237:~# docker run -it --volume-driver=vsphere -v Vol22@sharedVmfs-0:/v1 --name=abc busybox
docker: Error response from daemon: create Vol22@sharedVmfs-0: Post http://%2Frun%2Fdocker%2Fplugins%2Fa2341bfd26d15ba333e64eb30eb53e8174d87716ed1168313e9fecc779f7b759%2Fvsphere.sock/VolumeDriver.Create: http: ContentLength=42 with Body length 0.
See 'docker run --help'.

Admin cli ls and docker volume ls lists the volume - Vol22@sharedVmfs-0

[root@sc2-rdops-vm01-dhcp-40-37:~] /usr/lib/vmware/vmdkops/bin/vmdkops_admin.py volume ls
Volume  Datastore     VMGroup   Capacity  Used  Filesystem  Policy  Disk Format  Attached-to   Access      Attach-as               Created By    Created Date
------  ------------  --------  --------  ----  ----------  ------  -----------  ------------  ----------  ----------------------  ------------  ------------------------
Vol22   sharedVmfs-0  _DEFAULT  100MB     0     N/A         N/A     thin         ubuntu-VM2.2  read-write  independent_persistent  ubuntu-VM2.2  Fri Jul 21 00:49:52 2017

[root@sc2-rdops-vm01-dhcp-40-37:~]


root@sc-rdops-vm02-dhcp-52-237:~# docker volume ls
DRIVER              VOLUME NAME
vsphere:latest      Vol22@sharedVmfs-0
root@sc-rdops-vm02-dhcp-52-237:~#

Docker volume inspect lists volume as attached.

root@sc-rdops-vm02-dhcp-52-237:~# docker volume inspect Vol22@sharedVmfs-0
[
    {
        "Driver": "vsphere:latest",
        "Labels": null,
        "Mountpoint": "/mnt/vmdk/Vol22@sharedVmfs-0",
        "Name": "Vol22@sharedVmfs-0",
        "Options": {},
        "Scope": "global",
        "Status": {
            "access": "read-write",
            "attach-as": "independent_persistent",
            "attached to VM": "ubuntu-VM2.2",
            "attachedVMDevice": {
                "ControllerPciSlotNumber": "160",
                "Unit": "0"
            },
            "capacity": {
                "allocated": "0",
                "size": "100MB"
            },
            "clone-from": "None",
            "created": "Fri Jul 21 00:49:52 2017",
            "created by VM": "ubuntu-VM2.2",
            "datastore": "sharedVmfs-0",
            "diskformat": "thin",
            "status": "attached"     <<<<<<<<<<<<<<<<<<<<<<<<
        }
    }
]
root@sc-rdops-vm02-dhcp-52-237:~#

Verified that no containers are running

root@sc-rdops-vm02-dhcp-52-237:~# docker ps -a
CONTAINER ID        IMAGE               COMMAND             CREATED             STATUS              PORTS               NAMES
root@sc-rdops-vm02-dhcp-52-237:~#

Logs:
docker-volume-vsphere.txt
vmdk_ops.txt

The text was updated successfully, but these errors were encountered:

govint · 2017-07-21T04:40:11Z

The last logs from both the service and the plugin show that the volume was attached to ubuntu VM2.2 for formatting and there are no more plugin logs after that. Obviously there won't be an FS on the volume as formatting hasn't completed.

2017-07-20 17:49:52.023570077 -0700 PDT [INFO] Attaching volume and creating filesystem fstype= name="Vol22@sharedVmfs-0"
2017-07-20 17:49:52.531810723 -0700 PDT [INFO] Scan complete device="/dev/disk/by-path/pci-0000:03:00.0-scsi-0:0:0:0" event="/dev/disk/by-path/pci-0000:03:00.0-scsi-0:0:0:0": 0x100 == IN_CREATE

Before this, the plugin logs show another issue where the plugin wants to remove a volume sVmotionVol2233 thats in use by the same VM - was this intentional

2017-07-20 17:45:08.123023396 -0700 PDT [INFO] Successfully retrieved mountsmap=map[]
2017-07-20 17:45:08.123040542 -0700 PDT [INFO] Discovered 0 volumes in use.
2017-07-20 17:45:08.123045888 -0700 PDT [INFO] Refcounting successfully completed
2017-07-20 17:45:08.123054215 -0700 PDT [INFO] Docker VMDK plugin started version="vSphere Volume Driver v0.5" port=1019 mock_esx=false
2017-07-20 17:45:08.123127782 -0700 PDT [INFO] Going into ServeUnix - Listening on Unix socket address="/run/docker/plugins/vsphere.sock"
2017-07-20 17:45:33.377613041 -0700 PDT [INFO] Removing volume name="sVmotionVol2233@sharedVmfs-0"
2017-07-20 17:45:33.475507734 -0700 PDT [ERROR] Failed to remove volume name="sVmotionVol2233@sharedVmfs-0" error="Failed to remove volume sVmotionVol2233, in use by VM = ubuntu-VM2.2."
2017-07-20 17:45:33.948459076 -0700 PDT [INFO] Removing volume name="sVmotionVol22@sharedVmfs-0"
2017-07-20 17:45:34.407685985 -0700 PDT [INFO] Removing volume name="sVmotionVol22@sharedVmfs-1"
2017-07-20 17:45:34.891577315 -0700 PDT [INFO] Removing volume name="sVmotionVol33@sharedVmfs-0"
2017-07-20 17:45:34.991637775 -0700 PDT [ERROR] Failed to remove volume name="sVmotionVol33@sharedVmfs-0" error="Failed to remove volume sVmotionVol33, in use by VM = ubuntu-VM2.2."
2017-07-20 17:45:35.344471003 -0700 PDT [INFO] Removing volume name="sVmotionVolXXXX@sharedVmfs-0"

shuklanirdesh82 · 2017-07-21T04:52:19Z

@govint shouldn't we need to block the volume creation from docker run command?

ashahi1 · 2017-07-21T05:48:54Z

@govint Yes, I was trying to remove volume sVmotionVol2233

govint · 2017-07-21T06:34:17Z

@shuklanirdesh82, in this case docker volume create command hasn't complete yet, so docker has correctly reported a creation error.

Why creation failed, there are no logs.

ashahi1 · 2017-07-21T07:26:46Z

@govint Fresh logs have been uploaded.

Logs:
docker-volume-vsphere.txt
vmdk_ops.txt

Volume name: Vol22@sharedVmfs-0
Error: docker: Error response from daemon: create Vol22@sharedVmfs-0: Post http://%2Frun%2Fdocker%2Fplugins%2Fd6b3f5a58ff311a4ef2e52e13c68255de2fe4185c28628b6208bd4ea505c9663%2Fvsphere.sock/VolumeDriver.Create: http: ContentLength=42 with Body length 0.
See 'docker run --help'.

Admin cli volume ls:

[root@sc-rdops-vm04-dhcp-109-225:~] /usr/lib/vmware/vmdkops/bin/vmdkops_admin.py volume ls
Volume  Datastore     VMGroup   Capacity  Used  Filesystem  Policy  Disk Format  Attached-to   Access      Attach-as               Created By    Created Date
------  ------------  --------  --------  ----  ----------  ------  -----------  ------------  ----------  ----------------------  ------------  ------------------------
Vol22   sharedVmfs-0  _DEFAULT  100MB     0     N/A         N/A     thin         ubuntu-VM0.0  read-write  independent_persistent  ubuntu-VM0.0  Fri Jul 21 07:18:48 2017

[root@sc-rdops-vm04-dhcp-109-225:~]

govint · 2017-07-24T06:12:19Z

@ashahi1, these new logs don't have anything beyond the FS creation step in the plugin logs, seems to be something specific to this setup.

On my photon VM, same command:
root@photon-machine [ /vol/vpl-testbed/docker-volume-vsphere ]# docker run -it --volume-driver=vsphere -v Vol22@sharedVmfs-0:/v1 --name=abc busybox
/ #

docker volume inspect Vol22@sharedVmfs-0
[
{
"Driver": "vsphere:latest",
"Labels": null,
"Mountpoint": "/mnt/vmdk/Vol22@sharedVmfs-0",
"Name": "Vol22@sharedVmfs-0",
"Options": {},
"Scope": "global",
"Status": {
"access": "read-write",
"attach-as": "independent_persistent",
"attached to VM": "master-VM0.0",
"attachedVMDevice": {
"ControllerPciSlotNumber": "160",
"Unit": "0"
},
"capacity": {
"allocated": "15MB",
"size": "100MB"
},
"clone-from": "None",
"created": "Mon Jul 24 06:10:09 2017",
"created by VM": "master-VM0.0",
"datastore": "sharedVmfs-0",
"diskformat": "thin",
"fstype": "ext4",
"status": "attached"
}
}
]

govint · 2017-07-24T10:21:19Z

Making P1 as the command works and most likely is a set up specific issue.

ashahi1 · 2017-07-25T21:48:10Z

@govint I got the latest code from vmware:master and I could repro the issue on photon as well as ubuntu VMs.
Then I tried to use our 0.15 release builds (https://github.com/vmware/docker-volume-vsphere/releases/tag/0.15) but issue is not reproducible on photon or ubuntu vm.

This looks to be a regression that we are seeing only on latest code on vmware:master.
Changing the property to P0.

govint · 2017-07-26T03:36:56Z

@ashahi1 if the logs are truncated then I'm not sure if it can be debugged, let me try the ToT again.

govint · 2017-07-26T05:12:50Z

Tried the ToT and the plugin is crashing, will debug and fix.
]# ./docker-volume-vsphere
WARN[0000] Failed to load config file /etc/docker-volume-vsphere.conf: open /etc/docker-volume-vsphere.conf: no such file or directory
2017/07/26 05:11:45 http: panic serving @: runtime error: index out of range
goroutine 13 [running]:
net/http.(*conn).serve.func1(0xc420222c00)
/usr/local/go/src/net/http/server.go:1491 +0x12a
panic(0x770e60, 0xc42000c110)
/usr/local/go/src/runtime/panic.go:458 +0x243
github.com/vmware/docker-volume-vsphere/client_plugin/utils/fs.MkfsByDevicePath(0x0, 0x0, 0xc42030e460, 0x16, 0xc4202ecf60, 0x2f, 0x0, 0x0)
/go/src/github.com/vmware/docker-volume-vsphere/client_plugin/utils/fs/fs_linux.go:143 +0x440
github.com/vmware/docker-volume-vsphere/client_plugin/utils/fs.Mkfs(0x0, 0x0, 0xc42030e460, 0x16, 0xc42030f100, 0xc42030f100, 0x0)
/go/src/github.com/vmware/docker-volume-vsphere/client_plugin/utils/fs/fs_linux.go:129 +0x2b1
github.com/vmware/docker-volume-vsphere/client_plugin/drivers/vmdk.(*VolumeDriver).Create(0xc4201ad340, 0xc42030e460, 0x16, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
/go/src/github.com/vmware/docker-volume-vsphere/client_plugin/drivers/vmdk/vmdk_driver.go:384 +0xa2d
github.com/vmware/docker-volume-vsphere/vendor/github.com/docker/go-plugins-helpers/volume.(*Handler).initMux.func1(0xc42030e460, 0x16, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
/go/src/github.com/vmware/docker-volume-vsphere/vendor/github.com/docker/go-plugins-helpers/volume/api.go:94 +0x8d
github.com/vmware/docker-volume-vsphere/vendor/github.com/docker/go-plugins-helpers/volume.(*Handler).handle.func1(0xb4e180, 0xc4202f0750, 0xc4200c70e0)
/go/src/github.com/vmware/docker-volume-vsphere/vendor/github.com/docker/go-plugins-helpers/volume/api.go:132 +0xde
net/http.HandlerFunc.ServeHTTP(0xc42028ae90, 0xb4e180, 0xc4202f0750, 0xc4200c70e0)
/usr/local/go/src/net/http/server.go:1726 +0x44
net/http.(*ServeMux).ServeHTTP(0xc42028cf30, 0xb4e180, 0xc4202f0750, 0xc4200c70e0)
/usr/local/go/src/net/http/server.go:2022 +0x7f
net/http.serverHandler.ServeHTTP(0xc4202c0280, 0xb4e180, 0xc4202f0750, 0xc4200c70e0)
/usr/local/go/src/net/http/server.go:2202 +0x7d
net/http.(*conn).serve(0xc420222c00, 0xb4e740, 0xc420294dc0)
/usr/local/go/src/net/http/server.go:1579 +0x4b7
created by net/http.(*Server).Serve
/usr/local/go/src/net/http/server.go:2293 +0x44d

govint · 2017-07-26T07:25:04Z

Bug is in Docker and the way the request structure is initialized in the plugin.

For docker create, docker sends us an empty map which is initialized in prepareCreateOptions() in the vmdk driver.

For docker run, with volume create option, Docker sends a nil map, and the plugin has a bug where prepareCreateOptions() gets passed the request structure by value vs. as a pointer. So, the request struct gets initialized inside prepareCreateOptions() but the caller (Create()) doesn't see that and accessing the nil options map causes the crash.

Fairly simple issue to handle in the vmdk/photon drivers. The bug in docker can also be fixed and will raise the issue there.

Fixed via #1636

ashahi1 added kind/bug P1 labels Jul 21, 2017

ashahi1 added this to the Sprint - Timon milestone Jul 21, 2017

ashahi1 added P0 and removed P1 labels Jul 21, 2017

govint added P1 and removed P0 labels Jul 24, 2017

ashahi1 added P0 and removed P1 labels Jul 25, 2017

govint self-assigned this Jul 26, 2017

lipingxue mentioned this issue Jul 26, 2017

Fixed request options init for create op. #1636

Merged

govint closed this as completed Jul 27, 2017

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

File system for created volume is N/A #1615

File system for created volume is N/A #1615

ashahi1 commented Jul 21, 2017 •

edited

govint commented Jul 21, 2017

shuklanirdesh82 commented Jul 21, 2017

ashahi1 commented Jul 21, 2017

govint commented Jul 21, 2017

ashahi1 commented Jul 21, 2017 •

edited

govint commented Jul 24, 2017 •

edited

govint commented Jul 24, 2017

ashahi1 commented Jul 25, 2017 •

edited

govint commented Jul 26, 2017

govint commented Jul 26, 2017

govint commented Jul 26, 2017 •

edited

File system for created volume is N/A #1615

File system for created volume is N/A #1615

Comments

ashahi1 commented Jul 21, 2017 • edited

govint commented Jul 21, 2017

shuklanirdesh82 commented Jul 21, 2017

ashahi1 commented Jul 21, 2017

govint commented Jul 21, 2017

ashahi1 commented Jul 21, 2017 • edited

govint commented Jul 24, 2017 • edited

govint commented Jul 24, 2017

ashahi1 commented Jul 25, 2017 • edited

govint commented Jul 26, 2017

govint commented Jul 26, 2017

govint commented Jul 26, 2017 • edited

ashahi1 commented Jul 21, 2017 •

edited

ashahi1 commented Jul 21, 2017 •

edited

govint commented Jul 24, 2017 •

edited

ashahi1 commented Jul 25, 2017 •

edited

govint commented Jul 26, 2017 •

edited