Restore redirection of output streams in bash

Question

I have a script named run.sh and another script named download-and-run.sh which downloads something and then calls the first one. I may also call run.sh independently.

I want to print timestamp of each message logged to the stdout/stderr when running these scripts. To do so, I added exec > >(ts '[%R:%S %x %Z]') 2>&1 in the beginning of both of the scripts. Then, when I call download-and-run.sh it prints the date twice, which is expected.

It's worth to mention that I need to use set -x to track the variables, etc. for debugging purposes. For the record, help set says:

-x Print commands and their arguments as they are executed.

Let's say these are my files:

run.sh

#!/usr/bin/env bash
exec > >(ts '[%R:%S %x %Z]') 2>&1
set -x
echo Hi from run.sh

download-and-run.sh

#!/usr/bin/env bash
exec > >(ts '[%R:%S %x %Z]') 2>&1
set -x
echo This is a curl command
./run.sh

I get this output when running download-and-run.sh (Note the bash prompt ($) before starting printing timestamps; I guess it may indicate something):

$ ./download-and-run.sh
$ [19:40:48 04/21/2022 EDT] + echo This is a curl command
[19:40:48 04/21/2022 EDT] This is a curl command
[19:40:48 04/21/2022 EDT] + ./run.sh
[19:40:48 04/21/2022 EDT] ++ exec
[19:40:48 04/21/2022 EDT] +++ ts '[%R:%S %x %Z]'
[19:40:48 04/21/2022 EDT] [19:40:48 04/21/2022 EDT] ++ echo Hi from run.sh
[19:40:48 04/21/2022 EDT] [19:40:48 04/21/2022 EDT] Hi from run.sh

---

To solve having two timestamps, I found this answer to revert back the original stdout/stderr streams in download-and-run.sh just before calling ./run.sh so that the double piping to ts is fixed, but the following modified version will strangely print calling ./run.sh at the first of the output like it's called before anything.

Modified download-and-run.sh:

#!/usr/bin/env bash
exec 3>&1 4>&2  # Saving stdout and stderr in fd=3,4
exec > >(ts '[%R:%S %x %Z]') 2>&1
set -x
echo This is a curl command
exec >&3 2>&4  # Reverting back normal stdout and stderr from pipe
./run.sh

This is the output (Again, note the bash prompt ($) before starting printing timestamps; I guess it may indicate something):

$ ./download-and-run.sh
+ ./run.sh
++ exec
+++ ts '[%R:%S %x %Z]'
$ [19:42:32 04/21/2022 EDT] + echo This is a curl command
[19:42:32 04/21/2022 EDT] This is a curl command
[19:42:32 04/21/2022 EDT] + exec
[19:42:32 04/21/2022 EDT] ++ echo Hi from run.sh
[19:42:32 04/21/2022 EDT] Hi from run.sh

This output has two problems:

1. It doesn't have timestamps in some of the messages.
2. It prints some commands out of order of their execution.

How can I fix them to have only a single timestamp printed before logs when I call download-and-run.sh?

---

Here's what I expect to have (there may be some commands added in the scripts to fix the issue which may be printed because of set -x and it's okay):

$ ./download-and-run.sh
[19:40:48 04/21/2022 EDT] + echo This is a curl command
[19:40:48 04/21/2022 EDT] This is a curl command
[19:40:48 04/21/2022 EDT] + ./run.sh
[19:40:48 04/21/2022 EDT] ++ echo Hi from run.sh
[19:40:48 04/21/2022 EDT] Hi from run.sh

and for run.sh solely:

$ ./run.sh
[19:40:48 04/21/2022 EDT] + echo Hi from run.sh
[19:40:48 04/21/2022 EDT] Hi from run.sh

Answer 1

You could use an environment variable to determine if timestamps are already enabled. e.g.:

run.sh

#!/usr/bin/env bash
if [ -z "${TIMESTAMPS_ENABLED}" ]; then
  exec > >(ts '[%R:%S %x %Z]') 2>&1
fi
set -x
echo Hi from run.sh

download-and-run.sh

#!/usr/bin/env bash
exec > >(ts '[%R:%S %x %Z]') 2>&1
export TIMESTAMPS_ENABLED="YES"
set -x
echo This is a curl command
./run.sh

To answer your question about "out of sequence" printing, You have to understand how the scripts make use of child processes to do the work. Hopefully this diagram will help:

Process
1        Start "download_and_run.sh"
1        Redirect output
  2        Start "ts '[%R:%S %x %Z]'" (this takes some time)
1        set -x
1        echo This is a curl command (trace & output sent to Process 2)
1        Undo redirection
1        ./run.sh (trace sent to console)
    3        Start "./run.sh"
1        Wait for Process 3 to finish
    3        Redirect output (trace sent to console)
      4        Start "ts '[%R:%S %x %Z]'" (takes some time & trace sent to console)
    3        set -x
    3        echo Hi from run.sh (trace & output sent to Process 4)
    3        exit
1        exit
  2        write output to console
  2        exit
      4      write output to console
      4      exit

This gives the following output from each process:

Process
1       + ./run.sh
3       ++ exec
4       +++ ts '[%R:%S %x %Z]'
  At this point, process 3 and process 4 exit, returning a prompt to the user
        $
2       [19:42:32 04/21/2022 EDT] + echo This is a curl command
2       [19:42:32 04/21/2022 EDT] This is a curl command
   Process 2 exits
4       [19:42:32 04/21/2022 EDT] + exec
4       [19:42:32 04/21/2022 EDT] ++ echo Hi from run.sh
4       [19:42:32 04/21/2022 EDT] Hi from run.sh
   Process 4 exits

It is important to realize that the two 'ts' commands run in separate processes and take some time to initialize. Process 1 and Process 2 write their output to a pipe and do not wait for the other end to read that output. So they can each exit before the process at the other end of their pipe has finished initializing.

Run_and_download.sh does wait for run.sh to finish, but not the 'ts' command.