4 Replies Latest reply on May 28, 2015 3:26 PM by 831622

    Error reading SMTP packet

    831622

      Hi Friend,

      I have front end and back end Oracle Messaging Server, both are running:

           bash-3.00# ./imsimta version

           Oracle Communications Messaging Exchange Server 7u4-18.01 64bit (built Jul 15 2010)

           libimta.so 7u4-18.01 64bit (built 13:19:32, Jul 15 2010)

           Using /opt/sun/comms/messaging64/config/imta.cnf (compiled)

           SunOS BDG2SMSG0301 5.10 Generic_142910-17 i86pc i386 i86pc

       

      I have problem with Gmail. An user from my domain1 can send email to Gmail but some account from Gmail can not send mail to my server and have log on MTA as below:

       

      27-May-2015 09:48:11.50 58d.9c8.9299 tcp_local    tcp_intranet VES 0 <aaa>@gmail.com rfc822;<yyy1>@domain1.com @BDG2SMSG0101.vntt.vn:catchall@domain1.com   mailsrv mail-pd0-f174.google.com ([209.85.192.174]) Error reading SMTP packet

       

       

      27-May-2015 10:11:30.51 743.166.1276 tcp_local    tcp_intranet VES 0 <bbb>@gmail.com rfc822;<yyy2>@domain1.com @BDG2SMSG0101.vntt.vn:catchall@domain1.com   mailsrv mail-wi0-f173.google.com ([209.85.212.173]) Error reading SMTP packet

       

       

      27-May-2015 10:11:30.51 743.166.1276 tcp_local    tcp_intranet VES 0 <bbb>@gmail.com rfc822;<yyy3>@domain1.com @BDG2SMSG0101.vntt.vn:sales7@domain1.com   mailsrv mail-wi0-f173.google.com ([209.85.212.173]) Error reading SMTP packet

       

       

      27-May-2015 10:13:06.58 743.192.1468 tcp_local    tcp_intranet VES 0 <ccc>@gmail.com rfc822;<yyy4>@domain1.com @BDG2SMSG0101.vntt.vn:catchall@domain1.com   mailsrv mail-pd0-f173.google.com ([209.85.192.173]) Error reading SMTP packet

       

       

      In this log file, <aaa>gmail.com can not send email to domain1.com but domain1.com always can send mail to gmail.com.

      Not all email from Gmail, just some email from Gmail can not send email to domain1.com.

      Can you help me? What's problem ?

        • 1. Re: Error reading SMTP packet
          Kellyc-Oracle

          This looks like the problem is on the gmail side. The "Error reading SMTP packet" error means that the Messaging Server MTA tcp_smtp_server process was waiting for more data from the remote MTA and it never arrived or the connection was broken. This could be a problem on the remote MTA or with a firewall or other intermediate network-level system in between.

          If you have some firewall system which gets involved with incoming connections at the SMTP layer, that would be the first place to look.

          From the Messaging Server side, you could enable debugging to get more details of what is going on. It is very likely to show you want I have already said.

          The easiest way to enable this debugging is to add the slave_debug keyword to the channel which is receiving the messages, tcp_local in this case. However, enabling that debug for all messages coming into your system will create tons of log files. You would want to enable it, do imsimta cnbuild; imsimta resstart dispatcher, duplicate the problem, and disable it again as quickly as possible.

           

          Alternatively, you could use $U in a mapping table to enable the debug more specifically. For more info about that, see the following MOS knowledge article:

              Use $U5 in PORT_ACCESS to Enable Debug for a Specific Client (Doc ID 1986794.1)

          Unfortunately, there was a bug which prevented that from being useful. It was fixed in 7.0.4.24.0 -- a few patch revs newer than the old version you are running.

          The current version and patch rev is 7.0.5.35.0.

           

          Once you have the debug enabled and duplicate the problem, grep the slave_debug log files for the sender email address and find the log file that matches the time of mail.log_current error about it. In that log file, you will see the details of the connection and SMTP transaction up to the point of the failure. I expect the time stamps will show a long gap between the previous line and the line which reports the failure. It will have been a long timeout waiting for the next packet from the remote MTA.

           

          What we often see is that a firewall is involved in processing the SMTP transaction, it does not like something about this message, so it silently drops the connection. That leaves both ends thinking the other end has failed to respond. If that is the case, the solution will lie with the firewall vendor/support.

          1 person found this helpful
          • 2. Re: Error reading SMTP packet
            831622

            Thank you so much for your reply, this is very helpful to me. I was debug an email and result as below:

             

            20:50:30.28: Debug output enabled, program version V7.4 compiled Jul 15 2010 13:21:28

            20:50:30.28: Oracle Communications Messaging Exchange Server shared library version 7u4-18.01 linked 13:19:32, Jul 15 2010

            20:50:30.28: SMTP server initiated on socket 13

            20:50:30.28: Received connection from @[209.85.160.176]

            20:50:30.28: Transport/application information for connection: TCP|x.y.z.w|25|209.85.160.176|33108 SMTP

            20:50:30.28: Applying PORT_ACCESS mapping to "TCP|x.y.z.w|25|209.85.160.176|33108"

            20:50:30.28: PORT_ACCESS result: EXTERNAL

            20:50:30.28: Ruleset: EXTERNAL

            20:50:30.28: Realm:

            20:50:30.28: Sending    : "220 smtp.mx.domain.com -- Server ESMTP  Authorised Use Only"

            20:50:30.28: Session/transaction timer check

            20:50:30.55: Received   : "EHLO mail-yk0-f176.google.com"

            20:50:30.55: Remote host IDENT information: [209.85.160.176]

            20:50:30.55: Attempting channel switch: Rewriting "user@[209.85.160.176]"

            20:50:30.55: Creating SASL context for service "smtp" and ruleset "EXTERNAL"

            20:50:30.55: SASL context creation returned status = 0

            20:50:30.55: Sending    : "250-smtp.mx.domain.com"

            20:50:30.55: Sending    : "250-8BITMIME"

            20:50:30.55: Sending    : "250-PIPELINING"

            20:50:30.55: Sending    : "250-CHUNKING"

            20:50:30.55: Sending    : "250-DSN"

            20:50:30.55: Sending    : "250-ENHANCEDSTATUSCODES"

            20:50:30.55: Sending    : "250-EXPN"

            20:50:30.55: Sending    : "250-HELP"

            20:50:30.55: Sending    : "250-XADR"

            20:50:30.55: Sending    : "250-XSTA"

            20:50:30.55: Sending    : "250-XCIR"

            20:50:30.55: Sending    : "250-XGEN"

            20:50:30.55: Sending    : "250-XLOOP 05D57CFB3B62041490C784FA5FE723EB"

            20:50:30.55: Sending    : "250-STARTTLS"

            20:50:30.55: Listing available SASL mechanisms

            20:50:30.55: SASL mechanism list status = 0

            20:50:30.55: Sending    : "250-AUTH PLAIN LOGIN"

            20:50:30.55: Sending    : "250-AUTH=LOGIN PLAIN"

            20:50:30.55: Sending    : "250-ETRN"

            20:50:30.55: Sending    : "250-NO-SOLICITING"

            20:50:30.55: Sending    : "250 SIZE 0"

            20:50:30.82: Received   : "STARTTLS"

            20:50:30.82: Sending    : "220 2.5.0 Go ahead with TLS negotiation.

            20:50:30.82: TLS ignore bad certificate flag = 1

            20:50:31.37: TLS negotiation accepted

            20:50:31.64: Received   : "EHLO mail-yk0-f176.google.com"

            20:50:31.64: Remote host IDENT information: [209.85.160.176]

            20:50:31.64: Attempting channel switch: Rewriting "user@[209.85.160.176]"

            20:50:31.64: Sending    : "250-smtp.mx.domain.com"

            20:50:31.64: Sending    : "250-8BITMIME"

            20:50:31.64: Sending    : "250-PIPELINING"

            20:50:31.64: Sending    : "250-CHUNKING"

            20:50:31.64: Sending    : "250-DSN"

            20:50:31.64: Sending    : "250-ENHANCEDSTATUSCODES"

            20:50:31.64: Sending    : "250-EXPN"

            20:50:31.64: Sending    : "250-HELP"

            20:50:31.64: Sending    : "250-XADR"

            20:50:31.64: Sending    : "250-XSTA"

            20:50:31.64: Sending    : "250-XCIR"

            20:50:31.64: Sending    : "250-XGEN"

            20:50:31.64: Sending    : "250-XLOOP 05D57CFB3B62041490C784FA5FE723EB"

            20:50:31.64: Listing available SASL mechanisms

            20:50:31.64: SASL mechanism list status = 0

            20:50:31.64: Sending    : "250-AUTH PLAIN LOGIN"

            20:50:31.64: Sending    : "250-AUTH=LOGIN PLAIN"

            20:50:31.64: Sending    : "250-ETRN"

            20:50:31.64: Sending    : "250-NO-SOLICITING"

            20:50:31.64: Sending    : "250 SIZE 0"

            20:50:31.91: Received   : "MAIL FROM:<usergmail@gmail.com> SIZE=96258"

            20:50:31.91: Debug output enabled, system hostname.domain.com, process 2780.5b, message enqueue routines version V7.4 compiled Jul

            15 2010 13:19:36

            20:50:31.91: Initializing SpamAssassin message context

            20:50:31.91: SpamAssassin connection info (not used): 209.85.160.176

            20:50:31.91: SpamAssassin envelope from (not used): usergmail@gmail.com

            20:50:31.91: Initializing ClamAV message context system->message_buffer_size = 1048576

            20:50:31.91: ClamAV connection info (not used): 209.85.160.176

            20:50:31.91: ClamAV envelope from (not used): usergmail@gmail.com

            20:50:31.91: Sending    : "250 2.5.0 Address and options OK."

            20:50:31.91: Received   : "RCPT TO:<user@domain1.com>"

            20:50:31.91: SpamAssassin recipient: @hostname.domain.com:all@domain1.com

            20:50:31.91:   Optin value: spam

            20:50:31.91: ClamAV recipient: @hostname.domain.com:all@domain1.com

            20:50:31.91: Sending    : "250 2.1.5 user@domain1.com OK."

            20:50:31.91: Received   : "RCPT TO:<doc1@navicorp.com.vn>"

            20:50:31.91: SpamAssassin recipient: @hostname.domain.com:all@domain1.com

            20:50:31.91:   Optin value: spam

            20:50:31.91: ClamAV recipient: @hostname.domain.com:all@domain1.com

            20:50:31.91: Sending    : "250 2.1.5 user1@domain1.com OK."

            20:50:31.91: Received   : "RCPT TO:<user2@domain1.com>"

            20:50:31.91: SpamAssassin recipient: @hostname.domain.com:all@domain1.com

            20:50:31.91:   Optin value: spam

            20:50:31.91: ClamAV recipient: @hostname.domain.com:all@domain1.com

            20:50:31.91: Sending    : "250 2.1.5 user2@domain1.com OK."

            20:50:31.91: Received   : "BDAT 65536"

            20:50:31.91: Session/transaction timer check

            20:50:32.23: Session/transaction timer check

            20:50:32.48: Session/transaction timer check

            20:50:32.53: Session/transaction timer check

            20:50:32.57: Session/transaction timer check

            20:50:32.59: Sending    : "250 2.5.0 Message chunk received."

            20:50:32.59: Sending    : "250 2.5.0 Message chunk received."

            20:50:32.59: Sending    : "250 2.5.0 Message chunk received."

            20:50:32.86: os_smtp_read: [13] network read returned no data

            20:50:32.86: Freeing SpamAssassin message context

            20:50:32.86: Freeing ClamAV message context

            20:50:32.86: Shutting down SASL server context

            20:50:32.86: smtpc_enqueue returning a status of 201 (Basic no)

            20:50:32.86: SMTP routine failure from SMTPC_ENQUEUE

            20:50:32.86: pmt_close: [13] status 0

             

            What is <"Received :"BDAT 65536"> and <"Sending    : "250 2.5.0 Message chunk received.">

             

            Thank you so much!

            • 3. Re: Error reading SMTP packet
              Kellyc-Oracle

              BDAT is from RFC 3030 - SMTP Service Extensions for Transmission of Large and Binary MIME Messages

               

              If you enable the debug using $U5 in a mapping table (if you have a sufficiently recent version where that will work), the "5" sets the MM_DEBUG level as well as enabling the debug.

              If you only use slave_debug on the channel, then you also need to add MM_DEBUG=5 to option.dat (and imsimta cnbuild; and imsimta restart dispatcher) to get the same level of info.

              You may also need OS_DEBUG=1.

              That will show data as it is arriving where right now you are only showing the higher level, like 'Received   : "BDAT 65536"' and 'Sending    : "250 2.5.0 Message chunk received."'

               

              The error and the timing do not indicate the timeout type problem I was expecting:

               

              20:50:31.91: Received   : "BDAT 65536"

              20:50:31.91: Session/transaction timer check

              20:50:32.23: Session/transaction timer check

              20:50:32.48: Session/transaction timer check

              20:50:32.53: Session/transaction timer check

              20:50:32.57: Session/transaction timer check

              20:50:32.59: Sending    : "250 2.5.0 Message chunk received."

              20:50:32.59: Sending    : "250 2.5.0 Message chunk received."

              20:50:32.59: Sending    : "250 2.5.0 Message chunk received."

              20:50:32.86: os_smtp_read: [13] network read returned no data

               

              There have been some fixes related to BDAT in more recent patch.

               

              I am not sure if enabling more detailed debug will show it is one of those problems or if this still might be a firewall problem.

              • 4. Re: Error reading SMTP packet
                831622

                Thank you so much!