Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Open
wants to merge 10 commits into
base: main
Choose a base branch
from

Conversation

the-c0d3r
Copy link

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.

@the-c0d3r the-c0d3r changed the title Option to prepend timestamp to stdout and stderr log file with config. Option to prepend timestamp to stdout and stderr log file with config. Implements #553 Feb 9, 2021
@the-c0d3r the-c0d3r changed the title Option to prepend timestamp to stdout and stderr log file with config. Implements #553 Option to prepend timestamp to stdout and stderr log file with config. Resolves #553 Feb 9, 2021
@mnaberez
Copy link
Member

mnaberez commented Feb 9, 2021

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
Copy link
Author

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
Copy link
Member

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
Copy link

waiting

@the-c0d3r
Copy link
Author

the-c0d3r commented Mar 18, 2021

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
Copy link
Member

mnaberez commented Mar 20, 2021

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
Copy link

ZPascal commented Mar 16, 2022

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
Copy link
Author

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
Copy link
Author

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
Copy link
Member

mnaberez commented Mar 26, 2022

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
Copy link

ZPascal commented Apr 18, 2022

@the-c0d3r Thank you for the detailed explanation.

@SergeySetti
Copy link

Ok, when?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Development

Successfully merging this pull request may close these issues.

5 participants