Startup hangs intermittently



  • This example is using a 2.1-DEVELOPMENT 2G nanobsd snapshot from 7 March on ALIX 2D13. But I also get similar things on my production 2.0.1 ALIX systems. In my environment (remote locations in Nepal) the power goes off unexpectedly quite often, and our UPS systems are not perfect! So we often just have our routers powered off without a software shutdown. For nanobsd, I don't think this should be an issue, since the real files and config used at boot are mounted RO anyway. All the /tmp and /var stuff gets created from scratch at boot time in RAM.

    Quite often, when we powerup, the front LEDs start doing their flashing after about 1 minute (i.e. after the inital BIOS and FreeBSD startup gets to the pfSense bit). But then the flashing goes on for a long time/more than 30 minutes/forever. I did have an example yesterday when there was a pause of 6 minutes between "Starting syslog…done." and "Configuring firewall..." During this time the LED flashing stopped. So sometimes something delays the startup, but then it gets going again and finishes.

    Yesterday I had this happen on a test system where I was watching the console. I never got the "Configuring firewall..." message - console output stopped after "Starting syslog...done.".

    This system (and all my systems) have pfBlocker, Squid and SquidGuard packages. As it happens, pfBlocker was installed but not enabled on this system.

    I could logon to the router with SSH and (re)start the webGUI. So I have captured some data:

    system.log

    
    Mar 13 11:03:07 davis21dev syslogd: kernel boot file is /boot/kernel/kernel
    Mar 13 11:03:07 davis21dev kernel: Copyright (c) 1992-2012 The FreeBSD Project.
    Mar 13 11:03:07 davis21dev kernel: Copyright (c) 1979, 1980, 1983, 1986, 1988, 1989, 1991, 1992, 1993, 1994
    Mar 13 11:03:07 davis21dev kernel: The Regents of the University of California. All rights reserved.
    Mar 13 11:03:07 davis21dev kernel: FreeBSD is a registered trademark of The FreeBSD Foundation.
    Mar 13 11:03:07 davis21dev kernel: FreeBSD 8.3-RC1 #3: Wed Mar  7 22:27:59 CET 2012
    Mar 13 11:03:07 davis21dev kernel: root@b83i386.dnsalias.org:/usr/obj.pfSense/usr/pfSensesrc/src/sys/pfSense_wrap.8.i386 i386
    Mar 13 11:03:07 davis21dev kernel: Timecounter "i8254" frequency 1193182 Hz quality 0
    Mar 13 11:03:07 davis21dev kernel: CPU: Geode(TM) Integrated Processor by AMD PCS (498.05-MHz 586-class CPU)
    Mar 13 11:03:07 davis21dev kernel: Origin = "AuthenticAMD"  Id = 0x5a2  Family = 5  Model = a  Stepping = 2
    Mar 13 11:03:07 davis21dev kernel: Features=0x88a93d <fpu,de,pse,tsc,msr,cx8,sep,pge,cmov,clflush,mmx>Mar 13 11:03:07 davis21dev kernel: AMD Features=0xc0400000 <mmx+,3dnow!+,3dnow!>Mar 13 11:03:07 davis21dev kernel: real memory  = 268435456 (256 MB)
    Mar 13 11:03:07 davis21dev kernel: avail memory = 239239168 (228 MB)
    Mar 13 11:03:07 davis21dev kernel: pnpbios: Bad PnP BIOS data checksum
    Mar 13 11:03:07 davis21dev kernel: netisr_init: forcing maxthreads to 1 and bindthreads to 0 for device polling
    Mar 13 11:03:07 davis21dev kernel: ipw_ibss: You need to read the LICENSE file in /usr/share/doc/legal/intel_ipw/.
    Mar 13 11:03:07 davis21dev kernel: ipw_ibss: If you agree with the license, set legal.intel_ipw.license_ack=1 in /boot/loader.conf.
    Mar 13 11:03:07 davis21dev kernel: module_register_init: MOD_LOAD (ipw_ibss_fw, 0xc0720ce0, 0) error 1
    Mar 13 11:03:07 davis21dev kernel: ipw_monitor: You need to read the LICENSE file in /usr/share/doc/legal/intel_ipw/.
    Mar 13 11:03:07 davis21dev kernel: ipw_monitor: If you agree with the license, set legal.intel_ipw.license_ack=1 in /boot/loader.conf.
    Mar 13 11:03:07 davis21dev kernel: module_register_init: MOD_LOAD (ipw_monitor_fw, 0xc0720d80, 0) error 1
    Mar 13 11:03:07 davis21dev kernel: wlan: mac acl policy registered
    Mar 13 11:03:07 davis21dev kernel: ipw_bss: You need to read the LICENSE file in /usr/share/doc/legal/intel_ipw/.
    Mar 13 11:03:07 davis21dev kernel: ipw_bss: If you agree with the license, set legal.intel_ipw.license_ack=1 in /boot/loader.conf.
    Mar 13 11:03:07 davis21dev kernel: module_register_init: MOD_LOAD (ipw_bss_fw, 0xc0720c40, 0) error 1
    Mar 13 11:03:07 davis21dev kernel: K6-family MTRR support enabled (2 registers)
    Mar 13 11:03:07 davis21dev kernel: ACPI Error: A valid RSDP was not found (20101013/tbxfroot-309)
    Mar 13 11:03:07 davis21dev kernel: ACPI: Table initialisation failed: AE_NOT_FOUND
    Mar 13 11:03:07 davis21dev kernel: ACPI: Try disabling either ACPI or apic support.
    Mar 13 11:03:07 davis21dev kernel: cryptosoft0: <software crypto="">on motherboard
    Mar 13 11:03:07 davis21dev kernel: padlock0: No ACE support.
    Mar 13 11:03:07 davis21dev kernel: pcib0: <host to="" pci="" bridge="">pcibus 0 on motherboard
    Mar 13 11:03:07 davis21dev kernel: pci0: <pci bus="">on pcib0
    Mar 13 11:03:07 davis21dev kernel: Geode LX: PC Engines ALIX.2 v0.99h tinyBIOS V1.4a (C)1997-2007
    Mar 13 11:03:07 davis21dev kernel: pci0: <encrypt decrypt,="" entertainment="" crypto="">at device 1.2 (no driver attached)
    Mar 13 11:03:07 davis21dev kernel: vr0: <via 10="" vt6105m="" rhine="" iii="" 100basetx="">port 0x1000-0x10ff mem 0xe0000000-0xe00000ff irq 10 at device 9.0 on pci0
    Mar 13 11:03:07 davis21dev kernel: vr0: Quirks: 0x2
    Mar 13 11:03:07 davis21dev kernel: vr0: Revision: 0x96
    Mar 13 11:03:07 davis21dev kernel: miibus0: <mii bus="">on vr0
    Mar 13 11:03:07 davis21dev kernel: ukphy0: <generic ieee="" 802.3u="" media="" interface="">PHY 1 on miibus0
    Mar 13 11:03:07 davis21dev kernel: ukphy0:  none, 10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, auto, auto-flow
    Mar 13 11:03:07 davis21dev kernel: vr0: [ITHREAD]
    Mar 13 11:03:07 davis21dev kernel: vr1: <via 10="" vt6105m="" rhine="" iii="" 100basetx="">port 0x1400-0x14ff mem 0xe0040000-0xe00400ff irq 11 at device 10.0 on pci0
    Mar 13 11:03:07 davis21dev kernel: vr1: Quirks: 0x2
    Mar 13 11:03:07 davis21dev kernel: vr1: Revision: 0x96
    Mar 13 11:03:07 davis21dev kernel: miibus1: <mii bus="">on vr1
    Mar 13 11:03:07 davis21dev kernel: ukphy1: <generic ieee="" 802.3u="" media="" interface="">PHY 1 on miibus1
    Mar 13 11:03:07 davis21dev kernel: ukphy1:  none, 10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, auto, auto-flow
    Mar 13 11:03:07 davis21dev kernel: vr1: [ITHREAD]
    Mar 13 11:03:07 davis21dev kernel: vr2: <via 10="" vt6105m="" rhine="" iii="" 100basetx="">port 0x1800-0x18ff mem 0xe0080000-0xe00800ff irq 15 at device 11.0 on pci0
    Mar 13 11:03:07 davis21dev kernel: vr2: Quirks: 0x2
    Mar 13 11:03:07 davis21dev kernel: vr2: Revision: 0x96
    Mar 13 11:03:07 davis21dev kernel: miibus2: <mii bus="">on vr2
    Mar 13 11:03:07 davis21dev kernel: ukphy2: <generic ieee="" 802.3u="" media="" interface="">PHY 1 on miibus2
    Mar 13 11:03:07 davis21dev kernel: ukphy2:  none, 10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, auto, auto-flow
    Mar 13 11:03:07 davis21dev kernel: vr2: [ITHREAD]
    Mar 13 11:03:07 davis21dev kernel: isab0: <pci-isa bridge="">port 0x6000-0x6007,0x6100-0x61ff,0x6200-0x623f,0x9d00-0x9d7f,0x9c00-0x9c3f at device 15.0 on pci0
    Mar 13 11:03:07 davis21dev kernel: isa0: <isa bus="">on isab0
    Mar 13 11:03:07 davis21dev kernel: atapci0: <amd cs5536="" udma100="" controller="">port 0x1f0-0x1f7,0x3f6,0x170-0x177,0x376,0xff00-0xff0f at device 15.2 on pci0
    Mar 13 11:03:07 davis21dev kernel: ata0: <ata channel="">at channel 0 on atapci0
    Mar 13 11:03:07 davis21dev kernel: ata0: [ITHREAD]
    Mar 13 11:03:07 davis21dev kernel: ata1: <ata channel="">at channel 1 on atapci0
    Mar 13 11:03:07 davis21dev kernel: ata1: [ITHREAD]
    Mar 13 11:03:07 davis21dev kernel: ohci0: <ohci (generic)="" usb="" controller="">mem 0xefffe000-0xefffefff irq 12 at device 15.4 on pci0
    Mar 13 11:03:07 davis21dev kernel: ohci0: [ITHREAD]
    Mar 13 11:03:07 davis21dev kernel: usbus0: <ohci (generic)="" usb="" controller="">on ohci0
    Mar 13 11:03:07 davis21dev kernel: ehci0: <amd cs5536="" (geode)="" usb="" 2.0="" controller="">mem 0xefffd000-0xefffdfff irq 12 at device 15.5 on pci0
    Mar 13 11:03:07 davis21dev kernel: ehci0: [ITHREAD]
    Mar 13 11:03:07 davis21dev kernel: usbus1: EHCI version 1.0
    Mar 13 11:03:07 davis21dev kernel: usbus1: <amd cs5536="" (geode)="" usb="" 2.0="" controller="">on ehci0
    Mar 13 11:03:07 davis21dev kernel: cpu0 on motherboard
    Mar 13 11:03:07 davis21dev kernel: orm0: <isa option="" rom="">at iomem 0xe0000-0xea7ff pnpid ORM0000 on isa0
    Mar 13 11:03:07 davis21dev kernel: atrtc0: <at real="" time="" clock="">at port 0x70 irq 8 on isa0
    Mar 13 11:03:07 davis21dev kernel: ppc0: parallel port not found.
    Mar 13 11:03:07 davis21dev kernel: uart0: <16550 or compatible> at port 0x3f8-0x3ff irq 4 flags 0x10 on isa0
    Mar 13 11:03:07 davis21dev kernel: uart0: [FILTER]
    Mar 13 11:03:07 davis21dev kernel: uart0: console (9600,n,8,1)
    Mar 13 11:03:07 davis21dev kernel: uart1: <16550 or compatible> at port 0x2f8-0x2ff irq 3 on isa0
    Mar 13 11:03:07 davis21dev kernel: uart1: [FILTER]
    Mar 13 11:03:07 davis21dev kernel: Timecounter "TSC" frequency 498052802 Hz quality 800
    Mar 13 11:03:07 davis21dev kernel: Timecounters tick every 10.000 msec
    Mar 13 11:03:07 davis21dev kernel: IPsec: Initialized Security Association Processing.
    Mar 13 11:03:07 davis21dev kernel: usbus0: 12Mbps Full Speed USB v1.0
    Mar 13 11:03:07 davis21dev kernel: usbus1: 480Mbps High Speed USB v2.0
    Mar 13 11:03:07 davis21dev kernel: ugen0.1: <amd>at usbus0
    Mar 13 11:03:07 davis21dev kernel: uhub0: <amd 1="" 9="" ohci="" root="" hub,="" class="" 0,="" rev="" 1.00="" 1.00,="" addr="">on usbus0
    Mar 13 11:03:07 davis21dev kernel: ugen1.1: <amd>at usbus1
    Mar 13 11:03:07 davis21dev kernel: uhub1: <amd 1="" 9="" ehci="" root="" hub,="" class="" 0,="" rev="" 2.00="" 1.00,="" addr="">on usbus1
    Mar 13 11:03:07 davis21dev kernel: ad0: 1907MB <sandisk sdcfh-002g="" hdx="" 6.02="">at ata0-master PIO4 
    Mar 13 11:03:07 davis21dev kernel: Root mount waiting for: usbus1 usbus0
    Mar 13 11:03:07 davis21dev kernel: uhub0: 4 ports with 4 removable, self powered
    Mar 13 11:03:07 davis21dev kernel: Root mount waiting for: usbus1
    Mar 13 11:03:07 davis21dev kernel: uhub1: 4 ports with 4 removable, self powered
    Mar 13 11:03:07 davis21dev kernel: Trying to mount root from ufs:/dev/ufs/pfsense0
    Mar 13 11:03:07 davis21dev kernel: WARNING: / was not properly dismounted
    Mar 13 11:03:07 davis21dev kernel: ad0: FAILURE - SETFEATURES 0x85 status=51 <ready,dsc,error>error=4 <aborted>Mar 13 11:03:09 davis21dev check_reload_status: Linkup starting vr0
    Mar 13 11:03:09 davis21dev kernel: vr0: link state changed to UP
    Mar 13 11:03:13 davis21dev check_reload_status: Syncing firewall
    Mar 13 11:03:15 davis21dev apinger: Error while feeding rrdtool: Broken pipe
    Mar 13 11:03:15 davis21dev php: : Starting Squid
    Mar 13 11:03:15 davis21dev squid[43129]: Squid Parent: child process 43652 started
    Mar 13 11:03:16 davis21dev check_reload_status: Reloading filter
    Mar 13 11:03:17 davis21dev check_reload_status: Syncing firewall
    Mar 13 11:03:18 davis21dev squid[43652]: The url_rewriter helpers are crashing too rapidly, need help!
    Mar 13 11:03:18 davis21dev squid[43129]: Squid Parent: child process 43652 exited due to signal 6
    Mar 13 11:03:18 davis21dev kernel: pid 43652 (squid), uid 62: exited on signal 6
    Mar 13 11:03:21 davis21dev squid[43129]: Squid Parent: child process 48603 started
    Mar 13 11:04:15 davis21dev apinger: /usr/local/bin/rrdtool respawning too fast, waiting 300s.
    Mar 13 11:10:35 davis21dev sshd[24315]: Accepted keyboard-interactive/pam for admin from 192.168.2.2 port 49567 ssh2
    Mar 13 11:10:35 davis21dev sshlockout[32722]: sshlockout/webConfigurator v3.0 starting up
    Mar 13 12:02:08 davis21dev dhclient: RENEW
    Mar 13 12:02:08 davis21dev dhclient: Creating resolv.conf
    Mar 13 12:22:28 davis21dev sshd[49679]: Accepted keyboard-interactive/pam for admin from 192.168.2.2 port 49574 ssh2
    Mar 13 12:54:38 davis21dev sshd[24315]: Timeout, client not responding.
    Mar 13 13:02:09 davis21dev dhclient: RENEW
    Mar 13 13:02:09 davis21dev dhclient: Creating resolv.conf
    Mar 13 14:02:09 davis21dev dhclient: RENEW
    Mar 13 14:02:09 davis21dev dhclient: Creating resolv.conf
    Mar 13 14:32:09 davis21dev php: : Creating rrd update script
    Mar 13 14:32:18 davis21dev apinger: Error while feeding rrdtool: Broken pipe
    Mar 13 14:32:23 davis21dev php: /index.php: Successful login for user 'admin' from: 192.168.2.2
    Mar 13 14:32:23 davis21dev php: /index.php: Successful login for user 'admin' from: 192.168.2.2
    Mar 13 15:02:14 davis21dev dhclient: RENEW
    Mar 13 15:02:14 davis21dev dhclient: Creating resolv.conf</aborted></ready,dsc,error></sandisk></amd></amd></amd></amd></at></isa></amd></amd></ohci></ohci></ata></ata></amd></isa></pci-isa></generic></mii></via></generic></mii></via></generic></mii></via></encrypt></pci></host></software></mmx+,3dnow!+,3dnow!></fpu,de,pse,tsc,msr,cx8,sep,pge,cmov,clflush,mmx> 
    

    ps ax output

    
      PID  TT  STAT      TIME COMMAND
        0  ??  DLs    0:00.05 [kernel]
        1  ??  ILs    0:00.19 /sbin/init --
        2  ??  DL     0:00.06 [g_event]
        3  ??  DL     0:06.05 [g_up]
        4  ??  DL     0:08.91 [g_down]
        5  ??  DL     0:00.00 [crypto]
        6  ??  DL     0:00.00 [crypto returns]
        7  ??  DL     0:00.11 [pfpurge]
        8  ??  DL     0:00.00 [xpt_thrd]
        9  ??  DL     0:01.11 [pagedaemon]
       10  ??  RL   224:04.16 [idle]
       11  ??  WL     9:29.00 [intr]
       12  ??  DL     0:00.00 [ng_queue]
       13  ??  DL     0:19.96 [yarrow]
       14  ??  DL     0:00.38 [usb]
       15  ??  DL     0:00.00 [vmdaemon]
       16  ??  DL     0:00.03 [idlepoll]
       17  ??  DL     0:00.00 [pagezero]
       18  ??  DL     0:00.11 [bufdaemon]
       19  ??  DL     0:00.65 [vnlru]
       20  ??  DL     0:03.78 [syncer]
       21  ??  DL     0:00.10 [softdepflush]
       29  ??  DL     0:00.50 [md0]
       35  ??  DL     0:01.25 [md1]
      268  ??  INs    0:00.02 /usr/local/sbin/check_reload_status
      270  ??  IN     0:00.00 check_reload_status: Monitoring daemon of check_reloa
      288  ??  Is     0:00.01 /sbin/devd
     8161  ??  Is     0:00.01 /usr/sbin/sshd
     8699  ??  Is     0:00.02 dhclient: vr1 [priv] (dhclient)
    10337  ??  SN     0:00.00 sleep 55
    14613  ??  Is     0:00.02 dhclient: vr1 (dhclient)
    17350  ??  IN     0:01.05 /usr/local/bin/php -f /etc/rc.filter_configure_sync
    17952  ??  SNs    0:04.44 /usr/local/sbin/apinger -c /var/etc/apinger.conf
    27465  ??  S      0:00.62 /usr/local/sbin/lighttpd -f /var/etc/lighty-webConfig
    27746  ??  Is     0:00.28 /usr/local/bin/php
    28394  ??  Is     0:00.28 /usr/local/bin/php
    30007  ??  I      0:01.09 /usr/local/bin/php
    30351  ??  I      0:00.00 /usr/local/bin/php
    30664  ??  I      0:01.86 /usr/local/bin/php
    31001  ??  I      0:01.10 /usr/local/bin/php
    32722  ??  Is     0:00.02 /usr/local/sbin/sshlockout_pf 15
    33598  ??  IN     0:01.05 /usr/local/bin/php -f /etc/rc.filter_configure_sync
    34240  ??  SN     0:00.32 /usr/sbin/tcpdump -s 256 -v -l -n -e -ttt -i pflog0
    34399  ??  IN     0:00.00 logger -t pf -p local0.info
    38888  ??  Is     0:00.10 /usr/sbin/syslogd -c -c -l /var/dhcpd/var/run/log -f 
    43049  ??  INs    0:00.01 ntpd: [priv] (ntpd)
    43105  ??  SN     0:00.29 ntpd: ntp engine (ntpd)
    43129  ??  INs    0:00.00 /usr/pbi/squid-i386/sbin/squid -D -f /usr/local/etc/s
    43452  ??  IN     0:00.00 ntpd: dns engine (ntpd)
    47869  ??  SN     0:00.70 /bin/sh /usr/local/etc/rc.d/proxy_monitor.sh start
    48203  ??  IN     0:01.05 /usr/local/bin/php -f /etc/rc.filter_configure_sync
    48603  ??  SN     0:00.84 (squid) -D -f /usr/local/etc/squid/squid.conf (squid)
    48694  ??  IN     0:00.01 /bin/sh /usr/local/bin/squidGuard -c /usr/local/etc/s
    48898  ??  IN     0:00.01 /bin/sh /usr/local/bin/squidGuard -c /usr/local/etc/s
    49135  ??  IN     0:00.01 /bin/sh /usr/local/bin/squidGuard -c /usr/local/etc/s
    49519  ??  IN     0:00.00 (unlinkd) (unlinkd)
    49679  ??  Ss     0:03.41 sshd: admin@pts/1 (sshd)
    49805  ??  IN     0:00.01 /usr/pbi/squidguard-i386/bin/squidGuard -c /usr/local
    50193  ??  IN     0:00.01 /usr/pbi/squidguard-i386/bin/squidGuard -c /usr/local
    50201  ??  IN     0:00.01 /usr/pbi/squidguard-i386/bin/squidGuard -c /usr/local
    50256  ??  IN     0:00.04 /usr/local/bin/rrdtool -
    54334  ??  IN     0:01.07 /usr/local/bin/php -f /etc/rc.filter_configure_sync
    60322  ??  IN     0:01.05 /usr/local/bin/php -f /etc/rc.filter_configure_sync
    62444  ??  Is     0:00.06 /usr/local/sbin/dhcp6c -d -c /var/etc/dhcp6c_wan.conf
       22  u0  Is+    0:00.07 sh /etc/rc autoboot
      273  u0  I+     0:03.62 /usr/local/bin/php -f /etc/rc.bootup
     7674   1  SN     0:00.00 sleep 60
    10503   1  R+     0:00.01 ps ax
    17270   1  Is     0:00.03 /bin/sh /etc/rc.initial
    29368   1  SN     0:00.69 /bin/sh /var/db/rrd/updaterrd.sh
    52567   1  S      0:00.20 /bin/tcsh
    
    

    rc processes with their elapsed times:

    
        03:54:58 17350 /usr/local/bin/php -f /etc/rc.filter_configure_sync
        03:54:51 33598 /usr/local/bin/php -f /etc/rc.filter_configure_sync
        03:54:35 47869 /bin/sh /usr/local/etc/rc.d/proxy_monitor.sh start
        03:54:34 48203 /usr/local/bin/php -f /etc/rc.filter_configure_sync
        03:55:11 54334 /usr/local/bin/php -f /etc/rc.filter_configure_sync
        03:55:05 60322 /usr/local/bin/php -f /etc/rc.filter_configure_sync
        03:56:23    22 sh /etc/rc autoboot
        03:56:03   273 /usr/local/bin/php -f /etc/rc.bootup
        02:35:27 17270 /bin/sh /etc/rc.initial
    
    

    Both /tmp/config.lock and /tmp/filter.lock existed. By running other scripts that needed these locks, I could determine that the config lock was available, but that something was holding the filter lock. You will notice that after autoboot and rc.bootup, 5 copies of rc.filter_configure_sync started not too far apart in time. Presumably one of these processes was hung up for some reason and held the filter lock. Then other things were queued up behind it.

    I also noticed that there are Squid and SquidGuard processes out of /usr/pbi… and /usr/local... - that must be a "feature" of 2.1-DEV that I will also need to look into!

    I will try to reproduce this, and see if it can happen after a clean shutdown, or if it only happens after a power-off and fsck on startup.

    Does anyone else experience startup hangs/delays?
    If so, what are you running - nanobsd/embedded hardware or other? 2.0.n or 2.1-DEV or both? what mix of packages? any other interesting environment?


Log in to reply