While reloading rules connection choose the wrong interface

[ggzengel]

I have multi wan with gateway group (wan1=tier1;cable=tier3; dsl=tier5).
At 5:00 my dsl interface will be reset. At this time my rsync connection will go through dsl and will stay there.

I have an application which uses rsync and pulls every second files and push files if there are some.

My log say the problem exists since 24.6.2013. Never had this before.

[eri--]

Its the state that is staying there nothing else.
The states do not move along with the tier since otherwise connectivity will break especially for TCP.

For applications that can recover there is nothing there that will reset the states after a higher tier comes up since it makes no sense in general.

[ggzengel]

There is no state. rsync runs once per second.
tier1 is up, tier2 is up, and at 5:00 tier3 will be restarted like every night.
Than it changes to tier3 while all the others are up.

It look like it restart all interfaces and dsl will first be up, but the other are not down.

[ggzengel]

Here is the log from 5:00:

Jul 2 05:00:54	ntop[2440]: THREADMGMT[t34629828672]: RRD: Throughput data collection: Thread running [p2440]
Jul 2 05:00:54	ntop[2440]: THREADMGMT[t34418502336]: RRD: Data collection thread running [p2440]
Jul 2 05:00:54	ntop[2440]: THREADMGMT[t34629828672]: RRD: Throughput data collection: Thread starting [p2440]
Jul 2 05:00:54	ntop[2440]: THREADMGMT[t34629828672]: RRD: Started thread for throughput data collection
Jul 2 05:00:49	ntop[2440]: CHKVER: This version of ntop is the CURRENT stable version
Jul 2 05:00:49	ntop[2440]: CHKVER: as of date is '2012-10-16T11:00:47'
Jul 2 05:00:49	ntop[2440]: CHKVER: Version file is from 'version.ntop.org'
Jul 2 05:00:49	ntop[2440]: CHKVER: Checking current ntop version at version.ntop.org/version.xml
Jul 2 05:00:44	ntop[2440]: THREADMGMT[t34424801024]: SFP: Fingerprint scan thread running [p2440]
Jul 2 05:00:44	ntop[2440]: THREADMGMT[t34424800576]: SIH: Idle host scan thread running [p2440]
Jul 2 05:00:44	ntop[2440]: THREADMGMT[t34418498752]: NPS(em1): pcapDispatch thread running [p2440]
Jul 2 05:00:44	ntop[2440]: THREADMGMT[t34418499648]: NPS(ovpns2): pcapDispatch thread running [p2440]
Jul 2 05:00:44	ntop[2440]: THREADMGMT[t34418498752]: NPS(em1): pcapDispatch thread starting [p2440]
Jul 2 05:00:44	ntop[2440]: THREADMGMT[t34418499200]: NPS(ovpns3): pcapDispatch thread running [p2440]
Jul 2 05:00:44	ntop[2440]: THREADMGMT[t34418498752]: NPS(8): Started thread for network packet sniffing [em1]
Jul 2 05:00:44	ntop[2440]: THREADMGMT[t34418499200]: NPS(ovpns3): pcapDispatch thread starting [p2440]
Jul 2 05:00:44	ntop[2440]: THREADMGMT[t34418499200]: NPS(7): Started thread for network packet sniffing [ovpns3]
Jul 2 05:00:44	ntop[2440]: THREADMGMT[t34418500096]: NPS(ovpns1): pcapDispatch thread running [p2440]
Jul 2 05:00:44	ntop[2440]: THREADMGMT[t34418499648]: NPS(ovpns2): pcapDispatch thread starting [p2440]
Jul 2 05:00:44	ntop[2440]: THREADMGMT[t34418499648]: NPS(6): Started thread for network packet sniffing [ovpns2]
Jul 2 05:00:44	ntop[2440]: THREADMGMT[t34418500096]: NPS(ovpns1): pcapDispatch thread starting [p2440]
Jul 2 05:00:44	ntop[2440]: THREADMGMT[t34418500992]: NPS(em6): pcapDispatch thread running [p2440]
Jul 2 05:00:44	ntop[2440]: THREADMGMT[t34418500096]: NPS(5): Started thread for network packet sniffing [ovpns1]
Jul 2 05:00:44	ntop[2440]: THREADMGMT[t34418500992]: NPS(em6): pcapDispatch thread starting [p2440]
Jul 2 05:00:44	ntop[2440]: THREADMGMT[t34418501888]: NPS(em0): pcapDispatch thread running [p2440]
Jul 2 05:00:44	ntop[2440]: THREADMGMT[t34418501440]: NPS(em2): pcapDispatch thread running [p2440]
Jul 2 05:00:44	ntop[2440]: THREADMGMT[t34418500992]: NPS(3): Started thread for network packet sniffing [em6]
Jul 2 05:00:44	ntop[2440]: THREADMGMT[t34418501440]: NPS(em2): pcapDispatch thread starting [p2440]
Jul 2 05:00:44	ntop[2440]: THREADMGMT[t34418501440]: NPS(2): Started thread for network packet sniffing [em2]
Jul 2 05:00:44	ntop[2440]: THREADMGMT[t34418501888]: NPS(em0): pcapDispatch thread starting [p2440]
Jul 2 05:00:44	ntop[2440]: THREADMGMT[t34418501888]: NPS(1): Started thread for network packet sniffing [em0]
Jul 2 05:00:44	ntop[2440]: THREADMGMT[t34418475456]: ntop RUNSTATE: RUN(4)
Jul 2 05:00:44	ntop[2440]: INIT: Created pid file (/var/run/ntop.pid)
Jul 2 05:00:44	ntop[2440]: Note: Reporting device initally set to 0 [em0]
Jul 2 05:00:44	ntop[2440]: Now running as requested user 'root' (0:0)
Jul 2 05:00:44	ntop[2440]: THREADMGMT[t34418502336]: RRD: Data collection thread starting [p2440]
Jul 2 05:00:44	ntop[2440]: THREADMGMT: RRD: Started thread (t34418502336) for data collection
Jul 2 05:00:44	ntop[2440]: RRD: Mask for new files is 0066
Jul 2 05:00:44	ntop[2440]: RRD: Mask for new directories is 0700
Jul 2 05:00:44	ntop[2440]: RRD: Welcome to the RRD plugin
Jul 2 05:00:44	ntop[2440]: Calling plugin start functions (if any)
Jul 2 05:00:44	ntop[2440]: SFLOW: Welcome to sFlow.(C) 2002-12 by Luca Deri
Jul 2 05:00:44	ntop[2440]: RRD: Welcome to Round-Robin Database. (C) 2002-12 by Luca Deri.
Jul 2 05:00:44	ntop[2440]: NETFLOW: Welcome to NetFlow.(C) 2002-12 by Luca Deri
Jul 2 05:00:44	ntop[2440]: Searching for plugins in /usr/pbi/ntop-amd64/lib/ntop/plugins
Jul 2 05:00:44	ntop[2440]: WEB: ntop's web server is now processing requests
Jul 2 05:00:44	ntop[2440]: THREADMGMT[t34418502784]: WEB: Server connection thread running [p2440]
Jul 2 05:00:44	ntop[2440]: Note: SIGPIPE handler set (ignore)
Jul 2 05:00:44	ntop[2440]: Loading Plugins
Jul 2 05:00:44	ntop[2440]: THREADMGMT[t34418502784]: WEB: Server connection thread starting [p2440]
Jul 2 05:00:44	ntop[2440]: THREADMGMT[t34418502784]: INITWEB: Started thread for web server
Jul 2 05:00:44	ntop[2440]: INITWEB: Starting web server
Jul 2 05:00:44	ntop[2440]: INITWEB: Waiting for HTTP connections on port 3000
Jul 2 05:00:44	ntop[2440]: INITWEB: Initialized socket, port 3000, address (any)
Jul 2 05:00:44	ntop[2440]: INITWEB: Initializing TCP/IP socket connections for web server
Jul 2 05:00:44	ntop[2440]: INITWEB: Initializing web server
Jul 2 05:00:44	ntop[2440]: SSL is present but https is disabled: use -W <https port="">for enabling it
Jul 2 05:00:44	ntop[2440]: NOTE: Interface merge disabled by default
Jul 2 05:00:44	ntop[2440]: GeoIP: loaded ASN config file /usr/pbi/ntop-amd64/etc/ntop/GeoIPASNum.dat
Jul 2 05:00:44	ntop[2440]: GeoIP: loaded config file /usr/pbi/ntop-amd64/etc/ntop/GeoLiteCity.dat
Jul 2 05:00:44	ntop[2440]: Calling plugin start functions (if any)
Jul 2 05:00:44	ntop[2440]: THREADMGMT[t34418503232]: DNSAR(3): Address resolution thread running
Jul 2 05:00:44	ntop[2440]: THREADMGMT[t34418503232]: DNSAR(3): Started thread for DNS address resolution
Jul 2 05:00:44	ntop[2440]: THREADMGMT[t34424799680]: DNSAR(2): Address resolution thread running
Jul 2 05:00:44	ntop[2440]: THREADMGMT[t34424799680]: DNSAR(2): Started thread for DNS address resolution
Jul 2 05:00:44	ntop[2440]: THREADMGMT[t34424800128]: DNSAR(1): Address resolution thread running
Jul 2 05:00:44	ntop[2440]: THREADMGMT[t34424800128]: DNSAR(1): Started thread for DNS address resolution
Jul 2 05:00:44	ntop[2440]: THREADMGMT[t34424800576]: SIH: Idle host scan thread starting [p2440]
Jul 2 05:00:44	ntop[2440]: THREADMGMT[t34424800576]: SIH: Started thread for idle hosts detection
Jul 2 05:00:44	ntop[2440]: THREADMGMT[t34424801024]: SFP: Fingerprint scan thread starting [p2440]
Jul 2 05:00:44	ntop[2440]: THREADMGMT[t34424801024]: SFP: Started thread for fingerprinting
Jul 2 05:00:44	ntop[2440]: Initializing external applications
Jul 2 05:00:44	kernel: em1: promiscuous mode enabled
Jul 2 05:00:44	kernel: ovpns3: promiscuous mode enabled
Jul 2 05:00:44	kernel: ovpns2: promiscuous mode enabled
Jul 2 05:00:44	kernel: ovpns1: promiscuous mode enabled
Jul 2 05:00:44	kernel: em6: promiscuous mode enabled
Jul 2 05:00:44	kernel: em2: promiscuous mode enabled
Jul 2 05:00:44	ntop[2440]: THREADMGMT[t34418475456]: Now running as a daemon
Jul 2 05:00:44	kernel: em0: promiscuous mode enabled
Jul 2 05:00:44	ntop[2112]: THREADMGMT[t34418475456]: ntop RUNSTATE: INIT(2)
Jul 2 05:00:44	ntop[2112]: THREADMGMT[t34418475456]: ntop RUNSTATE: PREINIT(1)
Jul 2 05:00:40	php: : The command '/usr/local/etc/rc.d/ntop.sh stop' returned exit code '1', the output was 'No matching processes were found'
Jul 2 05:00:38	ntop[99774]: THREADMGMT[t34418475456]: ntop RUNSTATE: INIT(2)
Jul 2 05:00:38	ntop[99774]: THREADMGMT[t34418475456]: ntop RUNSTATE: PREINIT(1)
Jul 2 05:00:22	upsd[58637]: User monuser@127.0.0.1 logged into UPS [APC]
Jul 2 05:00:22	upsmon[58912]: Startup successful
Jul 2 05:00:22	upsd[58637]: Startup successful
Jul 2 05:00:22	upsd[58574]: Connected to UPS [APC]: snmp-ups-APC
Jul 2 05:00:22	upsd[58574]: listening on 127.0.0.1 port 3493
Jul 2 05:00:22	upsd[58574]: listening on ::1 port 3493
Jul 2 05:00:22	snmp-ups[58455]: Startup successful
Jul 2 05:00:19	kernel: em1: promiscuous mode disabled
Jul 2 05:00:19	kernel: ovpns3: promiscuous mode disabled
Jul 2 05:00:19	kernel: ovpns2: promiscuous mode disabled
Jul 2 05:00:19	kernel: ovpns1: promiscuous mode disabled
Jul 2 05:00:19	kernel: em6: promiscuous mode disabled
Jul 2 05:00:19	kernel: em2: promiscuous mode disabled
Jul 2 05:00:19	kernel: em0: promiscuous mode disabled
Jul 2 05:00:19	ntop[83892]: ===================================
Jul 2 05:00:19	ntop[83892]: ntop is shutdown...
Jul 2 05:00:19	ntop[83892]: ===================================
Jul 2 05:00:19	ntop[83892]: CLEANUP[t34632944384]: Still running threads SFP SIH WEB
Jul 2 05:00:19	ntop[83892]: THREADMGMT[t34632944384]: ntop RUNSTATE: TERM(8)
Jul 2 05:00:19	ntop[83892]: CLEANUP: Clean up complete
Jul 2 05:00:19	ntop[83892]: TERM: Removed pid file (/var/run/ntop.pid)
Jul 2 05:00:19	ntop[83892]: CLEANUP: Freeing device em1
Jul 2 05:00:19	ntop[83892]: CLEANUP: Freeing device ovpns3
Jul 2 05:00:19	ntop[83892]: CLEANUP: Freeing device ovpns2
Jul 2 05:00:19	ntop[83892]: CLEANUP: Freeing device ovpns1
Jul 2 05:00:19	ntop[83892]: CLEANUP: Freeing device em6
Jul 2 05:00:19	ntop[83892]: CLEANUP: Freeing device em2
Jul 2 05:00:19	ntop[83892]: CLEANUP: Freeing device em0
Jul 2 05:00:19	ntop[83892]: RRD: Done
Jul 2 05:00:19	ntop[83892]: RRD: Thanks for using the rrdPlugin
Jul 2 05:00:19	ntop[83892]: THREADMGMT[t34632944384]: RRD: Plugin shutdown continuing
Jul 2 05:00:19	ntop[83892]: THREADMGMT[t34632944384]: RRD: killThread(rrdTrafficThread) succeeded
Jul 2 05:00:19	ntop[83892]: THREADMGMT[t34632944384]: RRD: killThread(rrdThread) succeeded
Jul 2 05:00:19	ntop[83892]: RRD: Shutting down, locking mutex (may block for a little while)
Jul 2 05:00:19	ntop[83892]: PLUGIN_TERM: Unloading plugins (if any)
Jul 2 05:00:19	ntop[83892]: DEBUG: freeDeviceSessions: freed 56 sessions
Jul 2 05:00:19	ntop[83892]: freeDeviceSessions() called for device 7
Jul 2 05:00:19	ntop[83892]: FREE_HOST: End, freed 0
Jul 2 05:00:19	ntop[83892]: FREE_HOST: Start, 8 device(s)
Jul 2 05:00:19	ntop[83892]: DEBUG: freeDeviceSessions: freed 3 sessions
Jul 2 05:00:19	ntop[83892]: freeDeviceSessions() called for device 6
Jul 2 05:00:19	ntop[83892]: FREE_HOST: End, freed 0
Jul 2 05:00:19	ntop[83892]: FREE_HOST: Start, 8 device(s)
Jul 2 05:00:19	ntop[83892]: DEBUG: freeDeviceSessions: freed 9 sessions
Jul 2 05:00:19	ntop[83892]: freeDeviceSessions() called for device 5
Jul 2 05:00:19	ntop[83892]: FREE_HOST: End, freed 0
Jul 2 05:00:19	ntop[83892]: FREE_HOST: Start, 8 device(s)
Jul 2 05:00:19	ntop[83892]: DEBUG: freeDeviceSessions: freed 1 sessions
Jul 2 05:00:19	ntop[83892]: freeDeviceSessions() called for device 4
Jul 2 05:00:19	ntop[83892]: FREE_HOST: End, freed 0
Jul 2 05:00:19	ntop[83892]: FREE_HOST: Start, 8 device(s)
Jul 2 05:00:19	ntop[83892]: FREE_HOST: End, freed 0
Jul 2 05:00:19	ntop[83892]: FREE_HOST: Start, 8 device(s)
Jul 2 05:00:19	ntop[83892]: FREE_HOST: End, freed 0
Jul 2 05:00:19	ntop[83892]: FREE_HOST: Start, 8 device(s)
Jul 2 05:00:19	ntop[83892]: DEBUG: freeDeviceSessions: freed 49 sessions
Jul 2 05:00:19	ntop[83892]: freeDeviceSessions() called for device 1
Jul 2 05:00:19	ntop[83892]: FREE_HOST: End, freed 0
Jul 2 05:00:19	ntop[83892]: FREE_HOST: Start, 8 device(s)
Jul 2 05:00:19	ntop[83892]: DEBUG: freeDeviceSessions: freed 107 sessions
Jul 2 05:00:19	ntop[83892]: freeDeviceSessions() called for device 0
Jul 2 05:00:19	ntop[83892]: FREE_HOST: End, freed 1854
Jul 2 05:00:19	ntop[83892]: FREE_HOST: Start, 8 device(s)
Jul 2 05:00:19	ntop[83892]: CLEANUP: Continues (still running SFP SIH WEB)
Jul 2 05:00:19	ntop[83892]: CLEANUP: Locked purge mutex, continuing shutdown
Jul 2 05:00:19	ntop[83892]: CLEANUP: Locking purge mutex (may block for a little while)
Jul 2 05:00:19	ntop[83892]: THREADMGMT[t34418498752]: NPS(em1): pcapDispatch thread terminated [p83892]
Jul 2 05:00:18	ntop[83892]: Joining thread NPS(em1) [t34418498752]
Jul 2 05:00:18	ntop[83892]: STATS: 0 packets dropped (by ntop)
Jul 2 05:00:18	ntop[83892]: STATS: 0 packets dropped (according to libpcap)
Jul 2 05:00:18	ntop[83892]: STATS: 36,572,959 packets received by filter on em1
Jul 2 05:00:18	ntop[83892]: THREADMGMT[t34418500992]: NPS(em6): pcapDispatch thread terminated [p83892]
Jul 2 05:00:18	ntop[83892]: THREADMGMT[t34418499648]: NPS(ovpns2): pcapDispatch thread terminated [p83892]
Jul 2 05:00:18	ntop[83892]: Joining thread NPS(em6) [t34418500992]
Jul 2 05:00:18	ntop[83892]: STATS: 0 packets dropped (by ntop)
Jul 2 05:00:18	ntop[83892]: STATS: 0 packets dropped (according to libpcap)
Jul 2 05:00:18	ntop[83892]: STATS: 2,879 packets received by filter on em6
Jul 2 05:00:18	ntop[83892]: THREADMGMT[t34418501440]: NPS(em2): pcapDispatch thread terminated [p83892]
Jul 2 05:00:18	ntop[83892]: THREADMGMT[t34418499200]: NPS(ovpns3): pcapDispatch thread terminated [p83892]
Jul 2 05:00:18	ntop[83892]: Joining thread NPS(em2) [t34418501440]
Jul 2 05:00:18	ntop[83892]: STATS: 0 packets dropped (by ntop)
Jul 2 05:00:18	ntop[83892]: STATS: 0 packets dropped (according to libpcap)
Jul 2 05:00:18	ntop[83892]: STATS: 2,523,266 packets received by filter on em2
Jul 2 05:00:18	ntop[83892]: THREADMGMT[t34418501888]: NPS(em0): pcapDispatch thread terminated [p83892]
Jul 2 05:00:18	ntop[83892]: THREADMGMT[t34418500096]: NPS(ovpns1): pcapDispatch thread terminated [p83892]
Jul 2 05:00:18	ntop[83892]: THREADMGMT[t34418503232]: DNSAR(3): Address resolution thread terminated [p83892]
Jul 2 05:00:18	ntop[83892]: Joining thread NPS(em0) [t34418501888]
Jul 2 05:00:18	ntop[83892]: STATS: 0 packets dropped (by ntop)
Jul 2 05:00:18	ntop[83892]: STATS: 0 packets dropped (according to libpcap)
Jul 2 05:00:18	ntop[83892]: STATS: 40,167,494 packets received by filter on em0
Jul 2 05:00:18	ntop[83892]: THREADMGMT[t34424800128]: DNSAR(1): Address resolution thread terminated [p83892]
Jul 2 05:00:18	ntop[83892]: Signaling thread DNSAR3
Jul 2 05:00:18	ntop[83892]: THREADMGMT[t34424799680]: DNSAR(2): Address resolution thread terminated [p83892]
Jul 2 05:00:18	ntop[83892]: Signaling thread DNSAR2
Jul 2 05:00:18	ntop[83892]: Signaling thread DNSAR1
Jul 2 05:00:18	ntop[83892]: CLEANUP: Running threads SFP SIH WEB DNSAR1 DNSAR2 DNSAR3 NPS(em0) NPS(em2) NPS(em6) NPS(ovpns1) NPS(ovpns2) NPS(ovpns3) NPS(em1)
Jul 2 05:00:18	ntop[83892]: CLEANUP[t34632944384] catching thread is unknown
Jul 2 05:00:18	ntop[83892]: THREADMGMT[t34632944384]: ntop RUNSTATE: SHUTDOWN(7)
Jul 2 05:00:18	ntop[83892]: Active sessions=107/Active hosts=653
Jul 2 05:00:18	ntop[83892]: CLEANUP[t34632944384]: ntop caught signal 15 [state=4]
Jul 2 05:00:14	snmp-ups[44678]: Signal 15: exiting
Jul 2 05:00:14	upsd[45262]: Signal 15: exiting
Jul 2 05:00:14	upsd[45262]: mainloop: Interrupted system call
Jul 2 05:00:14	upsd[45262]: User monuser@127.0.0.1 logged out from UPS [APC]
Jul 2 05:00:14	upsmon[45637]: Signal 15: exiting
Jul 2 05:00:13	php: : Restarting/Starting all packages.
Jul 2 05:00:13	kernel: pid 24744 (ntpd), uid 0: exited on signal 11 (core dumped)
Jul 2 05:00:11	check_reload_status: Reloading filter
Jul 2 05:00:11	check_reload_status: Starting packages
Jul 2 05:00:11	php: : pfSense package system has detected an ip change 80.153.72.177 -> 80.153.72.177 ... Restarting packages.
Jul 2 05:00:09	php: : Creating rrd update script
Jul 2 05:00:09	php: : Resyncing OpenVPN instances for interface 3_TDSL.
Jul 2 05:00:09	php: : Ignoring IPsec racoon daemon reload since there are no tunnels on interface opt5
Jul 2 05:00:02	check_reload_status: Rewriting resolv.conf
Jul 2 05:00:02	php: : rc.kill_states: Removing states for IP 80.153.72.177/32
Jul 2 05:00:02	php: : Starting 3gstats.php on device '' for interface 'opt5'
Jul 2 05:00:00	check_reload_status: Configuring interface opt5</https> 

[eri--]

By any chance you are using switch default route option in the advanced section?

[ggzengel]

Yes and I have a rule for rsync which uses the gateway group.