#1588 Issue closed: Verbose logging when using BORG backend?

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

ChojinDSL opened issue at 2017-11-21 12:20:

Hi, I'm using BORG backup as a backend with REAR.
Is there any way to display the progress when using REAR with BORG as a backend?

If I just run "rear -v -d mkbackup"
then the log file only lists the steps up until the point where the actual transfer via borg happens. It would be nice to be able to see how far a long the backup process is when using BORG.

gozora commented at 2017-11-21 12:25:

I guess that I've suppresses Borg backup output, unfortunately I don't remember the exact reason any more. (probably it messed up logs).

I'll take a look on this issue and let you know ...

V.

jsmeix commented at 2017-11-21 12:40:

@gozora
because in backup/BORG/default/500_make_backup.sh there is

# Start actual Borg backup.
borg create --one-file-system --verbose --stats $BORGBACKUP_OPT_COMPRESSION \
$BORGBACKUP_OPT_REMOTE_PATH --exclude-from $TMP_DIR/backup-exclude.txt \
$BORGBACKUP_USERNAME@$BORGBACKUP_HOST:$BORGBACKUP_REPO::\
${BORGBACKUP_ARCHIVE_PREFIX}_$BORGBACKUP_SUFFIX \
${include_list[@]}

I guess that the '--verbose' output is no longer visible
since STDOUT is redirected into the log file, cf.
https://github.com/rear/rear/issues/885
and
https://github.com/rear/rear/issues/1398

The general solution to show intended output
on the user's terminal is described at
"What to do with stdout and stderr" in
https://github.com/rear/rear/wiki/Coding-Style

FYI:
In general there should be no hardcoded '--verbose'.
To run commands verbosely only in verbose mode
(i.e. when ReaR was called with the '-v' option) use

COMMAND $verbose

or

COMMAND $v

because usr/sbin/rear sets $verbose and $v in verbose mode.

jsmeix commented at 2017-11-21 14:25:

@gozora
I guess the following 'borg' command calls
may need to be enhanced:

In backup/BORG/default/500_make_backup.sh

borg create --one-file-system --verbose ...

In backup/BORG/default/800_prune_old_backups.sh

borg prune --verbose ...

In restore/BORG/default/400_restore_backup.sh

borg extract ...

In prep/BORG/default/300_init_archive.sh

borg init ...

gozora commented at 2017-11-21 17:02:

Hello @jsmeix,

Would approach like this be acceptable ?

# Run Borg with verbose options (output to stdout)
if [[ "$VERBOSE" ]]; then
    borg create --one-file-system --progress $verbose --stats \
$BORGBACKUP_OPT_COMPRESSION $BORGBACKUP_OPT_REMOTE_PATH \
--exclude-from $TMP_DIR/backup-exclude.txt \
$BORGBACKUP_USERNAME@$BORGBACKUP_HOST:$BORGBACKUP_REPO::\
${BORGBACKUP_ARCHIVE_PREFIX}_$BORGBACKUP_SUFFIX \
${include_list[@]} 1>&7 2>&8
else
# Run Borg silently (just output to logfile)
    borg create --one-file-system --stats $BORGBACKUP_OPT_COMPRESSION \
$BORGBACKUP_OPT_REMOTE_PATH --exclude-from $TMP_DIR/backup-exclude.txt \
$BORGBACKUP_USERNAME@$BORGBACKUP_HOST:$BORGBACKUP_REPO::\
${BORGBACKUP_ARCHIVE_PREFIX}_$BORGBACKUP_SUFFIX \
${include_list[@]}
fi

The functionality we are looking for is --progress and I've did not used it because it outputs in pretty way to terminal (just updates last line of terminal) but it messes up logfile pretty badly.

V.

jsmeix commented at 2017-11-21 17:35:

@gozora
I would not repeat the whole complicated 'borg' command
because it makes it hard to see what the difference is.

I would only define the relevant options as variables
and leave them empty if not needed, something like:

local borg_progress=''
# Only in ReaR verbose mode also show borg progress output:
test "$verbose" && borg_progress='--progress'
# Have STDIN and STDOUT on the user's terminal
# (perhaps borg asks for user confirmation via STDOUT)
# but keep STDERR in the ReaR log file:
borg create $verbose $borg_progress --one-file-system ... 0<&6 1>&7

If borg might ask the user via messages on STDERR
(many programs do it this way - e.g. the 'read' bash builtin)
you would have to call it as

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

to also get STDERR on the user's termial.

jsmeix commented at 2017-11-21 17:38:

To be on the safe side also redirect STDIN to the
user's terminal because in special cases we may have
to redirect it to "something weird" in the future, cf.
https://github.com/gdha/rear-automated-testing/issues/36

gozora commented at 2017-11-21 18:02:

Hello @jsmeix,

if you run Borg command they always do some output e.g.:

#borg create ...

------------------------------------------------------------------------------                                                          
Archive name: rear_19
Archive fingerprint: 0049718df7c683d82609189acd7f220a77f3bf1f9485b940546f6127a32c8b1d
Time (start): Tue, 2017-11-21 18:53:43
Time (end):   Tue, 2017-11-21 18:53:57
Duration: 14.01 seconds
Number of files: 59414
Utilization of max. archive size: 0%
------------------------------------------------------------------------------
                       Original size      Compressed size    Deduplicated size
This archive:                1.78 GB            750.02 MB              1.77 MB
All archives:                3.57 GB              1.50 GB            708.54 MB

                       Unique chunks         Total chunks
Chunk index:                   48655               109021
------------------------------------------------------------------------------

This would mean a unwanted output when running plain rear mkbackup

What about something like this, where repeating command if omitted and things stays separated:

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

local borg_command="borg create --one-file-system $borg_progress $verbose
--stats $BORGBACKUP_OPT_COMPRESSION $BORGBACKUP_OPT_REMOTE_PATH \
--exclude-from $TMP_DIR/backup-exclude.txt \
$BORGBACKUP_USERNAME@$BORGBACKUP_HOST:$BORGBACKUP_REPO::\
${BORGBACKUP_ARCHIVE_PREFIX}_$BORGBACKUP_SUFFIX \
${include_list[@]}"

if [[ $verbose ]]; then
    $borg_command 0<&6 1>&7 2>&8
else
    $borg_command
fi

V.

gozora commented at 2017-11-21 18:17:

@jsmeix ignore my https://github.com/rear/rear/issues/1588#issuecomment-346110754 as it is simply not true. The Borg output can be silenced by removing --stats option.
So I guess we can patch this as you proposed in https://github.com/rear/rear/issues/1588#issuecomment-346102893.

V.

jsmeix commented at 2017-11-22 10:27:

@gozora
I am sorry I did my above comments in a hurry
so I probably caused more confusion than being helpful
but - as always - sleeping over it helped to clear my mind:

I am not a borg user so that I cannot tell what the right way
is when calling borg commands.

Regarding '--stats' you may still show that but only in verbose mode
or perhaps even only in debug mode (implement it as you like)
e.g. via

local borg_stats=''
test "$DEBUG" && borg_stats='--stats'
...
borg create $verbose $borg_stats ... 0<&6 1>&7 2>&8

In general when calling commands in ReaR the crucial point
is whether or not a command is or could be interactive.

When a command is or could be somehow interactive
(also progress output is "somehow interactive")
it should usually be called as

COMMAND ... 0<&6 1>&7 2>&8

to ensure any command output will be visible by the user
and the command can get input from the user.

Examples:

The bash builtin 'read' gets input from STDIN,
echoes the input probably via STDOUT (or directly to the terminal?)
and shows its prompt via STDERR so that it must be called like

read -p 'enter your input ' user_input 0<&6 1>&7 2>&8

The command 'rm -v -I' only prompts when removing more
than three files and then its prompt is shown on STDERR
(but also error messages are shown on STDERR)
and its verbose output is shown via SDTOUT
so that it can be called like

rm -v -I $files 0<&6 1>&2 2>&8

to get only its verbose output in the ReaR log file
but error messages are shown to the user
or more consistent and therefore probably better

rm -v -I $files 0<&6 1>&7 2>&8

that simply and consistently shows all output to the user.

From the last example I conclude that in general
when a command is or could be interactive
it should usually be called as

COMMAND ... 0<&6 1>&7 2>&8

to ensure the command behaves consistently to the user.

I think in case of doubt it is more important
that ReaR behaves consistently to the user
than having everything in the ReaR log.

When a command is called as

COMMAND ... 0<&6 1>&7 2>&8

it is still possible to have something meaningful in the log like

if COMMAND ... 0<&6 1>&7 2>&8 ; then
    Log "COMMAND finished with zero exit code"
else
    Log "COMMAND finished with non-zero exit code $?"
fi

Optionally only FYI you may have a look at
backup/NETFS/default/500_make_backup.sh
what advanced code there is implemented only
to show some progress information to the user
while the 'tar' backup command is running.
It runs the 'tar' backup command in a sub-process
while the parent bash polls the backuparchive file size
that gets shown to the user.

gozora commented at 2017-11-22 19:38:

@ChojinDSL I pushed #1594 so you can test if it suits better your needs now.

V.

gozora commented at 2017-11-23 15:34:

With #1594 merged, I guess we can close this one.

V.


[Export of Github issue for rear/rear.]