Suppressing stderr by default decreases usability

[OliverO2]

I am aware of #2416. It just does not work for me.

Use Case

I invoke rear mkrescue without options. An unexpected problem occurs. I cannot see what went wrong precisely, because relevant error messages are missing in the log file.

Edit: As @pcahyna has correctly pointed out, this does not apply to rear recover which runs in verbose mode by default.

Suggestion

Please do not suppress stderr globally. The extra output in the log file seems way more acceptable than seeing a clean log file when actually something bad had happened.

The only workaround right now would be to always invoke rear with verbose or debug options. This seems like overkill as in most case just the normal stderr would give a reasonable indication what the problem might have been. Also, increased verbosity makes ReaR harder to use as more lines appear on the terminal, burying possible important messages.

When there are spots which routinely pollute the log file with expected output looking like errors, such spots could be cleaned up individually.

[pcahyna]

I invoke rear recover without options. (...) The only workaround right now would be to always invoke rear with verbose or debug options.

Note that rear recover is verbose by default.

[OliverO2]

@pcahyna You are right. This does not apply to rear recover. I have corrected the issue description accordingly.

Seems like I was trained by repeated invocations of rear mkrescue with missing log information that I did not even look into the log file of rear recover as I was not expecting it to contain anything useful.

[OliverO2]

A practical example. This example is a bit primitive, because in this case ReaR directly uses an Error statement. When we are not that lucky, the error case would not be checked by ReaR at all, but would surface sometime later when a follow-up error occurs.

1. With stderr completely suppressed, as is now the case, it looks like this:

   $ sudo usr/sbin/rear mkrescue
   ERROR: Mount command 'sshfs maintenance@backup-hub.example.com:/nonexistent /tmp/rear.jIL8Nfe59j0uBjo/outputfs -o rw,noatime' failed.
   Some latest log messages since the last called script 100_mount_output_path.sh:
   2021-06-03 22:28:12.395891117 Including output/default/100_mount_output_path.sh
   2021-06-03 22:28:12.406362038 Mounting with 'sshfs maintenance@backup-hub.example.com:/nonexistent /tmp/rear.jIL8Nfe59j0uBjo/outputfs -o rw,noatime'
   Aborting due to an error, check /home/oliver/Repositories/open-source/rear/var/log/rear/rear-juliet.log for details
   Terminated
   

   • So a Mount command ... failed. Why that? User not existing? Host name misspelled? Permission denied? Something else?

   • The last action logged was Mounting with..., then afterwards (we do not know whether immediately or several statements later) "an error" occurred.

   • ReaR tells me to check the log file for details, but there is no further information than what is shown above, followed by Exiting rear mkrescue....

2. With stderr going to the log file, it looks like this:

   $ sudo usr/sbin/rear mkrescue
   ERROR: Mount command 'sshfs maintenance@backup-hub.example.com:/nonexistent /tmp/rear.IeoteOoHosexvDi/outputfs -o rw,noatime' failed.
   Some latest log messages since the last called script 100_mount_output_path.sh:
   2021-06-03 22:26:07.247867501 Including output/default/100_mount_output_path.sh
   2021-06-03 22:26:07.258859399 Mounting with 'sshfs maintenance@backup-hub.example.com:/nonexistent /tmp/rear.IeoteOoHosexvDi/outputfs -o rw,noatime'
   maintenance@backup-hub.example.com:/nonexistent: No such file or directory
   Aborting due to an error, check /home/oliver/Repositories/open-source/rear/var/log/rear/rear-juliet.log for details
   Terminated
   

   • This immediately shows the root cause of the problem:

     maintenance@backup-hub.example.com:/nonexistent: No such file or directory
     

   • The log file contains the above information (including the root cause), plus a stack trace, showing the line numbers of all statements which were executed at the time, followed by Exiting rear mkrescue....

[jsmeix]

Only a quick initial note:

I implemented
#2498
intentionally as I did it because of
#2473
therein in particular because of how users experienced it as in
#2473 (comment)

I do not want to spend any more minute of my precious time with
possible further issue reports where users who call rear or rear -v
misunderstand some message from some program as an error of ReaR.

Since #2498
we (i.e. the ReaR developers) control what users see up to rear -v.

Since #2498
the user must explicitly request to also get "low level 'debug' messages"
and then he is hopefully experienced enough to not misunderstand
arbitrary messages from programs (where we have no control what
a particular program may show under what specific curcumstances)
as an error of ReaR.

Personally I always use rear -D because I need that during development.

I think users who are interested what goes on "behind ReaR's surface"
must use at least rear -d.

@OliverO2
is there a reason why you can't use rear -d?

Should it perhaps be better documented that
since #2498
what goes on "behind ReaR's surface" is intentionally hidden
to make the content in the log less confusing for users
unless 'debug' messaging was explicitly requested?

[OliverO2]

1. I understand that you don't want to answer repeated enquiries about stderr messages which are just part of ReaR's normal operation. The underlying problem should definitely be fixed.

2. Globally suppressing errors is considered an unsafe development practice. This is based on a long history of failures. If we'd go down that route, we will experience missing substantial error messages over and over again, on the console and in log files. It is impossible to foresee all conditions which might result in an important error. I/O errors and out-of-memory errors, for example, can occur at any time.

3. I generally invoke rear mkrescue without any options as I need to focus on the task. What's the task?

   • The task is getting a reliable rescue medium.
   • The task is not to learn about ReaR's internal operations.
   • The task is not to debug ReaR.

   So on the console and in the log file, I want substantial information only, not more, not less. Each additional (unimportant) line of output distracts me, wastes my time and risks that I overlook something important.

   Now look what happens:

   • rear mkrescue already outputs three lines, none of which is important for me, but I can live with that:

     Ignoring non-existing btrfs subvolume listed as mounted: /var/lib/docker/btrfs
     Symlink '/lib/modules/5.8.0-55-generic/build' -> '/usr/src/linux-headers-5.8.0-55-generic' refers to a non-existing directory on the recovery system.
     It will not be copied by default. You can include '/usr/src/linux-headers-5.8.0-55-generic' via the 'COPY_AS_IS' configuration variable.
     

   • rear -d mkrescue outputs 112 lines, all about ReaR's internal considerations, none of which is important for me. This puts an unnecessary cognitive load on me ("What if I miss some important information in between?") and distracts me from my task. As a user, I feel disrespected when I have to bear this:

     Relax-and-Recover 2.6 / Git
     Running rear mkrescue (PID 36709 date 2021-06-07 16:49:44)
     Using log file: /home/oliver/Repositories/open-source/rear/var/log/rear/rear-juliet.log
     Running workflow mkrescue on the normal/original system
     Found EFI system partition /dev/sda1 on /boot/efi type vfat
     Using UEFI Boot Loader for Linux (USING_UEFI_BOOTLOADER=1)
     Using local PBA image file '/home/oliver/Repositories/open-source/rear/var/lib/rear/TCG-Opal-PBA/juliet/TCG-Opal-PBA-juliet.raw'
     Using autodetected kernel '/boot/vmlinuz-5.8.0-55-generic' as kernel in the recovery system
     Creating disk layout
     Overwriting existing disk layout file /home/oliver/Repositories/open-source/rear/var/lib/rear/layout/disklayout.conf
     Docker is running, skipping filesystems mounted below Docker Root Dir /var/lib/docker
     Ignoring non-existing btrfs subvolume listed as mounted: /var/lib/docker/btrfs
     Disabling excluded components in /home/oliver/Repositories/open-source/rear/var/lib/rear/layout/disklayout.conf
     Using guessed bootloader 'EFI' (found in first bytes on /dev/sda)
     Verifying that the entries in /home/oliver/Repositories/open-source/rear/var/lib/rear/layout/disklayout.conf are correct
     Created disk layout (check the results in /home/oliver/Repositories/open-source/rear/var/lib/rear/layout/disklayout.conf)
     Creating recovery system root filesystem skeleton layout
     Skipping 'br-14542ceec047': not bound to any physical interface.
     Skipping 'br-fb9c38f9ba2f': not bound to any physical interface.
     Handling network interface 'bridge0'
     bridge0 is a bridge
     bridge0 has lower interface eno1
     eno1 is a physical device
     Handled network interface 'bridge0'
     Skipping 'docker0': not bound to any physical interface.
     Skipping 'virbr0': not bound to any physical interface.
     Included current keyboard mapping (via 'dumpkeys -f')
     No default US keyboard mapping included (no KEYMAPS_DEFAULT_DIRECTORY specified)
     No support for different keyboard layouts (neither KEYMAPS_DEFAULT_DIRECTORY nor KEYMAPS_DIRECTORIES specified)
     Trying to find what to use as UEFI bootloader...
     Trying to find a 'well known file' to be used as UEFI bootloader...
     Using '/boot/efi/EFI/ubuntu/grubx64.efi' as UEFI bootloader file
     Copying logfile /home/oliver/Repositories/open-source/rear/var/log/rear/rear-juliet.log into initramfs as '/tmp/rear-juliet-partial-2021-06-07T16:49:57+02:00.log'
     Copying files and directories
     Copying binaries and libraries
     Copying all kernel modules in /lib/modules/5.8.0-55-generic (MODULES contains 'all_modules')
     Copying all files in /lib*/firmware/
     Skip copying broken symlink '/etc/mtab' target '/proc/45618/mounts' on /proc/ /sys/ /dev/ or /run/
     Skip copying broken symlink '/etc/resolv.conf' target '/run/systemd/resolve/stub-resolv.conf' on /proc/ /sys/ /dev/ or /run/
     Symlink '/lib/modules/5.8.0-55-generic/build' -> '/usr/src/linux-headers-5.8.0-55-generic' refers to a non-existing directory on the recovery system.
     It will not be copied by default. You can include '/usr/src/linux-headers-5.8.0-55-generic' via the 'COPY_AS_IS' configuration variable.
     Testing that the recovery system in /tmp/rear.jTWZ3BAx5GJA0kO/rootfs contains a usable system
     Testing each binary with 'ldd' and look for 'not found' libraries within the recovery system
     Testing that the existing programs in the PROGS array can be found as executable command within the recovery system
     Testing that each program in the REQUIRED_PROGS array can be found as executable command within the recovery system
     Creating recovery/rescue system initramfs/initrd initrd.cgz with gzip default compression
     Created initrd.cgz with gzip default compression (433981547 bytes) in 41 seconds
     Using syslinux to create an EFI bootloader
     Creating 455 MiB raw disk image "rear-juliet.raw"
     Using syslinux to install a Legacy BIOS bootloader
     Installing the EFI rescue system to partitions labeled 'Rescue System'
     Could not detect suitable partitions labeled 'Rescue System'
     Copying resulting files to sshfs location
     Saving /home/oliver/Repositories/open-source/rear/var/log/rear/rear-juliet.log as rear-juliet.log to sshfs location
     Copying result files '/tmp/rear.jTWZ3BAx5GJA0kO/tmp/rear-juliet.raw.gz /tmp/rear.jTWZ3BAx5GJA0kO/tmp/VERSION /tmp/rear.jTWZ3BAx5GJA0kO/tmp/README /tmp/rear.jTWZ3BAx5GJA0kO/tmp/rear-juliet.log' to /tmp/rear.jTWZ3BAx5GJA0kO/outputfs/juliet at sshfs location
     Exiting rear mkrescue (PID 36709) and its descendant processes ...
     Running exit tasks
     

4. In this case, the correct fix to eliminate misleading messages from the log file is to treat them specifically. It could be as easy as prefixing affected script lines with expect_stderr:

   #!/bin/bash
   
   function Log() {
       echo "LOG: $*" > /dev/tty
   }
   
   function expect_stderr() {
       local stderr_output exit_status
       if [[ "$VERBOSE" ]]; then
           { stderr_output=$("$@" 2>&1 1>&9-) ;} 9>&1
           exit_status=$?
           [[ -n "$stderr_output" ]] && Log "[THIS MESSAGE IS EXPECTED] $stderr_output"
       else
           "$@" 2>/dev/null
           exit_status=$?
       fi
       return $exit_status
   }
   
   function has_binary() {
       for bin in "$@"; do
           expect_stderr type $bin 1>/dev/null && return 0
       done
       return 1
   }
   
   echo "***VERBOSE unset"
   for x in /bin/bash /bin/basxh; do
       has_binary $x && echo has $x || echo no $x
   done
   
   echo ""
   echo "*** VERBOSE=1"
   VERBOSE=1
   for x in /bin/bash /bin/basxh; do
       has_binary $x && echo has $x || echo no $x
   done

EDIT: Script (4.) corrected.

[github-actions]

Stale issue message