internal protocol error from sendmail for messages > message_size_limit
Paul B. Henson
and the behavior when trying to submit messages through the sendmail
interface seems to have changed.
In the previous version, if a message exceeded the configured
message_size_limit, it would look like this:
$ (printf "From: ro...@csupomona.edu\nTo: hen...@csupomona.edu\nSubject: big email test\n\n"; yes test | head -c 10000000) | /usr/sbin/sendmail -t
postdrop: warning: uid=1005: File too large
sendmail: fatal: henson(1005): message file too big
With the new version, it now emits:
$ (printf "From: ro...@csupomona.edu\nTo: hen...@csupomona.edu\nSubject: big email test\n\n"; yes test | head -c 10000000) | /usr/sbin/sendmail -t
sendmail: fatal: henson(1005): internal protocol error
At first I thought something was broken with my new installation, but
everything seems to be working ok other than this different message.
Was this an intentional change? Accidental change? I've got something
broken after all?
The systems in question are running gentoo linux, with the following
config:
# postconf -n
allow_mail_to_commands =
allow_mail_to_files =
biff = no
command_directory = /usr/sbin
config_directory = /etc/postfix
daemon_directory = //usr/lib64/postfix
data_directory = /var/lib/postfix
fast_flush_domains =
forward_path =
html_directory = /usr/share/doc/postfix-2.6.5/html
local_transport = error:local delivery is disabled
mail_owner = postfix
mailq_path = /usr/bin/mailq
manpage_directory = /usr/share/man
message_size_limit = 10240000
mydomain = unx.csupomona.edu
mynetworks_style = host
myorigin = csupomona.edu
newaliases_path = /usr/bin/newaliases
queue_directory = /var/spool/postfix
readme_directory = /usr/share/doc/postfix-2.6.5/readme
relayhost = [smtp.csupomona.edu]
sample_directory = /etc/postfix
sendmail_path = /usr/sbin/sendmail
setgid_group = postdrop
Thanks...
--
Paul B. Henson | (909) 979-6361 | http://www.csupomona.edu/~henson/
Operating Systems and Network Analyst | hen...@csupomona.edu
California State Polytechnic University | Pomona CA 91768
Wietse Venema
> We recently upgraded some systems from postfix 2.6.6 to postfix 2.7.4,
> and the behavior when trying to submit messages through the sendmail
> interface seems to have changed.
>
> In the previous version, if a message exceeded the configured
> message_size_limit, it would look like this:
>
> $ (printf "From: ro...@csupomona.edu\nTo: hen...@csupomona.edu\nSubject: big email test\n\n"; yes test | head -c 10000000) | /usr/sbin/sendmail -t
> postdrop: warning: uid=1005: File too large
> sendmail: fatal: henson(1005): message file too big
>
> With the new version, it now emits:
>
> $ (printf "From: ro...@csupomona.edu\nTo: hen...@csupomona.edu\nSubject: big email test\n\n"; yes test | head -c 10000000) | /usr/sbin/sendmail -t
> sendmail: fatal: henson(1005): internal protocol error
[FreeBSD 8.0]
% postconf mail_version
mail_version = 2.9-20110501
% limit filesize 1k
% sendmail wietse </etc/termcap
postdrop: warning: uid=1001: File too large
sendmail: fatal: wietse(1001): message file too big
[Ubuntu 10.04]
$ postconf mail_version
mail_version = 2.9-20110219
$ ulimit -f 1
$ man man|sendmail wietse
postdrop: warning: uid=1000: File too large
sendmail: fatal: wietse(1000): message file too big
Postfix hasn't changed, as far as I can tell. Perhaps something on
your system has changed.
I notice that your postdrop aborts before it logs the "File too
large" warning. Apparently the program is killed, and that explains
why sendmail logs the protocol error.
You may want to investigate with "strace -f" to see what kills off
the postdrop program. This requires root privileges (when postdrop
runs under strace, the postdrop setgid bit is ignored).
Wietse
Paul B. Henson
> Postfix hasn't changed, as far as I can tell. Perhaps something on
> your system has changed.
We did update a number of components, and after viewing postfix
changelogs and source code without anything popping out, we went back to
a system with the original config and updated only postfix (and db,
which the packaging system pulled in), and verified the same change in
behavior before I posted.
> I notice that your postdrop aborts before it logs the "File too
> large" warning. Apparently the program is killed, and that explains
> why sendmail logs the protocol error.
The postdrop executable appears to exit normally and successfully send a
status back to sendmail:
[pid 24094] close(4) = 0
[pid 24094] write(1, "status\0001\0reason\0\0\0", 18) = 18
[pid 24094] exit_group(1) = ?
For comparison, this is strace output from the older version of postfix:
[pid 2227] close(4) = 0
[pid 2227] write(2, "postdrop: warning: uid=0: File t"..., 41postdrop:
warning: uid=0: File too large
[pid 2227] gettimeofday({1307042952, 7166}, NULL) = 0
[pid 2227] sendto(3, "<20>Jun 2 19:29:12 postfix/post"..., 75,
MSG_NOSIGNAL, NULL, 0) = 75
[pid 2227] rt_sigaction(SIGINT, {SIG_IGN, [INT],
SA_RESTORER|SA_RESTART, 0x7fba90647230}, {0x402e50, [INT],
SA_RESTORER|SA_RESTART, 0x7fba90647230}, 8) = 0
[pid 2227] rt_sigaction(SIGQUIT, {SIG_IGN, [QUIT],
SA_RESTORER|SA_RESTART, 0x7fba90647230}, {0x402e50, [QUIT],
SA_RESTORER|SA_RESTART, 0x7fba90647230}, 8) = 0
[pid 2227] rt_sigaction(SIGTERM, {SIG_IGN, [TERM],
SA_RESTORER|SA_RESTART, 0x7fba90647230}, {0x402e50, [TERM],
SA_RESTORER|SA_RESTART, 0x7fba90647230}, 8) = 0
[pid 2227] rt_sigaction(SIGHUP, {SIG_IGN, [HUP],
SA_RESTORER|SA_RESTART, 0x7fba90647230}, {0x402e50, [HUP],
SA_RESTORER|SA_RESTART, 0x7fba90647230}, 8) = 0
[pid 2227] unlink("maildrop/088D870065") = 0
[pid 2227] write(1, "status\0004\0reason\0\0\0", 18) = 18
[pid 2227] exit_group(4) = ?
The new version returns a status of 1 rather than 4, and does not print
out an error or send one to syslog.
Here's the tail end of the sendmail process with the new version:
[pid 24078] write(5, "testN\4testN\4testN\4testN\4testN\4te"..., 2964
<unfinished ...>
[pid 24078] <... write resumed> ) = 2964
[pid 24078] --- SIGCHLD (Child exited) @ 0 (0) ---
[pid 24078] read(5, "status\0001\0reason\0\0\0", 4096) = 18
[pid 24078] close(5) = 0
[pid 24078] wait4(24094, [{WIFEXITED(s) && WEXITSTATUS(s) == 1}], 0,
NULL) = 24094
[pid 24078] write(2, "sendmail: fatal: root(0): intern"..., 50sendmail:
fatal: root(0): internal protocol error
[pid 24078] sendto(3, "<18>Jun 2 06:57:10 postfix/send"..., 85,
MSG_NOSIGNAL, NULL, 0) = 85
[pid 24078] exit_group(75) = ?
And the old:
[pid 2220] write(5, "testN\4testN\4testN\4testN\4testN\4te"..., 2964
<unfinished ...>
[pid 2220] <... write resumed> ) = 2964
[pid 2220] read(5, <unfinished ...>
[pid 2220] <... read resumed> "status\0004\0reason\0\0\0", 4096) = 18
[pid 2220] close(5 <unfinished ...>
[pid 2220] <... close resumed> ) = 0
[pid 2220] wait4(2227, [{WIFEXITED(s) && WEXITSTATUS(s) == 4}], 0,
NULL) = 2227
[pid 2220] --- SIGCHLD (Child exited) @ 0 (0) ---
[pid 2220] write(2, "sendmail: fatal: root(0): messag"..., 47sendmail:
fatal: root(0): message file too big
[pid 2220] gettimeofday({1307042952, 12857}, NULL) = 0
[pid 2220] sendto(3, "<18>Jun 2 12:29:12 postfix/send"..., 81,
MSG_NOSIGNAL, NULL, 0) = 81
[pid 2220] exit_group(75) = ?
The postdrop process in the new version does seem to exit before
sendmail reads the status, as opposed to the old version, but that might
just be a timing issue with the trace. There's no apparent failure of
the postdrop process, it seems to be intentionally sending an status of
1 and voluntarily exiting.
Any other thoughts? What's the best way to turn on debugging for
postdrop? The faq mentions updating master.cf for daemons, but I didn't
see a way to pass a couple -v's to postdrop. Woops, cancel that, looks
like running sendmail with -v passes that on to postdrop.
Debug output from new version:
postdrop: rec_get: type N len 4 data test
postdrop: rec_get: type X len 0 data
postdrop: rec_get: type R len 20 data henson@csu
postdrop: rec_get: type E len 0 data
postdrop: vstream_fflush_some: fd 4 flush 4096
postdrop: send attr status = 1
postdrop: send attr reason =
postdrop: vstream_fflush_some: fd 1 flush 18
sendmail: vstream_buf_get_ready: fd 5 got 18
sendmail: /usr/sbin/postdrop -r -v -v -v -v: wanted attribute: status
sendmail: input attribute name: status
sendmail: input attribute value: 1
sendmail: /usr/sbin/postdrop -r -v -v -v -v: wanted attribute: (list
terminator)
sendmail: input attribute name: reason
sendmail: input attribute value: (end)
sendmail: /usr/sbin/postdrop -r -v -v -v -v: wanted attribute: (list
terminator)
sendmail: input attribute name: (end)
sendmail: fatal: root(0): internal protocol error
From old version:
postdrop: rec_get: type N len 4 data test
postdrop: rec_get: type X len 0 data
postdrop: rec_get: type R len 20 data henson@csu
postdrop: rec_get: type E len 0 data
postdrop: vstream_fflush_some: fd 4 flush 4096
postdrop: vstream_fflush_some: fd 4 flush 4096
postdrop: warning: uid=0: File too large
postdrop: send attr status = 4
postdrop: send attr reason =
postdrop: vstream_fflush_some: fd 1 flush 18
sendmail: vstream_buf_get_ready: fd 5 got 18
sendmail: /usr/sbin/postdrop -r -v -v -v: wanted attribute: status
sendmail: input attribute name: status
sendmail: input attribute value: 4
sendmail: /usr/sbin/postdrop -r -v -v -v: wanted attribute: (list
terminator)
sendmail: input attribute name: reason
sendmail: input attribute value: (end)
sendmail: /usr/sbin/postdrop -r -v -v -v: wanted attribute: (list
terminator)
sendmail: input attribute name: (end)
sendmail: fatal: root(0): message file too big
The only difference I see is the new version only has 1
vstream_fflush_some, while the old version has 2. And the new version
reports a status of 1 rather than 4.
Victor Duchovni
> On Wed, Jun 01, 2011 at 05:45:31PM -0700, Wietse Venema wrote:
>
> > Postfix hasn't changed, as far as I can tell. Perhaps something on
> > your system has changed.
>
> We did update a number of components, and after viewing postfix
> changelogs and source code without anything popping out, we went back to
> a system with the original config and updated only postfix (and db,
> which the packaging system pulled in), and verified the same change in
> behavior before I posted.
>
I see the same issue, on a host with 2.5.6, 2.7.2 and 2.8.3 all installed
in separate install trees, the 2.5.6 sendmail reports file size too large,
while 2.7.2 and 2.8.3 both report the protocol error.
$ for vers in 2.5.6 2.7.2 2.8.3; do echo $vers; (printf "From: vik...@example.com\nTo: vik...@example.com\nSubject: big email test\n\n"; yes test | head -c 100000000) | /path/to/postfix/$vers/sbin/sendmail -t; done
2.5.6
postdrop: warning: uid=0: File too large
sendmail: fatal: root(0): message file too big
2.7.2
sendmail: fatal: root(0): internal protocol error
2.8.3
sendmail: fatal: root(0): internal protocol error
The major change in 2.7 is below. The problem is that when sendmail(1)
extracts recipients from the headers, and the message is too large,
postdrop(1) will never see the extracted recipients.
@@ -452,9 +462,31 @@
vstring_free(buf);
/*
+ * As of Postfix 2.7 the pickup daemon discards mail without recipients.
+ * Such mail may enter the maildrop queue when "postsuper -r" is invoked
+ * before the queue manager deletes an already delivered message. Looking
+ * at file ownership is not a good way to make decisions on what mail to
+ * discard. Instead, the pickup server now requires that new submissions
+ * always have at least one recipient record.
+ *
+ * The Postfix sendmail command already rejects mail without recipients.
+ * However, in the future postdrop may receive mail via other programs,
+ * so we add a redundant recipient check here for future proofing.
+ *
+ * The test for the sender address is just for consistency of error
+ * reporting (report at submission time instead of pickup time). Besides
+ * the segment terminator records, there aren't any other mandatory
+ * records in a Postfix submission queue file.
+ */
+ if (from_count == 0 || rcpt_count == 0) {
+ status = CLEANUP_STAT_BAD;
+ mail_stream_cleanup(dst);
+ }
+
+ /*
* Finish the file.
*/
- if ((status = mail_stream_finish(dst, (VSTRING *) 0)) != 0) {
+ else if ((status = mail_stream_finish(dst, (VSTRING *) 0)) != 0) {
msg_warn("uid=%ld: %m", (long) uid);
postdrop_cleanup();
}
--
Viktor.
Wietse Venema
> On Thu, Jun 02, 2011 at 12:55:21PM -0700, Paul B. Henson wrote:
>
> > On Wed, Jun 01, 2011 at 05:45:31PM -0700, Wietse Venema wrote:
> >
> > > Postfix hasn't changed, as far as I can tell. Perhaps something on
> > > your system has changed.
> >
> > We did update a number of components, and after viewing postfix
> > changelogs and source code without anything popping out, we went back to
> > a system with the original config and updated only postfix (and db,
> > which the packaging system pulled in), and verified the same change in
> > behavior before I posted.
> >
>
> I see the same issue, on a host with 2.5.6, 2.7.2 and 2.8.3 all installed
> in separate install trees, the 2.5.6 sendmail reports file size too large,
> while 2.7.2 and 2.8.3 both report the protocol error.
Well no-one told me it happens with "sendmail -t", so I did not
test for that option (or the bazillion other permutations of Postfix
options). Let this be a reminder that a problem report should
contain all the information that is necessary to reproduce the
condition.
Wietse
*** src/postdrop/postdrop.c- Fri Jan 15 20:21:50 2010
--- src/postdrop/postdrop.c Thu Jun 2 20:34:06 2011
***************
*** 450,458 ****
saved_errno = errno;
while ((rec_type = rec_get_raw(VSTREAM_IN, buf, var_line_limit,
REC_FLAG_NONE)) != REC_TYPE_END
! && rec_type != REC_TYPE_EOF)
if (rec_type == REC_TYPE_ERROR)
msg_fatal("uid=%ld: malformed input", (long) uid);
errno = saved_errno;
break;
}
--- 450,464 ----
saved_errno = errno;
while ((rec_type = rec_get_raw(VSTREAM_IN, buf, var_line_limit,
REC_FLAG_NONE)) != REC_TYPE_END
! && rec_type != REC_TYPE_EOF) {
! /* Check these at submission time instead of pickup time. */
! if (rec_type == REC_TYPE_FROM)
! from_count++;
! if (rec_type == REC_TYPE_RCPT)
! rcpt_count++;
if (rec_type == REC_TYPE_ERROR)
msg_fatal("uid=%ld: malformed input", (long) uid);
+ }
errno = saved_errno;
break;
}
Only in src/postdrop: postdrop.o
Paul B. Henson
> The major change in 2.7 is below. The problem is that when sendmail(1)
> extracts recipients from the headers, and the message is too large,
> postdrop(1) will never see the extracted recipients.
Ah, Wietse tested with a recipient on the sendmail command line, the
problem only occurs when you pass -t and the receipient is read from the
headers.
Thanks for tracking this down. It's not causing any functional issues,
but the error message is a bit confusing. It would be nice if the
previous error message behavior could be restored.
Paul B. Henson
> Well no-one told me it happens with "sendmail -t", so I did not
> test for that option (or the bazillion other permutations of Postfix
> options). Let this be a reminder that a problem report should
> contain all the information that is necessary to reproduce the
> condition.
Well, I did include the test I was using in my original post:
$ (printf "From: rootcsupomona.edu\nTo: hensoncsupomona.edu\nSubject: big email test\n\n"; yes test | head -c 10000000) | /usr/sbin/sendmail -t
sendmail: fatal: henson(1005): internal protocol error
But it was certainly easy to miss the details, sorry.
Thanks much for the fix...
Wietse Venema
> On Thu, Jun 02, 2011 at 05:41:55PM -0700, Wietse Venema wrote:
>
> > Well no-one told me it happens with "sendmail -t", so I did not
> > test for that option (or the bazillion other permutations of Postfix
> > options). Let this be a reminder that a problem report should
> > contain all the information that is necessary to reproduce the
> > condition.
>
> Well, I did include the test I was using in my original post:
>
> $ (printf "From: rootcsupomona.edu\nTo: hensoncsupomona.edu\nSubject: big email test\n\n"; yes test | head -c 10000000) | /usr/sbin/sendmail -t
> sendmail: fatal: henson(1005): internal protocol error
I missed that. Below is the final patch.
Instead of yesterday's patch which adds (duplicated) input validation
support after write error, the final version simply disables input
validation after write error.
Wietse
[file: 20110603-postdrop-patch]
20110603
Bugfix (introduced: Postfix 2.7): "sendmail -t" reported
"protocol error" after queue file write error. File:
postdrop/postdrop.c.
*** /var/tmp/postfix-2.9-20110501/src/postdrop/postdrop.c Fri Jan 15 20:21:50 2010
--- src/postdrop/postdrop.c Fri Jun 3 07:58:04 2011
***************
*** 235,240 ****
--- 235,241 ----
int saved_errno;
int from_count = 0;
int rcpt_count = 0;
+ int validate_input = 1;
/*
* Fingerprint executables and core dumps.
***************
*** 453,458 ****
--- 454,460 ----
&& rec_type != REC_TYPE_EOF)
if (rec_type == REC_TYPE_ERROR)
msg_fatal("uid=%ld: malformed input", (long) uid);
+ validate_input = 0;
errno = saved_errno;
break;
}
***************
*** 478,484 ****
* the segment terminator records, there aren't any other mandatory
* records in a Postfix submission queue file.
*/
! if (from_count == 0 || rcpt_count == 0) {
status = CLEANUP_STAT_BAD;
mail_stream_cleanup(dst);
}
--- 480,486 ----
* the segment terminator records, there aren't any other mandatory
* records in a Postfix submission queue file.
*/
! if (validate_input && (from_count == 0 || rcpt_count == 0)) {
status = CLEANUP_STAT_BAD;
mail_stream_cleanup(dst);
}