On Thu, Jul 01, 2010 at 02:35:22PM -0400, Wietse Venema wrote:
> David Hill:
> > Hello,
> >
> > I am using Postfix 2.7.1. The header_checks manpage says REJECT will
> > insert a default enhanced status code of 5.7.1 if the optional text is
> > not specified. However, the server gives back 450 4.7.1.
> >
> > 220 mail.server.com ESMTP Postfix
> > EHLO hostname
> > 250-mail.server.com
> > 250-PIPELINING
> > 250-SIZE 35651584
> > 250-ETRN
> > 250-STARTTLS
> > 250-ENHANCEDSTATUSCODES
> > 250-8BITMIME
> > 250 DSN
> > MAIL FROM: <da...@wmol.com>
> > 250 2.1.0 Ok
> > RCPT TO: <da...@wmol.com>
> > 250 2.1.5 Ok
> > DATA
> > 354 End data with <CR><LF>.<CR><LF>
> > Subject: Viagra
> >
> > .
> > 450 4.7.1 Spam.
> >
> > /var/log/maillog shows 5.7.1 was returned?
> > Jul 1 11:16:18 mail postfix/cleanup[28982]: 01B6B72347: reject: header
> > Subject: Viagra from localhost[127.0.0.1];
> > from=<da...@wmol.com> to=<da...@wmol.com> proto=ESMTP
> > helo=<hostname>: 5.7.1 Spam
> >
> > # grep Viagra /etc/postfix/config/header_checks
> > /^Subject:.*Viagra/ REJECT 5.7.1 Spam.
> >
> > # /usr/local/sbin/postconf | grep ^header_checks
> > header_checks = pcre:/etc/postfix/config/header_checks
> >
> > What am I doing wrong?
>
> As I replied to your direct mail, Postfix has 600+ configuration
> parameters. For a proper problem report see
> http://www.postfix.org/DEBUG_README.html#mail
>
> Wietse
I changed header_checks to just the following:
/^Subject:.*Viagra/ REJECT
I used ktrace and kdump and see this... (snippet)
"DATA\r
"
26399 smtpd RET read 6
26399 smtpd CALL gettimeofday(0x23c4ee9c,0)
26399 smtpd RET gettimeofday 0
26399 smtpd CALL gettimeofday(0xffff7558,0)
26399 smtpd RET gettimeofday 0
26399 smtpd CALL getpid()
26399 smtpd RET getpid 26399/0x671f
26399 smtpd CALL sendto(0xa,0xffff79d8,0x4f,0,0,0)
26399 smtpd GIO fd 10 wrote 79 bytes
"<22>Jul 1 15:06:46 postfix/smtpd[26399]: <
office.i2k.com[66.255.222.70]: DATA"
26399 smtpd RET sendto 79/0x4f
26399 smtpd CALL ioctl(0xc,FIONREAD,0xffff83d8)
26399 smtpd RET ioctl 0
26399 smtpd CALL sigprocmask(0x1,0)
26399 smtpd RET sigprocmask 0
26399 smtpd CALL gettimeofday(0xffff73d8,0)
26399 smtpd RET gettimeofday 0
26399 smtpd CALL getpid()
26399 smtpd RET getpid 26399/0x671f
26399 smtpd CALL sendto(0xa,0xffff7858,0x51,0,0,0)
26399 smtpd GIO fd 10 wrote 81 bytes
"<22>Jul 1 15:06:46 postfix/smtpd[26399]: >>> START Data command
RESTRICTIONS <<<"
26399 smtpd RET sendto 81/0x51
26399 smtpd CALL gettimeofday(0xffff73d8,0)
26399 smtpd RET gettimeofday 0
26399 smtpd CALL getpid()
26399 smtpd RET getpid 26399/0x671f
26399 smtpd CALL sendto(0xa,0xffff7858,0x57,0,0,0)
26399 smtpd GIO fd 10 wrote 87 bytes
"<22>Jul 1 15:06:46 postfix/smtpd[26399]: generic_checks:
name=reject_unauth_pipelining"
26399 smtpd RET sendto 87/0x57
26399 smtpd CALL gettimeofday(0xffff73b8,0)
26399 smtpd RET gettimeofday 0
26399 smtpd CALL getpid()
26399 smtpd RET getpid 26399/0x671f
26399 smtpd CALL sendto(0xa,0xffff7838,0x48,0,0,0)
26399 smtpd GIO fd 10 wrote 72 bytes
"<22>Jul 1 15:06:46 postfix/smtpd[26399]: reject_unauth_pipelining:
DATA"
26399 smtpd RET sendto 72/0x48
26399 smtpd CALL gettimeofday(0xffff73d8,0)
26399 smtpd RET gettimeofday 0
26399 smtpd CALL getpid()
26399 smtpd RET getpid 26399/0x671f
26399 smtpd CALL sendto(0xa,0xffff7858,0x60,0,0,0)
26399 smtpd GIO fd 10 wrote 96 bytes
"<22>Jul 1 15:06:46 postfix/smtpd[26399]: generic_checks:
name=reject_unauth_pipelining status=0"
26399 smtpd RET sendto 96/0x60
26399 smtpd CALL gettimeofday(0xffff73d8,0)
26399 smtpd RET gettimeofday 0
26399 smtpd CALL getpid()
26399 smtpd RET getpid 26399/0x671f
26399 smtpd CALL sendto(0xa,0xffff7858,0x5c,0,0,0)
26399 smtpd GIO fd 10 wrote 92 bytes
"<22>Jul 1 15:06:46 postfix/smtpd[26399]: generic_checks:
name=reject_multi_recipient_bounce"
26399 smtpd RET sendto 92/0x5c
26399 smtpd CALL gettimeofday(0xffff73d8,0)
26399 smtpd RET gettimeofday 0
26399 smtpd CALL getpid()
26399 smtpd RET getpid 26399/0x671f
26399 smtpd CALL sendto(0xa,0xffff7858,0x65,0,0,0)
26399 smtpd GIO fd 10 wrote 101 bytes
"<22>Jul 1 15:06:46 postfix/smtpd[26399]: generic_checks:
name=reject_multi_recipient_bounce status=0"
26399 smtpd RET sendto 101/0x65
26399 smtpd CALL gettimeofday(0xffff73d8,0)
26399 smtpd RET gettimeofday 0
26399 smtpd CALL getpid()
26399 smtpd RET getpid 26399/0x671f
26399 smtpd CALL sendto(0xa,0xffff7858,0x4f,0,0,0)
26399 smtpd GIO fd 10 wrote 79 bytes
"<22>Jul 1 15:06:46 postfix/smtpd[26399]: >>> END Data command
RESTRICTIONS <<<"
26399 smtpd RET sendto 79/0x4f
26399 smtpd CALL sigprocmask(0x1,0xffffffff)
26399 smtpd RET sigprocmask 0
26399 smtpd CALL mprotect(0x18b7000,0x2000,0x7)
26399 smtpd RET mprotect 0
26399 smtpd CALL mprotect(0x18b7000,0x2000,0x5)
26399 smtpd RET mprotect 0
26399 smtpd CALL sigprocmask(0x3,0)
26399 smtpd RET sigprocmask -65793/0xfffefeff
26399 smtpd CALL sigprocmask(0x1,0xffffffff)
26399 smtpd RET sigprocmask 0
26399 smtpd CALL mprotect(0x28155000,0x3000,0x7)
26399 smtpd RET mprotect 0
26399 smtpd CALL mprotect(0x28155000,0x3000,0x5)
26399 smtpd RET mprotect 0
26399 smtpd CALL sigprocmask(0x3,0)
26399 smtpd RET sigprocmask -65793/0xfffefeff
26399 smtpd CALL issetugid()
26399 smtpd RET issetugid 0
26399 smtpd CALL sigprocmask(0x1,0xffffffff)
26399 smtpd RET sigprocmask 0
26399 smtpd CALL mprotect(0x28155000,0x3000,0x7)
26399 smtpd RET mprotect 0
26399 smtpd CALL mprotect(0x28155000,0x3000,0x5)
26399 smtpd RET mprotect 0
26399 smtpd CALL sigprocmask(0x3,0)
26399 smtpd RET sigprocmask -65793/0xfffefeff
26399 smtpd CALL open(0xffff7e58,0,0x400)
26399 smtpd NAMI "/usr/share/zoneinfo/GMT"
26399 smtpd RET open 21/0x15
26399 smtpd CALL read(0x15,0xfffedde8,0x7148)
26399 smtpd GIO fd 21 read 56 bytes
"TZif\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\^A\0\0\0\^A\0\0\0\0\0\0\0\0\0\0\0\^A\0\0\0\^D\0\0\0\0\0\0GMT\0\0\0"
26399 smtpd RET read 56/0x38
26399 smtpd CALL close(0x15)
26399 smtpd RET close 0
26399 smtpd CALL sigprocmask(0x1,0xffffffff)
26399 smtpd RET sigprocmask 0
26399 smtpd CALL mprotect(0x18b7000,0x2000,0x7)
26399 smtpd RET mprotect 0
26399 smtpd CALL mprotect(0x18b7000,0x2000,0x5)
26399 smtpd RET mprotect 0
26399 smtpd CALL sigprocmask(0x3,0)
26399 smtpd RET sigprocmask -65793/0xfffefeff
26399 smtpd CALL sigprocmask(0x1,0xffffffff)
26399 smtpd RET sigprocmask 0
26399 smtpd CALL mprotect(0x18b7000,0x2000,0x7)
26399 smtpd RET mprotect 0
26399 smtpd CALL mprotect(0x18b7000,0x2000,0x5)
26399 smtpd RET mprotect 0
26399 smtpd CALL sigprocmask(0x3,0)
26399 smtpd RET sigprocmask -65793/0xfffefeff
26399 smtpd CALL gettimeofday(0xffff7478,0)
26399 smtpd RET gettimeofday 0
26399 smtpd CALL getpid()
26399 smtpd RET getpid 26399/0x671f
26399 smtpd CALL sendto(0xa,0xffff78f8,0x6e,0,0,0)
26399 smtpd GIO fd 10 wrote 110 bytes
"<22>Jul 1 15:06:46 postfix/smtpd[26399]: >
office.i2k.com[66.255.222.70]: 354 End data with <CR><LF>.<CR><LF>"
26399 smtpd RET sendto 110/0x6e
26399 smtpd CALL gettimeofday(0xffff82c8,0)
26399 smtpd RET gettimeofday 0
26399 smtpd CALL poll(0xffff8298,0x1,0x493e0)
26399 smtpd RET poll 1
26399 smtpd CALL write(0xc,0x23374008,0x25)
26399 smtpd GIO fd 12 wrote 37 bytes
"354 End data with <CR><LF>.<CR><LF>\r
"
26399 smtpd RET write 37/0x25
26399 smtpd CALL gettimeofday(0x23c4ee9c,0)
26399 smtpd RET gettimeofday 0
26399 smtpd CALL poll(0xffff82c8,0x1,0x493e0)
26399 smtpd RET poll 1
26399 smtpd CALL read(0xc,0x23376008,0x1000)
26399 smtpd GIO fd 12 read 17 bytes
"Subject: Viagra\r
"
26399 smtpd RET read 17/0x11
26399 smtpd CALL gettimeofday(0x23c4ee9c,0)
26399 smtpd RET gettimeofday 0
26399 smtpd CALL poll(0xffff82c8,0x1,0x493e0)
26399 smtpd RET poll 1
26399 smtpd CALL read(0xc,0x23376008,0x1000)
26399 smtpd GIO fd 12 read 3 bytes
".\r
"
26399 smtpd RET read 3
26399 smtpd CALL gettimeofday(0x23c4ee9c,0)
26399 smtpd RET gettimeofday 0
26399 smtpd CALL sigprocmask(0x1,0)
26399 smtpd RET sigprocmask 0
26399 smtpd CALL poll(0xffff8318,0x1,0x36ee80)
26399 smtpd RET poll 1
26399 smtpd CALL write(0x13,0x2c1d5008,0xcf)
26399 smtpd GIO fd 19 wrote 207 bytes
"M\0N>Received: from office.i2k.com (office.i2k.com [66.255.222.70])N5
by fig.mindcry.org (Postfix) with SMTP id A8A5972347N? for
<dh...@mindcry.org>; Thu, 1 Jul 2010 15:06:42 -0400 (EDT)N\^OSubject:
ViagraX\0E\0"
26399 smtpd RET write 207/0xcf
26399 smtpd CALL gettimeofday(0x2545b69c,0)
26399 smtpd RET gettimeofday 0
26399 smtpd CALL poll(0xffff81f8,0x1,0x36ee80)
26399 smtpd RET poll 1
26399 smtpd CALL read(0x13,0x2c1d5008,0x1000)
26399 smtpd GIO fd 19 read 48 bytes
"status\08\0reason\0005.7.1 message content rejected\0\0"
26399 smtpd RET read 48/0x30
26399 smtpd CALL gettimeofday(0x2545b69c,0)
26399 smtpd RET gettimeofday 0
26399 smtpd CALL gettimeofday(0xffff7418,0)
26399 smtpd RET gettimeofday 0
26399 smtpd CALL getpid()
26399 smtpd RET getpid 26399/0x671f
26399 smtpd CALL sendto(0xa,0xffff7898,0x59,0,0,0)
26399 smtpd GIO fd 10 wrote 89 bytes
"<22>Jul 1 15:06:50 postfix/smtpd[26399]: public/cleanup socket: wanted
attribute: status"
26399 smtpd RET sendto 89/0x59
26399 smtpd CALL gettimeofday(0xffff73f8,0)
26399 smtpd RET gettimeofday 0
26399 smtpd CALL getpid()
26399 smtpd RET getpid 26399/0x671f
26399 smtpd CALL sendto(0xa,0xffff7878,0x46,0,0,0)
26399 smtpd GIO fd 10 wrote 70 bytes
"<22>Jul 1 15:06:50 postfix/smtpd[26399]: input attribute name: status"
26399 smtpd RET sendto 70/0x46
26399 smtpd CALL gettimeofday(0xffff73c8,0)
26399 smtpd RET gettimeofday 0
26399 smtpd CALL getpid()
26399 smtpd RET getpid 26399/0x671f
26399 smtpd CALL sendto(0xa,0xffff7848,0x42,0,0,0)
26399 smtpd GIO fd 10 wrote 66 bytes
"<22>Jul 1 15:06:50 postfix/smtpd[26399]: input attribute value: 8"
26399 smtpd RET sendto 66/0x42
26399 smtpd CALL gettimeofday(0xffff7418,0)
26399 smtpd RET gettimeofday 0
26399 smtpd CALL getpid()
26399 smtpd RET getpid 26399/0x671f
26399 smtpd CALL sendto(0xa,0xffff7898,0x59,0,0,0)
26399 smtpd GIO fd 10 wrote 89 bytes
"<22>Jul 1 15:06:50 postfix/smtpd[26399]: public/cleanup socket: wanted
attribute: reason"
26399 smtpd RET sendto 89/0x59
26399 smtpd CALL gettimeofday(0xffff73f8,0)
26399 smtpd RET gettimeofday 0
26399 smtpd CALL getpid()
26399 smtpd RET getpid 26399/0x671f
26399 smtpd CALL sendto(0xa,0xffff7878,0x46,0,0,0)
26399 smtpd GIO fd 10 wrote 70 bytes
"<22>Jul 1 15:06:50 postfix/smtpd[26399]: input attribute name: reason"
26399 smtpd RET sendto 70/0x46
26399 smtpd CALL gettimeofday(0xffff73f8,0)
26399 smtpd RET gettimeofday 0
26399 smtpd CALL getpid()
26399 smtpd RET getpid 26399/0x671f
26399 smtpd CALL sendto(0xa,0xffff7878,0x5f,0,0,0)
26399 smtpd GIO fd 10 wrote 95 bytes
"<22>Jul 1 15:06:50 postfix/smtpd[26399]: input attribute value: 5.7.1
message content rejected"
26399 smtpd RET sendto 95/0x5f
26399 smtpd CALL gettimeofday(0xffff7418,0)
26399 smtpd RET gettimeofday 0
26399 smtpd CALL getpid()
26399 smtpd RET getpid 26399/0x671f
26399 smtpd CALL sendto(0xa,0xffff7898,0x64,0,0,0)
26399 smtpd GIO fd 10 wrote 100 bytes
"<22>Jul 1 15:06:50 postfix/smtpd[26399]: public/cleanup socket: wanted
attribute: (list terminator)"
26399 smtpd RET sendto 100/0x64
26399 smtpd CALL gettimeofday(0xffff73f8,0)
26399 smtpd RET gettimeofday 0
26399 smtpd CALL getpid()
26399 smtpd RET getpid 26399/0x671f
26399 smtpd CALL sendto(0xa,0xffff7878,0x45,0,0,0)
26399 smtpd GIO fd 10 wrote 69 bytes
"<22>Jul 1 15:06:50 postfix/smtpd[26399]: input attribute name: (end)"
26399 smtpd RET sendto 69/0x45
26399 smtpd CALL close(0x13)
26399 smtpd RET close 0
26399 smtpd CALL gettimeofday(0xffff7478,0)
26399 smtpd RET gettimeofday 0
26399 smtpd CALL getpid()
26399 smtpd RET getpid 26399/0x671f
26399 smtpd CALL sendto(0xa,0xffff78f8,0x6d,0,0,0)
26399 smtpd GIO fd 10 wrote 109 bytes
"<22>Jul 1 15:06:50 postfix/smtpd[26399]: >
office.i2k.com[66.255.222.70]: 450 4.7.1 message content rejected"
26399 smtpd RET sendto 109/0x6d
26399 smtpd CALL gettimeofday(0xffff82c8,0)
26399 smtpd RET gettimeofday 0
26399 smtpd CALL poll(0xffff82c8,0x1,0x493e0)
26399 smtpd RET poll 1
26399 smtpd CALL write(0xc,0x23374008,0x24)
26399 smtpd GIO fd 12 wrote 36 bytes
"450 4.7.1 message content rejected\r
"
26399 smtpd RET write 36/0x24
26399 smtpd CALL gettimeofday(0x23c4ee9c,0)
26399 smtpd RET gettimeofday 0
26399 smtpd CALL poll(0xffff82f8,0x1,0x493e0)
26399 smtpd RET poll 1
26399 smtpd CALL read(0xc,0x23376008,0x1000)
26399 smtpd GIO fd 12 read 6 bytes
"quit\r
"
26399 smtpd RET read 6
26399 smtpd CALL gettimeofday(0x23c4ee9c,0)
26399 smtpd RET gettimeofday 0
26399 smtpd CALL gettimeofday(0xffff7558,0)
26399 smtpd RET gettimeofday 0
26399 smtpd CALL getpid()
26399 smtpd RET getpid 26399/0x671f
26399 smtpd CALL sendto(0xa,0xffff79d8,0x4f,0,0,0)
26399 smtpd GIO fd 10 wrote 79 bytes
