Niklaas Baudet von Gersdorff [2016-11-17 21:26 +0100] :
> I found the following, which might be of interest:
>
> BAD Error in IMAP command UID STORE: Invalid uidset (0.001 + 0.107 + 0.106
> secs).
>
> I assume this is Dovecot's response. But I'm still desperately
> looking for the command that was sent by SOGo.
I've got some news on this. I used Dovecot's rawlog_dir feature
[1] to get a full transcript of IMAP sessions. In the following
you can see two log pairs, one for an example when marking the
message read fails, and one for an example when marking the
message read succeeds.
- Log of the commands sent by SOGo [failure]:
1 1479494975.487768 2 capability
2 1479494975.597790 3 ID ("x-originating-ip" "80.128.92.18, 80.128.92.18,
10.1.4.1")
3 1479494975.702911 4 namespace
4 1479494975.805228 5 LIST "" ""
5 1479494975.911216 6 status "INBOX" (UIDVALIDITY)
6 1479494976.015683 7 select "INBOX"
7 1479494976.017657 8 uid fetch 2239792419 (FLAGS ENVELOPE BODYSTRUCTURE
RFC822.SIZE RFC822.HEADER)
8 1479494976.237562 9 uid fetch 2239792419 (body.peek[text])
9 1479494976.454405 10 uid store -2055174877 +FLAGS (\seen)
10 1479494976.560037 11 logout
Line 9 is the most interesting one. To me this looks like an
integer overflow.
- Log of the commands sent back by Dovecot [failure]:
1 1479494975.409990 L OK [CAPABILITY IMAP4rev1 LITERAL+ SASL-IR
LOGIN-REFERRALS ID ENABLE IDLE SORT SORT=DISPLAY THREAD=REFERENCES THREAD=REFS
THREAD=ORDEREDSUBJECT MULTIAPPEND URL-PARTIAL CATENATE UNSELECT CHILDREN
NAMESPACE UIDPLUS LIST-EXTENDED I18NLEVEL=1 CONDSTORE QRESYNC ESEARCH ESORT
SEARCHRES WITHIN CONTEXT=SEARCH LIST-STATUS BINARY MOVE SPECIAL-USE QUOTA]
Logged in
2 1479494975.596099 * CAPABILITY IMAP4rev1 LITERAL+ SASL-IR
LOGIN-REFERRALS ID ENABLE IDLE SORT SORT=DISPLAY THREAD=REFERENCES THREAD=REFS
THREAD=ORDEREDSUBJECT MULTIAPPEND URL-PARTIAL CATENATE UNSELECT CHILDREN
NAMESPACE UIDPLUS LIST-EXTENDED I18NLEVEL=1 CONDSTORE QRESYNC ESEARCH ESORT
SEARCHRES WITHIN CONTEXT=SEARCH LIST-STATUS BINARY MOVE SPECIAL-USE QUOTA
3 1479494975.596157 2 OK Capability completed (0.000 + 0.109 + 0.108
secs).
4 1479494975.701265 * ID ("name" "Dovecot")
5 1479494975.701289 3 OK ID completed (0.001 + 0.104 + 0.103 secs).
6 1479494975.803571 * NAMESPACE (("" "/")) NIL NIL
7 1479494975.803604 4 OK Namespace completed (0.000 + 0.101 + 0.100 secs).
8 1479494975.909212 * LIST (\Noselect) "/" ""
9 1479494975.909252 5 OK List completed (0.001 + 0.104 + 0.104 secs).
10 1479494975.912913 * STATUS INBOX (UIDVALIDITY 1470121274)
11 1479494975.913070 6 OK Status completed (0.000 + 0.000 + 0.001 secs).
12 1479494976.016096 * FLAGS (\Answered \Flagged \Deleted \Seen \Draft Old)
13 1479494976.016120 * OK [PERMANENTFLAGS (\Answered \Flagged \Deleted
\Seen \Draft Old \*)] Flags permitted.
14 1479494976.016131 * 24 EXISTS
15 1479494976.016141 * 0 RECENT
16 1479494976.016151 * OK [UNSEEN 18] First unseen.
17 1479494976.016161 * OK [UIDVALIDITY 1470121274] UIDs valid
18 1479494976.016170 * OK [UIDNEXT 2239792420] Predicted next UID
19 1479494976.016181 * OK [HIGHESTMODSEQ 22849] Highest
20 1479494976.016209 7 OK [READ-WRITE] Select completed (0.000 + 0.000
secs).
21 1479494976.125146 * 24 FETCH (UID 2239792419 FLAGS () RFC822.SIZE 5239
ENVELOPE ("Fri, 18 Nov 2016 18:47:03 +0000" {109}
22
23 {removed}
24
25 1479494976.128037 )
26 1479494976.128376 8 OK Fetch completed (0.004 + 0.107 secs).
27 1479494976.344820 * 24 FETCH (UID 2239792419 BODY[TEXT] {975}
28
29 {removed}
30
31 1479494976.344963 )
32 1479494976.345168 9 OK Fetch completed (0.001 + 0.107 secs).
33 1479494976.556124 10 BAD Error in IMAP command UID STORE: Invalid
uidset (0.001 + 0.102 + 0.101 secs).
34 1479494976.560080 * BYE Logging out
35 1479494976.560133 11 OK Logout completed (0.000 + 0.000 secs).
Line 33 is the most interesting one.
For comparison the following is the log pair when marking the
message read succeeds.
- Log of the commands sent by SOGo [success]:
1 1479495516.981928 2 capability
2 1479495517.088561 3 ID ("x-originating-ip" "80.128.92.18, 80.128.92.18,
10.1.4.1")
3 1479495517.193587 4 namespace
4 1479495517.299703 5 LIST "" ""
5 1479495517.407754 6 status "INBOX" (UIDVALIDITY)
6 1479495517.510810 7 select "INBOX"
7 1479495517.513942 8 uid fetch 7766 (FLAGS ENVELOPE BODYSTRUCTURE
RFC822.SIZE RFC822.HEADER)
8 1479495517.841574 9 uid fetch 7766 (body.peek[1] body.peek[2])
9 1479495518.163159 10 uid store 7766 +FLAGS (\seen)
10 1479495518.280185 11 logout
- Log of the commands sent back by Dovecot [success]:
1 1479495516.903069 L OK [CAPABILITY IMAP4rev1 LITERAL+ SASL-IR
LOGIN-REFERRALS ID ENABLE IDLE SORT SORT=DISPLAY THREAD=REFERENCES THREAD=REFS
THREAD=ORDEREDSUBJECT MULTIAPPEND URL-PARTIAL CATENATE UNSELECT CHILDREN
NAMESPACE UIDPLUS LIST-EXTENDED I18NLEVEL=1 CONDSTORE QRESYNC ESEARCH ESORT
SEARCHRES WITHIN CONTEXT=SEARCH LIST-STATUS BINARY MOVE SPECIAL-USE QUOTA]
Logged in
2 1479495517.086760 * CAPABILITY IMAP4rev1 LITERAL+ SASL-IR
LOGIN-REFERRALS ID ENABLE IDLE SORT SORT=DISPLAY THREAD=REFERENCES THREAD=REFS
THREAD=ORDEREDSUBJECT MULTIAPPEND URL-PARTIAL CATENATE UNSELECT CHILDREN
NAMESPACE UIDPLUS LIST-EXTENDED I18NLEVEL=1 CONDSTORE QRESYNC ESEARCH ESORT
SEARCHRES WITHIN CONTEXT=SEARCH LIST-STATUS BINARY MOVE SPECIAL-USE QUOTA
3 1479495517.086792 2 OK Capability completed (0.000 + 0.105 + 0.104
secs).
4 1479495517.192109 * ID ("name" "Dovecot")
5 1479495517.192148 3 OK ID completed (0.001 + 0.104 + 0.103 secs).
6 1479495517.297915 * NAMESPACE (("" "/")) NIL NIL
7 1479495517.297948 4 OK Namespace completed (0.000 + 0.105 + 0.104 secs).
8 1479495517.403391 * LIST (\Noselect) "/" ""
9 1479495517.403447 5 OK List completed (0.001 + 0.104 + 0.103 secs).
10 1479495517.409553 * STATUS INBOX (UIDVALIDITY 1470121274)
11 1479495517.409595 6 OK Status completed (0.000 + 0.000 + 0.001 secs).
12 1479495517.511399 * FLAGS (\Answered \Flagged \Deleted \Seen \Draft Old)
13 1479495517.511466 * OK [PERMANENTFLAGS (\Answered \Flagged \Deleted
\Seen \Draft Old \*)] Flags permitted.
14 1479495517.511507 * 23 EXISTS
15 1479495517.511540 * 0 RECENT
16 1479495517.511563 * OK [UNSEEN 9] First unseen.
17 1479495517.511586 * OK [UIDVALIDITY 1470121274] UIDs valid
18 1479495517.511609 * OK [UIDNEXT 2239792421] Predicted next UID
19 1479495517.511632 * OK [HIGHESTMODSEQ 22858] Highest
20 1479495517.511662 7 OK [READ-WRITE] Select completed (0.000 + 0.000
secs).
21 1479495517.622021 * 9 FETCH (UID 7766 FLAGS (\Flagged) RFC822.SIZE 6609
ENVELOPE ("Tue, 5 Jul 2016 10:19:35 +0200" "XXX" (("XXX" NIL "XXX" "XXX"))
(("XXX" NIL "XXX" "XXX")) (("XXX" NIL "XXX" "XXX")) (("XXX" NIL "XXX" "XXX"))
NIL NIL NIL "XXX") BODYSTRUCTURE (("text" "plain" ("charset" "UTF-8") NIL NIL
"quoted-printable" 1488 29 NIL NIL NIL NIL)("text" "html" ("charset" "UTF-8")
NIL NIL "quoted-printable" 2393 42 NIL NIL NIL NIL) "alternative" ("boundary"
"001a1137b20c04ca980536df1d79") NIL NIL NIL) RFC822.HEADER {2451}
22
23 {removed}
24
25 1479495517.948966 )
26 1479495517.949200 9 OK Fetch completed (0.001 + 0.107 secs).
27 1479495518.270898 * 9 FETCH (UID 7766 FLAGS (\Flagged \Seen))
28 1479495518.271646 10 OK Store completed (0.003 + 0.105 + 0.003 secs).
29 1479495518.280253 * BYE Logging out
30 1479495518.280303 11 OK Logout completed (0.000 + 0.000 secs).
Does this help for debugging the issue? Do you need further
information?
Niklaas
1: http://wiki2.dovecot.org/Debugging/Rawlog
--
[email protected]
https://inverse.ca/sogo/lists
