[Raw Msg Headers][Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

Re: smtpserver bind() query and logfile problems



On Tue, Jan 25, 2005 at 06:01:14PM +0000, Darryl L. Miles wrote:
> I'm using the current CVS version of zmailer.
> 
> 1)
> 
> During startup of the SMTP server it always seems to try and bind to the 
> same addresses twice, the 2nd attempt always fails:
> 
> 00000000000#    000-setting up: bind(s=4, v4, addr='192.168.0.1' port=25)
> 00000000000#    000-setting up: bind(s=6, v4, addr='192.168.0.1' port=25)
> 00000000000#    000-bind(s=6, v4, port=25) failed; errno=Address already 
> in use
> 00000000000#    000-setting up: bind(s=6, v4, addr='192.168.0.1' port=465)
> 00000000000#    000-setting up: bind(s=7, v4, addr='192.168.0.1' port=465)
> 00000000000#    000-bind(s=7, v4, port=465) failed; errno=Address 
> already in use
> 00000000000#    000-started server pid 11196 at Sat, 22 Jan 2005 
> 16:14:11 +0000
> 
> Is this correct ?

Yes, correct but suboptimal.

It depends on how you have set up the service ports.
I have following:

PARAM BindSmtp          any6
PARAM BindSmtp          any
PARAM BindSmtpS         any6
PARAM BindSmtpS         any
PARAM BindSubmit        any6
PARAM BindSubmit        any

which results in this setup report:

000-setting up: bind(s=4, v6, addr='::' port=25)
000-setting up: bind(s=8, v6, addr='::' port=25)
000-bind(s=8, v6, port=25) failed; errno=Address already in use
000-setting up: bind(s=8, v4, addr='0.0.0.0' port=25)
000-setting up: bind(s=9, v4, addr='0.0.0.0' port=25)
000-bind(s=9, v4, port=25) failed; errno=Address already in use
000-setting up: bind(s=9, v6, addr='::' port=465)
000-setting up: bind(s=10, v6, addr='::' port=465)
000-bind(s=10, v6, port=465) failed; errno=Address already in use
000-setting up: bind(s=10, v4, addr='0.0.0.0' port=465)
000-setting up: bind(s=11, v4, addr='0.0.0.0' port=465)
000-bind(s=11, v4, port=465) failed; errno=Address already in use
000-setting up: bind(s=11, v6, addr='::' port=587)
000-setting up: bind(s=12, v6, addr='::' port=587)
000-bind(s=12, v6, port=587) failed; errno=Address already in use
000-setting up: bind(s=12, v4, addr='0.0.0.0' port=587)
000-setting up: bind(s=13, v4, addr='0.0.0.0' port=587)
000-bind(s=13, v4, port=587) failed; errno=Address already in use

Scratching my head...    zgetbindaddr() does parse IPv6 addresses
successfully, even when it is supposed not to..
Sockets matching properly for bound protocol addresses, I get:

000-setting up: bind(s=4, v6, addr='::' port=25)
000-setting up: bind(s=8, v4, addr='0.0.0.0' port=25)
000-setting up: bind(s=9, v6, addr='::' port=465)
000-setting up: bind(s=10, v4, addr='0.0.0.0' port=465)
000-setting up: bind(s=11, v6, addr='::' port=587)
000-setting up: bind(s=12, v4, addr='0.0.0.0' port=587)

Which is proper.



I am not entirely sure of why you see v4 address duplicates.
  ...
Aaahh...  I think you have:

PARAM BindSmtp          any
PARAM BindSmtpS         any

or perhaps that older configuration style of:

PARAM BindPort         25
PARAM BindAddress   iface:eth0
PARAM listen-ssmtp

(as you get non "0.0.0.0" address for binding) and the system
is at first called to create IPv6 socket (which your runtime
supports, but you don't tell to be ok with explicite 'any6'
bound address) but the registered IP address is IPv4 one, and
in such a case, the server socket creation does automagically
translate the call to IPv4 binding..
 ..
not anymore.


The  'iface:' magic is problematic in IPv6 case.
My code doesn't know how to extract correct IPv6 address in
every case from system.  I think presently it doesn't even
try...  Nor is it easy;  I do have code that can find addresses,
but see an example from zmailer.org  machine:

IPv4:       lo [127.0.0.1]
IPv4:     eth0 [62.78.96.67]
IPv6:       lo [IPv6:::1]
IPv6:   dummy0 [IPv6:2001:14b8:10:1::1]
IPv6:   dummy0 [IPv6:fe80::f843:29ff:fed2:ee82]
IPv6:     eth0 [IPv6:fe80::250:8dff:fef1:9fa]
IPv6:     sit1 [IPv6:fe80::3e4e:6043]
IPv6:     sit2 [IPv6:fe80::3e4e:6043]
IPv6:     sit3 [IPv6:2001:14b8:100:65::2]
IPv6:     sit3 [IPv6:fe80::3e4e:6043]

It really isn't all that trivial to know which address in given
interface to use.  Especially as in my case the real answer is
global scope  address of 'dummy0', not those link scope things
on eth* or sit* interfaces.     Using 'any6' and 'any' are way
simpler choices...


 
> 2)
> 
> I've been hunting a bug that has made all session logging by the smtp 
> server stop right after authentication.

I do agree that there is problematic code in reaper() routine.
I wonder why I added it..

> The closest I have got is that I use an external program to verify 
> authentication credentials (not SASL) with the "PARAM SMTP-auth-pipe" 
> option.  There are very few places that explicitly NULL the logfp 
> pointer, I think the reaper() code is cause in my case but I have not 
> got as far to verify it yet.
> 
> Linux STRACE output of the point.  "foobar" is the password sent to the 
> pipe.  close(3) is the logfile being closed AARRGGHH!.  Then I get a 
> strange open("") for a bogus filename (char *logfile points to environ 
> space, its not strdup()ed, also char *pidfile and *cfgfile the their 
> lifetimes seem short) maybe it re-opening the log.  The EACCES is 
> because the cwd() is /opt/zmailer/smtpserver.conf/ which is owned by a 
> user called zmailer, and smtpserver is running as daemon.
> 
> write(10, "foobar\n", 7)                = 7
> close(10)                               = 0
> munmap(0xb7f0b000, 4096)                = 0
> wait4(-1, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL) = 9982
> --- SIGCHLD (Child exited) @ 0 (0) ---

reaper() is running here..

> rt_sigprocmask(SIG_BLOCK, [CHLD], NULL, 8) = 0

This is  openlogfp()  call without 'SS' parameter...

> time([1106673578])                      = 1106673578

.. within it there is fclose(logfp)

> close(3)                                = 0
> munmap(0xb7f5b000, 131072)              = 0

.. and this open, which disturbs me immensely...

> open("in-addr.btopenworld.com AUTH LOGIN", O_WRONLY|O_APPEND|O_CREAT, 0644)
> = -1 EACCES (Permission denied)

This really doesn't look too good..   but it must be  openlogfp()
call with  NULL for 'SS', and 1 for 'insecure'.  

That open() should not be called, unless  *logfile  points to some
string somewhere, but is the pointer scrabled too badly in case of
this being run under signal handler ?

 ...

Aargh!   yes,   logfile   needs to be strdup()ed in  getopt()  processing.
Same with pidfile, and cfgfile.  (Last one is not really necessary.)


> waitpid(-1, 0xbffe7828, WNOHANG)        = -1 ECHILD (No child processes)
> rt_sigaction(SIGCHLD, {0x804e7e4, [], SA_INTERRUPT|SA_NOMASK}, NULL, 8) = 0
> rt_sigprocmask(SIG_UNBLOCK, [CHLD], NULL, 8) = 0

reaper() ends here-abouts.


> v1.182 of smtpserver.c from Jun-2004 adds the code in smtpserver.c:reaper():
> 
> +
> +    if (logfp)
> +      fclose(logfp);
> +    logfp = NULL;
> +
> 
> I wouldn't understand why its there but think its the cause.

I was doing subdaemon work back then, and apparently it relates
on that.  That was a result of observing  logfp  handle hanging
open on some subdaemon that had been restarted after logfp was
opened.  Things have been rewamped twice or thrice since then,
and that is nuisance left-over code.

I need to ponder more on these.
"It works for me", but I need to verify these once I wake up again.


> -- 
> Darryl L. Miles

-- 
/Matti Aarnio	<mea@nic.funet.fi>
-
To unsubscribe from this list: send the line "unsubscribe zmailer" in
the body of a message to majordomo@nic.funet.fi