twigphp / Twig

Twig, the flexible, fast, and secure template language for PHP
https://twig.symfony.com/
BSD 3-Clause "New" or "Revised" License
8.18k stars 1.25k forks source link

Call to undefined method setSourceContext() #3871

Closed hultberg closed 11 months ago

hultberg commented 1 year ago

Hello :wave:

I've been experiencing some weird call to undefined method errors from internally in twig. In production I have an apache2 webserver running mod_php with mpm_prefork and I have opcache and JIT enabled. I'm also using twig template caching with the default \Twig\Cache\FilesystemCache implementation. Deployment to production is by essentially syncing the new files into the directory (there is no symlink changes), clearing opcache, and removing the old twig cache. After a while (and seemingly at random) I get the following error which I "fix" by reloading apache2 (which clears opcache cache):

I have been unsuccessful at reproducing this error. I have also not been able to debug the issue since production crashes for everyone when it occurs giving me a quite small timeframe to resolve the issue. Searching the internet for the error message gives no helpful results.

The reason I'm reporting this issue is to get help from the people that are more familiar with twig internals in figuring it out.

The following is the stacktrace for twig:

Error: Call to undefined method Twig\\Token::setSourceContext() in /srv/app/vendor/twig/twig/src/Node/Node.php:171
Stack trace:
#0 /srv/app/vendor/twig/twig/src/Node/Node.php(171): Twig\\Node\\Node->setSourceContext()
#1 /srv/app/vendor/twig/twig/src/Node/Node.php(171): Twig\\Node\\Node->setSourceContext()
#2 /srv/app/vendor/twig/twig/src/Node/Node.php(171): Twig\\Node\\Node->setSourceContext()
#3 /srv/app/vendor/twig/twig/src/Node/Node.php(171): Twig\\Node\\Node->setSourceContext()
#4 /srv/app/vendor/twig/twig/src/Node/ModuleNode.php(55): Twig\\Node\\Node->setSourceContext()
#5 /srv/app/vendor/twig/twig/src/Parser.php(100): Twig\\Node\\ModuleNode->__construct()
#6 /srv/app/vendor/twig/twig/src/Environment.php(491): Twig\\Parser->parse()
#7 /srv/app/vendor/twig/twig/src/Environment.php(519): Twig\\Environment->parse()
#8 /srv/app/vendor/twig/twig/src/Environment.php(351): Twig\\Environment->compileSource()
#9 /srv/app/vendor/twig/twig/src/Environment.php(312): Twig\\Environment->loadTemplate()
#10 /srv/app/vendor/twig/twig/src/Environment.php(280): Twig\\Environment->load()
#11 /srv/app/src/HttpController.php(65): Twig\\Environment->render()

Twig is initialized like this in production:

<?php

$options = [
    'cache' => new \Twig\Cache\FilesystemCache('CACHEDIR', \Twig\Cache\FilesystemCache::FORCE_BYTECODE_INVALIDATION),
    'debug' => false,
    'strict_variables' => false,
];
$loader = new \Twig\Loader\FilesystemLoader(['VIEWSDIR']);
$twigEnv = new \Twig\Environment($loader, $options);
$twigEnv->addExtension(CUSTOM EXTENSION);

The custom extension adds some global variables, filters, and functions.

The twig render and display methods are used multiple times for different template parts in the app.

Deployment steps performed:

# files are synced over
dbmigrate
systemctl reload apache2
rm -r /var/cache/twig/

Specific opcache settings for the webserver (all other are default):

opcache.enable = On
opcache.enable_cli = Off
opcache.memory_consumption = 512
opcache.interned_strings_buffer = 128
opcache.max_wasted_percentage = 15
opcache.max_accelerated_files = 130987
opcache.use_cwd = On
opcache.validate_timestamps = Off
opcache.file_update_protection = 0
opcache.save_comments = On
opcache.jit = tracing
opcache.jit_buffer_size = 64M

Versions:

PHP 8.2.8
Apache 2.4.41
Twig 3.5.1
stof commented 1 year ago

there is no reason to have a Twig\Token inside the list of child nodes of a Node. This could happen if a broken extension instantiates a broken node (not respecting the contract of the Node constructor). But without the code of the extensions you use, I cannot check whether this is the case.

hultberg commented 1 year ago

@stof Here is the custom TwigExtension class with modifications and business logic removed:

EDIT: to be clear, the business logic is just more functions and filters. All of the functions and filters use callables and one or two use is_safe=html

<?php

namespace App;

use App\Utils;
use App\User;
use App\AccessManager;
use App\TranslatorInterface;
use Twig\Extension\AbstractExtension;
use Twig\Extension\GlobalsInterface;
use Twig\TwigFilter;
use Twig\TwigFunction;

class TwigExtension extends AbstractExtension implements GlobalsInterface
{
    public function __construct(
        private User|null $globalUser,
        private AccessManager $accessManager,
        private TranslatorInterface $translator,
    ) { }

    public function getGlobals(): array
    {
        return [
            '_globals' => [
                'user' => $this->globalUser ? [
                    'id' => $this->globalUser->getId(),
                    'name' => $this->globalUser->getName(),
                ] : null,
            ],
        ];
    }

    public function getFunctions()
    {
        return [
            new TwigFunction('datediff', Utils::dateDifference(...)),
            new TwigFunction('has_read_access', fn (string $key): bool => $this->accessManager->hasReadAccess($key)),
            new TwigFunction('has_write_access', fn (string $key): bool => $this->accessManager->hasWriteAccess($key)),
            new TwigFunction('csrf_token', Utils::generateCsrfToken(...)),
        ];
    }

    public function getFilters(): array
    {
        return [
            new TwigFilter('lang', $this->getLanguageString(...)),
            new TwigFilter('trans', $this->translator->trans(...)),
            new TwigFilter('trans_choice', $this->translator->transChoice(...)),
        ];
    }

    /**
     * @param string|string[] $tag
     * @return string
     */
    private function getLanguageString($tag): string
    {
        // LEGACY LANGUAGE
        return 'legacy' . $tag;
    }
}
hultberg commented 1 year ago

@stof The twig template used in the specific stacktrace is mostly just html and some filter calls to lang and trans, and verbatim blocks.

hultberg commented 1 year ago

@stof I attempted to reproduce this bug by running loads of requests and calling opcache_reset repeatedly in a while loop. In my testing I did get the same exception with apache2 segfaults but I have not been able to reproduce consistently yet. In production there are no segfaults and when the setSourceContext exception occurs the site is broken until I reset opcache.

I have attached different exception stack traces since the exception message varies:

Error: Call to a member function setSourceContext() on int in /srv/app/vendor/twig/twig/src/Node/Node.php:171
Stack trace:
#0 /srv/app/vendor/twig/twig/src/Node/Node.php(171): Twig\\Node\\Node->setSourceContext()
#1 /srv/app/vendor/twig/twig/src/Node/Node.php(171): Twig\\Node\\Node->setSourceContext()
#2 /srv/app/vendor/twig/twig/src/Node/Node.php(171): Twig\\Node\\Node->setSourceContext()
#3 /srv/app/vendor/twig/twig/src/Node/Node.php(171): Twig\\Node\\Node->setSourceContext()
#4 /srv/app/vendor/twig/twig/src/Node/Node.php(171): Twig\\Node\\Node->setSourceContext()
#5 /srv/app/vendor/twig/twig/src/Node/Node.php(171): Twig\\Node\\Node->setSourceContext()
#6 /srv/app/vendor/twig/twig/src/Node/Node.php(171): Twig\\Node\\Node->setSourceContext()
#7 /srv/app/vendor/twig/twig/src/Node/ModuleNode.php(55): Twig\\Node\\Node->setSourceContext()
#8 /srv/app/vendor/twig/twig/src/Parser.php(100): Twig\\Node\\ModuleNode->__construct()
#9 /srv/app/vendor/twig/twig/src/Environment.php(491): Twig\\Parser->parse()
#10 /srv/app/vendor/twig/twig/src/Environment.php(519): Twig\\Environment->parse()
#11 /srv/app/vendor/twig/twig/src/Environment.php(351): Twig\\Environment->compileSource()
#12 /srv/app/vendor/twig/twig/src/Environment.php(312): Twig\\Environment->loadTemplate()
#13 /srv/app/vendor/twig/twig/src/Environment.php(280): Twig\\Environment->load()
#14 /srv/app/HttpController.php(2824): Twig\\Environment->render()
#17 {main}
Error: Call to a member function setSourceContext() on null in /srv/app/vendor/twig/twig/src/Node/Node.php:171
Stack trace:
#0 /srv/app/vendor/twig/twig/src/Node/Node.php(171): Twig\\Node\\Node->setSourceContext()
#1 /srv/app/vendor/twig/twig/src/Node/Node.php(171): Twig\\Node\\Node->setSourceContext()
#2 /srv/app/vendor/twig/twig/src/Node/Node.php(171): Twig\\Node\\Node->setSourceContext()
#3 /srv/app/vendor/twig/twig/src/Node/Node.php(171): Twig\\Node\\Node->setSourceContext()
#4 /srv/app/vendor/twig/twig/src/Node/ModuleNode.php(55): Twig\\Node\\Node->setSourceContext()
#5 /srv/app/vendor/twig/twig/src/Parser.php(100): Twig\\Node\\ModuleNode->__construct()
#6 /srv/app/vendor/twig/twig/src/Environment.php(491): Twig\\Parser->parse()
#7 /srv/app/vendor/twig/twig/src/Environment.php(519): Twig\\Environment->parse()
#8 /srv/app/vendor/twig/twig/src/Environment.php(351): Twig\\Environment->compileSource()
#9 /srv/app/vendor/twig/twig/src/Environment.php(312): Twig\\Environment->loadTemplate()
#10 /srv/app/vendor/twig/twig/src/Environment.php(294): Twig\\Environment->load()
#11 Twig\\Environment->display()
meistro2k commented 1 year ago

What happens if you disable JIT using opcache.jit_buffer_size=0, do you still get the setSourceContext errors appearing in production?

RocketMan commented 11 months ago

FWIW, I got a similar error when upgrading from PHP 8.2.12 to 8.2.13 in my development environment.

I'm using Apache PHP mod, JIT enabled, Twig template cache disabled.

Restarting Apache had no effect. However, disabling JIT cleared the issue. I also found that it continued to work as expected after re-enabling JIT.

PHP Fatal error:  Uncaught Error: Call to a member function setSourceContext() on null in /srv/http/zookeeper/vendor/twig/twig/src/Node/Node.php:171
Stack trace:
#0 /srv/http/zookeeper/vendor/twig/twig/src/Node/Node.php(171): Twig\\Node\\Node->setSourceContext()
#1 /srv/http/zookeeper/vendor/twig/twig/src/Node/Node.php(171): Twig\\Node\\Node->setSourceContext()
#2 /srv/http/zookeeper/vendor/twig/twig/src/Node/Node.php(171): Twig\\Node\\Node->setSourceContext()
#3 /srv/http/zookeeper/vendor/twig/twig/src/Node/Node.php(171): Twig\\Node\\Node->setSourceContext()
#4 /srv/http/zookeeper/vendor/twig/twig/src/Node/Node.php(171): Twig\\Node\\Node->setSourceContext()
#5 /srv/http/zookeeper/vendor/twig/twig/src/Node/Node.php(171): Twig\\Node\\Node->setSourceContext()
#6 /srv/http/zookeeper/vendor/twig/twig/src/Node/Node.php(171): Twig\\Node\\Node->setSourceContext()
#7 /srv/http/zookeeper/vendor/twig/twig/src/Node/ModuleNode.php(55): Twig\\Node\\Node->setSourceContext()
#8 /srv/http/zookeeper/vendor/twig/twig/src/Parser.php(100): Twig\\Node\\ModuleNode->__construct()
#9 /srv/http/zookeeper/vendor/twig/twig/src/Environment.php(491): Twig\\Parser->parse()
#10 /srv/http/zookeeper/vendor/twig/twig/src/Environment.php(519): Twig\\Environment->parse()
#11 /srv/http/zookeeper/vendor/twig/twig/src/Environment.php(351): Twig\\Environment->compileSource()
#12 /srv/http/zookeeper/vendor/twig/twig/src/Environment.php(312): Twig\\Environment->loadTemplate()
#13 /srv/http/zookeeper/engine/TemplateFactory.php(107): Twig\\Environment->load()
#14 /srv/http/zookeeper/ui/UIController.php(175): ZK\\Engine\\TemplateFactory->load()
#15 /srv/http/zookeeper/controllers/Dispatcher.php(50): ZK\\UI\\UIController->processRequest()
#16 /srv/http/zookeeper/index.php(38): ZK\\Controllers\\Dispatcher->processRequest()
#17 {main}
  thrown in /srv/http/zookeeper/vendor/twig/twig/src/Node/Node.php on line 171

AH00052: child pid 17234 exit signal Segmentation fault (11)
hultberg commented 11 months ago

A quick update from my side. I disabled JIT in production and this issue has not occurred since that. The issue seem too be related to the JIT somehow. I've been reading that JIT is being reworked for php 8.4 so this issue might become moot at some point in the future.

fabpot commented 11 months ago

Closing then as it doesn't seem we can't do anything about it.