Systemd service crashes

Gir4 · November 7, 2021, 1:21am

What is the problem you are having with rclone?

Systemd service crashes when I start my OS (Manjaro).
I put around 5GB files into a mounted folder, sync started, before finish I reboot the system, thought that it would continue syncing since I'm using a cache directory.
But the systemd service crashes.
journalctl shows several unsuccesfull file syncs and timeout:

systemd[1]: rclone.service: Consumed 7min 32.555s CPU time.

and it deactivates the service.
During the timeout some traffic is generated from the rclone process, I assume it tried to upload all files but since timeout is not enough the service terminates the process.
I guess I need to continue the process but same time not crash the service and mount the folder, but how can it be

What is your rclone version (output from `rclone version`)

rclone v1.56.2

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

Google Drive

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

sudo systemctl enable --now rclone.service

The rclone config contents with secrets removed.

[Unit]
Description=rclone gdrive mount
After=network-online.target

[Service]
Type=notify
User=xxx
ExecStart=/usr/bin/rclone mount \
        --config=/home/xxx/.config/rclone/rclone.conf \
        --cache-dir=/mnt/xxx/.cache_storage/gdrive \
        --vfs-cache-mode full \
        --vfs-cache-max-size 500G \
        --vfs-cache-max-age 5000h \
        --no-modtime \
        gdrive_crypt: /home/xxx/my_mounts/gdrive
ExecStop=/bin/fusermount -uz /home/xxx/my_mounts/gdrive
Restart=on-failure
RestartSec=10

[Install]
WantedBy=default.target

A log from the command with the `-vv` flag

It's a systemd service

Animosity022 · November 7, 2021, 2:49am

Add -vv --log-file /rclone.log

Recreate the issue and share a log.

Gir4 · November 7, 2021, 9:31am

2021/11/07 09:26:27 DEBUG : rclone: Version "v1.56.2" starting with parameters ["/usr/bin/rclone" "mount" "--config=/home/xxx/.config/rclone/rclone.conf" "--cache-dir=/mnt/xxx/.cache_storage/gdrive" "--vfs-cache-mode" "full" "--vfs-cache-max-size" "500G" "--vfs-cache-max-age" "5000h" "--no-modtime" "-vv" "--log-file" "/home/xxx/logs/rclone.log" "gdrive_crypt:" "/home/xxx/my_mounts/gdrive"]

2021/11/07 09:26:27 DEBUG : Creating backend with remote "gdrive_crypt:"

2021/11/07 09:26:27 DEBUG : Using config file from "/home/xxx/.config/rclone/rclone.conf"

2021/11/07 09:26:27 DEBUG : Creating backend with remote "gdrive:rclone_generic"

2021/11/07 09:26:28 DEBUG : Google drive root 'rclone_generic': 'root_folder_id = 0AJrAfidSi5_4Uk9PVA' - save this in the config to speed up startup

2021/11/07 09:26:28 DEBUG : rclone: Version "v1.56.2" starting with parameters ["/usr/bin/rclone" "mount" "--config=/home/xxx/.config/rclone/rclone.conf" "--cache-dir=/mnt/HDD/.cache_storage/gdrive" "--vfs-cache-mode" "full" "--vfs-cache-max-size" "500G" "--vfs-cache-max-age" "5000h" "--no-modtime" "-vv" "--log-file" "/home/xxx/logs/rclone.log" "gdrive_crypt:" "/home/xxx/my_mounts/gdrive"]

2021/11/07 09:26:28 DEBUG : Creating backend with remote "gdrive_crypt:"

2021/11/07 09:26:28 DEBUG : Using config file from "/home/xxx/.config/rclone/rclone.conf"

2021/11/07 09:26:28 DEBUG : Creating backend with remote "gdrive:rclone_generic"

2021/11/07 09:26:28 DEBUG : Google drive root 'rclone_generic': 'root_folder_id = 0AJrAfidSi5_4Uk9PVA' - save this in the config to speed up startup

2021/11/07 09:26:29 DEBUG : vfs cache: root is "/mnt/HDD/.cache_storage/gdrive/vfs/gdrive_crypt"

2021/11/07 09:26:29 DEBUG : vfs cache: metadata root is "/mnt/HDD/.cache_storage/gdrive/vfs/gdrive_crypt"

2021/11/07 09:26:29 DEBUG : Creating backend with remote "/mnt/HDD/.cache_storage/gdrive/vfs/gdrive_crypt"

2021/11/07 09:26:29 DEBUG : Creating backend with remote "/mnt/HDD/.cache_storage/gdrive/vfsMeta/gdrive_crypt"

2021/11/07 09:26:31 DEBUG : Languages/xxx/xxx xxx/Stage 4/Lesson 4/EN A2 - Course 3 - Unit 4 - Video 4 (720p with 25fps).mp4: vfs cache: truncate to size=302777050
2021/11/07 09:26:31 DEBUG : Languages/xxx/xxx xxx/Stage 4/Lesson 4/EN A2 - Course 3 - Unit 4 - Video 4 (720p with 25fps).mp4: vfs cache: setting modification time to 2021-11-06 23:36:37.902232704 +0000 UTC
2021/11/07 09:26:31 INFO  : Languages/xxx/xxx xxx/Stage 4/Lesson 4/EN A2 - Course 3 - Unit 4 - Video 4 (720p with 25fps).mp4: vfs cache: queuing for upload in 5s
...
2021/11/07 09:28:16 DEBUG : Languages/xxx/xxx xxx/Stage 4/Lesson 4/EN A2 - Course 3 - Unit 4 - Video 4 (720p with 25fps).mp4: vfs cache: starting upload
...

and goes like this over and over for different files

even the service crashes the uploading still is going

Animosity022 · November 7, 2021, 11:07am

Can you share the full log file? There's no crash or stop of service in your log.

Gir4 · November 7, 2021, 3:05pm

Log goes on like this even now, indexing and uploading files, after filling 20mb I turn off logging, it goes on...

This is log from journalctl -xeu:

Nov 07 15:00:25 xxx systemd[1]: Starting rclone gdrive mount...
░░ Subject: A start job for unit rclone.service has begun execution
░░ Defined-By: systemd
░░ Support: https://forum.manjaro.org/c/support
░░ 
░░ A start job for unit xxx.service has begun execution.
░░ 
░░ The job identifier is 24299.
Nov 07 15:01:55 xxx systemd[1]: rclone.service: start operation timed out. Terminating.
Nov 07 15:01:55 xxx systemd[1]: rclone.service: Failed with result 'timeout'.
░░ Subject: Unit failed
░░ Defined-By: systemd
░░ Support: https://forum.manjaro.org/c/support
░░ 
░░ The unit rclone.service has entered the 'failed' state with result 'timeout'.
Nov 07 15:01:55 xxx systemd[1]: Failed to start rclone gdrive mount.
░░ Subject: A start job for unit rclone.service has failed
░░ Defined-By: systemd
░░ Support: https://forum.manjaro.org/c/support
░░ 
░░ A start job for unit rclone.service has finished with a failure.
░░ 
░░ The job identifier is 24299 and the job result is failed.
Nov 07 15:01:55 xxx systemd[1]: rclone.service: Consumed 1.931s CPU time.
░░ Subject: Resources consumed by unit runtime
░░ Defined-By: systemd
░░ Support: https://forum.manjaro.org/c/support
░░ 
░░ The unit rclone.service completed and consumed the indicated resources.
Nov 07 15:02:06 xxx systemd[1]: rclone.service: Scheduled restart job, restart counter is at 190.
░░ Subject: Automatic restarting of a unit has been scheduled
░░ Defined-By: systemd
░░ Support: https://forum.manjaro.org/c/support
░░ 
░░ Automatic restarting of the unit rclone.service has been scheduled, as the result for
░░ the configured Restart= setting for the unit.
Nov 07 15:02:06 xxx systemd[1]: Stopped rclone gdrive mount.
░░ Subject: A stop job for unit rclone.service has finished
░░ Defined-By: systemd
░░ Support: https://forum.manjaro.org/c/support
░░ 
░░ A stop job for unit rclone.service has finished.
░░ 
░░ The job identifier is 24398 and the job result is done.
Nov 07 15:02:06 xxx systemd[1]: rclone.service: Consumed 1.931s CPU time.
░░ Subject: Resources consumed by unit runtime
░░ Defined-By: systemd
░░ Support: https://forum.manjaro.org/c/support
░░ 
░░ The unit rclone.service completed and consumed the indicated resources.
Nov 07 15:02:06 xxx systemd[1]: Starting rclone gdrive mount...
░░ Subject: A start job for unit rclone.service has begun execution
░░ Defined-By: systemd
░░ Support: https://forum.manjaro.org/c/support
░░ 
░░ A start job for unit rclone.service has begun execution.
░░ 
░░ The job identifier is 24398.

Animosity022 · November 7, 2021, 3:07pm

Did you want to share the full log or nah?

Gir4 · November 7, 2021, 3:16pm

The log file is full of PII, there is no any kind of error, failure in the log file, only similar entries what I already posted but for different files, nothing else

Animosity022 · November 7, 2021, 3:17pm

I'm just telling you what I need to assist. It's like going to the doctor and refusing to let them take your vitals.

Good luck.

Gir4 · November 7, 2021, 3:18pm

There is this line after some entry:

2021/11/07 15:10:45 DEBUG : Languages/xxx/xxx xxx/Stage 4/Lesson 5/Part-04-Lesson-05.mp3: vfs cache: delaying writeback as --transfers exceeded

Animosity022 · November 7, 2021, 3:22pm

Dunno as without the full log, it's somewhat pointless as we're just guessing and wasting my time.

Gir4 · November 7, 2021, 3:48pm

I'm sorry for inconvenience, I shared the full log file as DM

Animosity022 · November 7, 2021, 3:56pm

Fuse mounts are somewhat challenging to shut down depending on what you have going on.

If you don't set a KillMode in your service file, it'll finally result to killing the process, which leaves things in an odd state as it doesn't fully stop until all the IO against the mount is stopped.

I use:

KillMode=none

and I also make sure anything program/application that is going to use my fuse mount (rclone), it has a service dependency back to that process.

You want to be sure to stop all IO to the mount point, stop the service which is really doing a fusermount and it won't exit rclone until all the IO is done. If systemd doesn't have that killmode set, it'll kill the process forcefully and you get into a bad state.

In your log, you can see it started up twice:

2021/11/07 15:30:11 DEBUG : rclone: Version "v1.56.2" starting with parameters ["/usr/bin/rclone" "mount" "--config=/home/dmitry/.config/rclone/rclone.conf" "--cache-dir=/mnt/HDD/.cache_storage/gdrive" "--vfs-cache-mode" "full" "--vfs-cache-max-size" "500G" "--vfs-cache-max-age" "5000h" "--no-modtime" "-vv" "--log-file" "/home/dmitry/logs/rclone.log" "gdrive_crypt:" "/home/dmitry/my_mounts/gdrive"]
2021/11/07 15:32:43 DEBUG : rclone: Version "v1.56.2" starting with parameters ["/usr/bin/rclone" "mount" "--config=/home/dmitry/.config/rclone/rclone.conf" "--cache-dir=/mnt/HDD/.cache_storage/gdrive" "--vfs-cache-mode" "full" "--vfs-cache-max-size" "500G" "--vfs-cache-max-age" "5000h" "--no-modtime" "-vv" "--log-file" "/home/dmitry/logs/rclone.log" "gdrive_crypt:" "/home/dmitry/my_mounts/gdrive"]

These logs just mean:

vfs cache: delaying writeback as --transfers exceeded

That by default, it does 4 transfers at a time based on the transfers default so anything past that gets queued up.

So what I would do:

stop the service
ensure any IO processes against the mountpoint are stoped (if you have root, you can validate that with lsof
start the rclone command via command line and let things settle. It has to empty the queue out.

Once that finishes, add the KillMode=none, systemctl daemon-reload to refresh the service and validate that way. In the end, you do not want systemd killing rclone for you.

Gir4 · November 7, 2021, 4:04pm

After manually launching it looks like it's not restarting any more, thank you!

Animosity022 · November 7, 2021, 4:05pm

Fuse mounts are super annoying at times as they get 'stuck'. Glad you got it working!

ivandeex · November 7, 2021, 4:31pm

I just thought this might help with it

[Service]
Exec=rclone mount ... /mnt/point
ExecStopPre=-/bin/fusermount -uz /mnt/point
ExecStopPre=-/usr/bin/fuser -kMm /mnt/point

Lazy unmount will "hide" the mount from new access attempts keeping it for currently using processes.

Fuser will send SIGTERM to processes currently using the mount.

After that systemd will send SIGTERM to rclone.

This will not solve 100% cases but should make stopping more reliable.

Bad or ugly?

Animosity022 · November 7, 2021, 8:32pm

Hmm, I was doing some testing and I didn't have any luck with fuser.

I tried doing:

fusermount first and that made fuser not find a mount point since it was kind of dismounted.
If I swapped order, no real change.

My use case:

rclone mount to some mount point
cd into mountpoint which makes it in use
I tried fusermount/fuser and fuser/fusermount in order

I think the issue with systemd comes with it does a regular kill and after that doesn't work, it -9 the process which leaves the non connected transport state since some IO is still pegged to it.

I just try to make systemd services dependent so if rclone stops, anything that needs it also stops so I never get into that situation. Honestly, I never have had rclone crash or be unstable so it just runs for me with very little interaction.

system · November 10, 2021, 8:32pm

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