Squirrelmail/dovecot authentication error

Discussion in 'General' started by Sharone, Jul 23, 2020.

  1. Sharone

    Sharone Member

    Hi there,
    I'm having trouble authenticating new accounts or reset passwords on Squirrelmail. Existing accounts are fine until a password is reset. I suspect the problem might be with dovecot and/or MySQL or worse, mail server not talking to the db server (master). I'm running a multiserver setup on Ubuntu 18.04, ISPConfig v3.1.5p3.

    Code:
    [email protected]:~# tail -f /var/log/syslog 
    Jul 22 13:39:21 mail-20 dovecot: auth-worker(6980): Debug: sql([email protected],127.0.0.1,<Po9HWgWrlJx/AAAB>): query: SELECT email as user, password, maildir as userdb_home, CONCAT( maildir_format, ':', maildir, '/', IF(maildir_format='maildir','Maildir',maildir_format)) as userdb_mail, uid as userdb_uid, gid as userdb_gid, CONCAT('*:storage=', quota, 'B') AS userdb_quota_rule, CONCAT(maildir, '/.sieve') as userdb_sieve FROM mail_user WHERE (login = '[email protected]' OR email = '[email protected]') AND `disableimap` = 'n' AND server_id = '2'
    
    Jul 22 13:39:21 mail dovecot: auth-worker(6980): sql([email protected],127.0.0.1,<Po9HWgWrlJx/AAAB>): unknown user
    
    Jul 22 13:39:23 mail dovecot: auth: Debug: client passdb out: FAIL#0111#[email protected]
    
    Jul 22 13:39:23 mail dovecot: imap-login: Aborted login (auth failed, 1 attempts in 2 secs): user=<[email protected]>, method=PLAIN, rip=127.0.0.1, lip=127.0.0.1, secured, session=<Po9HWgWrlJx/AAAB>
    Code:
    [email protected]:~# dovecot -n
    # 2.2.27 (c0f36b0): /usr/local/etc/dovecot/dovecot.conf
    # OS: Linux 5.3.0-61-generic x86_64 Ubuntu 18.04.4 LTS
    auth_mechanisms = plain login
    disable_plaintext_auth = no
    listen = *,[::]
    log_timestamp = "%Y-%m-%d %H:%M:%S "
    mail_max_userip_connections = 100
    mail_plugins = " quota"
    mail_privileged_group = vmail
    passdb {
      args = /etc/dovecot/dovecot-sql.conf
      driver = sql
    }
    plugin {
      quota = dict:user::file:/var/vmail/%d/%n/.quotausage
      sieve = /var/vmail/%d/%n/.sieve
      sieve_max_redirects = 25
    }
    postmaster_address = [email protected]
    protocols = imap pop3
    service auth {
      unix_listener /var/spool/postfix/private/auth {
        group = postfix
        mode = 0660
        user = postfix
      }
      unix_listener auth-userdb {
        group = vmail
        mode = 0600
        user = vmail
      }
      user = root
    }
    service imap-login {
      client_limit = 1000
      process_limit = 512
    }
    service lmtp {
      unix_listener /var/spool/postfix/private/dovecot-lmtp {
        group = postfix
        mode = 0600
        user = postfix
      }
    }
    ssl_cert = </etc/postfix/smtpd.cert
    ssl_key =  # hidden, use -P to show it
    userdb {
      driver = prefetch
    }
    userdb {
      args = /etc/dovecot/dovecot-sql.conf
      driver = sql
    }
    protocol imap {
      mail_plugins = quota imap_quota
    }
    protocol pop3 {
      mail_plugins = quota
      pop3_uidl_format = %08Xu%08Xv
    }
    protocol lda {
      mail_plugins = sieve quota
      postmaster_address = [email protected]
    }
    protocol lmtp {
      mail_plugins = quota sieve
      postmaster_address = [email protected]
    }
    MySQL error logs

    Code:
    2020-07-23T13:09:00.439896+03:00 213097 [Note] Aborted connection 213097 to db: 'dbispconfig' user: 'ispconfig' host: 'localhost' (Got an error reading communication packets)
    2020-07-23T13:09:00.439934+03:00 213049 [Note] Aborted connection 213049 to db: 'dbispconfig' user: 'ispconfig' host: 'localhost' (Got an error reading communication packets)
    2020-07-23T13:09:00.439982+03:00 213048 [Note] Aborted connection 213048 to db: 'dbispconfig' user: 'ispconfig' host: 'localhost' (Got an error reading communication packets)
    2020-07-23T13:09:00.439896+03:00 213096 [Note] Aborted connection 213096 to db: 'dbispconfig' user: 'ispconfig' host: 'localhost' (Got an error reading communication packets)
    2020-07-23T13:09:00.439916+03:00 213050 [Note] Aborted connection 213050 to db: 'dbispconfig' user: 'ispconfig' host: 'localhost' (Got an error reading communication packets)
    2020-07-23T13:09:31.909295+03:00 213084 [Note] Aborted connection 213084 to db: 'dbispconfig' user: 'ispconfig' host: 'localhost' (Got an error reading communication packets)
    2020-07-23T13:09:31.909345+03:00 213067 [Note] Aborted connection 213067 to db: 'dbispconfig' user: 'ispconfig' host: 'localhost' (Got an error reading communication packets)
    2020-07-23T13:09:31.909347+03:00 213072 [Note] Aborted connection 213072 to db: 'dbispconfig' user: 'ispconfig' host: 'localhost' (Got an error reading communication packets)
    2020-07-23T13:09:31.909364+03:00 213068 [Note] Aborted connection 213068 to db: 'dbispconfig' user: 'ispconfig' host: 'localhost' (Got an error reading communication packets)
    2020-07-23T13:09:31.909295+03:00 213083 [Note] Aborted connection 213083 to db: 'dbispconfig' user: 'ispconfig' host: 'localhost' (Got an error reading communication packets)
    
    Any pointers will help
     
  2. till

    till Super Moderator Staff Member ISPConfig Developer

    Check if the password has in master and slave database is the same.
     
  3. Sharone

    Sharone Member

    Yes I can authenticate to the db on the slave and master using the same credentials.
     
  4. till

    till Super Moderator Staff Member ISPConfig Developer

    That's not what I meant. You said that it might be that the changed password does not get populated to the database on the slave. Therefore it might be useful to know if the password on the slave is the same than the one on the master, the easiest way to check that is by having a look in the mail_user table, select an affected user and check if the password hash stored in the password column is the same.
     
  5. Sharone

    Sharone Member

    The passwords are different. I also just realized that some email accounts added after the recent upgrade to the ISPConfig portal do not exist in the mail server database. I have resynced several times on the portal.
     
  6. till

    till Super Moderator Staff Member ISPConfig Developer

  7. Sharone

    Sharone Member

    This is what I got from running server.sh
    Code:
    [email protected]:~# /usr/local/ispconfig/server/server.sh
    
    
    23.07.2020-19:20 - DEBUG - Remove Lock: /usr/local/ispconfig/server/temp/.ispconfig_lock
    finished.
    
     
  8. Taleman

    Taleman Well-Known Member HowtoForge Supporter

    That shows there was nothing to do. Are you sure you ran it on the correct server that had pending jobs?
     
  9. Sharone

    Sharone Member

    Yes I enabled debug and run the command on the mail server (slave)
     
  10. Jesse Norell

    Jesse Norell ISPConfig Developer Staff Member ISPConfig Developer

    Make sure the /usr/local/ispconfig/server/plugins-enabled/postfix_server_plugin.inc.php symlink exists (to the plugins-available file) on the slave.
     
  11. Sharone

    Sharone Member

    Yes I see symlinks although I'm not certain whether the date matters?
    Code:
    [email protected]:~# ll /usr/local/ispconfig/server/plugins-enabled/
    total 64
    drwxr-x---  2 root root 4096 Jun 22 11:36 ./
    drwxr-x--- 13 root root 4096 Jun 22 11:36 ../
    lrwxrwxrwx  1 root root   67 Jun 23  2016 backup_plugin.inc.php -> /usr/local/ispconfig/server/plugins-available/backup_plugin.inc.php*
    -rwxr-x---  1 root root   45 Jul  3 12:09 empty.dir*
    lrwxrwxrwx  1 root root   69 Jun 23  2016 firewall_plugin.inc.php -> /usr/local/ispconfig/server/plugins-available/firewall_plugin.inc.php*
    lrwxrwxrwx  1 root root   68 Jun 23  2016 getmail_plugin.inc.php -> /usr/local/ispconfig/server/plugins-available/getmail_plugin.inc.php*
    lrwxrwxrwx  1 root root   72 Jun 23  2016 maildeliver_plugin.inc.php -> /usr/local/ispconfig/server/plugins-available/maildeliver_plugin.inc.php*
    lrwxrwxrwx  1 root root   68 Jun 23  2016 mailman_plugin.inc.php -> /usr/local/ispconfig/server/plugins-available/mailman_plugin.inc.php*
    lrwxrwxrwx  1 root root   70 Jun 22 11:36 mail_plugin_dkim.inc.php -> /usr/local/ispconfig/server/plugins-available/mail_plugin_dkim.inc.php*
    lrwxrwxrwx  1 root root   65 Jun 23  2016 mail_plugin.inc.php -> /usr/local/ispconfig/server/plugins-available/mail_plugin.inc.php*
    lrwxrwxrwx  1 root root   75 Jun 23  2016 mysql_clientdb_plugin.inc.php -> /usr/local/ispconfig/server/plugins-available/mysql_clientdb_plugin.inc.php*
    lrwxrwxrwx  1 root root   77 Jun 23  2016 network_settings_plugin.inc.php -> /usr/local/ispconfig/server/plugins-available/network_settings_plugin.inc.php*
    lrwxrwxrwx  1 root root   75 Jun 23  2016 postfix_filter_plugin.inc.php -> /usr/local/ispconfig/server/plugins-available/postfix_filter_plugin.inc.php*
    lrwxrwxrwx  1 root root   75 Jun 23  2016 postfix_server_plugin.inc.php -> /usr/local/ispconfig/server/plugins-available/postfix_server_plugin.inc.php*
    lrwxrwxrwx  1 root root   67 Jun 22 11:36 rspamd_plugin.inc.php -> /usr/local/ispconfig/server/plugins-available/rspamd_plugin.inc.php*
    lrwxrwxrwx  1 root root   76 Jun 23  2016 software_update_plugin.inc.php -> /usr/local/ispconfig/server/plugins-available/software_update_plugin.inc.php*
    
    /plugins-available
    Code:
    [email protected]:~# ll /usr/local/ispconfig/server/plugins-available/
    total 816
    drwxr-x---  2 root root   4096 Jun 22 11:36 ./
    drwxr-x--- 13 root root   4096 Jun 22 11:36 ../
    -rwxr-x---  1 root root 161034 Jul  3 12:09 apache2_plugin.inc.php*
    -rwxr-x---  1 root root  10068 Jul  3 12:09 apps_vhost_plugin.inc.php*
    -rwxr-x---  1 root root   3794 Jul  3 12:09 aps_plugin.inc.php*
    -rwxr-x---  1 root root  16397 Jul  3 12:09 backup_plugin.inc.php*
    -rwxr-x---  1 root root  11201 Jul  3 12:09 bind_dlz_plugin.inc.php*
    -rwxr-x---  1 root root  24073 Jul  3 12:09 bind_plugin.inc.php*
    -rwxr-x---  1 root root  10943 Jul  3 12:09 cron_jailkit_plugin.inc.php*
    -rwxr-x---  1 root root  11721 Jul  3 12:09 cron_plugin.inc.php*
    -rwxr-x---  1 root root   9273 Jul  3 12:09 firewall_plugin.inc.php*
    -rwxr-x---  1 root root   4731 Jul  3 12:09 ftpuser_base_plugin.inc.php*
    -rwxr-x---  1 root root   6590 Jul  3 12:09 getmail_plugin.inc.php*
    -rwxr-x---  1 root root   1965 Jul  3 12:09 iptables_plugin.inc.php*
    -rwxr-x---  1 root root   9842 Jul  3 12:09 maildeliver_plugin.inc.php*
    -rwxr-x---  1 root root  12427 Jul  3 12:09 maildrop_plugin.inc.php*
    -rwxr-x---  1 root root   6643 Jul  3 12:09 mailman_plugin.inc.php*
    -rwxr-x---  1 root root  17137 Jul  3 12:09 mail_plugin_dkim.inc.php*
    -rwxr-x---  1 root root  25835 Jul  3 12:09 mail_plugin.inc.php*
    -rwxr-x---  1 root root  25834 Jul  3 12:09 mongo_clientdb_plugin.inc.php~*
    -rwxr-x---  1 root root  37729 Jul  3 12:09 mysql_clientdb_plugin.inc.php*
    -rwxr-x---  1 root root  13629 Jul  3 12:09 network_settings_plugin.inc.php*
    -rwxr-x---  1 root root 159822 Jul  3 12:09 nginx_plugin.inc.php*
    -rwxr-x---  1 root root  11903 Jul  3 12:09 nginx_reverseproxy_plugin.inc.php*
    -rwxr-x---  1 root root   6979 Jul  3 12:09 openvz_plugin.inc.php*
    -rwxr-x---  1 root root   4358 Jul  3 12:09 pma_symlink_plugin.inc.php*
    -rwxr-x---  1 root root   5046 Jul  3 12:09 postfix_filter_plugin.inc.php*
    -rwxr-x---  1 root root  10912 Jul  3 12:09 postfix_server_plugin.inc.php*
    -rwxr-x---  1 root root  23886 Jul  3 12:09 powerdns_plugin.inc.php*
    -rwxr-x---  1 root root  15542 Jul  3 12:09 rspamd_plugin.inc.php*
    -rwxr-x---  1 root root  20301 Jul  3 12:09 shelluser_base_plugin.inc.php*
    -rwxr-x---  1 root root  20453 Jul  3 12:09 shelluser_jailkit_plugin.inc.php*
    -rwxr-x---  1 root root  11626 Jul  3 12:09 software_update_plugin.inc.php*
    -rwxr-x---  1 root root   5510 Jul  3 12:09 squid_plugin.inc.php*
    -rwxr-x---  1 root root   4349 Jul  3 12:09 webmail_symlink_plugin.inc.php*
    -rwxr-x---  1 root root   6446 Jul  3 12:09 webserver_plugin.inc.php*
    -rwxr-x---  1 root root  18244 Jul  3 12:09 xmpp_plugin.inc.php*
    -rwxr-x---  1 root root   4927 Jul  3 12:09 z_php_fpm_incron_reload_plugin.inc.php*
    
     
  12. till

    till Super Moderator Staff Member ISPConfig Developer

    The symlinks are ok. Maybe you did not disable server.sh cronjob on the slave for debugging as described in the instructions? Take care that the cronjob is disabled, then change a mailbox of this server in the ispconfig gui, e.g. increase quote. then run server.sh to see the debug output.
     
  13. Sharone

    Sharone Member

    At the time I had no jobs running when I followed the instructions, apologies.
    I have increased mailbox size for a user

    Code:
    [email protected]:~# /usr/local/ispconfig/server/server.sh
    
    
    24.07.2020-10:46 - DEBUG - Found 1 changes, starting update process.
    24.07.2020-10:46 - WARNING - Falsche Anfrage / Wrong QuerySQL-Query = REPLACE INTO `mail_user` (`mailuser_id`,`sys_userid`,`sys_groupid`,`sys_perm_user`,`sys_perm_group`,`sys_perm_other`,`server_id`,`email`,`password`,`name`,`uid`,`gid`,`maildir`,`maildir_format`,`quota`,`cc`,`sender_cc`,`homedir`,`autoresponder`,`autoresponder_start_date`,`autoresponder_end_date`,`autoresponder_subject`,`autoresponder_text`,`move_junk`,`custom_mailfilter`,`postfix`,`greylisting`,`access`,`disableimap`,`disablepop3`,`disabledeliver`,`disablesmtp`,`login`,`disablesieve`,`disablesieve-filter`,`disablelda`,`disablelmtp`,`disabledoveadm`,`last_quota_notification`,`backup_interval`,`backup_copies`) VALUES ('1448','205','134','riud','riud','','2','[email protected]','$1$PQivmBE/$mBWSyoLvhoXVzc01aNI650','Sharone user','5000','5000','/var/vmail/domain.tld/user','maildir','629145600','','','/var/vmail','n','0000-00-00 00:00:00','0000-00-00 00:00:00','Out of office reply','','n','','y','n','n','n','n','n','n','[email protected]','n','n','n','n','n',NULL,'none','1') -> 1292 (Incorrect datetime value: '0000-00-00 00:00:00' for column 'autoresponder_start_date' at row 1)
    24.07.2020-10:46 - DEBUG - Replicated from master: REPLACE INTO `mail_user` (`mailuser_id`,`sys_userid`,`sys_groupid`,`sys_perm_user`,`sys_perm_group`,`sys_perm_other`,`server_id`,`email`,`password`,`name`,`uid`,`gid`,`maildir`,`maildir_format`,`quota`,`cc`,`sender_cc`,`homedir`,`autoresponder`,`autoresponder_start_date`,`autoresponder_end_date`,`autoresponder_subject`,`autoresponder_text`,`move_junk`,`custom_mailfilter`,`postfix`,`greylisting`,`access`,`disableimap`,`disablepop3`,`disabledeliver`,`disablesmtp`,`login`,`disablesieve`,`disablesieve-filter`,`disablelda`,`disablelmtp`,`disabledoveadm`,`last_quota_notification`,`backup_interval`,`backup_copies`) VALUES ('1448','205','134','riud','riud','','2','[email protected]','$1$PQivmBE/$mBWSyoLvhoXVzc01aNI650','Sharone user','5000','5000','/var/vmail/domain.tld/user','maildir','629145600','','','/var/vmail','n','0000-00-00 00:00:00','0000-00-00 00:00:00','Out of office reply','','n','','y','n','n','n','n','n','n','[email protected]','n','n','n','n','n',NULL,'none','1')
    24.07.2020-10:46 - DEBUG - Calling function 'user_update' from plugin 'mail_plugin' raised by event 'mail_user_update'.
    24.07.2020-10:46 - DEBUG - Mailuser uid: 5000, gid: 5000
    24.07.2020-10:46 - DEBUG - Created Directory: /var/vmail/domain.tld
    24.07.2020-10:46 - DEBUG - Created Maildir /var/vmail/domain.tld/user/Maildir with subfolder: Sent
    24.07.2020-10:46 - DEBUG - Created Maildir /var/vmail/domain.tld/user/Maildir with subfolder: Drafts
    24.07.2020-10:46 - DEBUG - Created Maildir /var/vmail/domain.tld/user/Maildir with subfolder: Trash
    24.07.2020-10:46 - DEBUG - Created Maildir /var/vmail/domain.tld/user/Maildir with subfolder: Junk
    24.07.2020-10:46 - DEBUG - safe_exec cmd: chown -R 'vmail':'vmail' '/var/vmail/domain.tld/user' - return code: 0
    24.07.2020-10:46 - DEBUG - Set ownership on /var/vmail/domain.tld/user
    24.07.2020-10:46 - DEBUG - Calling function 'update' from plugin 'maildeliver_plugin' raised by event 'mail_user_update'.
    24.07.2020-10:46 - DEBUG - Calling function 'user_settings_update' from plugin 'rspamd_plugin' raised by event 'mail_user_update'.
    24.07.2020-10:46 - DEBUG - Processed datalog_id 171580
    24.07.2020-10:46 - DEBUG - Remove Lock: /usr/local/ispconfig/server/temp/.ispconfig_lock
    finished.
     
  14. Sharone

    Sharone Member

    I corrected the invalid datetime value error. I run the script again after attempting to change a password and got this.
    Code:
    [email protected]:~# /usr/local/ispconfig/server/server.sh
    
    
    24.07.2020-11:38 - DEBUG - Found 1 changes, starting update process.
    24.07.2020-11:38 - DEBUG - Replicated from master: REPLACE INTO `mail_user` (`mailuser_id`,`sys_userid`,`sys_groupid`,`sys_perm_user`,`sys_perm_group`,`sys_perm_other`,`server_id`,`email`,`password`,`name`,`uid`,`gid`,`maildir`,`maildir_format`,`quota`,`cc`,`sender_cc`,`homedir`,`autoresponder`,`autoresponder_start_date`,`autoresponder_end_date`,`autoresponder_subject`,`autoresponder_text`,`move_junk`,`custom_mailfilter`,`postfix`,`greylisting`,`access`,`disableimap`,`disablepop3`,`disabledeliver`,`disablesmtp`,`login`,`disablesieve`,`disablesieve-filter`,`disablelda`,`disablelmtp`,`disabledoveadm`,`last_quota_notification`,`backup_interval`,`backup_copies`) VALUES ('1586','289','276','riud','riud','','2','[email protected]','$6$rounds=5000$5093348733bc1088$iYu5Gap46Rs0tZ8hniBzXDtNI2Qp6ewe4GTExwhehlT619ilB62DOHi7UC5iutrr2B/1Vhg/kXSATlWRwOFvI/','All','5000','5000','/var/vmail/domain.tld/all','maildir','104857600','','','/var/vmail','n','0000-00-00 00:00:00','0000-00-00 00:00:00','Out of office reply',NULL,'n',NULL,'y','n','y','n','n','n','n','[email protected]','n','n','n','n','n',NULL,'none','1')
    24.07.2020-11:38 - DEBUG - Calling function 'user_update' from plugin 'mail_plugin' raised by event 'mail_user_update'.
    24.07.2020-11:38 - DEBUG - Mailuser uid: 5000, gid: 5000
    24.07.2020-11:38 - DEBUG - Created Directory: /var/vmail/domain.tld
    24.07.2020-11:38 - DEBUG - Created Maildir /var/vmail/domain.tld/all/Maildir with subfolder: Sent
    24.07.2020-11:38 - DEBUG - Created Maildir /var/vmail/domain.tld/all/Maildir with subfolder: Drafts
    24.07.2020-11:38 - DEBUG - Created Maildir /var/vmail/domain.tld/all/Maildir with subfolder: Trash
    24.07.2020-11:38 - DEBUG - Created Maildir /var/vmail/domain.tld/all/Maildir with subfolder: Junk
    24.07.2020-11:38 - DEBUG - safe_exec cmd: chown -R 'vmail':'vmail' '/var/vmail/domain.tld/all' - return code: 0
    24.07.2020-11:38 - DEBUG - Set ownership on /var/vmail/domain.tld/all
    24.07.2020-11:38 - DEBUG - Calling function 'update' from plugin 'maildeliver_plugin' raised by event 'mail_user_update'.
    24.07.2020-11:38 - DEBUG - Calling function 'user_settings_update' from plugin 'rspamd_plugin' raised by event 'mail_user_update'.
    24.07.2020-11:38 - DEBUG - Processed datalog_id 171582
    24.07.2020-11:38 - DEBUG - Remove Lock: /usr/local/ispconfig/server/temp/.ispconfig_lock
    finished.
     
  15. till

    till Super Moderator Staff Member ISPConfig Developer

    This looks good so far. Dies the mail user login work and is the password hash for that mail user identical on master and this slave node?
     
  16. Sharone

    Sharone Member

    I am now able to authenticate. Very much appreciated :D
     

Share This Page