Regression: Mass PHP Errors (Permission denied) after opnsense Update #3241

uKev · 2019-02-17T17:25:12Z

Important notices
Before you add a new report, we ask you kindly to acknowledge the following:

[x] I have read the contributing guide lines at https://github.com/opnsense/core/blob/master/CONTRIBUTING.md

[x] I have searched the existing issues and I'm convinced that mine is new.

Describe the bug
Opnsense fills up the disk writing php error messages to /tmp/PHP_errors.log.
Lobby -> Dashboard takes a long time to load and has an error message "A problem was detected. Click here for more information."
Clicking on the link shows "Unfortunately we have detected at least one programming bug."
And a very long scrollbar shows the php error file.

To Reproduce
I updated from version 18.7.9 to 19.1. The error started after this update, so my guess is the migration scripts are not perfect, yet. This is the first regression for years.
Issue still exists after update to 19.1.1.

Expected behavior
There should be no errors. If there are errors, they should not fill up the disk completely.

Relevant log files
tail -n 40 /tmp/PHP_errors.log

#8 {main}
thrown in /usr/local/opnsense/mvc/app/library/OPNsense/Core/Config.php on line 319
[17-Feb-2019 17:51:40 Europe/Berlin] PHP Warning: fopen(/conf/config.xml): failed to open stream: Permission denied in /usr/local/opnsense/mvc/app/library/OPNsense/Core/Config.php on line 354
[17-Feb-2019 17:51:40 Europe/Berlin] PHP Warning: fseek() expects parameter 1 to be resource, boolean given in /usr/local/opnsense/mvc/app/library/OPNsense/Core/Config.php on line 316
[17-Feb-2019 17:51:40 Europe/Berlin] PHP Warning: stream_get_contents() expects parameter 1 to be resource, boolean given in /usr/local/opnsense/mvc/app/library/OPNsense/Core/Config.php on line 317
[17-Feb-2019 17:51:40 Europe/Berlin] PHP Warning: copy(/conf/config.xml): failed to open stream: Permission denied in /usr/local/opnsense/mvc/app/library/OPNsense/Core/Config.php on line 522
[17-Feb-2019 17:51:40 Europe/Berlin] PHP Warning: fopen(/conf/config.xml): failed to open stream: Permission denied in /usr/local/opnsense/mvc/app/library/OPNsense/Core/Config.php on line 354
[17-Feb-2019 17:51:40 Europe/Berlin] PHP Warning: fseek() expects parameter 1 to be resource, boolean given in /usr/local/opnsense/mvc/app/library/OPNsense/Core/Config.php on line 316
[17-Feb-2019 17:51:40 Europe/Berlin] PHP Warning: stream_get_contents() expects parameter 1 to be resource, boolean given in /usr/local/opnsense/mvc/app/library/OPNsense/Core/Config.php on line 317
[17-Feb-2019 17:51:40 Europe/Berlin] PHP Fatal error: Uncaught OPNsense\Core\ConfigException: empty file in /usr/local/opnsense/mvc/app/library/OPNsense/Core/Config.php:319
Stack trace:
#0 /usr/local/opnsense/mvc/app/library/OPNsense/Core/Config.php(357): OPNsense\Core\Config->loadFromStream(false)
#1 /usr/local/opnsense/mvc/app/library/OPNsense/Core/Config.php(523): OPNsense\Core\Config->load()
#2 /usr/local/opnsense/mvc/app/library/OPNsense/Core/Config.php(291): OPNsense\Core\Config->restoreBackup('/conf/backup/co...')
#3 /usr/local/opnsense/mvc/app/library/OPNsense/Core/Singleton.php(49): OPNsense\Core\Config->init()
#4 /usr/local/opnsense/mvc/app/library/OPNsense/Core/Singleton.php(70): OPNsense\Core\Singleton->__construct()
#5 /usr/local/etc/inc/config.inc(68): OPNsense\Core\Singleton::getInstance()
#6 /usr/local/etc/inc/config.inc(331): parse_config()
#7 /usr/local/etc/inc/plugins.inc.d/squid/auth-user.php(31): require_once('/usr/local/etc/...')
#8 {main}
thrown in /usr/local/opnsense/mvc/app/library/OPNsense/Core/Config.php on line 319
[17-Feb-2019 17:51:40 Europe/Berlin] PHP Warning: fopen(/conf/config.xml): failed to open stream: Permission denied in /usr/local/opnsense/mvc/app/library/OPNsense/Core/Config.php on line 354
[17-Feb-2019 17:51:40 Europe/Berlin] PHP Warning: fseek() expects parameter 1 to be resource, boolean given in /usr/local/opnsense/mvc/app/library/OPNsense/Core/Config.php on line 316
[17-Feb-2019 17:51:40 Europe/Berlin] PHP Warning: stream_get_contents() expects parameter 1 to be resource, boolean given in /usr/local/opnsense/mvc/app/library/OPNsense/Core/Config.php on line 317
[17-Feb-2019 17:51:40 Europe/Berlin] PHP Warning: copy(/conf/config.xml): failed to open stream: Permission denied in /usr/local/opnsense/mvc/app/library/OPNsense/Core/Config.php on line 522
[17-Feb-2019 17:51:40 Europe/Berlin] PHP Warning: fopen(/conf/config.xml): failed to open stream: Permission denied in /usr/local/opnsense/mvc/app/library/OPNsense/Core/Config.php on line 354
[17-Feb-2019 17:51:40 Europe/Berlin] PHP Warning: fseek() expects parameter 1 to be resource, boolean given in /usr/local/opnsense/mvc/app/library/OPNsense/Core/Config.php on line 316
[17-Feb-2019 17:51:40 Europe/Berlin] PHP Warning: stream_get_contents() expects parameter 1 to be resource, boolean given in /usr/local/opnsense/mvc/app/library/OPNsense/Core/Config.php on line 317
[17-Feb-2019 17:51:40 Europe/Berlin] PHP Fatal error: Uncaught OPNsense\Core\ConfigException: empty file in /usr/local/opnsense/mvc/app/library/OPNsense/Core/Config.php:319
Stack trace:
#0 /usr/local/opnsense/mvc/app/library/OPNsense/Core/Config.php(357): OPNsense\Core\Config->loadFromStream(false)
#1 /usr/local/opnsense/mvc/app/library/OPNsense/Core/Config.php(523): OPNsense\Core\Config->load()
#2 /usr/local/opnsense/mvc/app/library/OPNsense/Core/Config.php(291): OPNsense\Core\Config->restoreBackup('/conf/backup/co...')
#3 /usr/local/opnsense/mvc/app/library/OPNsense/Core/Singleton.php(49): OPNsense\Core\Config->init()
#4 /usr/local/opnsense/mvc/app/library/OPNsense/Core/Singleton.php(70): OPNsense\Core\Singleton->__construct()
#5 /usr/local/etc/inc/config.inc(68): OPNsense\Core\Singleton::getInstance()
#6 /usr/local/etc/inc/config.inc(331): parse_config()
#7 /usr/local/etc/inc/plugins.inc.d/squid/auth-user.php(31): require_once('/usr/local/etc/...')
#8 {main}
thrown in /usr/local/opnsense/mvc/app/library/OPNsense/Core/Config.php on line 319

(always the same error)

ls -lah /tmp/PHP_errors.log

-rw-r----- 1 squid wheel 454M Feb 17 17:51 /tmp/PHP_errors.log

ls -lah /conf/config.xml

-rw-r--r-- 1 root wheel 159K Feb 17 15:14 /conf/config.xml

ls -lah /usr/local/etc/inc/plugins.inc.d/squid/auth-user.php

-rwxr-xr-x 1 root wheel 3.7K Feb 4 00:53 /usr/local/etc/inc/plugins.inc.d/squid/auth-user.php

uptime

6:03PM up 1 day, 2:38, 1 user, load averages: 1.96, 1.84, 1.69

After a few days of uptime the disk is full.

Environment

OPNsense 19.1.1 (OpenSSL).
qemu
libvirt
virtio

I'm happy to provide additional information if it's required, just ask what you need.

AdSchellevis · 2019-02-17T17:36:55Z

@lattera could there be some kernel security setting which prevents the user squid from reading /conf/config.xml ? I've seen this one time before on a vm with 19.1, but I think it went away at some point.

@uKev can you try the following:

service squid stop
rm /tmp/PHP_errors.log
service squid start

And check if the errors are returning instantly?

uKev · 2019-02-17T17:50:21Z

Thanks for the quick reply.

Just tried your commands out: No, the errors are not returning instantly.

Besides this I did delete the file two weeks ago ago and rebootet the system. It needed some time until the file comes back. Besides the error message squid works fine as it should.

In the System -> Log Files -> General I just noticed the following messages:

Feb 17 18:38:10 | config[7720]: No valid config.xml found, attempting last known config restore.
Feb 17 18:38:10 | config[379]: No valid config.xml found, attempting last known config restore.
Feb 17 18:38:09 | config[80597]: No valid config.xml found, attempting last known config restore.
Feb 17 18:38:09 | config[72330]: No valid config.xml found, attempting last known config restore.
Feb 17 18:38:09 | config[71596]: No valid config.xml found, attempting last known config restore.
Feb 17 18:38:08 | config[23798]: No valid config.xml found, attempting last known config restore.
Feb 17 18:38:08 | config[90501]: No valid config.xml found, attempting last known config restore.

Also the page "Services -> Web Proxy -> Log File -> Cache" needs a long time to load.

AdSchellevis · 2019-02-17T18:03:54Z

so after a restart of squid, no new errors and authentication still works?

lattera · 2019-02-17T19:07:58Z

Are hardlinks being used? Take a look at the hardlink hardening in HardenedBSD: https://github.com/HardenedBSD/hardenedBSD/wiki#modified-sysctl-nodes

In particular, these sysctl nodes:

security.bsd.hardlink_check_gid
security.bsd.hardlink_check_uid

AdSchellevis · 2019-02-17T19:11:12Z

There shouldn't be any hard links involved, but I can see if there's a way to replicate the issue this week and set both to 0.... you never know.

uKev · 2019-02-17T19:23:57Z

At the moment there are no new errors. But I think they will come back in a few days.

I don't use authentication. I started with opnsense when proxy auth was not required. Later I remember that I had to configure "Allowed Subnets" and "Unrestricted IP addresses" in Access Control List to use it again. Looking at it now I see "Authentication method" has "nothing selected" as value:

fichtner · 2019-02-17T20:22:41Z

I remember these two from over the years...

https://forum.opnsense.org/index.php?topic=2886.msg8875#msg8875
https://forum.opnsense.org/index.php?topic=2090.msg6638#msg6638

But it looks like a new problem.

Make sure that all packages are correctly installed so that their permissions are correct as well (squid3 and opnsense, best to hit reinstall for those two).

AdSchellevis · 2019-02-18T08:07:02Z

hmm, with basic auth disabled, it shouldn't even try to do this.

can you check if the following returns anything?

grep auth_param /usr/local/etc/squid/squid.conf

AdSchellevis · 2019-02-18T08:38:37Z

@lattera it doesn't seem to be related to the hard link settings, but seems fairly easy to reproduce.

Using sysctl I've set both the hardlink settings to 0, which didn't show any difference.

To reproduce the issue, go to the "web proxy" --> "forward proxy" --> "authentication settings" and choose "Local Database". Apply settings, stop the proxy and go to a console.

Flush the cache log, start squid and tail the log.

rm /var/log/squid/cache.log
service squid start
tail -f /var/log/squid/cache.log

Now configure your browser to use the proxy, you will be asked for a username and a password, try something (doesn't matter what), and see the tail get flooded by:

2019/02/18 09:29:57 kid1| helperOpenServers: Starting 1/5 'auth-user.php' processes
PHP Warning:  fopen(/conf/config.xml): failed to open stream: Permission denied in /usr/local/opnsense/mvc/app/library/OPNsense/Core/Config.php on line 354
PHP Stack trace:
PHP   1. {main}() /usr/local/etc/inc/plugins.inc.d/squid/auth-user.php:0
PHP   2. require_once() /usr/local/etc/inc/plugins.inc.d/squid/auth-user.php:31
PHP   3. parse_config() /usr/local/etc/inc/config.inc:331
PHP   4. OPNsense\Core\Singleton::getInstance() /usr/local/etc/inc/config.inc:68
PHP   5. OPNsense\Core\Config->__construct() /usr/local/opnsense/mvc/app/library/OPNsense/Core/Singleton.php:70
PHP   6. OPNsense\Core\Config->init() /usr/local/opnsense/mvc/app/library/OPNsense/Core/Singleton.php:49
PHP   7. OPNsense\Core\Config->load() /usr/local/opnsense/mvc/app/library/OPNsense/Core/Config.php:282
PHP   8. fopen() /usr/local/opnsense/mvc/app/library/OPNsense/Core/Config.php:354

Installing an older squid version (from 18.7), doesn't seem to show much difference, I've tried to install the version from 18.7.1 (pkg add -f https://pkg.opnsense.org/FreeBSD:11:amd64/18.7/MINT/18.7.1/OpenSSL/All/squid3-3.5.27_3.txz)

I don't have a stock FreeBSD version around, so I'm not 100% sure this relates only to HardenedBSD.

uKev · 2019-02-18T09:33:51Z

Great that you could reproduce it.

Here is the output:

# grep auth_param /usr/local/etc/squid/squid.conf
auth_param basic program /usr/local/etc/inc/plugins.inc.d/squid/auth-user.php
auth_param basic realm OPNsense proxy authentication
auth_param basic credentialsttl 2 hours
auth_param basic children 5

As expected the error log appeared again. It started exactly at midnight (cronjob?):

# ls -lah /tmp/PHP_errors.log 
-rw-r-----  1 squid  wheel   269M Feb 18 10:10 /tmp/PHP_errors.log

# head /tmp/PHP_errors.log
[18-Feb-2019 00:00:00 Europe/Berlin] PHP Warning:  fopen(/conf/config.xml): failed to open stream: Permission denied in /usr/local/opnsense/mvc/app/library/OPNsense/Core/Config.php on line 354
[18-Feb-2019 00:00:00 Europe/Berlin] PHP Warning:  fseek() expects parameter 1 to be resource, boolean given in /usr/local/opnsense/mvc/app/library/OPNsense/Core/Config.php on line 316
[18-Feb-2019 00:00:00 Europe/Berlin] PHP Warning:  stream_get_contents() expects parameter 1 to be resource, boolean given in /usr/local/opnsense/mvc/app/library/OPNsense/Core/Config.php on line 317
[18-Feb-2019 00:00:00 Europe/Berlin] PHP Warning:  copy(/conf/config.xml): failed to open stream: Permission denied in /usr/local/opnsense/mvc/app/library/OPNsense/Core/Config.php on line 522
[18-Feb-2019 00:00:00 Europe/Berlin] PHP Warning:  fopen(/conf/config.xml): failed to open stream: Permission denied in /usr/local/opnsense/mvc/app/library/OPNsense/Core/Config.php on line 354
[18-Feb-2019 00:00:00 Europe/Berlin] PHP Warning:  fseek() expects parameter 1 to be resource, boolean given in /usr/local/opnsense/mvc/app/library/OPNsense/Core/Config.php on line 316
[18-Feb-2019 00:00:00 Europe/Berlin] PHP Warning:  stream_get_contents() expects parameter 1 to be resource, boolean given in /usr/local/opnsense/mvc/app/library/OPNsense/Core/Config.php on line 317
[18-Feb-2019 00:00:00 Europe/Berlin] PHP Fatal error:  Uncaught OPNsense\Core\ConfigException: empty file in /usr/local/opnsense/mvc/app/library/OPNsense/Core/Config.php:319
Stack trace:
#0 /usr/local/opnsense/mvc/app/library/OPNsense/Core/Config.php(357): OPNsense\Core\Config->loadFromStream(false)

And just for completeness here is the update history:

# cat /var/log/pkg.log | strings | grep opnsense
Dec 22 16:30:02 OPNsense pkg-static: opnsense upgraded: 18.7 -> 18.7.9 
Feb  2 12:35:00 OPNsense pkg-static: opnsense-update upgraded: 18.7.9 -> 18.7.10 
Feb  2 12:35:51 OPNsense pkg-static: opnsense upgraded: 18.7.9 -> 18.7.10_4 
Feb  9 18:12:35 OPNsense pkg-static: opnsense upgraded: 19.1 -> 19.1.1

AdSchellevis · 2019-02-18T09:40:30Z

@uKev can you save the proxy settings, and grep again? Since your authentication isn't enabled, the issue shouldn't affect you, so it looks like something went wrong with your configuration, saving settings might help. (the auth_param tags shouldn't be there in your case)

If the auth_params are gone, your issue should be fixed, but the real issue however remains. Hopefully @lattera has some ideas around the subject.

uKev · 2019-02-18T09:51:48Z

Applying the settings was not enough. I had to press "Clear All" on "Authentication method" to remove the auth_param lines from squid.conf.

Now I removed the error log again and restarted squid. It shouldn't reappear. If it does, I will leave a note.

Thanks for your work to everyone.

AdSchellevis · 2019-02-18T09:53:15Z

ok, thanks for reporting, we're keeping this open as bug for the authentication issue.

AdSchellevis · 2019-02-19T15:30:02Z

found it, when introducing config locking, I forgot about read-only access 5123277

…s not writeable. closes #3241 (cherry picked from commit 5123277)

Wirewrap64 · 2019-02-24T22:48:42Z

Hi everyone
I am new in the opnsense world.
I found this post trying to solve the problem that on opnsense 19.1, Squid did not authenticate the user.
Now I have replaced the Config.php file in /usr/local/opnsense/mvc/app/library/OPNsense/Core/ and Squid authentication works correctly or at least it seems so.
Is this the correct solution or should I apply some other fix?
When will it be updated on new installations?
Excuse me for the trivial questions and for my english, but I have just arrived on OPNsense.
Thank you

fichtner · 2019-02-25T03:56:00Z

Hi @Wirewrap64,

The patch will be part of the 19.1.2 stable release this week.

It won't be updated on new installations for 19.1 unless we release new images based on 19.1.x which currently is not planned, so each new 19.1 installation must be updated to 19.1.2 in order to fix the bug or you need to issue the patch command (or copy the file as you did) on 19.1 and 19.1.1:

# opnsense-patch 5123277

Cheers,
Franco

Wirewrap64 · 2019-02-25T18:27:50Z

Hi @fichtner,

thank for the answers !!!

Ciao
Wirewrap64 (Gaetano)

fichtner · 2019-02-25T18:32:39Z

@Wirewrap64 of course, no problem :)

AdSchellevis mentioned this issue Feb 18, 2019

PAM: extend opnsense-auth to support different helpers #3242

Closed

AdSchellevis added the bug Production bug label Feb 18, 2019

AdSchellevis self-assigned this Feb 19, 2019

AdSchellevis closed this as completed in 5123277 Feb 19, 2019

fichtner pushed a commit that referenced this issue Feb 24, 2019

config access, don't try to open config.xml in write mode when file i…

eb66736

…s not writeable. closes #3241 (cherry picked from commit 5123277)

fichtner added this to the 19.7 milestone Feb 25, 2019

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Regression: Mass PHP Errors (Permission denied) after opnsense Update #3241

Regression: Mass PHP Errors (Permission denied) after opnsense Update #3241

uKev commented Feb 17, 2019

AdSchellevis commented Feb 17, 2019

uKev commented Feb 17, 2019

AdSchellevis commented Feb 17, 2019

lattera commented Feb 17, 2019

AdSchellevis commented Feb 17, 2019

uKev commented Feb 17, 2019

fichtner commented Feb 17, 2019

AdSchellevis commented Feb 18, 2019

AdSchellevis commented Feb 18, 2019

uKev commented Feb 18, 2019

AdSchellevis commented Feb 18, 2019

uKev commented Feb 18, 2019

AdSchellevis commented Feb 18, 2019

AdSchellevis commented Feb 19, 2019

Wirewrap64 commented Feb 24, 2019

fichtner commented Feb 25, 2019

Wirewrap64 commented Feb 25, 2019

fichtner commented Feb 25, 2019

Regression: Mass PHP Errors (Permission denied) after opnsense Update #3241

Regression: Mass PHP Errors (Permission denied) after opnsense Update #3241

Comments

uKev commented Feb 17, 2019

ls -lah /tmp/PHP_errors.log

ls -lah /conf/config.xml

ls -lah /usr/local/etc/inc/plugins.inc.d/squid/auth-user.php

uptime

AdSchellevis commented Feb 17, 2019

uKev commented Feb 17, 2019

AdSchellevis commented Feb 17, 2019

lattera commented Feb 17, 2019

AdSchellevis commented Feb 17, 2019

uKev commented Feb 17, 2019

fichtner commented Feb 17, 2019

AdSchellevis commented Feb 18, 2019

AdSchellevis commented Feb 18, 2019

uKev commented Feb 18, 2019

AdSchellevis commented Feb 18, 2019

uKev commented Feb 18, 2019

AdSchellevis commented Feb 18, 2019

AdSchellevis commented Feb 19, 2019

Wirewrap64 commented Feb 24, 2019

fichtner commented Feb 25, 2019

Wirewrap64 commented Feb 25, 2019

fichtner commented Feb 25, 2019