Messages

Probably this is the link: https://github.com/opnsense/plugins/issues/4342#issuecomment-2466184969

The suggested patch:

Code Select Expand

opnsense-patch -c plugins 1e23572

I did find a post on the github project / issues that provides a patch for that and another one for nginx logs that show permission denied on write

It would be nice if you share the link to your findings as I cannot find any similar issue right now.

Hello,

I have freshly installed Nginx plugin.
However, any attempt to configure it (add new "Location", for example) leads to the same strange error:

Unexpected error, check log for details

No information in the logs, but System Firmware Reporter gave me several errors like this:

Code Select Expand

Error: Call to undefined method OPNsense\Base\Constraints\NgxBusyBufferConstraint::isEmpty() in /usr/local/opnsense/mvc/app/models/OPNsense/Base/Constraints/NgxBusyBufferConstraint.php:46
Stack trace:
#0 /usr/local/opnsense/mvc/app/models/OPNsense/Base/Validation.php(83): OPNsense\Base\Constraints\NgxBusyBufferConstraint->validate(Object(OPNsense\Base\Validation), 'location.661a48...')
#1 /usr/local/opnsense/mvc/app/models/OPNsense/Base/BaseModel.php(517): OPNsense\Base\Validation->validate(Array)
#2 /usr/local/opnsense/mvc/app/controllers/OPNsense/Base/ApiMutableModelControllerBase.php(260): OPNsense\Base\BaseModel->performValidation(false)
#3 /usr/local/opnsense/mvc/app/controllers/OPNsense/Base/ApiMutableModelControllerBase.php(466): OPNsense\Base\ApiMutableModelControllerBase->validate(Object(OPNsense\Base\FieldTypes\ContainerField), 'location')
#4 /usr/local/opnsense/mvc/app/controllers/OPNsense/Nginx/Api/SettingsController.php(192): OPNsense\Base\ApiMutableModelControllerBase->addBase('location', 'location')
#5 /usr/local/opnsense/mvc/app/library/OPNsense/Mvc/Dispatcher.php(165): OPNsense\Nginx\Api\SettingsController->addlocationAction()
#6 /usr/local/opnsense/mvc/app/library/OPNsense/Mvc/Router.php(156): OPNsense\Mvc\Dispatcher->dispatch(Object(OPNsense\Mvc\Request), Object(OPNsense\Mvc\Response), Object(OPNsense\Mvc\Session))
#7 /usr/local/opnsense/mvc/app/library/OPNsense/Mvc/Router.php(139): OPNsense\Mvc\Router->performRequest(Object(OPNsense\Mvc\Dispatcher))
#8 /usr/local/opnsense/www/api.php(36): OPNsense\Mvc\Router->routeRequest('/api/nginx/sett...', Array)
#9 {main}

Is anything wrong with my OPNsense installation or it is broken for everybody?

[Enable]

To reproduce:
* Set Unbound log level to 1
* Enable "Flush DNS Cache during reload"
* Run as root: sh -c 'while :; do  pluginctl unbound_start; sleep 20; done'

After a few iterations the startup problem should be triggered.

It should be easier to reproduce the issue now.
I hope the developers will take a look on it.

The problem seems to be OPNsense-only.

I found no report about similar problems on Linux, pure FreeBSD, PFsense or anything.
However, it easy to find several similar reports for OPNsense.

[restart]

Looks like it is not a restart problem, but it is a start problem.

The process stuck at 100% CPU is the new Unbound process. Not the old one.

Two things may significantly reduce the chances of startup problems: Log level 3 or higher, not enabled "Flush DNS Cache during reload".
Both things seems to just slow down the startup and resolve the race condition.

To reproduce:
* Set Unbound log level to 1
* Enable "Flush DNS Cache during reload"
* Run as root: sh -c 'while :; do  pluginctl unbound_start; sleep 20; done'

After a few iterations the startup problem should be triggered.

[Flush DNS Cache during reload]

I do have Flush DNS Cache during reload enabled, which I now wonder if that exacerbated this issue.

BTW I have it enabled as well.
Maybe "disabled" just slow down startup enough to have mask the issue?

[stopping]

Only after two weeks of running with # opnsense-patch 845fbd384fe I got freeze of Unbound again.

The last lines in the log:

Code Select Expand

2023-11-01T16:06:07 Notice unbound 17147 [17147:0] notice: init module 0: python
2023-11-01T16:03:33 Informational unbound 15198 [15198:0] info: service stopped (unbound 1.18.0).
2023-11-01T15:53:34 Informational unbound 15198 [15198:1] info: generate keytag query _ta-4f66. NULL IN

Note: at 16:06 I manually killed unbound process with kill -9.

The system log:

Code Select Expand

2023-11-01T16:06:07 Notice opnsense /usr/local/etc/rc.newwanip: plugins_configure newwanip (execute task : webgui_configure_do(,opt1))
2023-11-01T16:06:07 Notice opnsense /usr/local/etc/rc.newwanip: plugins_configure newwanip (execute task : vxlan_configure_do())
2023-11-01T16:03:32 Notice opnsense /usr/local/etc/rc.newwanip: plugins_configure newwanip (execute task : unbound_configure_do(,opt1))
2023-11-01T16:03:32 Notice opnsense /usr/local/etc/rc.newwanip: plugins_configure newwanip (execute task : openssh_configure_do(,opt1))
2023-11-01T16:03:32 Notice opnsense /usr/local/etc/rc.newwanip: plugins_configure newwanip (execute task : opendns_configure_do())
2023-11-01T16:03:32 Notice opnsense /usr/local/etc/rc.newwanip: plugins_configure newwanip (execute task : ntpd_configure_do())
2023-11-01T16:03:32 Notice opnsense /usr/local/etc/rc.newwanip: plugins_configure newwanip (execute task : dnsmasq_configure_do())
2023-11-01T16:03:32 Notice opnsense /usr/local/etc/rc.newwanip: plugins_configure newwanip (,opt1)


Observations: Unbound wasn't actually stopped.

Probably the problem is not with Unbound start, but with Unboud stop procedure.

OPNsense thinks that Unbound is stopped (reported in Unbound log), but actually Unbound is still running. The parallel start of the Unbound, while another copy is still running resulted in various problems.

Previously reported high CPU load was produced by the stopping Unbound process, not by the just started process.

[before]

https://github.com/opnsense/core/commit/845fbd384fe

# opnsense-patch 845fbd384fe

This patch significantly changed the situation.
Unbound is not crashing anymore, while without this patch Unbound was crashing daily.
I'm testing it for several days. The settings were chosen to trigger crash as much as possible (no debugging logging, parallel threads).

Probably without this patch the file is created in parallel with normal Unbound startup.
With this patch the file is created always before the start of Unbound.

The behaviour is different.
Unbound just crashed and I was able to simply restart it in GUI.
Without the test patch Unbound uses 100% CPU and had to be killed by 'kill -9' in CLI.

So something has changed.

Tried with the "diagnose tool" patch.

After ~100 restarts, Unbound silently crashed.
Had to (re-)start it manually.

The log:

Code Select Expand

2023-10-18T11:00:00 Informational unbound 24371 [24371:1] info: generate keytag query _ta-4f66. NULL IN
2023-10-18T11:00:00 Informational unbound 24371 [24371:0] info: start of service (unbound 1.18.0).
2023-10-18T11:00:00 Notice unbound 24371 [24371:0] notice: init module 2: iterator
2023-10-18T11:00:00 Notice unbound 24371 [24371:0] notice: init module 1: validator
2023-10-18T11:00:00 Notice unbound 24378 daemonize unbound dhcpd watcher.
2023-10-18T11:00:00 Notice unbound 24371 [24371:0] notice: init module 0: python
2023-10-18T10:52:02 Notice unbound 23736 [23736:0] notice: init module 2: iterator
2023-10-18T10:52:02 Notice unbound 23736 [23736:0] notice: init module 1: validator
2023-10-18T10:52:02 Notice unbound 23743 daemonize unbound dhcpd watcher.
2023-10-18T10:52:02 Notice unbound 23736 [23736:0] notice: init module 0: python


Relevant record from the system log:

Code Select Expand

2023-10-18T10:52:02 Notice kernel <6>pid 23736 (unbound), jid 0, uid 59: exited on signal 11

We're talking about a very narrow window of opportunity here that seems to be 100% reproducible?

It happens one time out of 150-200 starts. So it is far from 100% reproducible.

I'm still a bit sceptical. But you could just try to make a copy of the file and change the source code for the unbound.conf to point to that one that is not touched...

These theories are very easy to test when you can reproduce. If not it's impossible.

I tried to isolate Unbound-related changes from other changes in OPNsense between 23.1 and 23.7, but I failed.
Too many changes and I'm not sure that all of them could be reverted without making changes in other components or frameworks.

Could you, please, point me to the easiest way to test OPNsense changes for Unbound isolated from other changes?

Probably relevant:
https://forum.opnsense.org/index.php?topic=35527.0

Or third option: the file is being created in parallel with the start of Unbound. Then file content should be OK, while Unbound may read the file with an error.
I summarised possible options here: https://forum.opnsense.org/index.php?topic=35527.msg177257#msg177257

OK - unbound has been crashing - executed the above - will monitor.

This will not help.

If Unbound is started successfully, it will continue to work fine until restarted.
When OPNsense (re-)starts Unbound, the script re-creates '/var/unbound/root.hints' automatically.