Hello,
I'm getting the following error while Mozilla Mail is downloading >4000 emails:
The RETR command did not succeed. Error retrieving message. Mail server xxx responded: Message is deleted.
So what's the error? Can't I retrieve a message, that has been marked as deleted before? If the Mesage-ID wouldn't exist, the error message would be different. I don't know what Mozilla Mail is doing and on which message id it is failing. Also, there's no output in the logfiles. Any ideas?
Regards Marten
On Thu, 2005-04-28 at 17:08 +0200, Marten Lehmann wrote:
I'm getting the following error while Mozilla Mail is downloading >4000 emails:
The RETR command did not succeed. Error retrieving message. Mail server xxx responded: Message is deleted.
So what's the error? Can't I retrieve a message, that has been marked as deleted before?
That's right. Like the POP3 spec says:
RETR msg
Arguments:
a message-number (required) which may NOT refer to a
message marked as deleted
.. DELE msg
The POP3 server marks the message as deleted. Any future
reference to the message-number associated with the message
in a POP3 command generates an error. The POP3 server does
not actually delete the message until the POP3 session
enters the UPDATE state.
If the Mesage-ID wouldn't exist, the error message would be different. I don't know what Mozilla Mail is doing and on which message id it is failing. Also, there's no output in the logfiles. Any ideas?
I looked at the code and didn't see any problems with how DELE/RETR handles the messages. So it sounds like Mozilla deletes something and tries to fetch it again later for some reason..
Hello,
That's right. Like the POP3 spec says:
today it happened again. I was out of office for several days and now I had to download >3.500 messages at once. dovecot pop3 struggled after downloading about 1000 messages or so. I started downloading again. Some error again after about 1000 messages. I removed all dovecot-files from the Maildir. It happened again. This must be an error in dovecot. So I switched back the pop3 service to qmail-pop3d now, while imap is still running through dovecot. With qmail, the error didn't happen. The dovecot-response "Message is deleted" is not correct and does NOT result in downloading a deleted message. I checked with qmail:
retr 7
<message-data> . dele 7 +OK retr 7 -ERR already deleted
So if it really would be a problem of Mozilla Mail, it would have occured with qmail anyway.
Regards Marten
(05.06.01 kl.18:31) Marten Lehmann skrev följande till dovecot@dovecot.org:
Hello,
That's right. Like the POP3 spec says:
today it happened again. I was out of office for several days and now I had to download >3.500 messages at once. dovecot pop3 struggled after downloading about 1000 messages or so. I started downloading again. Some error again after about 1000 messages. I removed all dovecot-files from the Maildir. It happened again. This must be an error in dovecot. So I switched back the pop3 service to qmail-pop3d now, while imap is still running through dovecot. With qmail, the error didn't happen. The dovecot-response "Message is deleted" is not correct and does NOT result in downloading a deleted message. I checked with qmail:
retr 7
<message-data> . dele 7 +OK retr 7 -ERR already deleted
So if it really would be a problem of Mozilla Mail, it would have occured with qmail anyway.
I see the same thing. The error occurs with dovecot but not with qpopper (ouch).
When I last tried to debug this it seemed tbird did RETR on the last DELE message, which of course fails. Strangely enough it works with qpopper. Ill run the same debugrun again and see if I can figure it out.
I thought initially it might have been due to the pop3 hang problem but this seems to be a different one.
(tbird also behaves badly when it encounters the error. It simple disconnects instead of doing QUIT. So the mails are never expunged and the problem occurs over and over again.)
Cheers, Jens
Regards Marten
'This mail automatically becomes portable when carried.'
Jens Låås Email: jens.laas@data.slu.se
Department of Computer Services, SLU Phone: +46 18 67 35 15
Vindbrovägen 1
P.O. Box 7079
S-750 07 Uppsala
SWEDEN
(05.06.02 kl.11:16) Jens Laas skrev följande till Marten Lehmann:
(05.06.01 kl.18:31) Marten Lehmann skrev följande till dovecot@dovecot.org:
Hello,
That's right. Like the POP3 spec says:
today it happened again. I was out of office for several days and now I had
retr 7
<message-data> . dele 7 +OK retr 7 -ERR already deleted
So if it really would be a problem of Mozilla Mail, it would have occured with qmail anyway.
I see the same thing. The error occurs with dovecot but not with qpopper (ouch).
When I last tried to debug this it seemed tbird did RETR on the last DELE message, which of course fails. Strangely enough it works with qpopper. Ill run the same debugrun again and see if I can figure it out.
This is with added debug info. message numbers are external (1..) not internal (0..).
Same thing:
dovecot: Jun 02 12:39:45 Info: POP3(jenslt): RETR: fetch 1944 dovecot: Jun 02 12:39:45 Info: POP3(jenslt): DELE msg 1944 deleted (1944/11449 deleted) dovecot: Jun 02 12:39:45 Info: POP3(jenslt): RETR: fetch 1945 dovecot: Jun 02 12:39:45 Info: POP3(jenslt): DELE msg 1945 deleted (1945/11449 deleted) dovecot: Jun 02 12:39:46 Info: POP3(jenslt): RETR: fetch 1946 dovecot: Jun 02 12:39:46 Info: POP3(jenslt): DELE msg 1946 deleted (1946/11449 deleted) dovecot: Jun 02 12:39:46 Info: POP3(jenslt): get_msgnum: msg 1946 is deleted dovecot: Jun 02 12:39:46 Info: POP3(jenslt): RETR: no such msg 1946 dovecot: Jun 02 12:48:10 Info: POP3(jenslt): Disconnected top=0/0, retr=1946/14318447, del=1946/11449, size=78665433
Could it be possible for dovecot to somehow repeatably process the same commands over again ? But this seems strange as it needs to repeat two commands not simply the last command.
Something is really wierd. Again: it works with other pop servers.
Maybe Timo has a bright idea.. debug patch? :-)
Jens
'This mail automatically becomes portable when carried.'
Jens Låås Email: jens.laas@data.slu.se
Department of Computer Services, SLU Phone: +46 18 67 35 15
Vindbrovägen 1
P.O. Box 7079
S-750 07 Uppsala
SWEDEN
On Thu, 2005-06-02 at 12:52 +0200, Jens Laas wrote:
dovecot: Jun 02 12:39:46 Info: POP3(jenslt): DELE msg 1946 deleted (1946/11449 deleted) dovecot: Jun 02 12:39:46 Info: POP3(jenslt): get_msgnum: msg 1946 is deleted dovecot: Jun 02 12:39:46 Info: POP3(jenslt): RETR: no such msg 1946
Could it be possible for dovecot to somehow repeatably process the same commands over again ? But this seems strange as it needs to repeat two commands not simply the last command.
I can't really think of how that could happen if the problem is with Dovecot itself.
Something is really wierd. Again: it works with other pop servers.
Maybe Timo has a bright idea.. debug patch? :-)
Are the other POP3 servers advertising PIPELINING capability? Maybe try if this happen with it removed from Dovecot? (src/pop3/capability.h, rebuild).
(05.06.06 kl.15:26) Timo Sirainen skrev följande till Jens Laas:
On Thu, 2005-06-02 at 12:52 +0200, Jens Laas wrote:
dovecot: Jun 02 12:39:46 Info: POP3(jenslt): DELE msg 1946 deleted (1946/11449 deleted) dovecot: Jun 02 12:39:46 Info: POP3(jenslt): get_msgnum: msg 1946 is deleted dovecot: Jun 02 12:39:46 Info: POP3(jenslt): RETR: no such msg 1946
Could it be possible for dovecot to somehow repeatably process the same commands over again ? But this seems strange as it needs to repeat two commands not simply the last command.
I can't really think of how that could happen if the problem is with Dovecot itself.
Something is really wierd. Again: it works with other pop servers.
Maybe Timo has a bright idea.. debug patch? :-)
Are the other POP3 servers advertising PIPELINING capability? Maybe try if this happen with it removed from Dovecot? (src/pop3/capability.h, rebuild).
Nope. That wasnt it.
+OK Dovecot ready. capa +OK CAPA TOP UIDL RESP-CODES STLS USER SASL PLAIN .
Still fails at: dovecot: Jun 07 09:18:35 Info: POP3(jenslt): DELE msg 1944 deleted (1944/11841 deleted) dovecot: Jun 07 09:18:35 Info: POP3(jenslt): DELE msg 1945 deleted (1945/11841 deleted) dovecot: Jun 07 09:18:35 Info: POP3(jenslt): DELE msg 1946 deleted (1946/11841 deleted) dovecot: Jun 07 09:18:35 Info: POP3(jenslt): get_msgnum: msg 1946 is deleted dovecot: Jun 07 09:18:35 Info: POP3(jenslt): RETR: no such msg 1946 dovecot: Jun 07 09:18:35 Info: POP3(jenslt): client bad command RETR 1946 dovecot: Jun 07 09:18:35 Info: POP3(jenslt): Disconnected top=0/0, retr=0/0, del=1946/11841, size=81017250
I cannot understand how this could be dovecots problem, but evidently dovecot triggers this anyway.
This time when restarting tbird it started with trying to delete the 1945(6) messages it successfully downloaded last time. After issuing dele 1 .. dele 1946 it does RETR 1946 which plainly must be a tbird bug. I cannot explain this as other than a tbird off by one bug which is somehow triggered by dovecot.
Ill try and have a look at thunderbird which i rather suspect is a beast.
Thanks, Jens
'This mail automatically becomes portable when carried.'
Jens Låås Email: jens.laas@data.slu.se
Department of Computer Services, SLU Phone: +46 18 67 35 15
Vindbrovägen 1
P.O. Box 7079
S-750 07 Uppsala
SWEDEN
Hi,
Are the other POP3 servers advertising PIPELINING capability? Maybe try if this happen with it removed from Dovecot? (src/pop3/capability.h, rebuild).
Nope. That wasnt it.
thanks for testing it, I didn't had the time to do it yet. Since we couldn't live with this error, we switched back to qmail-pop3d for the pop3 service, letting dovecot handle imap only. To check if the error disappeared in current releases, I downloaded the latest stable release 20050624. I compiled and installed it, but the error still remained. Downloading of about 1649 messages stopped after the 843rd message, again with the message "-ERR Message is deleted" (src/pop3/commands.c, line 50).
It is really important for us, that this bug is resolved. This shall not sound like a threat, but we are indead evaluating a migration to Courier IMAP (although I never liked it very much), but a stable pop3 service is essential for us. And we don't want to use qmail-pop3d, because it doesn't log anything.
Regards Marten
(05.06.26 kl.18:54) Marten Lehmann skrev följande till dovecot@dovecot.org:
Hi,
Are the other POP3 servers advertising PIPELINING capability? Maybe try if this happen with it removed from Dovecot? (src/pop3/capability.h, rebuild).
Nope. That wasnt it.
thanks for testing it, I didn't had the time to do it yet. Since we couldn't live with this error, we switched back to qmail-pop3d for the pop3 service, letting dovecot handle imap only. To check if the error disappeared in current releases, I downloaded the latest stable release 20050624. I compiled and installed it, but the error still remained. Downloading of about 1649 messages stopped after the 843rd message, again with the message "-ERR Message is deleted" (src/pop3/commands.c, line 50).
It is really important for us, that this bug is resolved. This shall not sound like a threat, but we are indead evaluating a migration to Courier IMAP (although I never liked it very much), but a stable pop3 service is essential for us. And we don't want to use qmail-pop3d, because it doesn't log anything.
To recap: I see this too. So far only with thunderbird. Do you Marten see it with other clients too ?
The bug is really strange since everything I can log/see about the conversion between dovecot and tbird suggests tbird has the bug. BUT when I run tbird with other pop3 server it works.
The error triggered is that tbird tries to download an already deleted message (infact it just deleted it). And if I restart tbird it will start download at the last deleted message (error again).
I think our only hope is Timo or possibly some tbird developer.
Cheers Jens
Regards Marten
'This mail automatically becomes portable when carried.'
Jens Låås Email: jens.laas@data.slu.se
Department of Computer Services, SLU Phone: +46 18 67 35 15
Vindbrovägen 1
P.O. Box 7079
S-750 07 Uppsala
SWEDEN
Jens Laas wrote:
(05.06.26 kl.18:54) Marten Lehmann skrev följande till dovecot@dovecot.org:
Hi,
Are the other POP3 servers advertising PIPELINING capability? Maybe try if this happen with it removed from Dovecot? (src/pop3/capability.h, rebuild).
Nope. That wasnt it.
thanks for testing it, I didn't had the time to do it yet. Since we couldn't live with this error, we switched back to qmail-pop3d for the pop3 service, letting dovecot handle imap only. To check if the error disappeared in current releases, I downloaded the latest stable release 20050624. I compiled and installed it, but the error still remained. Downloading of about 1649 messages stopped after the 843rd message, again with the message "-ERR Message is deleted" (src/pop3/commands.c, line 50).
It is really important for us, that this bug is resolved. This shall not sound like a threat, but we are indead evaluating a migration to Courier IMAP (although I never liked it very much), but a stable pop3 service is essential for us. And we don't want to use qmail-pop3d, because it doesn't log anything.
To recap: I see this too. So far only with thunderbird. Do you Marten see it with other clients too ?
The bug is really strange since everything I can log/see about the conversion between dovecot and tbird suggests tbird has the bug. BUT when I run tbird with other pop3 server it works.
The error triggered is that tbird tries to download an already deleted message (infact it just deleted it). And if I restart tbird it will start download at the last deleted message (error again).
I think our only hope is Timo or possibly some tbird developer.
Cheers Jens
Ditto with various customers using test72. All seem to be using different mail clients. Can't really see a pattern at all, small and big Maildirs. Deleting the UID list and indexes seems to fix it. It happens for about 2 customers in 6000 a week.
Regards Andrew
Hi,
To recap: I see this too. So far only with thunderbird. Do you Marten see it with other clients too ?
I have not installed any other mail-clients, I'm using Mozilla Mail. But I haven't seen this problem with any other pop3-server.
The bug is really strange since everything I can log/see about the conversion between dovecot and tbird suggests tbird has the bug. BUT when I run tbird with other pop3 server it works.
Correct. And if Mozilla tries to download it message is has deleted just before, I'm asking myself what causes tbird to do it? As we are currently working with qmail-pop3d, I can't see any different behaviour of the server regarding retrieval of deleted messages.
The error triggered is that tbird tries to download an already deleted message (infact it just deleted it). And if I restart tbird it will start download at the last deleted message (error again).
I think our only hope is Timo or possibly some tbird developer.
I thought pop3 is one of the easiest protocols, but obviously it can have very strange side-effects. Maybe Timo can compare to Courier-IMAP (pop3 included), because there is a compile-time option to enable workarounds for certain client problems.
Regards Marten
On Mon, 2005-06-27 at 09:46 +0200, Jens Laas wrote:
I see this too. So far only with thunderbird. Do you Marten see it with other clients too ?
The bug is really strange since everything I can log/see about the conversion between dovecot and tbird suggests tbird has the bug. BUT when I run tbird with other pop3 server it works.
Maybe it has something to do with how data gets split into TCP/IP packets? If nothing else looks different, then that's pretty much the only difference left. Dovecot tries to use as few packets as possible, other servers may eg. always send separate messages in separate packets, or things like that.. I know there used to be a problem with some clients when Dovecot sent separate packets for the actual line contents and another packet with CR+LF.
Anyway, I'll try to test this myself sometime soon..
Timo Sirainen wrote:
On Mon, 2005-06-27 at 09:46 +0200, Jens Laas wrote:
I see this too. So far only with thunderbird. Do you Marten see it with other clients too ?
The bug is really strange since everything I can log/see about the conversion between dovecot and tbird suggests tbird has the bug. BUT when I run tbird with other pop3 server it works.
Maybe it has something to do with how data gets split into TCP/IP packets? If nothing else looks different, then that's pretty much the only difference left. Dovecot tries to use as few packets as possible, other servers may eg. always send separate messages in separate packets, or things like that.. I know there used to be a problem with some clients when Dovecot sent separate packets for the actual line contents and another packet with CR+LF.
Anyway, I'll try to test this myself sometime soon..
I've just been having a go, trying to download 4000 messages in 1.0-stable from Thunderbird 1.0.2 and it crashed the first time after 1427 messages, then got stuck after 72 (pop3 process was just idling and eventually died) then got stuck again after 2500 or so. The last time it was set to leave mail on the server (so presumably no DELE commands).
I haven't tried protocol logging yet ...
Best Wishes, Chris
On 27.6.2005, at 10:46, Jens Laas wrote:
The bug is really strange since everything I can log/see about the conversion between dovecot and tbird suggests tbird has the bug. BUT when I run tbird with other pop3 server it works.
Well, maybe this is simply because many other servers ignore the problem? UW, Courier and qmail-pop3d at least do. Then again Cyrus, popa3d and qpopper give error message. Anyone wish to try to reproduce the problem with them?
Anyway the simplest fix for Dovecot is to make it also ignore the error. src/pop3/commands.c line 47 comment out the if (client->deleted) { ... } block. Although that ignores a bit too many errors.. If the bug can be reproduced with other servers I'll make up some workaround option which ignores it only with DELE.
(05.06.28 kl.03:52) Timo Sirainen skrev följande till Jens Laas:
On 27.6.2005, at 10:46, Jens Laas wrote:
The bug is really strange since everything I can log/see about the conversion between dovecot and tbird suggests tbird has the bug. BUT when I run tbird with other pop3 server it works.
Well, maybe this is simply because many other servers ignore the problem? UW, Courier and qmail-pop3d at least do. Then again Cyrus, popa3d and qpopper give error message. Anyone wish to try to reproduce the problem with them?
We run qpopper here which works with tbird. (evolution works with dovecot though :)
Packet split might be it. But I cant really understand how that would trigger this either.
Anyway the simplest fix for Dovecot is to make it also ignore the error. src/pop3/commands.c line 47 comment out the if (client->deleted) { ... } block. Although that ignores a bit too many errors.. If the bug can be reproduced with other servers I'll make up some workaround option which ignores it only with DELE.
Not reproduced with qpopper atleast. In case of work around it should check that it is the last message deleted. But .. it looks so ugly :-(
Jens
'This mail automatically becomes portable when carried.'
Jens Låås Email: jens.laas@data.slu.se
Department of Computer Services, SLU Phone: +46 18 67 35 15
Vindbrovägen 1
P.O. Box 7079
S-750 07 Uppsala
SWEDEN
Well, maybe this is simply because many other servers ignore the problem? UW, Courier and qmail-pop3d at least do.
Which problem? I'm using qmail-pop3d and it doesn't allow to RETR a message, that just has been DELE before. Also, it doesn't show DELEted messages in the LIST. But this behaviour is identical in qmail-pop3d and dovecot. I have no debug logging turned on in my dovecot, so I can't see whats happening internally. As of the logs from Jens, thunderbird seems to try downloading a message, that it deleted before. But is it really as it seems? Is it possible, that the index of dovecot may break? Or is it possible that dovecot tries to work on a different message than the client asks it to work on?
Regards Marten
participants (5)
-
Andrew Hutchings
-
Chris Wakelin
-
Jens Laas
-
Marten Lehmann
-
Timo Sirainen