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