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-07-29 08:32 UTC
From: ca at lsp dot net Assigned: cmb (profile)
Status: Suspended Package: opcache
PHP Version: 7.3.19 OS: Windows Server 2016 Standard
Private report: No CVE-ID: None
View Add Comment Developer Edit
Anyone can comment on a bug. Have a simpler test case? Does it work for you on a different platform? Let us know!
Just going to say 'Me too!'? Don't clutter the database with that please — but make sure to vote on the bug!
Your email address:
MUST BE VALID
Solve the problem:
47 - 14 = ?
Subscribe to this entry?

 
 [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?
 [2020-07-07 12:56 UTC] cmb@php.net
> 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.

That's actually nonsense wrt. apache2handler (assuming you're
running a single httpd instance).  That error can only occur on
Apache startup, and in that case the base mapping file should be
deleted, and Apache restarted.  Or delete the base mapping file
right away before restarting Apache.  The base mapping file is in
the temp folder, and its name is

    ZendOPcache.MemoryBase@<user>@apache2handler@<md5>

This needs to be documented, and preferably also improved.
 [2020-07-13 12:11 UTC] ca at lsp dot net
We have observed another strange behaviour last Thursday, namely a `PDOException`:

```
SQLSTATE[42000]: Syntax error or access violation: 1064 You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near '; 'own_req') 
 OR (perms.name = 'process' 
 AND perms.unit ; 'req') 
 
         ' at line 15,
```

The weird thing is that the corresponding code that generates the SQL conditions actually has "perms_unit =" hardcoded, so "perms_unit ;" should never occur:

``` 
            $sql_perm .= " perms.name = '$name' \n";
            $sql_perm .= " AND perms.unit = '$unit' \n $condition";
```

Note: The `$sql_perm` variable is used to create the final statement using `sprintf`, but that shouldn't make any difference.

The resulting SQL statement contained the mistake twice, since the code snippet above is part of a loop:

```
(perms.name = 'process' 
 AND perms.unit ; 'own_req') 
 OR (perms.name = 'process' 
 AND perms.unit ; 'req') 
```

Again, the problem disappeared after resetting the OPcache.
 [2020-07-13 13:25 UTC] cmb@php.net
That might have the same root cause as the truncated identifiers
(memory corruption).  Did that happen with
opcache.optimization_level=0?
 [2020-07-13 14:34 UTC] ca at lsp dot net
Thanks, I have set `opcache.optimization_level=0` now and will report back in a couple of weeks (if the error does not occur again).
 [2020-07-17 08:11 UTC] cmb@php.net
> Thanks, I have set `opcache.optimization_level=0` now and will
> report back in a couple of weeks (if the error does not occur
> again).

Thanks.  That might help to track to issue down.

Anyhow, my former comment regarding apache2handler startup
behavior[1] is wrong.  Actually, when running at most a single
httpd instance, the message "Opcode handlers are unusable due to
ASLR." is not supposed to occur, ever.  Thus, this issue may have
been reported by a PHP CLI process.

> This needs to be documented, and preferably also improved.

This holds, though.

[1] <https://bugs.php.net/bug.php?id=79729#1594126606>
 [2020-07-29 08:32 UTC] cmb@php.net
-Status: Assigned +Status: Suspended
 [2020-07-29 08:32 UTC] cmb@php.net
> This needs to be documented, and preferably also improved.

This has been done with <https://github.com/php/php-src/pull/5875>.

> […] and will report back in a couple of weeks (if the error does
> not occur again).

Please report back regardless of the outcome.  For the time being,
I'm suspending this ticket.
 
PHP Copyright © 2001-2020 The PHP Group
All rights reserved.
Last updated: Wed Aug 12 16:01:25 2020 UTC