[SOLVED] Squid proxy crashing (unexpected read from basicauthenticator)

[denmmx]

Hi,
some days ago Squid proxy began to crash periodically (NOT every day) somewhere about after 1 AM with next entries in cache.log:

Code Select Expand

2016/08/24 00:01:11 kid1| WARNING: basicauthenticator #Hlpr1334 exited
2016/08/24 00:01:11 kid1| Too few basicauthenticator processes are running (need 1/20)
2016/08/24 00:01:11 kid1| Starting new helpers
2016/08/24 00:01:11 kid1| helperOpenServers: Starting 1/20 'squid.auth-user.php' processes
2016/08/24 00:01:12 kid1| helperHandleRead: unexpected read from basicauthenticator #Hlpr1335, 325 bytes '
Warning: require_once(script/load_phalcon.php): failed to open stream: No such file or directory in /usr/local/etc/inc/legacy_bindings.inc on line 30

Fatal error: require_once(): Failed opening required 'script/load_phalcon.php' (include_path='.:/usr/local/share/pear') in /usr/local/etc/inc/legacy_bindings.inc on line 30
'
2016/08/24 00:01:12 kid1| WARNING: basicauthenticator #Hlpr1335 exited
2016/08/24 00:01:12 kid1| Too few basicauthenticator processes are running (need 1/20)
2016/08/24 00:01:12 kid1| Starting new helpers
2016/08/24 00:01:12 kid1| helperOpenServers: Starting 1/20 'squid.auth-user.php' processes
2016/08/24 00:01:12 kid1| helperHandleRead: unexpected read from basicauthenticator #Hlpr1336, 325 bytes '
Warning: require_once(script/load_phalcon.php): failed to open stream: No such file or directory in /usr/local/etc/inc/legacy_bindings.inc on line 30

Fatal error: require_once(): Failed opening required 'script/load_phalcon.php' (include_path='.:/usr/local/share/pear') in /usr/local/etc/inc/legacy_bindings.inc on line 30
'


...and entries repeating indefinitely. What could be the problem??
Thanks!

[franco]

The include path for PHP is incomplete. Is this 16.7.2 or lower? Any modifications?

# pkg query %v php56

If this returns "5.6.24_1" then you can try to run:

# /usr/local/etc/rc.php_ini_setup

[denmmx]

I'm running 16.7.2-amd64 release, w/o any modifications.

Code Select Expand

pkg query %v php56
returns "5.6.24_1" and I run

Code Select Expand

# /usr/local/etc/rc.php_ini_setup

as you advised. This command doesn't return anything, all works normally so far :)

[denmmx]

Today, all night long, same error with authenticator module appears again, squid crashed with auth.
There is example of error message (same as previous):

Code Select Expand

2016/08/31 03:24:05 kid1| WARNING: basicauthenticator #Hlpr200888 exited
2016/08/31 03:24:05 kid1| Too few basicauthenticator processes are running (need 1/20)
2016/08/31 03:24:05 kid1| Starting new helpers
2016/08/31 03:24:05 kid1| helperOpenServers: Starting 1/20 'squid.auth-user.php' processes
2016/08/31 03:24:05 kid1| helperHandleRead: unexpected read from basicauthenticator #Hlpr200889, 325 bytes '
Warning: require_once(script/load_phalcon.php): failed to open stream: No such file or directory in /usr/local/etc/inc/legacy_bindings.inc on line 30

Fatal error: require_once(): Failed opening required 'script/load_phalcon.php' (include_path='.:/usr/local/share/pear') in /usr/local/etc/inc/legacy_bindings.inc on line 30

How I can fix it??

[franco]

It's the same problem and the fix should work again.

Something clobbers your /usr/local/etc/php.ini -- do you have any modifications, plugins  or other packages installed?

[denmmx]

No additional packages are installed. No modifications and plugins.

This is my  /usr/local/etc/php.ini

Code Select Expand

; File generated via rc.php_ini_setup
output_buffering = "0"
expose_php = Off
implicit_flush = true
magic_quotes_gpc = Off
max_execution_time = 900
max_input_time = 1800
max_input_vars = 5000
memory_limit = 256M
register_argc_argv = On
register_long_arrays = Off
variables_order = "GPCS"
file_uploads = On
upload_tmp_dir = /tmp
upload_max_filesize = 200M
post_max_size = 200M
html_errors = Off
zlib.output_compression = Off
zlib.output_compression_level = 1
include_path = ".:/usr/local/etc/inc:/usr/local/www:/usr/local/opnsense/mvc:/usr/local/share/pear:/usr/local/opnsense/contrib"
ignore_repeated_errors = on
error_reporting = E_ALL ^ (E_NOTICE | E_DEPRECATED | E_STRICT)
display_errors=on
log_errors=on
error_log=/tmp/PHP_errors.log
extension_dir=/usr/local/lib/php/20131226/
date.timezone="Europe/Moscow"

[suhosin]
suhosin.get.max_array_depth = 5000
suhosin.get.max_array_index_length = 256
suhosin.get.max_vars = 5000
suhosin.get.max_value_length = 500000
suhosin.post.max_array_depth = 5000
suhosin.post.max_array_index_length = 256
suhosin.post.max_vars = 5000
suhosin.post.max_value_length = 9000000
suhosin.request.max_array_depth = 5000
suhosin.request.max_array_index_length = 256
suhosin.request.max_vars = 5000
suhosin.request.max_value_length = 9000000
suhosin.memory_limit = 512435456
suhosin.session.cryptdocroot=Off



So strange, but this error with squid at same time with period in some days, the reason of his behavior is unknown. What app or service can modify php.ini?

[franco]

In general this only happens when a firmware update is run, the box reboots or the web interface restart is forced.

Do you have a cron job for firmware updates?

[denmmx]

Do you have a cron job for firmware updates?

Yes, I tuned it to update automatically at 4:00AM every 2-nd day of week, but Squid crashed today (3-rd day, Wedn.) and near midhight; here is screenshot.

P.S. Server was rebooted at 10 AM manually.

[franco]

It's definitely something that happens within your system. How do other graphs look, especially memory graph?

[denmmx]

Here is CPU and RAM graphs (31.08.2016, 0:00 AM - 31.08.2016, 9:30 AM, till reboot) (during Squid errors and writing it to cache.log)

[denmmx]

Up! Release 16.7.3, and error appeared again today at 0 AM... Or 'm really need to add cron task

Code Select Expand

/usr/local/etc/rc.php_ini_setup
to run every day??

Someone can help me?

[franco]

Can you post the contents of /usr/local/lib/php.ini and /usr/local/etc/php.ini right after the crash?

I understand that this is annoying, but it's also highly unusual and hard to debug remotely.

I can reproduce something similar now and will provide a test patch soon, but other than guessing that this might be it, I have no idea why it's being triggered. Be right back...

[denmmx]

Ok, I will post php.ini files after next crashing... Thanks for your help!

[franco]

I could reproduce the faulty include path by forcefully flushing php.ini files (empty) and there is one spot in that script that does that. It's been like this for years and I can't make out whether that's the problem or how it is triggered, but I tightened the code as there is no downside from doing so.

To get this new file, run these commands:

# cd /usr/local/etc
# mv rc.php_ini_setup rc.php_ini_setup.bak
# fetch https://raw.githubusercontent.com/opnsense/core/bd66467db/src/etc/rc.php_ini_setup

And the respective commit for information:

https://github.com/opnsense/core/commit/bd66467db8df7


Cheers,
Franco

[denmmx]

It is need to run new rc.php_ini_setup?