#1398 Issue `closed`: Possible regressions because of redirected STDOUT¶

Labels: bug, cleanup, fixed / solved / done

jsmeix opened issue at 2017-06-28 14:25:¶

Since https://github.com/rear/rear/pull/1391 is merged
therein in particular via
https://github.com/rear/rear/pull/1391/commits/523b956f5dc7a8dd87c9037e3b7adb02a215398d
both STDOUT and STDERR are redirected to the log file.

The redirection of STDOUT causes regressions for things
that are intended to run in an interactive way with a user.

Any code that "just calls" interactively working tools like

less "$some_file"
vi "$another_file"

will appear as if ReaR had hang up because the user
does not see any STDOUT output on his terminal
unless proper specification to use the the original STDIN
STDOUT and STDERR when rear was launched by the user
as follows:

less "$some_file" 0<&6 1>&7 2>&8
vi "$another_file" 0<&6 1>&7 2>&8

cf. "What to do with stdout and stderr" in
https://github.com/rear/rear/wiki/Coding-Style

Because I @jsmeix cannot check the whole code
I assume there are some places where interactive tools
are "just called" that need to be fixed.

schlomo commented at 2017-06-28 14:33:¶

So did you check the use of an editor / viewer in the recovery workflow when the disks are different? IMHO we should fix at least that part.

jsmeix commented at 2017-06-28 14:51:¶

The calls of 'less' and 'vi' in
usr/share/rear/layout/prepare/default/200_recreate_hpraid.sh
usr/share/rear/layout/prepare/default/500_confirm_layout.sh
usr/share/rear/layout/recreate/default/100_ask_confirmation.sh
usr/share/rear/layout/recreate/default/200_run_script.sh
should be o.k. because they happen within a select command
that uses the the original STDIN STDOUT and STDERR
basically like (excerpts):

        select choice in "${choices[@]}"; do
            case "$REPLY" in
                (1) less $RUNTIME_LOGFILE;;
                (2) less $VAR_DIR/layout/config/df.txt;;
                (3) rear_shell;;
                (4) vi $LAYOUT_FILE;;
                (5) vi $LAYOUT_CODE;;
            esac
        done 0<&6 1>&7 2>&8

The 'vi' calls in
usr/share/rear/restore/BACULA/default/400_restore_backup.sh
should be o.k. because they happen within a rear_shell function
that uses the the original STDIN STDOUT and STDERR

function rear_shell () {
...
    HISTFILE="$histfile" bash --noprofile --rcfile $bashrc 0<&6 1>&7 2>&8
}

I had adapted the 'read' and 'select' calls and the rear_shell
function via the commits in https://github.com/rear/rear/pull/1391
so that we should be "mostly o.k".

But I cannot know what other arbitrary interactive tools
might be "just called" in which various ways and where.

schlomo commented at 2017-06-28 19:31:¶

So again, should we revert this or not? How could we decide this question?

gdha commented at 2017-06-29 06:58:¶

Just test it out and lets make a decision afterwards

Gratien

Op 28 jun. 2017 om 21:31 heeft Schlomo Schapiro notifications@github.com het volgende geschreven:

So again, should we revert this or not? How could we decide this question?

—
You are receiving this because you are subscribed to this thread.
Reply to this email directly, view it on GitHub, or mute the thread.

jsmeix commented at 2017-06-29 07:35:¶

@schlomo
regarding "should we revert this":
In case of issues because of of redirected STDOUT
all one needs to do is this change in usr/sbin/rear

- exec 1>&2
+ # exec 1>&2

to get back the old behaviour without redirected STDOUT.

@gdha
I agree with you to keep the redirected STDOUT at least for now
so that courageous users who use the current GitHub master code
can try it out how it behaves with redirected STDOUT in their
particular environments and for their particular use cases.
E.g. I cannot test how third party backup tools behave.
Possibly there are issues when third party backup tools
work interactively and need "0<&6 1>&7 2>&8" added.
Until the ReaR v 2.2 Milestone release date
(which is currently end of September 2017)
we have plenty of time to collect user feedback
and I have plenty of time to fix the issues, cf.
https://github.com/rear/rear/pull/1391#issuecomment-311043325
If I fail to fix things we can easily do the above
change in usr/sbin/rear for the ReaR 2.2 release.

jsmeix commented at 2017-06-29 08:58:¶

During https://github.com/rear/rear/pull/1391
I had only tested that "read ... 0<&6 1>&7 2>&8"
and "select ... do ... done 0<&6 1>&7 2>&8"
work with the original STDIN STDOUT and STDERR
but I had not explicitly tested that commands that
are called within "select ... do ... done 0<&6 1>&7 2>&8"
also work with the original STDIN STDOUT and STDERR.

Now I explicitly tested the latter and it works (as expected).

FYI how I tested it:

At the beginning of init/default/030_update_recovery_system.sh
I added this testing code (I used an 'init' stage script because
that is run both during "rear mkbackup" and "rear recover"):

UserOutput "user output"
LogUserOutput "log user output"

LogPrint "test stdout and stderr output"
echo "stdout output"
echo "stderr output" 1>&2

LogPrint "test command stdout and stderr output"
cat /etc/issue qqq

LogPrint "test read"
read -p "Type some user input: " 0<&6 1>&7 2>&8
LogPrint "user input is '$REPLY'"

LogPrint "test select"
test_file="/tmp/rear_test_file"
rear_shell_history="echo foo
echo bar
echo baz"
choices=(
    "View Relax-and-Recover log"
    "Go to Relax-and-Recover shell"
    "Edit $test_file"
    "View $test_file"
    "Exit select"
)
# Use the original STDIN STDOUT and STDERR when rear was launched by the user
# to get input from the user and to show output to the user (cf. _input-output-functions.sh):
select choice in "${choices[@]}"; do
    case "$REPLY" in
        (1) less "$RUNTIME_LOGFILE";;
        (2) rear_shell "" "$rear_shell_history";;
        (3) vi "$test_file";;
        (4) less "$test_file";;
        (5) break;;
    esac
    LogPrint "User selected: $REPLY) ${choices[$REPLY-1]}"
    # Reprint menu options when returning from less, shell or vi
    Print ""
    for (( i=1; i <= ${#choices[@]}; i++ )); do
        Print "$i) ${choices[$i-1]}"
    done
done 0<&6 1>&7 2>&8

For me it works as expected.
Note the interesting effect of the LogPrint call that
happens within the "0<&6 1>&7 2>&8" environment:
Here LogPrint logs to the terminal because the original
STDERR is used within the "0<&6 1>&7 2>&8" environment
which proves that things fully work as expected.

To test if it also works with redirected STDIN (to be future-proof)
I added in usr/sbin/rear below the STDOUT and STDERR redirections

# Discard STDIN as a test:
exec 0</dev/null

For me it still works as expected.

I did a "rear mkbackup" and then
a "rear recover" on a system with a bigger disk
to get the disk migration dialogs and
for me all works as expected.

jsmeix commented at 2017-06-29 13:27:¶

@schlomo @gdha @gozora
if you have an idea how I could automatically check
the ReaR bash scripts which external programs they call
I would very much appreciate helping information.

schlomo commented at 2017-06-29 15:27:¶

Like this:

$ sudo strace -qq -f -e execve rear mkrescue 2>&1 | sed -ne 's#.*execve("\([^"]*\).*$#\1#p' | sort -u
/bin/btrfs
/bin/cat
/bin/chmod
/bin/chown
/bin/cp
/bin/cpio
/bin/date
/bin/dd
/bin/df
/bin/efibootmgr
/bin/egrep
/bin/findmnt
/bin/grep
/bin/gunzip
/bin/gzip
/bin/hostname
/bin/ln
/bin/ls
/bin/mkdir
/bin/mktemp
/bin/mount
/bin/mv
/bin/pidof
/bin/ps
/bin/readlink
/bin/rm
/bin/sed
/bin/stty
/bin/systemd-notify
/bin/tar
/bin/umount
/bin/uname
/lib64/ld-linux-x86-64.so.2
/sbin/blkid
/sbin/cat
/sbin/depmod
/sbin/dmsetup
/sbin/ethtool
/sbin/grep
/sbin/gzip
/sbin/ip
/sbin/lsmod
/sbin/mkfs.vfat
/sbin/modinfo
/sbin/modprobe
/sbin/parted
/sbin/udevadm
/usr/bin/awk
/usr/bin/basename
/usr/bin/blkid
/usr/bin/cat
/usr/bin/cut
/usr/bin/dig
/usr/bin/dirname
/usr/bin/du
/usr/bin/dumpkeys
/usr/bin/file
/usr/bin/find
/usr/bin/getent
/usr/bin/getopt
/usr/bin/grep
/usr/bin/grub-mkimage
/usr/bin/gzip
/usr/bin/head
/usr/bin/hexdump
/usr/bin/id
/usr/bin/ldd
/usr/bin/logger
/usr/bin/lsattr
/usr/bin/lsb_release
/usr/bin/md5sum
/usr/bin/pgrep
/usr/bin/seq
/usr/bin/sort
/usr/bin/stat
/usr/bin/strings
/usr/bin/syslinux
/usr/bin/tac
/usr/bin/tail
/usr/bin/tee
/usr/bin/touch
/usr/bin/tr
/usr/bin/wc
/usr/bin/xargs
/usr/bin/xorrisofs
/usr/local/bin/bash
/usr/local/bin/blkid
/usr/local/bin/cat
/usr/local/bin/grep
/usr/local/bin/gzip
/usr/local/sbin/bash
/usr/local/sbin/blkid
/usr/local/sbin/cat
/usr/local/sbin/grep
/usr/local/sbin/gzip
/usr/sbin/bash
/usr/sbin/blkid
/usr/sbin/cat
/usr/sbin/chroot
/usr/sbin/grep
/usr/sbin/grub-probe
/usr/sbin/gzip
/usr/sbin/rear

If you want to check an interactive rear recover then you'll need to take strace along with PROGS+=(strace) and run it like this or similar:

strace -qq -f -o log.txt -e execve rear recover
sed -ne 's#.*execve("\([^"]*\).*$#\1#p' <log.txt | sort -u | tee >/mnt/local/root/rear-progs.txt

jsmeix commented at 2017-06-30 10:00:¶

@schlomo
thanks for your input!

Perhaps I can use it for another task but for what I would like
to get here I think it does not help (as far as I understand it).
Things like 'strace' or anything that monitors a currently
running 'rear' can only show what that current run does.
To find out how interactive stuff behaves during a current run
I just need to do and watch that current run.

But what I would like to find out is what interactive stuff
could be hidden at any place in the code that I do not see
when I run it myself.
Think about code like

if CONDITION ; then
    echo "Please confirm removal of $some_file"
    rm -i $some_file
fi

When CONDITION is not true when I run it in my environment
I can never see myself that this code would no longer work.

Simply put:
I was looking for some kind of static code analysis.

schlomo commented at 2017-06-30 14:26:¶

I think static code analysis for bash is really tricky.

find usr $ -name \*.conf -o -name \*.sh $ -exec cat '{}' \+ | sed -n -e 's#^[\t ]\+##' -e 's/ .*$//' -e '/^[#"()[{};>*$]/b' -e '/[=()|$:]/b' -e 'p' | sort -u gives too many false positives because it doesn't understand multi-line strings, here strings etc.

find usr $ -name \*.conf -o -name \*.sh $ -exec cat '{}' \+ | sed -n -e 's#^[\t ]\+##' -e 's/ .*$//' -e '/^[#"()[{};>*$-]/b' -e '/[=()|$:"'"'"']/b' -e 'p' | sort -u | xargs which only finds programs that you actually have installed, but you can be sure that all of them can be called by ReaR.

Maybe we can actually use this last part to automatically populate the PROGS variable ☺

HTH,
Schlomo

jsmeix commented at 2017-07-03 12:12:¶

Things are somewhat worse than expected.
Currently my primary concern are the zillions of 'echo' commands
and things like that.
In most cases their output is not meant for the user.
But some output is actually for the user.

I will fix as many regressions as I can
(which means as many as I detect).

If current redirected STDOUT is too bad for normal usage
I found meanwhile a good way how one could work easily
with redirected STDOUT for testing and development
but the default is no redirected STDOUT
via this change in usr/sbin/rear

 # Make stdout the same what stderr already is.
 # This keeps strict ordering of stdout and stderr outputs
 # because now both stdout and stderr use one same file descriptor:
-exec 1>&2
+test "$REAR_STDOUT_INTO_LOG" && exec 1>&2

Now one can call

REAR_STDOUT_INTO_LOG=y usr/sbin/rear ...

to run it with redirected STDOUT for testing
but otherwise it runs as before.

jsmeix commented at 2017-07-04 14:07:¶

@schabrolles
I ask you because in https://github.com/rear/rear/pull/1348
it seems you are a TSM user:

restore/TSM/default/400_restore_with_tsm.sh
contains 'echo' commands where I do not fully understand
how they are meant so that I cannot fix them to work
with redirected STDOUT.

Could you please have a look?

schabrolles commented at 2017-07-04 15:58:¶

@jsmeix,

Most of the echo used in this script are used to produce an animation showing restoration in progress.
"Cursor" animation : '/' '-' '' '|'
and number of files restored change and stay in a single line.

I don't think we need to copy this in a log file ... May be only the result (number of files restored)

jsmeix commented at 2017-07-05 11:26:¶

@schabrolles
thanks for your information!

I like it so much to have functions that are named
as existing (and totally different) tools:

# type -a star
star is /usr/bin/star

# man star
...
DESCRIPTION
  Star is a very fast tar(1) like tape archiver
  with improved functionality.

;-)

You may have a look at my changed
restore/TSM/default/400_restore_with_tsm.sh
in
https://github.com/rear/rear/pull/1401/commits/d6c266bb796f49aa5299c9ebbde205cd9c1c9952
or view it directly and completely in
https://raw.githubusercontent.com/jsmeix/rear/use_UserOutput_when_output_is_meant_for_the_user_issue_1398/usr/share/rear/restore/TSM/default/400_restore_with_tsm.sh

schlomo commented at 2017-07-05 12:01:¶

@schabrolles we got rid of the progress indicator (spinner) in ReaR, is your code doing something like that?

jsmeix commented at 2017-07-05 13:05:¶

I wonder in general to what extent an animated cursor
is useful when the animation only proceeds if there
is output from a long running command, i.e. when
the code is of this form:

# for each animated_cursor function call
# show one of the characters / - \ |
function animated_cursor () {
    ...
}

long_running_command \
  | while read long_running_command_stdout ; do
        echo $long_running_command_stdout
        animated_cursor
    done

When long_running_command outputs there is no real need
for an additional animated cursor but as long as
long_running_command does not output (i.e. when there would be
a real need for an animated cursor) nothing is shown.

I think a more useful implementation might be like

long_running_command_output=""
long_running_command 2>&1 \
  | while read -t 1 long_running_command_output || TODO ; do
        if test "$long_running_command_output" ; then
            echo $long_running_command_output
            long_running_command_output=""
        else
            animated_cursor
        fi
    done

The problem is that read returns non-zero exit code when it
times out so that "wile read -t 1 ... || ..." must be used
to continue the while loop when read times out.
But "wile read -t 1 ... || true" results an endless loop.
Currently I don't know what TODO in this case to
continue the while loop only when read times out.

jsmeix commented at 2017-07-05 13:19:¶

The only thing that works for me is this way

long_running_command_output=""
{ echo foo ; sleep 5 ; cat /etc/issue ; sleep 5 ; cat qqq ; sleep 5 ; echo FINISHED ; } 2>&1 \
  | while read -t 1 long_running_command_output || true ; do
        if test "$long_running_command_output" ; then
            test "FINISHED" = "$long_running_command_output" && break
            echo $long_running_command_output
            long_running_command_output=""
        else
            animated_cursor
        fi
    done 1>&7

via an artificial special final "FINISHED" string
to break the endless while loop.

gdha commented at 2017-07-05 14:22:¶

@jsmeix @schabrolles @schlomo I would prefer to get rid with the animation - any objection?

schlomo commented at 2017-07-05 14:53:¶

That's what I meant.

jsmeix commented at 2017-07-05 15:24:¶

I also would prefer to get rid of the animated cursor,
at least in its currently implemented form.

In general I think ReaR does not need to provide
any automated ongoing "I am still alive" messaging.

jsmeix commented at 2017-07-07 13:40:¶

With https://github.com/rear/rear/pull/1401 merged
I think I found and fixed (hopefully) almost all places
where 'echo' was used to output on STDOUT.
What is not yet fixed are arbitrary program calls
like "less some_file" or "vi another_file"
which will be my work for the next week...

jsmeix commented at 2017-07-13 14:39:¶

@gdha
it seems you changed the milestone date
for ReaR v 2.2 to 20 July 2017
from end of September 2017 cf. my above
https://github.com/rear/rear/issues/1398#issuecomment-311886920

@schlomo @gdha
in this case I think it is perhaps better for ReaR v 2.2
to stay on the safe side and to not have STDOUT redirected
by default by disabling the STDOUT redirection in usr/sbin/rear

- exec 1>&2
+ # exec 1>&2

Alternativerly we may have STDOUT redirected by default
unless the '-v' option is specified so that users who miss
user dialogs could easily get them back via "rear -v ..".

What do you think what is best for ReaR v 2.2?

For ReaR v 2.3 that is currently dated end of October 2017
we can reconsider if the STDOUT redirection should
then be done by default in any case.

gdha commented at 2017-07-14 09:46:¶

@jsmeix @schlomo The purpose of ReaR v2.2 is to have an intermediate package on request of a customer (where Schlomo did some updates for [which are not yet in the master]). The question of STDOUT redirects by default? If you do not mind to post-pone to the 2.3 release then I would go for that track?

schlomo commented at 2017-07-14 09:49:¶

+1

On 14 July 2017 at 11:46, gdha notifications@github.com wrote:

@jsmeix https://github.com/jsmeix @schlomo https://github.com/schlomo
The purpose of ReaR v2.2 is to have an intermediate package on request of a
customer (where Schlomo did some updates for [which are not yet in the
master]). The question of STDOUT redirects by default? If you do not mind
to post-pone to the 2.3 release then I would go for that track?

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
https://github.com/rear/rear/issues/1398#issuecomment-315318878, or mute
the thread
https://github.com/notifications/unsubscribe-auth/AAGMCLroBxhumcPtS5tAqWlhr_43l4Jsks5sNzjwgaJpZM4OICrD
.

jsmeix commented at 2017-07-14 10:18:¶

I postponed the redirection of STDOUT vor ReaR v 2.2 in
https://github.com/rear/rear/commit/f47f705c0857e46b93c2ccc49b8ba504c05559eb

This obsoletes https://github.com/rear/rear/pull/1409

jsmeix commented at 2017-07-14 10:22:¶

@gdha @schlomo
I even prefer to have redirection of STDOUT postponed
vor ReaR v 2.2 because this is best for our users.

After the ReaR v 2.2 release I will re-enable it again so that
we can get user feedback how redirected STDOUT behaves.

jsmeix commented at 2017-09-04 14:01:¶

With
https://github.com/rear/rear/commit/6ab3c4173fe425bb018880af4a8461bf575ba1e0
redirection of stdout into the log file is re-enabled
as intended for ReaR v 2.3 and if I cannot fix the
possible regressions we can again postpone it.

jsmeix commented at 2017-11-28 11:03:¶

Sufficiently done for ReaR 2.3.

Remaining things can be fixed for ReaR 2.4 or later
as time permits and as users ask for it.

[Export of Github issue for rear/rear.]

#1398 Issue closed: Possible regressions because of redirected STDOUT¶