Re: [SOGo] markMessageRead gives HTTP 500 error

2016-11-19 Thread Niklaas Baudet von Gersdorff 
Niklaas Baudet von Gersdorff [2016-11-18 20:17 +0100] :

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

[...]

> - Log of the commands sent by SOGo [failure]:
> 
>  11479494975.487768 2 capability
>  21479494975.597790 3 ID ("x-originating-ip" "80.128.92.18, 
> 80.128.92.18, 10.1.4.1")
>  31479494975.702911 4 namespace
>  41479494975.805228 5 LIST "" ""
>  51479494975.911216 6 status "INBOX" (UIDVALIDITY)
>  61479494976.015683 7 select "INBOX"
>  71479494976.017657 8 uid fetch 2239792419 (FLAGS ENVELOPE 
> BODYSTRUCTURE RFC822.SIZE RFC822.HEADER)
>  81479494976.237562 9 uid fetch 2239792419 (body.peek[text])
>  91479494976.454405 10 uid store -2055174877 +FLAGS (\seen)
> 101479494976.560037 11 logout
> 
>   Line 9 is the most interesting one. To me this looks like an
>   integer overflow.

[...]

> Does this help for debugging the issue? Do you need further
> information?

I created a PR:

  https://sogo.nu/bugs/view.php?id=3908

Niklaas
-- 
users@sogo.nu
https://inverse.ca/sogo/lists

Re: [SOGo] markMessageRead gives HTTP 500 error

2016-11-18 Thread Niklaas Baudet von Gersdorff 
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 +" {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

Re: [SOGo] markMessageRead gives HTTP 500 error

2016-11-17 Thread Niklaas Baudet von Gersdorff 
Francis Lachapelle [2016-11-17 13:27 -0500] :

> >> Use imapproxy and configure SOGo to connect to imapproxy rather than 
> >> directly to your Dovecot server.
> > 
> > I see. Looks like a tool for my utility belt, anyway. :-) I'm
> > setting it up.
> > 
> > And imapproxy's log is more informative? Or shall I configure
> > SOGo to connect to imapproxy on 143 while imapproxy connects to
> > Dovecot on 993, so that I can tcpdump between SOGo and imapproxy?
> 
> The latter.

OK, so in the end I didn't have to use imapproxy because I have
haproxy in front of multiple dovecot proxies and their connection
is unencrypted. Well, anyway...

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 dont't know the protocol but I suspect SOGo sending something
containing UID STORE. So what I did was

  $ tcpdump -Anli lo0 | grep 'UID STORE'

but the only thing I get when selecting a message is the error
above. Maybe this already helps?

Any advise for further debugging this is very much appreciated.

Niklaas
-- 
users@sogo.nu
https://inverse.ca/sogo/lists

Re: [SOGo] markMessageRead gives HTTP 500 error

2016-11-17 Thread Francis Lachapelle 
> On Nov 17, 2016, at 1:23 PM, Niklaas Baudet von Gersdorff (st...@niklaas.eu) 
>  wrote:
> 
> Francis Lachapelle [2016-11-17 12:56 -0500] :
> 
>>> Francis Lachapelle [2016-11-17 10:20 -0500] :
>>> 
 Sniff your IMAP traffic to see the error returned from your IMAP server.
>>> 
>>> What's the best way to do that? I tried `tcpdump` but I cannot
>>> decipher its output. Because SOGo and Dovecot communicate over
>>> 993 there will be not a lot for me to see, I guess.
>> 
>> Use imapproxy and configure SOGo to connect to imapproxy rather than 
>> directly to your Dovecot server.
> 
> I see. Looks like a tool for my utility belt, anyway. :-) I'm
> setting it up.
> 
> And imapproxy's log is more informative? Or shall I configure
> SOGo to connect to imapproxy on 143 while imapproxy connects to
> Dovecot on 993, so that I can tcpdump between SOGo and imapproxy?

The latter.

>>> anything suspicious. However, I suspect that this is not an issue
>>> with Dovecot but with SOGo because other clients such as Mutt and
>>> AquaMail work as expected.
>> 
>> We still need to know the full discussion exchanged between SOGo and Dovecot 
>> if there is one.
> 
> Of course.
> 
>Niklaas



-- 
users@sogo.nu
https://inverse.ca/sogo/lists

Re: [SOGo] markMessageRead gives HTTP 500 error

2016-11-17 Thread Niklaas Baudet von Gersdorff 
Francis Lachapelle [2016-11-17 12:56 -0500] :

> > Francis Lachapelle [2016-11-17 10:20 -0500] :
> > 
> >> Sniff your IMAP traffic to see the error returned from your IMAP server.
> > 
> > What's the best way to do that? I tried `tcpdump` but I cannot
> > decipher its output. Because SOGo and Dovecot communicate over
> > 993 there will be not a lot for me to see, I guess.
> 
> Use imapproxy and configure SOGo to connect to imapproxy rather than directly 
> to your Dovecot server.

I see. Looks like a tool for my utility belt, anyway. :-) I'm
setting it up.

And imapproxy's log is more informative? Or shall I configure
SOGo to connect to imapproxy on 143 while imapproxy connects to
Dovecot on 993, so that I can tcpdump between SOGo and imapproxy?

> > anything suspicious. However, I suspect that this is not an issue
> > with Dovecot but with SOGo because other clients such as Mutt and
> > AquaMail work as expected.
> 
> We still need to know the full discussion exchanged between SOGo and Dovecot 
> if there is one.

Of course.

Niklaas
-- 
users@sogo.nu
https://inverse.ca/sogo/lists

Re: [SOGo] markMessageRead gives HTTP 500 error

2016-11-17 Thread Francis Lachapelle 
> On Nov 17, 2016, at 12:43 PM, Niklaas Baudet von Gersdorff (st...@niklaas.eu) 
>  wrote:
> 
> Francis, thank you for your reply.
> 
> Francis Lachapelle [2016-11-17 10:20 -0500] :
> 
>> Sniff your IMAP traffic to see the error returned from your IMAP server.
> 
> What's the best way to do that? I tried `tcpdump` but I cannot
> decipher its output. Because SOGo and Dovecot communicate over
> 993 there will be not a lot for me to see, I guess.

Use imapproxy and configure SOGo to connect to imapproxy rather than directly 
to your Dovecot server.

> I also enabled Dovecot's `mail_debug=yes` but I can't see
> anything suspicious. However, I suspect that this is not an issue
> with Dovecot but with SOGo because other clients such as Mutt and
> AquaMail work as expected.

We still need to know the full discussion exchanged between SOGo and Dovecot if 
there is one.


Francis
-- 
users@sogo.nu
https://inverse.ca/sogo/lists

Re: [SOGo] markMessageRead gives HTTP 500 error

2016-11-17 Thread Niklaas Baudet von Gersdorff 
Francis, thank you for your reply.

Francis Lachapelle [2016-11-17 10:20 -0500] :

> Sniff your IMAP traffic to see the error returned from your IMAP server.

What's the best way to do that? I tried `tcpdump` but I cannot
decipher its output. Because SOGo and Dovecot communicate over
993 there will be not a lot for me to see, I guess.

I also enabled Dovecot's `mail_debug=yes` but I can't see
anything suspicious. However, I suspect that this is not an issue
with Dovecot but with SOGo because other clients such as Mutt and
AquaMail work as expected.

Niklaas
-- 
users@sogo.nu
https://inverse.ca/sogo/lists

Re: [SOGo] markMessageRead gives HTTP 500 error

2016-11-17 Thread Francis Lachapelle 
Hello Niklaas

> On Nov 17, 2016, at 9:46 AM, Niklaas Baudet von Gersdorff (st...@niklaas.eu) 
>  wrote:
> 
> What follows is a problem description for version 3.1.5. After
> updating to 3.2.1, the issue seems to be resolved only *partly*.
> At the end of the mail, you can find a problem description for
> version 3.2.1.
> 
> [snip]

> As you can see, something must have happened between November 4th
> and 17th that
> 
> 1. caused markMessageRead to return 500 instead of 204
> 
> 2. made the ID of mails jump from 9269 to 2239792221

Sniff your IMAP traffic to see the error returned from your IMAP server.


Francis


-- 
users@sogo.nu
https://inverse.ca/sogo/lists

[SOGo] markMessageRead gives HTTP 500 error

2016-11-17 Thread Niklaas Baudet von Gersdorff 
What follows is a problem description for version 3.1.5. After
updating to 3.2.1, the issue seems to be resolved only *partly*.
At the end of the mail, you can find a problem description for
version 3.2.1.

When selecting a message in the Mail module, the message is
displayed in the preview pane on the right side but it is not
marked as read. In the top right an error message says:

  Request failed

Looking at the log file of sogod I see error messages such as the
following each time I select a message:

  Nov 17 12:28:35 sogod [54352]: 80.128.92.18, 80.128.92.18, 10.1.4.1 "GET 
/SOGo/so/n...@niklaas.eu/Mail/0/folderINBOX/2239792221/markMessageRead 
HTTP/1.1" 500 286/0 0.875 - - -

Apparently, it's an HTTP 500 error (Apache24 says the same in its
log file). I don't know how to debug this further.

As it seems, the error occurs on my account only. I don't use the
webmail interface very often, so I cannot say since when this
error occurs. The following I have found out so far:

  $ grep markMessageRead /var/log/sogo/sogo.log | grep n...@niklaas.eu

  Oct 07 17:43:58 sogod [69895]: 37.201.169.224, 37.201.169.224, 10.1.4.1 "GET 
/SOGo/so/n...@niklaas.eu/Mail/0/folderINBOX/6089/markMessageRead HTTP/1.1" 204 
0/0 0.875 - - -
  Oct 09 12:02:00 sogod [88029]: 37.201.169.224, 37.201.169.224, 10.1.4.1 "GET 
/SOGo/so/n...@niklaas.eu/Mail/0/folderINBOX/6217/markMessageRead HTTP/1.1" 204 
0/0 0.880 - - -
  Oct 09 12:02:10 sogod [88029]: 37.201.169.224, 37.201.169.224, 10.1.4.1 "GET 
/SOGo/so/n...@niklaas.eu/Mail/0/folderINBOX/6193/markMessageRead HTTP/1.1" 204 
0/0 0.884 - - -
  Oct 15 00:55:15 sogod [45507]: 80.128.92.18, 80.128.92.18, 10.1.4.1 "GET 
/SOGo/so/n...@niklaas.eu/Mail/0/folderINBOX/6766/markMessageRead HTTP/1.1" 204 
0/0 0.874 - - -
  Nov 04 08:41:41 sogod [67386]: 80.128.92.18, 80.128.92.18, 10.1.4.1 "GET 
/SOGo/so/n...@niklaas.eu/Mail/0/folderINBOX/9269/markMessageRead HTTP/1.1" 204 
0/0 0.876 - - -
  Nov 17 12:27:10 sogod [54354]: 80.128.92.18, 80.128.92.18, 10.1.4.1 "GET 
/SOGo/so/n...@niklaas.eu/Mail/0/folderINBOX/2239792221/markMessageRead 
HTTP/1.1" 500 286/0 0.895 - - -
  Nov 17 12:27:23 sogod [54354]: 80.128.92.18, 80.128.92.18, 10.1.4.1 "GET 
/SOGo/so/n...@niklaas.eu/Mail/0/folderINBOX/2239792220/markMessageRead 
HTTP/1.1" 500 286/0 0.867 - - -
  Nov 17 12:27:48 sogod [54351]: 80.128.92.18, 80.128.92.18, 10.1.4.1 "GET 
/SOGo/so/n...@niklaas.eu/Mail/0/folderINBOX/2239792220/markMessageRead 
HTTP/1.1" 500 286/0 0.866 - - -
  Nov 17 12:28:35 sogod [54352]: 80.128.92.18, 80.128.92.18, 10.1.4.1 "GET 
/SOGo/so/n...@niklaas.eu/Mail/0/folderINBOX/2239792221/markMessageRead 
HTTP/1.1" 500 286/0 0.875 - - -

As you can see, something must have happened between November 4th
and 17th that

1. caused markMessageRead to return 500 instead of 204

2. made the ID of mails jump from 9269 to 2239792221

I don't know whether these two changes/issues are interrelated.
As far as I can judge from the log file other users are not
affected and the IDs of their mails remain in multiples of 10^3
(instead of 10^9). (I don't know sogo's internals well, so
I suspect it's something like an ID that changed here.)

So, I just updated to version 3.2.1, which partly resolved the
issue. What has changed since version 3.1.5 is the following:

- The webmail client doesn't show an error message saying
  "Request failed".

- After previewing the message in the pane on the right, the
  message is marked as read in the message list.

However, when refreshing the mailbox every message that was just
marked as read will be shown as unread again.

- In the logs I cannot see any reference to markMessageRead.

I suspect that there had been some work done on this issue
between the two versions I stated above but I cannot find any
reference in the bug tracking system.

Do you have any recommendations on how to debug the issue further
or ideas what might cause the error?

Any help is very much appreciated.

Niklaas
-- 
users@sogo.nu
https://inverse.ca/sogo/lists