"No such volume error" thrown by Docker daemon even when creating and returning volume info

After days of research I created a simple NodeJS dummy plugin that was working and analysed the communications between Docker daemon and the plugin (from NodeJS vs Go version) and found that when the field "CreatedAt" is empty (the default behavior of go-plugins-helpers) the daemon throws that error!

What made it hard to discover is that this is an undocumented field from Docker docs. My suggestion is to hide it by default in responses.

RBD PLUGIN ERROR "docker: Error response from daemon: error while mounting volume '': get volumes/myimage2: no such volume."

Ncat: Connection from a client on Unix domain socket.
Ncat: Connection from .
POST /VolumeDriver.Get HTTP/1.1
Host:
User-Agent: Go-http-client/1.1
Content-Length: 28
Accept: application/vnd.docker.plugins.v1.2+json

{"Name":"volumes/myimage2"}
Ncat: Version 7.60 ( https://nmap.org/ncat )
Ncat: Connected to /run/docker/plugins/rbd.sock.
HTTP/1.1 500 Internal Server Error
Content-Type: application/vnd.docker.plugins.v1.1+json
Date: Sun, 12 Aug 2018 10:22:26 GMT
Content-Length: 48

{"Err":"Volume not found for volumes/myimage2"}
POST /VolumeDriver.Create HTTP/1.1
Host:
User-Agent: Go-http-client/1.1
Content-Length: 40
Accept: application/vnd.docker.plugins.v1.2+json

{"Name":"volumes/myimage2","Opts":null}
HTTP/1.1 200 OK
Content-Type: application/vnd.docker.plugins.v1.1+json
Date: Sun, 12 Aug 2018 10:22:35 GMT
Content-Length: 3

{}
POST /VolumeDriver.Get HTTP/1.1
Host:
User-Agent: Go-http-client/1.1
Content-Length: 28
Accept: application/vnd.docker.plugins.v1.2+json

{"Name":"volumes/myimage2"}
HTTP/1.1 200 OK
Content-Type: application/vnd.docker.plugins.v1.1+json
Date: Sun, 12 Aug 2018 10:22:35 GMT
Content-Length: 84

{"Volume":{"Name":"volumes/myimage2","Mountpoint":"","CreatedAt":"","Status":null}}

CREATION WORKING WITH NODEJS DUMMY

Ncat: Connection from 192.168.2.16.
Ncat: Connection from 192.168.2.16:46766.
POST /VolumeDriver.Get HTTP/1.1
Host: 192.168.2.16:8000
User-Agent: Go-http-client/1.1
Content-Length: 28
Accept: application/vnd.docker.plugins.v1.2+json
Accept-Encoding: gzip

{"Name":"volumes/myimage4"}
Ncat: Version 7.60 ( https://nmap.org/ncat )
Ncat: Connected to 192.168.2.16:8001.
HTTP/1.1 500 Internal Server Error
X-Powered-By: Express
Content-Type: application/vnd.docker.plugins.v1.2+json; charset=utf-8
Content-Length: 26
ETag: W/"1a-gLh77I4qB8K5MpdkbYaTWe3K73U"
Date: Sun, 12 Aug 2018 10:15:47 GMT
Connection: keep-alive

{"Err":"Volume not found"}POST /VolumeDriver.Get HTTP/1.1
Host: 192.168.2.16:8000
User-Agent: Go-http-client/1.1
Content-Length: 28
Accept: application/vnd.docker.plugins.v1.2+json
Accept-Encoding: gzip

{"Name":"volumes/myimage4"}
HTTP/1.1 500 Internal Server Error
X-Powered-By: Express
Content-Type: application/vnd.docker.plugins.v1.2+json; charset=utf-8
Content-Length: 26
ETag: W/"1a-gLh77I4qB8K5MpdkbYaTWe3K73U"
Date: Sun, 12 Aug 2018 10:15:47 GMT
Connection: keep-alive

{"Err":"Volume not found"}POST /VolumeDriver.Create HTTP/1.1
Host: 192.168.2.16:8000
User-Agent: Go-http-client/1.1
Content-Length: 40
Accept: application/vnd.docker.plugins.v1.2+json
Accept-Encoding: gzip

{"Name":"volumes/myimage4","Opts":null}
HTTP/1.1 200 OK
X-Powered-By: Express
Content-Type: application/vnd.docker.plugins.v1.2+json; charset=utf-8
Content-Length: 10
ETag: W/"a-PMpGUhGfujZ/BYCYLgyUsmVNUho"
Date: Sun, 12 Aug 2018 10:15:47 GMT
Connection: keep-alive

{"Err":""}POST /VolumeDriver.Get HTTP/1.1
Host: 192.168.2.16:8000
User-Agent: Go-http-client/1.1
Content-Length: 28
Accept: application/vnd.docker.plugins.v1.2+json
Accept-Encoding: gzip

{"Name":"volumes/myimage4"}
HTTP/1.1 200 OK
X-Powered-By: Express
Content-Type: application/vnd.docker.plugins.v1.2+json; charset=utf-8
Content-Length: 59
ETag: W/"3b-0/2Cs8/zvrImAkH/KmyLKay7KlU"
Date: Sun, 12 Aug 2018 10:15:47 GMT
Connection: keep-alive

{"Volume":{"Name":"volumes/myimage4","Status":{}},"Err":""}POST /VolumeDriver.Mount HTTP/1.1
Host: 192.168.2.16:8000
User-Agent: Go-http-client/1.1
Content-Length: 100
Accept: application/vnd.docker.plugins.v1.2+json
Accept-Encoding: gzip

{"Name":"volumes/myimage4","ID":"44361eac3b99a3a056cafcc90b2f94d963c647e44053525009e9456065948b42"}
HTTP/1.1 200 OK
X-Powered-By: Express
Content-Type: application/vnd.docker.plugins.v1.2+json; charset=utf-8
Content-Length: 35
ETag: W/"23-YP0WfdR0PgjgN+V5Kv6YU/o1fXc"
Date: Sun, 12 Aug 2018 10:15:47 GMT
Connection: keep-alive

{"Mountpoint":"/mnt/test","Err":""}POST /VolumeDriver.Get HTTP/1.1
Host: 192.168.2.16:8000
User-Agent: Go-http-client/1.1
Content-Length: 28
Accept: application/vnd.docker.plugins.v1.2+json
Accept-Encoding: gzip

{"Name":"volumes/myimage4"}
HTTP/1.1 200 OK
X-Powered-By: Express
Content-Type: application/vnd.docker.plugins.v1.2+json; charset=utf-8
Content-Length: 59
ETag: W/"3b-0/2Cs8/zvrImAkH/KmyLKay7KlU"
Date: Sun, 12 Aug 2018 10:15:47 GMT
Connection: keep-alive

{"Volume":{"Name":"volumes/myimage4","Status":{}},"Err":""}POST /VolumeDriver.Unmount HTTP/1.1
Host: 192.168.2.16:8000
User-Agent: Go-http-client/1.1
Content-Length: 100
Accept: application/vnd.docker.plugins.v1.2+json
Accept-Encoding: gzip

{"Name":"volumes/myimage4","ID":"44361eac3b99a3a056cafcc90b2f94d963c647e44053525009e9456065948b42"}
HTTP/1.1 200 OK
X-Powered-By: Express
Content-Type: application/vnd.docker.plugins.v1.2+json; charset=utf-8
Content-Length: 10
ETag: W/"a-PMpGUhGfujZ/BYCYLgyUsmVNUho"
Date: Sun, 12 Aug 2018 10:15:47 GMT
Connection: keep-alive

I sniffed plugin communications using: ncat -lkv 192.168.2.16 8000 -c 'tee /dev/stderr | ncat -v 192.168.2.16 8001 | tee /dev/stderr’

ncat -lkv -U /run/docker/plugins/rbd2.sock -c 'tee /dev/stderr | ncat -v -U /run/docker/plugins/rbd.sock | tee /dev/stderr’

docker / go-plugins-helpers

"No such volume error" thrown by Docker daemon even when creating and returning volume info #108