dovecot - Sep 2011 - error in logs, but system appears to work

I'm bringing up a system with dovecot that has been running for years with
uw-imap. In making the
switch, I put a tail on the log file, made the switch, and sent a test mail and
received it. I was
able to receive mail with no apparent difficulties, but the log file was
disconcerting. A number of
users connected during the few minutes I had it running, and for each of them
there was an error,
e.g., "chown ~user/mail/.imap/INBOX failed: Operation not permitted"
and "mkdir
~user/mail/.imap/INBOX failed: not owner". But those directories and files
appeared to have been
made. The first of those errors finishes with "group based on
/var/mail/user". That makes no sense.

I'm hoping someone can give me an idea what might cause this.

Here are the log entries in debug mode and the directories for one such user:

Sep  2 17:31:33 eclogite dovecot: [ID 583609 local2.info] auth(default): new
auth connection: pid=7248
Sep  2 17:31:43 eclogite dovecot: [ID 583609 local2.info] auth(default): client
in: AUTH        1       PLAIN   service=pop3    secured lip=128.119.45.20      
rip=128.119.45.9        lport=995       rport=53865    
resp=AGVicmFkbGV5AFJvd2luZzEzKg=Sep  2 17:31:43 eclogite dovecot: [ID 583609
local2.info] auth(default): shadow(ebradley,128.119.45.9): lookup
Sep  2 17:31:43 eclogite dovecot: [ID 583609 local2.info] auth(default): client
out: OK 1       user=ebradley
Sep  2 17:31:43 eclogite dovecot: [ID 583609 local2.info] auth(default): master
in: REQUEST     37      7248    1
Sep  2 17:31:43 eclogite dovecot: [ID 583609 local2.info] auth(default):
passwd(ebradley,128.119.45.9): lookup
Sep  2 17:31:43 eclogite dovecot: [ID 583609 local2.info] auth(default): master
out: USER       37      ebradley        system_groups_user=ebradley     uid=6633
gid=100 home=/u1/home/grad/ebradley
Sep  2 17:31:43 eclogite dovecot: [ID 583609 local2.info] POP3(ebradley):
Effective uid=6633, gid=100, home=/u1/home/grad/ebradley
Sep  2 17:31:43 eclogite dovecot: [ID 583609 local2.info] POP3(ebradley): mbox:
data=~/mail:INBOX=/var/mail/ebradley
Sep  2 17:31:43 eclogite dovecot: [ID 583609 local2.info] POP3(ebradley): fs:
root=/u1/home/grad/ebradley/mail, index=, control=, inbox=/var/mail/ebradley
Sep  2 17:31:43 eclogite dovecot: [ID 583609 local2.info] POP3(ebradley):
Namespace : Using permissions from /u1/home/grad/ebradley/mail: mode=0700 gid=-1
Sep  2 17:31:43 eclogite dovecot: [ID 583609 local2.error] POP3(ebradley):
chown(/u1/home/grad/ebradley/mail/.imap/INBOX, -1, 6(mail)) failed: Operation
not permitted (egid=100(geolgrad), group based on /var/mail/ebradley)
Sep  2 17:31:43 eclogite dovecot: [ID 583609 local2.error] POP3(ebradley):
mkdir(/u1/home/grad/ebradley/mail/.imap/INBOX) failed: Not owner
Sep  2 17:31:43 eclogite dovecot: [ID 583609 local2.info] pop3-login: Login:
user=<ebradley>, method=PLAIN, rip=128.119.45.9, lip=128.119.45.20, TLS

When I looked at their home directory, I found:

drwx------   4 ebradley geolgrad     512 Jul 28  2009 /u1/home/grad/ebradley
drwx------   4 ebradley geolgrad     512 Sep  2 17:31
/u1/home/grad/ebradley/mail
drwx------   3 ebradley geolgrad     512 Sep  2 17:31
/u1/home/grad/ebradley/mail/.imap
drwxrwx---   2 ebradley geolgrad     512 Sep  2 17:31
/u1/home/grad/ebradley/mail/.imap/INBOX

-rw-rw----   1 ebradley mail     9484323 Sep  6 15:16 /var/mail/ebradley
  

My dovecot configuration is at the end. The other pieces are sendmail,
milter-greylist, mimedefang, etc.

-- 
---------------

Chris Hoogendyk

-
    O__  ---- Systems Administrator
   c/ /'_ --- Biology&  Geology Departments
  (*) \(*) -- 140 Morrill Science Center
~~~~~~~~~~ - University of Massachusetts, Amherst

<hoogendyk at bio.umass.edu>

---------------

Erd?s 4



# dovecot -a

# 1.2.17: /usr/local/etc/dovecot.conf
Warning: fd limit 256 is lower than what Dovecot can use under full load (more
than 768). Either grow the limit or change login_max_processes_count and
max_mail_processes settings
# OS: SunOS 5.9 sun4u
base_dir: /var/run/dovecot/
log_path:
info_log_path:
log_timestamp: %b %d %H:%M:%S
syslog_facility: local2
protocols: imaps pop3s
listen: *
ssl_listen: *
ssl: required
ssl_ca_file: /etc/mail/certs/ca-bundle.crt
ssl_cert_file: /etc/mail/certs/sendmail.pem
ssl_key_file: /etc/mail/certs/sendmail.pem
ssl_key_password:
ssl_parameters_regenerate: 168
ssl_cipher_list:
ssl_cert_username_field: commonName
ssl_verify_client_cert: no
disable_plaintext_auth: yes
verbose_ssl: no
shutdown_clients: yes
nfs_check: yes
version_ignore: 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_user: dovecot
login_greeting: ready.
login_log_format_elements: user=<%u>  method=%m rip=%r lip=%l %c
login_log_format: %$: %s
login_process_per_connection: yes
login_chroot: yes
login_trusted_networks:
login_process_size: 64
login_processes_count: 3
login_max_processes_count: 128
login_max_connections: 256
valid_chroot_dirs:
mail_chroot:
max_mail_processes: 512
mail_max_userip_connections(default): 10
mail_max_userip_connections(imap): 10
mail_max_userip_connections(pop3): 3
verbose_proctitle: no
first_valid_uid: 1000
last_valid_uid: 0
first_valid_gid: 98
last_valid_gid: 0
mail_access_groups:
mail_privileged_group: mail
mail_uid:
mail_gid:
mail_location: mbox:~/mail:INBOX=/var/mail/%u
mail_cache_fields:
mail_never_cache_fields: imap.envelope
mail_cache_min_mail_count: 0
mailbox_idle_check_interval: 30
mail_debug: yes
mail_full_filesystem_access: no
mail_max_keyword_length: 50
mail_save_crlf: no
mmap_disable: no
dotlock_use_excl: yes
fsync_disable: no
mail_nfs_storage: no
mail_nfs_index: no
mailbox_list_index_disable: yes
lock_method: fcntl
maildir_stat_dirs: no
maildir_copy_with_hardlinks: yes
maildir_copy_preserve_filename: no
maildir_very_dirty_syncs: no
mbox_read_locks: fcntl
mbox_write_locks: dotlock fcntl
mbox_lock_timeout: 300
mbox_dotlock_change_timeout: 120
mbox_min_index_size: 0
mbox_dirty_syncs: yes
mbox_very_dirty_syncs: no
mbox_lazy_writes: yes
dbox_rotate_size: 2048
dbox_rotate_min_size: 16
dbox_rotate_days: 1
mail_drop_priv_before_exec: no
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_process_size: 256
mail_plugins:
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_log_prefix: %Us(%u):
mail_log_max_lines_per_sec: 10
imap_max_line_length: 65536
imap_capability:
imap_client_workarounds:
imap_logout_format: bytes=%i/%o
imap_id_send:
imap_id_log:
imap_idle_notify_interval: 120
pop3_no_flag_updates: no
pop3_enable_last: no
pop3_reuse_xuidl(default): no
pop3_reuse_xuidl(imap): no
pop3_reuse_xuidl(pop3): yes
pop3_save_uidl: no
pop3_lock_session: no
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
pop3_logout_format: top=%t/%p, retr=%r/%b, del=%d/%m, size=%s
dict_db_config:
dict_process_count: 1
auth default:
   mechanisms: plain
   realms:
   default_realm:
   cache_size: 0
   cache_ttl: 3600
   cache_negative_ttl: 3600
   executable: /usr/local/libexec/dovecot/dovecot-auth
   user: root
   chroot:
   username_chars:
abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ01234567890.-_
   username_translation:
   username_format:
   master_user_separator:
   anonymous_username: anonymous
   krb5_keytab:
   gssapi_hostname:
   winbind_helper_path: /usr/bin/ntlm_auth
   failure_delay: 2
   verbose: yes
   debug: yes
   debug_passwords: yes
   ssl_require_client_cert: no
   ssl_username_from_cert: no
   use_winbind: no
   count: 1
   worker_max_count: 30
   process_size: 256
   passdb:
     driver: shadow
     args:
     deny: no
     pass: no
     master: no
   userdb:
     driver: passwd
     args:

#

On 6.9.2011, at 22.35, Chris Hoogendyk wrote:
> -rw-rw----   1 ebradley mail     9484323 Sep  6 15:16 /var/mail/ebradley
Is there any reason for this to be 0660? Most likely not, so your problem goes
away simply with chmod 0600 /var/mail/* and at the same time makes your system
more secure.

Chris Hoogendyk writes:
> So, looking at my other system that has been running dovecot for over a
> year, I see that the entries are mostly 0600, but there are a few 0660.
> The system I was just implementing has mostly 0660, but some 0600.  We
> had seen occasional similar errors on the other system.
Been there, done that.  Timo already gave an explanation of why 0600
gets rid of the problem.  I'll add a reminder that you'll need to
track down the reason why mailboxes are created user:mail/0660 in the
first place.  It's usually done by the LDA when creating a brand new
mailbox (for example, Solaris's mail.local).

If you've replaced your LDA with Dovecot's deliver, then this won't
be
a problem anymore.

You may also have to scour your userbase's personal mail collection for
mailboxes that has 1) mode 0660, and 2) group membership the user is
not a part of, and fix up the permissions.  Such a thing could happen
if you've reassigned a user's GID.

Joseph Tam <jtam.home at gmail.com>