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

Add ability to specify log format #553

Open
mminer opened this issue Jan 8, 2015 · 58 comments · May be fixed by #1426
Open

Add ability to specify log format #553

mminer opened this issue Jan 8, 2015 · 58 comments · May be fixed by #1426
Labels

Comments

@mminer
Copy link

mminer commented Jan 8, 2015

It would be helpful to have control over the format of the log output. For inspiration, other tools that allow you to customize the log format include Celery (CELERYD_LOG_FORMAT) and Gunicorn (access_log_format).

@SebastianSzturo
Copy link

👍
Need heroku-style application name and output in one line.

@avli
Copy link

avli commented Mar 25, 2015

+1

@silvexis
Copy link

+1

@LouisKottmann
Copy link

Any reason why this was closed? I'd like to remove the timestamps because syslog-ng does it already for example (and my log aggregator can understand syslog-ng ones)

+1

@pearofducks
Copy link

@LouisKottmann - it looks like this is still open for Supervisor, and closed in the dokku-supervisord project (which just referenced this issue)

@LouisKottmann
Copy link

Ah you're right, my bad

@lciti
Copy link

lciti commented Nov 29, 2016

+1
circusd, a similar project, also has it: stdout_stream.time_format = %Y-%m-%d %H:%M:%S

@Fire-Brand
Copy link

+1

@nicbou
Copy link

nicbou commented Aug 3, 2017

We really need this. It's currently impossible to use supervisord with some logging tools because the format is completely random and inflexible.

@boblozano
Copy link

For us it's not impossible, just awkward. Of course because it's logging, the reminders are constant.

@samirop
Copy link

samirop commented Oct 12, 2017

Still no news regarding this? We'd need at least a timestamp in log lines

@Kimamisa
Copy link

+1

5 similar comments
@harpcio
Copy link

harpcio commented Jan 3, 2018

+1

@isavl
Copy link

isavl commented Feb 20, 2018

+1

@dingman
Copy link

dingman commented Feb 20, 2018

+1

@Yucheng-Ren
Copy link

+1

@keune
Copy link

keune commented Mar 29, 2018

+1

@ScottConnor-COT
Copy link

ScottConnor-COT commented Apr 11, 2018

I was able to get this working by using a shell script in the following manner (definitely would be nice to not have to do this workaround but it worked)

#!/bin/bash WORKER_NAME=$1 bash -c 'php -f /PATH_TO_WORKER/"$WORKER_NAME".php | ts '"'"'[%d-%b-%Y %H:%M:%S]'"'"
and then the supervisor config command can look as such

[program:worker] command=/PATH_TO_SHELL/run-worker.sh "WORKER_NAME"
P.S. to use ts you may need to get the moreutils package if not already installed. Cheers!

@Adam2Marsh
Copy link

+1

@the-c0d3r
Copy link

the-c0d3r commented Oct 13, 2018

To all those people who needs this feature, here's a quick patch for it. Just apply the patch, or modify the code manually, or use my forked repo. Then do a manual installation by python setup.py install.
Supervisor timestamp patch - Gist, My Forked Repo

I referred to this #333 PR and modified the code where the logger formatter is defined. I'm not sure why that PR wasn't merged to the master. I only added timestamp, I didn't add in other config option or anything.

If someone can tell me what's required, I can probably put in some time for a proper PR for this. I would also really like to have this feature in the master branch, so I don't have to keep deploying old supervisor version. Please advice, thanks.

@bikong0411
Copy link

command=/path/to/command 2>&1 | sed "s/^/[$(date +%Y%m%d\ %T)] /" >/var/log/supervisord/worker_log;
use sed command add time format

@HristoA
Copy link

HristoA commented Dec 20, 2019

supervisord uses the % character for its own format strings in the config file.
So right syntax is:
command=/path/to/command 2>&1 | sed "s/^/[$(date +%%Y%%m%%d\ %%T)] /" > /var/log/supervisord/worker_log;

In case that after supervisorctl restart log wile is not field most probably executor user=xxx don`t have a permission to write this logfile.

@axil
Copy link

axil commented May 21, 2020

Let's give it another try: PR #1349
While this PR is under consideraction, @the-c0d3r's patch is still valid:

--- /usr/lib/python2.7/dist-packages/supervisor/dispatchers.py~ 2016-08-03 05:33:42.000000000 +0100
+++ /usr/lib/python2.7/dist-packages/supervisor/dispatchers.py 2020-05-21 09:04:14.502793781 +0100
@@ -87,7 +87,7 @@
         if logfile:
             maxbytes = getattr(process.config, '%s_logfile_maxbytes' % channel)
             backups = getattr(process.config, '%s_logfile_backups' % channel)
-            fmt = '%(message)s'
+            fmt = '%(asctime)s %(message)s'
             if logfile == 'syslog':
                 fmt = ' '.join((process.config.name, fmt))
             self.mainlog = process.config.options.getLogger(

@the-c0d3r
Copy link

the-c0d3r commented Feb 7, 2021

@mnaberez could you please advice me on writing the tests for the PR #333 , which adds those timestamp prepend options? The code base is quite big and I'm getting lost in the unit tests.

Edit 1:

I have been looking at the unit testing code, PR #333 modifies PEventListenerDispatcher, which has the tests at tests/test_dispatcher.py.

I have been trying to write tests under the PEventListenerDispatcherTests, but it looks like none of the tests look at the log files.

Then I looked at POutputDispatcherTests, which tests the output dispatchers. But they are also not testing the output log files. The tests are using DummyLogger, which does not trigger PEventListenerDispatcher's childlog logger.
Any advice on this? Do I need to write another logger class to bypass the dummy logger and make it use the childlog logger?

Edit 2:

It looks like PR #333 change the wrong class. I migrate it to POutputDispatcher and I have managed to get the test working, partially.

    def test_stdout_prepend_timestamp(self):
        from supervisor import loggers
        from supervisor.loggers import getLogger

        options = DummyOptions()
        options.getLogger = getLogger # actually use real logger
        options.loglevel = loggers.LevelsByName.TRAC

        logfile = '/tmp/foo'
        config = DummyPConfig(options, 'process1', '/bin/process1',
                              stdout_logfile=logfile, stdout_prepend_timestamp=True)
        process = DummyProcess(config)
        dispatcher = self._makeOne(process)
        dispatcher.output_buffer = 'a'
        dispatcher.record_output()

        [x.flush() for x in dispatcher.childlog.handlers]
        with open(logfile, 'rb') as f:
            self.assertEqual(b'testing stdout prepend timestamp', f.read())

With this, I get the timestamp, but the log output is a bit malformed. I believe this is due to my lack of understanding on what data format is required for record_output() function.

The following is the unittest output. Even though I only passed the word "a" into the output buffer, it seem to have additional stuff in it. The logger formatter also looks correct to me formatter = '%(asctime)s: %(message)s'

Traceback (most recent call last):
  File "/opt/pycharm/plugins/python/helpers/pycharm/teamcity/diff_tools.py", line 32, in _patched_equals
    old(self, first, second, msg)
  File "/usr/lib/python3.9/unittest/case.py", line 831, in assertEqual
    assertion_func(first, second, msg=msg)
  File "/usr/lib/python3.9/unittest/case.py", line 824, in _baseAssertEqual
    raise self.failureException(msg)
AssertionError: b'testing stdout prepend timestamp' != b'2021-02-07 20:41:25,122 a2021-02-07 20:41[447 chars]4: a'

I have tried feeding in the data with the token as well. Similar results.

from supervisor.events import ProcessCommunicationEvent
BEGIN_TOKEN = ProcessCommunicationEvent.BEGIN_TOKEN
END_TOKEN = ProcessCommunicationEvent.END_TOKEN
data = BEGIN_TOKEN + 'a' + END_TOKEN

Any chance you could explain on what's wrong, how to make it work, or any docs for me to read?
My forked branch in case you need to check my commits.

@mnaberez
Copy link
Member

mnaberez commented Feb 7, 2021

@mnaberez could you please advice me

I don't have any particular advice or insight, sorry. You may know as much about it as I do at this point. I did not write the code in question. It might be best to direct questions about its design to its author.

@the-c0d3r
Copy link

Hi @mnaberez, thanks for your response.
But I would like to know more about the supervisor internals. The PR works fine as it only change the logger's formatter. I suspect that I am lacking in understanding of supervisor's internal message structure, leading to malformed messages in the test output.

For example, I'm not sure if dispatcher.output_buffer is expecting just a string from the program output or does it require specific format, such as the BEGIN_TOKEN and END_TOKEN. Can you point me to a unit test where it test the logger's output to file? I tried to follow the test that I found, but I'm not sure if that's the correct test.

Is there anywhere I can read about supervisor's internals? I find the documentation to be very lacking in the code.

@mnaberez
Copy link
Member

mnaberez commented Feb 8, 2021

Is there anywhere I can read about supervisor's internals? I find the documentation to be very lacking in the code.

I am not aware of anything.

@the-c0d3r
Copy link

@mnaberez
I have created a PR for this issue at PR #1407. Please review and merge, thanks.

@mnaberez
Copy link
Member

mnaberez commented Feb 9, 2021

@mnaberez
I have created a PR for this issue at PR #1407. Please review and merge, thanks.

As I explained above, I'm not an expert on this code, sorry. I left a comment on the PR that it seems to break the supervisorctl fg mode feature. I think I'm getting pulled into this discussion because I closed the original PR. There are some PRs that do not meet standards (completely broken, no tests at all, no response to feedback after a long time). I believe the original PR for this was one of those, which is why I closed it. Beyond that, I'm afraid I can't provide useful input on how to redesign this and I probably should not approve changes unless I learn how the dispatcher subsystem works. There are other committers who do understand it, so I'll leave the PR open for them or until I can understand it.

Note: For visitors who came here for this ticket ("Add ability to specify a log format"), PR #1407 mentioned immediately above probably would not close this issue. This issue seems to be people requesting to be able to specify the log format, but PR #1407 is about optionally prepending a timestamp with a fixed format.

@the-c0d3r
Copy link

@mnaberez Thanks for the review. Sorry I dragged you into this. Yes, it's because I saw you reviewing the 2 previous PRs related to this issue, and you are a member of "supervisor" organisation.

I assumed all unit tests passed, since travis build all passed. I didn't know it break anything. I will test out the feature you mentioned supervisorctl fg, which I have not used before.

I just realised that you are right about the Issue and the PR. I also noticed that there is a similar PR #1197 which seem to fit this issue better.

I don't know what the maintainers/committers opinion on this, but personally I think it would benefit to have two options, one to customise the log format (be it down to specific timestamp formatting, levels, etc), and another to just prepend timestamp (which IMHO should have been implemented as default from the start).

In the meantime while awaiting for other maintainers/committers, I will look into the feature that you mentioned, and into how I can change my PR to support the aforementioned first option.

@FazlanFarook
Copy link

+1

1 similar comment
@sudheeshkottay
Copy link

+1

@allinws
Copy link

allinws commented Jan 4, 2022

+1 - 5 years? Come on guys, we need this, especially with docker when you want to put all logs from all applications into stdout - it becomes impossible to distinguish the apps when you have a number of them.

@amks1
Copy link

amks1 commented Jan 20, 2022

So we still can't disable supervisord-added timestamps in the logs?

@ReallyLiri
Copy link

To all those people who needs this feature, here's a quick patch for it. Just apply the patch, or modify the code manually, or use my forked repo. Then do a manual installation by python setup.py install. Supervisor timestamp patch - Gist, My Forked Repo

I referred to this #333 PR and modified the code where the logger formatter is defined. I'm not sure why that PR wasn't merged to the master. I only added timestamp, I didn't add in other config option or anything.

If someone can tell me what's required, I can probably put in some time for a proper PR for this. I would also really like to have this feature in the master branch, so I don't have to keep deploying old supervisor version. Please advice, thanks.

This didn't work well for me, as only once every X lines I'd get the prefix. It seems the call to formatter is not done for each line, but for a buffer of some size.

In the meantime as a complementary solution I edited the handler in supervisor/loggers.py to split message lines before calling emit. See https://stackoverflow.com/a/38458877/1236401

But this still won't work well if message is truncated from previous line.

@capital-G
Copy link

Another hack I started using is creating another program which simple tails all logs via parallel (copied from https://unix.stackexchange.com/a/337779) - by using awk or else it would be also possible to add a date string to the output.

[program:logging]
command=parallel --tagstring "{}:" --line-buffer tail -f {} ::: foo.log bar.log baz.log
user=root
directory=/root/
priority=40
startsecs=10
autostart=true
autorestart=true
stdout_logfile=/dev/fd/1
stdout_logfile_maxbytes=0
redirect_stderr=true

generates something like this

sound_1        | janus.log:     Creating new session: 2439449193897045; 0x7f6fc4cf00a0
sound_1        | janus.log:     Creating new handle in session 2439449193897045: 497279846078378; 0x7f6fc4cf00a0 0x7f6fc6a70970
sound_1        | janus.log:     [497279846078378] Creating ICE agent (ICE Full mode, controlling)
sound_1        | janus.log:     [497279846078378] The DTLS handshake has been completed
sound_1        | janus.log:     [janus.plugin.streaming-0x7f6fc4bddd60] WebRTC media is now available

@Gourds
Copy link

Gourds commented Mar 21, 2022

+1

1 similar comment
@AntoineBachet
Copy link

+1

@DavidAntliff
Copy link

I was able to get this working by using a shell script in the following manner (definitely would be nice to not have to do this workaround but it worked)

#!/bin/bash WORKER_NAME=$1 bash -c 'php -f /PATH_TO_WORKER/"$WORKER_NAME".php | ts '"'"'[%d-%b-%Y %H:%M:%S]'"'" and then the supervisor config command can look as such

[program:worker] command=/PATH_TO_SHELL/run-worker.sh "WORKER_NAME" P.S. to use ts you may need to get the moreutils package if not already installed. Cheers!

One issue with this is that piping a program's output to ts results in buffering, such that you may not see output in the logs for quite some time... especially if your program's output is infrequent.

Having spent several hours trying to change the buffering using stdbuf and other tricks, I've not reached a working solution. There's something about the way supervisord runs processes that makes piping through ts impractical. And worse, stopping a managed process doesn't seem to flush the logs, and any buffered data that hasn't been written to the log simply disappears.

@LVladymyr
Copy link

+1

@vstelmakh
Copy link

For ones who are looking for some workaround. Here is how I ended with prefixing output with process name:

supervisor.conf

[program:process-1]
command=/path-to/prefix-output.sh executable1

[program:process-2]
command=/path-to/prefix-output.sh executable2

prefix-output.sh

#!/bin/bash

# Get prefix from SUPERVISOR_PROCESS_NAME environment variable
printf -v PREFIX "%-10.10s" "${SUPERVISOR_PROCESS_NAME}"

# Prefix stdout and stderr
exec 1> >( perl -ne '$| = 1; print "'"${PREFIX}"' | $_"' >&1)
exec 2> >( perl -ne '$| = 1; print "'"${PREFIX}"' | $_"' >&2)

exec "$@"

Example output

process-1  | Some process output
process-2  | Very important message
...

Inspired and mostly copy-pasted from: https://serverfault.com/a/946271

@oponcea-dn
Copy link

+1

@sscarduzio
Copy link

This should be added as a core feature in supervisord, it's not a job for weird wrapper scripts.

@j0wns
Copy link

j0wns commented Jun 9, 2023

For ones who are looking for some workaround. Here is how I ended with prefixing output with process name:

supervisor.conf

[program:process-1]
command=/path-to/prefix-output.sh executable1

[program:process-2]
command=/path-to/prefix-output.sh executable2

prefix-output.sh

#!/bin/bash

# Get prefix from SUPERVISOR_PROCESS_NAME environment variable
printf -v PREFIX "%-10.10s" "${SUPERVISOR_PROCESS_NAME}"

# Prefix stdout and stderr
exec 1> >( perl -ne '$| = 1; print "'"${PREFIX}"' | $_"' >&1)
exec 2> >( perl -ne '$| = 1; print "'"${PREFIX}"' | $_"' >&2)

exec "$@"

Example output

process-1  | Some process output
process-2  | Very important message
...

Inspired and mostly copy-pasted from: https://serverfault.com/a/946271

This was an excellent starting point for adding a static name to subprocess output.

I wanted improve the consistency for readability and parsing by adding per-line time stamps that matched supervisord's format: '2023-06-09 17:25:36,778 INFO Included extra file "/etc/supervisor/conf.d/example.conf" during parsing'

This perl in the following heredoc will calculate a timestamp at run time for each line that is sent to stdout and stderr

# https://github.com/Supervisor/supervisor/issues/553
# Refer: https://stackoverflow.com/questions/26032541/how-to-get-system-time-in-nano-seconds-in-perl
cat << 'EOF' > /opt/supervisord/prefix-output.sh
#!/bin/bash

# Prefix outputs with Time Stamp and Process Name
exec 1> >( perl -ne 'use Time::HiRes qw(time); use POSIX qw( strftime ); $time=time; $microsecs = ($time - int($time)) * 1e3; $| = 1; printf( "%s,%03.0f '"${SUPERVISOR_PROCESS_NAME}"' %s", strftime("%Y-%m-%d %H:%M:%S", gmtime($time)), $microsecs, $_);' >&1)
exec 2> >( perl -ne 'use Time::HiRes qw(time); use POSIX qw( strftime ); $time=time; $microsecs = ($time - int($time)) * 1e3; $| = 1; printf( "%s,%03.0f '"${SUPERVISOR_PROCESS_NAME}"' %s", strftime("%Y-%m-%d %H:%M:%S", gmtime($time)), $microsecs, $_);' >&2)

exec "$@"
EOF

Example Output running within a docker container

container  | 2023-06-09 17:39:30,474 INFO spawned: 'env' with pid 61
container  | 2023-06-09 17:39:30,474 INFO success: env entered RUNNING state, process has stayed up for > than 0 seconds (startsecs)
container  | 2023-06-09 17:39:30,507 env SUPERVISOR_GROUP_NAME=init
container  | 2023-06-09 17:39:30,507 env SUPERVISOR_SERVER_URL=unix:///var/run/supervisor.sock

dantefromhell added a commit to dantefromhell/humhub-docker that referenced this issue Jan 31, 2024
@kadirgun
Copy link

+1

4 similar comments
@mrtzgh
Copy link

mrtzgh commented May 23, 2024

+1

@CRCinAU
Copy link

CRCinAU commented May 25, 2024

+1

@Pre-Z
Copy link

Pre-Z commented Aug 14, 2024

+1

@RDonii
Copy link

RDonii commented Sep 9, 2024

+1

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

Successfully merging a pull request may close this issue.