2

Is there a way for a script to log both, the command line run (including piped ones) plus its output without duplicating the line for the command?

The intention is that the script should have a clean output, but should log verbosely into a log file (so no set -x). Apart from the output, it shall also log the command line causing the output, which could be a piped command-one liner.

The most basic approach is to duplicate the command line in the script and then dump it into the log followed by the captured output of the actual command being run:

echo "command argument1 \"quoted argument2\" | grep -oE \"some output\"" >> file.log
output="$(command argument1 "quoted argument2" 2>&1 | grep -oE "some output")"
echo "${output}" >> file.log

This has the side effect that quoted sections would need to be escaped for the log, which can lead to errors resulting in confusion.

If none of the commands were piped, one could store the command line in an array and then "run" the array.

command=(command argument1 "quoted argument2")
echo "${command[@]}" >> file.log
output="$("${command[@]}" 2>&1)"
echo "${output}" >> file.log

Though with this approach "quoted argument2" would become quoted argument2 in the log.

Is there a way (in bash) to realize this without having to duplicate the commands?

Phoenix
  • 186
  • 9
  • Did you try `eval`? Something like `cmd="..."; echo "$cmd" &>> file.log; eval "$cmd" &>> file.log`. – Renaud Pacalet Aug 06 '21 at 08:56
  • `eval` is still a mystery to me on what it does. So, I usually use it sparsely as I prefer to understand a tool before using it extensively. I can surely tinker with it and give it a try. Will report back if that solves what I intend to do. Thanks! – Phoenix Aug 06 '21 at 09:01
  • Be careful with `eval`, however. Its use for this case is probably not the best idea. By the way, why turning the `-x` option on and off on demand is not an option? – Renaud Pacalet Aug 06 '21 at 09:08
  • If I enabled `-x`, it would pump out everything to STDOUT to my understanding. This would no longer provide a clean output to the user. Though I have not tried running it inside a command substitution where the output is captured in a variable. However, apart from outputting the commands and results, which is what I actually want, it will also introduce new characters (namely "+") at the beginning of each line as well as itself (`+ set +x`) when disabling it again. If possible, I would like to avoid that. – Phoenix Aug 06 '21 at 09:34
  • What I suggested was just to turn `-x` on before the command you are interested in, and off just after. And unseting `PS4` suppresses the `+`. So `PS4=; set -x; ; set+x` should do almost what you want (except for the `set +x` that will be logged too). Of course, you'll have to redirect everything else elsewhere with some `exec ` commands. – Renaud Pacalet Aug 06 '21 at 09:50
  • Thanks! I can experiment with that as well and see if the result is pleasing. While there are possibly few who can truly say they know bash, I am for sure still learning. I knew that there were "PS1" through "PS4", but readily only knew the purpose of "PS1" and "PS2" (I guess some more `man bash` is in order). If `set +x` is really the only thing left, I can possibly "sed" that out of the log at the end. Just want to avoid going through the log extensively to make it readable. Would possibly defeat its purpose of being verbose. ;-) – Phoenix Aug 06 '21 at 10:02
  • See my answer for a proposal of use of redirections to automate all this, plus clean up the logs such that you will not even need to post-process them. – Renaud Pacalet Aug 06 '21 at 10:59

2 Answers2

4

You could play with redirections, switch the x option on and off on demand, unset PS4 to get rid of the leading + , and define log_on and log_off functions for easier coding. Something like this:

$ cat script.sh
#!/usr/bin/env bash

function log_on {
  exec 3>&1 4>&2
  exec &> >( sed -E '/^(set \+x|log_off)$/d' >> file.log )
  ps4=$PS4
  PS4=
  set -x
}

function log_off {
  set +x
  exec 1>&3 2>&4
  PS4=$ps4
}

echo something not logged
log_on
echo something logged
log_off
echo something else not logged
$ rm -f file.log
$ ./script.sh
something not logged
something else not logged
$ cat file.log
echo something logged
something logged

The exec <redirection> commands look a bit cryptic (as most redirections) but they are rather simple:

  • exec 3>&1 4>&2 makes copies of file descriptors fd1 and fd2 (stdout and stderr by default) to be able to restore these in log_off. After this fd3 and fd4 are copies of fd1 and fd2, respectively. Pick other fd than 3 or 4 if you already use them.

  • exec &> >( sed ... ) redirect fd1 and fd2 to the standard input of a sed command.

  • The sed command sed -E '/^(set \+x|log_off)$/d' >> file.log deletes lines containing only set + or log_off and appends its output to file.log. Without this sed command you would always see the two following lines:

      log_off
  set +x

    in your logs, after a group of logged commands.

  • exec 1>&3 2>&4 restores fd1 and fd2 from their copies in fd3 and fd4.

The rest is straightforward: save PS4 in ps4 such that it can be restored, enable/disable the x option. This should be easy to adapt or extend if needed.

The x option displays the simple commands separately. It breaks pipes, for instance. If you prefer a command log that looks more like the commands you wrote you can replace set -/+x by set -/+v.

Renaud Pacalet
  • 25,260
  • 3
  • 34
  • 51
  • Merci professeur! I tried your example and it generally worked. However, piped commands are line-broken instead of using the pipe. Reading the bash man page, it appears that this may be the intended behavior for `set +x` as it expands each "simple command". So `echo something logged | sed "s/logged/locked/"` will become two lines. Trying to wrap my head around now how this could be reversed. – Phoenix Aug 06 '21 at 13:36
  • Oh, just use `-v/+v` instead of `-x/+x`. I edit my answer accordingly. – Renaud Pacalet Aug 06 '21 at 13:41
  • I don't want to disappoint, but with `-v` it does no longer expand any variables in the command line to their values. :/ – Phoenix Aug 06 '21 at 13:47
  • I even tried `-vx`, but that made matters worse. ;-) – Phoenix Aug 06 '21 at 13:48
  • Hmm. What you're asking for seams very difficult and/or a bit underspecified. What would you like to log when there is a command substitution, for instance? Say `echo $(seq 3)`? `seq` is itself a command. Shall it be logged too as such? Or do you want to see only `echo $(seq 3)`? Or `echo` followed by the expansion of `$(seq 3)`? But then how do you want to see it? One 3 consecutive lines? And what about function calls? I do not see much other choices than simple, expanded commands (`-x`) or the original shell input lines (`-v`). What else do you have in mind? – Renaud Pacalet Aug 06 '21 at 13:55
  • You make a good point. The intention was to see the (main) command "as is" with their variables (and substitutions) expanded, so one could see if the reason of a failure was an incorrect value. Maybe I can fill an associated array with the variable names as key and then use one log function with `-x` to dump the variables alongside their values and the command with `-v` using that array. – Phoenix Aug 06 '21 at 14:22
0

IMHO this has already been answered here:

For simplicity the set linux command is what you need. set -x or set -v

Dominique
  • 16,450
  • 15
  • 56
  • 112
tsdogs
  • 36
  • 2
  • This would contradict with "the script should have a clean output" to my understanding as it will output everything onto STDOUT. Hence I stated that `set -x` would not be a good solution. – Phoenix Aug 06 '21 at 08:21