#2024 PR merged: Suppress dispensable 'set -x' debug output unless called with '--debugscripts x'

Labels: enhancement, fixed / solved / done

jsmeix opened issue at 2019-01-24 15:06:

Intent:
Improve readability of the ReaR log file by suppressing
particular set -x debug output that is usually of no interest
so that it gets easier for our users and for us to analyze an issue
by inspecting the log file when rear was called in debugscripts mode.

  • Type: Enhancement

  • Impact: Low

  • How was this pull request tested?
    By me on my openSUSE Leap 15.0 system

  • Brief description of the changes in this pull request:

I think a noticeable part of the set -x debugscripts output
(that part is about 25% for my initial test, see below)
is usually of no interest and therefore dispensable by default.

This pull request is a proposal how we could suppress dispensable
debug output by default (in particular when rear is called with '-D')
unless rear is called with '--debugscripts x' where the full debugscripts
output is still there as it was before.

The basic idea is to suppress uninteresting output that goes to stderr
(in particular where set -x debugscripts output is usually of no interest)
by default via setting in usr/sbin/rear (i.e. this is no user config variable)

DISPENSABLE_OUTPUT_DEV="null"

and by using where applicable in the scripts code of the form

{ command_1
  command_2
  ...
  command_N
} 2>>/dev/$DISPENSABLE_OUTPUT_DEV

provided none of the commands outputs intentionally to stderr
(i.e. there is only set -x debugscripts output for the commands)
unless rear is called with '--debugscripts x' where in usr/sbin/rear

DISPENSABLE_OUTPUT_DEV="stderr"

is set which results in the above code

...
} 2>>/dev/stderr

and /dev/stderr is fd2 which is redirected to append to RUNTIME_LOGFILE
so that 2>>/dev/stderr does not change things and fd2 output is still
appended to RUNTIME_LOGFILE.

What happens in compacted form is with 2>>/dev/null

# ( cat /dev/null >/tmp/mystderr ; exec 2>>/tmp/mystderr ; exec 1>&2 ; echo foo ; cat qqq ; echo bar ; cat QQQ 2>>/dev/null ; echo baz ) ; cat -n /tmp/mystderr
     1  foo
     2  cat: qqq: No such file or directory
     3  bar
     4  baz

versus with 2>>/dev/stderr

# ( cat /dev/null >/tmp/mystderr ; exec 2>>/tmp/mystderr ; exec 1>&2 ; echo foo ; cat qqq ; echo bar ; cat QQQ 2>>/dev/stderr ; echo baz ) ; cat -n /tmp/mystderr
     1  foo
     2  cat: qqq: No such file or directory
     3  bar
     4  cat: QQQ: No such file or directory
     5  baz

FYI how things go wrong when 2>/dev/stderr is used:

# ( cat /dev/null >/tmp/mystderr ; exec 2>>/tmp/mystderr ; exec 1>&2 ; echo foo ; cat qqq ; echo bar ; cat QQQ 2>/dev/stderr ; echo baz ) ; cat -n /tmp/mystderr
     1  cat: QQQ: No such file or directory
     2  baz

because 2>/file truncates the file to zero size.

I tested rear -D mkrescue versus rear --debugscripts x mkrescue
and got 53807 set -x lines in the log file with suppressed dispensable debug output
versus 68862 set -x lines in the log file with full debugscripts output as it was before.

My initial suppressed dispensable debug output is primarily
the set -x debugscripts output for some outupt functions and
the set -x debugscripts output for IsInArray() and RmInArray().

@rear/contributors
if you agree to the general idea behind and
if my implementation is not somehow broken by design
we could likely find more functions (or other code parts)
where the full set -x debug output is usually of no interest.

jsmeix commented at 2019-01-28 10:18:

If there are no objections I would like to merge it tomorrow afternoon.

jsmeix commented at 2019-01-29 14:55:

For the future some offhanded ideas for some more places
where debug or verbose output is usually of no interest:

In simple helper functions therein somewhat 'dumb' loops
the set -x debug output of such loops is usually of no interest
for example

  • the for loop in the 'percent_encode' function
  • the while loop in the 'FindStorageDrivers' function
  • the while (( $# > 1 )) loop in the 'copy_binaries' function

Also for somewhat 'dumb' loops in scripts the set -x
debug output of such loops is usually of no interest
for example

  • the for loop in rescue/GNU/Linux/390_check_usb_modules.sh
  • the while read -r copy_as_is_file loop in build/GNU/Linux/100_copy_as_is.sh
  • the for required_library in $( RequiredSharedObjects ... loop in build/GNU/Linux/100_copy_as_is.sh
  • the for bin in "${PROGS[@]}" "${REQUIRED_PROGS[@]}" loop in build/GNU/Linux/390_copy_binaries_libraries.sh
  • the for lib in "${all_libs[@]}" loop in build/GNU/Linux/390_copy_binaries_libraries.sh
  • the for prog in "${REQUIRED_PROGS[@]}" loop in build/default/950_check_missing_programs.sh
  • the for binary in $( find $ROOTFS_DIR -type f -executable loop in build/default/990_verify_rootfs.sh
  • the for program in "${PROGS[@]}" loop in build/default/990_verify_rootfs.sh
  • the for required_program in "${REQUIRED_PROGS[@]}" loop in build/default/990_verify_rootfs.sh

A similar but somewhat different case are verbose command messages
(via $v or $verbose) that could be too much by default in certain cases
for example

  • the cp $verbose -t $ROOTFS_DIR -a --parents /lib/modules/$KERNEL_VERSION in build/GNU/Linux/400_copy_modules.sh when "Copying all kernel modules" that results in my case 4850 lines of verbose cp command messages in the ReaR log file
  • the $gmkimage $v -O x86_64-efi in the build_bootx86_efi function that results in my case 3449 lines of verbose grub2-mkimage command messages in the ReaR log file

jsmeix commented at 2019-11-25 17:22:

Some of the places where debug or verbose output
is usually of no interest that I mentioned in
https://github.com/rear/rear/pull/2024#issuecomment-458569873
are added via
https://github.com/rear/rear/pull/2286

[Export of Github issue for rear/rear.]