#1096 Issue closed: How to enhance logging and progress for multiple 'rear' running in parallel?

Labels: enhancement, fixed / solved / done

jsmeix opened issue at 2016-12-01 14:02:

I can run multiple "rear mkbackuponly" and
multiple "rear restoreonly" in parallel, see

But ReaR's current logging is not prepared for multiple
simultaneous rear runs and also ReaR's current
progress subsystem is not prepared for multiple
simultaneous rear runs.

On the terminal the messages from different simultaneous
rear runs mix up indistinguishable and when the
current progress subsystem additionallyoutputs
it basically messes up what there is visible on the terminal
because of its terminal control sequences.

I did some quick-and-dirty experimantal logging enhancements
and progress subsystem changes (mainly showing messages
with a leading PID and let the progress subsystem output each
message on a separated line which effectively disables the intent
of the progress subsystem, cf. lib/progresssubsystem.nosh)
that make the terminal output work o.k. for me.

Now (for two simultaneous "rear mkbackupony" runs)
the terminal output looks like

# usr/sbin/rear -C rootbackup -d -D mkbackuponly & usr/sbin/rear -C homebackup -d -D mkbackuponly & wait ; echo done
[1] 23905
[2] 23906
23906 Relax-and-Recover 1.19 / Git
23905 Relax-and-Recover 1.19 / Git
23906 Using log file: /root/rear/var/log/rear/rear-d25-23906.log
23905 Using log file: /root/rear/var/log/rear/rear-d25-23905.log
23906 Creating tar archive '/tmp/rear.jFUrPHh4h8TQYdv/outputfs/d25/backup-homebackup.tar.gz'
23906 ProgressStart: Preparing archive operation
23905 Creating tar archive '/tmp/rear.6zpcz6nQp1GR5nC/outputfs/d25/backup-rootbackup.tar.gz'
23905 ProgressStart: Preparing archive operation
23906 ProgressInfo: Archived 22 MiB [avg 11648 KiB/sec] 
23905 ProgressInfo: Archived 9 MiB [avg 4816 KiB/sec] 
23906 ProgressInfo: Archived 154 MiB [avg 12199 KiB/sec] 
23905 ProgressInfo: Archived 145 MiB [avg 10648 KiB/sec] 
23906 ProgressStop:  OK
23905 ProgressInfo: Archived 166 MiB [avg 11356 KiB/sec] 
23906 Archived 154 MiB in 15 seconds [avg 10572 KiB/sec]
23905 ProgressInfo: Archived 190 MiB [avg 12190 KiB/sec] 
23906 Saving /root/rear/var/log/rear/rear-d25-23906.log as /root/rear/var/log/rear/rear-d25-mkbackuponly-homebackup.log
23905 ProgressInfo: Archived 222 MiB [avg 13406 KiB/sec] 
23905 ProgressInfo: Archived 314 MiB [avg 15340 KiB/sec] 
23905 ProgressStop:  OK
23905 Archived 314 MiB in 22 seconds [avg 14642 KiB/sec]
23905 Saving /root/rear/var/log/rear/rear-d25-23905.log as /root/rear/var/log/rear/rear-d25-mkbackuponly-rootbackup.log
[1]-  Done  usr/sbin/rear -C rootbackup -d -D mkbackuponly
[2]+  Done  usr/sbin/rear -C homebackup -d -D mkbackuponly

Such changes would be backward incompatible
because the messages look different now.

Hereby I ask for comments what you think about it?

Are such changes how the messages look
a severe backward incompatible change
or is it o.k. to implement it this way?

Personally I think for the ReaR major version bump to 2.x
such backward incompatible changes should be o.k.

By the way I think we should now really
get rid of the progress subsystem, cf.

jsmeix commented at 2016-12-01 14:20:

@gdha @schlomo
what do you think?

jsmeix commented at 2016-12-05 09:13:

It helped to sleep over it over the weekend:
I have a plan now:

I will add support for a new variable MESSAGE_PREFIX
that is by default empty so that by default nothing changes
but the user can set it e.g. to MESSAGE_PREFIX="PID$$: "
and all functions that output something will be changed to
do the output basically via something like

echo "${MESSAGE_PREFIX}$*"

I will add support for a new variable PROGRESS_MODE
that can be PROGRESS_MODE="ANSI" (current behaviour)
or PROGRESS_MODE="plain" (needed as described above)
that is by default empty which means
PROGRESS_MODE="ANSI" is used as fallback
so that by default nothing changes but the user can set it
to PROGRESS_MODE="plain" when needed.

jsmeix commented at 2016-12-05 11:17:

merged I consider this issue to be sufficiently fixed.

I added another new variable PROGRESS_WAIT_SECONDS
that specifies the number of seconds between progress messages
that are aoutput while a longer task (usually backup or restore) runs.
The default/fallback is 1 second to keep the current behaviour, cf.

Documentation of all that happens later when
"Multiple simultaneous backups or restores"
work sufficiently well for me, cf.

[Export of Github issue for rear/rear.]