Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

cinder: Volume detection & detach fails w Docker Swarm #913

Closed
dave08 opened this issue Jul 2, 2017 · 34 comments
Closed

cinder: Volume detection & detach fails w Docker Swarm #913

dave08 opened this issue Jul 2, 2017 · 34 comments

Comments

@dave08
Copy link

dave08 commented Jul 2, 2017

Summary

When I create stateful services in swarm mode and they fail, or a node goes down and the service gets rescheduled, the stateful services keep on having cinder errors. This makes it a manual process to remove each of these services manually unmount the volumes with cinder or openstack panel, and redeploy the stacks. If there is a sudden failure, this would effectively defeat the purpose of swarm orchestration...

Bug Reports

Cinder driver fails to detach or detect volume in docker swarm mode. I currently have settings like recommended here.

Version

$ rexray version
REX-Ray
-------  
Binary: /usr/bin/rexray
Flavor: client+agent+controller
SemVer: 0.9.1  
OsArch: Linux-x86_64
Branch: v0.9.1
Commit: 2373541479478b817a8b143629e552f404f75226  
Formed: Fri, 09 Jun 2017 19:23:38 UTC
  
libStorage
----------  
SemVer: 0.6.1
OsArch: Linux-x86_64  
Branch: v0.9.1
Commit: fd26f0ec72b077ffa7c82160fbd12a276e12c2ad
Formed: Fri, 09 Jun 2017 19:23:05 UTC

Expected Behavior

The failed services should restart with the appropriate volumes mounted without any errors.

Actual Behavior

Getting either:
VolumeDriver.Mount: {"Error":"error detaching volume"}
or
VolumeDriver.Mount: {"Error":"open /dev/vdc: no such file or directory"}

@fabio-barile
Copy link

Same issue for me.
If I restart a node from my cluster , rexray is not able to umount the volumes and the scheduling of the container on other nodes fails as the volumes are already attached

@codenrhoden
Copy link
Member

@dave08

Just to confirm, you have the following set your in /etc/rexray/config.yaml file?

libstorage:
  integration:
    volume:
      operations:
        mount:
          preempt: true

This would need to be set on the node where the service is getting restarted/rescheduled to. This allows the new node to steal the volume from the old host, as it can only be mounted in one place at a time.

FWIW, I think you do have that set, because you are seeing the failure as "error detaching volume" -- meaning that it is actually trying to detach from the old host, and that call is failing. Looking at the code just now, I think I see the reason why. I'll have to try and recreate...

@dave08
Copy link
Author

dave08 commented Jul 19, 2017

Yes, it was set, also used ignoreusedcount: true (which can't be set from the plugin...). This problem caused me to switch from openstack to digital ocean, but it would be great if it could be fixed, I could always use some extra swarm nodes on openstack...! Thanks.

@fabio-barile
Copy link

Same behavior for me with openstack.

@fabio-barile
Copy link

On my side I have create the config.yml file using your tool http://rexrayconfig.codedellemc.com/

the confile file is the following :

rexray:
  logLevel: debug
libstorage:
  logging:
    level: debug
  service: cinder
  integration:
    volume:
      operations:
        create:
          default:
            size: 2
        mount:
          preempt: true
        unmount:
          ignoreUsedCount: true

cinder:
      authUrl:              xxxxx
      username:             xxxxx
      password:             xxxxx
      tenantId:            xxxxx
      tenantName:           xxxxx
      identityApiVersion:   3
      domainName:           xxxx
      regionName:           xxxx
      availabilityZoneName: xxxx

I have also try to detach the voume usin the rexray command :

rexray volume detach devops2_mongodb-rs3

it fails with the output:

INFO[0000] updated log level                             logLevel=debug
DEBU[0000] os.args                                       time=1500612245511 val=[rexray volume detach devops2_mongodb-rs3]
DEBU[0000] activating libStorage                         cmd=detach time=1500612245511
DEBU[0000] parseSafeHost - no change                     postParse=unix:///var/run/libstorage/621766146.sock preParse=unix:///var/run/libstorage/621766146.sock time=1500612245514
DEBU[0000] read spec file                                host=unix:///var/run/libstorage/621766146.sock path=/var/run/rexray/rexray.spec time=1500612245514
DEBU[0000] is local unix server active                   sock=/var/run/libstorage/621766146.sock time=1500612245514
DEBU[0000] set host in context                           host=unix:///var/run/libstorage/621766146.sock time=1500612245514
DEBU[0000] set host in config                            host=unix:///var/run/libstorage/621766146.sock time=1500612245514
DEBU[0000] not starting embedded server; already running  host=unix:///var/run/libstorage/621766146.sock time=1500612245514
DEBU[0000] creating libStorage client                    cmd=detach host=unix:///var/run/libstorage/621766146.sock time=1500612245514
DEBU[0000] created scoped scope                          new=libstorage.client parentScopes=rexray,
INFO[0000] configured logging                            host=unix:///var/run/libstorage/621766146.sock libstorage.logging.httpRequests=false libstorage.logging.httpResponses=false libstorage.logging.level=debug time=1500612245575
DEBU[0000] got configured host address                   host=unix:///var/run/libstorage/621766146.sock service=cinder storageDriver=libstorage time=1500612245583
DEBU[0000] disabling tls for unix sockets                host=unix:///var/run/libstorage/621766146.sock service=cinder storageDriver=libstorage time=1500612245585
DEBU[0000] getHost proto == "unix"                       getHost=libstorage-server host=unix:///var/run/libstorage/621766146.sock service=cinder storageDriver=libstorage time=1500612245585
INFO[0000] created libStorage client                     clientType=integration disableKeepAlive=false enableInstanceIDHeaders=true enableLocalDevicesHeaders=true host=unix:///var/run/libstorage/621766146.sock lAddr=libstorage-server logRequests=false logResponses=false lsxMutexPath=/var/run/libstorage/lsx-linux.lock lsxPath=/var/lib/libstorage/lsx-linux service=cinder storageDriver=libstorage time=1500612245599
INFO[0000] registered custom context key                 externalID=Libstorage-Tx internalID=2 keyBitmask=2
INFO[0000] registered custom context key                 externalID=Libstorage-Instanceid internalID=3 keyBitmask=2
INFO[0000] registered custom context key                 externalID=Libstorage-Localdevices internalID=4 keyBitmask=2
INFO[0000] registered custom context key                 externalID=Authorization internalID=5 keyBitmask=2
DEBU[0000] successful connection                         host=unix:///var/run/libstorage/621766146.sock service=cinder storageDriver=libstorage time=1500612245599
INFO[0000] initializing executors cache                  host=unix:///var/run/libstorage/621766146.sock service=cinder storageDriver=libstorage time=1500612245606
DEBU[0000] updating executor                             host=unix:///var/run/libstorage/621766146.sock service=cinder storageDriver=libstorage time=1500612245607
DEBU[0000] waiting on executor lock                      host=unix:///var/run/libstorage/621766146.sock service=cinder storageDriver=libstorage time=1500612245607
DEBU[0000] executor exists, getting local checksum       host=unix:///var/run/libstorage/621766146.sock service=cinder storageDriver=libstorage time=1500612245607
DEBU[0000] getting executor checksum                     host=unix:///var/run/libstorage/621766146.sock service=cinder storageDriver=libstorage time=1500612245608
DEBU[0000] got local executor checksum                   host=unix:///var/run/libstorage/621766146.sock localChecksum=1f7949a40e27d07dda7e223c93e9c4c2 service=cinder storageDriver=libstorage time=1500612245646
DEBU[0000] signalling executor lock                      host=unix:///var/run/libstorage/621766146.sock service=cinder storageDriver=libstorage time=1500612245647
INFO[0000] initializing supported cache                  host=unix:///var/run/libstorage/621766146.sock server=valley-thunder-nu service=cinder storageDriver=libstorage time=1500612245647
DEBU[0000] waiting on executor lock                      host=unix:///var/run/libstorage/621766146.sock server=valley-thunder-nu service=cinder storageDriver=libstorage time=1500612245647 txCR=1500612245 txID=d36704a7-cd13-4ac8-7378-6803451a0458
DEBU[0000] invoking executor cli                         args=[cinder supported] cmd=/var/lib/libstorage/lsx-linux host=unix:///var/run/libstorage/621766146.sock server=valley-thunder-nu service=cinder storageDriver=libstorage time=1500612245647 txCR=1500612245 txID=d36704a7-cd13-4ac8-7378-6803451a0458
DEBU[0000] signalling executor lock                      host=unix:///var/run/libstorage/621766146.sock server=valley-thunder-nu service=cinder storageDriver=libstorage time=1500612245776 txCR=1500612245 txID=d36704a7-cd13-4ac8-7378-6803451a0458
WARN[0000] supported cmd not implemented                 host=unix:///var/run/libstorage/621766146.sock server=valley-thunder-nu service=cinder serviceDriver=cinder storageDriver=libstorage time=1500612245776 txCR=1500612245 txID=d36704a7-cd13-4ac8-7378-6803451a0458
DEBU[0000] cached supported flag                         host=unix:///var/run/libstorage/621766146.sock server=valley-thunder-nu service=cinder storageDriver=libstorage supported=true time=1500612245776 txCR=1500612245 txID=d36704a7-cd13-4ac8-7378-6803451a0458
INFO[0000] initializing instance ID cache                host=unix:///var/run/libstorage/621766146.sock server=valley-thunder-nu service=cinder storageDriver=libstorage time=1500612245776
DEBU[0000] waiting on executor lock                      host=unix:///var/run/libstorage/621766146.sock server=valley-thunder-nu service=cinder storageDriver=libstorage time=1500612245776 txCR=1500612245 txID=706cb15c-4172-4198-7722-ec06fcc8575e
DEBU[0000] invoking executor cli                         args=[cinder instanceID] cmd=/var/lib/libstorage/lsx-linux host=unix:///var/run/libstorage/621766146.sock server=valley-thunder-nu service=cinder storageDriver=libstorage time=1500612245776 txCR=1500612245 txID=706cb15c-4172-4198-7722-ec06fcc8575e
DEBU[0000] signalling executor lock                      host=unix:///var/run/libstorage/621766146.sock server=valley-thunder-nu service=cinder storageDriver=libstorage time=1500612246041 txCR=1500612245 txID=706cb15c-4172-4198-7722-ec06fcc8575e
DEBU[0000] cached instanceID                             host=unix:///var/run/libstorage/621766146.sock instanceID=cinder=a1bfd46d-a167-47b2-980a-0fa8a858bf50 server=valley-thunder-nu service=cinder storageDriver=libstorage time=1500612246041 txCR=1500612245 txID=706cb15c-4172-4198-7722-ec06fcc8575e
DEBU[0000] xli instanceID success                        host=unix:///var/run/libstorage/621766146.sock instanceID=cinder=a1bfd46d-a167-47b2-980a-0fa8a858bf50 server=valley-thunder-nu service=cinder storageDriver=libstorage time=1500612246041 txCR=1500612245 txID=706cb15c-4172-4198-7722-ec06fcc8575e
INFO[0000] successefully dialed libStorage server        host=unix:///var/run/libstorage/621766146.sock server=valley-thunder-nu service=cinder storageDriver=libstorage time=1500612246041
INFO[0000] storage driver initialized                    host=unix:///var/run/libstorage/621766146.sock service=cinder storageDriver=libstorage time=1500612246041
INFO[0000] os driver initialized                         host=unix:///var/run/libstorage/621766146.sock osDriver=linux service=cinder storageDriver=libstorage time=1500612246044
INFO[0000] linux integration driver successfully initialized  host=unix:///var/run/libstorage/621766146.sock integrationDriver=linux libstorage.integration.volume.operations.create.default.IOPS=0 libstorage.integration.volume.operations.create.default.availabilityZone= libstorage.integration.volume.operations.create.default.fsType=ext4 libstorage.integration.volume.operations.create.default.size=2 libstorage.integration.volume.operations.create.default.type= libstorage.integration.volume.operations.create.implicit=true libstorage.integration.volume.operations.mount.path=/var/lib/libstorage/volumes libstorage.integration.volume.operations.mount.rootPath=/data osDriver=linux service=cinder storageDriver=libstorage time=1500612246077
INFO[0000] path cache initializion disabled              host=unix:///var/run/libstorage/621766146.sock integrationDriver=linux osDriver=linux service=cinder storageDriver=libstorage time=1500612246083
INFO[0000] libStorage integration driver successfully initialized  host=unix:///var/run/libstorage/621766146.sock integrationDriver=linux libstorage.integration.volume.operations.create.disable=false libstorage.integration.volume.operations.mount.preempt=true libstorage.integration.volume.operations.path.cache.async=true libstorage.integration.volume.operations.path.cache.enabled=false libstorage.integration.volume.operations.remove.disable=false libstorage.integration.volume.operations.unmount.ignoreusedcount=true osDriver=linux service=cinder storageDriver=libstorage time=1500612246102
INFO[0000] integration driver initialized                host=unix:///var/run/libstorage/621766146.sock integrationDriver=linux osDriver=linux service=cinder storageDriver=libstorage time=1500612246102
INFO[0000] created libStorage client                     host=unix:///var/run/libstorage/621766146.sock integrationDriver=linux osDriver=linux service=cinder storageDriver=libstorage time=1500612246102
DEBU[0000] waiting on executor lock                      host=unix:///var/run/libstorage/621766146.sock instanceID=cinder=a1bfd46d-a167-47b2-980a-0fa8a858bf50 integrationDriver=linux osDriver=linux server=valley-thunder-nu service=cinder storageDriver=libstorage time=1500612246102 txCR=1500612246 txID=912f35b5-581a-4705-4d4f-1a5b19d4c633
DEBU[0000] invoking executor cli                         args=[cinder localDevices quick] cmd=/var/lib/libstorage/lsx-linux host=unix:///var/run/libstorage/621766146.sock instanceID=cinder=a1bfd46d-a167-47b2-980a-0fa8a858bf50 integrationDriver=linux osDriver=linux server=valley-thunder-nu service=cinder storageDriver=libstorage time=1500612246103 txCR=1500612246 txID=912f35b5-581a-4705-4d4f-1a5b19d4c633
DEBU[0000] signalling executor lock                      host=unix:///var/run/libstorage/621766146.sock instanceID=cinder=a1bfd46d-a167-47b2-980a-0fa8a858bf50 integrationDriver=linux osDriver=linux server=valley-thunder-nu service=cinder storageDriver=libstorage time=1500612246230 txCR=1500612246 txID=912f35b5-581a-4705-4d4f-1a5b19d4c633
WARN[0000] removing local device w/ invalid volume id    deviceID=/dev/sda host=unix:///var/run/libstorage/621766146.sock instanceID=cinder=a1bfd46d-a167-47b2-980a-0fa8a858bf50 integrationDriver=linux osDriver=linux server=valley-thunder-nu service=cinder storageDriver=libstorage time=1500612246230 txCR=1500612246 txID=912f35b5-581a-4705-4d4f-1a5b19d4c633
WARN[0000] removing local device w/ invalid volume id    deviceID=/dev/sda1 host=unix:///var/run/libstorage/621766146.sock instanceID=cinder=a1bfd46d-a167-47b2-980a-0fa8a858bf50 integrationDriver=linux osDriver=linux server=valley-thunder-nu service=cinder storageDriver=libstorage time=1500612246230 txCR=1500612246 txID=912f35b5-581a-4705-4d4f-1a5b19d4c633
DEBU[0000] xli localdevices success                      host=unix:///var/run/libstorage/621766146.sock instanceID=cinder=a1bfd46d-a167-47b2-980a-0fa8a858bf50 integrationDriver=linux osDriver=linux server=valley-thunder-nu service=cinder storageDriver=libstorage time=1500612246231 txCR=1500612246 txID=912f35b5-581a-4705-4d4f-1a5b19d4c633
DEBU[0001] waiting on executor lock                      host=unix:///var/run/libstorage/621766146.sock instanceID=cinder=a1bfd46d-a167-47b2-980a-0fa8a858bf50 integrationDriver=linux osDriver=linux server=valley-thunder-nu service=cinder storageDriver=libstorage time=1500612246785 txCR=1500612246 txID=a25acd3b-7094-4b9d-7135-3a12b230840a
DEBU[0001] invoking executor cli                         args=[cinder localDevices quick] cmd=/var/lib/libstorage/lsx-linux host=unix:///var/run/libstorage/621766146.sock instanceID=cinder=a1bfd46d-a167-47b2-980a-0fa8a858bf50 integrationDriver=linux osDriver=linux server=valley-thunder-nu service=cinder storageDriver=libstorage time=1500612246785 txCR=1500612246 txID=a25acd3b-7094-4b9d-7135-3a12b230840a
DEBU[0001] signalling executor lock                      host=unix:///var/run/libstorage/621766146.sock instanceID=cinder=a1bfd46d-a167-47b2-980a-0fa8a858bf50 integrationDriver=linux osDriver=linux server=valley-thunder-nu service=cinder storageDriver=libstorage time=1500612246913 txCR=1500612246 txID=a25acd3b-7094-4b9d-7135-3a12b230840a
WARN[0001] removing local device w/ invalid volume id    deviceID=/dev/sda host=unix:///var/run/libstorage/621766146.sock instanceID=cinder=a1bfd46d-a167-47b2-980a-0fa8a858bf50 integrationDriver=linux osDriver=linux server=valley-thunder-nu service=cinder storageDriver=libstorage time=1500612246913 txCR=1500612246 txID=a25acd3b-7094-4b9d-7135-3a12b230840a
WARN[0001] removing local device w/ invalid volume id    deviceID=/dev/sda1 host=unix:///var/run/libstorage/621766146.sock instanceID=cinder=a1bfd46d-a167-47b2-980a-0fa8a858bf50 integrationDriver=linux osDriver=linux server=valley-thunder-nu service=cinder storageDriver=libstorage time=1500612246914 txCR=1500612246 txID=a25acd3b-7094-4b9d-7135-3a12b230840a
DEBU[0001] xli localdevices success                      host=unix:///var/run/libstorage/621766146.sock instanceID=cinder=a1bfd46d-a167-47b2-980a-0fa8a858bf50 integrationDriver=linux osDriver=linux server=valley-thunder-nu service=cinder storageDriver=libstorage time=1500612246914 txCR=1500612246 txID=a25acd3b-7094-4b9d-7135-3a12b230840a
DEBU[0001] built output template                         host=unix:///var/run/libstorage/621766146.sock template={{define "printStringSlice"}}{{.}}{{end}}{{define "printEncVolumeWithPathFields"}}{{.ID}}      {{.Name}}       {{.Volume.AttachmentState | printAttState}}     {{.Size}}       {{.Encrypted}}  {{.Path}}{{end}}{{define "printServiceFields"}}{{.Name}}        {{.Driver.Name}}{{end}}{{define "printScriptFields"}}{{.Path}}  {{.Installed}}  {{.Modified}}{{end}}{{define "printAuthTokenFields"}}{{.Subject}}       {{.IssuedAt}}   {{.NotBefore}}  {{.Expires}}{{end}}{{define "printObject"}}{{printf "%v" .}}{{end}}{{define "printEncVolumeFields"}}{{.ID}}     {{.Name}}       {{.AttachmentState | printAttState}}    {{.Size}}       {{.Encrypted}}{{end}}{{define "printMountFields"}}{{.ID}}       {{.Source}}     {{.MountPoint}}{{end}}{{define "printVolumeWithPathFields"}}{{.ID}}     {{.Name}}       {{.Volume.AttachmentState | printAttState}}     {{.Size}}       {{.Path}}{{end}}{{define "printVolumeID"}}{{.ID}}{{end}}{{define "printSnapshotFields"}}{{.ID}} {{.Name}}       {{.Status}}     {{.VolumeID}}{{end}}{{define "printJSON"}}{{. | json}}{{end}}{{define "printVolumeFields"}}{{.ID}}      {{.Name}}       {{.AttachmentState | printAttState}}    {{.Size}}{{end}}{{define "printInstanceFields"}}{{.InstanceID.ID}}      {{.Name}}      {{.ProviderName}}        {{.Region}}{{end}}{{define "printPrettyJSON"}}{{. | jsonp}}{{end}}ID    Name    Status  Size
{{range sort .D "Name" }}{{template "printVolumeFields" .}}
{{end}} time=1500612247149
ID  Name  Status  Size
FATA[0001] error detaching volume                        error.inner.instanceId=a1bfd46d-a167-47b2-980a-0fa8a858bf50 error.inner.provider=cinder error.inner.volumeId=692cb61c-5777-4fd4-bcdb-7b6bbb75a93a error.status=500 volume=devops2_mongodb-rs3


@fabio-barile
Copy link

According to the log above, I can see that the command fail because it is not able to remove the local device .


WARN[0001] removing local device w/ invalid volume id    deviceID=/dev/sda host=unix:///var/run/libstorage/621766146.sock instanceID=cinder=a1bfd46d-a167-47b2-980a-0fa8a858bf50 integrationDriver=linux osDriver=linux server=valley-thunder-nu service=cinder storageDriver=libstorage time=1500612246913 txCR=1500612246 txID=a25acd3b-7094-4b9d-7135-3a12b230840a
WARN[0001] removing local device w/ invalid volume id    deviceID=/dev/sda1 host=unix:///var/run/libstorage/621766146.sock instanceID=cinder=a1bfd46d-a167-47b2-980a-0fa8a858bf50 integrationDriver=linux osDriver=linux server=valley-thunder-nu service=cinder storageDriver=libstorage time=1500612246914 txCR=1500612246 txID=a25acd3b-7094-4b9d-7135-3a12b230840a

I have tried to execute the detach command from the host where is attached the volume and it works fine.

So to summarize this issue, rexray is not able to detach a volume mounted on a REMOTE host

@fabio-barile
Copy link

hi @codenrhoden
let's me know if you need additional test for this issue, I would like to use rexray on a production system so I am really waiting for a fix :)
Do you have an idea when such fix could be released ?

Regards

@codenrhoden codenrhoden added this to the 2017.09-1 milestone Jul 21, 2017
@MatMaul
Copy link
Contributor

MatMaul commented Jul 21, 2017

is /dev/sda(1) the good one to unmount ?

@fabio-barile
Copy link

Yes but on a remote server ( the one to which is attached the device)

@akutz
Copy link
Member

akutz commented Aug 9, 2017

Hi @MatMaul,

Do you have the bandwidth to address this issue?

@MatMaul
Copy link
Contributor

MatMaul commented Aug 10, 2017

Not yet. For now I can't test anything with master (cf #935), I'll have a look once I can ;)
It is perhaps fix by my patch since it looks related to device name handling, TBC.
There is also #863 regarding failure after the initial token expired.

@unkusr007
Copy link

unkusr007 commented Sep 1, 2017

Hello,

I might have found the issue: https://github.com/codedellemc/rexray/blob/e8d7a016221ac2ff82e243466cff2d5d214da75d/libstorage/drivers/storage/cinder/storage/cinder_storage.go#L643

the volumeID is used for detaching, but the attachmentID is needed for this method:
https://github.com/gophercloud/gophercloud/blob/master/openstack/compute/v2/extensions/volumeattach/doc.go

I'm not sure about this since i'm not a Go developer, I hope it will help.

@MatMaul
Copy link
Contributor

MatMaul commented Sep 6, 2017

You are completely right. If you want to try to fix it and send a PR be my guest, otherwise let me know I'll fix it.
It probably involves storing a map of (volumeID, serverID)->attachmentID after attaching to avoid doing one more call to fetch the attachment ID.

@unkusr007
Copy link

Hello, in fact i'm not right at all :)
I changed the code, and it's gophercloud that has an error into documentation.
After reviewing the whole api calls, volumeId the indeed the good one, but the problem is related to instance Id, cinder must reuse the instance id provided into the attachment structure, and not the one provided by the auth.
Even with this fix, there's more issues later, related to the mount.

@codenrhoden
Copy link
Member

I'm wondering if this is also fixed by #935.

@benoitm76
Copy link

Same problem for me.

When a node of my swarm cluster crashes for any reason, Libstorage is not able to detach the volume of the dead node to attach it elsewhere. I have all the time the error:

VolumeDriver.Mount: {"Error":"resource not found"}

But if I detach manually the volume it's working.

@codenrhoden I am using the latest unstable version of Rexray. I don't know if the fix #935 is include in this version.

REX-Ray
-------
Binary: /usr/bin/rexray
Flavor: client+agent+controller
SemVer: 0.10.0-rc2+7
OsArch: Linux-x86_64
Commit: 97dbe46866327f61e3a9ea93cc34ef69d372cc5a
Formed: Fri, 08 Sep 2017 05:18:11 UTC

@akutz
Copy link
Member

akutz commented Sep 8, 2017

Hi @benoitm76,

It's not the latest version. There was a big fix around idempotency in commit 97dbe46 around midnight earlier this morning.

@MatMaul
Copy link
Contributor

MatMaul commented Sep 13, 2017

A new version with a cinder fix has been released, if you can check if it helps.
@bastiflew instanceID should be stable so I don't think there is a problem there, or we have a flaw in the code fetching the instance ID.

@n1b0r
Copy link

n1b0r commented Sep 14, 2017

Hello, I'm still getting the error detaching volume when service is rescheduled on a node where volume is not yet attached.

Here is my test case.
Three nodes swarm managed (all managers).
On each node:

$ docker plugin install rexray/cinder \
	CINDER_AUTHURL=******** \
	CINDER_USERNAME=******** \
	CINDER_PASSWORD=******** \
	CINDER_TENANTNAME=******** \
	CINDER_TENANTID=******** \
	CINDER_REGIONNAME=******** \
	REXRAY_PREEMPT=true \
	REXRAY_LOGLEVEL=debug

$ docker volume ls
DRIVER                 VOLUME NAME
rexray/cinder:latest   test-cinder-volume

Start test service :

docker service create \
    --name test \
    --mount type=volume,source=test-cinder-volume,destination=/tmp/test,volume-driver=rexray/cinder \
    jwilder/whoami
debian@test-cinder1:~$ docker service ps --no-trunc test
ID                          NAME                IMAGE                                                                                           NODE                DESIRED STATE       CURRENT STATE            ERROR               PORTS
gbges5q0mjw325w5q7o4ufqet   test.1              jwilder/whoami:latest@sha256:1ae692d7db4f4f77f512bf4ac1283e6eacb8d5c04971976750297505eea3b86a   test-cinder2        Running             Running 10 seconds ago  

Shutdown node test-cinder2

Then

debian@test-cinder1:~$ docker service ps --no-trunc test
ID                          NAME                IMAGE                                                                                           NODE                DESIRED STATE       CURRENT STATE          ERROR               PORTS
o2dqpvi6cxdnyribu4czndpg3   test.1              jwilder/whoami:latest@sha256:1ae692d7db4f4f77f512bf4ac1283e6eacb8d5c04971976750297505eea3b86a   test-cinder4        Ready               Starting less than a second ago                         
68to2je5ot746oxyhzx940z7a    \_ test.1          jwilder/whoami:latest@sha256:1ae692d7db4f4f77f512bf4ac1283e6eacb8d5c04971976750297505eea3b86a   test-cinder4        Shutdown            Failed 2 seconds ago   "starting container failed: error while mounting volume '/var/lib/docker/plugins/ac336cabd13905a77d45fae939eb8637c511908cbd1ae49f105a54a1bf8230c1/rootfs': VolumeDriver.Mount: {"Error":"error detaching volume"}
"                           
gbges5q0mjw325w5q7o4ufqet    \_ test.1          jwilder/whoami:latest@sha256:1ae692d7db4f4f77f512bf4ac1283e6eacb8d5c04971976750297505eea3b86a   test-cinder2        Shutdown            Running 24 seconds ago 

@benoitm76
Copy link

Same for me.

REX-Ray
-------
Binary: /usr/bin/rexray
Flavor: client+agent+controller
SemVer: 0.10.2
OsArch: Linux-x86_64
Commit: 4c451f856336c83680cc250ff62998bc70876c40
Formed: Tue, 12 Sep 2017 21:18:02 UTC

I am using rexray in service mode on my docker swarm cluster. If I stop a node, I still encounter this error: VolumeDriver.Mount: {"Error":"resource not found"} even with the new version.

Is it normal to have all my volume in state unavailable when I am running rexray volume ls on my libstorage controller ?

ID                                    Name                                 Status       Size
74c61e45-45bf-47da-a9c9-aca16bddeba5  bitbucket_stack_bitbucket-data       unavailable  5
3ccce994-86e1-4c68-865b-7db0a58115c8  bitbucket_stack_postgres-data        unavailable  5
dbb65188-d5b6-457c-8f3f-db8a33c952b4  confluence_stack_confluence-data     unavailable  5
4a6915e8-dd89-4d81-a2de-def91c756026  confluence_stack_postgres-data       unavailable  5
43bbc798-d6b6-4039-a690-61a8c0f13bb5  default                              available    1
4e3463bf-9cad-49ee-b3b7-de8eadc27e71  jenkins_stack_jenkins_data           unavailable  5
83f9180b-81ed-40bc-83d9-b7045aadcc08  jira_stack_jira-data                 unavailable  5
52e3f8b3-324a-492c-8a1e-1f61f5673fee  jira_stack_postgres-data             unavailable  5
1664e16a-0cb4-47ec-9a9b-c8e347d697ef  nexus_stack_nexus-data               unavailable  5

@akutz
Copy link
Member

akutz commented Sep 14, 2017

Hi @benoitm76,

Is it normal to have all my volume in state unavailable when I am running rexray volume ls on my libstorage controller ?

That depends, are those volumes attached to some node? If so, then yes, unavailable is the appropriate status. It indicates the volume is attached to some instance other than the one specified in the API call that requested the volume information.

Here is a full list of the volume status values and their descriptions:

Status Code Status Name Description
1 unknown The driver has set the state, but it is explicitly unknown and should not be inferred from the list of attachments alone.
2 attached The volume is attached to the instance specified in the API call that requested the volume information.
3 available The volume is not attached to any instance.
4 unavailable The volume is attached to some instance other than the one specified in the API call that requested the volume information.

@harrycain72
Copy link

Same for me:

Using the latest version of the rexray/cinder docker plugin on each node

docker plugin install --grant-all-permissions rexray/cinder:edge \ CINDER_AUTHURL=http://opencloud.xxxx.net:5000/v2.0 \ CINDER_USERNAME=xxxx \ CINDER_PASSWORD=xxxx \ CINDER_TENANTID=7c3a792a340e4cbc849abb4cd6d7adb2 \ REXRAY_FSTYPE=ext4 \ REXRAY_PREEMPT=true

I would love to see this working on swarm mode with a working rexray/cinder driver.

Whenever a node gets shut down or paused where a task of a service - i.e. Postgres - is running, rexray is not able to detach the volume and attach it to a different node.

As a consequence the docker swarm service is stopped, if your service is set up with just one replica.

Please help, as it is really quite frustrating.

using the command docker service ps pg you get this output:

ID NAME IMAGE NODE DESIRED STATE CURRENT STATE ERROR PORTS u6fca591ek2c pg.1 postgres:latest cvm03265.xxxx.net Running Preparing 12 seconds ago 7mk20mywai8g \_ pg.1 postgres:latest cvm02741.xxxx.net Shutdown Rejected 16 seconds ago "VolumeDriver.Mount: {"Error":…"

If you inspect this task using docker inspect u6 you get:

{

    "ID": "u6fca591ek2c22fw8vq20sa5l",
    "Version": {
        "Index": 85
    },
    "CreatedAt": "2017-09-16T10:48:20.674785226Z",
    "UpdatedAt": "2017-09-16T10:48:36.453805544Z",
    "Spec": {
        "ContainerSpec": {
            "Image": "postgres:latest@sha256:f594c0086738f808f3aa6de591b0c3349dd23ebcc42b45d16ed2ba1e9f09b02a",
            "Env": [
                "POSTGRES_PASSWORD=mysecretpassword"
            ],
            "Mounts": [
                {
                    "Type": "volume",
                    "Source": "volrexray",
                    "Target": "/var/lib/postgresql/data/",
                    "VolumeOptions": {
                        "DriverConfig": {
                            "Name": "rexray/cinder:edge"
                        }
                    }
                }
            ],
            "DNSConfig": {}
        },
        "Resources": {
            "Limits": {},
            "Reservations": {}
        },
        "RestartPolicy": {
            "Condition": "any",
            "MaxAttempts": 0
        },
        "Placement": {
            "Constraints": [
                "node.role == worker"
            ]
        },
        "ForceUpdate": 0
    },
    "ServiceID": "9n49riucyj9jo7uwk3d652g1k",
    "Slot": 1,
    "NodeID": "nap40xrbqqxr4vkqgmv8xh6uv",
    "Status": {
        "Timestamp": "2017-09-16T10:48:35.037852621Z",
        "State": "rejected",
        "Message": "preparing",
        "Err": "VolumeDriver.Mount: {\"Error\":\"error detaching volume\"}\n",
        "ContainerStatus": {},
        "PortStatus": {}
    },
    "DesiredState": "shutdown"
}

@MatMaul
Copy link
Contributor

MatMaul commented Sep 18, 2017

I am unable to make it work on the first place.
Fedora 26 + Docker CE 17.06.2 (Docker from Fedora fails because of a known selinux/vol bug).

swarm init on one node and swarm join on 2 other nodes.
docker node update --availability pause mymaster
This is to avoid scheduling on the master (so I can shut down the node where the task get scheduled).
docker service create --name test --mount type=volume,source=myvol,destination=/data,volume-driver=rexray jwilder/whoami
The container never get scheduled. If I don't disable the master it does launch, but on the master which I don't want.

Rexray 0.10.2 is launched on all nodes, as root with a working config file.
docker volume list correctly reports my volume.

Ideas ?

@harrycain72
Copy link

hi @MatMaul ,wouldn't using a constraint solve your problem?

docker service create --replicas 1 --name pg -e POSTGRES_PASSWORD=mysecretpassword --mount type=volume,source=volrexray,target=/var/lib/postgresql/data/,volume-driver=rexray/cinder --constraint 'node.role == worker' postgres

@MatMaul
Copy link
Contributor

MatMaul commented Sep 19, 2017

@harrycain72 it gives me the same result as when I put the master in pause :(
The container is never scheduled and no log appears on the rexray daemons.
Removing the mount allows scheduling so it is not a generic scheduling problem.

I tried with docker plugin install instead of manually running rexray, it is even worse: in the log I get connection refused on /run/docker/plugins/rexray.sock and even a simple docker volume ls get stuck.

I think I'll need a step by step, with exact version of Docker/OS.

@olivibernard
Copy link

The same problem occurs when I use docker swarm in legacy mode.

yvao9990 is the swarm node that runs the container using rexray volume.
yvao9980 is the swarm node where I expect the container is rescheduled by swarm.

Steps to reproduce
. on MASTER VM : docker run with swarm env exported, using a rexray vol

. on yvao9990 : halt -f

. on MASTER VM :

docker logs swarm-agent-master
time="2017-09-15T12:40:38Z" level=info msg="Removed Engine yvao9990"
time="2017-09-15T12:40:43Z" level=info msg="Rescheduled container 7016675523d83b0292f625126e2393de0ba375f2ee1746b7885bbea7cc419872 from yvao9990 to yvao9980 as 8efaeb808ffc2fb99bf8f3774f9aab7ae9929fc315ecefb96279c7e1f1bf2d78"
time="2017-09-15T12:40:43Z" level=info msg="Container 7016675523d83b0292f625126e2393de0ba375f2ee1746b7885bbea7cc419872 was running, starting container 8efaeb808ffc2fb99bf8f3774f9aab7ae9929fc315ecefb96279c7e1f1bf2d78"
time="2017-09-15T12:40:44Z" level=error msg="Failed to start rescheduled container 8efaeb808ffc2fb99bf8f3774f9aab7ae9929fc315ecefb96279c7e1f1bf2d78: Error response from daemon: error while mounting volume '/': VolumeDriver.Mount: {\"Error\":\"error detaching volume\"}"

From Openstack dashboard, I see volume is still attached to the failing node yvao9990.
Cinder only allows 1 attachment for one volume. Removing this attachment is not possible when the VM is in the RUNNING state (openstack status).
Openstack admins told me there is a cinder command that forces detach.
Maybe rexray should use it in some cases ?

Docker version 17.07.0-ce, build 8784753
Rexray 0.10.2
Ubuntu 16.04.3 LTS

@olivibernard
Copy link

Hi.
The problem is the same without swarm.

At the beginning, both 2 nodes see the rexray volume as available :

rexray volume ls |grep -w rex
f901045a-68c5-4201-bb6d-4532986a81ae  rex                      available    2

Openstack : rex volume has no attachement.

Node 1 - openstack ID=4686db80-9835-4506-b212-f9aa12d2e7ae
start a container with the rex volume.

root@yvao9980:~# docker run -ti --volume-driver=rexray -v rex:/data alpine sh
/ # df -h /data
Filesystem                Size      Used Available Use% Mounted on
/dev/vde                  1.9G      3.0M      1.8G   0% /data

-> the continer is still running.
Rexray on node 1 the volume status is attached.
f901045a-68c5-4201-bb6d-4532986a81ae rex attached 2
Rexray on node 2 the volume status is unavailable.
f901045a-68c5-4201-bb6d-4532986a81ae rex unavailable 2
On openstack, the volume is attached to node 1
Status = in-use
Attachement = Attached to yvao9980 on /dev/vde

Node 2 - openstack ID=0d75f444-60fc-4655-9621-741c9fc5d21e
start another container with the same volume, with rexray env |grep PREEMPT
LIBSTORAGE_INTEGRATION_VOLUME_OPERATIONS_MOUNT_PREEMPT=true

docker run -ti --volume-driver=rexray -v rex:/data alpine sh
docker: Error response from daemon: error while mounting volume '/': VolumeDriver.Mount: {"Error":"error detaching volume"}.

Logs on both nodes are available.
rexray.log.noswarm.node1.yvao9980.txt
rexray.log.noswarm.node2.yvao9990.txt

I would expect that preempt option in rexray env with allow to detach volume from node 1 and then attach volume to node 2.
If I try to detach the volume manually in openstack dashboard, the detach is allowed even if the container is still active and using volume rex. So Openstack is not the problem.

It seems that node 2 try to detach on itself. Rexray should detach the attachement between node 1 and volume.
In my view, @fabio-barile is right :

So to summarize this issue, rexray is not able to detach a volume mounted on a REMOTE host

@MatMaul
Copy link
Contributor

MatMaul commented Sep 22, 2017

ok thanks I completely missed @fabio-barile statement. Simple enough to be reproducible easily, investigating.

@MatMaul
Copy link
Contributor

MatMaul commented Sep 22, 2017

Problem spotted: the detach takes the ID of the server on top of the volume ID, and we always take the ID of the server where we run the detach.

@akutz what is the expected behavior ? How is PREEMPT handled ? I don't have the option specified in my config and it looks like it calls VolumeDetach anyway. When happening on a remote server should I only detach if opts.Force is true ? or everytime ?

@MatMaul
Copy link
Contributor

MatMaul commented Sep 22, 2017

@akutz another question, it looks like rexray lists the volumes before calling detach. Is it possible to access the result of that list in VolumeDetach ? If not perhaps we should store it in the context, I would like to avoid to make a 3rd API call to retrieve an info provided by list (server ID where the volume is attached).

@codenrhoden
Copy link
Member

@MatMaul

Problem spotted: the detach takes the ID of the server on top of the volume ID, and we always take the ID of the server where we run the detach.
@akutz what is the expected behavior ? How is PREEMPT handled ? I don't have the option specified in my config and it looks like it calls VolumeDetach anyway. When happening on a remote server should I only detach if opts.Force is true ? or everytime ?

Yeah, I see that Detach is always using the IID to do the detach, e.g. https://github.com/codedellemc/rexray/blob/3dce0e4a20cee6ce8878a95734315b8565d5d3aa/libstorage/drivers/storage/cinder/storage/cinder_storage.go#L643-L646

Instead, detach needs to use the ID of the node the volume is attached to. REX-Ray builds off of the paradigm that a block volume can only be attached to one node at a time, so detach methods generally don't care who the caller is. Depending on the cloud/storage provider's API, either it detaches the volume and this happens everywhere automatically (EBS does this) or it has to cycle through all the places where it is attached and detaches each one by one. GCE does this: https://github.com/codedellemc/rexray/blob/3dce0e4a20cee6ce8878a95734315b8565d5d3aa/libstorage/drivers/storage/gcepd/storage/gce_storage.go#L1050-L1065

The expected behavior is that PREEMPT gets translated to opts.Force in an attach call. During an attach, if the volume is already attached anywhere, it's an error. Unless force is true, then we are to call Detach to force/pre-empt the existing mount and move it to the newly requested node.

opts.Force doesn't usually come into play for Detach. Only if there is a concept of a "force detach", which EBS does have: https://github.com/codedellemc/rexray/blob/3dce0e4a20cee6ce8878a95734315b8565d5d3aa/libstorage/drivers/storage/ebs/storage/ebs_storage.go#L685-L688. That's the only one I know of off the top of my head...

So, the main thing that needs to change here for Cinder is that Detach needs to query the volume to see where it is attached, and detach it from any and all nodes. I'm not sure what the opts.Force field is doing here: https://github.com/codedellemc/rexray/blob/3dce0e4a20cee6ce8878a95734315b8565d5d3aa/libstorage/drivers/storage/cinder/storage/cinder_storage.go#L654 Is this a v1 vs v2 thing? Not sure, but I suspect that it isn't needed.

The attach logic in Cinder is also a bit weird re: Force: https://github.com/codedellemc/rexray/blob/master/libstorage/drivers/storage/cinder/storage/cinder_storage.go#L593-L602

It's only querying the state of the volume if force is specified. Most other drivers always query it, then change their behavior based on Force. For example, if it's already attached but force is false, it's an error. As written, the code would have the weird behavior of if you called Attach with an IID where the volume was already attached and force was true, it would detach it from the node and then just reattach it. The EBS logic may be helpful here: https://github.com/codedellemc/rexray/blob/3dce0e4a20cee6ce8878a95734315b8565d5d3aa/libstorage/drivers/storage/ebs/storage/ebs_storage.go#L604-L619

another question, it looks like rexray lists the volumes before calling detach. Is it possible to access the result of that list in VolumeDetach ? If not perhaps we should store it in the context, I would like to avoid to make a 3rd API call to retrieve an info provided by list (server ID where the volume is attached).

Not sure what "list" you are talking about? Are you talking about a list in the libStorage client? If so, this does happen and can be run on any node, not necessarily where the libStorage server is running, so no it can't be shared. If you are talking about the VolumeInspect here, the best way to handle that is to refactor VolumeDetach to use a private d.detach() method that both VolumeAttach and VolumeDetach can call. GCE is another good example of this. you'll see that detach helper function doesn't have make any additional API calls to get the list of nodes that a volume is attached to.

I know that's a lot to throw at you, but it's mostly explanation. The fix here is probably pretty straightforward.

@akutz akutz changed the title Cinder driver fails to detach or detect volume in docker swarm mode cinder: Volume detection & detach fails w Docker Swarm Sep 27, 2017
@harrycain72
Copy link

@codenrhoden Thanks a lot for fixing this issue. Testing on openstack && docker swarm is looking very good! Greetings from Munich.

@codenrhoden
Copy link
Member

@harrycain72 so glad to hear!

@MatMaul
Copy link
Contributor

MatMaul commented Oct 20, 2017

Thanks for fixing that @codenrhoden :)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

10 participants