Loosing IMAP connection after 2 minutes of: mchk -v

[Thiago Facchini]

I really dont know what is happening.

I just know that if I run: "/usr/local/psa/admin/sbin/mchk -v" I can get my IMAP connection back, BUT, after 2 minutes I cant connect with IMAP service from any mail client.

I read alot and search alot and cant figure out how to fix it.
So Im posting here, my last hope.

Sorry for my english and thanks in advance.

 

[Thiago Facchini]

Update:
In server console I can telnet 143 and log in.

But, I still cant connect from mail clients.

 

[IgorG]

Did you try to find a reason in /usr/local/psa/var/log/maillog ?

 

[Thiago Facchini]

Igor,

Looking for the log maybe I created a new obstacle, let me try explain:

How I know how to make the "problem" happen again, I reseted the maillog file.
So I Restore mail configuration settings using mchk and make the error happen sometimes again, to see in log as you said.

But for my surprise when I check the log he still empty. So now I have 2 problems, the 1st is mentioned in topic and now my maillog file is always empty.

How proceed Igor?

Thanks in advance and sorry for bad english.
Thiago Facchini

 

[Thiago Facchini]

INFO UPDATE: Monitoring the logs I discovered that 3 things:

1. Everytime that I connect from Macintosh Mail the service problem starts, I dont have any idea about what is causing error, but, when I close Macintosh Mail, after some seconds, it happens (log) and everything came to normal again.

Jun 30 15:00:50 izzy01 postfix/smtpd[13549]: warning: 189.110.24.35: hostname 189-110-24-35.dsl.telesp.net.br verification failed: Name or service not known
Jun 30 15:00:50 izzy01 postfix/smtpd[13549]: connect from unknown[189.110.24.35]
Jun 30 15:00:50 izzy01 postfix/smtpd[13630]: warning: 189.110.24.35: hostname 189-110-24-35.dsl.telesp.net.br verification failed: Name or service not known
Jun 30 15:00:50 izzy01 postfix/smtpd[13630]: connect from unknown[189.110.24.35]
Jun 30 15:00:50 izzy01 postfix/smtpd[13632]: warning: 189.110.24.35: hostname 189-110-24-35.dsl.telesp.net.br verification failed: Name or service not known
Jun 30 15:00:50 izzy01 postfix/smtpd[13632]: connect from unknown[189.110.24.35]
Jun 30 15:00:50 izzy01 plesk_saslauthd[13639]: listen=6, status=5, dbpath='/plesk/passwd.db', chroot=1, unprivileged=1
Jun 30 15:00:50 izzy01 plesk_saslauthd[13639]: privileges set to (104:113) (effective 104:113)
Jun 30 15:00:50 izzy01 plesk_saslauthd[13639]: main cycle started
Jun 30 15:00:50 izzy01 plesk_saslauthd[13639]: main cycle iteration
Jun 30 15:00:50 izzy01 plesk_saslauthd[13639]: activity on 1 channel(s)
Jun 30 15:00:50 izzy01 plesk_saslauthd[13639]: new client (fd=10) registered
Jun 30 15:00:50 izzy01 plesk_saslauthd[13639]: main cycle iteration
Jun 30 15:00:50 izzy01 plesk_saslauthd[13639]: activity on 2 channel(s)
Jun 30 15:00:50 izzy01 plesk_saslauthd[13639]: new client (fd=11) registered
Jun 30 15:00:50 izzy01 plesk_saslauthd[13639]: some read activity on client 10
Jun 30 15:00:50 izzy01 plesk_saslauthd[13639]: read(10, &buf, 2)=2
Jun 30 15:00:50 izzy01 plesk_saslauthd[13639]: processing client data chunk [state=0]
Jun 30 15:00:50 izzy01 plesk_saslauthd[13639]: read(10, &buf, 7)=7
Jun 30 15:00:50 izzy01 plesk_saslauthd[13639]: processing client data chunk [state=1]
Jun 30 15:00:50 izzy01 plesk_saslauthd[13639]: read(10, &buf, 2)=2
Jun 30 15:00:50 izzy01 plesk_saslauthd[13639]: processing client data chunk [state=2]
Jun 30 15:00:50 izzy01 plesk_saslauthd[13639]: read(10, &buf, 11)=11
Jun 30 15:00:50 izzy01 plesk_saslauthd[13639]: processing client data chunk [state=3]
Jun 30 15:00:50 izzy01 plesk_saslauthd[13639]: read(10, &buf, 2)=2
Jun 30 15:00:50 izzy01 plesk_saslauthd[13639]: processing client data chunk [state=4]
Jun 30 15:00:50 izzy01 plesk_saslauthd[13639]: read(10, &buf, 4)=4
Jun 30 15:00:50 izzy01 plesk_saslauthd[13639]: processing client data chunk [state=5]
Jun 30 15:00:50 izzy01 plesk_saslauthd[13639]: read(10, &buf, 2)=2
Jun 30 15:00:50 izzy01 plesk_saslauthd[13639]: processing client data chunk [state=6]
Jun 30 15:00:50 izzy01 plesk_saslauthd[13639]: read(10, &buf, 14)=14
Jun 30 15:00:50 izzy01 plesk_saslauthd[13639]: processing client data chunk [state=7]
Jun 30 15:00:50 izzy01 plesk_saslauthd[13639]: No such user '[email protected]' in mail authorization database
Jun 30 15:00:50 izzy01 plesk_saslauthd[13639]: failed mail authenticatication attempt for user '[email protected]' (password len=12)
Jun 30 15:00:50 izzy01 plesk_saslauthd[13639]: main cycle iteration
Jun 30 15:00:50 izzy01 plesk_saslauthd[13639]: activity on 2 channel(s)
Jun 30 15:00:50 izzy01 plesk_saslauthd[13639]: some write activity on client 10
Jun 30 15:00:50 izzy01 plesk_saslauthd[13639]: attempt to write(10, &buf, 4)
Jun 30 15:00:50 izzy01 plesk_saslauthd[13639]: client 10 processed
Jun 30 15:00:50 izzy01 plesk_saslauthd[13639]: some read activity on client 11
Jun 30 15:00:50 izzy01 plesk_saslauthd[13639]: read(11, &buf, 2)=2
Jun 30 15:00:50 izzy01 plesk_saslauthd[13639]: processing client data chunk [state=0]
Jun 30 15:00:50 izzy01 plesk_saslauthd[13639]: read(11, &buf, 5)=5
Jun 30 15:00:50 izzy01 plesk_saslauthd[13639]: processing client data chunk [state=1]
Jun 30 15:00:50 izzy01 plesk_saslauthd[13639]: read(11, &buf, 2)=2
Jun 30 15:00:50 izzy01 plesk_saslauthd[13639]: processing client data chunk [state=2]
Jun 30 15:00:50 izzy01 plesk_saslauthd[13639]: read(11, &buf, 6)=6
Jun 30 15:00:50 izzy01 plesk_saslauthd[13639]: processing client data chunk [state=3]
Jun 30 15:00:50 izzy01 plesk_saslauthd[13639]: read(11, &buf, 2)=2
Jun 30 15:00:50 izzy01 plesk_saslauthd[13639]: processing client data chunk [state=4]
Jun 30 15:00:50 izzy01 plesk_saslauthd[13639]: read(11, &buf, 4)=4
Jun 30 15:00:50 izzy01 plesk_saslauthd[13639]: processing client data chunk [state=5]
Jun 30 15:00:50 izzy01 plesk_saslauthd[13639]: read(11, &buf, 2)=2
Jun 30 15:00:50 izzy01 plesk_saslauthd[13639]: processing client data chunk [state=6]
Jun 30 15:00:50 izzy01 plesk_saslauthd[13639]: read(11, &buf, 16)=16
Jun 30 15:00:50 izzy01 plesk_saslauthd[13639]: processing client data chunk [state=7]
Jun 30 15:00:50 izzy01 plesk_saslauthd[13639]: No such user '[email protected]' in mail authorization database
Jun 30 15:00:50 izzy01 plesk_saslauthd[13639]: failed mail authenticatication attempt for user '[email protected]' (password len=7)
Jun 30 15:00:50 izzy01 plesk_saslauthd[13639]: main cycle iteration
Jun 30 15:00:50 izzy01 plesk_saslauthd[13639]: activity on 1 channel(s)
Jun 30 15:00:50 izzy01 plesk_saslauthd[13639]: some write activity on client 11
Jun 30 15:00:50 izzy01 plesk_saslauthd[13639]: attempt to write(11, &buf, 4)
Jun 30 15:00:50 izzy01 plesk_saslauthd[13639]: client 11 processed
Jun 30 15:00:50 izzy01 plesk_saslauthd[13639]: main cycle iteration
Jun 30 15:00:50 izzy01 postfix/smtpd[13632]: warning: SASL authentication failure: Password verification failed
Jun 30 15:00:50 izzy01 postfix/smtpd[13632]: warning: unknown[189.110.24.35]: SASL PLAIN authentication failed: authentication failure
Jun 30 15:00:50 izzy01 postfix/smtpd[13630]: warning: SASL authentication failure: Password verification failed
Jun 30 15:00:50 izzy01 postfix/smtpd[13630]: warning: unknown[189.110.24.35]: SASL PLAIN authentication failed: authentication failure
Jun 30 15:00:50 izzy01 postfix/smtpd[13549]: disconnect from unknown[189.110.24.35]
Jun 30 15:00:50 izzy01 postfix/smtpd[13630]: disconnect from unknown[189.110.24.35]
Jun 30 15:00:50 izzy01 postfix/smtpd[13632]: disconnect from unknown[189.110.24.35]

Jun 30 15:00:54 izzy01 imapd: 1309456854.294124 LOGOUT, [email protected], ip=[189.110.24.35], headers=0, body=0, rcvd=97, sent=792, maildir=/var/qmail/mailnames/izzyweb.com.br/tfacchini/Maildir
Jun 30 15:00:54 izzy01 imapd: 1309456854.298124 LOGOUT, [email protected], ip=[189.110.24.35], headers=0, body=0, rcvd=517, sent=1619, maildir=/var/qmail/mailnames/izzyweb.com.br/tfacchini/Maildir
Jun 30 15:00:54 izzy01 imapd: 1309456854.298124 LOGOUT, [email protected], ip=[189.110.24.35], headers=0, body=0, rcvd=364, sent=816, maildir=/var/qmail/mailnames/izzyweb.com.br/tfacchini/Maildir
Jun 30 15:00:54 izzy01 imapd: 1309456854.314124 LOGOUT, [email protected], ip=[189.110.24.35], headers=505, body=2181, rcvd=709, sent=6692, maildir=/var/qmail/mailnames/izzyweb.com.br/tfacchini/Maildir

2 - After each 26 seconds, this activity is recorded in the logs:

Jun 30 15:23:45 izzy01 imapd: Connection, ip=[10.1.28.2]
Jun 30 15:23:45 izzy01 imapd: IMAP connect from @ [10.1.28.2]INFO: LOGIN, [email protected], ip=[10.1.28.2], protocol=IMAP
Jun 30 15:23:45 izzy01 imapd: 1309458225.450124 DISCONNECTED, [email protected], ip=[10.1.28.2], headers=0, body=48865, rcvd=174, sent=52858, maildir=/var/qmail/mailnames/izzyweb.com.br/tfacchini/Maildir

Even when all client mails are closed.

3 - In 1st part of the log I found [email protected] and [email protected], the curious is that the both mail accounts dont exist. I deleted that accounts day ago...

I will really appreciate if someone can help me.