One-line stats missing timestamp, includes <#> prefix?

Help and Support
1

What is the problem you are having with rclone?

I've written a PySide6 GUI that calls rclone as a subprocess (QProcess). In order to track progress, I run rclone with one-line stats and parse the stderr output. For debug purposes, I print the raw stderr output to the console and app log when parsing fails.

I've recently deployed this app to a remote Ubuntu 20.04 machine. When I run the app over ssh with X11 forwarding, everything parses as expected. However, when a local user runs the app, the stderr output doesn't contain the timestamp but does include a <#> prefix that causes parsing to fail:

# Messages when source directory does not exist
<5>NOTICE: Config file "/home/USER/.config/rclone/rclone.conf" not found - using defaults
<3>ERROR : Local file system at /media/USER/DIRECTORY: error reading source root directory: directory not found
<3>ERROR : Attempt 1/3 failed with 1 errors and: directory not found
<3>ERROR : Local file system at /media/USER/DIRECTORY: error reading source root directory: directory not found
<3>ERROR : Attempt 2/3 failed with 1 errors and: directory not found
<3>ERROR : Local file system at /media/USER/DIRECTORY: error reading source root directory: directory not found
<3>ERROR : Attempt 3/3 failed with 1 errors and: directory not found
<5>NOTICE:           0 B / 0 B, -, 0 B/s, ETA -

# Messages when source directory does exist
<5>NOTICE: Config file "/home/USER/.config/rclone/rclone.conf" not found - using defaults
<5>NOTICE:           0 B / 0 B, -, 0 B/s, ETA -
<5>NOTICE:           0 B / 0 B, -, 0 B/s, ETA -
<5>NOTICE:     7.422 MiB / 75.335 GiB, 0%, 0 B/s, ETA - (xfr#0/8072)
<5>NOTICE:   112.151 MiB / 75.503 GiB, 0%, 0 B/s, ETA - (xfr#10/8091)
<5>NOTICE:   206.184 MiB / 75.503 GiB, 0%, 153.187 MiB/s, ETA 8m23s (xfr#20/8091)
<5>NOTICE:   317.744 MiB / 75.503 GiB, 0%, 153.187 MiB/s, ETA 8m22s (xfr#31/8091)

I don't think this is an rclone issue so much as it is me not fully understanding the stats output. My intuition is that it might have something to do with character encoding differences between the remote and local sessions. Does --stats-one-line include console control characters that might create something like this if transformed to a utf-8 string?

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

rclone v1.60.0
- os/version: ubuntu 20.04 (64 bit)
- os/kernel: 5.4.0-131-generic (x86_64)
- os/type: linux
- os/arch: amd64
- go/version: go1.19.2
- go/linking: static
- go/tags: none

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

Local file system transfers only.

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

rclone --max-backlog 100000 --stats 500ms --stats-log-level NOTICE --stats-one-line copy SRC DEST

A log from the command with the -vv flag

Not sure how useful this is as I can't reproduce on the command line:

2022/11/18 16:04:29 DEBUG : rclone: Version "v1.60.0" starting with parameters ["/tmp/_MEIQduGpq/rclone" "-vv" "--max-backlog" "100000" "--stats" "500ms" "--stats-log-level" "NOTICE" "--stats-one-line" "copy" "SRC" "DEST"]
2022/11/18 16:04:29 DEBUG : Creating backend with remote "SRC"
2022/11/18 16:04:29 NOTICE: Config file "/home/databot/.config/rclone/rclone.conf" not found - using defaults
2022/11/18 16:04:29 DEBUG : Creating backend with remote "DEST"
2022/11/18 16:04:29 ERROR : Local file system at SRC: error reading source root directory: directory not found
2022/11/18 16:04:29 DEBUG : Local file system at DEST: Waiting for checks to finish
2022/11/18 16:04:29 DEBUG : Local file system at DEST: Waiting for transfers to finish
2022/11/18 16:04:29 ERROR : Attempt 1/3 failed with 1 errors and: directory not found
2022/11/18 16:04:29 ERROR : Local file system at SRC: error reading source root directory: directory not found
2022/11/18 16:04:29 DEBUG : Local file system at DEST: Waiting for checks to finish
2022/11/18 16:04:29 DEBUG : Local file system at DEST: Waiting for transfers to finish
2022/11/18 16:04:29 ERROR : Attempt 2/3 failed with 1 errors and: directory not found
2022/11/18 16:04:29 ERROR : Local file system at SRC: error reading source root directory: directory not found
2022/11/18 16:04:29 DEBUG : Local file system at DEST: Waiting for checks to finish
2022/11/18 16:04:29 DEBUG : Local file system at DEST: Waiting for transfers to finish
2022/11/18 16:04:29 ERROR : Attempt 3/3 failed with 1 errors and: directory not found
2022/11/18 16:04:29 NOTICE:           0 B / 0 B, -, 0 B/s, ETA -
2022/11/18 16:04:29 DEBUG : 3 go routines active
2022/11/18 16:04:29 Failed to copy: directory not found
2

That means that rclone thinks it is running under systemd so is producing systemd format logs.

Is it?

If not there will be an environment variable set (I forget which one and I'm not at my computer!)

1 Like
3

That's interesting. My gut reaction is to say no in that my app is not explicitly installed or running as a systemd service. However, I see differing behavior when I launch from the terminal over ssh (not a systemd managed session?) versus when I launch by double-clicking my app on the desktop (are lightdm sessions managed by systemd?). It also explains why I don't see similar behavior on macOS or Windows at all.

This is a good lead! I feel like maybe I need to explore this a bit more at runtime. Thanks!

4

A quick grep of the code... It is looking for the environment variable INVOCATION_ID - if that is set it will assume it is running under systemd.

1 Like
5

After some investigation, I can confirm that this is because GUI apps launched from the desktop environment are considered a child process of systemd. Trimmed ps -x --forest results:

    PID TTY      STAT   TIME COMMAND
3190815 ?        S      0:00 sshd: USER@pts/0
3190818 pts/0    Ss     0:00  \_ -bash
3190842 pts/0    S+     0:01      \_ ./Desktop/CopyTool
3190844 pts/0    Sl+    0:00          \_ ./Desktop/CopyTool          # launched via ssh -X
...
3168039 ?        Ss     0:01 /lib/systemd/systemd --user
3178022 ?        Ssl  139:09  \_ /usr/bin/gnome-shell
3189428 ?        S      0:01  |   \_ /home/USER/Desktop/CopyTool
3189429 ?        Rl    65:07  |       \_ /home/USER/Desktop/CopyTool # launched from desktop

I'm just glad to understand why it's doing what it's doing. I've modified my app to handle parsing of both the standard and systemd prefixes. Thanks!

1 Like
6

Ah ha!

Unsetting the environment variable will fix it too.

7

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