[Dovecot] Misbehavior with Dovecot and Mulberry
I'm having a bit of misbehavior wherein Dovecot seems to refuse to cooperate with my Mulberry MUA. By and large, everything works great.
I can move mail back and forth happily. I can compose a note and copy the outgoing mail to my Dovecot "Sent" folder using my default Mulberry settings. But if I reply or forward a mail, I get a Mulberry error popup saying that it "couldn't decode the response from the server" and that the operation was unsuccessful.
This was somewhat mystifying (especially since this does work for a newly composed message as opposed to a reply/forward), so I turned on Mulberry logging.
This is what I see (with unrelated operations clipped from the log).
First, the first case where I create a new message, send it, and save a copy in my Sent folder:
--> #6.3408 Mon Sep 5 23:24:27 2005
A00085 APPEND Sent (\Seen) {418+}
* 5544 EXISTS
* 1 RECENT
A00085 OK Append completed.All's well there. Mulberry does a FETCH to grab the new message (reply) from my Sent folder and then does a SORT so that it can order it properly in the display. This too succeeds but is probably irrelevant to us.
After a couple NOOP commands come and go in the background, I try to reply to a message in one of my mailboxes. In this case it happens to be the one in my Sent folder.
So Mulberry issues a FETCH (you can see the original mail there in the FETCH response from Dovecot). It then does a STORE of the original mail, apparently to update the \Answered flag.
It then tries to APPEND the reply to the Sent folder, but this time, the server comes back with a NO. See below
--> #6.3408 Mon Sep 5 23:24:43 2005
A00089 FETCH 5544 (BODY[1])
* 5544 FETCH (BODY[1] {63}
)
A00089 OK Fetch completed.
--> #6.3408 Mon Sep 5 23:25:13 2005
A00090 FETCH 5544 (RFC822.HEADER)
* 5544 FETCH (RFC822.HEADER {355}
Date: Mon, 05 Sep 2005 23:24:27 -0500
From: Jon Roma <roma@uiuc.edu>
To: Jon R Roma <roma@uiuc.edu>
Subject: Test 1
Message-ID: <DDDD999F0F4E38F8C1510CC8@jrr2.isdn.uiuc.edu>
X-Mailer: Mulberry/3.1.6 (Win32)
MIME-Version: 1.0
Content-Type: text/plain; charset=us-ascii; format=flowed
Content-Transfer-Encoding: 7bit
Content-Disposition: inline
)
A00090 OK Fetch completed.
--> #6.3408 Mon Sep 5 23:25:13 2005
A00091 STORE 5544 +FLAGS (\Answered)
* 5544 FETCH (FLAGS (\Answered \Seen \Recent))
A00091 OK Store completed.
--> #6.3408 Mon Sep 5 23:25:13 2005
A00092 APPEND Sent (\Seen) {610+}
A00092 NOI am having similar problem saving a draft to my Drafts folder and suspect the same thing is behind both of these. I didn't create a Mulberry trace log for this but can do so if need be.
I am running 1.0-test80 with Timo's patch to fix the "time off by 200 minutes" error with mbox. All my folders are maildir at this point -- I've converted them out of my UW mbx format store. My client is Mulberry 3.1.6 for Windows and the OS is AIX 5.1.
This weird behavior is a mystery to me!
On Mon, 2005-09-05 at 23:57 -0500, Jon Roma wrote:
That happens if some function returned -1 but didn't set any error. Shouldn't happen..
So, they are maildirs? Do these changes help: Index: src/imap/cmd-append.c =================================================================== RCS file: /var/lib/cvs/dovecot/src/imap/cmd-append.c,v retrieving revision 1.64 retrieving revision 1.65 diff -u -r1.64 -r1.65 --- src/imap/cmd-append.c 28 Jun 2005 11:15:57 -0000 1.64 +++ src/imap/cmd-append.c 18 Sep 2005 16:58:01 -0000 1.65 @@ -292,8 +292,7 @@ int failed; if (ctx->save_ctx != NULL) { - if (mailbox_save_continue(ctx->save_ctx) < 0 || - client->input->closed) { + if (mailbox_save_continue(ctx->save_ctx) < 0) { /* we still have to finish reading the message from client */ mailbox_save_cancel(ctx->save_ctx); Index: src/lib-storage/index/maildir/maildir-save.c =================================================================== RCS file: /var/lib/cvs/dovecot/src/lib-storage/index/maildir/maildir-save.c,v retrieving revision 1.57 retrieving revision 1.58 diff -u -r1.57 -r1.58 --- src/lib-storage/index/maildir/maildir-save.c 14 Aug 2005 19:02:54 -0000 1.57 +++ src/lib-storage/index/maildir/maildir-save.c 18 Sep 2005 16:58:31 -0000 1.58 @@ -217,6 +217,10 @@ return -1; if (o_stream_send_istream(ctx->output, ctx->input) < 0) { + mail_storage_set_critical(STORAGE(ctx->mbox->storage), + "o_stream_send_istream(%s) failed: %m", + t_strconcat(ctx->tmpdir, "/", + ctx->files->basename, NULL)); ctx->failed = TRUE; return -1; }
Timo Sirainen <tss@iki.fi> wrote:
Timo: Yes, my mailboxes are maildirs. Your patch seems to have fixed the problem -- I can now append outgoing mail to a Dovecot maildir 'Sent' mailbox as it gets sent. And I can now also save a draft in my Dovecot maildir 'Drafts' mailbox when desired. What this means is that I no longer need UW (Yay!) -- I was saving my outgoing mail and drafts in a skeletal UW tree pending resolution of this problem. There is still an anomaly when using the Mulberry client to move mail from the UW tree to Dovecot (which I now want to do in preparation for getting rid of UW imapd. Using Mulberry to move mail from UW to Dovecot only works with some messages and not others. Maybe this is not important -- I can slurp my last two UW mboxes into a Dovecot namespace and then move them as desired into the default namespace. But perhaps this behavior is something you are interested in -- here's the transcript on the client side. First a copy/move that succeeded. I am in the source folder (under UW) and have chosen a message that I want to move to the Dovecot 'Sent' folder is the destination. --> #25.2768 Sun Sep 18 13:10:26 2005 A00145 FETCH 170 (BODY[1]) * 170 FETCH (BODY[1] {280} ) A00145 OK FETCH completed --> #1.2768 Sun Sep 18 13:10:34 2005 A00010 APPEND Sent (\Seen) "15-Sep-2005 18:00:43 -0500" {813+} --> #25.2768 Sun Sep 18 13:10:34 2005 A00146 FETCH 170 (BODY.PEEK[]) * 170 FETCH (BODY[] {813} ) A00146 OK FETCH completed A00010 OK Append completed. --> #1.2768 Sun Sep 18 13:10:35 2005 A00011 STATUS Sent (MESSAGES RECENT UNSEEN UIDVALIDITY UIDNEXT) * STATUS "Sent" (MESSAGES 5547 RECENT 1 UIDNEXT 5552 UIDVALIDITY 1125869336 UNSEEN 0) A00011 OK Status completed. --> #25.2768 Sun Sep 18 13:10:35 2005 A00147 STORE 170 +FLAGS (\Deleted) * 170 FETCH (FLAGS (\Seen \Deleted)) A00147 OK STORE completed This move succeeded. Now I choose a different message in Mulberry and try to do the same move operation. This one fails. --> #25.2768 Sun Sep 18 13:10:35 2005 A00148 FETCH 171 (BODY[1]) * 171 FETCH (BODY[1] {268} ) A00148 OK FETCH completed --> #1.2768 Sun Sep 18 13:10:44 2005 A00012 APPEND Sent (\Seen) "15-Sep-2005 19:52:14 -0500" {832+} --> #25.2768 Sun Sep 18 13:10:44 2005 A00149 FETCH 171 (BODY.PEEK[]) * 171 FETCH (BODY[] {832} ) A00149 OK FETCH completed A00012 NO Internal error occurred. Refer to server log for more information. [2005-09-18 13:10:44] The corresponding syslog message is Sep 18 13:10:44 zippy dovecot: IMAP(roma): o_stream_send_istrea (/var/imap/dovecot/roma/.Sent/tmp/1127067044.P44216Q3.zippy.cso.uiuc.edu) failed: Invalid argument Maybe this isn't important, but I send it in case you think it's something you want to look at. I'll leave the relevant mailbox around so I can try this again if necessary. Thanks for the patch!
On Sun, 2005-09-18 at 13:28 -0500, Jon Roma wrote:
Well, that's a bit strange since I didn't expect it to fix it. Except if Mulberry works by closing the connection immediately after appending the mail..
This is actually what I was hoping to see instead. Do you have HAVE_FREEBSD_SENDFILE, HAVE_LINUX_SENDFILE or HAVE_SOLARIS_SENDFILE defined in config.h?
On Sun, 2005-09-18 at 14:07 -0500, Jon Roma wrote:
Well, that doesn't help since this problem is internal to Dovecot. I just can't figure out why it would happen. Do you have mail_save_crlf=yes?
Can you run gdb? Or could you try the attached patch and see what it prints to logs when this error happens?
I do not have 'mail_safe_crlf' set -- my configuration changes very few of the defaults, and uses the default 'no' for this setting.
I don't have gcc/gdb on the box in question, but I will try the patch later today and will report further. The problem is at least easy to reproduce!
Thanks.
Timo Sirainen <tss@iki.fi> wrote:
Timo Sirainen <tss@iki.fi> wrote:
OK, I've applied your debug patch and have the following to report:
Result of telling Mulberry to file a copy of an outgoing mail into my Dovecot 'Sent' folder:
Sep 25 17:19:18 zippy dovecot: imap-login: Login: user=<roma>, method=PLAIN, rip=192.17.16.93, lip=130.126.113.16, TLS Sep 25 17:19:25 zippy dovecot: imap(roma): o_stream_sendv() -> EINVAL Sep 25 17:19:25 zippy dovecot: imap(roma): o_stream_send_istream(/var/imap/dovecot/roma/.Sent/tmp/1127686765.P17140Q0M417376.zippy.cso.uiuc.edu) failed: Invalid argument
When asking Mulberry to save a draft mail into my Dovecot 'Drafts' folder, it was a bit more interesting. Creating a new draft saved just fine. However, taking an existing draft, editing it and then re-saving it gave the usual error. (Note that doing this in Mulberry creates a new message in the 'Drafts' folder rather than overwriting the earlier draft.)
Anyway, here are the log messages resulting from *this* operation with a draft.
Sep 25 17:23:28 zippy dovecot: imap-login: Login: user=<roma>, method=PLAIN, rip=192.17.16.93, lip=130.126.113.16, TLS Sep 25 17:23:29 zippy dovecot: imap(roma): o_stream_sendv() -> EINVAL Sep 25 17:23:29 zippy dovecot: imap(roma): o_stream_send_istream(/var/imap/dovecot/roma/.Drafts/tmp/1127687009.P26994Q0M217945.zippy.cso.uiuc.edu) failed: Invalid argument
Incidentally, as you can tell from the log messages, these are all maildir folders. However, I experimented and got the same errors using mbox folders as well.
Before running these tests I upgraded from -test80 to alpha3.
Hope this helps. Thanks.
On 26.9.2005, at 01:36, Jon Roma wrote:
Sep 25 17:19:25 zippy dovecot: imap(roma): o_stream_sendv() -> EINVAL
OK, so it must be writev() call that's failing.
Have you HAVE_WRITEV and HAVE_STRUCT_IOVEC defined in config.h? If yes, try removing HAVE_WRITEV so Dovecot uses write() instead internally. Also if you compile and run this, what does it say:
#include <sys/uio.h> #include <stdio.h>
int main(void) { struct iovec iov; printf("%d %d %d\n", sizeof(iov), sizeof(iov.iov_base), sizeof(iov.iov_len)); return 0; }
Timo Sirainen <tss@iki.fi> wrote:
Timo:
Your speed amazes me. :-)
Both HAVE_WRITEV and HAVE_STRUCT_IOVEC are defined in config.h. The platform is AIX 5.1 -- forgot to mention that in my most recent post.
The compile/run of the test program yields the following results:
3243: cc -o test_writev test_writev.c 3244: ./test_writev 8 4 4
If this doesn't tell you anything, I'll manually disable those two HAVE_ settings from config.h and rebuild/reinstall.
Thanks!
On Sun, 2005-09-25 at 18:00 -0500, Jon Roma wrote:
So it's a 32bit system?
If this doesn't tell you anything, I'll manually disable those two HAVE_ settings from config.h and rebuild/reinstall.
Remove only HAVE_WRITEV. Removing HAVE_STRUCT_IOVEC probably just gives errors.
Timo Sirainen <tss@iki.fi> wrote:
The hardware is 32-bit and the machine is running the 32-bit kernel, though the same OS has a 64-bit version that runs on newer hardware, with binary compatibility for old executables.
More is at
<http://www.developer.ibm.com/isv/tech/faq/individual?oid=2:79647>and (fluffy marketing stuff) at
<http://www-03.ibm.com/servers/aix/os/51spec.html>The AIX man page for write/writev, etc. is at
<http://publibn.boulder.ibm.com/doc_link/en_US/a_doc_lib/libs/basetrf2/write.htm>
Now, re-reading this man page and looking through the include files gives me an idea what is happening.
Dovecot, in file src/lib/ostream-file.c, is using the UIO_MAXIOV preprocessor variable to determine how many iovec objects can be handed to the writev(2) system call.
Now, the AIX 5.1 man page says that the maximum vector count must be less than IOV_MAX, which AIX defines as 16 in <sys/limits.h> and <sys/uio.h>. And the call returns EINVAL if the vector count is zero or >= 16.
AIX does define UIO_MAXIOV in <sys/socket.h> at 1024 -- not sure what this variable is supposed to mean under AIX given the writev(2) says it uses IOV_MAX instead. Anyway since Dovecot is using this value, it's not hard to see why it's getting EINVAL errors when the underlying system only allows a vector count < 16.
For a comparison, I looked on another system (running Red Hat Enterprise Linux 3), and it gets even more murky.
The Linux man page for writev(2) says that the vector count must be between 0 and MAX_IOVEC. MAX_IOVEC is defined as 10 in <linux/sunrpc/xprt.h>, which doesn't seem a logical place for it. Anyway, on RHEL 3, UIO_MAXIOV is defined in <linux/uio.h> and <bits/uio.h> and IOV_MAX is defined in <bits/stdio_lim.h> -- and is defined as 1024 in these definitions. There's also a _POSIX_UIO_MAXIOV defined at 16 in <bits/posix1_lim.h>.
My suspicion is that the Linux man page is wrong with respect to the preprocessor variable that matters.
I have also looked at Solaris 9 system. The man page is at
<http://docs.sun.com/app/docs/doc/816-5167/6mbb2jama?a=view>
and it like AIX refers to IOV_MAX (which is defined in <limits.h>. In fact Solaris doesn't have *any* definition for UIO_MAXIOV.
So I wonder if IOV_MAX is the better or more portable way to make this work, and that some of this worked by coincidence because UIO_MAXIOV and IOV_MAX happened to be the same on Linux, which is probably the most common platform people have tested on.
Since Dovecot, in src/lib/ostream-file.c, defines UIO_MAXIOV as 16 for any system (like Solaris) which doesn't have that variable defined, this all works fine on that platform too.
Anyway, I think this all looks promising and I'll throw together a patch after dinner to see if it fixes the weirdness for me. I'll let you know how it goes later tonight.
Of course I could just manually unset HAVE_WRITEV as you suggested in your debugging hints, but I'm sure being able to use the native writev(2) would be more efficient and thus preferable.
--On Monday, September 26, 2005 7:58 PM -0500 Jon Roma <roma@uiuc.edu> wrote:
I poked around in glibc and kernel sources (FC2) and found UIO_MAXIOV and IOV_MAX are the two symbols in use and are set to 1024. Googling for these two symbols together turned up this interesting nugget:
<http://lists.freebsd.org/pipermail/freebsd-standards/2004-February/000399.html>
The search:
<http://www.google.com/search?num=100&hl=en&lr=&safe=off&c2coff=1&q=uio_maxiov+iov_max&btnG=Search>
The glibc code looks like in some circumstances it mallocs a temporary buffer to assemble the write and then issues a write() on the temporary. Additionally, each filesystem driver gets a chance to independently choose how to implement writev, with many passing it to a generic version of the function.
Kenneth Porter <shiva@sewingwitch.com> wrote:
Kenneth:
Thank you for providing that bit of information, which helps clear things up a bit. Though I'm a long-time UNIX guy, I've not got that much in the way of experience with Linux and the modern *BSD flavors. So this helps me get the feeling that I was on the right track.
Timo:
I found eight references to UIO_MAXIOV in src/lib/ostream-file.c and changed all to IOV_MAX. I cleaned, rebuilt, and installed -- happily, the previously-reported EINVAL errors are now gone!
Trivial patch attached.
participants (3)
-
Jon Roma
-
Kenneth Porter
-
Timo Sirainen