Option to prepend timestamp to stdout and stderr log file with config. Resolves #553

[the-c0d3r]

This is to revive the PR #333 , but this time, I have added proper unit testing for the output dispatcher.

I retained all the original changes from the PR #333 and merged to current master, and added 2 new unit test functions and 4 new tests to the existing test function.

Let me know if the unit testing is insufficient, or is there anything else to change.

Related Issue: #553 Add ability to specify log format (6 years old issue)
Related PR: #1349 (closed due to lack of unit tests)
Credits to @nirmalc for the original code change.

[mnaberez]

I was asked to review and merge this, but I don't really understand this subsystem enough to do that. However, I did test it anyway, and it seems to break supervisorctl fgmode. I'll leave this open until one of the other committers who understands this subsystem can work on it, or perhaps a future time when I understand it.

[the-c0d3r]

Hi @mnaberez, may I ask what is the status with this PR?

Could you please tell me how it breaks supervisorctl fg?
Based on my brief testing on the fg mode, it doesn't seem to have an issue.

[mnaberez]

Hi @mnaberez, may I ask what is the status with this PR?

#1407 (comment)

Could you please tell me how it breaks supervisorctl fg?
Based on my brief testing on the fg mode, it doesn't seem to have an issue.

The timestamps are mixed into the output, making fg mode unusable.

[FazlanFarook]

waiting

[the-c0d3r]

Based on my testing with simple bash script and supervisorctl fg mode, I only get the timestamp if I set the stdout_prepend_timestamp to true. And when the timestamp is prepended, it also behaves as programmed.

I do not see an issue with this, maybe you can elaborate more on this?

[mnaberez]

I do not see an issue with this, maybe you can elaborate more on this?

I don't think most users would expect changing a logging option would cause unexpected output to be injected into fg mode. It would make using a lot of software under fg mode unusable. My opinion is that fg mode should probably work correctly regardless of which logging options are set.

[ZPascal]

Hi community,

thanks for the PR @the-c0d3r. I think it's a helpful feature, and we should solve the problem. Could you please explain how do you test the fg mode? Maybe we can solve the issue together and someone can merge the PR at the end of the process.

[the-c0d3r]

Hi @ZPascal,
I don't think that fg thing can be solved. I traced the supervisorctl's fg mode, it calls HTTP api that is hosted by the supervisord, which will actually open the log file of the process and send it to the stdout from supervisorctl. So the only way to make the prepended timestamp not affect the fg mode is to change supervisord's HTTP api to strip the timestamp when reading the log file, which I don't think is the way to go.

If you are looking for how to test the fg mode, here's how.
config.conf file content

[unix_http_server]
file=/tmp/supervisor.sock   ; the path to the socket file

[supervisord]
logfile=/tmp/supervisord.log ; main log file; default $CWD/supervisord.log
logfile_maxbytes=50MB        ; max main logfile bytes b4 rotation; default 50MB
logfile_backups=10           ; # of main logfile backups; 0 means none, default 10
loglevel=info                ; log level; default info; others: debug,warn,trace
pidfile=/tmp/supervisord.pid ; supervisord pidfile; default supervisord.pid
nodaemon=false               ; start in foreground if true; default false
silent=false                 ; no logs to stdout if true; default false
minfds=1024                  ; min. avail startup file descriptors; default 1024
minprocs=200                 ; min. avail process descriptors;default 200

[rpcinterface:supervisor]
supervisor.rpcinterface_factory = supervisor.rpcinterface:make_main_rpcinterface

[inet_http_server]
port = 127.0.0.1:9001

[supervisorctl]
serverurl=unix:///tmp/supervisor.sock ; use a unix:// URL  for a unix socket

[program:bash]
command=/tmp/test.sh
stdout_prepend_timestamp=true

/tmp/test.sh content

#!/bin/bash
while true; do
    echo "This is from test.sh $(date)";
    sleep 1;
done;

Run it as follows

supervisord -c config.conf
supervisorctl
> fg bash

---

As for the status of this PR, somewhere on the #553 , it was mentioned that this PR will not close it, as it only prepend timestamp, but the issue #553 is about specifying the log format. I will find some time to work on it and push the change for a customised timestamp format soon.

[the-c0d3r]

I have pushed a change that will allow one to specify the format of the timestamp to prepend.

stdout_prepend_timestamp=true
stdout_prepend_timestamp_format=%%Y-%%m-%%d; customise prepend timestamp to stdout log file (default %%Y-%%m-%%d %%H:%%M:%%S)

Since "Supervisor uses Python string interpolation when parsing the config file" (quoting from #291), we have to escape the % with double %%.
This is all I can do for this PR for now, as I have no idea how the fg mode is supposed to be fixed or whether it requires any fixes.

To the maintainer/reviewers, please let me know what else to be done for this PR to be merged. Thanks.

[mnaberez]

This is all I can do for this PR for now, as I have no idea how the fg mode is supposed to be fixed or whether it requires any fixes.

As I indicated above, I don't think users will accept unexpected output being injected into fg mode, so from my perspective, it requires fixes. I don't think we can add new features that break existing features. It would be nice to add the feature but it would have to work with the rest of the system.

People use fgmode often, e.g. just recently in #1494 a question about fg mode was posted. That screenshot in that issue shows a debugging session in fg mode, which I think would probably not be usable if this PR was merged and the user had the timestamp enabled. I think the implementation of fg mode would have to change if something like this PR was to be merged. Perhaps instead of tailing the logfile from disk (which would have timestamps mixed in), the daemon could keep a small circular buffer or use a temporary file for fg mode.

Another thing that would have to be checked if is a patch like this would also interfere with the events system. There are events emitted for process log output and these must not have unexpected output mixed it.

I was reading #553 (comment) and I believe the problem described in that comment may apply here as well. Depending on how/when the dispatcher flushes, the timestamp may not get added correctly.

[ZPascal]

@the-c0d3r Thank you for the detailed explanation.

[SergeySetti]

Ok, when?