slightly OT: size data

classic Classic list List threaded Threaded
10 messages Options
Reply | Threaded
Open this post in threaded view
|

slightly OT: size data

Stan Hoeppner
Hi all,

Until a day or two ago I'd never seen this in my pflogsumm output:

Messages with no size data
--------------------------

 03B593DA160  [hidden email]
 0E4283DA160  [hidden email]
 118663DA160  [hidden email]
 1D5973DA160  [hidden email]
 1EDF13DA160  [hidden email]
 25BE03DA160  [hidden email]
 296B53DA160  [hidden email]
 2B3F83DA160  [hidden email]
 2E79B3DA160  [hidden email]

That's a sample.  There are about 30 of these from yesterday.  I grep'd
for the message IDs and most of them are from the postfix-users
cloud9.net servers.  That in and of itself doesn't mean much though
because a large % of my legit mail is from postfix-users.  One of these
'size-less' messages originated from my workstation and was relayed
outbound, and this _really_ piques my curiosity.  If all these size-less
messages came from the outside world, I'd not think much of this issue.
 I wouldn't think a message originated locally from my MUA would
suddenly have no size data, when this hasn't occurred in 4 years.  This
make me think something goofy is going on with my Postfix.

AFAIK, I've made no recent config changes in main.cf that might cause
this.  And I've never, ever touched master.cf.

Any ideas why I've run this same postfix box for over 4 years, and have
never seen missing size data reported in pflogsumm?  I haven't upgraded
pflogsumm either.  I'm still running the first/only version I ever
installed.  And I've not upgraded Postfix recently, still on
2.3.8/Debian/Etch for quite some time.

The only recent change I've made is the two DNS resolvers in my router
config (it proxies DNS requests for LAN hosts).  But, I think I made
this change _after_ I started noticing the 'missing size data' entries.

Obviously this isn't critical (I don't think).  I'm just baffled and
wondering what's causing this.  Weird...

--
Stan
Reply | Threaded
Open this post in threaded view
|

Re: slightly OT: size data

Wietse Venema
If you have a question about POSTFIX logs, then it is a good idea
to send samples of POSTFIX logging.

        Wietse
Reply | Threaded
Open this post in threaded view
|

Re: slightly OT: size data

Stan Hoeppner
Wietse Venema put forth on 9/27/2009 7:39 AM:
> If you have a question about POSTFIX logs, then it is a good idea
> to send samples of POSTFIX logging.
>
> Wietse


Point taken, sry Wietse.   Upon grabbing these sample entries, I noticed
the transactions pflogsumm is flagging have no qmgr entries.  That
explains why pflogsumm is complaining there is no size data.  So, I
guess the question is, why did qmgr intermittently/randomly stop
stamping the log file, as of a day or two ago?

/../gcml.sh

#!/bin/sh
grep $1 /var/log/mail.log


greer:/home/stan# gcml 0602C3DA160
Sep 27 04:54:28 greer postfix/smtpd[25766]: 0602C3DA160:
client=camomile.cloud9.net[168.100.1.3]
Sep 27 04:54:28 greer postfix/cleanup[25769]: 0602C3DA160:
message-id=<[hidden email]>
Sep 27 04:54:28 greer postfix/smtp[25770]: 0602C3DA160:
to=<[hidden email]>, relay=192.168.100.2[192.168.100.2]:25,
delay=2.4, delays=2/0.03/0.13/0.28, dsn=2.0.0, status=sent (250 OK)

greer:/home/stan# gcml B8D863DA160
Sep 27 07:40:05 greer postfix/smtpd[26560]: B8D863DA160:
client=english-breakfast.cloud9.net[168.100.1.7]
Sep 27 07:40:05 greer postfix/cleanup[26563]: B8D863DA160:
message-id=<[hidden email]>
Sep 27 07:40:05 greer postfix/qmgr[26156]: B8D863DA160:
from=<[hidden email]>, size=3339, nrcpt=1 (queue active)
Sep 27 07:40:06 greer postfix/smtp[26564]: B8D863DA160:
to=<[hidden email]>, relay=192.168.100.2[192.168.100.2]:25,
delay=2, delays=1.5/0.03/0.17/0.35, dsn=2.0.0, status=sent (250 OK)
Sep 27 07:40:06 greer postfix/qmgr[26156]: B8D863DA160: removed

Reply | Threaded
Open this post in threaded view
|

Re: slightly OT: size data

Wietse Venema
Stan Hoeppner:
> Wietse Venema put forth on 9/27/2009 7:39 AM:
> > If you have a question about POSTFIX logs, then it is a good idea
> > to send samples of POSTFIX logging.
>
> Point taken, sry Wietse.   Upon grabbing these sample entries, I noticed
> the transactions pflogsumm is flagging have no qmgr entries.  That
> explains why pflogsumm is complaining there is no size data.  So, I
> guess the question is, why did qmgr intermittently/randomly stop
> stamping the log file, as of a day or two ago?

Apparently, your system runs daemons in a chroot environment that
does not contain the required syslog socket.

As shipped by me, Postfix does not run daemons in a chroot environment,
because the details vary with operating system and with system
version. If a maintainer or system administrator turns on the
Postfix chroot feature, then it is their responsibility to set
things up properly.

        Wietse
Reply | Threaded
Open this post in threaded view
|

Re: slightly OT: size data

Stan Hoeppner
Wietse Venema put forth on 9/27/2009 8:30 AM:

> Stan Hoeppner:
>> Wietse Venema put forth on 9/27/2009 7:39 AM:
>>> If you have a question about POSTFIX logs, then it is a good idea
>>> to send samples of POSTFIX logging.
>> Point taken, sry Wietse.   Upon grabbing these sample entries, I noticed
>> the transactions pflogsumm is flagging have no qmgr entries.  That
>> explains why pflogsumm is complaining there is no size data.  So, I
>> guess the question is, why did qmgr intermittently/randomly stop
>> stamping the log file, as of a day or two ago?
>
> Apparently, your system runs daemons in a chroot environment that
> does not contain the required syslog socket.
>
> As shipped by me, Postfix does not run daemons in a chroot environment,
> because the details vary with operating system and with system
> version. If a maintainer or system administrator turns on the
> Postfix chroot feature, then it is their responsibility to set
> things up properly.

Hi Wietse,

If the chroot environment does not contain the required syslog socket,
then why does qmgr place a stamp in the log for some message
transactions and not others?  From what I can see in the log file, more
messages have a qmgr stamp than not.  I'm not very familiar with chroot,
other than the basic theory behind it, and the fact that this seems to
be the Debian default Postfix configuration.

Something I thought of since I originally posted about this is that I
tried to change the Debian log rotation a couple of days ago from
rolling the mail log every 4 days to 14 days.  Since this is done by
cron it has nothing to do with syslogd.  However, at the time, I made a
change that I thought required restarting the syslogd daemon.  I'm
wondering if merely restarting syslogd while the system was running may
have played a part in this inconsistent qmgr logging.  So, I rebooted
the box late yesterday to see if things come back to normal.  I'll post
back later today after I have enough log data to make a sensible
determination.

Sorry for taking up folks' time with this, as the cause may not be
related to Postfix.  I'm not an expert WRT Postfix logging mechanisms or
syslogd.  And Debian defaulting to a chroot Postfix environment
obviously doesn't make troubleshooting this a routine or mundane exercise.

Thanks for your help, and patience with me.

--
Stan


Reply | Threaded
Open this post in threaded view
|

Re: slightly OT: size data

Wietse Venema
Stan Hoeppner:

> Wietse Venema put forth on 9/27/2009 8:30 AM:
> > Stan Hoeppner:
> >> Wietse Venema put forth on 9/27/2009 7:39 AM:
> >>> If you have a question about POSTFIX logs, then it is a good idea
> >>> to send samples of POSTFIX logging.
> >> Point taken, sry Wietse.   Upon grabbing these sample entries, I noticed
> >> the transactions pflogsumm is flagging have no qmgr entries.  That
> >> explains why pflogsumm is complaining there is no size data.  So, I
> >> guess the question is, why did qmgr intermittently/randomly stop
> >> stamping the log file, as of a day or two ago?
> >
> > Apparently, your system runs daemons in a chroot environment that
> > does not contain the required syslog socket.
> >
> > As shipped by me, Postfix does not run daemons in a chroot environment,
> > because the details vary with operating system and with system
> > version. If a maintainer or system administrator turns on the
> > Postfix chroot feature, then it is their responsibility to set
> > things up properly.
>
> Hi Wietse,
>
> If the chroot environment does not contain the required syslog socket,
> then why does qmgr place a stamp in the log for some message
> transactions and not others?

Oh, ye of little faith.

When you analyze the logs carefully, you will see that

1) qmgr logging starts after qmgr is restarted. Here, qmgr opens
   the syslog socket BEFORE it enters the chroot environment.

2) qmgr logging stops after syslogd is restarted. Here, qmgr cannot
   reopen the syslog socket, because there is no socket in the
   chroot environment.

Now PLEASE go beat up the maintainers who ship Postfix in a broken
configuration. The more people compolain, the more likely that it
will get fixed,

        Wietse
Reply | Threaded
Open this post in threaded view
|

Re: slightly OT: size data

Stan Hoeppner
Wietse Venema put forth on 9/28/2009 5:26 AM:

>> If the chroot environment does not contain the required syslog socket,
>> then why does qmgr place a stamp in the log for some message
>> transactions and not others?
>
> Oh, ye of little faith.

Ye of not enough understanding of the subject (me) is more accurate. :(

> When you analyze the logs carefully, you will see that
>
> 1) qmgr logging starts after qmgr is restarted. Here, qmgr opens
>    the syslog socket BEFORE it enters the chroot environment.
>
> 2) qmgr logging stops after syslogd is restarted. Here, qmgr cannot
>    reopen the syslog socket, because there is no socket in the
>    chroot environment.

I think I follow you Wietse.  So it seems this problem is related to me
restarting syslogd the other day without restarting Postfix immediately
afterwards?

> Now PLEASE go beat up the maintainers who ship Postfix in a broken
> configuration. The more people compolain, the more likely that it
> will get fixed,
>
> Wietse

I will surely do so.  Is there anything specific I should tell them?  Is
the goal to have them _not_ run Postfix in a chroot, or to fix their
chroot implementation?

Thanks again for all your help.

--
Stan


Reply | Threaded
Open this post in threaded view
|

Re: slightly OT: size data

Wietse Venema
Stan Hoeppner:
[ Charset ISO-8859-1 unsupported, converting... ]

> Wietse Venema put forth on 9/28/2009 5:26 AM:
>
> >> If the chroot environment does not contain the required syslog socket,
> >> then why does qmgr place a stamp in the log for some message
> >> transactions and not others?
> >
> > Oh, ye of little faith.
>
> Ye of not enough understanding of the subject (me) is more accurate. :(
>
> > When you analyze the logs carefully, you will see that
> >
> > 1) qmgr logging starts after qmgr is restarted. Here, qmgr opens
> >    the syslog socket BEFORE it enters the chroot environment.
> >
> > 2) qmgr logging stops after syslogd is restarted. Here, qmgr cannot
> >    reopen the syslog socket, because there is no socket in the
> >    chroot environment.
>
> I think I follow you Wietse.  So it seems this problem is related to me
> restarting syslogd the other day without restarting Postfix immediately
> afterwards?

The problem is using a chroot environment without syslog socket.

> > Now PLEASE go beat up the maintainers who ship Postfix in a broken
> > configuration. The more people compolain, the more likely that it
> > will get fixed,
>
> I will surely do so.  Is there anything specific I should tell them?  Is
> the goal to have them _not_ run Postfix in a chroot, or to fix their
> chroot implementation?

Tell them to either turn off Postfix chroot, or to provide a working
chroot environment.

        Wietse
Reply | Threaded
Open this post in threaded view
|

Debian Postfix chroot and syslog problem -- was slightly OT: size data

Stan Hoeppner
Wietse Venema put forth on 9/28/2009 7:56 AM:

> The problem is using a chroot environment without syslog socket.
>
>>> Now PLEASE go beat up the maintainers who ship Postfix in a broken
>>> configuration. The more people compolain, the more likely that it
>>> will get fixed,
>> I will surely do so.  Is there anything specific I should tell them?  Is
>> the goal to have them _not_ run Postfix in a chroot, or to fix their
>> chroot implementation?
>
> Tell them to either turn off Postfix chroot, or to provide a working
> chroot environment.

Hi Wietse,

I was still running Etch (Debian 4.0), which was about 2.5 years old,
when I reported this problem (apparently it was never addressed in
Postfix security, or other, updates, given that I frequently ran the
updates).  I've since upgraded to Lenny (Debian 5.0, latest stable
release), which uses rsyslog in place of syslogd and klogd.  Apparently,
with the change to rsyslog and Postfix 2.5.5-1.1 (up from 2.3.8), this
was added:

greer:/etc/rsyslog.d# cat postfix.conf
# Create an additional socket in postfix's chroot in order not to break
# mail logging when rsyslog is restarted.  If the directory is missing,
# rsyslog will silently skip creating the socket.
$AddUnixListenSocket /var/spool/postfix/dev/log

I checked and I have the directory and the socket.  So, thankfully, I
don't need to go beat up on the Debian maintainers. :)

--
Stan

Reply | Threaded
Open this post in threaded view
|

Re: Debian Postfix chroot and syslog problem -- was slightly OT: size data

Wietse Venema
Stan Hoeppner:
> greer:/etc/rsyslog.d# cat postfix.conf
> # Create an additional socket in postfix's chroot in order not to break
> # mail logging when rsyslog is restarted.  If the directory is missing,
> # rsyslog will silently skip creating the socket.
> $AddUnixListenSocket /var/spool/postfix/dev/log
>
> I checked and I have the directory and the socket.  So, thankfully, I
> don't need to go beat up on the Debian maintainers. :)

Neat. Now, there are enhancements from Debian from many years ago
that haven't all made it into Postfix and that I should look at.

        Wietse