#2007 Issue closed: Borg stats do not appear in log file even in verbose mode

Labels: enhancement, support / question, fixed / solved / done

nikasl opened issue at 2018-12-19 13:44:

Relax-and-Recover (ReaR) Issue Template

Fill in the following items before submitting a new issue
(quick response is not guaranteed with free support):

  • ReaR version ("/usr/sbin/rear -V"):
    2.4-2.el7

  • OS version ("cat /etc/rear/os.conf" or "lsb_release -a" or "cat /etc/os-release"): CentOS Linux release 7.3.1611 (Core)

  • ReaR configuration files ("cat /etc/rear/site.conf" and/or "cat /etc/rear/local.conf"):

# Rescue ISO                                    
OUTPUT=ISO
OUTPUT_URL=rsync://backuper@172.16.10.33/rear_rescue_images
# Borg Backup 
BACKUP=BORG
BACKUP_PROG_EXCLUDE=( ${BACKUP_PROG_EXCLUDE[@]} '/var/log/lastlog' '/var/lib/mysql' )
BORGBACKUP_HOST=172.16.10.33
BORGBACKUP_USERNAME=backuper
BORGBACKUP_REPO=/sambamnt/borg_backups/prf3
BORGBACKUP_ARCHIVE_PREFIX="rear"
BORGBACKUP_COMPRESSION="lz4"
BORGBACKUP_ENC_TYPE="none"
BORGBACKUP_REMOTE_PATH="/usr/bin/borg"
export BORG_RELOCATED_REPO_ACCESS_IS_OK="yes"
export BORG_UNKNOWN_UNENCRYPTED_REPO_ACCESS_IS_OK="yes"
# Borg retention policy
BORGBACKUP_PRUNE_DAILY=14
BORGBACKUP_PRUNE_WEEKLY=6
BORGBACKUP_PRUNE_MONTHLY=24
  • Hardware (PC or PowerNV BareMetal or ARM) or virtual machine (KVM guest or PoverVM LPAR):
    XenServer guest

  • System architecture (x86 compatible or PPC64/PPC64LE or what exact ARM device):
    x86_64

  • Firmware (BIOS or UEFI or Open Firmware) and bootloader (GRUB or ELILO or Petitboot):
    GRUB

  • Storage (lokal disk or SSD) and/or SAN (FC or iSCSI or FCoE) and/or multipath (DM or NVMe):
    SAN FC

  • Description of the issue (ideally so that others can reproduce it):
    When rear is called through a script that runs from crontab, no Borg stats appear in the log file, as was the case until at least rear v 2.00. If rear is run manually in the command line then the stats appear in the screen but not in the log files. As we are analyzing Borg stats in the log files to decide if the backup was successful for over 100 servers, this creates a problem for us.

  • Workaround, if any:
    To manually replace the new "500_make_backup.sh" script with the old one, every time rear is updated.

  • Attachments, as applicable ("rear -D mkrescue/mkbackup/recover" debug log files):

gozora commented at 2018-12-19 14:18:

What is full command used to launch ReaR from cron ?

V.

nikasl commented at 2018-12-19 14:24:

Crontab entry:

8 2 * * * /opt/scripts/system_backup.sh

And the script:

#!/bin/bash        
/usr/sbin/rear -v -C local mkbackup

jsmeix commented at 2018-12-19 14:24:

I just guess it might be somehow related to
https://github.com/rear/rear/issues/1588
therein in particular
https://github.com/rear/rear/issues/1588#issuecomment-346014845

nikasl commented at 2018-12-19 14:29:

Probably.
Is there any other way to have Borg stats to the log file?

For now, after every version upgrade we are copying the older "500_make_backup.sh" files to all servers using Ansible.

gozora commented at 2018-12-19 14:34:

What data exactly you need to have stored in log ?
Is it maybe following table:

Archive name: rear_17
Archive fingerprint: 28ddf7efd0ca94a2767e54fe120e769e6f75c814c6629476953310e67b074eed
Time (start): Wed, 2018-12-19 15:31:32
Time (end):   Wed, 2018-12-19 15:31:46
Duration: 14.01 seconds
Number of files: 75673
Utilization of max. archive size: 0%
------------------------------------------------------------------------------
                       Original size      Compressed size    Deduplicated size
This archive:                2.44 GB              1.55 GB              1.60 MB
All archives:                7.32 GB              4.64 GB              1.49 GB

                       Unique chunks         Total chunks
Chunk index:                   54205               180423
------------------------------------------------------------------------------

V.

nikasl commented at 2018-12-19 14:36:

Exactly

jsmeix commented at 2018-12-19 14:40:

In backup/BORG/default/500_make_backup.sh (excerpt)

borg create ... 0<&6 1>&7 2>&8

runs borg create with the original stdin, stdout, and stderr file descriptors
when rear was launched that are saved as fd6, fd7, and fd8 respectively,
cf. "What to do with stdin, stdout, and stderr" in
https://github.com/rear/rear/wiki/Coding-Style

Accordingly it should work to launch rear with appropriately redirected
stdout, and stderr to some separated log file.

For example for me

usr/sbin/rear -D mkrescue 2>&1 | tee -a /tmp/rear.tty.log

seems to work as expected (I get in /tmp/rear.tty.log
the same as I get on my terminal where I run it).

Regarding stdin see "It should be possible to run ReaR unattended" at
https://github.com/rear/rear/wiki/Coding-Style

nikasl commented at 2018-12-19 14:59:

Nice idea, but I'm also getting in the log file all the mumbo jumbo of the borg progress output. It would be very nice if I could only get the final stats.

jsmeix commented at 2018-12-19 15:17:

I am not a Borg user so that I don't know what
the borg progress output actually is, if it is caused
by the --progress or --stats option but basically it seems
to be in backup/BORG/default/500_make_backup.sh the lines

# Only in ReaR verbose mode also show borg progress output and stats
local borg_progress=''
test "$verbose" && borg_progress='--progress --stats'

where you get both if you run rear -v.

I guess one of them should be only shown in debug mode, cf.
https://github.com/rear/rear/issues/1588#issuecomment-346308767
i.e. something like

# Only in ReaR verbose mode also show Borg stats output
# and in ReaR debug mode additionally show Borg progress
# (debug mode implies verbose mode, cf. usr/sbin/rear):
local borg_progress=''
test "$VERBOSE" && borg_progress='--stats'
test "$DEBUG" && borg_progress='--progress --stats'

or similar (not tested by me because I do not use Borg).

gozora commented at 2018-12-19 17:12:

@jsmeix like many time before your guess is right!
I'll prepare PR to allow user to decide if he wants to have stats and progress shown or not.
My idea would be to give user final power to decide what will be shown using booleans BORGBACKUP_SHOW_STATS="yes/no" and BORGBACKUP_SHOW_PROGRESS="yes/no"

The reason why I don't like test "$DEBUG" && borg_progress='--progress --stats' very much is that some users might want to see just a progress without additional debugging information.

V.

gozora commented at 2018-12-19 17:58:

With code in https://github.com/rear/rear/pull/2008 I can have following outputs:
With BORGBACKUP_SHOW_STATS="yes"

fedora:(/root)(root)# rear mkbackuponly      
------------------------------------------------------------------------------                                                              
Archive name: rear_25
Archive fingerprint: 11d8c2dcff56be4af267e08c835c461d63c7ae9e029c14cf64f58664aefbdd73
Time (start): Wed, 2018-12-19 18:39:42
Time (end):   Wed, 2018-12-19 18:39:56
Duration: 13.60 seconds
Number of files: 75681
Utilization of max. archive size: 0%
------------------------------------------------------------------------------
                       Original size      Compressed size    Deduplicated size
This archive:                2.45 GB              1.55 GB              2.24 MB
All archives:                7.34 GB              4.64 GB              1.49 GB

                       Unique chunks         Total chunks
Chunk index:                   54217               180442
------------------------------------------------------------------------------

@nikasl You will still need to tee output somewhere ...

With BORGBACKUP_SHOW_PROGRESS="yes"

fedora:(/root)(root)# rear mkbackuponly      
851.51 MB O 424.73 MB C 2.19 MB D 7042 N usr/lib64/python3.6/distutils/__pycache__/unixccompiler.cpython-36.opt-2.pyc

Side-effect of this change is that what Borg shows is not longer controlled by rear --verbose or rear --debug, but I think this gives finer control for output.

V.

nikasl commented at 2018-12-20 07:54:

Thanks for your help guys, it should be much better this way, to have finer control on the output.

jsmeix commented at 2018-12-20 11:40:

@nikasl
a side note regarding your
https://github.com/rear/rear/issues/2007#issuecomment-448613291
/usr/sbin/rear -v -C local mkbackup:

According to man rear
https://github.com/rear/rear/blob/master/doc/rear.8.adoc
the -C option is only for an additional config file
and not for the default config files like etc/rear/local.conf.

With -C local the default config file etc/rear/local.conf
gets sourced (and executed) two times.
First by default and then again because of -C local
cf. in usr/sbin/rear "Combine configuration files" in particular starting at
https://github.com/rear/rear/blob/master/usr/sbin/rear#L442

Usually this has no negative effect but when you specify e.g.

BACKUP_PROG_EXCLUDE=( ${BACKUP_PROG_EXCLUDE[@]} '/var/log/lastlog' '/var/lib/mysql' )

you get that executed two times which results that '/var/log/lastlog' and
'/var/lib/mysql' are added two times to the BACKUP_PROG_EXCLUDE array
which probably does by luck also not have an actual negative effect
but things do not work fully right this way.

nikasl commented at 2018-12-20 11:49:

@jsmeix

Thank you very much for this info!!

gozora commented at 2018-12-20 16:35:

With https://github.com/rear/rear/pull/2008 merged user can now decide with:

BORGBACKUP_SHOW_STATS="yes/no"
BORGBACKUP_SHOW_PROGRESS="yes/no"

if he wants to see Borg stats after ReaR backup finished and/or Borg progress during ReaR backup session.
Since this output will not be stored into ReaR log file, user is advised to use other Linux tools to store this information.
One great example can be found in https://github.com/rear/rear/issues/2007#issuecomment-448618562.

I guess no one would mind if I close this issue now.

V.

jsmeix commented at 2018-12-21 09:20:

@nikasl
because neither @gozora nor I are Borg users
we need now your feedback whether or not the enhancement in
https://github.com/rear/rear/pull/2008
makes things work for you as you need it.

FYI:

How to try out our current ReaR upstream GitHub master code:

Basically "git clone" our current ReaR upstream GitHub master code
into a separated directory and then configure and run ReaR
from within that directory like:

# git clone https://github.com/rear/rear.git

# mv rear rear.github.master

# cd rear.github.master

# vi etc/rear/local.conf

# usr/sbin/rear -D mkbackup

Note the relative paths "etc/rear/" and "usr/sbin/".


[Export of Github issue for rear/rear.]