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

Improve logging for unattended backups with cron #667

Closed
zcalusic opened this Issue Nov 10, 2016 · 5 comments

Comments

Projects
None yet
3 participants
@zcalusic
Member

zcalusic commented Nov 10, 2016

I'd say that most production uses of restic would be through cron. You set backup to fire up in the dead of the night, when systems are more idle than during the day, and let it do it's job. In the morning, you expect email from cron, reporting some statistics about the run and any errors that might've occured while you were sleeping. At least that's how I usually do it.

Now, we have 2 modes of logging, the usual pretty progress bars on console, and -q quiet switch to not log at all. I'd say none of those is suitable to be used from cron. For some time I run with -q, but I missed email reports in the morning. :( Now, that I've switched to verbose logging, all those progresses come as a spam in the mailbox. What's worse, errors are hidden among lots of lines, like this:

[3:10] 55.65%  29.937 MiB/s  5.555 GiB / 9.981 GiB  106000 / 108756 items  0 errors  ETA 2:31 
[3:20] 63.74%  32.572 MiB/s  6.362 GiB / 9.981 GiB  106060 / 108756 items  0 errors  ETA 1:53 
[3:30] 70.39%  34.261 MiB/s  7.026 GiB / 9.981 GiB  106586 / 108756 items  0 errors  ETA 1:28 
error for /var/log/account/pacct: errors saving node "/var/log/account/pacct": saved 79426496 bytes, wanted 79424640 bytes
[3:40] 77.30%  35.914 MiB/s  7.716 GiB / 9.981 GiB  106589 / 108756 items  1 errors  ETA 1:04 
[3:50] 84.52%  37.559 MiB/s  8.436 GiB / 9.981 GiB  106598 / 108756 items  1 errors  ETA 0:42 

And it's ugly as hell, you must admit. ;)

So, I propose third way of logging, suitable for unattended runs. Which would log everything, except progress.

There are at least 2 ways to do this, I'll let you decide which you prefer better.

  • either introduce --progress or --no-progress switches to control what is printed, or
  • there's a simple way to detect if the program has controlling tty, so if one is detected, the progress would be printed as usual, otherwise not

If you prefer the second version, I'll send the required few lines of code, I already used this mechanism in some of my apps.

@zcalusic

This comment has been minimized.

Show comment
Hide comment
@zcalusic

zcalusic Nov 10, 2016

Member

I wanted to name this "Inadequate logging", but using that word makes the ticket close fast without resolution. Let's see if shortening issue title helps. ;)

Member

zcalusic commented Nov 10, 2016

I wanted to name this "Inadequate logging", but using that word makes the ticket close fast without resolution. Let's see if shortening issue title helps. ;)

@fd0

This comment has been minimized.

Show comment
Hide comment
@fd0

fd0 Nov 10, 2016

Member

I agree, we should find a solution here that's suitable for cron.

Member

fd0 commented Nov 10, 2016

I agree, we should find a solution here that's suitable for cron.

@fd0 fd0 changed the title from Logging to Improve logging for unattended backups with cron Nov 10, 2016

@zcalusic

This comment has been minimized.

Show comment
Hide comment
@zcalusic

zcalusic May 26, 2017

Member

#974 is a great success! Thank you very much for working on this long standing issue. Finally I can read backup reports in the morning. 👍

This is what we have now:

using parent snapshot 1d9a2eab
scan [/]
[0:30] 172385 directories, 937777 files, 34.696 GiB
scanned 172385 directories, 937777 files in 0:30
[36:18] 100.00%  0B/s  34.696 GiB / 34.696 GiB  1110161 / 1110162 items  0 errors  ETA 0:00 

duration: 36:18, 16.31MiB/s
snapshot dd004fab saved
[4:32] 74.538 GiB  0B/s

duration: 4:32, 280.16MiB/s
archived as 3e956747

Few nitpicks:

  • we have now 0B/s in the final progress lines, previously it was the average speed of the process, would be great if we could keep the feature, otherwise just remove it
  • some repetition can now be seen, I find it great that you could print (only) the final progress line, maybe we can now lose the additional lines?
  • total nitpick, maybe if 100.00% & ETA 0:00 can be easily removed, since they don't carry any useful info?
  • total nitpick no2, extra empty lines...

IOW, this would be really perfect output, based on the example and comments above:

using parent snapshot 1d9a2eab
scan [/]
[0:30] 172385 directories, 937777 files, 34.696 GiB
[36:18] 16.749 MiB/s 34.696 GiB / 34.696 GiB  1110161 / 1110162 items  0 errors
snapshot dd004fab saved
[4:32] 74.538 GiB  280.16MiB/s
archived as 3e956747

But hey, even if you just close the ticket without any additional improvement, I'm happy and grateful, this is much better output now, compared what we had before.

Member

zcalusic commented May 26, 2017

#974 is a great success! Thank you very much for working on this long standing issue. Finally I can read backup reports in the morning. 👍

This is what we have now:

using parent snapshot 1d9a2eab
scan [/]
[0:30] 172385 directories, 937777 files, 34.696 GiB
scanned 172385 directories, 937777 files in 0:30
[36:18] 100.00%  0B/s  34.696 GiB / 34.696 GiB  1110161 / 1110162 items  0 errors  ETA 0:00 

duration: 36:18, 16.31MiB/s
snapshot dd004fab saved
[4:32] 74.538 GiB  0B/s

duration: 4:32, 280.16MiB/s
archived as 3e956747

Few nitpicks:

  • we have now 0B/s in the final progress lines, previously it was the average speed of the process, would be great if we could keep the feature, otherwise just remove it
  • some repetition can now be seen, I find it great that you could print (only) the final progress line, maybe we can now lose the additional lines?
  • total nitpick, maybe if 100.00% & ETA 0:00 can be easily removed, since they don't carry any useful info?
  • total nitpick no2, extra empty lines...

IOW, this would be really perfect output, based on the example and comments above:

using parent snapshot 1d9a2eab
scan [/]
[0:30] 172385 directories, 937777 files, 34.696 GiB
[36:18] 16.749 MiB/s 34.696 GiB / 34.696 GiB  1110161 / 1110162 items  0 errors
snapshot dd004fab saved
[4:32] 74.538 GiB  280.16MiB/s
archived as 3e956747

But hey, even if you just close the ticket without any additional improvement, I'm happy and grateful, this is much better output now, compared what we had before.

@fd0

This comment has been minimized.

Show comment
Hide comment
@fd0

fd0 May 26, 2017

Member

So I'm going to close this for now.

Member

fd0 commented May 26, 2017

So I'm going to close this for now.

@fd0 fd0 closed this May 26, 2017

@tomwaldnz

This comment has been minimized.

Show comment
Hide comment
@tomwaldnz

tomwaldnz Jul 16, 2018

Question - how do you use this? I can't see anything in the documentation that seems to suggest it turns on or off progress indicators other than -q mentioned above, and the linked bug doesn't say. Does restic automatically detect whether it's being run interactively? I have cron and windows scheduler run restic so this is of interest.

tomwaldnz commented Jul 16, 2018

Question - how do you use this? I can't see anything in the documentation that seems to suggest it turns on or off progress indicators other than -q mentioned above, and the linked bug doesn't say. Does restic automatically detect whether it's being run interactively? I have cron and windows scheduler run restic so this is of interest.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment