Failed to save key "%5BTsBet%5CPlayer%5CEntity%5CBE%5CDiscountsBirthdays%5D%5B1%5D" (array) #21995

Ere5 · 2017-03-14T12:08:09Z

Q	A
Bug report?	yes
Feature request?	no
BC Break report?	no
RFC?	no
Symfony version	3.2.6

I'm using symfony 3.2.6 on production server getting errors regarding array cache adapter.

Stack trace.

NoticedError: Failed to save key "%5BTsBet%5CPlayer%5CEntity%5CBE%5CDiscountsBirthdays%5D%5B1%5D" (array)
in newrelic_notice_error called at /var/www/vhosts/app/api.example.com/releases/20170314153900_dev/vendor/monolog/monolog/src/Monolog/Handler/NewRelicHandler.php (91)
in Monolog\Handler\NewRelicHandler::write called at /var/www/vhosts/app/api.example.com/releases/20170314153900_dev/app/cache/prod/classes.php (8132)
in Monolog\Handler\AbstractProcessingHandler::handle called at /var/www/vhosts/app/api.example.com/releases/20170314153900_dev/app/cache/prod/classes.php (8634)
in Monolog\Logger::addRecord called at /var/www/vhosts/app/api.example.com/releases/20170314153900_dev/app/cache/prod/classes.php (8725)
in Monolog\Logger::warning called at /var/www/vhosts/app/api.example.com/releases/20170314153900_dev/app/cache/prod/classes.php (1409)
in Symfony\Component\Cache\CacheItem::log called at /var/www/vhosts/app/api.example.com/releases/20170314153900_dev/app/cache/prod/classes.php (1029)
in Symfony\Component\Cache\Adapter\AbstractAdapter::commit called at /var/www/vhosts/app/api.example.com/releases/20170314153900_dev/app/cache/prod/classes.php (997)
in Symfony\Component\Cache\Adapter\AbstractAdapter::save called at /var/www/vhosts/app/api.example.com/releases/20170314153900_dev/vendor/symfony/symfony/src/Symfony/Component/Cache/Adapter/ChainAdapter.php (64)
in Symfony\Component\Cache\CacheItem::Symfony\Component\Cache\Adapter{closure} called at /var/www/vhosts/app/api.example.com/releases/20170314153900_dev/vendor/symfony/symfony/src/Symfony/Component/Cache/Adapter/ChainAdapter.php (84)
in Symfony\Component\Cache\Adapter\ChainAdapter::getItem called at /var/www/vhosts/app/api.example.com/releases/20170314153900_dev/app/cache/prod/classes.php (2705)
in Symfony\Component\Cache\DoctrineProvider::doFetch called at /var/www/vhosts/app/api.example.com/releases/20170314153900_dev/app/cache/prod/classes.php (2591)
in Doctrine\Common\Cache\CacheProvider::fetch called at /var/www/vhosts/app/api.example.com/releases/20170314153900_dev/vendor/doctrine/annotations/lib/Doctrine/Common/Annotations/CachedReader.php (188)
in Doctrine\Common\Annotations\CachedReader::fetchFromCache called at /var/www/vhosts/app/api.example.com/releases/20170314153900_dev/vendor/doctrine/annotations/lib/Doctrine/Common/Annotations/CachedReader.php (78)
in Doctrine\Common\Annotations\CachedReader::getClassAnnotations called at /var/www/vhosts/app/api.example.com/releases/20170314153900_dev/vendor/doctrine/orm/lib/Doctrine/ORM/Mapping/Driver/AnnotationDriver.php (63)
in Doctrine\ORM\Mapping\Driver\AnnotationDriver::loadMetadataForClass called at /var/www/vhosts/app/api.example.com/releases/20170314153900_dev/vendor/doctrine/common/lib/Doctrine/Common/Persistence/Mapping/Driver/MappingDriverChain.php (102)
in Doctrine\Common\Persistence\Mapping\Driver\MappingDriverChain::loadMetadataForClass called at /var/www/vhosts/app/api.example.com/releases/20170314153900_dev/vendor/doctrine/orm/lib/Doctrine/ORM/Mapping/ClassMetadataFactory.php (151)
in Doctrine\ORM\Mapping\ClassMetadataFactory::doLoadMetadata called at /var/www/vhosts/app/api.example.com/releases/20170314153900_dev/vendor/doctrine/common/lib/Doctrine/Common/Persistence/Mapping/AbstractClassMetadataFactory.php (332)
in Doctrine\Common\Persistence\Mapping\AbstractClassMetadataFactory::loadMetadata called at /var/www/vhosts/app/api.example.com/releases/20170314153900_dev/vendor/doctrine/orm/lib/Doctrine/ORM/Mapping/ClassMetadataFactory.php (78)
in Doctrine\ORM\Mapping\ClassMetadataFactory::loadMetadata called at /var/www/vhosts/app/api.example.com/releases/20170314153900_dev/vendor/doctrine/common/lib/Doctrine/Common/Persistence/Mapping/AbstractClassMetadataFactory.php (216)
in Doctrine\Common\Persistence\Mapping\AbstractClassMetadataFactory::getMetadataFor called at /var/www/vhosts/app/api.example.com/releases/20170314153900_dev/vendor/doctrine/orm/lib/Doctrine/ORM/EntityManager.php (281)

PS. with 3.2.3 version there was no errors like this. PHP version 5.6.26

nicolas-grekas · 2017-03-14T12:29:22Z

Can you please apply #21996 an report any additional info that it may provide?

Ere5 · 2017-03-15T21:05:17Z

What kind of information i can provide to approve fix for this?

nicolas-grekas · 2017-03-15T21:09:08Z

you can apply the patch in #21996 and report the new log messages (you should have more context info)

Ere5 · 2017-03-16T07:55:43Z

it's impossible to apply patch on production servers. On stage and dev environments can't reproduce this issue. Will try again today.

…olas-grekas) This PR was merged into the 3.2 branch. Discussion ---------- [Cache] Enhance error reporting for FilesystemAdapter | Q | A | ------------- | --- | Branch? | 3.2 | Bug fix? | yes | New feature? | no | BC breaks? | no | Deprecations? | no | Tests pass? | yes/no | Fixed tickets | - | License | MIT | Doc PR | - So that we can provide feedback for cases like #21995 Commits ------- ebb316d [Cache] Enhance error reporting for FilesystemAdapter

emodus · 2017-04-10T11:39:36Z

Hi,
centos 6.5
php5.6
Symfony 3.2.7
production pool servers still giving same errors

NoticedError: Failed to save key "Symfony.Component.Form.Form" (Symfony\Component\Validator\Mapping\ClassMetadata)
in newrelic_notice_error called at /var/www/vhosts/app/api.example.com/releases/20170410133820_dev/vendor/monolog/monolog/src/Monolog/Handler/NewRelicHandler.php (91)
in Monolog\Handler\NewRelicHandler::write called at /var/www/vhosts/app/api.example.com/releases/20170410133820_dev/app/cache/prod/classes.php (8163)
in Monolog\Handler\AbstractProcessingHandler::handle called at /var/www/vhosts/app/api.example.com/releases/20170410133820_dev/app/cache/prod/classes.php (8665)
in Monolog\Logger::addRecord called at /var/www/vhosts/app/api.example.com/releases/20170410133820_dev/app/cache/prod/classes.php (8756)
in Monolog\Logger::warning called at /var/www/vhosts/app/api.example.com/releases/20170410133820_dev/app/cache/prod/classes.php (1421)
in Symfony\Component\Cache\CacheItem::log called at /var/www/vhosts/app/api.example.com/releases/20170410133820_dev/app/cache/prod/classes.php (1029)
in Symfony\Component\Cache\Adapter\AbstractAdapter::commit called at /var/www/vhosts/app/api.example.com/releases/20170410133820_dev/app/cache/prod/classes.php (997)
in Symfony\Component\Cache\Adapter\AbstractAdapter::save called at /var/www/vhosts/app/api.example.com/releases/20170410133820_dev/vendor/symfony/symfony/src/Symfony/Component/Cache/Adapter/ChainAdapter.php (64)
in Symfony\Component\Cache\CacheItem::Symfony\Component\Cache\Adapter\{closure} called at /var/www/vhosts/app/api.example.com/releases/20170410133820_dev/vendor/symfony/symfony/src/Symfony/Component/Cache/Adapter/ChainAdapter.php (84)
in Symfony\Component\Cache\Adapter\ChainAdapter::getItem called at /var/www/vhosts/app/api.example.com/releases/20170410133820_dev/vendor/symfony/symfony/src/Symfony/Component/Validator/Mapping/Cache/Psr6Cache.php (47)
in Symfony\Component\Validator\Mapping\Cache\Psr6Cache::read called at /var/www/vhosts/app/api.example.com/releases/20170410133820_dev/vendor/symfony/symfony/src/Symfony/Component/Validator/Mapping/Factory/LazyLoadingMetadataFactory.php (102)
in Symfony\Component\Validator\Mapping\Factory\LazyLoadingMetadataFactory::getMetadataFor called at /var/www/vhosts/app/api.example.com/releases/20170410133820_dev/vendor/symfony/symfony/src/Symfony/Component/Validator/Validator/RecursiveContextualValidator.php (349)
in Symfony\Component\Validator\Validator\RecursiveContextualValidator::validateObject called at /var/www/vhosts/app/api.example.com/releases/20170410133820_dev/vendor/symfony/symfony/src/Symfony/Component/Validator/Validator/RecursiveContextualValidator.php (163)
in Symfony\Component\Validator\Validator\RecursiveContextualValidator::validate called at /var/www/vhosts/app/api.example.com/releases/20170410133820_dev/vendor/symfony/symfony/src/Symfony/Component/Validator/Validator/RecursiveValidator.php (115)
in Symfony\Component\Validator\Validator\RecursiveValidator::validate called at /var/www/vhosts/app/api.example.com/releases/20170410133820_dev/vendor/symfony/symfony/src/Symfony/Component/Form/Extension/Validator/EventListener/ValidationListener.php (55)
in Symfony\Component\Form\Extension\Validator\EventListener\ValidationListener::validateForm called at ? (?)
in call_user_func called at /var/www/vhosts/app/api.example.com/releases/20170410133820_dev/app/cache/prod/classes.php (3720)
in Symfony\Component\EventDispatcher\EventDispatcher::doDispatch called at /var/www/vhosts/app/api.example.com/releases/20170410133820_dev/app/cache/prod/classes.php (3635)
in Symfony\Component\EventDispatcher\EventDispatcher::dispatch called at /var/www/vhosts/app/api.example.com/releases/20170410133820_dev/vendor/symfony/symfony/src/Symfony/Component/EventDispatcher/ImmutableEventDispatcher.php (43)
in Symfony\Component\EventDispatcher\ImmutableEventDispatcher::dispatch called at /var/www/vhosts/app/api.example.com/releases/20170410133820_dev/vendor/symfony/symfony/src/Symfony/Component/Form/Form.php (667)```

nicolas-grekas · 2017-04-10T11:52:09Z

What is a "NoticedError" ?

emodus · 2017-04-10T11:58:07Z

We are using newrelic for monitoring production applications.

from 3.2.6 (including 3.2.7) it starts generate this type of notice errors...
sf 3.2.5 was ok.

Our monolog config:

monolog:
    handlers:
        applog:
            type: stream
            path: '%kernel.logs_dir%/%kernel.environment%.log'
            level: error
        main:
            type: fingers_crossed
            action_level: warning
            handler: file
        file:
            type: stream
            level: debug
        syslog:
            type: syslog
            level: error
        newrelic:
            type: newrelic
            level: warning

I am not sure hut our app is very busy, so maybe its cache racing, but as I mentioned in SF 3.2.5 we do not had any similar issues...

emodus · 2017-04-10T12:04:34Z

This type error raising related almost all doctrine entities... with same cache reason...

Application stats:
1500 Request per minute
0.3% cache error rate

arendjantetteroo · 2017-07-04T10:52:36Z

We are now faced with this same error blocking our deploys.
Previously we only got a few of these notices since 3.2.6 but things kept working.
Trying to upgrade to 3.2.10 now results in a continously barrage of these messages and getting our deploy scripts stuck.

I get both Failed to save key and Failed to fetch key messages.

We are using the snc redis bundle for doctrine metadata caching of mongodb doctrine annotations and trying to flush this cache on our staging server on each deploy with :
php app/console doctrine:mongodb:cache:clear-metadata --env=prod

just running php app/console --env=prod is resulting in the same messages and the console command never finishes (or not within a normal time period, ran for more than 5 minutes).

Disabling the redis bundle for metadata caching does not seem to help either.

What can i do to get you more information, so we can debug this issue?

arendjantetteroo · 2017-07-04T10:57:07Z

Found some more logs after changing the log level :
[2017-07-04 12:54:52] cache.WARNING: Failed to fetch key "DoctrineNamespaceCacheKey%5B%5D" {"key":"DoctrineNamespaceCacheKey%5B%5D","exception":"[object] (Symfony\Component\Debug\Exception\ContextErrorException(code: 0): Warning: Invalid argument supplied for foreach() at /deploy/haasdeploy/symfony3.2.10/releases/20170704122043/vendor/symfony/symfony/src/Symfony/Component/Cache/Adapter/AbstractAdapter.php:179)"} {"token":"-3fcbb165","env":"management_stage_prod","project":"/deploy/haasdeploy/symfony3.2.10/releases/20170704122043/app","file":"/deploy/haasdeploy/symfony3.2.10/releases/20170704122043/vendor/symfony/symfony/src/Symfony/Component/Cache/CacheItem.php","line":161,"class":"Symfony\Component\Cache\CacheItem","function":"log"}
[2017-07-04 12:54:53] cache.WARNING: Failed to fetch key "%5BEinder%5CHas%5CToolsBundle%5CDocument%5CToolCategory%5D%5B1%5D" {"key":"%5BEinder%5CHas%5CToolsBundle%5CDocument%5CToolCategory%5D%5B1%5D","exception":"[object] (Symfony\Component\Debug\Exception\ContextErrorException(code: 0): Warning: Invalid argument supplied for foreach() at /deploy/haasdeploy/symfony3.2.10/releases/20170704122043/vendor/symfony/symfony/src/Symfony/Component/Cache/Adapter/AbstractAdapter.php:179)"} {"token":"-3fcbb165","env":"management_stage_prod","project":"/deploy/haasdeploy/symfony3.2.10/releases/20170704122043/app","file":"/deploy/haasdeploy/symfony3.2.10/releases/20170704122043/vendor/symfony/symfony/src/Symfony/Component/Cache/CacheItem.php","line":161,"class":"Symfony\Component\Cache\CacheItem","function":"log"}
[2017-07-04 12:54:53] cache.WARNING: Failed to save key "%5BEinder%5CHas%5CToolsBundle%5CDocument%5CToolCategory%5D%5B1%5D" (array) {"key":"%5BEinder%5CHas%5CToolsBundle%5CDocument%5CToolCategory%5D%5B1%5D","type":"array","exception":"[object] (Symfony\Component\Debug\Exception\ContextErrorException(code: 0): Warning: array_keys() expects parameter 1 to be array, boolean given at /deploy/haasdeploy/symfony3.2.10/releases/20170704122043/vendor/symfony/symfony/src/Symfony/Component/Cache/Adapter/ApcuAdapter.php:95)"} {"token":"-3fcbb165","env":"management_stage_prod","project":"/deploy/haasdeploy/symfony3.2.10/releases/20170704122043/app","file":"/deploy/haasdeploy/symfony3.2.10/releases/20170704122043/vendor/symfony/symfony/src/Symfony/Component/Cache/CacheItem.php","line":161,"class":"Symfony\Component\Cache\CacheItem","function":"log"}
[2017-07-04 12:54:54] cache.WARNING: Failed to fetch key "%5B%5BC%5DEinder%5CHas%5CToolsBundle%5CDocument%5CToolCategory%5D%5B1%5D" {"key":"%5B%5BC%5DEinder%5CHas%5CToolsBundle%5CDocument%5CToolCategory%5D%5B1%5D","exception":"[object] (Symfony\Component\Debug\Exception\ContextErrorException(code: 0): Warning: Invalid argument supplied for foreach() at /deploy/haasdeploy/symfony3.2.10/releases/20170704122043/vendor/symfony/symfony/src/Symfony/Component/Cache/Adapter/AbstractAdapter.php:179)"} {"token":"-3fcbb165","env":"management_stage_prod","project":"/deploy/haasdeploy/symfony3.2.10/releases/20170704122043/app","file":"/deploy/haasdeploy/symfony3.2.10/releases/20170704122043/vendor/symfony/symfony/src/Symfony/Component/Cache/CacheItem.php","line":161,"class":"Symfony\Component\Cache\CacheItem","function":"log"}
[2017-07-04 12:54:54] cache.WARNING: Failed to save key "%5B%5BC%5DEinder%5CHas%5CToolsBundle%5CDocument%5CToolCategory%5D%5B1%5D" (integer) {"key":"%5B%5BC%5DEinder%5CHas%5CToolsBundle%5CDocument%5CToolCategory%5D%5B1%5D","type":"integer","exception":"[object] (Symfony\Component\Debug\Exception\ContextErrorException(code: 0): Warning: array_keys() expects parameter 1 to be array, boolean given at /deploy/haasdeploy/symfony3.2.10/releases/20170704122043/vendor/symfony/symfony/src/Symfony/Component/Cache/Adapter/ApcuAdapter.php:95)"} {"token":"-3fcbb165","env":"management_stage_prod","project":"/deploy/haasdeploy/symfony3.2.10/releases/20170704122043/app","file":"/deploy/haasdeploy/symfony3.2.10/releases/20170704122043/vendor/symfony/symfony/src/Symfony/Component/Cache/CacheItem.php","line":161,"class":"Symfony\Component\Cache\CacheItem","function":"log"}

Any ideas?

nicolas-grekas · 2017-07-04T15:03:12Z

I'm closing this one: very likely, the issue is that your APCu cache is full, thus yes, some keys cannot be saved.
You should monitor your APCu stats and tweak its size to fit your apps I guess.

nicolas-grekas · 2017-07-04T15:24:07Z

See also #23390 which solves a similar issue.

arendjantetteroo · 2017-07-04T16:22:37Z

In my case it seems that APCu was not enabled for the cli.
When setting apc.enable_cli=1 in php.ini these errors goes away and the console command shows the list again. I guess 23390 makes sense. Thanks @nicolas-grekas

alitvinenko · 2017-07-05T09:23:08Z

@arendjantetteroo, @nicolas-grekas thank you.
My case is equivalent to yours. APCu was not enabled for the cli.

xabbuh added Bug Cache labels Mar 14, 2017

carsonbot added the Status: Needs Review label Mar 14, 2017

nicolas-grekas mentioned this issue Mar 14, 2017

[Cache] Enhance error reporting for FilesystemAdapter #21996

Merged

javiereguiluz added the Status: Waiting feedback label Mar 15, 2017

nicolas-grekas self-assigned this Apr 17, 2017

javiereguiluz removed the Status: Waiting feedback label May 7, 2017

nicolas-grekas closed this as completed Jul 4, 2017

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Failed to save key "%5BTsBet%5CPlayer%5CEntity%5CBE%5CDiscountsBirthdays%5D%5B1%5D" (array) #21995

Failed to save key "%5BTsBet%5CPlayer%5CEntity%5CBE%5CDiscountsBirthdays%5D%5B1%5D" (array) #21995

Ere5 commented Mar 14, 2017

nicolas-grekas commented Mar 14, 2017

Ere5 commented Mar 15, 2017

nicolas-grekas commented Mar 15, 2017

Ere5 commented Mar 16, 2017 •

edited

Loading

emodus commented Apr 10, 2017 •

edited

Loading

nicolas-grekas commented Apr 10, 2017

emodus commented Apr 10, 2017 •

edited

Loading

emodus commented Apr 10, 2017

arendjantetteroo commented Jul 4, 2017 •

edited

Loading

arendjantetteroo commented Jul 4, 2017

nicolas-grekas commented Jul 4, 2017 •

edited

Loading

nicolas-grekas commented Jul 4, 2017 •

edited

Loading

arendjantetteroo commented Jul 4, 2017 •

edited

Loading

alitvinenko commented Jul 5, 2017

Failed to save key "%5BTsBet%5CPlayer%5CEntity%5CBE%5CDiscountsBirthdays%5D%5B1%5D" (array) #21995

Failed to save key "%5BTsBet%5CPlayer%5CEntity%5CBE%5CDiscountsBirthdays%5D%5B1%5D" (array) #21995

Comments

Ere5 commented Mar 14, 2017

nicolas-grekas commented Mar 14, 2017

Ere5 commented Mar 15, 2017

nicolas-grekas commented Mar 15, 2017

Ere5 commented Mar 16, 2017 • edited Loading

emodus commented Apr 10, 2017 • edited Loading

nicolas-grekas commented Apr 10, 2017

emodus commented Apr 10, 2017 • edited Loading

emodus commented Apr 10, 2017

arendjantetteroo commented Jul 4, 2017 • edited Loading

arendjantetteroo commented Jul 4, 2017

nicolas-grekas commented Jul 4, 2017 • edited Loading

nicolas-grekas commented Jul 4, 2017 • edited Loading

arendjantetteroo commented Jul 4, 2017 • edited Loading

alitvinenko commented Jul 5, 2017

Ere5 commented Mar 16, 2017 •

edited

Loading

emodus commented Apr 10, 2017 •

edited

Loading

emodus commented Apr 10, 2017 •

edited

Loading

arendjantetteroo commented Jul 4, 2017 •

edited

Loading

nicolas-grekas commented Jul 4, 2017 •

edited

Loading

nicolas-grekas commented Jul 4, 2017 •

edited

Loading

arendjantetteroo commented Jul 4, 2017 •

edited

Loading