Re: IMP behaves weirdly while composing messages; duplicates drafts, it may fail to save message in 'Sent'
Jan Schneider <[email protected]> Tue, 18 Apr 2017 10:12:37 +0000
| Newsgroups | gmane.comp.horde.imp |
|---|---|
| Message-ID | <[email protected]> |
Zitat von Leonardo Bruno Lopes <[email protected]>: > Quoting Leonardo Bruno Lopes <[email protected]>: > >> Citando Michael J Rubinsky <[email protected]>: >> >>> Quoting Leonardo Bruno Lopes <[email protected]>: >>> >>>> Hi everyone! >>>> >>>> I sometimes notice the following behavior while composing >>>> messages in IMP Dynamic view: >>>> >>>> While I am writing the message, IMP correctly saves the drafts >>>> every minute (according to my prefs), but instead of create a new >>>> draft at the first time it is saved and then update the *same >>>> draft*, IMP saves a *new draft* every time. As a result, if I >>>> take 15 minutes to compose the message, I will have at end nearly >>>> 15 drafts in my 'Drafts' folder. >>>> >>>> As I said, it doesn't happen every time I compose messages, when >>>> it does, the log says: >>>> >>>> Apr 13 12:25:41 my_horde_server HORDE: [imp] [store] IMAP error >>>> reported by server. [pid 12672 on line 726 of >>>> "/usr/share/horde/imp/lib/Imap.php"] >>>> Apr 13 12:26:42 my_horde_server HORDE: [imp] [store] IMAP error >>>> reported by server. [pid 13523 on line 726 of >>>> "/usr/share/horde/imp/lib/Imap.php"] >>>> Apr 13 12:27:41 my_horde_server HORDE: [imp] [store] IMAP error >>>> reported by server. [pid 12672 on line 726 of >>>> "/usr/share/horde/imp/lib/Imap.php"] >>>> Apr 13 12:28:41 my_horde_server HORDE: [imp] [store] IMAP error >>>> reported by server. [pid 12674 on line 726 of >>>> "/usr/share/horde/imp/lib/Imap.php"] >>>> Apr 13 12:29:42 my_horde_server HORDE: [imp] [store] IMAP error >>>> reported by server. [pid 12735 on line 726 of >>>> "/usr/share/horde/imp/lib/Imap.php"] >>>> Apr 13 12:30:41 my_horde_server HORDE: [imp] [store] IMAP error >>>> reported by server. [pid 12728 on line 726 of >>>> "/usr/share/horde/imp/lib/Imap.php"] >>>> Apr 13 12:31:41 my_horde_server HORDE: [imp] [store] IMAP error >>>> reported by server. [pid 12722 on line 726 of >>>> "/usr/share/horde/imp/lib/Imap.php"] >>>> Apr 13 12:46:21 my_horde_server HORDE: [imp] Message sent to >>>> [email protected] from [email protected] (xx.xx.xx.xx) [pid 12728 >>>> on line 964 of "/usr/share/horde/imp/lib/Compose.php"] >>>> Apr 13 12:46:21 my_horde_server HORDE: [imp] [store] IMAP error >>>> reported by server. [pid 12728 on line 726 of >>>> "/usr/share/horde/imp/lib/Imap.php"] >>>> >>>> Notice that there is one error messages for each time IMP tries >>>> to update the draft; then a new one is placed on Drafts folder. >>>> The last 2 logs messages reports the mail being sent and the last >>>> error that -- I suppose -- is generated when IMP tries to remove >>>> the draft (s ?). >>>> >>>> The mail is in fact sent; however the message may or may not be >>>> saved in 'Sent' folder. If it was not, the red error box will pop >>>> up and tell the user 'There was an error flagging messages in the >>>> mailbox "Inbox": IMAP error reported by server'. The blue info >>>> box will also be shown: 'Message sent successfully, but not saved >>>> to Sent'. >>>> >>>> Of course this can/should be related to my Dovecot 2.2.13 IMAP >>>> server, but the truth is that Dovecot log shows nothing at the >>>> time IMP logs the errors above, even I have increase the debug >>>> level. >>>> >>>> Can someone please help me with this? >> >> Hi Mike and List! >> >> First of all, I forgot to say I am using Imapproxy version 1.2.7 >> which runs on the same machine as Horde. IMP connects to Imapproxy >> through 143 port with 'secure'=false. Imapproxy connects over SSL >> to my Dovecot 2.2.13 server running on another machine. >> >>> Enable IMAP debugging in imp/config/backends.local.php. See >>> backends.php for instructions. >> >> I enabled debug in my backends.local.php and started to compose a >> message (an answer to Samba mail list). These are the debug log >> messages that was generated at the same times Horde saved the drafs >> (sorry, it's pretty long): >> >> ------------------------------ >>>> Thu, 13 Apr 2017 21:10:00 +0000 >>>> Connection to: imap://localhost/ >>>> Server connection took 0,0002 seconds. >> S: * OK [CAPABILITY IMAP4rev1 LITERAL+ LOGIN-REFERRALS ID ENABLE >> XIMAPPROXY] Dovecot ready. >> C: 1 LOGIN [email protected] [PASSWORD] >> S: * OK [XPROXYREUSE] IMAP connection reused by imapproxy >> S: 1 OK User logged in >>>> Command 1 took 0,0382 seconds. >> C: 2 STATUS Samba (UIDVALIDITY) >> S: * STATUS Samba (UIDVALIDITY 1489694687) >> S: 2 OK Status completed. >>>> Command 2 took 0,0013 seconds. >> C: 3 APPEND Drafts (\draft $mdnsent) {3147} >> S: + OK >> C: [LITERAL DATA: 3147 bytes] >> C: >> S: 3 OK [APPENDUID 1489694684 245] Append completed. >>>> Command 3 took 0,0043 seconds. >> C: 4 STATUS Drafts (UIDVALIDITY) >> S: * STATUS Drafts (UIDVALIDITY 1489694684) >> S: 4 OK Status completed. >>>> Command 4 took 0,0008 seconds. >>>> CACHE: Using the Horde_Imap_Client_Cache_Backend_Cache storage driver. >> C: 5 EXAMINE Drafts >> S: * FLAGS (\Answered \Flagged \Deleted \Seen \Draft $mdnsent) >> S: * OK [PERMANENTFLAGS ()] Read-only mailbox. >> S: * 2 EXISTS >> S: * 1 RECENT >> S: * OK [UNSEEN 1] First unseen. >> S: * OK [UIDVALIDITY 1489694684] UIDs valid >> S: * OK [UIDNEXT 246] Predicted next UID >> S: * OK [HIGHESTMODSEQ 694] Highest >> S: 5 OK [READ-ONLY] Examine completed (0.000 secs). >>>> Command 5 took 0,0019 seconds. >>>> CACHE: Stored metadata (_m,uidvalid [Drafts]) >> C: 6 UID FETCH 244 (ENVELOPE) >> S: * 1 FETCH (UID 244 ENVELOPE ("Thu, 13 Apr 2017 21:08:00 +0000" {105} >> S: [LITERAL DATA: 105 bytes] >> S: (("Leonardo Bruno Lopes" NIL "leonardo" "cefetmg.br")) >> (("Leonardo Bruno Lopes" NIL "leonardo" "cefetmg.br")) (("Leonardo >> Bruno Lopes" NIL "leonardo" "cefetmg.br")) (("Andrew Bartlett" NIL >> "abartlet" "samba.org")) ((NIL NIL "samba" "lists.samba.org")) NIL >> "<[email protected]>" >> "<[email protected]>")) >> S: 6 OK Fetch completed. >>>> Command 6 took 0,0025 seconds. >>>> CACHE: Stored messages [Drafts; 244] >> C: 7 SELECT Drafts (QRESYNC (1489694684 694 244)) >> S: 7 BAD Error in IMAP command SELECT: QRESYNC not enabled >>>> Command 7 took 0,0006 seconds. >> C: 8 LOGOUT >> S: * OK [CLOSED] Previous mailbox closed. >> S: * BYE LOGOUT received >> S: 8 OK Completed >>>> Command 8 took 0,0006 seconds. >> ------------------------------ >>>> Thu, 13 Apr 2017 21:10:00 +0000 >>>> Connection to: imap://localhost/ >>>> Server connection took 0,0002 seconds. >> S: * OK [CAPABILITY IMAP4rev1 LITERAL+ LOGIN-REFERRALS ID ENABLE >> XIMAPPROXY] Dovecot ready. >> C: 1 LOGIN [email protected] [PASSWORD] >> S: * OK [XPROXYREUSE] IMAP connection reused by imapproxy >> S: 1 OK User logged in >>>> Command 1 took 0,0377 seconds. >> C: 2 STATUS Drafts (MESSAGES UIDNEXT UIDVALIDITY HIGHESTMODSEQ) >> S: * STATUS Drafts (MESSAGES 2 UIDNEXT 246 UIDVALIDITY 1489694684 >> HIGHESTMODSEQ 694) >> S: 2 OK Status completed. >>>> Command 2 took 0,001 seconds. >>>> CACHE: Using the Horde_Imap_Client_Cache_Backend_Cache storage driver. >> C: 3 SELECT Drafts >> S: * FLAGS (\Answered \Flagged \Deleted \Seen \Draft $mdnsent) >> S: * OK [PERMANENTFLAGS (\Answered \Flagged \Deleted \Seen \Draft >> $mdnsent \*)] Flags permitted. >> S: * 2 EXISTS >> S: * 1 RECENT >> S: * OK [UNSEEN 1] First unseen. >> S: * OK [UIDVALIDITY 1489694684] UIDs valid >> S: * OK [UIDNEXT 246] Predicted next UID >> S: * OK [HIGHESTMODSEQ 694] Highest >> S: 3 OK [READ-WRITE] Select completed (0.000 secs). >>>> Command 3 took 0,0023 seconds. >>>> CACHE: Stored metadata (_m,uidvalid [Drafts]) >>>> SEARCH: Expired from cache [Drafts] >> C: 4 UID SEARCH RETURN (ALL COUNT) ALL >> S: * ESEARCH (TAG "4") UID ALL 244:245 COUNT 2 >> S: 4 OK Search completed (0.000 secs). >>>> Command 4 took 0,0009 seconds. >>>> CACHE: Stored metadata (_s,_i [Drafts]) >>>> SEARCH: Saved search to cache (3b99c058 [Drafts]) >> C: 5 UID SEARCH RETURN (ALL COUNT) MODSEQ 693 >> S: * ESEARCH (TAG "5") UID ALL 245 COUNT 1 MODSEQ 694 >> S: 5 OK Search completed (0.000 secs). >>>> Command 5 took 0,0008 seconds. >>>> CACHE: Stored metadata (_s,_i [Drafts]) >>>> SEARCH: Saved search to cache (4418eeff [Drafts]) >> C: 6 UID FETCH 245 (ENVELOPE FLAGS RFC822.SIZE >> BODY.PEEK[HEADER.FIELDS (IMPORTANCE LIST-POST X-PRIORITY)]) >> S: * 2 FETCH (UID 245 FLAGS (\Draft \Recent $mdnsent) RFC822.SIZE >> 3147 ENVELOPE ("Thu, 13 Apr 2017 21:10:00 +0000" {105} >> S: [LITERAL DATA: 105 bytes] >> S: (("Leonardo Bruno Lopes" NIL "leonardo" "cefetmg.br")) >> (("Leonardo Bruno Lopes" NIL "leonardo" "cefetmg.br")) (("Leonardo >> Bruno Lopes" NIL "leonardo" "cefetmg.br")) (("Andrew Bartlett" NIL >> "abartlet" "samba.org")) ((NIL NIL "samba" "lists.samba.org")) NIL >> "<[email protected]>" >> "<[email protected]>") >> BODY[HEADER.FIELDS (IMPORTANCE LIST-POST X-PRIORITY)] {2} >> S: [LITERAL DATA: 2 bytes] >> S: ) >> S: 6 OK Fetch completed. >>>> Command 6 took 0,0032 seconds. >>>> CACHE: Stored messages [Drafts; 245] >> C: 7 SEARCH RETURN (MIN COUNT) UNSEEN >> S: * ESEARCH (TAG "7") MIN 1 COUNT 2 >> S: 7 OK Search completed (0.000 secs). >>>> Command 7 took 0,0008 seconds. >>>> CACHE: Stored metadata (_s,_i [Drafts]) >>>> SEARCH: Saved search to cache (d383cfdc [Drafts]) >> C: 8 LIST () "" (INBOX Sent Trash Templates Spam Horde IMP Samba) >> RETURN (STATUS (UNSEEN)) >> S: * LIST () "/" Templates >> S: * STATUS Templates (UNSEEN 0) >> S: * LIST () "/" IMP >> S: * STATUS IMP (UNSEEN 0) >> S: * LIST () "/" Sent >> S: * STATUS Sent (UNSEEN 0) >> S: * LIST () "/" Spam >> S: * STATUS Spam (UNSEEN 0) >> S: * LIST () "/" Horde >> S: * STATUS Horde (UNSEEN 0) >> S: * LIST () "/" Trash >> S: * STATUS Trash (UNSEEN 0) >> S: * LIST () "/" Samba >> S: * STATUS Samba (UNSEEN 0) >> S: * LIST () "/" INBOX >> S: * STATUS INBOX (UNSEEN 0) >> S: 8 OK List completed. >>>> Command 8 took 0,0045 seconds. >> C: 9 GETQUOTAROOT Drafts >> S: * QUOTAROOT Drafts "User quota" >> S: * QUOTA "User quota" (STORAGE 863 3145728) >> S: 9 OK Getquotaroot completed. >>>> Command 9 took 0,001 seconds. >> C: 10 LOGOUT >> S: * OK [CLOSED] Previous mailbox closed. >> S: * BYE LOGOUT received >> S: 10 OK Completed >>>> Command 10 took 0,0008 seconds. >> ------------------------------ >>>> Thu, 13 Apr 2017 21:13:00 +0000 >>>> Connection to: imap://localhost/ >>>> Server connection took 0,0012 seconds. >> S: * OK [CAPABILITY IMAP4rev1 LITERAL+ LOGIN-REFERRALS ID ENABLE >> XIMAPPROXY] Dovecot ready. >> C: 1 LOGIN [email protected] [PASSWORD] >> S: * OK [XPROXYREUSE] IMAP connection reused by imapproxy >> S: 1 OK User logged in >>>> Command 1 took 0,0381 seconds. >> C: 2 STATUS Samba (UIDVALIDITY) >> S: * STATUS Samba (UIDVALIDITY 1489694687) >> S: 2 OK Status completed. >>>> Command 2 took 0,0013 seconds. >> C: 3 APPEND Drafts (\draft $mdnsent) {3145} >> S: + OK >> C: [LITERAL DATA: 3145 bytes] >> C: >> S: 3 OK [APPENDUID 1489694684 246] Append completed. >>>> Command 3 took 0,0044 seconds. >> C: 4 STATUS Drafts (UIDVALIDITY) >> S: * STATUS Drafts (UIDVALIDITY 1489694684) >> S: 4 OK Status completed. >>>> Command 4 took 0,0008 seconds. >>>> CACHE: Using the Horde_Imap_Client_Cache_Backend_Cache storage driver. >> C: 5 EXAMINE Drafts >> S: * FLAGS (\Answered \Flagged \Deleted \Seen \Draft $mdnsent) >> S: * OK [PERMANENTFLAGS ()] Read-only mailbox. >> S: * 3 EXISTS >> S: * 1 RECENT >> S: * OK [UNSEEN 1] First unseen. >> S: * OK [UIDVALIDITY 1489694684] UIDs valid >> S: * OK [UIDNEXT 247] Predicted next UID >> S: * OK [HIGHESTMODSEQ 696] Highest >> S: 5 OK [READ-ONLY] Examine completed (0.000 secs). >>>> Command 5 took 0,002 seconds. >>>> CACHE: Stored metadata (_m,uidvalid [Drafts]) >> C: 6 UID FETCH 245 (ENVELOPE) >> S: * 2 FETCH (UID 245 ENVELOPE ("Thu, 13 Apr 2017 21:10:00 +0000" {105} >> S: [LITERAL DATA: 105 bytes] >> S: (("Leonardo Bruno Lopes" NIL "leonardo" "cefetmg.br")) >> (("Leonardo Bruno Lopes" NIL "leonardo" "cefetmg.br")) (("Leonardo >> Bruno Lopes" NIL "leonardo" "cefetmg.br")) (("Andrew Bartlett" NIL >> "abartlet" "samba.org")) ((NIL NIL "samba" "lists.samba.org")) NIL >> "<[email protected]>" >> "<[email protected]>")) >> S: 6 OK Fetch completed. >>>> Command 6 took 0,0025 seconds. >>>> CACHE: Stored messages [Drafts; 245] >> C: 7 SELECT Drafts (QRESYNC (1489694684 696 245)) >> S: 7 BAD Error in IMAP command SELECT: QRESYNC not enabled >>>> Command 7 took 0,0006 seconds. >> C: 8 LOGOUT >> S: * OK [CLOSED] Previous mailbox closed. >> S: * BYE LOGOUT received >> S: 8 OK Completed >>>> Command 8 took 0,001 seconds. >> ------------------------------ >>>> Thu, 13 Apr 2017 21:13:00 +0000 >>>> Connection to: imap://localhost/ >>>> Server connection took 0,0002 seconds. >> S: * OK [CAPABILITY IMAP4rev1 LITERAL+ LOGIN-REFERRALS ID ENABLE >> XIMAPPROXY] Dovecot ready. >> C: 1 LOGIN [email protected] [PASSWORD] >> S: * OK [XPROXYREUSE] IMAP connection reused by imapproxy >> S: 1 OK User logged in >>>> Command 1 took 0,0402 seconds. >> C: 2 STATUS Drafts (MESSAGES UIDNEXT UIDVALIDITY HIGHESTMODSEQ) >> S: * STATUS Drafts (MESSAGES 3 UIDNEXT 247 UIDVALIDITY 1489694684 >> HIGHESTMODSEQ 696) >> S: 2 OK Status completed. >>>> Command 2 took 0,001 seconds. >>>> CACHE: Using the Horde_Imap_Client_Cache_Backend_Cache storage driver. >> C: 3 SELECT Drafts >> S: * FLAGS (\Answered \Flagged \Deleted \Seen \Draft $mdnsent) >> S: * OK [PERMANENTFLAGS (\Answered \Flagged \Deleted \Seen \Draft >> $mdnsent \*)] Flags permitted. >> S: * 3 EXISTS >> S: * 1 RECENT >> S: * OK [UNSEEN 1] First unseen. >> S: * OK [UIDVALIDITY 1489694684] UIDs valid >> S: * OK [UIDNEXT 247] Predicted next UID >> S: * OK [HIGHESTMODSEQ 696] Highest >> S: 3 OK [READ-WRITE] Select completed (0.000 secs). >>>> Command 3 took 0,0018 seconds. >>>> CACHE: Stored metadata (_m,uidvalid [Drafts]) >>>> SEARCH: Expired from cache [Drafts] >> C: 4 UID SEARCH RETURN (ALL COUNT) ALL >> S: * ESEARCH (TAG "4") UID ALL 244:246 COUNT 3 >> S: 4 OK Search completed (0.000 secs). >>>> Command 4 took 0,0008 seconds. >>>> CACHE: Stored metadata (_s,_i [Drafts]) >>>> SEARCH: Saved search to cache (3b99c058 [Drafts]) >> C: 5 UID SEARCH RETURN (ALL COUNT) MODSEQ 695 >> S: * ESEARCH (TAG "5") UID ALL 246 COUNT 1 MODSEQ 696 >> S: 5 OK Search completed (0.000 secs). >>>> Command 5 took 0,0009 seconds. >>>> CACHE: Stored metadata (_s,_i [Drafts]) >>>> SEARCH: Saved search to cache (8cbc9c36 [Drafts]) >> C: 6 UID FETCH 246 (ENVELOPE FLAGS RFC822.SIZE >> BODY.PEEK[HEADER.FIELDS (IMPORTANCE LIST-POST X-PRIORITY)]) >> S: * 3 FETCH (UID 246 FLAGS (\Draft \Recent $mdnsent) RFC822.SIZE >> 3145 ENVELOPE ("Thu, 13 Apr 2017 21:13:00 +0000" {105} >> S: [LITERAL DATA: 105 bytes] >> S: (("Leonardo Bruno Lopes" NIL "leonardo" "cefetmg.br")) >> (("Leonardo Bruno Lopes" NIL "leonardo" "cefetmg.br")) (("Leonardo >> Bruno Lopes" NIL "leonardo" "cefetmg.br")) (("Andrew Bartlett" NIL >> "abartlet" "samba.org")) ((NIL NIL "samba" "lists.samba.org")) NIL >> "<[email protected]>" >> "<[email protected]>") >> BODY[HEADER.FIELDS (IMPORTANCE LIST-POST X-PRIORITY)] {2} >> S: [LITERAL DATA: 2 bytes] >> S: ) >> S: 6 OK Fetch completed. >>>> Command 6 took 0,003 seconds. >>>> CACHE: Stored messages [Drafts; 246] >> C: 7 SEARCH RETURN (MIN COUNT) UNSEEN >> S: * ESEARCH (TAG "7") MIN 1 COUNT 3 >> S: 7 OK Search completed (0.000 secs). >>>> Command 7 took 0,0008 seconds. >>>> CACHE: Stored metadata (_s,_i [Drafts]) >>>> SEARCH: Saved search to cache (d383cfdc [Drafts]) >> C: 8 LIST () "" (INBOX Sent Trash Templates Spam Horde IMP Samba) >> RETURN (STATUS (UNSEEN)) >> S: * LIST () "/" Templates >> S: * STATUS Templates (UNSEEN 0) >> S: * LIST () "/" IMP >> S: * STATUS IMP (UNSEEN 0) >> S: * LIST () "/" Sent >> S: * STATUS Sent (UNSEEN 0) >> S: * LIST () "/" Spam >> S: * STATUS Spam (UNSEEN 0) >> S: * LIST () "/" Horde >> S: * STATUS Horde (UNSEEN 0) >> S: * LIST () "/" Trash >> S: * STATUS Trash (UNSEEN 0) >> S: * LIST () "/" Samba >> S: * STATUS Samba (UNSEEN 0) >> S: * LIST () "/" INBOX >> S: * STATUS INBOX (UNSEEN 0) >> S: 8 OK List completed. >>>> Command 8 took 0,0046 seconds. >> C: 9 GETQUOTAROOT Drafts >> S: * QUOTAROOT Drafts "User quota" >> S: * QUOTA "User quota" (STORAGE 866 3145728) >> S: 9 OK Getquotaroot completed. >>>> Command 9 took 0,002 seconds. >> C: 10 LOGOUT >> S: * OK [CLOSED] Previous mailbox closed. >> S: * BYE LOGOUT received >> S: 10 OK Completed >>>> Command 10 took 0,0009 seconds. >> ------------------------------ >> >> And here are the Horde logs also generated at the same times (note >> that for these the timezone is GMT-3): >> >> Apr 13 18:10:00 mydomain.com HORDE: [imp] [store] IMAP error >> reported by server. [pid 17172 on line 726 of >> "/usr/share/horde/imp/lib/Imap.php"] >> Apr 13 18:13:00 mydomain.com HORDE: [imp] [store] IMAP error >> reported by server. [pid 17178 on line 726 of >> "/usr/share/horde/imp/lib/Imap.php"] >> >> Any ideas? I will try to connect directly to the Dovecot server to >> see if it's related to Imapproxy. >> >> Thanks, >> Leonardo > > Dear list, > > I don't know if it's OK to reply my own message, but I want to add > some more information I believe will help you guys to help me. > > Well, as I said just before, I am using imapproxy 1.2.7. So I > changed my backends.local.php to connect directly to my IMAP Dovecot. > > It's the 4th day since I did this and, althought IMP is very slow I > didn't notice that strange behavior I firstly reported. I mean, the > drafts are saved corectly without any duplication. No signal of that > errors in logs. > > So, *it seems* to be something related to IMP 6.2.2 <-> imapproxy > 1.2.7. Any ideas about what could be happening? > > Thanks, > Leonardo Maybe https://bugs.horde.org/ticket/13144 -- Jan Schneider The Horde Project https://www.horde.org/ -- imp mailing list Frequently Asked Questions: http://wiki.horde.org/FAQ To unsubscribe, mail: [email protected]