dovecot - May 2009 - pop3 gives a permission denied error on chdir

hi,

I am running debian lenny standard install and dovecot also as a standard 
install. I have a problem with POP3 access. The error message is:

May 19 09:16:10 greenchilly dovecot: chdir(/home/vmail/example.com/john) 
failed with uid 5000: Permission denied
May 19 09:16:10 greenchilly dovecot: child 26253 (pop3) returned error 89
May 19 09:16:10 greenchilly dovecot: pop3-login: Login: 
user=<john at example.com>, method=PLAIN, rip=127.0.0.1, lip=127.0.0.1,
secured

I have looked at the archives and see that the problem has been reported 
before, but cannot find any solution. Dovecot as LDA has no problem accessing 
and writing mails to the directory as UID 5000. I suspect that it is trying to 
access some other directory and the error message is misleading. The directory 
/home/vmail/example.com/john is owned by user vmail with UID 5000. Any clues?

my config:

greenchilly:/etc/dovecot# dovecot -n
# 1.0.15: /etc/dovecot/dovecot.conf 
log_timestamp: %Y-%m-%d %H:%M:%S    
protocols: imap imaps pop3 pop3s    
login_dir: /var/run/dovecot/login   
login_executable(default): /usr/lib/dovecot/imap-login
login_executable(imap): /usr/lib/dovecot/imap-login   
login_executable(pop3): /usr/lib/dovecot/pop3-login   
mail_privileged_group: mail                           
mail_location: maildir:/home/vmail/%d/%n/Maildir      
mail_executable(default): /usr/lib/dovecot/imap       
mail_executable(imap): /usr/lib/dovecot/imap
mail_executable(pop3): /usr/lib/dovecot/pop3
mail_plugin_dir(default): /usr/lib/dovecot/modules/imap
mail_plugin_dir(imap): /usr/lib/dovecot/modules/imap
mail_plugin_dir(pop3): /usr/lib/dovecot/modules/pop3
pop3_uidl_format(default):
pop3_uidl_format(imap):
pop3_uidl_format(pop3): %08Xu%08Xv
auth default:
  mechanisms: plain login
  passdb:
    driver: sql
    args: /etc/dovecot/dovecot-sql.conf
  userdb:
    driver: passwd
  userdb:
    driver: static
    args: uid=5000 gid=5000 home=/home/vmail/%d/%n allow_all_users=yes
  socket:
    type: listen
    client:
      path: /var/spool/postfix/private/auth
      mode: 432
      user: postfix
      group: postfix
    master:
      path: /var/run/dovecot/auth-master
      mode: 384
      user: vmail

-- 
regards
Kenneth Gonsalves
Associate
NRC-FOSS
http://nrcfosshelpline.in/web/

On Tue, 2009-05-19 at 13:35 +0530, Kenneth Gonsalves
wrote:
> May 19 09:16:10 greenchilly dovecot: chdir(/home/vmail/example.com/john) 
> failed with uid 5000: Permission denied
..
> I have looked at the archives and see that the problem has been reported 
> before, but cannot find any solution. Dovecot as LDA has no problem
accessing
> and writing mails to the directory as UID 5000. I suspect that it is trying
to
> access some other directory and the error message is misleading. The
directory
> /home/vmail/example.com/john is owned by user vmail with UID 5000. Any
clues?
And all the directories before that are also available for that user?
Are you using NFS? Are you using SELinux or something? Anyway that
chdir() syscall really failed with that error message. The reason for
that is less clear then.. v1.1+ would give a much nicer error message
here telling exactly what is wrong..

-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 197 bytes
Desc: This is a digitally signed message part
URL:
<http://dovecot.org/pipermail/dovecot/attachments/20090519/7fa1f395/attachment-0002.bin>

On Wednesday 20 May 2009 01:20:37 you wrote:
> On Tue, 2009-05-19 at 13:35 +0530, Kenneth Gonsalves wrote:
> > May 19 09:16:10 greenchilly dovecot:
chdir(/home/vmail/example.com/john)
> > failed with uid 5000: Permission denied
>
> ..
>
> > I have looked at the archives and see that the problem has been
reported
> > before, but cannot find any solution. Dovecot as LDA has no problem
> > accessing and writing mails to the directory as UID 5000. I suspect
that
> > it is trying to access some other directory and the error message is
> > misleading. The directory /home/vmail/example.com/john is owned by
user
> > vmail with UID 5000. Any clues?
>
> And all the directories before that are also available for that user?
yes
> Are you using NFS? Are you using SELinux or something? 
no
> Anyway that
> chdir() syscall really failed with that error message. The reason for
> that is less clear then.. v1.1+ would give a much nicer error message
> here telling exactly what is wrong..
I have installed version 1.1.13, here is the mail log:

May 20 10:33:54 greenchilly dovecot: auth(default): new auth connection: 
pid=1181
May 20 10:34:07 greenchilly dovecot: auth(default): client in: 
AUTH^I1^IPLAIN^Iservice=pop3^Isecured^Ilip=127.0.0.1^Irip=127.0.0.1^Ilport=110^Irport=42418^Iresp=<hidden>
May 20 10:34:07 greenchilly dovecot: auth-worker(default): 
pam(john at example.com,127.0.0.1): lookup service=dovecot
May 20 10:34:07 greenchilly dovecot: auth-worker(default): 
pam(john at example.com,127.0.0.1): #1/1 style=1 msg=Password:
May 20 10:34:10 greenchilly dovecot: auth-worker(default): 
pam(john at example.com,127.0.0.1): unknown user
May 20 10:34:10 greenchilly dovecot: auth(default): 
sql(john at example.com,127.0.0.1): query: SELECT email as user, passwd as 
password FROM view_users WHERE email='john at example.com';
May 20 10:34:10 greenchilly dovecot: auth(default): client out: 
OK^I1^Iuser=john at example.com
May 20 10:34:10 greenchilly dovecot: auth(default): master in: 
REQUEST^I3^I1166^I1
May 20 10:34:10 greenchilly dovecot: auth(default): 
passwd(john at example.com,127.0.0.1): lookup
May 20 10:34:10 greenchilly dovecot: auth(default): 
passwd(john at example.com,127.0.0.1): unknown user
May 20 10:34:10 greenchilly dovecot: auth(default): master out: 
USER^I3^Ijohn at
example.com^Iuid=5000^Igid=5000^Ihome=/home/vmail/example.com/john
May 20 10:34:10 greenchilly dovecot: Fatal: 
chdir(/home/vmail/example.com/john) failed with uid 5000: Permission denied
May 20 10:34:10 greenchilly dovecot: child 1182 (pop3) returned error 89 
(Fatal failure)
May 20 10:34:10 greenchilly dovecot: pop3-login: Login: 
user=<john at example.com>, method=PLAIN, rip=127.0.0.1, lip=127.0.0.1,
secured

and here is the session info:

lawgon at greenchilly:~$ telnet localhost pop3
Trying 127.0.0.1...
Connected to localhost.localdomain.
Escape character is '^]'.
+OK Dovecot ready.
user john at example.com
+OK
pass summersun
+OK Logged in.
Connection closed by foreign host.

-- 
regards
Kenneth Gonsalves
Associate
NRC-FOSS
http://nrcfosshelpline.in/web/

On Thursday 21 May 2009 12:40:00 you wrote:
> exec "strace -f -o /tmp/access.log -etrace=file -p
<pid_of_dovecot>"
> then try to access pop3 when fail occurs send us /tmp/access.log
> (gzipped)
attached

-- 
regards
Kenneth Gonsalves
Associate
NRC-FOSS
http://nrcfosshelpline.in/web/
-------------- next part --------------
A non-text attachment was scrubbed...
Name: access.log.gz
Type: application/x-gzip
Size: 595 bytes
Desc: not available
URL:
<http://dovecot.org/pipermail/dovecot/attachments/20090521/68336a1d/attachment-0002.gz>

On Thursday 21 May 2009 12:51:11 Kenneth Gonsalves
wrote:
> On Thursday 21 May 2009 12:40:00 you wrote:
> > exec "strace -f -o /tmp/access.log -etrace=file -p
<pid_of_dovecot>"
> > then try to access pop3 when fail occurs send us /tmp/access.log
> > (gzipped)
>
> attached
were you able to detect anything? I am still stuck with the problem.
-- 
regards
Kenneth Gonsalves
Associate
NRC-FOSS
http://nrcfosshelpline.in/web/

On May 25, 2009, at 7:16 AM, Kenneth Gonsalves wrote:
> On Thursday 21 May 2009 12:51:11 Kenneth Gonsalves wrote:
>> On Thursday 21 May 2009 12:40:00 you wrote:
>>> exec "strace -f -o /tmp/access.log -etrace=file -p
<pid_of_dovecot>"
>>> then try to access pop3 when fail occurs send us /tmp/access.log
>>> (gzipped)
>>
>> attached
>
> were you able to detect anything? I am still stuck with the problem.
Well, strace says what Dovecot also says:

5598  chdir("/home/vmail/example.com/john") = -1 EACCES (Permission  
denied)