CODEWITHSUNDEEP
bashstdoutsupervisordstderr
Meni Katz
Meni Katz

Reputation: 11

add timestamp to stdout and stderr logs of program running in supervisord

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 ...

Upvotes: 1

Views: 44

Answers (1)

KamilCuk
KamilCuk

Reputation: 141698

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.com/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.com/questions/124127/kill-all-descendant-processes

Upvotes: 2

Related Questions