schedule-log log file is empty.

[adilfulara]

With the following yaml set in the profile block

default:
    backup:
        verbose: true
        schedule: daily
        schedule-log: '{{ tempFile "backup.log" }}'
        run-finally: 'cp {{ tempFile "backup.log" }} /home/adilfulara/restic-config/backup{{ .Now.Format "2006-01-02T15-04-05"}}.log'
        check-after: true
        check-before: true
        one-file-system: true

and running

$ restic version
restic 0.12.1 compiled with go1.18.1 on linux/amd64

$ resticprofile version
resticprofile version 0.26.0 commit 2ab1f3a38467114aeb4095c0924817b369280e39

The log lines do not get added to the file at scheduled run.

ll backup*
-rw-r--r-- 1 adilfulara adilfulara 0 Apr  7 16:05 backup2024-04-07T16-05-47.log
-rw-r--r-- 1 adilfulara adilfulara 0 Apr  7 20:25 backup2024-04-07T20-25-45.log
-rw-r--r-- 1 adilfulara adilfulara 0 Apr  7 20:26 backup2024-04-07T20-26-24.log
-rw-r--r-- 1 adilfulara adilfulara 0 Apr  8 00:00 backup2024-04-08T00-00-04.log

When i running it ad-hoc, i see the log lines as expected on stdout.

The systemctl unit file is

cat /home/adilfulara/.config/systemd/user/[email protected]
[Unit]
Description=backup timer for profile default in profiles.yaml

[Timer]
OnCalendar=daily
[email protected]
Persistent=true

[Install]
WantedBy=timers.target

What am i doing wrong for the log output to the file?

[jkellerer]

Had you tried to recreate the schedule (unschedule, schedule)?

Up to the released version schedules rendered the cli args into the service file. This will be fixed in the next release.

[adilfulara]

@jkellerer thank you for helping. I did recreate but i dont see a difference in the cli args. where would i need to check if the args are correctly set? Is there a related issue for the bug you are referring to so we can link it here.

[jkellerer]

@adilfulara , it isn't really a bug but up-to now resticprofile creates CLI args for itself in the service files, e.g. in cat /home/adilfulara/.config/systemd/user/[email protected] at the time the schedule is created.

This will be changed with the next release so that schedules don't need to be recreated when settings changed.

For log to get written this means the service file should contain an argument like this --log temp:/t/backup.log ( e.g. see https://creativeprojects.github.io/resticprofile/usage/index.html#command-line-reference )

If it still goes wrong, maybe the systemd journal output contains more info. When log configuration cannot be applied, log to stdout should be used as fallback.

[adilfulara]

thank you for clarifying. maybe i misunderstood the doc. so just to be clear 'schedule-log' does not work for systemd?
is that a correct understanding? it probably works with other schedule systems.

looking forward to the next release.

[jkellerer]

schedule-log does work with systemd, what I mean is when you recreate the schedule, the service file receives the log argument, e.g.:

cat /etc/systemd/system/[email protected]
[Unit]
Description=resticprofile backup for profile vms in /etc/resticprofile/profiles.yaml

[Service]
Type=notify
WorkingDirectory=/root
ExecStart=/usr/local/bin/resticprofile --no-prio --no-ansi --config /etc/resticprofile/profiles.yaml --name vms --log temp:/t/backup.log --lock-wait 45m0s backup
Nice=5
Environment="HOME=/root"

If a --log temp:/t/backup.log is present like here in ExecStart but you still have no log then it may mean that the log file cannot be opened.

[adilfulara]

@jkellerer where would i find the file you refer to? i couldn't find it. apologies for the lack of my systemd knowledge.

[jkellerer]

Don't you have the following files?

/home/adilfulara/.config/systemd/user/[email protected]
/home/adilfulara/.config/systemd/user/[email protected]

[adilfulara]

i found the following under /home/adilfulara/.config/systemd/user

cat [email protected]
[Unit]
Description=resticprofile backup for profile default in /home/adilfulara/.config/resticprofile/profiles.yaml

[Service]
Type=notify
WorkingDirectory=/home/adilfulara/.config/systemd/user
ExecStart=/usr/local/bin/resticprofile --no-prio --no-ansi --config /home/adilfulara/.config/resticprofile/profiles.yaml --name default --log temp:/t/backup.log backup
Nice=5
Environment="HOME=/home/adilfulara"

[jkellerer]

What happens when you run /usr/local/bin/resticprofile --no-prio --no-ansi --config /home/adilfulara/.config/resticprofile/profiles.yaml --name default --log temp:/t/backup.log backup with user adilfulara?

[adilfulara]

it does run but does not print logs to stdout

➜  user /usr/local/bin/resticprofile --no-prio --no-ansi --config /home/adilfulara/.config/resticprofile/profiles.yaml --name default --log temp:/t/backup.log backup
➜  user resticprofile snapshots
2024/04/09 11:19:30 using configuration file: /home/adilfulara/.config/resticprofile/profiles.yaml
2024/04/09 11:19:30 profile 'default': initializing repository (if not existing)
2024/04/09 11:19:31 profile 'default': starting 'snapshots'
repository 97079471 opened successfully, password is correct
ID        Time                 Host        Tags        Paths
-----------------------------------------------------------------------------
dccfadea  2024-03-24 18:04:59  pop-os                  /home/adilfulara/Share
64da3f3b  2024-03-25 00:00:07  pop-os                  /home/adilfulara/Share
80a910f2  2024-03-26 00:00:08  pop-os                  /home/adilfulara/Share
a13bf926  2024-03-27 00:00:03  pop-os                  /home/adilfulara/Share
f901d25f  2024-03-28 00:00:07  pop-os                  /home/adilfulara/Share
cd0e2c42  2024-03-29 00:00:07  pop-os                  /home/adilfulara/Share
7a7f8c50  2024-03-30 00:00:04  pop-os                  /home/adilfulara/Share
1f33ac13  2024-03-31 00:00:07  pop-os                  /home/adilfulara/Share
051f866a  2024-04-01 00:00:05  pop-os                  /home/adilfulara/Share
9171e318  2024-04-02 00:00:08  pop-os                  /home/adilfulara/Share
db4e6bb1  2024-04-03 00:00:08  pop-os                  /home/adilfulara/Share
607623dc  2024-04-04 00:00:07  pop-os                  /home/adilfulara/Share
a7b5c6ac  2024-04-05 00:00:07  pop-os                  /home/adilfulara/Share
eb141b3e  2024-04-06 00:00:08  pop-os                  /home/adilfulara/Share
d1d44e7c  2024-04-07 20:26:28  pop-os                  /home/adilfulara/Share
ac2d136e  2024-04-08 00:00:07  pop-os                  /home/adilfulara/Share
9da3a7a5  2024-04-09 11:19:11  pop-os                  /home/adilfulara/Share
-----------------------------------------------------------------------------
17 snapshots
2024/04/09 11:19:32 profile 'default': finished 'snapshots'

[adilfulara]

apologies for my ignorance but what does temp:/t/backup.log mean? I do not have /t directory on my desktop.

[jkellerer]

The prefix temp: means the log file should be created in a volatile temp folder that exists only during resticprofile is being executed. When you use {{ tempFile "somefile" }} in the config file, then the path will be this folder from temp: plus a /t prefix for files referenced in the configuration (to not get in conflict with other temp files that resticprofile may use).

So long story short :) temp:/t/backup.log translates to the same path as {{ tempFile "backup.log" }} used in the config file. The exact physical path depends on the OS but in your case it should be something like /tmp/resticprofile-1234567/t/backup.log.

[jkellerer]

What you could do to troubleshoot is: Add a run-finally line like "sleep 30" and look for the file in the /tmp or /var/tmp to see if it does get filled before the sleep ends (as it will get deleted when resticprofile ends).

[adilfulara]

@jkellerer sorry for the delay. i updated the file as follows

default:
  backup:
    verbose: true
    schedule: 
    - "daily"
    - "*-*-* *:*:00"
    schedule-log: '{{ tempFile "backup.log" }}'
    run-finally: 'cp {{ tempFile "backup.log" }} /home/adilfulara/restic-config/backup{{ .Now.Format "2006-01-02T15-04-05" }}.log && sleep 60'

and i do see the files

ll backup*
-rw-r--r-- 1 adilfulara adilfulara    0 Apr  7 16:05 backup2024-04-07T16-05-47.log
-rw-r--r-- 1 adilfulara adilfulara    0 Apr  7 20:25 backup2024-04-07T20-25-45.log
-rw-r--r-- 1 adilfulara adilfulara    0 Apr  7 20:26 backup2024-04-07T20-26-24.log
-rw-r--r-- 1 adilfulara adilfulara    0 Apr  8 00:00 backup2024-04-08T00-00-04.log
-rw-r--r-- 1 adilfulara adilfulara    0 Apr  9 00:00 backup2024-04-09T00-00-04.log
-rw-r--r-- 1 adilfulara adilfulara 4.6K Apr  9 11:19 backup2024-04-09T11-19-07.log
-rw-r--r-- 1 adilfulara adilfulara 4.8K Apr  9 13:26 backup2024-04-09T13-26-08.log
-rw-r--r-- 1 adilfulara adilfulara 4.9K Apr  9 13:27 backup2024-04-09T13-27-19.log
-rw-r--r-- 1 adilfulara adilfulara 5.0K Apr  9 13:29 backup2024-04-09T13-29-14.log

so i am not sure what changed other than the schedule and sleep.

is this a race condition that the file is deleted before getting copied?

[jkellerer]

Based on the file timestamps (first log file with a size was written 2 hours prior the others, I assume the rescheduling fixed it , which was expected with resticprofile 0.26. Next release will address the need for rescheduling (it works then without it)

So with other words if you remove sleep it should still work. A timing problem is very unlikely.