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