Hello,
I'm trying to configure the dovecot-antispam plugin. Now I've run into a problem: whenever I try to move/copy a message in/from the spam mailbox, Thunderbird (and also Sylpheed, haven't tried anything else) says:
The current command did not succeed. The mail server responded: Failed to read mail beginning.
and in the logs I get:
dovecot: Aug 07 10:41:23 Error: IMAP(username): Next message unexpectedly lost from 337928 dovecot: Aug 07 10:41:23 Error: IMAP(username): Next message unexpectedly lost from 337928
The message is not moved/copied.
My config (dovecot -n):
base_dir: /var/run/dovecot_test/ log_path: /var/log/dovecot/test_log info_log_path: /var/log/dovecot/test_info_log protocols: pop3s imaps pop3 imap listen(default): *:10143 listen(imap): *:10143 listen(pop3): *:10110 ssl_listen(default): *:10993 ssl_listen(imap): *:10993 ssl_listen(pop3): *:10995 ssl_cert_file: /etc/ssl/anxur.pem ssl_key_file: /etc/ssl/anxur.pem ssl_parameters_regenerate: 24 login_dir: /var/run/dovecot_test/login login_executable(default): /packages/run.64/dovecot-1.1.2/libexec/dovecot/imap-login login_executable(imap): /packages/run.64/dovecot-1.1.2/libexec/dovecot/imap-login login_executable(pop3): /packages/run.64/dovecot-1.1.2/libexec/dovecot/pop3-login login_greeting: HI! login_greeting_capability(default): yes login_greeting_capability(imap): yes login_greeting_capability(pop3): no verbose_proctitle: yes first_valid_uid: 200 mail_location: mbox:/home/%u/mail/:INBOX=/var/mail/%u:INDEX=/home/%u/mail/.imap mail_debug: yes mail_full_filesystem_access: yes maildir_copy_with_hardlinks: no mbox_write_locks: fcntl mbox_dirty_syncs: no mbox_lazy_writes: no dbox_rotate_days: 0 mail_executable(default): /packages/run.64/dovecot-1.1.2/libexec/dovecot/imap mail_executable(imap): /packages/run.64/dovecot-1.1.2/libexec/dovecot/imap mail_executable(pop3): /packages/run.64/dovecot-1.1.2/libexec/dovecot/pop3 mail_plugins(default): antispam mail_plugins(imap): antispam mail_plugins(pop3): mail_plugin_dir(default): /packages/run.64/dovecot-1.1.2/lib/dovecot/imap mail_plugin_dir(imap): /packages/run.64/dovecot-1.1.2/lib/dovecot/imap mail_plugin_dir(pop3): /packages/run.64/dovecot-1.1.2//lib/dovecot/pop3 mail_log_max_lines_per_sec: 20 imap_max_line_length(default): 131072 imap_max_line_length(imap): 131072 imap_max_line_length(pop3): 65536 imap_client_workarounds(default): delay-newmail outlook-idle tb-extra-mailbox-sep imap_client_workarounds(imap): delay-newmail outlook-idle tb-extra-mailbox-sep imap_client_workarounds(pop3): pop3_uidl_format(default): %08Xu%08Xv pop3_uidl_format(imap): %08Xu%08Xv pop3_uidl_format(pop3): %08Xv%08Xu pop3_client_workarounds(default): pop3_client_workarounds(imap): pop3_client_workarounds(pop3): outlook-no-nuls oe-ns-eoh auth default: mechanisms: gssapi plain executable: /packages/run.64/dovecot-1.1.2/libexec/dovecot/dovecot-auth krb5_keytab: /etc/krb5.imap verbose: yes debug: yes passdb: driver: pam args: dovecot userdb: driver: passwd plugin: antispam_spam: mailbox.spam antispam_trash: trash;Trash;Deleted Items antispam_mail_spam: spam@mysite.org antispam_mail_notspam: notspam@mysite.org antispam_mail_sendmail: /home/username/fake_sendmail
Dovecot is version 1.1.2, dovecot-antispam is the latest snapshot. Running on Red Hat Enterprise Linux Server release 5.2, x86_64, filesystem is ext3 (on lvm).
Attached is the strace -p of the session.
The code seems to be this in i_stream_raw_mbox_read:
if (stream->istream.v_offset -
rstream->hdr_offset + new_pos > rstream->mail_size) {
/* istream_raw_mbox_set_next_offset() used invalid
cached next_offset? */
i_error("Next message unexpectedly lost from %"PRIuUOFF_T, rstream->hdr_offset + rstream->mail_size); rstream->eof = TRUE; rstream->corrupted = TRUE; return -1; }
If I comment it out (after I backup my mail), everything seems to work as expected.
Jiri Novosad
epoll_wait(6, {{EPOLLIN, {u32=7035872, u64=7035872}}}, 4, 492) = 1
gettimeofday({1218008692, 930362}, NULL) = 0
gettimeofday({1218008692, 930446}, NULL) = 0
read(0, "452 uid copy 4 \"mailbox.", 24) = 24
gettimeofday({1218008692, 930610}, NULL) = 0
epoll_wait(6, {{EPOLLIN, {u32=7035872, u64=7035872}}}, 4, 423) = 1
gettimeofday({1218008692, 930806}, NULL) = 0
gettimeofday({1218008692, 930903}, NULL) = 0
read(0, "spam\"\r\n", 4087) = 7
stat("/home/username/mail/mailbox.spam", {st_mode=S_IFREG|0644, st_size=140169, ...}) = 0
stat("/home/username/mail/mailbox.spam", {st_mode=S_IFREG|0644, st_size=140169, ...}) = 0
stat("/home/username/mail/.imap/.imap/mailbox.spam", {st_mode=S_IFDIR|0700, st_size=4096, ...}) = 0
gettimeofday({1218008692, 931707}, NULL) = 0
access("/home/username/mail/mailbox.spam", R_OK|W_OK) = 0
open("/home/username/mail/.imap/.imap/mailbox.spam/dovecot.index.log", O_RDWR) = 10
fstat(10, {st_mode=S_IFREG|0600, st_size=10908, ...}) = 0
pread(10, "\1\0\30\0\373\264\226H\4\0\0\0\3\0\0\0\364\334\0\0|\"\230H", 24, 0) = 24
stat("/home/username/mail/.imap/.imap/mailbox.spam/dovecot.index.log.2", 0x7fffd3bb6f50) = -1 ENOENT (No such file or directory)
open("/home/username/mail/.imap/.imap/mailbox.spam/dovecot.index", O_RDWR) = 11
alarm(120) = 0
fcntl(11, F_SETLKW, {type=F_RDLCK, whence=SEEK_SET, start=0, len=0}) = 0
alarm(0) = 120
fstat(11, {st_mode=S_IFREG|0600, st_size=1136, ...}) = 0
pread(11, "\7\2x\0x\1\0\0(\0\0\0\1\0\0\0\373\264\226H\0\0\0\0\373\264\226H\232\10\0\0"..., 4096, 0) = 1136
fcntl(11, F_SETLK, {type=F_UNLCK, whence=SEEK_SET, start=0, len=0}) = 0
stat("/home/username/mail/.imap/.imap/mailbox.spam/dovecot.index.log", {st_mode=S_IFREG|0600, st_size=10908, ...}) = 0
fstat(10, {st_mode=S_IFREG|0600, st_size=10908, ...}) = 0
pread(10, "\200\200\200\204 \0\0\20P\0\4\0\322P\231H\200\200\200\204 \0\0\0200\0\4\0\232\10\0\0"..., 1024, 10204) = 704
pread(10, "", 1024, 10908) = 0
mkdir("/tmp/antispam-mail-GYlEb4", 0700) = 0
mkdir("/tmp/antispam-mail-Rb3HAN", 0700) = 0
gettimeofday({1218008692, 933917}, NULL) = 0
gettimeofday({1218008692, 934014}, NULL) = 0
stat("/home/username/mail/sent-mail", {st_mode=S_IFREG|0644, st_size=2143, ...}) = 0
gettimeofday({1218008692, 934308}, NULL) = 0
alarm(5) = 0
fcntl(19, F_SETLKW, {type=F_RDLCK, whence=SEEK_SET, start=0, len=0}) = 0
alarm(0) = 5
stat("/home/username/mail/sent-mail", {st_mode=S_IFREG|0644, st_size=2143, ...}) = 0
stat("/home/username/mail/.imap/.imap/sent-mail/dovecot.index.log", {st_mode=S_IFREG|0600, st_size=2088, ...}) = 0
fstat(8, {st_mode=S_IFREG|0600, st_size=2088, ...}) = 0
fstat(19, {st_mode=S_IFREG|0644, st_size=2143, ...}) = 0
pread(19, "\nFrom popel@mysite.org Thu Jul "..., 4096, 551) = 1592
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2246, ...}) = 0
stat("/home/username/mail/.imap/.imap/sent-mail/dovecot.index.log", {st_mode=S_IFREG|0600, st_size=2088, ...}) = 0
fstat(8, {st_mode=S_IFREG|0600, st_size=2088, ...}) = 0
gettimeofday({1218008692, 935474}, NULL) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2246, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2246, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2246, ...}) = 0
sendto(7, "<14>Aug 6 09:44:52 imap: antisp"..., 71, MSG_NOSIGNAL, NULL, 0) = 71
gettimeofday({1218008692, 936290}, NULL) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2246, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2246, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2246, ...}) = 0
sendto(7, "<14>Aug 6 09:44:52 imap: antisp"..., 67, MSG_NOSIGNAL, NULL, 0) = 67
gettimeofday({1218008692, 937117}, NULL) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2246, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2246, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2246, ...}) = 0
sendto(7, "<14>Aug 6 09:44:52 imap: antisp"..., 70, MSG_NOSIGNAL, NULL, 0) = 70
gettimeofday({1218008692, 937848}, NULL) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2246, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2246, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2246, ...}) = 0
sendto(7, "<14>Aug 6 09:44:52 imap: antisp"..., 74, MSG_NOSIGNAL, NULL, 0) = 74
gettimeofday({1218008692, 938501}, NULL) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2246, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2246, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2246, ...}) = 0
sendto(7, "<14>Aug 6 09:44:52 imap: antisp"..., 66, MSG_NOSIGNAL, NULL, 0) = 66
gettimeofday({1218008692, 939236}, NULL) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2246, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2246, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2246, ...}) = 0
sendto(7, "<14>Aug 6 09:44:52 imap: antisp"..., 69, MSG_NOSIGNAL, NULL, 0) = 69
gettimeofday({1218008692, 939981}, NULL) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2246, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2246, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2246, ...}) = 0
sendto(7, "<14>Aug 6 09:44:52 imap: antisp"..., 68, MSG_NOSIGNAL, NULL, 0) = 68
gettimeofday({1218008692, 940611}, NULL) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2246, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2246, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2246, ...}) = 0
sendto(7, "<14>Aug 6 09:44:52 imap: antisp"..., 87, MSG_NOSIGNAL, NULL, 0) = 87
gettimeofday({1218008692, 941375}, NULL) = 0
gettimeofday({1218008692, 941511}, NULL) = 0
open("/home/username/mail/mailbox.spam", O_RDWR) = 12
fstat(12, {st_mode=S_IFREG|0644, st_size=140169, ...}) = 0
gettimeofday({1218008692, 941777}, NULL) = 0
alarm(5) = 0
fcntl(12, F_SETLKW, {type=F_WRLCK, whence=SEEK_SET, start=0, len=0}) = 0
alarm(0) = 5
stat("/home/username/mail/mailbox.spam", {st_mode=S_IFREG|0644, st_size=140169, ...}) = 0
stat("/home/username/mail/mailbox.spam", {st_mode=S_IFREG|0644, st_size=140169, ...}) = 0
alarm(180) = 0
fcntl(10, F_SETLKW, {type=F_WRLCK, whence=SEEK_SET, start=0, len=0}) = 0
alarm(0) = 180
stat("/home/username/mail/.imap/.imap/mailbox.spam/dovecot.index.log", {st_mode=S_IFREG|0600, st_size=10908, ...}) = 0
fstat(10, {st_mode=S_IFREG|0600, st_size=10908, ...}) = 0
fcntl(10, F_SETLK, {type=F_UNLCK, whence=SEEK_SET, start=0, len=0}) = 0
stat("/home/username/mail/.imap/.imap/mailbox.spam/dovecot.index.log", {st_mode=S_IFREG|0600, st_size=10908, ...}) = 0
fstat(10, {st_mode=S_IFREG|0600, st_size=10908, ...}) = 0
fstat(12, {st_mode=S_IFREG|0644, st_size=140169, ...}) = 0
lseek(12, 140168, SEEK_SET) = 140168
read(12, "\n", 1) = 1
fstat(12, {st_mode=S_IFREG|0644, st_size=140169, ...}) = 0
fstat(12, {st_mode=S_IFREG|0644, st_size=140169, ...}) = 0
pread(12, "\n", 4096, 140168) = 1
pread(12, "", 4095, 140169) = 0
pread(19, "Return-Path: popel@mysite.org\n"..., 4096, 600) = 1543
pread(19, "", 2553, 2143) = 0
pread(19, "", 2553, 2143) = 0
pread(19, "", 2553, 2143) = 0
write(12, "From popel@mysite.org Thu Jul 3"..., 1593) = 1593
pwrite(12, "\nContent-Length: 581", 20, 141159) = 20
creat("/tmp/antispam-mail-GYlEb4/0", 0600) = 13
lseek(13, 0, SEEK_CUR) = 0
fstat(13, {st_mode=S_IFREG|0600, st_size=0, ...}) = 0
write(13, "\1\0\0\0", 4) = 4
pread(12, "From popel@mysite.org Thu Jul 3"..., 4095, 140169) = 1593
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2246, ...}) = 0
write(2, "\1ENext message unexpectedly lost"..., 45) = 45
pread(12, "\nFrom popel@mysite.org Thu Jul "..., 4096, 140168) = 1594
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2246, ...}) = 0
write(2, "\1ENext message unexpectedly lost"..., 45) = 45
close(13) = 0
close(13) = -1 EBADF (Bad file descriptor)
rmdir("/tmp/antispam-mail-Rb3HAN") = 0
stat("/home/username/mail/.imap/.imap/sent-mail/dovecot.index.log", {st_mode=S_IFREG|0600, st_size=2088, ...}) = 0
fstat(8, {st_mode=S_IFREG|0600, st_size=2088, ...}) = 0
fcntl(19, F_SETLK, {type=F_UNLCK, whence=SEEK_SET, start=0, len=0}) = 0
alarm(0) = 0
write(12, "\n", 1) = 1
ftruncate(12, 140169) = 0
fcntl(12, F_SETLK, {type=F_UNLCK, whence=SEEK_SET, start=0, len=0}) = 0
alarm(0) = 0
unlink("/tmp/antispam-mail-GYlEb4/0") = 0
rmdir("/tmp/antispam-mail-GYlEb4") = 0
close(12) = 0
gettimeofday({1218008692, 946718}, NULL) = 0
write(1, "452 NO Failed to read mail begin"..., 38) = 38
gettimeofday({1218008692, 946937}, NULL) = 0
epoll_wait(6, {}, 4, 407) = 0
gettimeofday({1218008693, 353573}, NULL) = 0
gettimeofday({1218008693, 353660}, NULL) = 0
epoll_wait(6, {{EPOLLIN, {u32=7035872, u64=7035872}}}, 4, 5000) = 1
gettimeofday({1218008694, 161166}, NULL) = 0
gettimeofday({1218008694, 161210}, NULL) = 0
read(0, "453 IDLE\r\n", 4080) = 10
gettimeofday({1218008694, 161352}, NULL) = 0
inotify_add_watch(18, "/home/username/mail/sent-mail", IN_MODIFY|IN_CLOSE_WRITE|IN_CLOSE_NOWRITE|IN_MOVED_FROM|IN_MOVED_TO|IN_CREATE|IN_DELETE|IN_DELETE_SELF) = 123
epoll_ctl(6, EPOLL_CTL_ADD, 18, {EPOLLIN|EPOLLPRI|EPOLLERR|EPOLLHUP, {u32=7144768, u64=7144768}}) = 0
stat("/home/username/mail/sent-mail", {st_mode=S_IFREG|0644, st_size=2143, ...}) = 0
gettimeofday({1218008694, 161636}, NULL) = 0
epoll_ctl(6, EPOLL_CTL_DEL, 0, {0, {u32=7035872, u64=7035872}}) = 0
epoll_ctl(6, EPOLL_CTL_ADD, 0, {EPOLLIN|EPOLLPRI|EPOLLERR|EPOLLHUP, {u32=7035872, u64=7035872}}) = 0
gettimeofday({1218008694, 161895}, NULL) = 0
stat("/home/username/mail/sent-mail", {st_mode=S_IFREG|0644, st_size=2143, ...}) = 0
alarm(180) = 0
fcntl(8, F_SETLKW, {type=F_WRLCK, whence=SEEK_SET, start=0, len=0}) = 0
alarm(0) = 180
stat("/home/username/mail/.imap/.imap/sent-mail/dovecot.index.log", {st_mode=S_IFREG|0600, st_size=2088, ...}) = 0
fstat(8, {st_mode=S_IFREG|0600, st_size=2088, ...}) = 0
fcntl(8, F_SETLK, {type=F_UNLCK, whence=SEEK_SET, start=0, len=0}) = 0
mkdir("/tmp/antispam-mail-3WExWz", 0700) = 0
rmdir("/tmp/antispam-mail-3WExWz") = 0
stat("/home/username/mail/.imap/.imap/sent-mail/dovecot.index.log", {st_mode=S_IFREG|0600, st_size=2088, ...}) = 0
fstat(8, {st_mode=S_IFREG|0600, st_size=2088, ...}) = 0
write(1, "+ idling\r\n", 10) = 10
gettimeofday({1218008694, 164036}, NULL) = 0
epoll_wait(6, {{EPOLLIN, {u32=7144768, u64=7144768}}}, 4, 4189) = 1
gettimeofday({1218008694, 164168}, NULL) = 0
read(18, "z\0\0\0\0\200\0\0\0\0\0\0\0\0\0\0", 32768) = 16
gettimeofday({1218008694, 164332}, NULL) = 0
gettimeofday({1218008694, 164400}, NULL) = 0
epoll_wait(6, ^C