forum.excito.org

Since yesterday I cannot access my mail anymore
(worked without problem for days):


login name bill
password xyz


kmail

Could not connect to host zefod: Unknown error

Horde

login failed

Yesterday I made the following changes:

On my laptop updated kde 4.1.3 to kde 4.2

on the bubba I installed ntpdate:


2009-01-31 20:33:45 install ntpdate <none> 1:4.2.2.p4+dfsg-2
2009-01-31 20:33:45 status half-installed ntpdate 1:4.2.2.p4+dfsg-2
2009-01-31 20:33:46 status unpacked ntpdate 1:4.2.2.p4+dfsg-2
2009-01-31 20:33:46 status unpacked ntpdate 1:4.2.2.p4+dfsg-2
2009-01-31 20:33:46 status unpacked ntpdate 1:4.2.2.p4+dfsg-2
2009-01-31 20:33:46 status unpacked ntpdate 1:4.2.2.p4+dfsg-2
2009-01-31 20:33:46 status unpacked ntpdate 1:4.2.2.p4+dfsg-2
2009-01-31 20:33:46 status unpacked ntpdate 1:4.2.2.p4+dfsg-2
2009-01-31 20:33:46 status unpacked ntpdate 1:4.2.2.p4+dfsg-2
2009-01-31 20:33:46 status half-configured ntpdate 1:4.2.2.p4+dfsg-2
2009-01-31 20:33:46 status installed ntpdate 1:4.2.2.p4+dfsg-2

modified crontab root:

# m h dom mon dow command
0 */2 * * * /usr/sbin/ntpdate ntp1.sp.se



Logs:

mail.log

Feb 1 09:35:48 zefod fetchmail[2556]: sleeping at Sun 01 Feb 2009 10:35:48 AM CET for 300 seconds
Feb 1 09:38:43 zefod postfix/qmgr[15903]: 6D0A593EE3: from=<root@bubba.localdomain>, size=600, nrcpt=1 (queue active)
Feb 1 09:38:43 zefod postfix/qmgr[15903]: 4670E93EC3: from=<root@bubba.localdomain>, size=767, nrcpt=1 (queue active)
Feb 1 09:38:43 zefod postfix/qmgr[15903]: AC63B93EDA: from=<root@bubba.localdomain>, size=600, nrcpt=1 (queue active)
Feb 1 09:38:43 zefod postfix/qmgr[15903]: 2E72E93ED4: from=<root@bubba.localdomain>, size=600, nrcpt=1 (queue active)
Feb 1 09:38:43 zefod postfix/qmgr[15903]: 3A9CB93ED9: from=<root@bubba.localdomain>, size=600, nrcpt=1 (queue active)
Feb 1 09:38:43 zefod postfix/qmgr[15903]: 3F10B93EC7: from=<root@bubba.localdomain>, size=601, nrcpt=1 (queue active)
Feb 1 09:38:43 zefod postfix/qmgr[15903]: 5890693ED7: from=<root@bubba.localdomain>, size=600, nrcpt=1 (queue active)
Feb 1 09:38:43 zefod postfix/qmgr[15903]: 80B3993EC8: from=<root@bubba.localdomain>, size=767, nrcpt=1 (queue active)
Feb 1 09:38:43 zefod deliver(nobody): stat(/root/Mail/cur) failed: Permission denied
Feb 1 09:38:43 zefod last message repeated 2 times
Feb 1 09:38:43 zefod deliver(nobody): msgid=<20090131220002.6D0A593EE3@bubba.localdomain>: Couldn't open mailbox INBOX: Internal error occurred. Refer to server log for more information. [2009-02-01 10:38:43]
Feb 1 09:38:44 zefod deliver(nobody): stat(/root/Mail/cur) failed: Permission denied
Feb 1 09:38:44 zefod deliver(nobody): msgid=<20090130062530.4670E93EC3@bubba.localdomain>: Couldn't open mailbox INBOX: Internal error occurred. Refer to server log for more information. [2009-02-01 10:38:43]
Feb 1 09:38:44 zefod postfix/local[23971]: 6D0A593EE3: to=<root@bubba.localdomain>, orig_to=<root>, relay=local, delay=41922, delays=41922/0.18/0/0.17, dsn=4.3.0, status=deferred (temporary failure)
Feb 1 09:38:44 zefod postfix/local[23972]: 4670E93EC3: to=<root@bubba.localdomain>, orig_to=<root>, relay=local, delay=184397, delays=184396/0.14/0/0.17, dsn=4.3.0, status=deferred (temporary failure)
Feb 1 09:38:44 zefod deliver(nobody): stat(/root/Mail/cur) failed: Permission denied
Feb 1 09:38:44 zefod last message repeated 3 times
Feb 1 09:38:44 zefod deliver(nobody): msgid=<20090201000003.2E72E93ED4@bubba.localdomain>: Couldn't open mailbox INBOX: Internal error occurred. Refer to server log for more information. [2009-02-01 10:38:44]
Feb 1 09:38:44 zefod deliver(nobody): msgid=<20090201060002.AC63B93EDA@bubba.localdomain>: Couldn't open mailbox INBOX: Internal error occurred. Refer to server log for more information. [2009-02-01 10:38:44]
Feb 1 09:38:44 zefod postfix/local[23972]: 2E72E93ED4: to=<root@bubba.localdomain>, orig_to=<root>, relay=local, delay=34721, delays=34721/0.42/0/0.06, dsn=4.3.0, status=deferred (temporary failure)
Feb 1 09:38:44 zefod postfix/local[23971]: AC63B93EDA: to=<root@bubba.localdomain>, orig_to=<root>, relay=local, delay=13122, delays=13121/0.4/0/0.11, dsn=4.3.0, status=deferred (temporary failure)
Feb 1 09:38:44 zefod deliver(nobody): stat(/root/Mail/cur) failed: Permission denied
Feb 1 09:38:44 zefod last message repeated 2 times
Feb 1 09:38:44 zefod deliver(nobody): msgid=<20090131210011.3F10B93EC7@bubba.localdomain>: Couldn't open mailbox INBOX: Internal error occurred. Refer to server log for more information. [2009-02-01 10:38:44]
Feb 1 09:38:44 zefod deliver(nobody): stat(/root/Mail/cur) failed: Permission denied
Feb 1 09:38:44 zefod deliver(nobody): msgid=<20090201040002.3A9CB93ED9@bubba.localdomain>: Couldn't open mailbox INBOX: Internal error occurred. Refer to server log for more information. [2009-02-01 10:38:44]
Feb 1 09:38:44 zefod postfix/local[23971]: 3F10B93EC7: to=<root@bubba.localdomain>, orig_to=<root>, relay=local, delay=45513, delays=45513/0.51/0/0.06, dsn=4.3.0, status=deferred (temporary failure)
Feb 1 09:38:44 zefod postfix/local[23972]: 3A9CB93ED9: to=<root@bubba.localdomain>, orig_to=<root>, relay=local, delay=20322, delays=20322/0.49/0/0.12, dsn=4.3.0, status=deferred (temporary failure)
Feb 1 09:38:44 zefod deliver(nobody): stat(/root/Mail/cur) failed: Permission denied
Feb 1 09:38:44 zefod last message repeated 3 times
Feb 1 09:38:44 zefod deliver(nobody): msgid=<20090131062526.80B3993EC8@bubba.localdomain>: Couldn't open mailbox INBOX: Internal error occurred. Refer to server log for more information. [2009-02-01 10:38:44]
Feb 1 09:38:44 zefod deliver(nobody): msgid=<20090201020002.5890693ED7@bubba.localdomain>: Couldn't open mailbox INBOX: Internal error occurred. Refer to server log for more information. [2009-02-01 10:38:44]
Feb 1 09:38:44 zefod postfix/local[23971]: 5890693ED7: to=<root@bubba.localdomain>, orig_to=<root>, relay=local, delay=27522, delays=27521/0.57/0/0.11, dsn=4.3.0, status=deferred (temporary failure)
Feb 1 09:38:44 zefod postfix/local[23972]: 80B3993EC8: to=<root@bubba.localdomain>, orig_to=<root>, relay=local, delay=98001, delays=98000/0.6/0/0.09, dsn=4.3.0, status=deferred (temporary failure)


horde.log

Feb 01 11:22:28 HORDE [error] [imp] FAILED LOGIN for bill [192.168.10.51] to {localhost:143 [imap/notls]} [pid 29962 on line 139 of "/usr/share/horde3/imp/lib/Auth/imp.php"]
Feb 01 11:22:42 HORDE [error] [imp] FAILED LOGIN for bill [192.168.10.51] to {localhost:143 [imap/notls]} [pid 29962 on line 139 of "/usr/share/horde3/imp/lib/Auth/imp.php"]
Feb 01 11:46:39 HORDE [error] [imp] FAILED LOGIN for bill [192.168.10.51] to {localhost:143 [imap/notls]} [pid 29962 on line 139 of "/usr/share/horde3/imp/lib/Auth/imp.php"]
Feb 01 11:47:04 HORDE [error] [imp] FAILED LOGIN for mariejose [192.168.10.51] to {localhost:143 [imap/notls]} [pid 17043 on line 139 of "/usr/share/horde3/imp/lib/Auth/imp.php"]
Feb 01 11:47:21 HORDE [error] [imp] FAILED LOGIN for bill [192.168.10.51] to {localhost:143 [imap/notls]} [pid 17043 on line 139 of "/usr/share/horde3/imp/lib/Auth/imp.php"]
Feb 01 12:22:17 HORDE [error] [imp] FAILED LOGIN for bill [192.168.10.51] to {localhost:143 [imap/notls]} [pid 16147 on line 139 of "/usr/share/horde3/imp/lib/Auth/imp.php"]
Feb 01 11:43:45 HORDE [error] [imp] FAILED LOGIN for bill [192.168.10.51] to {localhost:143 [imap/notls]} [pid 17043 on line 139 of "/usr/share/horde3/imp/lib/Auth/imp.php"]

???????????

Leo

From mail.log

Feb 3 11:31:09 zefod deliver(nobody): msgid=<20090201062537.8C41E93EE1@bubba.localdomain>: Couldn't open mailbox INBOX: Internal error occurred. Refer to server log for more information. [2009-02-03 12:31:09]


I don't know what "server log" I must look into, and i'm desperately in need for more information. What does "internal error" mean?

SOLVED!


Carl at excito helped me to solve the problem.

He wrote me:

Hopefully you won't need to do an full reinstall.
one reason for the suddenly failed login in horde can be a direct result
of actions made by ntpdate (which will be unneeded in next upgrade from
us which will include ntp directly). The reason for this is that the
imap server (dovecot in our case) will shut down if it recognize a
sudden change in time (see http://wiki.dovecot.org/TimeMovedBackwards).
You could try either to restart the bubba, or issue as root:
/etc/init.d/dovecot restart

I removed the relevant line from crontab and rebooted the Bubba and voila mail works again.
Thanks Carl

Leo

billdbr wrote:SOLVED!


Carl at excito helped me to solve the problem.

He wrote me:

Hopefully you won't need to do an full reinstall.
one reason for the suddenly failed login in horde can be a direct result
of actions made by ntpdate (which will be unneeded in next upgrade from
us which will include ntp directly). The reason for this is that the
imap server (dovecot in our case) will shut down if it recognize a
sudden change in time (see http://wiki.dovecot.org/TimeMovedBackwards).
You could try either to restart the bubba, or issue as root:
/etc/init.d/dovecot restart

I removed the relevant line from crontab and rebooted the Bubba and voila mail works again.
Thanks Carl

Leo

Thank you for posting that info billdbr,
That helped me 2

Rewien