Milter-greylist

This morning I noticed that milter-greylist (4.5.16 running on OmniOS 
r151016) had stopped writing to its dedicated log file on the 13th. 
I restarted it and then it resumed writing the log file.  It seems 
that milter-greylist did not resume writing its log file on a day when 
I was doing some experimentation with various configurations and 
restarting it often.

Are there any known issues with milter-greylist writing its log file?

The directory ownership is sufficient that milter-greylist is able to 
write its greylist.db in the same directory, bug the log file is owned 
by root.

Thanks,

Bob
-- 
Bob Friesenhahn
bfriesen@..., http://www.simplesystems.org/users/bfriesen/
GraphicsMagick Maintainer,    http://www.GraphicsMagick.org/

17 \u0444\u0435\u0432\u0440\u0430\u043b\u044f 2016�\u0433. 15:13:09 CET, "Bob Friesenhahn bfriesen@... [milter-greylist]" <milter-greylist@yahoogroups.com> \u043f\u0438\u0448\u0435\u0442:
>This morning I noticed that milter-greylist (4.5.16 running on OmniOS 
>r151016) had stopped writing to its dedicated log file on the 13th. 
>I restarted it and then it resumed writing the log file.  It seems 
>that milter-greylist did not resume writing its log file on a day when 
>I was doing some experimentation with various configurations and 
>restarting it often.
>
>Are there any known issues with milter-greylist writing its log file?
>
>The directory ownership is sufficient that milter-greylist is able to 
>write its greylist.db in the same directory, bug the log file is owned 
>by root.
>
>Thanks,
>
>Bob

Actually, you "should not have to" restart it for new configs: when processing a new message, MGL starts by verifying if its config is up to date, and reloads/reapplies it if it is not. It has a check (-c ?) CLI option to validate a new candidate config before you feed it into/replace the live cfg file, so the service is uninterrupted as you change it.

Regarding logs: do you start MGL as root and then drop (via config user), or start as non-root, or is this close to what you changed recently? ;)

Jim

Jim
--
Typos courtesy of K-9 Mail on my Samsung Android

On Wed, 17 Feb 2016, Jim Klimov jimklimov@... [milter-greylist] wrote:
>
> Actually, you "should not have to" restart it for new configs: when 
> processing a new message, MGL starts by verifying if its config is 
> up to date, and reloads/reapplies it if it is not. It has a check 
> (-c ?) CLI option to validate a new candidate config before you feed 
> it into/replace the live cfg file, so the service is uninterrupted 
> as you change it.

Thanks for this info.  I did not know it auto-reloaded the config 
file.  Instead I have been restarting the service.

> Regarding logs: do you start MGL as root and then drop (via config 
> user), or start as non-root, or is this close to what you changed 
> recently? ;)

It is started as root and then drops to a safe user via the config 
file.  This aspect has not changed lately.

What has been changing is experimentation with SPF handling based on 
your own ideas posted to this list in 2013.

Bob
-- 
Bob Friesenhahn
bfriesen@..., http://www.simplesystems.org/users/bfriesen/
GraphicsMagick Maintainer,    http://www.GraphicsMagick.org/

On Wed, 17 Feb 2016, Jim Klimov jimklimov@... [milter-greylist] wrote:
>>
>> Are there any known issues with milter-greylist writing its log file?

Today I noticed this in syslog after having just updated 
greylist.conf:

Feb 18 20:40:34 smtp milter-greylist: [ID 594051 mail.info] reloading config file "/etc/mail/greylist.conf"
Feb 18 20:40:34 smtp milter-greylist: [ID 133745 mail.error] fopen_ext: failed and descriptor 72 lost!
Feb 18 20:40:34 smtp milter-greylist: [ID 975932 mail.warning] cannot open ">>/var/milter-greylist/greylist.log" at line 15: out of stdio streams
Feb 18 20:40:34 smtp milter-greylist: [ID 994696 mail.info] reloaded config file "/etc/mail/greylist.conf" in 0.011320s

I am using version 4.5.16 on an OmniOS system (Solaris-based, 32-bit 
build), configured with the --enable-stdio-hack option.

It seems that not writing the log file is due to an actual bug. 
Perhaps it needs to reserve a spare file descriptor or there is a more 
severe problem.

There are only a couple of mail accounts here and it seems 
unreasonable that milter-greylist would be so busy to have exhausted 
all file descriptors (it did not look terribly busy at the time).

Bob
-- 
Bob Friesenhahn
bfriesen@..., http://www.simplesystems.org/users/bfriesen/
GraphicsMagick Maintainer,    http://www.GraphicsMagick.org/

On Thu, 18 Feb 2016, Bob Friesenhahn bfriesen@... [milter-greylist] wrote:
>
> It seems that not writing the log file is due to an actual bug.
> Perhaps it needs to reserve a spare file descriptor or there is a more
> severe problem.
>
> There are only a couple of mail accounts here and it seems
> unreasonable that milter-greylist would be so busy to have exhausted
> all file descriptors (it did not look terribly busy at the time).

It seems that the problem is that the "stdio-hack" works by 
pre-acquiring (almost) 256 file handles and then doing:

         /* we have a low descriptor */
         close(descriptor);

         /* after releasing it, we hope the following fopen() call can aquire it ... */
         stream = fopen(path, mode);

It then tests if 'stream' uses the same descriptor as the one from the 
pool which was just closed.  The returned file handle should 
apparently still work, but the original has been lost from the pool. 
However, it did not seem like the file handle was actually usable 
since milter-greylist says it was not.

I will explore the preload hack described at:

http://www.oracle.com/technetwork/server-storage/solaris10/stdio-256-136698.html

and stop using --enable-stdio-hack.

Bob
-- 
Bob Friesenhahn
bfriesen@..., http://www.simplesystems.org/users/bfriesen/
GraphicsMagick Maintainer,    http://www.GraphicsMagick.org/

Bob Friesenhahn bfriesen@... [milter-greylist]
<milter-greylist@yahoogroups.com> wrote:

> Feb 18 20:40:34 smtp milter-greylist: [ID 975932 mail.warning] cannot open
> ">>/var/milter-greylist/greylist.log" at line 15: out of stdio streams

There may be a stream leak. I understand you get if after reloading the
configuration automatically. Do you see the message if you restart
milter-greylist on configuration change?

-- 
Emmanuel Dreyfus
http://hcpnet.free.fr/pubz
manu@...

On Fri, 19 Feb 2016, manu@... [milter-greylist] wrote:

> Bob Friesenhahn bfriesen@... [milter-greylist]
> <milter-greylist@yahoogroups.com> wrote:
>
>> Feb 18 20:40:34 smtp milter-greylist: [ID 975932 mail.warning] cannot open
>> ">>/var/milter-greylist/greylist.log" at line 15: out of stdio streams
>
> There may be a stream leak. I understand you get if after reloading the
> configuration automatically. Do you see the message if you restart
> milter-greylist on configuration change?

No.  As far as I am aware, it has only happened due to automatic 
reload.

This time it happened while I was watching the syslog output.

Bob
-- 
Bob Friesenhahn
bfriesen@..., http://www.simplesystems.org/users/bfriesen/
GraphicsMagick Maintainer,    http://www.GraphicsMagick.org/

On Fri, 19 Feb 2016, manu@... [milter-greylist] wrote:

> Bob Friesenhahn bfriesen@... [milter-greylist]
> <milter-greylist@yahoogroups.com> wrote:
>
>> Feb 18 20:40:34 smtp milter-greylist: [ID 975932 mail.warning] cannot open
>> ">>/var/milter-greylist/greylist.log" at line 15: out of stdio streams
>
> There may be a stream leak. I understand you get if after reloading the
> configuration automatically. Do you see the message if you restart
> milter-greylist on configuration change?

I saw the problem again shortly after updating the configuration file. 
Otherwise mail seems to be received ok so if has somehow leaked, it is 
not causing serious harm.

The problem may be specific to the log file.

This system has 8 cores, 16 hyper-threads, and is very lightly loaded, 
so it is pretty easy for some other thread to get in edgewise. 
Voluntary context switching is most likely to occur during file I/O 
related events.

Bob
-- 
Bob Friesenhahn
bfriesen@..., http://www.simplesystems.org/users/bfriesen/
GraphicsMagick Maintainer,    http://www.GraphicsMagick.org/

Bob Friesenhahn bfriesen@... [milter-greylist]
<milter-greylist@yahoogroups.com> wrote:

> I saw the problem again shortly after updating the configuration file.
> Otherwise mail seems to be received ok so if has somehow leaked, it is
> not causing serious harm.

Well, if autoreload is broken for Solaris, we could just disable it on
that platform. You could still restart.

-- 
Emmanuel Dreyfus
http://hcpnet.free.fr/pubz
manu@...

Yesterday I rebuilt milter-greylist 4.5.16 without --enable-stdio-hack 
and started it with a script which starts like:

MAXFILES=8000 # Maximum number of open files
# Large number of open files solution
# 
http://www.oracle.com/technetwork/server-storage/solaris10/stdio-256-136698.html
LD_PRELOAD_32=/usr/lib/extendedFILE.so.1
export LD_PRELOAD_32
ulimit -n $MAXFILES

This should allow milter-greylist to be able to open 8000 files, which 
seems like plenty to me.

Today I updated greylist.conf and observed the same problem occuring 
except that first it reported that it was out of stdio streams, and 
then it reported that it reloaded the config file:

Feb 21 14:16:09 smtp milter-greylist: [ID 594051 mail.info] reloading 
config file "/etc/mail/greylist.conf"
Feb 21 14:16:09 smtp milter-greylist: [ID 975932 mail.warning] cannot 
open ">>/var/milter-greylist/greylist.log" at line 15: out of stdio 
streams
Feb 21 14:16:09 smtp milter-greylist: [ID 994696 mail.info] reloaded 
config file "/etc/mail/greylist.conf" in 0.010098s

A little while after this I observed milter-greylist start logging in 
verbose mode even though verbose was not enabled in the configuration 
file.

Bob
-- 
Bob Friesenhahn
bfriesen@..., http://www.simplesystems.org/users/bfriesen/
GraphicsMagick Maintainer,    http://www.GraphicsMagick.org/

Bob Friesenhahn bfriesen@... [milter-greylist]
<milter-greylist@yahoogroups.com> wrote:

> MAXFILES=8000 # Maximum number of open files

If I recall correctly, the stream limitation on Solaris is not a probem
with open file descriptors. This is why an option to book low numbered
file descriptors was contributed. If it was as simple as using ulimit
-n, we would not need it.

-- 
Emmanuel Dreyfus
http://hcpnet.free.fr/pubz
manu@...

On Mon, 22 Feb 2016, manu@... [milter-greylist] wrote:

> Bob Friesenhahn bfriesen@... [milter-greylist]
> <milter-greylist@yahoogroups.com> wrote:
>
>> MAXFILES=8000 # Maximum number of open files
>
> If I recall correctly, the stream limitation on Solaris is not a probem
> with open file descriptors. This is why an option to book low numbered
> file descriptors was contributed. If it was as simple as using ulimit
> -n, we would not need it.

The Solaris problem is that the stdio FILE structure only uses 8 bits 
to store the file descriptor.  However, these shell commands:

   LD_PRELOAD_32=/usr/lib/extendedFILE.so.1
   export LD_PRELOAD_32

preloads a module which updates the stdio implementation to use a 
different FILE member for the file descriptors, which is much larger.

Regardless, the same issue occurs with both the stdio-hack and 
without.  There are no other errors pertaining to file handles so I 
think that this issue must be specifically due to a bug in the log 
file re-opening code.

Bob
-- 
Bob Friesenhahn
bfriesen@..., http://www.simplesystems.org/users/bfriesen/
GraphicsMagick Maintainer,    http://www.GraphicsMagick.org/

On Mon, Feb 22, 2016 at 09:35:53PM +0100, manu@... [milter-greylist] wrote:
> Bob Friesenhahn bfriesen@... [milter-greylist]
> <milter-greylist@yahoogroups.com> wrote:
> 
> > MAXFILES=8000 # Maximum number of open files
> 
> If I recall correctly, the stream limitation on Solaris is not a probem
> with open file descriptors. This is why an option to book low numbered
> file descriptors was contributed. If it was as simple as using ulimit
> -n, we would not need it.

Just for completeness
http://milter-greylist.wikidot.com/solaris-filedescriptor-limitation