[Dovecot] Proxy problems with 1.0.5 !

Ed W

13 Sep 2007 13 Sep '07

4:05 a.m.

I am trying to do a staged migration over to dovecot, but having troubles at the first hurdle. I setup the proxy feature to redirect most of our users back to the current Courier imap/pop server, and it's partly working, but I'm getting some serious errors using Thunderbird and IMAP.

Now, I had expected the proxying to be fairly transparent and basically just dovecot doing an auth and then passing the stream on to the other server? My problem is that using Thunderbird I can read all my folders OK, but I can't save anything in my Sent Items or Drafts folders...
Basically I get errors every time I try and send an email, or try to save to the draft folder.

Curiously, directly browsing into those folders works fine, as does deleting emails, and apparently copying them works fine also... Why is the saving of sent messages failing...?

The setup is basically taking a working Thunderbird install, changing the server name from pointing at the Courier server to point at the dovecot server - dovecot in turn is told to proxy back to the original server.

All I'm getting from Thunderbird is an "Invalid Command" response. Is there an easy way to get a look inside the imap stream to try and see what's failing?

Any suggestions on why this is happening at all?

One idea is that I have setup completely different namespaces in Dovecot, (with a hidden namespace which should be courier compatible), but I wouldn't have expected this to affect the Proxy stuff at all?!

Grateful for any pointers to debug this - it's a fairly major hurdle for my rollout

Thanks

Ed W

Show replies by date

Troy Engel

13 Sep 13 Sep

4:11 a.m.

Ed W wrote:

...

All I'm getting from Thunderbird is an "Invalid Command" response. Is there an easy way to get a look inside the imap stream to try and see what's failing?

From the client end of things: http://wiki.dovecot.org/Debugging/Thunderbird

-te

-- Troy Engel | Systems Engineer Fluid Inc. | http://www.fluid.com

Ed W

4:29 a.m.

Thanks Troy

Can anyone help translate this (also why it's only breaking through the proxy mode?)

5188[50431f8]: 2998a00:mail.mailasail.com:A:CreateNewLineFromSocket: 4 OK LSUB completed

5188[50431f8]: 2998a00:mail.mailasail.com:A:SendData: 5 lsub "" "#shared.*"

5188[50431f8]: ReadNextLine [stream=2e682c8 nb=21 needmore=0] 5188[50431f8]: 2998a00:mail.mailasail.com:A:CreateNewLineFromSocket: 5 OK LSUB completed

5188[50431f8]: 2998a00:mail.mailasail.com:A:SendData: 6 lsub "" "shared.*"

5188[50431f8]: ReadNextLine [stream=2e682c8 nb=21 needmore=0] 5188[50431f8]: 2998a00:mail.mailasail.com:A:CreateNewLineFromSocket: 6 OK LSUB completed

5188[50431f8]: 2998a00:mail.mailasail.com:A:SendData: 7 list "" "INBOX"

5188[50431f8]: ReadNextLine [stream=2e682c8 nb=43 needmore=0] 5188[50431f8]: 2998a00:mail.mailasail.com:A:CreateNewLineFromSocket: * LIST (\Marked \HasChildren) "." "INBOX"

5188[50431f8]: ReadNextLine [stream=2e682c8 nb=21 needmore=0] 5188[50431f8]: 2998a00:mail.mailasail.com:A:CreateNewLineFromSocket: 7 OK LIST completed

5188[50431f8]: 2998a00:mail.mailasail.com:A:SendData: 8 select "INBOX.Drafts"

5188[50431f8]: ReadNextLine [stream=2e682c8 nb=60 needmore=0] 5188[50431f8]: 2998a00:mail.mailasail.com:A:CreateNewLineFromSocket: * FLAGS (\Draft \Answered \Flagged \Deleted \Seen \Recent)

5188[50431f8]: ReadNextLine [stream=2e682c8 nb=77 needmore=0] 5188[50431f8]: 2998a00:mail.mailasail.com:A:CreateNewLineFromSocket: * OK [PERMANENTFLAGS (\* \Draft \Answered \Flagged \Deleted \Seen)] Limited

5188[50431f8]: ReadNextLine [stream=2e682c8 nb=14 needmore=0] 5188[50431f8]: 2998a00:mail.mailasail.com:A:CreateNewLineFromSocket: * 104 EXISTS

5188[50431f8]: ReadNextLine [stream=2e682c8 nb=12 needmore=0] 5188[50431f8]: 2998a00:mail.mailasail.com:A:CreateNewLineFromSocket: * 0 RECENT

5188[50431f8]: ReadNextLine [stream=2e682c8 nb=34 needmore=0] 5188[50431f8]: 2998a00:mail.mailasail.com:A:CreateNewLineFromSocket: * OK [UIDVALIDITY 1016267950] Ok

5188[50431f8]: ReadNextLine [stream=2e682c8 nb=32 needmore=0] 5188[50431f8]: 2998a00:mail.mailasail.com:A:CreateNewLineFromSocket: * OK [MYRIGHTS "acdilrsw"] ACL

5188[50431f8]: ReadNextLine [stream=2e682c8 nb=22 needmore=0] 5188[50431f8]: 2998a00:mail.mailasail.com:A:CreateNewLineFromSocket: 8 OK [READ-WRITE] Ok

5188[50431f8]: 2998a00:mail.mailasail.com:S-INBOX.Drafts:SendData: 9 UID fetch 1:* (FLAGS)

5188[50431f8]: ReadNextLine [stream=2e682c8 nb=35 needmore=0] 5188[50431f8]: 2998a00:mail.mailasail.com:S-INBOX.Drafts:CreateNewLineFromSocket: * 1 FETCH (UID 120 FLAGS (\Seen))

5188[50431f8]: ReadNextLine [stream=2e682c8 nb=35 needmore=0] 5188[50431f8]: 2998a00:mail.mailasail.com:S-INBOX.Drafts:CreateNewLineFromSocket: * 2 FETCH (UID 121 FLAGS (\Seen))

5188[50431f8]: ReadNextLine [stream=2e682c8 nb=35 needmore=0] 5188[50431f8]: 2998a00:mail.mailasail.com:S-INBOX.Drafts:CreateNewLineFromSocket: * 3 FETCH (UID 184 FLAGS (\Seen)) .... .... ....

5188[50431f8]: ReadNextLine [stream=2e682c8 nb=54 needmore=0] 5188[50431f8]: 2998a00:mail.mailasail.com:S-INBOX.Drafts:CreateNewLineFromSocket: * 102 FETCH (UID 1214 FLAGS (\Draft \Seen \Deleted))

5188[50431f8]: ReadNextLine [stream=2e682c8 nb=54 needmore=0] 5188[50431f8]: 2998a00:mail.mailasail.com:S-INBOX.Drafts:CreateNewLineFromSocket: * 103 FETCH (UID 1215 FLAGS (\Draft \Seen \Deleted))

5188[50431f8]: ReadNextLine [stream=2e682c8 nb=54 needmore=0] 5188[50431f8]: 2998a00:mail.mailasail.com:S-INBOX.Drafts:CreateNewLineFromSocket: * 104 FETCH (UID 1216 FLAGS (\Draft \Seen \Deleted))

5188[50431f8]: ReadNextLine [stream=2e682c8 nb=23 needmore=0] 5188[50431f8]: 2998a00:mail.mailasail.com:S-INBOX.Drafts:CreateNewLineFromSocket: 9 OK FETCH completed.

5188[50431f8]: 2998a00:mail.mailasail.com:S-INBOX.Drafts:SendData: 10 append "INBOX.Drafts" (\Seen \Draft) {598+}

5188[50431f8]: 2998a00:mail.mailasail.com:S-INBOX.Drafts:SendData: FCC: imap://mailasail%40mailasail.com@mail.mailasail.com/INBOX/Sent Items

X-Identity-Key: id1

Message-ID: 46E89188.2030008@mailasail.com

Date: Thu, 13 Sep 2007 02:25:28 +0100

From: Ed W xxx@mailasail.com

X-Mozilla-Draft-Info: internal/draft; vcard=0; receipt=0; uuencode=0

User-Agent: Thunderbird 2.0.0.6 (Windows/20070728)

MIME-Version: 1.0

5188[50431f8]: 2998a00:mail.mailasail.com:S-INBOX.Drafts:SendData:

5188[50431f8]: ReadNextLine [stream=2e682c8 nb=49 needmore=0] 5188[50431f8]: 2998a00:mail.mailasail.com:S-INBOX.Drafts:CreateNewLineFromSocket: 10 NO Error in IMAP command received by server.

Ed W

4:31 a.m.

# dovecot -n

# 1.0.5: /etc/dovecot/dovecot.conf base_dir: /var/run/dovecot/ protocols: imap imaps pop3 pop3s listen: [87.106.95.71] ssl_cert_file: /etc/ssl/dovecot/server.pem ssl_key_file: /etc/ssl/dovecot/server.key disable_plaintext_auth: no login_dir: /var/run/dovecot//login login_executable(default): /usr/libexec/dovecot/imap-login login_executable(imap): /usr/libexec/dovecot/imap-login login_executable(pop3): /usr/libexec/dovecot/pop3-login login_greeting: MailASail Mail Server Ready. login_max_processes_count: 256 verbose_proctitle: yes mail_extra_groups: mail mail_location: mbox:/var/spool/mail/%u:INDEX=/var/dovecot/%u maildir_copy_with_hardlinks: yes maildir_copy_preserve_filename: yes mail_executable(default): /usr/libexec/dovecot/imap mail_executable(imap): /usr/libexec/dovecot/imap mail_executable(pop3): /usr/libexec/dovecot/pop3 mail_plugin_dir(default): /usr/lib/dovecot/imap mail_plugin_dir(imap): /usr/lib/dovecot/imap mail_plugin_dir(pop3): /usr/lib/dovecot/pop3 imap_client_workarounds(default): outlook-idle tb-extra-mailbox-sep imap_client_workarounds(imap): outlook-idle tb-extra-mailbox-sep imap_client_workarounds(pop3): outlook-idle pop3_uidl_format(default): pop3_uidl_format(imap): pop3_uidl_format(pop3): UID%u-%v pop3_client_workarounds(default): pop3_client_workarounds(imap): pop3_client_workarounds(pop3): outlook-no-nuls oe-ns-eoh namespace: type: private separator: . prefix: INBOX. inbox: yes auth default: mechanisms: plain login verbose: yes passdb: driver: sql args: /etc/dovecot/dovecot-sql.conf userdb: driver: prefetch userdb: driver: sql args: /etc/dovecot/dovecot-sql.conf socket: type: listen client: path: /var/spool/postfix/private/auth mode: 432 user: postfix group: postfix

Ed W

4:50 a.m.

...

5188[50431f8]: 2998a00:mail.mailasail.com:S-INBOX.Drafts:SendData:

5188[50431f8]: ReadNextLine [stream=2e682c8 nb=49 needmore=0] 5188[50431f8]: 2998a00:mail.mailasail.com:S-INBOX.Drafts:CreateNewLineFromSocket: 10 NO Error in IMAP command received by server.

I just tried this connecting back to the server *without* the proxy inline and it works perfectly - debug log is almost identical except for the last line which reads:

5220[5dbc968]: 571ab90:localhost:S-INBOX.Drafts:CreateNewLineFromSocket: 8 OK [APPENDUID 1006384217 224] APPEND Ok.

Could it be that Dovecot is returning the error due to some problem with the way it's parsing the request or is dovecot strictly proxying the traffic backwards and forwards? (In which case could it be mangling the stream in some way which causes the remove to error?)

Grateful for any help debugging

Ed W

5:45 a.m.

New subject: [Dovecot] Proxying very broken with (breaks?) Thunderbird and IMAP?

Tried sending a message with an attachment and Thunderbird simply continually loops, logging in, doing something, logging in, doing something, etc

The TB log from the bottom of one email (which doesn't appear to finish) to the start of the next loop is below. Can someone translate for me please?

(mime attachment starts...)

i554bCmklxjsFNj7Hin/ALVD/NKnViYLHbrsgPA12gESqkJ1FoIGvKk3lxSKTeHFGJuypPmZ

4544[534ae38]: Db7dzBDWja34Kplj9HjN8S4/iEQRqY1hDydbcVh8J+9ys9Ibu6hSP5Ur0DDGgXB9Bbu6jX5S

fwXfYg0Ckh182SGyP62P2dHyfMBv4QvKb/pL0/66P29JuH7z4/Fq8vv+kr9fCIENnCInL 4544[534ae38]: 2997d28:mail.mailasail.com:A:SendData: clearing IMAP_CONNECTION_IS_OPEN 4544[534ae38]: 2997d28:mail.mailasail.com:A:TellThreadToDie: close socket connection 4544[534ae38]: 2997d28:mail.mailasail.com:A:SendData: clearing IMAP_CONNECTION_IS_OPEN 4544[534ae38]: 2997d28:mail.mailasail.com:A:TellThreadToDie: close socket connection 4544[534ae38]: 2997d28:mail.mailasail.com:A:SendData: clearing IMAP_CONNECTION_IS_OPEN 4544[534ae38]: 2997d28:mail.mailasail.com:A:TellThreadToDie: close socket connection 4544[534ae38]: 2997d28:mail.mailasail.com:A:SendData: clearing IMAP_CONNECTION_IS_OPEN 4544[534ae38]: 2997d28:mail.mailasail.com:A:TellThreadToDie: close socket connection 4544[534ae38]: 2997d28:mail.mailasail.com:A:SendData: clearing IMAP_CONNECTION_IS_OPEN 4544[534ae38]: 2997d28:mail.mailasail.com:A:TellThreadToDie: close socket connection 4544[534ae38]: 2997d28:mail.mailasail.com:A:SendData: clearing IMAP_CONNECTION_IS_OPEN 4544[534ae38]: 2997d28:mail.mailasail.com:A:TellThreadToDie: close socket connection 4544[534ae38]: 2997d28:mail.mailasail.com:A:SendData: clearing IMAP_CONNECTION_IS_OPEN 4544[534ae38]: 2997d28:mail.mailasail.com:A:TellThreadToDie: close socket connection 4544[534ae38]: 2997d28:mail.mailasail.com:A:SendData: clearing IMAP_CONNECTION_IS_OPEN 4544[534ae38]: 2997d28:mail.mailasail.com:A:TellThreadToDie: close socket connection 4544[534ae38]: 2997d28:mail.mailasail.com:A:SendData: clearing IMAP_CONNECTION_IS_OPEN 4544[534ae38]: 2997d28:mail.mailasail.com:A:TellThreadToDie: close socket connection 4544[534ae38]: 2997d28:mail.mailasail.com:A:SendData: clearing IMAP_CONNECTION_IS_OPEN 4544[534ae38]: 2997d28:mail.mailasail.com:A:TellThreadToDie: close socket connection 4544[534ae38]: 2997d28:mail.mailasail.com:A:SendData: clearing IMAP_CONNECTION_IS_OPEN 4544[534ae38]: 2997d28:mail.mailasail.com:A:TellThreadToDie: close socket connection 4544[534ae38]: 2997d28:mail.mailasail.com:A:SendData: clearing IMAP_CONNECTION_IS_OPEN 4544[534ae38]: 2997d28:mail.mailasail.com:A:TellThreadToDie: close socket connection 4544[534ae38]: 2997d28:mail.mailasail.com:A:SendData: clearing IMAP_CONNECTION_IS_OPEN 4544[534ae38]: 2997d28:mail.mailasail.com:A:TellThreadToDie: close socket connection 4544[534ae38]: 2997d28:mail.mailasail.com:A:SendData: clearing IMAP_CONNECTION_IS_OPEN 4544[534ae38]: 2997d28:mail.mailasail.com:A:TellThreadToDie: close socket connection 4544[534ae38]: 2997d28:mail.mailasail.com:A:SendData: clearing IMAP_CONNECTION_IS_OPEN 4544[534ae38]: 2997d28:mail.mailasail.com:A:TellThreadToDie: close socket connection 4544[534ae38]: 2997d28:mail.mailasail.com:A:SendData: clearing IMAP_CONNECTION_IS_OPEN 4544[534ae38]: 2997d28:mail.mailasail.com:A:TellThreadToDie: close socket connection 4544[534ae38]: 2997d28:mail.mailasail.com:A:SendData: clearing IMAP_CONNECTION_IS_OPEN 4544[534ae38]: 2997d28:mail.mailasail.com:A:TellThreadToDie: close socket connection 4544[534ae38]: 2997d28:mail.mailasail.com:A:SendData: clearing IMAP_CONNECTION_IS_OPEN 4544[534ae38]: 2997d28:mail.mailasail.com:A:TellThreadToDie: close socket connection 4544[534ae38]: 2997d28:mail.mailasail.com:A:SendData: clearing IMAP_CONNECTION_IS_OPEN 4544[534ae38]: 2997d28:mail.mailasail.com:A:TellThreadToDie: close socket connection 4544[534ae38]: 2997d28:mail.mailasail.com:A:SendData: clearing IMAP_CONNECTION_IS_OPEN 4544[534ae38]: 2997d28:mail.mailasail.com:A:TellThreadToDie: close socket connection 4544[534ae38]: 2997d28:mail.mailasail.com:A:SendData: clearing IMAP_CONNECTION_IS_OPEN 4544[534ae38]: 2997d28:mail.mailasail.com:A:TellThreadToDie: close socket connection 4544[534ae38]: 2997d28:mail.mailasail.com:A:SendData: clearing IMAP_CONNECTION_IS_OPEN 4544[534ae38]: 2997d28:mail.mailasail.com:A:TellThreadToDie: close socket connection 4544[534ae38]: 2997d28:mail.mailasail.com:A:SendData: clearing IMAP_CONNECTION_IS_OPEN 4544[534ae38]: 2997d28:mail.mailasail.com:A:TellThreadToDie: close socket connection 4544[534ae38]: 2997d28:mail.mailasail.com:A:SendData: clearing IMAP_CONNECTION_IS_OPEN 4544[534ae38]: 2997d28:mail.mailasail.com:A:TellThreadToDie: close socket connection 4544[534ae38]: 2997d28:mail.mailasail.com:A:SendData: clearing IMAP_CONNECTION_IS_OPEN 4544[534ae38]: 2997d28:mail.mailasail.com:A:TellThreadToDie: close socket connection 4544[534ae38]: 2997d28:mail.mailasail.com:A:SendData: clearing IMAP_CONNECTION_IS_OPEN 4544[534ae38]: 2997d28:mail.mailasail.com:A:TellThreadToDie: close socket connection 0[1850b80]: creating protocol instance to retry queued url:imap://mailasail@mailasail.com@mail.mailasail.com:143/appendmsgfromfile>.INBOX.Sent Items 0[1850b80]: retrying
url:imap://mailasail@mailasail.com@mail.mailasail.com:143/appendmsgfromfile>.INBOX.Sent Items 0[1850b80]: 571daa8:mail.mailasail.com:NA:SetupWithUrl: clearing IMAP_CONNECTION_IS_OPEN 1952[534bd98]: ImapThreadMainLoop entering [this=571daa8] 4544[534ae38]: ImapThreadMainLoop leaving [this=2997d28] 1952[534bd98]: 571daa8:mail.mailasail.com:NA:ProcessCurrentURL: entering 1952[534bd98]: 571daa8:mail.mailasail.com:NA:ProcessCurrentURL:imap://mailasail%40mailasail%2Ecom@mail.mailasail.com:143/appendmsgfromfile%3E.INBOX.Sent%20Items:
= currentUrl 1952[534bd98]: ReadNextLine [stream=63c2ee0 nb=35 needmore=0] 1952[534bd98]: 571daa8:mail.mailasail.com:NA:CreateNewLineFromSocket: * OK MailASail Mail Server Ready.

1952[534bd98]: 571daa8:mail.mailasail.com:NA:SendData: 1 capability

1952[534bd98]: ReadNextLine [stream=63c2ee0 nb=156 needmore=0] 1952[534bd98]: 571daa8:mail.mailasail.com:NA:CreateNewLineFromSocket: * CAPABILITY IMAP4rev1 SASL-IR SORT THREAD=REFERENCES MULTIAPPEND UNSELECT LITERAL+ IDLE CHILDREN NAMESPACE LOGIN-REFERRALS STARTTLS AUTH=PLAIN AUTH=LOGIN

1952[534bd98]: ReadNextLine [stream=63c2ee0 nb=28 needmore=0] 1952[534bd98]: 571daa8:mail.mailasail.com:NA:CreateNewLineFromSocket: 1 OK Capability completed.

1952[534bd98]: 571daa8:mail.mailasail.com:NA:SendData: 2 authenticate plain

1952[534bd98]: ReadNextLine [stream=63c2ee0 nb=4 needmore=0] 1952[534bd98]: 571daa8:mail.mailasail.com:NA:CreateNewLineFromSocket: +

1952[534bd98]: 571daa8:mail.mailasail.com:NA:SendData: Logging suppressed for this command (it probably contained authentication information) 1952[534bd98]: ReadNextLine [stream=63c2ee0 nb=0 needmore=1] 1952[534bd98]: ReadNextLine [stream=63c2ee0 nb=16 needmore=0] 1952[534bd98]: 571daa8:mail.mailasail.com:NA:CreateNewLineFromSocket: 2 OK LOGIN Ok.

1952[534bd98]: 571daa8:mail.mailasail.com:A:SendData: 3 append "INBOX.Sent Items" (\Seen) {473162+}

1952[534bd98]: 571daa8:mail.mailasail.com:A:SendData: Message-ID: 46E8A2C6.1070807@mailasail.com

Date: Thu, 13 Sep 2007 03:39:02 +0100

From: Ed W xxx@mailasail.com

User-Agent: Thunderbird 2.0.0.6 (Windows/20070728)

MIME-Version: 1.0

To: Ayyy info@xxx.se

Subject: Re: xxxx

Timo Sirainen

15 Sep 15 Sep

4:28 p.m.

On Thu, 2007-09-13 at 02:29 +0100, Ed W wrote:

...

5188[50431f8]: 2998a00:mail.mailasail.com:S-INBOX.Drafts:SendData: 10 append "INBOX.Drafts" (\Seen \Draft) {598+} .. 2998a00:mail.mailasail.com:S-INBOX.Drafts:CreateNewLineFromSocket: 10 NO Error in IMAP command received by server.

IIRC Courier doesn't support LITERAL+ extension, but Thunderbird is trying to use it there anyway ("+" in {598+}). Are you sure there's no LITERAL+ advertised in CAPABILITY reply? If not, TB must have seen it at some point and cached it. Maybe some kind of account cache flush/recreation fixes it.

HenkJan Wolthuis

13 Sep 13 Sep

10:06 a.m.

Hi,

...

I am trying to do a staged migration over to dovecot, but having troubles at the first hurdle. I setup the proxy feature to redirect most of our users back to the current Courier imap/pop server, and it's partly working, but I'm getting Maybe your courier server doesn't support some extensions that dovecot advertises in its CAPABILITY response, we solved some problems in a similar setup by making sure that dovecot sends the same capability as courier. (it's configurable in the config file)

success,

henkjan

Ed W

10:28 a.m.

HenkJan Wolthuis wrote:

...

Hi,

...
I am trying to do a staged migration over to dovecot, but having troubles at the first hurdle. I setup the proxy feature to redirect most of our users back to the current Courier imap/pop server, and it's partly working, but I'm getting Maybe your courier server doesn't support some extensions that dovecot advertises in its CAPABILITY response, we solved some problems in a similar setup by making sure that dovecot sends the same capability as courier. (it's configurable in the config file)

No, I already checked that the only capability results are the ones from Courier (Remember that it's breaking under the Proxy setup, the capability results come directly from Courier, I don't have banner capabilities on either)

Also, if you look at the two log files (or what I posted of them), then they look identical in working and non working cases. I would hazard a guess that some line breaks are getting swapped, hence breaking the length? I don't have more than a working knowledge of IMAP, but would that explain why I am getting an error from a valid looking APPEND command?

Ed W

6278

Age (days ago)

6280

Last active (days ago)

List overview

8 comments

4 participants

participants (4)

Ed W
HenkJan Wolthuis
Timo Sirainen
Troy Engel