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

+1

+1

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

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

Ah you're right, my bad

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

+1

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

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

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

+1

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!

+1

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.

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

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.

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(

+1

This is an absolute must. Please do something about this:) We (docker-mailserver/docker-mailserver) are heavily reliant on Supervisor.

Just sharing to those on the thread how I tackled this issue. I have 2 processes running in a Docker container and I need to see their timestamps and delineate between the two processes. This is what I was able to get to work:

Original:

command=node cctail/dist/cctail.js %(ENV_CCTAIL_ARGS)s

Edited:

command=sh -c "node cctail/dist/cctail.js %(ENV_CCTAIL_ARGS)s \ 
  | awk '{ print strftime(\"cctail:\ %%Y-%%m-%%d\ %%H:%%M:%%S\ -\"), $0 }'";

This was a really cumbersome workaround, and one that took a while to get right, given all of the necessary character escaping. I agree with everyone on this thread that Supervisor should provide customized log formatting.

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

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.

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.

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

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

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

+1

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

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

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.

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

+1

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.

+1

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

+1

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

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

+1