It would also appear at first glance that the rawlog doesn't work as I might expect when using COMPRESS ? I see something like this in my logs (but nothing further):

 6 compress deflate
 2v??uQ??s???

I'm trying to figure out why a client isn't working correctly (Profimail on N97), but as near as I can see the rawlog might simply stop logging once the connection switches to COMPRESS? I'm not 100% sure though because I can't *see* anything else being logged, but at the same time I'm debugging a client that is hanging only when using COMPRESS so it could be a bunch of things going on...

Thanks for any insight?

...Actually, hijacking my thread here, but might as well give some more info now that I started:

• Profimail has 4 accounts setup using IMAP on the same server.
• Each of the 4 account is setup very similarly (type of auth, check only INBOX, same namespaces, etc, etc)
• Without COMPRESS enabled on the server all 4 accounts are checked for new mail perfectly
• With COMPRESS enabled, 3 accounts work perfectly, but one account hangs at "authenticating" (although the dovecot logs show that it finishes authing and hangs soon after initiating a COMPRESS command)

Any thoughts on how to debug this further?

Thanks

Ed W

Hi

...

It would also appear at first glance that the rawlog doesn't work as I might expect when using COMPRESS ? I see something like this in my logs (but nothing further):

6 compress deflate
2v??uQ??s???

Yeah, rawlog logs the data it sees from imap process. The compression is started after logging in, so this happens. You just delete the data before the compress command and then uncompress the rest (although I think gzip doesn't like the input because it doesn't have gz header).

I have fiddled a bit trying to get a valid header

I tried creating one with: echo -n -e "\x1F\x8B"

gunzip then gives me: gzip: test.in.gz: unknown method 50 -- not supported

Examining the raw data makes me suspect that we are missing the header data in the logged output? I'm trying to follow the code in imap_zlib_plugin.c, but I can't see how the logging works?

Can you please help?

...

• With COMPRESS enabled, 3 accounts work perfectly, but one account hangs at "authenticating" (although the dovecot logs show that it finishes authing and hangs soon after initiating a COMPRESS command) I guess there's a bug somewhere, either in Dovecot or in the client..

I have probed this a bit without being able to see the decompressed output. I have several working accounts using this client, and yet this single account (which also has many more messages than the other accounts) keeps hanging at the "auth" stage. It hasn't changed the symptoms by: adding/removing messages from the account, recreating the settings on the client, fiddling with namespace options - which seems to rule out some of the obvious parsing flaws that could be happening here

I think I need to see inside the data sent to the client. My client has no obvious debugging support, so grateful if you can help construct a valid header here?

Thanks

Ed W

On 03/11/2010 16:29, Timo Sirainen wrote:

On Wed, 2010-11-03 at 12:40 +0000, Ed W wrote:

...

Examining the raw data makes me suspect that we are missing the header data in the logged output? I'm trying to follow the code in imap_zlib_plugin.c, but I can't see how the logging works?

Can you please help? Here: http://hg.dovecot.org/dovecot-2.0/rev/708fd6faca39 http://hg.dovecot.org/dovecot-2.0/rev/e21d08bf5e9d

Thankyou so much for implementing this - I believe it may have traced a Dovecot side bug in the COMPRESS protocol

Here is the xx.in trace:

6 compress deflate 7 SELECT INBOX 8 SEARCH SINCE 2-Nov-2010 doveadm(root): Error: zlib.read(): unexpected EOF at 63

Here is the xx.out *while* the client is connecting and sitting apparently doing nothing:

• CAPABILITY IMAP4rev1 LITERAL+ SASL-IR LOGIN-REFERRALS ID ENABLE IDLE SORT SORT=DISPLAY THREAD=REFERENCES THREAD=REFS MULTIAPPEND UNSELECT IDLE CHILDREN NAMESPACE UIDPLUS LIST-EXTENDED I18NLEVEL=1 CONDSTORE QRESYNC ESEARCH ESORT SEARCHRES WITHIN CONTEXT=SEARCH LIST-STATUS COMPRESS=DEFLATE 5 OK Logged in 6 OK Begin compression.
• FLAGS (\Answered \Flagged \Deleted \Seen \Draft NonJunk $Forwarded $MDNSent $Label1 $Label4 $label5 Junk $label2 $label3 approved)
• OK [PERMANENTFLAGS (\Answered \Flagged \Deleted \Seen \Draft NonJunk $Forwarded $MDNSent $Label1 $Label4 $label5 Junk $label2 $label3 approved \*)] Flags permitted.
• 36211 EXISTS
• 0 RECENT
• OK [UNSEEN 5975] First unseen.
• OK [UIDVALIDITY 1154000160] UIDs valid
• OK [UIDNEXT 58187] Predicted next UID
• OK [HIGHESTMODSEQ 16008] Highest 7 OK [READ-WRITE] Select completed.
• SEARCH 35941 35942 35943 35944 35945 35946 35947 35948 35949 35950 35951 35952 35953 35954 35955 35956 35957 35958 35959 35960 35961 35962 35963 35964 35965 35966 35967 35968 35969 35970 35971 35972 35973 35974 35975 35976 35977 35978 35979 35980 35981 35982 35983 35984 35985 35986 35987 35988 35989 35990 35991 35992 35993 35994 35995 35996 35997 35998 35999 36000 36001 36002 36003 36004 36005 36006 36007 36008 36009 36010 36011 36012 36013 36014 36015 36016 36017 36018 36019 36020 36021 36022 36023 36024 36025 36026 36027 36028 36029 36030 36031 36032 36033 36034 36035 36036 36037 36038 36039 36040 36041 36042 36043 36044 36045 36046 36047 36048 36049 36050 36051 36052 36053 36054 36055 36056 36057 36058 36059 36060 36061 36062 36063 36064 36065 36066 36067 36068 36069 36070 36071 36072 36073 36074 36075 36076 36077 36078 36079 36080 36081 36082 36083 36084 36085 36086 36087 36088 36089 36090 36091 36092 36093 36094 36095 36096 36097 36098 36099 36100 36101 36102 36103 36104 36105 36106 36107 36108 36109 36110 36111 36112 36113 36114 36115 36116 36117 36118 36119 36120 36121 36122 36123 36124 36125 36126 36127 36128 36129 36130 36131 36132 36133 36134 36135 36136 36137 36138 36139 36140 36141 36142 36143 36144 36145 36146 36147 36148 36149 36150 36151 36152 36153 36154 36155 36156 36157 36158 36159 36160 36161 36162 36163 36164 36165 36166 36167 36168 36169 36170 36171 36172 36173 36174 36175 36176 36177 36178 36179 36180 36181 36182 36183 36184 36185 36186 36187 36188 36189 36190 36191 36192 36193 36194 36195 36196 36197 36198 36199 36200 36201 36202 36203 36204 36205 36206 36207 36208 36209 36210 36211 doveadm(root): Error: zlib.read(): unexpected EOF at 2489

I now restart the server (while the client sitting and hanging), abbreviated output: .... 183 36184 36185 36186 36187 36188 36189 36190 36191 36192 36193 36194 36195 36196 36197 36198 36199 36200 36201 36202 36203 36204 36205 36206 36207 36208 36209 36210 36211 8 OK Search completed (0.381 secs).

• BYE Server shutting down. doveadm(root): Error: zlib.read(): unexpected EOF at 2555

So, this suggests that unless the logging isn't working right, that the response isn't being completely returned? (Running the search manually shows that 26211 is the expected last item.)

Annoyingly, I can't repro this using another email account on the same server. The problem account has way more messages than other accounts, but for example same client pulling down messages from another reasonable sized inbox gives:

....

• SEARCH 5865 5866 5867 5868 5869 5870 5871 5872 5873 5874 5875 5876 5877 5878 5879 5880 5881 5882 5883 5884 5885 5886 5887 5888 5889 5890 5891 5892 5893 5894 5895 5896 5897 5898 5899 5900 5901 5902 5903 5904 5905 5906 5907 5908 5909 5910 5911 5912 5913 5914 5915 5916 5917 5918 5919 5920 5921 5922 5923 5924 5925 5926 5927 5928 5929 5930 5931 5932 5933 5934 5935 5936 5937 5938 5939 5940 5941 5942 5943 5944 5945 5946 5947 5948 5949 5950 5951 5952 5953 5954 5955 5956 5957 5958 5959 5960 5961 5962 5963 5964 5965 5966 5967 5968 5969 5970 5971 5972 5973 5974 5975 5976 5977 5978 5979 5980 5981 5982 5983 5984 5985 5986 5987 5988 8 OK Search completed (0.255 secs).
• 5865 FETCH (UID 15329 FLAGS (\Seen NonJunk))
• 5866 FETCH (UID 15330 FLAGS (\Answered \Seen NonJunk))
• 5867 FETCH (UID 15331 FLAGS (\Answered \Seen NonJunk)) ...

The whole configuration is mysql driven and at least in theory all accounts are maildir and they are supposed to all be configured the same...

Logging in using telnet (no compression) gives a sensible result to the above IMAP commands. Also disabling compression in the configuration and my client starts working again fine...

Client is a Profimail on Nokia N97. Thunderbird working fine on same inbox

Grateful if you can help?

Many thanks

Ed W

On 09/11/2010 21:07, Timo Sirainen wrote:

On Tue, 2010-11-09 at 19:20 +0000, Ed W wrote:

...

36203 36204 36205 36206 36207 36208 36209 36210 36211 doveadm(root): Error: zlib.read(): unexpected EOF at 2489 I now restart the server (while the client sitting and hanging), abbreviated output: .... 36207 36208 36209 36210 36211 8 OK Search completed (0.381 secs). Yeah, looks like the "OK Search completed" gets stuck somewhere. Wonder if http://hg.dovecot.org/dovecot-2.0/rev/631e0d846e57 would help? I'm not too optimistic though.

OK, this made no difference to the observed symptoms sadly.

Just to re-iterate the peculiarity of the symptoms:

• Only noticed it on this one account, 3 other accounts are not showing symptoms
• It's only the Search which appears to go wrong
• I varied the Search timeframe a little to vary the size of result, made no difference (trying to see if it's packet length dependent or similar)
• Asking the client to receive ALL emails is ok (not tested, but presume it uses a different set of IMAP commands)

I find it very odd that it's basically a symptom on one login and not all logins? Also that it's persistent through time and basically independent of small variations in result size (ie probably not zlib related or network packet size related). I guess the main thing which seems different about this account is the high numbers for the IDs being returned, all other accounts have fewer messages and lower numbers - very peculiar?

Thanks for any insight?

Ed W

On 09/11/2010 21:07, Timo Sirainen wrote:

On Tue, 2010-11-09 at 19:20 +0000, Ed W wrote:

...

36203 36204 36205 36206 36207 36208 36209 36210 36211 doveadm(root): Error: zlib.read(): unexpected EOF at 2489 I now restart the server (while the client sitting and hanging), abbreviated output: .... 36207 36208 36209 36210 36211 8 OK Search completed (0.381 secs). Yeah, looks like the "OK Search completed" gets stuck somewhere. Wonder if http://hg.dovecot.org/dovecot-2.0/rev/631e0d846e57 would help? I'm not too optimistic though.

OK, some time has passed, but now back and I have traced this to it being an issue once a folder gets a certain number of emails in it.

So to summarise:

• Zlib enabled
• COMPRESS initiated in the connection
• 30,000 messages in a single maildir folder
• IMAP SEARCH SINCE requested
• Dovecot 2.0.7 "hangs" without sending the closing stanza of the SEARCH result command (exact imap trace in previous email in this thread)

IF

• Remove a single email from the folder (29,999 left) then everything completes successfully!

I have tested this with various permutations of 30,000 real emails and that seems to repeatably be the point problems occur.

(Note: A slight curiousity is that removing a single email to get things working, then adding the email back again sometimes seems to keep working, not sure why? However, it's fairly easy to cause it to fail again, eg I moved ALL emails out of the folder, search, then add all emails back in again - now it starts to hang again. Just mentioning this because there might be some ways that would stop you repro-ing it if you simply "add" emails to a folder until it breaks, rather than removing them from a folder which is already broken?)

Grateful if you can figure out the underlying problem in Dovecot?

Many thanks

Ed W