"./docker.test -test.v -test.timeout 1h0m0s -remote '' -verbose" - Starting (try 1/5)
=== RUN   TestDockerPluginLogic
2024/09/23 20:38:52 DEBUG : Creating backend with remote "/tmp/rclone37825678"
2024/09/23 20:38:52 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2024/09/23 20:38:52 DEBUG : Create volume "vol1"
2024/09/23 20:38:52 DEBUG : Create volume "vol1"
2024/09/23 20:38:52 DEBUG : Setup volume "vol1" as ":local:/tmp/rclone37825678" at path /tmp/rclone37825678/vol1
2024/09/23 20:38:52 DEBUG : Save state [vol1] to /tmp/rclone37825678/docker-plugin.state
2024/09/23 20:38:52 DEBUG : Create volume "vol1"
2024/09/23 20:38:52 DEBUG : Monitoring 0 volumes
2024/09/23 20:38:52 DEBUG : Create volume "vol2"
2024/09/23 20:38:52 DEBUG : Setup volume "vol2" as ":local:/tmp/rclone37825678" at path /tmp/rclone37825678/vol2
2024/09/23 20:38:52 DEBUG : Save state [vol1 vol2] to /tmp/rclone37825678/docker-plugin.state
2024/09/23 20:38:52 DEBUG : List: [vol1 vol2]
2024/09/23 20:38:52 DEBUG : Create volume "vol99"
2024/09/23 20:38:52 DEBUG : Create volume "vol99"
2024/09/23 20:38:52 DEBUG : Create volume "vol99"
2024/09/23 20:38:52 DEBUG : Create volume "vol99"
2024/09/23 20:38:52 NOTICE: Option "memory-option-broken" is not supported by backend "memory"
2024/09/23 20:38:52 DEBUG : Mount volume "vol2" for id "id1" at path /tmp/rclone37825678/vol2 (count 0)
2024/09/23 20:38:52 DEBUG : Save state [vol1 vol2] to /tmp/rclone37825678/docker-plugin.state
2024/09/23 20:38:52 DEBUG : Mount volume "vol2" for id "id1" at path /tmp/rclone37825678/vol2 (count 1)
2024/09/23 20:38:52 DEBUG : Mount volume "vol2" for id "id2" at path /tmp/rclone37825678/vol2 (count 1)
2024/09/23 20:38:52 DEBUG : Save state [vol1 vol2] to /tmp/rclone37825678/docker-plugin.state
2024/09/23 20:38:52 DEBUG : Unmount volume "vol2" from id "id1" at path /tmp/rclone37825678/vol2 (count 2)
2024/09/23 20:38:52 DEBUG : Save state [vol1 vol2] to /tmp/rclone37825678/docker-plugin.state
2024/09/23 20:38:52 DEBUG : Unmount volume "vol2" from id "id1" at path /tmp/rclone37825678/vol2 (count 1)
2024/09/23 20:38:52 DEBUG : Restore state from /tmp/rclone37825678/docker-plugin.state
2024/09/23 20:38:52 DEBUG : Setup volume "vol1" as ":local:/tmp/rclone37825678" at path /tmp/rclone37825678/vol1
2024/09/23 20:38:52 DEBUG : Setup volume "vol2" as ":local:/tmp/rclone37825678" at path /tmp/rclone37825678/vol2
2024/09/23 20:38:52 DEBUG : Mount volume "vol2" for id "id2" at path /tmp/rclone37825678/vol2 (count 0)
2024/09/23 20:38:52 DEBUG : List: [vol1 vol2]
2024/09/23 20:38:52 DEBUG : Remove volume "vol2" (count 1)
2024/09/23 20:38:52 DEBUG : Unmount volume "vol2" from id "id1" at path /tmp/rclone37825678/vol2 (count 1)
2024/09/23 20:38:52 DEBUG : Unmount volume "vol2" from id "id2" at path /tmp/rclone37825678/vol2 (count 1)
2024/09/23 20:38:52 DEBUG : Save state [vol1 vol2] to /tmp/rclone37825678/docker-plugin.state
2024/09/23 20:38:52 DEBUG : Unmount volume "vol2" from id "id2" at path /tmp/rclone37825678/vol2 (count 0)
2024/09/23 20:38:52 DEBUG : Remove volume "vol2" (count 0)
2024/09/23 20:38:52 DEBUG : Save state [vol1] to /tmp/rclone37825678/docker-plugin.state
2024/09/23 20:38:52 DEBUG : Monitoring 0 volumes
2024/09/23 20:38:52 DEBUG : Local file system at /tmp/rclone37825678: Purge object "docker-plugin.state"
2024/09/23 20:38:52 DEBUG : Local file system at /tmp/rclone37825678: Purge dir "vol2"
2024/09/23 20:38:52 DEBUG : Local file system at /tmp/rclone37825678: Purge dir "vol1"
2024/09/23 20:38:52 DEBUG : Local file system at /tmp/rclone37825678: Purge dir ""
--- PASS: TestDockerPluginLogic (0.02s)
=== RUN   TestDockerPluginMountTCP
2024/09/23 20:38:52 DEBUG : Creating backend with remote "/tmp/rclone1349580539"
2024/09/23 20:38:52 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2024/09/23 20:38:52 DEBUG : Monitoring 0 volumes
2024/09/23 20:38:52 DEBUG : Plugin spec has been written to /tmp/rclone1349580539/rclone.spec
2024/09/23 20:38:52 INFO  : Serving TCP socket: 127.0.0.1:53789
2024/09/23 20:38:52 NOTICE: Activate: <-- {}
2024/09/23 20:38:52 NOTICE: Activate: --> {"Implements":["VolumeDriver"]}
2024/09/23 20:38:52 NOTICE: Create: <-- {"Name":"vol1","Opts":{"remote":"/tmp/rclone1349580539/path1"}}
2024/09/23 20:38:52 DEBUG : Create volume "vol1"
2024/09/23 20:38:52 DEBUG : Setup volume "vol1" as ":local:/tmp/rclone1349580539/path1" at path /tmp/rclone1349580539/vol1
2024/09/23 20:38:52 DEBUG : Creating backend with remote ":local:/tmp/rclone1349580539/path1"
2024/09/23 20:38:52 DEBUG : Save state [vol1] to /tmp/rclone1349580539/docker-plugin.state
2024/09/23 20:38:52 NOTICE: Create: --> {}
2024/09/23 20:38:52 NOTICE: Create: <-- {"Name":"vol1","Opts":{"remote":"/tmp/rclone1349580539/path1"}}
2024/09/23 20:38:52 DEBUG : Create volume "vol1"
2024/09/23 20:38:52 DEBUG : /VolumeDriver.Create: Request returned error: volume already exists
2024/09/23 20:38:52 NOTICE: Create: --> {"Err":"volume already exists"}
2024/09/23 20:38:52 NOTICE: Mount: <-- {"Name":"vol1","ID":"id1"}
2024/09/23 20:38:52 DEBUG : Mount volume "vol1" for id "id1" at path /tmp/rclone1349580539/vol1 (count 0)
2024/09/23 20:38:52 INFO  : Local file system at /tmp/rclone1349580539/path1: poll-interval is not supported by this remote
2024/09/23 20:38:52 DEBUG : Local file system at /tmp/rclone1349580539/path1: Mounting on "/tmp/rclone1349580539/vol1"
2024/09/23 20:38:52 DEBUG : Save state [vol1] to /tmp/rclone1349580539/docker-plugin.state
2024/09/23 20:38:52 DEBUG : Monitoring 1 volumes
2024/09/23 20:38:52 NOTICE: Mount: --> {"Mountpoint":"/tmp/rclone1349580539/vol1"}
2024/09/23 20:38:52 DEBUG : : Root: 
2024/09/23 20:38:52 DEBUG : : >Root: node=/, err=<nil>
2024/09/23 20:38:52 NOTICE: Mount: <-- {"Name":"vol1","ID":"id1"}
2024/09/23 20:38:52 DEBUG : Mount volume "vol1" for id "id1" at path /tmp/rclone1349580539/vol1 (count 1)
2024/09/23 20:38:52 DEBUG : /VolumeDriver.Mount: Request returned error: volume is already mounted by this id
2024/09/23 20:38:52 NOTICE: Mount: --> {"Err":"volume is already mounted by this id"}
2024/09/23 20:38:52 NOTICE: Remove: <-- {"Name":"vol1"}
2024/09/23 20:38:52 DEBUG : Remove volume "vol1" (count 1)
2024/09/23 20:38:52 DEBUG : /VolumeDriver.Remove: Request returned error: volume is in use
2024/09/23 20:38:52 NOTICE: Remove: --> {"Err":"volume is in use"}
2024/09/23 20:38:52 DEBUG : /: Lookup: name="txt"
2024/09/23 20:38:52 DEBUG : /: >Lookup: node=<nil>, err=no such file or directory
2024/09/23 20:38:52 DEBUG : /: Create: name="txt"
2024/09/23 20:38:52 DEBUG : txt: Open: flags=O_WRONLY|O_CREATE|O_TRUNC
2024/09/23 20:38:52 DEBUG : : Added virtual directory entry vAddFile: "txt"
2024/09/23 20:38:52 DEBUG : txt: >Open: fd=txt (w), err=<nil>
2024/09/23 20:38:52 DEBUG : /: >Create: node=txt, handle=&{txt (w)}, err=<nil>
2024/09/23 20:38:52 DEBUG : txt: Attr: 
2024/09/23 20:38:52 DEBUG : txt: >Attr: a=valid=1s ino=0 size=0 mode=-rw-rw-r--, err=<nil>
2024/09/23 20:38:52 DEBUG : &{txt (w)}: Write: len=6, offset=0
2024/09/23 20:38:52 DEBUG : : Added virtual directory entry vAddFile: "txt"
2024/09/23 20:38:52 DEBUG : &{txt (w)}: >Write: written=6, err=<nil>
2024/09/23 20:38:52 DEBUG : &{txt (w)}: Flush: 
2024/09/23 20:38:52 DEBUG : Local file system at /tmp/rclone1349580539/path1: File to upload is small (6 bytes), uploading instead of streaming
2024/09/23 20:38:52 DEBUG : txt: md5 = 72b302bf297a228a75730123efef7c41 OK
2024/09/23 20:38:52 DEBUG : txt: Size and md5 of src and dst objects identical
2024/09/23 20:38:52 DEBUG : : Added virtual directory entry vAddFile: "txt"
2024/09/23 20:38:52 DEBUG : &{txt (w)}: >Flush: err=<nil>
2024/09/23 20:38:52 DEBUG : &{txt (w)}: Release: 
2024/09/23 20:38:52 DEBUG : txt: WriteFileHandle.Release nothing to do
2024/09/23 20:38:52 DEBUG : &{txt (w)}: >Release: err=<nil>
2024/09/23 20:38:52 NOTICE: Unmount: <-- {"Name":"vol1","ID":"id1"}
2024/09/23 20:38:52 DEBUG : Unmount volume "vol1" from id "id1" at path /tmp/rclone1349580539/vol1 (count 1)
2024/09/23 20:38:52 INFO  : Volume "vol1" unmounted externally
2024/09/23 20:38:52 DEBUG : Save state [vol1] to /tmp/rclone1349580539/docker-plugin.state
2024/09/23 20:38:52 DEBUG : Monitoring 0 volumes
2024/09/23 20:38:52 DEBUG : Monitoring 0 volumes
2024/09/23 20:38:52 NOTICE: Unmount: --> {}
2024/09/23 20:38:52 NOTICE: Unmount: <-- {"Name":"vol1","ID":"id1"}
2024/09/23 20:38:52 DEBUG : Unmount volume "vol1" from id "id1" at path /tmp/rclone1349580539/vol1 (count 0)
2024/09/23 20:38:52 DEBUG : /VolumeDriver.Unmount: Request returned error: volume is not mounted
2024/09/23 20:38:52 NOTICE: Unmount: --> {"Err":"volume is not mounted"}
2024/09/23 20:38:52 NOTICE: Remove: <-- {"Name":"vol1"}
2024/09/23 20:38:52 DEBUG : Remove volume "vol1" (count 0)
2024/09/23 20:38:52 DEBUG : Save state [] to /tmp/rclone1349580539/docker-plugin.state
2024/09/23 20:38:52 NOTICE: Remove: --> {}
2024/09/23 20:38:52 NOTICE: Remove: <-- {"Name":"vol1"}
2024/09/23 20:38:52 DEBUG : /VolumeDriver.Remove: Request returned error: volume not found
2024/09/23 20:38:52 NOTICE: Remove: --> {"Err":"volume not found"}
2024/09/23 20:38:52 NOTICE: List: <-- {}
2024/09/23 20:38:52 DEBUG : List: []
2024/09/23 20:38:52 NOTICE: List: --> {"Volumes":[]}
2024/09/23 20:38:52 NOTICE: Server stopped
2024/09/23 20:38:52 DEBUG : Unmount all volumes
2024/09/23 20:38:52 DEBUG : Save state [] to /tmp/rclone1349580539/docker-plugin.state
2024/09/23 20:38:52 DEBUG : Local file system at /tmp/rclone1349580539: Purge object "docker-plugin.state"
2024/09/23 20:38:52 DEBUG : Clear all caches
2024/09/23 20:38:52 DEBUG : Monitoring 0 volumes
2024/09/23 20:38:52 DEBUG : Local file system at /tmp/rclone1349580539: Purge object "rclone.spec"
2024/09/23 20:38:52 DEBUG : Local file system at /tmp/rclone1349580539: Purge object "path1/txt"
2024/09/23 20:38:52 DEBUG : Local file system at /tmp/rclone1349580539: Purge dir "vol1"
2024/09/23 20:38:52 DEBUG : Local file system at /tmp/rclone1349580539: Purge dir "path1"
2024/09/23 20:38:52 DEBUG : Local file system at /tmp/rclone1349580539: Purge dir ""
--- PASS: TestDockerPluginMountTCP (0.21s)
=== RUN   TestDockerPluginMountUnix
2024/09/23 20:38:52 DEBUG : Creating backend with remote "/tmp/rclone380287453"
2024/09/23 20:38:52 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2024/09/23 20:38:52 DEBUG : Monitoring 0 volumes
2024/09/23 20:38:52 INFO  : Serving unix socket: /tmp/rclone380287453/rclone.sock
2024/09/23 20:38:52 NOTICE: Activate: <-- {}
2024/09/23 20:38:52 NOTICE: Activate: --> {"Implements":["VolumeDriver"]}
2024/09/23 20:38:52 NOTICE: Create: <-- {"Name":"vol1","Opts":{"remote":"/tmp/rclone380287453/path1"}}
2024/09/23 20:38:52 DEBUG : Create volume "vol1"
2024/09/23 20:38:52 DEBUG : Setup volume "vol1" as ":local:/tmp/rclone380287453/path1" at path /tmp/rclone380287453/vol1
2024/09/23 20:38:52 DEBUG : Creating backend with remote ":local:/tmp/rclone380287453/path1"
2024/09/23 20:38:52 DEBUG : Save state [vol1] to /tmp/rclone380287453/docker-plugin.state
2024/09/23 20:38:52 NOTICE: Create: --> {}
2024/09/23 20:38:52 NOTICE: Create: <-- {"Name":"vol1","Opts":{"remote":"/tmp/rclone380287453/path1"}}
2024/09/23 20:38:52 DEBUG : Create volume "vol1"
2024/09/23 20:38:52 DEBUG : /VolumeDriver.Create: Request returned error: volume already exists
2024/09/23 20:38:52 NOTICE: Create: --> {"Err":"volume already exists"}
2024/09/23 20:38:52 NOTICE: Mount: <-- {"Name":"vol1","ID":"id1"}
2024/09/23 20:38:52 DEBUG : Mount volume "vol1" for id "id1" at path /tmp/rclone380287453/vol1 (count 0)
2024/09/23 20:38:52 INFO  : Local file system at /tmp/rclone380287453/path1: poll-interval is not supported by this remote
2024/09/23 20:38:52 DEBUG : Local file system at /tmp/rclone380287453/path1: Mounting on "/tmp/rclone380287453/vol1"
2024/09/23 20:38:52 DEBUG : Save state [vol1] to /tmp/rclone380287453/docker-plugin.state
2024/09/23 20:38:52 DEBUG : : Root: 
2024/09/23 20:38:52 DEBUG : : >Root: node=/, err=<nil>
2024/09/23 20:38:52 NOTICE: Mount: --> {"Mountpoint":"/tmp/rclone380287453/vol1"}
2024/09/23 20:38:52 DEBUG : Monitoring 1 volumes
2024/09/23 20:38:52 NOTICE: Mount: <-- {"Name":"vol1","ID":"id1"}
2024/09/23 20:38:52 DEBUG : Mount volume "vol1" for id "id1" at path /tmp/rclone380287453/vol1 (count 1)
2024/09/23 20:38:52 DEBUG : /VolumeDriver.Mount: Request returned error: volume is already mounted by this id
2024/09/23 20:38:52 NOTICE: Mount: --> {"Err":"volume is already mounted by this id"}
2024/09/23 20:38:52 NOTICE: Remove: <-- {"Name":"vol1"}
2024/09/23 20:38:52 DEBUG : Remove volume "vol1" (count 1)
2024/09/23 20:38:52 DEBUG : /VolumeDriver.Remove: Request returned error: volume is in use
2024/09/23 20:38:52 NOTICE: Remove: --> {"Err":"volume is in use"}
2024/09/23 20:38:52 DEBUG : /: Lookup: name="txt"
2024/09/23 20:38:52 DEBUG : /: >Lookup: node=<nil>, err=no such file or directory
2024/09/23 20:38:52 DEBUG : /: Create: name="txt"
2024/09/23 20:38:52 DEBUG : txt: Open: flags=O_WRONLY|O_CREATE|O_TRUNC
2024/09/23 20:38:52 DEBUG : : Added virtual directory entry vAddFile: "txt"
2024/09/23 20:38:52 DEBUG : txt: >Open: fd=txt (w), err=<nil>
2024/09/23 20:38:52 DEBUG : /: >Create: node=txt, handle=&{txt (w)}, err=<nil>
2024/09/23 20:38:52 DEBUG : txt: Attr: 
2024/09/23 20:38:52 DEBUG : txt: >Attr: a=valid=1s ino=0 size=0 mode=-rw-rw-r--, err=<nil>
2024/09/23 20:38:52 DEBUG : &{txt (w)}: Write: len=6, offset=0
2024/09/23 20:38:52 DEBUG : : Added virtual directory entry vAddFile: "txt"
2024/09/23 20:38:52 DEBUG : &{txt (w)}: >Write: written=6, err=<nil>
2024/09/23 20:38:52 DEBUG : &{txt (w)}: Flush: 
2024/09/23 20:38:52 DEBUG : Local file system at /tmp/rclone380287453/path1: File to upload is small (6 bytes), uploading instead of streaming
2024/09/23 20:38:52 DEBUG : txt: md5 = 72b302bf297a228a75730123efef7c41 OK
2024/09/23 20:38:52 DEBUG : txt: Size and md5 of src and dst objects identical
2024/09/23 20:38:52 DEBUG : : Added virtual directory entry vAddFile: "txt"
2024/09/23 20:38:52 DEBUG : &{txt (w)}: >Flush: err=<nil>
2024/09/23 20:38:52 DEBUG : &{txt (w)}: Release: 
2024/09/23 20:38:52 DEBUG : txt: WriteFileHandle.Release nothing to do
2024/09/23 20:38:52 DEBUG : &{txt (w)}: >Release: err=<nil>
2024/09/23 20:38:52 NOTICE: Unmount: <-- {"Name":"vol1","ID":"id1"}
2024/09/23 20:38:52 DEBUG : Unmount volume "vol1" from id "id1" at path /tmp/rclone380287453/vol1 (count 1)
2024/09/23 20:38:52 INFO  : Volume "vol1" unmounted externally
2024/09/23 20:38:52 DEBUG : Save state [vol1] to /tmp/rclone380287453/docker-plugin.state
2024/09/23 20:38:52 NOTICE: Unmount: --> {}
2024/09/23 20:38:52 DEBUG : Monitoring 0 volumes
2024/09/23 20:38:52 DEBUG : Monitoring 0 volumes
2024/09/23 20:38:52 NOTICE: Unmount: <-- {"Name":"vol1","ID":"id1"}
2024/09/23 20:38:52 DEBUG : Unmount volume "vol1" from id "id1" at path /tmp/rclone380287453/vol1 (count 0)
2024/09/23 20:38:52 DEBUG : /VolumeDriver.Unmount: Request returned error: volume is not mounted
2024/09/23 20:38:52 NOTICE: Unmount: --> {"Err":"volume is not mounted"}
2024/09/23 20:38:52 NOTICE: Remove: <-- {"Name":"vol1"}
2024/09/23 20:38:52 DEBUG : Remove volume "vol1" (count 0)
2024/09/23 20:38:52 DEBUG : Save state [] to /tmp/rclone380287453/docker-plugin.state
2024/09/23 20:38:52 NOTICE: Remove: --> {}
2024/09/23 20:38:52 NOTICE: Remove: <-- {"Name":"vol1"}
2024/09/23 20:38:52 DEBUG : /VolumeDriver.Remove: Request returned error: volume not found
2024/09/23 20:38:52 NOTICE: Remove: --> {"Err":"volume not found"}
2024/09/23 20:38:52 NOTICE: List: <-- {}
2024/09/23 20:38:52 DEBUG : List: []
2024/09/23 20:38:52 NOTICE: List: --> {"Volumes":[]}
2024/09/23 20:38:52 NOTICE: Server stopped
2024/09/23 20:38:52 DEBUG : Unmount all volumes
2024/09/23 20:38:52 DEBUG : Save state [] to /tmp/rclone380287453/docker-plugin.state
2024/09/23 20:38:52 DEBUG : Local file system at /tmp/rclone380287453: Purge object "docker-plugin.state"
2024/09/23 20:38:52 DEBUG : Clear all caches
2024/09/23 20:38:52 DEBUG : Monitoring 0 volumes
2024/09/23 20:38:52 DEBUG : Local file system at /tmp/rclone380287453: Purge object "path1/txt"
2024/09/23 20:38:52 DEBUG : Local file system at /tmp/rclone380287453: Purge dir "vol1"
2024/09/23 20:38:52 DEBUG : Local file system at /tmp/rclone380287453: Purge dir "path1"
2024/09/23 20:38:52 DEBUG : Local file system at /tmp/rclone380287453: Purge dir ""
--- PASS: TestDockerPluginMountUnix (0.18s)
PASS
"./docker.test -test.v -test.timeout 1h0m0s -remote '' -verbose" - Finished OK in 455.869169ms (try 1/5)