Problem/Motivation

Some users report when clearing a cache or opening module page

Fatal error: Illegal length modifier specified 'f' in s[np]printf call in /core/lib/Drupal/Component/PhpStorage/MTimeProtectedFastFileStorage.php on line 88

in the mtime protected storage.

Steps to reproduce

No reliable reproduction steps have emerged.

Proposed resolution

Change the extension in MTimeProtectedFastFileStorage::getFullPath which is confirmed in #79 to avoid the problem. AFAIK include does not rely on file extension, the PHP engine is already off for the files directory so it's not like we ever wanted to load these from a browser. The security of the system relies on the file names being unguessable already.

Remaining tasks

Please give commit credit to Peter Pulsifier who came up with the idea.

User interface changes

API changes

Data model changes

Release notes snippet

Support from Acquia helps fund testing for Drupal Acquia logo

Comments

ayushst created an issue. See original summary.

longwave’s picture

Status: Active » Postponed (maintainer needs more info)

Line 88 of that file should be

    $result = rename($temporary_path, $full_path);

This has been the same since 2016, and there is no call to printf or related functions anywhere in the file. Are you running a patched version of Drupal? Can you post the lines around line 88 from that file?

ayushst’s picture

Yes, There are same code you have sent
$result = rename($temporary_path, $full_path);
No, I am not using patch version

longwave’s picture

Title: Illegal length modifier specified 'f' in s[np]printf call » Illegal length modifier specified 'f' in s[np]printf call on rename() in MTimeProtectedFastFileStorage
Assigned: ayushst » Unassigned
Status: Postponed (maintainer needs more info) » Active
Issue tags: +Needs steps to reproduce

There is an identical error message reported with a bit more investigation but no solution on Stack Overflow: https://stackoverflow.com/questions/61861990/illegal-length-modifier-spe...

I guess rename() must call sprintf() internally? But even so, the paths shouldn't be treated as format strings.

You say this only happens on your live server: is that Windows or Linux? Which version of PHP?

ayushst’s picture

Yes, I have searched more but didn't get any solution. I am using linux server with PHP 7.3 also I have checked with change PHP version.

brainiacque’s picture

I am having the same issue too. Like ayushst, I am only having the issue on my hosting server but not on my local machine. I upgraded to Drupal 8.9.2 tonight hoping that it would go away, but it's still happening. I am using shared hosting with Hostmonster at PHP version 7.3.19.

Digitill’s picture

I created the stackoverflow question in #4.

// Move the temporary file into the proper directory. Note that POSIX
// compliant systems as well as modern Windows perform the rename operation
// atomically, i.e. there is no point at which another process attempting to
// access the new path will find it missing.
$directory = $this->getContainingDirectoryFullPath($name);
$this->ensureDirectory($directory);
$full_path = $this->getFullPath($name, $directory, $mtime);
$result = rename($temporary_path, $full_path);

When the Drupal "Clear all caches" process is initiated, the php rename() function successfully renames the first temporary twig file in the sites->default->files->php->twig directory to the $full_path twig file name. Then for an unknown reason an error is thrown by the "internal" spprintf php function before the php rename() function can successfully return. The php_error "Fatal error: Illegal length modifier specified 'f'" message is generated on line 741 of the php spprintf.c function. I'm not sure what "Illegal length modifier specified 'f'" could be referring to in the spprintf.c file. Any insight into that matter would be appreciated.

fmt_error:
php_error(E_ERROR, "Illegal length modifier specified '%c' in s[np]printf call", *fmt);
/*
* The default case is for unrecognized %'s.
* We print %<char> to help the user identify what
* option is not understood.

https://github.com/php/php-src/blob/master/main/spprintf.c

When the error page is reloaded, the "Illegal length modifier specified" error is thrown again while renaming the next temporary twig file in the Drupal twig caching process. From what I can tell, the error is thrown while attempting to rename the first 8 twig files in Drupal twig caching process. On the 9th page load the rest of the twig files are renamed without any issues and the entire caching process is able to be completed.

I recored an error log showing which files fail to complete the php rename() function during the twig caching process.


system-config-form.html
temporary_path- sites/default/files/php/twig/.8QOnFg88NKKLp-gbk2qtY3LyAJc
full_path- sites/default/files/php/twig/5f12babce0515_system-config-form.html.t_TUsY6MT23t0UiObWO1AaiHU5F/lnHYlKAqsX1gmZ-8tnEP-xxeKAA3RPqSJZqcwVfOSno.php
PHP Fatal error:  Illegal length modifier specified 'f' in s[np]printf call in /home/public_html/core/lib/Drupal/Component/PhpStorage/MTimeProtectedFastFileStorage.php on line 90

input.html.twig
temporary_path- sites/default/files/php/twig/.LxriDhSzO_h3EELBUNKhdajsV_E
full_path- sites/default/files/php/twig/5f12babce0515_input.html.twig_Xi0HNf5GQEYMlze-Z5DeWiQoQ/rMaaTCvZnUUfjTzauRJ4dmjbW9Rbx1mpGSSg5kr9G9k.php
PHP Fatal error:  Illegal length modifier specified 'f' in s[np]printf call in /home/public_html/core/lib/Drupal/Component/PhpStorage/MTimeProtectedFastFileStorage.php on line 90

details.html.twig
temporary_path- sites/default/files/php/twig/.eXdgpJCxA3E5uwHDcbPTyMDNBC8
full_path- sites/default/files/php/twig/5f12babce0515_details.html.twig_TKmQQp1VVggoy51goISMXVVG4/bibIfpz13z9a4KjYA7799GCaQ0ACoHzkd-3F-1Ooom0.php
PHP Fatal error:  Illegal length modifier specified 'f' in s[np]printf call in /home/public_html/core/lib/Drupal/Component/PhpStorage/MTimeProtectedFastFileStorage.php on line 90

select.html.twig
temporary_path- sites/default/files/php/twig/.6Ika4LGPahSM3LNzLvs349rmxD4
full_path- sites/default/files/php/twig/5f12babce0515_select.html.twig_KQ7f2aANHl_XX7VHaphMdwFDV/8A3b6yVb-zleWEYbHAIunqLENkK92ymdeeNPPbnBSgg.php
PHP Fatal error:  Illegal length modifier specified 'f' in s[np]printf call in /home/public_html/core/lib/Drupal/Component/PhpStorage/MTimeProtectedFastFileStorage.php on line 90

form-element.html.twig
temporary_path- sites/default/files/php/twig/.QL7KeZUIZa_lvKlNs2jIoGyI0Ao
full_path- sites/default/files/php/twig/5f12babce0515_form-element.html.twig_EA3goqsDkggXS0JqKiVCs8BaU/m5Xdh0CaJdqHO3MGkHfiYdxngo5fFpIF4jItWizRETA.php
PHP Fatal error:  Illegal length modifier specified 'f' in s[np]printf call in /home/public_html/core/lib/Drupal/Component/PhpStorage/MTimeProtectedFastFileStorage.php on line 90

form-element-label.html
temporary_path- sites/default/files/php/twig/.auHWfTkyP4Hk_8bhZnD25NbNoBo
full_path- sites/default/files/php/twig/5f12babce0515_form-element-label.html.t_FMJOqVzOPDu3yMS1H9orCG5Hd/hprJjm9oceNwYoH7sBKtbjm7c7tsFxZIMSvw2yhq54A.php
PHP Fatal error:  Illegal length modifier specified 'f' in s[np]printf call in /home/public_html/core/lib/Drupal/Component/PhpStorage/MTimeProtectedFastFileStorage.php on line 90

container.html.twig
temporary_path- sites/default/files/php/twig/.9gb5Xp0Ny3884Zfj4OsmstVamaE
full_path- sites/default/files/php/twig/5f12babce0515_container.html.twig_Nb3VSOiSzmY_QZJ4tK339NmWO/c4qeM0Llf4A1r-mjnLoF4OpubDFbbEgtN7BoLQRREqM.php
PHP Fatal error:  Illegal length modifier specified 'f' in s[np]printf call in /home/public_html/core/lib/Drupal/Component/PhpStorage/MTimeProtectedFastFileStorage.php on line 90

form.html.twig
temporary_path- sites/default/files/php/twig/.Id95UkxkdDVdpLdpsvcjUd5pxfs
full_path- sites/default/files/php/twig/5f12babce0515_form.html.twig_3UYx53zgmjZlaFXcjn6HLB-DU/H690N0-gbcYNybiJBWMax5hnu9K4nC8pOui4W_isrqg.php
PHP Fatal error:  Illegal length modifier specified 'f' in s[np]printf call in /home/public_html/core/lib/Drupal/Component/PhpStorage/MTimeProtectedFastFileStorage.php on line 90

html.html.twig
temporary_path- sites/default/files/php/twig/.xikXLecbXzO75IZFcLLVI6HhjI8
full_path- sites/default/files/php/twig/5f12babce0515_html.html.twig_cQ0HsWsQXe9HHLeSTOe4-SdV9/nXnMsZ2xjSagwOQtf1SwrZvNE4t7dhj3xEV1ECqJkAk.php

menu--toolbar.html.twig
temporary_path- sites/default/files/php/twig/.0Q2l6AiIeZwUyVIArgRcp9-Z0RE
full_path- sites/default/files/php/twig/5f12babce0515_menu--toolbar.html.twig_ryiLfeBwamQ995sfMrRF7ZmR8/6j3S5e4qZJ5-LaU0OXm3Aplha454m1MZc_JcwvvOnGc.php

toolbar.html.twig
temporary_path- sites/default/files/php/twig/.DtrngCJImBfTPhXPNJGxLxBsvqA
full_path- sites/default/files/php/twig/5f12babce0515_toolbar.html.twig_4iriJAeHfddn0coPE3KM9X7VR/sA_RX0I5ivFfsX5mOX3GnqmBNvdL8zDlZXFo_qkgl1M.php

page.html.twig
temporary_path- sites/default/files/php/twig/.NflPhvu17q26Ne3R1-bV1T3qbGw
full_path- sites/default/files/php/twig/5f12babce0515_page.html.twig_mT6oXRMXjgFo7s2EfEKF6cWkC/hf089WL0dzl4m4DgOESOhfGnGz3v2_JeHWBC0xkmWEs.php

block.html.twig
temporary_path- sites/default/files/php/twig/.cPKdWyO7FALco75rQBT5KPJ6i70
full_path- sites/default/files/php/twig/5f12babce0515_block.html.twig_D4TEY2uh7S_sf57JQPb78G9PC/IsZtIaSTOMRaJPXt8ZHNUXz7klElh0ZsbqZHF1FPorM.php

page-title.html.twig
temporary_path- sites/default/files/php/twig/.YWsXNOGzsxbamG05VqeoQj0_8NA
full_path- sites/default/files/php/twig/5f12babce0515_page-title.html.twig_ZVwaPw0bjY-r2TU_0l_ydm4XS/Ut2hGKZjUc4VSnRc2gKKDyC5IBD4LM63MtXn5_jW7ck.php

region.html.twig
temporary_path- sites/default/files/php/twig/.R6TpLTekLV4g8z5AYN1RexPOw_E
full_path- sites/default/files/php/twig/5f12babce0515_region.html.twig_LJArt82XlLlmiPNAWBSabDd60/O5pdrDGlbCrXzc2DLhra7M2h5q622y2gGjo2UI-F54U.php

breadcrumb.html.twig
temporary_path- sites/default/files/php/twig/.YETIiTyvsa63QpKihOCvFVYLP9c
full_path- sites/default/files/php/twig/5f12babce0515_breadcrumb.html.twig_MEv5qfairfoCQmfPYwnsp7uGN/r7nntd5OLyI4AsQegzezRkGOhdlVQHkoGAnpLmRVVm8.php

block--system-messages
temporary_path- sites/default/files/php/twig/.Qv2UryD4nKs9uBdpya3fffDP-pk
full_path- sites/default/files/php/twig/5f12babce0515_block--system-messages-bl_KpPTZucpN0c4N7IX9WgAk3qtD/wTw794Y1QA44bTH6tbnu3mQ1hTMDNO6BFFZMv_sOicc.php

off-canvas-page-wrapper
temporary_path- sites/default/files/php/twig/.frl1-N_dBNUD8ROpVjd5-0lkHqc
full_path- sites/default/files/php/twig/5f12babce0515_off-canvas-page-wrapper.h_All6Y7Nf-xrkc_7a_xAKIhaUc/uv_M7YG8zfqtsNe95PHXTdxnMDOd-27mmmo_7FbsqV0.php

links.html.twig
temporary_path- sites/default/files/php/twig/.HjkoU9Aaa41uAHoNjlT3wUB6xko
full_path- sites/default/files/php/twig/5f12babce0515_links.html.twig_6vChyA8xl-TxZN4cYpzAMnvAt/q8qgpMgVd_YEnC153dEJpWsFuifuyI4foBYd7KKoPuA.php

status-messages.html.twig
temporary_path- sites/default/files/php/twig/.IV3k4JBjisuNpshrmj26mmyfITo
full_path- sites/default/files/php/twig/5f12babce0515_status-messages.html.twig_WVajP5MGUAzjNK5jWM6APgthm/Ma9bldKO56BPa7tmValqVgQcqlt1_7KG3_4VS6--8yQ.php

I am using shared hosting and PHP 7.3. I do not believe the issue has anything to do with file character length, illegal characters, or file permissions. I'm not sure how to test internal php errors.

I have set up a subdomain with admin and FTP access to a new Drupal 8.9.2 install where the error is easily reproduced. I'm not sure the best way to go about this, but I am willing to give someone access and compensate them for their time if they think they can get to the bottom of this issue.

brainiacque’s picture

@digitill do you use composer to manage your site?

apaderno’s picture

It's an internal PHP error. As @longwave said, rename() internally calls sprintf(). It's not an error caused from Drupal.

longwave’s picture

For anyone who can reproduce this, I wonder if your host has compiled PHP themselves, and perhaps modified it in a way that causes this error? What is the full PHP version string from either the status report or php -v? If you have the option to change to a different PHP version, does that make any difference?

brainiacque’s picture

My host has me on PHP 7.3.20. I've tried switching PHP versions and it doesn't make a difference.

Digitill’s picture

Digitill’s picture

@brainiacque I am using a Linux shared hosting environment with WebHostingHub. They do not allow SSH access to their shared hosting accounts so I do not have a way to install and run composer as far as I know. I am experiencing this issue on a new Drupal 8.9.2 install. I have talked with my hosting support people and they told me it's a "coding" issue since it only happens with Drupal so they won't help me. I have never experienced an internal php error before and I think they are pretty rare. I feel like I am stuck between a rock and a hard place because my hosting company won't help and technically this is a php error, but it only happens with Drupal 8. My hosting company also doesn't currently meet the requirement for Drupal 9 so if I can't find someone that I can pay to figure out this problem for me I'm either going to have to abandon Drupal or switch hosting companies, neither of which I want to do.

apaderno’s picture

It's not an error specific to Drupal. Googling, it's possible to find Constant Contact Forms for WordPress V 1.82 fatal error which is about a similar error in WordPress.

Error log: PHP Fatal error: Illegal length modifier specified ‘f’ in s[np]printf call in /home/custo451/public_html/wp-content/plugins/constant-contact-forms/vendor/guzzlehttp/streams/src/StreamInterface.php on line 7

There is also Prestashop 1.7.6.4 error loading page where the reported error is the following one.

Fatal error: Illegal length modifier specified 'f' in s[np]printf call in /public_html/vendor/symfony/symfony/src/Symfony/Component/Config/Definition/Builder/NodeParentInterface.php on line 19

longwave’s picture

The WordPress issue linked also mentions WebHostingHub as the host.

brainiacque’s picture

I think I may have some hope for us. As of 11:30 AM ET, my web host allowed me to get PHP 7.4.8 and I haven't experienced this error any more. I'll do more testing to see if it happens again and report back to the group.

Digitill’s picture

I can confirm that switching to PHP 7.4.8 does seem to have solved this issue. I wish I knew what the issue was and I hope it doesn't come back, but everything seems to be working fine for me with PHP 7.4.8.

fkelly12054@gmail.com’s picture

Wow! Spent literally days tracking this down. Replicated entire site over onto Wampserver/locallhost ... couldn't get the problem to re-occur there. Downgraded from 8.9.5 to 8.9.4 both locally and on shared hosting. Problem didn't happen locally, kept happening shared. Got PHP error reporting going on shared hosting site, found the error, searched here, found this thread, upgraded to 7.4 on shared and problem went away.

Problem is that the shared site appears to work normally for all non-admin tasks. Then a white screen when you go into certain admin tasks. Rebuild.php resets things temporarily but then a subset of admin tasks locks you out of admin with a white screen. Php error logging shows the culprit but many shared hosting sites don't have that turned on by default and you have to go spelunking through their help screens to figure it out.

Maybe this problem and the solution could be displayed prominently in the release notes or somewhere else on Drupal.org where people will see it? I will post it over in the Forums where people who aren't rummaging through issue queues may see it. Later: posted something in Forums.

Just wondering: could the issue title be changed to something like "locked out of admin (and other problems) because of PHP bugs when using PHP < 7.4" or something similar? It would make it easier for people searching the issue queue to determine where their problem is.

cilefen’s picture

Title: Illegal length modifier specified 'f' in s[np]printf call on rename() in MTimeProtectedFastFileStorage » [PHP bug] Illegal length modifier specified 'f' in s[np]printf call on rename() in MTimeProtectedFastFileStorage
Category: Bug report » Support request
onewomanbiz’s picture

Thanks to everyone for sharing. I got the same error after updatng to Drupal 8.9.5 on a live site when I tried to login. At the same tiime, the site was still visible as normal. So I was surprised because the new version worked fine when I installed it on my local machine WAMP64 setup.

As others have posted, I was able to solve the problem on the production site by switching the site to PHP 7.4 . Then login as admin was sccessful.

TerraCoders’s picture

Same problem on Drupal 8.7.5; just wanted to note that the problem occurred at JustHost. As with most others, the move to PHP7.4 looks to have fixed the issue.

Peter Pulsifer’s picture

I had experienced this issue under php 7.2 and fixed it by switching to php 7.4. However, a couple of months later, it has just reappeared, I'm not sure if whether due to Drupal upgrade (now 8.9.13) or php upgrade (now 7.4.11). It is annoying, but it appears to be resolvable by reloading the page.

fkelly12054@gmail.com’s picture

Drupal 9.1.4 newly installed using Composer on shared web server. Using the database driver specified in:

https://www.drupal.org/project/mysql56

Since even after moving my files to a different web server in their complex (inmotionhosting) I am apparently not using a recent enough version of MariaDB. I've posted about version craziness over at the mysql56 project. But that seems to be patched over enough to get my installation to run.

Had to run
$ composer require drupal/mysql56

to get a recent enough driver. Installation runs. PHP version shown as 7.4.11 on installation requirements screen. Installation runs to apparent completion except winds up in a blank screen. PHP error log showing:

[26-Feb-2021 17:06:33 America/New_York] PHP Fatal error: Illegal length modifier specified 'f' in s[np]printf call in /home/fkelly5/public_html/fkellysite/web/core/lib/Drupal/Component/PhpStorage/MTimeProtectedFastFileStorage.php on line 88

The database is created successfully and can be viewed in PHPMYADMIN, so installation at least completed that. But, with the printf error I can't go further.

fkelly12054@gmail.com’s picture

Looking further at #23, I seems strange that I can run 9.1.4 without any problem on localhost/Wampserver but not on Inmotionhosting. Both installed with Composer. Wampserver has a more recent MYSQl version, but I seem to have overcome MYSQL issues on the hosting site. Only other difference I can see is that I have PHP 7.4.11 on hosting site and 7.4.6 on Wampserver. Wondering if they (PHP) re-introduced the bug in 7.4.11.

I'm running a lengthy file by file comparison on the two sites. May see if I can upgrade Wampserver to PHP 7.4.11 and if the bug reappears.

fkelly12054@gmail.com’s picture

Given the way that this problem keeps recurring with different versions of PHP just wondering if there might be a different way for Drupal to accomplish the goal of line 88 of MTimeProtectedFastFileStorage.php without using the rename function? Well beyond my expertise level to do anything beyond suggesting that.

quickfixerupper’s picture

For anyone looking for a workaround, open up /core/lib/Drupal/Component/PhpStorage/MTimeProtectedFastFileStorage.php, go to line 88, and replace this:

$result = rename($temporary_path, $full_path);

with this:

system('mv {$temporary_path} {$full_path}', $result);

Should work as intended, assuming your webhost lets you execute the system() method - mine did.

fkelly12054@gmail.com’s picture

Thanks @quickfixerupper. My composer based installation of 9.1.4 was returning unexpected error messages. I only had one instance of the sprintf related message in my PHP error log but any time I tried to access anything on the site I just got unexpected error with nothing in the logs. I put messages into index.php and into the various autoload files in both core and composer. I could see my site getting as far as bootstrap.inc but then dying. I'm guessing my initial installation "died" partway through. I don't know if it is a bug introduced in PHP 7.4.11 or something else.

I deleted everything from my new site. Reran composer install. Had to muck around through:

https://www.drupal.org/project/mysql56

to get a driver that would work with my hosting service. Some of the composer install instructions there did not work the first or second time. But eventually ...

So now my site is installed and working on 9.1.4. Shared hosting with different document roots for Drupal8(production) and Drupal9. Ability to use Composer on both.

I have no idea whether a bug in MimeProtectedFastFileStorage.php could foul up an installation so it is unusable. But applying the "fix" suggested in #26 seems to have me back in action after a full reinstall.

refman1073’s picture

I have this same problem. As I was preparing to move to another hosting provider I noticed that some tables and columns had collation setting as utf8mb4_0900_ai_ci, which the new provider does not support. I changed the collation on everything to utf8mb4_unicode_ci and the problem seems to be gone.

Since the problem is encountered moving the twig compiled files, I flushed the cache and as expected the files in files/php/twig were erased. Then visiting many pages, that directory was populated without error.

Hoping this is relevant :)

sjmethawee’s picture

For me looking for a workaround, open up /core/lib/Drupal/Component/PhpStorage/MTimeProtectedFastFileStorage.php, go to line 88, and replace this:

$result = rename($temporary_path, $full_path);

with this:

system('mv {$temporary_path} {$full_path}', $result);

It works as intended to apply the "fix" suggested in #26 too.

fkelly12054@gmail.com’s picture

I had the "fix" suggested in #25 and #29 working fine. Then did the security fix in 9.1.9 ... worked okay, and started on 9.1.10 today (6/5/2021). The bug mentioned in #19 reoccurred when I went to clear cache in preparation for moving the 9.1.10 set of files onto my site. PHP error log shows a bunch of these:

[05-Jun-2021 16:02:01 America/New_York] PHP Fatal error: Illegal length modifier specified 'f' in s[np]printf call in /home/fkelly5/public_html/drupal8/core/lib/Drupal/Component/PhpStorage/MTimeProtectedFastFileStorage.php on line 88

made the fix from #29. Can clear cache. I also "fixed" the replacement file in the Drupal 9.1.10 set of files since I don't want to dig myself back into this hole.

This is well beyond my salary grade or expertise level but maybe we should escalate the priority level and see if one of the committers can take a look.

cilefen’s picture

I agree with commenters there is unlikely a change in Drupal that would fix this, and it is rather a bug in PHP itself.

The best way forward is for someone to reproduce the error without Drupal by trying on similar filenames on affected platforms. #7 above depicts some example filenames. I suspect something about the filenames themselves exposes a bug in PHP's rename function, for example the following (from #7) should be reproducible on an affected platform:

<?php
rename('sites/default/files/php/twig/.8QOnFg88NKKLp-gbk2qtY3LyAJc', 'sites/default/files/php/twig/5f12babce0515_system-config-form.html.t_TUsY6MT23t0UiObWO1AaiHU5F/lnHYlKAqsX1gmZ-8tnEP-xxeKAA3RPqSJZqcwVfOSno.php');

It would be especially interesting if once reproduced, someone can figure out which part of those filename strings is responsible. If that can be found then possibly we could patch Drupal to work around this one.

Assuming it can, then the next step is to figure out if it is PHP version-related. If it is not reproducible on a newer PHP version then consult the PHP 7 changelog for likely fixes. As just an example, perhaps https://bugs.php.net/bug.php?id=77630, which involves rename, and was released on several PHP 7 versions, fixed it, (or causes it!).

If it is not PHP version-related the next place to look for clues is in how PHP was built on the platform. Compare the output of a working platform's phpinfo() with that of an affected platform.

Open a bug report on php.net with reproduction information if at that stage, there is no answer.

Further comments on this issue should address these points.

fkelly12054@gmail.com’s picture

For what it's worth, on my inmotionhosting shared server where I have the ability to use the Cpanel tool Multiphp to designate a PHP version for my public_html directory (where of course I run Drupal) I designate PHP7.4. The error still occurs. Looking further at phpinfo, I can determine that the full PHP version is 7.4.16. That is dated 04 Mar 2021. There have been several PHP "patches" since that:

7.4.18 29 -- Apr 2021
7.4.19 06 -- May 2021 (just one reversion)
7.4.29 -- 03 June 2021

Inmotionhosting hasn't gotten around to these last three. I don't see any silver bullets in that list of fixes.

If someone has this working properly on a specific PHP version (including the patch number) and someone else doesn't (as I don't on 7.4.16) that could be useful information to keep us from chasing our tails more than necessary.

Peter Pulsifer’s picture

I am in the same situation as fkelly, on an Inmotionhosting shared server. The problem pops up randomly, most recently just a few days ago. I haven't yet tried the system() patch in #26, #28, as I'd rather avoid system(), but I might resort to it.

Peter Pulsifer’s picture

I put in a logger before and after the rename() call at line 88, then cleared the cache. Got a blank white screen, which was resolved by reloading the page. The clicked on the "Extend" menu and got the error message "Illegal length modifier specified 'f' in s[np]printf call on rename() in MTimeProtectedFastFileStorage". The log message, which was not followed by a "successful rename" I(meaning that this is probably an operation that caused a problem), was

renaming sites/default/files/php/twig/.eHjkmL89jkn_HnM1RF0UNqWolV8 to sites/default/files/php/twig/60bd63d87edb2_system-modules-details.ht_4XG70mCUs6SEERGwA_CfvxFcL/6u0QVQLEUtj9LsQhom3HXocoDNbUwyXMo2Uta_0kZ60.php

After viewing recent log messages (to get the above message), clicked on "Extend" again and got the error message again. The log message was

renaming sites/default/files/php/twig/.eHjkmL89jkn_HnM1RF0UNqWolV8 to sites/default/files/php/twig/60bd63d87edb2_system-modules-details.ht_4XG70mCUs6SEERGwA_CfvxFcL/6u0QVQLEUtj9LsQhom3HXocoDNbUwyXMo2Uta_0kZ60.php

Repeated the process a third time, and the "Extend" page loaded properly.

My added logger records dozens of rename operations a minute. It is only a few that cause the fault.

fkelly12054@gmail.com’s picture

@digitill posted on Stackoverflow at:
https://stackoverflow.com/questions/61861990/illegal-length-modifier-spe...

and provides useful background.

One problem impeding resolution is that the error seems to be "buried" in an internal PHP function beneath the rename function. That function is spprintfc and the code for it is at:

https://github.com/php/php-src/blob/master/main/spprintf.c

I'm pretty sure that is still "operative" and is what is generating the errors we see intermittently. I'm not sure that the PHP version (within limits of 7.4.x up to 7.4.20 makes any difference. I can't get the error to reoccur on my Wampserver setup locally no matter what PHP version I use, but it happens regardless of PHP version (any 7.4.?) using the official Drupal code on my shared web hosting.

$result = rename($temporary_path, $full_path);
from MTimeProtectedFastFileStorage.php.

The rename function kicks off use of the spprintf.c file. As @Cifelen hints in #31, there may be something in one or more of the twig file names that is "confusing" spprintf.c about what the format is.

Ghost of Drupal Past’s picture

@Peter Pulsifer thanks that looks great.

Could you please run this Drupal independent script and see what happens?

$source = 'sites/default/files/php/twig/.eHjkmL89jkn_HnM1RF0UNqWolV8';
$dir = 'sites/default/files/php/twig/60bd63d87edb2_system-modules-details.ht_4XG70mCUs6SEERGwA_CfvxFcL';
file_put_contents($source, 'test');
@mkdir($dir);
rename($source, "$dir/6u0QVQLEUtj9LsQhom3HXocoDNbUwyXMo2Uta_0kZ60.php");

and see whether any error happens and whether the rename happens?

Edit: the reports in #14 are decidedly weird. Those are interfaces and yet PHP reports an error in them? You can't run code from an interface. That, and the weirdness and long time persistence of the issue suggests we are looking at a pointer which goes to somewhere it really should not and chasing this from userspace is hopeless. One of the reports quoted said there was a difference from 5.6 to 7.2 and here we see differences from 7.3 to 7.4. Smells like a heisenbug to me and those are lovely to debug. If an unusually enterprising soul happens to have unfetttered access to an environment where this occurs, I can recommend my brief post on how to use gdb with PHP. But let's see the script above first.

Peter Pulsifer’s picture

@Charlie ChX Negyesi I'm kind of sorry to say that the script worked as expected - no errors, and the rename was successful. I tried it with a couple of the other files that had failed the rename and one that succeeded, and in every case things went smoothly.

apaderno’s picture

@cilefen in comment #31 suggested to try the following script.

<?php
rename('sites/default/files/php/twig/.8QOnFg88NKKLp-gbk2qtY3LyAJc', 'sites/default/files/php/twig/5f12babce0515_system-config-form.html.t_TUsY6MT23t0UiObWO1AaiHU5F/lnHYlKAqsX1gmZ-8tnEP-xxeKAA3RPqSJZqcwVfOSno.php');

Probably it's a matter of finding the right filenames that cause the issue.

Ghost of Drupal Past’s picture

@Peter Pulsifier would you have the time for a chat some time? I am on Drupal Slack quite often. I have some ideas here but it's a bit complicated and iterations would be faster in chat.

fkelly12054@gmail.com’s picture

Per #38 "Probably it's a matter of finding the right filenames that cause the issue." I'm working on this but will be happy if someone else solves it first.

I'm not sure that the system MV fix last mentioned in #29 is "good". It alleviates the symptoms of the problem on my hosted system but the "hidden" (prepended with "." ) files that are created on a cache clear are stuffed in the same directory as the twig files. In other words under the directory "PHP/Twig" you get a series of files like this
S0c0b9d28f4fd stringjemplate d3e79b_vAW73yrG08N48GWsidtgadrmo
S0c0b9d28f4fd_admin-block-content.html._KU_8mgH0M348GMGKTP4hgo-C3
50c0b9d28f4fd_admin-block.html.twigJ3xPpD96ph8MakzlNS0DVOSCj
50c0b9d28f4fd_admin-page.html.twig_wOba8-mu3XUE4OWx_vYpT97ml

followed by the hidden files in the same /php/twig directory such as:

.0H7hNBr16WxhtQzMTHRISk6sM o
.ON-GGO-gxlkFvPOE4DzuLb_dHRc
.21E1X1rDblN3l7XEOe-vyhZCL4k
.2MexXlo34MvUXZp_VxxPR-8LpFc

where each of those files has a . in front of it (hidden).

In the official Drupal code, using the PHP rename function, the hidden files are in separate directories corresponding to the twig file they "correspond" to.

When I restore the "official" rename version of the code the hidden files are created in the "right" place (i.e., directory) but at some point the PHP rename error kicks in and I get a white screen. I'm trying to capture the exact point where that happens (which file is causing the problem).

Perhaps different themes generate twig file names differently and one or more is doing it improperly? This might explain why the error occurs so sporadically.

I will keep working at it ... I don't have a very sophisticated (obviously) diagnostic framework and can't get the problem to happen on my local Wampserver sites so I have to simulate it on my live site.

fkelly12054@gmail.com’s picture

Tried a little experiment. On my Wampserver, virtual host the rename function has always worked reliably. Trying to see if any file names were causing rename to choke, I backed up the php/twig directory on local site and downloaded a copy of the default/files/php/twig directory from my inmotionahosting site (production) to the local default/files/php/twig.

On local Wampserver using php 7.4.20 rename works fine. On inmotionhosting with php 7.4.16 it generates the sprintf error and white screens reliably when I do performance/clear cache.

I don't think PHP versions are causing this. There haven't been any recent changes to the rename function that I can find. But then the same exact set of files run through the rename function on Wampserver but not on inmotionhosting. In the Wampserver version clearing cache even cleared up the "problem" I mentioned in #40 where the system mv command puts the hidden (prefixed with ".") files at the same directory level as the twig files.

Could be that hosting services are doing something strange in setting up PHP for shared hosting sites? This could account for the sporadic nature of the error reports on this.

fkelly12054@gmail.com’s picture

After going down (what for my skill level) is a rabbit hole trying to determine which file might be causing the PHP sprintf error for a while, I started to question:

does Drupal really need to use the seemingly unreliable PHP rename function here?

If I go into my disposable Wampserver local site and just use file manager to delete everything in the PHP/twig directory, Drupal rebuilds it on the next page load. There are also cache clearing commands in the core.api.php program that don't require rename. Could core take an alternate approach? As far as I can tell "rename" is only used once in the whole of Drupal. Could we make it zero?

For what it's worth I copied the entire PHP/twig directory over to my Wampserver local site (so same files). The error occurs reliably on shared hosting and never on Wampserver. Yeah, it could be something in how Inmotionhosting set up PHP but figuring that out is just guesswork and not something we (poor shared hosting users) have much control over. I don't think the error is PHP version related: I've used several versions on Wampserver without hitting the error.

cilefen’s picture

@fkelly Understood, but as far as I know rename is a bog-standard PHP function, not known for being particularly unreliable. This issue here IMO certainly points to a bug in it, and it would be nice to reproduce it with plain PHP.

FWIW the Wampserver environment is going to be only superficially similar to production hosting setups. I've asked but no one has yet provided a phpinfo() diff between a working and a broken environment, nor has anyone tried the reproduction script in isolation of Drupal. It would be nice.

fkelly12054@gmail.com’s picture

FileSize
33.69 KB
32.88 KB
fkelly12054@gmail.com’s picture

@cifelen ... not sure how you would do a diff on the files I just uploaded. I can compare them side by side using Beyond Compare on my Windows machine but don't know how to assess whether any of the settings could be causing problems. The in_motion file is from my shared server at Inmotionhosting. The "wamp" file is from my local Wampserver. I don't know how you would work "backwards" from these to infer which setting(s) could cause problems with PHP rename.

I know that the Drupal core developers are up to their eyeballs. But I wish someone could just step back and look at what we are trying to do here. It seems like what is happening is that we want to store a bunch of twig files in the file system so they don't have to be regenerated on each page load. Since the code behind them can change we might want to periodically regenerate those twig files, which would follow a cache clear of the PHP/TWIG directory. If I manually just delete the files there, they get regenerated by Drupal automatically ... as far as I can see. Could this not be accomplished by some other means?

I will try to see if I can isolate one or more files that are causing the PHP error. (Is there no way to "catch" the error and report back the file causing it rather then terminating the request with a white screen?). One problem I that I tried the same "set" of files on Wampserver that I was running on my production shared server. No errors on Wampserver, white screen on Inmotion. I want to confirm this with a new set of files now that I have 9.2 running both places.

longwave’s picture

The inmotionhosting output mentions at least two third party PHP extensions, I wonder if one of these is the issue:

1. IonCube24 - https://ioncube24.com/

ionCube Loader
ionCube logo ionCube24 logo
ionCube Loader developed by ionCube Ltd.
Visit ioncube.com for latest Loaders and support.
This Loader also includes features for real-time error reporting and malware protection. Visit ioncube24.com for more details.

2. Monarx - https://www.monarx.com/

monarxprotect
monarxprotect  enabled
Version   4.2.56

This is somewhat of a guess, but both of these claim to provide "PHP malware protection" - I wonder if somehow they are hooking into rename() and other filesystem functions to detect malware, and somehow this is triggering this bug?

It would be interesting to see if these extensions are also present on other hosting environments that are triggering this bug.

fkelly12054@gmail.com’s picture

FileSize
38.44 KB

Thanks @longwave. If it is of any interest I uploaded the PHP 7.4 ini file that's in use. You'll see a "do not edit" warning at the top so I'm not sure which settings I can change. I will be happy to talk to tech support at Inmotionhosting if you see any "red flags" or have any suggestions about what changes we should try.

apaderno’s picture

@fkelly Does inmotion allow you to enable/disable PHP extensions? The .ini file says it should be done via cPanel MultiPHP INI Editor, so I guess it should be available.
I will see if I can test this on the hosting I am using, as it allows me to enable PHP extensions, which include also ioCube Loader.

Does the following code work too for testing the issue?

rename('.8QOnFg88NKKLp-gbk2qtY3LyAJc', '5f12babce0515_system-config-form.html.t_TUsY6MT23t0UiObWO1AaiHU5F/lnHYlKAqsX1gmZ-8tnEP-xxeKAA3RPqSJZqcwVfOSno.php');

Differently from the code shown in comment #31 it renames a file in the current directory.

Basing on the description for the ioCube Loader extension I read in cPanel, I take longwave could be right.

Introduces tools to protect software written using the PHP programming language from being viewed, changed, and run on unlicensed computers

It seems plausible that renaming a file and adding the extension for PHP files is seen as a tentative to change PHP software.

apaderno’s picture

Unfortunately, my test didn't work. The hosting I am using allows me to enable the ioCube Loader extension, but it sets the ic24.enable directive to 0, and it doesn't allow me to change that value.

fkelly12054@gmail.com’s picture

@kiamlaluno ... I will have to look at a couple of your suggestions later. Unfortunately, as I mentioned in #40 using the System and MV commands in place of rename seems to put the generated files in an "incorrect" directory structure. Going back to the official rename code results in a partial generation of the correct structure but then a bunch of sprintf errors and white screens.

I am trying to get your code to work. Drupal and htaccess prevent it from being run from sites/default/files/php/twig of course. So I created files and the rename test program in my "root" directory. Rename running from there but files not being found right now. I'll be back to it. Out of time right now.

I'll check on what I can enable and disable from the multi-php ini file editor. There are two versions of the editor: a light and a more detailed one. They have warnings about not changing the more detailed one. If I can disable IconCube as a test, I will.

Ghost of Drupal Past’s picture

Note you can always switch to a much less secure PHP storage with something like $settings['php_storage']['default']= 'core/lib/Drupal/Component/PhpStorage/FileStorage.php'. While it is not in itself a security hole, it increases the chances of a remote code execution hole seriously.

I'd like to quote https://www.drupal.org/docs/system-requirements/php-requirements

Drupal is designed to work with PHP as distributed on PHP.net. Every effort is made to make it work with PHP versions from other sources but this is only done on a best effort basis. In particular, Suhosin is known to break certain features; and some operating systems move core components into other packages.

My advice at this juncture would be to add monarxprotect there and close this issue.

fkelly12054@gmail.com’s picture

Responding to #48 ... I can see that both Ioncube and Monarx are active from the phpinfo file. However none of the ini files or methods of changing ini files give me any access to inactivate them. The directories where their respective ini files are stored are not accessible to a shared hosting user. I suspect Inmotion wants these running on all shared hosting sites, but I can confirm with them next week. Since we don't know whether they are causing the problem I'd be reluctant to pound too hard on the table. It would be interesting to know if sites on other hosting sites than Inmotion are having the rename problem and whether sites running either or both Monarx and Ioncube are avoiding the problem.

Responding to #51, I suppose that if changing the settings file to point to PhpStorage/FileStorage is the only way to make the rename problem go away it's worth looking at. I think this needs more discussion before the issue is closed.

I haven't been able to get the code suggested in #48 running properly to test the rename issue. It can't find the file(s) I'm trying to rename. I will keep working at it. Found it: PHP wants oldname first then newname. Idiot! I can get it running now and will.

longwave’s picture

As these extensions are security related it is unlikely the host will let you disable them.

Hostmonster and WebHostingHub were mentioned earlier in this thread as other hosts that suffer from this issue. It would be great if someone who uses one of these can get phpinfo output so we can compare with inmotionhosting.

apaderno’s picture

Note that the code I shown in comment #48 moves the files in a sub-directory (5f12babce0515_system-config-form.html.t_TUsY6MT23t0UiObWO1AaiHU5F) which must exist for the code to work.

A more complete code would be similar to the following one.

<?php
$file = '.8QOnFg88NKKLp-gbk2qtY3LyAJc';
$subDir = '5f12babce0515_system-config-form.html.t_TUsY6MT23t0UiObWO1AaiHU5F';
$newFilename = 'lnHYlKAqsX1gmZ-8tnEP-xxeKAA3RPqSJZqcwVfOSno.php';

if (!is_directory($file) && !is_file($subDir)) {
  $fh = fopen($file, 'w')) or die('Unable to write file.');
  $count = fwrite($fh, '<?php phpinfo(); >?');
  fclose($fh);
  if (!$count) {
    die('Unable to write file.');
  }
  if (!file_exists($subDir)) {
    mkdir($subDir) or die('Unable to find sub-directory.');
  }
  if (file_exists("$subDir/$newFilename")) {
    is_file("$subDir/$newFilename") or die("Unable to rename $file to $subDir/$newFilename: There is already a directory with that name.");
    unlink("$subDir/$newFilename") or die("Unable to delete $subDir/$newFilename.");
  }
  rename($file, "$subDir/$newFilename");
}

Probably the code is too self-protective, but it can run multiple times, as it doesn't require to manually create directories or delete the renamed file.

fkelly12054@gmail.com’s picture

Thanks @Kiamaluno. I made a couple of adjustments and can get the PHP rename function to run on my Inmotion Host. In other words I can rename a file named "abc" to "def" and even "nHYlKAqsX1gmZ-8tnEP-xxeKAA3RPqSJZqcwVfOSno.php' to nHYlKAqsX1gmZ-8tnEP-xxeKAA3RPqSJZqcwVfOSNO.php'. That eliminates at least one extreme hypothesis (PHP rename not working at all on Inmotion).

The adjusted code is quoted here:

$file = '.8QOnFg88NKKLp-gbk2qtY3LyAJc';
$subDir = '5f12babce0515_system-config-form.html.t_TUsY6MT23t0UiObWO1AaiHU5F';
$newFilename = 'lnHYlKAqsX1gmZ-8tnEP-xxeKAA3RPqSJZqcwVfOSno.php';

if (!is_dir($file) && !is_file($subDir)) {
  $fh = fopen($file, 'w') or die('Unable to write file.');
  $count = fwrite($fh, '<?php phpinfo(); >?');
  fclose($fh);
  if (!$count) {
    die('Unable to write file.');
  }
  if (!file_exists($subDir)) {
    mkdir($subDir) or die('Unable to find sub-directory.');
  }
  if (file_exists("$subDir/$newFilename")) {
    if(is_file("$subDir/$newFilename") or die("Unable to rename $file to $subDir/$newFilename: There is already a directory with that name.")) {
    unlink("$subDir/$newFilename") or die("Unable to delete $subDir/$newFilename.");
  }
  }
  echo $subDir . ' ' . $newFilename;
  rename($file, "$subDir/$newFilename");
}

The adjustments were that is_directory should be is_dir and there is a needed extra if statement down after if(file_exists) ... (I think). Also and extra echo down at the bottom just to remind myself which subdir and newFilename I am processing.

Working on this I have confirmed once again that the "official" (MtimeProtectedFastFileStorage) code with the rename function in use on Inmotionhosting is truly borked. I'm not saying that Drupal causes this or PHP causes it or some PHP add-on that Inmotion uses causes it ... I don't know. I do know that if I run the official code and clear cache my PHP/twig directory gets severely truncated after the first time the rename function fails. It gets built up again quickly just by running normal Drupal functions (i.e., using the web site) until you come in and do a cache clear again.

Just speculation but maybe the Ioncube and/or Monarx security add ons don't like the strange file names we create in the twig directory and trigger some type of error in the PHP rename function. But that's speculation.

Once I get this code working fully I will get back to seeing if I can track down which exact filenames are causing the PHP rename error.

fkelly12054@gmail.com’s picture

New to this so doing some reading to get up to speed. It looks like this general issue was active 6 years ago, then resolved with a commit fairly early in the Drupal 8 life cycle.

see in particular: https://www.drupal.org/project/drupal/issues/2527478 ... Resolve infinite stampede in mtime protected PHP storage and it's parent issue: https://www.drupal.org/project/drupal/issues/2547827 ... PhpStorage: past, present and future. Not recommending that anyone go digging back through those discussions but take a look at #15 in issue 2527478. The author asks if the return value of the rename operation should not be checked. I don't see any resolution to that suggestion. I've pondered it too. I know that the failing sprintf function is off in a PHP function, but is there no way we can detect and log (beyond just a PHP error that terminates the process) what file or files are failing to be renamed)?

Right now I'm attempting (based on Cifelen's suggestion in #31 to write a program that would iteratively try to rename a bunch of file copied from the PHP/Twig directory to see if any of the file names cause a problem with PHP rename. Initial indications are that PHP rename works just fine on my Hosting Service outside of Drupal.

And just to check something that was suggested in #54 -- we should not be ever want to rename a file to a new "hidden" file with a . prefix would we? If I understand the code properly that is just a temporary step to keep the temporary file from being viewable while the cache clear is completing? For example I have a file:

"60d0e8f7ea539_system-config-form.html.t_iksJ7HWD1WcPo5CcTJzgyoqWN\9rZcbi8GR-W4YcEIm9kAm2FAWpzMjIl2z_f1akk2Qjo.php"
before clearing cache. I wouldn't want to rename it to ".9rZcbi8GR-W4YcEIm9kAm2FAWpzMjIl2z_f1akk2Qjo.php"? Probably not a good idea to rename it to the prior file name either 9rZcbi8GR-W4YcEIm9kAm2FAWpzMjIl2z_f1akk2Qjo.php. Just change one character arbitrarily. ??

Which raises another question: seems to me that the reason more of these problems are not being reported is because Drupal does a good job of rebuilding the PHP/twig directory anyway. I can delete everything in it and with a few page loads in my site have it rebuilt. Would it be possible to delete everything on a cache clear and rely on Drupal to rebuild it?

Ghost of Drupal Past’s picture

I reached out to webhostinghub

IonCube24 is installed and runs on all php version currently available, however monarxprotect is not installed. That would require a VPS plan.

As prestashop and moodle reported the same bug, to me it seems obvious there's no Drupal bug to be found and this is on the C side of the fence. I raised the issue with ioncube, my ticket ID is #QAK-982-12262.

fkelly12054@gmail.com’s picture

Re. #57 ... I looked for your ticket but can't find it on Ioncube web site. I can get into their forums and found this (which also gives others here a link to the Ioncube forms generally)

https://forum.ioncube.com/viewtopic.php?t=4624&highlight=rename

I posted the following:

"Working on a Drupal site. There is a program that renames a bunch of PHP files that are used for caching TWIG programs.

The program works fine on most servers and on a my local wampserver. However, it generates PHP errors intermittently when the PHP rename function is called. The files it is renaming are PHP files. Just wondering if having these files encoded could be causing the rename function to fail.

In my PHPinfo file on my localhost wampserver, while it says IONCUBE 10.4.5 is loaded none of the directives are set (e.g., ic24.sec.block_uploaded_files). On my hosted site (inmotionhosting) on a shared server there are a dozen directives set ... but the host determines these settings. "

As you'll note I have the Ioncube loader working on Wampserver with PHP 7.4.20. MTimeProtectedFastFileStorage seems to run just fine on my Wampserver site. The PHP files get renamed and the modified time for them changes. On Inmotionhosting this is not true.

fkelly12054@gmail.com’s picture

Following on #58 I am contacting IONCUBE support to find out how I can set up directives on Wampserver that are identical to those that show up in the IONCUBE section of PHPinfo on Inmotionhosting.

ic24.api.log_msg_errors 0 0
ic24.api.max_timeout 7 7
ic24.api_access_key ******** ********
ic24.api_check_ip 1 1
ic24.enable 0 0
ic24.home_dir no value no value
ic24.phperr.enable auto auto
ic24.phperr.ignore 0 0
ic24.sec.block_stdin 1 1
ic24.sec.block_uploaded_files 1 1
ic24.sec.enable auto auto
ic24.sec.exclusion_key ******** ********
ic24.sec.initial_action block block
ic24.sec.initial_cache_all 1 1
ic24.sec.initial_notify always always
ic24.sec.initial_state 1 1
ic24.sec.stop_on_error 1 1
ic24.sec.trusted_include_paths ******** ********
ic24.slt 7 7
ic24.update_domains_retry_interval 30 30
ioncube.loader.encoded_paths no value no value

We don't know that IONCUBE is causing the PHP rename problem ... it's just a hypothesis at this point. If other sites are running Ioncube with similar settings and not getting errors on rename this would tend to invalidate the hypothesis.

Of course someone on shared hosting who is NOT having this problem is probably not looking in this thread.

fkelly12054@gmail.com’s picture

Here is correspondence from IONCUBE tech support:

You wrote that: "So, essentially (as I understand it) the file contents get sent to the PHP function where it tries to deduce a format string."

If the Twig files have the .php extension then they will be encoded. However, they are not pure PHP files which is why they have to be read and interpreted for constructs such as {{ var }}. That obviously is quite hopeless with encoded files as the source PHP code no longer exists.

This situation is very similar to that with Laravel and its Blade template files which also have the PHP extension despite not being pure PHP. We have a blog article about that at https://blog.ioncube.com/2016/12/19/ioncube-encoding-laravel-project-con...

A brief summary of that artcle is that the template files must be encrypted rather than encoded using the Encoder's encryption feature for non-PHP files. Then the files can only be decrypted by using the ioncube_read_file function from an encoded file. Thus in your case you will have to modify the code that reads the Twig templates in to use ioncube_read_file and, also, that file that uses ioncube_read_file must be encoded also.

I thought at first that this might be helpful with the problem underlying this issue. But, it appears to me that the files we are trying to rename are truly PHP files, not template files that could be problematic. I will send a sample to IONCUBE for verification.

I'm not sure that there is any advantage to have Drupal PHP files encoded in the first instance. They are open source and freely available. But shared hosting such as Inmotion basically applies IONCUBE encoding to all sites. I'm not sure they would make an exception. I'm going to try to find out more about how encoding is applied and whether there is a way to except our files from it. This may not be relevant to solving this issue.

If anyone here who has more expertise with Drupal than I (which I think is just about everyone) wants to jump in, you are welcome.

fkelly12054@gmail.com’s picture

I sent one of Drupal's PHP files from the the PHP/twig directory on to IONCUBE, who have raised additional questions that go well beyond my expertise level. They have asked that I not post their responses here without permission. I'm trying to get that.

Let's just say that it looks possible that IONCUBE encoding could be causing a problem. But we need someone from the Drupal side who is well above my expertise level to be involved. @Charlie ChX Negyesi ... have you received a response to your Ioncube ticket. One user cannot access another user's ticket on Ioncube ... which is understandable.

I'm going to check with Inmotionhosting to see if I can get Ioncube turned off for my site (or at least for the PHP/twig directory). I doubt it but I'll check.

Ghost of Drupal Past’s picture

Can we try #36 again but instead of 'test' , could we copy an actual twig compiled file? so

file_put_contents($source, file_get_contents('path/to/some/compiled/twig/file'));

fkelly12054@gmail.com’s picture

Re. Ioncube: I have the loader working on Wamp and have downloaded and installed the Encoder. The Encoder gives a lot of options on which files in your Drupal distribution get encoded. You basically use your installed Drupal version as the "source" and set up a project with a target directory (and of course subdirectories). I can get a Wamp based site running but keep encountering Drupal errors at various points.
So, I am experimenting with excluding directories: for instance not encoding the vendor directories at all. Thus, you can run with a mix of encoded files and copied (non-encoded) files. I have a two week test period with the Encoder.

I can't tell from my shared (Inmotion) site which directories and files they have chosen to Encode. I will talk to their tech support next week. I'm going to see if I can get IONCUBE turned off entirely for my site ... I doubt it. I do think that they should at least tell us how Ioncube is set up ... what they've encoded and what they haven't. Without that info. I can't really replicate the Inmotion setup on Wamp.

Big picture: I think it may be a really bad idea to try to encode a Drupal site with Ioncube. I could see us coming out of this with a Drupal requirement to not encode your darned files. From what I know, I don't see the Drupal committers agreeing to modify Drupal code to make it work with Ioncube encoded files. But that's getting at least a week ahead of myself.

fkelly12054@gmail.com’s picture

Working forward with the IONCUBE free test encoder I was able to get a localhost (Wampserver) site installed. You just can't IONCUBE encode the whole Drupal (or Vendor) ... you get installation errors which I haven't the slightest interest in tracking down. But I did manage to get the sites/PHP/twig directory set up with IONCUBE encoded PHP files. And I could move around and test the site.

I was working off the hypothesis that maybe the PHP rename function would not work on an IONCUBE encoded PHP file. That doesn't seem to be true. PHP Rename seems to rename them okay. I even put a test for the value of $result on the rename function and it turns out to be 1 (or True).

Whatever you do within Drupal, somewhere in it's bowels, seems to self-cure by replacing the PHP files in the PHP/twig directory with non-IONCUBE encoded files (i.e.) normal PHP files.

I'm going to check with Inmotionhosting and see how they have things set up ... or how much they will tell me.

I think that the "self-curing" nature of the Drupal code ... a new set of PHP/TWIG files seems to get created even if the rename function causes errors ... maybe why this is not getting attention as a critical error.

And, though I've mentioned it before: while the system MV command that is suggested as a work around does eliminate the PHP rename errors, it is putting the hidden files in the wrong place. I'm using the work around but the real solution is to fix the underlying problem. But to fix the underlying problem we need to nail down what it is. I can run the PHP rename command successfully outside of Drupal (on Inmotionhosting) and even with files with names such as those in the PHP/twig directory. But it causes errors within Drupal.

fkelly12054@gmail.com’s picture

Just continuing the glacial pace of "progress" on this. I can create IONCUBE encoded php files locally. They run fine on Wamp. If I put a bunch in the php/twig directory, the cache clear (thus the PHP rename function) works to rename the files to a new set of plain PHP files.

If I copy one of the IONCUBE encoded PHP files to my Inmotion host (outside of Drupal) and then run a simple rename script on it, rename works just fine. The file contents are not changed ... just the name of the file. Thinking twice about it, that's the way it should be: PHP rename should not be mucking about with file contents.

This still leaves completely open the question of why PHP rename is failing on a certain group of shared hosts.

fkelly12054@gmail.com’s picture

Just want to post this link:

https://drupal.stackexchange.com/questions/201705/some-templates-are-not...

IN particular:

"If the template name is too long, which can easily happen with theme suggestions, it will cause PHP to fail to perform the rename() operation successfully. I don't know why it stores the code in a temporary file and then it copies it into target directory instead of creating it directly in the target directory and/or file but that's how it is."

I'm still trying to figure out a reliable way to figure out which files are failing on rename. I think we've more or less ruled out it being a matter of the contents of the file.

cilefen’s picture

I think that issue affected Windows and that we fixed it in https://www.drupal.org/project/drupal/issues/2606772

fkelly12054@gmail.com’s picture

@cifelen ... you may well be right. But we still need to figure out which files are failing on rename. My attempts to "debug" this on a local Wampserver are getting nowhere since I can't get the error to reproduce there. It only happens on shared web hosting ... in my case Inmotion. Inmotion lets me have a second domain so I spent this morning setting up a test site. I've been meaning to test a composer install on shared hosting (Composer 2 makes that possible). That worked well using the spare database Inmotion allows. Got to the Drupal install screen and through most of the steps when I got a white screen. Sure enough: the
"[18-Jul-2021 10:59:03 America/New_York] PHP Fatal error: Illegal length modifier specified 'f' in s[np]printf call in /xxxx/yyyy/public_html/zzzzz/web/core/lib/Drupal/Component/PhpStorage/MTimeProtectedFastFileStorage.php on line 88"

caused a white screen. Modified the program to use the system mv command work around. Installation completed and I have a test site.

The work around is not the solution. Basically we need to delete all the files in the directory and let Drupal rebuild it then try to isolate which files are causing exceptions in rename ... and why.

We know that PHP rename can successfully rename an IONCUBE compressed PHP file ... rename doesn't care about file contents I don't think but there could still be something IONCUBE related. Or not.

To be continued.

fkelly12054@gmail.com’s picture

Dead ended. My Inmotionhosted test site works with Drupal 9.2.1 ... installed 7/18/21 with Composer. Just a plain vanilla site with no content.

Getting the printf PHP error whenever clearing cache. Reloading the page and temporarily ignoring the error eventually rebuilds the PHP/twig directory.

I created a new testing directory right under my web root/ public_html. I copied some of the files from the php/twig directory and did short and sweet PHP renames on them: e.g.,

<?php
echo 'in renametest2' . '<br/>';

rename("/home/fkelly5/public_html/toplevel/60f590e294486_system-config-form.html.t_zXjbkeou-BrCCX9Y6GVTBMZ1X/3wAjy0DZg0KV1_esc6Ek_Y6vo_zPjCAidE9AkdapnzI.php" , "subdef.php");
echo 'dir to subdef <br/>';

?>

I tried at least a half dozen files. Can't get the printf error to happen manually. It happens every time MTimeProtectedFastFileStorage.php is run. You can keep reloading the page and eventually get it to "complete".

I called Inmotionhosting tech support. They are helpful and professional. But, long and short, on shared hosting you get a cookie cutter setup. They can't (won't) disable IONCube for one client. Not that we know that would solve the problem anyway. I don't want to pay $30 to $40 per month for a VPS ... where there is no guarantee that this problem would disappear.

I looked at Charlie's suggested settings.php code from #51 ($settings['php_storage']['default']= 'core/lib/Drupal/Component/PhpStorage/FileStorage.php'

That is not documented anywhere that I can find and doesn't work on my test system.

Ghost of Drupal Past’s picture

Sorry, the settings need to be the class name not the filename.

$settings['php_storage']['default']['class'] = '\Drupal\Component\PhpStorage\FileStorage';

ought to work. And yeah, it's undocumented as far as I can tell, that'd be a separate issue with maybe #2238935: [meta] Complete missing documentation for special strings and metadata like annotation keys, routing parameters, tagged services, etc. as a parent -- as far as I can see see , most settings overrides like this is undocumented.

fkelly12054@gmail.com’s picture

$settings['php_storage']['default']['class'] = '\Drupal\Component\PhpStorage\FileStorage';

results in:
"Warning: file_put_contents(sites/default/files/php/twig/60f9c22fee0ac_admin-block-content.html._dNvqx-a2l_IKrU2qS5LcIDcMB): failed to open stream: Is a directory in Drupal\Component\PhpStorage\FileStorage->save() (line 55 of /home/fkelly5/public_html/drupal8/core/lib/Drupal/Component/PhpStorage/FileStorage.php). => "

I tried the settings change after installing the 9.2.2 security update. Don't want to "fork" this issue thread though.

Been thinking about the Inmotion shared server and IONCUBE issues further. I have an email in to them and I spent a few hours trying to isolate what happens when PHP rename fails. Thinking things over:

1. I don't think it is just a matter of rename "choking" on the file name per #31. If it was then it would fail on Wampserver as well as on Inmotion shared server (and other shared servers).

2. I don't think file contents come into it at all. I could be wrong since I don't know the internals but I don't think PHP rename deals with the contents at all. I can rename IONCUBE encoded files just fine on my local system.

3. I don't know which PHP files Inmotion encodes and which they don't. I will waiting on a response from Inmotion on some other issues including whether they will consider at least a test non-IONCUBE shared server setup.

4. Aside from encoding IONCUBE also provides a set of security settings and a security console. End users don't have access to the console. I will try to get someone from Inmotion to look at the console to see if there are any warning issued at the same time that the rename function on my site fails. I wonder if the intrusion detection is thinking that the PHP rename is some type of intrusion and killing it.
This could account for the intermittent nature of the problem.

I've looked around at other shared server write-ups. Many of them have IONCUBE installed. At least one says you can't install it at all.

I briefly tried putting the rename in a try catch loop. But I'm not an expert developer and don't know what the "exception" would be or whether you can "catch" an error like that. I was wondering whether, given the intermittent and seeming transient nature of the problem you could keep trying the rename until it succeeds.

Ghost of Drupal Past’s picture

Please file a bug report for the settings.

fkelly12054@gmail.com’s picture

It may not be a bug

Sigh.
I was just about finished writing up an issue for this when I looked at the wording of the error message ... particularly "failed to open stream: Is a directory in Drupal\Component\PhpStorage\FileStorage->save() (line 55 of ..."
Looking at the PHP/TWIG directory in my cpanel file manager I saw a bunch of directories under it. I wondered if the "is a directory " statement was leading to a solution. I deleted everything from the directory and made the settings.php change. The site worked fine, including allowing me to clear cache.

The above was on a test site on shared hosting. Buoyed by this success I made corresponding changes to my production system on the same shared hosting. (Delete everything in PHP/TWIG, change settings.php to point to FileStorage, rummage through the site a bit, then clear cache. It works: with no PHP error message.

I'm mindful of the warning that this could compromise security in an extreme case. Having PHP error messages causing white screens whenever I do anything "administrative" on my site compromises my sanity. So I will continue to use this solution ... at least for the time being. Hopefully next week I will have further discussions with InMotion hosting. I'm particularly interested in seeing whether their intrusion detection logs show any issues at the same time that PHP sprintf error messages are generated.

I'm not going to file a separate bug report at this time, since I can't reproduce it. Thank you @Charlie.

apaderno’s picture

@fkelly I take Charlie meant opening a bug report about $settings['php_storage']['default']['class'] not being documented.

fkelly12054@gmail.com’s picture

@aparderno ... okay, thanks. I can do that. Issue 2238935 seems both tangential and outdated. The "workaround" using the setting Charlie suggested seems to be working fine and will alleviate my immediate issue. I'll get to the bug report next week.

I am corresponding with Inmotion about whether they might set up some special shared server hosting for Drupal (like they have for Wordpress). I think it's a long shot but worth exploring. Shared server hosts have a hard time keeping up with Drupal's leading edge software requirements ... just generally.

Peter Pulsifer’s picture

You guys are really sticking with this issue! Sorry that I have just been too busy to contribute, but I did try a few things. I have added some code to MTimeProtectedFastFileStorage.php so that it logs every rename attempt to a file. The site is not very busy, but over the past 10 days or so there have been 957 successful renames and 38 failures. In every case the source ($temporary_path) file existed before rename, and the dest file ($full_path) did not - which is expected. There were no special characters in any file names, and the same characters were found in successful and in unsuccessful file names - so it's not like some particular characters are being encoded by sprintf(). Thinking it might be a problem with rename(), I tried substituting copy() followed by unlink(), but the problem occurs just as often, on the copy.

There's no point in checking the $result value because when the glitch occurs the code aborts and there is no return. I think the same problem would defeat a try/catch, though I haven't tried that yet. It's a micro-coding issue within php. (I don't know how IonCube works, but something that alters normal php execution is an attractive candidate for being the problem).

I can eliminate the white screen problem by using system() per #26 and #29, but, as with @fkelly (I'm on InMotion, too), this actually seems to simply turn off the caching because the "mv" does not actually move the files - they remain in the top "twig" directory. I'm really puzzled as to why that occurs! The "mv" works properly on other systems where I have shell access, but here it has no effect. The twig directory seems to have 777 permissions.

BTW, I believe that after
system('mv {$temporary_path} {$full_path}', $result)
the variable $result has the opposite meaning from $result=rename(): For the shell, success is 0 (php false), whereas the php rename returns true for success.

Also BTW, regarding #54 concerns about whether the destination directory exists, I believe the directory is created on line 66 of MTimeProtectedFastFileStorage.php by ensureDirectory().

If you'd like a list of successful and failed rename operations, I could supply one!

Peter Pulsifer’s picture

One more thought. This process is moving cached php code. Maybe the issue is in that cached code. If one of the renamed php files is accessed asynchronously immediately or very soon after being made available, it might throw an error that is reported as originating in MTimeProtectedFastFileStorage.php. I've glanced at a couple of the moved php files and don't see any sprintf's, but there could be a lot of ways to get there. It seems to me that this problem only comes up in a caching context - in Drupal or WordPress or elsewhere. (Though I could be wrong!)

I started wondering why rename could be defective only in this section of Drupal code - there must be lots of other uses of rename in the Drupal codebase (though actually, after doing a search, plain old php rename isn't used much, there are several customized versions - but there are a few!).

I did add a try/catch block, and nothing was caught - white screen still came up.

Here FWIW, is a list of the destinations of files that were being renamed when it crashed. I thought if it was one type of file that might give an indication of what might be problem code. But I don't see any patterns offhand. In this list, to save space, I have stripped the random characters in the directory and the actual file names, which are just random strings anyway. For example, for the file
60f02d68470b4_views-slideshow-cycle-mai_u3DGdjH8dMp_Be33SpKzrzd-y/nrcpPlWIhRP7v63yc1JMhQ5YYcHiktWZ0bapAMk2rDc.php
I just wrote
views-slideshow-cycle-mai_u3DGdjH8dMp_***

The list:

  • views-slideshow-cycle-mai_u3DGdjH8dMp_***
  • form--search-block-form.h_3UzJPYlXbfA0q1hEVaalz2OkJ/mKruM1jgfJ7AchEDzSbfg1lJmB8R_***
  • form.html.twig_FfVjwCX0HB1KyUgY5cPBfB0cg/5V5fj44Bd4GN96N_UYa4sZmeVkJm2jdrBpvw8_***
  • webform-submission-form.h_***
  • webform-element-help.html_***
  • radios.html.twig_***
  • views-slideshow-cycle-mai_u3DGdjH8dMp_***
  • webform-submission-form.h_***
  • radios.html.twig_***
  • form.html.twig_FfVjwCX0HB1KyUgY5cPBfB0cg/EF6_***
  • views-slideshow-cycle-mai_DnmPux4_NBBBgm0eSPCubckCj/Q2XczcvDOsDUHmoXUFkjBI9zfB2WtViXDcmFT37c8_***
  • form--search-block-form.h_3UzJPYlXbfA0q1hEVaalz2OkJ/Qi6c-FxxCdsz8CqFqjkyS4eP_***
  • views-slideshow-cycle-mai_u3DGdjH8dMp_***
  • form--search-block-form.h_***
  • form--search-block-form.h_***
  • form--search-block-form.h_***
  • radios.html.twig_F4MIv1hrY-dvicYjjZRjl0sN8/aPkED6Px2pj_Yo9_***
  • webform-submission-form.h_WG-h7xdSUM9ZNX4gCHpT8mM9c/ZRM-vH8IjSRT8eYleBqVjLeZeTWCqtDcr4_***
  • form.html.twig_***
  • form--search-block-form.h_3UzJPYlXbfA0q1hEVaalz2OkJ/OngeiT2TpUv_qTLIkP3q0zrKU2kj-L_***
  • views-slideshow-cycle-mai_***
  • webform-html-editor-marku_hsAESSB7sGUZuNnyaAE2i1IAs/NVtSZzKkGIsSMCPXy0O8g1QAFQ4-j0_***
  • views-slideshow-cycle-mai_DnmPux4_NBBBgm0eSPCubckCj/s9ioXqhs0u8CCUjEAYYD__***
  • form--search-block-form.h_***
  • views-slideshow-cycle-mai_u3DGdjH8dMp_***
  • form.html.twig_FfVjwCX0HB1KyUgY5cPBfB0cg/7cBSUQKtdvGrZ1d9K44__***
  • media.html.twig_***
  • views-slideshow-cycle-mai_aFnzWQO-h5XQ4joef-UhusFKg/JF1jPSAwbym2TNNIWEUGEhv0pbyGX7_***
  • form.html.twig_***
  • views-slideshow-cycle-mai_u3DGdjH8dMp_Be33SpKzrzd-y/XgvQwdINLn6q_***
  • table.html.twig_***
  • views-slideshow-cycle-mai_***
  • form.html.twig_FfVjwCX0HB1KyUgY5cPBfB0cg/j5ZRRI_***
  • fieldset.html.twig_Be5iydUaPjCVXlx7Lv_***
  • media.html.twig_GIh6TCIdVWLocxlqSuGUUNuMc/DOvIFCGiMKL-3tY3fFyDmSN_***
  • form--search-block-form.h_***
  • webform-submission-form.h_WG-h7xdSUM9ZNX4gCHpT8mM9c/jIjZ4p1tNhvDVL5WRyrXoGDEndOvww_2yWfx_***
  • form--search-block-form.h_3UzJPYlXbfA0q1hEVaalz2OkJ/cXXNjmwSBRMX0cHFDLGbwTK3uq8_***
  • form--search-block-form.h_***
  • fieldset.html.twig_Be5iydUaPjCVXlx7Lv_Qu1T3T/_***
  • field-multiple-value-form_PkLEFdOTC3oMAV1nH7F0MQMaq/7RCTO3exthluE_Wo_32x_qG0u_***
  • webform-html-editor-marku_***
  • views-slideshow-cycle-mai_DnmPux4_***
  • webform-element-help.html_***
  • form--search-block-form.h_***
  • checkboxes.html.twig_***
  • webform-html-editor-marku_hsAESSB7sGUZuNnyaAE2i1IAs/E2_***
  • table.html.twig_***
  • views-slideshow-cycle-mai_DnmPux4_***
  • views-slideshow-cycle-mai_aFnzWQO-h5XQ4joef-UhusFKg/ce6UXcu_jxlTAgq_***
fkelly12054@gmail.com’s picture

@Peter ... thanks ... I think that is what Cifelen was looking for in #31. I have potentially useful correspondence going with Inmotion tech support. I'm going to see if they can look at their intrusion detection logs (IONCUBE) while I kick off a PHP rename error. I'm getting proficient at causing that to happen. Charlie's settings.php modification is keeping my PHP error log clear of rename errors for the time being.

I don't think that either the file names or the file contents have anything to do with this.

Peter Pulsifer’s picture

I altered the rename process slightly to remove the last character of $full_path - so the file extensions are .ph instead of .php. This, of course, makes the renamed files inaccessible to whatever other code might try to use them. That seems to eliminate the exception problem. The rename by itself works fine under those conditions.

Thinking I might be onto something, I altered the file names while keeping the .php extension. The exceptions returned (maybe worse). From the MTimeProtectedFastFileStorage.php comments, the internal file names are supposed to be "a hash of the virtual file name, a cryptographic secret, and the containing directory mtime. If the file is overridden by an insecure upload script, the directory mtime gets modified, invalidating the file, thus protecting against untrusted code getting executed." Either this system isn't working, or something else is acting on those php files.

When I alter the file names, a few of the twig/ directories contain files with names like .mx.21823667.mx - I don't see any of those files when I use the original file names.

fkelly12054@gmail.com’s picture

@Peter:

I altered the rename process slightly to remove the last character of $full_path - so the file extensions are .ph instead of .php. This, of course, makes the renamed files inaccessible to whatever other code might try to use them. That seems to eliminate the exception problem. The rename by itself works fine under those conditions.

Brilliant idea! Now combine that with the fact that the exception is both intermittent and transient. By intermittent I mean that some (many) of the PHP files get renamed okay. And transient I mean, if you keep reloading the page after the exception, the process seems to complete. Then add in the fact that this problem only appears to happen on a subset of shared web hosting services. (Correct me if I'm wrong on any of these).

I'm going to have an interesting phone call with Inmotion tech support a bit later today.

Ghost of Drupal Past’s picture

Title: [PHP bug] Illegal length modifier specified 'f' in s[np]printf call on rename() in MTimeProtectedFastFileStorage » Do not use the .php extension in mtime protected storage to work around bogus PHP extensions
Category: Support request » Task
Issue summary: View changes

Re #77

I've glanced at a couple of the moved php files and don't see any sprintf's

The error is Fatal error: Illegal length modifier specified 'f' in s[np]printf call and snprintf/spprintf are C functions. The problem is not in userspace code.

Changing the extension of the files is a possibility, however. Please file a patch. As the person who wrote this subsystem: I see no security problems with doing this but of course we will need to see what others see :)

I have updated the issue to steer towards this.

fkelly12054@gmail.com’s picture

Before I wrote up a separate issue for $settings['php_storage']['default']['class'] not being documented I did some spelunking using the search function on drupal.org. I also searched through the /core code in my PHPeditor to see if I could determine how/where $setttings['php_storage]... might be being used. There are some tangential hits but long and short there is nothing to tell a site admin how to adjust settings for php_storage. Or where it might be used. Or why.

I did come across this issue:
https://www.drupal.org/project/drupal/issues/2700019
MTimeProtectedFastFileStorage crashes with concurrency.

There is a pending patch for Drupal 9.3.x. It appears to me that 2700019 has a tangential rather than a direct relation to issue here but it might be helpful if someone more knowledgeable than I took a look to see if it's applicable.

On the ongoing saga here, I have a ticket created with Inmotion hosted to have them look at their intrusion detection log and try to correlate it with PHP rename errors. It's shared hosting so their tech support has no access to server logs and so the ticket has to get to their system administration group for action. I'm not holding my breath. They would rather have me spend $40 a month on a VPS.

I'm going to try Peter's solution ASAP. It appears to be a one character code change and it's why I have a test site on shared hosting.

Ghost of Drupal Past’s picture

If you do file that documentation issue, link it to #2547827: PhpStorage: past, present and future please so the documentation appropriately notes the bare FileStorage works but it is very strongly not recommended.

Thanks for your tenacity in this issue.

fkelly12054@gmail.com’s picture

Thank you @Charlie. My priority right now is to try out Peter's proposed fix. Unfortunately, tenacity is a weak substitute for expertise.

While the "concurrency" mentioned in issue 2700019 doesn't pertain directly to our immediate situation in this issue, I was wondering overnight if there could be lurking issues relating to concurrency on shared hosting systems. If I'm not mistaken, in MTimeProtectedFastFileStorage Drupal could be doing say 30 to 50 PHP file renames right on top of each other. What happens if other sites on the same server are hitting at PHP rename at the same time?

I also found an extended discussion by core committers and developers in:

https://www.drupal.org/project/drupal/issues/2544932

The fix was committed 6 years ago but I wonder if some artifacts/deficiencies may have leaked into the current situation. The PHP error bugs I'm seeing are intermittent and transient. If I do a bunch of renames one by one outside of Drupal I can't get one to occur.

And, this needs confirmation, but afaik this bug ONLY occurs on shared hosting. If fact I'd guess this is the reason it has not attracted more high level attention from core developers and core committers.

fkelly12054@gmail.com’s picture

@Peter ... I'm trying to use your suggestion in #79. First, would we make two changes? In the getFullPath function at line 79 write:

return $directory . '/' . Crypt::hmacBase64($name, $this->secret . $directory_mtime) . '.ph';

Second, in function getContainingDirectoryFullPath
at line 204 do this

 if (substr($name, -3) === '.ph') {
      $name = substr($name, 0, -3);

I wasn't sure if both are needed.

On my test system on shared hosting this results in a series of files with .ph extensions. And no PHP errors on rename. But would this affect functionality? My shaky understanding is that Drupal uses these "pre-built" files for caching. Will this work with a .ph extension?

Ghost of Drupal Past’s picture

>
And, this needs confirmation, but afaik this bug ONLY occurs on shared hosting.

No, this bug occurs because a non-standard PHP extension is used by your provider. Me and I suspect a lot others are running Drupal 9 sites without a problem on other shared hosts.

Peter Pulsifer’s picture

@fkelly Yes, I think your two modifications would do the trick. I was a bit less subtle, I just replaced the

$result = rename($temporary_path, $full_path);

in line 88 with

$test_path = substr($full_path,0,-1);
$result = rename($temporary_path, $test_path);

and a bunch of other test and debug output stuff.

So all of the twig template files have .ph extensions instead of .php extensions. I have been monitoring this for a day or so and haven't seen any crashes - though, interestingly, I have seen some instances where the save method seems to be called again while it is doing a rename operation (at least that's my guess as to what's happening).

I too am confused to the effect on functionality. I believe from some of the links you're referenced that the .php extension is not required for twig templates, but I would think that code that uses those templates might looks for certain filenames, and those filenames might be expected to end in .php. @Charlie, could you shed any light on that?

fkelly12054@gmail.com’s picture

@Charlie ... this bug occurs because a non-standard PHP extension is used by your provider
You mean IONCUBE or something else? I've posted PHPINFO and can again. I have no problem "bugging" Inmotion if something (an extension) that's not legitimate or desirable is being added to PHP.

@peter ... as to the effects on functionality ... yeah ... and that's why I think it's probably premature to start posting patches. I will try your suggestions on my production system next week ... they are already on test. But the people who posted in the other threads I listed in #84 and @Charlie are much more qualified than I to start posting patches and trying to get to a RTBC status. That's a slippery slope when you aren't even sure how the functionality is supposed to work.

I think that some variant of this issue has been simmering beneath surface for 6 years now. I don't see anything happening in Drupal in June 2020 when this issue was first reported that would have kicked this off.

fkelly12054@gmail.com’s picture

If we change the file extension to "ph" instead of "php" we need to insure that the "ph" files are actually being used.

Naively I thought that if I just edited one of them and stuck a die statement in I could do this. I get no results ... I can't see where the "ph" files are being used. On the other hand switching the code back to generate "php" files goes back to regenerating PHP rename errors. And even when you keep ignoring the errors and reloading the cache clear page and get a decent set of PHP files in the twig directory I can't confirm that they are actually being used. DIE does no good except perhaps to demonstrate my programming deficiencies.

My unclear understanding was that Drupal uses the files in /twig to avoid recompiling all the templates. If so, we need a way to demonstrate that any changes we make won't undermine caching.

I found:

https://www.drupal.org/project/drupal/issues/2752961

which starts with a good discussion of the purpose and operation of twig caching. But then it devolves into an extended discussion by top Drupal developers and committers. It also partially documents the settings that affect PHPstorage.

I'll be back to pick this up next week.

Ghost of Drupal Past’s picture

The new issue summary proposed resolution tells you where / what to edit in Drupal: the function getFullPath in core/lib/Drupal/Component/PhpStorage/MTimeProtectedFastFileStorage.php

Ghost of Drupal Past’s picture

Version: 8.8.x-dev » 9.3.x-dev
Component: cache system » base system
Status: Active » Needs review
FileSize
1.69 KB

Please try this one.

fkelly12054@gmail.com’s picture

I applied @Charlie's patch from#91 to my 9.2.2 test system on Inmotion Hosting. It works.

Charlie's statement about "this bug occurs because a non-standard PHP extension is used by your provider" is ringing in my ears. Inmotion did some testing over the weekend and can't get to the bottom of this. I will keep following up with them but don't expect great results. Bottom line appears to be Drupal has to "code around" the apparent fact that on certain shared hosting sites, some "unknown" PHP extension is causing the PHP rename function to return intermittent errors. If the files Drupal generates don't have a "php" extension the error doesn't seem to happen.

Whether and when the core committers would choose to apply this "fix" is way beyond my predictive powers.

There is a separate issue (which @Charlie has recently commented on):

https://www.drupal.org/project/drupal/issues/2700019 (MTimeProtectedFastFileStorage crashes with concurrency). The proposed changes there would eliminate use of PHP rename starting with Drupal 9.3. This has been on back burner for quite some time.

Both the changes suggested in this issue and in 2700019 would seem to resolve the problem but testing would be required to make sure they don't cause ancillary problems.

longwave’s picture

Status: Needs review » Reviewed & tested by the community
Issue tags: -Needs steps to reproduce +Needs security review

The change here is simple and according to user reports, fixes the issue with shared hosts using certain PHP "security" extensions.

There is no effect in Drupal itself in removing the file extension. If a user somehow requests these files via a web browser then the file will likely be delivered to them as plaintext with no extension, instead of executing and doing nothing as it does when they are .php. However, the files live in a secret directory with a secret filename and are also protected by .htaccess rules. To me this is good enough protection, but adding "Needs security review" to get another opinion on this change.

fkelly12054@gmail.com’s picture

@longwave ... thanks!! for looking in on this. And to @charlie for coming up with this elegant fix.

fwiw ... I did a composer update for 9.2.3 to my Inmotion (shared hosting) test site. As expected got a white screen (with, I am sure, a PHP rename error behind that) on logging in. Made Charley's change to MTimeProtectedFastFileStorage.php. Site works like a charm.
bit the bullet and did the tar.gz update to my live site on shared hosting. (I still need to "composerize" this site). Redid the change to MTimeProtectedFastFileStorage.php. Ran update.php and the status report comes out clean with the site updated to 9.2.3.

Couldn't ask for more! Hope that by the time 9.2.4 comes along a commit for this issue is in.

Ghost of Drupal Past’s picture

Issue summary: View changes

Thanks but praise and commit credit should go Peter Pulsifier , see #79

fkelly12054@gmail.com’s picture

re. #95. Let's say @Peter came up with a prototype fix which @Charlie simplified and refined. :)

The big takeaway is that some of the shared hosting services have some extra PHP extensions or other so called "security" software running that causes intermittent errors with PHP rename when the file being renamed has a PHP extension. And they can't afford the resources to be doing a deep dive into resolving the problem for Drupal, which probably constitutes a single figure percentage of their business.

catch’s picture

This conflicts with #7269: [meta] Add .php extension to PHP files, but that issue has been open since 2004 and should probably be won't fix at this point.

Ghost of Drupal Past’s picture

Here are the main points from the other issue:

  1. "Newcomers not only have to learn Drupal, they need to configure their IDE and/or OS to open a file with the correct program and get some syntax highlighting working" -- I doubt this applies. Newcomers certainly won't open generated PHP files and even seasoned developers do extremely rarely. (Or maybe I need more seasoning.)
  2. "Not all sites run on apache or IIS where we have config files to stop them from serving those files displayable directly to the browser." -- we already rely on these files not being discoverable by the virtue of their names being long random strings. sites/default/files under Apache has phpengine off so if the discoverability presumption fails then the files today in the wild are downloadable.
  3. "PSR-0 mandates that classes end must end in .php for autoloader interoperability." -- these files are not PSR-0 compatible, these are not loaded by any autoloader, even.

In summary: even if that issue does go forward , it won't collide with this one in my opinion.

fkelly12054@gmail.com’s picture

This was marked as RTBC a month ago ... but also needing a security review. I know the security team has been very busy, but is there any way of bringing this to their attention? It's a five minute change to manually apply Charlie's fix every time there is a new release but I suspect that there are at least a few folks on shared hosting that need to remember to do this every time.

alexpott’s picture

Status: Reviewed & tested by the community » Needs work

I think from a security perspective this change doesn't influence much. There's an htaccess file in sites/default/files/php/twig that prevents access and nginx won't serve PHP from this location either. I think one issue might be that nginx serve the file because it now has no file extension. Before when it was .php nginx would refuse to serve it because it wouldn't be configured to. See the suggested nginx recipe on https://www.nginx.com/resources/wiki/start/topics/recipes/drupal/

Maybe the solution here is allow the extension to differ and depend if ioncube or another extension is loaded? That way there would be no change for the majority of sites. But affected sites would now work.

Additionally I think this should be coupled with a check in system_requirements that a file in the twig php cache is not publicly available.

alexpott’s picture

I'm also wondering about the affect of this on our docs. Specifically:

/**
 * Stores the code as regular PHP files.
 */
class FileStorage implements PhpStorageInterface {

and

/**
 * Stores and loads PHP code.
 *
 * Each interface function takes $name as a parameter. This is a virtual file
 * name: for example, 'foo.php' or 'some/relative/path/to/foo.php'. The
 * storage implementation may store these as files within the local file system,
 * use a remote stream, combine multiple virtual files into an archive, store
 * them in database records, or use some other storage technique.
 */
interface PhpStorageInterface {
longwave’s picture

.htaccess blocks these:

# Protect files and directories from prying eyes.
<FilesMatch "\.(engine|inc|install|make|module|profile|po|sh|.*sql|theme|twig|tpl(\.php)?|xtmpl|yml)(~|\.sw[op]|\.bak|\.orig|\.save)?$|^(\.(?!well-known).*|Entries.*|Repository|Root|Tag|Template|composer\.(json|lock)|web\.config)$|^#.*#$|\.php(~|\.sw[op]|\.bak|\.orig|\.save)$">
  <IfModule mod_authz_core.c>
    Require all denied
  </IfModule>
  <IfModule !mod_authz_core.c>
    Order allow,deny
  </IfModule>
</FilesMatch>

The sample nginx config blocks these:

    # Protect files and directories from prying eyes.
    location ~* \.(engine|inc|install|make|module|profile|po|sh|.*sql|theme|twig|tpl(\.php)?|xtmpl|yml)(~|\.sw[op]|\.bak|\.orig|\.save)?$|^(\.(?!well-known).*|Entries.*|Repository|Root|Tag|Template|composer\.(json|lock)|web\.config)$|^#.*#$|\.php(~|\.sw[op]|\.bak|\.orig|\.save)$ {
        deny all;
        return 404;
    }

We could reuse one of these file extensions instead of .php, maybe .inc is a good call, or we could try something like .php.twig even.

fkelly12054@gmail.com’s picture

Maybe the solution here is allow the extension to differ and depend if ioncube or another extension is loaded?

We don't know for sure whether IONCUBE or another extension is causing this. We suspect it, but the shared hosting tech. support (I use Inmotion) is not going to go back to their hosting consoles and dig into logs to confirm this for us. Nor are they willing to experiment by setting up some shared accounts without IONCUBE and others with it to help isolate the problem. All we know for sure is that, on a few shared hosting accounts (using different hosting) the rename to PHP files fails intermittently. And the proposed patch makes the failure go away.

It is a five minute inconvenience every time an update (e.g., 9.2.6 to 9.2.7) comes out to edit the new mtime protected storage file. Not a big deal but a minor step to remember.

catch’s picture

.inc sounds better than no extension to me.

fkelly12054@gmail.com’s picture

re. #104
".inc sounds better than no extension to me."

Not sure if it's helpful, but since the only place I can reproduce this is on my live site on Inmotionhosting I made the suggested change there.

  public function getFullPath($name, &$directory = NULL, &$directory_mtime = NULL) {
    if (!isset($directory)) {
      $directory = $this->getContainingDirectoryFullPath($name);
    }
    if (!isset($directory_mtime)) {
      $directory_mtime = file_exists($directory) ? filemtime($directory) : 0;
    }
    return $directory . '/' . Crypt::hmacBase64($name, $this->secret . $directory_mtime) . '.inc';
   // return $directory . '/' . Crypt::hmacBase64($name, $this->secret . $directory_mtime);
  }

"Inc" works fine. Just to be sure that some change on the hosting side hasn't made the problem go away in the last month, I changed inc. back to "php" and the sprintf bug immediately reappeared. Put it back to "inc" and it works fine again.

Thanks for looking at this isolated and idiosyncratic bug.

Ghost of Drupal Past’s picture

Status: Needs work » Needs review
FileSize
1.71 KB

While I don't think there's any point in .inc security wise (see issue summary -- the URL is completely random), there's merit in choosing it because this fixes the IDE problem I noted, no matter how rare it is. Thanks for the suggestion.

fkelly12054@gmail.com’s picture

Status: Needs review » Reviewed & tested by the community

Going from 9.2.7 to 9.2.8 I manually re-applied the patch in #106 (after the update). It works. I don't know if a security review is still required or not. It would be nice for shared hosting sufferers if this got committed someday. I am well aware that core committers have bigger fish to fry.

alexpott’s picture

Status: Reviewed & tested by the community » Needs work

We certainly need to document why we are choosing .inc over .php in the code base.

fkelly12054@gmail.com’s picture

We certainly need to document why we are choosing .inc over .php in the code base.

How about for starters:

"In issue 3152749 users documented that a PHP error e.g., PHP Fatal error: Illegal length modifier specified 'f' in s[np]printf call in ... web/core/lib/Drupal/Component/PhpStorage/MTimeProtectedFastFileStorage.php on line 88

was generated when the PHP code attempted to rename a series of PHP files. This appears to only happen on shared hosting systems and may be related to additional security software running on top of Drupal on the shared hosts. Using "inc" instead of "php" as the file extension eliminates this error without sacrificing any functionality or security. "?

alexpott’s picture

We don't need to link to this issue - the commit message is good for that. I would do something like:

The extension "inc" is used here due to errors renaming files that use a "php" extension on some shared hosting.
It appears this is caused by security extensions that are used by some hosts.
fkelly12054@gmail.com’s picture

@AlexPott ... you know far more about what's appropriate for this than I will ever approach. Thanks!

Version: 9.3.x-dev » 9.4.x-dev

Drupal 9.3.0-rc1 was released on November 26, 2021, which means new developments and disruptive changes should now be targeted for the 9.4.x-dev branch. For more information see the Drupal core minor version schedule and the Allowed changes during the Drupal core release cycle.

fkelly12054@gmail.com’s picture

Today, 2/2/2022, I applied the 9.3.4 update via composer to my site. Over the past few months I have had to then manually reapply the patch in #106 for mimetimeprotectedfastfilestorage.php to my system (usually by just copying a saved version of the file to my system). I can see from file manager that the file is now modified as of 2/2/2022 and looking at the code the patch is not in it. I have not updated my PHP version or made any other changes that should affect this. HOWEVER, without applying the patch, the error is gone.

This may indicate that the hosting service has made some other change to the environment that eliminates the error. We have suspected, but can't prove that Ioncube or some other software in the hosting environment might be causing the problem. (I use Inmotionhosting).

Unless another user of a shared hosting service reports that the problem remains we might be able to close this issue and never apply the patch. I have been able to clear cache and generally "rummage" around my site without any re-occurrence of the PHP error (which was last recorded November 28, 2021).

I will leave it to a maintainer to mark this as fixed as they see fit.

apaderno’s picture

Status: Needs work » Needs review
FileSize
1.9 KB
longwave’s picture

@fkelly the November 28th date is interesting because this is close to a major release of the Ioncube software, which we suspected may be the problem. According to https://www.ioncube.com/sa/RELEASE-NOTES.txt Ioncube 11.0.0 was released in November 2021 and a further 11.0.1 update was released on the 27th. It seems possible that InMotion upgraded the software shortly after release and that happened to fix this issue.

fkelly12054@gmail.com’s picture

@longwave ... thanks for that information about Ioncube. I read through the release notes but don't see any fixes directly pertinent to our problem. Not sure what "Support is added for encoding files using PHP 7.4 syntax " means. Back in the Fall I spent time talking to tech support at InMotionhosting. But, as a shared hosting user paying them a few dollars a month, you are never going to get past 1st or second level tech support and talk to the people who actually set up the servers or who have direct access to the server consoles or the ability to test and monitor things, go through logs etc. Nor are they going to customize a server for you or let you run a site without Ioncube or any other security software they choose. It's all cookie cutter. And that's not a complaint.

For my single site on shared hosting I have a very workable work-around. If other shared hosting users who have registered problems in this thread find that the problem has gone away, the thread should probably be closed. If not, it could be left open as a resource (and even if it's closed, someone with the problem will probably find it in a search).

Peter Pulsifer’s picture

Like @fkelly I have not seen the issue in a while. I upgraded to D9 on December 18, 2021 and haven't needed the patch, and before that went through one or two D8 upgrades without issue - though with this sporadic error it's hard to be sure. Of course, I too am on an Inmotion shared server. I agree that the Ioncube dates match what we've seen, but Inmotion has changed a couple of php-related things as well. I would still be in favor of going ahead with the making the change, maybe as per #106, but so far so good, as far as I'm concerned. I agree that this thread is a good resource.

Version: 9.4.x-dev » 9.5.x-dev

Drupal 9.4.0-alpha1 was released on May 6, 2022, which means new developments and disruptive changes should now be targeted for the 9.5.x-dev branch. For more information see the Drupal core minor version schedule and the Allowed changes during the Drupal core release cycle.

Version: 9.5.x-dev » 10.1.x-dev

Drupal 9.5.0-beta2 and Drupal 10.0.0-beta2 were released on September 29, 2022, which means new developments and disruptive changes should now be targeted for the 10.1.x-dev branch. For more information see the Drupal core minor version schedule and the Allowed changes during the Drupal core release cycle.

smustgrave’s picture

Status: Needs review » Needs work
Issue tags: +Needs steps to reproduce

This issue is being reviewed by the kind folks in Slack, #needs-review-queue-initiative. We are working to keep the size of Needs Review queue [2700+ issues] to around 400 (1 month or less), following Review a patch or merge request as a guide.

Know it seems difficult to pinpoint the steps to reproduce but think we will really need them before moving forward. Still needs security review though.

longwave’s picture

Status: Needs work » Postponed (maintainer needs more info)

As we've not had any further reports of this in over a year, it seems likely the problem is resolved and Drupal core does not need to make any changes.

Marking as postponed for now; if there are no further reports within six months then I think this issue can be closed.

Version: 10.1.x-dev » 11.x-dev

Drupal core is moving towards using a “main” branch. As an interim step, a new 11.x branch has been opened, as Drupal.org infrastructure cannot currently fully support a branch named main. New developments and disruptive changes should now be targeted for the 11.x branch, which currently accepts only minor-version allowed changes. For more information, see the Drupal core minor version schedule and the Allowed changes during the Drupal core release cycle.