Re: IMP behaves weirdly while composing messages; duplicates drafts, it may fail to save message in 'Sent'

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

>
>>
>> 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]