So many filterdns instances…

dhatz · Jan 18, 2013, 5:21 PM

Upgraded to today's latest snapshot, I'm still getting "exited on signal 11 (core dumped)" and I see only one filterdns process running (whereas in the past there used to be more filterdns processes – for ipsec / CP / etc)

iamzam · Jan 18, 2013, 5:50 PM

I have been following this thread because of similar problems with filterdns crash/core dumps and I have an observation:

My problem seems to be related to the filterdns that gets started through the vpn/ipsec stuff.

After updating to the latest snapshot today:

2.1-BETA1 (amd64)
built on Fri Jan 18 04:21:30 EST 2013
FreeBSD 8.3-RELEASE-p5

I increased the filterdns debug level to 10 (in vpn.inc, line 984, '-d 10' switch) and clicked save on the VPN -> IPsec page to restart the filterdns process monitoring the vpn endpoints.

Here is the log output I get after this:

Jan 18 12:29:51 pfs check_reload_status: Syncing firewall
Jan 18 12:29:51 pfs filterdns: Found hostname vpn.net.loc with netmask 32.
Jan 18 12:29:51 pfs filterdns: found entry 10.5.0.6 for (null)
Jan 18 12:29:51 pfs filterdns: found entry 10.5.0.6 for (null)
Jan 18 12:29:51 pfs filterdns: entry 10.5.0.6 exists in table (null)
Jan 18 12:29:51 pfs filterdns: found entry 10.5.0.6 for (null)
Jan 18 12:29:51 pfs filterdns: entry 10.5.0.6 exists in table (null)
Jan 18 12:29:51 pfs filterdns: Found 1 entries for vpn.net.loc
Jan 18 12:29:51 pfs check_reload_status: Restarting ipsec tunnels
Jan 18 12:29:51 pfs filterdns: Ran command /usr/local/sbin/pfSctl -c "service reload ipsecdns" with exit status 0 because a dns change on hostname vpn.net.loc was detected.
Jan 18 12:29:53 pfs php: : IPSEC: One or more IPsec tunnel endpoints has changed its IP. Refreshing.
Jan 18 12:29:58 pfs php: : Could not determine VPN endpoint for 'WAN IPv4 IPsec Mobile Phase1 '
Jan 18 12:30:03 pfs php: : Could not determine VPN endpoint for 'WAN IPv4 IPsec Mobile Phase1 '
Jan 18 12:30:03 pfs filterdns: Received signal SIGHUP(1).
Jan 18 12:30:03 pfs kernel: pid 61925 (filterdns), uid 0: exited on signal 11 (core dumped)

This is probably not causing any real problems on my system because my remote vpn endpoint dns doesn't change or if it's related to the mobile ipsec phase1 not having an endpoint I am not sure how that would affect me, but I have noticed the core dump syslog messages and I have read that there can be up to three running filterdns processes (filter, vpn, captiveportal).

Hope this helps…

eri-- · Jan 19, 2013, 3:21 PM

I think all this happens because a filter reload will clear the contents of the table with what the filter config sends in.
I changed filterdns again to force update of addresses on table when a SIGHUP happens.

Hopefully by monday snapshot the updated filterdns will be there.

phil.davis · Jan 20, 2013, 5:28 PM

2.1-BETA1 (i386)
built on Sat Jan 19 20:44:40 EST 2013
Looking good - Alix nanoBSD test system has been up 9 hours. The table that should translate 11 names to 11 IPs now has 14 IP address entries. (3 of the names have dynamically switched IP in this time.) filterdns is adding to the table and not removing old entries, but I don't really care about that (feature or bug?)

bardelot · Jan 20, 2013, 6:28 PM

@phil.davis:

2.1-BETA1 (i386)
built on Sat Jan 19 20:44:40 EST 2013

There have been a few more changes after that date, you will have to try again tomorrow or so with a newer snapshot.

dhatz · Jan 20, 2013, 11:31 PM

I just upgraded to latest snapshot but still get filterdns problems:

FreeBSD fw.localdomain 8.3-RELEASE-p5 FreeBSD 8.3-RELEASE-p5 #1: Sat Jan 19 21:12:44 EST 2013 root@snapshots-8_3-i386.builders.pfsense.org:/usr/obj./usr/pfSensesrc/src/sys/pfSense_SMP.8 i386

MD5 (/usr/local/sbin/filterdns) = 6949816348947b7762586fe3c59b356e

…
Jan 21 00:05:28 fw kernel: pid 47308 (filterdns), uid 0: exited on signal 11 (core dumped)
Jan 21 00:05:29 fw check_reload_status: Restarting ipsec tunnels
Jan 21 00:05:30 fw login: login on ttyv0 as root
Jan 21 00:05:36 fw php: : IPSEC: One or more IPsec tunnel endpoints has changed its IP. Refreshing.
Jan 21 00:05:37 fw check_reload_status: Updating all dyndns
Jan 21 00:05:37 fw check_reload_status: Restarting OpenVPN tunnels/interfaces
Jan 21 00:05:38 fw check_reload_status: Reloading filter
Jan 21 00:05:40 fw kernel: pid 83611 (filterdns), uid 0: exited on signal 11 (core dumped)

eri-- · Jan 21, 2013, 8:35 AM

dhatz that happens probably because of upgrade is not replacing the filterdns process.
Can you kill all you filterdns processes before running an upgrade and try again or
extract the archive of the upgrade and install manually the filterdns binary, it is located on usr/local/sbin iirc.

I am tracking even this issue of upgrade not replacing binaries at some time.

dhatz · Jan 21, 2013, 2:02 PM

Indeed it seems that the filterdns binary is not replaced by the upgrade process.

I will upgrade as soon as a new 2.1 snapshot image becomes available (currently the latest snapshot is from 19-Jan) and let you know how it goes.

phil.davis · Jan 23, 2013, 2:50 AM

nanobsd upgrade to 2.1-BETA1 (i386) built on Tue Jan 22 05:52:55 EST 2013 gets the version feature (1.1), but that is kind of obvious since nanoBSD is provided with a full slice. We will see what dhatz gets with a upgrade of a full install.
filterdns working well for me - but it does accumulate all the IP addresses known to it over time for the list of names. My table now has 15 IPs for 11 names.

dhatz · Jan 26, 2013, 11:28 PM

@ermal:

dhatz that happens probably because of upgrade is not replacing the filterdns process.
Can you kill all you filterdns processes before running an upgrade and try again or
I am tracking even this issue of upgrade not replacing binaries at some time.

Just a quick reminder that doing an upgrade still won't replace the old filterdns binary.

Btw I have tried killing all filterdns processes before running an upgrade (and verified they had been killed just before starting the upgrade procedure).

eri-- · Jan 27, 2013, 3:49 PM

Is the issue fixed for you dhatz?

dhatz · Jan 27, 2013, 9:03 PM

Ermal, I upgraded the filterdns binary to
MD5 (/usr/local/sbin/filterdns) = af355106eef6aff00d9e6653cca696eb

However it seems that the new filterdns needs too much memory at system startup, causing errors like:

swap_pager_getswapspace(16): failed
swap_pager_getswapspace(12): failed
swap_pager_getswapspace(6): failed
swap_pager_getswapspace(16): failed
swap_pager_getswapspace(12): failed
swap_pager_getswapspace(9): failed

and it dies shortly after…

I've been running the latest pfsense-2.1 snap in a 256MB VM for the past ~10 months and never had this type of problem before.

eri-- · Jan 27, 2013, 10:37 PM

Do you have a long list of aliases in the one where you have the hostname?

AhnHEL · Jan 27, 2013, 10:47 PM

@dhatz:

However it seems that the new filterdns needs too much memory at system startup, causing errors like:

swap_pager_getswapspace(16): failed
swap_pager_getswapspace(12): failed
swap_pager_getswapspace(6): failed
swap_pager_getswapspace(16): failed
swap_pager_getswapspace(12): failed
swap_pager_getswapspace(9): failed

and it dies shortly after…

I'm seeing this too on my Atom box but not on my Whitebox. Same snap from yesterday and both amd64. Filterdns eats up all my memory and then uses up all the swap space before it dies.

dhatz · Jan 27, 2013, 10:43 PM

@ermal:

Do you have a long list of aliases in the one where you have the hostname?

I have

two (2) aliases in fw -> aliases
www_google_com
www_paypal_com
(note: this was just for testing)
one (1) hostname in IPsec
no "allowed hostnames" in CP

In the past (until ~2 months ago) these settings resulted into two filterdns processes: one for fw-aliases and one for ipsec, none for CP.

jimp · Jan 28, 2013, 2:23 AM

It's chewing through 100% cpu and all my RAM until it runs out of swap space for me, and I only have three aliases that contain hostnames.

truss -p on the filterdns proc shows it trying doing mmap over and over again.


mmap(0x0,1048576,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON,-1,0x0) = -1953497088 (0x8b900000)
mmap(0x0,1048576,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON,-1,0x0) = -1952448512 (0x8ba00000)
mmap(0x0,1048576,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON,-1,0x0) = -1951399936 (0x8bb00000)
mmap(0x0,1048576,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON,-1,0x0) = -1950351360 (0x8bc00000)
mmap(0x0,1048576,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON,-1,0x0) = -1949302784 (0x8bd00000)

I have a few decent-sized aliases but nothing huge. The filterdns.conf file on this box was only three lines. The size of the aliases involved in the filterdns thread were 1, 63, and 3. So it shouldn't have been all that busy/large.

68313 root     124   20   545M   543M RUN      0:05 35.35% filterdns{github.com}
68313 root     124   20   545M   543M RUN      0:05 35.35% filterdns{filterdns}
68313 root     124   20   545M   543M RUN      0:05 35.25% filterdns{some.other.hostname.you.dont.need.to.see}
  262 root      76   20  3416K   736K kqread   1:14 12.35% check_reload_status
68313 root      76   20   545M   543M ucond    0:00 10.99% filterdns{signal-thread}

filterdns -v shows 1.1.

Size and sha256 match the one on the builder so it is the most current build. (tar is set to preserve old creation times, so of course the date doesn't update…)

-r-xr-xr-x  1 root  wheel  24160 Nov 19 05:07 /usr/local/sbin/filterdns
SHA256 (/usr/local/sbin/filterdns) = 193ebd8250147041b79385d84efe0f5d09f9ce868ba666b18f91b5098ecce1f3

It was being run with the following parameters:

/usr/local/sbin/filterdns -p /var/run/filterdns.pid -i 300 -c /var/etc/filterdns.conf -d 1

phil.davis · Jan 28, 2013, 2:56 AM

@ermal - when you sort this out, and each time filterdns is updated, can you bump the version number in filterdns.c - that will make it very easy for us all to quickly see which version we have.

eri-- · Jan 28, 2013, 8:32 AM

Should be better on the later snapshots.
Sorry for the noise.

jimp · Jan 28, 2013, 12:23 PM

Seems a bit better so far, copied a binary off the builder to my box and it isn't constantly using that much cpu now, though it did still spike up and use 100% total for about 20-30 sec it did eventually slow down and fall off the first screen of top output.

dhatz · Jan 28, 2013, 4:47 PM

Latest snap v1.2 seems better (no more out-of-swap issues) but is still exits and dumps core:

Jan 28 06:34:45 fw kernel: pid 18434 (filterdns), uid 0: exited on signal 11 (core dumped)
Jan 28 06:34:53 fw kernel: pid 26566 (filterdns), uid 0: exited on signal 11 (core dumped)
Jan 28 06:35:23 fw kernel: pid 21538 (filterdns), uid 0, was killed: out of swap space
Jan 28 08:25:37 fw kernel: pid 49708 (filterdns), uid 0: exited on signal 11 (core dumped)
Jan 28 08:25:50 fw kernel: pid 71990 (filterdns), uid 0: exited on signal 11 (core dumped)
Jan 28 08:25:52 fw kernel: pid 81465 (filterdns), uid 0: exited on signal 11 (core dumped)
Jan 28 18:26:29 fw kernel: pid 10297 (filterdns), uid 0: exited on signal 11 (core dumped) <– updated to latest snap

MD5 (/usr/local/sbin/filterdns) = aea0850239de6ab9817f9330f1807cec
SHA256 (/usr/local/sbin/filterdns) = f2c43ff8e8d6f21047c351e071a203df48bc2899ca7f1564a9cd1998e690081d

On my system there is currently only one filterdns process, whereas there should be a second one handling ipsec hostname(s) – at least that was the case until ~2 months ago.

Edit: There are only two filterdns-related files on my system:

/var/etc/filterdns.conf
pf www.google.com www_google_com
pf www.paypal.com www_paypal_com

and

/var/etc/ipsec/filterdns-ipsec.hosts
cmd vpn.example.com '/usr/local/sbin/pfSctl -c "service reload ipsecdns"'
(whereas vpn.example.com is the name used in P1 remote gw)

Finally /var/run/filterdns-ipsec.pid shows 10297 and timestamp 18:26 which is the process that had crashed earlier (see syslog extract copied above)