2.0-RC1 miniupnpd weirdness

spock521

Hi!

First of all congratulations to RC1! And many thanks for this awesome piece of software :)

This morning I upgraded two systems to RC1 (from mirrors) and it went flawlessly, except this one thing with miniupnpd which I'm looking for some insight on. To begin with, one of the systems do not produce this problem, but the other one does. The working system is an Alix 2c3, and the one with miniupnpd problem is an older Soekris net4801.

The problem is that miniupnpd service is not started at boot, and if I click the "start/play" button, I end up on the "Status: Services page", and it says "miniupnpd has been started." But it has not, it's still red and not running. I can make it run properly by going to "Services: UPnP & NAT-PMP", disabling the service, pressing change, then enabling the service, and pressing change again. Simply pressing change immediately will not work, it has to be unticked, saved, reticked and saved again.

But then at the next reboot, the same problem will be back. Since it's a very remote system I can't do a factory reset to check if it fixes things. The net4801 has only 128mb of memory so I was thinking that maybe it ran out of memory during bootup or something like that, but it states only 49% memory used, and I see no signs of out of memory problems.

This problem might have been around longer then just RC1 (I never checked the services status page earlier), the previous snapshot it was running was from mid-to-end of january 2011 (which was also used for the initial installation and configuration).

I have attached the configuration file in case it might be of assistance here.

Any thoughts and/or suggestions on this? :)

config.xml.txt

cmb

anything relevant in the system log?

spock521

@cmb:

anything relevant in the system log?

This is the system log after bootup:

Mar 1 07:33:10	php: : Resyncing OpenVPN instances for interface WAN.
Mar 1 07:33:08	php: : phpDynDNS: No change in my IP address and/or 25 days has not passed. Not updating dynamic DNS entry.
Mar 1 07:33:08	php: : DynDns: Cached IP: xx.xx.xx.xx
Mar 1 07:33:08	php: : DynDns: Current WAN IP: xx.xx.xx.xx
Mar 1 07:33:08	php: : DynDns debug information: xx.xx.xx.xx extracted from local system.
Mar 1 07:33:08	php: : DynDns: _checkIP() starting.
Mar 1 07:33:08	php: : DynDns: _detectChange() starting.
Mar 1 07:33:07	php: : DynDns: updatedns() starting
Mar 1 07:33:07	php: : DynDns: Running updatedns()
Mar 1 07:33:03	php: : phpDynDNS: No change in my IP address and/or 25 days has not passed. Not updating dynamic DNS entry.
Mar 1 07:33:03	php: : DynDns: Cached IP: xx.xx.xx.xx
Mar 1 07:33:03	php: : DynDns: Current WAN IP: xx.xx.xx.xx
Mar 1 07:33:03	php: : DynDns debug information: xx.xx.xx.xx extracted from local system.
Mar 1 07:33:03	php: : DynDns: _checkIP() starting.
Mar 1 07:33:03	php: : DynDns: _detectChange() starting.
Mar 1 07:33:03	php: : DynDns: updatedns() starting
Mar 1 07:33:03	php: : DynDns: Running updatedns()
Mar 1 07:33:02	apinger: Starting Alarm Pinger, apinger(47271)
Mar 1 07:33:01	check_reload_status: reloading filter
Mar 1 07:33:00	apinger: Exiting on signal 15.
Mar 1 07:33:00	php: : ROUTING: change default route to xx.xx.xx.xx
Mar 1 07:32:48	login: login on console as root
Mar 1 07:32:44	php: : rc.newwanip: on (IP address: xx.xx.xx.xx) (interface: wan) (real interface: sis1).
Mar 1 07:32:42	php: : rc.newwanip: Informational is starting sis1.
Mar 1 07:32:33	php: : Hotplug event detected for lan but ignoring since interface is configured with static IP (xx.xx.xx.xx)
Mar 1 07:32:32	sshlockout[16824]: sshlockout/webConfigurator v3.0 starting up
Mar 1 07:32:32	php: /index.php: Successful webConfigurator login for user 'admin' from xx.xx.xx.xx
Mar 1 07:32:32	php: /index.php: Successful webConfigurator login for user 'admin' from xx.xx.xx.xx
Mar 1 07:32:32	php: : Hotplug event detected for opt1 but ignoring since interface is configured with static IP ()
Mar 1 07:32:31	php: : Resyncing configuration for all packages.
Mar 1 07:32:29	kernel: pid 2858 (php), uid 0, was killed: out of swap space
Mar 1 07:32:17	kernel: pid 252 (php), uid 0, was killed: out of swap space
Mar 1 07:32:00	check_reload_status: updating all dyndns
Mar 1 07:32:00	dnsmasq[51955]: read /etc/hosts - 3 addresses
Mar 1 07:32:00	dnsmasq[51955]: using nameserver xx.xx.xx.xx#53
Mar 1 07:32:00	dnsmasq[51955]: using nameserver xx.xx.xx.xx#53
Mar 1 07:32:00	dnsmasq[51955]: reading /etc/resolv.conf
Mar 1 07:32:00	dnsmasq[51955]: compile time options: IPv6 GNU-getopt no-DBus I18N DHCP TFTP
Mar 1 07:32:00	dnsmasq[51955]: started, version 2.55 cachesize 10000
Mar 1 07:32:00	dhcpleases: Could not deliver signal HUP to process because its pidfile does not exist, No such file or directory.
Mar 1 07:31:59	dhcpd: For info, please visit https://www.isc.org/software/dhcp/
Mar 1 07:31:59	dhcpd: All rights reserved.
Mar 1 07:31:59	dhcpd: Copyright 2004-2010 Internet Systems Consortium.
Mar 1 07:31:59	dhcpd: Internet Systems Consortium DHCP Server 4.1.1-P1
Mar 1 07:31:56	php: : ROUTING: change default route to xx.xx.xx.xx
Mar 1 07:31:42	apinger: Starting Alarm Pinger, apinger(36501)
Mar 1 07:31:36	kernel: pflog0: promiscuous mode enabled
Mar 1 07:31:36	kernel: Trying to mount root from ufs:/dev/ufs/pfsense0
Mar 1 07:31:36	kernel: uhub0: 3 ports with 3 removable, self powered
Mar 1 07:31:36	kernel: Root mount waiting for: usbus0

After just trying to press "start" on the miniupnpd service, there is nothing added to the log (and nothing happening either).

Actually this time I booted it worked to only go to the miniupnpd page and press "change" to get the service back up and running again, that has not worked on previous reboots. :o

And after getting miniupnpd up and running again only this is added (which is the normal output I believe):

Mar 1 07:36:00	miniupnpd[32999]: Listening for NAT-PMP traffic on port 5351
Mar 1 07:36:00	miniupnpd[32999]: Listening for NAT-PMP traffic on port 5351
Mar 1 07:36:00	miniupnpd[32999]: HTTP listening on port 2189
Mar 1 07:36:00	miniupnpd[32999]: HTTP listening on port 2189
Mar 1 07:36:00	php: miniupnpd: Starting service on interface: lan

edit: Just noticed the "out of swap space".. Guess it might be a memory problem after all then? But if so, why doesnt the "start" button work initially, and going to upnp page and pressing "change", does work?

wallabybob

@spock:

edit: Just noticed the "out of swap space".. Guess it might be a memory problem after all then? But if so, why doesnt the "start" button work initially, and going to upnp page and pressing "change", does work?

Possibly because there can be a heavy demand on memory and swap when a number of applications are starting up around the same time.

How much memory and swap space on each of the two systems?

spock521

@wallabybob:

Possibly because there can be a heavy demand on memory and swap when a number of applications are starting up around the same time.

How much memory and swap space on each of the two systems?

It's nanobsd on both, so no swap space. The alix has 256mb, and the net4801 has 128mb. Still I find it odd that only miniupnpd is affected here, since I tried to add more services like openvpn server, snmpd, pptp server and such and it has never shown any problems with only 128mb ram. Also the memory use after bootup is around 50% on the net4801.

cmb

I run a 4801 with 2.0 in a limited role and it sits around 50% RAM usage. I don't use miniupnpd though. Maybe run top and watch it while you start miniupnpd and see what happens. Apparently it's a pig, wouldn't think it would be though.

spock521

I tested some manual restarts of miniupnpd with top running and it starts and stays at 3.3MB. Couldn't see any peaks or anything weird. But I'm not so accustomed to debugging these things. :-\

Just a question, is it normal behaviour that when miniupnpd has failed to start at bootup, that the service "start" button doesn't work (ever). But going into the upnp setup page and pressing "change" works?

Anyway if there is something I can do to test this better please tell, otherwise I'll just let it be.

jimp

@spock:

Just a question, is it normal behaviour that when miniupnpd has failed to start at bootup, that the service "start" button doesn't work (ever). But going into the upnp setup page and pressing "change" works?

That may suggest that its configuration wasn't correct at the time, which should be in the logs. Editing the config and pressing save doesn't just restart the process, it rewrites the config first.

eri--

I pushed some fixes that you can get from next snapshot.