[Dovecot] Test environment question
My production DC machine owns the mail filesystems and is running DC V1.0.15 and mbox folder format. I am looking to test V1.1.3 on another machine, which NFS mounts the mail filesystems, but has its own local index FS.
I have made this test environment my default connection in TBird, and it seems to work just fine. Also, I have made sure that my TBird client isn't connecting to the production server (it has multiple accounts but I have turned off the cehck for mail when starting and check for new mail every N minutes functions, and then check the ps table to make sure there are no imap connections) However, I'm seeing two errmsgs in the maillog on the test machine:
Sep 22 11:54:13 egg mail:err|error dovecot: IMAP(sdean): posix_fallocate() faile d: Protocol not available Sep 22 11:54:13 egg mail:err|error dovecot: IMAP(sdean): file_set_size() failed with mbox file /var/spool/mail/sdean: Protocol not available which appear to happen AFTER mail arrives at the production server....it seems to happen on my test server the next time my client goes to access mail AFTER mail has arrived at the production server. Subsequent client requests of the test server execute without error until AFTER the next time mail arrives at and my inbox is updated with it.
Again, if I hadn't looked at the logs, I wouldn't know there was a problem...I can see my new mail just fine from the test server.
The questions: Is this anything I should be concerned about? Is this a bug or a legit problem coming from my improper use of two servers against the same data.
FWIW, I am using fcntl for both mbox read and write locks. procmail in
the MDA on the production server, and its locking hierarchy
Thanks!
Production dovecot -n output:
# 1.0.15: /usr/local/etc/dovecot.conf listen: *:143 ssl_listen: *:993 disable_plaintext_auth: no verbose_ssl: yes login_dir: /var/run/dovecot/login login_executable: /usr/local/libexec/dovecot/imap-login login_processes_count: 12 login_max_processes_count: 774 verbose_proctitle: yes first_valid_uid: 200 mail_location: mbox:~/mail:INBOX=/var/spool/mail/%u:INDEX=/var/dcindx/%u mbox_write_locks: fcntl mbox_dirty_syncs: no auth default: passdb: driver: pam userdb: driver: passwd Test dovecot -n output: # 1.1.3: /usr/local/etc/dovecot.conf listen: *:143 ssl_listen: *:993 disable_plaintext_auth: no verbose_ssl: yes login_dir: /var/run/dovecot/login login_executable: /usr/local/libexec/dovecot/imap-login login_processes_count: 12 login_max_processes_count: 774 max_mail_processes: 1024 verbose_proctitle: yes first_valid_uid: 200 mail_location: mbox:~/mail:INBOX=/var/spool/mail/%u:INDEX=/var/dcindx/%u mbox_write_locks: fcntl mbox_dirty_syncs: no auth default: passdb: driver: pam userdb: driver: passwd
On Mon, 2008-09-22 at 13:04 -0400, Stewart Dean wrote:
Sep 22 11:54:13 egg mail:err|error dovecot: IMAP(sdean): posix_fallocate() faile d: Protocol not available
See if this helps: http://hg.dovecot.org/dovecot-1.1/rev/ad13463328aa
Timo Sirainen wrote:
On Mon, 2008-09-22 at 13:04 -0400, Stewart Dean wrote:
Sep 22 11:54:13 egg mail:err|error dovecot: IMAP(sdean): posix_fallocate() faile d: Protocol not available
See if this helps: http://hg.dovecot.org/dovecot-1.1/rev/ad13463328aa
My apologies for not getting back to you...I was sick and out last week and am not exactly shining brightly this week :)
Sep 30 13:24:13 egg mail:info dovecot: Dovecot v1.1.3 starting up Sep 30 13:24:26 egg mail:info dovecot: imap-login: Login: user=<sdean>, method=P LAIN, rip=10.20.10.169, lip=192.246.229.31 Sep 30 13:24:28 egg mail:info dovecot: imap-login: Login: user=<sdean>, method=P LAIN, rip=10.20.10.169, lip=192.246.229.31 Sep 30 13:24:30 egg mail:err|error dovecot: IMAP(sdean): mbox sync: UID inserted in the middle of mailbox /var/spool/mail/sdean (646581 > 646564, seq=1125, idx_ msgs=1126) Sep 30 13:24:31 egg mail:err|error dovecot: IMAP(sdean): mbox sync: UID inserted in the middle of mailbox /var/spool/mail/sdean (646581 > 646564, seq=1125, idx_ msgs=1126) Sep 30 13:24:33 egg mail:err|error dovecot: IMAP(sdean): posix_fallocate() faile d: File exists Sep 30 13:24:33 egg mail:err|error dovecot: IMAP(sdean): file_set_size() failed with mbox file /var/spool/mail/sdean: File exists Sep 30 13:24:35 egg mail:err|error dovecot: IMAP(sdean): posix_fallocate() faile d: File exists Sep 30 13:24:35 egg mail:err|error dovecot: IMAP(sdean): file_set_size() failed with mbox file /var/spool/mail/sdean: File exists Sep 30 13:25:37 egg mail:info dovecot: ssl-build-param: SSL parameters regenerat ion completed Sep 30 13:27:42 egg mail:info dovecot: imap-login: Login: user=<sdean>, method=P LAIN, rip=10.20.10.169, lip=192.246.229.31 Sep 30 13:30:28 egg mail:info dovecot: imap-login: Login: user=<sdean>, method=P LAIN, rip=10.20.10.169, lip=192.246.229.31 I would assume that, when the test server started up, the index and such stuff it had from the last time it was run was grossly out of synch and
I rebuilt with the patch you specified. I made sure that my imap session from my TBird client to my production (DC V1.0.15) server was shut down, that it was reconfigured NOT to periodically look for mail, and I have rechecked since then to make sure that there are no session in the PS table for it. When I started up on my DC V1.1.3 test server, I got the following messages: that this is therefore just DC on the test server setting things right.
Since then, as I wrote a message, DC on the test machine coughed out an errmsg relating to the Drafts folder, which again makes sense as it also likely out of sync:
Sep 30 13:49:25 egg mail:info dovecot: imap-login: Login: user=<sdean>, method=P LAIN, rip=10.20.10.169, lip=192.246.229.31 Sep 30 13:51:03 egg mail:err|error dovecot: IMAP(sdean): mbox sync: UID inserted in the middle of mailbox /home/hcrc/sdean/mail/Drafts (9422 > 9403, seq=607, id x_msgs=651) Sep 30 13:51:04 egg mail:err|error dovecot: IMAP(sdean): mbox sync: UID inserted in the middle of mailbox /home/hcrc/sdean/mail/Drafts (9422 > 9403, seq=607, id x_msgs=651) Sep 30 13:53:45 egg mail:info dovecot: IMAP(sdean): Disconnected: Logged out byt es=73/3631 So there are two possibilities
- That this just happens once (for any given folder), as long as the test DC server is the only one to ride heard on the folders and/or
- even so, these messages shouldn't happen and something is wrong.
I will watch it carefully for a day and see if I can confirm that #1 is true........
I have attached my original note with its copies of the dovecot -n output for both machines
I have V1.1 running on a test server that NFS mounts mbox-formatted inbox and home folder dirs. I have eliminated the profile listing for connection to the V1.0 production servers so that can't start up and corrupt the synch of the test servers indices
I am seeing posix_fallocate and file_set_size errmsgs in the mail syslog, but see a pattern:
- They only happen with the /var/spool/mail inbox NOT with any of the /home folders and appear to be happening every 10 minutes from the time I started DC (9AM, 10/1/98) until 11AM, 10/2...and then ceased The every ten minute message sets looked like this:
Oct 1 22:30:31 egg mail:err|error dovecot: IMAP(sdean): posix_fallocate() failed: Resource temporarily unavailable Oct 1 22:30:31 egg mail:err|error dovecot: IMAP(sdean): file_set_size() failed with mbox file /var/spool/mail/sdean: Resource temporarily unavailable Oct 1 22:40:31 egg mail:err|error dovecot: IMAP(sdean): posix_fallocate() failed: Resource temporarily unavailable Oct 1 22:40:31 egg mail:err|error dovecot: IMAP(sdean): file_set_size() failed with mbox file /var/spool/mail/sdean: Resource temporarily unavailable Oct 1 22:50:31 egg mail:err|error dovecot: IMAP(sdean): posix_fallocate() failed: Resource temporarily unavailable
My Thunderbird client's server settings are set to check for mail every 10 minutes AND I don't access the mail overnight, so it this must be causing it! I did check the crontabs on both my test and production servers and they had nothing with this time periodicity
However, then there was the following: a) If I used webmail, which accessed the production server and got the indices on my test server out of sync, I got this error message from in the mail syslog on my test server:
Oct 3 12:20:23 egg mail:err|error dovecot: IMAP(sdean): mbox sync: UID inserted in the middle of mailbox /var/spool/mail/sdean (648818 > 648046, seq=1153, idx_ msgs=1187) Which is what one would expect...once the V1.1 code is on production server that won't happen anymore, so that's OK and can be ignored b) I seem to end up having leftover imap session on the test server. Around 1PM today, I was unable to get mail and saw these messages in the test server's mail syslog: Oct 3 12:44:58 egg mail:info dovecot: imap-login: Maximum number of connections from user+IP exceeded: user=<sdean>, method=PLAIN, rip=10.20.10.169, lip=192.24 6.229.31 Turns out I had 10+ sessions, one back from yesterday, so I killed them all and could get mail, but...about six minutes later, I had the two posix_fallocate and file_set_size errmsgs again after not having any for a day. So something about new connections maybe causes this?
Any ideas why: a) I am having leftover IMAP sessions on my test server? This doesn't happen on my production DC V1.0 server b) Ditto on the the posix_fallocate and file_set_size errmsgs which also aren't found on my production server's mail syslog. ?
I do realize that these seem to be related to Tbird, but they don't happen with V1.0....
I have attached my original note with its copies of the dovecot -n output for both machines
On Fri, 2008-10-03 at 14:33 -0400, Stewart Dean wrote:
I am seeing posix_fallocate and file_set_size errmsgs in the mail syslog, but see a pattern:
- They only happen with the /var/spool/mail inbox NOT with any of the /home folders and appear to be happening every 10 minutes from the time I started DC (9AM, 10/1/98) until 11AM, 10/2...and then ceased The every ten minute message sets looked like this:
Oct 1 22:30:31 egg mail:err|error dovecot: IMAP(sdean): posix_fallocate() failed: Resource temporarily unavailable
The main problem here is that posix_fallocate() is broken in your AIX (v1.0 doesn't even try to use it). My previous patch attempted to make Dovecot detect this and silently fallback to not using it, but apparently it can fail in more ways. I thought about adding another check for EAGAIN, but perhaps posix_fallocate() just returns the previous errno so it can't be checked that way. So I moved the check to configure instead:
http://hg.dovecot.org/dovecot-1.1/rev/12565ef10d1c
Alternatively you could just remove HAVE_POSIX_FALLOCATE from config.h after running configure. Or yet another way would be to try to find out if it's already been fixed in AIX. This looks related: http://www-01.ibm.com/support/docview.wss?uid=isg1IY77112
- However, then there was the following: a) If I used webmail, which accessed the production server and got the indices on my test server out of sync, I got this error message from in the mail syslog on my test server:
Oct 3 12:20:23 egg mail:err|error dovecot: IMAP(sdean): mbox sync: UID inserted in the middle of mailbox /var/spool/mail/sdean (648818 > 648046, seq=1153, idx_ msgs=1187)
v1.1 also has a bug that can cause this, although normally it should be visible only when index files aren't being used, or they're out of sync for some reason. This'll fix it: http://hg.dovecot.org/dovecot-1.1/rev/a5bf7e12f3cc
Oct 3 12:44:58 egg mail:info dovecot: imap-login: Maximum number of connections from user+IP exceeded: user=<sdean>, method=PLAIN, rip=10.20.10.169, lip=192.24 6.229.31 Turns out I had 10+ sessions, one back from yesterday, so I killed them all and could get mail, but...about six minutes later, I had the two posix_fallocate and file_set_size errmsgs again after not having any for a day. So something about new connections maybe causes this?
Any ideas why: a) I am having leftover IMAP sessions on my test server? This doesn't happen on my production DC V1.0 server
Are you sure? Perhaps you just didn't notice them since v1.0 didn't have any limits to how many were allowed? I think it's more likely that the client(s) really just left that many connections. So the choices are:
a) Increase mail_max_userip_connections setting.
b) Figure out where the sessions are from and see if you can do something about them on the client side. In Thunderbird there's a setting which specifies how many connections it can use.
I have a call open to IBM with their Compiler group on this to see if this can't be fixed right. A side question: how come is it that this happens when the session starts up and reoccurs periodically for the first day or so...and then not again unless and until those imap process sessions are closed out
Timo Sirainen wrote:
On Fri, 2008-10-03 at 14:33 -0400, Stewart Dean wrote:
I am seeing posix_fallocate and file_set_size errmsgs in the mail syslog, but see a pattern:
- They only happen with the /var/spool/mail inbox NOT with any of the /home folders and appear to be happening every 10 minutes from the time I started DC (9AM, 10/1/98) until 11AM, 10/2...and then ceased The every ten minute message sets looked like this:
Oct 1 22:30:31 egg mail:err|error dovecot: IMAP(sdean): posix_fallocate() failed: Resource temporarily unavailable
The main problem here is that posix_fallocate() is broken in your AIX (v1.0 doesn't even try to use it). My previous patch attempted to make Dovecot detect this and silently fallback to not using it, but apparently it can fail in more ways. I thought about adding another check for EAGAIN, but perhaps posix_fallocate() just returns the previous errno so it can't be checked that way. So I moved the check to configure instead:
http://hg.dovecot.org/dovecot-1.1/rev/12565ef10d1c
Alternatively you could just remove HAVE_POSIX_FALLOCATE from config.h after running configure. Or yet another way would be to try to find out if it's already been fixed in AIX. This looks related: http://www-01.ibm.com/support/docview.wss?uid=isg1IY77112
- However, then there was the following: a) If I used webmail, which accessed the production server and got the indices on my test server out of sync, I got this error message from in the mail syslog on my test server:
Oct 3 12:20:23 egg mail:err|error dovecot: IMAP(sdean): mbox sync: UID inserted in the middle of mailbox /var/spool/mail/sdean (648818 > 648046, seq=1153, idx_ msgs=1187)
v1.1 also has a bug that can cause this, although normally it should be visible only when index files aren't being used, or they're out of sync for some reason. This'll fix it: http://hg.dovecot.org/dovecot-1.1/rev/a5bf7e12f3cc
Oct 3 12:44:58 egg mail:info dovecot: imap-login: Maximum number of connections from user+IP exceeded: user=<sdean>, method=PLAIN, rip=10.20.10.169, lip=192.24 6.229.31
Turns out I had 10+ sessions, one back from yesterday, so I killed them all and could get mail, but...about six minutes later, I had the two posix_fallocate and file_set_size errmsgs again after not having any for a day. So something about new connections maybe causes this?
Any ideas why: a) I am having leftover IMAP sessions on my test server? This doesn't happen on my production DC V1.0 server
Are you sure? Perhaps you just didn't notice them since v1.0 didn't have any limits to how many were allowed? I think it's more likely that the client(s) really just left that many connections. So the choices are:
a) Increase mail_max_userip_connections setting.
b) Figure out where the sessions are from and see if you can do something about them on the client side. In Thunderbird there's a setting which specifies how many connections it can use.
The code has some checks that if posix_fallocate() fails with a
specific errno it stops trying to use it. Maybe it hits that condition
at some point. Or maybe the code just isn't called for some reason, I
don't really know..
On Oct 9, 2008, at 6:45 PM, Stewart Dean wrote:
I have a call open to IBM with their Compiler group on this to see
if this can't be fixed right. A side question: how come is it that
this happens when the session starts up and reoccurs periodically
for the first day or so...and then not again unless and until those
imap process sessions are closed outTimo Sirainen wrote:
On Fri, 2008-10-03 at 14:33 -0400, Stewart Dean wrote:
I am seeing posix_fallocate and file_set_size errmsgs in the mail
syslog, but see a pattern:
- They only happen with the /var/spool/mail inbox NOT with any of
the /home folders and appear to be happening every 10 minutes from the time
I started DC (9AM, 10/1/98) until 11AM, 10/2...and then ceased The every ten minute message sets looked like this:Oct 1 22:30:31 egg mail:err|error dovecot: IMAP(sdean):
posix_fallocate() failed: Resource temporarily unavailableThe main problem here is that posix_fallocate() is broken in your AIX (v1.0 doesn't even try to use it). My previous patch attempted to
make Dovecot detect this and silently fallback to not using it, but apparently it can fail in more ways. I thought about adding another check for EAGAIN, but perhaps posix_fallocate() just returns the previous errno so it can't be checked that way. So I moved the
check to configure instead:http://hg.dovecot.org/dovecot-1.1/rev/12565ef10d1c
Alternatively you could just remove HAVE_POSIX_FALLOCATE from
config.h after running configure. Or yet another way would be to try to find
out if it's already been fixed in AIX. This looks related: http://www-01.ibm.com/support/docview.wss?uid=isg1IY77112
- However, then there was the following: a) If I used webmail, which accessed the production server and got
the indices on my test server out of sync, I got this error message from in
the mail syslog on my test server:Oct 3 12:20:23 egg mail:err|error dovecot: IMAP(sdean): mbox
sync: UID inserted in the middle of mailbox /var/spool/mail/sdean (648818 > 648046,
seq=1153, idx_ msgs=1187)v1.1 also has a bug that can cause this, although normally it
should be visible only when index files aren't being used, or they're out of
sync for some reason. This'll fix it: http://hg.dovecot.org/dovecot-1.1/rev/a5bf7e12f3ccOct 3 12:44:58 egg mail:info dovecot: imap-login: Maximum number
of connections from user+IP exceeded: user=<sdean>, method=PLAIN,
rip=10.20.10.169, lip=192.24 6.229.31Turns out I had 10+ sessions, one back from yesterday, so I killed
them all and could get mail, but...about six minutes later, I had the two
posix_fallocate and file_set_size errmsgs again after not having any for a day. So
something about new connections maybe causes this?Any ideas why: a) I am having leftover IMAP sessions on my test server? This
doesn't happen on my production DC V1.0 serverAre you sure? Perhaps you just didn't notice them since v1.0 didn't
have any limits to how many were allowed? I think it's more likely that
the client(s) really just left that many connections. So the choices are:a) Increase mail_max_userip_connections setting.
b) Figure out where the sessions are from and see if you can do something about them on the client side. In Thunderbird there's a setting which specifies how many connections it can use.
participants (2)
-
Stewart Dean
-
Timo Sirainen