Re: IMP behaves weirdly while composing messages; duplicates drafts, it may fail to save message in 'Sent'
Leonardo Bruno Lopes <[email protected]> Mon, 17 Apr 2017 23:16:30 +0000
| Newsgroups | gmane.comp.horde.imp |
|---|---|
| Message-ID | <[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 > >> >>> >>> Best regards, >>> Leonardo >>> >>> >>> -- >>> Esta mensagem foi verificada pelo sistema de antivírus e >>> acredita-se estar livre de perigo. >>> >>> -- >>> imp mailing list >>> Frequently Asked Questions: http://wiki.horde.org/FAQ >>> To unsubscribe, mail: [email protected] >> >> >> >> -- >> mike >> The Horde Project >> http://www.horde.org >> https://www.facebook.com/hordeproject >> https://www.twitter.com/hordeproject > > > > > -- > Esta mensagem foi verificada pelo sistema de antivírus e > acredita-se estar livre de perigo. > > -- > imp mailing list > Frequently Asked Questions: http://wiki.horde.org/FAQ > To unsubscribe, mail: [email protected] -- Esta mensagem foi verificada pelo sistema de antivírus e acredita-se estar livre de perigo. -- imp mailing list Frequently Asked Questions: http://wiki.horde.org/FAQ To unsubscribe, mail: [email protected]