RClone Windows installed with NSSM constantly needs to be restarted

Ldelarosa · June 20, 2023, 4:39pm

What is the problem you are having with rclone?

I have RClone installed as a Windows Service by using NSSM. The connection seems to drop or stop working and the only way to get it restored is to stop and start the windows service.

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

C:\tools\rclone-v1.54.1-windows-amd64>rclone version
rclone v1.54.1

os/arch: windows/amd64
go version: go1.15.8

C:\tools\rclone-v1.54.1-windows-amd64>

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

Microsoft Azure Blob

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

The nssm Arguments that I used are...
mount AzureBlobQA1:hybris "E:\AzureBlobStorage\QA1" --log-file "C:\tools\logs\rcloneQA1.log" --dir-cache-time=160h --buffer-size=64M --attr-timeout=1s --vfs-read-chunk-size=2M --vfs-read-chunk-size-limit=2G --vfs-cache-max-age=5m --vfs-cache-mode=writes --cache-dir=C:\tools\RCloneCache\QA1 --config=C:\tools\rcloneQA1.conf

The rclone config contents with secrets removed.

[AzureBlobQA1]
type = azureblob
account = ojoxxxxxxxxxx
key = N9I+3kRId9XQU5Zxxxxxxxxxxxx

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

Log file does not contain any information

Thank you all for any help you can provide.

asdffdsa · June 20, 2023, 4:49pm

hello and welcome to the forum,

please update to latest stable and test again - v1.62.2
might try rclone selfupdate
if that does not work, then download latest version from
https://rclone.org/downloads/

add --log-level=DEBUG

Ldelarosa · June 21, 2023, 1:15pm

The update of the software seems to have helped keep the service alive for a longer period of time. Thanks. But the service did become unavailable / unresponsive. The overall program sends a file with a .TMP file extension to the mounted BLOB path. Then a Batch job is run to rename the .TMP file to a .CSV file. The service seems to allow the .TMP file to be written but times out during the rename when the service becomes unresponsive. Simply stopping and starting the windows service gets everything back to normal. I have a very large LOG file. Here is a portion from the end of the log...

2023/06/21 07:00:24 DEBUG : /: >Getattr: errc=0
2023/06/21 07:00:24 DEBUG : /: Opendir:
2023/06/21 07:00:24 DEBUG : /: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2023/06/21 07:00:24 DEBUG : /: >OpenFile: fd=/ (r), err=
2023/06/21 07:00:24 DEBUG : /: >Opendir: errc=0, fh=0x0
2023/06/21 07:00:24 DEBUG : /master: Getattr: fh=0xFFFFFFFFFFFFFFFF
2023/06/21 07:00:24 DEBUG : /master: >Getattr: errc=0
2023/06/21 07:00:24 DEBUG : /: Releasedir: fh=0x0
2023/06/21 07:00:24 DEBUG : /: >Releasedir: errc=0
2023/06/21 07:00:24 DEBUG : /master: Getattr: fh=0xFFFFFFFFFFFFFFFF
2023/06/21 07:00:24 DEBUG : /master: >Getattr: errc=0
2023/06/21 07:00:24 DEBUG : /master: Getattr: fh=0xFFFFFFFFFFFFFFFF
2023/06/21 07:00:24 DEBUG : /master: >Getattr: errc=0
2023/06/21 07:00:24 DEBUG : /master: Opendir:
2023/06/21 07:00:24 DEBUG : /master: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2023/06/21 07:00:24 DEBUG : /master: >OpenFile: fd=master/ (r), err=
2023/06/21 07:00:24 DEBUG : /master: >Opendir: errc=0, fh=0x0
2023/06/21 07:00:24 DEBUG : /master/inbound: Getattr: fh=0xFFFFFFFFFFFFFFFF
2023/06/21 07:00:24 DEBUG : /master/inbound: >Getattr: errc=0
2023/06/21 07:00:24 DEBUG : /master: Releasedir: fh=0x0
2023/06/21 07:00:24 DEBUG : /master: >Releasedir: errc=0
2023/06/21 07:00:24 DEBUG : /master/inbound: Getattr: fh=0xFFFFFFFFFFFFFFFF
2023/06/21 07:00:24 DEBUG : /master/inbound: >Getattr: errc=0
2023/06/21 07:00:24 DEBUG : /master/inbound: Getattr: fh=0xFFFFFFFFFFFFFFFF
2023/06/21 07:00:24 DEBUG : /master/inbound: >Getattr: errc=0
2023/06/21 07:00:24 DEBUG : /master/inbound: Opendir:
2023/06/21 07:00:24 DEBUG : /master/inbound: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2023/06/21 07:00:24 DEBUG : /master/inbound: >OpenFile: fd=master/inbound/ (r), err=
2023/06/21 07:00:24 DEBUG : /master/inbound: >Opendir: errc=0, fh=0x0
2023/06/21 07:00:24 DEBUG : /master/inbound: Releasedir: fh=0x0
2023/06/21 07:00:24 DEBUG : /master/inbound: >Releasedir: errc=0
2023/06/21 07:00:24 DEBUG : /master/inbound: Getattr: fh=0xFFFFFFFFFFFFFFFF
2023/06/21 07:00:24 DEBUG : /master/inbound: >Getattr: errc=0
2023/06/21 07:00:24 DEBUG : /master/inbound: Getattr: fh=0xFFFFFFFFFFFFFFFF
2023/06/21 07:00:24 DEBUG : /master/inbound: >Getattr: errc=0
2023/06/21 07:00:24 DEBUG : /master/inbound: Opendir:
2023/06/21 07:00:24 DEBUG : /master/inbound: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2023/06/21 07:00:24 DEBUG : /master/inbound: >OpenFile: fd=master/inbound/ (r), err=
2023/06/21 07:00:24 DEBUG : /master/inbound: >Opendir: errc=0, fh=0x0
2023/06/21 07:00:24 DEBUG : /master/inbound/inventory_sgws_170_20230621105930141.csv.tmp: Getattr: fh=0xFFFFFFFFFFFFFFFF
2023/06/21 07:00:24 DEBUG : /master/inbound/inventory_sgws_170_20230621105930141.csv.tmp: >Getattr: errc=0
2023/06/21 07:00:24 DEBUG : /master/inbound/inventory_sgws_170_20230621105930141.csv.tmp: Getattr: fh=0xFFFFFFFFFFFFFFFF
2023/06/21 07:00:24 DEBUG : /master/inbound/inventory_sgws_170_20230621105930141.csv.tmp: >Getattr: errc=0
2023/06/21 07:00:24 DEBUG : /master/inbound/inventory_sgws_170_20230621105930141.csv.tmp: OpenEx: flags=0x0
2023/06/21 07:00:24 DEBUG : /master/inbound/inventory_sgws_170_20230621105930141.csv.tmp: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2023/06/21 07:00:24 DEBUG : master/inbound/inventory_sgws_170_20230621105930141.csv.tmp: Open: flags=O_RDONLY
2023/06/21 07:00:24 DEBUG : master/inbound/inventory_sgws_170_20230621105930141.csv.tmp: newRWFileHandle:
2023/06/21 07:00:24 DEBUG : master/inbound/inventory_sgws_170_20230621105930141.csv.tmp: >newRWFileHandle: err=
2023/06/21 07:00:24 DEBUG : master/inbound/inventory_sgws_170_20230621105930141.csv.tmp: >Open: fd=master/inbound/inventory_sgws_170_20230621105930141.csv.tmp (rw), err=
2023/06/21 07:00:24 DEBUG : /master/inbound/inventory_sgws_170_20230621105930141.csv.tmp: >OpenFile: fd=master/inbound/inventory_sgws_170_20230621105930141.csv.tmp (rw), err=
2023/06/21 07:00:24 DEBUG : /master/inbound/inventory_sgws_170_20230621105930141.csv.tmp: >OpenEx: errc=0, fh=0x7
2023/06/21 07:00:24 DEBUG : /master/inbound/inventory_sgws_170_20230621105930141.csv.tmp: Flush: fh=0x7
2023/06/21 07:00:24 DEBUG : master/inbound/inventory_sgws_170_20230621105930141.csv.tmp(0xc009d43440): RWFileHandle.Flush
2023/06/21 07:00:24 DEBUG : /master/inbound/inventory_sgws_170_20230621105930141.csv.tmp: >Flush: errc=0
2023/06/21 07:00:24 DEBUG : /master/inbound/inventory_sgws_170_20230621105930141.csv.tmp: Getattr: fh=0xFFFFFFFFFFFFFFFF
2023/06/21 07:00:24 DEBUG : /master/inbound/inventory_sgws_170_20230621105930141.csv.tmp: Release: fh=0x7
2023/06/21 07:00:24 DEBUG : master/inbound/inventory_sgws_170_20230621105930141.csv.tmp(0xc009d43440): RWFileHandle.Release
2023/06/21 07:00:24 DEBUG : /master/inbound/inventory_sgws_170_20230621105930141.csv.tmp: >Getattr: errc=0
2023/06/21 07:00:24 DEBUG : master/inbound/inventory_sgws_170_20230621105930141.csv.tmp(0xc009d43440): close:
2023/06/21 07:00:24 DEBUG : master/inbound/inventory_sgws_170_20230621105930141.csv.tmp(0xc009d43440): >close: err=
2023/06/21 07:00:24 DEBUG : /master/inbound/inventory_sgws_170_20230621105930141.csv.tmp: >Release: errc=0
2023/06/21 07:00:24 DEBUG : /master/inbound/inventory_sgws_170_20230621105930141.csv.tmp: Getattr: fh=0xFFFFFFFFFFFFFFFF
2023/06/21 07:00:24 DEBUG : /master/inbound/inventory_sgws_170_20230621105930141.csv.tmp: >Getattr: errc=0
2023/06/21 07:00:24 DEBUG : /master/inbound/inventory_sgws_170_20230621105930141.csv.tmp: OpenEx: flags=0x0
2023/06/21 07:00:24 DEBUG : /master/inbound/inventory_sgws_170_20230621105930141.csv.tmp: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2023/06/21 07:00:24 DEBUG : master/inbound/inventory_sgws_170_20230621105930141.csv.tmp: Open: flags=O_RDONLY
2023/06/21 07:00:24 DEBUG : master/inbound/inventory_sgws_170_20230621105930141.csv.tmp: newRWFileHandle:
2023/06/21 07:00:24 DEBUG : master/inbound/inventory_sgws_170_20230621105930141.csv.tmp: >newRWFileHandle: err=
2023/06/21 07:00:24 DEBUG : master/inbound/inventory_sgws_170_20230621105930141.csv.tmp: >Open: fd=master/inbound/inventory_sgws_170_20230621105930141.csv.tmp (rw), err=
2023/06/21 07:00:24 DEBUG : /master/inbound/inventory_sgws_170_20230621105930141.csv.tmp: >OpenFile: fd=master/inbound/inventory_sgws_170_20230621105930141.csv.tmp (rw), err=
2023/06/21 07:00:24 DEBUG : /master/inbound/inventory_sgws_170_20230621105930141.csv.tmp: >OpenEx: errc=0, fh=0x7
2023/06/21 07:00:24 DEBUG : /master/inbound/inventory_sgws_170_20230621105930141.csv.tmp: Flush: fh=0x7
2023/06/21 07:00:24 DEBUG : master/inbound/inventory_sgws_170_20230621105930141.csv.tmp(0xc000f020c0): RWFileHandle.Flush
2023/06/21 07:00:24 DEBUG : /master/inbound/inventory_sgws_170_20230621105930141.csv.tmp: >Flush: errc=0
2023/06/21 07:00:24 DEBUG : /master/inbound/inventory_sgws_170_20230621105930141.csv.tmp: Release: fh=0x7
2023/06/21 07:00:24 DEBUG : master/inbound/inventory_sgws_170_20230621105930141.csv.tmp(0xc000f020c0): RWFileHandle.Release
2023/06/21 07:00:24 DEBUG : master/inbound/inventory_sgws_170_20230621105930141.csv.tmp(0xc000f020c0): close:
2023/06/21 07:00:24 DEBUG : master/inbound/inventory_sgws_170_20230621105930141.csv.tmp(0xc000f020c0): >close: err=
2023/06/21 07:00:24 DEBUG : /master/inbound/inventory_sgws_170_20230621105930141.csv.tmp: >Release: errc=0
2023/06/21 07:00:24 DEBUG : /master/inbound/inventory_sgws_170_20230621105930141.csv.tmp: Getattr: fh=0xFFFFFFFFFFFFFFFF
2023/06/21 07:00:24 DEBUG : /master/inbound/inventory_sgws_170_20230621105930141.csv.tmp: >Getattr: errc=0
2023/06/21 07:00:24 DEBUG : /master/inbound/inventory_sgws_170_20230621105930141.csv.tmp: Getattr: fh=0xFFFFFFFFFFFFFFFF
2023/06/21 07:00:24 DEBUG : /master/inbound/inventory_sgws_170_20230621105930141.csv.tmp: >Getattr: errc=0
2023/06/21 07:00:24 DEBUG : /master/inbound/inventory_sgws_170_20230621105930141.csv.tmp: OpenEx: flags=0x0
2023/06/21 07:00:24 DEBUG : /master/inbound/inventory_sgws_170_20230621105930141.csv.tmp: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2023/06/21 07:00:24 DEBUG : master/inbound/inventory_sgws_170_20230621105930141.csv.tmp: Open: flags=O_RDONLY
2023/06/21 07:00:24 DEBUG : master/inbound/inventory_sgws_170_20230621105930141.csv.tmp: newRWFileHandle:
2023/06/21 07:00:24 DEBUG : master/inbound/inventory_sgws_170_20230621105930141.csv.tmp: >newRWFileHandle: err=
2023/06/21 07:00:24 DEBUG : master/inbound/inventory_sgws_170_20230621105930141.csv.tmp: >Open: fd=master/inbound/inventory_sgws_170_20230621105930141.csv.tmp (rw), err=
2023/06/21 07:00:24 DEBUG : /master/inbound/inventory_sgws_170_20230621105930141.csv.tmp: >OpenFile: fd=master/inbound/inventory_sgws_170_20230621105930141.csv.tmp (rw), err=
2023/06/21 07:00:24 DEBUG : /master/inbound/inventory_sgws_170_20230621105930141.csv.tmp: >OpenEx: errc=0, fh=0x7
2023/06/21 07:00:24 DEBUG : /master/inbound/inventory_sgws_170_20230621105930141.csv.tmp: Flush: fh=0x7
2023/06/21 07:00:24 DEBUG : master/inbound/inventory_sgws_170_20230621105930141.csv.tmp(0xc0088ac540): RWFileHandle.Flush
2023/06/21 07:00:24 DEBUG : /master/inbound/inventory_sgws_170_20230621105930141.csv.tmp: >Flush: errc=0
2023/06/21 07:00:24 DEBUG : /master/inbound/inventory_sgws_170_20230621105930141.csv.tmp: Release: fh=0x7
2023/06/21 07:00:24 DEBUG : master/inbound/inventory_sgws_170_20230621105930141.csv.tmp(0xc0088ac540): RWFileHandle.Release
2023/06/21 07:00:24 DEBUG : /master/inbound: Getattr: fh=0xFFFFFFFFFFFFFFFF
2023/06/21 07:00:24 DEBUG : /master/inbound: >Getattr: errc=0
2023/06/21 07:00:24 DEBUG : master/inbound/inventory_sgws_170_20230621105930141.csv.tmp(0xc0088ac540): close:
2023/06/21 07:00:24 DEBUG : /master/inbound: Getattr: fh=0xFFFFFFFFFFFFFFFF
2023/06/21 07:00:24 DEBUG : /master/inbound: >Getattr: errc=0
2023/06/21 07:00:24 DEBUG : master/inbound/inventory_sgws_170_20230621105930141.csv.tmp(0xc0088ac540): >close: err=
2023/06/21 07:00:24 DEBUG : /master/inbound/inventory_sgws_170_20230621105930141.csv.tmp: >Release: errc=0
2023/06/21 07:00:24 DEBUG : /master/inbound: Opendir:
2023/06/21 07:00:24 DEBUG : /master/inbound: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2023/06/21 07:00:24 DEBUG : /master/inbound: >OpenFile: fd=master/inbound/ (r), err=
2023/06/21 07:00:24 DEBUG : /master/inbound: >Opendir: errc=0, fh=0x7
2023/06/21 07:00:24 DEBUG : /master/inbound/inventory_sgws_170_20230621105930141.csv.tmp: Getattr: fh=0xFFFFFFFFFFFFFFFF
2023/06/21 07:00:24 DEBUG : /master/inbound/inventory_sgws_170_20230621105930141.csv.tmp: >Getattr: errc=0
2023/06/21 07:00:24 DEBUG : /master/inbound/inventory_sgws_170_20230621105930141.csv.tmp: Getattr: fh=0xFFFFFFFFFFFFFFFF
2023/06/21 07:00:24 DEBUG : /master/inbound/inventory_sgws_170_20230621105930141.csv.tmp: >Getattr: errc=0
2023/06/21 07:00:24 DEBUG : /master/inbound/inventory_sgws_170_20230621105930141.csv.tmp: Getattr: fh=0xFFFFFFFFFFFFFFFF
2023/06/21 07:00:24 DEBUG : /master/inbound/inventory_sgws_170_20230621105930141.csv.tmp: >Getattr: errc=0
2023/06/21 07:00:24 DEBUG : /master/inbound/inventory_sgws_170_20230621105930141.csv.tmp: OpenEx: flags=0x0
2023/06/21 07:00:24 DEBUG : /master/inbound/inventory_sgws_170_20230621105930141.csv.tmp: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2023/06/21 07:00:24 DEBUG : master/inbound/inventory_sgws_170_20230621105930141.csv.tmp: Open: flags=O_RDONLY
2023/06/21 07:00:24 DEBUG : master/inbound/inventory_sgws_170_20230621105930141.csv.tmp: newRWFileHandle:
2023/06/21 07:00:24 DEBUG : master/inbound/inventory_sgws_170_20230621105930141.csv.tmp: >newRWFileHandle: err=
2023/06/21 07:00:24 DEBUG : master/inbound/inventory_sgws_170_20230621105930141.csv.tmp: >Open: fd=master/inbound/inventory_sgws_170_20230621105930141.csv.tmp (rw), err=
2023/06/21 07:00:24 DEBUG : /master/inbound/inventory_sgws_170_20230621105930141.csv.tmp: >OpenFile: fd=master/inbound/inventory_sgws_170_20230621105930141.csv.tmp (rw), err=
2023/06/21 07:00:24 DEBUG : /master/inbound/inventory_sgws_170_20230621105930141.csv.tmp: >OpenEx: errc=0, fh=0x8
2023/06/21 07:00:24 DEBUG : /master/inbound: Getattr: fh=0xFFFFFFFFFFFFFFFF
2023/06/21 07:00:24 DEBUG : /master/inbound: >Getattr: errc=0
2023/06/21 07:00:24 DEBUG : /master/inbound: Getattr: fh=0xFFFFFFFFFFFFFFFF
2023/06/21 07:00:24 DEBUG : /master/inbound: >Getattr: errc=0
2023/06/21 07:00:24 DEBUG : /master/inbound: Opendir:
2023/06/21 07:00:24 DEBUG : /master/inbound: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2023/06/21 07:00:24 DEBUG : /master/inbound: >OpenFile: fd=master/inbound/ (r), err=
2023/06/21 07:00:24 DEBUG : /master/inbound: >Opendir: errc=0, fh=0x9
2023/06/21 07:00:24 DEBUG : /master/inbound/inventory_sgws_170_20230621105930141.csv: Getattr: fh=0xFFFFFFFFFFFFFFFF
2023/06/21 07:00:24 DEBUG : /master/inbound/inventory_sgws_170_20230621105930141.csv: >Getattr: errc=-2
2023/06/21 07:00:24 DEBUG : /MASTER/INBOUND: Getattr: fh=0xFFFFFFFFFFFFFFFF
2023/06/21 07:00:24 DEBUG : /MASTER/INBOUND: >Getattr: errc=0
2023/06/21 07:00:24 DEBUG : /MASTER/INBOUND: Opendir:
2023/06/21 07:00:24 DEBUG : /MASTER/INBOUND: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2023/06/21 07:00:24 DEBUG : /MASTER/INBOUND: >OpenFile: fd=master/inbound/ (r), err=
2023/06/21 07:00:24 DEBUG : /MASTER/INBOUND: >Opendir: errc=0, fh=0xA
2023/06/21 07:00:24 DEBUG : /MASTER: Getattr: fh=0xFFFFFFFFFFFFFFFF
2023/06/21 07:00:24 DEBUG : /MASTER: >Getattr: errc=0
2023/06/21 07:00:24 DEBUG : /MASTER: Opendir:
2023/06/21 07:00:24 DEBUG : /MASTER: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2023/06/21 07:00:24 DEBUG : /MASTER: >OpenFile: fd=master/ (r), err=
2023/06/21 07:00:24 DEBUG : /MASTER: >Opendir: errc=0, fh=0xB
2023/06/21 07:00:24 DEBUG : /MASTER/INBOUND: Getattr: fh=0xFFFFFFFFFFFFFFFF
2023/06/21 07:00:24 DEBUG : /MASTER/INBOUND: >Getattr: errc=0
2023/06/21 07:00:24 DEBUG : /MASTER: Releasedir: fh=0xB
2023/06/21 07:00:24 DEBUG : /MASTER: >Releasedir: errc=0
2023/06/21 07:00:24 DEBUG : /MASTER/INBOUND: Releasedir: fh=0xA
2023/06/21 07:00:24 DEBUG : /MASTER/INBOUND: >Releasedir: errc=0
2023/06/21 07:00:24 DEBUG : /master/inbound/inventory_sgws_170_20230621105930141.csv: Getattr: fh=0xFFFFFFFFFFFFFFFF
2023/06/21 07:00:24 DEBUG : /master/inbound/inventory_sgws_170_20230621105930141.csv: >Getattr: errc=-2
2023/06/21 07:00:24 DEBUG : /master/inbound/inventory_sgws_170_20230621105930141.csv.tmp: Rename: newPath="/master/inbound/inventory_sgws_170_20230621105930141.csv"
2023/06/21 07:00:24 INFO : master/inbound/inventory_sgws_170_20230621105930141.csv.tmp: vfs cache: renamed in cache to "master/inbound/inventory_sgws_170_20230621105930141.csv"
2023/06/21 07:00:24 DEBUG : master/inbound/inventory_sgws_170_20230621105930141.csv: Updating file with 0xc0054a0f00
2023/06/21 07:00:24 DEBUG : master/inbound: Added virtual directory entry vDel: "inventory_sgws_170_20230621105930141.csv.tmp"
2023/06/21 07:00:24 DEBUG : master/inbound: Added virtual directory entry vAddFile: "inventory_sgws_170_20230621105930141.csv"
2023/06/21 07:00:24 DEBUG : /master/inbound/inventory_sgws_170_20230621105930141.csv.tmp: >Rename: errc=0
2023/06/21 07:00:24 DEBUG : /master/inbound: Releasedir: fh=0x9
2023/06/21 07:00:24 DEBUG : /master/inbound: >Releasedir: errc=0
2023/06/21 07:00:24 DEBUG : /master/inbound/inventory_sgws_170_20230621105930141.csv.tmp: Flush: fh=0x8
2023/06/21 07:00:24 DEBUG : master/inbound/inventory_sgws_170_20230621105930141.csv(0xc009d43480): RWFileHandle.Flush
2023/06/21 07:00:24 DEBUG : /master/inbound/inventory_sgws_170_20230621105930141.csv.tmp: >Flush: errc=0
2023/06/21 07:00:24 DEBUG : /master/inbound/inventory_sgws_170_20230621105930141.csv.tmp: Release: fh=0x8
2023/06/21 07:00:24 DEBUG : master/inbound/inventory_sgws_170_20230621105930141.csv(0xc009d43480): RWFileHandle.Release
2023/06/21 07:00:24 DEBUG : master/inbound/inventory_sgws_170_20230621105930141.csv(0xc009d43480): close:
2023/06/21 07:00:24 DEBUG : master/inbound/inventory_sgws_170_20230621105930141.csv(0xc009d43480): >close: err=
2023/06/21 07:00:24 DEBUG : /master/inbound/inventory_sgws_170_20230621105930141.csv.tmp: >Release: errc=0
2023/06/21 07:00:24 DEBUG : /master/inbound: Releasedir: fh=0x7
2023/06/21 07:00:24 DEBUG : /master/inbound: >Releasedir: errc=0
2023/06/21 07:00:24 DEBUG : /master/inbound: Releasedir: fh=0x0
2023/06/21 07:00:24 DEBUG : /master/inbound: >Releasedir: errc=0
2023/06/21 07:00:29 DEBUG : master/inbound/inventory_sgws_170_20230621105930141.csv: vfs cache: starting upload
2023/06/21 07:00:29 DEBUG : master/inbound/inventory_sgws_170_20230621105930141.csv: md5 = eba3d5699441d4a77853ef4f6a3309b0 OK
2023/06/21 07:00:29 INFO : master/inbound/inventory_sgws_170_20230621105930141.csv: Copied (new)
2023/06/21 07:00:29 DEBUG : master/inbound/inventory_sgws_170_20230621105930141.csv: vfs cache: fingerprint now "123,2023-06-21 11:00:24.8126353 +0000 UTC,eba3d5699441d4a77853ef4f6a3309b0"
2023/06/21 07:00:29 DEBUG : master/inbound/inventory_sgws_170_20230621105930141.csv: vfs cache: writeback object to VFS layer
2023/06/21 07:00:29 DEBUG : master/inbound: Added virtual directory entry vAddFile: "inventory_sgws_170_20230621105930141.csv"
2023/06/21 07:00:29 INFO : master/inbound/inventory_sgws_170_20230621105930141.csv: vfs cache: upload succeeded try #1
2023/06/21 07:01:03 DEBUG : vfs cache RemoveNotInUse (maxAge=300000000000, emptyOnly=false): item master/outbound/OrderReport_14_2_2023_1676361775431.csv not removed, freed 0 bytes
2023/06/21 07:01:03 DEBUG : vfs cache RemoveNotInUse (maxAge=300000000000, emptyOnly=false): item master/outbound/OrderReport_15_4_2023_1681542037465.csv not removed, freed 0 bytes
2023/06/21 07:01:03 DEBUG : vfs cache RemoveNotInUse (maxAge=300000000000, emptyOnly=false): item master/outbound/TestHybrisOrders_06-08-2022.csv not removed, freed 0 bytes

Thanks.

kapitainsky · June 21, 2023, 1:31pm

I would try simplified mount command to make sure that it is not one of the extra options causing problems, e.g.:

mount AzureBlobQA1:hybris "E:\AzureBlobStorage\QA1" --log-file "C:\tools\logs\rcloneQA1.log" --vfs-cache-mode full --cache-dir C:\tools\RCloneCache\QA1 --config C:\tools\rcloneQA1.conf

Also make sure that you have the latest winfsp. Your rclone was ancient so it can be also outdated.

https://winfsp.dev/

asdffdsa · June 21, 2023, 1:32pm

the log snippet looks ok, did not see any unusual delays.
the .tmp is renamed to .csv and then rclone uploads the file successfully.
and after that, the mount command continues to run with expected output.

as a test, run the mount, not as a service, but via command line.

Ldelarosa · June 25, 2023, 1:30pm

Thanks, I tried your suggestion. It made things worse. The connection would drop more often that with all the original switches.

Ldelarosa · June 25, 2023, 1:33pm

I have not tried this yet. But what I have done is the following. When I receive an error message that my program has timed out trying to execute the rename batch job I have logged on to the server and opened a command line prompt. Changed directories to the mounted drive and drilled down to the destination folder. Everything seems to be working and response times are ok. So I restart my program and that seems to keep the issue away for much longer.

Is there some time of "alive" switch in the RClone config that I can use?

asdffdsa · June 25, 2023, 1:40pm

what program?

what message?

the mount is always alive

kapitainsky · June 25, 2023, 2:33pm

This would suggest that it is not rclone mount freezing but your program. Then you say "rename batch job" so it implies multiple renames happening. It can be some limitations of winfsp causing problem with too many requests per second. It is easy to validate by adding delay between individual rename operations. As a proof of concept I would try with 1s - and if it works get it lower. Maybe something as small 10ms can be enough. Only test can tell.

Also make sure you have the latest winfsp. This program unfortunately does not have any autoupdate or notification about new version so often people use what they installed years ago.

Ldelarosa · June 26, 2023, 1:15am

I am not using Winfsp. I am using NSSM along with RClone to have the mount start as a Windows service. I can try to slow the process down but the renames are specific to the file names being Transmitted to the Blob account.

To be clear, the activity on the server that has the RClone mount drive is that the drive is unavailable at the time when the issue appears. If I start Windows Explorer and attempt to go to the mounted drive the hour glass spins for ever. This will last until I stop the Windows Service and start it up again. At that point all is well again.

Ldelarosa · June 26, 2023, 1:18am

The overall program used to move data around is an IBM Application called Sterling B2B Integrator. This application is running a business process developed by my team and when this process is unable to complete it's task, renaming the .TMP to .CSV on the Mounted Blob Drive, my team receives an error message from the process that states that the DOS rename command timed out.

kapitainsky · June 26, 2023, 5:26am

It is not possible. It is actual program which provides mount functionality on windows - rclone only interacts with it. There is ongoing winfsp development with tones of fixes and improvements in every version. This is why it is important to have the latest version installed. No Winfsp - no mount working at all.

NSSM is completely different story and has nothing to do with mount itself. It is service manager you use to launch rclone. Which also can be done using WinFsp Launcher. But it is not related to WinFsp itself.

Ldelarosa · June 26, 2023, 1:10pm

I stand corrected. I did install WINFSP on my servers. Let me upgrade that to see if that helps.
Thanks.

kapitainsky · June 26, 2023, 1:12pm

Let us know if it helps - it can be helpful for others with similar problems.

system · July 26, 2023, 1:13pm

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