Exception calling XMLRPC method restore_config_section # -1: Authentication failed: Invalid username or password error when creating or deleting a user in the local pfsense database

Abelardo A.M. · Apr 16, 2020, 5:55 PM

Hi

I have two pfsense (2.4.5) servers in HA. It shows me a sync error when creating or deleting a user in the local pfsense database:
Exception calling XMLRPC method restore_config_section # -1: Authentication failed: Invalid username or password

I use a specific user for synchronization with the appropriate permissions (that is not admin user). These are the tests I have done:

Put the same password on the user that is used to synchronize on the two servers. Also on the HA panel.
I have used the admin user to synchronise with both servers.
It is verified that in /etc/passwd the same users exist on both servers.
The error described above only occurs when a user is created or deleted. Another change, like disabling a firewall rule or changing a user's password does not give the error.

Any suggestion?

Thanks for your attention.

Apr 16 19:02:49 php-fpm /rc.filter_synchronize: XMLRPC reload data success with https://172.16.0.2:40223/xmlrpc.php (pfsense.restore_config_section).
Apr 16 19:02:45 php-cgi notify_monitor.php: Message sent to myemail@miisp.local OK
Apr 16 19:02:45 php-fpm /rc.filter_synchronize: Beginning XMLRPC sync data to https://172.16.0.2:40223/xmlrpc.php.
Apr 16 19:02:45 php-fpm /rc.filter_synchronize: New alert found: Exception calling XMLRPC method restore_config_section #-1 : Authentication failed: Invalid username or password
Apr 16 19:02:45 php-fpm /rc.filter_synchronize: Exception calling XMLRPC method restore_config_section #-1 : Authentication failed: Invalid username or password
Apr 16 19:02:44 php-fpm /rc.filter_synchronize: Beginning XMLRPC sync data to https://172.16.0.2:40223/xmlrpc.php.
Apr 16 19:02:44 php-fpm /rc.filter_synchronize: XMLRPC versioncheck: 19.1 -- 19.1
Apr 16 19:02:44 php-fpm /rc.filter_synchronize: XMLRPC reload data success with https://172.16.0.2:40223/xmlrpc.php (pfsense.host_firmware_version).
Apr 16 19:02:44 php-fpm /rc.filter_synchronize: Beginning XMLRPC sync data to https://172.16.0.2:40223/xmlrpc.php.
Apr 16 19:02:43 php-fpm Local User Database: Successfully deleted user: 1238asads
Apr 16 19:02:43 check_reload_status Syncing firewall
Apr 16 19:00:25 php-fpm /rc.filter_synchronize: XMLRPC reload data success with https://172.16.0.2:40223/xmlrpc.php (pfsense.restore_config_section).
Apr 16 19:00:20 php-fpm /rc.filter_synchronize: Beginning XMLRPC sync data to https://172.16.0.2:40223/xmlrpc.php.
Apr 16 19:00:20 php-fpm /rc.filter_synchronize: XMLRPC versioncheck: 19.1 -- 19.1
Apr 16 19:00:20 php-fpm /rc.filter_synchronize: XMLRPC reload data success with https://172.16.0.2:40223/xmlrpc.php (pfsense.host_firmware_version).
Apr 16 19:00:20 php-fpm /rc.filter_synchronize: Beginning XMLRPC sync data to https://172.16.0.2:40223/xmlrpc.php.
Apr 16 19:00:19 php-fpm Local User Database: Successfully edited user 1238asads
Apr 16 19:00:19 check_reload_status Syncing firewall
Apr 16 19:00:15 php [pfBlockerNG] No changes to Firewall rules, skipping Filter Reload
Apr 16 19:00:13 php [pfBlockerNG] Starting cron process.
Apr 16 18:59:37 php-fpm /rc.filter_synchronize: XMLRPC reload data success with https://172.16.0.2:40223/xmlrpc.php (pfsense.restore_config_section).
Apr 16 18:59:33 check_reload_status Reloading filter
Apr 16 18:59:33 php-fpm /rc.filter_synchronize: Beginning XMLRPC sync data to https://172.16.0.2:40223/xmlrpc.php.
Apr 16 18:59:33 php-fpm /rc.filter_synchronize: XMLRPC versioncheck: 19.1 -- 19.1
Apr 16 18:59:33 php-fpm /rc.filter_synchronize: XMLRPC reload data success with https://172.16.0.2:40223/xmlrpc.php (pfsense.host_firmware_version).
Apr 16 18:59:33 php-fpm /rc.filter_synchronize: Beginning XMLRPC sync data to https://172.16.0.2:40223/xmlrpc.php.
Apr 16 18:59:32 check_reload_status Syncing firewall
Apr 16 18:59:21 php-fpm /rc.filter_synchronize: XMLRPC reload data success with https://172.16.0.2:40223/xmlrpc.php (pfsense.restore_config_section).
Apr 16 18:59:17 check_reload_status Reloading filter
Apr 16 18:59:17 php-fpm /rc.filter_synchronize: Beginning XMLRPC sync data to https://172.16.0.2:40223/xmlrpc.php.
Apr 16 18:59:17 php-fpm /rc.filter_synchronize: XMLRPC versioncheck: 19.1 -- 19.1
Apr 16 18:59:17 php-fpm /rc.filter_synchronize: XMLRPC reload data success with https://172.16.0.2:40223/xmlrpc.php (pfsense.host_firmware_version).
Apr 16 18:59:17 php-fpm /rc.filter_synchronize: Beginning XMLRPC sync data to https://172.16.0.2:40223/xmlrpc.php.
Apr 16 18:59:16 check_reload_status Syncing firewall

davidredekop · Apr 27, 2020, 2:17 PM

I noticed in the official documentation here:

https://docs.netgate.com/pfsense/en/latest/highavailability/configuring-high-availability.html

In the "Enable Configuration Synchronization (XMLRPC Sync)" section it states the following:

Enter admin for the Remote System Username (other usernames will not work)

I found this post because I'm getting the same issue on 2.4.5 on HA systems have been functional for at least 3 months, and I am actually using username admin.

Oddly enough, sync continues to work, just one lone entry in my alerts, which is suspicious. Wasn't even during device reboot or maintenance either.

jimp · Apr 27, 2020, 6:39 PM

That note in the docs is outdated, you can use any account now so long as it has the correct privilege to allow HA sync. The admin account is safe no matter what.

Do you maybe have a package setup for HA which has its own set of sync credentials?

davidredekop · Apr 27, 2020, 11:14 PM

Thank you for the update, Jim. Just doing regular native HA, just according to documentation.

jimp · Apr 28, 2020, 3:03 PM

Hmm, I can't seem to reproduce that here. I can add a user, change passwords, delete, all operations succeed without error.

What shows up in the logs on the other side?

Abelardo A.M. · Apr 28, 2020, 8:16 PM

Hi,

Thanks for answering.

@davidredekop , I have already tried to put the admin user in HA SYNC but with no result.

@jimp, in response to your comment I have the following packages installed:
arpwatch, dakstat, Lightsquid, mailreport, openvpn-client-export, pfBlockerNG, Service_Watchdog, squid, squidGuard, Status_Traffic_Totals, meerkat and zabbix-agent44.
I have already checked the configuration of all those packages and I have found that I had the Squid sync with an incorrect configuration. I have reconfigurated it but the problem persists. So I have carried out the following test:
a) Disable Squid sync
b) Review all the packages and verify the synchronization configuration, disabling it if there was one.
c) HA SYNC has been disabled and re-enabled.
d) All HA SYNC sync have been disabled but the user and group sync
e) I can log in with sync user and password in both pfSense correctly.

After carrying out all those test the same problem persists.

LOGS for create user,delete user, disable rule, enable rule

LOG MASTER 172.16.0.1

Apr 28 21:05:51 php-fpm /rc.filter_synchronize: XMLRPC reload data success with https://172.16.0.2:40223/xmlrpc.php (pfsense.restore_config_section).
Apr 28 21:05:48 check_reload_status Reloading filter
Apr 28 21:05:47 php-fpm /rc.filter_synchronize: Beginning XMLRPC sync data to https://172.16.0.2:40223/xmlrpc.php.
Apr 28 21:05:47 php-fpm /rc.filter_synchronize: XMLRPC versioncheck: 19.1 -- 19.1
Apr 28 21:05:47 php-fpm /rc.filter_synchronize: XMLRPC reload data success with https://172.16.0.2:40223/xmlrpc.php (pfsense.host_firmware_version).
Apr 28 21:05:47 php-fpm /rc.filter_synchronize: Beginning XMLRPC sync data to https://172.16.0.2:40223/xmlrpc.php.
Apr 28 21:05:46 check_reload_status Syncing firewall
Apr 28 21:05:25 php-fpm /rc.filter_synchronize: XMLRPC reload data success with https://172.16.0.2:40223/xmlrpc.php (pfsense.restore_config_section).
Apr 28 21:05:24 check_reload_status Reloading filter
Apr 28 21:05:21 php-fpm /rc.filter_synchronize: Beginning XMLRPC sync data to https://172.16.0.2:40223/xmlrpc.php.
Apr 28 21:05:21 php-fpm /rc.filter_synchronize: XMLRPC versioncheck: 19.1 -- 19.1
Apr 28 21:05:21 php-fpm /rc.filter_synchronize: XMLRPC reload data success with https://172.16.0.2:40223/xmlrpc.php (pfsense.host_firmware_version).
Apr 28 21:05:21 php-fpm /rc.filter_synchronize: Beginning XMLRPC sync data to https://172.16.0.2:40223/xmlrpc.php.
Apr 28 21:05:20 check_reload_status Syncing firewall
Apr 28 21:05:09 php-cgi notify_monitor.php: Message sent to myemail@miisp.local OK
Apr 28 21:05:03 php-fpm /rc.filter_synchronize: XMLRPC reload data success with https://172.16.0.2:40223/xmlrpc.php (pfsense.restore_config_section).
Apr 28 21:04:59 php-fpm /rc.filter_synchronize: Beginning XMLRPC sync data to https://172.16.0.2:40223/xmlrpc.php.
Apr 28 21:04:59 php-fpm /rc.filter_synchronize: New alert found: Exception calling XMLRPC method restore_config_section #-1 : Authentication failed: Invalid username or password
Apr 28 21:04:59 php-fpm /rc.filter_synchronize: Exception calling XMLRPC method restore_config_section #-1 : Authentication failed: Invalid username or password
Apr 28 21:04:58 php-fpm /rc.filter_synchronize: Beginning XMLRPC sync data to https://172.16.0.2:40223/xmlrpc.php.
Apr 28 21:04:58 php-fpm /rc.filter_synchronize: XMLRPC versioncheck: 19.1 -- 19.1
Apr 28 21:04:58 php-fpm /rc.filter_synchronize: XMLRPC reload data success with https://172.16.0.2:40223/xmlrpc.php (pfsense.host_firmware_version).
Apr 28 21:04:58 php-fpm /rc.filter_synchronize: Beginning XMLRPC sync data to https://172.16.0.2:40223/xmlrpc.php.
Apr 28 21:04:57 php-fpm Local User Database: Successfully deleted user: 1111user
Apr 28 21:04:57 check_reload_status Syncing firewall
Apr 28 21:04:52 php-fpm /rc.filter_synchronize: XMLRPC reload data success with https://172.16.0.2:40223/xmlrpc.php (pfsense.restore_config_section).
Apr 28 21:04:49 php-cgi notify_monitor.php: Message sent to myemail@miisp.local OK
Apr 28 21:04:48 php-fpm /rc.filter_synchronize: Beginning XMLRPC sync data to https://172.16.0.2:40223/xmlrpc.php.
Apr 28 21:04:48 php-fpm /rc.filter_synchronize: New alert found: Exception calling XMLRPC method restore_config_section #-1 : Authentication failed: Invalid username or password
Apr 28 21:04:48 php-fpm /rc.filter_synchronize: Exception calling XMLRPC method restore_config_section #-1 : Authentication failed: Invalid username or password
Apr 28 21:04:48 php-fpm /rc.filter_synchronize: Beginning XMLRPC sync data to https://172.16.0.2:40223/xmlrpc.php.
Apr 28 21:04:48 php-fpm /rc.filter_synchronize: XMLRPC versioncheck: 19.1 -- 19.1
Apr 28 21:04:48 php-fpm /rc.filter_synchronize: XMLRPC reload data success with https://172.16.0.2:40223/xmlrpc.php (pfsense.host_firmware_version).
Apr 28 21:04:47 php-fpm /rc.filter_synchronize: Beginning XMLRPC sync data to https://172.16.0.2:40223/xmlrpc.php.
Apr 28 21:04:46 php-fpm Local User Database: Successfully created user 1111user
Apr 28 21:04:46 check_reload_status Syncing firewall

LOG SLAVE 172.16.0.2

Apr 28 21:06:05 php-fpm 39968 /rc.newipsecdns: WARNING: Setting i_dont_care_about_security_and_use_aggressive_mode_psk option because a phase 1 is configured using aggressive mode with pre-shared keys. This is not a secure configuration.
Apr 28 21:06:05 check_reload_status Reloading filter
Apr 28 21:06:05 php-fpm 39968 /rc.newipsecdns: IPSEC: One or more IPsec tunnel endpoints has changed its IP. Refreshing.
Apr 28 21:05:57 php-fpm 79048 /rc.start_packages: The command '/usr/local/etc/rc.d/arpwatch.sh stop' returned exit code '1', the output was ''
Apr 28 21:05:57 check_reload_status Reloading filter
Apr 28 21:05:57 check_reload_status Syncing firewall
Apr 28 21:05:57 check_reload_status Syncing firewall
Apr 28 21:05:57 php-fpm 79048 [pfBlockerNG] Starting cron process.
Apr 28 21:05:57 check_reload_status Reloading filter
Apr 28 21:05:56 php-fpm 79048 /rc.start_packages: [squid] Starting a proxy monitor script
Apr 28 21:05:56 php-fpm 79048 /rc.start_packages: [squid] Reloading for configuration sync...
Apr 28 21:05:55 php-fpm 79048 /rc.start_packages: [squid] Stopping any running proxy monitors
Apr 28 21:05:55 php-fpm 79048 /rc.start_packages: [squid] Reloading C-ICAP...
Apr 28 21:05:55 php-fpm 79048 /rc.start_packages: [squid] Reloading ClamAV...
Apr 28 21:05:55 php-fpm 79048 /rc.start_packages: [squid] Creating 'clamd.sh' rc script.
Apr 28 21:05:55 check_reload_status Syncing firewall
Apr 28 21:05:55 php-fpm 79048 /rc.start_packages: [squid] Adding freshclam cronjob.
Apr 28 21:05:55 php-fpm 79048 /rc.start_packages: [squid] Adding cronjobs ...
Apr 28 21:05:54 php-fpm 79048 /rc.start_packages: [squid] - squid_resync function call pr:1 bp: rpc:no
Apr 28 21:05:54 check_reload_status Reloading filter
Apr 28 21:05:53 php-fpm 79048 /rc.start_packages: [squid] Starting a proxy monitor script
Apr 28 21:05:53 php-fpm 79048 /rc.start_packages: [squid] Reloading for configuration sync...
Apr 28 21:05:52 php-fpm 79048 /rc.start_packages: [squid] Stopping any running proxy monitors
Apr 28 21:05:52 php-fpm 79048 /rc.start_packages: [squid] Reloading C-ICAP...
Apr 28 21:05:52 php-fpm 79048 /rc.start_packages: [squid] Reloading ClamAV...
Apr 28 21:05:52 php-fpm 79048 /rc.start_packages: [squid] Creating 'clamd.sh' rc script.
Apr 28 21:05:52 check_reload_status Syncing firewall
Apr 28 21:05:52 php-fpm 79048 /rc.start_packages: [squid] Adding freshclam cronjob.
Apr 28 21:05:52 php-fpm 79048 /rc.start_packages: [squid] Adding cronjobs ...
Apr 28 21:05:52 php-fpm 79048 /rc.start_packages: [squid] - squid_resync function call pr:1 bp: rpc:no
Apr 28 21:05:52 php-fpm 79048 /rc.start_packages: [lightsquid] Removing all cronjobs...
Apr 28 21:05:52 php-fpm 79048 /rc.start_packages: [lightsquid] Successfully created '/usr/local/etc/lightsquid/lightsquid.cfg' configuration file.
Apr 28 21:05:52 php-fpm 79048 /rc.start_packages: [lightsquid] Loaded default '/usr/local/etc/lightsquid/lightsquid.cfg.sample' configuration file.
Apr 28 21:05:52 php-fpm 79048 /rc.start_packages: Restarting/Starting all packages.
Apr 28 21:05:51 check_reload_status Starting packages
Apr 28 21:05:51 check_reload_status Reloading filter
Apr 28 21:05:51 php-fpm 37910 /rc.newwanip: pfSense package system has detected an IP change or dynamic WAN reconnection - -> 192.168.6.1 - Restarting packages.
Apr 28 21:05:51 php-fpm 37910 /rc.newwanip: rc.newwanip called with empty interface.
Apr 28 21:05:51 php-fpm 37910 /rc.newwanip: rc.newwanip: on (IP address: 192.168.6.1) (interface: []) (real interface: ovpns1).
Apr 28 21:05:51 php-fpm 37910 /rc.newwanip: rc.newwanip: Info: starting on ovpns1.
Apr 28 21:05:50 php-fpm 363 /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use GW_SCDS_MIKROTIK.
Apr 28 21:05:50 check_reload_status rc.newwanip starting ovpns1
Apr 28 21:05:50 php-fpm 11155 OpenVPN PID written: 55583
Apr 28 21:05:50 kernel ovpns1: link state changed to UP
Apr 28 21:05:49 kernel ovpns1: link state changed to DOWN
Apr 28 21:05:49 php-fpm 11155 OpenVPN terminate old pid: 47491
Apr 28 21:05:49 check_reload_status Reloading filter
Apr 28 21:05:49 check_reload_status Restarting OpenVPN tunnels/interfaces
Apr 28 21:05:49 check_reload_status Restarting ipsec tunnels
Apr 28 21:05:49 check_reload_status updating dyndns GW_SCDS_MIKROTIK
Apr 28 21:05:49 rc.gateway_alarm 89088 >>> Gateway alarm: GW_SCDS_MIKROTIK (Addr:10.20.80.4 Alarm:1 RTT:0.000ms RTTsd:0.000ms Loss:100%)
Apr 28 21:05:47 php-fpm 11155 /xmlrpc.php: Resyncing OpenVPN instances.
Apr 28 21:05:47 check_reload_status Reloading filter
Apr 28 21:05:47 check_reload_status Syncing firewall
Apr 28 21:05:39 php-fpm 11155 /rc.newipsecdns: WARNING: Setting i_dont_care_about_security_and_use_aggressive_mode_psk option because a phase 1 is configured using aggressive mode with pre-shared keys. This is not a secure configuration.
Apr 28 21:05:39 check_reload_status Reloading filter
Apr 28 21:05:39 php-fpm 11155 /rc.newipsecdns: IPSEC: One or more IPsec tunnel endpoints has changed its IP. Refreshing.
Apr 28 21:05:31 php-fpm 39968 /rc.start_packages: The command '/usr/local/etc/rc.d/arpwatch.sh stop' returned exit code '1', the output was ''
Apr 28 21:05:31 check_reload_status Reloading filter
Apr 28 21:05:31 check_reload_status Syncing firewall
Apr 28 21:05:31 check_reload_status Syncing firewall
Apr 28 21:05:31 php-fpm 39968 [pfBlockerNG] Starting cron process.
Apr 28 21:05:31 check_reload_status Reloading filter
Apr 28 21:05:30 php-fpm 39968 /rc.start_packages: [squid] Starting a proxy monitor script
Apr 28 21:05:30 php-fpm 39968 /rc.start_packages: [squid] Reloading for configuration sync...
Apr 28 21:05:29 php-fpm 39968 /rc.start_packages: [squid] Stopping any running proxy monitors
Apr 28 21:05:29 php-fpm 39968 /rc.start_packages: [squid] Reloading C-ICAP...
Apr 28 21:05:29 php-fpm 39968 /rc.start_packages: [squid] Reloading ClamAV...
Apr 28 21:05:29 php-fpm 39968 /rc.start_packages: [squid] Creating 'clamd.sh' rc script.
Apr 28 21:05:29 check_reload_status Syncing firewall
Apr 28 21:05:29 php-fpm 39968 /rc.start_packages: [squid] Adding freshclam cronjob.
Apr 28 21:05:29 php-fpm 39968 /rc.start_packages: [squid] Adding cronjobs ...
Apr 28 21:05:28 php-fpm 39968 /rc.start_packages: [squid] - squid_resync function call pr:1 bp: rpc:no
Apr 28 21:05:28 check_reload_status Reloading filter
Apr 28 21:05:27 php-fpm 39968 /rc.start_packages: [squid] Starting a proxy monitor script
Apr 28 21:05:27 php-fpm 39968 /rc.start_packages: [squid] Reloading for configuration sync...
Apr 28 21:05:26 php-fpm 39968 /rc.start_packages: [squid] Stopping any running proxy monitors
Apr 28 21:05:26 php-fpm 39968 /rc.start_packages: [squid] Reloading C-ICAP...
Apr 28 21:05:26 php-fpm 39968 /rc.start_packages: [squid] Reloading ClamAV...
Apr 28 21:05:26 php-fpm 39968 /rc.start_packages: [squid] Creating 'clamd.sh' rc script.
Apr 28 21:05:26 check_reload_status Syncing firewall
Apr 28 21:05:26 php-fpm 39968 /rc.start_packages: [squid] Adding freshclam cronjob.
Apr 28 21:05:26 php-fpm 39968 /rc.start_packages: [squid] Adding cronjobs ...
Apr 28 21:05:26 php-fpm 39968 /rc.start_packages: [squid] - squid_resync function call pr:1 bp: rpc:no
Apr 28 21:05:26 php-fpm 39968 /rc.start_packages: [lightsquid] Removing all cronjobs...
Apr 28 21:05:26 php-fpm 39968 /rc.start_packages: [lightsquid] Successfully created '/usr/local/etc/lightsquid/lightsquid.cfg' configuration file.
Apr 28 21:05:26 php-fpm 39968 /rc.start_packages: [lightsquid] Loaded default '/usr/local/etc/lightsquid/lightsquid.cfg.sample' configuration file.
Apr 28 21:05:26 php-fpm 39968 /rc.start_packages: Restarting/Starting all packages.
Apr 28 21:05:25 check_reload_status Starting packages
Apr 28 21:05:25 check_reload_status Reloading filter
Apr 28 21:05:25 php-fpm 94975 /rc.newwanip: pfSense package system has detected an IP change or dynamic WAN reconnection - -> 192.168.6.1 - Restarting packages.
Apr 28 21:05:25 php-fpm 94975 /rc.newwanip: rc.newwanip called with empty interface.
Apr 28 21:05:25 php-fpm 94975 /rc.newwanip: rc.newwanip: on (IP address: 192.168.6.1) (interface: []) (real interface: ovpns1).
Apr 28 21:05:25 php-fpm 94975 /rc.newwanip: rc.newwanip: Info: starting on ovpns1.
Apr 28 21:05:24 php-fpm 92304 /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use GW_SCDS_MIKROTIK.
Apr 28 21:05:23 check_reload_status rc.newwanip starting ovpns1
Apr 28 21:05:23 php-fpm 37910 OpenVPN PID written: 47491
Apr 28 21:05:23 kernel ovpns1: link state changed to UP
Apr 28 21:05:23 kernel ovpns1: link state changed to DOWN
Apr 28 21:05:23 php-fpm 37910 OpenVPN terminate old pid: 52175
Apr 28 21:05:23 check_reload_status Reloading filter
Apr 28 21:05:23 check_reload_status Restarting OpenVPN tunnels/interfaces
Apr 28 21:05:23 check_reload_status Restarting ipsec tunnels
Apr 28 21:05:23 check_reload_status updating dyndns GW_SCDS_MIKROTIK
Apr 28 21:05:23 rc.gateway_alarm 76523 >>> Gateway alarm: GW_SCDS_MIKROTIK (Addr:10.20.80.4 Alarm:1 RTT:0.000ms RTTsd:0.000ms Loss:100%)
Apr 28 21:05:21 php-fpm 37910 /xmlrpc.php: Resyncing OpenVPN instances.
Apr 28 21:05:21 check_reload_status Reloading filter
Apr 28 21:05:21 check_reload_status Syncing firewall
Apr 28 21:05:10 php-fpm 94975 /rc.start_packages: The command '/usr/local/etc/rc.d/arpwatch.sh stop' returned exit code '1', the output was ''
Apr 28 21:05:10 check_reload_status Reloading filter
Apr 28 21:05:10 check_reload_status Syncing firewall
Apr 28 21:05:10 check_reload_status Syncing firewall
Apr 28 21:05:09 php-fpm 94975 [pfBlockerNG] Starting cron process.
Apr 28 21:05:09 check_reload_status Reloading filter
Apr 28 21:05:08 php-fpm 94975 /rc.start_packages: [squid] Starting a proxy monitor script
Apr 28 21:05:08 php-fpm 94975 /rc.start_packages: [squid] Reloading for configuration sync...
Apr 28 21:05:07 php-fpm 94975 /rc.start_packages: [squid] Stopping any running proxy monitors
Apr 28 21:05:07 php-fpm 94975 /rc.start_packages: [squid] Reloading C-ICAP...
Apr 28 21:05:07 php-fpm 94975 /rc.start_packages: [squid] Reloading ClamAV...
Apr 28 21:05:07 php-fpm 94975 /rc.start_packages: [squid] Creating 'clamd.sh' rc script.
Apr 28 21:05:07 check_reload_status Syncing firewall
Apr 28 21:05:07 php-fpm 94975 /rc.start_packages: [squid] Adding freshclam cronjob.
Apr 28 21:05:07 php-fpm 94975 /rc.start_packages: [squid] Adding cronjobs ...
Apr 28 21:05:07 php-fpm 39968 /rc.newipsecdns: WARNING: Setting i_dont_care_about_security_and_use_aggressive_mode_psk option because a phase 1 is configured using aggressive mode with pre-shared keys. This is not a secure configuration.
Apr 28 21:05:07 check_reload_status Reloading filter
Apr 28 21:05:07 php-fpm 39968 /rc.newipsecdns: IPSEC: One or more IPsec tunnel endpoints has changed its IP. Refreshing.
Apr 28 21:05:07 php-fpm 94975 /rc.start_packages: [squid] - squid_resync function call pr:1 bp: rpc:no
Apr 28 21:05:07 check_reload_status Reloading filter
Apr 28 21:05:06 php-fpm 94975 /rc.start_packages: [squid] Starting a proxy monitor script
Apr 28 21:05:06 php-fpm 94975 /rc.start_packages: [squid] Reloading for configuration sync...
Apr 28 21:05:05 php-fpm 94975 /rc.start_packages: [squid] Stopping any running proxy monitors
Apr 28 21:05:05 php-fpm 94975 /rc.start_packages: [squid] Reloading C-ICAP...
Apr 28 21:05:05 php-fpm 94975 /rc.start_packages: [squid] Reloading ClamAV...
Apr 28 21:05:05 php-fpm 94975 /rc.start_packages: [squid] Creating 'clamd.sh' rc script.
Apr 28 21:05:05 check_reload_status Syncing firewall
Apr 28 21:05:05 php-fpm 94975 /rc.start_packages: [squid] Adding freshclam cronjob.
Apr 28 21:05:05 php-fpm 94975 /rc.start_packages: [squid] Adding cronjobs ...
Apr 28 21:05:04 php-fpm 94975 /rc.start_packages: [squid] - squid_resync function call pr:1 bp: rpc:no
Apr 28 21:05:04 php-fpm 94975 /rc.start_packages: [lightsquid] Removing all cronjobs...
Apr 28 21:05:04 php-fpm 94975 /rc.start_packages: [lightsquid] Successfully created '/usr/local/etc/lightsquid/lightsquid.cfg' configuration file.
Apr 28 21:05:04 php-fpm 94975 /rc.start_packages: [lightsquid] Loaded default '/usr/local/etc/lightsquid/lightsquid.cfg.sample' configuration file.
Apr 28 21:05:04 php-fpm 94975 /rc.start_packages: Restarting/Starting all packages.
Apr 28 21:05:03 check_reload_status Starting packages
Apr 28 21:05:03 php-fpm 37910 /rc.newwanip: pfSense package system has detected an IP change or dynamic WAN reconnection - -> 192.168.6.1 - Restarting packages.
Apr 28 21:05:03 check_reload_status Reloading filter
Apr 28 21:05:03 php-fpm 37910 /rc.newwanip: rc.newwanip called with empty interface.
Apr 28 21:05:03 php-fpm 37910 /rc.newwanip: rc.newwanip: on (IP address: 192.168.6.1) (interface: []) (real interface: ovpns1).
Apr 28 21:05:03 php-fpm 37910 /rc.newwanip: rc.newwanip: Info: starting on ovpns1.
Apr 28 21:05:03 php-fpm 94975 /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use GW_SCDS_MIKROTIK.
Apr 28 21:05:02 check_reload_status rc.newwanip starting ovpns1
Apr 28 21:05:02 check_reload_status Reloading filter
Apr 28 21:05:02 php-fpm 11155 OpenVPN PID written: 52175
Apr 28 21:05:02 kernel ovpns1: link state changed to UP
Apr 28 21:05:02 kernel ovpns1: link state changed to DOWN
Apr 28 21:05:02 php-fpm 11155 OpenVPN terminate old pid: 26520
Apr 28 21:05:02 check_reload_status Reloading filter
Apr 28 21:05:02 check_reload_status Restarting OpenVPN tunnels/interfaces
Apr 28 21:05:02 check_reload_status Restarting ipsec tunnels
Apr 28 21:05:02 check_reload_status updating dyndns GW_SCDS_MIKROTIK
Apr 28 21:05:02 rc.gateway_alarm 77212 >>> Gateway alarm: GW_SCDS_MIKROTIK (Addr:10.20.80.4 Alarm:1 RTT:0.000ms RTTsd:0.000ms Loss:100%)
Apr 28 21:05:00 php-fpm 11155 /xmlrpc.php: Resyncing OpenVPN instances.
Apr 28 21:04:59 php-fpm 11155 /xmlrpc.php: webConfigurator authentication error for user 'upfsync' from: 172.16.0.1
Apr 28 21:04:59 php-fpm 11155 /xmlrpc.php: Removing user: 1111user
Apr 28 21:04:59 php-fpm 363 /rc.start_packages: The command '/usr/local/etc/rc.d/arpwatch.sh stop' returned exit code '1', the output was ''
Apr 28 21:04:59 check_reload_status Reloading filter
Apr 28 21:04:59 check_reload_status Syncing firewall
Apr 28 21:04:59 check_reload_status Syncing firewall
Apr 28 21:04:58 php-fpm 363 [pfBlockerNG] Starting cron process.
Apr 28 21:04:58 check_reload_status Reloading filter
Apr 28 21:04:57 php-fpm 363 /rc.start_packages: [squid] Starting a proxy monitor script
Apr 28 21:04:57 php-fpm 363 /rc.start_packages: [squid] Reloading for configuration sync...
Apr 28 21:04:56 php-fpm 363 /rc.start_packages: [squid] Stopping any running proxy monitors
Apr 28 21:04:56 php-fpm 363 /rc.start_packages: [squid] Reloading C-ICAP...
Apr 28 21:04:56 php-fpm 363 /rc.start_packages: [squid] Reloading ClamAV...
Apr 28 21:04:56 php-fpm 363 /rc.start_packages: [squid] Creating 'clamd.sh' rc script.
Apr 28 21:04:56 check_reload_status Syncing firewall
Apr 28 21:04:56 php-fpm 363 /rc.start_packages: [squid] Adding freshclam cronjob.
Apr 28 21:04:56 php-fpm 363 /rc.start_packages: [squid] Adding cronjobs ...
Apr 28 21:04:56 php-fpm 363 /rc.start_packages: [squid] - squid_resync function call pr:1 bp: rpc:no
Apr 28 21:04:56 check_reload_status Reloading filter
Apr 28 21:04:55 php-fpm 363 /rc.start_packages: [squid] Starting a proxy monitor script
Apr 28 21:04:55 php-fpm 363 /rc.start_packages: [squid] Reloading for configuration sync...
Apr 28 21:04:54 php-fpm 363 /rc.start_packages: [squid] Stopping any running proxy monitors
Apr 28 21:04:54 php-fpm 363 /rc.start_packages: [squid] Reloading C-ICAP...
Apr 28 21:04:54 php-fpm 363 /rc.start_packages: [squid] Reloading ClamAV...
Apr 28 21:04:54 php-fpm 363 /rc.start_packages: [squid] Creating 'clamd.sh' rc script.
Apr 28 21:04:54 check_reload_status Syncing firewall
Apr 28 21:04:53 php-fpm 363 /rc.start_packages: [squid] Adding freshclam cronjob.
Apr 28 21:04:53 php-fpm 363 /rc.start_packages: [squid] Adding cronjobs ...
Apr 28 21:04:53 php-fpm 363 /rc.start_packages: [squid] - squid_resync function call pr:1 bp: rpc:no
Apr 28 21:04:53 php-fpm 363 /rc.start_packages: [lightsquid] Removing all cronjobs...
Apr 28 21:04:53 php-fpm 363 /rc.start_packages: [lightsquid] Successfully created '/usr/local/etc/lightsquid/lightsquid.cfg' configuration file.
Apr 28 21:04:53 php-fpm 363 /rc.start_packages: [lightsquid] Loaded default '/usr/local/etc/lightsquid/lightsquid.cfg.sample' configuration file.
Apr 28 21:04:53 php-fpm 363 /rc.start_packages: Restarting/Starting all packages.
Apr 28 21:04:52 check_reload_status Starting packages
Apr 28 21:04:52 php-fpm 94975 /rc.newwanip: pfSense package system has detected an IP change or dynamic WAN reconnection - -> 192.168.6.1 - Restarting packages.
Apr 28 21:04:52 check_reload_status Reloading filter
Apr 28 21:04:52 php-fpm 94975 /rc.newwanip: rc.newwanip called with empty interface.
Apr 28 21:04:52 php-fpm 94975 /rc.newwanip: rc.newwanip: on (IP address: 192.168.6.1) (interface: []) (real interface: ovpns1).
Apr 28 21:04:52 php-fpm 94975 /rc.newwanip: rc.newwanip: Info: starting on ovpns1.
Apr 28 21:04:52 php-fpm 92304 /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use GW_SCDS_MIKROTIK.
Apr 28 21:04:51 check_reload_status rc.newwanip starting ovpns1
Apr 28 21:04:51 php-fpm 11155 OpenVPN PID written: 26520
Apr 28 21:04:51 kernel ovpns1: link state changed to UP
Apr 28 21:04:51 kernel ovpns1: link state changed to DOWN
Apr 28 21:04:51 php-fpm 11155 OpenVPN terminate old pid: 92582
Apr 28 21:04:51 check_reload_status Reloading filter
Apr 28 21:04:51 check_reload_status Restarting OpenVPN tunnels/interfaces
Apr 28 21:04:51 check_reload_status Restarting ipsec tunnels
Apr 28 21:04:51 check_reload_status updating dyndns GW_SCDS_MIKROTIK
Apr 28 21:04:51 rc.gateway_alarm 63264 >>> Gateway alarm: GW_SCDS_MIKROTIK (Addr:10.20.80.4 Alarm:1 RTT:0.000ms RTTsd:0.000ms Loss:100%)
Apr 28 21:04:49 php-fpm 11155 /xmlrpc.php: Resyncing OpenVPN instances.
Apr 28 21:04:49 check_reload_status Reloading filter
Apr 28 21:04:48 php-fpm 11155 /xmlrpc.php: webConfigurator authentication error for user 'upfsync' from: 172.16.0.1
Apr 28 21:04:48 check_reload_status Syncing firewall
Apr 28 21:04:48 php-fpm 11155 /xmlrpc.php: Adding user: 1111user
Apr 28 21:04:48 check_reload_status Syncing firewall

Thank you.

jimp · Apr 29, 2020, 2:29 PM

Odd. I don't see anything in there that would explain why, but it does appear that the secondary is rejecting the auth inconsistently.

How many user accounts are there in the user manager? We have seen some issues with slowness associated with large numbers of accounts before, perhaps it's in the middle of rewriting the users when the auth fails.

Abelardo A.M. · Apr 29, 2020, 4:44 PM

Hi @jimp

We have 111 users because the firewall is used as vpn server (openvpn)

Thank you

jimp · Apr 29, 2020, 5:30 PM

That many users you should consider using a central authentication setup (RADIUS, LDAP, etc) and not the user manager.

Though the one I'm testing on has 40 users, it's possible there is another contributing factor, like the speed of the hardware.

jimp · Apr 29, 2020, 5:32 PM

Here is the older bug I was thinking of, but it hasn't been an issue in a while: https://redmine.pfsense.org/issues/7469

Abelardo A.M. · May 22, 2020, 7:05 PM

Hi:
More information about this problem:
https://redmine.pfsense.org/issues/10585

@jimp, thanks you for all information.