Docker plugin fail to start/reinstall

What is the problem you are having with rclone?

I had installed the rclone docker plugin and used it for a couple of days, but it sudently stop working.
When trying to start my docker-compose stack I got this error :

ERROR: get build_remote-rclone: error while checking if volume "build_remote-rclone" exists in driver "rclone:latest": error looking up volume plugin rclone:latest: plugin rclone:latest found but disabled

So I tried re-enabling the plugin :

$ docker plugin enable rclone:latest
Error response from daemon: dial unix /run/docker/plugins/10585001507c0cf3af21c74472155d6958b569d232484270054be8b545c5662e/rclone.sock: connect: no such file or directory

and even tried to remove/reinstall the plugin :

XXX@docker:$ docker plugin rm rclone:latest
rclone:latest
XXX@docker:$ docker plugin install rclone/docker-volume-rclone:amd64 args="-v" --alias rclone --grant-all-permissions
amd64: Pulling from rclone/docker-volume-rclone
Digest: sha256:9db0559f0f32db36e42d9bc92358ef4013a06222b6c275215bc0fffedc3b3bd5
a84d98b8bb73: Complete
Error response from daemon: dial unix /run/docker/plugins/46be0fce963bfbbf4962ed34c5fe1a763b8e9bbca28501eef3c362941ce37936/rclone.sock: connect: no such file or directory

The only thig I did before I saw it

Run the command 'rclone version' and share the full output of the command.

rclone v1.58.0
- os/version: ubuntu 22.04 (64 bit)
- os/kernel: 5.15.0-23-generic (x86_64)
- os/type: linux
- os/arch: amd64
- go/version: go1.17.8
- go/linking: static
- go/tags: none

Which cloud storage system are you using? (eg Google Drive)

gdrive + encryption

The command you were trying to run (eg rclone copy /tmp remote:tmp)

see above

The rclone config contents with secrets removed.

[GDriveBackupNeo]
type = drive
client_id = <redacted>
client_secret = <redacted>
scope = drive
root_folder_id = <redacted>
token = <redacted>

[GDriveBackupNeoEncrypted]
type = crypt
remote = GDriveBackupNeo:
filename_encryption = standard
directory_name_encryption = true
password = <redacted>

A log from the command with the -vv flag

none

Can you check rclone is working properly on the underlying machine first with rclone lsf -vv GDriveBackupNeoEncrypted:?

Yes :

root@docker:# rclone lsf -vv GDriveBackupNeoEncrypted: --config /var/lib/docker-plugins/rclone/config/rclone.conf
2022/03/24 08:54:38 DEBUG : rclone: Version "v1.58.0" starting with parameters ["rclone" "lsf" "-vv" "GDriveBackupNeoEncrypted:" "--config" "/var/lib/docker-plugins/rclone/config/rclone.conf"]
2022/03/24 08:54:38 DEBUG : Creating backend with remote "GDriveBackupNeoEncrypted:"
2022/03/24 08:54:38 DEBUG : Using config file from "/var/lib/docker-plugins/rclone/config/rclone.conf"
2022/03/24 08:54:39 DEBUG : Creating backend with remote "GDriveBackupNeo:"
A****_Backup/
P****_Backup/
S*****_Backup/
T*****_Backup/
T*******_Backup/
T******/
V******_Backup/
2022/03/24 08:54:39 DEBUG : 4 go routines active

I think I'm going to have to put the bat signal out for @ivandeex who knows a lot about this.

Maybe we should have a troubleshooting section in the docs?

Please have a careful look at the docs, in particular:

Restart your plugin with higher verbosity:

docker plugin disable rclone         # just to be sure, probably unneeded
docker plugin set rclone args="-vv"  # bump up verbosity
docker plugin enable rclone          # this will fail :( but also report in the log :)

The docker plugin log goes into the docker daemon log which is located OS dependent:

/var/log/syslog
/var/log/messages
/var/log/docker.log
journalctl --unit docker

Find the last few log messages for rclone plugin and paste below for analysis.

1 Like

@scipio

If you find documentation unclear, please take your time to help the community.
Please register / login on github, then
Open the document source by this link below
Click the top-right PEN icon.
Edit the document right in the browser to your taste.
Github will extract the difference and create a change request from your name.
We will later review your changes.

cc @ncw

1 Like

I have no issue with the documentation, I just plainy missed the troubleshooting section, and that's on me :slight_smile:

Here is the logs from journalctl :

Mar 25 18:23:01 docker dockerd[1023]: time="2022-03-25T18:23:01Z" level=error msg="2022/03/25 18:23:01 DEBUG : Setting --base-dir \"/mnt\" from environment variable RCLONE_BASE_DIR=\"/mnt\"" plugin=46be0fce963bfbbf4962ed34c5fe1a763b8e9bbca28501eef3c362941ce37936
Mar 25 18:23:01 docker dockerd[1023]: time="2022-03-25T18:23:01Z" level=error msg="2022/03/25 18:23:01 DEBUG : Setting --verbose \"0\" from environment variable RCLONE_VERBOSE=\"0\"" plugin=46be0fce963bfbbf4962ed34c5fe1a763b8e9bbca28501eef3c362941ce37936
Mar 25 18:23:01 docker dockerd[1023]: time="2022-03-25T18:23:01Z" level=error msg="2022/03/25 18:23:01 DEBUG : Setting --config \"/data/config/rclone.conf\" from environment variable RCLONE_CONFIG=\"/data/config/rclone.conf\"" plugin=46be0fce963bfbbf4962ed34c5fe1a763b8e9bbca28501eef3c362941ce37936
Mar 25 18:23:01 docker dockerd[1023]: time="2022-03-25T18:23:01Z" level=error msg="2022/03/25 18:23:01 DEBUG : Setting --cache-dir \"/data/cache\" from environment variable RCLONE_CACHE_DIR=\"/data/cache\"" plugin=46be0fce963bfbbf4962ed34c5fe1a763b8e9bbca28501eef3c362941ce37936
Mar 25 18:23:01 docker dockerd[1023]: time="2022-03-25T18:23:01Z" level=error msg="2022/03/25 18:23:01 DEBUG : rclone: Version \"v1.58.0\" starting with parameters [\"rclone\" \"serve\" \"docker\" \"-vv\"]" plugin=46be0fce963bfbbf4962ed34c5fe1a763b8e9bbca28501eef3c362941ce37936
Mar 25 18:23:01 docker dockerd[1023]: time="2022-03-25T18:23:01Z" level=error msg="2022/03/25 18:23:01 DEBUG : Restore state from /data/cache/docker-plugin.state" plugin=46be0fce963bfbbf4962ed34c5fe1a763b8e9bbca28501eef3c362941ce37936
Mar 25 18:23:01 docker dockerd[1023]: time="2022-03-25T18:23:01Z" level=error msg="2022/03/25 18:23:01 DEBUG : Using config file from \"/data/config/rclone.conf\"" plugin=46be0fce963bfbbf4962ed34c5fe1a763b8e9bbca28501eef3c362941ce37936
Mar 25 18:23:01 docker dockerd[1023]: time="2022-03-25T18:23:01Z" level=error msg="2022/03/25 18:23:01 DEBUG : Setup volume \"build_remote-rclone\" as \"GDriveBackupNeoEncrypted:\" at path /mnt/build_remote-rclone" plugin=46be0fce963bfbbf4962ed34c5fe1a763b8e9bbca28501eef3c362941ce37936
Mar 25 18:23:01 docker dockerd[1023]: time="2022-03-25T18:23:01Z" level=error msg="2022/03/25 18:23:01 DEBUG : Creating backend with remote \"GDriveBackupNeoEncrypted:\"" plugin=46be0fce963bfbbf4962ed34c5fe1a763b8e9bbca28501eef3c362941ce37936
Mar 25 18:23:01 docker dockerd[1023]: time="2022-03-25T18:23:01Z" level=error msg="2022/03/25 18:23:01 DEBUG : Creating backend with remote \"GDriveBackupNeo:\"" plugin=46be0fce963bfbbf4962ed34c5fe1a763b8e9bbca28501eef3c362941ce37936
Mar 25 18:23:01 docker dockerd[1023]: time="2022-03-25T18:23:01Z" level=error msg="2022/03/25 18:23:01 DEBUG : Mount volume \"build_remote-rclone\" for id \"8484f1268d056376f54daf431edcb6144911ba7f4bb1afa4c14789e27d06185a\" at path /mnt/build_remote-rclone (count 0)" plugin=46be0fce963bfbbf4962ed34c5fe1a763b8e9bbca28501eef3c362941ce37936
Mar 25 18:23:01 docker dockerd[1023]: time="2022-03-25T18:23:01Z" level=error msg="2022/03/25 18:23:01 DEBUG : GDriveBackupNeo: Loaded invalid token from config file - ignoring" plugin=46be0fce963bfbbf4962ed34c5fe1a763b8e9bbca28501eef3c362941ce37936
Mar 25 18:23:01 docker dockerd[1023]: time="2022-03-25T18:23:01Z" level=error msg="2022/03/25 18:23:01 DEBUG : Saving config \"token\" in section \"GDriveBackupNeo\" of the config file" plugin=46be0fce963bfbbf4962ed34c5fe1a763b8e9bbca28501eef3c362941ce37936
Mar 25 18:23:01 docker dockerd[1023]: time="2022-03-25T18:23:01Z" level=error msg="2022/03/25 18:23:01 DEBUG : Keeping previous permissions for config file: -rw-r--r--" plugin=46be0fce963bfbbf4962ed34c5fe1a763b8e9bbca28501eef3c362941ce37936
Mar 25 18:23:01 docker dockerd[1023]: time="2022-03-25T18:23:01Z" level=error msg="2022/03/25 18:23:01 DEBUG : GDriveBackupNeo: Saved new token in config file" plugin=46be0fce963bfbbf4962ed34c5fe1a763b8e9bbca28501eef3c362941ce37936
Mar 25 18:23:01 docker dockerd[1023]: time="2022-03-25T18:23:01Z" level=error msg="2022/03/25 18:23:01 DEBUG : vfs cache: root is \"/data/cache\"" plugin=46be0fce963bfbbf4962ed34c5fe1a763b8e9bbca28501eef3c362941ce37936
Mar 25 18:23:01 docker dockerd[1023]: time="2022-03-25T18:23:01Z" level=error msg="2022/03/25 18:23:01 DEBUG : vfs cache: data root is \"/data/cache/vfs/GDriveBackupNeoEncrypted\"" plugin=46be0fce963bfbbf4962ed34c5fe1a763b8e9bbca28501eef3c362941ce37936
Mar 25 18:23:01 docker dockerd[1023]: time="2022-03-25T18:23:01Z" level=error msg="2022/03/25 18:23:01 DEBUG : vfs cache: metadata root is \"/data/cache/vfsMeta/GDriveBackupNeoEncrypted\"" plugin=46be0fce963bfbbf4962ed34c5fe1a763b8e9bbca28501eef3c362941ce37936
Mar 25 18:23:01 docker dockerd[1023]: time="2022-03-25T18:23:01Z" level=error msg="2022/03/25 18:23:01 DEBUG : Creating backend with remote \"/data/cache/vfs/GDriveBackupNeoEncrypted/\"" plugin=46be0fce963bfbbf4962ed34c5fe1a763b8e9bbca28501eef3c362941ce37936
Mar 25 18:23:01 docker dockerd[1023]: time="2022-03-25T18:23:01Z" level=error msg="2022/03/25 18:23:01 DEBUG : Creating backend with remote \"/data/cache/vfsMeta/GDriveBackupNeoEncrypted/\"" plugin=46be0fce963bfbbf4962ed34c5fe1a763b8e9bbca28501eef3c362941ce37936
Mar 25 18:23:01 docker dockerd[1023]: time="2022-03-25T18:23:01Z" level=error msg="2022/03/25 18:23:01 DEBUG : Encrypted drive 'GDriveBackupNeoEncrypted:': Mounting on \"/mnt/build_remote-rclone\"" plugin=46be0fce963bfbbf4962ed34c5fe1a763b8e9bbca28501eef3c362941ce37936
Mar 25 18:23:01 docker dockerd[1023]: time="2022-03-25T18:23:01Z" level=error msg="2022/03/25 18:23:01 INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)" plugin=46be0fce963bfbbf4962ed34c5fe1a763b8e9bbca28501eef3c362941ce37936
Mar 25 18:23:01 docker dockerd[1023]: time="2022-03-25T18:23:01Z" level=error msg="2022/03/25 18:23:01 DEBUG : : Root: " plugin=46be0fce963bfbbf4962ed34c5fe1a763b8e9bbca28501eef3c362941ce37936
Mar 25 18:23:01 docker dockerd[1023]: time="2022-03-25T18:23:01Z" level=error msg="2022/03/25 18:23:01 DEBUG : : >Root: node=/, err=<nil>" plugin=46be0fce963bfbbf4962ed34c5fe1a763b8e9bbca28501eef3c362941ce37936
Mar 25 18:23:13 docker dockerd[1023]: time="2022-03-25T18:23:13.633153807Z" level=info msg="ignoring event" container=46be0fce963bfbbf4962ed34c5fe1a763b8e9bbca28501eef3c362941ce37936 module=libcontainerd namespace=plugins.moby topic=/tasks/delete type="*events.TaskDelete"
Mar 25 18:23:13 docker dockerd[1023]: time="2022-03-25T18:23:13.665396300Z" level=error msg="Handler for POST /v1.41/plugins/rclone/enable returned error: dial unix /run/docker/plugins/46be0fce963bfbbf4962ed34c5fe1a763b8e9bbca28501eef3c362941ce37936/rclone.sock: connect: no such file or directory"

/val/log/syslog contained the same infos.

I see in the log it try to attach/recreate the volume I created in my docker compose. For referece I had ths :

  remote-rclone:
    driver: rclone:latest
    driver_opts:
#      config: "$(base64 /root/rclone.conf)"
      remote: 'GDriveBackupNeoEncrypted:'
      allow_other: 'true'
      vfs_cache_mode: full
#      user-agent: "Docker Ndin"
      poll_interval: 0

I can see from the log that the plugin had started up, restored its saved state and successfully finished mounting Google Drive at 18:23:01, but docker daemon failed to ping its health at 18:23:13, probably due to unexpected program abort.
Let's see what happens if you start the plugin cleanly.

  1. Stop all compose jobs and docker containers using the remote
  2. Stop the plugin with: docker plugin disable rclone
  3. Remove saved plugin state on the host: sudo rm /var/lib/docker-plugins/rclone/cache/docker-plugin.state
  4. Start the plugin again: docker plugin enable rclone
  5. Check that plugin process is still running as seen from the host: ps -efa | grep "rclone serve docker"
  6. Look in the docker daemon log: sudo cat /var/log/syslog | grep dockerd | less

Is everything OK yet? I hope so...

  1. Start your mount-related containers / compose jobs now.
  2. Check again if the plugin is still running?

If it works, just use it.
If the plugin will die, let's get rid of the docker for a moment and troubleshoot things simplistically:

  1. Install rclone normally on the host as per this link: Install
  2. Copy your plugin'ified rclone config locally: sudo cat /var/lib/docker-plugins/rclone/config/rclone.conf | cat > ./rclone.conf
  3. Run ordinary rclone mount, mimicing the composed options: rclone --config ./rclone.conf mount GDriveBackupNeoEncrypted: /tmp/test-mount-dir --poll-interval=0 --vfs-cache-mode=full --allow-other
  4. Manually check the mount trying to behave like your compose'd program: list directories, copy files, etc

I wish your hunt were fruitful... Let me know below...

It seem the first set of commands is working, I will keep an eye on it, It was fine too for at least a few hours last time, finger crossed.

As you suggested earlier, I might submit a documentation update proposal : I thought the uninstall/reinstall of the plugin would clear the state. I will submit an update with the state removal command as an addition in the troubleshooting section, with of course an accompagniing warning of its destructive side effect.

In any case thanks for the help :slight_smile:

FWIW: I had a similar problem which appeared following a server reboot cycle and one of my containers using the rclone plugin failed to auto-start.

Here was the state of the plugin:

# docker plugin ls
ID             NAME            DESCRIPTION                       ENABLED
683199f0659d   rclone:latest   Rclone volume plugin for Docker   false

I then attempted to enable:

# docker plugin enable rclone
Error response from daemon: dial unix /run/docker/plugins/683199f0659d741976aae8c5c08c624c7bc2704ace3bfe93e8ab693c95a7e9f3/rclone.sock: connect: no such file or directory

And then went through your steps above and the problem was resolved. :sunglasses: Will keep an eye on things and report back if I have more details or repro steps.

1 Like

Just to chime in and say I am facing similar problems here every time the docker daemon is restarted. It's definitely a frustrating occurrence, and I'd welcome any comments on how to resolve this issue.

This topic was automatically closed 30 days after the last reply. New replies are no longer allowed.