[Dovecot] COMPRESS bug?

Tue Nov 9 21:20:52 EET 2010

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