Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

schedule-log log file is empty. #362

Open
adilfulara opened this issue Apr 9, 2024 · 15 comments
Open

schedule-log log file is empty. #362

adilfulara opened this issue Apr 9, 2024 · 15 comments

Comments

@adilfulara
Copy link

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/resticprofile-backup@profile-default.timer
[Unit]
Description=backup timer for profile default in profiles.yaml

[Timer]
OnCalendar=daily
Unit=resticprofile-backup@profile-default.service
Persistent=true

[Install]
WantedBy=timers.target

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

@jkellerer
Copy link
Collaborator

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
Copy link
Author

@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
Copy link
Collaborator

@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/resticprofile-backup@profile-default.service 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
Copy link
Author

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
Copy link
Collaborator

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/resticprofile-backup@profile-vms.service
[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
Copy link
Author

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

@jkellerer
Copy link
Collaborator

Don't you have the following files?

/home/adilfulara/.config/systemd/user/resticprofile-backup@profile-default.timer
/home/adilfulara/.config/systemd/user/resticprofile-backup@profile-default.service

@adilfulara
Copy link
Author

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

cat resticprofile-backup@profile-default.service
[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
Copy link
Collaborator

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
Copy link
Author

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
Copy link
Author

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

@jkellerer
Copy link
Collaborator

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
Copy link
Collaborator

jkellerer commented Apr 9, 2024

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
Copy link
Author

adilfulara commented Apr 9, 2024

@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
Copy link
Collaborator

jkellerer commented Apr 10, 2024

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants