#2466 PR `merged`: 500_make_backup.sh: filter informational tar messages from output¶

Labels: enhancement, fixed / solved / done

casantos opened issue at 2020-08-04 01:32:¶

Type: Bug Fix
Impact: Low
Reference to related issue (URL): #2465
How was this pull request tested? See steps to reproduce in issue #2465
Brief description of the changes in this pull request:

When tar exits with status greater than zero rear copies the last three
tar messages from backup.log to its own log. Those lines are also shown
to the user when rear is invoked with the "-v" option.

Some tar messages, however, are purely informational, e.g.

    tar: Removing leading `/' from member names
    tar: Removing leading `/' from hard link targets
    tar: /var/spool/postfix/private/discard: socket ignored

Strip the informational messages and show only actual errors, e.g.

    tar: /etc/grub.d/README: file changed as we read it

Fixes: issue #2465
Fixes: https://bugzilla.redhat.com/show_bug.cgi?id=1865697

Signed-off-by: Carlos Santos <casantos@redhat.com>

jsmeix commented at 2020-08-04 11:02:¶

@casantos
could it ever happen that tar exits with exit code 1
only because of things like

tar: /var/spool/postfix/private/discard: socket ignored

but without anything like

tar: /etc/grub.d/README: file changed as we read it

?

If yes I won't accept it to suppress messages that would explain to the user
that "tar exits with exit code 1" is actually false alarm.

For example
https://bugzilla.redhat.com/show_bug.cgi?id=1865697
shows (excerpts)

# rear -v mkbackup
...
WARNING: tar ended with return code 1 and below output:
  ---snip---
  tar: /var/spool/postfix/public/qmgr: socket ignored
  tar: /var/spool/postfix/public/flush: socket ignored
  tar: /var/spool/postfix/public/showq: socket ignored
  ----------
This means that files have been modified during the archiving
process. As a result the backup may not be completely consistent
or may not be a perfect copy of the system. Relax-and-Recover
will continue, however it is highly advisable to verify the
backup in order to be sure to safely recover this system.

The question is if "tar ended with return code 1" only because of

tar: /var/spool/postfix/public/qmgr: socket ignored
tar: /var/spool/postfix/public/flush: socket ignored
tar: /var/spool/postfix/public/showq: socket ignored

or if there was also an actual issue that is only visible in the backup log file.

jsmeix commented at 2020-08-04 11:11:¶

Perhaps the actual root cause is the | tail -n3 pipe
that suppresses useful information to be shown directly to the user.

What is also missing is an information where the backup log file is
that the user needs to inspect to see what actually happened.

jsmeix commented at 2020-08-04 11:16:¶

The tail -n3 pipe was added via
https://github.com/rear/rear/commit/46ee5cf592caaba5d2fb5e6555154cc32bd98f1b
but - as usual (sigh!) - without any explanation why.
Why exactly 3 lines and not e.g. the tail default of 10 lines?

casantos commented at 2020-08-04 12:01:¶

The tail -n3 pipe was added via
46ee5cf
but - as usual (sigh!) - without any explanation why.
Why exactly 3 lines and not e.g. the tail default of 10 lines?

Ten lines would still potentially hide the relevant output. In my test, for instance, the tar output is this:

tar: Removing leading `/' from member names
tar: /etc/grub.d/README: file changed as we read it
tar: Removing leading `/' from hard link targets
tar: /var/lib/gssproxy/default.sock: socket ignored
tar: /var/spool/postfix/private/discard: socket ignored
tar: /var/spool/postfix/private/local: socket ignored
tar: /var/spool/postfix/private/virtual: socket ignored
tar: /var/spool/postfix/private/anvil: socket ignored
tar: /var/spool/postfix/private/scache: socket ignored
tar: /var/spool/postfix/private/tlsmgr: socket ignored
tar: /var/spool/postfix/private/rewrite: socket ignored
tar: /var/spool/postfix/private/bounce: socket ignored
tar: /var/spool/postfix/private/defer: socket ignored
tar: /var/spool/postfix/private/trace: socket ignored
tar: /var/spool/postfix/private/verify: socket ignored
tar: /var/spool/postfix/private/proxymap: socket ignored
tar: /var/spool/postfix/private/proxywrite: socket ignored
tar: /var/spool/postfix/private/smtp: socket ignored
tar: /var/spool/postfix/private/relay: socket ignored
tar: /var/spool/postfix/private/error: socket ignored
tar: /var/spool/postfix/private/retry: socket ignored
tar: /var/spool/postfix/private/lmtp: socket ignored
tar: /var/spool/postfix/public/pickup: socket ignored
tar: /var/spool/postfix/public/cleanup: socket ignored
tar: /var/spool/postfix/public/qmgr: socket ignored
tar: /var/spool/postfix/public/flush: socket ignored
tar: /var/spool/postfix/public/showq: socket ignored

casantos commented at 2020-08-04 12:07:¶

@casantos
could it ever happen that tar exits with exit code 1
only because of things like
tar: /var/spool/postfix/private/discard: socket ignored

No. The "socket ignored" and "Removing leading `/' from..." messages are purely informational and tar exits with status if these are the only messages sent, e.g.

# tar -cf -  /var/spool/postfix/ > /dev/null
tar: Removing leading `/' from member names
tar: /var/spool/postfix/private/discard: socket ignored
tar: /var/spool/postfix/private/local: socket ignored
tar: /var/spool/postfix/private/virtual: socket ignored
tar: /var/spool/postfix/private/anvil: socket ignored
tar: /var/spool/postfix/private/scache: socket ignored
tar: /var/spool/postfix/private/tlsmgr: socket ignored
tar: /var/spool/postfix/private/rewrite: socket ignored
tar: /var/spool/postfix/private/bounce: socket ignored
tar: /var/spool/postfix/private/defer: socket ignored
tar: /var/spool/postfix/private/trace: socket ignored
tar: /var/spool/postfix/private/verify: socket ignored
tar: /var/spool/postfix/private/proxymap: socket ignored
tar: /var/spool/postfix/private/proxywrite: socket ignored
tar: /var/spool/postfix/private/smtp: socket ignored
tar: /var/spool/postfix/private/relay: socket ignored
tar: /var/spool/postfix/private/error: socket ignored
tar: /var/spool/postfix/private/retry: socket ignored
tar: /var/spool/postfix/private/lmtp: socket ignored
tar: /var/spool/postfix/public/pickup: socket ignored
tar: /var/spool/postfix/public/cleanup: socket ignored
tar: /var/spool/postfix/public/qmgr: socket ignored
tar: /var/spool/postfix/public/flush: socket ignored
tar: /var/spool/postfix/public/showq: socket ignored
# echo $?
0

jsmeix commented at 2020-08-04 13:38:¶

@casantos
thank you for https://github.com/rear/rear/pull/2466#issuecomment-668553552
and https://github.com/rear/rear/pull/2466#issuecomment-668556196

Now I see and understand.

I agree we need to filter out purely informational tar messages
to make those tar messages that show the reason for exit code 1
more easily visible for the user.

I am wondering if we should also omit the tail -n3 pipe
so that all tar messages that show reasons for exit code 1
are directly visible to the user.

Or at least show more than only three lines
and in this case tell the user that the output is truncated.

casantos commented at 2020-08-04 14:09:¶

@casantos
thank you for #2466 (comment)
and #2466 (comment)

Now I see and understand.

I agree we need to filter out purely informational tar messages
to make those tar messages that show the reason for exit code 1
more easily visible for the user.

I am wondering if we should also omit the tail -n3 pipe
so that all tar messages that show reasons for exit code 1
are directly visible to the user.

This is dangerous, since the output is captured in a shell string to be printed. A large number of errors can lead bash to crash.

Or at least show more than only three lines
and in this case tell the user that the output is truncated.

This seems to be a the most reasonable approach.

casantos commented at 2020-08-04 14:14:¶

I just noticed that the fix must be applied to the else branch of that if too. Updating the commit.

jsmeix commented at 2020-08-05 12:37:¶

https://github.com/rear/rear/pull/2466/files
shows that now also doc/rear.8 is changed which is unrelated.

Furthermore we have
https://github.com/rear/rear/issues/2265

Meanwhile I see what I did wrong via
https://github.com/rear/rear/commit/2674807f6ad48da80b193ae977d345ad2ef5fdd1
because I removed the BACKUP_PROG_CRYPT_OPTIONS="cat"
which breaks the exit code logic around pipes_rc=( ${PIPESTATUS[@]} )
because backup_prog_shortnames does no longer match.

So I need to fix that first by another pull request and by the way I will
also integrate what this pull requests intends to do.

casantos commented at 2020-08-05 13:01:¶

https://github.com/rear/rear/pull/2466/files
shows that now also doc/rear.8 is changed which is unrelated.

Furthermore we have
#2265

Meanwhile I see what I did wrong via
2674807
because I removed the BACKUP_PROG_CRYPT_OPTIONS="cat"
which breaks the exit code logic around pipes_rc=( ${PIPESTATUS[@]} )
because backup_prog_shortnames does no longer match.

So I need to fix that first by another pull request and by the way I will
also integrate what this pull requests intends to do.

Don't worry, I already have a fix for this too.

jsmeix commented at 2020-08-05 14:09:¶

Ouch!
No rush please.

I did not notice your
https://github.com/rear/rear/pull/2466#issuecomment-669179634
because I was working on
https://github.com/rear/rear/pull/2472

Now we have conflicting pull requests that try to implement the same
which is unfortunate because it means needlessly work was done twice.

casantos commented at 2020-08-06 11:35:¶

@casantos
I could merge it if you removed the unrelated change
of doc/rear.8 from this pull request, cf. the first part in
#2466 (comment)

Done.

jsmeix commented at 2020-08-06 11:41:¶

@rear/contributors
I would like to merge it tomorrow morning provided there are no objections
regardless of the minor left issue https://github.com/rear/rear/pull/2466/files#r466347471
which we can improve later if we find a reasonable way how to solve that dilemma.

jsmeix commented at 2020-08-06 14:01:¶

Via https://github.com/rear/rear/pull/2466/commits/3eb5dec3240115f1e207ff5f0240f14c2027a835
I added an explanatory comment in the code,
cf. https://github.com/rear/rear/pull/2466#discussion_r464971854
and have the user informed that only the "last 5 lines" are shown
cf. https://github.com/rear/rear/pull/2466#issuecomment-668602013

jsmeix commented at 2020-08-07 10:53:¶

@casantos
thank you for your enhancement!

[Export of Github issue for rear/rear.]

#2466 PR merged: 500_make_backup.sh: filter informational tar messages from output¶