Improve logging significantly – color is back! by georglauterbach · Pull Request #1758 · docker-mailserver/docker-mailserver

georglauterbach · 2021-01-21T09:32:41Z

This one is important to me. What happened:

I added an environment variable which enables users to set the log-level
I re-enabled color :D See yourself:

Enhanced some output that did not use _notify but just echo
Improved supervisor configuration
Got rid of (confusing) CRIT messages during startup

Here is why you should like and approve it:

First of all, the log right now is all over the place. See:

2021-01-21 00:01:16,377 CRIT Supervisor is running as root.  Privileges were not dropped because no user is specified in the config file.  If you intend to run as root, you can set user=root in the config file to avoid this message.
2021-01-21 00:01:16,377 INFO Included extra file "/etc/supervisor/conf.d/saslauth.conf" during parsing
2021-01-21 00:01:16,377 INFO Included extra file "/etc/supervisor/conf.d/supervisor-app.conf" during parsing
2021-01-21 00:01:16,394 INFO RPC interface 'supervisor' initialized
2021-01-21 00:01:16,394 CRIT Server 'unix_http_server' running without any HTTP authentication checking
2021-01-21 00:01:16,394 INFO supervisord started with pid 8
2021-01-21 00:01:17,398 INFO spawned: 'mailserver' with pid 11
 
2021-01-21 00:01:17,444 INFO success: mailserver entered RUNNING state, process has stayed up for > than 0 seconds (startsecs)
[ TASKLOG ]  Welcome to docker-mailserver!
 
[ TASKLOG ]  Initializing setup
[ TASKLOG ]  Checking configuration
[ TASKLOG ]  Configuring mail server
Cert found in /etc/letsencrypt/acme.json for mail.Domain.com

[ TASKLOG ]  Startin misc
[ TASKLOG ]  Starting mail server
2021-01-21 00:01:21,967 INFO spawned: 'cron' with pid 264
2021-01-21 00:01:21,968 INFO success: cron entered RUNNING state, process has stayed up for > than 0 seconds (startsecs)
cron: started

Let's break this down. At the moment, there is no color in our logs. With this PR, this is not the case anymore. More importantly, there are two CRIT messages, which absolutely should not be there:

2021-01-21 00:01:16,377 CRIT Supervisor is running as root.  Privileges were not dropped because no user is specified in the config file.  If you intend to run as root, you can set user=root in the config file to avoid this message.

2021-01-21 00:01:16,394 CRIT Server 'unix_http_server' running without any HTTP authentication checking

This was due to a sloppy supervisor configuration. This is now fixed. The configuration file has been cleaned up and improved.

Someone introduced a plain echo here:

Cert found in /etc/letsencrypt/acme.json for mail.itbsd.com

This is now a _notify. (Note here that I had to adjust the unit tests to not check against our own logs. We never do that and we can't because of a limitation of ANSI-escape parsing. That is absolutely fine though.)

You can see that I changed the supervisor log-level to warn. Before you light this PR up, let me explain:) Currently, you will see this next to our log:

2021-01-21 00:01:16,377 INFO Included extra file "/etc/supervisor/conf.d/saslauth.conf" during parsing
2021-01-21 00:01:16,377 INFO Included extra file "/etc/supervisor/conf.d/supervisor-app.conf" during parsing
2021-01-21 00:01:16,394 INFO RPC interface 'supervisor' initialized
2021-01-21 00:01:16,394 INFO supervisord started with pid 8
2021-01-21 00:01:17,398 INFO spawned: 'mailserver' with pid 11
 
2021-01-21 00:01:17,444 INFO success: mailserver entered RUNNING state, process has stayed up for > than 0 seconds (startsecs)

This will now not be printed anymore. Is this a problem? I argue it's not:

This will always work, because it is baked into the Dockerfile:

2021-01-21 00:01:16,377 INFO Included extra file "/etc/supervisor/conf.d/saslauth.conf" during parsing
2021-01-21 00:01:16,377 INFO Included extra file "/etc/supervisor/conf.d/supervisor-app.conf" during parsing

If it's not, a warning is issued and you will see it. Then for

2021-01-21 00:01:16,394 INFO RPC interface 'supervisor' initialized

it's the same line of reasoning. If you#re interested in the PIDs:

2021-01-21 00:01:16,394 INFO supervisord started with pid 8
2021-01-21 00:01:17,398 INFO spawned: 'mailserver' with pid 11

run docker exec mail ps. The last message:

2021-01-21 00:01:17,444 INFO success: mailserver entered RUNNING state, process has stayed up for > than 0 seconds (startsecs)

has the same line of reasoning as the first two arguments. Now, when start-mailserver.sh is running, the default log-level will be warn if you want (and by default). But now you have the choice. You could set it back to info.

I'd like to see this merged as fast as possible :D

georglauterbach · 2021-01-21T16:14:21Z

Just FYI: This is what it will look like with log-level warn:

Please note that I used _notify in user-patches.sh too and I changed Amavis' log level in the user-patches.sh - that's why you're not seeing it here.

wernerfred

LGTM 👍🏻

I personally like the changes you introduced to color up the output and allow setting the supervisor loglevel.

Regarding "to not break backwards compatability" my opinion (apart from this PR/change but in general) is that major releases are justified by breaking changes so if you/we think keeping the default by "warn" from now on then there is no better timing as now as we are close to 8.0.0.

georglauterbach · 2021-01-21T20:02:32Z

LGTM 👍🏻

I personally like the changes you introduced to color up the output and allow setting the supervisor loglevel.

Regarding "to not break backwards compatability" my opinion (apart from this PR/change but in general) is that major releases are justified by breaking changes so if you/we think keeping the default by "warn" from now on then there is no better timing as now as we are close to 8.0.0.

I like this idea. I will adjust this PR to use warn by default.

Closes #1768 and sadly partly reverts #1758

casperklein · 2021-01-31T23:46:39Z

Now, when start-mailserver.sh is running, the default log-level will be warn if you want (and by default). But now you have the choice. You could set it back to info

Doesn't work for me. I've set it to info, but don't get any info logs. For example on container stop, there should be stuff like:

2021-02-01 00:40:02,464 WARN received SIGTERM indicating exit request
2021-02-01 00:40:02,464 INFO waiting for rsyslog, postfix, cron, amavis, changedetector, fail2ban, opendkim, opendmarc, dovecot, mailserver to die
2021-02-01 00:40:02,464 INFO stopped: mailserver (terminated by SIGTERM)

Can someone confirm this?

georglauterbach · 2021-01-31T23:49:08Z

Now, when start-mailserver.sh is running, the default log-level will be warn if you want (and by default). But now you have the choice. You could set it back to info

Doesn't work for me. I've set it to info, but don't get any info logs. For example on container stop, there should be stuff like:
2021-02-01 00:40:02,464 WARN received SIGTERM indicating exit request

2021-02-01 00:40:02,464 INFO waiting for rsyslog, postfix, cron, amavis, changedetector, fail2ban, opendkim, opendmarc, dovecot, mailserver to die

2021-02-01 00:40:02,464 INFO stopped: mailserver (terminated by SIGTERM)
Can someone confirm this?

Do you see at least the WARN message? Can you then set SUPERVISOR_LOGLEVEL to something ridiculous, like some random string, and see if a warning is printed that the values is not recognised?

casperklein · 2021-01-31T23:55:45Z

Yes. The warn message is always there. And the modification to supervisord.conf seems to be successful:

root@mail:/# grep loglevel /etc/supervisor/supervisord.conf
loglevel = info

casperklein · 2021-01-31T23:57:38Z

Can you then set SUPERVISOR_LOGLEVEL to something ridiculous

That leads to this startup warning as expected:

[ WARNING ] SUPERVISOR_LOGLEVEL value 'aendeavor-told-me-so' unknown. Defaulting to 'warn'

georglauterbach · 2021-01-31T23:59:39Z

Good. Then I suspect supervisord needs more than an update? Maybe it needs to be restarted too?

casperklein · 2021-01-31T23:59:44Z

The Problem is, that supervisord does not seem to recognize the change.

Additional to supervisorctl update, I've also tried this without success: supervisorctl reread

georglauterbach · 2021-02-01T00:02:48Z

The Problem is, that supervisord does not seem to recognize the change.

Additional to supervisorctl update, I've also tried this without success: supervisorctl reread

Is there something like a self-restart command? I investigate too, but I'll do this in a few hours:)

casperklein · 2021-02-01T00:03:23Z

Maybe it needs to be restarted too?

I am not sure, but I don't think that is possible, as supervisor is our PID1. Killing it will stop the container.

georglauterbach · 2021-02-01T09:25:21Z

Maybe it needs to be restarted too?

I am not sure, but I don't think that is possible, as supervisor is our PID1. Killing it will stop the container.

No, dumb-init is - you created the PR yourself :D

But, according to this forum post, ~~first a re-read and then an update should do it. I will test this.~~ You already tried this, I just now read it. I will try what the systemctl restart supervisord does

georglauterbach · 2021-02-01T10:26:39Z

Oh my - supervisorctl reload seems to have worked...

I will provide a PR.

casperklein · 2021-02-01T10:44:20Z

No, dumb-init is - you created the PR yourself :D

Yes, I know. Take a look at this 😉

USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
root         1  0.0  0.0   2144   740 ?        Ss   11:39   0:00 /usr/bin/dumb-init -- supervisord -c /etc/supervisor/supervisord.conf

casperklein · 2021-02-01T10:48:43Z

the default log-level will be warn if you want (and by default). But now you have the choice. You could set it back to info.

BTW Thats not 100% true. It's not fully possible to get the old behavior back. INFO messages that would appear before start-mailserver.sh modifies supervisord.conf are lost.

georglauterbach · 2021-02-01T11:57:31Z

the default log-level will be warn if you want (and by default). But now you have the choice. You could set it back to info.

BTW Thats not 100% true. It's not fully possible to get the old behavior back. [...]

I made this point clear from the start:

You can see that I changed the supervisor log-level to warn. Before you light this PR up, let me explain:) Currently, you will see this next to our log:

2021-01-21 00:01:16,377 INFO Included extra file "/etc/supervisor/conf.d/saslauth.conf" during parsing
2021-01-21 00:01:16,377 INFO Included extra file "/etc/supervisor/conf.d/supervisor-app.conf" during parsing
2021-01-21 00:01:16,394 INFO RPC interface 'supervisor' initialized
2021-01-21 00:01:16,394 INFO supervisord started with pid 8
2021-01-21 00:01:17,398 INFO spawned: 'mailserver' with pid 11

2021-01-21 00:01:17,444 INFO success: mailserver entered RUNNING state, process has stayed up for > than 0 seconds (startsecs)

This will now not be printed anymore. Is this a problem? I argue it's not...

Only these 5 INFO messages are "lost", and I believe this to be fine.

#1778 should take care of the rest.

casperklein · 2021-02-01T12:39:56Z

Sorry for not being more precise. I had read it and it's fine. But I thought that should be mentioned in the README?

When someone sets a log level, then the assumption probably is, that no messages are suppressed in that log level. For example you set it to debug for some reason, you could be wondering why there a no debug message from the startup until start-mailserver is invoked.

georglauterbach · 2021-02-01T13:31:06Z

Sorry for not being more precise. I had read it and it's fine. But I thought that should be mentioned in the README?

When someone sets a log level, then the assumption probably is, that no messages are suppressed in that log level. For example you set it to debug for some reason, you could be wondering why there a no debug message from the startup until start-mailserver is invoked.

We could add this to mailserver.env, if you want. I think it's not that important, since this project is not debugging supervisord, and the messages are only for PIDs and loaded conf files, which cannot be altered before anyway:)

improve logging significantly

cd55cf9

georglauterbach added pr/need review kind/question Someone asked a question - feel free to answer priority/high area/scripts labels Jan 21, 2021

georglauterbach added this to the v8.0.0 milestone Jan 21, 2021

georglauterbach requested a review from a team January 21, 2021 09:32

georglauterbach self-assigned this Jan 21, 2021

georglauterbach requested review from casperklein and wernerfred and removed request for a team January 21, 2021 15:56

wernerfred approved these changes Jan 21, 2021

View reviewed changes

Comment thread target/supervisor/supervisord.conf

Comment thread target/supervisor/supervisord.conf

georglauterbach added 3 commits January 21, 2021 21:08

now defaulting to warn

cbeeba4

final adjustments

9eaddbc

correcting not-escaped $ in sed

63a68b2

georglauterbach removed the pr/need review label Jan 22, 2021

georglauterbach merged commit 324ee8e into docker-mailserver:master Jan 22, 2021

georglauterbach deleted the logging branch January 22, 2021 09:03

wernerfred added a commit that referenced this pull request Jan 25, 2021

Strip all ANSI escape sequences from child log files

11bbda4

Closes #1768 and sadly partly reverts #1758

georglauterbach mentioned this pull request Feb 1, 2021

correct application of the new SUPERVISOR_LOGLEVEL variable #1787

Merged

polarathene reviewed Oct 15, 2021

View reviewed changes

Comment thread test/mail_ssl_letsencrypt.bats

This was referenced Sep 30, 2023

[TODO]: Migrate away from legacy docker user + group #3557

Open

feature request: Vector for log management #3561

Open

Uh oh!

Conversation

georglauterbach commented Jan 21, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

georglauterbach commented Jan 21, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

wernerfred left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

georglauterbach commented Jan 21, 2021

Uh oh!

casperklein commented Jan 31, 2021

Uh oh!

georglauterbach commented Jan 31, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

casperklein commented Jan 31, 2021

Uh oh!

casperklein commented Jan 31, 2021

Uh oh!

georglauterbach commented Jan 31, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

casperklein commented Jan 31, 2021

Uh oh!

georglauterbach commented Feb 1, 2021

Uh oh!

casperklein commented Feb 1, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

georglauterbach commented Feb 1, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

georglauterbach commented Feb 1, 2021

Uh oh!

casperklein commented Feb 1, 2021

Uh oh!

casperklein commented Feb 1, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

georglauterbach commented Feb 1, 2021

Uh oh!

casperklein commented Feb 1, 2021

Uh oh!

georglauterbach commented Feb 1, 2021

Uh oh!

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

4 participants

georglauterbach commented Jan 21, 2021 •

edited

Loading

georglauterbach commented Jan 21, 2021 •

edited

Loading

georglauterbach commented Jan 31, 2021 •

edited

Loading

georglauterbach commented Jan 31, 2021 •

edited

Loading

casperklein commented Feb 1, 2021 •

edited

Loading

georglauterbach commented Feb 1, 2021 •

edited

Loading

casperklein commented Feb 1, 2021 •

edited

Loading