Rclone cmount silently stops

Help and Support
1

What is the problem you are having with rclone?

Hello,

I have setup rclone cmount on an Azure blob storage. The mount randomly disappear after a few minute of normal usage. It also crashes when I try to open a directory with many files (>10K). I have been trying to solve this problem for 2 weeks now and I could not find the issue.
The logs are not informative / clear to me what could be the issue.

Would you have any recommendations ?

What is your rclone version (output from rclone version)

❯ rclone --version
rclone v1.53.4

  • os/arch: darwin/amd64
  • go version: go1.15.6

Which OS you are using and how many bits (eg Windows 7, 64 bit)

MacOS Big Sur 11.1 (20C69)

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

Azure blob storage

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

rclone cmount sail:azureml-blobstore-<id> /Users/thomassajot/mnt/azure_storage --vfs-cache-max-age 1h0m0s --dir-cache-time 1h0m0s --poll-interval 0 --vfs-cache-poll-interval 0  -vvvv

The rclone config contents with secrets removed.

[sail]
type = azureblob
account = <blob account name>
key =<azure key>

A log from the command with the -vv flag

I removed the following repeated 2 lines to lighten the logs

2021/01/29 18:11:47 DEBUG : /: Access: mask=00
2021/01/29 18:11:47 DEBUG : /: >Access: errc=0

2021/01/29 18:11:47 DEBUG : rclone: Version "v1.53.4" starting with parameters ["rclone" "cmount" "sail:azureml-blobstore-<id>" "/Users/thomassajot/mnt/azure_storage" "--vfs-cache-max-age" "1h0m0s" "--dir-cache-time" "1h0m0s" "--poll-interval" "0" "--vfs-cache-poll-interval" "0" "-vvvv"]
2021/01/29 18:11:47 DEBUG : Creating backend with remote "sail:azureml-blobstore-<id>"
2021/01/29 18:11:47 DEBUG : Using config file from "/Users/thomassajot/.config/rclone/rclone.conf"
2021/01/29 18:11:47 INFO  : Azure container azureml-blobstore-<id>: poll-interval is not supported by this remote
2021/01/29 18:11:47 DEBUG : Azure container azureml-blobstore-<id>: Mounting on "/Users/thomassajot/mnt/azure_storage"
2021/01/29 18:11:47 DEBUG : Azure container azureml-blobstore-<id>: Mounting with options: ["-o" "fsname=sail:azureml-blobstore-<id>" "-o" "subtype=rclone" "-o" "max_readahead=131072" "-o" "attr_timeout=1" "-o" "atomic_o_trunc" "-o" "noappledouble" "-o" "volname=sail azureml-blobstore-<id>"]
2021/01/29 18:11:47 DEBUG : Azure container azureml-blobstore-<id>: Init:
2021/01/29 18:11:47 DEBUG : Azure container azureml-blobstore-<id>: >Init:
2021/01/29 18:11:47 DEBUG : /: Statfs:
2021/01/29 18:11:47 DEBUG : /: >Statfs: stat={Bsize:4096 Frsize:4096 Blocks:4294967295 Bfree:4294967295 Bavail:4294967295 Files:1000000000 Ffree:1000000000 Favail:0 Fsid:0 Flag:0 Namemax:255}, errc=0
2021/01/29 18:11:47 DEBUG : /: Statfs:
2021/01/29 18:11:47 DEBUG : /: Statfs:
2021/01/29 18:11:47 DEBUG : /: Statfs:
2021/01/29 18:11:47 DEBUG : /: >Statfs: stat={Bsize:4096 Frsize:4096 Blocks:4294967295 Bfree:4294967295 Bavail:4294967295 Files:1000000000 Ffree:1000000000 Favail:0 Fsid:0 Flag:0 Namemax:255}, errc=0
2021/01/29 18:11:47 DEBUG : /: >Statfs: stat={Bsize:4096 Frsize:4096 Blocks:4294967295 Bfree:4294967295 Bavail:4294967295 Files:1000000000 Ffree:1000000000 Favail:0 Fsid:0 Flag:0 Namemax:255}, errc=0
2021/01/29 18:11:47 DEBUG : /: >Statfs: stat={Bsize:4096 Frsize:4096 Blocks:4294967295 Bfree:4294967295 Bavail:4294967295 Files:1000000000 Ffree:1000000000 Favail:0 Fsid:0 Flag:0 Namemax:255}, errc=0
2021/01/29 18:11:47 DEBUG : /: Statfs:
2021/01/29 18:11:47 DEBUG : /: >Statfs: stat={Bsize:4096 Frsize:4096 Blocks:4294967295 Bfree:4294967295 Bavail:4294967295 Files:1000000000 Ffree:1000000000 Favail:0 Fsid:0 Flag:0 Namemax:255}, errc=0
2021/01/29 18:11:47 DEBUG : /: Statfs:
2021/01/29 18:11:47 DEBUG : /: >Statfs: stat={Bsize:4096 Frsize:4096 Blocks:4294967295 Bfree:4294967295 Bavail:4294967295 Files:1000000000 Ffree:1000000000 Favail:0 Fsid:0 Flag:0 Namemax:255}, errc=0
2021/01/29 18:11:47 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/01/29 18:11:47 DEBUG : /: >Getattr: errc=0
2021/01/29 18:11:47 DEBUG : /: Statfs:
2021/01/29 18:11:47 DEBUG : /: >Statfs: stat={Bsize:4096 Frsize:4096 Blocks:4294967295 Bfree:4294967295 Bavail:4294967295 Files:1000000000 Ffree:1000000000 Favail:0 Fsid:0 Flag:0 Namemax:255}, errc=0
2021/01/29 18:11:47 DEBUG : /: Statfs:
2021/01/29 18:11:47 DEBUG : /: Statfs:
2021/01/29 18:11:47 DEBUG : /: >Statfs: stat={Bsize:4096 Frsize:4096 Blocks:4294967295 Bfree:4294967295 Bavail:4294967295 Files:1000000000 Ffree:1000000000 Favail:0 Fsid:0 Flag:0 Namemax:255}, errc=0
2021/01/29 18:11:47 DEBUG : /: >Statfs: stat={Bsize:4096 Frsize:4096 Blocks:4294967295 Bfree:4294967295 Bavail:4294967295 Files:1000000000 Ffree:1000000000 Favail:0 Fsid:0 Flag:0 Namemax:255}, errc=0
2021/01/29 18:11:47 DEBUG : /: Statfs:
2021/01/29 18:11:47 DEBUG : /: >Statfs: stat={Bsize:4096 Frsize:4096 Blocks:4294967295 Bfree:4294967295 Bavail:4294967295 Files:1000000000 Ffree:1000000000 Favail:0 Fsid:0 Flag:0 Namemax:255}, errc=0
2021/01/29 18:11:47 DEBUG : /: Statfs:
2021/01/29 18:11:47 DEBUG : /: >Statfs: stat={Bsize:4096 Frsize:4096 Blocks:4294967295 Bfree:4294967295 Bavail:4294967295 Files:1000000000 Ffree:1000000000 Favail:0 Fsid:0 Flag:0 Namemax:255}, errc=0
2021/01/29 18:11:47 DEBUG : /: Statfs:
2021/01/29 18:11:47 DEBUG : /: >Statfs: stat={Bsize:4096 Frsize:4096 Blocks:4294967295 Bfree:4294967295 Bavail:4294967295 Files:1000000000 Ffree:1000000000 Favail:0 Fsid:0 Flag:0 Namemax:255}, errc=0
2021/01/29 18:11:47 DEBUG : /: Statfs:
2021/01/29 18:11:47 DEBUG : /: >Statfs: stat={Bsize:4096 Frsize:4096 Blocks:4294967295 Bfree:4294967295 Bavail:4294967295 Files:1000000000 Ffree:1000000000 Favail:0 Fsid:0 Flag:0 Namemax:255}, errc=0
2021/01/29 18:11:47 DEBUG : /: Statfs:
2021/01/29 18:11:47 DEBUG : /: >Statfs: stat={Bsize:4096 Frsize:4096 Blocks:4294967295 Bfree:4294967295 Bavail:4294967295 Files:1000000000 Ffree:1000000000 Favail:0 Fsid:0 Flag:0 Namemax:255}, errc=0
2021/01/29 18:11:47 DEBUG : /: Access: mask=04
2021/01/29 18:11:47 DEBUG : /: Access: mask=04
2021/01/29 18:11:47 DEBUG : /: Access: mask=02
2021/01/29 18:11:47 DEBUG : /: Access: mask=04
2021/01/29 18:11:47 DEBUG : /: Access: mask=01
2021/01/29 18:11:47 DEBUG : /: Access: mask=02
2021/01/29 18:11:47 DEBUG : /: Access: mask=04
2021/01/29 18:11:47 DEBUG : /: Access: mask=01
2021/01/29 18:11:47 DEBUG : /: Access: mask=02
2021/01/29 18:11:47 DEBUG : /: Access: mask=04
2021/01/29 18:11:47 DEBUG : /: Access: mask=01
2021/01/29 18:11:47 DEBUG : /: Statfs:
2021/01/29 18:11:47 DEBUG : /: >Statfs: stat={Bsize:4096 Frsize:4096 Blocks:4294967295 Bfree:4294967295 Bavail:4294967295 Files:1000000000 Ffree:1000000000 Favail:0 Fsid:0 Flag:0 Namemax:255}, errc=0
2021/01/29 18:11:47 DEBUG : /: Statfs:
2021/01/29 18:11:47 DEBUG : /: >Statfs: stat={Bsize:4096 Frsize:4096 Blocks:4294967295 Bfree:4294967295 Bavail:4294967295 Files:1000000000 Ffree:1000000000 Favail:0 Fsid:0 Flag:0 Namemax:255}, errc=0
2021/01/29 18:11:47 DEBUG : /: Statfs:
2021/01/29 18:11:47 DEBUG : /: >Statfs: stat={Bsize:4096 Frsize:4096 Blocks:4294967295 Bfree:4294967295 Bavail:4294967295 Files:1000000000 Ffree:1000000000 Favail:0 Fsid:0 Flag:0 Namemax:255}, errc=0
2021/01/29 18:11:47 DEBUG : /: Statfs:
2021/01/29 18:11:47 DEBUG : /: >Statfs: stat={Bsize:4096 Frsize:4096 Blocks:4294967295 Bfree:4294967295 Bavail:4294967295 Files:1000000000 Ffree:1000000000 Favail:0 Fsid:0 Flag:0 Namemax:255}, errc=0
2021/01/29 18:11:47 DEBUG : /: Statfs:
2021/01/29 18:11:47 DEBUG : /: >Statfs: stat={Bsize:4096 Frsize:4096 Blocks:4294967295 Bfree:4294967295 Bavail:4294967295 Files:1000000000 Ffree:1000000000 Favail:0 Fsid:0 Flag:0 Namemax:255}, errc=0
2021/01/29 18:11:47 DEBUG : /: Statfs:
2021/01/29 18:11:47 DEBUG : /: >Statfs: stat={Bsize:4096 Frsize:4096 Blocks:4294967295 Bfree:4294967295 Bavail:4294967295 Files:1000000000 Ffree:1000000000 Favail:0 Fsid:0 Flag:0 Namemax:255}, errc=0
2021/01/29 18:11:47 DEBUG : /: Statfs:
2021/01/29 18:11:47 DEBUG : /: Statfs:
2021/01/29 18:11:47 DEBUG : /: >Statfs: stat={Bsize:4096 Frsize:4096 Blocks:4294967295 Bfree:4294967295 Bavail:4294967295 Files:1000000000 Ffree:1000000000 Favail:0 Fsid:0 Flag:0 Namemax:255}, errc=0
2021/01/29 18:11:47 DEBUG : /: >Statfs: stat={Bsize:4096 Frsize:4096 Blocks:4294967295 Bfree:4294967295 Bavail:4294967295 Files:1000000000 Ffree:1000000000 Favail:0 Fsid:0 Flag:0 Namemax:255}, errc=0
2021/01/29 18:11:47 DEBUG : /: Statfs:
2021/01/29 18:11:47 DEBUG : /: Statfs:
2021/01/29 18:11:47 DEBUG : /: >Statfs: stat={Bsize:4096 Frsize:4096 Blocks:4294967295 Bfree:4294967295 Bavail:4294967295 Files:1000000000 Ffree:1000000000 Favail:0 Fsid:0 Flag:0 Namemax:255}, errc=0
2021/01/29 18:11:47 DEBUG : /: >Statfs: stat={Bsize:4096 Frsize:4096 Blocks:4294967295 Bfree:4294967295 Bavail:4294967295 Files:1000000000 Ffree:1000000000 Favail:0 Fsid:0 Flag:0 Namemax:255}, errc=0
2021/01/29 18:11:47 DEBUG : /: Statfs:
2021/01/29 18:11:47 DEBUG : /: >Statfs: stat={Bsize:4096 Frsize:4096 Blocks:4294967295 Bfree:4294967295 Bavail:4294967295 Files:1000000000 Ffree:1000000000 Favail:0 Fsid:0 Flag:0 Namemax:255}, errc=0
2021/01/29 18:11:47 DEBUG : /: Statfs:
2021/01/29 18:11:47 DEBUG : /: Statfs:
2021/01/29 18:11:47 DEBUG : /: >Statfs: stat={Bsize:4096 Frsize:4096 Blocks:4294967295 Bfree:4294967295 Bavail:4294967295 Files:1000000000 Ffree:1000000000 Favail:0 Fsid:0 Flag:0 Namemax:255}, errc=0
2021/01/29 18:11:47 DEBUG : /: >Statfs: stat={Bsize:4096 Frsize:4096 Blocks:4294967295 Bfree:4294967295 Bavail:4294967295 Files:1000000000 Ffree:1000000000 Favail:0 Fsid:0 Flag:0 Namemax:255}, errc=0
2021/01/29 18:11:47 DEBUG : /: Statfs:
2021/01/29 18:11:47 DEBUG : /: >Statfs: stat={Bsize:4096 Frsize:4096 Blocks:4294967295 Bfree:4294967295 Bavail:4294967295 Files:1000000000 Ffree:1000000000 Favail:0 Fsid:0 Flag:0 Namemax:255}, errc=0
2021/01/29 18:11:47 DEBUG : /: Statfs:
2021/01/29 18:11:47 DEBUG : /: >Statfs: stat={Bsize:4096 Frsize:4096 Blocks:4294967295 Bfree:4294967295 Bavail:4294967295 Files:1000000000 Ffree:1000000000 Favail:0 Fsid:0 Flag:0 Namemax:255}, errc=0
2021/01/29 18:11:47 DEBUG : /: Access: mask=02
2021/01/29 18:11:47 DEBUG : /: Access: mask=04
2021/01/29 18:11:47 DEBUG : /: Access: mask=01
2021/01/29 18:11:47 DEBUG : /: Statfs:
2021/01/29 18:11:47 DEBUG : /: >Statfs: stat={Bsize:4096 Frsize:4096 Blocks:4294967295 Bfree:4294967295 Bavail:4294967295 Files:1000000000 Ffree:1000000000 Favail:0 Fsid:0 Flag:0 Namemax:255}, errc=0
2021/01/29 18:11:47 DEBUG : /: Statfs:
2021/01/29 18:11:47 DEBUG : /: >Statfs: stat={Bsize:4096 Frsize:4096 Blocks:4294967295 Bfree:4294967295 Bavail:4294967295 Files:1000000000 Ffree:1000000000 Favail:0 Fsid:0 Flag:0 Namemax:255}, errc=0
2021/01/29 18:11:47 DEBUG : /: Access: mask=02
2021/01/29 18:11:47 DEBUG : /: Access: mask=04
2021/01/29 18:11:47 DEBUG : /: Access: mask=01
2021/01/29 18:11:47 DEBUG : /: Access: mask=02
2021/01/29 18:11:47 DEBUG : /: Access: mask=04
2021/01/29 18:11:47 DEBUG : /: Access: mask=01
2021/01/29 18:11:47 DEBUG : /: Access: mask=01
2021/01/29 18:11:47 DEBUG : /.hidden: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/01/29 18:11:48 DEBUG : /.hidden: >Getattr: errc=-2
2021/01/29 18:11:48 DEBUG : /: Access: mask=01
2021/01/29 18:11:48 DEBUG : /.hidden: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/01/29 18:11:48 DEBUG : /.hidden: >Getattr: errc=-2
2021/01/29 18:11:48 DEBUG : /: Access: mask=02
2021/01/29 18:11:48 DEBUG : /: Access: mask=04
2021/01/29 18:11:48 DEBUG : /: Access: mask=01
2021/01/29 18:11:48 DEBUG : /: Access: mask=04
2021/01/29 18:11:48 DEBUG : /: Access: mask=04
2021/01/29 18:11:48 DEBUG : /: Statfs:
2021/01/29 18:11:48 DEBUG : /: >Statfs: stat={Bsize:4096 Frsize:4096 Blocks:4294967295 Bfree:4294967295 Bavail:4294967295 Files:1000000000 Ffree:1000000000 Favail:0 Fsid:0 Flag:0 Namemax:255}, errc=0
2021/01/29 18:11:48 DEBUG : /: Access: mask=01
2021/01/29 18:11:48 DEBUG : /.hidden: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/01/29 18:11:48 DEBUG : /.hidden: >Getattr: errc=-2
2021/01/29 18:11:48 DEBUG : /: Statfs:
2021/01/29 18:11:48 DEBUG : /: >Statfs: stat={Bsize:4096 Frsize:4096 Blocks:4294967295 Bfree:4294967295 Bavail:4294967295 Files:1000000000 Ffree:1000000000 Favail:0 Fsid:0 Flag:0 Namemax:255}, errc=0
2021/01/29 18:11:48 DEBUG : /: Access: mask=02
2021/01/29 18:11:48 DEBUG : /: Access: mask=04
2021/01/29 18:11:48 DEBUG : /: Access: mask=01
2021/01/29 18:11:48 DEBUG : /: Access: mask=02
2021/01/29 18:11:48 DEBUG : /: Access: mask=04
2021/01/29 18:11:48 DEBUG : /: Access: mask=01
2021/01/29 18:11:48 DEBUG : /: Access: mask=01
2021/01/29 18:11:53 DEBUG : /: Access: mask=02
2021/01/29 18:11:53 DEBUG : /: Access: mask=02
2021/01/29 18:11:53 DEBUG : /: Access: mask=02
2021/01/29 18:11:53 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/01/29 18:11:53 DEBUG : /: >Getattr: errc=0
2021/01/29 18:11:53 DEBUG : /: Access: mask=02
2021/01/29 18:11:53 DEBUG : /: Access: mask=04
2021/01/29 18:11:53 DEBUG : /: Access: mask=01
2021/01/29 18:11:53 DEBUG : /: Access: mask=02
2021/01/29 18:11:53 DEBUG : /: Access: mask=02
2021/01/29 18:11:53 DEBUG : /: Access: mask=02
2021/01/29 18:11:53 DEBUG : /: Access: mask=04
2021/01/29 18:11:53 DEBUG : /: Access: mask=04
2021/01/29 18:11:53 DEBUG : /: Statfs:
2021/01/29 18:11:53 DEBUG : /: >Statfs: stat={Bsize:4096 Frsize:4096 Blocks:4294967295 Bfree:4294967295 Bavail:4294967295 Files:1000000000 Ffree:1000000000 Favail:0 Fsid:0 Flag:0 Namemax:255}, errc=0
2021/01/29 18:11:53 DEBUG : /: Access: mask=04
2021/01/29 18:11:53 DEBUG : /: Statfs:
2021/01/29 18:11:53 DEBUG : /: >Statfs: stat={Bsize:4096 Frsize:4096 Blocks:4294967295 Bfree:4294967295 Bavail:4294967295 Files:1000000000 Ffree:1000000000 Favail:0 Fsid:0 Flag:0 Namemax:255}, errc=0
2021/01/29 18:11:53 DEBUG : /: Access: mask=02
2021/01/29 18:11:53 DEBUG : /: Access: mask=04
2021/01/29 18:11:53 DEBUG : /: Access: mask=01
2021/01/29 18:11:53 DEBUG : /: Access: mask=04
2021/01/29 18:11:53 DEBUG : /: Opendir:
2021/01/29 18:11:53 DEBUG : /: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2021/01/29 18:11:53 DEBUG : /: >OpenFile: fd=/ (r), err=<nil>
2021/01/29 18:11:53 DEBUG : /: >Opendir: errc=0, fh=0x0
2021/01/29 18:11:53 DEBUG : /: Access: mask=05
2021/01/29 18:11:53 DEBUG : /: Readdir: ofst=0, fh=0x0
2021/01/29 18:11:53 DEBUG : /: >Readdir: items=4, errc=0
2021/01/29 18:11:53 DEBUG : /: Access: mask=01
2021/01/29 18:11:53 DEBUG : /JLR: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/01/29 18:11:53 DEBUG : /JLR: >Getattr: errc=0
2021/01/29 18:11:53 DEBUG : /JLR: Access: mask=00
2021/01/29 18:11:53 DEBUG : /JLR: >Access: errc=0
2021/01/29 18:11:53 DEBUG : /JLR: Access: mask=02
2021/01/29 18:11:53 DEBUG : /JLR: >Access: errc=0
2021/01/29 18:11:53 DEBUG : /JLR: Access: mask=04
2021/01/29 18:11:53 DEBUG : /JLR: >Access: errc=0
2021/01/29 18:11:53 DEBUG : /JLR: Access: mask=01
2021/01/29 18:11:53 DEBUG : /JLR: >Access: errc=0
2021/01/29 18:11:53 DEBUG : /Master_Invoices: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/01/29 18:11:53 DEBUG : /Master_Invoices: >Getattr: errc=0
2021/01/29 18:11:53 DEBUG : /Master_Invoices: Access: mask=00
2021/01/29 18:11:53 DEBUG : /Master_Invoices: >Access: errc=0
2021/01/29 18:11:53 DEBUG : /Master_Invoices: Access: mask=02
2021/01/29 18:11:53 DEBUG : /Master_Invoices: >Access: errc=0
2021/01/29 18:11:53 DEBUG : /Master_Invoices: Access: mask=04
2021/01/29 18:11:53 DEBUG : /Master_Invoices: >Access: errc=0
2021/01/29 18:11:53 DEBUG : /Master_Invoices: Access: mask=01
2021/01/29 18:11:53 DEBUG : /Master_Invoices: >Access: errc=0
2021/01/29 18:11:53 DEBUG : /ABC_FOLDER: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/01/29 18:11:53 DEBUG : /ABC_FOLDER: >Getattr: errc=0
2021/01/29 18:11:53 DEBUG : /ABC_FOLDER: Access: mask=00
2021/01/29 18:11:53 DEBUG : /ABC_FOLDER: >Access: errc=0
2021/01/29 18:11:53 DEBUG : /ABC_FOLDER: Access: mask=02
2021/01/29 18:11:53 DEBUG : /ABC_FOLDER: >Access: errc=0
2021/01/29 18:11:53 DEBUG : /ABC_FOLDER: Access: mask=04
2021/01/29 18:11:53 DEBUG : /ABC_FOLDER: >Access: errc=0
2021/01/29 18:11:53 DEBUG : /ABC_FOLDER: Access: mask=01
2021/01/29 18:11:53 DEBUG : /ABC_FOLDER: >Access: errc=0
2021/01/29 18:11:53 DEBUG : /models: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/01/29 18:11:53 DEBUG : /models: >Getattr: errc=0
2021/01/29 18:11:53 DEBUG : /models: Access: mask=00
2021/01/29 18:11:53 DEBUG : /models: >Access: errc=0
2021/01/29 18:11:53 DEBUG : /models: Access: mask=02
2021/01/29 18:11:53 DEBUG : /models: >Access: errc=0
2021/01/29 18:11:53 DEBUG : /models: Access: mask=04
2021/01/29 18:11:53 DEBUG : /models: >Access: errc=0
2021/01/29 18:11:53 DEBUG : /models: Access: mask=01
2021/01/29 18:11:53 DEBUG : /models: >Access: errc=0
2021/01/29 18:11:53 DEBUG : /: Access: mask=05
2021/01/29 18:11:53 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/01/29 18:11:53 DEBUG : /: >Getattr: errc=0
2021/01/29 18:11:53 DEBUG : /: Releasedir: fh=0x0
2021/01/29 18:11:53 DEBUG : /: >Releasedir: errc=0
2021/01/29 18:11:53 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/01/29 18:11:53 DEBUG : /: >Getattr: errc=0
2021/01/29 18:11:53 DEBUG : /: Statfs:
2021/01/29 18:11:53 DEBUG : /: >Statfs: stat={Bsize:4096 Frsize:4096 Blocks:4294967295 Bfree:4294967295 Bavail:4294967295 Files:1000000000 Ffree:1000000000 Favail:0 Fsid:0 Flag:0 Namemax:255}, errc=0
2021/01/29 18:11:53 DEBUG : /JLR: Access: mask=00
2021/01/29 18:11:53 DEBUG : /JLR: >Access: errc=0
2021/01/29 18:11:53 DEBUG : /Master_Invoices: Access: mask=00
2021/01/29 18:11:53 DEBUG : /Master_Invoices: >Access: errc=0
2021/01/29 18:11:53 DEBUG : /JLR: Access: mask=00
2021/01/29 18:11:53 DEBUG : /JLR: >Access: errc=0
2021/01/29 18:11:53 DEBUG : /JLR: Access: mask=00
2021/01/29 18:11:53 DEBUG : /JLR: >Access: errc=0
2021/01/29 18:11:53 DEBUG : /JLR: Access: mask=00
2021/01/29 18:11:53 DEBUG : /JLR: >Access: errc=0
2021/01/29 18:11:53 DEBUG : /JLR: Access: mask=02
2021/01/29 18:11:53 DEBUG : /JLR: >Access: errc=0
2021/01/29 18:11:53 DEBUG : /models: Access: mask=00
2021/01/29 18:11:53 DEBUG : /models: >Access: errc=0
2021/01/29 18:11:53 DEBUG : /JLR: Access: mask=04
2021/01/29 18:11:53 DEBUG : /JLR: >Access: errc=0
2021/01/29 18:11:53 DEBUG : /JLR: Access: mask=01
2021/01/29 18:11:53 DEBUG : /JLR: >Access: errc=0
2021/01/29 18:11:53 DEBUG : /ABC_FOLDER: Access: mask=00
2021/01/29 18:11:53 DEBUG : /ABC_FOLDER: >Access: errc=0
2021/01/29 18:11:53 DEBUG : /JLR: Access: mask=00
2021/01/29 18:11:53 DEBUG : /JLR: >Access: errc=0
2021/01/29 18:11:53 DEBUG : /JLR: Access: mask=00
2021/01/29 18:11:53 DEBUG : /JLR: >Access: errc=0
2021/01/29 18:11:53 DEBUG : /: Access: mask=02
2021/01/29 18:11:53 DEBUG : /: Access: mask=04
2021/01/29 18:11:53 DEBUG : /: Access: mask=01
2021/01/29 18:11:53 DEBUG : /Master_Invoices: Access: mask=00
2021/01/29 18:11:53 DEBUG : /Master_Invoices: >Access: errc=0
2021/01/29 18:11:53 DEBUG : /Master_Invoices: Access: mask=00
2021/01/29 18:11:53 DEBUG : /Master_Invoices: >Access: errc=0
2021/01/29 18:11:53 DEBUG : /Master_Invoices: Access: mask=00
2021/01/29 18:11:53 DEBUG : /Master_Invoices: >Access: errc=0
2021/01/29 18:11:53 DEBUG : /Master_Invoices: Access: mask=02
2021/01/29 18:11:53 DEBUG : /Master_Invoices: >Access: errc=0
2021/01/29 18:11:53 DEBUG : /Master_Invoices: Access: mask=04
2021/01/29 18:11:53 DEBUG : /Master_Invoices: >Access: errc=0
2021/01/29 18:11:53 DEBUG : /Master_Invoices: Access: mask=01
2021/01/29 18:11:53 DEBUG : /Master_Invoices: >Access: errc=0
2021/01/29 18:11:53 DEBUG : /Master_Invoices: Access: mask=00
2021/01/29 18:11:53 DEBUG : /Master_Invoices: >Access: errc=0
2021/01/29 18:11:53 DEBUG : /Master_Invoices: Access: mask=00
2021/01/29 18:11:53 DEBUG : /Master_Invoices: >Access: errc=0
2021/01/29 18:11:53 DEBUG : /: Access: mask=02
2021/01/29 18:11:53 DEBUG : /: Access: mask=04
2021/01/29 18:11:53 DEBUG : /: Access: mask=01
2021/01/29 18:11:53 DEBUG : /models: Access: mask=00
2021/01/29 18:11:53 DEBUG : /models: >Access: errc=0
2021/01/29 18:11:53 DEBUG : /models: Access: mask=00
2021/01/29 18:11:53 DEBUG : /models: >Access: errc=0
2021/01/29 18:11:53 DEBUG : /models: Access: mask=00
2021/01/29 18:11:53 DEBUG : /models: >Access: errc=0
2021/01/29 18:11:53 DEBUG : /models: Access: mask=02
2021/01/29 18:11:53 DEBUG : /models: >Access: errc=0
2021/01/29 18:11:53 DEBUG : /models: Access: mask=04
2021/01/29 18:11:53 DEBUG : /models: >Access: errc=0
2021/01/29 18:11:53 DEBUG : /models: Access: mask=01
2021/01/29 18:11:53 DEBUG : /models: >Access: errc=0
2021/01/29 18:11:53 DEBUG : /models: Access: mask=00
2021/01/29 18:11:53 DEBUG : /models: >Access: errc=0
2021/01/29 18:11:53 DEBUG : /models: Access: mask=00
2021/01/29 18:11:53 DEBUG : /models: >Access: errc=0
2021/01/29 18:11:53 DEBUG : /: Access: mask=02
2021/01/29 18:11:53 DEBUG : /: Access: mask=04
2021/01/29 18:11:53 DEBUG : /: Access: mask=01
2021/01/29 18:11:53 DEBUG : /ABC_FOLDER: Access: mask=00
2021/01/29 18:11:53 DEBUG : /ABC_FOLDER: >Access: errc=0
2021/01/29 18:11:53 DEBUG : /ABC_FOLDER: Access: mask=00
2021/01/29 18:11:53 DEBUG : /ABC_FOLDER: >Access: errc=0
2021/01/29 18:11:53 DEBUG : /ABC_FOLDER: Access: mask=00
2021/01/29 18:11:53 DEBUG : /ABC_FOLDER: >Access: errc=0
2021/01/29 18:11:53 DEBUG : /ABC_FOLDER: Access: mask=02
2021/01/29 18:11:53 DEBUG : /ABC_FOLDER: >Access: errc=0
2021/01/29 18:11:53 DEBUG : /ABC_FOLDER: Access: mask=04
2021/01/29 18:11:53 DEBUG : /ABC_FOLDER: >Access: errc=0
2021/01/29 18:11:53 DEBUG : /ABC_FOLDER: Access: mask=01
2021/01/29 18:11:53 DEBUG : /ABC_FOLDER: >Access: errc=0
2021/01/29 18:11:53 DEBUG : /ABC_FOLDER: Access: mask=00
2021/01/29 18:11:53 DEBUG : /ABC_FOLDER: >Access: errc=0
2021/01/29 18:11:53 DEBUG : /ABC_FOLDER: Access: mask=00
2021/01/29 18:11:53 DEBUG : /ABC_FOLDER: >Access: errc=0
2021/01/29 18:11:53 DEBUG : /: Access: mask=02
2021/01/29 18:11:53 DEBUG : /: Access: mask=04
2021/01/29 18:11:53 DEBUG : /: Access: mask=01
2021/01/29 18:11:55 DEBUG : /ABC_FOLDER: Access: mask=02
2021/01/29 18:11:55 DEBUG : /ABC_FOLDER: Access: mask=02
2021/01/29 18:11:55 DEBUG : /ABC_FOLDER: Access: mask=02
2021/01/29 18:11:55 DEBUG : /ABC_FOLDER: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/01/29 18:11:55 DEBUG : /ABC_FOLDER: >Getattr: errc=0
2021/01/29 18:11:55 DEBUG : /ABC_FOLDER: Access: mask=02
2021/01/29 18:11:55 DEBUG : /ABC_FOLDER: Access: mask=04
2021/01/29 18:11:55 DEBUG : /ABC_FOLDER: Access: mask=01
2021/01/29 18:11:55 DEBUG : /ABC_FOLDER: Access: mask=02
2021/01/29 18:11:55 DEBUG : /ABC_FOLDER: Access: mask=02
2021/01/29 18:11:55 DEBUG : /ABC_FOLDER: Access: mask=02
2021/01/29 18:11:55 DEBUG : /ABC_FOLDER: Access: mask=02
2021/01/29 18:11:55 DEBUG : /ABC_FOLDER: Access: mask=04
2021/01/29 18:11:55 DEBUG : /ABC_FOLDER: Access: mask=01
2021/01/29 18:11:55 DEBUG : /ABC_FOLDER: Access: mask=02
2021/01/29 18:11:55 DEBUG : /ABC_FOLDER: Access: mask=02
2021/01/29 18:11:55 DEBUG : /ABC_FOLDER: Access: mask=02
2021/01/29 18:11:55 DEBUG : /ABC_FOLDER: Access: mask=02
2021/01/29 18:11:55 DEBUG : /ABC_FOLDER: Access: mask=04
2021/01/29 18:11:55 DEBUG : /ABC_FOLDER: Access: mask=02
2021/01/29 18:11:55 DEBUG : /ABC_FOLDER: Access: mask=04
2021/01/29 18:11:55 DEBUG : /ABC_FOLDER: Access: mask=01
2021/01/29 18:11:55 DEBUG : /ABC_FOLDER: Access: mask=01
2021/01/29 18:11:55 DEBUG : /ABC_FOLDER: Access: mask=04
2021/01/29 18:11:55 DEBUG : /ABC_FOLDER: Opendir:
2021/01/29 18:11:55 DEBUG : /ABC_FOLDER: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2021/01/29 18:11:55 DEBUG : /ABC_FOLDER: >OpenFile: fd=ABC_FOLDER/ (r), err=<nil>
2021/01/29 18:11:55 DEBUG : /ABC_FOLDER: >Opendir: errc=0, fh=0x0
2021/01/29 18:11:55 DEBUG : /ABC_FOLDER: Access: mask=05
2021/01/29 18:11:55 DEBUG : /ABC_FOLDER: Readdir: ofst=0, fh=0x0
2021/01/29 18:14:18 DEBUG : /ABC_FOLDER: >Readdir: items=131628, errc=0
2021/01/29 18:14:18 DEBUG : Azure container azureml-blobstore-<id>: Destroy:
2021/01/29 18:14:18 DEBUG : Azure container azureml-blobstore-<id>: >Destroy:
2021/01/29 18:14:18 DEBUG : Calling host.Unmount
2021/01/29 18:14:18 DEBUG : host.Unmount failed
2021/01/29 18:14:18 DEBUG : rclone: Version "v1.53.4" finishing with parameters ["rclone" "cmount" "sail:azureml-blobstore-<id>" "/Users/thomassajot/mnt/azure_storage" "--vfs-cache-max-age" "1h0m0s" "--dir-cache-time" "1h0m0s" "--poll-interval" "0" "--vfs-cache-poll-interval" "0" "-vvvv"]
2

This means that something killed rclone or unmounted it externally.

We've seem problems on mac's before where the kernel complains about rclone's wakeups per second and kills it.

Can you check your kernel logs?

3

Hi Ncw,
Thanks for the quick reply.
I do not seem to have kernel logs in my macos. Looking into /var/log/ there is only system.log, should I look into this file (or the tar files of older records) ?

I improved my internet speed over the week end and I actually cannot reproduce (yet) this issue I had for the past few weeks. Could the internet speed be related to this issue ?

4

Sorry, I don't have a mac! But a bit of searching indicates you need to use the log command.

Possibly if the transactions were timing out...

5

So I ran the following:

log show --debug --end '2021-01-29 18:14:20' --start '2021-01-29 18:14:15' --timezone local

and got:

Skipping info messages, pass --info to include.
Timestamp                       Thread     Type        Activity             PID    TTL
2021-01-29 18:14:15.001274+0200 0x270bfe   Default     0x0                  0      0    kernel: (AppleSmartBatteryManager) Starting poll type 4
2021-01-29 18:14:15.001282+0200 0x270bfe   Default     0x0                  0      0    kernel: (AppleSmartBatteryManager) Restarting poll type 4
2021-01-29 18:14:15.015923+0200 0x255c5f   Default     0x0                  0      0    kernel: (AppleSmartBatteryManager) SmartBattery: finished polling type 4
2021-01-29 18:14:15.016041+0200 0x255c5f   Default     0x0                  0      0    kernel: (IOgPTPPlugin) Using IOSkywalkLegacyEthernet as no other controller was found
2021-01-29 18:14:15.094196+0200 0x271bab   Activity    0x221e00             5657   0    xpcproxy: (libsystem_info.dylib) Retrieve User by ID
2021-01-29 18:14:15.094462+0200 0x271bac   Activity    0x221e10             5658   0    xpcproxy: (libsystem_info.dylib) Retrieve User by ID
2021-01-29 18:14:15.094783+0200 0x271bab   Activity    0x221e01             5657   0    xpcproxy: (libsystem_info.dylib) Resolve user group list
2021-01-29 18:14:15.094893+0200 0x271bac   Activity    0x221e11             5658   0    xpcproxy: (libsystem_info.dylib) Resolve user group list
2021-01-29 18:14:15.095087+0200 0x271bab   Activity    0x221e02             5657   0    xpcproxy: (libsystem_info.dylib) Membership API: translate identifier
2021-01-29 18:14:15.095155+0200 0x271bac   Activity    0x221e12             5658   0    xpcproxy: (libsystem_info.dylib) Membership API: translate identifier
2021-01-29 18:14:15.102254+0200 0x271baf   Activity    0x221e20             5657   0    mdworker_shared: (libsystem_info.dylib) Retrieve User by ID
2021-01-29 18:14:15.102294+0200 0x271bb0   Activity    0x221e30             5658   0    mdworker_shared: (libsystem_info.dylib) Retrieve User by ID
2021-01-29 18:14:15.104981+0200 0x21c2c6   Activity    0x221ad5             71624  0    com.avast.fileshield: (Security) SecTrustEvaluateIfNecessary
2021-01-29 18:14:15.107345+0200 0x21c2c6   Activity    0x221ad6             71624  0    com.avast.fileshield: (Security) SecTrustEvaluateIfNecessary
2021-01-29 18:14:15.145758+0200 0x271bb1   Activity    0x221e21             5657   0    mdworker_shared: (libsystem_info.dylib) Membership API: translate identifier
2021-01-29 18:14:15.145799+0200 0x271bb2   Activity    0x221e31             5658   0    mdworker_shared: (libsystem_info.dylib) Membership API: translate identifier
2021-01-29 18:14:15.193297+0200 0x271bb7   Activity    0x221e32             5658   0    mdworker_shared: (CoreFoundation) Loading Preferences From System CFPrefsD
2021-01-29 18:14:15.193297+0200 0x271bb8   Activity    0x221e22             5657   0    mdworker_shared: (CoreFoundation) Loading Preferences From System CFPrefsD
2021-01-29 18:14:15.299772+0200 0x271bb7   Activity    0x221e33             5658   0    mdworker_shared: (CoreFoundation) Loading Preferences From User CFPrefsD
2021-01-29 18:14:15.302112+0200 0x271bb8   Activity    0x221e23             5657   0    mdworker_shared: (CoreFoundation) Loading Preferences From User CFPrefsD
2021-01-29 18:14:15.378753+0200 0x2719c8   Default     0x0                  144    0    WindowServer: (MultitouchHID) [com.apple.Multitouch:Plugin] [HID] [MT] dispatchEvent Dispatching event with 2 children, _eventMask=0x42 _childEventMask=0x42 Cancel=0 Touching=0 inRange=1
2021-01-29 18:14:15.564559+0200 0x2704e8   Default     0x0                  144    0    WindowServer: (MultitouchHID) [com.apple.Multitouch:Plugin] [HID] [MT] dispatchEvent Dispatching event with 2 children, _eventMask=0x23 _childEventMask=0x22 Cancel=0 Touching=1 inRange=1
2021-01-29 18:14:15.715949+0200 0x2459a8   Default     0x0                  0      0    kernel: (AppleMobileFileIntegrity) macOSTaskPolicy: (<unknown>) may not get the taskport of (mdworker_shared) (pid: 5658): SIP is off but (<unknown>) is not root, (mdworker_shared) is not get-task-allow and (<unknown>) is not a declared debugger
2021-01-29 18:14:15.716034+0200 0x2459a8   Default     0x0                  0      0    kernel: (AppleMobileFileIntegrity) macOSTaskPolicy: (<unknown>) may not get the taskport of (mdworker_shared) (pid: 5657): SIP is off but (<unknown>) is not root, (mdworker_shared) is not get-task-allow and (<unknown>) is not a declared debugger
2021-01-29 18:14:15.716105+0200 0x2459a8   Default     0x0                  0      0    kernel: (AppleMobileFileIntegrity) macOSTaskPolicy: (<unknown>) may not get the taskport of (mdworker_shared) (pid: 5655): SIP is off but (<unknown>) is not root, (mdworker_shared) is not get-task-allow and (<unknown>) is not a declared debugger
2021-01-29 18:14:15.948256+0200 0x27191a   Default     0x0                  205    0    airportd: (CoreWiFi) [com.apple.WiFiManager:] [corewifi] LQM: rssi=-79dBm noise=-97dBm snr=18 cca=4.0% txRate=45.0Mbps txFrames=22 txFail=0 txRetrans=7 txFallbackRate=7.2Mbps rxRate=120.0Mbps rxFrames=31 rxRetryFrames=12 beaconRecv=44 beaconSched=49 txFwFrames=15 txFwFail=0 txFwRetrans=1
2021-01-29 18:14:15.999526+0200 0x27191b   Activity    0x220e97             17739  0    searchpartyuseragent: beaconObservationStore.verifyManualTime
2021-01-29 18:14:15.999565+0200 0x27191b   Default     0x220e97             17739  0    searchpartyuseragent: [com.apple.icloud.searchpartyd:transaction] Opened <private>
2021-01-29 18:14:15.999669+0200 0x271bbd   Activity    0x220e98             17739  0    searchpartyuseragent: (CoreTime) TMIsAutomaticTimeEnabled
2021-01-29 18:14:16.000174+0200 0x271bbd   Default     0x220e97             17739  0    searchpartyuseragent: [com.apple.icloud.searchpartyd:transaction] Closed <private>
2021-01-29 18:14:16.843446+0200 0x271944   Default     0x0                  65670  0    Activity Monitor: (GPUWrangler) [com.apple.GPUWrangler:default] (reg) gpu 0x56ff flags 0x10 (IG) vid.did=8086.3ea5 b:d:f=0:2:0
gpu 0x56ff        pci 0x100000225 IOService:/AppleACPIPlatformExpert/PCI0@0/AppleACPIPCI/IGPU@2
gpu 0x56ff       agdc 0x100000582     /AppleIntelFramebufferController/IntelFBClientControl
gpu 0x56ff       gpuc 0x000000000
gpu 0x56ff agdpclient 0x1000005a1     /AppleIntelFramebufferController/IntelFBClientControl/AppleGraphicsDevicePolicy/AGDPClientControl
gpu 0x56ff      accel 0x10000056a     /IntelAccelerator
gpu 0x56ff      fb0:0 0x100000576     /AppleIntelFramebuffer@0
gpu 0x56ff      fb1:1 0x100000577     /AppleIntelFramebuffer@1
gpu 0x56ff      fb2:2 0x100000578     /AppleIntelFramebuffer@2
2021-01-29 18:14:16.856763+0200 0x271449   Default     0x0                  0      0    kernel: (IO80211FamilyV2) LQM-WiFi:TX(F0:86:20:1C:BB:93) AC<SU MS NB NRS NA CM EX TF FFP MRET FLE> BE<26 0 0 0 0 0 0 0 0 0 0> (5000ms)
2021-01-29 18:14:16.856776+0200 0x271449   Default     0x0                  0      0    kernel: (IO80211FamilyV2) LQM-WiFi:TX(F0:86:20:1C:BB:93) AC<SU MS NB NRS NA CM EX TF FFP MRET FLE> BK<0 0 0 0 0 0 0 0 0 0 0> (5000ms)
2021-01-29 18:14:16.856786+0200 0x271449   Default     0x0                  0      0    kernel: (IO80211FamilyV2) LQM-WiFi:TX(F0:86:20:1C:BB:93) AC<SU MS NB NRS NA CM EX TF FFP MRET FLE> VI<0 0 0 0 0 0 0 0 0 0 0> (5000ms)
2021-01-29 18:14:16.856796+0200 0x271449   Default     0x0                  0      0    kernel: (IO80211FamilyV2) LQM-WiFi:TX(F0:86:20:1C:BB:93) AC<SU MS NB NRS NA CM EX TF FFP MRET FLE> VO<0 0 0 0 0 0 0 0 0 0 0> (5000ms)
2021-01-29 18:14:16.856813+0200 0x271449   Default     0x0                  0      0    kernel: (IO80211FamilyV2) LQM-WiFi:L3 Control VO TX(F0:86:20:1C:BB:93) Success=0 NoACK=0 Expired=0 OtherErr=0
2021-01-29 18:14:16.856823+0200 0x271449   Default     0x0                  0      0    kernel: (IO80211FamilyV2) LQM-WiFi:TX(FF:FF:FF:FF:FF:FF) AC<SU MS NB NRS NA CM EX TF FFP MRET FLE> BE<1 0 0 0 0 0 0 0 0 0 0> (5000ms)
2021-01-29 18:14:16.978442+0200 0x271781   Default     0x0                  144    0    WindowServer: (MultitouchHID) [com.apple.Multitouch:Plugin] [HID] [MT] dispatchEvent Dispatching event with 2 children, _eventMask=0x2 _childEventMask=0x2 Cancel=0 Touching=0 inRange=1
2021-01-29 18:14:17.452090+0200 0x4b6      Default     0x0                  115    0    distnoted: [com.apple.distnoted:diagnostic] register name: org.eyebeam.SelfControl.SCSettingsValueChanged object: kCFNotificationAnyObject token: 100000000 pid: 5659
2021-01-29 18:14:17.453806+0200 0x271bc6   Activity    0x221e40             5659   0    org.eyebeam.SelfControl: (libsystem_info.dylib) Retrieve User by ID
2021-01-29 18:14:17.459614+0200 0x271bc6   Default     0x0                  5659   0    org.eyebeam.SelfControl: INFO: Checkup ran, no action needed.
2021-01-29 18:14:17.617713+0200 0x2704e8   Default     0x0                  144    0    WindowServer: (MultitouchHID) [com.apple.Multitouch:Plugin] [HID] [MT] dispatchEvent Dispatching event with 2 children, _eventMask=0x61 _childEventMask=0x62 Cancel=0 Touching=1 inRange=1
2021-01-29 18:14:18.206320+0200 0x6ad      Default     0x0                  257    0    mDNSResponder: [com.apple.mDNSResponder:Default] [R262078] DNSServiceQueryRecord(1D000, 0, <mask.hash: 'tsGX0vhmC9mKtoHcY1Ynyw=='>, Addr) START PID[2385](Brave Browser H)
2021-01-29 18:14:18.206875+0200 0x6ad      Default     0x0                  257    0    mDNSResponder: [com.apple.mDNSResponder:Default] [Q21333] InitDNSConfig: Setting StopTime on the uDNS question 0x7faf3903bae0 <mask.hash: 'cXOobgXf4ieQu9h4WFMHow=='> (Addr)
2021-01-29 18:14:18.206966+0200 0x6ad      Default     0x0                  257    0    mDNSResponder: [com.apple.mDNSResponder:Default] [R262078->Q21333] Question for <mask.hash: 'cXOobgXf4ieQu9h4WFMHow=='> (Addr) assigned DNS service -- id: 13, type: Do53, source: sc, scope: none, interface: /0, servers: {<IPv4:127.0.0.1>:53}, domains: {.}, attributes: {a-ok, aaaa-ok}, interface properties: {}
2021-01-29 18:14:18.207565+0200 0x271a2d   Default     0x0                  257    0    mDNSResponder: [com.apple.mdns:resolver] [Q21333] Sent 42-byte query #1 to <IPv4:127.0.0.1> over UDP via any interface -- id: 0x9241 (37441), flags: 0x0100 (Q/Query, RD, NoError), counts: 1/0/0/0, BBLOzGiv IN A?
2021-01-29 18:14:18.220374+0200 0x271a2d   Default     0x0                  257    0    mDNSResponder: [com.apple.mdns:resolver] [Q21333] Received acceptable 122-byte response from <IPv4:127.0.0.1> over UDP via any interface -- id: 0x9241 (37441), flags: 0x8180 (R/Query, RD, RA, NoError), counts: 1/2/0/0, BBLOzGiv IN A?, 33 IN A BBWedVvC, 33 IN A BBCAIHeY
2021-01-29 18:14:18.220421+0200 0x62a      Default     0x0                  257    0    mDNSResponder: [com.apple.mDNSResponder:Default] [Q21333] Handling concluded querier: BBLOzGiv A IN
2021-01-29 18:14:18.220442+0200 0x62a      Default     0x0                  257    0    mDNSResponder: [com.apple.mDNSResponder:Default] [R262078->Q21333] DNSServiceQueryRecord(<mask.hash: 'cXOobgXf4ieQu9h4WFMHow=='>, Addr) RESULT ADD interface 0: (mortal)<mask.hash: '+ZqzRhf1tYIJbv0vmepOOQ=='>
2021-01-29 18:14:18.220448+0200 0x62a      Default     0x0                  257    0    mDNSResponder: [com.apple.mDNSResponder:Default] [R262078->Q21333] DNSServiceQueryRecord(<mask.hash: 'cXOobgXf4ieQu9h4WFMHow=='>, Addr) RESULT ADD interface 0: (mortal)<mask.hash: 'w1qj1wnBlr6IYFZb1xqrSA=='>
2021-01-29 18:14:18.220548+0200 0x6ad      Default     0x0                  257    0    mDNSResponder: [com.apple.mDNSResponder:Default] [R262078] DNSServiceQueryRecord(1D000, 0, <mask.hash: 'cXOobgXf4ieQu9h4WFMHow=='>, Addr) STOP PID[2385](Brave Browser H)
2021-01-29 18:14:18.295327+0200 0x2704e8   Default     0x0                  144    0    WindowServer: (MultitouchHID) [com.apple.Multitouch:Plugin] [HID] [MT] dispatchEvent Dispatching event with 2 children, _eventMask=0x2 _childEventMask=0x2 Cancel=0 Touching=0 inRange=1
2021-01-29 18:14:18.877492+0200 0x2704e8   Default     0x0                  144    0    WindowServer: (MultitouchHID) [com.apple.Multitouch:Plugin] [HID] [MT] dispatchEvent Dispatching event with 2 children, _eventMask=0x63 _childEventMask=0x62 Cancel=0 Touching=1 inRange=1
2021-01-29 18:14:19.031555+0200 0x270bfc   Default     0x0                  144    0    WindowServer: (MultitouchHID) [com.apple.Multitouch:Plugin] [HID] [MT] dispatchEvent Dispatching event with 2 children, _eventMask=0x42 _childEventMask=0x42 Cancel=0 Touching=0 inRange=1
2021-01-29 18:14:19.151724+0200 0x270bfc   Default     0x0                  144    0    WindowServer: (MultitouchHID) [com.apple.Multitouch:Plugin] [HID] [MT] dispatchEvent Dispatching event with 2 children, _eventMask=0x63 _childEventMask=0x62 Cancel=0 Touching=1 inRange=1
2021-01-29 18:14:19.329699+0200 0x2704e8   Default     0x0                  144    0    WindowServer: (MultitouchHID) [com.apple.Multitouch:Plugin] [HID] [MT] dispatchEvent Dispatching event with 2 children, _eventMask=0x2 _childEventMask=0x2 Cancel=0 Touching=0 inRange=1
2021-01-29 18:14:19.418216+0200 0x270bfc   Default     0x0                  144    0    WindowServer: (MultitouchHID) [com.apple.Multitouch:Plugin] [HID] [MT] dispatchEvent Dispatching event with 2 children, _eventMask=0x63 _childEventMask=0x62 Cancel=0 Touching=1 inRange=1
2021-01-29 18:14:19.583433+0200 0x2587     Error       0x0                  2415   0    taskgated: (libsqlite3.dylib) [com.apple.libsqlite3:logging-persist] cannot open file at line 44580 of [02c344acea]
2021-01-29 18:14:19.583436+0200 0x2587     Error       0x0                  2415   0    taskgated: (libsqlite3.dylib) [com.apple.libsqlite3:logging-persist] os_unix.c:44580: (2) open(/var/db/DetachedSignatures) - No such file or directory
2021-01-29 18:14:19.583483+0200 0x2587     Default     0x0                  2415   0    taskgated: (Security) [com.apple.securityd:security_exception] MacOS error: -67062
--------------------------------------------------------------------------------------------------------------------
Log      - Default:         39, Info:                0, Debug:             0, Error:          2, Fault:          0
Activity - Create:          19, Transition:          0, Actions:           0

I do not see anything of interest, however, I am not sure what to look for.

6

Sorry I may have some timezones issue, running this new command (I have a 2 hour difference compared to the rclone logs):

log show --debug --info --end '2021-01-29 20:14:20' --start '2021-01-29 20:14:14' --timezone 0

I got:

Timestamp                       Thread     Type        Activity             PID    TTL  
2021-01-29 18:14:16.006396+0000 0x2976c1   Default     0x0                  144    0    WindowServer: (MultitouchHID) [com.apple.Multitouch:Plugin] [HID] [MT] dispatchEvent Dispatching event with 2 children, _eventMask=0x2 _childEventMask=0x2 Cancel=0 Touching=1 inRange=1
2021-01-29 18:14:16.126847+0000 0x297bde   Activity    0x2405fb             17739  0    searchpartyuseragent: beaconObservationStore.verifyManualTime
2021-01-29 18:14:16.126906+0000 0x297bde   Default     0x2405fb             17739  0    searchpartyuseragent: [com.apple.icloud.searchpartyd:transaction] Opened <private>
2021-01-29 18:14:16.127066+0000 0x297e67   Activity    0x2405fc             17739  0    searchpartyuseragent: (CoreTime) TMIsAutomaticTimeEnabled
2021-01-29 18:14:16.127748+0000 0x297e67   Default     0x2405fb             17739  0    searchpartyuseragent: [com.apple.icloud.searchpartyd:transaction] Closed <private>
2021-01-29 18:14:16.668603+0000 0x297d60   Default     0x0                  144    0    WindowServer: (MultitouchHID) [com.apple.Multitouch:Plugin] [HID] [MT] dispatchEvent Dispatching event with 2 children, _eventMask=0x2 _childEventMask=0x2 Cancel=0 Touching=0 inRange=1
2021-01-29 18:14:17.080689+0000 0x297df5   Default     0x0                  113    8    dasd: [com.apple.duetactivityscheduler:lifecycle] Attempting to suspend based on triggers: (     "com.apple.duetactivityscheduler.photospolicy.appchanged",     "com.apple.das.apppolicy.appInFocus",     "com.apple.das.apppolicy.appchanged" )
2021-01-29 18:14:17.080762+0000 0x297df5   Default     0x0                  113    8    dasd: [com.apple.duetactivityscheduler:default] Ignoring trigger com.apple.duetactivityscheduler.photospolicy.appchanged because conditions are deteriorating
2021-01-29 18:14:17.080811+0000 0x297df5   Default     0x0                  113    8    dasd: [com.apple.duetactivityscheduler:lifecycle] Evaluating 0 activities based on triggers
2021-01-29 18:14:17.240547+0000 0x4b6      Default     0x0                  115    0    distnoted: [com.apple.distnoted:diagnostic] register name: org.eyebeam.SelfControl.SCSettingsValueChanged object: kCFNotificationAnyObject token: 100000000 pid: 40613
2021-01-29 18:14:17.241454+0000 0x297e6c   Activity    0x2416f0             40613  0    org.eyebeam.SelfControl: (libsystem_info.dylib) Retrieve User by ID
2021-01-29 18:14:17.246556+0000 0x297e6c   Default     0x0                  40613  0    org.eyebeam.SelfControl: INFO: Checkup ran, no action needed.
2021-01-29 18:14:17.516874+0000 0x2972cf   Default     0x0                  144    0    WindowServer: (MultitouchHID) [com.apple.Multitouch:Plugin] [HID] [MT] dispatchEvent Dispatching event with 2 children, _eventMask=0x23 _childEventMask=0x22 Cancel=0 Touching=1 inRange=1
2021-01-29 18:14:17.734551+0000 0x2972cf   Default     0x0                  144    0    WindowServer: (MultitouchHID) [com.apple.Multitouch:Plugin] [HID] [MT] dispatchEvent Dispatching event with 2 children, _eventMask=0x42 _childEventMask=0x42 Cancel=0 Touching=0 inRange=1
2021-01-29 18:14:17.815280+0000 0x297e2b   Default     0x0                  0      0    kernel: (IO80211FamilyV2) LQM-WiFi:TX(F0:86:20:1C:BB:93) AC<SU MS NB NRS NA CM EX TF FFP MRET FLE> BE<589 0 0 0 0 0 0 0 0 0 0> (5001ms)
2021-01-29 18:14:17.815285+0000 0x297e2b   Default     0x0                  0      0    kernel: (IO80211FamilyV2) LQM-WiFi:TX(F0:86:20:1C:BB:93) AC<SU MS NB NRS NA CM EX TF FFP MRET FLE> BK<1 0 0 0 0 0 0 0 0 0 0> (5001ms)
2021-01-29 18:14:17.815289+0000 0x297e2b   Default     0x0                  0      0    kernel: (IO80211FamilyV2) LQM-WiFi:TX(F0:86:20:1C:BB:93) AC<SU MS NB NRS NA CM EX TF FFP MRET FLE> VI<0 0 0 0 0 0 0 0 0 0 0> (5001ms)
2021-01-29 18:14:17.815292+0000 0x297e2b   Default     0x0                  0      0    kernel: (IO80211FamilyV2) LQM-WiFi:TX(F0:86:20:1C:BB:93) AC<SU MS NB NRS NA CM EX TF FFP MRET FLE> VO<0 0 0 0 0 0 0 0 0 0 0> (5001ms)
2021-01-29 18:14:17.815299+0000 0x297e2b   Default     0x0                  0      0    kernel: (IO80211FamilyV2) LQM-WiFi:L3 Control VO TX(F0:86:20:1C:BB:93) Success=0 NoACK=0 Expired=0 OtherErr=0
2021-01-29 18:14:17.815302+0000 0x297e2b   Default     0x0                  0      0    kernel: (IO80211FamilyV2) LQM-WiFi:TX(FF:FF:FF:FF:FF:FF) AC<SU MS NB NRS NA CM EX TF FFP MRET FLE> BE<0 0 0 0 0 0 0 0 0 0 0> (5001ms)
2021-01-29 18:14:17.882151+0000 0x111      Default     0x0                  0      0    kernel: (AppleBCMWLANCoreMac)  44 a 20MHz n CCA 18% duration: 501 congest: 95 ts: 258078
2021-01-29 18:14:18.533147+0000 0x297e70   Default     0x0                  11274  0    pidinfo: proc_pidinfo flavor=9 pid=37405 arg=0 size=2352 returned 0 with errno 1
2021-01-29 18:14:18.536807+0000 0x297747   Default     0x0                  40378  0    rclone: (CoreAnalytics) [com.apple.CoreAnalytics:client] Entering exit handler.
2021-01-29 18:14:18.536809+0000 0x297747   Default     0x0                  40378  0    rclone: (CoreAnalytics) [com.apple.CoreAnalytics:client] Exiting exit handler.
2021-01-29 18:14:18.539019+0000 0x297644   Default     0x0                  85     0    mds: [com.apple.spotlightserver:Volume] <DiskArb>BEGIN diskUnmountApprovalCallback <private>
2021-01-29 18:14:18.539026+0000 0x297644   Default     0x0                  85     0    mds: [com.apple.spotlightserver:Volume] <DiskArb>END diskUnmountApprovalCallback - no volume
2021-01-29 18:14:18.540294+0000 0x297a75   Default     0x0                  1258   0    Finder: (DesktopServicesPriv) [com.apple.DesktopServices:General] TNode::CFVolumeObserverCallback 2 <private>: <private> (-158)
2021-01-29 18:14:18.541073+0000 0x297308   Default     0x0                  7562   30   photoanalysisd: (PhotoLibraryServices) [com.apple.photos.backend:Backend] Unmount of this disk is not interesting. Does not match <private>
2021-01-29 18:14:18.541148+0000 0x297145   Default     0x0                  1436   30   photolibraryd: (PhotoLibraryServices) [com.apple.photos.backend:Backend] Unmount of this disk is not interesting. Does not match <private>
2021-01-29 18:14:18.541331+0000 0x297144   Default     0x0                  7637   14   cloudphotod: [com.apple.photos.cpl:diskarbitration] Unmount of this disk is not interesting. Does not match <private>
2021-01-29 18:14:18.542131+0000 0x29756a   Default     0x0                  46262  30   com.apple.CloudPhotosConfiguration: (PhotoLibraryServices) [com.apple.photos.backend:Backend] Unmount of this disk is not interesting. Does not match <private>
2021-01-29 18:14:18.542533+0000 0x297e74   Default     0x0                  46262  30   com.apple.CloudPhotosConfiguration: (PhotoLibraryServices) [com.apple.photos.backend:Backend] Unmount of this disk is not interesting. Does not match <private>
2021-01-29 18:14:18.542768+0000 0x297e64   Default     0x0                  25395  0    DocumentPopoverViewService: (DesktopServicesPriv) [com.apple.DesktopServices:General] TNode::CFVolumeObserverCallback 2 <private>: <private> (-158)
2021-01-29 18:14:18.542973+0000 0x297d54   Default     0x0                  12049  0    com.apple.appkit.xpc.openAndSavePanelService: (DesktopServicesPriv) [com.apple.DesktopServices:General] TNode::CFVolumeObserverCallback 2 <private>: <private> (-158)
2021-01-29 18:14:18.543738+0000 0x297b76   Error       0x0                  40525  0    mdworker_shared: [com.apple.spotlightserver:ImportBailout] Asked to exit for Diskarb
2021-01-29 18:14:18.543964+0000 0x29768c   Error       0x0                  40373  0    mdworker_shared: [com.apple.spotlightserver:ImportBailout] Asked to exit for Diskarb
2021-01-29 18:14:18.544348+0000 0x297b77   Error       0x0                  40524  0    mdworker_shared: [com.apple.spotlightserver:ImportBailout] Asked to exit for Diskarb
2021-01-29 18:14:18.544741+0000 0x297b79   Error       0x0                  40527  0    mdworker_shared: [com.apple.spotlightserver:ImportBailout] Asked to exit for Diskarb
2021-01-29 18:14:18.555433+0000 0x6ad      Default     0x0                  257    0    mDNSResponder: [com.apple.mDNSResponder:Default] [R272950] DNSServiceCreateConnection STOP PID[40378](rclone)
2021-01-29 18:14:18.556824+0000 0x297e70   Default     0x0                  11274  0    pidinfo: proc_pidinfo flavor=9 pid=37405 arg=0 size=2352 returned 0 with errno 1
2021-01-29 18:14:18.577724+0000 0x297bba   Error       0x0                  40533  0    mdworker_shared: [com.apple.spotlightserver:ImportBailout] Asked to exit for Diskarb
2021-01-29 18:14:18.577727+0000 0x297d9f   Error       0x0                  40607  0    mdworker_shared: [com.apple.spotlightserver:ImportBailout] Asked to exit for Diskarb
2021-01-29 18:14:18.577728+0000 0x297bc8   Error       0x0                  40534  0    mdworker_shared: [com.apple.spotlightserver:ImportBailout] Asked to exit for Diskarb
2021-01-29 18:14:18.577731+0000 0x297da1   Error       0x0                  40605  0    mdworker_shared: [com.apple.spotlightserver:ImportBailout] Asked to exit for Diskarb
2021-01-29 18:14:18.577732+0000 0x297da3   Error       0x0                  40609  0    mdworker_shared: [com.apple.spotlightserver:ImportBailout] Asked to exit for Diskarb
2021-01-29 18:14:18.578804+0000 0x297da0   Error       0x0                  40606  0    mdworker_shared: [com.apple.spotlightserver:ImportBailout] Asked to exit for Diskarb
2021-01-29 18:14:18.579712+0000 0x297da2   Error       0x0                  40608  0    mdworker_shared: [com.apple.spotlightserver:ImportBailout] Asked to exit for Diskarb
2021-01-29 18:14:18.581300+0000 0x297e41   Error       0x0                  40612  0    mdworker_shared: [com.apple.spotlightserver:ImportBailout] Asked to exit for Diskarb
2021-01-29 18:14:18.583118+0000 0x2972cf   Default     0x0                  144    0    WindowServer: (MultitouchHID) [com.apple.Multitouch:Plugin] [HID] [MT] dispatchEvent Dispatching event with 2 children, _eventMask=0x63 _childEventMask=0x62 Cancel=0 Touching=1 inRange=1
2021-01-29 18:14:18.599899+0000 0x297e71   Activity    0x23d9a4             1288   0    AXVisualSupportAgent: (SharedFileList) #SFLAPI LSSharedFileListCopySnapshot
2021-01-29 18:14:18.600283+0000 0x29710f   Activity    0x229dbc             1252   0    MirrorDisplays: (SharedFileList) #SFLAPI LSSharedFileListCopySnapshot
2021-01-29 18:14:18.600673+0000 0x297e4f   Activity    0x1b5acd             1988   0    TextInputMenuAgent: (SharedFileList) #SFLAPI LSSharedFileListCopySnapshot
2021-01-29 18:14:18.600800+0000 0x2970f7   Activity    0x240c51             2067   0    CoreLocationAgent: (SharedFileList) #SFLAPI LSSharedFileListCopySnapshot
2021-01-29 18:14:18.601196+0000 0x297e35   Activity    0x23d375             1974   0    Siri: (SharedFileList) #SFLAPI LSSharedFileListCopySnapshot
2021-01-29 18:14:18.601774+0000 0x2970f4   Activity    0x21fe3e             5172   0    Slack: (SharedFileList) #SFLAPI LSSharedFileListCopySnapshot
2021-01-29 18:14:18.601846+0000 0x2970d1   Activity    0x2119af             47389  0    Slack: (SharedFileList) #SFLAPI LSSharedFileListCopySnapshot
2021-01-29 18:14:18.602030+0000 0x2970cd   Activity    0x2119bf             9992   0    Slack: (SharedFileList) #SFLAPI LSSharedFileListCopySnapshot
2021-01-29 18:14:18.608694+0000 0x297e85   Default     0x0                  40615  0    automount: [com.apple.filesystem.autofs:automount] start
2021-01-29 18:14:18.609728+0000 0x297e85   Activity    0x241720             40615  0    automount: (CFOpenDirectory) Open a given node
2021-01-29 18:14:18.611919+0000 0x1b3a     Activity    0x239ba9             1876   0    sharingd: (SharedFileList) #SFLAPI LSSharedFileListCopySnapshot
2021-01-29 18:14:18.612353+0000 0x297e85   Activity    0x241721             40615  0    automount: (CFOpenDirectory) Querying records from directories
2021-01-29 18:14:18.613321+0000 0x297c86   Default     0x241721             98     0    opendirectoryd: (PlistFile) [com.apple.opendirectoryd:session] recordtype 'automount' attribute 'dsAttrTypeStandard:MetaAutomountMap' is not indexed: performance hit
2021-01-29 18:14:18.614022+0000 0x297e85   Activity    0x241722             40615  0    automount: (CFOpenDirectory) Closing a node reference
2021-01-29 18:14:18.615039+0000 0x297e85   Activity    0x241723             40615  0    automount: (libsystem_info.dylib) Performance impact - Enumerate all FS entries
2021-01-29 18:14:18.618003+0000 0x297e85   Default     0x0                  40615  0    automount: [com.apple.filesystem.autofs:automount] master map loaded
2021-01-29 18:14:18.618779+0000 0x297e85   Activity    0x241724             40615  0    automount: (CFOpenDirectory) Open a given node
2021-01-29 18:14:18.619600+0000 0x297e85   Activity    0x241725             40615  0    automount: (CFOpenDirectory) Copy subnode names for the current node
2021-01-29 18:14:18.620030+0000 0x297e85   Activity    0x241726             40615  0    automount: (CFOpenDirectory) Closing a node reference
2021-01-29 18:14:18.620961+0000 0x297e85   Default     0x0                  40615  0    automount: [com.apple.filesystem.autofs:automount] finish
2021-01-29 18:14:18.627736+0000 0x27bce6   Default     0x0                  53684  0    DiskUnmountWatcher: DiskUnmountWatcher: callback
2021-01-29 18:14:18.627808+0000 0x27bce6   Default     0x0                  53684  0    DiskUnmountWatcher: DiskUnmountWatcher: callback find and release <private>
2021-01-29 18:14:18.628426+0000 0x27bce6   Default     0x0                  53684  0    DiskUnmountWatcher: (KerberosHelper) [com.apple.KerberosHelper:KerberosHelper] NAHFindByLabelAndRelease: looking for label <private>
2021-01-29 18:14:18.628472+0000 0x297308   Default     0x0                  7562   30   photoanalysisd: (PhotoLibraryServices) [com.apple.photos.backend:Backend] PLFileSystemVolumeManager: diskDisappearedCallback for <private>
2021-01-29 18:14:18.628508+0000 0x29714a   Default     0x0                  7638   0    deleted: [com.apple.cache_delete:daemon] Disk with (NULL) DAMediaBSDName disappeared, ignoring event.
2021-01-29 18:14:18.628594+0000 0x297308   Default     0x0                  7562   30   photoanalysisd: (PhotoLibraryServices) [com.apple.photos.backend:Backend] ignoring diskDisappeared due to missing volumeUUID for <private>
2021-01-29 18:14:18.628733+0000 0x29776d   Activity    0x23914b             1442   0    sharedfilelistd: VolumeManager.handleEvent
2021-01-29 18:14:18.629154+0000 0x297d2a   Default     0x0                  1258   0    Finder: (DesktopServicesPriv) [com.apple.DesktopServices:General] TNode::CFVolumeObserverCallback 8 <private>: <private> (-158)
2021-01-29 18:14:18.629200+0000 0x297150   Activity    0x229dcc             46259  0    storeuid: (SharedFileList) #SFLAPI LSSharedFileListCopySnapshot
2021-01-29 18:14:18.629337+0000 0x297156   Activity    0x1ddfcf             18618  0    nbagent: (SharedFileList) #SFLAPI LSSharedFileListCopySnapshot
2021-01-29 18:14:18.630037+0000 0x297d53   Default     0x0                  25395  0    DocumentPopoverViewService: (DesktopServicesPriv) [com.apple.DesktopServices:General] TNode::CFVolumeObserverCallback 8 <private>: <private> (-158)
2021-01-29 18:14:18.630162+0000 0x297e65   Default     0x0                  12049  0    com.apple.appkit.xpc.openAndSavePanelService: (DesktopServicesPriv) [com.apple.DesktopServices:General] TNode::CFVolumeObserverCallback 8 <private>: <private> (-158)
2021-01-29 18:14:18.630520+0000 0x297580   Activity    0x23e55a             12045  0    Preview: (SharedFileList) #SFLAPI LSSharedFileListCopySnapshot
2021-01-29 18:14:18.649562+0000 0x297e90   Activity    0x241740             40616  0    kcm: (Security) SecTrustEvaluateIfNecessary
2021-01-29 18:14:18.653258+0000 0x297e90   Activity    0x241741             40616  0    kcm: (Security) SecTrustEvaluateIfNecessary
2021-01-29 18:14:18.655683+0000 0x297e90   Default     0x0                  40616  0    kcm: (Heimdal) [com.apple.Heimdal:libkrb5] Plugin AppSSOLocatePlugin_macOS is signed by Apple
2021-01-29 18:14:18.663078+0000 0x297e90   Activity    0x241742             40616  0    kcm: (Security) SecTrustEvaluateIfNecessary
2021-01-29 18:14:18.666745+0000 0x297e90   Activity    0x241743             40616  0    kcm: (Security) SecTrustEvaluateIfNecessary
2021-01-29 18:14:18.668757+0000 0x297e90   Default     0x0                  40616  0    kcm: (Heimdal) [com.apple.Heimdal:libkrb5] Plugin AppSSOConfigPlugin_macOS is signed by Apple
2021-01-29 18:14:18.671085+0000 0x297e90   Activity    0x241744             40616  0    kcm: (Security) SecTrustEvaluateIfNecessary
2021-01-29 18:14:18.675175+0000 0x297e90   Activity    0x241745             40616  0    kcm: (Security) SecTrustEvaluateIfNecessary
2021-01-29 18:14:18.677305+0000 0x297e90   Default     0x0                  40616  0    kcm: (Heimdal) [com.apple.Heimdal:libkrb5] Plugin heimdalodpac is signed by Apple
2021-01-29 18:14:18.677673+0000 0x297119   Default     0x0                  184    0    analyticsd: [com.apple.analyticsd:xpc] Setting new client connection handler. 275 active connections
2021-01-29 18:14:18.677880+0000 0x297e93   Default     0x0                  40616  0    kcm: (CoreAnalytics) [com.apple.CoreAnalytics:client] Received configuration update from daemon (initial)
2021-01-29 18:14:18.678037+0000 0x297e87   Activity    0x241530             1258   0    Finder: (SharedFileList) GenericList.resolveItemWithIdentifier
2021-01-29 18:14:18.678052+0000 0x297e87   Default     0x241530             1258   0    Finder: (SharedFileList) [com.apple.sharedfilelist:XPC] Resolve item 541A0B26-39CC-4FDF-89C1-34F6E546FD1F, options: 768, list: com.apple.LSSharedFileList.FavoriteItems
2021-01-29 18:14:18.678408+0000 0x297e87   Default     0x241530             1258   0    Finder: (SharedFileList) [com.apple.sharedfilelist:XPC] received: com.apple.LSSharedFileList.FavoriteItems
2021-01-29 18:14:18.679673+0000 0x297e90   Activity    0x241746             40616  0    kcm: (Security) SecTrustEvaluateIfNecessary
2021-01-29 18:14:18.683507+0000 0x297e90   Activity    0x241747             40616  0    kcm: (Security) SecTrustEvaluateIfNecessary
2021-01-29 18:14:18.686010+0000 0x297e90   Default     0x0                  40616  0    kcm: (Heimdal) [com.apple.Heimdal:libkrb5] Plugin Reachability is signed by Apple
2021-01-29 18:14:18.689276+0000 0x297e90   Activity    0x241748             40616  0    kcm: (Security) SecTrustEvaluateIfNecessary
2021-01-29 18:14:18.692782+0000 0x297e90   Activity    0x241749             40616  0    kcm: (Security) SecTrustEvaluateIfNecessary
2021-01-29 18:14:18.695135+0000 0x297e90   Default     0x0                  40616  0    kcm: (Heimdal) [com.apple.Heimdal:libkrb5] Plugin SCKerberosConfig is signed by Apple
2021-01-29 18:14:18.736978+0000 0x297dcb   Default     0x0                  65670  0    Activity Monitor: (GPUWrangler) [com.apple.GPUWrangler:default] (reg) gpu 0x56ff flags 0x10 (IG) vid.did=8086.3ea5 b:d:f=0:2:0 
gpu 0x56ff        pci 0x100000225 IOService:/AppleACPIPlatformExpert/PCI0@0/AppleACPIPCI/IGPU@2
gpu 0x56ff       agdc 0x100000582     /AppleIntelFramebufferController/IntelFBClientControl
gpu 0x56ff       gpuc 0x000000000 
gpu 0x56ff agdpclient 0x1000005a1     /AppleIntelFramebufferController/IntelFBClientControl/AppleGraphicsDevicePolicy/AGDPClientControl
gpu 0x56ff      accel 0x10000056a     /IntelAccelerator
gpu 0x56ff      fb0:0 0x100000576     /AppleIntelFramebuffer@0
gpu 0x56ff      fb1:1 0x100000577     /AppleIntelFramebuffer@1
gpu 0x56ff      fb2:2 0x100000578     /AppleIntelFramebuffer@2
2021-01-29 18:14:18.740343+0000 0x297d2a   Activity    0x241531             1258   0    Finder: (CoreServicesInternal) CFURLCreateBookmarkData
2021-01-29 18:14:19.140561+0000 0x2972cf   Default     0x0                  144    0    WindowServer: (MultitouchHID) [com.apple.Multitouch:Plugin] [HID] [MT] dispatchEvent Dispatching event with 2 children, _eventMask=0x42 _childEventMask=0x42 Cancel=0 Touching=0 inRange=1
2021-01-29 18:14:19.178613+0000 0x297e87   Activity    0x241532             1258   0    Finder: (SharedFileList) GenericList.resolveItemWithIdentifier
2021-01-29 18:14:19.178644+0000 0x297e87   Default     0x241532             1258   0    Finder: (SharedFileList) [com.apple.sharedfilelist:XPC] Resolve item 541A0B26-39CC-4FDF-89C1-34F6E546FD1F, options: 768, list: com.apple.LSSharedFileList.FavoriteItems
2021-01-29 18:14:19.179668+0000 0x297e87   Default     0x241532             1258   0    Finder: (SharedFileList) [com.apple.sharedfilelist:XPC] received: com.apple.LSSharedFileList.FavoriteItems
2021-01-29 18:14:19.285949+0000 0x297d60   Default     0x0                  144    0    WindowServer: (MultitouchHID) [com.apple.Multitouch:Plugin] [HID] [MT] dispatchEvent Dispatching event with 2 children, _eventMask=0x63 _childEventMask=0x62 Cancel=0 Touching=1 inRange=1
2021-01-29 18:14:19.511949+0000 0x2972cf   Default     0x0                  144    0    WindowServer: (MultitouchHID) [com.apple.Multitouch:Plugin] [HID] [MT] dispatchEvent Dispatching event with 2 children, _eventMask=0x42 _childEventMask=0x42 Cancel=0 Touching=0 inRange=1
2021-01-29 18:14:19.943655+0000 0x297e9f   Activity    0x241750             40617  0    xpcproxy: (libsystem_info.dylib) Retrieve User by ID
2021-01-29 18:14:19.944078+0000 0x297ea0   Activity    0x241760             40618  0    xpcproxy: (libsystem_info.dylib) Retrieve User by ID
2021-01-29 18:14:19.944492+0000 0x297e9f   Activity    0x241751             40617  0    xpcproxy: (libsystem_info.dylib) Resolve user group list
2021-01-29 18:14:19.944597+0000 0x297ea0   Activity    0x241761             40618  0    xpcproxy: (libsystem_info.dylib) Resolve user group list
2021-01-29 18:14:19.944892+0000 0x297e9f   Activity    0x241752             40617  0    xpcproxy: (libsystem_info.dylib) Membership API: translate identifier
2021-01-29 18:14:19.944953+0000 0x297ea0   Activity    0x241762             40618  0    xpcproxy: (libsystem_info.dylib) Membership API: translate identifier
2021-01-29 18:14:19.953070+0000 0x297ea2   Activity    0x241770             40617  0    mdworker_shared: (libsystem_info.dylib) Retrieve User by ID
2021-01-29 18:14:19.953094+0000 0x297ea1   Activity    0x241780             40618  0    mdworker_shared: (libsystem_info.dylib) Retrieve User by ID
2021-01-29 18:14:19.955717+0000 0x21c2c6   Activity    0x241611             71624  0    com.avast.fileshield: (Security) SecTrustEvaluateIfNecessary
2021-01-29 18:14:19.958434+0000 0x21c2c6   Activity    0x241612             71624  0    com.avast.fileshield: (Security) SecTrustEvaluateIfNecessary
2021-01-29 18:14:19.987504+0000 0x297ea4   Activity    0x241781             40618  0    mdworker_shared: (libsystem_info.dylib) Membership API: translate identifier
2021-01-29 18:14:19.987661+0000 0x297ea3   Activity    0x241771             40617  0    mdworker_shared: (libsystem_info.dylib) Membership API: translate identifier

Where we can see some calls to DiskUnmount which are suspicious.

7

That looks like, if anything, that spotlight unmounted the disk...

8

Unfortunately I cannot find more information about this issue. I will monitor and come back to this thread with more failing examples.

Thanks for your help

1 Like
9

Just to add to your experience, I have had something similar happen with cmount on a mac running 11.2 and rclone v1.54.0 (I updated just now to see if the new version made a difference).
In my case, I use minio to share a folder through zerotier. I then mount that minio-s3 path using rclone cmount in a launchd script. This is very cool, because I get to access our files from anywhere that I have internet access. However, when there are more than a few thousand files in a folder, or when a program tries to access many files in succession, the mount essentially seems to time out or crash.
An example is when I use the application DxO PhotoLab to open my photo library, after browsing a few folders, the mount will disappear.

In addition, there seems to be a problem with cmount and special (é) characters, but I will open a new post for that.

10

If you could try to find out why it disappeared that would be very useful. SO looking at kernel logs, system logs etc.

You can also try increasing this

  --daemon-timeout duration                Time limit for rclone to respond to kernel. Not supported on Windows.

It is currently 15 minutes so unless you are waiting 15 minutes, that probably isn't the solution.

11

Hello @ncw thank you for replying! I will try to find the time to do some actual testing and some logs for this tomorrow!

1 Like
12

I have set up some testing for this. As I already know that the issue appears when opening many files in succession, I have prepared a folder with many different files.

Now I have a folder filled in a random way to contain a variety of files, ranging from media files like cr2 raw files, mlv magic lantern raw video and regular jpeg to normal files such as config and log files.
This folder contains 24972 files and the file size is between 13,28 GB and 8 bytes. The folder is 119,87 GB in size. The mount path is /Drive/Fotomateriaal/Unknown/

I have a new photo application that I would like to use to index my photo library. The library is on the same mount, one directory higher in /Drive/Fotomateriaal. I start this application and then browse to the above folder /Drive/Fotomateriaal/Unknown/ with the Finder.

Test 1: opening mounted remote from launchagent mount

When opening the folder with Finder, I almost immediately get a spinner which disappears after several minutes.
A spindump for rclone log shows up in Console.app:

Date/Time:        2021-02-06 11:24:40.273 +0100
End time:         2021-02-06 11:24:47.148 +0100
OS Version:       macOS 11.2 (Build 20D64)
Architecture:     x86_64h
Report Version:   32
Incident Identifier: C1E42E85-8A29-4521-BF5A-4EF081C3A2AB
Share With Devs:  Yes

Data Source:      Microstackshots
Shared Cache:     A33707D1-FC47-30FB-A239-A6AFA68DA7C0 slid base address 0x7fff2020a000, slide 0x20a000

Command:          rclone
Path:             /usr/local/bin/rclone
Version:          ??? (???)
Parent:           UNKNOWN [2991]
PID:              14257

Event:            wakeups
Action taken:     none
Wakeups:          45001 wakeups over the last 7 seconds (6545 wakeups per second average), exceeding limit of 150 wakeups per second over 300 seconds
Wakeups limit:    45000
Limit duration:   300s
Wakeups caused:   45001
Wakeups duration: 7s
Duration:         6.88s
Duration Sampled: 0.00s
Steps:            1

Hardware model:   MacBookAir7,2
Active cpus:      4

Fan speed:        1218 rpm

Heaviest stack for the target process:
  1  runtime.mcall + 91 (rclone + 472251) [0x40734bb]
  1  runtime.park_m + 157 (rclone + 282429) [0x4044f3d]
  1  runtime.schedule + 727 (rclone + 280983) [0x4044997]
  1  runtime.findrunnable + 3318 (rclone + 278422) [0x4043f96]
  1  runtime.netpoll + 174 (rclone + 228654) [0x4037d2e]
  1  runtime.kevent + 57 (rclone + 377177) [0x405c159]
  1  runtime.asmcgocall + 173 (rclone + 478989) [0x4074f0d]
  1  kevent + 10 (libsystem_kernel.dylib + 22498) [0x7fff204eb7e2]


Powerstats for:   rclone [14257]
UUID:             0DE4E3D1-9F77-3FDF-9B0A-7052C05C5C10
Path:             /usr/local/bin/rclone
Architecture:     x86_64
Parent:           UNKNOWN [2991]
UID:              501
Footprint:        169.93 MB
Start time:       2021-02-06 11:24:46.946 +0100
End time:         2021-02-06 11:24:46.946 +0100
Num samples:      1 (100%)
Primary state:    1 samples Non-Frontmost App, Non-Suppressed, Kernel mode, Effective Thread QoS Default, Requested Thread QoS Default, Override Thread QoS Unspecified
User Activity:    0 samples Idle, 1 samples Active
Power Source:     0 samples on Battery, 1 samples on AC
  1  runtime.mcall + 91 (rclone + 472251) [0x40734bb]
    1  runtime.park_m + 157 (rclone + 282429) [0x4044f3d]
      1  runtime.schedule + 727 (rclone + 280983) [0x4044997]
        1  runtime.findrunnable + 3318 (rclone + 278422) [0x4043f96]
          1  runtime.netpoll + 174 (rclone + 228654) [0x4037d2e]
            1  runtime.kevent + 57 (rclone + 377177) [0x405c159]
              1  runtime.asmcgocall + 173 (rclone + 478989) [0x4074f0d]
                1  kevent + 10 (libsystem_kernel.dylib + 22498) [0x7fff204eb7e2]

  Binary Images:
             0x4000000 -          0x675bfff  rclone (0)                         <0DE4E3D1-9F77-3FDF-9B0A-7052C05C5C10>  /usr/local/bin/rclone
        0x7fff204e6000 -     0x7fff20514fff  libsystem_kernel.dylib (7195.81.3) <AB413518-ECDE-3F04-A61C-278D3CF43076>  /usr/lib/system/libsystem_kernel.dylib

After some time, around 8 minutes (not the 15 minutes timeout), the spinner stops turning and the folder is shown as containing 0 files. Get info (in the Finder) on the folder still shows something else:
119.795.652.098 bytes (119,87 GB op schijf) voor 24.972 onderdelen.
Trying to list that specific folder in the terminal gives me:
ls: .: Device not configured
Going to the mount in ~/Drive gives me

❯ ls ~/Drive/
ls: : Device not configured

Looking at rclone processes, I can see that one rclone process has gone away (I have 3 mounts)

❯ ps -axc|grep rclone
  521 ??         0:25.85 rclone
  564 ??         0:21.07 rclone

The system.log is now filling with rclone mentions such as the following:

Feb  6 13:34:39 metacortex com.apple.xpc.launchd[1] (rclone-drive-pve6[32861]): Service exited with abnormal code: 1
Feb  6 13:34:39 metacortex com.apple.xpc.launchd[1] (rclone-drive-pve6): Service only ran for 0 seconds. Pushing respawn out by 10 seconds.
Feb  6 13:34:50 metacortex com.apple.xpc.launchd[1] (rclone-drive-pve6[32867]): Service exited with abnormal code: 1
Feb  6 13:34:50 metacortex com.apple.xpc.launchd[1] (rclone-drive-pve6): Service only ran for 0 seconds. Pushing respawn out by 10 seconds.

The rclone logfile only contains one line at this point, repeated infinitely.
Here is one of the last lines:

2021/02/06 13:36:00 Fatal error: Can not open: /Users/fvanlint/Drive: open /Users/fvanlint/Drive: device not configured

Test 2: terminal mount with rclone log -vv

The next step is to mount the drive through terminal to a temporary mount and using -vv. I expect this file to get pretty big :slight_smile:

I will use the following command:
rclone mount drive: ~/drive-test --vfs-cache-mode=writes --allow-other -vv --log-file=manyfiles-logfile.txt
Subsequently I will again list the folder in the Finder while simultaneously running the new photo application.

time remark
13:45 My test starts. I have mounted the remote with rclone through the above terminal command and am starting the photo app.
13:47 The photo app has started indexing at. I also start to browse the Finder and attempt to open the folder located at /Drive/Fotomateriaal/Unknown/. Finder immediately hangs and shows the spinner.
13:50 The spinner stops, and the folder is opened, but shows an 'loading' sign.
13:51 The contents of the folder are shown. Scrolling the folder is fast. This appears different from my previous test, where the folder content was not shown. I switch back to the photo application, which says it is still loading the first folder in the library, about to start indexing.
13:54 When switching back to the finder at the finder has hung again and showing the spinner.
13:56 The spinner disappears, and I can scroll and show the folder contents.
13:57 The photo app is still showing it is about to start indexing.
13:58 The photo app has started indexing. I will leave it for a bit and see what happens.
14:09 This is becoming somewhat embarrassing, but the terminal mounted remote is still working fine, albeit with an occasional spinner. The photo application has indexed over 40000 images without a problem :sweat_smile:
14:23 The photo app crashed at around 70000 images, and the Finder folder is now empty as before (though it took much longer). I captured a crash log for the photo app as well.
14:27 Attempting to stop the rclone mount command in the Terminal fails, the command is not responding to ctrl+c. My machine is slow to respond and fans are spinning fast.
14:29 The rclone mount command has stopped.

Apparently, whatever is the reason for the mount to disappear is not related to the amount of files in the folder, as I first thought. The prepared folder with many different types of files worked fine. Instead, the mount appears to have crashed through sustained requests from my photo app test.

Log files for test 2

Unfortunately, the log file has become even larger than anticipated at 2,46 GB.
Also, the machine itself has become a bit unstable, with my browser crashing, console.app crashing when copying logs and Finder being slow to respond.

Here is the first part of the crash log for my new photo app, in case it helps:

Process:               Luminar AI [33111]
Path:                  /Applications/Luminar AI.app/Contents/MacOS/Luminar AI
Identifier:            Luminar AI
Version:               1.0.1 (8548)
Code Type:             X86-64 (Native)
Parent Process:        ??? [1]
Responsible:           Luminar AI [33111]
User ID:               501

Date/Time:             2021-02-06 14:23:43.240 +0100
OS Version:            macOS 11.2 (20D64)
Report Version:        12
Anonymous UUID:        352D4186-CB3E-1010-77DE-25245B6E5877


Time Awake Since Boot: 91000 seconds

System Integrity Protection: enabled

Crashed Thread:        37  SentryCrash Exception Handler (Primary)

Exception Type:        EXC_BAD_ACCESS (SIGSEGV)
Exception Codes:       EXC_I386_GPFLT
Exception Note:        EXC_CORPSE_NOTIFY

Thread 0:: Dispatch queue: com.apple.main-thread

Here is the system log from around when the photo app crashed and the Finder started showing 0 files inside the folder:

Feb  6 14:23:00 metacortex com.apple.xpc.launchd[1] (com.apple.mdworker.shared.07000000-0000-0000-0000-000000000000[33679]): Service exited due to SIGKILL | sent by mds[96]
Feb  6 14:23:00 metacortex com.apple.xpc.launchd[1] (com.apple.mdworker.shared.03000000-0000-0000-0000-000000000000[33674]): Service exited due to SIGKILL | sent by mds[96]
Feb  6 14:23:02 metacortex com.apple.xpc.launchd[1] (rclone-drive-pve6[33692]): Service exited with abnormal code: 1
Feb  6 14:23:02 metacortex com.apple.xpc.launchd[1] (rclone-drive-pve6): Service only ran for 0 seconds. Pushing respawn out by 10 seconds.
Feb  6 14:23:13 metacortex com.apple.xpc.launchd[1] (rclone-drive-pve6[33697]): Service exited with abnormal code: 1
Feb  6 14:23:13 metacortex com.apple.xpc.launchd[1] (rclone-drive-pve6): Service only ran for 0 seconds. Pushing respawn out by 10 seconds.
Feb  6 14:23:23 metacortex com.apple.xpc.launchd[1] (rclone-drive-pve6[33699]): Service exited with abnormal code: 1
Feb  6 14:23:23 metacortex com.apple.xpc.launchd[1] (rclone-drive-pve6): Service only ran for 0 seconds. Pushing respawn out by 10 seconds.
Feb  6 14:23:27 metacortex com.apple.xpc.launchd[1] (com.apple.mdworker.shared.0F000000-0400-0000-0000-000000000000[33688]): Service exited due to SIGKILL | sent by mds[96]
Feb  6 14:23:31 metacortex com.apple.xpc.launchd[1] (com.apple.mdworker.shared.0D000000-0400-0000-0000-000000000000[33659]): Service exited due to SIGKILL | sent by mds[96]
Feb  6 14:23:34 metacortex com.apple.xpc.launchd[1] (com.apple.mdworker.shared.0D000000-0000-0000-0000-000000000000[33691]): Service exited due to SIGKILL | sent by mds[96]
Feb  6 14:23:34 metacortex com.apple.xpc.launchd[1] (rclone-drive-pve6[33701]): Service exited with abnormal code: 1
Feb  6 14:23:34 metacortex com.apple.xpc.launchd[1] (rclone-drive-pve6): Service only ran for 1 seconds. Pushing respawn out by 9 seconds.
Feb  6 14:23:43 metacortex com.apple.xpc.launchd[1] (application.com.skylum.luminarAI.8736589216.8736589224[33111]): Service exited due to SIGSEGV
Feb  6 14:23:44 metacortex com.apple.xpc.launchd[1] (rclone-drive-pve6[33703]): Service exited with abnormal code: 1
Feb  6 14:23:44 metacortex com.apple.xpc.launchd[1] (rclone-drive-pve6): Service only ran for 0 seconds. Pushing respawn out by 10 seconds.
Feb  6 14:23:44 metacortex com.apple.xpc.launchd[1] (com.apple.mdworker.shared.0E000000-0300-0000-0000-000000000000[33693]): Service exited due to SIGKILL | sent by mds[96]
Feb  6 14:23:46 metacortex com.apple.xpc.launchd[1] (com.apple.mdworker.shared.0C000000-0100-0000-0000-000000000000[33694]): Service exited due to SIGKILL | sent by mds[96]
Feb  6 14:23:49 metacortex com.apple.xpc.launchd[1] (com.apple.mdworker.shared.08000000-0100-0000-0000-000000000000[33696]): Service exited due to SIGKILL | sent by mds[96]
Feb  6 14:23:50 metacortex com.apple.xpc.launchd[1] (com.apple.mdworker.shared.10000000-0400-0000-0000-000000000000[33695]): Service exited due to SIGKILL | sent by mds[96]
Feb  6 14:23:52 metacortex Vivaldi Helper[2021]: Libnotify: notify_register_coalesced_registration failed with code 9 on line 2835
Feb  6 14:23:54 metacortex com.apple.xpc.launchd[1] (com.apple.mdworker.shared.0A000000-0400-0000-0000-000000000000[33698]): Service exited due to SIGKILL | sent by mds[96]
Feb  6 14:23:57 metacortex com.apple.xpc.launchd[1] (rclone-drive-pve6[33712]): Service exited with abnormal code: 1
Feb  6 14:23:57 metacortex com.apple.xpc.launchd[1] (rclone-drive-pve6): Service only ran for 3 seconds. Pushing respawn out by 7 seconds.

I have to attend to something now, but I will attempt to comb through the huge logfile later with some terminal commands. It might help if you have some suggestions what to look for @ncw if that is not a bother.

13

My understanding (which may be wrong) is that the kernel kills the process at this point.

That agrees with my understanding. Rclone gets killed off when it reaches that wakeups/second limit. However wakeups / s are entirely due to the users of the mount not rclone itself.

I can't see anything obvious in the logs.

A

What I'd really like to know is why did rclone die. This should be at the end of the log file.

I made a test binary with a new flag --mount-tpslimit - can you try it with --mount-tpslimit 100 and see if that works. If it doesn't then halve it until it does. This might slow things down a lot but hopefully it will stop rclone waking up too much.

Ideally we want to opt rclone out of the wakeup protection, but I don't know how to do that - any ideas gratefully received!

v1.55.0-beta.5156.cbe049b52.fix-macos-mounttps on branch fix-macos-mounttps (uploaded in 15-30 mins)

1 Like
14

Hello @ncw thanks again for your help here and in the other thread. And a new build even, to test with. Really amazing :slight_smile:

In my test, I promised to look for some relevant parts, but you suggested that you might only need the last part of the log. Below is what I got when I tailed the last few lines of the previous log.


2021/02/06 14:27:13 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item Fotomateriaal/2017/08/13/_99A2250.CR2 not removed, freed 0 bytes
2021/02/06 14:27:13 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item Fotomateriaal/2017/01/08/_MG_5531.CR2 not removed, freed 0 bytes
2021/02/06 14:27:13 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item Fotomateriaal/2017/08/05/_99A1643.CR2 not removed, freed 0 bytes
2021/02/06 14:27:13 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item Fotomateriaal/2017/08/13/_99A2374.CR2 not removed, freed 0 bytes
2021/02/06 14:27:13 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item Fotomateriaal/2017/08/26/_99A4249_DxO.jpg not removed, freed 0 bytes
2021/02/06 14:27:13 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item Fotomateriaal/2020/01/01/_99A9141.CR2 not removed, freed 0 bytes
2021/02/06 14:27:13 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item Fotomateriaal/2017/07/08/_99A7208.CR2 not removed, freed 0 bytes
2021/02/06 14:27:13 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item Fotomateriaal/2017/11/11/_99A2762.CR2 not removed, freed 0 bytes
2021/02/06 14:27:13 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item Fotomateriaal/2016/03/19/_MG_9624.CR2 not removed, freed 0 bytes
2021/02/06 14:27:13 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item Fotomateriaal/2020/01/05/_99A9296.CR2 not removed, freed 0 bytes
2021/02/06 14:27:13 INFO  : vfs cache: cleaned: objects 77917 (was 77917) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2021/02/06 14:27:14 DEBUG : /: Access: mask=00
2021/02/06 14:27:14 DEBUG : /: >Access: errc=0
2021/02/06 14:27:14 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/02/06 14:27:14 DEBUG : /: >Getattr: errc=0
2021/02/06 14:27:15 DEBUG : /: Access: mask=00
2021/02/06 14:27:15 DEBUG : /: >Access: errc=0
2021/02/06 14:27:15 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/02/06 14:27:15 DEBUG : /: >Getattr: errc=0
2021/02/06 14:27:16 DEBUG : /: Access: mask=00
2021/02/06 14:27:16 DEBUG : /: >Access: errc=0
2021/02/06 14:27:18 DEBUG : /: Access: mask=00
2021/02/06 14:27:18 DEBUG : /: >Access: errc=0
2021/02/06 14:27:18 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/02/06 14:27:18 DEBUG : /: >Getattr: errc=0
2021/02/06 14:27:18 DEBUG : /: Access: mask=00
2021/02/06 14:27:18 DEBUG : /: >Access: errc=0
2021/02/06 14:27:20 DEBUG : /: Access: mask=00
2021/02/06 14:27:20 DEBUG : /: >Access: errc=0
2021/02/06 14:27:20 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/02/06 14:27:20 DEBUG : /: >Getattr: errc=0
2021/02/06 14:27:20 DEBUG : /: Access: mask=00
2021/02/06 14:27:20 DEBUG : /: >Access: errc=0
2021/02/06 14:27:21 DEBUG : /: Access: mask=00
2021/02/06 14:27:21 DEBUG : /: >Access: errc=0
2021/02/06 14:27:21 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/02/06 14:27:21 DEBUG : /: >Getattr: errc=0
2021/02/06 14:27:21 DEBUG : /: Access: mask=02
2021/02/06 14:27:21 DEBUG : /: >Access: errc=0
2021/02/06 14:27:21 DEBUG : /: Access: mask=04
2021/02/06 14:27:21 DEBUG : /: >Access: errc=0
2021/02/06 14:27:21 DEBUG : /: Access: mask=01
2021/02/06 14:27:21 DEBUG : /: >Access: errc=0
2021/02/06 14:27:21 DEBUG : /: Access: mask=02
2021/02/06 14:27:21 DEBUG : /: >Access: errc=0
2021/02/06 14:27:21 DEBUG : /: Access: mask=00
2021/02/06 14:27:21 DEBUG : /: >Access: errc=0
2021/02/06 14:27:21 DEBUG : /: Access: mask=02
2021/02/06 14:27:21 DEBUG : /: >Access: errc=0
2021/02/06 14:27:21 DEBUG : /: Access: mask=02
2021/02/06 14:27:21 DEBUG : /: >Access: errc=0
2021/02/06 14:27:21 DEBUG : /: Access: mask=02
2021/02/06 14:27:21 DEBUG : /: >Access: errc=0
2021/02/06 14:27:21 DEBUG : /: Access: mask=00
2021/02/06 14:27:21 DEBUG : /: >Access: errc=0
2021/02/06 14:27:21 DEBUG : /: Access: mask=02
2021/02/06 14:27:21 DEBUG : /: >Access: errc=0
2021/02/06 14:27:21 DEBUG : /: Access: mask=02
2021/02/06 14:27:21 DEBUG : /: >Access: errc=0
2021/02/06 14:27:21 DEBUG : /: Access: mask=04
2021/02/06 14:27:21 DEBUG : /: >Access: errc=0
2021/02/06 14:27:21 DEBUG : /: Access: mask=00
2021/02/06 14:27:21 DEBUG : /: >Access: errc=0
2021/02/06 14:27:21 DEBUG : /: Access: mask=00
2021/02/06 14:27:21 DEBUG : /: >Access: errc=0
2021/02/06 14:27:21 DEBUG : /: Statfs:
2021/02/06 14:27:21 DEBUG : /: >Statfs: stat={Bsize:4096 Frsize:4096 Blocks:4294967295 Bfree:4294967295 Bavail:4294967295 Files:1000000000 Ffree:1000000000 Favail:0 Fsid:0 Flag:0 Namemax:255}, errc=0
2021/02/06 14:27:22 DEBUG : /: Access: mask=00
2021/02/06 14:27:22 DEBUG : /: >Access: errc=0
2021/02/06 14:27:23 DEBUG : /: Statfs:
2021/02/06 14:27:23 DEBUG : /: >Statfs: stat={Bsize:4096 Frsize:4096 Blocks:4294967295 Bfree:4294967295 Bavail:4294967295 Files:1000000000 Ffree:1000000000 Favail:0 Fsid:0 Flag:0 Namemax:255}, errc=0
2021/02/06 14:27:24 DEBUG : /: Access: mask=00
2021/02/06 14:27:24 DEBUG : /: >Access: errc=0
2021/02/06 14:27:24 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/02/06 14:27:24 DEBUG : /: >Getattr: errc=0
2021/02/06 14:27:26 DEBUG : /: Access: mask=00
2021/02/06 14:27:26 DEBUG : /: >Access: errc=0
2021/02/06 14:27:26 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/02/06 14:27:26 DEBUG : /: >Getattr: errc=0
2021/02/06 14:27:26 DEBUG : /: Access: mask=00
2021/02/06 14:27:26 DEBUG : /: >Access: errc=0
2021/02/06 14:27:26 DEBUG : /: Access: mask=02
2021/02/06 14:27:26 DEBUG : /: >Access: errc=0
2021/02/06 14:27:26 DEBUG : /: Access: mask=04
2021/02/06 14:27:26 DEBUG : /: >Access: errc=0
2021/02/06 14:27:26 DEBUG : /: Access: mask=01
2021/02/06 14:27:26 DEBUG : /: >Access: errc=0
2021/02/06 14:27:26 DEBUG : /: Access: mask=00
2021/02/06 14:27:26 DEBUG : /: >Access: errc=0
2021/02/06 14:27:26 DEBUG : /: Access: mask=02
2021/02/06 14:27:26 DEBUG : /: >Access: errc=0
2021/02/06 14:27:26 DEBUG : /: Access: mask=00
2021/02/06 14:27:26 DEBUG : /: >Access: errc=0
2021/02/06 14:27:26 DEBUG : /: Access: mask=02
2021/02/06 14:27:26 DEBUG : /: >Access: errc=0
2021/02/06 14:27:26 DEBUG : /: Access: mask=02
2021/02/06 14:27:26 DEBUG : /: >Access: errc=0
2021/02/06 14:27:26 DEBUG : /: Access: mask=02
2021/02/06 14:27:26 DEBUG : /: >Access: errc=0
2021/02/06 14:27:26 DEBUG : /: Access: mask=00
2021/02/06 14:27:26 DEBUG : /: >Access: errc=0
2021/02/06 14:27:26 DEBUG : /: Access: mask=02
2021/02/06 14:27:26 DEBUG : /: >Access: errc=0
2021/02/06 14:27:26 DEBUG : /: Access: mask=02
2021/02/06 14:27:26 DEBUG : /: >Access: errc=0
2021/02/06 14:27:26 DEBUG : /: Access: mask=04
2021/02/06 14:27:26 DEBUG : /: >Access: errc=0
2021/02/06 14:27:26 DEBUG : /: Access: mask=00
2021/02/06 14:27:26 DEBUG : /: >Access: errc=0
2021/02/06 14:27:26 DEBUG : /: Access: mask=00
2021/02/06 14:27:26 DEBUG : /: >Access: errc=0
2021/02/06 14:27:26 DEBUG : /: Statfs:
2021/02/06 14:27:26 DEBUG : /: >Statfs: stat={Bsize:4096 Frsize:4096 Blocks:4294967295 Bfree:4294967295 Bavail:4294967295 Files:1000000000 Ffree:1000000000 Favail:0 Fsid:0 Flag:0 Namemax:255}, errc=0
2021/02/06 14:27:28 DEBUG : /: Access: mask=00
2021/02/06 14:27:28 DEBUG : /: >Access: errc=0
2021/02/06 14:27:28 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/02/06 14:27:28 DEBUG : /: >Getattr: errc=0
2021/02/06 14:27:30 DEBUG : /: Access: mask=00
2021/02/06 14:27:30 DEBUG : /: >Access: errc=0
2021/02/06 14:27:30 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/02/06 14:27:30 DEBUG : /: >Getattr: errc=0
2021/02/06 14:27:31 DEBUG : /: Access: mask=00
2021/02/06 14:27:31 DEBUG : /: >Access: errc=0
2021/02/06 14:27:32 DEBUG : /: Access: mask=00
2021/02/06 14:27:32 DEBUG : /: >Access: errc=0
2021/02/06 14:27:32 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/02/06 14:27:32 DEBUG : /: >Getattr: errc=0
2021/02/06 14:27:34 DEBUG : /: Access: mask=00
2021/02/06 14:27:34 DEBUG : /: >Access: errc=0
2021/02/06 14:27:34 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/02/06 14:27:34 DEBUG : /: >Getattr: errc=0
2021/02/06 14:27:36 DEBUG : /: Access: mask=00
2021/02/06 14:27:36 DEBUG : /: >Access: errc=0
2021/02/06 14:27:36 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/02/06 14:27:36 DEBUG : /: >Getattr: errc=0
2021/02/06 14:27:36 INFO  : Signal received: interrupt
2021/02/06 14:27:36 DEBUG : Not calling host.Unmount as signal received
2021/02/06 14:27:36 DEBUG : Unmounted successfully
2021/02/06 14:27:36 INFO  : Exiting...
2021/02/06 14:27:36 DEBUG : vfs cache: cleaner exiting

I am currently running the photo app test as before, but now with these options from your test build:

rclone mount drive: ~/drive-test --vfs-cache-mode=writes --allow-other -vv --log-file=manyfiles2-logfile.txt -o modules=iconv,from_code=UTF-8,to_code=UTF-8-MAC --mount-tpslimit 100

As soon as something happens (or not!) I will edit this post.

Edit: The mount stopped working after about 8 minutes. Right after starting the mount, I immediately noticed that browsing folders is really slow. A lot of spinners even when opening folders with only a few hundred files. Opening the prepared test folder with many different items was still loading when the mount stopped and the folders all showed 0 items.

Here are the last lines of the new log:

2021/02/09 17:19:29 DEBUG : /: Statfs: 
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/05/08/IMG_2553.MOV: >Getattr: errc=0
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/05/08/IMG_2553.MOV: Access: mask=00
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/03/29/_MG_9828.CR2: >Access: errc=0
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/03/29/_MG_9828.CR2: Access: mask=00
2021/02/09 17:19:29 DEBUG : /: >Statfs: stat={Bsize:4096 Frsize:4096 Blocks:4294967295 Bfree:4294967295 Bavail:4294967295 Files:1000000000 Ffree:1000000000 Favail:0 Fsid:0 Flag:0 Namemax:255}, errc=0
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/05/08/IMG_2553.MOV: >Access: errc=0
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/05/08/IMG_2554.JPG: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/03/29/_MG_9828.CR2: >Access: errc=0
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/03/29/_MG_9832.CR2: Access: mask=00
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/05/08/IMG_2554.JPG: >Getattr: errc=0
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/05/08/IMG_2554.JPG: Access: mask=00
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/03/29/_MG_9832.CR2: >Access: errc=0
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/03/29/_MG_9832.CR2: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/05/08/IMG_2554.JPG: >Access: errc=0
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/05/08/IMG_2554.MOV: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/03/29/_MG_9832.CR2: >Getattr: errc=0
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/03/29/_MG_9832.CR2: Access: mask=00
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/05/08/IMG_2554.MOV: >Getattr: errc=0
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/05/08/IMG_2554.MOV: Access: mask=00
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/03/29/_MG_9832.CR2: >Access: errc=0
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/05/08/IMG_2554.MOV: >Access: errc=0
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/05/08/IMG_2555.JPG: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/05/08/IMG_2555.JPG: >Getattr: errc=0
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/05/08/IMG_2555.JPG: Access: mask=00
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/03/29/_MG_9832.CR2: Access: mask=00
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/05/08/IMG_2555.JPG: >Access: errc=0
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/05/08/IMG_2555.MOV: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/03/29/_MG_9832.CR2: >Access: errc=0
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/03/29/_MG_9832.CR2: Access: mask=00
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/05/08/IMG_2555.MOV: >Getattr: errc=0
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/05/08/IMG_2555.MOV: Access: mask=00
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/03/29/_MG_9832.CR2: >Access: errc=0
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/03/29/IMG_2129.JPG: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/05/08/IMG_2555.MOV: >Access: errc=0
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/05/08/IMG_2556.JPG: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/03/29/IMG_2129.JPG: >Getattr: errc=0
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/03/29/IMG_2129.JPG: Access: mask=00
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/05/08/IMG_2556.JPG: >Getattr: errc=0
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/05/08/IMG_2556.JPG: Access: mask=00
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/03/29/IMG_2129.JPG: >Access: errc=0
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/03/29/IMG_2129.JPG: Access: mask=00
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/05/08/IMG_2556.JPG: >Access: errc=0
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/05/08/IMG_2556.MOV: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/03/29/IMG_2129.JPG: >Access: errc=0
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/03/29/IMG_2129.JPG: Access: mask=00
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/05/08/IMG_2556.MOV: >Getattr: errc=0
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/05/08/IMG_2556.MOV: Access: mask=00
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/03/29/IMG_2129.JPG: >Access: errc=0
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/03/29/IMG_2129.JPG: Access: mask=00
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/05/08/IMG_2556.MOV: >Access: errc=0
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/05/08/IMG_2557.JPG: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/03/29/IMG_2129.JPG: >Access: errc=0
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/03/29/_MG_9753.CR2: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/05/08/IMG_2557.JPG: >Getattr: errc=0
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/05/08/IMG_2557.JPG: Access: mask=00
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/03/29/_MG_9753.CR2: >Getattr: errc=0
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/03/29/_MG_9753.CR2: Access: mask=00
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/05/08/IMG_2557.JPG: >Access: errc=0
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/05/08/IMG_2557.MOV: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/03/29/_MG_9753.CR2: >Access: errc=0
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/03/29/_MG_9753.CR2: Access: mask=00
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/05/08/IMG_2557.MOV: >Getattr: errc=0
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/05/08/IMG_2557.MOV: Access: mask=00
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/03/29/_MG_9753.CR2: >Access: errc=0
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/03/29/_MG_9753.CR2: Access: mask=00
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/05/08/IMG_2557.MOV: >Access: errc=0
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/05/08/IMG_2558.JPG: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/03/29/_MG_9753.CR2: >Access: errc=0
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/03/29/_MG_9753.CR2: Access: mask=00
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/05/08/IMG_2558.JPG: >Getattr: errc=0
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/05/08/IMG_2558.JPG: Access: mask=00
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/03/29/_MG_9753.CR2: >Access: errc=0
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/03/29/_MG_9749.CR2: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/05/08/IMG_2558.JPG: >Access: errc=0
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/05/08/IMG_2558.MOV: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/03/29/_MG_9749.CR2: >Getattr: errc=0
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/03/29/_MG_9749.CR2: Access: mask=00
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/05/08/IMG_2558.MOV: >Getattr: errc=0
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/05/08/IMG_2558.MOV: Access: mask=00
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/03/29/_MG_9749.CR2: >Access: errc=0
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/03/29/_MG_9749.CR2: Access: mask=00
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/05/08/IMG_2558.MOV: >Access: errc=0
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/05/08/IMG_2559.JPG: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/03/29/_MG_9749.CR2: >Access: errc=0
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/03/29/_MG_9749.CR2: Access: mask=00
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/05/08/IMG_2559.JPG: >Getattr: errc=0
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/05/08/IMG_2559.JPG: Access: mask=00
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/03/29/_MG_9749.CR2: >Access: errc=0
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/03/29/_MG_9749.CR2: Access: mask=00
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/05/08/IMG_2559.JPG: >Access: errc=0
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/05/08/IMG_2559.MOV: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/03/29/_MG_9749.CR2: >Access: errc=0
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/03/29/_MG_9795.CR2: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/05/08/IMG_2559.MOV: >Getattr: errc=0
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/05/08/IMG_2559.MOV: Access: mask=00
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/03/29/_MG_9795.CR2: >Getattr: errc=0
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/03/29/_MG_9795.CR2: Access: mask=00
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/05/08/IMG_2559.MOV: >Access: errc=0
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/05/08/IMG_2560.JPG: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/03/29/_MG_9795.CR2: >Access: errc=0
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/03/29/_MG_9795.CR2: Access: mask=00
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/05/08/IMG_2560.JPG: >Getattr: errc=0
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/05/08/IMG_2560.JPG: Access: mask=00
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/03/29/_MG_9795.CR2: >Access: errc=0
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/03/29/_MG_9795.CR2: Access: mask=00
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/05/08/IMG_2560.JPG: >Access: errc=0
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/05/08/IMG_2560.MOV: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/03/29/_MG_9795.CR2: >Access: errc=0
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/03/29/_MG_9795.CR2: Access: mask=00
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/05/08/IMG_2560.MOV: >Getattr: errc=0
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/05/08/IMG_2560.MOV: Access: mask=00
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/03/29/_MG_9795.CR2: >Access: errc=0
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/03/29/2016-03-29 Schop in de grond GDW00027.jpg: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/05/08/IMG_2560.MOV: >Access: errc=0
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/05/08/IMG_2561.JPG: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/03/29/2016-03-29 Schop in de grond GDW00027.jpg: >Getattr: errc=0
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/03/29/2016-03-29 Schop in de grond GDW00027.jpg: Access: mask=00
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/05/08/IMG_2561.JPG: >Getattr: errc=0
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/05/08/IMG_2561.JPG: Access: mask=00
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/03/29/2016-03-29 Schop in de grond GDW00027.jpg: >Access: errc=0
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/03/29/2016-03-29 Schop in de grond GDW00027.jpg: Access: mask=00
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/05/08/IMG_2561.JPG: >Access: errc=0
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/05/08/IMG_2561.MOV: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/03/29/2016-03-29 Schop in de grond GDW00027.jpg: >Access: errc=0
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/03/29/2016-03-29 Schop in de grond GDW00027.jpg: Access: mask=00
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/05/08/IMG_2561.MOV: >Getattr: errc=0
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/05/08/IMG_2561.MOV: Access: mask=00
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/03/29/2016-03-29 Schop in de grond GDW00027.jpg: >Access: errc=0
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/03/29/2016-03-29 Schop in de grond GDW00027.jpg: Access: mask=00
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/05/08/IMG_2561.MOV: >Access: errc=0
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/05/08/IMG_2562.JPG: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/03/29/2016-03-29 Schop in de grond GDW00027.jpg: >Access: errc=0
2021/02/09 17:19:29 DEBUG : /Fotomateriaal/2016/03/29/2016-03-29 Schop in de grond GDW00008.jpg: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/02/09 17:19:30 DEBUG : /Fotomateriaal/2016/05/08/IMG_2562.JPG: >Getattr: errc=0
2021/02/09 17:19:30 DEBUG : /Fotomateriaal/2016/05/08/IMG_2562.JPG: Access: mask=00
2021/02/09 17:19:30 DEBUG : /Fotomateriaal/2016/03/29/2016-03-29 Schop in de grond GDW00008.jpg: >Getattr: errc=0
2021/02/09 17:19:30 DEBUG : /Fotomateriaal/2016/05/08/IMG_2562.JPG: >Access: errc=0
2021/02/09 17:19:42 INFO  : Signal received: interrupt
2021/02/09 17:19:42 DEBUG : Not calling host.Unmount as signal received
2021/02/09 17:19:42 DEBUG : Unmounted successfully
2021/02/09 17:19:42 INFO  : Exiting...
2021/02/09 17:19:42 DEBUG : vfs cache: cleaner exiting
15

This is the smoking gun - something sent rclone a kill signal. I suspect the OS. Does this timestamp line up with an OS message?

Or maybe it was you pressing CTRL-C? That generates an interrupt signal. OSes don't normally kill things with SIGINT, normally SIGTERM so I'm a bit confused!

:frowning:

Yes that will be the effect of limiting rclone to 100 transactions per second

Can you try decreasing that 100 number and see if you can find a number where it doesn't get killed. I'd halve it and keep halving until you find a number which works.

Killed by OS (or something), RIP!

1 Like
16

Hello @ncw, thank you for your help again :slight_smile:

Or maybe it was you pressing CTRL-C

Yes, I did end up CTRL-C killing the mount after it crashed. I am sorry if that has caused ambiguous results. I will continue waiting during this test too see if that makes a difference.

I got a bit confused with the two builds, 5166.242026906 does not support the --mount-tpslimit command, which took me embarrassingly long to realize.

I am now using

❯ rclone version
rclone v1.55.0-beta.5156.cbe049b52.fix-macos-mounttps
- os/arch: darwin/amd64
- go version: go1.16rc1

The command I am using:
rclone mount drive: ~/drive-test --vfs-cache-mode=writes --allow-other -vv --log-file=manyfiles2-logfile.txt --mount-tpslimit 50

time remark
13:03 starting mount (pid 69675)
13:04 starting photo app
13:05 Finder shows a spinner in any window or folder, rendering it almost unusable. I have not opened the mount folder with Finder, only started the photo app.
13:06 console.app shows a wakeups_resource log (shown below)
13:15 managed to get to the prepared folder /Fotomateriaal/unknown though it is of course causing nearly continuous spinners in Finder
13:16 mount appears to have stopped, Finder shows 0 items inside /Fotomateriaal and when moving up, the mount shows as empty.
13:16 the photo app has crashed, not using ctrl-c but waiting
13:17 the command prompt has returned, rclone process has exited

13:06 console.app log:

Date/Time:        2021-02-11 13:03:39.646 +0100
End time:         2021-02-11 13:05:51.149 +0100
OS Version:       macOS 11.2 (Build 20D64)
Architecture:     x86_64h
Report Version:   32
Incident Identifier: 8A46684C-2531-4984-B4AA-95B39FA5729A
Share With Devs:  Yes

Data Source:      Microstackshots
Shared Cache:     A33707D1-FC47-30FB-A239-A6AFA68DA7C0 slid base address 0x7fff202c1000, slide 0x2c1000

Command:          rclone
Path:             /usr/local/bin/rclone
Version:          ??? (???)
Parent:           UNKNOWN [68971]
PID:              69675

Event:            wakeups
Action taken:     none
Wakeups:          45001 wakeups over the last 132 seconds (342 wakeups per second average), exceeding limit of 150 wakeups per second over 300 seconds
Wakeups limit:    45000
Limit duration:   300s
Wakeups caused:   45001
Wakeups duration: 132s
Duration:         131.50s
Duration Sampled: 60.57s
Steps:            6

Hardware model:   MacBookAir7,2
Active cpus:      4

Fan speed:        1199 rpm

Heaviest stack for the target process:
  2  thread_start + 15 (libsystem_pthread.dylib + 9339) [0x7fff205ce47b]
  2  _pthread_start + 224 (libsystem_pthread.dylib + 26960) [0x7fff205d2950]
  2  crosscall_amd64 + 12 (rclone + 20737964) [0x53c6fac]
  2  runtime.mstart + 102 (rclone + 268454) [0x40418a6]
  2  runtime.mstart1 + 200 (rclone + 268680) [0x4041988]
  1  runtime.sysmon + 1093 (rclone + 305829) [0x404aaa5]
  1  runtime.notetsleep + 88 (rclone + 67640) [0x4010838]
  1  runtime.notetsleep_internal + 279 (rclone + 67159) [0x4010657]
  1  runtime.semasleep + 276 (rclone + 230356) [0x40383d4]
  1  runtime.pthread_cond_timedwait_relative_np + 57 (rclone + 383577) [0x405da59]
  1  runtime.asmcgocall + 173 (rclone + 487245) [0x4076f4d]
  1  runtime.pthread_cond_timedwait_relative_np_trampoline + 20 (rclone + 495636) [0x4079014]
  1  __psynch_cvwait + 10 (libsystem_kernel.dylib + 14562) [0x7fff205a08e2]


Powerstats for:   rclone [69675]
UUID:             56489049-B186-3F21-9BF0-9347BB7DADE7
Path:             /usr/local/bin/rclone
Architecture:     x86_64
Parent:           UNKNOWN [68971]
UID:              501
Footprint:        16.11 MB
Pageins:          14 pages
Start time:       2021-02-11 13:04:48.665 +0100
End time:         2021-02-11 13:05:49.232 +0100
Num samples:      6 (100%)
Primary state:    6 samples Non-Frontmost App, Non-Suppressed, Kernel mode, Effective Thread QoS Default, Requested Thread QoS Default, Override Thread QoS Unspecified
User Activity:    0 samples Idle, 6 samples Active
Power Source:     0 samples on Battery, 6 samples on AC
  2  thread_start + 15 (libsystem_pthread.dylib + 9339) [0x7fff205ce47b]
    2  _pthread_start + 224 (libsystem_pthread.dylib + 26960) [0x7fff205d2950]
      2  crosscall_amd64 + 12 (rclone + 20737964) [0x53c6fac]
        2  runtime.mstart + 102 (rclone + 268454) [0x40418a6]
          2  runtime.mstart1 + 200 (rclone + 268680) [0x4041988]
            1  runtime.sysmon + 1093 (rclone + 305829) [0x404aaa5]
              1  runtime.notetsleep + 88 (rclone + 67640) [0x4010838]
                1  runtime.notetsleep_internal + 279 (rclone + 67159) [0x4010657]
                  1  runtime.semasleep + 276 (rclone + 230356) [0x40383d4]
                    1  runtime.pthread_cond_timedwait_relative_np + 57 (rclone + 383577) [0x405da59]
                      1  runtime.asmcgocall + 173 (rclone + 487245) [0x4076f4d]
                        1  runtime.pthread_cond_timedwait_relative_np_trampoline + 20 (rclone + 495636) [0x4079014]
                          1  __psynch_cvwait + 10 (libsystem_kernel.dylib + 14562) [0x7fff205a08e2]
            1  runtime.sysmon + 197 (rclone + 304933) [0x404a725]
              1  runtime.nanotime1 + 23 (rclone + 382039) [0x405d457]
  2  runtime.asmcgocall + 112 (rclone + 487184) [0x4076f10]
    1  write + 10 (libsystem_kernel.dylib + 15450) [0x7fff205a0c5a]
    1  runtime.usleep_trampoline + 11 (rclone + 494955) [0x4078d6b]
      1  usleep + 53 (libsystem_c.dylib + 494476) [0x7fff2051db8c]
        1  __semwait_signal + 10 (libsystem_kernel.dylib + 14262) [0x7fff205a07b6]
  1  runtime.systemstack + 102 (rclone + 480486) [0x40754e6]
    1  runtime.callers.func1 + 134 (rclone + 454054) [0x406eda6]
      1  runtime.gentraceback + 4076 (rclone + 414540) [0x406534c]
        1  runtime.pcdatavalue + 123 (rclone + 379387) [0x405c9fb]
          1  runtime.pcvalue + 357 (rclone + 376005) [0x405bcc5]
            1  runtime.step + 36 (rclone + 380068) [0x405cca4]
  1  runtime.mcall + 91 (rclone + 480315) [0x407543b]
    1  runtime.park_m + 157 (rclone + 286269) [0x4045e3d]
      1  runtime.schedule + 727 (rclone + 284855) [0x40458b7]
        1  runtime.findrunnable + 1006 (rclone + 279086) [0x404422e]
          1  runtime.netpoll + 174 (rclone + 229070) [0x4037ece]
            1  runtime.kevent + 57 (rclone + 383001) [0x405d819]
              1  runtime.asmcgocall + 173 (rclone + 487245) [0x4076f4d]
                1  kevent + 10 (libsystem_kernel.dylib + 22498) [0x7fff205a27e2]

  Binary Images:
             0x4000000 -          0x679ffff  rclone (0)                         <56489049-B186-3F21-9BF0-9347BB7DADE7>  /usr/local/bin/rclone
        0x7fff204a5000 -     0x7fff2052dfff  libsystem_c.dylib (1439.40.11)     <4AF71812-4099-3E96-B271-1F259491A2B2>  /usr/lib/system/libsystem_c.dylib
        0x7fff2059d000 -     0x7fff205cbfff  libsystem_kernel.dylib (7195.81.3) <AB413518-ECDE-3F04-A61C-278D3CF43076>  /usr/lib/system/libsystem_kernel.dylib
        0x7fff205cc000 -     0x7fff205d7fff  libsystem_pthread.dylib (454.80.2) <B989DF6C-ADFE-3AF9-9C91-07D2521F9E47>  /usr/lib/system/libsystem_pthread.dylib

last few lines of the rclone log

2021/02/11 13:16:22 DEBUG : /Fotomateriaal/2018/04/01/_99A0547.CR2: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/02/11 13:16:22 DEBUG : /Fotomateriaal/2018/02/10/_99A0053 1.CR2: >Access: errc=0
2021/02/11 13:16:22 DEBUG : /Fotomateriaal/2018/02/10/_99A0053 1.CR2: Access: mask=00
2021/02/11 13:16:22 DEBUG : /Fotomateriaal/2018/04/01/_99A0547.CR2: >Getattr: errc=0
2021/02/11 13:16:22 DEBUG : /Fotomateriaal/2018/04/01/_99A0547.CR2: Access: mask=00
2021/02/11 13:16:22 DEBUG : /Fotomateriaal/2018/02/10/_99A0053 1.CR2: >Access: errc=0
2021/02/11 13:16:22 DEBUG : /Fotomateriaal/2018/02/10/_99A0053 1.CR2: Access: mask=00
2021/02/11 13:16:22 DEBUG : /Fotomateriaal/2018/04/01/_99A0547.CR2: >Access: errc=0
2021/02/11 13:16:22 DEBUG : /Fotomateriaal/2018/04/01/_99A0548.CR2: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/02/11 13:16:22 DEBUG : /Fotomateriaal/2018/02/10/_99A0053 1.CR2: >Access: errc=0
2021/02/11 13:16:22 DEBUG : /Fotomateriaal/2018/04/01/_99A0548.CR2: >Getattr: errc=0
2021/02/11 13:16:40 INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2021/02/11 13:16:51 DEBUG : /Fotomateriaal/unknown: >Readdir: items=31175, errc=0
2021/02/11 13:16:51 DEBUG : S3 root: Destroy: 
2021/02/11 13:16:51 DEBUG : S3 root: >Destroy: 
2021/02/11 13:16:51 DEBUG : Not calling host.Unmount as mount already Destroyed
2021/02/11 13:16:51 DEBUG : Unmounted successfully
2021/02/11 13:16:51 DEBUG : rclone: Version "v1.55.0-beta.5156.cbe049b52.fix-macos-mounttps" finishing with parameters ["rclone" "mount" "drive:" "/Users/fvanlint/drive-test" "--vfs-cache-mode=writes" "--allow-other" "-vv" "--log-file=manyfiles2-logfile.txt" "--mount-tpslimit" "50"]
2021/02/11 13:16:51 DEBUG : vfs cache: cleaner exiting

Now I will try again but with tpslimit 25
The command looks like this rclone mount drive: ~/drive-test --vfs-cache-mode=writes --allow-other --allow-non-empty -vv --log-file=manyfiles25-logfile.txt --mount-tpslimit 25.
I had to add --allow-non-empty because macOS made a .DS_Store file inside ~/drive-test

This time around, the mount would not start:

2021/02/11 13:25:22 DEBUG : rclone: Version "v1.55.0-beta.5156.cbe049b52.fix-macos-mounttps" starting with parameters ["rclone" "mount" "drive:" "/Users/fvanlint/drive-test" "--vfs-cache-mode=writes" "--allow-other" "-vv" "--log-file=manyfiles25-logfile.txt" "--mount-tpslimit" "25"]
2021/02/11 13:25:22 DEBUG : Creating backend with remote "drive:"
2021/02/11 13:25:22 DEBUG : Using config file from "/Users/fvanlint/.config/rclone/rclone.conf"
2021/02/11 13:25:22 Fatal error: Directory is not empty: /Users/fvanlint/drive-test If you want to mount it anyway use: --allow-non-empty option
2021/02/11 13:27:58 DEBUG : rclone: Version "v1.55.0-beta.5156.cbe049b52.fix-macos-mounttps" starting with parameters ["rclone" "mount" "drive:" "/Users/fvanlint/drive-test" "--vfs-cache-mode=writes" "--allow-other" "--allow-non-empty" "-vv" "--log-file=manyfiles25-logfile.txt" "--mount-tpslimit" "25"]
2021/02/11 13:27:58 DEBUG : Creating backend with remote "drive:"
2021/02/11 13:27:58 DEBUG : Using config file from "/Users/fvanlint/.config/rclone/rclone.conf"
2021/02/11 13:27:58 INFO  : S3 root: poll-interval is not supported by this remote
2021/02/11 13:27:58 DEBUG : vfs cache: root is "/Users/fvanlint/Library/Caches/rclone/vfs/drive"
2021/02/11 13:27:58 DEBUG : vfs cache: metadata root is "/Users/fvanlint/Library/Caches/rclone/vfs/drive"
2021/02/11 13:27:58 DEBUG : Creating backend with remote "/Users/fvanlint/Library/Caches/rclone/vfs/drive"
2021/02/11 13:27:58 DEBUG : Mounting on "/Users/fvanlint/drive-test" ("drive")
2021/02/11 13:27:58 INFO  : Starting mount transaction limiter: max 25 transactions/s with burst 100
2021/02/11 13:27:58 DEBUG : S3 root: Mounting with options: ["-o" "attr_timeout=1" "-o" "fsname=drive:" "-o" "subtype=rclone" "-o" "max_readahead=131072" "-o" "atomic_o_trunc" "-o" "nonempty" "-o" "allow_other" "-o" "volname=drive" "-o" "noappledouble"]
2021/02/11 13:27:58 INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
fuse: unknown option `nonempty'
2021/02/11 13:27:58 ERROR : S3 root: Mount failed
2021/02/11 13:27:58 Fatal error: failed to mount FUSE fs: mount stopped before calling Init: mount failed

My regular / launchagent rclone mounts are still working:

❯ ps -axc|grep rclone
  770 ??         1:24.96 rclone
  807 ??         1:08.39 rclone
 3209 ??         2:09.58 rclone

system.log does not show anything regarding FUSE or rclone, and there are no new diagnostic logs or spindumps.

I am not sure if (and how) I should investigate this further or if I should just reboot :slight_smile:

17

Hmm, that looks like the OS unmounted the filing system. The Destroy callback got called from fuse.

Annoyingly we still don't know why it got umounted.

The mount stopped at 13:16:51 according to the above. The last request from the kernel finished at 13:16:22 so 30 seconds before which is suspicious...

Did you see any other logs from the kernel/console? Something at about that time?

This is the --allow-non-empty flag. Did you use that before? Apparently macfuse doesn't understand it.

Can you try adding the --debug-fuse flag also. This will generate even more logs, but it might throw some light on the messages sent from the kernel to rclone - maybe rclone is ignoring an important message.

If you could upload somewhere a complete log with -vv --debug-fuse then I can go through it with a fine toothed comb and see if I can see any hints!

I've just looked through all the macfuse issues and I don't see a particularly relevant one. I can make an issue with a --debug-fuse log and hopefully get some help :slight_smile:

1 Like
18

Hello @ncw, thank you again for your reply and help :slight_smile:

Did you see any other logs from the kernel/console? Something at about that time?

Sadly, no. I looked inside system.log as well as in the spindumps and diagnostics, but while it is full of mdworker and Vivaldi, nothing about rclone nor about fuse.

This is the --allow-non-empty flag. Did you use that before?

No, I only had to try using --allow-non-empty because MacOS insisted on putting a .DS_Store file in the drive-test folder. I probably should have understood that error, sorry about that.

I a few minutes I will try this again with the --debug-fuse on a new folder with the same name made from the terminal (this stops Finder from making .DS_Store files as long as I don't open the folder in Finder).

This command is what I will use:
rclone mount drive: ~/drive-test --vfs-cache-mode=writes --allow-other -vv --debug-fuse --log-file=tpslimit-50-logfile.txt --mount-tpslimit 50

Update:
Sorry, I got distracted by something. I will update once I am able to run the test.

1 Like
19

@ncw It appears I cannot append to my earlier post, so I will continue here.

I ran the earlier mentioned command, which showed the exact same behaviour as before. So at the least, we have found a way to reproduce the problem reliably.

The log file from rclone with --debug-fuse looks like the following.
I had to snip out a fair amount of lines in order to be able to post it, but I think they were mostly more or less repetitions of the same.

2021/02/13 15:37:23 DEBUG : rclone: Version "v1.55.0-beta.5156.cbe049b52.fix-macos-mounttps" starting with parameters ["rclone" "mount" "drive:" "/Users/fvanlint/drive-test" "--vfs-cache-mode=writes" "--allow-other" "-vv" "--debug-fuse" "--log-file=tpslimit-50-logfile.txt" "--mount-tpslimit" "50"]
2021/02/13 15:37:23 DEBUG : Creating backend with remote "drive:"
2021/02/13 15:37:23 DEBUG : Using config file from "/Users/fvanlint/.config/rclone/rclone.conf"
2021/02/13 15:37:23 INFO  : S3 root: poll-interval is not supported by this remote
2021/02/13 15:37:23 DEBUG : vfs cache: root is "/Users/fvanlint/Library/Caches/rclone/vfs/drive"
2021/02/13 15:37:23 DEBUG : vfs cache: metadata root is "/Users/fvanlint/Library/Caches/rclone/vfs/drive"
2021/02/13 15:37:23 DEBUG : Creating backend with remote "/Users/fvanlint/Library/Caches/rclone/vfs/drive"
2021/02/13 15:37:24 DEBUG : Mounting on "/Users/fvanlint/drive-test" ("drive")
2021/02/13 15:37:24 INFO  : Starting mount transaction limiter: max 50 transactions/s with burst 100
2021/02/13 15:37:24 DEBUG : S3 root: Mounting with options: ["-o" "attr_timeout=1" "-o" "debug" "-o" "fsname=drive:" "-o" "subtype=rclone" "-o" "max_readahead=131072" "-o" "atomic_o_trunc" "-o" "allow_other" "-o" "volname=drive" "-o" "noappledouble"]
2021/02/13 15:37:24 INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
FUSE library version: 2.9.9
nullpath_ok: 0
nopath: 0
utime_omit_ok: 0
unique: 2, opcode: INIT (26), nodeid: 0, insize: 56, pid: 27179
INIT: 7.19
flags=0xee000008
max_readahead=0x00100000
2021/02/13 15:37:24 DEBUG : S3 root: Init: 
2021/02/13 15:37:24 DEBUG : S3 root: >Init: 
   INIT: 7.19
   flags=0x00000018
   max_readahead=0x00020000
   max_write=0x02000000
   max_background=0
   congestion_threshold=0
   unique: 2, success, outsize: 40
unique: 2, opcode: STATFS (17), nodeid: 1, insize: 40, pid: 0
unique: 3, opcode: STATFS (17), nodeid: 1, insize: 40, pid: 27179
statfs /
2021/02/13 15:37:24 DEBUG : /: Statfs: 
statfs /
2021/02/13 15:37:24 DEBUG : /: >Statfs: stat={Bsize:4096 Frsize:4096 Blocks:4294967295 Bfree:4294967295 Bavail:4294967295 Files:1000000000 Ffree:1000000000 Favail:0 Fsid:0 Flag:0 Namemax:255}, errc=0
   unique: 2, success, outsize: 96
2021/02/13 15:37:24 DEBUG : /: Statfs: 
2021/02/13 15:37:24 DEBUG : /: >Statfs: stat={Bsize:4096 Frsize:4096 Blocks:4294967295 Bfree:4294967295 Bavail:4294967295 Files:1000000000 Ffree:1000000000 Favail:0 Fsid:0 Flag:0 Namemax:255}, errc=0
   unique: 3, success, outsize: 96
unique: 3, opcode: STATFS (17), nodeid: 1, insize: 40, pid: 148
statfs /
unique: 2, opcode: STATFS (17), nodeid: 1, insize: 40, pid: 99
2021/02/13 15:37:24 DEBUG : /: Statfs: 
statfs /
2021/02/13 15:37:24 DEBUG : /: >Statfs: stat={Bsize:4096 Frsize:4096 Blocks:4294967295 Bfree:4294967295 Bavail:4294967295 Files:1000000000 Ffree:1000000000 Favail:0 Fsid:0 Flag:0 Namemax:255}, errc=0
2021/02/13 15:37:24 DEBUG : /: Statfs: 
   unique: 3, success, outsize: 96
2021/02/13 15:37:24 DEBUG : /: >Statfs: stat={Bsize:4096 Frsize:4096 Blocks:4294967295 Bfree:4294967295 Bavail:4294967295 Files:1000000000 Ffree:1000000000 Favail:0 Fsid:0 Flag:0 Namemax:255}, errc=0
   unique: 2, success, outsize: 96
unique: 3, opcode: STATFS (17), nodeid: 1, insize: 40, pid: 148
statfs /
2021/02/13 15:37:24 DEBUG : /: Statfs: 
2021/02/13 15:37:24 DEBUG : /: >Statfs: stat={Bsize:4096 Frsize:4096 Blocks:4294967295 Bfree:4294967295 Bavail:4294967295 Files:1000000000 Ffree:1000000000 Favail:0 Fsid:0 Flag:0 Namemax:255}, errc=0
   unique: 3, success, outsize: 96
unique: 2, opcode: STATFS (17), nodeid: 1, insize: 40, pid: 148

<snipped to fit post>
  
   unique: 6, success, outsize: 160
unique: 5, opcode: ACCESS (34), nodeid: 689, insize: 48, pid: 27190
access /Fotomateriaal/2020/01/01/_99A9045.CR2.dop 00
2021/02/13 15:41:06 DEBUG : /Fotomateriaal/2020/01/01/_99A9045.CR2.dop: Access: mask=00
2021/02/13 15:41:06 DEBUG : /Fotomateriaal/2020/01/01/_99A9045.CR2.dop: >Access: errc=0
   unique: 5, success, outsize: 16
unique: 7, opcode: LOOKUP (1), nodeid: 72, insize: 53, pid: 27190
LOOKUP /Fotomateriaal/2020/01/01/_99A9046.CR2
getattr /Fotomateriaal/2020/01/01/_99A9046.CR2
2021/02/13 15:41:06 DEBUG : /Fotomateriaal/2020/01/01/_99A9046.CR2: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/02/13 15:41:06 DEBUG : /Fotomateriaal/2020/01/01/_99A9046.CR2: >Getattr: errc=0
   NODEID: 690
   unique: 7, success, outsize: 160
unique: 2, opcode: ACCESS (34), nodeid: 690, insize: 48, pid: 27190
access /Fotomateriaal/2020/01/01/_99A9046.CR2 00
2021/02/13 15:41:06 DEBUG : /Fotomateriaal/2020/01/01/_99A9046.CR2: Access: mask=00
2021/02/13 15:41:06 DEBUG : /Fotomateriaal/2020/01/01/_99A9046.CR2: >Access: errc=0
   unique: 2, success, outsize: 16
unique: 6, opcode: LOOKUP (1), nodeid: 72, insize: 57, pid: 27190
LOOKUP /Fotomateriaal/2020/01/01/_99A9046.CR2.dop
getattr /Fotomateriaal/2020/01/01/_99A9046.CR2.dop
2021/02/13 15:41:06 DEBUG : /Fotomateriaal/2020/01/01/_99A9046.CR2.dop: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/02/13 15:41:06 DEBUG : /Fotomateriaal/2020/01/01/_99A9046.CR2.dop: >Getattr: errc=0
   NODEID: 691
   unique: 6, success, outsize: 160
unique: 5, opcode: ACCESS (34), nodeid: 691, insize: 48, pid: 27190
access /Fotomateriaal/2020/01/01/_99A9046.CR2.dop 00
2021/02/13 15:41:06 DEBUG : /Fotomateriaal/2020/01/01/_99A9046.CR2.dop: Access: mask=00
2021/02/13 15:41:06 DEBUG : /Fotomateriaal/2020/01/01/_99A9046.CR2.dop: >Access: errc=0
   unique: 5, success, outsize: 16
unique: 7, opcode: LOOKUP (1), nodeid: 72, insize: 53, pid: 27190
LOOKUP /Fotomateriaal/2020/01/01/_99A9047.CR2
getattr /Fotomateriaal/2020/01/01/_99A9047.CR2
2021/02/13 15:41:06 DEBUG : /Fotomateriaal/2020/01/01/_99A9047.CR2: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/02/13 15:41:06 DEBUG : /Fotomateriaal/2020/01/01/_99A9047.CR2: >Getattr: errc=0
   NODEID: 692
   unique: 7, success, outsize: 160
unique: 2, opcode: ACCESS (34), nodeid: 692, insize: 48, pid: 27190
access /Fotomateriaal/2020/01/01/_99A9047.CR2 00
2021/02/13 15:41:06 DEBUG : /Fotomateriaal/2020/01/01/_99A9047.CR2: Access: mask=00
2021/02/13 15:41:06 DEBUG : /Fotomateriaal/2020/01/01/_99A9047.CR2: >Access: errc=0
   unique: 2, success, outsize: 16
unique: 6, opcode: LOOKUP (1), nodeid: 72, insize: 57, pid: 27190
LOOKUP /Fotomateriaal/2020/01/01/_99A9047.CR2.dop
getattr /Fotomateriaal/2020/01/01/_99A9047.CR2.dop
2021/02/13 15:41:06 DEBUG : /Fotomateriaal/2020/01/01/_99A9047.CR2.dop: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/02/13 15:41:06 DEBUG : /Fotomateriaal/2020/01/01/_99A9047.CR2.dop: >Getattr: errc=0
   NODEID: 693
   unique: 6, success, outsize: 160
unique: 5, opcode: ACCESS (34), nodeid: 693, insize: 48, pid: 27190
access /Fotomateriaal/2020/01/01/_99A9047.CR2.dop 00
2021/02/13 15:41:06 DEBUG : /Fotomateriaal/2020/01/01/_99A9047.CR2.dop: Access: mask=00
2021/02/13 15:41:06 DEBUG : /Fotomateriaal/2020/01/01/_99A9047.CR2.dop: >Access: errc=0
   unique: 5, success, outsize: 16
unique: 7, opcode: LOOKUP (1), nodeid: 72, insize: 53, pid: 27190
LOOKUP /Fotomateriaal/2020/01/01/_99A9048.CR2
getattr /Fotomateriaal/2020/01/01/_99A9048.CR2
2021/02/13 15:41:06 DEBUG : /Fotomateriaal/2020/01/01/_99A9048.CR2: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/02/13 15:41:06 DEBUG : /Fotomateriaal/2020/01/01/_99A9048.CR2: >Getattr: errc=0
   NODEID: 694
   unique: 7, success, outsize: 160
unique: 2, opcode: ACCESS (34), nodeid: 694, insize: 48, pid: 27190
access /Fotomateriaal/2020/01/01/_99A9048.CR2 00
2021/02/13 15:41:06 DEBUG : /Fotomateriaal/2020/01/01/_99A9048.CR2: Access: mask=00
2021/02/13 15:41:06 DEBUG : /Fotomateriaal/2020/01/01/_99A9048.CR2: >Access: errc=0
   unique: 2, success, outsize: 16
unique: 6, opcode: LOOKUP (1), nodeid: 72, insize: 57, pid: 27190
LOOKUP /Fotomateriaal/2020/01/01/_99A9048.CR2.dop
getattr /Fotomateriaal/2020/01/01/_99A9048.CR2.dop
2021/02/13 15:41:06 DEBUG : /Fotomateriaal/2020/01/01/_99A9048.CR2.dop: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/02/13 15:41:06 DEBUG : /Fotomateriaal/2020/01/01/_99A9048.CR2.dop: >Getattr: errc=0
   NODEID: 695
   unique: 6, success, outsize: 160
unique: 5, opcode: ACCESS (34), nodeid: 695, insize: 48, pid: 27190
access /Fotomateriaal/2020/01/01/_99A9048.CR2.dop 00
2021/02/13 15:41:06 DEBUG : /Fotomateriaal/2020/01/01/_99A9048.CR2.dop: Access: mask=00
2021/02/13 15:41:06 DEBUG : /Fotomateriaal/2020/01/01/_99A9048.CR2.dop: >Access: errc=0
   unique: 5, success, outsize: 16
unique: 7, opcode: LOOKUP (1), nodeid: 72, insize: 53, pid: 27190
LOOKUP /Fotomateriaal/2020/01/01/_99A9049.CR2
getattr /Fotomateriaal/2020/01/01/_99A9049.CR2
2021/02/13 15:41:06 DEBUG : /Fotomateriaal/2020/01/01/_99A9049.CR2: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/02/13 15:41:06 DEBUG : /Fotomateriaal/2020/01/01/_99A9049.CR2: >Getattr: errc=0
   NODEID: 696
   unique: 7, success, outsize: 160
unique: 2, opcode: ACCESS (34), nodeid: 696, insize: 48, pid: 27190
access /Fotomateriaal/2020/01/01/_99A9049.CR2 00
2021/02/13 15:41:06 DEBUG : /Fotomateriaal/2020/01/01/_99A9049.CR2: Access: mask=00
2021/02/13 15:41:07 DEBUG : /Fotomateriaal/2020/01/01/_99A9049.CR2: >Access: errc=0
   unique: 2, success, outsize: 16
unique: 6, opcode: LOOKUP (1), nodeid: 72, insize: 57, pid: 27190
LOOKUP /Fotomateriaal/2020/01/01/_99A9049.CR2.dop
getattr /Fotomateriaal/2020/01/01/_99A9049.CR2.dop
2021/02/13 15:41:07 DEBUG : /Fotomateriaal/2020/01/01/_99A9049.CR2.dop: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/02/13 15:41:07 DEBUG : /Fotomateriaal/2020/01/01/_99A9049.CR2.dop: >Getattr: errc=0
   NODEID: 697
   unique: 6, success, outsize: 160
unique: 5, opcode: ACCESS (34), nodeid: 697, insize: 48, pid: 27190
access /Fotomateriaal/2020/01/01/_99A9049.CR2.dop 00
2021/02/13 15:41:07 DEBUG : /Fotomateriaal/2020/01/01/_99A9049.CR2.dop: Access: mask=00
2021/02/13 15:41:07 DEBUG : /Fotomateriaal/2020/01/01/_99A9049.CR2.dop: >Access: errc=0
   unique: 5, success, outsize: 16
unique: 7, opcode: LOOKUP (1), nodeid: 72, insize: 53, pid: 27190
LOOKUP /Fotomateriaal/2020/01/01/_99A9050.CR2
getattr /Fotomateriaal/2020/01/01/_99A9050.CR2
2021/02/13 15:41:07 DEBUG : /Fotomateriaal/2020/01/01/_99A9050.CR2: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/02/13 15:41:07 DEBUG : /Fotomateriaal/2020/01/01/_99A9050.CR2: >Getattr: errc=0
   NODEID: 698
   unique: 7, success, outsize: 160
unique: 2, opcode: ACCESS (34), nodeid: 698, insize: 48, pid: 27190
access /Fotomateriaal/2020/01/01/_99A9050.CR2 00
2021/02/13 15:41:07 DEBUG : /Fotomateriaal/2020/01/01/_99A9050.CR2: Access: mask=00
2021/02/13 15:41:07 DEBUG : /Fotomateriaal/2020/01/01/_99A9050.CR2: >Access: errc=0
   unique: 2, success, outsize: 16
unique: 6, opcode: READDIR (28), nodeid: 72, insize: 80, pid: 27190
   unique: 6, success, outsize: 854
unique: 6, opcode: READDIR (28), nodeid: 72, insize: 80, pid: 27190
   unique: 6, success, outsize: 150
unique: 5, opcode: LOOKUP (1), nodeid: 72, insize: 57, pid: 27190
LOOKUP /Fotomateriaal/2020/01/01/_99A9050.CR2.dop
getattr /Fotomateriaal/2020/01/01/_99A9050.CR2.dop
2021/02/13 15:41:07 DEBUG : /Fotomateriaal/2020/01/01/_99A9050.CR2.dop: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/02/13 15:41:07 DEBUG : /Fotomateriaal/2020/01/01/_99A9050.CR2.dop: >Getattr: errc=0
   NODEID: 699
   unique: 5, success, outsize: 160
unique: 7, opcode: ACCESS (34), nodeid: 699, insize: 48, pid: 27190
access /Fotomateriaal/2020/01/01/_99A9050.CR2.dop 00
2021/02/13 15:41:07 DEBUG : /Fotomateriaal/2020/01/01/_99A9050.CR2.dop: Access: mask=00
2021/02/13 15:41:07 DEBUG : /Fotomateriaal/2020/01/01/_99A9050.CR2.dop: >Access: errc=0
   unique: 7, success, outsize: 16
unique: 2, opcode: LOOKUP (1), nodeid: 72, insize: 53, pid: 27190
LOOKUP /Fotomateriaal/2020/01/01/_99A9051.CR2
getattr /Fotomateriaal/2020/01/01/_99A9051.CR2
2021/02/13 15:41:07 DEBUG : /Fotomateriaal/2020/01/01/_99A9051.CR2: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/02/13 15:41:07 DEBUG : /Fotomateriaal/2020/01/01/_99A9051.CR2: >Getattr: errc=0
   NODEID: 700
   unique: 2, success, outsize: 160
unique: 6, opcode: ACCESS (34), nodeid: 700, insize: 48, pid: 27190
access /Fotomateriaal/2020/01/01/_99A9051.CR2 00
2021/02/13 15:41:07 DEBUG : /Fotomateriaal/2020/01/01/_99A9051.CR2: Access: mask=00
2021/02/13 15:41:07 DEBUG : /Fotomateriaal/2020/01/01/_99A9051.CR2: >Access: errc=0
   unique: 6, success, outsize: 16
unique: 5, opcode: LOOKUP (1), nodeid: 72, insize: 57, pid: 27190
LOOKUP /Fotomateriaal/2020/01/01/_99A9051.CR2.dop
getattr /Fotomateriaal/2020/01/01/_99A9051.CR2.dop
2021/02/13 15:41:07 DEBUG : /Fotomateriaal/2020/01/01/_99A9051.CR2.dop: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/02/13 15:41:07 DEBUG : /Fotomateriaal/2020/01/01/_99A9051.CR2.dop: >Getattr: errc=0
   NODEID: 701
   unique: 5, success, outsize: 160
unique: 7, opcode: ACCESS (34), nodeid: 701, insize: 48, pid: 27190
access /Fotomateriaal/2020/01/01/_99A9051.CR2.dop 00
2021/02/13 15:41:07 DEBUG : /Fotomateriaal/2020/01/01/_99A9051.CR2.dop: Access: mask=00
2021/02/13 15:41:07 DEBUG : /Fotomateriaal/2020/01/01/_99A9051.CR2.dop: >Access: errc=0
   unique: 7, success, outsize: 16
unique: 2, opcode: LOOKUP (1), nodeid: 72, insize: 53, pid: 27190
LOOKUP /Fotomateriaal/2020/01/01/_99A9052.CR2
getattr /Fotomateriaal/2020/01/01/_99A9052.CR2
2021/02/13 15:41:07 DEBUG : /Fotomateriaal/2020/01/01/_99A9052.CR2: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/02/13 15:41:07 DEBUG : /Fotomateriaal/2020/01/01/_99A9052.CR2: >Getattr: errc=0
   NODEID: 702
   unique: 2, success, outsize: 160
unique: 6, opcode: ACCESS (34), nodeid: 702, insize: 48, pid: 27190
access /Fotomateriaal/2020/01/01/_99A9052.CR2 00
2021/02/13 15:41:07 DEBUG : /Fotomateriaal/2020/01/01/_99A9052.CR2: Access: mask=00
2021/02/13 15:41:07 DEBUG : /Fotomateriaal/2020/01/01/_99A9052.CR2: >Access: errc=0
   unique: 6, success, outsize: 16
unique: 5, opcode: LOOKUP (1), nodeid: 72, insize: 57, pid: 27190
LOOKUP /Fotomateriaal/2020/01/01/_99A9052.CR2.dop
getattr /Fotomateriaal/2020/01/01/_99A9052.CR2.dop
2021/02/13 15:41:07 DEBUG : /Fotomateriaal/2020/01/01/_99A9052.CR2.dop: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/02/13 15:41:07 DEBUG : /Fotomateriaal/2020/01/01/_99A9052.CR2.dop: >Getattr: errc=0
   NODEID: 703
   unique: 5, success, outsize: 160
unique: 7, opcode: ACCESS (34), nodeid: 703, insize: 48, pid: 27190
access /Fotomateriaal/2020/01/01/_99A9052.CR2.dop 00
2021/02/13 15:41:07 DEBUG : /Fotomateriaal/2020/01/01/_99A9052.CR2.dop: Access: mask=00
2021/02/13 15:41:07 DEBUG : /Fotomateriaal/2020/01/01/_99A9052.CR2.dop: >Access: errc=0
   unique: 7, success, outsize: 16
unique: 2, opcode: LOOKUP (1), nodeid: 72, insize: 53, pid: 27190
LOOKUP /Fotomateriaal/2020/01/01/_99A9053.CR2
getattr /Fotomateriaal/2020/01/01/_99A9053.CR2
2021/02/13 15:41:07 DEBUG : /Fotomateriaal/2020/01/01/_99A9053.CR2: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/02/13 15:41:07 DEBUG : /Fotomateriaal/2020/01/01/_99A9053.CR2: >Getattr: errc=0
   NODEID: 704
   unique: 2, success, outsize: 160
unique: 6, opcode: ACCESS (34), nodeid: 704, insize: 48, pid: 27190
access /Fotomateriaal/2020/01/01/_99A9053.CR2 00
2021/02/13 15:41:07 DEBUG : /Fotomateriaal/2020/01/01/_99A9053.CR2: Access: mask=00
2021/02/13 15:41:07 DEBUG : /Fotomateriaal/2020/01/01/_99A9053.CR2: >Access: errc=0
   unique: 6, success, outsize: 16
unique: 5, opcode: LOOKUP (1), nodeid: 72, insize: 57, pid: 27190
LOOKUP /Fotomateriaal/2020/01/01/_99A9053.CR2.dop
getattr /Fotomateriaal/2020/01/01/_99A9053.CR2.dop
2021/02/13 15:41:07 DEBUG : /Fotomateriaal/2020/01/01/_99A9053.CR2.dop: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/02/13 15:41:07 DEBUG : /Fotomateriaal/2020/01/01/_99A9053.CR2.dop: >Getattr: errc=0
   NODEID: 705
   unique: 5, success, outsize: 160
unique: 7, opcode: ACCESS (34), nodeid: 705, insize: 48, pid: 27190
access /Fotomateriaal/2020/01/01/_99A9053.CR2.dop 00
2021/02/13 15:41:07 DEBUG : /Fotomateriaal/2020/01/01/_99A9053.CR2.dop: Access: mask=00
2021/02/13 15:41:07 DEBUG : /Fotomateriaal/2020/01/01/_99A9053.CR2.dop: >Access: errc=0
   unique: 7, success, outsize: 16
unique: 2, opcode: LOOKUP (1), nodeid: 72, insize: 53, pid: 27190
LOOKUP /Fotomateriaal/2020/01/01/_99A9054.CR2
getattr /Fotomateriaal/2020/01/01/_99A9054.CR2
2021/02/13 15:41:07 DEBUG : /Fotomateriaal/2020/01/01/_99A9054.CR2: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/02/13 15:41:07 DEBUG : /Fotomateriaal/2020/01/01/_99A9054.CR2: >Getattr: errc=0
   NODEID: 706
   unique: 2, success, outsize: 160
unique: 6, opcode: ACCESS (34), nodeid: 706, insize: 48, pid: 27190
access /Fotomateriaal/2020/01/01/_99A9054.CR2 00
2021/02/13 15:41:07 DEBUG : /Fotomateriaal/2020/01/01/_99A9054.CR2: Access: mask=00
2021/02/13 15:41:07 DEBUG : /Fotomateriaal/2020/01/01/_99A9054.CR2: >Access: errc=0
   unique: 6, success, outsize: 16
unique: 5, opcode: LOOKUP (1), nodeid: 72, insize: 57, pid: 27190
LOOKUP /Fotomateriaal/2020/01/01/_99A9054.CR2.dop
getattr /Fotomateriaal/2020/01/01/_99A9054.CR2.dop
2021/02/13 15:41:07 DEBUG : /Fotomateriaal/2020/01/01/_99A9054.CR2.dop: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/02/13 15:41:07 DEBUG : /Fotomateriaal/2020/01/01/_99A9054.CR2.dop: >Getattr: errc=0
   NODEID: 707
   unique: 5, success, outsize: 160
unique: 7, opcode: ACCESS (34), nodeid: 707, insize: 48, pid: 27190
access /Fotomateriaal/2020/01/01/_99A9054.CR2.dop 00
2021/02/13 15:41:07 DEBUG : /Fotomateriaal/2020/01/01/_99A9054.CR2.dop: Access: mask=00
2021/02/13 15:41:07 DEBUG : /Fotomateriaal/2020/01/01/_99A9054.CR2.dop: >Access: errc=0
   unique: 7, success, outsize: 16
unique: 2, opcode: LOOKUP (1), nodeid: 72, insize: 53, pid: 27190
LOOKUP /Fotomateriaal/2020/01/01/_99A9055.CR2
getattr /Fotomateriaal/2020/01/01/_99A9055.CR2
2021/02/13 15:41:07 DEBUG : /Fotomateriaal/2020/01/01/_99A9055.CR2: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/02/13 15:41:07 DEBUG : /Fotomateriaal/2020/01/01/_99A9055.CR2: >Getattr: errc=0
   NODEID: 708
   unique: 2, success, outsize: 160
unique: 6, opcode: ACCESS (34), nodeid: 708, insize: 48, pid: 27190
access /Fotomateriaal/2020/01/01/_99A9055.CR2 00
2021/02/13 15:41:07 DEBUG : /Fotomateriaal/2020/01/01/_99A9055.CR2: Access: mask=00
2021/02/13 15:41:07 DEBUG : /Fotomateriaal/2020/01/01/_99A9055.CR2: >Access: errc=0
   unique: 6, success, outsize: 16
unique: 5, opcode: LOOKUP (1), nodeid: 72, insize: 57, pid: 27190
LOOKUP /Fotomateriaal/2020/01/01/_99A9055.CR2.dop
getattr /Fotomateriaal/2020/01/01/_99A9055.CR2.dop
2021/02/13 15:41:07 DEBUG : /Fotomateriaal/2020/01/01/_99A9055.CR2.dop: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/02/13 15:41:07 DEBUG : /Fotomateriaal/2020/01/01/_99A9055.CR2.dop: >Getattr: errc=0
   NODEID: 709
   unique: 5, success, outsize: 160
unique: 7, opcode: ACCESS (34), nodeid: 709, insize: 48, pid: 27190
access /Fotomateriaal/2020/01/01/_99A9055.CR2.dop 00
2021/02/13 15:41:07 DEBUG : /Fotomateriaal/2020/01/01/_99A9055.CR2.dop: Access: mask=00
2021/02/13 15:41:07 DEBUG : /Fotomateriaal/2020/01/01/_99A9055.CR2.dop: >Access: errc=0
   unique: 7, success, outsize: 16
unique: 2, opcode: LOOKUP (1), nodeid: 72, insize: 53, pid: 27190
LOOKUP /Fotomateriaal/2020/01/01/_99A9056.CR2
getattr /Fotomateriaal/2020/01/01/_99A9056.CR2
2021/02/13 15:41:07 DEBUG : /Fotomateriaal/2020/01/01/_99A9056.CR2: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/02/13 15:41:07 DEBUG : /Fotomateriaal/2020/01/01/_99A9056.CR2: >Getattr: errc=0
   NODEID: 710
   unique: 2, success, outsize: 160
unique: 6, opcode: ACCESS (34), nodeid: 710, insize: 48, pid: 27190
access /Fotomateriaal/2020/01/01/_99A9056.CR2 00
2021/02/13 15:41:07 DEBUG : /Fotomateriaal/2020/01/01/_99A9056.CR2: Access: mask=00
2021/02/13 15:41:07 DEBUG : /Fotomateriaal/2020/01/01/_99A9056.CR2: >Access: errc=0
   unique: 6, success, outsize: 16
unique: 5, opcode: LOOKUP (1), nodeid: 72, insize: 57, pid: 27190
LOOKUP /Fotomateriaal/2020/01/01/_99A9056.CR2.dop
getattr /Fotomateriaal/2020/01/01/_99A9056.CR2.dop
2021/02/13 15:41:07 DEBUG : /Fotomateriaal/2020/01/01/_99A9056.CR2.dop: Getattr: fh=0xFFFFFFFFFFFFFFFF
2021/02/13 15:41:07 DEBUG : /Fotomateriaal/2020/01/01/_99A9056.CR2.dop: >Getattr: errc=0
   NODEID: 711
   unique: 5, success, outsize: 160
unique: 7, opcode: ACCESS (34), nodeid: 711, insize: 48, pid: 27190
access /Fotomateriaal/2020/01/01/_99A9056.CR2.dop 00
2021/02/13 15:41:07 DEBUG : /Fotomateriaal/2020/01/01/_99A9056.CR2.dop: Access: mask=00
2021/02/13 15:41:07 DEBUG : /Fotomateriaal/2020/01/01/_99A9056.CR2.dop: >Access: errc=0
   unique: 7, success, outsize: 16
2021/02/13 15:41:24 INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2021/02/13 15:42:24 INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2021/02/13 15:43:07 DEBUG : /Fotomateriaal/unknown: >Readdir: items=31190, errc=0
   unique: 3, success, outsize: 854
2021/02/13 15:43:07 DEBUG : S3 root: Destroy: 
2021/02/13 15:43:07 DEBUG : S3 root: >Destroy: 
2021/02/13 15:43:07 DEBUG : vfs cache: cleaner exiting
2021/02/13 15:43:07 DEBUG : Not calling host.Unmount as mount already Destroyed
2021/02/13 15:43:07 DEBUG : Unmounted successfully
2021/02/13 15:43:07 DEBUG : rclone: Version "v1.55.0-beta.5156.cbe049b52.fix-macos-mounttps" finishing with parameters ["rclone" "mount" "drive:" "/Users/fvanlint/drive-test" "--vfs-cache-mode=writes" "--allow-other" "-vv" "--debug-fuse" "--log-file=tpslimit-50-logfile.txt" "--mount-tpslimit" "50"]

Unfortunately, I am not sure this actually tells you anything more about the reason that the mount is killed.

20

There is one clue...

Then a long pause, then

This is a read directory returning back to the kernel, and only then is rclone killed.

So reading that directory took a very long time?

I can't see the entry into rclone log - it should look like

DEBUG : /Fotomateriaal/unknown: Readdir

Can you find that one and post it?

Maybe you could post the entire log somewhere (pastebin or share it on drive/dropbox etc)?

1 Like