Long boots after 22.01 update on SG-3100 with pfBlockerng

lohphat · Feb 26, 2022, 9:21 PM

The webUI starts but the boot messages seems to hang for 3 minutes at the same place during CRON startup. It might be an issue with pfBLockerNG-devel startup not providing real-time feedback as that's where it "hangs".

...
Starting CRON... done.
Starting package ntopng...done.
Starting package Avahi...done.
Starting package OpenVPN Client Export Utility...done.
Starting package System Patches...done.    <----- this is the last line displayed then it hangs for 3 minutes. WebUI is available.
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 · Feb 26, 2022, 9:28 PM

Before or after '...done'?

Leading pfBlocker seems more likely to be taking time.

Try pressing ctl+t while it appears to hang. What process is it waiting for?

Steve

lohphat · Feb 26, 2022, 9:31 PM

@stephenw10 After the "...done." it completes the line, adds a new-line, then just stops, so it's not the System Patches task.

Three minutes later the pfBLockerNG-devel line prints.

lohphat · Feb 26, 2022, 9:37 PM

@stephenw10

Here you go. I hit Ctrl-T every few seconds:

Starting package System Patches...done.
load: 1.02  cmd: php-cgi 43649 [nanslp] 2.65r 0.70u 0.16s 8% 32292k
load: 0.94  cmd: php-cgi 43649 [nanslp] 7.25r 0.70u 0.16s 4% 32292k
load: 1.02  cmd: php-cgi 43649 [nanslp] 13.17r 0.70u 0.16s 1% 32292k
load: 1.10  cmd: php-cgi 43649 [nanslp] 18.86r 0.70u 0.16s 0% 32292k
load: 1.09  cmd: php-cgi 43649 [nanslp] 23.63r 0.70u 0.16s 0% 32292k
load: 1.16  cmd: php-cgi 43649 [nanslp] 28.35r 0.70u 0.16s 0% 32292k
load: 1.30  cmd: sh 80767 [wait] 37.26r 0.00u 0.06s 0% 2408k
load: 1.27  cmd: sh 80767 [wait] 42.27r 0.00u 0.06s 0% 2408k
load: 1.27  cmd: sh 80767 [wait] 45.99r 0.00u 0.06s 0% 2408k
load: 1.25  cmd: sh 80767 [wait] 50.14r 0.00u 0.06s 0% 2408k
load: 1.23  cmd: sh 80767 [wait] 54.99r 0.00u 0.06s 0% 2408k
load: 1.21  cmd: sh 80767 [wait] 59.80r 0.00u 0.06s 0% 2408k
load: 1.20  cmd: cut 78146 [piperd] 0.86r 0.00u 0.00s 0% 1936k
load: 1.18  cmd: sh 80767 [wait] 69.84r 0.00u 0.09s 0% 2404k
load: 1.17  cmd: sh 80767 [wait] 76.31r 0.00u 0.09s 0% 2404k
load: 1.15  cmd: sh 80767 [wait] 81.48r 0.00u 0.09s 0% 2404k
load: 1.13  cmd: sh 80767 [wait] 89.80r 0.00u 0.09s 0% 2404k
load: 1.12  cmd: sh 80767 [wait] 95.01r 0.00u 0.09s 0% 2404k
load: 1.10  cmd: sh 80767 [wait] 102.20r 0.00u 0.09s 0% 2404k
 Starting package pfBlockerNG-devel...done.

stephenw10 · Feb 27, 2022, 1:57 PM

Hmm, what patches are you loading?

Do you a very large number of pfBlocker lists/rules?

I expected to see it waiting on pfctl directly there which would have pointed to this: https://redmine.pfsense.org/issues/12827 But it doesn't look like you are hitting that.

Steve

lohphat · Feb 27, 2022, 4:53 PM

@stephenw10 No patches loaded. I should probably remove it as it was only installed for the old PHP bug.

I have what I'd consider basic pfB rules.

lohphat · Feb 27, 2022, 5:10 PM

@stephenw10 So I did the update to System Patches and disabled pfB-devel and still got the delay. (FYI, it didn't delay this way in the last firmware release.)

But the Ctrl-T list is a bit different with pfB-devel disabled:

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.55  cmd: fcgicli 91461 [sbwait] 30.31r 0.00u 0.00s 0% 2088k
load: 1.46  cmd: fcgicli 91461 [sbwait] 40.95r 0.00u 0.00s 0% 2088k
load: 1.39  cmd: fcgicli 91461 [sbwait] 49.12r 0.00u 0.00s 0% 2088k
load: 1.36  cmd: fcgicli 91461 [sbwait] 54.33r 0.00u 0.00s 0% 2088k
load: 1.41  cmd: sleep 89616 [nanslp] 0.53r 0.00u 0.00s 0% 1908k
load: 1.38  cmd: sleep 89616 [nanslp] 4.35r 0.00u 0.00s 0% 1912k
load: 1.35  cmd: fcgicli 91461 [sbwait] 71.00r 0.00u 0.00s 0% 2088k
load: 1.32  cmd: fcgicli 91461 [sbwait] 74.36r 0.00u 0.00s 0% 2088k
load: 1.37  cmd: fcgicli 91461 [sbwait] 79.15r 0.00u 0.00s 0% 2088k
load: 1.34  cmd: fcgicli 91461 [sbwait] 84.16r 0.00u 0.00s 0% 2088k
load: 1.34  cmd: fcgicli 91461 [sbwait] 88.01r 0.00u 0.00s 0% 2088k
load: 1.31  cmd: fcgicli 91461 [sbwait] 92.50r 0.00u 0.00s 0% 2088k
load: 1.29  cmd: fcgicli 91461 [sbwait] 97.60r 0.00u 0.00s 0% 2088k
load: 1.27  cmd: fcgicli 91461 [sbwait] 102.41r 0.00u 0.00s 0% 2088k
load: 1.24  cmd: fcgicli 91461 [sbwait] 106.22r 0.00u 0.00s 0% 2088k
 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

I will now try again with System Patches removed, then I'll try removing pfB-devel (keeping settings).

lohphat · Feb 27, 2022, 5:24 PM

@stephenw10 pfB-devel seems to be the culprit.

Disabling didn't have an effect but after I removed the package, the boot sped through the CRON startup section as expected.

However, with the package removed, the following lines appeared in the boot console even after several reboots.

Loading configuration......done.
sh: /usr/local/pkg/pfblockerng/pfblockerng.sh: not found
Updating configuration...done.

I'm reinstalling the package now to see if that clears the behavior.

lohphat · Feb 27, 2022, 5:29 PM

@stephenw10

Confirming that re-installing the current pfBlocker-devel causes the boot delay to return even if the package is disabled.

I'd be fine if this thread were moved to the appropriate module forum.

stephenw10 · Feb 28, 2022, 5:30 AM

You might try the patch for pfctl latency anyway. See if that makes any difference to the boot times.

lohphat · Feb 28, 2022, 5:30 AM

@stephenw10 Unfamiliar with that patch. Link?

Gertjan · Feb 28, 2022, 3:04 PM

@lohphat said in Long boots after 22.01 update on SG-3100 with pfBlockerng:

Link

Install the System_Patches, version 2.0_2.
Go to System > Patches
Probably this one :

( part of the " Recommended System Patches for Netgate pfSense software version 2.6.0 " list )

lohphat · Feb 28, 2022, 3:04 PM

@gertjan

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 · Mar 1, 2022, 4:28 AM

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

lohphat · Mar 1, 2022, 4:28 AM

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

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

stephenw10 · Mar 1, 2022, 2:30 PM

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 · Mar 1, 2022, 2:46 PM

@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 · Mar 1, 2022, 3:42 PM

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 · Mar 4, 2022, 5:32 PM

@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 · Mar 24, 2022, 10:02 PM

This post is deleted!