So many filterdns instances…

dhatz · Dec 27, 2012, 3:35 PM

I've also noticed this issue, although not to the extreme extent in your example.

root 24929 0.0 0.6 4696 1468 ?? Is 8:01AM 0:00.04 /usr/local/sbin/filterdns -p /tmp/filterdns.pid -i 300 -c /var/etc/filterdns.conf -d 1
root 42328 0.0 0.6 4696 1564 ?? INs 2:54PM 0:00.02 /usr/local/sbin/filterdns -p /tmp/filterdns.pid -i 300 -c /var/etc/filterdns.conf -d 1
root 42685 0.0 0.6 4568 1456 ?? SNs 2:54PM 0:00.05 /usr/local/sbin/filterdns -p /var/run/filterdns-ipsec.pid -i 60 -c /var/etc/ipsec/filterdns-ipsec.hosts -d 1

cat /tmp/filterdns.pid

42328

How many filterdns processes are supposed to be running at any given moment?

cmb · Dec 28, 2012, 5:40 AM

There should be 1, 2 or 3 depending. One for filter, one for dynamic IPsec if using it, one for hostnames in CP if using them. The one for filter is what's getting duplicated in those instances. There's only one spot it gets launched and that code behaves fine. Ermal will have to check it out.
https://redmine.pfsense.org/issues/2737

bardelot · Dec 28, 2012, 1:48 PM

The one for ipsec is using a sleep(1); call between the killing and restarting, so maybe that could help here as well?

eri-- · Dec 28, 2012, 2:11 PM

Can you please put a debugging level of 8 on the filter.inc file and see what it logs that you get these many of them?

stefb · Dec 30, 2012, 9:21 PM

I'll be back home on the 2nd, i'll post debug output by then…

Cheers...
Stéphane

dhatz · Dec 30, 2012, 10:20 PM

Another small fix to consider while having a look at the issue of multiple filterdns processes, is that the invoking script should use a consistent path for all filterdns pid files, rather than storing them in both /tmp and /var/run …

/tmp/filterdns.pid
/var/run/filterdns-ipsec.pid

eri-- · Dec 31, 2012, 8:28 AM

I am working on cleaning those up.

phil.davis · Jan 3, 2013, 3:40 AM

I upgraded 1 system to:
2.1-BETA1 (i386)
built on Wed Jan 2 16:40:07 EST 2013
FreeBSD 8.3-RELEASE-p5

In the system log, every 5 minutes, is:

Jan  3 08:16:35 imp-rt-01 filterdns: host_dns: failed looking up "(null)": hostname nor servname provided, or not known
Jan  3 08:21:35 imp-rt-01 filterdns: host_dns: failed looking up "(null)": hostname nor servname provided, or not known
Jan  3 08:26:35 imp-rt-01 filterdns: host_dns: failed looking up "(null)": hostname nor servname provided, or not known
Jan  3 08:31:35 imp-rt-01 filterdns: host_dns: failed looking up "(null)": hostname nor servname provided, or not known
Jan  3 08:36:35 imp-rt-01 filterdns: host_dns: failed looking up "(null)": hostname nor servname provided, or not known
Jan  3 08:41:35 imp-rt-01 filterdns: host_dns: failed looking up "(null)": hostname nor servname provided, or not known
Jan  3 08:46:36 imp-rt-01 filterdns: host_dns: failed looking up "(null)": hostname nor servname provided, or not known
Jan  3 08:51:36 imp-rt-01 filterdns: host_dns: failed looking up "(null)": hostname nor servname provided, or not known
Jan  3 08:56:36 imp-rt-01 filterdns: host_dns: failed looking up "(null)": hostname nor servname provided, or not known
Jan  3 09:01:36 imp-rt-01 filterdns: host_dns: failed looking up "(null)": hostname nor servname provided, or not known
Jan  3 09:06:36 imp-rt-01 filterdns: host_dns: failed looking up "(null)": hostname nor servname provided, or not known
Jan  3 09:11:36 imp-rt-01 filterdns: host_dns: failed looking up "(null)": hostname nor servname provided, or not known

/var/etc/filterdns.conf just has a list of dynDNS IP names that are used in an alias (actual names changed in the text below):

pf name-1.dyndns-ip.com INF_inet_ips
pf name-2.dyndns-ip.com INF_inet_ips
pf name-3.dyndns-ip.com INF_inet_ips
pf name-4.dyndns-ip.com INF_inet_ips
pf name-5.dyndns-ip.com INF_inet_ips
pf name-6.dyndns-ip.com INF_inet_ips
pf name-7.dyndns-ip.com INF_inet_ips
pf name-8.dyndns-ip.com INF_inet_ips
pf name-9.dyndns-ip.com INF_inet_ips
pf name-10.dyndns-ip.com INF_inet_ips
pf name-11.dyndns-ip.com INF_inet_ips

Systems on 31 Dec 2012 snapshots are not getting this in the system log.
I guess something in the recent filterdns code changes that Ermal is working on is processing a blank line somewhere?

eri-- · Jan 3, 2013, 8:29 AM

Upgrade to today snapshot(Jan 3) it should be better maybe you caught a snap with intermediate changes.

Also if you run top -H you should see the hostnames on each tread run for them.

phil.davis · Jan 3, 2013, 9:05 AM

A later/Jan 3 snap is not up yet. I will upgrade and report back when Jan 3 snap appears.

phil.davis · Jan 3, 2013, 4:10 PM

2.1-BETA1 (i386)
built on Thu Jan 3 02:32:11 EST 2013
FreeBSD 8.3-RELEASE-p5
still has the same failed looking up "(null)" message every 5 minutes.
There is another snap up now 06:39 - I'll load that now and see…

phil.davis · Jan 4, 2013, 3:26 AM

2.1-BETA1 (i386)
built on Thu Jan 3 19:04:10 EST 2013
FreeBSD 8.3-RELEASE-p5

Jan  4 08:51:17 imp-rt-01 filterdns: host_dns: failed looking up "(null)": hostname nor servname provided, or not known
Jan  4 08:56:17 imp-rt-01 filterdns: host_dns: failed looking up "(null)": hostname nor servname provided, or not known
Jan  4 09:01:18 imp-rt-01 filterdns: host_dns: failed looking up "(null)": hostname nor servname provided, or not known
Jan  4 09:06:18 imp-rt-01 filterdns: host_dns: failed looking up "(null)": hostname nor servname provided, or not known

This message is still logged every 5 minutes.

phil.davis · Jan 4, 2013, 8:01 AM

I checked in Diagnostics:Tables.

On a system that is running Mon Dec 31 12:20:48 EST 2012 snap (before the recent filterdns changes), my INF_iinet_ips table is long - it has the current 11 IP addresses that go with the 11 names in the table, and also has lots of old IP addresses that were dynamically allocated in the past.
(I think the recent filterdns changes will now be clearing up old entries)
On the system running Thu Jan 3 19:04:10 EST 2013 snap, there are exactly 11 IP addresses in the table, but they are out-of-date compared to the addresses I get with nslookup from my desktop. I rebooted and the 11 IP addresses are now current (so filterdns must be looking them up OK when it starts). I will monitor the table and see if the addresses go out-of-date over time.

filterdns: host_dns: failed looking up "(null)": hostname nor servname provided, or not known

still in syslog every 5 minutes.

eri-- · Jan 4, 2013, 10:11 PM

Should be corrected with tomorrow snapshot.

phil.davis · Jan 5, 2013, 6:20 AM

2.1-BETA1 (i386)
built on Fri Jan 4 17:38:46 EST 2013
FreeBSD 8.3-RELEASE-p5
Alix 32-bit nanoBSD
filterdns starts at bootup and successfully fills gets the current IP addresses for the 11 names in my alias table.
5 minutes later it dies (when it wakes up to check again, I suppose), with this in syslog:

kernel: pid 24638 (filterdns), uid 0: exited on signal 11

ps ax | grep filterdns
reveals that there is no filterdns process any more.
I rebooted, and the same behaviour is repeatable.

cybercare · Jan 5, 2013, 2:28 PM

You probably need to try todays snap as he said yesterday it would be in todays and you are still listing a jan 4 snap.

dhatz · Jan 5, 2013, 11:36 PM

Seems that running latest snapshot filterdns still has some issues

clog system.log | tail

Jan 6 00:58:26 fw php: : Creating rrd update script
Jan 6 00:58:28 fw php: : Forcefully reloading IPsec racoon daemon
Jan 6 00:58:28 fw php: : Restarting/Starting all packages.
Jan 6 00:58:30 fw dhclient[17095]: DHCPREQUEST on em0 to x.y.z.w port 67
Jan 6 00:58:30 fw dhclient[17095]: DHCPACK from x.y.z.w
Jan 6 00:58:30 fw dhclient: RENEW
Jan 6 00:58:30 fw dhclient: Creating resolv.conf
Jan 6 00:58:30 fw dhclient[17095]: bound to x.y.z.201 – renewal in 43200 seconds.
Jan 6 00:58:31 fw php: : Resyncing OpenVPN instances for interface WAN.
Jan 6 00:58:31 fw kernel: pid 50069 (filterdns), uid 0: exited on signal 11 (core dumped)
Jan 6 00:58:32 fw php: : IPSEC: One or more IPsec tunnel endpoints has changed its IP. Refreshing.
Jan 6 00:58:34 fw login: login on ttyv0 as root
Jan 6 00:58:36 fw check_reload_status: Updating all dyndns
Jan 6 00:58:36 fw check_reload_status: Restarting ipsec tunnels
Jan 6 00:58:36 fw check_reload_status: Restarting OpenVPN tunnels/interfaces
Jan 6 00:58:36 fw check_reload_status: Reloading filter
Jan 6 00:58:43 fw php: : IPSEC: One or more IPsec tunnel endpoints has changed its IP. Refreshing.
Jan 6 00:58:47 fw kernel: pid 87410 (filterdns), uid 0: exited on signal 11 (core dumped)
Jan 6 01:01:22 fw php: /firewall_rules.php: Successful login for user 'admin' from: 192.168.100.12
Jan 6 01:01:22 fw php: /firewall_rules.php: Successful login for user 'admin' from: 192.168.100.12

uname -a

FreeBSD fw.localdomain 8.3-RELEASE-p5 FreeBSD 8.3-RELEASE-p5 #1: Sat Jan 5 13:23:58 EST 2013 root@snapshots-8_3-i386.builders.pfsense.org:/usr/obj./usr/pfSensesrc/src/sys/pfSense_SMP.8 i386

It had the same issue with previous snapshots:

Jan 5 00:17:03 fw kernel: pid 48375 (filterdns), uid 0: exited on signal 11 (core dumped)
Jan 5 03:25:34 fw kernel: pid 45341 (filterdns), uid 0: exited on signal 11 (core dumped)
Jan 5 03:36:13 fw filterdns: host_dns: failed looking up "(null)": hostname nor servname provided, or not known
Jan 5 03:46:55 fw filterdns: host_dns: failed looking up "(null)": hostname nor servname provided, or not known
Jan 5 03:57:37 fw filterdns: host_dns: failed looking up "(null)": hostname nor servname provided, or not known
Jan 5 04:08:19 fw filterdns: host_dns: failed looking up "(null)": hostname nor servname provided, or not known
Jan 5 04:19:01 fw filterdns: host_dns: failed looking up "(null)": hostname nor servname provided, or not known
Jan 5 04:29:44 fw filterdns: host_dns: failed looking up "(null)": hostname nor servname provided, or not known
Jan 5 04:40:26 fw filterdns: host_dns: failed looking up "(null)": hostname nor servname provided, or not known
Jan 5 04:51:08 fw filterdns: host_dns: failed looking up "(null)": hostname nor servname provided, or not known
Jan 5 05:02:15 fw filterdns: host_dns: failed looking up "(null)": hostname nor servname provided, or not known
Jan 6 00:58:31 fw kernel: pid 50069 (filterdns), uid 0: exited on signal 11 (core dumped)
Jan 6 00:58:47 fw kernel: pid 87410 (filterdns), uid 0: exited on signal 11 (core dumped)
Jan 6 01:08:57 fw kernel: pid 24930 (filterdns), uid 0: exited on signal 11 (core dumped)

ls -la /filterdns.core

-rw–----- 1 root wheel 4661248 Jan 6 01:08 /filterdns.core

phil.davis · Jan 6, 2013, 6:12 AM

2.1-BETA1 (i386)
built on Sat Jan 5 17:06:02 EST 2013
FreeBSD 8.3-RELEASE-p5
Now I should definitely have all the recent filterdns code changes. Still have the same symptoms, the table gets the correct 11 IP addresses translated from the names at boot. 5 minutes later, filterdns dies:

[2.1-BETA1][admin@imp-rt-01.imp.infn]/var/log(6): clog system.log | grep filterdns
Jan  6 11:55:27 imp-rt-01 kernel: pid 27624 (filterdns), uid 0: exited on signal 11

eri-- · Jan 6, 2013, 5:30 PM

Hrm strange that you see that.
5 minutes is the default update interval for rechecking names.

I have run test here with 5 seconds and 10 second update intervals but no issues in that regard!
That makes still thing the snaps do not have the latest version of filterdns.

Can you make a md5 of your filterdns ?

dhatz · Jan 6, 2013, 6:50 PM

@ermal:

Can you make a md5 of your filterdns ?

MD5 (/usr/local/sbin/filterdns) = b25470f1942956d6f887ff87c99761c4