#1877 PR merged: Show last programs messages in Error function (related to issue1875)

Labels: enhancement, fixed / solved / done

jsmeix opened issue at 2018-07-23 15:31:

Now the Error function shows the last 5 lines of stdout and stderr messages
of the called programs on the user's terminal that should hopefully
make the root cause of an error exit more obvious to the user
without the need to analyze the log file in any case.

Additionally I adapted output/default/200_make_prefix_dir.sh
to provide a better Error function text that now talks about
Failed to create ... directory under the mounted network filesystem share.

How it looks on my SLES12 test system when I reproduce it as in
https://github.com/rear/rear/issues/1875#issuecomment-406987662

Could not mkdir '/tmp/rear.SKQq4qAbCh3GIg4/outputfs/f144'
ERROR: Failed to create 'f144' directory under the mounted network filesystem share
Log messages of latest run programs (most significant ones at the bottom):
  mount.nfs: trying text-based options 'nfsvers=3,nolock,addr=10.160.4.244'
  mount.nfs: prog 100003, trying vers=3, prot=6
  mount.nfs: prog 100005, trying vers=3, prot=17
  mkdir: created directory '/tmp/rear.SKQq4qAbCh3GIg4/tmp/boot'
  mkdir: cannot create directory '/tmp/rear.SKQq4qAbCh3GIg4/outputfs/f144': Permission denied
Aborting due to an error, check /root/rear.github.master/var/log/rear/rear-f144.log for details
Exiting rear mkrescue (PID 21235) and its descendant processes

jsmeix commented at 2018-07-24 08:45:

As always sleeping over it improved things.

With my recent commit
https://github.com/rear/rear/pull/1877/commits/32525a172ec580cdeed09ce5e7c4221e2c31ab68
I canged what log messages are show
from only the normal stdout and stderr messages of the last called programs
to all latest log messages (including stdout and stderr of the called programs)
but only from the last called script (except 'set -x' low-level debug lines).

Reason:
I assume that for the user it is more helpful to see
the latest log plus stdout and stderr messages
but those only from the last called script
compared to see only stdout and stderr messages
but also from previous scripts
because I think messages from previous scripts
may cause more confusion than help.

How it looks now on my SLES12 test system when I reproduce it as in
https://github.com/rear/rear/issues/1875#issuecomment-406987662

# usr/sbin/rear -v mkrescue
...
ERROR: Failed to create 'f144' directory under the mounted network filesystem share
Some latest log messages from the last called script 200_make_prefix_dir.sh:
  2018-07-24 10:21:53.338473069 Including output/default/200_make_prefix_dir.sh
  mkdir: cannot create directory '/tmp/rear.Fq7nrzQfe1XCa5k/outputfs/f144': Permission denied
Aborting due to an error, check /root/rear.github.master/var/log/rear/rear-f144.log for details
Exiting rear mkrescue (PID 15436) and its descendant processes

jsmeix commented at 2018-07-24 09:23:

Things can look bad in debugscripts mode (e.g. rear -D mkrescue)
when it aborts with BugError (then it greps useless lines from the log)
I like to fix that...

jsmeix commented at 2018-07-24 09:58:

With my latest commit
https://github.com/rear/rear/pull/1877/commits/111bb691ff19bf2cf54c9aada71e488ee2b853d9
things look o.k. even in case of BugError function i.e. when the Error function is called
multi line messages and debugscripts mode is used.

To simulate BugError I changed in output/default/200_make_prefix_dir.sh

Error "Failed to create ...

to

BugError "Failed to create ...

and now things look for me in debugscripts mode

# usr/sbin/rear -D mkrescue
...
ERROR: 
====================
BUG in /root/rear.github.master/usr/share/rear/output/default/200_make_prefix_dir.sh line 21:
'Failed to create 'f144' directory under the mounted network filesystem share'
--------------------
Please report this issue at https://github.com/rear/rear/issues
and include the relevant parts from /root/rear.github.master/var/log/rear/rear-f144.log
preferably with full debug information via 'rear -d -D mkrescue'
====================
Some latest log messages from the last called script 200_make_prefix_dir.sh:
  2018-07-24 11:45:33.831619017 Including output/default/200_make_prefix_dir.sh
  2018-07-24 11:45:33.832337303 Entering debugscripts mode via 'set -x'.
  mkdir: cannot create directory '/tmp/rear.tfltIJJxkoVkovD/outputfs/f144': Permission denied
  2018-07-24 11:45:33.842322685 Aborting ReaR with 'BugError'
Aborting due to an error, check /root/rear.github.master/var/log/rear/rear-f144.log for details
Exiting rear mkrescue (PID 3114) and its descendant processes

versus the same but only in verbose mode

# usr/sbin/rear -v mkrescue
...
ERROR: 
====================
BUG in /root/rear.github.master/usr/share/rear/output/default/200_make_prefix_dir.sh line 21:
'Failed to create 'f144' directory under the mounted network filesystem share'
--------------------
Please report this issue at https://github.com/rear/rear/issues
and include the relevant parts from /root/rear.github.master/var/log/rear/rear-f144.log
preferably with full debug information via 'rear -d -D mkrescue'
====================
Some latest log messages from the last called script 200_make_prefix_dir.sh:
  2018-07-24 11:53:30.802518432 Including output/default/200_make_prefix_dir.sh
  mkdir: cannot create directory '/tmp/rear.RC3tVKoTWEZrYUo/outputfs/f144': Permission denied
  2018-07-24 11:53:30.808719247 Aborting ReaR with 'BugError'
Aborting due to an error, check /root/rear.github.master/var/log/rear/rear-f144.log for details
Exiting rear mkrescue (PID 17520) and its descendant processes

For comparison how it looks with the normal Error function
in debugscripts mode

# usr/sbin/rear -D mkrescue

ERROR: Failed to create 'f144' directory under the mounted network filesystem share
Some latest log messages from the last called script 200_make_prefix_dir.sh:
  2018-07-24 11:55:24.880196127 Including output/default/200_make_prefix_dir.sh
  2018-07-24 11:55:24.880900120 Entering debugscripts mode via 'set -x'.
  mkdir: cannot create directory '/tmp/rear.7Y43tAf2vYYRpC5/outputfs/f144': Permission denied
  2018-07-24 11:55:24.890792247 Aborting ReaR ...
Aborting due to an error, check /root/rear.github.master/var/log/rear/rear-f144.log for details
Exiting rear mkrescue (PID 10529) and its descendant processes

versus in verbose mode

# usr/sbin/rear -v mkrescue
...
ERROR: Failed to create 'f144' directory under the mounted network filesystem share
Some latest log messages from the last called script 200_make_prefix_dir.sh:
  2018-07-24 11:55:02.128570054 Including output/default/200_make_prefix_dir.sh
  mkdir: cannot create directory '/tmp/rear.MiPGSPlP7eVdqZG/outputfs/f144': Permission denied
  2018-07-24 11:55:02.134746653 Aborting ReaR ...
Aborting due to an error, check /root/rear.github.master/var/log/rear/rear-f144.log for details
Exiting rear mkrescue (PID 30216) and its descendant processes

jsmeix commented at 2018-07-24 10:00:

@rear/contributors
now things look o.k. to me
so that I would like to merge it soon
if there are no objections.

As far as I see there cannot be real regressions because
it should be all only about what messages are shown.

jsmeix commented at 2018-07-24 13:30:

It still does not work as expected when the Error function
is called with a multi line error message like

Error "Failed to
create '$OUTPUT_PREFIX' directory
under the mounted
network filesystem share"

I think I have already a fix which is even simpler than before...

jsmeix commented at 2018-07-24 13:55:

Now also when the Error function is called with a multi line error message like

Error "Failed to
create '$OUTPUT_PREFIX' directory
under the mounted
network filesystem share"

things really look o.k. to me (excerpts):

# usr/sbin/rear -D mkrescue
...
ERROR: Failed to
create 'f144' directory
under the mounted
network filesystem share
Some latest log messages from the last called script 200_make_prefix_dir.sh:
  2018-07-24 15:30:51.010132470 Including output/default/200_make_prefix_dir.sh
  2018-07-24 15:30:51.010883541 Entering debugscripts mode via 'set -x'.
  mkdir: cannot create directory '/tmp/rear.S1FLxksxiNyjV17/outputfs/f144': Permission denied
Aborting due to an error, check /root/rear.github.master/var/log/rear/rear-f144.log for details
Exiting rear mkrescue (PID 12483) and its descendant processes

and normally

# usr/sbin/rear mkrescue
...
ERROR: Failed to
create 'f144' directory
under the mounted
network filesystem share
Some latest log messages from the last called script 200_make_prefix_dir.sh:
  2018-07-24 15:31:38.065558308 Including output/default/200_make_prefix_dir.sh
  mkdir: cannot create directory '/tmp/rear.UagwIJeXk6aRQYa/outputfs/f144': Permission denied
Aborting due to an error, check /root/rear.github.master/var/log/rear/rear-f144.log for details

and when the BugError function is called with a multi line error message like

BugError "Failed to
create '$OUTPUT_PREFIX' directory
under the mounted
network filesystem share"

in debugscripts mode

# usr/sbin/rear -D mkrescue
...
ERROR: 
====================
BUG in /root/rear.github.master/usr/share/rear/output/default/200_make_prefix_dir.sh line 24:
'Failed to
create 'f144' directory
under the mounted
network filesystem share'
--------------------
Please report this issue at https://github.com/rear/rear/issues
and include the relevant parts from /root/rear.github.master/var/log/rear/rear-f144.log
preferably with full debug information via 'rear -d -D mkrescue'
====================
Some latest log messages from the last called script 200_make_prefix_dir.sh:
  2018-07-24 15:46:37.805607004 Including output/default/200_make_prefix_dir.sh
  2018-07-24 15:46:37.806297048 Entering debugscripts mode via 'set -x'.
  mkdir: cannot create directory '/tmp/rear.cCGS59mJ19jHjqw/outputfs/f144': Permission denied
Aborting due to an error, check /root/rear.github.master/var/log/rear/rear-f144.log for details
Exiting rear mkrescue (PID 1670) and its descendant processes

and normally

# usr/sbin/rear mkrescue
...
ERROR: 
====================
BUG in /root/rear.github.master/usr/share/rear/output/default/200_make_prefix_dir.sh line 24:
'Failed to
create 'f144' directory
under the mounted
network filesystem share'
--------------------
Please report this issue at https://github.com/rear/rear/issues
and include the relevant parts from /root/rear.github.master/var/log/rear/rear-f144.log
preferably with full debug information via 'rear -d -D mkrescue'
====================
Some latest log messages from the last called script 200_make_prefix_dir.sh:
  2018-07-24 15:47:22.591618565 Including output/default/200_make_prefix_dir.sh
  mkdir: cannot create directory '/tmp/rear.muztRiXoBDhGYUn/outputfs/f144': Permission denied
Aborting due to an error, check /root/rear.github.master/var/log/rear/rear-f144.log for details

jsmeix commented at 2018-07-24 13:59:

I will sleep over it and
if there are no objections
I would merge it tomorrow.

jsmeix commented at 2018-07-25 10:19:

As always sleeping over it one more time improved things one more time.

Still not working as good as I like it because sometimes Error or BugError
is not called in an actual script but in a lib/whatever-functions.sh
and then the current implementation shows whatever-functions.sh
but I like to show the actually last sourced script to the user
because I think the latter is much more helpful for the user.

I think I have already a fix which is not simpler but more straightforward than before...

jsmeix commented at 2018-07-25 10:47:

By the way I also simplified all 'rear -d -D ...' to 'rear -D ...'
because since https://github.com/rear/rear/pull/1577
the 'debugscript mode' ( '-D' ) automatically also sets 'debug mode' ( '-d' )
and 'verbose mode' ( '-v' ).

jsmeix commented at 2018-07-25 10:57:

How an Error from the mount_url function in lib/global-functions.sh looks now:

# usr/sbin/rear -D mkrescue
...
ERROR: Mount command 'mount -v -o nfsvers=3,nolock /dev/disk/by-label/REAR-000 /tmp/rear.GWJdRzPCWRMr5QM/outputfs' failed.
Some latest log messages since the last called script 060_mount_NETFS_path.sh:
  mkdir: created directory '/tmp/rear.GWJdRzPCWRMr5QM/outputfs'
  2018-07-25 12:53:23.956582779 Added 'rmdir -v /tmp/rear.GWJdRzPCWRMr5QM/outputfs >&2' as an exit task
  2018-07-25 12:53:23.959343177 Mounting with 'mount -v -o nfsvers=3,nolock /dev/disk/by-label/REAR-000 /tmp/rear.GWJdRzPCWRMr5QM/outputfs'
  mount: wrong fs type, bad option, bad superblock on /dev/sdc1,
         missing codepage or helper program, or other error

         In some cases useful info is found in syslog - try
         dmesg | tail or so.
Aborting due to an error, check /root/rear.github.master/var/log/rear/rear-f144.log for details

FYI:
The reason for this error was wrong BACKUP_OPTIONS in local.conf:

OUTPUT=USB
USB_DEVICE=/dev/disk/by-label/REAR-000
BACKUP_URL=usb:///dev/disk/by-label/REAR-000
USB_SUFFIX="mybackups"
BACKUP=NETFS
BACKUP_OPTIONS="nfsvers=3,nolock"

jsmeix commented at 2018-07-26 09:51:

Sleeping over it the third time did not produce further improvement ideas
so that I will merge it soon today - unless there are objections.

[Export of Github issue for rear/rear.]