Race conditions in the twig template cache

For me this happened in some scenarios when the stream wrappers haven't been setup properly.

I must say, that I was looking at the TestBot queue to see how big it was and couldn't help but read this issue...

Twig uses a double caching logic to avoid having to check the filesystem again and again for things that are in cache.

Therefore a race condition during cache clear could be expected.

I think the class_exists($cls, FALSE) is the proper fix.

HEAD just had a random fail with this as well.

Drupal core - 8.0.x fail: https://qa.drupal.org/8.0.x-status

Overall Summary
==============================================

FAILED: [[SimpleTest]]: [PHP 5.4 MySQL] 87,171 pass(es), 1 fail(s), and 0 exception(s).

Individual Environment Summaries
==============================================

-- [[SimpleTest]]: [PHP 5.4 MySQL] --

* Drupal\update\Tests\UpdateCoreTest (852 pass(es), 1 fail(s), and 0 exception(s))
   - [fail] [PHP Fatal error] " Class '__TwigTemplate_834b8992aafa7a111df3eb478be6ddcbc43ccfb5d5020e08270ddf79a80c5e7c' not found" in TwigEnvironment.php on line 141 of Unknown.

The caching logic happens in isFresh() and likely that test for a cache miss is wrong, but this should not affect core as its only happening when auto_reload => TRUE, which we don't do for performance reasons.

That means somehow either ->save() to storage fails or ->load() loads something else.

That is tricky for sure, hardening we should do anyway, so as proposed already:

-        if (!$this->storage()->load($cache_filename)) {
+        if (!$this->storage()->load($cache_filename) || !lclass_exists($cls, FALSE)) {

at the minimum.

Then we could again do a check afterwards and throw an Exception, though that is really fatal if a newly dumped file cannot be loaded as class ...

Why not?

If the class does not exist and we store and retrieve it then, it should exist afterwards or not?

Would a `flock($handle, LOCK_EX);` be appropriate here? Since the lock is needed to write the cache and not read it, it won't be a huge performance hit?

Hmm. PhpStorage doesn't use handles, so flock() can't be used directly unless we also add a lockfile to the Twig cache.

Maybe just this is all that needed?

We could @mkdir to make the warnings go away, but it kinda sounds like there are still two processes in PhpStorage::save() at the same time.

Do we need to add an optional lock to PhpStorage or make a LockablePhpStorage, either of which whose constructor accepts a LockBackendInterface, and then protect save with it? Or a lock in TwigEnvironment?

Quick and dirty locking in FileStorage::save() to see what implodes. No other changes from HEAD.

OK, some additional testing with increased concurrency in ab reveals that Bad Things happen with a lock there, and I still got the Twig errors...

Cottser sent me this way from #2234229: PHP Fatal Error: Class __TwigTemplate not found in TwigEnvironment.php... I had the same strange issue on an infrastructure with a replicated file system:

In setting up the Dramble cluster of D8 servers, I was running into the same issue. A while back, it had to do with file permissions issues in the shared GlusterFS mount, but I had resolved that error. After a few hours' debugging, I found that this WSOD and the exact same error can be caused by time drift on multiple servers with a shared mount.

It was the strangest thing, too. If I pointed the load balancer at just one of the servers, everything worked perfectly. If I pointed it at more than one server, then after accessing the second server, the Twig error would start popping up in the logs for all servers, and they'd all WSOD. Then if I pointed the balancer at one server again, that server would load Drupal just fine.

In my case, since I was using Raspberry Pis (without built-in clocks) on a local network, the time from system boot had about +/- 3 seconds of drift, and apparently that was enough to cause this strange error. I even tried having APC on with stat=0, APC on with stat=1, and APC off, and none of those changes made a difference.

#27: Your best bet is to put the twig template cache on /tmp, by setting up the phpstorage configuration in settings.php.

The template cache is also DB backed, so a global cache clear will clear all templates as the mtime is stored in the database.

Your best bet is to put the twig template cache on /tmp, by setting up the phpstorage configuration in settings.php.

But doesn't the twig cache need to be on a shared filesystem if you have multiple webservers? Otherwise, each server would have to regenerate its own twig cache on each request... at least that's how it seems this would work. I could turn off the Twig cache entirely, but that would result in abysmal performance on the Raspberry Pis.

Sounds like we need these additional tags.

#29: Right, thats not active, I was mistaken there.

Still putting it on /tmp/drupal-cache/ is good.

Need to clear /tmp/drupal-cache then on code deploys, but with code deploy on multiple webservers being usually by jenkins, that is not a big deal either ...

Fixed a couple of nitpicks.

I just had this issue as well on a vagrant box, this patch fixed it :)

Nope, lets get this in.

This is RTBC.

Indeed, git bisect points to #2453399: Use VFS for FileStorage tests.

Maybe this? Used `parse_url` so the tests wouldn't have to rely on the file_system service just to check the scheme.

Grrr.

+++ b/core/modules/system/src/Tests/Theme/TwigEnvironmentTest.php
@@ -44,6 +45,19 @@ public function testInlineTemplate() {
+    $element['test'] = array(
+      '#type' => 'inline_template',
+      '#template' => $name,
+    );

I had to look three times, but yes due to how ChainedFileLoader works, you should indeed be able to embed not only inline templates, but also real templates ...

However is this still true? (We fixed some error messages and changed that part.)

Let's check that first ...

This gives just back the string maintenance-html.twig, but that is fine (as that is a valid twig template).

Therefore - even though that is probably not what berdir wanted originally - as it successfully tests the condition of a wrong template in the cache => RTBC.

If we wanted to we could change:

$template = 'Hello World - {{ 1+0 }} ';

or something like that ...

But leave the rest the same.

+++ b/core/lib/Drupal/Core/Template/TwigEnvironment.php
@@ -127,10 +127,20 @@ public function loadTemplate($name, $index = NULL) {
+          eval('?' . '>' . $compiled_source);

I really don't like adding the eval() here even in a rare case. Is it worth looking at the switch to include Berdir mentioned in #16?

Also if we have to have this protection for reads, what indication is there that the lock on write is doing anything?

1. +++ b/core/lib/Drupal/Component/PhpStorage/FileStorage.php
   @@ -53,14 +53,15 @@ public function load($name) {
   +      if (!file_exists($htaccess_path) && file_put_contents($htaccess_path, static::htaccessLines(), $flags)) {
   

   file_put_contents() doesn't care if you write to an already existing file, so what does the LOCK_EX actually help with here?

   It'll stop another process from writing to the file at the same time, but then it's going to write once the lock is released - it won't stop the write from happening at all. So potentially we'll actually spend longer writing to the same file?

   I'm not sure what the implication actually is, but that needs inline documentation (if it's actually useful here).

2. +++ b/core/lib/Drupal/Component/PhpStorage/FileStorage.php
   @@ -168,7 +170,7 @@ protected function createDirectory($directory, $mode = 0777, $is_backwards_recur
   +      if ($status = @mkdir($directory)) {
   

   Needs a comment.

3. +++ b/core/lib/Drupal/Core/Template/TwigEnvironment.php
   @@ -127,10 +127,20 @@ public function loadTemplate($name, $index = NULL) {
   +          // have failed load load the class. In that case, execute the code
   

   "failed to load".

#51 has been addressed, but as I wrote out the comment for (1), I wondered if file_put_contents($path, $code, LOCK_EX); is really sufficient. It will grab an exclusive lock for the .htaccess (if needed), and the file itself, but two processes could still be in the function at the same time making the directory. I'm wondering if the ::save() method needs to be refactored to use flock() directly to make the entire method process exclusive?

From everything I could fine, LOCK_EX is only a write lock, it's not a read lock at all, i.e. http://php.net/manual/en/function.flock.php

If it was a read lock, we wouldn't need the fallback to eval() later on in the patch.

If it's only a write lock, then I don't see how it helps the race condition - it might even make it worse since you'd have two, subsequent writes to the file, where it can be partially read from, rather than two concurrent ones which may finish faster.

I am going to try to get confirmation about LOCK_EX; maybe I can raise @ircmaxell. My understanding from the comments is that it is an exclusive lock, which means only one process can have the file at any time; IOW it would block both readers and writers to the file.

There's a stackoverflow thread here: http://stackoverflow.com/questions/4899737/should-lock-ex-on-both-read-w... which says it's only an advisory lock - so it'd work if all calling code used LOCK_EX - but file_get_contents() can't. Also it looks like ircmaxell answered that thread..

Blerg. Do you think refactoring this to create a class AtomicFileStorage implements PhpStorageInterface would be worth it?

My solution would be to remove exists from PhpStorageInterface as it is pointless and rather pass an optional callable to PhpStorageInterface::load which it can run after including to determine whether the loading was successful. The caller has logic already to deal with load failures.

This patch removes exists as it is unusable and adds loadClass instead.

+++ b/core/lib/Drupal/Component/PhpStorage/FileStorage.php
@@ -33,14 +33,30 @@ public function __construct(array $configuration) {
+    while (!($exists = class_exists($class_name, FALSE)) && $this->doLoadClass($name, TRUE) && !($exists = class_exists($class_name, FALSE)) && $retry--) {
+      usleep(mt_rand($wait, 2 * $wait));
+    }

It would be great to explain why we are waiting here ...

Sure.

Thank you chx. I'm sorry that I haven't see the bit on the interface.

Last fail: @covers exists when exists no longer , well, exists.

If it were fundamentally broken nothing would work since this loads DrupalKernel. If we badly want to test this then we could test the implementation which I never like by creating two files:

// This goes to a known fixed path.
class foobar();

// Put this in phpstorage.
if ($GLOBALS['test_retry']--) return;
include_once 'know/fixed/path/foobar.php';

and then test

$GLOBALS['test_retry'] = 5;
for ($i = 0; $i < 9 && !class_exists('foobar', FALSE); $i++) {
  include "x.php";
}
// assert $i is 6.

We could use a success callable which opens the door for success checking including arrays, functions and whatever else. Even if we want to go back to the previous version, there are small improvements in this one compared to previous.

Only 22439 fails? I need to work harder.

Regarding test coverage, I think non race condition problem will be visible immediately, given how often we render something using a template,
so that part is fine for me :)

+++ b/core/lib/Drupal/Component/PhpStorage/FileStorage.php
@@ -33,18 +33,55 @@ public function __construct(array $configuration) {
+    if (!isset($success)) {
+      return $this->doIncludeOnce($name);
+    }
...
+    while ($this->doInclude($name) && !($return = $success()) && $retry--) {

It seems entirely not obvious why we have both doIncludeOnce and doInclude ... do you mind explaining this somewhere? I assume there is some intention behind it?

Added code and doxygen to make load and loadClass safe by default but overridable. Much nicer and very visible of why doIncludeOnce is necessary:

    if (!isset($success)) {
      return $force ? $this->doInclude($name) : $this->doIncludeOnce($name);
    }

Something is odd here: we write the file first to a random location (str_shuffle combined with microtime) and then do a rename. And yet somehow we manage to read a partially written file? How come?

So (mostly for my own benefit), I can reproduce the error:

2015/05/08 21:59:34 [error] 2192#0: *23 FastCGI sent in stderr: "PHP message: PHP Fatal error:  Class '__TwigTemplate_3df18936b0043763da1aa91635787628747bdf2bc4c34a6457aea4fc3f8fa5ea' not found in /var/www/drupal/core/lib/Drupal/Core/Template/TwigEnvironment.php on line 141" while reading response header from upstream, client: 10.0.1.60, server: 10.0.1.61, request: "GET /user/login HTTP/1.0", upstream: "fastcgi://unix:/var/run/php5-fpm.sock:", host: "pidramble.com"

On my Raspberry Pi Dramble stack (4 webservers using a shared Gluster mount).

Steps to reproduce:

1. Set up Drupal 8 HEAD (or beta10), have all servers' clocks in sync (in my case, 4 servers behind Nginx as a load balancer, with Nginx + PHP-fpm on each webserver, with all Drupal system defaults, e.g. Twig cache stored in normal files folder—files folder mounted via GlusterFS shared on all the webservers).
2. Load up the user login page (notice that it works fine on any of the servers).
3. Set the date on each of the webservers to be about a minute off from each other.
4. Reload the user login page, get WSOD, see above error.

Notes:

1. If I switch the Nginx load balancer to point at only one of the webservers (any one of them), everything works fine again.
2. If I reset all the clocks to be the exact same time (e.g. $ ansible all -m shell -a "date --set='10:25:55'" -s, everything works fine again.
3. Interestingly, every once in a while, the login page (or I've also tested the 'create new account' and 'reset password' pages) will actually load, randomly, from one of the four webservers behind the balancer. But if I run through a bunch of refreshes again, the same server WSODs with the above error again).

I'm at the DrupalCon LA sprints, and I will be testing the patch here and seeing if I can help get this resolved (or at least more thoroughly tested) today.

@geerlingguy, are you NTP synced, or just jam syncing?

I tested the patch in #74, and while it doesn't solve the WSOD issue on the Pis with time drift, it doesn't cause any regression either, and seems like a good approach towards improving the situation. Still doing more testing, too, and I'll try to wrk with chx via IRC if I can some time this afternoon.

@mpdonadio - to test time drift, I set each of the four webservers' clocks explicitly to a value +/- 5 seconds from the actual time (using, e.g. sudo date --set='21:52:48'). Then, to bring them back in sync, I'm jam syncing from my Mac's current time to the stack.

Since the servers have no RTC, and are not connected to the Internet (and don't have NTP), they don't have any (simple) ability to keep their time in sync otherwise. I've thought about setting up one of the servers as an NTP server, with an RTC set up through GPIO, so the other servers could sync to the master clock, but haven't yet set that up (see: https://github.com/geerlingguy/raspberry-pi-dramble/issues/43).

Granted, this is (or at least should be) a pretty rare use case—having a multi-server setup with the twig cache on a shared filesystem with servers that have out-of-sync clocks. So we might not want to bikeshed on that. I'd just like to see if I can figure out exactly where the issue is coming from, since the twig file exists on all the servers, and it seems like a semi-random failure (some requests go through, some are 500s with the above error).

Yes, if you can figure this out, the ocntents of the file being read would be invaluable. See #79

@chx - I've attached the file that's present at /mnt/gluster/files/php/twig/1#36#e9#218a72f912db7dd7fe18458418b9145115f045ba90b5100e5d5fe8b5716d/4cc1fc2e1dc455a9a45bbe4ad00241000181573fffb63d719af245daa0036c36.php (that file is available at that mount, which is mounted at the point /var/www/drupal/sites/default/files). The watchdog message that appears when that file is trying to be loaded is:

2015/05/09 21:58:35 [error] 4073#0: *3059 FastCGI sent in stderr: "PHP message: PHP Fatal error:  Class '__TwigTemplate_36e9218a72f912db7dd7fe18458418b9145115f045ba90b5100e5d5fe8b5716d' not found in /var/www/drupal/core/lib/Drupal/Core/Template/TwigEnvironment.php on line 141" while reading response header from upstream, client: 10.0.1.60, server: 10.0.1.61, request: "GET /user/login HTTP/1.0", upstream: "fastcgi://unix:/var/run/php5-fpm.sock:", host: "pidramble.com"

The file is definitely present on the system, it just won't be loaded for some reason, when the clock drifts from other servers handling active requests.

I'm also trying to reproduce the OP's bug on the Dramble stack, and can't quite do so—steps followed:

1. Start a cache clear on one of the webservers: drush cr
2. (While the cache clear is ongoing): Refresh page over and over. Page loads slowly, but loads after a few seconds with a 200.
3. (Also while the cache clear is ongoing): Run wrk -t4 -c24 -d10 http://pidramble.com/?nocache=true (this loads the page continuously). Page loads slowly, but all requests still go through, with 0 errors.

I tried the above with both beta10 and with HEAD, and I can't reproduce the original issue, except when I explicitly set the Pi clocks to drift. The patch in #74 seems like it's a good approach here for any edge cases, but I am finding it hard to reproduce the actual issue with the cache rebuild race condition.

I also added the debug code inside MTimeProtectedFileStorage.php:

  public function load($name) {
    file_put_contents('/tmp/log.txt', $name, FILE_APPEND);
    if (($filename = $this->checkFile($name)) !== FALSE) {
      // Inline parent::load() to avoid an expensive getFullPath() call.
      return (@include_once $filename) !== FALSE;
    }
    return FALSE;
  }

Contents of /tmp/log.txt:

service_container_prod.php

And with that call to file_put_contents() (and no other changes), I'm now getting a new error message in the logs:

2015/05/09 15:56:50 [error] 5110#0: *15 FastCGI sent in stderr: "PHP message: PHP Fatal error:  Class 'Drupal\Core\Template\Loader\FilesystemLoader' not found in /mnt/gluster/files/php/service_container/service_container_prod/38461dd565579de4d7e93cbc2d9ac60601804d7fbd95e49d31cbf6ae8400643f.php on line 6859" while reading response header from upstream, client: 10.0.1.60, server: 10.0.1.61, request: "GET /user/login?oijsdfasd HTTP/1.0", upstream: "fastcgi://unix:/var/run/php5-fpm.sock:", host: "pidramble.com"

I will attach the loaded service container file as mentioned in the above error message in the next comment.

(And a note: sorry for oversharing the data here... I just want to make sure I put as much debug info into this issue as possible since it's rare I get more than a few minutes to dig into this bug, and it's probably not a bug that's quick/easy to reproduce!)

Attached is the service container mentioned in the previous comment.

This patch implements logic similar to DrupalKernel to make sure the error can't exist.

I had the same issue on a fresh Drupal 8 install made with http://www.drupalvm.com/, the patch in #89 fixed it.

@pbuyle @chx - Strangely, I just started seeing Twig errors on initial site install (they cleared up after a second page refresh) today, reliably reproducible on a fresh Drupal 8 HEAD install on either Ubuntu 14.04 or 12.04 with PHP 5.5. I'm testing this patch now (using Drupal VM).

To reproduce (if you don't want to set up a cluster of servers with a Gluster filesystem):

1. Build an instance of Drupal VM with the default settings (will install D8 HEAD)
2. Load the default URL for the D8 site http://drupaltest.dev/
3. Observe a twig error:
   

   No front page content has been created yet.
   
   Fatal error: Class '__TwigTemplate_94bd2225e3fafe16fc2afc51cd67340aa54d733f8325c53771de007781bb0398' not found in /var/www/drupal/core/lib/Drupal/Core/Template/TwigEnvironment.php on line 141
   

4. Refresh the page, and observe that the site loads correctly (with the default standard profile home page layout).

After applying the patch in #89, and completely rebuilding the VM from scratch (or reinstalling the site, the first page load is fine.

I was able to reproduce 3/3 tries, and used both Ubuntu 12.04 and 14.04, with PHP 5.5 and 5.6 with each of the OSes. The patch was also successful in not resulting in an error on first page load 3/3 tries.

Thumbs up from me; this is an annoying bugger, and I think I've now spent at least 12 hours of my life on it! Thanks so much for the patch, @chx :)

RTBC + 1, even if chx' approach in the other issue is looking promising, this should help to at least avoid the race condition for now.

Can we open a (postponed) follow-up based on #2513326: Performance: create a PHP storage backend directly backed by cache to enable that for twig templates, too.

I hesitate to ask but is this in anyway testable?

@alexpott - I can reproduce 100% of the time in two different scenarios (one that's simple enough for anyone to reproduce, anywhere, the other requiring a set of servers that have their filesystems shared via GlusterFS... so the first way is probably the simplest for easy reproduction):

1. Follow the Drupal VM Quick Start Guide to install an instance of Drupal VM.
2. After about 5-10 minutes (depending on connection speed), provisioning will be complete, with D8 HEAD installed.
3. Fire up your web browser and load http://drupalvm.dev/. Observe attached image and logged PHP error in /var/log/apache2/error.log (pasted below).

[Fri Jul 03 20:36:26.943786 2015] [:error] [pid 23023] [client 192.168.88.1:63018] Uncaught PHP Exception Drupal\\Core\\Database\\DatabaseExceptionWrapper: "SQLSTATE[40001]: Serialization failure: 1213 Deadlock found when trying to get lock; try restarting transaction: INSERT INTO {cache_config} (cid, expire, created, tags, checksum, data, serialized) VALUES (:db_insert_placeholder_0, :db_insert_placeholder_1, :db_insert_placeholder_2, :db_insert_placeholder_3, :db_insert_placeholder_4, :db_insert_placeholder_5, :db_insert_placeholder_6); Array\n(\n    [:db_insert_placeholder_0] => bartik.settings\n    [:db_insert_placeholder_1] => -1\n    [:db_insert_placeholder_2] => 1435955786.931\n    [:db_insert_placeholder_3] => \n    [:db_insert_placeholder_4] => 0\n    [:db_insert_placeholder_5] => b:0;\n    [:db_insert_placeholder_6] => 1\n)\n" at /var/www/drupal/core/lib/Drupal/Core/Database/Connection.php line 609

Side note: Judging by the error message above, this could be related to #2336627: Deadlock on cache_config (DatabaseBackend::setMultiple()) as well. Regardless, it seems the patch in #89 fixes at least this particular issue.

To reproduce, vagrant destroy -f && vagrant up, then load the page again. If I add the patch to the drush make example that's included with Drupal VM, then provision a new instance of the VM, the error is 100% reliably fixed! I also tested it on the Raspberry Pi #Dramble cluster, and while it's harder to reliably reproduce in that scenario, with the patch applied I never saw the error, but without it, I did see the error from time to time when the clocks were more than a few seconds out of sync (since they're not synced via NTP, they drift after a few days).

Here's the exact Drupal make file I was using with Drupal VM (could work with other setups, just make sure PHP/webserver has been cleanly restarted so nothing is in memory already prior to first page load, and make sure you don't install Drupal via web UI, since that may pre-build some of the twig caches):

---
api: 2
core: "8.x"

projects:

  drupal:
    type: "core"
    download:
      branch: "8.0.x"
    patch:
      - "https://www.drupal.org/files/issues/2429659_89.patch"

  devel: "1.x-dev"

Nudging testbot again...

Forgot to attach the first page load error image (this is what the first visitor to a new site sees):

I don't think its possible to test the race condition, but the manual testing should be good enough.

Added beta evaluation

Yes, right, sorry berdir I totally forgot that #3 had a test, which at least tests the error condition part of it.

Lets merge the test of #3 into this patch.

Just to give a little more of a push for this; I fired up a fresh instance of the entire Dramble stack (I re-imaged all the 6 Pi microSD cards, then reprovisioned everything, and installed Drupal 8 HEAD from this morning), and now it seems about every 5th or 6th page load (when logged in) results in a WSOD on first load, then if I refresh, the page loads fine.

I currently have the Nginx balancer set to go round-robin, with no IP pinning, so each request goes to a new web node behind the balancer. If I turn IP pinning on, then requests work correctly. But in the real world, most requests would be distributed amongst the backend servers, resulting in users hitting the WSOD pages on initial page load.

The error in the Nginx log on the backend server is as follows:

2015/07/04 22:22:59 [error] 2290#0: *52 FastCGI sent in stderr: "PHP message: PHP Fatal error:  Class '__TwigTemplate_813b6bb6bcccc2ae6f6de69fbc5bf6c3ebe61f1c97eb2e81de9e4d330bb17c61' not found in /var/www/drupal/core/lib/Drupal/Core/Template/TwigEnvironment.php on line 141" while reading response header from upstream, client: 10.0.1.60, server: 10.0.1.61, request: "GET /admin/reports/dblog?page=2 HTTP/1.0", upstream: "fastcgi://unix:/var/run/php5-fpm.sock:", host: "pidramble.com", referrer: "http://pidramble.com/admin/reports/dblog?page=1"

I definitely still agree with 'Major' priority... might even argue for Critical, since now I can reproduce this error in three different environments—running Debian 7.8 with PHP 7.0.0 beta1 compiled, I get errors like the following on every 3-5 page loads:

Error: Class '__TwigTemplate_408ac94a722c70a8d9e243d9eebb745aeff646c4fc11d22dd91885dbb5553bce' not found in Drupal\Core\Template\TwigEnvironment->loadTemplate() (line 141 of core/lib/Drupal/Core/Template/TwigEnvironment.php).

This is on a Raspberry Pi with slow disk writes (since Drupal is running on a microSD card)... maybe the slow disk access is causing the template to not be found? The compiled directory/file is most definitely present at sites/default/files/php/twig/1#40#8a#c94a722c70a8d9e243d9eebb745aeff646c4fc11d22dd91885dbb5553bce, but the .php file is empty...

Though the Pi is an exceptional use case, I have definitely seen weird/slow disk writes in many cloud environments, and I can imagine more people will run into these issues as well.

Update: It seems that it may have been a weird case of FPM having some split-brained behavior. A full restart of the server seems to have cleared up the errors this time; maybe different child processes had different/broken cached file directory information or something.

I can't get the test-only to fail, but here's something.

Still RTBC in my book—and that test probably won't ever fail unless you can make testbots do multiple concurrent requests (#2527478: Resolve infinite stampede in mtime protected PHP storage should help). Let's stop the bleeding...

+++ b/core/modules/system/src/Tests/Theme/TwigEnvironmentTest.php
@@ -46,6 +47,19 @@ public function testInlineTemplate() {
+    $cache_file = $environment->getCacheFilename($name);
...
+      '#template' => $name,

Don't we add something by now to inline template names in the InlineLoader?

I think if we want to fool the cache, we need to do the same {# #} comment adding here ...

Yup that is probably needed to calculate the cache filename properly: https://api.drupal.org/api/drupal/core%21lib%21Drupal%21Core%21Template%...

Doing a quick test of this:
$cache_file = $environment->getCacheFilename('{# inline_template_start #}' . $name);

Seemed to result in an infinite loop for me. Not sure why…

Edit: And also combined with doing an actual inline template like @Fabianx suggested earlier: Hello World - {{ 1+0 }}.

Hmm, maybe lets use a real template then instead of an inline template or call twig_render_template directly?

Reroll of #108; test file changed.

Note that this patch is still necessary to get things working with Drupal 8 on my little Raspberry Pi cluster, using GlusterFS for a shared files directory mount. I seem to have encountered another race condition over in #2540912: Installation fails with files directory on glusterfs: "Warning: mkdir(): File exists", but it looks like that one is resolved by #2497243-188: Replace Symfony container with a Drupal one, stored in cache.

I'd been assuming this was self-healing, but had missed berdir's comment in https://www.drupal.org/node/2429659#comment-9845943 where he pointed out the site was down permanently until they manually intervened. Since berdir's site is more or less the only 8.x site with any traffic at the moment, we should assume that people will run into this more often.

I'm bumping this to critical. However also this is pretty much there except for test coverage. Given it's very hard to test, and we have months of manual testing on patched installs, let's add the regression test in a follow-up issue.

RTBC then, we can fix the test in a follow-up. (and should create one for it)

I've seen this problem too so agree that this is quite critical

Should we not remove the test and put it back in the follow-up?

Or is it worth having the test there to avoid a further regression which might actually make the test fail? If so I could go for that, but I think it needs a @todo in the test to point out that we've not been able to get it to fail.

Patch with bugfix-only is attached. I'll split the test into a separate patch for a follow-up issue, to be opened momentarily...

Updated IS, since it's been a while...

Added related issue #2541440: Add tests for race conditions in Twig template cache for the tests. I'll supply the first patch, with the broken out test, over there.

Can we get an RTBC on the above reroll without the tests?

I kinda think we should add a @todo linking to the issue mentioning, and also mention that there is no coverage for that code.

I kinda think we should add a @todo linking to the issue mentioning, and also mention that there is no coverage for that code.

+1 for that idea. Yeah race conditions can be hard to test, this is for sur.

Thank you @geerlingguy for updating the issue summary.

From the look of this, the main bug is actually in \Drupal\Component\PhpStorage\FileStorage, this has more race conditions than lines of code.

The main problem is the implementation of PhpStorageInterface::save(), which is basically a wrapper around file_put_contents() and as a consequence has two major problems:

• First, it is not protected against partial writes. By default file_put_contents() doesn't perform any kind of locking, which means that readers are going to see partial content. Because the readers are using @include, all the errors are ignored, and partial content is most likely going to appear as a cache miss (but really, who knows? we could also totally load a partial template, or execute some arbitrary code);
• Second, it doesn't call fsync() on the file, which means that the write is not guaranteed to be immediately committed (and as a consequence visible from the other nodes in a distributed filesystem).

We need to implement a standard "write to a temporary file, flush and rename" protocol here.

We could also use a fixed name for the temporary file, and lock it with LOCK_EX, which might or might not help with stampedes. (Nowadays, most distributed filesystems have locking primitives, but it might be only local to the node.)

Edited: cross-post with the first part of #125.

So, should I stick a @todo mentioning the other issue in the loadTemplate() method, or somewhere else?

#127: Lets add the @todo to the test that the current test is non-functional and will be fixed in that other issue.

@Fabianx - latest patch (#119) removes the test entirely as per #118 and above comments. Should we add that test back in for now, and leave the @todo with that test, or keep the test out for now, and put the todo with the changed function?

Oh, I missed #119. The code does not need a comment as the test is major.

The patch attached improves the situation so I'm going ahead before beta 13 since this is not disruptive at all. I agree with @Damien Tournoud and @znerol - the real issue will be solved in #2527478: Resolve infinite stampede in mtime protected PHP storage which looks promising.

Committed 7595aa7 and pushed to 8.0.x. Thanks!

I'm working on #2555243: Upgrade path / plan to Twig 2.x aka 2.0 which involves porting some of our custom code in TwigEnvironment into a new Twig cache class.

I'm wondering if #2527478: Resolve infinite stampede in mtime protected PHP storage maybe makes this change no longer necessary. I'm a bit stuck because I don't see a way right now to incorporate this "just in case" handling into the cache class I'm writing so I'd like to ask for some testing to see if this issue can be reproduced with the current code.

If @geerlingguy or @Berdir or anyone else who was able to reproduce this can test the following patch that would be extremely helpful:

#2426563-93: Ignore: Patch testing issue
https://www.drupal.org/files/issues/upgrade_twig_test_1.x-cache4.patch

I tried it myself using @geerlingguy's Drupal VM steps in #96 on Drupal 8 HEAD with the patch and couldn't reproduce any errors. However I also tested on Drupal 8 commit b158c354b15abee86b58c2342c985456392d44a8 (based on the timestamp of #96) and was still not able to reproduce the error so I don't consider my testing to be definitive. I also tried with an older version of Drupal VM (3d5b33be5c974f4e26c96947d4f82239231c5301) just in case but still no luck breaking it.

Actually I just got it to break using Drupal 8 b158c354b15abee86b58c2342c985456392d44a8 and the latest Drupal VM. Yay! I'll try with the patch on D8 HEAD a few more times.

Development has now moved to a proper issue of its own (#2568171: Upgrade to Twig 1.22 and implement our own cache class) and we have some plans now for re-implementing this fallback in our cache class. Still would be good to have it tested manually once we have some code because we don't have automated tests for it.