Long boots after 22.01 update on SG-3100 with pfBlockerng

lohphat

Still long delay during boot after applying patch:

Starting CRON... done.
 Starting package ntopng...done.
 Starting package Avahi...done.
 Starting package OpenVPN Client Export Utility...done.
 Starting package System Patches...done.
load: 1.20  cmd: php-cgi 62419 [nanslp] 7.64r 0.74u 0.12s 3% 32304k
load: 1.18  cmd: php-cgi 62419 [nanslp] 11.46r 0.74u 0.12s 2% 32304k
load: 1.18  cmd: php-cgi 62419 [nanslp] 14.91r 0.74u 0.12s 1% 32304k
load: 1.17  cmd: php-cgi 62419 [nanslp] 18.47r 0.74u 0.12s 0% 32304k
load: 1.15  cmd: php-cgi 62419 [nanslp] 22.77r 0.74u 0.12s 0% 32304k
load: 1.14  cmd: php-cgi 62419 [nanslp] 26.28r 0.74u 0.12s 0% 32304k
load: 1.14  cmd: php-cgi 62419 [nanslp] 29.63r 0.74u 0.12s 0% 32304k
load: 1.13  cmd: sh 99162 [wait] 36.16r 0.00u 0.06s 0% 2408k
load: 1.12  cmd: sh 99162 [wait] 38.75r 0.00u 0.06s 0% 2408k
load: 1.12  cmd: sh 99162 [wait] 41.85r 0.00u 0.06s 0% 2408k
load: 1.11  cmd: sh 99162 [wait] 44.27r 0.00u 0.06s 0% 2408k
load: 1.11  cmd: sh 99162 [wait] 46.87r 0.00u 0.06s 0% 2408k
load: 1.10  cmd: sh 99162 [wait] 49.87r 0.00u 0.06s 0% 2408k
load: 1.09  cmd: sh 99162 [wait] 53.35r 0.00u 0.06s 0% 2408k
load: 1.09  cmd: sh 99162 [wait] 56.46r 0.00u 0.06s 0% 2408k
load: 1.08  cmd: sh 99162 [wait] 59.37r 0.00u 0.06s 0% 2408k
load: 1.08  cmd: sh 99162 [wait] 62.32r 0.00u 0.06s 0% 2408k
load: 1.08  cmd: sleep 91323 [runnable] 0.00r 0.00u 0.00s 0% 1852k
load: 1.07  cmd: sh 99162 [wait] 68.90r 0.00u 0.13s 0% 2404k
load: 1.07  cmd: sleep 91323 [nanslp] 6.62r 0.00u 0.00s 0% 1912k
load: 1.07  cmd: sh 99162 [wait] 75.85r 0.00u 0.13s 0% 2404k
load: 1.06  cmd: sh 99162 [wait] 79.77r 0.00u 0.13s 0% 2404k
load: 1.06  cmd: sh 99162 [wait] 83.12r 0.00u 0.13s 0% 2404k
load: 1.06  cmd: sh 99162 [wait] 86.71r 0.00u 0.13s 0% 2404k
load: 1.05  cmd: sh 99162 [wait] 90.06r 0.00u 0.13s 0% 2404k
load: 1.05  cmd: sh 99162 [wait] 93.93r 0.00u 0.13s 0% 2404k
load: 1.04  cmd: sh 99162 [wait] 97.54r 0.00u 0.13s 0% 2404k
load: 1.04  cmd: sh 99162 [wait] 101.57r 0.00u 0.13s 0% 2404k
load: 1.04  cmd: sh 99162 [wait] 105.56r 0.00u 0.13s 0% 2404k
load: 1.04  cmd: sh 99162 [wait] 109.68r 0.00u 0.13s 0% 2404k
 Starting package pfBlockerNG-devel...done.
 Starting /usr/local/etc/rc.d/pfb_dnsbl.sh...done.
 Starting /usr/local/etc/rc.d/pfb_filter.sh...done.
Netgate pfSense Plus 22.01-RELEASE arm Mon Feb 07 16:39:01 UTC 2022
Bootup complete

stephenw10

Does it do the same if you restart the service? Or running forced update or reload in pfBlocker?

lohphat

@stephenw10 The boot would delay even if the package was disabled.

I've run the reload and is completes in 10-15 seconds.

stephenw10

If the aliases are present it may still be populating them even when disabled. Do you have a load of things selected in pfBlocker? It could be having to time-out on some if they are not responding.

Steve

lohphat

@stephenw10 I can reload sources in 10-15 seconds when it's up and running.

Also, why wouldn't "Starting package pfBlockerNG-devel..." display while it is processing and then print "done.\n" when finished after the long delay? It's hanging for several minutes at boot then prints the entire line "Starting package pfBlockerNG-devel...done." all at once -- even if the package is disabled.

stephenw10

Well it depends how that script is run. What I suspect is that the actual service the pfBlocker installs starts pretty much instantly. The aliases are not a service though. It's probably trying to populate those before it tries to start 'pfBlockerNG DNSBL Web Server'.

Steve

lohphat

@stephenw10

FOUND IT!

It's related to "pfBlockerNG-devel: Version 3.1.0_2 - Fix for #12706" topic.

If /tmp and /var are set to use a ramdisk then the long boot delay appears. Disabling it results in no delay.

lohphat

This post is deleted!

lohphat

The 3.1.0_2 update did not fix the long boot delay.

The Ctrl-T process output at the hang point is similar.

lohphat

Note: there seems to be a v3.1.0_3 on its way...

lohphat

Just updated to 3.1.0_4 and the delay at boot is still happening if the ramdisk for /etc and /var are enabled.

cantor

@lohphat

For me 3.1.0_4 works. With ramdisk enabled rebooting of the system (22.01) takes about. 80 s.

lohphat

@cantor

To be clear, the WebConfigurator UI comes up fine but the boot isn't complete.

Here's more interesting data (BTW, using unbound in python mode and pfBlocker python extensions enabled):

Long boot even if 3.1.0_4 is installed but disabled.
Short boot when I remove the package entirely.
I noticed that when I reinstalled 3.1.0_4 (retaining old configs) that during the reinstall the message:
"Executing custom_php_resync_config_command()..."
was taking about the SAME TIME time as the boot delay.

So this time I removed the package and DID NOT save my prior config and reinstalled so I'd have a blank config.

The boot time was short.

AHA!

So it seems my old config was the culprit.

I am now rebuilding my config (I have a dual WAN and multiple internal network segments, e.g. IoT corralled on own SSID) so it will take some time.

I will report back if the long delay returns again.

lohphat

The issue of long boot seems to be related to Maxmind. Once I enter my license key and reload then any subsequent reboot is long.

lohphat

@lohphat

It's still happening even after the recommended 22.05 patch for unbound.

It happens only if:

maxmind key entered in MaxMind GeoIP configuration section AND
RAMdisk is enabled for /tmp and /var

As of 23aug2022:

Boot console output:

Starting CRON... done.
 Starting package ntopng...done.
 Starting package Avahi...done.
 Starting package OpenVPN Client Export Utility...done.
 Starting package System Patches...done.

(representative samples from System Activity since Webconfigurator has already started)
  PID USERNAME    PRI NICE   SIZE    RES STATE    C   TIME    WCPU COMMAND
18489 root        101    0    54M    37M CPU1     1   0:26  99.76% /usr/local/bin/php /usr/local/www/pfblockerng/pfblockerng.php dc{php}
18489 root         96    0    54M    37M CPU1     1   0:49  81.69% /usr/local/bin/php /usr/local/www/pfblockerng/pfblockerng.php dc{php}
18489 root        102    0    54M    37M CPU1     1   1:09 100.00% /usr/local/bin/php /usr/local/www/pfblockerng/pfblockerng.php dc{php}
18489 root        102    0    54M    37M CPU1     1   1:17 100.00% /usr/local/bin/php /usr/local/www/pfblockerng/pfblockerng.php dc{php}
18489 root        103    0    54M    37M CPU1     1   1:22 100.00% /usr/local/bin/php /usr/local/www/pfblockerng/pfblockerng.php dc{php}

1:50 delay at this point, otherwise it would only normally pause 3-5 seconds between "System Patches...done." and "...pfBLockerNG-devel...done."

 Starting package pfBlockerNG-devel...done.
 Starting package suricata...done.
 Starting /usr/local/etc/rc.d/pfb_dnsbl.sh...done.
 Starting /usr/local/etc/rc.d/pfb_filter.sh...done.
Netgate pfSense Plus 22.05-RELEASE arm Wed Jun 22 18:56:40 UTC 2022
Bootup complete

FreeBSD/arm (pfSense.localdomain) (ttyu0)