Can't seem to get Debug level for SMTP logging

Question

Level 4

1,464 points

Can't seem to get Debug level for SMTP logging

Hello, I've used SA to turn on debug logging for SMTP, but I don't think it's happening, as I'm not seeing very verbose information. I suspect that SA is not updating the right file in the right place. I've taken a peak at /etc/postfix/main.cf and /etc/syslog.conf but not sure what I'm looking for.

Does anyone know the directive?

The specific information I'm looking for is to see if a remote user is properly authenticating over SMTP before sending, as they're getting 'relay access denied' errors while other users are not. Is this information I should expect to see when debug logging is activated?

MacBook, Mac OS X (10.4.8)

Posted on Dec 6, 2006 5:38 PM

Reply

Answer 1

rhwalker

Level 3

589 points

Dec 7, 2006 2:00 PM in response to jaydisc

It's a bit confusing because postfix is always putting out the logging stuff; some of it gets dropped.

syslog.conf is where the stuff all happens.

You will see, toward the top, that critical postfix errors
(mail.crit) go to the console, system.log, and serial port.

Towards the middle of the file, informational logging (mail.info) (the default) goes to /var/log/mail.log. If you
want to merge debug info into mail.log (for easy viewing with Server Admin), you could change the line in syslog.conf from

mail.info /var/log/mail.log

to

mail.info;mail.debug /var/log/mail.log

or you could have debug logging go to some separate file by
adding a new line

mail.debug /var/log/maildebug.log

Enjoy the reams of output. You will probably want to do a fgrep, etc., on the log file to filter out the garbage from what you really need. Disable the debug logging when you are done or else you will have a mighty big log file.

You will need to send a HUP to syslogd after you modify
syslog.conf in order to get it to re-read the config stuff.

See man syslogd for details.

Russ

Xserve G5 2.0 GHz 2 GB RAM Mac OS X (10.4.8) Apple Hardware RAID, ATTO UL4D, Exabyte VXA-2 1x10 1u

Reply

Answer 2

jaydisc Author

Level 4

1,464 points

Dec 7, 2006 6:36 PM in response to rhwalker

HI Russ,

Thanks for the tips. When I have SA set to log at the Informative level, syslog.conf has the following line as you described:

mail.info /var/log/mail.log

When i set it to Debug level, that line is altered as:

mail.* /var/log/mail.log

However, no difference to the output in mail.log. I tried leaving SA set to Informative level, and added an additional line in syslog.conf, and HUP'd it:

mail.info /var/log/mail.log
mail.debug /var/log/maildebug.log

And within seconds maildebug.log started loading up with info, but to my eyes, the info is no different than from that in mail.log

Perhaps I'm expecting info that just isn't there?

Here is a debug example:

Dec 8 13:35:15 imac postfix/smtpd[29131]: 729A149FCDD: client=unknown[219.144.61.51]
Dec 8 13:35:20 imac postfix/cleanup[29135]: 729A149FCDD: message-id=<2128957240.9150385183@ **.co.uk>
Dec 8 13:35:20 imac postfix/qmgr[29110]: 729A149FCDD: from=<nick. ***@***.co.uk>, size=646, nrcpt=1 (queue active)
Dec 8 13:35:21 imac postfix/smtpd[29131]: disconnect from unknown[219.144.61.51]
Dec 8 13:35:36 imac postfix/smtpd[29161]: connect from localhost[127.0.0.1]
Dec 8 13:35:36 imac postfix/smtpd[29161]: 2DC7749FCFB: client=localhost[127.0.0.1]
Dec 8 13:35:36 imac postfix/cleanup[29135]: 2DC7749FCFB: message-id=<2128957240.9150385183@ **.co.uk>
Dec 8 13:35:36 imac postfix/qmgr[29110]: 2DC7749FCFB: from=<nick.collettsfer@ **.co.uk>, size=1270, nrcpt=1 (queue active)
Dec 8 13:35:36 imac postfix/smtpd[29161]: disconnect from localhost[127.0.0.1]
Dec 8 13:35:36 imac postfix/smtp[29140]: 729A149FCDD: to=<angela@imac. **.com>, orig_to=<angela@ **.com>, relay=127.0.0.1[127.0.0.1], delay=24, status=sent (250 2.6.0 Ok, id=27358-10, from MTA: 250 Ok: queued as 2DC7749FCFB)
Dec 8 13:35:36 imac postfix/qmgr[29110]: 729A149FCDD: removed
Dec 8 13:35:37 imac postfix/pipe[29164]: 2DC7749FCFB: to=<angela@imac. **.com>, relay=cyrus, delay=1, status=sent (imac. **.com)
Dec 8 13:35:37 imac postfix/qmgr[29110]: 2DC7749FCFB: removed
Dec 8 13:35:42 imac postfix/smtpd[29131]: connect from unknown[59.39.106.119]
Dec 8 13:35:45 imac postfix/smtpd[29131]: NOQUEUE: reject: RCPT from unknown[59.39.106.119]: 504 <langjian>: Helo command rejected: need fully-qualified hostname; from=<info@ **.com.au> to=<info@ **.com.au> proto=SMTP helo=<langjian>
Dec 8 13:35:45 imac postfix/smtpd[29131]: lost connection after RCPT from unknown[59.39.106.119]
Dec 8 13:35:45 imac postfix/smtpd[29131]: disconnect from unknown[59.39.106.119]

Am I expecting something that doesn't exist? What further information should I expect to come from Debug that wouldn't be in Informative?

Reply

Answer 3

rhwalker

Level 3

589 points

Dec 7, 2006 7:48 PM in response to jaydisc

What further information should I expect to come from Debug
that wouldn't be in Informative?

I don't know what DEBUG level options Apple compiled postfix
with, so I'm not able to answer that. But I do know how to
make syslogd log to different levels.

Your log looks about like mine. I only look at it when there
becomes an issue as to whether a missing email that a client
says didn't get sent/delivered actually did. In all cases,
I have been able to show that the client's server accepted
the email for delivery from our server, and the client then
usually finds the email in their spam quarantine.

Wish I could be of more help.

Russ

Xserve G5 2.0 GHz 2 GB RAM Mac OS X (10.4.8) Apple Hardware RAID, ATTO UL4D, Exabyte VXA-2 1x10 1u

Reply

Answer 4

pterobyte

Level 6

11,104 points

Dec 8, 2006 1:21 AM in response to jaydisc

The information you expect to see should look similar to this:

Dec 8 10:00:50 sabertooth postfix/smtpd[25281]: DCB771C7BDE: client=yourmachine.domain.com[123.45.67.89], sasl_method=CRAM-MD5, sasl_username=youruser

I am not sure about Server Admin anymore in this case, as I largely ignore it. However, "Information" should be enough for this. I could be wrong because in this respect I have made so many modifications that I can't be sure anymore 😉

This is what the relevant bits look like in my syslog.conf :
<pre>
.err;kern.;auth.notice;authpriv,remoteauth,install.none;mail.crit /dev/console
*.notice;authpriv,remoteauth,ftp,install.none;kern.debug;mail.crit /var/log/system.log

mail.info /var/log/mail.log
local6.info /var/log/mailaccess.log
auth. ;sasl*. /var/log/auth.log
</pre>

Reply

Answer 5

jaydisc Author

Level 4

1,464 points

Dec 10, 2006 6:23 PM in response to pterobyte

Thanks for the tips everyone, but I can't see any difference between Informative and Debug options.

Reply

Answer 6

Dec 11, 2006 2:43 AM in response to jaydisc

This is what you want, in " /etc/postfix/master.cf"

Change:<pre># for the SMTP server: localhost:smtp receives mail via the loopback
smtp inet n - n - - smtpd</pre>to:<pre># for the SMTP server: localhost:smtp receives mail via the loopback
smtp inet n - n - - smtpd -v</pre>
Don't forget to undo it when you're done otherwise your logs will fill quickly.

B&W G3 400 ~ Dual 1GHz G4 ~ Dual 2GHz G5 ~ Dual 3GHz MacPro Mac OS X (10.4.8)

Reply

Answer 7

jaydisc Author

Level 4

1,464 points

Dec 11, 2006 3:29 AM in response to Dale Walsh

Awesome. Thank you.

Reply