It appears as though dovecot doesn't like syslogd being restarted.

My system.log is rotated nightly followed by a pretty standard
syslogd restart...

if [ -f /var/run/syslog.pid ]; then kill -HUP $(cat /var/run/ syslog.pid | head -1);

It appears from that point on dovecot no longer writes to mail.log.
Killing and restarting dovecot causes it to write to the log again.

If you care to take a stab at a suggestion, please kind in mind that
I'm having to run dovecot with the -F switch (see below).

Thanks in advance,

B. Bodger Ronkonkoma, NY

On May 11, 2007, at 6:17 AM, Bruce Bodger wrote:

Please disregard the below reported bug report. I experienced the
same problem today and this time "sleep" was not involved.

I rotate mail.log weekly. This morning I noticed that dovecot was
no longer logging to mail.log although, again, it was running fine.

Is it possible that dovecot has a problem after midnight and will
not log with the new day? Something is stopping dovecot from
logging and it appears that it might have to do with change of the
day?

This is a new (two day old) dovecot installation. Coming from uw- imap. It never exhibited this problem.

Thank you, B. Bodger Ronkonkoma, NY

On May 10, 2007, at 7:34 AM, Bruce Bodger wrote:

...

Version: dovecot --version: 1.0.0 OS: OS X - 10.4.9 Architecture: G5 Dual/1.8Ghz

Had a fairly normal time correction last night: May 9 20:56:56 G518X2 ntpd[219]: time set -1.212733 s

Which dovecot duly noted: May 9 20:56:56 G518X2 dovecot: auth(default): Time just moved
backwards by 1 seconds. I'll sleep now until we're back in present.

This morning all of the dovecot processes are running fine but
dovecot has stopped logging. (I have modified nothing in
dovecot.conf relative to logging: dovecot logs to syslog using the
"mail" syslog_facility.)

ps -aux | grep dovecot root 53 0.0 -0.0 27772 544 ?? Ss 4:23PM
0:04.69 /usr/local/sbin/dovecot -F root 79 0.0 -0.0 28176 556 ?? S 4:23PM
0:03.21 dovecot-auth dovecot 9548 0.0 -0.0 27780 496 ?? S 7:12AM
0:00.05 imap-login dovecot 9631 0.0 -0.0 27780 500 ?? S 7:17AM
0:00.03 imap-login dovecot 9632 0.0 -0.0 27780 500 ?? S 7:17AM
0:00.03 imap-login

I am starting dovecot via OS X's launchdaemon facility thus the "- F" command line switch requirement.

Sending a "kill -HUP" to the process did not get it to start logging. Sending a "Kill -9" to the process forced a restart and logging
began again.

ps -aux | grep dovecot root 9738 0.0 -0.0 27772 540 ?? Ss 7:26AM
0:00.03 /usr/local/sbin/dovecot -F root 9739 0.0 -0.0 28176 544 ?? S 7:26AM
0:00.02 dovecot-auth dovecot 9740 0.0 -0.0 27780 500 ?? S 7:26AM
0:00.02 imap-login dovecot 9751 0.0 -0.0 27780 500 ?? S 7:27AM
0:00.01 imap-login dovecot 9762 0.0 -0.0 27780 500 ?? S 7:27AM
0:00.01 imap-login

Before posting this bug I compared v1.0.0's /src/lib/ioloop.c to
that in the nightly snapshot and saw no adjustments in, what I
presumed to be, the relevant portion of the code.

Output of "dovecot -n"

protocols: imap ssl_disable: yes disable_plaintext_auth: no login_dir: /usr/local/var/run/dovecot/login login_executable: /usr/local/libexec/dovecot/imap-login first_valid_uid: 490 mail_extra_groups: mail mail_location: mbox:~/Library/Mail/IMAP:INBOX=/var/mail/%u:INDEX=% h/Library/Mail/DOVECOT.indexes dotlock_use_excl: yes auth default: mechanisms: plain login passdb: driver: pam userdb: driver: passwd

Thank you.

Thank you very much, Charles. I have resorted to that workaround
(restarting dovecot) which does, indeed, work. I just wanted to
document the situation since dovecot's behavior in this regard is
unlike other imap servers.

Best regards, Bruce

On May 11, 2007, at 8:27 AM, Charles Marcus wrote:

Bruce Bodger wrote:

...

It appears as though dovecot doesn't like syslogd being restarted.

Hmmm... could this possibly be a fix, or at least a workaround?

www.dovecot.org/list/dovecot/2004-November/005219.html

--

Best regards,

Charles

At 7:04 AM -0400 5/11/07, Bruce Bodger imposed structure on a stream of electrons, yielding:

It appears as though dovecot doesn't like syslogd being restarted.

That's probably not it.

The whole point of syslog is for individual message sources (e.g. dovecot) to not have to worry about where the messages go.

This is actually at least partly a bug in the MacOS X syslog implementation. With 10.4, Apple decided that neither traditional BSD syslog or syslog-ng was what they wanted, so they reimplemented from the ground up and did a lousy job.

My system.log is rotated nightly followed by a pretty standard syslogd restart...

if [ -f /var/run/syslog.pid ]; then kill -HUP $(cat /var/run/syslog.pid | head -1);

That's not a restart, it is a 'hangup' signal that will make a normal syslogd reread the config file. The problem with that is that when you do it, Apple's syslogd completely stops logging. I'm not sure why that is, but I've been working around it since the 10.4 release and Apple has had a bug report for that long.

If you actually kill syslogd with a TERM or KILL signal it will be restarted by launchd and it should log properly.

It appears from that point on dovecot no longer writes to mail.log.

Dovecot was never writing to mail.log. Syslogd was, and it was broken.

Killing and restarting dovecot causes it to write to the log again.

That's a bit surprising, since if you are using syslog, the dovecot processes don't know anything about the specific log files that syslog is using. The implication of what you are seeing is that the breakage is between dovecot and syslogd, and that restarting dovecot fixes it.

-- Bill Cole
bill@scconsult.com

On Fri, 2007-05-11 at 10:57 -0400, Bruce Bodger wrote:

Applied the patch, recompiled v1.1.0 using same line to config as
before..

./configure --with-ssldir=/System/Library/OpenSSL --with-ssl=openssl

Sorry... no change: does not fix it.

In that case there's nothing I can do. You'll just have to restart Dovecot. Or make it log directly into files instead of using syslog (log_path setting).

At 9:54 AM -0400 9/8/07, Bruce Bodger wrote:

Timo,

Compiled and installed v1.0.4 this morning on OS X 10.4.10...

./configure --with-ssldir=/System/Library/OpenSSL --with-ssl=openssl --with-notify=kqueue

...all is well.

I wonder if you remember the conversation that we had back on May 11. This was the situation where after the system ran nightly maintenance dovecot info stopped appearing in mail.log (I'm being careful how I state that: I believe you had surmised a problem with Apple's syslogd implementation.

If you run them, you would also note that Postfix, BIND, INN, and MIMEDefang all suffer from the same problem. In fact, I don't know of any non-Apple daemon that does not have this problem. I believe it is a bug in Apple's ground-up re-implementation of system logging in Tiger.

The condition is a silent failure for clients of the syslog subsystem using the BSD standard (i.e. portable) API. There's no feedback from the system to alert a caller to syslog() that the call didn't actually result in anything getting written to a log file, since the call returns no value and doesn't set errno. The only way a program could know of the failure would be to trace the syslog configuration and look for whether messages are appearing, then take action (probably calling closelog() and openlog()) as needed. Alternatively, a program might just do that as housekeeping every few minutes, but that seems like an awfully busy bit of accommodation for a broken OS subsystem.

In short: Apple needs to fix this. It's their bug, created by their decision to replace traditional BSD syslog with fresh new code written by people who couldn't be bothered to look at what had been done by others before them or at how their code interoperated with existing widely used software. Just like the embarrassment called LaunchD, ASL is the replacement of a *very mature* set of software with software that in the same metaphor might best be termed *infantile*. Hopefully both will at least reach juvenile or adolescent status in Leopard...

-- Bill Cole
bill@scconsult.com

On Sat, 2007-09-08 at 12:36 -0400, Bill Cole wrote:

The only way a program could know of the failure would be to trace the syslog configuration and look for whether messages are appearing, then take action (probably calling closelog() and openlog()) as needed.

I already sent a patch that did closelog() when reopening logs, but that didn't help. I forgot openlog(), but that shouldn't be needed..