Loading ...
Sorry, an error occurred while loading the content.

Re: internal protocol error from sendmail for messages > message_size_limit

Expand Messages
  • Wietse Venema
    ... [FreeBSD 8.0] % postconf mail_version mail_version = 2.9-20110501 % limit filesize 1k % sendmail wietse
    Message 1 of 8 , Jun 1, 2011
    • 0 Attachment
      Paul B. Henson:
      > 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: root@...\nTo: henson@...\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: root@...\nTo: henson@...\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
      ... 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
      Message 2 of 8 , Jun 2, 2011
      • 0 Attachment
        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 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.

        Thanks...


        --
        Paul B. Henson | (909) 979-6361 | http://www.csupomona.edu/~henson/
        Operating Systems and Network Analyst | henson@...
        California State Polytechnic University | Pomona CA 91768
      • Victor Duchovni
        ... 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
        Message 3 of 8 , Jun 2, 2011
        • 0 Attachment
          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.

          $ for vers in 2.5.6 2.7.2 2.8.3; do echo $vers; (printf "From: viktor@...\nTo: viktor@...\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
          ... 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
          Message 4 of 8 , Jun 2, 2011
          • 0 Attachment
            Victor Duchovni:
            > 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
            ... 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.
            Message 5 of 8 , Jun 2, 2011
            • 0 Attachment
              On Thu, Jun 02, 2011 at 03:41:06PM -0700, Victor Duchovni wrote:

              > 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 | (909) 979-6361 | http://www.csupomona.edu/~henson/
              Operating Systems and Network Analyst | henson@...
              California State Polytechnic University | Pomona CA 91768
            • Paul B. Henson
              ... 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 ;
              Message 6 of 8 , Jun 2, 2011
              • 0 Attachment
                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

                But it was certainly easy to miss the details, sorry.

                Thanks much for the fix...


                --
                Paul B. Henson | (909) 979-6361 | http://www.csupomona.edu/~henson/
                Operating Systems and Network Analyst | henson@...
                California State Polytechnic University | Pomona CA 91768
              • Wietse Venema
                ... 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
                Message 7 of 8 , Jun 3, 2011
                • 0 Attachment
                  Paul B. Henson:
                  > 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);
                  }
                Your message has been successfully submitted and would be delivered to recipients shortly.