Rexray plugin unable to access EBS volumes and create new ones

Question

I'm presently running two stacks one on EBS and one on VirtualBox.

My VirtualBox setup is able to create and access volumes without trouble but I'm unable to reach an equivalent state with the rexray/ebs plugin where I can create and attach volumes to containers.

On my instance (Ubuntu 18.04 - T2.small us-west-1) i'm running the following versions of docker and rexray

1. docker version 19.03.4, build 9013bf583a
2. docker-machine version 0.16.0, build 702c267f
3. docker plugin ls

ID                  NAME                DESCRIPTION              ENABLED
e3b496c6a066        rexray/ebs:latest   REX-Ray for Amazon EBS   true

My EBS based rexray config looks like this. code-sample1

libstorage:
  logging:
    level: debug
  service: ebs
  integration:
    volume:
      operations:
        mount:
          preempt: true
docker:
  size: 1

ebs:
  accessKey: valid_access_key
  secretKey: valid_secret
  region: us-west-1
  maxRetries: 10

On VirtualBox i explicitly provide a path for libstorage to connect with VirtualBox which acts as the volume driver via the API. In this case http://10.0.0.6:18083.

My VirtualBox configuration for rexray /etc/config/rexray.yml

code-sample2

rexray:
  loglevel: warn
  storageDrivers:
    - virtualbox
  volumeDrivers:
    - docker

  docker:
    size: 1

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

virtualbox:
  endpoint: http://10.0.0.6:18083
  volumePath: "/home/sidravic/VirtualBox VMs"
  controllerName: SATA
  tls: false

With EBS however my assumption is the plugin identifies where to connect for AWS depending on the region to manipulate volumes so I run it simply as a service without providing a server configuration in the yml

The problem however is when I try to create an new volume via rexray the logs seems to be calling a unix socket

Nov 10 10:16:10 ip-172-31-1-66 dockerd[3128]: time="2019-11-10T10:16:10Z" level=error msg="time=\"2019-11-10T10:16:10Z\" level=error msg=\"error creating volume\" availabilityZone=0xc420194200 host=\"unix:///var/run/rexray/156329133.sock\" instanceID=\"ebs=i-03656f91f34f2d9f4,availabilityZone=us-west-1b&region=us-west-1\" iops=0xc420194208 route=volumeCreate server=snapdragon-paw-eg service=ebs size=0xc420194210 storageDriver=ebs task=0 time=1573380970129 tls=false txCR=1573380969 txID=eb4f7412-ca73-4c69-6977-a68c0aa90744 type=0xc420194218 volumeName=test-vol1 " plugin=e3b496c6a06643ecc9babd1e1648606fef2cc964946d9ba003e73868847ef8c7
Nov 10 10:16:10 ip-172-31-1-66 dockerd[3128]: time="2019-11-10T10:16:10Z" level=error msg="time=\"2019-11-10T10:16:10Z\" level=error msg=\"error creating volume with EC2 API call\" host=\"unix:///var/run/rexray/156329133.sock\" instanceID=\"ebs=i-03656f91f34f2d9f4,availabilityZone=us-west-1b&region=us-west-1\" route=volumeCreate server=snapdragon-paw-eg service=ebs storageDriver=ebs task=0 time=1573380970130 tls=false txCR=1573380969 txID=eb4f7412-ca73-4c69-6977-a68c0aa90744 " plugin=e3b496c6a06643ecc9babd1e1648606fef2cc964946d9ba003e73868847ef8c7
Nov 10 10:16:10 ip-172-31-1-66 dockerd[3128]: time="2019-11-10T10:16:10Z" level=error msg="time=\"2019-11-10T10:16:10Z\" level=error msg=\"error: api call failed\" host=\"unix:///var/run/rexray/156329133.sock\" route=volumeCreate server=snapdragon-paw-eg time=1573380970131 tls=false txCR=1573380969 txID=eb4f7412-ca73-4c69-6977-a68c0aa90744 " plugin=e3b496c6a06643ecc9babd1e1648606fef2cc964946d9ba003e73868847ef8c7
Nov 10 10:16:10 ip-172-31-1-66 dockerd[3128]: time="2019-11-10T10:16:10Z" level=error msg="time=\"2019-11-10T10:16:10Z\" level=error msg=\"docker-legacy: Create: test-vol1: failed: error creating volume with EC2 API call\" host=\"unix:///var/run/rexray/156329133.sock\" integrationDriver=linux osDriver=linux service=ebs storageDriver=libstorage time=1573380970133 " plugin=e3b496c6a06643ecc9babd1e1648606fef2cc964946d9ba003e73868847ef8c7
Nov 10 10:16:10 ip-172-31-1-66 dockerd[3128]: time="2019-11-10T10:16:10.134279110Z" level=error msg="Handler for POST /v1.40/volumes/create returned error: create test-vol1: VolumeDriver.Create: docker-legacy: Create: test-vol1: failed: error creating volume with EC2 API call"

The rexray command itself returns this error

$ sudo rexray volume create test-vol1 --size=2 -c /etc/rexray/config.yml
...
INFO[0000] DockerLegacyMode                              enabled=true time=1573381404622
INFO[0000] loaded custom config                          path=/etc/rexray/config.yml time=1573381404622
DEBU[0000] trapped signals                               time=1573381404622
DEBU[0000] usage template path                           path=/root/.rexray/usage.template time=1573381404624
DEBU[0000] loaded usage template                         source=UsageTemplate time=1573381404624
DEBU[0000] created scoped scope                          new=rexray.cli parentScopes=rexray,
DEBU[0000] updating log level                            level=debug time=1573381404628
INFO[0000] updated log level                             logLevel=debug
DEBU[0000] os.args                                       time=1573381404634 val=[rexray volume create test-vol1 --size=2 -c /etc/rexray/config.yml]
DEBU[0000] activating libStorage                         cmd=create time=1573381404634
DEBU[0000] parseSafeHost - no change                     postParse=unix:///var/run/rexray/157173546.sock preParse=unix:///var/run/rexray/157173546.sock time=1573381404642
DEBU[0000] read spec file                                host=unix:///var/run/rexray/157173546.sock path=/var/run/rexray/rexray.spec time=1573381404642
DEBU[0000] is local unix server active                   sock=/var/run/rexray/157173546.sock time=1573381404642
DEBU[0000] set host in context                           host=unix:///var/run/rexray/157173546.sock time=1573381404643
DEBU[0000] set host in config                            host=unix:///var/run/rexray/157173546.sock time=1573381404643
DEBU[0000] not starting embedded server; already running  host=unix:///var/run/rexray/157173546.sock time=1573381404643
DEBU[0000] creating libStorage client                    cmd=create host=unix:///var/run/rexray/157173546.sock time=1573381404643
DEBU[0000] created scoped scope                          new=libstorage.client parentScopes=rexray.cli,rexray,
INFO[0000] configured logging                            host=unix:///var/run/rexray/157173546.sock libstorage.logging.httpRequests=false libstorage.logging.httpResponses=false libstorage.logging.level=debug time=1573381404783
INFO[0000] set client service name                       host=unix:///var/run/rexray/157173546.sock service=ebs serviceName=ebs time=1573381404787
DEBU[0000] got configured host address                   host=unix:///var/run/rexray/157173546.sock service=ebs storageDriver=libstorage time=1573381404795
DEBU[0000] disabling tls for unix sockets                host=unix:///var/run/rexray/157173546.sock service=ebs storageDriver=libstorage time=1573381404799
DEBU[0000] getHost proto == "unix"                       getHost=libstorage-server host=unix:///var/run/rexray/157173546.sock service=ebs storageDriver=libstorage time=1573381404799
INFO[0000] created libStorage client                     clientType=integration disableKeepAlive=false enableInstanceIDHeaders=true enableLocalDevicesHeaders=true host=unix:///var/run/rexray/157173546.sock lAddr=libstorage-server logRequests=false logResponses=false lsxPath= service=ebs storageDriver=libstorage time=1573381404829
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/rexray/157173546.sock service=ebs storageDriver=libstorage time=1573381404830
INFO[0000] initializing supported cache                  host=unix:///var/run/rexray/157173546.sock server=wheat-heron-vi service=ebs storageDriver=libstorage time=1573381404833
DEBU[0000] executor using large device range             host=unix:///var/run/rexray/157173546.sock server=wheat-heron-vi service=ebs storageDriver=libstorage time=1573381404926 txCR=1573381404 txID=a36adacb-decc-435c-5089-df382ad39d6d
DEBU[0000] cached supported flag                         host=unix:///var/run/rexray/157173546.sock server=wheat-heron-vi service=ebs storageDriver=libstorage supported=15 time=1573381404932 txCR=1573381404 txID=a36adacb-decc-435c-5089-df382ad39d6d
INFO[0000] initializing instance ID cache                host=unix:///var/run/rexray/157173546.sock server=wheat-heron-vi service=ebs storageDriver=libstorage time=1573381404932
DEBU[0000] executor using large device range             host=unix:///var/run/rexray/157173546.sock server=wheat-heron-vi service=ebs storageDriver=libstorage time=1573381405023 txCR=1573381404 txID=ec3f824e-dd49-4789-572c-511efb5bb972
DEBU[0000] cached instanceID                             host=unix:///var/run/rexray/157173546.sock instanceID=ebs=i-03656f91f34f2d9f4,availabilityZone=us-west-1b&region=us-west-1 server=wheat-heron-vi service=ebs storageDriver=libstorage time=1573381405032 txCR=1573381404 txID=ec3f824e-dd49-4789-572c-511efb5bb972
DEBU[0000] xli instanceID success                        host=unix:///var/run/rexray/157173546.sock instanceID=ebs=i-03656f91f34f2d9f4,availabilityZone=us-west-1b&region=us-west-1 server=wheat-heron-vi service=ebs storageDriver=libstorage time=1573381405033 txCR=1573381404 txID=ec3f824e-dd49-4789-572c-511efb5bb972
INFO[0000] successefully dialed libStorage server        host=unix:///var/run/rexray/157173546.sock server=wheat-heron-vi service=ebs storageDriver=libstorage time=1573381405033
INFO[0000] storage driver initialized                    host=unix:///var/run/rexray/157173546.sock service=ebs storageDriver=libstorage time=1573381405033
INFO[0000] os driver initialized                         host=unix:///var/run/rexray/157173546.sock osDriver=linux service=ebs storageDriver=libstorage time=1573381405037
INFO[0000] linux integration driver successfully initialized  host=unix:///var/run/rexray/157173546.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=16 libstorage.integration.volume.operations.create.default.type= libstorage.integration.volume.operations.create.implicit=true libstorage.integration.volume.operations.mount.path=/var/lib/rexray/volumes libstorage.integration.volume.operations.mount.rootPath=/data osDriver=linux service=ebs storageDriver=libstorage time=1573381405080
INFO[0000] path cache initializion disabled              host=unix:///var/run/rexray/157173546.sock integrationDriver=linux osDriver=linux service=ebs storageDriver=libstorage time=1573381405092
INFO[0000] libStorage integration driver successfully initialized  host=unix:///var/run/rexray/157173546.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=false osDriver=linux service=ebs storageDriver=libstorage time=1573381405122
INFO[0000] integration driver initialized                host=unix:///var/run/rexray/157173546.sock integrationDriver=linux osDriver=linux service=ebs storageDriver=libstorage time=1573381405122
INFO[0000] created libStorage client                     host=unix:///var/run/rexray/157173546.sock integrationDriver=linux osDriver=linux service=ebs storageDriver=libstorage time=1573381405122
DEBU[0000] executor using large device range             host=unix:///var/run/rexray/157173546.sock instanceID=ebs=i-03656f91f34f2d9f4,availabilityZone=us-west-1b&region=us-west-1 integrationDriver=linux osDriver=linux server=wheat-heron-vi service=ebs storageDriver=libstorage time=1573381405213 txCR=1573381405 txID=0b934f6e-10af-48c0-6236-e12964e11416
WARN[0000] device does not match                         deviceName=name deviceRX=^xvd[f-p]$ host=unix:///var/run/rexray/157173546.sock instanceID=ebs=i-03656f91f34f2d9f4,availabilityZone=us-west-1b&region=us-west-1 integrationDriver=linux osDriver=linux server=wheat-heron-vi service=ebs storageDriver=libstorage time=1573381405218 txCR=1573381405 txID=0b934f6e-10af-48c0-6236-e12964e11416
WARN[0000] device does not match                         deviceName=loop0 deviceRX=^xvd[f-p]$ host=unix:///var/run/rexray/157173546.sock instanceID=ebs=i-03656f91f34f2d9f4,availabilityZone=us-west-1b&region=us-west-1 integrationDriver=linux osDriver=linux server=wheat-heron-vi service=ebs storageDriver=libstorage time=1573381405219 txCR=1573381405 txID=0b934f6e-10af-48c0-6236-e12964e11416
WARN[0000] device does not match                         deviceName=loop1 deviceRX=^xvd[f-p]$ host=unix:///var/run/rexray/157173546.sock instanceID=ebs=i-03656f91f34f2d9f4,availabilityZone=us-west-1b&region=us-west-1 integrationDriver=linux osDriver=linux server=wheat-heron-vi service=ebs storageDriver=libstorage time=1573381405219 txCR=1573381405 txID=0b934f6e-10af-48c0-6236-e12964e11416
WARN[0000] device does not match                         deviceName=xvda deviceRX=^xvd[f-p]$ host=unix:///var/run/rexray/157173546.sock instanceID=ebs=i-03656f91f34f2d9f4,availabilityZone=us-west-1b&region=us-west-1 integrationDriver=linux osDriver=linux server=wheat-heron-vi service=ebs storageDriver=libstorage time=1573381405219 txCR=1573381405 txID=0b934f6e-10af-48c0-6236-e12964e11416
WARN[0000] device does not match                         deviceName=xvda1 deviceRX=^xvd[f-p]$ host=unix:///var/run/rexray/157173546.sock instanceID=ebs=i-03656f91f34f2d9f4,availabilityZone=us-west-1b&region=us-west-1 integrationDriver=linux osDriver=linux server=wheat-heron-vi service=ebs storageDriver=libstorage time=1573381405219 txCR=1573381405 txID=0b934f6e-10af-48c0-6236-e12964e11416
DEBU[0000] xli localdevices success                      host=unix:///var/run/rexray/157173546.sock instanceID=ebs=i-03656f91f34f2d9f4,availabilityZone=us-west-1b&region=us-west-1 integrationDriver=linux osDriver=linux server=wheat-heron-vi service=ebs storageDriver=libstorage time=1573381405219 txCR=1573381405 txID=0b934f6e-10af-48c0-6236-e12964e11416
DEBU[0000] built output template                         host=unix:///var/run/rexray/157173546.sock template={{define "printVolumeID"}}{{.ID}}{{end}}{{define "printAuthTokenFields"}}{{.Subject}}  {{.IssuedAt}}   {{.NotBefore}}  {{.Expires}}{{end}}{{define "printEncVolumeWithPathFields"}}{{.ID}} {{.Name}}   {{.Volume.AttachmentState | printAttState}} {{.Size}}   {{.Encrypted}}  {{.Path}}{{end}}{{define "printInstanceFields"}}{{.InstanceID.ID}}  {{.Name}}   {{.ProviderName}}   {{.Region}}{{end}}{{define "printServiceFields"}}{{.Name}}  {{.Driver.Name}}{{end}}{{define "printScriptFields"}}{{.Path}}  {{.Installed}}  {{.Modified}}{{end}}{{define "printObject"}}{{printf "%v" .}}{{end}}{{define "printStringSlice"}}{{.}}{{end}}{{define "printJSON"}}{{. | json}}{{end}}{{define "printPrettyJSON"}}{{. | jsonp}}{{end}}{{define "printEncVolumeFields"}}{{.ID}}  {{.Name}}   {{.AttachmentState | printAttState}}    {{.Size}}   {{.Encrypted}}{{end}}{{define "printSnapshotFields"}}{{.ID}}    {{.Name}}   {{.Status}} {{.VolumeID}}{{end}}{{define "printMountFields"}}{{.ID}}    {{.Source}} {{.MountPoint}}{{end}}{{define "printVolumeFields"}}{{.ID}} {{.Name}}   {{.AttachmentState | printAttState}}    {{.Size}}{{end}}{{define "printVolumeWithPathFields"}}{{.ID}}   {{.Name}}   {{.Volume.AttachmentState | printAttState}} {{.Size}}   {{.Path}}{{end}}{{range .D }}{{template "printObject" .}}
{{end}} time=1573381405385
FATA[0000] error creating volume                         error.status=500 error.msg=error creating volume with EC2 API call volume=test-vol1
ubuntu@ip-172-31-1-66:/etc/rexray$ sudo rexray volume create test-vol1 --size=2 -c /etc/rexray/config.yml

I feel i'm missing something very fundamental here. Help!

Answer 1

So i've managed to figure out the problem.

1. The primary issue being the use of wrong credentials for EBS_ACCESS which caused the error of not being able to identify the instanceID for the node.

2. The plugin launches it's own instances of rexray which is available here

~$ ps aux | grep rexray
root     14931  0.0  1.2  38624 24800 ?        Ssl  13:26   0:02 rexray start -f --nopid
ubuntu   15373  0.0  0.0  14856  1108 pts/0    S+   17:33   0:00 grep rexray

So the flaw in my understanding was that there is no need to launch a separate rexray process and link it up with docker volume as I did with the /etc/rexray/config.yml

This is essential with Virtualbox but not with the docker managed plugins which automatically launches a client that accesses the volumes based on the EBS_REGION attribute used to initialise the plugin.

With VirtualBox the rexray plugin needs to be explicitly told where to send requests to and hence the launched webservice endpoint described here in the yaml

virtualbox:
  endpoint: http://10.0.0.6:18083
  volumePath: "/home/sidravic/VirtualBox VMs"
  controllerName: SATA
  tls: false

Another useful step to remember is to pass the parameters at the time of initialising the plugin like so

docker plugin install rexray/ebs:latest REXRAY_PREEMPT=true EBS_REGION=us-west-1 EBS_ACCESSKEY=valid_key EBS_SECRETKEY=valid_Secret --grant-all-permissions EBS_ENDPOINT=ec2.us-west-1.amazonaws.com EBS_USELARGEDEVICERANGE=true

The specification of the EBS_ENDPOINT though is not required as it's inferred from the region.