HAproxy not rebinding properly after WAN DHCP IP change



  • pfSense 2.3.2
    haproxy package 0.48 (dependency haproxy-1.6.6)

    Issue:
    After my WAN interface received a new IP (DHCP), the haproxy service did not rebind properly to the new IP.
    HAproxy configuration interface showed the new IP correctly in the "address" column for my frontend, but attempting to access the backend via my domain name over https, redirected me to pfsense, which gave me the typical "Potential DNS Rebind attack detected" warning.

    Recovery:
    Restart HAproxy service.

    There's nothing obvious in syslog to indicate why haproxy did not restart properly.

    Is this a known issue fixed in later versions of this package, or pfSense?
    I haven't found a way to get a changelog for the newer versions of this package.

    How can I find out if this is known (and corrected), or if I need to file a bug report (and where do I do that)?

    
    Nov 11 02:08:53	check_reload_status		updating dyndns WAN_DHCP
    Nov 11 02:08:53	check_reload_status		Restarting ipsec tunnels
    Nov 11 02:08:53	check_reload_status		Restarting OpenVPN tunnels/interfaces
    Nov 11 02:08:53	check_reload_status		Reloading filter
    Nov 11 02:08:55	php-fpm	53556	/rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use WAN_DHCP.
    Nov 11 02:08:55	xinetd	18912	Starting reconfiguration
    Nov 11 02:08:55	xinetd	18912	Swapping defaults
    Nov 11 02:08:55	xinetd	18912	readjusting service 6969-udp
    Nov 11 02:08:55	xinetd	18912	Reconfigured: new=0 old=1 dropped=0 (services)
    Nov 11 02:09:10	php-fpm	64326	/rc.newipsecdns: IPSEC: One or more IPsec tunnel endpoints has changed its IP. Refreshing.
    Nov 11 02:09:10	php-fpm	64326	/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.
    Nov 11 02:09:10	check_reload_status		Reloading filter
    Nov 11 02:09:11	xinetd	18912	Starting reconfiguration
    Nov 11 02:09:11	xinetd	18912	Swapping defaults
    Nov 11 02:09:11	xinetd	18912	readjusting service 6969-udp
    Nov 11 02:09:11	xinetd	18912	Reconfigured: new=0 old=1 dropped=0 (services)
    Nov 11 02:56:35	kernel		arpresolve: can't allocate llinfo for <ip-of-old-default-route> on vmx0
    Nov 11 02:56:35	kernel		arpresolve: can't allocate llinfo for <ip-of-old-default-route> on vmx0
    Nov 11 02:56:36	kernel		arpresolve: can't allocate llinfo for <ip-of-old-default-route> on vmx0
    Nov 11 02:56:36	kernel		arpresolve: can't allocate llinfo for <ip-of-old-default-route> on vmx0
    Nov 11 02:56:36	kernel		arpresolve: can't allocate llinfo for <ip-of-old-default-route> on vmx0
    Nov 11 02:56:36	kernel		arpresolve: can't allocate llinfo for <ip-of-old-default-route> on vmx0
    Nov 11 02:56:36	kernel		arpresolve: can't allocate llinfo for <ip-of-old-default-route> on vmx0
    Nov 11 02:56:36	kernel		arpresolve: can't allocate llinfo for <ip-of-old-default-route> on vmx0
    Nov 11 02:56:36	kernel		arpresolve: can't allocate llinfo for <ip-of-old-default-route> on vmx0
    Nov 11 02:56:36	kernel		arpresolve: can't allocate llinfo for <ip-of-old-default-route> on vmx0
    Nov 11 02:56:36	kernel		arpresolve: can't allocate llinfo for <ip-of-old-default-route> on vmx0
    Nov 11 02:56:37	kernel		arpresolve: can't allocate llinfo for <ip-of-old-default-route> on vmx0
    Nov 11 02:56:37	kernel		arpresolve: can't allocate llinfo for <ip-of-old-default-route> on vmx0
    Nov 11 02:56:37	kernel		arpresolve: can't allocate llinfo for <ip-of-old-default-route> on vmx0
    Nov 11 02:56:37	kernel		arpresolve: can't allocate llinfo for <ip-of-old-default-route> on vmx0
    Nov 11 02:56:38	kernel		arpresolve: can't allocate llinfo for <ip-of-old-default-route> on vmx0
    Nov 11 02:56:38	kernel		arpresolve: can't allocate llinfo for <ip-of-old-default-route> on vmx0
    Nov 11 02:56:38	kernel		arpresolve: can't allocate llinfo for <ip-of-old-default-route> on vmx0
    Nov 11 02:56:38	kernel		arpresolve: can't allocate llinfo for <ip-of-old-default-route> on vmx0
    Nov 11 02:56:38	kernel		arpresolve: can't allocate llinfo for <ip-of-old-default-route> on vmx0
    Nov 11 02:56:38	kernel		arpresolve: can't allocate llinfo for <ip-of-old-default-route> on vmx0
    Nov 11 02:56:39	kernel		arpresolve: can't allocate llinfo for <ip-of-old-default-route> on vmx0
    Nov 11 02:56:39	kernel		arpresolve: can't allocate llinfo for <ip-of-old-default-route> on vmx0
    Nov 11 02:56:39	kernel		arpresolve: can't allocate llinfo for <ip-of-old-default-route> on vmx0
    Nov 11 02:56:39	kernel		arpresolve: can't allocate llinfo for <ip-of-old-default-route> on vmx0
    Nov 11 02:56:40	kernel		arpresolve: can't allocate llinfo for <ip-of-old-default-route> on vmx0
    Nov 11 02:56:40	kernel		arpresolve: can't allocate llinfo for <ip-of-old-default-route> on vmx0
    Nov 11 02:56:40	kernel		arpresolve: can't allocate llinfo for <ip-of-old-default-route> on vmx0
    Nov 11 02:56:41	kernel		arpresolve: can't allocate llinfo for <ip-of-old-default-route> on vmx0
    Nov 11 02:56:41	kernel		arpresolve: can't allocate llinfo for <ip-of-old-default-route> on vmx0
    Nov 11 02:56:41	kernel		arpresolve: can't allocate llinfo for <ip-of-old-default-route> on vmx0
    Nov 11 02:56:41	kernel		arpresolve: can't allocate llinfo for <ip-of-old-default-route> on vmx0
    Nov 11 02:56:41	kernel		arpresolve: can't allocate llinfo for <ip-of-old-default-route> on vmx0
    Nov 11 02:56:42	kernel		arpresolve: can't allocate llinfo for <ip-of-old-default-route> on vmx0
    Nov 11 02:56:42	kernel		arpresolve: can't allocate llinfo for <ip-of-old-default-route> on vmx0
    Nov 11 02:56:42	kernel		arpresolve: can't allocate llinfo for <ip-of-old-default-route> on vmx0
    Nov 11 02:56:43	kernel		arpresolve: can't allocate llinfo for <ip-of-old-default-route> on vmx0
    Nov 11 02:56:44	kernel		arpresolve: can't allocate llinfo for <ip-of-old-default-route> on vmx0
    Nov 11 02:56:45	kernel		arpresolve: can't allocate llinfo for <ip-of-old-default-route> on vmx0
    Nov 11 02:56:45	kernel		arpresolve: can't allocate llinfo for <ip-of-old-default-route> on vmx0
    Nov 11 02:56:45	kernel		arpresolve: can't allocate llinfo for <ip-of-old-default-route> on vmx0
    Nov 11 02:56:47	kernel		arpresolve: can't allocate llinfo for <ip-of-old-default-route> on vmx0
    Nov 11 02:56:51	kernel		arpresolve: can't allocate llinfo for <ip-of-old-default-route> on vmx0
    Nov 11 02:56:51	kernel		arpresolve: can't allocate llinfo for <ip-of-old-default-route> on vmx0
    Nov 11 02:56:51	kernel		arpresolve: can't allocate llinfo for <ip-of-old-default-route> on vmx0
    Nov 11 02:56:51	kernel		arpresolve: can't allocate llinfo for <ip-of-old-default-route> on vmx0
    Nov 11 02:56:57	kernel		arpresolve: can't allocate llinfo for <ip-of-old-default-route> on vmx0
    Nov 11 02:57:39	kernel		arpresolve: can't allocate llinfo for <ip-of-old-default-route> on vmx0
    Nov 11 03:06:48	check_reload_status		rc.newwanip starting vmx0
    Nov 11 03:06:48	kernel		arpresolve: can't allocate llinfo for <ip-of-old-default-route> on vmx0
    Nov 11 03:06:48	kernel		arpresolve: can't allocate llinfo for <ip-of-old-default-route> on vmx0
    Nov 11 03:06:48	kernel		arpresolve: can't allocate llinfo for <ip-of-old-default-route> on vmx0
    Nov 11 03:06:49	kernel		arpresolve: can't allocate llinfo for <ip-of-old-default-route> on vmx0
    Nov 11 03:06:49	kernel		arpresolve: can't allocate llinfo for <ip-of-old-default-route> on vmx0
    Nov 11 03:06:49	php-fpm	53556	/rc.newwanip: rc.newwanip: Info: starting on vmx0.
    Nov 11 03:06:49	php-fpm	53556	/rc.newwanip: rc.newwanip: on (IP address: <new-wan-ip>) (interface: WAN[wan]) (real interface: vmx0).
    Nov 11 03:06:49	php-fpm	53556	/rc.newwanip: IP has changed, killing states on former IP 0.0.0.0.
    Nov 11 03:06:49	kernel		arpresolve: can't allocate llinfo for <ip-of-old-default-route> on vmx0
    Nov 11 03:06:49	xinetd	18912	Starting reconfiguration
    Nov 11 03:06:49	xinetd	18912	Swapping defaults
    Nov 11 03:06:49	xinetd	18912	readjusting service 6969-udp
    Nov 11 03:06:49	xinetd	18912	Reconfigured: new=0 old=1 dropped=0 (services)
    Nov 11 03:06:49	kernel		arpresolve: can't allocate llinfo for <ip-of-old-default-route> on vmx0
    Nov 11 03:06:49	php-fpm	53556	/rc.newwanip: ROUTING: setting default route to <ip-of-new-default-route>
    Nov 11 03:06:51	kernel		arpresolve: can't allocate llinfo for <ip-of-old-default-route> on vmx0
    Nov 11 03:06:51	kernel		arpresolve: can't allocate llinfo for <ip-of-old-default-route> on vmx0
    Nov 11 03:06:51	kernel		arpresolve: can't allocate llinfo for <ip-of-old-default-route> on vmx0
    Nov 11 03:06:52	kernel		arpresolve: can't allocate llinfo for <ip-of-old-default-route> on vmx0
    Nov 11 03:06:52	kernel		arpresolve: can't allocate llinfo for <ip-of-old-default-route> on vmx0
    Nov 11 03:06:52	kernel		arpresolve: can't allocate llinfo for <ip-of-old-default-route> on vmx0
    Nov 11 03:06:54	php-fpm	53556	/rc.newwanip: Forcefully reloading IPsec
    Nov 11 03:06:54	check_reload_status		Reloading filter
    Nov 11 03:06:54	php-fpm	53556	/rc.newwanip: 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.
    Nov 11 03:06:54	php-fpm	53556	/rc.newwanip: Resyncing OpenVPN instances for interface WAN.
    Nov 11 03:06:54	kernel		ovpns2: link state changed to DOWN
    Nov 11 03:06:54	check_reload_status		Reloading filter
    Nov 11 03:06:54	php-fpm	53556	/rc.newwanip: Creating rrd update script
    Nov 11 03:06:54	kernel		ovpns2: link state changed to UP
    Nov 11 03:06:54	check_reload_status		rc.newwanip starting ovpns2
    Nov 11 03:06:55	xinetd	18912	Starting reconfiguration
    Nov 11 03:06:55	xinetd	18912	Swapping defaults
    Nov 11 03:06:55	xinetd	18912	readjusting service 6969-udp
    Nov 11 03:06:55	xinetd	18912	Reconfigured: new=0 old=1 dropped=0 (services)
    Nov 11 03:06:56	xinetd	18912	Starting reconfiguration
    Nov 11 03:06:56	xinetd	18912	Swapping defaults
    Nov 11 03:06:56	xinetd	18912	readjusting service 6969-udp
    Nov 11 03:06:56	xinetd	18912	Reconfigured: new=0 old=1 dropped=0 (services)
    Nov 11 03:06:56	php-fpm	37660	/rc.newwanip: rc.newwanip: Info: starting on ovpns2.
    Nov 11 03:06:56	php-fpm	37660	/rc.newwanip: rc.newwanip: on (IP address: <internal-vpn-ip>) (interface: []) (real interface: ovpns2).
    Nov 11 03:06:56	php-fpm	37660	/rc.newwanip: rc.newwanip called with empty interface.
    Nov 11 03:06:56	php-fpm	37660	/rc.newwanip: pfSense package system has detected an IP change or dynamic WAN reconnection - -> <internal-vpn-ip> - Restarting packages.
    Nov 11 03:06:56	check_reload_status		Reloading filter
    Nov 11 03:06:56	check_reload_status		Starting packages
    Nov 11 03:06:56	php-fpm	53556	/rc.newwanip: pfSense package system has detected an IP change or dynamic WAN reconnection - 0.0.0.0 -> <new-wan-ip> - Restarting packages.
    Nov 11 03:06:56	check_reload_status		Starting packages
    Nov 11 03:06:56	snmpd	73950	disk_OS_get_disks: adding device 'da0' to device list
    Nov 11 03:06:56	snmpd	73950	disk_OS_get_disks: adding device 'cd0' to device list
    Nov 11 03:06:56	snmpd	73950	hrPrinterTable: printcap entry for <noname?> has errors, skipping
    Nov 11 03:06:57	php-fpm	37660	/rc.start_packages: Restarting/Starting all packages.
    Nov 11 03:06:57	php-fpm	64326	/rc.start_packages: Skipping STARTing packages process because previous/another instance is already running</noname?></new-wan-ip></internal-vpn-ip></internal-vpn-ip></ip-of-old-default-route></ip-of-old-default-route></ip-of-old-default-route></ip-of-old-default-route></ip-of-old-default-route></ip-of-old-default-route></ip-of-new-default-route></ip-of-old-default-route></ip-of-old-default-route></new-wan-ip></ip-of-old-default-route></ip-of-old-default-route></ip-of-old-default-route></ip-of-old-default-route></ip-of-old-default-route></ip-of-old-default-route></ip-of-old-default-route></ip-of-old-default-route></ip-of-old-default-route></ip-of-old-default-route></ip-of-old-default-route></ip-of-old-default-route></ip-of-old-default-route></ip-of-old-default-route></ip-of-old-default-route></ip-of-old-default-route></ip-of-old-default-route></ip-of-old-default-route></ip-of-old-default-route></ip-of-old-default-route></ip-of-old-default-route></ip-of-old-default-route></ip-of-old-default-route></ip-of-old-default-route></ip-of-old-default-route></ip-of-old-default-route></ip-of-old-default-route></ip-of-old-default-route></ip-of-old-default-route></ip-of-old-default-route></ip-of-old-default-route></ip-of-old-default-route></ip-of-old-default-route></ip-of-old-default-route></ip-of-old-default-route></ip-of-old-default-route></ip-of-old-default-route></ip-of-old-default-route></ip-of-old-default-route></ip-of-old-default-route></ip-of-old-default-route></ip-of-old-default-route></ip-of-old-default-route></ip-of-old-default-route></ip-of-old-default-route></ip-of-old-default-route></ip-of-old-default-route></ip-of-old-default-route></ip-of-old-default-route></ip-of-old-default-route></ip-of-old-default-route></ip-of-old-default-route></ip-of-old-default-route>
    


  • Hi Logan,

    Even though your log mentions "/rc.start_packages: Restarting/Starting all packages."  that command does not actually REstart packages.. It only calls start_service($internal_name); which means for haproxy that it checks if its already running and does nothing if it is.. The fix seems simple enough, change it to restart_service($internal_name); however that stops+starts packages, while it should actually be restarting/reloading them.. As with a stop+start its shortly not running at all. possibly interfering with internal services that should not be affected by a wan-ip change.

    Probably should create a bugreport on https://redmine.pfsense.org/projects/pfsense/issues for it if one does not exist.