[Dovecot] Index file (date timestamp) issue on OS X 10.6.2 Server
Hi,
I've run into a bit of a problem and exhausted my knowledge and research. I'm hoping that I've overlooked something very obvious! I moved from a single Apple OS X 10.6.2 server Dovecot environment to a NFS clustered environment, currently with two servers. Both servers are identical hardware, software. Currently both the Dovecot index and data files are on the NFS RAID array. Both servers are configured to work with NFS per the Dovecot guides. The index and data files are accessed via a target link to the NFS mount via /var/spool/imap/dovecot. Email can be sent and received via either server and there are no errors being reported (both platforms are in debug mode). In essence everything appears to be working fine.
The issue is that after the index is initially built (all email timestamps are correct) however any new incoming email is timestamped: 8 July 2037 23:53
I checked the index files: drwx------ 5 XXXX mail 4096 Nov 12 20:41 .UND -rw------- 1 XXXX staff 1472 Nov 13 12:30 .nfs.2005105c.0583 -rw------- 2 XXXX mail 56668 Nov 13 15:44 .nfs.200514ff.0583 -rw------- 2 XXXX mail 1364 Nov 13 15:44 .nfs.20051500.0583 drwx------ 2 XXXX mail 12288 Nov 13 15:44 cur -rw------- 1 XXXX mail 118 Nov 13 10:04 dovecot-keywords -rw------- 1 XXXX staff 5359 Nov 13 15:44 dovecot-uidlist -rw------- 1 XXXX staff 8 Nov 12 21:12 dovecot-uidvalidity -rw------- 1 XXXX mail 0 Jul 8 2037 dovecot-uidvalidity.4afc7a3a -rw------- 1 XXXX staff 1472 Nov 13 15:44 dovecot.index -rw------- 2 XXXX mail 56668 Nov 13 15:44 dovecot.index.cache -rw------- 2 XXXX mail 1364 Nov 13 15:44 dovecot.index.log -rw------- 1 XXXX mail 3859 Nov 13 15:47 maildirsize drwx------ 2 XXXX mail 4096 Nov 13 15:44 new -rw------- 1 XXXX mail 902 Nov 1 14:07 subscriptions drwx------ 2 XXXX mail 4096 Nov 13 15:44 tmp
When checking the "stand alone" old data - the files are all correctly dated.
This issue is the same for all users.
Any ideas?
Many thanks,
Darren
sh-3.2# /usr/sbin/dovecotd -n # 1.1.17apple0.5: /private/etc/dovecot/dovecot.conf Warning: fd limit 256 is lower than what Dovecot can use under full load (more than 456). Either grow the limit or change login_max_processes_count and max_mail_processes settings # OS: Darwin 10.0.0 i386 nfs base_dir: /var/run/dovecot syslog_facility: local6 protocols: managesieve imaps listen(default): * listen(imap): * listen(managesieve): *:2000 ssl_cert_file: /etc/certificates/X.X.org.X.cert.pem ssl_key_file: /etc/certificates/X.X.org.X.key.pem ssl_cipher_list: ALL:!LOW:!SSLv2:!aNULL:!ADH:!eNULL login_dir: /var/run/dovecot/login login_executable(default): /usr/libexec/dovecot/imap-login login_executable(imap): /usr/libexec/dovecot/imap-login login_executable(managesieve): /usr/libexec/dovecot/managesieve-login login_user: _dovecot login_process_per_connection: no max_mail_processes: 200 mail_max_userip_connections(default): 20 mail_max_userip_connections(imap): 20 mail_max_userip_connections(managesieve): 10 verbose_proctitle: yes first_valid_uid: 6 first_valid_gid: 6 mail_access_groups: mail mail_location: maildir:/var/spool/imap/dovecot/mail/%u mail_debug: yes mmap_disable: yes dotlock_use_excl: no mail_nfs_storage: yes mail_nfs_index: yes lock_method: dotlock mbox_read_locks: fcntl dotlock mbox_write_locks: fcntl dotlock mail_executable(default): /usr/libexec/dovecot/imap mail_executable(imap): /usr/libexec/dovecot/imap mail_executable(managesieve): /usr/libexec/dovecot/managesieve mail_process_sharing(default): full mail_process_sharing(imap): full mail_process_sharing(managesieve): none mail_max_connections(default): 5 mail_max_connections(imap): 5 mail_max_connections(managesieve): 20 mail_plugins(default): quota imap_quota mail_plugins(imap): quota imap_quota mail_plugins(managesieve): mail_plugin_dir(default): /usr/lib/dovecot/imap mail_plugin_dir(imap): /usr/lib/dovecot/imap mail_plugin_dir(managesieve): /usr/lib/dovecot/managesieve sieve_storage(default): sieve_storage(imap): sieve_storage(managesieve): /var/spool/imap/dovecot/sieve-scripts/%u sieve(default): sieve(imap): sieve(managesieve): /var/spool/imap/dovecot/sieve-scripts/%u/dovecot.sieve auth default: mechanisms: gssapi cram-md5 verbose: yes debug: yes debug_passwords: yes passdb: driver: od userdb: driver: od args: partition=/etc/dovecot/partition_map.conf enforce_quotas=no socket: type: listen master: path: /var/run/dovecot/auth-master mode: 384 user: _dovecot group: mail plugin: quota_warning: storage=100%% /usr/libexec/dovecot/quota-exceeded.sh quota: maildir:User quota sieve: /var/spool/imap/dovecot/sieve-scripts/%u/dovecot.sieve
Further update..
Volumes of emails arriving - hits either server, some will be correctly received with date/time, others time stamped with 8 July 2037, 23:53 Same server could give either the correct or the 2037 timestamp.
Again, no errors being reported in the logs.
Any ideas?
Many thanks,
Darren
On 13 Nov 2009, at 16:10, Darren Latter wrote:
Hi,
I've run into a bit of a problem and exhausted my knowledge and research. I'm hoping that I've overlooked something very obvious! I moved from a single Apple OS X 10.6.2 server Dovecot environment to a NFS clustered environment, currently with two servers. Both servers are identical hardware, software. Currently both the Dovecot index and data files are on the NFS RAID array. Both servers are configured to work with NFS per the Dovecot guides. The index and data files are accessed via a target link to the NFS mount via /var/spool/imap/dovecot. Email can be sent and received via either server and there are no errors being reported (both platforms are in debug mode). In essence everything appears to be working fine.
The issue is that after the index is initially built (all email timestamps are correct) however any new incoming email is timestamped: 8 July 2037 23:53
I checked the index files: drwx------ 5 XXXX mail 4096 Nov 12 20:41 .UND -rw------- 1 XXXX staff 1472 Nov 13 12:30 .nfs.2005105c.0583 -rw------- 2 XXXX mail 56668 Nov 13 15:44 .nfs.200514ff.0583 -rw------- 2 XXXX mail 1364 Nov 13 15:44 .nfs.20051500.0583 drwx------ 2 XXXX mail 12288 Nov 13 15:44 cur -rw------- 1 XXXX mail 118 Nov 13 10:04 dovecot-keywords -rw------- 1 XXXX staff 5359 Nov 13 15:44 dovecot-uidlist -rw------- 1 XXXX staff 8 Nov 12 21:12 dovecot-uidvalidity -rw------- 1 XXXX mail 0 Jul 8 2037 dovecot-uidvalidity.4afc7a3a -rw------- 1 XXXX staff 1472 Nov 13 15:44 dovecot.index -rw------- 2 XXXX mail 56668 Nov 13 15:44 dovecot.index.cache -rw------- 2 XXXX mail 1364 Nov 13 15:44 dovecot.index.log -rw------- 1 XXXX mail 3859 Nov 13 15:47 maildirsize drwx------ 2 XXXX mail 4096 Nov 13 15:44 new -rw------- 1 XXXX mail 902 Nov 1 14:07 subscriptions drwx------ 2 XXXX mail 4096 Nov 13 15:44 tmp
When checking the "stand alone" old data - the files are all correctly dated.
This issue is the same for all users.
Any ideas?
Many thanks,
Darren
sh-3.2# /usr/sbin/dovecotd -n # 1.1.17apple0.5: /private/etc/dovecot/dovecot.conf Warning: fd limit 256 is lower than what Dovecot can use under full load (more than 456). Either grow the limit or change login_max_processes_count and max_mail_processes settings # OS: Darwin 10.0.0 i386 nfs base_dir: /var/run/dovecot syslog_facility: local6 protocols: managesieve imaps listen(default): * listen(imap): * listen(managesieve): *:2000 ssl_cert_file: /etc/certificates/X.X.org.X.cert.pem ssl_key_file: /etc/certificates/X.X.org.X.key.pem ssl_cipher_list: ALL:!LOW:!SSLv2:!aNULL:!ADH:!eNULL login_dir: /var/run/dovecot/login login_executable(default): /usr/libexec/dovecot/imap-login login_executable(imap): /usr/libexec/dovecot/imap-login login_executable(managesieve): /usr/libexec/dovecot/managesieve-login login_user: _dovecot login_process_per_connection: no max_mail_processes: 200 mail_max_userip_connections(default): 20 mail_max_userip_connections(imap): 20 mail_max_userip_connections(managesieve): 10 verbose_proctitle: yes first_valid_uid: 6 first_valid_gid: 6 mail_access_groups: mail mail_location: maildir:/var/spool/imap/dovecot/mail/%u mail_debug: yes mmap_disable: yes dotlock_use_excl: no mail_nfs_storage: yes mail_nfs_index: yes lock_method: dotlock mbox_read_locks: fcntl dotlock mbox_write_locks: fcntl dotlock mail_executable(default): /usr/libexec/dovecot/imap mail_executable(imap): /usr/libexec/dovecot/imap mail_executable(managesieve): /usr/libexec/dovecot/managesieve mail_process_sharing(default): full mail_process_sharing(imap): full mail_process_sharing(managesieve): none mail_max_connections(default): 5 mail_max_connections(imap): 5 mail_max_connections(managesieve): 20 mail_plugins(default): quota imap_quota mail_plugins(imap): quota imap_quota mail_plugins(managesieve): mail_plugin_dir(default): /usr/lib/dovecot/imap mail_plugin_dir(imap): /usr/lib/dovecot/imap mail_plugin_dir(managesieve): /usr/lib/dovecot/managesieve sieve_storage(default): sieve_storage(imap): sieve_storage(managesieve): /var/spool/imap/dovecot/sieve-scripts/%u sieve(default): sieve(imap): sieve(managesieve): /var/spool/imap/dovecot/sieve-scripts/%u/dovecot.sieve auth default: mechanisms: gssapi cram-md5 verbose: yes debug: yes debug_passwords: yes passdb: driver: od userdb: driver: od args: partition=/etc/dovecot/partition_map.conf enforce_quotas=no socket: type: listen master: path: /var/run/dovecot/auth-master mode: 384 user: _dovecot group: mail plugin: quota_warning: storage=100%% /usr/libexec/dovecot/quota-exceeded.sh quota: maildir:User quota sieve: /var/spool/imap/dovecot/sieve-scripts/%u/dovecot.sieve
On Fri, 2009-11-13 at 20:15 +0000, Darren Latter wrote:
Further update..
Volumes of emails arriving - hits either server, some will be correctly received with date/time, others time stamped with 8 July 2037, 23:53 Same server could give either the correct or the 2037 timestamp.
What are the files' mtimes? What happens if you delete dovecot.index.cache file and retry?
Hi Timo,
When deleting the index files they get regenerated with the current time. All email in the inbox then is shown with correct time.
-rw------- 2 XX mail 9924 Nov 13 20:21 .nfs.20052ab0.544d -rw------- 2 XX mail 67584 Nov 13 20:21 .nfs.20052ab3.544d drwx------ 2 XX mail 16384 Nov 13 20:20 cur -rw------- 1 XX mail 244 Nov 13 20:20 dovecot-keywords -rw------- 1 XX staff 5060 Nov 13 20:20 dovecot-uidlist -rw------- 1 XX staff 8 Nov 13 20:20 dovecot-uidvalidity -rw------- 1 XX mail 0 Jul 8 2037 dovecot-uidvalidity.4afdbfa4 -rw------- 1 XX staff 1688 Nov 13 20:21 dovecot.index -rw------- 2 XX mail 67584 Nov 13 20:21 dovecot.index.cache -rw------- 2 XX mail 9924 Nov 13 20:21 dovecot.index.log
New incoming email still has same issue - the email client will show either the correct time or the 2037 date. When checking the email headers - dates/times are correct.
Thanks,
Darren
On 13 Nov 2009, at 20:18, Timo Sirainen wrote:
On Fri, 2009-11-13 at 20:15 +0000, Darren Latter wrote:
Further update..
Volumes of emails arriving - hits either server, some will be correctly received with date/time, others time stamped with 8 July 2037, 23:53 Same server could give either the correct or the 2037 timestamp.
What are the files' mtimes? What happens if you delete dovecot.index.cache file and retry?
On Fri, 2009-11-13 at 20:25 +0000, Darren Latter wrote:
Hi Timo,
When deleting the index files they get regenerated with the current time. All email in the inbox then is shown with correct time.
-rw------- 2 XX mail 9924 Nov 13 20:21 .nfs.20052ab0.544d -rw------- 2 XX mail 67584 Nov 13 20:21 .nfs.20052ab3.544d drwx------ 2 XX mail 16384 Nov 13 20:20 cur -rw------- 1 XX mail 244 Nov 13 20:20 dovecot-keywords -rw------- 1 XX staff 5060 Nov 13 20:20 dovecot-uidlist -rw------- 1 XX staff 8 Nov 13 20:20 dovecot-uidvalidity -rw------- 1 XX mail 0 Jul 8 2037 dovecot-uidvalidity.4afdbfa4 -rw------- 1 XX staff 1688 Nov 13 20:21 dovecot.index -rw------- 2 XX mail 67584 Nov 13 20:21 dovecot.index.cache -rw------- 2 XX mail 9924 Nov 13 20:21 dovecot.index.log
The mail files are in new/ or cur/ directory. Those are the timestamps that matter, not the ones above.
New incoming email still has same issue - the email client will show either the correct time or the 2037 date. When checking the email headers - dates/times are correct.
Do you have idxview utility somewhere (probably in the same dir as e.g. imap binary)? You could then see what "idxview dovecot.index" says. Anyway, this sounds like a NFS-related bug. Dovecot gets saved message's time by fstat()ing the created file. Sounds like the fstat() returns mtime in future.. Probably because the hasn't actually been flushed to disk because it hasn't been close()d or fsync()ed yet.
I could probably write a patch to Dovecot that fsync()s first, then fstat()s to get the mtime. But since you're using Apple's Dovecot version that probably wouldn't help much.
On Nov 13, 2009, at 2:15 PM, Darren Latter wrote:
Volumes of emails arriving - hits either server, some will be
correctly received with date/time, others time stamped with 8 July
2037, 23:53 Same server could give either the correct or the 2037 timestamp.
It's a long shot, but are the emails that contain the errant date/time
stamp being created by any php mail routine? We ask because we've
seen similar issues with dates from a PEAR/Date library that's not php
v5.3 compliant.
B. Bodger
Hi Bruce,
OS X 10.6 Server uses Postfix and Dovecot so no PHP that I'm aware of - but thanks for the thought! I'm wondering if Apple have "enhanced" Dovecot for XSAN clustering/integration? I know that there are several parameters in the dovecot.conf file (mail file locations, index status) that are overridden by other Apple files.
On 13 Nov 2009, at 20:23, Bruce Bodger wrote:
On Nov 13, 2009, at 2:15 PM, Darren Latter wrote:
Volumes of emails arriving - hits either server, some will be correctly received with date/time, others time stamped with 8 July 2037, 23:53 Same server could give either the correct or the 2037 timestamp.
It's a long shot, but are the emails that contain the errant date/time stamp being created by any php mail routine? We ask because we've seen similar issues with dates from a PEAR/Date library that's not php v5.3 compliant.
B. Bodger
participants (4)
-
Bruce Bodger
-
Darren Latter
-
Darren Latter
-
Timo Sirainen