[Dovecot] Managesieve fails to retrieve scripts > 8kB on Dovecot 1.1.16
After some help with debugging tips on #dovecot, I have established that a sieve script on Dovecot 1.1.16 has to be less than 8kB in order to be retrieved by a managesieve client. I have been using managesieve for about 6 months over as many 1.1.n versions of dovecot as have been around during that time and hit this problem when I upgraded to Dovecot 1.1.16. I have gone back to Dovecot 1.1.15 and can once again manage my 9kB sieve script remotely.
Symptoms were that managesieve login was OK but instead of displaying my sieve script, the script editing window was empty. After 30 seconds the client gave me a timeout message. If I entered a small script in the empty client edit window and saved it, the new, small script was saved to the server and became active. I could then successfully retrieve and edit that small script.
I tried hacking a few lines at a time out of my 9kB script (locally on the server). When it was down to 8.4KB I still couldn't get it through managesieve. The next hack took it down to 7.7kB and I could get that through managesieve. So, I'm guessing there's a magic 8192 number in there somewhere - perhaps a buffer?
Server dovecot 1.1.16 dovecot-sieve 1.1.6 dovecot-managesieve 0.10.6 FreeBSD 7.2
Client Thunderbird 2.0.21 Sieve 0.1.6
A special thanks to all who write this stuff: it's great!
-- John Marshall
John Marshall schreef:
After some help with debugging tips on #dovecot, I have established that a sieve script on Dovecot 1.1.16 has to be less than 8kB in order to be retrieved by a managesieve client. I have been using managesieve for about 6 months over as many 1.1.n versions of dovecot as have been around during that time and hit this problem when I upgraded to Dovecot 1.1.16. I have gone back to Dovecot 1.1.15 and can once again manage my 9kB sieve script remotely.
Symptoms were that managesieve login was OK but instead of displaying my sieve script, the script editing window was empty. After 30 seconds the client gave me a timeout message. If I entered a small script in the empty client edit window and saved it, the new, small script was saved to the server and became active. I could then successfully retrieve and edit that small script.
I tried hacking a few lines at a time out of my 9kB script (locally on the server). When it was down to 8.4KB I still couldn't get it through managesieve. The next hack took it down to 7.7kB and I could get that through managesieve. So, I'm guessing there's a magic 8192 number in there somewhere - perhaps a buffer?
I cannot reproduce your problem at my end with the given information. A 14 kb script is no problem here (tried with large comment and repetitive if statements). I am using the same client you have.
A few questions:
- What is your exact config (i.e. dovecot -n)
- Do the logs say anything? Segfault perhaps (signal 11) ?
- Could you provide (an anonymized version of) the script you are trying to upload? (Make sure the version you send me is problematic as well)
If it truly does hang at some point, you could use the strace tool to get an idea what it the managesieve daemon doing at that time. If you are not using TLS, you can use the ngrep tool to capture the TCP traffic between client and server. That may also prove useful.
Regards,
-- Stephan Bosch stephan@rename-it.nl
On Fri, 19 Jun 2009, 23:20 +0200, Stephan Bosch wrote:
John Marshall schreef:
Symptoms were that managesieve login was OK but instead of displaying my sieve script, the script editing window was empty. After 30 seconds the client gave me a timeout message. If I entered a small script in the empty client edit window and saved it, the new, small script was saved to the server and became active. I could then successfully retrieve and edit that small script.
I cannot reproduce your problem at my end with the given information. A 14 kb script is no problem here (tried with large comment and repetitive if statements). I am using the same client you have.
Thank you Stephen for looking at this. I have just uninstalled Dovecot 1.1.15 and re-built and installed Dovecot 1.1.16 and the problem is back.
- What is your exact config (i.e. dovecot -n)
# 1.1.16: /usr/local/etc/dovecot.conf
# OS: FreeBSD 7.2-RELEASE i386
protocols: imap imaps pop3 pop3s managesieve
listen: 192.0.2.1
ssl_listen: 192.0.2.1
ssl_ca_file: /usr/local/openssl/certs/example.CACERT.pem
ssl_cert_file: /usr/local/openssl/certs/mail.example.com.CERT.pem
ssl_key_file: /usr/local/openssl/private/mail.example.com.KEY.pem
login_dir: /var/run/dovecot/login
login_executable(default): /usr/local/libexec/dovecot/imap-login
login_executable(imap): /usr/local/libexec/dovecot/imap-login
login_executable(pop3): /usr/local/libexec/dovecot/pop3-login
login_executable(managesieve): /usr/local/libexec/dovecot/managesieve-login
verbose_proctitle: yes
first_valid_uid: 1234
last_valid_uid: 1234
first_valid_gid: 1234
last_valid_gid: 1234
mail_privileged_group: mail
mail_location: maildir:%h/Maildir
mail_debug(default): no
mail_debug(imap): no
mail_debug(pop3): no
mail_debug(managesieve): yes
maildir_copy_preserve_filename: yes
mail_executable(default): /usr/local/libexec/dovecot/imap
mail_executable(imap): /usr/local/libexec/dovecot/imap
mail_executable(pop3): /usr/local/libexec/dovecot/pop3
mail_executable(managesieve): /usr/local/libexec/dovecot/managesieve
mail_plugin_dir(default): /usr/local/lib/dovecot/imap
mail_plugin_dir(imap): /usr/local/lib/dovecot/imap
mail_plugin_dir(pop3): /usr/local/lib/dovecot/pop3
mail_plugin_dir(managesieve): /usr/local/lib/dovecot/managesieve
imap_client_workarounds(default): delay-newmail netscape-eoh tb-extra-mailbox-sep
imap_client_workarounds(imap): delay-newmail netscape-eoh tb-extra-mailbox-sep
imap_client_workarounds(pop3):
imap_client_workarounds(managesieve):
pop3_client_workarounds(default):
pop3_client_workarounds(imap):
pop3_client_workarounds(pop3): outlook-no-nuls oe-ns-eoh
pop3_client_workarounds(managesieve):
sieve_storage(default):
sieve_storage(imap):
sieve_storage(pop3):
sieve_storage(managesieve): %h/sieve
sieve(default):
sieve(imap):
sieve(pop3):
sieve(managesieve): %h/.dovecot.sieve
auth default:
mechanisms: gssapi gss-spnego plain
gssapi_hostname: mail.example.com
passdb:
driver: passwd-file
args: /path/to/password-file
userdb:
driver: static
args: uid=1234 gid=1234 home=/path/to/maildirs/%d/%n
socket:
type: listen
client:
path: /var/run/dovecot/auth-client
mode: 432
master:
path: /var/run/dovecot/auth-master
mode: 384
user: maildirs_owner
group: maildirs_group
plugin:
sieve: %h/.dovecot.sieve
- Do the logs say anything? Segfault perhaps (signal 11) ?
The logs show successful managesieve-login and then nothing.
- Could you provide (an anonymized version of) the script you are trying to upload? (Make sure the version you send me is problematic as well)
The problem is not uploading. The problem is downloading. If I copy my sieve script to my client (by other means) I can upload it fine. The problem is that the client cannot retrieve it from the server for editing if it is bigger than 8kB. Here is a sample "problem" script:
# This is a sieve script file full of comments <--- snip (above line repeated 200 times) ---> keep;
If I lose 26 of those 200 comment lines then I can download as well as upload the script.
If it truly does hang at some point, you could use the strace tool to get an idea what it the managesieve daemon doing at that time. If you are not using TLS, you can use the ngrep tool to capture the TCP traffic between client and server. That may also prove useful.
It doesn't "hang". The script edit window pops up empty and 30 seconds later I see pop-up dialogue box: window title is "Alert"; Text is "A Timeout occured". I click OK to acknowledge the timeout and then I can enter/upload a large or small script or import/edit/upload a large or small script.
I don't have ngrep but if you can suggest a useful incantation for tcpdump I can provide that for you.
I reverted to 1.1.15 and everything worked again; I upgraded to 1.1.16 and the problem returned - all without touching the config or sieve script or client. The Thunderbird/Sieve client, by the way, is on FreeBSD not Microsoft.
-- John Marshall
Hi John,
John Marshall wrote:
Thank you Stephan for looking at this. I have just uninstalled Dovecot 1.1.15 and re-built and installed Dovecot 1.1.16 and the problem is back.
- What is your exact config (i.e. dovecot -n)
# 1.1.16: /usr/local/etc/dovecot.conf # OS: FreeBSD 7.2-RELEASE i386
Nothing strange here. Pretty much the same as what I use for testing.
- Do the logs say anything? Segfault perhaps (signal 11) ?
The logs show successful managesieve-login and then nothing. Considering the fact that you have mail_debug turned on for ManageSieve, you should have seen something like the following:
Jun 21 12:07:35 host dovecot: managesieve-login: Login: user=<test>, method=PLAIN, rip=<ip>, lip=<ip>, TLS Jun 21 12:07:35 host dovecot: MANAGESIEVE(test): Effective uid=2002, gid=2002, home=/home/test Jun 21 12:07:35 host dovecot: MANAGESIEVE(test): sieve-storage: using active sieve script path: ~/.dovecot.sieve Jun 21 12:07:35 host dovecot: MANAGESIEVE(test): sieve-storage: using active sieve script path: ~/.dovecot.sieve Jun 21 12:07:35 host dovecot: MANAGESIEVE(test): sieve-storage: using sieve script storage directory: ~/sieve Jun 21 12:07:35 host dovecot: MANAGESIEVE(test): sieve-storage: relative path to sieve storage in active link: sieve/
This suggests that the managesieve daemon fails to start or that somehow debug is not turned on after all.
- Could you provide (an anonymized version of) the script you are trying to upload? (Make sure the version you send me is problematic as well)
The problem is not uploading. The problem is downloading. If I copy my sieve script to my client (by other means) I can upload it fine. The problem is that the client cannot retrieve it from the server for editing if it is bigger than 8kB. Here is a sample "problem" script:
# This is a sieve script file full of comments <--- snip (above line repeated 200 times) ---> keep;
If I lose 26 of those 200 comment lines then I can download as well as upload the script. Somehow, this works here without incident.
If it truly does hang at some point, you could use the strace tool to get an idea what it the managesieve daemon doing at that time. If you are not using TLS, you can use the ngrep tool to capture the TCP traffic between client and server. That may also prove useful.
It doesn't "hang". The script edit window pops up empty and 30 seconds later I see pop-up dialogue box: window title is "Alert"; Text is "A Timeout occured". I click OK to acknowledge the timeout and then I can enter/upload a large or small script or import/edit/upload a large or small script.
I don't have ngrep but if you can suggest a useful incantation for tcpdump I can provide that for you. You could obtain ngrep from FreeBSD Ports. I've never managed to do the same with tcpdump.
To take your client out of the equation, you could also manually login to managesieve using telnet or netcat. Just follow the instructions of the Troubleshooting section of http://wiki.dovecot.org/ManageSieve and apply the GETSCRIPT command on your large script. This way, you can directly see what the server is doing and you can make a transcript without sniffing the traffic.
Regards,
-- Stephan Bosch stephan@rename-it.nl
On Sun, 21 Jun 2009, 12:31 +0200, Stephan Bosch wrote:
- Do the logs say anything? Segfault perhaps (signal 11) ?
The logs show successful managesieve-login and then nothing. Considering the fact that you have mail_debug turned on for ManageSieve, you should have seen something like the following:
Jun 21 12:07:35 host dovecot: managesieve-login: Login: user=<test>, method=PLAIN, rip=<ip>, lip=<ip>, TLS Jun 21 12:07:35 host dovecot: MANAGESIEVE(test): Effective uid=2002, gid=2002, home=/home/test Jun 21 12:07:35 host dovecot: MANAGESIEVE(test): sieve-storage: using active sieve script path: ~/.dovecot.sieve Jun 21 12:07:35 host dovecot: MANAGESIEVE(test): sieve-storage: using active sieve script path: ~/.dovecot.sieve Jun 21 12:07:35 host dovecot: MANAGESIEVE(test): sieve-storage: using sieve script storage directory: ~/sieve Jun 21 12:07:35 host dovecot: MANAGESIEVE(test): sieve-storage: relative path to sieve storage in active link: sieve/
This suggests that the managesieve daemon fails to start or that somehow debug is not turned on after all.
That's exactly what I see. The daemon is running. Everything works except fetching large scripts.
You could obtain ngrep from FreeBSD Ports. I've never managed to do the same with tcpdump.
Thanks, I've done that so I now have ngrep available if you can furnish me with a useful command line.
To take your client out of the equation, you could also manually login to managesieve using telnet or netcat. Just follow the instructions of the Troubleshooting section of http://wiki.dovecot.org/ManageSieve and apply the GETSCRIPT command on your large script. This way, you can directly see what the server is doing and you can make a transcript without sniffing the traffic.
Thank you very much for that. I followed the directions on the wiki page using gnutls-cli. Here are the results. Note that everything is still intact after the GETSCRIPT failure and that a subsequent fetch of a smaller script succeeds.
OK "Logged in." LISTSCRIPTS "john" ACTIVE "test_tiny" "test_8000" "test_9000" OK "Listscripts completed." GETSCRIPT "test_tiny" {7} keep;
OK "Getscript completed." GETSCRIPT "test_8000" {8167} # This is a sieve script file full of comments --< snip: 168 lines removed >-- # This is a sieve script file full of comments keep;
OK "Getscript completed." GETSCRIPT "test_9000" {9223} # This is a sieve script file full of comments --< snip: 169 lines removed >-- # This is a sieve script file fuNO "Unknown error"
GETSCRIPT "test_tiny" {7} keep;
OK "Getscript completed."
Is there a way to enable more detailed debug logging on the server?
-- John Marshall
John Marshall wrote:
--< snip: 169 lines removed >-- # This is a sieve script file fuNO "Unknown error"
There's our problem. There's only one location in the sources where this most informative error can occur :) . Apparently, Timo has fixed an old bug in the Dovecot stream implementation. This bugfix triggers a problem in ManageSieve that uses an older section of code of the imap daemon. Timo provided the solution and I've committed the fix:
http://hg.rename-it.nl/dovecot-1.1-managesieve/rev/75c9769339b8
Please apply this to your managesieve source and check whether the problem is gone. I'll make a new release when all is ok.
Regards,
Stephan.
On Tue, 23 Jun 2009, 18:29 +0200, Stephan Bosch wrote:
John Marshall wrote:
--< snip: 169 lines removed >-- # This is a sieve script file fuNO "Unknown error"
There's our problem. There's only one location in the sources where this most informative error can occur :) . Apparently, Timo has fixed an old bug in the Dovecot stream implementation. This bugfix triggers a problem in ManageSieve that uses an older section of code of the imap daemon. Timo provided the solution and I've committed the fix:
http://hg.rename-it.nl/dovecot-1.1-managesieve/rev/75c9769339b8
Please apply this to your managesieve source and check whether the problem is gone. I'll make a new release when all is ok.
Thank you Stephan,
Was the patch for cmd-getscript.c the only patch? I applied that patch to cmd-getscript.c and rebuilt. That eliminated the informative error message but still does not return the entire script.
GETSCRIPT "test_9000" {9223} # This is a sieve script file full of comments --< snip: 169 lines removed >-- # This is a sieve script file fu OK "Getscript completed."
Regards,
-- John Marshall
John Marshall schreef:
On Tue, 23 Jun 2009, 18:29 +0200, Stephan Bosch wrote:
John Marshall wrote:
--< snip: 169 lines removed >-- # This is a sieve script file fuNO "Unknown error"
There's our problem. There's only one location in the sources where this most informative error can occur :) . Apparently, Timo has fixed an old bug in the Dovecot stream implementation. This bugfix triggers a problem in ManageSieve that uses an older section of code of the imap daemon. Timo provided the solution and I've committed the fix:
http://hg.rename-it.nl/dovecot-1.1-managesieve/rev/75c9769339b8
Please apply this to your managesieve source and check whether the problem is gone. I'll make a new release when all is ok.
Thank you Stephan,
Was the patch for cmd-getscript.c the only patch? I applied that patch to cmd-getscript.c and rebuilt. That eliminated the informative error message but still does not return the entire script.
GETSCRIPT "test_9000" {9223} # This is a sieve script file full of comments --< snip: 169 lines removed >-- # This is a sieve script file fu OK "Getscript completed."
I was hoping that this uninformative error was now spurious, meaning that my 'fix' indeed only got rid of the error message. However, as it seems, the stream is still truncated. I rebuilt the truncation check, now with a proper error and disconnect (because the protocol state is invalid then).
However, regarding the core of this problem, I am unable to reproduce this at my end without access to a FreeBSD system. Could you (or some other FreeBSD user) try to dig a little deeper to find out exactly why the stream ends prematurely? Alternatively, I would have to install FreeBSD somewhere, which will take more time.
Regards,
-- Stephan Bosch stephan@rename-it.nl
On Sat, 04 Jul 2009, 12:41 +0200, Stephan Bosch wrote:
John Marshall schreef:
On Tue, 23 Jun 2009, 18:29 +0200, Stephan Bosch wrote:
John Marshall wrote:
--< snip: 169 lines removed >-- # This is a sieve script file fuNO "Unknown error"
There's our problem. There's only one location in the sources where this most informative error can occur :) . Apparently, Timo has fixed an old bug in the Dovecot stream implementation. This bugfix triggers a problem in ManageSieve that uses an older section of code of the imap daemon. Timo provided the solution and I've committed the fix:
http://hg.rename-it.nl/dovecot-1.1-managesieve/rev/75c9769339b8
Please apply this to your managesieve source and check whether the problem is gone. I'll make a new release when all is ok.
Thank you Stephan,
Was the patch for cmd-getscript.c the only patch? I applied that patch to cmd-getscript.c and rebuilt. That eliminated the informative error message but still does not return the entire script.
GETSCRIPT "test_9000" {9223} # This is a sieve script file full of comments --< snip: 169 lines removed >-- # This is a sieve script file fu OK "Getscript completed."
I was hoping that this uninformative error was now spurious, meaning that my 'fix' indeed only got rid of the error message. However, as it seems, the stream is still truncated. I rebuilt the truncation check, now with a proper error and disconnect (because the protocol state is invalid then).
However, regarding the core of this problem, I am unable to reproduce this at my end without access to a FreeBSD system. Could you (or some other FreeBSD user) try to dig a little deeper to find out exactly why the stream ends prematurely? Alternatively, I would have to install FreeBSD somewhere, which will take more time.
I happy to help but I don't know where/how to start. Are you able to provide me with some digging hints?
Thank you.
-- John Marshall
On Thu, 2009-07-09 at 19:34 +1000, John Marshall wrote:
I was hoping that this uninformative error was now spurious, meaning that my 'fix' indeed only got rid of the error message. However, as it seems, the stream is still truncated. I rebuilt the truncation check, now with a proper error and disconnect (because the protocol state is invalid then).
However, regarding the core of this problem, I am unable to reproduce this at my end without access to a FreeBSD system. Could you (or some other FreeBSD user) try to dig a little deeper to find out exactly why the stream ends prematurely? Alternatively, I would have to install FreeBSD somewhere, which will take more time.
I happy to help but I don't know where/how to start. Are you able to provide me with some digging hints?
With the latest changes from dovecot-1.1-managesieve hg I can't reproduce this anymore. I guess one of those Stephan's "error handling" changes fixed the bug? :)
On Thu, 2009-07-09 at 22:22 -0400, Timo Sirainen wrote:
With the latest changes from dovecot-1.1-managesieve hg I can't reproduce this anymore. I guess one of those Stephan's "error handling" changes fixed the bug? :)
Ah, right. http://hg.rename-it.nl/dovecot-1.1-managesieve/rev/75c9769339b8 didn't work because it had:
- if ( !i_stream_have_bytes_left(ctx->scriptstream) && !ctx->failed ) {
which should have been:
- if ( i_stream_have_bytes_left(ctx->scriptstream) && !ctx->failed ) {
And http://hg.rename-it.nl/dovecot-1.1-managesieve/rev/8dc698b544ce fixed that.
On Thu, 09 Jul 2009, 22:27 -0400, Timo Sirainen wrote:
On Thu, 2009-07-09 at 22:22 -0400, Timo Sirainen wrote:
With the latest changes from dovecot-1.1-managesieve hg I can't reproduce this anymore. I guess one of those Stephan's "error handling" changes fixed the bug? :)
Ah, right. http://hg.rename-it.nl/dovecot-1.1-managesieve/rev/75c9769339b8 didn't work because it had:
- if ( !i_stream_have_bytes_left(ctx->scriptstream) && !ctx->failed ) {
which should have been:
- if ( i_stream_have_bytes_left(ctx->scriptstream) && !ctx->failed ) {
And http://hg.rename-it.nl/dovecot-1.1-managesieve/rev/8dc698b544ce fixed that.
Thank you Timo and Stephan! That was it! I have applied the latest patches to cmd-getscript.c in dovecot-managesieve 0.10.6, rebuilt, and I can once again retrieve larger scripts from the server.
Regards,
-- John Marshall
On Fri, 2009-06-19 at 21:17 +1000, John Marshall wrote:
After some help with debugging tips on #dovecot, I have established that a sieve script on Dovecot 1.1.16 has to be less than 8kB in order to be retrieved by a managesieve client. I have been using managesieve for about 6 months over as many 1.1.n versions of dovecot as have been around during that time and hit this problem when I upgraded to Dovecot 1.1.16. I have gone back to Dovecot 1.1.15 and can once again manage my 9kB sieve script remotely.
I suppose it's because of this patch: diff -r 6604f9980a93 -r 7f6aaca52639 src/lib/ostream-file.c --- a/src/lib/ostream-file.c Sun May 17 22:06:11 2009 -0400 +++ b/src/lib/ostream-file.c Mon Jun 01 01:46:52 2009 -0400 @@ -631,6 +631,10 @@ } while ((uoff_t)ret != send_size); i_stream_seek(instream, v_offset); + if (ret == 0) { + /* we should be at EOF, verify it by reading instream */ + (void)i_stream_read(instream); + } return ret < 0 ? -1 : (off_t)(instream->v_offset - start_offset); } But that code is supposed to fix it, not break it..
participants (3)
-
John Marshall
-
Stephan Bosch
-
Timo Sirainen