php.net |  support |  documentation |  report a bug |  advanced search |  search howto |  statistics |  random bug |  login
Bug #79729 Strings missing last character (Apache + OPcache)
Submitted: 2020-06-24 10:18 UTC Modified: 2020-06-25 13:41 UTC
From: ca at lsp dot net Assigned: cmb (profile)
Status: Assigned Package: opcache
PHP Version: 7.3.19 OS: Windows Server 2016 Standard
Private report: No CVE-ID: None
Have you experienced this issue?
Rate the importance of this bug to you:

 [2020-06-24 10:18 UTC] ca at lsp dot net
Description:
------------
I observed a very strange behaviour in combination with Apache + OPcache today.

My colleague was using the test instance of our PHP application this morning (no deployment since yesterday), and it was working fine, until suddenly the following error appeared (and didn't disappear anymore):

```
Error: Uncaught  --> Smarty: Plugin 'cut_hea' not callable
```

The string "cut_hea" doesn't exist in our code base, but instead comes from a class constant string array containing the element "cut_head":

```
class SmartyModifiers
{
    const MODIFIERS = [
        "cut_head",
        ...
    ];

    public static function cut_head( ... )
    {
        ...
    }
}
```

This class constant is being used as follows:

```
foreach (SmartyModifiers::MODIFIERS as $modifier) {
    $ref = SmartyModifiers::class . '::' . $modifier;
    $this->registerPlugin("modifier", $modifier, $ref);
}
```

The error was logged inside the `registerPlugin` method, because `SmartyModifiers::cut_hea` (without the "d") doesn't exist and is therefore not callable.

Now, as if this wasn't strange enough, the corresponding Sentry event also contained the same anomaly:

```
There was 1 error encountered while processing this event
* environmen: Discarded unknown attribute
```

(Note the missing "t" in "environmen" vs. "environment".)

To mitigate the issue, I tried to `opcache_reset()` and restart the Apache server, but both didn't solve the issue. The only solution I found was to disable `zend_extension=php_opcache.dll` temporarily (disable, restart, enable, restart).

Our OPcache configuration is as follows, following the recommendations from [1]:

```
[opcache]
zend_extension=php_opcache.dll
opcache.memory_consumption=128
opcache.interned_strings_buffer=8
opcache.max_accelerated_files=4000
opcache.revalidate_freq=60
opcache.fast_shutdown=1
opcache.enable_cli=1
```

[1] https://www.php.net/manual/de/opcache.installation.php


Patches

Add a Patch

Pull Requests

Add a Pull Request

History

AllCommentsChangesGit/SVN commitsRelated reports
 [2020-06-24 10:30 UTC] nikic@php.net
Does opcache.optimization_level=0 fix the issue?
 [2020-06-24 10:38 UTC] cmb@php.net
-Status: Open +Status: Feedback -Assigned To: +Assigned To: cmb
 [2020-06-24 10:38 UTC] cmb@php.net
Are you really using PHP 7.3.19, or maybe an older 7.3 version?
If the latter, could you check with 7.3.19?

Also, do you use mod_php or FCGI; in other words, is about a ZTS
(thread-safe) or NTS (non thread-safe) PHP build?
 [2020-06-24 10:45 UTC] ca at lsp dot net
@nikic Thanks, I will try that once the issue occurs again (which I hope it does).

@cmb The server is running PHP 7.3.19 since 2020-06-11 (but actually the OS is Windows Server 2016 Standard, not Windows 10).

```
$ php --version
PHP 7.3.19 (cli) (built: Jun  9 2020 11:54:59) ( ZTS MSVC15 (Visual C++ 2017) x64 )
Copyright (c) 1997-2018 The PHP Group
Zend Engine v3.3.19, Copyright (c) 1998-2018 Zend Technologies
    with Zend OPcache v7.3.19, Copyright (c) 1999-2018, by Zend Technologies
```
 [2020-06-24 10:47 UTC] ca at lsp dot net
-Status: Feedback +Status: Assigned -Operating System: Windows 10 +Operating System: Windows Server 2016 Standard
 [2020-06-24 10:47 UTC] ca at lsp dot net
Updated OS.
 [2020-06-24 11:18 UTC] ca at lsp dot net
Just stumbled upon the following errors in the Windows Event Logs:

```
24.06.2020 08:43:00, Event 487, Zend OPcache
Opcode handlers are unusable due to ASLR. Please setup opcache.file_cache and opcache.file_cache_fallback directives for more convenient Opcache usage

...

23.06.2020 20:15:00, Event 0, Zend OPcache
Unable to read base address
```

Events 487 occur several times per day and sound like bug #79040, which should have been fixed in 7.3.14.

Events 0 occur not more than once per day.

The issues started 10 minutes after an Event 487:

```
[24/Jun/2020:08:53:13 +0200] "GET /admin/default*** HTTP/2.0" 302 -
[24/Jun/2020:08:53:13 +0200] "GET /admin/index*** HTTP/2.0" 500 921
```

But there are also two PHP cronjobs running every minute via CLI.
 [2020-06-24 12:25 UTC] cmb@php.net
> Events 487 occur several times per day and sound like bug
> #79040, which should have been fixed in 7.3.14.

That bug was actually why I asked for the exact PHP version
(thanks for the info!)  The fix addressed potential issues with
running diffent SAPIs simultaneously (such as apache2handler and
cli).

Other than that, "Opcode handlers are unusable due to ASLR."
warnings may occur on Windows, so we recommend to never disable
opcache.file_cache_fallback (which it is in your case); otherwise
the process exits, which is undesireable.

I don't think that these errors are related to the truncated
strings, though.

[1] <https://www.php.net/manual/en/opcache.configuration.php#ini.opcache.file-cache-fallback>
 [2020-06-24 12:40 UTC] ca at lsp dot net
> we recommend to never disable opcache.file_cache_fallback (which it is in your case)

I'm a bit confused, because `opcache.file_cache_fallback` is actually *not* disabled in our case (see OPcache configuration above). I just verified this (both via `php -i` and a `phpinfo()` script accessed via Apache, in case these may differ, which they don't seem to).

Here's the relevant section from the current output of `php -i` (coincidentally just after a deployment calling `opcache_reset()`, hence 0 hits/misses):

```
Zend OPcache

Opcode Caching => Up and Running
Optimization => Enabled
SHM Cache => Enabled
File Cache => Disabled
Startup => OK
Shared memory model => win32
Cache hits => 0
Cache misses => 0
Used memory => 8770936
Free memory => 125446792
Wasted memory => 0
Interned Strings Used memory => 342472
Interned Strings Free memory => 5948536
Cached scripts => 0
Cached keys => 0
Max keys => 7963
OOM restarts => 0
Hash keys restarts => 0
Manual restarts => 0

Directive => Local Value => Master Value
opcache.blacklist_filename => no value => no value
opcache.consistency_checks => 0 => 0
opcache.dups_fix => Off => Off
opcache.enable => On => On
opcache.enable_cli => On => On
opcache.enable_file_override => Off => Off
opcache.error_log => C:\***\opcache_error.log => C:\***\opcache_error.log
opcache.file_cache => no value => no value
opcache.file_cache_consistency_checks => On => On
opcache.file_cache_fallback => On => On
opcache.file_cache_only => Off => Off
opcache.file_update_protection => 2 => 2
opcache.force_restart_timeout => 180 => 180
opcache.interned_strings_buffer => 8 => 8
opcache.log_verbosity_level => 1 => 1
opcache.max_accelerated_files => 4000 => 4000
opcache.max_file_size => 0 => 0
opcache.max_wasted_percentage => 5 => 5
opcache.memory_consumption => 128 => 128
opcache.mmap_base => no value => no value
opcache.opt_debug_level => 0 => 0
opcache.optimization_level => 0x7FFEBFFF => 0x7FFEBFFF
opcache.preferred_memory_model => no value => no value
opcache.protect_memory => Off => Off
opcache.restrict_api => no value => no value
opcache.revalidate_freq => 60 => 60
opcache.revalidate_path => Off => Off
opcache.save_comments => On => On
opcache.use_cwd => On => On
opcache.validate_permission => Off => Off
opcache.validate_timestamps => On => On
```

PS: The only change I made since the issue ocurred was to set `opcache.error_log` (and to use `rsync --checksum` in deployment rather than `rsync --times` to avoid OPcache possibly being confused by timestamps not reflecting the deployment timestamp).
 [2020-06-24 12:43 UTC] cmb@php.net
> opcache.file_cache => no value => no value

To actually enable the file_cache_fallback, you also need to set
opcache.file_cache to an already existing (and writeable, and
preferably empty) directory.
 [2020-06-24 13:14 UTC] ca at lsp dot net
> To actually enable the file_cache_fallback, you also need to set
opcache.file_cache to an already existing (...) directory.

Thanks for the clarification. I would have expected the "Recommended php.ini settings" [1] to mention this though. Is it worth creating a separate bug for this documentation improvement?

As regards the truncated strings, is there any valuable data I could collect when the issue appears again, before trying `opcache.optimization_level=0`?

[1] https://www.php.net/manual/de/opcache.installation.php#opcache.installation.recommended
 [2020-06-24 14:48 UTC] cmb@php.net
I've just amended the recommended settings section in the docs[1];
will take a while until it is rolled out to the server.

I don't think there is any valuable data you could provide, if the
problem occurs again.  Of course, in that case, check the logs,
and maybe it's useful to set opcache.log_verbosity_level to 3 or 4
in advance.

[1] <http://svn.php.net/viewvc?view=revision&revision=350081>
 [2020-06-25 10:30 UTC] ca at lsp dot net
@cmb Thank you for the docs update, I have set those values now.

Today I observed the following (possibly related) exceptions in the same instance, all in the context of web requests:

```
10:14:02 CEST
Error: Uncaught Error: Call to undefined method ***\MyDB::searchByCol()

10:20:10 CEST
Error: Uncaught Error: Call to undefined method ***\MyDB::searchByCol()

10:23:33 CEST
Error: Uncaught Error: Call to undefined method ***\MyDB::searchByCol()

11:03:03 CEST
Error: Uncaught Error: Call to undefined method ***\MyDB::searchByCol()
```

(Note: The method `MyDB::searchByCol()` *does* exist.)

The same issue occurred 3x on June 12, two days after we enabled OPcache (and one day after the upgrade to 7.3.19).

Unfortunately I had obviously not restarted the Apache server after making the latest config changes, so the OPcache log verbosity was not sufficient for the web server requests (and possibly the file_cache value was not yet effective either), so I will have to wait and see if it occurs again.

One thing I should mention though is that we run multiple branches simultaneously on that test server:

- C:/app = test app for branch "develop"
- C:/app-review/12345-foo = review app for branch "12345-foo"

So could these issues be related to the fact that there are multiple `MyDB.php` files? I wonder if I have to enable `opcache.revalidate_path` to prevent the wrong file from being loaded by OPcache?
 [2020-06-25 13:41 UTC] ca at lsp dot net
Meanwhile, I opened bug 79735 for the "Call to undefined method" error.

After some consideration though, the root cause could be the same. This is the *complete* log entry for the current issue in the PHP error log:

```
[24-Jun-2020 06:53:14 UTC] PHP Fatal error:  Uncaught  --> Smarty: Plugin 'cut_hea' not callable <-- 
  thrown in C:\***\vendor\smarty\smarty\libs\sysplugins\smarty_internal_method_registerplugin.php on line 50
```

The short stacktrace suggests that this error occurred in an exception_handler or similar, and maybe OPcache isn't working properly in that context?
 
PHP Copyright © 2001-2020 The PHP Group
All rights reserved.
Last updated: Sun Jul 05 01:01:27 2020 UTC