Citando Michael J Rubinsky <mrubi...@horde.org>:
Quoting Leonardo Bruno Lopes <leona...@cefetmg.br>:
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
imp@lists.horde.org from u...@domain.com (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 leona...@cefetmg.br [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
"<1491680070.22218.50.ca...@samba.org>"
"<20170413210800.horde.vxq81jvue5vqmwxdcsyn...@email.cefetmg.br>"))
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 leona...@cefetmg.br [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
"<1491680070.22218.50.ca...@samba.org>"
"<20170413211000.horde.hfg_twfx0wmdl86vrhpq...@email.cefetmg.br>")
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 leona...@cefetmg.br [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
"<1491680070.22218.50.ca...@samba.org>"
"<20170413211000.horde.hfg_twfx0wmdl86vrhpq...@email.cefetmg.br>"))
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 leona...@cefetmg.br [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
"<1491680070.22218.50.ca...@samba.org>"
"<20170413211300.horde.zia98aaq6-oxscvo25lu...@email.cefetmg.br>")
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
