"./docker.test -test.v -test.timeout 1h0m0s -remote '' -verbose" - Starting (try 1/5)
=== RUN   TestDockerPluginLogic
2024/05/06 04:50:18 DEBUG : Creating backend with remote "/tmp/rclone240564171"
2024/05/06 04:50:18 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2024/05/06 04:50:18 DEBUG : Monitoring 0 volumes
2024/05/06 04:50:18 DEBUG : Create volume "vol1"
2024/05/06 04:50:18 DEBUG : Create volume "vol1"
2024/05/06 04:50:18 DEBUG : Setup volume "vol1" as ":local:/tmp/rclone240564171" at path /tmp/rclone240564171/vol1
2024/05/06 04:50:18 DEBUG : Save state [vol1] to /tmp/rclone240564171/docker-plugin.state
2024/05/06 04:50:18 DEBUG : Create volume "vol1"
2024/05/06 04:50:18 DEBUG : Create volume "vol2"
2024/05/06 04:50:18 DEBUG : Setup volume "vol2" as ":local:/tmp/rclone240564171" at path /tmp/rclone240564171/vol2
2024/05/06 04:50:18 DEBUG : Save state [vol1 vol2] to /tmp/rclone240564171/docker-plugin.state
2024/05/06 04:50:18 DEBUG : List: [vol1 vol2]
2024/05/06 04:50:18 DEBUG : Create volume "vol99"
2024/05/06 04:50:18 DEBUG : Create volume "vol99"
2024/05/06 04:50:18 DEBUG : Create volume "vol99"
2024/05/06 04:50:18 DEBUG : Create volume "vol99"
2024/05/06 04:50:18 NOTICE: Option "memory-option-broken" is not supported by backend "memory"
2024/05/06 04:50:18 DEBUG : Mount volume "vol2" for id "id1" at path /tmp/rclone240564171/vol2 (count 0)
2024/05/06 04:50:18 DEBUG : Save state [vol1 vol2] to /tmp/rclone240564171/docker-plugin.state
2024/05/06 04:50:18 DEBUG : Mount volume "vol2" for id "id1" at path /tmp/rclone240564171/vol2 (count 1)
2024/05/06 04:50:18 DEBUG : Mount volume "vol2" for id "id2" at path /tmp/rclone240564171/vol2 (count 1)
2024/05/06 04:50:18 DEBUG : Save state [vol1 vol2] to /tmp/rclone240564171/docker-plugin.state
2024/05/06 04:50:18 DEBUG : Unmount volume "vol2" from id "id1" at path /tmp/rclone240564171/vol2 (count 2)
2024/05/06 04:50:18 DEBUG : Save state [vol1 vol2] to /tmp/rclone240564171/docker-plugin.state
2024/05/06 04:50:18 DEBUG : Unmount volume "vol2" from id "id1" at path /tmp/rclone240564171/vol2 (count 1)
2024/05/06 04:50:18 DEBUG : Restore state from /tmp/rclone240564171/docker-plugin.state
2024/05/06 04:50:18 DEBUG : Setup volume "vol1" as ":local:/tmp/rclone240564171" at path /tmp/rclone240564171/vol1
2024/05/06 04:50:18 DEBUG : Setup volume "vol2" as ":local:/tmp/rclone240564171" at path /tmp/rclone240564171/vol2
2024/05/06 04:50:18 DEBUG : Mount volume "vol2" for id "id2" at path /tmp/rclone240564171/vol2 (count 0)
2024/05/06 04:50:18 DEBUG : List: [vol1 vol2]
2024/05/06 04:50:18 DEBUG : Remove volume "vol2" (count 1)
2024/05/06 04:50:18 DEBUG : Unmount volume "vol2" from id "id1" at path /tmp/rclone240564171/vol2 (count 1)
2024/05/06 04:50:18 DEBUG : Unmount volume "vol2" from id "id2" at path /tmp/rclone240564171/vol2 (count 1)
2024/05/06 04:50:18 DEBUG : Save state [vol1 vol2] to /tmp/rclone240564171/docker-plugin.state
2024/05/06 04:50:18 DEBUG : Monitoring 0 volumes
2024/05/06 04:50:18 DEBUG : Unmount volume "vol2" from id "id2" at path /tmp/rclone240564171/vol2 (count 0)
2024/05/06 04:50:18 DEBUG : Remove volume "vol2" (count 0)
2024/05/06 04:50:18 DEBUG : Save state [vol1] to /tmp/rclone240564171/docker-plugin.state
2024/05/06 04:50:18 DEBUG : Local file system at /tmp/rclone240564171: Purge object "docker-plugin.state"
2024/05/06 04:50:18 DEBUG : Local file system at /tmp/rclone240564171: Purge dir "vol2"
2024/05/06 04:50:18 DEBUG : Local file system at /tmp/rclone240564171: Purge dir "vol1"
2024/05/06 04:50:18 DEBUG : Local file system at /tmp/rclone240564171: Purge dir ""
--- PASS: TestDockerPluginLogic (0.01s)
=== RUN   TestDockerPluginMountTCP
2024/05/06 04:50:18 DEBUG : Creating backend with remote "/tmp/rclone1507173462"
2024/05/06 04:50:18 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2024/05/06 04:50:18 DEBUG : Monitoring 0 volumes
    docker_test.go:351: 
        	Error Trace:	/home/rclone/go/src/github.com/rclone/rclone/cmd/serve/docker/docker_test.go:351
        	            				/usr/local/go/src/runtime/asm_amd64.s:1695
        	Error:      	Target error should be in err chain:
        	            	expected: "http: Server closed"
        	            	in chain: "listen tcp 127.0.0.1:53789: bind: address already in use"
        	            		"bind: address already in use"
        	            		"address already in use"
        	Test:       	TestDockerPluginMountTCP
2024/05/06 04:50:18 NOTICE: Activate: <-- {}
    docker_test.go:274: 
        	Error Trace:	/home/rclone/go/src/github.com/rclone/rclone/cmd/serve/docker/docker_test.go:274
        	            				/home/rclone/go/src/github.com/rclone/rclone/cmd/serve/docker/docker_test.go:367
        	            				/home/rclone/go/src/github.com/rclone/rclone/cmd/serve/docker/docker_test.go:419
        	Error:      	Received unexpected error:
        	            	Post "http://localhost:53789/Plugin.Activate": context deadline exceeded (Client.Timeout exceeded while awaiting headers)
        	Test:       	TestDockerPluginMountTCP
2024/05/06 04:50:20 NOTICE: Server stopped
2024/05/06 04:50:20 DEBUG : Unmount all volumes
2024/05/06 04:50:20 DEBUG : Save state [] to /tmp/rclone1507173462/docker-plugin.state
2024/05/06 04:50:20 DEBUG : Monitoring stopped
--- FAIL: TestDockerPluginMountTCP (2.02s)
=== RUN   TestDockerPluginMountUnix
2024/05/06 04:50:20 DEBUG : Creating backend with remote "/tmp/rclone1388613600"
2024/05/06 04:50:20 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2024/05/06 04:50:20 DEBUG : Monitoring 0 volumes
2024/05/06 04:50:20 INFO  : Serving unix socket: /tmp/rclone1388613600/rclone.sock
2024/05/06 04:50:20 NOTICE: Activate: <-- {}
2024/05/06 04:50:20 NOTICE: Activate: --> {"Implements":["VolumeDriver"]}
2024/05/06 04:50:20 NOTICE: Create: <-- {"Name":"vol1","Opts":{"remote":"/tmp/rclone1388613600/path1"}}
2024/05/06 04:50:20 DEBUG : Create volume "vol1"
2024/05/06 04:50:20 DEBUG : Setup volume "vol1" as ":local:/tmp/rclone1388613600/path1" at path /tmp/rclone1388613600/vol1
2024/05/06 04:50:20 DEBUG : Creating backend with remote ":local:/tmp/rclone1388613600/path1"
2024/05/06 04:50:20 DEBUG : Save state [vol1] to /tmp/rclone1388613600/docker-plugin.state
2024/05/06 04:50:20 NOTICE: Create: --> {}
2024/05/06 04:50:20 NOTICE: Create: <-- {"Name":"vol1","Opts":{"remote":"/tmp/rclone1388613600/path1"}}
2024/05/06 04:50:20 DEBUG : Create volume "vol1"
2024/05/06 04:50:20 DEBUG : /VolumeDriver.Create: Request returned error: volume already exists
2024/05/06 04:50:20 NOTICE: Create: --> {"Err":"volume already exists"}
2024/05/06 04:50:20 NOTICE: Mount: <-- {"Name":"vol1","ID":"id1"}
2024/05/06 04:50:20 DEBUG : Mount volume "vol1" for id "id1" at path /tmp/rclone1388613600/vol1 (count 0)
2024/05/06 04:50:20 INFO  : Local file system at /tmp/rclone1388613600/path1: poll-interval is not supported by this remote
2024/05/06 04:50:20 DEBUG : Local file system at /tmp/rclone1388613600/path1: Mounting on "/tmp/rclone1388613600/vol1"
2024/05/06 04:50:20 DEBUG : Save state [vol1] to /tmp/rclone1388613600/docker-plugin.state
2024/05/06 04:50:20 DEBUG : : Root: 
2024/05/06 04:50:20 DEBUG : : >Root: node=/, err=<nil>
2024/05/06 04:50:20 NOTICE: Mount: --> {"Mountpoint":"/tmp/rclone1388613600/vol1"}
2024/05/06 04:50:20 DEBUG : Clear all caches
2024/05/06 04:50:20 DEBUG : : forgetting directory cache
2024/05/06 04:50:20 DEBUG : Monitoring 1 volumes
2024/05/06 04:50:20 NOTICE: Mount: <-- {"Name":"vol1","ID":"id1"}
2024/05/06 04:50:20 DEBUG : Mount volume "vol1" for id "id1" at path /tmp/rclone1388613600/vol1 (count 1)
2024/05/06 04:50:20 DEBUG : /VolumeDriver.Mount: Request returned error: volume is already mounted by this id
2024/05/06 04:50:20 NOTICE: Mount: --> {"Err":"volume is already mounted by this id"}
2024/05/06 04:50:20 NOTICE: Remove: <-- {"Name":"vol1"}
2024/05/06 04:50:20 DEBUG : Remove volume "vol1" (count 1)
2024/05/06 04:50:20 DEBUG : /VolumeDriver.Remove: Request returned error: volume is in use
2024/05/06 04:50:20 NOTICE: Remove: --> {"Err":"volume is in use"}
2024/05/06 04:50:20 DEBUG : /: Lookup: name="txt"
2024/05/06 04:50:20 DEBUG : /: >Lookup: node=<nil>, err=no such file or directory
2024/05/06 04:50:20 DEBUG : /: Create: name="txt"
2024/05/06 04:50:20 DEBUG : txt: Open: flags=O_WRONLY|O_CREATE|O_TRUNC
2024/05/06 04:50:20 DEBUG : : Added virtual directory entry vAddFile: "txt"
2024/05/06 04:50:20 DEBUG : txt: >Open: fd=txt (w), err=<nil>
2024/05/06 04:50:20 DEBUG : /: >Create: node=txt, handle=&{txt (w)}, err=<nil>
2024/05/06 04:50:20 DEBUG : txt: Attr: 
2024/05/06 04:50:20 DEBUG : txt: >Attr: a=valid=1s ino=0 size=0 mode=-rw-rw-r--, err=<nil>
2024/05/06 04:50:20 DEBUG : &{txt (w)}: Write: len=6, offset=0
2024/05/06 04:50:20 DEBUG : : Added virtual directory entry vAddFile: "txt"
2024/05/06 04:50:20 DEBUG : &{txt (w)}: >Write: written=6, err=<nil>
2024/05/06 04:50:20 DEBUG : &{txt (w)}: Flush: 
2024/05/06 04:50:20 DEBUG : Local file system at /tmp/rclone1388613600/path1: File to upload is small (6 bytes), uploading instead of streaming
2024/05/06 04:50:20 DEBUG : txt: md5 = 72b302bf297a228a75730123efef7c41 OK
2024/05/06 04:50:20 DEBUG : txt.lucoquw6.partial: renamed to: txt
2024/05/06 04:50:20 INFO  : txt: Copied (new)
2024/05/06 04:50:20 DEBUG : : Added virtual directory entry vAddFile: "txt"
2024/05/06 04:50:20 DEBUG : &{txt (w)}: >Flush: err=<nil>
2024/05/06 04:50:20 DEBUG : &{txt (w)}: Release: 
2024/05/06 04:50:20 DEBUG : txt: WriteFileHandle.Release nothing to do
2024/05/06 04:50:20 DEBUG : &{txt (w)}: >Release: err=<nil>
2024/05/06 04:50:20 NOTICE: Unmount: <-- {"Name":"vol1","ID":"id1"}
2024/05/06 04:50:20 DEBUG : Unmount volume "vol1" from id "id1" at path /tmp/rclone1388613600/vol1 (count 1)
2024/05/06 04:50:20 INFO  : Volume "vol1" unmounted externally
2024/05/06 04:50:20 DEBUG : Save state [vol1] to /tmp/rclone1388613600/docker-plugin.state
2024/05/06 04:50:20 DEBUG : Monitoring 0 volumes
2024/05/06 04:50:20 DEBUG : Clear all caches
2024/05/06 04:50:20 DEBUG : Monitoring 0 volumes
2024/05/06 04:50:20 NOTICE: Unmount: --> {}
2024/05/06 04:50:20 NOTICE: Unmount: <-- {"Name":"vol1","ID":"id1"}
2024/05/06 04:50:20 DEBUG : Unmount volume "vol1" from id "id1" at path /tmp/rclone1388613600/vol1 (count 0)
2024/05/06 04:50:20 DEBUG : /VolumeDriver.Unmount: Request returned error: volume is not mounted
2024/05/06 04:50:20 NOTICE: Unmount: --> {"Err":"volume is not mounted"}
2024/05/06 04:50:20 NOTICE: Remove: <-- {"Name":"vol1"}
2024/05/06 04:50:20 DEBUG : Remove volume "vol1" (count 0)
2024/05/06 04:50:20 DEBUG : Save state [] to /tmp/rclone1388613600/docker-plugin.state
2024/05/06 04:50:20 NOTICE: Remove: --> {}
2024/05/06 04:50:20 NOTICE: Remove: <-- {"Name":"vol1"}
2024/05/06 04:50:20 DEBUG : /VolumeDriver.Remove: Request returned error: volume not found
2024/05/06 04:50:20 NOTICE: Remove: --> {"Err":"volume not found"}
2024/05/06 04:50:20 NOTICE: List: <-- {}
2024/05/06 04:50:20 DEBUG : List: []
2024/05/06 04:50:20 NOTICE: List: --> {"Volumes":[]}
2024/05/06 04:50:20 NOTICE: Server stopped
2024/05/06 04:50:20 DEBUG : Unmount all volumes
2024/05/06 04:50:20 DEBUG : Save state [] to /tmp/rclone1388613600/docker-plugin.state
2024/05/06 04:50:20 DEBUG : Clear all caches
2024/05/06 04:50:20 DEBUG : Monitoring 0 volumes
2024/05/06 04:50:20 DEBUG : Local file system at /tmp/rclone1388613600: Purge object "docker-plugin.state"
2024/05/06 04:50:20 DEBUG : Local file system at /tmp/rclone1388613600: Purge object "path1/txt"
2024/05/06 04:50:20 DEBUG : Local file system at /tmp/rclone1388613600: Purge dir "vol1"
2024/05/06 04:50:20 DEBUG : Local file system at /tmp/rclone1388613600: Purge dir "path1"
2024/05/06 04:50:20 DEBUG : Local file system at /tmp/rclone1388613600: Purge dir ""
--- PASS: TestDockerPluginMountUnix (0.16s)
FAIL
"./docker.test -test.v -test.timeout 1h0m0s -remote '' -verbose" - Finished ERROR in 2.255856721s (try 1/5): exit status 1: Failed [TestDockerPluginMountTCP]