dovecot - Jun 2010 - [Dovecot 1.2.11(NFS used) & dovecot-antispam 1.2]: move message error

Hello! I am really need help!

I am using dovecot installation on ~700 users with dspam integration via
dovecot-antispam plugin.
Problem in unpredictable result of moving spam-mails from INBOX to Junk
and from Junk to INBOX. In some cases it works fine, but sometimes I see
error like "It's not possible to move the message" in client
(roundcube).

Two different samples on same configuration/server. Moving from INBOX into
Junk.
1. Successful moving (roundcube imap debug):
-------------%<------------
[19:05:35]: C: cpy1 UID COPY 2387 "Junk"
[19:05:35]: S: cpy1 OK [COPYUID 1273276423 2387 1280] Copy completed.
[19:05:35]: C: flg UID STORE 2387 +FLAGS (\Deleted)
[19:05:35]: S: * 1471 FETCH (UID 2387 FLAGS (\Deleted \Seen))
[19:05:35]: S: flg OK Store completed.
[19:05:35]: C: exp1 UID EXPUNGE 2387
[19:05:35]: S: * 1471 EXPUNGE
[19:05:35]: S: exp1 OK Expunge completed.
Result: message moved into Junk, dspam retrained. Success.
------------->%------------

2. Unsuccessful moving
-------------%<------------
[19:02:47]: C: cpy1 UID COPY 2386 "Junk"
[19:02:57]: S: * OK [CAPABILITY IMAP4rev1 LITERAL+ SASL-IR LOGIN-REFERRALS
ID ENABLE AUTH=PLAIN AUTH=LOGIN]
Dovecot ready.
[19:02:57]: C: cp01 CAPABILITY
[19:02:57]: S: * CAPABILITY IMAP4rev1 LITERAL+ SASL-IR LOGIN-REFERRALS ID
ENABLE SORT SORT=DISPLAY THREAD=RE
FERENCES THREAD=REFS MULTIAPPEND UNSELECT IDLE CHILDREN NAMESPACE UIDPLUS
LIST-EXTENDED I18NLEVEL=1 CONDSTORE QRESYNC ESEARCH
ESORT SEARCHRES WITHIN CONTEXT=SEARCH LIST-STATUS QUOTA AUTH=PLAIN
AUTH=LOGIN
[19:02:57]: S: cp01 OK Capability completed.
Result: I see moving error in roundcube. Sometimes I see several
duplicates of original message in Junk and original message also presented
in INBOX. Malfunction.
------------->%------------

Similar symptoms also affected while moving message from Junk into INBOX.
One more sample. Junk -> INBOX moving.
-------------%<------------
[20:20:16]: C: cpy1 UID COPY 2859 "INBOX"
[20:20:20]: S: * OK [CAPABILITY IMAP4rev1 LITERAL+ SASL-IR LOGIN-REFERRALS
ID ENABLE AUTH=PLAIN AUTH=LOGIN]
Dovecot ready.
[20:20:20]: C: cp01 CAPABILITY
[20:20:20]: S: * CAPABILITY IMAP4rev1 LITERAL+ SASL-IR LOGIN-REFERRALS ID
ENABLE SORT SORT=DISPLAY THREAD=RE
FERENCES THREAD=REFS MULTIAPPEND UNSELECT IDLE CHILDREN NAMESPACE UIDPLUS
LIST-EXTENDED I18NLEVEL=1 CONDSTORE QRESYNC ESEARCH
ESORT SEARCHRES WITHIN CONTEXT=SEARCH LIST-STATUS QUOTA AUTH=PLAIN
AUTH=LOGIN
[20:20:20]: S: cp01 OK Capability completed.
Result: move failure. Duplicates in INBOX.
------------->%------------

Mails stored on NFS server - Ubuntu 9.10 (Linux storage01
2.6.31-21-generic-pae #59-Ubuntu SMP Wed Mar 24 08:47:55 UTC 2010 i686
GNU/Linux). Indexes now stored locally, but I already try to store them on
NFS. No difference. 

Dovecot and NFS client running under FreeBSD 8.
-------------%<------------
mail01#uname -a
FreeBSD mail01.domain.net 8.0-RELEASE FreeBSD 8.0-RELEASE #0: Sat Nov 21
15:48:17 UTC 2009    
root at almeida.cse.buffalo.edu:/usr/obj/usr/src/sys/GENERIC  i386
------------->%------------

Mount options. Two variant:
1. 192.164.100.103:/mnt/storage/mailstores  /var/mail/mymail        nfs   
rw,acregmin=0,acregmax=0,acdirmin=0,acdirmax=0  0    0
2(current). 192.164.100.103:/mnt/storage/mailstores   /var/mail/mymail    
  nfs     rw,bg,tcp,nosuid        0       0
In both variants error detected.

-------------%<------------
mail01# dovecot --version
1.2.11
mail01# pkg_info | grep dspam
dovecot-antispam-1.2_4,1 Dovecot plugin to train dspam about spam or false
positives
dspam-3.9.0_1       Bayesian spam filter - stable maintenance version
------------->%------------
Dspam build with direct dspam training possibility, debug and
debug_verbose options.

All installed from ports.
Current dovecot configuration:
-------------%<------------
mail01# dovecot -n
# 1.2.11: /usr/local/etc/dovecot.conf
# OS: FreeBSD 8.0-RELEASE i386  nfs
base_dir: /var/run/dovecot/
log_path: /var/log/dovecot/dovecot.log
protocols: imap pop3
ssl: no
disable_plaintext_auth: no
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_max_processes_count: 256
verbose_proctitle: yes
first_valid_uid: 1
last_valid_uid: 10000
last_valid_gid: 10000
mail_privileged_group: mail
mail_uid: dovecot
mail_gid: mail
mail_location:
maildir:/var/mail/mymail/%d/%n:INDEX=/var/mail/indexes/%d/%n
mail_debug: yes
mail_nfs_storage: yes
mbox_write_locks: fcntl dotlock
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_plugins(default): quota imap_quota convert antispam autocreate
mail_plugins(imap): quota imap_quota convert antispam autocreate
mail_plugins(pop3): quota convert autocreate
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
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):
pop3_client_workarounds(default):
pop3_client_workarounds(imap):
pop3_client_workarounds(pop3): outlook-no-nuls oe-ns-eoh
lda:
  postmaster_address: admin at domain.net
  hostname: mail.domain2.net
  mail_plugins: quota
  mail_plugin_dir: /usr/local/lib/dovecot/lda
  quota_full_tempfail: yes
  sendmail_path: /usr/sbin/sendmail
  rejection_reason: Your message to <%t> was automatically rejected:%n%r
  auth_socket_path: /var/run/dovecot/auth-master
  log_path: /var/log/dovecot/dovecot-deliver.log
  info_log_path: /var/log/dovecot/dovecot-deliver.log
auth default:
  mechanisms: plain login
  default_realm: domain.net
  username_format: %Lu
  failure_delay: 3
  verbose: yes
  debug: yes
  debug_passwords: yes
  passdb:
    driver: sql
    args: /usr/local/etc/dovecot-sql.conf
  userdb:
    driver: sql
    args: /usr/local/etc/dovecot-sql.conf
  socket:
    type: listen
    client:
      path: /var/run/dovecot/auth-client
      mode: 438
    master:
      path: /var/run/dovecot/auth-master
      mode: 384
      user: mailnull
      group: mail
plugin:
  quota_rule: *:storage=50M
  quota: maildir
  convert_mail: mbox:/var/mail/old/%u
  antispam_signature: X-DSPAM-Signature
  antispam_spam: Junk
  antispam_trash: Trash
  antispam_signature_missing: move
  antispam_dspam_result_header: X-DSPAM-Result
  antispam_allow_append_to_spam: yes
  antispam_dspam_binary: /usr/local/bin/dspam
  antispam_dspam_args: --user;%u
  antispam_mail_tmpdir: /tmp
  autocreate: Trash
  autocreate2: Junk
  autocreate3: Sent
  autocreate4: Drafts
  autosubscribe: Trash
  autosubscribe2: Junk
  autosubscribe3: Sent
  autosubscribe4: Drafts
------------->%------------

User, maildir size independence.

Any ideas? What cause? What can do with this?
Really need to solve it.

On Fri, 2010-06-18 at 23:13 +0400, ????????????? wrote:
> 
> 2. Unsuccessful moving
> -------------%<------------
> [19:02:47]: C: cpy1 UID COPY 2386 "Junk"
> [19:02:57]: S: * OK [CAPABILITY IMAP4rev1 LITERAL+ SASL-IR
> LOGIN-REFERRALS
> ID ENABLE AUTH=PLAIN AUTH=LOGIN]
> Dovecot ready. 
That looks like it crashes. Did you look at the error log?

On Fri, 18 Jun 2010 20:18:54 +0100, Timo Sirainen <tss at iki.fi>
wrote:
> On Fri, 2010-06-18 at 23:13 +0400, ????????????? wrote:
>> 
>> 2. Unsuccessful moving
>> -------------%<------------
>> [19:02:47]: C: cpy1 UID COPY 2386 "Junk"
>> [19:02:57]: S: * OK [CAPABILITY IMAP4rev1 LITERAL+ SASL-IR
>> LOGIN-REFERRALS
>> ID ENABLE AUTH=PLAIN AUTH=LOGIN]
>> Dovecot ready. 
> 
> That looks like it crashes. Did you look at the error log?
I am afraid yes. There is only Info messages. I can do raw log or activate
mail_log if it can be useful.

Seems svn-trunk really much better =) Before this we use 0.3 stable and
0.4 beta - error occurred.
IMAP debug with svn-trunk:
-------------->%------------
...
[16:54:50]: C: cpy1 UID COPY
1761,1760,1759,1758,1757,1751,1750,1749,1748,1747,1746,1745,1744
"INBOX"
[16:54:56]: S: * OK [CAPABILITY IMAP4rev1 LITERAL+ SASL-IR LOGIN-REFERRALS
ID ENABLE AUTH=PLAIN AUTH=LOGIN]
 Dovecot ready.
[16:54:56]: C: cp01 CAPABILITY
[16:54:56]: S: * CAPABILITY IMAP4rev1 LITERAL+ SASL-IR LOGIN-REFERRALS ID
ENABLE SORT SORT=DISPLAY THREAD=R
EFERENCES THREAD=REFS MULTIAPPEND UNSELECT IDLE CHILDREN NAMESPACE UIDPLUS
LIST-EXTENDED I18NLEVEL=1 CONDSTORE QRESYNC ESEARC
H ESORT SEARCHRES WITHIN CONTEXT=SEARCH LIST-STATUS QUOTA AUTH=PLAIN
AUTH=LOGIN
[16:54:56]: S: cp01 OK Capability completed.
[16:54:56]: C: a001 LOGIN "dark at aspu.ru" "3784586"
[16:54:56]: S: a001 OK [CAPABILITY IMAP4rev1 LITERAL+ SASL-IR
LOGIN-REFERRALS ID ENABLE SORT SORT=DISPLAY T
HREAD=REFERENCES THREAD=REFS MULTIAPPEND UNSELECT IDLE CHILDREN NAMESPACE
UIDPLUS LIST-EXTENDED I18NLEVEL=1 CONDSTORE QRESYNC
 ESEARCH ESORT SEARCHRES WITHIN CONTEXT=SEARCH LIST-STATUS QUOTA] Logged
in
[16:54:56]: C: sel1 SELECT "Junk"
[16:54:56]: S: * FLAGS (\Answered \Flagged \Deleted \Seen \Draft)
[16:54:56]: S: * OK [PERMANENTFLAGS (\Answered \Flagged \Deleted \Seen
\Draft \*)] Flags permitted.
[16:54:56]: S: * 1536 EXISTS
[16:54:56]: S: * 0 RECENT
[16:54:56]: S: * OK [UNSEEN 1483] First unseen.
[16:54:56]: S: * OK [UIDVALIDITY 1273276432] UIDs valid
[16:54:56]: S: * OK [UIDNEXT 1762] Predicted next UID
[16:54:56]: S: * OK [HIGHESTMODSEQ 43] Highest
[16:54:56]: S: sel1 OK [READ-WRITE] Select completed.
[16:54:56]: C: fuid FETCH 1536 (UID)
[16:54:56]: S: * 1536 FETCH (UID 1761)
[16:54:56]: S: fuid OK Fetch completed.
[16:54:56]: C: srch1 SEARCH ALL UNSEEN
[16:54:56]: S: * SEARCH 1483 1484 1485 1486 1491 1492 1493 1494 1496 1497
1498 1499 1500 1501 1502 1503 150
4 1505 1506 1507 1509 1510 1511 1512 1513 1515 1516 1517 1518 1519 1520
1521 1522 1523 1524 1525 1526 1527 1528 1529 1530 153
1 1532 1533 1534 1535 1536
[16:54:56]: S: srch1 OK Search completed (0.000 secs).
[16:54:56]: C: I LOGOUT
[16:55:01]: S: cpy1 OK [COPYUID 1273276429 1744:1751,1757:1761 610:622]
Copy completed.
[16:55:01]: C: flg UID STORE
1761,1760,1759,1758,1757,1751,1750,1749,1748,1747,1746,1745,1744 +FLAGS
(\Dele
ted)
[16:55:01]: S: * 1524 FETCH (UID 1744 FLAGS (\Deleted))
[16:55:01]: S: * 1525 FETCH (UID 1745 FLAGS (\Deleted))
[16:55:01]: S: * 1526 FETCH (UID 1746 FLAGS (\Deleted))
[16:55:01]: S: * 1527 FETCH (UID 1747 FLAGS (\Deleted))
[16:55:01]: S: * 1528 FETCH (UID 1748 FLAGS (\Deleted))
[16:55:01]: S: * 1529 FETCH (UID 1749 FLAGS (\Deleted))
[16:55:01]: S: * 1530 FETCH (UID 1750 FLAGS (\Deleted))
[16:55:01]: S: * 1531 FETCH (UID 1751 FLAGS (\Deleted))
[16:55:01]: S: * 1532 FETCH (UID 1757 FLAGS (\Deleted))
[16:55:01]: S: * 1533 FETCH (UID 1758 FLAGS (\Deleted))
[16:55:01]: S: * 1534 FETCH (UID 1759 FLAGS (\Deleted))
[16:55:01]: S: * 1535 FETCH (UID 1760 FLAGS (\Deleted))
[16:55:01]: S: * 1536 FETCH (UID 1761 FLAGS (\Deleted))
[16:55:01]: S: flg OK Store completed.
[16:55:01]: C: exp1 UID EXPUNGE
1761,1760,1759,1758,1757,1751,1750,1749,1748,1747,1746,1745,1744
[16:55:01]: S: * 1536 EXPUNGE
[16:55:01]: S: * 1535 EXPUNGE
[16:55:01]: S: * 1534 EXPUNGE
[16:55:01]: S: * 1533 EXPUNGE
[16:55:01]: S: * 1532 EXPUNGE
[16:55:01]: S: * 1531 EXPUNGE
[16:55:01]: S: * 1530 EXPUNGE
[16:55:01]: S: * 1529 EXPUNGE
[16:55:01]: S: * 1528 EXPUNGE
[16:55:01]: S: * 1527 EXPUNGE
[16:55:01]: S: * 1526 EXPUNGE
[16:55:01]: S: * 1525 EXPUNGE
[16:55:01]: S: * 1524 EXPUNGE
[16:55:01]: S: exp1 OK Expunge completed.
[16:55:01]: C: sel1 SELECT "Junk"
[16:55:01]: S: * OK [CLOSED] Previous mailbox closed.
[16:55:01]: S: * FLAGS (\Answered \Flagged \Deleted \Seen \Draft)
...
--------------%<------------

No error with moving, but
-------------->%------------
[19-Jun-2010 16:54:50 +0400]: C: cpy1 UID COPY
1761,1760,1759,1758,1757,1751,1750,1749,1748,1747,1746,1745,1744
"INBOX"
[19-Jun-2010 16:54:56 +0400]: S: * OK [CAPABILITY IMAP4rev1 LITERAL+
SASL-IR LOGIN-REFERRALS ID ENABLE AUTH=PLAIN AUTH=LOGIN]
 Dovecot ready.
--------------%<------------
Is this reply correct?? Or maybe its part of another request if Roundcube
have something like multithreaded IMAP session??

Moving messages using other folder (where dovecot-antispam not used) works
perfect.

>> No error with moving, but
>> -------------->%------------
>> [19-Jun-2010 16:54:50 +0400]: C: cpy1 UID COPY
>> 1761,1760,1759,1758,1757,1751,1750,1749,1748,1747,1746,1745,1744
"INBOX"
>> [19-Jun-2010 16:54:56 +0400]: S: * OK [CAPABILITY IMAP4rev1 LITERAL+
>> SASL-IR LOGIN-REFERRALS ID ENABLE AUTH=PLAIN AUTH=LOGIN]
>>  Dovecot ready.
>> --------------%<------------
>> Is this reply correct?? Or maybe its part of another request if
Roundcube
>> have something like multithreaded IMAP session??
> 
> I think this is from another request, e.g. check-recent action.
It's really seems to be that. Big thanks for improvements in svn-trank
Roundcube version, I am waiting for official release for update.

Timo-san, which client most Dovecot compatible you think (non-Web)?? I
want to do more tests.