null¶

Labels: enhancement, cleanup, fixed / solved / done

jsmeix opened issue at 2020-06-03 08:29:¶

Currently stdout and stderr are redirected to the log file in any case.

The reason behind is that all what could be useful for later debugging
in case of issues must appear in ReaR's log file, cf.
"What to do with stdin, stdout, and stderr" in
https://github.com/rear/rear/wiki/Coding-Style

But this means that also error messages from commands
that fail when a possible failure is expected and handled in ReaR
appear in the log file.

I.e. for code of the general form like

TRY_COMMAND || FALLBACK_COMMAND || Error "..."

a failing TRY_COMMAND error message appears in the log file
which may confuse the user regardless that all works well
because it is only a "false alarm" message.

On the other hand the TRY_COMMAND error message must appear
in the log file because for later debugging in case of issues it is needed
to see how TRY_COMMAND had failed i.e. what its exact error message was
because it makes a difference to understand the root cause of an issue
if the TRY_COMMAND error message shows that its failure is OK
(and FALLBACK_COMMAND does "the right thing")
or if the TRY_COMMAND error message points to the root cause of an issue
(e.g. because TRY_COMMAND should have worked in a particular case
and FALLBACK_COMMAND should not have been run in that case).

So there is a dilemma between suppressing error messages
to not confuse the user with "false alarm" error messages
versus having all what could be useful for later debugging in the log file.

Perhaps a possible way out of that dilemma could be
to only redirect stdout and stderr to the log file
when rear is run in verbose mode (-v) or in debug modes (-d -D)
to avoid that such messages appear in the log and confuse the user
when the user has called rear in a "normal operation" mode and
in "normal operation" mode stdout and stderr are redirected to /dev/null.

Perhaps the best way might be:

In "normal operation" mode stdout and stderr are redirected to /dev/null.
In verbose mode stderr is still /dev/null but stdout is redirected to the log.
In debug modes stdout and stderr are redirected to the log.

It seems this would be in compliance with our $v $verbose usage

# touch foo

# cp -v foo foo.cp 2>/dev/null
'foo' -> 'foo.cp'

# mv -v foo.cp foo.mv 2>/dev/null
renamed 'foo.cp' -> 'foo.mv'

because it seems command verbose output happens usually on stdout.

I do no longer think that my above described "best way" works OK in practice, see
https://github.com/rear/rear/issues/2416#issuecomment-702142588

github-actions commented at 2020-08-03 01:34:¶

Stale issue message

jsmeix commented at 2020-09-30 13:22:¶

I will do a pull request right now:

jsmeix commented at 2020-10-01 13:40:¶

With the current changes in
https://github.com/rear/rear/pull/2498
i.e. with
https://github.com/rear/rear/pull/2498/commits/0f63d43236a0b28e020f5cb6cd2ff933438a481b
I do no longer think that our our $v $verbose usage is helpful for the user.

I think we should set the $v and $verbose variables in debug modes
but not in verbose mode.

Perhaps we may even set the $v and $verbose variables only in debugscript -D mode
because additional command verbose messages are mostly useless without context
in particular without the info what exact command was called
and that info is only provided in debugscript mode.

Reasoning:

Calling ReaR in verbose mode should make only ReaR itself verbose
in particular to show ReaR messages on the user's termial
but it should not also transitively make things that are called by ReaR verbose
because I think when the user likes to get such internal details of information
then the user is more in debugging state (i.e. looking for the cause of an issue).

Explanation:

Currently we do in usr/sbin/rear

# Set the variables v and verbose to be used in called programs
# that support the '-v' or '--verbose' options like
# "cp $v ..." or "rm $verbose ..." and so on:
v=""
verbose=""
if test "$VERBOSE" ; then
    v="-v"
    verbose="--verbose"
fi

so that in verbose mode many commands are run with verbose output
as described in "man rear"
https://github.com/rear/rear/blob/master/doc/rear.8.adoc

-v
    verbose mode (show more output and run many commands in verbose mode)

But from my point of view the commands verbose output in the log
is mainly confusing and does not actually help the user at all.

For example what additional commands verbose output I get in my log
during "rear -v recover" compared to "rear recover"
(excerpts from a diff output with long lines cut after 150 characters):

 Saving filesystem layout (using the findmnt command).
+- Docker Application Container Engine
+ Loaded: loaded (/usr/lib/systemd/system/docker.service; disabled; vendor preset: disabled)
+ Active: inactive (dead)
+   Docs: http://docs.docker.com
 Processing filesystem 'ext4' on '/dev/mapper/cr_ata-TOSHIBA_MQ01ABF050_Y2PLP02CT-part3' mounted at '/'
...
 Verifying that the 'disk' entries in /root/rear.github.master/var/lib/rear/layout/disklayout.conf are correct
+500107862016
 Verifying that the 'part' entries for /dev/sda in /root/rear.github.master/var/lib/rear/layout/disklayout.conf are correct
+8388608
+1048576
+4294967296
+9437184
+214748364800
+4304404480
+107374182400
+219052769280
+161061273600
+326426951680
+8589934592
+487488225280
+1073741824
+496078159872
+1073741824
+497151901696
 Verifying that the 'part' entries for /dev/sda in /root/rear.github.master/var/lib/rear/layout/disklayout.conf specify consecutive partitions
...
 Adding required libfreeblpriv3.so to LIBS
+directory '/tmp/rear.ocKP41xM43hJugw/rootfs//var/lib/sshd'
+'/tmp/rear.ocKP41xM43hJugw/rootfs//var/lib/sshd' changed from 0755 (rwxr-xr-x) to 0700 (rwx------)
 Including rescue/GNU/Linux/550_copy_ldconfig.sh
...
 Copying ReaR configuration directory
+'/tmp/rear.ocKP41xM43hJugw/rootfs/etc/rear/./local.conf'
+'/tmp/rear.ocKP41xM43hJugw/rootfs/etc/rear/./os.conf'
 Including build/GNU/Linux/110_touch_empty_files.sh
 Including build/GNU/Linux/130_create_dotfiles.sh
+'/tmp/rear.ocKP41xM43hJugw/rootfs//root/.bash_history' retained as 0644 (rw-r--r--)
 Including build/GNU/Linux/150_adjust_permissions.sh
...
 Including build/default/490_fix_broken_links.sh
+
+'./usr/lib/os-release'
+directory './usr/share/zoneinfo'
+directory './usr/share/zoneinfo/Europe'
+'./usr/share/zoneinfo/Europe/Berlin'
+'./usr/share/misc/termcap'
+~/rear.github.master
 Including build/default/500_ssh_setup.sh
 Including build/default/501_check_ssh_keys.sh
+
+~/rear.github.master
 Including build/default/502_include_mdadm_conf.sh
...
 Including build/GNU/Linux/630_verify_resolv_conf_file.sh
+'/tmp/rear.ocKP41xM43hJugw/rootfs/etc/resolv.conf'
 Supposedly valid nameserver 'fd00::7eff:4dff:fe5d:42b1' in /tmp/rear.ocKP41xM43hJugw/rootfs/etc/resolv.conf
...
 Testing that each program in the PROGS array can be found as executable command within the recovery system
+/usr/sbin/partprobe
+/sbin/partprobe
+/sbin/fdisk
...
+hashed (/usr/bin/rmdir)
...
+a shell builtin
...
+/usr/lib/ssh/sftp-server
+/sbin/sftp-server
 Testing that each program in the REQUIRED_PROGS array can be found as executable command within the recovery system
+/sbin/rear
+/sbin/awk
...
+a shell builtin
...
+/sbin/dmsetup
+/sbin/ldconfig
 Including build/default/995_md5sums_rootfs.sh
...
 Copying resulting files to file location
+'/tmp/rear.ocKP41xM43hJugw/tmp/README'
 Saving /root/rear.github.master/var/log/rear/rear-linux-h9wr.log as rear-linux-h9wr.log to file location
/tmp/VERSION /tmp/rear.0qMwd9fdzyhPbY
 Copying result files '/root/rear.github.master/var/lib/rear/output/rear-linux-h9wr.iso /tmp/rear.ocKP41xM43hJugw/tmp/VERSION /tmp/rear.ocKP41xM43hJug
+'/other/linux-h9wr/rear-linux-h9wr.iso'
+'/other/linux-h9wr/VERSION'
+'/other/linux-h9wr/README'
+'/other/linux-h9wr/rear-linux-h9wr.log'
 Including output/default/950_email_result_files.sh

All those + lines are completely useless from my point of view.
At least I do not understand anything what those additional command verbose messages mean
without context (in particular without the info what exact command was called).

jsmeix commented at 2020-10-01 14:05:¶

All the time since I had written in
https://github.com/rear/rear/issues/2416#issue-629800799

In verbose mode stderr is still /dev/null but stdout is redirected to the log.

I had some bad feeling to handle stderr and stdout differently.

Now I know it is a bad idea to handle stderr and stdout differently.

Most of the useless + lines in the log file excerpts in the above
https://github.com/rear/rear/issues/2416#issuecomment-702142588
are not because of additionally requested command verbose messages
but just normal command stdout messages that appear in the log
when in verbose mode stdout is redirected to the log.

E.g. the above

+- Docker Application Container Engine
+ Loaded: loaded (/usr/lib/systemd/system/docker.service; disabled; vendor preset: disabled)
+ Active: inactive (dead)
+   Docs: http://docs.docker.com

comes from layout/save/GNU/Linux/230_filesystem_layout.sh

if service docker status ; then

and for debugging purposes the service docker status message
must be in the log so that one could see at any time later whether or not
there have been issues with the service docker status command
at the time when ReaR was running (e.g. late at night), cf.
"What to do with stdin, stdout, and stderr" in
https://github.com/rear/rear/wiki/Coding-Style

jsmeix commented at 2020-10-06 13:22:¶

With https://github.com/rear/rear/pull/2498 merged this issue should be done.

OliverO2 commented at 2020-12-11 19:37:¶

As described in https://github.com/rear/rear/pull/2538#issuecomment-743365322, I had an issue with dd failing due to a missing input file.

Before considering the effects of #2498, my code would look like this:

dd if="$boot_partition" bs=1024 of="$install_partition" || Error "Could not copy the EFI rescue system to partition '$install_partition'"

producing output like this:

ERROR: Could not copy the EFI rescue system to partition '/dev/sda2'
Some latest log messages since the last called script 280_create_bootable_disk_image.sh:
  [...]
  2020-12-11 18:37:31.509370807 Installing the EFI rescue system to partition '/dev/sda2'

There is no detailed information about the cause of the problem.

Now I have changed it to:

dd if="$boot_partition" bs=1024 of="$install_partition" 2>>"$RUNTIME_LOGFILE" || Error "Could not copy the EFI rescue system to partition '$install_partition'"

which produces this output:

ERROR: Could not copy the EFI rescue system to partition '/dev/sda2'
Some latest log messages since the last called script 280_create_bootable_disk_image.sh:
  [...]
  2020-12-11 18:37:31.509370807 Installing the EFI rescue system to partition '/dev/sda2'
  dd: failed to open '/dev/loop6p1': No such file or directory

Now there is detailed information about the cause of the problem without requiring the user to enable debugscript mode.

So what is the better solution?

Leave everything as is, suppressing stderr messages giving details about the cause of an underlying error, requiring another invocation with -D (if the problem reproduces).
Change code like above to use 2>>"$RUNTIME_LOGFILE" redirections before error checks (|| Error "...").
Redirect stderr to the log file again at all times and use 2>>/dev/$DISPENSABLE_OUTPUT_DEV in places expected to produce (lots of) stderr output under normal circumstances (false positives).

My considerations:

I appreciate the effort to reduce unnecessary messages in the ReaR log, in particular lots of 'false positives'.
In case of real errors, I would like to have as much detail as possible instantly (not in a second invocation).
I am always a bit wary of posting large logs like those produced in debugscript mode, as I find it hard to screen them for sensitive information, which I would not like to leak.

jsmeix commented at 2021-06-07 13:53:¶

@OliverO2
Wow!
What a great analysis - as usual from you - much appreciated!

I prefer very much using

COMMAND ... 2>>"$RUNTIME_LOGFILE" || Error "..."

at specific places where we (i.e. the ReaR developers) know
(to some extent as far as possible with reasonable effort for us)
that this particular COMMAND call only outputs on stderr
when there is a real error so that ReaR exits with Error.

jsmeix commented at 2021-06-07 14:02:¶

@OliverO2
I think -D debugscript mode can easily leak sensitive information into the log file
in this or that special circumstaces so I would not use -D in environments
where ReaR's log file is not sufficiently safe.
But I think normal debug mode -d should be very much safer
against leaking sensitive information into the log file
but normal debug mode cannot be 100% safe because
we cannot know what arbitrary programs may output
on stdout or stderr under this or that special circumstances cf.
https://github.com/rear/rear/issues/2416#issuecomment-702159687
in particular when programs are called in verbose mode, cf.
https://github.com/rear/rear/issues/2416#issuecomment-702142588

jsmeix commented at 2021-06-07 14:07:¶

Hmmm - after reading again my
https://github.com/rear/rear/issues/2416#issuecomment-855956701
I even think now that
"Redirect stdout and stderr to the log only in debug modes - normally discard them to /dev/null"
(in particular with calling programs in verbose mode also only in debug modes)
is also a security feature because it avoids that whatever unexpected program output
may leak sensitive information into the log file - probably no secrets like passwords
but "internal" information that could be misused by someone who should not know that.

pcahyna commented at 2021-06-07 15:26:¶

(...) security feature because it avoids that whatever unexpected program output
may leak sensitive information into the log file

Is the log file world-readable? Apparently it is, but probably it should not be. (Files under /etc/rear are not.)

[Export of Github issue for rear/rear.]

#2416 Issue closed: Redirect stdout and stderr to the log only in debug modes - normally discard them to /dev/null¶