|  support |  documentation |  report a bug |  advanced search |  search howto |  statistics |  random bug |  login
Bug #74235 Memcache returns stale or incorrect data under heavy read loads
Submitted: 2017-03-10 20:28 UTC Modified: 2017-03-10 20:29 UTC
Avg. Score:5.0 ± 0.0
Reproduced:0 of 0 (0.0%)
From: malberts at zynga dot com Assigned:
Status: Open Package: memcache (PECL)
PHP Version: 5.6.29 OS: Amazon Linux AMI 2015.03
Private report: No CVE-ID: None
View Add Comment Developer Edit
Welcome! If you don't have a Git account, you can't do anything here.
You can add a comment by following this link or if you reported this bug, you can edit this bug over here.
Block user comment
Status: Assign to:
Bug Type:
From: malberts at zynga dot com
New email:
PHP Version: OS:


 [2017-03-10 20:28 UTC] malberts at zynga dot com
I believe this bug is related to The symptoms are similar.  

 - php56 - 5.6.29 (5.6.29-1.131.amzn1)
 - php56-pecl-memcache - 3.0.8 (3.0.8-6.17.amzn1)
 - amazon linux - 3.14.35-28.38.amzn1.x86_64 #1 SMP Wed Mar 11 22:50:37 UTC 2015 x86_64 x86_64 x86_64 GNU/Linux
 - mpm prefork
 - httpd 2.4 - (2.4.25-1.68.amzn1 )

I'm noticing stale data on read. It's not 100%, fairly low volume, ~25 per hour with a request volume of 50 million per hour.

I'm able to detect the issue by either
 1. processing a netcat execution from within the script
 2. processing a secondary read

Data Context
 - key - ZAPI_IDMAPPER_72752798226
 - value on first read - {"zapi_identity_player_result_72752798226":"{\\"i\\":{\\"72613683383\\":\\"24\\",\\"72752798226\\":\\"1\\"},\\"n2p\\":{\\"72613683383\\":{\\"5003043\\":\\"72613683383\\"}}}"}
 - value on second read - {"ZAPI_IDMAPPER_72752798226":"{\\"72613683383\\":\\"24\\",\\"72752798226\\":\\"1\\"}"}
 - value on netcat - ["VALUE ZAPI_IDMAPPER_72752798226 0 38","{\\"72613683383\\":\\"24\\",\\"72752798226\\":\\"1\\"}","END"]

Notice NetCat and the secondary read returned the same value, which is the correct value ... which is not that value returned on the initial read.

I cant provide another example that mirrors the report

 - key - zapi_playerid_mapping|n2p|72752798226
 - value on first read - {"ZAPI_IDMAPPER_72752798226":"{\\"72613683383\\":\\"24\\",\\"72752798226\\":\\"1\\"}"}
 - value on second read - []
 - value on netcat - [END] 

In both cases the value returned on the first read is a value that would have been returned on a lookup at an earlier stage in the execution.  In fact, in both cases, when the value returned is incorrect, the incorrect value would have been the result of the get preceding this one in the call stack (e.g. it appears to be returning stale data from the previous call to get).


Add a Patch

Pull Requests

Add a Pull Request


AllCommentsChangesGit/SVN commitsRelated reports
 [2017-03-10 20:29 UTC] malberts at zynga dot com
-PHP Version: 5.6.30 +PHP Version: 5.6.29
 [2017-03-10 20:29 UTC] malberts at zynga dot com
correcting version to 5.6.29
 [2020-02-13 22:46 UTC] tonyp at valvesoftware dot com
We're also seeing a small number of seemingly-random memcached reads returning data for the wrong key. We think we narrowed down the problem to OOM errors in an FPM environment causing a future read to return the data from the prior (OOming) execution.

Something like:
PHP Error: PID 27163: Allowed memory size of 167772160 bytes exhausted (tried to allocate 20480 bytes)

Followed shortly by our code detecting a mismatch. Something like:
AssertMsg() failed: PID 27163: GetApp mismatched appid, got 1127610 requested 1102322 from shared memcached:app_5678416_1102322_german_public

We use MemcachePool::get for this particular read.
PHP Copyright © 2001-2020 The PHP Group
All rights reserved.
Last updated: Fri Aug 07 22:01:24 2020 UTC