1 Topic by ghaecker

  • ghaecker
  • Member
  • Offline
  • Registered: 2015-06-19
  • Posts: 20

Topic: Dovecot login fails for non-admin account

==== Required information ====
- iRedMail version (check /etc/iredmail-release): 0.9.2
- Linux/BSD distribution name and version: RHEL 6.6
- Store mail accounts in which backend (LDAP/MySQL/PGSQL): MySQL
- Web server (Apache or Nginx): Apache
- Manage mail accounts with iRedAdmin-Pro? SQL-2.1.2
- Related log if you're reporting an issue: dovecot.log
====

postmaster/admin account logs into iRedMail with no problem.

Non-admin account fails after logging out of successful login.

Here's the failed login:

Jun 25 04:53:36 auth-worker(63151): Info: mysql(127.0.0.1): Connected to database vmail
Jun 25 04:53:38 imap-login: Info: Disconnected (auth failed, 1 attempts in 2 secs): user=<somesuscriber@ma.securimate.com>, method=PLAIN, rip=127.0.0.1, lip=127.0.0.1, secured, session=<C6z+Z1AZJQB/AAAB>

Here's the successful login.

Jun 25 04:34:59 auth-worker(61934): Info: mysql(127.0.0.1): Connected to database vmail
Jun 25 04:34:59 imap-login: Info: Login: user=<postmaster@ma.securimate.com>, method=PLAIN, rip=127.0.0.1, lip=127.0.0.1, mpid=61935, secured, session=<kJFrJVAZwAB/AAAB>
Jun 25 04:34:59 dict: Info: mysql(127.0.0.1): Connected to database vmail
Jun 25 04:34:59 imap(postmaster@ma.securimate.com): Info: Disconnected: Logged out in=248 out=941
Jun 25 04:34:59 imap-login: Info: Login: user=<postmaster@ma.securimate.com>, method=PLAIN, rip=127.0.0.1, lip=127.0.0.1, mpid=61938, secured, session=<hnhvJVAZxAB/AAAB>
Jun 25 04:34:59 imap(postmaster@ma.securimate.com): Info: Disconnected: Logged out in=70 out=758
Jun 25 04:35:00 imap-login: Info: Login: user=<postmaster@ma.securimate.com>, method=PLAIN, rip=127.0.0.1, lip=127.0.0.1, mpid=61941, secured, session=<hOl9JVAZxgB/AAAB>
Jun 25 04:35:00 imap-login: Info: Login: user=<postmaster@ma.securimate.com>, method=PLAIN, rip=127.0.0.1, lip=127.0.0.1, mpid=61943, secured, session=<2wR+JVAZyAB/AAAB>
Jun 25 04:35:00 dict: Info: mysql(127.0.0.1): Connected to database vmail
Jun 25 04:35:00 imap(postmaster@ma.securimate.com): Info: Disconnected: Logged out in=358 out=5070
Jun 25 04:35:00 imap(postmaster@ma.securimate.com): Info: Disconnected: Logged out in=312 out=1137
Jun 25 04:35:14 imap-login: Info: Login: user=<postmaster@ma.securimate.com>, method=PLAIN, rip=127.0.0.1, lip=127.0.0.1, mpid=61949, secured, session=<YXRLJlAZzQB/AAAB>
Jun 25 04:35:14 imap(postmaster@ma.securimate.com): Info: Disconnected: Logged out in=344 out=2898
Jun 25 04:35:17 imap-login: Info: Login: user=<postmaster@ma.securimate.com>, method=PLAIN, rip=127.0.0.1, lip=127.0.0.1, mpid=61952, secured, session=<hNuAJlAZzwB/AAAB>
Jun 25 04:35:17 imap(postmaster@ma.securimate.com): Info: Disconnected: Logged out in=358 out=5070
Jun 25 04:35:57 imap-login: Info: Login: user=<postmaster@ma.securimate.com>, method=PLAIN, rip=127.0.0.1, lip=127.0.0.1, mpid=61960, secured, session=<i87lKFAZ0gB/AAAB>
Jun 25 04:35:57 imap(postmaster@ma.securimate.com): Info: Disconnected: Logged out in=248 out=941
Jun 25 04:35:58 imap-login: Info: Login: user=<postmaster@ma.securimate.com>, method=PLAIN, rip=127.0.0.1, lip=127.0.0.1, mpid=61962, secured, session=<dC3pKFAZ1AB/AAAB>
Jun 25 04:35:58 imap(postmaster@ma.securimate.com): Info: Disconnected: Logged out in=70 out=758
Jun 25 04:35:59 imap-login: Info: Login: user=<postmaster@ma.securimate.com>, method=PLAIN, rip=127.0.0.1, lip=127.0.0.1, mpid=61965, secured, session=<qSL6KFAZ1gB/AAAB>
Jun 25 04:35:59 imap-login: Info: Login: user=<postmaster@ma.securimate.com>, method=PLAIN, rip=127.0.0.1, lip=127.0.0.1, mpid=61967, secured, session=<Q1/6KFAZ2AB/AAAB>
Jun 25 04:35:59 dict: Info: mysql(127.0.0.1): Connected to database vmail
Jun 25 04:35:59 imap(postmaster@ma.securimate.com): Info: Disconnected: Logged out in=358 out=5070
Jun 25 04:35:59 imap(postmaster@ma.securimate.com): Info: Disconnected: Logged out in=312 out=1137
Jun 25 04:43:41 auth-worker(62519): Info: mysql(127.0.0.1): Connected to database vmail
Jun 25 04:43:41 imap-login: Info: Login: user=<postmaster@ma.securimate.com>, method=PLAIN, rip=127.0.0.1, lip=127.0.0.1, mpid=62520, secured, session=<S9+HRFAZ9gB/AAAB>
Jun 25 04:43:41 dict: Info: mysql(127.0.0.1): Connected to database vmail
Jun 25 04:43:41 imap(postmaster@ma.securimate.com): Info: Disconnected: Logged out in=248 out=941
Jun 25 04:43:41 imap-login: Info: Login: user=<postmaster@ma.securimate.com>, method=PLAIN, rip=127.0.0.1, lip=127.0.0.1, mpid=62523, secured, session=<QgGMRFAZ+gB/AAAB>
Jun 25 04:43:41 imap(postmaster@ma.securimate.com): Info: Disconnected: Logged out in=70 out=758
Jun 25 04:43:42 imap-login: Info: Login: user=<postmaster@ma.securimate.com>, method=PLAIN, rip=127.0.0.1, lip=127.0.0.1, mpid=62526, secured, session=<70mbRFAZ/AB/AAAB>
Jun 25 04:43:42 imap-login: Info: Login: user=<postmaster@ma.securimate.com>, method=PLAIN, rip=127.0.0.1, lip=127.0.0.1, mpid=62528, secured, session=<FmubRFAZ/gB/AAAB>
Jun 25 04:43:42 dict: Info: mysql(127.0.0.1): Connected to database vmail
Jun 25 04:43:42 imap(postmaster@ma.securimate.com): Info: Disconnected: Logged out in=312 out=1137
Jun 25 04:43:42 imap(postmaster@ma.securimate.com): Info: Disconnected: Logged out in=358 out=5070
Jun 25 04:44:42 auth-worker(62580): Info: mysql(127.0.0.1): Connected to database vmail
Jun 25 04:44:42 imap-login: Info: Login: user=<postmaster@ma.securimate.com>, method=PLAIN, rip=127.0.0.1, lip=127.0.0.1, mpid=62581, secured, session=<VPEvSFAZBwB/AAAB>
Jun 25 04:44:42 imap(postmaster@ma.securimate.com): Info: Disconnected: Logged out in=531 out=3118

----

Spider Email Archiver: On-Premises, lightweight email archiving software developed by iRedMail team. Supports Amazon S3 compatible storage and custom branding.

2 Reply by ZhangHuangbin

  • ZhangHuangbin
  • ZhangHuangbin
  • iRedMail Developers
  • Offline
  • Registered: 2009-05-06
  • Posts: 31,088

Re: Dovecot login fails for non-admin account

Please turn on debug mode in Dovecot, login again, then paste related log in Dovecot log file.
Reference: http://www.iredmail.org/docs/debug.dovecot.html

3 Reply by ghaecker (edited by ghaecker 2015-06-25 15:28:39)

  • ghaecker
  • Member
  • Offline
  • Registered: 2015-06-19
  • Posts: 20

Re: Dovecot login fails for non-admin account

debug revealed a misspelled username copied from my notes.  Succeeded when I typed it correctly; failed when I copied and pasted from notes.  My fault - sorry about that.

However, with debug still enabled for dovecot,

acl owner 1     looks fine.
acl owner 0     files not found?  Is this something that needs to be addressed?

Jun 25 05:29:37 auth: Debug: auth client connected (pid=65140)
Jun 25 05:29:37 auth: Debug: client in: AUTH    1    PLAIN    service=imap    secured    session=hpPH6FAZ1wB/AAAB    lip=127.0.0.1    rip=127.0.0.1    lport=143    rport=34263    resp=*****THIS_PART_IS_CORRECT******
Jun 25 05:29:37 auth-worker(65141): Debug: Loading modules from directory: /usr/lib64/dovecot/auth
Jun 25 05:29:37 auth-worker(65141): Debug: Module loaded: /usr/lib64/dovecot/auth/libdriver_mysql.so
Jun 25 05:29:37 auth-worker(65141): Debug: Module loaded: /usr/lib64/dovecot/auth/libdriver_pgsql.so
Jun 25 05:29:37 auth-worker(65141): Debug: Module loaded: /usr/lib64/dovecot/auth/libdriver_sqlite.so
Jun 25 05:29:37 auth-worker(65141): Debug: passwd-file /etc/dovecot/dovecot-master-users: Read 1 users in 0 secs
Jun 25 05:29:37 auth-worker(65141): Info: mysql(127.0.0.1): Connected to database vmail
Jun 25 05:29:37 auth-worker(65141): Debug: sql(somesubscriber@ma.securimate.com,127.0.0.1): query: SELECT password, allow_nets FROM mailbox WHERE username='somesubscriber@ma.securimate.com' AND enableimapsecured=1 AND active=1
Jun 25 05:29:37 auth: Debug: client passdb out: OK    1    user=somesubscriber@ma.securimate.com
Jun 25 05:29:37 auth: Debug: master in: REQUEST    3428581377    65140    1    755e74873d0ad4aab22b32debf3579d8
Jun 25 05:29:37 auth-worker(65141): Debug: sql(somesubscriber@ma.securimate.com,127.0.0.1): SELECT 'somesubscriber@ma.securimate.com' AS master_user, CONCAT(mailbox.storagebasedirectory, '/', mailbox.storagenode, '/', mailbox.maildir) AS home, CONCAT('*:bytes=', mailbox.quota*1048576) AS quota_rule FROM mailbox,domain WHERE mailbox.username='somesubscriber@ma.securimate.com' AND mailbox.domain='ma.securimate.com' AND mailbox.`enableimapsecured`=1 AND mailbox.domain=domain.domain AND domain.backupmx=0 AND domain.active=1 AND mailbox.active=1
Jun 25 05:29:37 auth: Debug: master userdb out: USER    3428581377    somesubscriber@ma.securimate.com    master_user=somesubscriber@ma.securimate.com    home=/var/vmail/vmail1/ma.securimate.com/s/o/m/somesubscriber-2015.06.23.11.29.57/    quota_rule=*:bytes=0
Jun 25 05:29:37 imap: Debug: Loading modules from directory: /usr/lib64/dovecot
Jun 25 05:29:37 imap-login: Info: Login: user=<somesubscriber@ma.securimate.com>, method=PLAIN, rip=127.0.0.1, lip=127.0.0.1, mpid=65142, secured, session=<hpPH6FAZ1wB/AAAB>
Jun 25 05:29:37 imap: Debug: Module loaded: /usr/lib64/dovecot/lib01_acl_plugin.so
Jun 25 05:29:37 imap: Debug: Module loaded: /usr/lib64/dovecot/lib02_imap_acl_plugin.so
Jun 25 05:29:37 imap: Debug: Module loaded: /usr/lib64/dovecot/lib10_quota_plugin.so
Jun 25 05:29:37 imap: Debug: Module loaded: /usr/lib64/dovecot/lib11_imap_quota_plugin.so
Jun 25 05:29:37 imap: Debug: Module loaded: /usr/lib64/dovecot/lib20_autocreate_plugin.so
Jun 25 05:29:37 imap: Debug: Added userdb setting: plugin/master_user=somesubscriber@ma.securimate.com
Jun 25 05:29:37 imap: Debug: Added userdb setting: plugin/quota_rule=*:bytes=0
Jun 25 05:29:37 imap(somesubscriber@ma.securimate.com): Debug: Effective uid=2000, gid=2000, home=/var/vmail/vmail1/ma.securimate.com/s/o/m/somesubscriber-2015.06.23.11.29.57/
Jun 25 05:29:37 imap(somesubscriber@ma.securimate.com): Debug: Quota root: name=user backend=dict args=:proxy::quotadict
Jun 25 05:29:37 imap(somesubscriber@ma.securimate.com): Debug: Quota rule: root=user mailbox=* bytes=0 messages=0
Jun 25 05:29:37 imap(somesubscriber@ma.securimate.com): Debug: Quota warning: bytes=0 (85%) messages=0 reverse=no command=quota-warning 85 somesubscriber@ma.securimate.com
Jun 25 05:29:37 imap(somesubscriber@ma.securimate.com): Debug: Quota warning: bytes=0 (90%) messages=0 reverse=no command=quota-warning 90 somesubscriber@ma.securimate.com
Jun 25 05:29:37 imap(somesubscriber@ma.securimate.com): Debug: Quota warning: bytes=0 (95%) messages=0 reverse=no command=quota-warning 95 somesubscriber@ma.securimate.com
Jun 25 05:29:37 imap(somesubscriber@ma.securimate.com): Debug: dict quota: user=somesubscriber@ma.securimate.com, uri=proxy::quotadict, noenforcing=0
Jun 25 05:29:37 imap(somesubscriber@ma.securimate.com): Debug: Namespace : type=private, prefix=, sep=/, inbox=yes, hidden=no, list=yes, subscriptions=yes location=maildir:/var/vmail/vmail1/ma.securimate.com/s/o/m/somesubscriber-2015.06.23.11.29.57//Maildir/:INDEX=/var/vmail/vmail1/ma.securimate.com/s/o/m/somesubscriber-2015.06.23.11.29.57//Maildir/
Jun 25 05:29:37 imap(somesubscriber@ma.securimate.com): Debug: maildir++: root=/var/vmail/vmail1/ma.securimate.com/s/o/m/somesubscriber-2015.06.23.11.29.57//Maildir, index=, control=, inbox=/var/vmail/vmail1/ma.securimate.com/s/o/m/somesubscriber-2015.06.23.11.29.57//Maildir, alt=
Jun 25 05:29:37 imap(somesubscriber@ma.securimate.com): Debug: acl: initializing backend with data: vfile
Jun 25 05:29:37 imap(somesubscriber@ma.securimate.com): Debug: acl: acl username = somesubscriber@ma.securimate.com
Jun 25 05:29:37 imap(somesubscriber@ma.securimate.com): Debug: acl: owner = 1
Jun 25 05:29:37 imap(somesubscriber@ma.securimate.com): Debug: acl vfile: Global ACL directory: (none)
Jun 25 05:29:37 imap(somesubscriber@ma.securimate.com): Debug: Namespace : type=shared, prefix=Shared/%u/, sep=/, inbox=no, hidden=no, list=children, subscriptions=yes location=maildir:%Lh/Maildir/:INDEX=%Lh/Maildir/Shared/%u
Jun 25 05:29:37 imap(somesubscriber@ma.securimate.com): Debug: shared: root=/var/run/dovecot, index=, control=, inbox=, alt=
Jun 25 05:29:37 imap(somesubscriber@ma.securimate.com): Debug: acl: initializing backend with data: vfile
Jun 25 05:29:37 imap(somesubscriber@ma.securimate.com): Debug: acl: acl username = somesubscriber@ma.securimate.com
Jun 25 05:29:37 imap(somesubscriber@ma.securimate.com): Debug: acl: owner = 0
Jun 25 05:29:37 imap(somesubscriber@ma.securimate.com): Debug: acl vfile: Global ACL directory: (none)
Jun 25 05:29:37 imap(somesubscriber@ma.securimate.com): Debug: acl vfile: file /var/vmail/vmail1/ma.securimate.com/s/o/m/somesubscriber-2015.06.23.11.29.57//Maildir/dovecot-acl not found
Jun 25 05:29:37 imap(somesubscriber@ma.securimate.com): Debug: acl vfile: file /var/vmail/vmail1/ma.securimate.com/s/o/m/somesubscriber-2015.06.23.11.29.57//Maildir/.Sent/dovecot-acl not found
Jun 25 05:29:37 imap(somesubscriber@ma.securimate.com): Debug: acl vfile: file /var/vmail/vmail1/ma.securimate.com/s/o/m/somesubscriber-2015.06.23.11.29.57//Maildir/.Trash/dovecot-acl not found
Jun 25 05:29:37 imap(somesubscriber@ma.securimate.com): Debug: acl vfile: file /var/vmail/vmail1/ma.securimate.com/s/o/m/somesubscriber-2015.06.23.11.29.57//Maildir/.Drafts/dovecot-acl not found
Jun 25 05:29:37 imap(somesubscriber@ma.securimate.com): Debug: acl vfile: file /var/vmail/vmail1/ma.securimate.com/s/o/m/somesubscriber-2015.06.23.11.29.57//Maildir/.Junk/dovecot-acl not found
Jun 25 05:29:37 imap(somesubscriber@ma.securimate.com): Info: Disconnected: Logged out in=339 out=1782

4 Reply by ZhangHuangbin

  • ZhangHuangbin
  • ZhangHuangbin
  • iRedMail Developers
  • Offline
  • Registered: 2009-05-06
  • Posts: 31,088

Re: Dovecot login fails for non-admin account

ghaecker wrote:

However, with debug still enabled for dovecot,
acl owner 1     looks fine.
acl owner 0     files not found?  Is this something that needs to be addressed?

Safe to ignore this log.

5 Reply by ghaecker

  • ghaecker
  • Member
  • Offline
  • Registered: 2015-06-19
  • Posts: 20

Re: Dovecot login fails for non-admin account

This topic can be closed.