I'm trying to add timestamp to stdout and stderr of process running by supervisord. I've created bash script that wrap the program command line -

#!/bin/bash

# set piped processes to be killed when script is killed
set -o pipefail

# Function to generate a timestamp with milliseconds
timestamp() {
    echo -n "$(date "+%Y-%m-%d %H:%M:%S.$(date +%N | cut -c1-3)")"
}

# Run the binary, prepend timestamps to stdout and stderr
exec "$@" 2> >(while IFS= read -r line; do echo "$(timestamp) $line" >&2; done) \
                  | while IFS= read -r line; do echo "$(timestamp) $line"; done

and this is the conf file -

[program:alert_mgr]
command = %(ENV_bindir)s/wrap_timestamp.sh %(ENV_python3exec)s %(ENV_pythonflags)s -m cnm.services.alert_mgr
environment=MALLOC_ARENA_MAX=4
autostart = true
autorestart = true
priority = 300
oom_score_adj = -500
stopwaitsecs = 2
stdout_logfile=%(ENV_logdir)s/alert_mgr_stdout.log
stdout_logfile_maxbytes=100MB
stdout_logfile_backups=0
stderr_logfile=%(ENV_logdir)s/alert_mgr_stderr.log
stderr_logfile_maxbytes=100MB
stderr_logfile_backups=0

it looks like it does attach time stamp to both log files, but now supervisord trigger 4 processes 1 main and 3 sub instead of 1 main process -

ps aux | grep alert
redisla+ 57104  0.0  0.0   3848  2592 ?        S    23:39   0:00 /bin/bash /opt/redislabs/bin/wrap_timestamp.sh /opt/redislabs/bin/python3 -O -m cnm.services.alert_mgr
redisla+ 57105  0.5  1.0 240952 81304 ?        Sl   23:39   0:03 alert_mgr
redisla+ 57106  0.0  0.0   3848  1324 ?        S    23:39   0:00 /bin/bash /opt/redislabs/bin/wrap_timestamp.sh /opt/redislabs/bin/python3 -O -m cnm.services.alert_mgr
redisla+ 57107  0.0  0.0   3848  1644 ?        S    23:39   0:00 /bin/bash /opt/redislabs/bin/wrap_timestamp.sh /opt/redislabs/bin/python3 -O -m cnm.services.alert_mgr

and when i call supervisorctl stop alert_mgr, it stops only the first sub process and not the main alert_mgr (57105)

i've searched for solutions for that issue but couldn't find something that works ...

whould be happy to know how can i solve this ...

I'm trying to add timestamp to stdout and stderr of process running by supervisord. I've created bash script that wrap the program command line -

#!/bin/bash

# set piped processes to be killed when script is killed
set -o pipefail

# Function to generate a timestamp with milliseconds
timestamp() {
    echo -n "$(date "+%Y-%m-%d %H:%M:%S.$(date +%N | cut -c1-3)")"
}

# Run the binary, prepend timestamps to stdout and stderr
exec "$@" 2> >(while IFS= read -r line; do echo "$(timestamp) $line" >&2; done) \
                  | while IFS= read -r line; do echo "$(timestamp) $line"; done

and this is the conf file -

[program:alert_mgr]
command = %(ENV_bindir)s/wrap_timestamp.sh %(ENV_python3exec)s %(ENV_pythonflags)s -m cnm.services.alert_mgr
environment=MALLOC_ARENA_MAX=4
autostart = true
autorestart = true
priority = 300
oom_score_adj = -500
stopwaitsecs = 2
stdout_logfile=%(ENV_logdir)s/alert_mgr_stdout.log
stdout_logfile_maxbytes=100MB
stdout_logfile_backups=0
stderr_logfile=%(ENV_logdir)s/alert_mgr_stderr.log
stderr_logfile_maxbytes=100MB
stderr_logfile_backups=0

it looks like it does attach time stamp to both log files, but now supervisord trigger 4 processes 1 main and 3 sub instead of 1 main process -

ps aux | grep alert
redisla+ 57104  0.0  0.0   3848  2592 ?        S    23:39   0:00 /bin/bash /opt/redislabs/bin/wrap_timestamp.sh /opt/redislabs/bin/python3 -O -m cnm.services.alert_mgr
redisla+ 57105  0.5  1.0 240952 81304 ?        Sl   23:39   0:03 alert_mgr
redisla+ 57106  0.0  0.0   3848  1324 ?        S    23:39   0:00 /bin/bash /opt/redislabs/bin/wrap_timestamp.sh /opt/redislabs/bin/python3 -O -m cnm.services.alert_mgr
redisla+ 57107  0.0  0.0   3848  1644 ?        S    23:39   0:00 /bin/bash /opt/redislabs/bin/wrap_timestamp.sh /opt/redislabs/bin/python3 -O -m cnm.services.alert_mgr

and when i call supervisorctl stop alert_mgr, it stops only the first sub process and not the main alert_mgr (57105)

i've searched for solutions for that issue but couldn't find something that works ...

whould be happy to know how can i solve this ...

• bash
• stdout
• supervisord
• stderr

1 Answer 1

how can i solve this

Run the other pipeline in process substitution too.

ts() {
  while IFS= read -r line; do echo "$(timestamp) $line"; done
} 
"$@" > >(ts) 2> >(ts >&2)

Your echo $(timestamp) looks very slow. echo $(echo -n $(cmd)) is just cmd without a newline, but it's two subprocesses. You could do something along the following in pure Bash, but it ended complicated:

ts() {
  while IFS= read -r line; do
      now=$EPOCHREALTIME
      printf "%(%Y-%m-%d %H:%M:%S.%M)T.%03d %s\n"  ${now%%.*} $((10#${now##*.}/1000)) "$line"
  done
}

But my experience with while read line is that Bash by itself is slow to do that. Instead, see alternatives https://unix.stackexchange/a/26729/209955 .

set piped processes to be killed when script is killed
set -o pipefail

That is not the meaning of pipefail. pipefail means that the pipe expression a | b | c exit status is the first command with nonzero exit status. It is just the exit code, it affects the value of $? after the pipeline. pipefail has no effect on killing. See man bash. There are jobs in bash. See https://unix.stackexchange/questions/124127/kill-all-descendant-processes