Error occurred while attempting to call XMLRPC method filter_configure



  • Hi!

    Two pfsense 2.4.2-RELEASE-p1 on identical hardware with 6 Interfaces (2 on board, 4 on i350 card) are configured as HA cluster with dedicated interfaces for HA and Sync. That works very smart :)

    HA adresses on the dedicated interfaces are 10.10.10.1/24 and 10.10.10.2/24, Web-GUI port is on both HA members 4443. I could use the Web-GUI on both members with a browser (CARP 172.16.4.250, ha1 172.16.4.251 and ha2 172.16.4.252). The HA interfaces are directly connected, the other interfaces are all on a switch with configured VLANs for WAN, DMZ, LAN and GUEST.

    Since a few days there is sometimes a problem with the XMLRPC sync for the config, but only with filter_configure. The synchronisation of other configuration changes have no problems.

    Log:

    Mar  9 10:58:02 172.16.4.251 php-cgi: rc.filter_synchronize: Beginning XMLRPC sync data to https://10.10.10.2:4443/xmlrpc.php.
    Mar  9 10:58:02 172.16.4.251 php-cgi: rc.filter_synchronize: XMLRPC reload data success with https://10.10.10.2:4443/xmlrpc.php (pfsense.host_firmware_version).
    Mar  9 10:58:02 172.16.4.251 php-cgi: rc.filter_synchronize: XMLRPC versioncheck: 17.3 – 17.3
    Mar  9 10:58:02 172.16.4.251 php-cgi: rc.filter_synchronize: Beginning XMLRPC sync data to https://10.10.10.2:4443/xmlrpc.php.
    Mar  9 10:58:03 172.16.4.251 php-cgi: rc.filter_synchronize: XMLRPC reload data success with https://10.10.10.2:4443/xmlrpc.php (pfsense.restore_config_section).
    Mar  9 10:58:03 172.16.4.251 php-cgi: rc.filter_synchronize: Beginning XMLRPC sync data to https://10.10.10.2:4443/xmlrpc.php.
    Mar  9 10:59:03 172.16.4.251 php-cgi: rc.filter_synchronize: A communications error occurred while attempting to call XMLRPC method filter_configure:
    Mar  9 10:59:03 172.16.4.251 php-cgi: rc.filter_synchronize: New alert found: A communications error occurred while attempting to call XMLRPC method filter_configure:
    Mar  9 10:59:03 172.16.4.251 php-cgi: rc.filter_synchronize: Beginning XMLRPC sync data to https://10.10.10.2:4443/xmlrpc.php.
    Mar  9 11:00:03 172.16.4.251 php-cgi: rc.filter_synchronize: A communications error occurred while attempting to call XMLRPC method filter_configure:
    Mar  9 11:00:03 172.16.4.251 php-cgi: rc.filter_synchronize: New alert found: A communications error occurred while attempting to call XMLRPC method filter_configure:

    I compared both XML backup files with diff, but can't see anything, which could be wrong. I think about, that something is wrong with the firewall rules, i.e. some german Umlauts or other discrepancy, could that been? Is there a possibilty for a debug log or output if I call the rc.filter_synchronize script on console?

    Have a nice weekend!

    Tom


  • Netgate Administrator

    Is there any error shown on the secondary system log?

    Steve



  • I have similar problem,

    HA seems to work but very often both pfsesnse boxes are freezing while trying to make any changes or click here and there

    Typically I get errors like that on both sets of HA using original SG4860s, all version 2.4.2-RELEASE-p1

    A communications error occurred while attempting to call XMLRPC method host_firmware_version
    or
    A communications error occurred while attempting to call XMLRPC method filter_configure
    or
    A communications error occurred while attempting to call XMLRPC method restore_config_section

    What is weird I see HA generally working by what I mean I do see majority of times confings synched sucessfully in the logs but there are also a lot of errors

    And yes I see logs with problems on the slave logs too along with successfull ones


  • Netgate Administrator

    Do you have a large number of users? If you see reported success followed by time-outs after 1min you may be hitting this: https://redmine.pfsense.org/issues/7469

    That should be fixed in 2.4.3rel or in current snapshots if you're able to test them.

    Steve



  • basicaly no,  I am the only user, no load on pfsense



  • I double checked all passwords on my VIP, all interfaces seem to work fine,  in general HA works e.g when I change a rule but those errors and freezing are driving me crazy, is this a bug?

    Here are the typical master logs

    Mar 14 13:39:06 php-fpm 5316 /rc.filter_configure_sync: The gateway: ISP2WINDSTREAMGW is invalid or unknown, not using it.
    Mar 14 13:39:06 php-fpm 5316 /rc.filter_configure_sync: Default gateway down setting ISP1_VZ_DHCP as default!
    Mar 14 13:39:05 check_reload_status Reloading filter
    Mar 14 13:39:04 php-fpm 99980 /rc.filter_synchronize: Beginning XMLRPC sync data to https://1.1.1.2:8500/xmlrpc.php.
    Mar 14 13:39:04 php-fpm 99980 /rc.filter_synchronize: XMLRPC versioncheck: 17.3 – 17.3
    Mar 14 13:39:04 php-fpm 99980 /rc.filter_synchronize: XMLRPC reload data success with https://1.1.1.2:8500/xmlrpc.php (pfsense.host_firmware_version).
    Mar 14 13:39:04 php-fpm 99980 /rc.filter_synchronize: Beginning XMLRPC sync data to https://1.1.1.2:8500/xmlrpc.php.
    Mar 14 13:39:02 check_reload_status Syncing firewall
    Mar 14 13:39:02 php-fpm 84556 /firewall_rules_edit.php: Default gateway down setting ISP1_VZ_DHCP as default!
    Mar 14 13:38:56 php-fpm 84556 /firewall_rules_edit.php: Default gateway down setting ISP1_VZ_DHCP as default!
    Mar 14 13:32:28 php-fpm 83784 /rc.filter_synchronize: New alert found: A communications error occurred while attempting to call XMLRPC method filter_configure:
    Mar 14 13:32:28 php-fpm 83784 /rc.filter_synchronize: A communications error occurred while attempting to call XMLRPC method filter_configure:
    Mar 14 13:31:28 php-fpm 83784 /rc.filter_synchronize: Beginning XMLRPC sync data to https://1.1.1.2:8500/xmlrpc.php.
    Mar 14 13:31:28 php-fpm 83784 /rc.filter_synchronize: New alert found: A communications error occurred while attempting to call XMLRPC method filter_configure:
    Mar 14 13:31:28 php-fpm 83784 /rc.filter_synchronize: A communications error occurred while attempting to call XMLRPC method filter_configure:
    Mar 14 13:30:27 php-fpm 83784 /rc.filter_synchronize: Beginning XMLRPC sync data to https://1.1.1.2:8500/xmlrpc.php.
    Mar 14 13:30:27 php-fpm 83784 /rc.filter_synchronize: XMLRPC reload data success with https://1.1.1.2:8500/xmlrpc.php (pfsense.restore_config_section).
    Mar 14 13:29:54 php-fpm 83784 /rc.filter_synchronize: Beginning XMLRPC sync data to https://1.1.1.2:8500/xmlrpc.php.
    Mar 14 13:29:54 php-fpm 83784 /rc.filter_synchronize: New alert found: A communications error occurred while attempting to call XMLRPC method restore_config_section:
    Mar 14 13:29:54 php-fpm 83784 /rc.filter_synchronize: A communications error occurred while attempting to call XMLRPC method restore_config_section:

    Slave: (igb2 is the one of the WAN links connected but not online, ISP2WINDSTREAMGW - should not even be in the logs anymore since it was removed, only ISP1_VZ_DHCP is currently up)

    Mar 14 13:39:37 php-fpm 37373 /xmlrpc.php: Configuring CARP settings finalize...
    Mar 14 13:39:37 php-fpm 37373 /xmlrpc.php: pfsync done in 30 seconds.
    Mar 14 13:39:06 php-fpm 37373 /xmlrpc.php: waiting for pfsync...
    Mar 14 13:39:05 kernel igb2: promiscuous mode disabled
    Mar 14 13:39:05 kernel carp: demoted by -240 to 0 (vhid removed)
    Mar 14 13:39:05 kernel ifa_maintain_loopback_route: deletion failed for interface igb2: 3
    Mar 14 13:39:05 kernel ifa_maintain_loopback_route: deletion failed for interface igb2: 3
    Mar 14 13:39:05 kernel ifa_maintain_loopback_route: deletion failed for interface igb2: 3
    Mar 14 13:39:05 kernel carp: demoted by 240 to 240 (interface down)
    Mar 14 13:39:05 kernel igb2: promiscuous mode enabled
    Mar 14 13:39:04 check_reload_status Syncing firewall
    Mar 14 13:31:31 php-fpm 31492 /rc.filter_configure_sync: The gateway: ISP2WINDSTREAMGW is invalid or unknown, not using it.
    Mar 14 13:31:31 php-fpm 31492 /rc.filter_configure_sync: Default gateway down setting ISP1_VZ_DHCP as default!
    Mar 14 13:31:31 php-fpm 37373 /rc.dyndns.update: Default gateway down setting ISP1_VZ_DHCP as default!
    Mar 14 13:31:30 php-fpm 31492 /rc.filter_configure_sync: The gateway: ISP2WINDSTREAMGW is invalid or unknown, not using it.
    Mar 14 13:31:30 check_reload_status Reloading filter
    Mar 14 13:31:30 check_reload_status Restarting OpenVPN tunnels/interfaces
    Mar 14 13:31:30 check_reload_status Restarting ipsec tunnels
    Mar 14 13:31:30 check_reload_status updating dyndns MSTGW
    Mar 14 13:31:30 rc.gateway_alarm 37911 >>> Gateway alarm: MSTGW (Addr:8.8.8.8 Alarm:1 RTT:0ms RTTsd:0ms Loss:100%)
    Mar 14 13:31:30 php-fpm 31492 /rc.filter_configure_sync: Default gateway down setting ISP1_VZ_DHCP as default!
    Mar 14 13:31:28 php-fpm 73954 /xmlrpc.php: Resyncing OpenVPN instances.
    Mar 14 13:31:28 php-fpm 73954 /xmlrpc.php: Removing static route for monitor 8.8.8.8 and adding a new route through HIDE-PUBLIC-GW-1
    Mar 14 13:31:28 php-fpm 73954 /xmlrpc.php: ROUTING: setting default route to HIDE-PUBLIC-GW-1
    Mar 14 13:31:28 check_reload_status Reloading filter
    Mar 14 13:30:31 php-fpm 39022 /rc.filter_configure_sync: The gateway: ISP2WINDSTREAMGW is invalid or unknown, not using it.
    Mar 14 13:30:31 php-fpm 39022 /rc.filter_configure_sync: Default gateway down setting ISP1_VZ_DHCP as default!
    Mar 14 13:30:31 php-fpm 73954 /rc.dyndns.update: Default gateway down setting ISP1_VZ_DHCP as default!
    Mar 14 13:30:30 php-fpm 39022 /rc.filter_configure_sync: The gateway: ISP2WINDSTREAMGW is invalid or unknown, not using it.
    Mar 14 13:30:30 check_reload_status Reloading filter
    Mar 14 13:30:30 check_reload_status Restarting OpenVPN tunnels/interfaces
    Mar 14 13:30:30 check_reload_status Restarting ipsec tunnels
    Mar 14 13:30:30 check_reload_status updating dyndns MSTGW
    Mar 14 13:30:30 rc.gateway_alarm 74844 >>> Gateway alarm: MSTGW (Addr:8.8.8.8 Alarm:1 RTT:0ms RTTsd:0ms Loss:100%)
    Mar 14 13:30:30 php-fpm 39022 /rc.filter_configure_sync: Default gateway down setting ISP1_VZ_DHCP as default!
    Mar 14 13:30:28 php-fpm 1941 /xmlrpc.php: Resyncing OpenVPN instances.
    Mar 14 13:30:28 php-fpm 1941 /xmlrpc.php: Removing static route for monitor 8.8.8.8 and adding a new route through HIDE-PUBLIC-GW-1
    Mar 14 13:30:28 php-fpm 1941 /xmlrpc.php: ROUTING: setting default route to HIDE-PUBLIC-GW-1
    Mar 14 13:30:28 check_reload_status Reloading filter
    Mar 14 13:30:27 php-fpm 39022 /xmlrpc.php: Configuring CARP settings finalize...
    Mar 14 13:30:27 php-fpm 39022 /xmlrpc.php: pfsync done in 30 seconds.
    Mar 14 13:29:56 php-fpm 39022 /xmlrpc.php: waiting for pfsync...
    Mar 14 13:29:55 kernel igb2: promiscuous mode disabled
    Mar 14 13:29:55 kernel carp: demoted by -240 to 0 (vhid removed)
    Mar 14 13:29:55 kernel ifa_maintain_loopback_route: deletion failed for interface igb2: 3
    Mar 14 13:29:55 kernel ifa_maintain_loopback_route: deletion failed for interface igb2: 3
    Mar 14 13:29:55 kernel ifa_maintain_loopback_route: deletion failed for interface igb2: 3
    Mar 14 13:29:55 kernel carp: demoted by 240 to 240 (interface down)
    Mar 14 13:29:55 kernel igb2: promiscuous mode enabled
    Mar 14 13:29:55 check_reload_status Syncing firewall
    Mar 14 13:29:27 php-fpm 23130 /xmlrpc.php: Configuring CARP settings finalize...
    Mar 14 13:29:27 php-fpm 23130 /xmlrpc.php: pfsync done in 30 seconds.
    Mar 14 13:28:56 php-fpm 23130 /xmlrpc.php: waiting for pfsync...



  • Hi all, I am having identical issues to those listed. I am running a virtual HA pair on version 2.4.2-RELEASE-p1. Did you manage to get to the bottom of this?



  • Hi!

    Yesterday I installed the update, the 2.4.3-Release. I have done some configurations and always the synchronisation runs without error. I can't see thes error again until yet.

    Tom



  • Hello Friends,

    I'm having the same issues... created a post here: https://forum.netgate.com/topic/131916/pfsense-with-ha-closing-sessions-when-apply-any-rule

    Anyone have solved this issue? is this a bug?