LEDs keep blinking on Alix

mdima · Apr 14, 2013, 8:36 AM

Hello,
I don't know which snapshot it started from, but on my home pfSense, which is running on an Alix, the LEDs keep blinking "knight rider" style during all the system activity, once they were blinking like that only during the boot.
I also tried to turn it off and on again, the problem persists. Ok, that's not a problem itself for my definition of "problem", just it's different than before… ;)

Am I the only one experiencing this?

Thanks,
Michele

mdima · Apr 14, 2013, 10:13 AM

Here is the System Log just after an upgrade/reboot.

Apr 14 11:05:33	sshlockout[35571]: sshlockout/webConfigurator v3.0 starting up
Apr 14 11:05:33	login: login on console as root
Apr 14 11:05:28	php: : Restarting/Starting all packages.
Apr 14 11:05:27	syslogd: kernel boot file is /boot/kernel/kernel
Apr 14 11:05:27	syslogd: exiting on signal 15
Apr 14 11:05:26	check_reload_status: Syncing firewall
Apr 14 11:05:05	php: : Beginning package installation for iperf .
Apr 14 11:05:00	check_reload_status: Syncing firewall
Apr 14 11:04:12	php: : Beginning package installation for RRD Summary .
Apr 14 11:04:07	check_reload_status: Syncing firewall
Apr 14 11:03:29	miniupnpd[17476]: Listening for NAT-PMP traffic on port 5351
Apr 14 11:03:29	miniupnpd[17476]: HTTP listening on port 2189
Apr 14 11:03:29	php: : miniupnpd: Starting service on interface: opt3
Apr 14 11:03:29	php: : miniupnpd: Interface opt5 has no ip address, ignoring
Apr 14 11:03:29	php: : miniupnpd: Interface opt2 has no ip address, ignoring
Apr 14 11:03:29	php: : miniupnpd: Interface lan has no ip address, ignoring
Apr 14 11:03:29	php: : Creating rrd update script
Apr 14 11:03:16	check_reload_status: Restarting OpenVPN tunnels/interfaces
Apr 14 11:03:16	check_reload_status: Updating all dyndns
Apr 14 11:03:10	check_reload_status: Reloading filter
Apr 14 11:03:10	check_reload_status: Restarting OpenVPN tunnels/interfaces
Apr 14 11:03:10	check_reload_status: Restarting ipsec tunnels
Apr 14 11:03:10	check_reload_status: updating dyndns Gat_LAN
Apr 14 11:03:05	kernel: pid 87272 (php), uid 0, was killed: out of swap space
Apr 14 11:02:59	check_reload_status: Reloading filter
Apr 14 11:02:59	check_reload_status: Restarting OpenVPN tunnels/interfaces
Apr 14 11:02:59	check_reload_status: Updating all dyndns
Apr 14 11:02:58	php: : Restarting/Starting all packages.
Apr 14 11:02:55	check_reload_status: Restarting OpenVPN tunnels/interfaces
Apr 14 11:02:54	check_reload_status: Restarting ipsec tunnels
Apr 14 11:02:54	check_reload_status: updating dyndns Gat_LAN
Apr 14 11:02:47	check_reload_status: Reloading filter
Apr 14 11:02:47	check_reload_status: Starting packages
Apr 14 11:02:47	php: : pfSense package system has detected an ip change 0.0.0.0 -> xxxxxxxx ... Restarting packages.
Apr 14 11:02:45	php: : Creating rrd update script
Apr 14 11:02:42	php: : Resyncing OpenVPN instances for interface WAN.
Apr 14 11:02:39	php: : Forcefully reloading IPsec racoon daemon
Apr 14 11:02:33	check_reload_status: Reloading filter
Apr 14 11:02:33	check_reload_status: Restarting OpenVPN tunnels/interfaces
Apr 14 11:02:33	check_reload_status: Restarting ipsec tunnels
Apr 14 11:02:33	check_reload_status: updating dyndns Gat_LAN
Apr 14 11:02:33	php: : Removing static route for monitor 192.168.0.3 and adding a new route through 192.168.22.1
Apr 14 11:02:33	php: : ROUTING: setting default route to xxxxxxxx
Apr 14 11:02:26	check_reload_status: Updating all dyndns
Apr 14 11:02:26	dhcpleases: kqueue error: unkown
Apr 14 11:02:25	dhcpleases: Could not deliver signal HUP to process because its pidfile does not exist, No such file or directory.
Apr 14 11:02:24	php: : ROUTING: setting default route to xxxxxxxx
Apr 14 11:02:21	php: : Removing static route for monitor 192.168.0.3 and adding a new route through 192.168.22.1
Apr 14 11:02:19	kernel: pflog0: promiscuous mode enabled
Apr 14 11:02:19	dhcpleases: Could not deliver signal HUP to process because its pidfile does not exist, No such file or directory.
Apr 14 11:02:19	php: : Resyncing OpenVPN instances.
Apr 14 11:02:19	kernel: run0_wlan1: promiscuous mode enabled
Apr 14 11:02:19	kernel: vr0: promiscuous mode enabled
Apr 14 11:02:18	check_reload_status: Rewriting resolv.conf
Apr 14 11:02:17	kernel: vr0: link state changed to UP
Apr 14 11:02:17	check_reload_status: Linkup starting vr0
Apr 14 11:02:15	check_reload_status: Linkup starting vr2
Apr 14 11:02:15	kernel: vr2: link state changed to UP
Apr 14 11:02:14	sshd[12713]: Server listening on 0.0.0.0 port 22.
Apr 14 11:02:14	sshlockout[13040]: sshlockout/webConfigurator v3.0 starting up
Apr 14 11:02:14	sshd[12713]: Server listening on :: port 22.
Apr 14 11:02:14	kernel: vr0: link state changed to DOWN
Apr 14 11:02:14	check_reload_status: Linkup starting vr0
Apr 14 11:02:14	php: : Starting 3gstats.php on device '' for interface 'wan'
Apr 14 11:02:12	kernel: vr2: link state changed to DOWN
Apr 14 11:02:12	check_reload_status: Linkup starting vr2
Apr 14 11:02:12	kernel: wlan0: changing name to 'run0_wlan1'
Apr 14 11:02:11	php: : Cloning new wireless interface run0_wlan1
Apr 14 11:02:11	kernel: Trying to mount root from ufs:/dev/ad0s1a
Apr 14 11:02:11	kernel: run0: firmware RT2870 loaded
Apr 14 11:02:11	kernel: run0: MAC/BBP RT3070 (rev 0x0201), RF RT3020 (MIMO 1T1R), address 00:0c:43:a4:32:2c
Apr 14 11:02:11	kernel: run0: <1.0> on usbus1
Apr 14 11:02:11	kernel: ugen1.2: <ralink> at usbus1
Apr 14 11:02:11	kernel: Root mount waiting for: usbus1
Apr 14 11:02:11	kernel: uhub1: 4 ports with 4 removable, self powered
Apr 14 11:02:11	kernel: Root mount waiting for: usbus1
Apr 14 11:02:11	kernel: uhub0: 4 ports with 4 removable, self powered
Apr 14 11:02:11	kernel: Root mount waiting for: usbus1 usbus0
Apr 14 11:02:11	kernel: GEOM: ad0s1: geometry does not match label (255h,63s != 16h,63s).
Apr 14 11:02:11	kernel: ad0: 3823MB <ts4gcf150 20110407=""> at ata0-master UDMA100
Apr 14 11:02:11	kernel: uhub1: <amd 1="" 9="" ehci="" root="" hub,="" class="" 0,="" rev="" 2.00="" 1.00,="" addr=""> on usbus1
Apr 14 11:02:11	kernel: ugen1.1: <amd> at usbus1
Apr 14 11:02:11	kernel: uhub0: <amd 1="" 9="" ohci="" root="" hub,="" class="" 0,="" rev="" 1.00="" 1.00,="" addr=""> on usbus0
Apr 14 11:02:11	kernel: ugen0.1: <amd> at usbus0
Apr 14 11:02:11	kernel: usbus1: 480Mbps High Speed USB v2.0
Apr 14 11:02:11	kernel: usbus0: 12Mbps Full Speed USB v1.0
Apr 14 11:02:11	kernel: IPsec: Initialized Security Association Processing.
Apr 14 11:02:11	kernel: Timecounters tick every 10.000 msec
Apr 14 11:02:11	kernel: Timecounter "TSC" frequency 498052723 Hz quality 800
Apr 14 11:02:11	kernel: uart1: [FILTER]
Apr 14 11:02:11	kernel: uart1: <16550 or compatible> at port 0x2f8-0x2ff irq 3 on isa0
Apr 14 11:02:11	kernel: uart0: console (9600,n,8,1)
Apr 14 11:02:11	kernel: uart0: [FILTER]
Apr 14 11:02:11	kernel: uart0: <16550 or compatible> at port 0x3f8-0x3ff irq 4 flags 0x10 on isa0</amd></amd></amd></amd></ts4gcf150></ralink>

Thanks,
Michele

freebee · Apr 16, 2013, 3:50 PM

When this happens with me, is some startup script not well executed. In my Alix, using the terminal in serial mode, the login screen not appear.

jimp · Apr 16, 2013, 6:27 PM

We'd need to see the serial console output from the boot process to say for sure. It's getting hung up somewhere definitely. Probably a package.

darkcrucible · Apr 17, 2013, 7:16 PM

The serial bootup console should reveal what happened.

The Knight Rider lights show up for me only on occasion. Usually in the bootup console it's something like Starting RRD Graphs…Killed

If it says done instead of killed then I'll get a solid light. One work around I have found is to disable OpenVPN and then reboot. This greatly reduces the odds of getting the blinking lights. Then you can start OpenVPN after bootup.

Of course, if you're not running OpenVPN, then I'm not sure what you can do.

jimp · Apr 17, 2013, 9:32 PM

In those cases the ALIX is probably running out of RAM during the boot process.

mdima · Apr 17, 2013, 10:24 PM

it was iperf, the debug was quite easy because I only have two packages… :D

Now the LEDs don't blink anymore after the boot... ;)

Thanks for the suggestions!!

Michele

phil.davis · Apr 19, 2013, 4:41 PM

This line in the log is a giveaway:

Apr 14 11:03:05 kernel: pid 87272 (php), uid 0, was killed: out of swap space

The 256MB Alix systems are struggling with all the things that happen at boot time - I find particularly with multiple OpenVPN servers/clients - but particular/multiple packages will also be an issue as you have found. Once the system is up, it runs fine and for me shows memory 40-50% used. So it is not like the memory is really too little, it is a transient thing during the boot.
I am on leave away from my Alix systems at present, so can't play easily. But it would be good to look through the whole boot sequence and maybe see what could be done to "spread out" the startup of various stuff on low-memory systems.

mdima · Apr 22, 2013, 6:29 AM

mmhhh… I confirm, on an Alix, that every time I reboot the router the RRD data is totally empty... :(

I think that the Alix platform is good for a home environment (low power comsumption, totally noiseless), I hope this memory errors will be solved...

Thanks,
Michele

jimp · Apr 22, 2013, 8:29 PM

Are you rebooting cleanly using the menu, or just pulling the power out from the unit?

The RRD data is only saved during a clean shutdown, or if you have configured a periodic backup under System > Advanced on the Misc tab (2.1) or Diag > NanoBSD (2.0.x)

mdima · Apr 22, 2013, 10:01 PM

Hi Jim,
always clean… but your answer made me thought that I was enabling the RAM disk on my Alix... disabled the RAM disk, the problem is gone! ;)

Thanks,
Michele