#885 Issue closed: Messages on screen missing in log file¶
Labels: enhancement, cleanup, fixed / solved / done
jsmeix opened issue at 2016-06-17 13:22:¶
rear master
During
https://github.com/rear/rear/issues/882#issuecomment-226765335
I noticed messages on the screen
that are not logged in the rear log file.
I did "rear -d -D recover" and got this on the screen
(excerpts - long lines wrapped):
RESCUE g130:~ # rear -d -D recover
...
Creating filesystem of type btrfs with mount point / on /dev/sda3.
8 bytes [5f 42 48 52 66 53 5f 4d] erased at offset 0x10040 (btrfs)
Btrfs v3.18.2+
ATTENTION:
mkfs.btrfs is not intended to be used directly. Please use the
YaST partitioner to create and manage btrfs filesystems to be
in a supported state on SUSE Linux Enterprise systems.
Performing full device TRIM (18.38GiB) ...
Turning ON incompat feature 'extref': increased hardlink limit
per file to 65536
fs created label (null) on /dev/sda3
nodesize 4096 leafsize 4096 sectorsize 4096 size 18.38GiB
Mounting filesystem /
But in /var/log/rear/rear-g130.log (in the running recovery system)
there is only (excerpt - long lines wrapped):
+++ LogPrint 'Creating filesystem of type btrfs with mount point / on /dev/sda3.' +++ Log 'Creating filesystem of type btrfs with mount point / on /dev/sda3.' +++ test 1 -gt 0 ++++ Stamp ++++ date '+%Y-%m-%d %H:%M:%S.%N ' +++ echo '2016-06-17 14:42:24.248377595 Creating filesystem of type btrfs with mount point / on /dev/sda3.' 2016-06-17 14:42:24.248377595 Creating filesystem of type btrfs with mount point / on /dev/sda3. +++ Print 'Creating filesystem of type btrfs with mount point / on /dev/sda3.' +++ test -n 1 +++ echo -e 'Creating filesystem of type btrfs with mount point / on /dev/sda3.' +++ mount +++ grep -q /dev/sda3 +++ wipefs -a /dev/sda3 +++ grep -q /dev/sda3 +++ mount +++ mkfs -t btrfs -f /dev/sda3 ++++ grep -o 'uuid: .*' ++++ cut -d : -f 2 ++++ tr -d '[:space:]' ++++ btrfs filesystem show /dev/sda3 +++ new_uuid=56e33393-d7aa-4750-8a41-67a5e8b12fda +++ '[' ffa23495-df2a-4a08-9233-4b84faea5d40 '!=' 56e33393-d7aa-4750-8a41-67a5e8b12fda ']' +++ grep -q ffa23495-df2a-4a08-9233-4b84faea5d40 /var/lib/rear/layout/fs_uuid_mapping grep: /var/lib/rear/layout/fs_uuid_mapping: No such file or directory +++ echo 'ffa23495-df2a-4a08-9233-4b84faea5d40 56e33393-d7aa-4750-8a41-67a5e8b12fda /dev/sda3' +++ LogPrint 'Mounting filesystem /' +++ Log 'Mounting filesystem /' +++ test 1 -gt 0 ++++ Stamp ++++ date '+%Y-%m-%d %H:%M:%S.%N ' +++ echo '2016-06-17 14:42:24.390821545 Mounting filesystem /' 2016-06-17 14:42:24.390821545 Mounting filesystem / +++ Print 'Mounting filesystem /' +++ test -n 1 +++ echo -e 'Mounting filesystem /'
I.e. nothing at all in the log about
Btrfs v3.18.2+
ATTENTION:
mkfs.btrfs is not intended to be used directly. Please use the
YaST partitioner to create and manage btrfs filesystems to be
in a supported state on SUSE Linux Enterprise systems.
Performing full device TRIM (18.38GiB) ...
Turning ON incompat feature 'extref': increased hardlink limit
per file to 65536
fs created label (null) on /dev/sda3
nodesize 4096 leafsize 4096 sectorsize 4096 size 18.38GiB
Perhaps this is a general missing functionality in rear
that everything what appears on the screen is also logged?
@gdha
do you know if everything what appears on the screen
should also be logged when '-d' and '-D' is used
or do I do something wrong?
gdha commented at 2016-06-17 14:29:¶
@jsmeix Try using
https://github.com/gdha/mismas/blob/master/make_rear_diskrestore_script.sh
to generate the disk_restore.sh (see also
http://www.it3.be/2016/06/08/rear-diskrestore/
for more info).
You will notice that the mkfs commands do not have >&2 appended (I
guess that was done on purpose so that the user see something on the
screen).
jsmeix commented at 2016-06-17 14:41:¶
Do I understand it correctly that only stderr gets into the log
but stdout does not get into the log?
If in usr/sbin/rear the command
exec 2>"$LOGFILE" ...
is the only one that redirects things into the log
then only stderr gets into the log
but stdout stays on the screen.
To get both stdout and stderr on the screen and also in the log
see my scripts in the section
"Generic usage of the plain SUSE installation system for backup and
recovery"
in
https://en.opensuse.org/SDB:Disaster_Recovery
In those scripts I implemeted advanced logging functionality
so that everything what "appears on the screen" is also logged
as follows (excerpts):
# Start logging:
my_name=${0##*/}
starting_timestamp=$( date +%Y%m%d%H%M%S )
log_file=$my_name.$starting_timestamp.log
# Have a new file descriptor 3 which is a copy of the stdout file descriptor:
exec 3>&1
# Have a new file descriptor 4 which is a copy of the stderr file descriptor:
exec 4>&2
# Have stdout on the terminal and also in the log file:
exec 1> >( exec -a $my_name:tee tee -a $log_file )
logging_tee_pid=$!
# Make stderr what stdout already is (i.e. terminal and also in the log file):
exec 2>&1
...
# Stop logging:
# Have stdout and stderr on the terminal but no longer in the log file that is in use by the my_name:tee process
# which was forked at "Start logging" via: exec 1> >( exec -a $my_name:tee tee -a $log_file )
# Close stdout and stderr to finish the my_name:tee logging process:
exec 1>&-
exec 2>&-
# Reopen stdout as what was saved in file descriptor 3:
exec 1>&3
# Reopen stderr as what was saved in file descriptor 4:
exec 2>&4
# Wait one second to be on the safe side that the my_name:tee logging process has finished:
sleep 1
if ps $logging_tee_pid 1>/dev/null
then echo "$my_name:tee process (PID $logging_tee_pid) still running (writes to $log_file)."
echo "Waiting 10 seconds to give the $my_name:tee logging process more time to finish."
sleep 10
fi
@gdha
if you like to have such kind of advanced logging functionality
I can work on it to implement that also for rear.
Of course I will use appropriate command line options
so that by default the user does not get zillions of
debug log messages on the screen.
gdha commented at 2016-06-18 07:20:¶
@schlomo would like to see your opinion on this topic as well?
jsmeix commented at 2016-06-21 07:42:¶
To avoid misunderstanding:
I do not plan to change the current behaviour.
My current idea is to add two command line parameters like
Logging: -l have stdout on the terminal and also in the log file -L have stderr in the log file and also on the terminal By default (i.e. without '-l' and/or '-L') stdout is on the terminal and stderr goes to the log file.
schlomo commented at 2017-06-20 12:16:¶
I think it would be nice to also duplicate stdout into the log file. I don't see the additional benefit (beyond us developers) to mirror stderr to the terminal as well. Quite the opposite, for ReaR users it is our job to handle all the error situations either with a meaningful response in our code or by aborting and asking the user to look into the log file.
So, as in any case the logfile is the important source of truth I would
add the stdout to the logfile so that the logfile gives a more complete
picture. If a single command has output on stderr that we prefer on
stdout then for this single command we should redirect the output to
stdout (2>&1).
As in many other cases, I think that making this configurable adds more complexity for little value. Adding stdout to the log is however valuable to complete the picture in the logfile. BTW, looking at the title of this issue also reminds me to keep it simple and just implement that: screen messages in logfile.
jsmeix commented at 2017-06-20 14:25:¶
@schlomo
I will implement to duplicate stdout into the log file.
I agree that it is sufficient when all is in the log file.
It is not needed to have all on the terminal.
I think duplicating stdout into the log file could be done
in any case even without any additional option.
schlomo commented at 2017-06-20 14:32:¶
Yes, that's what I meant: Simply add all stdout into the logfile by default, that should not be an option.
jsmeix commented at 2017-06-20 14:42:¶
I like it so much that after some discussion
we find simple solutions that "just do the right thing"!
jsmeix commented at 2017-06-21 13:43:¶
Unfortunately it is not so simple as it looks to
"Simply add all stdout into the logfile"
if one wants to keep strict ordering of stdout and stderr outputs.
With
exec 1> >( exec -a $my_name:tee tee -i -a $log_file ) exec 2>>$log_file
one gets stdout on the terminal and also in the log file
and stderr only in the log file (but no longer on the terminal)
but then stdout and stderr outputs that happen at basically
the same time can show up in the opposite order in the log file
(usually stderr gets shown first).
I think the reason is that for stdout there is the 'tee' process
in beween where output is even further delayed by the named pipe
with its buffers that are also in beween compared to stderr
that gets directly appended to the log file.
What would keep the ordering is
exec 1> >( exec -a $my_name:tee tee -i -a $log_file ) exec 2>&1
because with 2>&1 both streams are correctly merged, cf.
https://unix.stackexchange.com/questions/157689/how-to-capture-ordered-stdout-stderr-and-add-timestamp-prefixes
because now bash outputs stdout and stderr both via
the exact same file descriptor (that happens to be a
named pipe with a 'tee' consumer process).
But of course one same file descriptor for stdout and stderr
results that both stdout and stderr appear on the terminal
(and in the log file) and I guess we definitely do not want
stderr on the terminal for "rear -d -D ..." ;-)
BUT:
Usually we also do not want stdout on the terminal,
cf. "What to do with stdout and stderr" in
https://github.com/rear/rear/wiki/Coding-Style
Therefore I wonder now if I should perhaps by default
redirect both stdout and stderr only to the log file
and have both of them no longer on the terminal.
For output that is really meant for the user on the terminal
one could use explicit termial output e.g. via things like
test -w /dev/tty && echo "output for the user" >/dev/tty
or like the Print function does it by explicitly using fd7
as implemented in _input-output-functions.sh
# duplication STDOUT to fd7 to use for Print
exec 7>&1
...
function Print () {
test "$VERBOSE" && echo -e "${MESSAGE_PREFIX}$*" >&7 || true
}
My question is now:
Should I implement stdout on the terminal and also in the log file
and stderr only in the log file (but not on the terminal)
without keeping strict ordering of stdout and stderr outputs
or
should I redirect both stdout and stderr only to the log file
and have both of them no longer on the terminal
(which keeps strict ordering of stdout and stderr outputs
in the log file).
In the latter case I would also have to fix all actually intended
user dialogs via the terminal - in particular all places that
ask the user for input via a generic user input function, cf.
https://github.com/rear/rear/issues/1366
schlomo commented at 2017-06-21 14:06:¶
I think that a first good step is to make sure that all output intended for the screen is generated by a ReaR custom function like Print and not plain echo.
Once that is done we can experiment with global redirects. I am afraid that if we start with global redirects before that then we might end up missing crucial messages.
jsmeix commented at 2017-06-21 14:31:¶
Of course I had meant fixing all actually intended user dialogs
via the terminal as a precondition before redirecting stdout
only to the log file.
But that could be a long task.
Therefore - if you agree - I would like to do the following:
As a first step for now I will implement
duplicating stdout on the terminal and also in the log file
without keeping strict ordering of stdout and stderr outputs.
Then as a second step I will fix all actually intended user messages
and dialogs by using generic ReaR user input/output functions.
Finally as last step (after wating some time for possible bugs)
I would implement redirecting both stdout and stderr
only to the log file.
schlomo commented at 2017-06-21 17:18:¶
@jsmeix I am afraid that adding stdout to the log with wrong ordering will do us more harm than good. It will be extremely confusing to analyze such logs as you will have to guess what belongs where.
jsmeix commented at 2017-06-22 07:56:¶
O.k. then I will do it right from the start:
First as a precondition I will fix all actually intended user messages
and dialogs by using generic ReaR user input/output functions
which means in particular that I will first do
https://github.com/rear/rear/issues/1366
jsmeix commented at 2017-06-22 08:05:¶
@schlomo
I think usually the ordering would not go totally wrong
but only a bit misplaced.
But theoretically the 'tee' process with its named pipe
could delay the stdout output arbitrarily so that it is not
impossible that the ordering gets arbitrarily messed up.
jsmeix commented at 2017-06-22 08:12:¶
FYI
here my stand-alone testing script
cf.
https://github.com/rear/rear/issues/885#issuecomment-226787322
#!/bin/bash
my_name=${0##*/}
starting_timestamp=$( date +%Y%m%d%H%M%S )
# Start logging:
# A side note regarding preserving the ordering of stdout and stderr outputs see
# https://stackoverflow.com/questions/12517519/how-to-redirect-stdoutstderr-to-one-file-while-keeping-streams-separate
# that states that it is futile to try to preserve ordering because it is impossible
# because when there are writes to stderr and stdout that happen basically at the same time
# they can show up in the opposite order in the log file and also on the terminal.
log_file=$my_name.$starting_timestamp.log
# Have a new file descriptor 3 which is a copy of the stdout file descriptor:
exec 3>&1
# Have a new file descriptor 4 which is a copy of the stderr file descriptor:
exec 4>&2
# Have stdout on the terminal and also in the log file by
# redirecting stdout '1>' into a named pipe '>()' running 'tee'.
# Using 'tee -i' to avoid that signal interrupts (traps) disrupt stdout in the main script
# e.g. if there is a "trap 'echo Exiting' EXIT" and one does [Ctrl]+[C] one will not have "Exiting" in the log file, cf.
# https://stackoverflow.com/questions/3173131/redirect-copy-of-stdout-to-log-file-from-within-bash-script-itself
exec 1> >( exec -a $my_name:tee tee -i -a $log_file )
logging_tee_pid=$!
# Have stderr only in the log file (but no longer on the terminal).
# This cannot keeping strict ordering of stdout and stderr outputs.
# It is crucial to append to the log file '>>' instead of plain writing to it '>'
# because when a program (bash in this case) is plain writing to the log file it can overwrite
# output of the simultaneously running 'tee -a' process that appends stdout to the log file
# (i.e. with plain '2>$log_file' at least some stdout would be missing in the log file):
#exec 2>>$log_file
# Make stderr the same what stdout already is (i.e. terminal and also in the log file).
# This keeps strict ordering of stdout and stderr outputs
# because now both stdout and stderr use one same file descriptor
# (that happens to be a named pipe with a 'tee' consumer process):
exec 2>&1
# Test logging:
trap 'echo Exiting' EXIT
for i in $( seq 9 )
do echo "a 1 stdout message $i"
echo "a 2 stderr message $i" 1>&2
echo "b 1 stdout message $i"
echo "b 2 stderr message $i" 1>&2
test -w /dev/tty && echo "tty sleeping 1 second" >>/dev/tty
sleep 1
done
# Stop logging:
# Have stdout and stderr on the terminal but no longer in the log file that is in use by the my_name:tee process
# which was forked at "Start logging" via: exec 1> >( exec -a $my_name:tee tee -i -a $log_file )
# Close stdout and stderr to finish the my_name:tee logging process:
exec 1>&-
exec 2>&-
# Reopen stdout as what was saved in file descriptor 3:
exec 1>&3
# Reopen stderr as what was saved in file descriptor 4:
exec 2>&4
# Wait one second to be on the safe side that the my_name:tee logging process has finished:
sleep 1
if ps $logging_tee_pid 1>/dev/null
then echo "$my_name:tee process (PID $logging_tee_pid) still running (writes to $log_file)."
echo "Waiting 10 seconds to give the $my_name:tee logging process more time to finish."
sleep 10
fi
jsmeix commented at 2017-06-22 14:05:¶
Only an intermediate info:
I am currently experimenting with this in usr/sbin/rear
to get both STDOUT and STDERR into the log file:
# Source usr/share/rear/lib/_input-output-functions.sh because therein
# the original STDOUT and STDERR file descriptors are saved as fd7 and fd8
# so that ReaR functions for actually intended user messages can use fd7 and fd8
# to show messages to the user regardless whereto STDOUT and STDERR are redirected:
source $SHARE_DIR/lib/_input-output-functions.sh
# Keep old log file:
test -r "$RUNTIME_LOGFILE" && mv -f "$RUNTIME_LOGFILE" "$RUNTIME_LOGFILE".old 2>/dev/null
# Start logging:
mkdir -p $LOG_DIR || echo "ERROR: Could not create $LOG_DIR" >&2
cat /dev/null >"$RUNTIME_LOGFILE"
# Redirect both STDOUT and STDERR into the log file:
exec 2>>"$RUNTIME_LOGFILE"
exec 1>&2
# Include functions after RUNTIME_LOGFILE is set and readonly
# so that functions can use a fixed RUNTIME_LOGFILE value:
for script in $SHARE_DIR/lib/[a-z]*.sh ; do
source $script
done
With this I get "interesting" looking results:
Now some scripts spit out error messages on the terminal
regardless that STDOUT and STDERR should go to the log file.
It seems there is much to do and to clean up
until also redirecting STDOUT works properly.
It seems parts of ReaR somehow depend
on STDOUT not being redirected.
I think ReaR should work properly regardless whereto
STDOUT and STDERR might be redirected because
I think it must be possible that the user calls 'rear' from
within any environment with any STDOUT and STDERR
redirections set up by the user as he likes it (e.g. for
whatever automated use case like via cron or whatever).
I think having by default STDOUT and STDERR redirected
into the log file is only one particular use case.
jsmeix commented at 2017-06-22 14:16:¶
Found a first easy explanation why error messages
appear unexpectedly on the terminal.
It is the old deprecated usage of '>&8'
e.g. as in prep/GNU/Linux/200_include_serial_console.sh
for devnode in $(ls /dev/ttyS[0-9]* | sort); do
if stty -F $devnode >&8 2>&1; then
USE_SERIAL_CONSOLE=y
fi
done
because now with my new _input-output-functions.sh
the original STDOUT and STDERR file descriptors
are now saved as fd7 and fd8 so that all what is sent to fd8
appears on the original STDERR which is the terminal.
I was already aware of it that I also have
to fix all the old deprecated usage of '>&8'
and if that is all, it is easy - much to do but easy.
I look forward to finally get all that old stuff cleaned up!
jsmeix commented at 2017-06-22 14:23:¶
I.e. solving
https://github.com/rear/rear/issues/887
is another precondition for this issue here.
jsmeix commented at 2017-06-26 12:26:¶
With
https://github.com/rear/rear/pull/1391
merged
this issue should be already solved regardless
that
https://github.com/rear/rear/issues/887
is not yet solved, for an explanation why see
https://github.com/rear/rear/pull/1391#issuecomment-311040948
jsmeix commented at 2017-06-26 12:45:¶
In
https://github.com/rear/rear/wiki/Coding-Style
I explained "What to do with stdout and stderr" when
both stdout and stderr are redirected into ReaR's log file.
jsmeix commented at 2017-06-28 14:29:¶
The redirection of STDOUT into the log file can
cause regressions when interactive tools are "just called",
see
https://github.com/rear/rear/issues/1398
jsmeix commented at 2017-07-19 09:03:¶
I reopen this issue because the
redirection of STDOUT into the log file
will not happen for ReaR v 2.2.
Because ReaR v 2.2 was preponed, cf.
https://github.com/rear/rear/issues/1398#issuecomment-315318878
I postponed the redirection of STDOUT vor ReaR v 2.2 in
https://github.com/rear/rear/commit/f47f705c0857e46b93c2ccc49b8ba504c05559eb
cf.
https://github.com/rear/rear/issues/1398#issuecomment-315325470
jsmeix commented at 2017-10-20 10:01:¶
For ReaR v2.3 redirection of stdout into the log file is re-enabled
via
https://github.com/rear/rear/commit/6ab3c4173fe425bb018880af4a8461bf575ba1e0
so that this issue is fixed for ReaR v 2.3.
jsmeix commented at 2018-05-18 08:56:¶
An addedum regarding the above
https://github.com/rear/rear/issues/885#issuecomment-310308763
that reads
# It is crucial to append to the log file '>>' instead of plain writing to it '>' # because when a program (bash in this case) is plain writing to the log file it can overwrite # output of the simultaneously running 'tee -a' process that appends stdout to the log file # (i.e. with plain '2>$log_file' at least some stdout would be missing in the log file):
here an example command that shows how append to one same log file works:
{ of=/tmp/out ; cat /dev/null >$of ; \
( for i in $( seq 10 29 ) ; do echo "i=$i" ; cat i=$i ; done 1>>$of 2>&1 ) & \
( for j in $( seq 10 29 ) ; do echo "j=$j" ; cat j=$j ; done 1>>$of 2>&1 ) & \
wait ; \
echo $( grep -o 'i=..' $of | wc -l ) i messages ; \
echo $( grep -o 'j=..' $of | wc -l ) j messages ; \
cat -n $of ; } | less
that results e.g. this output
40 i messages
40 j messages
1 i=10
2 j=10
3 cat: 'i=10': No such file or directory
4 cat: 'j=10': No such file or directory
5 i=11
6 j=11
7 cat: 'i=11': No such file or directory
8 cat: 'j=11': No such file or directory
9 i=12
10 j=12
11 cat: 'i=12': No such file or directorycat:
12 'j=12': No such file or directory
13 i=13
14 j=13
15 cat: 'i=13'cat: 'j=13': No such file or directory: No such file or directory
16
17 j=14
18 i=14
19 cat: 'i=14'cat: 'j=14': No such file or directory
20 : No such file or directory
21 i=15
22 j=15
23 cat: 'j=15'cat: 'i=15': No such file or directory
24 : No such file or directory
25 j=16
26 i=16
27 cat: 'j=16'cat: 'i=16': No such file or directory
28 : No such file or directory
29 j=17
30 i=17
31 cat: 'j=17': No such file or directory
32 cat: 'i=17': No such file or directory
33 j=18
34 i=18
35 cat: 'j=18': No such file or directory
36 cat: 'i=18': No such file or directory
37 j=19
38 i=19
39 cat: 'j=19'cat: 'i=19': No such file or directory
40 : No such file or directory
41 j=20
42 i=20
43 cat: 'i=20': No such file or directory
44 cat: 'j=20': No such file or directory
45 i=21
46 j=21
47 cat: 'i=21': No such file or directory
48 cat: 'j=21': No such file or directory
49 i=22
50 j=22
51 cat: 'i=22': No such file or directory
52 cat: 'j=22'i=23
53 : No such file or directory
54 j=23
55 cat: 'i=23': No such file or directory
56 cat: 'j=23': No such file or directory
57 i=24
58 j=24
59 cat: 'j=24'cat: 'i=24': No such file or directory
60 : No such file or directory
61 j=25
62 i=25
63 cat: 'i=25': No such file or directory
64 cat: 'j=25': No such file or directory
65 i=26
66 j=26
67 cat: 'i=26': No such file or directory
68 cat: 'j=26': No such file or directory
69 i=27
70 j=27
71 cat: 'j=27'cat: 'i=27': No such file or directory
72 : No such file or directory
73 j=28
74 i=28
75 cat: 'j=28': No such file or directory
76 j=29
77 cat: 'i=28': No such file or directory
78 i=29
79 cat: 'j=29': No such file or directory
80 cat: 'i=29': No such file or directory
Message lines of the two simultaneously running processes can get
intermixed
but on the other hand all output of the two processes appears in the log
file and
all output appears in the exact right chronological ordering
(which is the reason why message lines get intermixed).
[Export of Github issue for rear/rear.]