Subject: Re: debug through different log files - msg#00080

Previous Message by Date: click to view message preview

Re: debug through different log files

Benoit Schmid wrote: Could you explain me why the mail.log reports an error at the rcpt to level and the master file reports it after the data has been accepted? The debug log doesn't show that the data was accepted. If you review the debug logs again, you will see the remote Exim MTA to which the iMS MTA is attempting to send a message to, has advertised that it can handle command pipelining due to the presence of the PIPELINING keyword. The iMS MTA therefore batches up the MAIL FROM, RCPT TO and DATA commands. It is the remote MTA's responsibility to respond to each of the commands in the order that they were received. Since we only see one "250 OK" was received, then we know that we got a response to the MAIL FROM command, but no further responses. Am I wright by saying that we got a 250 response for the data, but there was a problem during the transmission of the email body? No, see above. What most likely happened was the network connection was terminated on the remote end (or something in between eg. firewall), although that's an assumption based on the fact that the iMS MTA was getting read failures. Debug logs or a network trace on the remote side would likely help to debug this further. Cheers Andrew 27-Aug-2007 09:05:45.43 0a93.111.967 tcp_mailcleaner QE 17 listbox+trampoline+2010138+C660D650-50FB-11DC-B289-DCC98C4BADF8+31064485-958bb3-B7dvP5mc3PhiK979QBapAg@xxxxxxxxxxxxxxxx rfc822;lozanov1-QrDOAlxOXrYXXHkOk0aIfQ@xxxxxxxxxxxxxxxx @mc.unige.ch:x@xxxxxxxxxxxx /opt/SUNWmsgsr/data/queue/tcp_mailcleaner/ZHf0G3M6NilrA.00 <20070822220541.E66B318459-5zO2nuI/Xm4jKIy/Ksm9WVaTQe2KTcn/@public.gmane.org> msguser mc.unige.ch Error reading SMTP packet; response to RCPT TO command expected 09:05:40.75: Initializing message dequeue via quc_rinit, file "/opt/SUNWmsgsr/data/queue/tcp_mailcleaner/ZHf0G3M6NilrA.00" 09:05:40.75: Reading first To: address 09:05:40.75: Forced routing to mc.unige.ch 09:05:40.75: Setting up connection to "x.unige.ch", initial mailbox "x" 09:05:40.75: No connection currently open 09:05:40.75: Opening new connection for x.unige.ch 09:05:40.75: No MX lookup done 09:05:40.75: pmt_smtp_open: Connecting to x.unige.ch 09:05:40.75: TCP active open: Trying to connect to 129.194.9.x 09:05:40.75: smtp_open to x.unige.ch returned 9 09:05:40.76: Reading initial status line from remote server... 09:05:40.76: Got status : "220 x.unige.ch ESMTP Exim 4.66 Mon, 27 Aug 2007 09:05:40 +0200" 09:05:40.76: Starting SMTP dialogue 09:05:40.76: Sending : "EHLO victor.unige.ch" 09:05:40.76: Got status : "250-x.unige.ch Hello victor.unige.ch [129.194.9.224]" 09:05:40.76: Got EHLO options: 09:05:40.76: - - - - - - - - - - - - 09:05:40.76: HELP= 09:05:40.76: PIPELINING= 09:05:40.76: SIZE=52428800 09:05:40.76: - - - - - - - - - - - - 09:05:40.76: DSN extension not found 09:05:40.76: Sending : "MAIL FROM:<listbox+trampoline+2010138+C660D650-50FB-11DC-B289-DCC98C4BADF8+31064485-958bb3-B7dvP5mc3PhiK979QBapAg@xxxxxxxxxxxxxxxx> SIZE=17408 09:05:40.76: Sending : "RCPT TO:<@x.unige.ch:x@xxxxxxxxxxxx> 09:05:40.76: Sending : "DATA" 09:05:45.43: Got status : "250 OK" 09:05:45.43: smtp_pmt_read: [0x0000000f] network read returned no data, repeating read 09:05:45.43: smtp_pmt_read: [0x0000000f] network read returned no data, repeating read 09:05:45.43: smtp_pmt_read: [0x0000000f] network read returned no data, repeating read 09:05:45.43: smtp_pmt_read: [0x0000000f] network read returned no data, repeating read 09:05:45.43: smtp_pmt_read: [0x0000000f] network read returned no data, repeating read 09:05:45.43: smtp_pmt_read: [0x0000000f] network read returned no data, repeating read 09:05:45.43: smtp_pmt_read: [0x0000000f] network read returned no data, repeating read 09:05:45.43: smtp_pmt_read: [0x0000000f] network read returned no data, repeating read 09:05:45.43: smtp_pmt_read: [0x0000000f] network read returned no data, repeating read 09:05:45.43: smtp_pmt_read: [0x0000000f] network read returned no data 09:05:45.43: smtp_pmt_close: [0x0000000f] status 0 09:05:45.43: Shutting down message dequeue and any open connections Thanks in advance for your help.

Next Message by Date: click to view message preview

Messages marked deleted

Sun Java(tm) System Messaging Server 6.2-8.04 (built Feb 28 2007) libimta.so 6.2-8.04 (built 19:28:07, Feb 28 2007) SunOS hostname 5.10 Generic_118833-36 sun4u sparc SUNW,Sun-Fire-V490 This is a continuation of a thread with the same name from 10/05/2005 I think that I have identified an account with the behavior Kelly describes. New messages are being given UIDs within the deleted list. Kelly never described how to fix this. Should I just modify store.usr and change the deleted list? store.usr: username 1188194536 174 1188159697 1:173 1:158,174:18624 imcheck: NAME: user/username EXISTS: 6 LAST UID: 178 UID VALIDITY: 1187575098 SUB: 1 ACL: username lrswipcda [27/Aug/2007:07:21:41 -0500] hostname imcheck[8985]: Store Warning: user/username invalid sequence in peruser flags: 18624 smime.p7s Description: S/MIME Cryptographic Signature

Previous Message by Thread: click to view message preview

Re: debug through different log files

Benoit Schmid wrote: Could you explain me why the mail.log reports an error at the rcpt to level and the master file reports it after the data has been accepted? The debug log doesn't show that the data was accepted. If you review the debug logs again, you will see the remote Exim MTA to which the iMS MTA is attempting to send a message to, has advertised that it can handle command pipelining due to the presence of the PIPELINING keyword. The iMS MTA therefore batches up the MAIL FROM, RCPT TO and DATA commands. It is the remote MTA's responsibility to respond to each of the commands in the order that they were received. Since we only see one "250 OK" was received, then we know that we got a response to the MAIL FROM command, but no further responses. Am I wright by saying that we got a 250 response for the data, but there was a problem during the transmission of the email body? No, see above. What most likely happened was the network connection was terminated on the remote end (or something in between eg. firewall), although that's an assumption based on the fact that the iMS MTA was getting read failures. Debug logs or a network trace on the remote side would likely help to debug this further. Cheers Andrew 27-Aug-2007 09:05:45.43 0a93.111.967 tcp_mailcleaner QE 17 listbox+trampoline+2010138+C660D650-50FB-11DC-B289-DCC98C4BADF8+31064485-958bb3-B7dvP5mc3PhiK979QBapAg@xxxxxxxxxxxxxxxx rfc822;lozanov1-QrDOAlxOXrYXXHkOk0aIfQ@xxxxxxxxxxxxxxxx @mc.unige.ch:x@xxxxxxxxxxxx /opt/SUNWmsgsr/data/queue/tcp_mailcleaner/ZHf0G3M6NilrA.00 <20070822220541.E66B318459-5zO2nuI/Xm4jKIy/Ksm9WVaTQe2KTcn/@public.gmane.org> msguser mc.unige.ch Error reading SMTP packet; response to RCPT TO command expected 09:05:40.75: Initializing message dequeue via quc_rinit, file "/opt/SUNWmsgsr/data/queue/tcp_mailcleaner/ZHf0G3M6NilrA.00" 09:05:40.75: Reading first To: address 09:05:40.75: Forced routing to mc.unige.ch 09:05:40.75: Setting up connection to "x.unige.ch", initial mailbox "x" 09:05:40.75: No connection currently open 09:05:40.75: Opening new connection for x.unige.ch 09:05:40.75: No MX lookup done 09:05:40.75: pmt_smtp_open: Connecting to x.unige.ch 09:05:40.75: TCP active open: Trying to connect to 129.194.9.x 09:05:40.75: smtp_open to x.unige.ch returned 9 09:05:40.76: Reading initial status line from remote server... 09:05:40.76: Got status : "220 x.unige.ch ESMTP Exim 4.66 Mon, 27 Aug 2007 09:05:40 +0200" 09:05:40.76: Starting SMTP dialogue 09:05:40.76: Sending : "EHLO victor.unige.ch" 09:05:40.76: Got status : "250-x.unige.ch Hello victor.unige.ch [129.194.9.224]" 09:05:40.76: Got EHLO options: 09:05:40.76: - - - - - - - - - - - - 09:05:40.76: HELP= 09:05:40.76: PIPELINING= 09:05:40.76: SIZE=52428800 09:05:40.76: - - - - - - - - - - - - 09:05:40.76: DSN extension not found 09:05:40.76: Sending : "MAIL FROM:<listbox+trampoline+2010138+C660D650-50FB-11DC-B289-DCC98C4BADF8+31064485-958bb3-B7dvP5mc3PhiK979QBapAg@xxxxxxxxxxxxxxxx> SIZE=17408 09:05:40.76: Sending : "RCPT TO:<@x.unige.ch:x@xxxxxxxxxxxx> 09:05:40.76: Sending : "DATA" 09:05:45.43: Got status : "250 OK" 09:05:45.43: smtp_pmt_read: [0x0000000f] network read returned no data, repeating read 09:05:45.43: smtp_pmt_read: [0x0000000f] network read returned no data, repeating read 09:05:45.43: smtp_pmt_read: [0x0000000f] network read returned no data, repeating read 09:05:45.43: smtp_pmt_read: [0x0000000f] network read returned no data, repeating read 09:05:45.43: smtp_pmt_read: [0x0000000f] network read returned no data, repeating read 09:05:45.43: smtp_pmt_read: [0x0000000f] network read returned no data, repeating read 09:05:45.43: smtp_pmt_read: [0x0000000f] network read returned no data, repeating read 09:05:45.43: smtp_pmt_read: [0x0000000f] network read returned no data, repeating read 09:05:45.43: smtp_pmt_read: [0x0000000f] network read returned no data, repeating read 09:05:45.43: smtp_pmt_read: [0x0000000f] network read returned no data 09:05:45.43: smtp_pmt_close: [0x0000000f] status 0 09:05:45.43: Shutting down message dequeue and any open connections Thanks in advance for your help.

Next Message by Thread: click to view message preview

Messages marked deleted

Sun Java(tm) System Messaging Server 6.2-8.04 (built Feb 28 2007) libimta.so 6.2-8.04 (built 19:28:07, Feb 28 2007) SunOS hostname 5.10 Generic_118833-36 sun4u sparc SUNW,Sun-Fire-V490 This is a continuation of a thread with the same name from 10/05/2005 I think that I have identified an account with the behavior Kelly describes. New messages are being given UIDs within the deleted list. Kelly never described how to fix this. Should I just modify store.usr and change the deleted list? store.usr: username 1188194536 174 1188159697 1:173 1:158,174:18624 imcheck: NAME: user/username EXISTS: 6 LAST UID: 178 UID VALIDITY: 1187575098 SUB: 1 ACL: username lrswipcda [27/Aug/2007:07:21:41 -0500] hostname imcheck[8985]: Store Warning: user/username invalid sequence in peruser flags: 18624 smime.p7s Description: S/MIME Cryptographic Signature