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: root@mail:~# 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: root@mail:~# 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
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.
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.
Ok, so the slave is not syncing with master anymore, you can find debug instructions here: https://www.faqforge.com/linux/debugging-ispconfig-3-server-actions-in-case-of-a-failure/ enable debugging on master for the slave and then run server.sh on the slave.
This is what I got from running server.sh Code: root@mail:~# /usr/local/ispconfig/server/server.sh 23.07.2020-19:20 - DEBUG - Remove Lock: /usr/local/ispconfig/server/temp/.ispconfig_lock finished.
That shows there was nothing to do. Are you sure you ran it on the correct server that had pending jobs?
Make sure the /usr/local/ispconfig/server/plugins-enabled/postfix_server_plugin.inc.php symlink exists (to the plugins-available file) on the slave.
Yes I see symlinks although I'm not certain whether the date matters? Code: root@mail:~# 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: root@mail:~# 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*
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.
At the time I had no jobs running when I followed the instructions, apologies. I have increased mailbox size for a user Code: root@mail:~# /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.
I corrected the invalid datetime value error. I run the script again after attempting to change a password and got this. Code: root@mail:~# /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.
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?
