Notice: Trying to get property of non-object in _dmemcache_get_pieces()

@jcnventura thanks for reporting the bug and providing a patch! Can you retest with the attached? I've made the following changes:

• Updated documentation, we never return FALSE
• Don't exit function early so we provide debug logging and statistics

I just applied this patch, didn't test much but it seems to work as advertised. Thanks.

patched also seems to work here.
2 ppl for such a small change seems enough imo.

Hi,
Is this getting committed? I just had the same issue in an Acquia environment and the patch fixed it for me.
Cheers,

This patch also fixed the problem for us (also Acquia in case that would matter).

This patch caused some wierd bugs for us. Wildcard cache clears stopped working correctly and this caused stale data to be returned and for some cache elements to never be rebuilt. It was unexpected and was pinpointed to this patch, removing it instantly fixed the issue.

We are testing the change in #10 in production.

This patch causes wildcard flushing issues for us too (also on Acquia).

I changed line 330 to:

$data .= isset($piece->data) ? $piece->data : '';

Seems to have fixed the problem as far as I can see, after some playing around with the stats in the footer the hit/miss levels seem fairly consistent.

It does seem like a case of fixing the symptom rather than the cause, but until a better solution comes along this does seem to fix the immediate problem.

Marking as needs work. We need a "final" patch based on #10 & #12.

Adding a patch for fixing the notice issue.

+++ b/dmemcache.inc
@@ -364,7 +364,7 @@ function _dmemcache_key_piece($key, $id) {
+ *   The item which was originally saved or an empty array.

Minor detail: for developers working with this code, it would be helpful if we document when the return value will be an empty array. Eg. "The item which was originally saved, or an empty array if [some situation occurred]."

Patch #14 is not working, I am providing a new one that is covering both #10 and #12.

We picked up patch #16 and ran into an obscure issue where Views would get stuck in cache. We are running on Acquia.

Here's where I've run into problems (Acquia environment)

* PHP 7.1.18, memcached PHP extension 3.0.4, memcache server v1.5.3
* PHP 7.2.6, memcached PHP extension 3.0.4, memcache server v1.5.3
* PHP 5.6.36, memcached PHP extension 2.2.0, memcache server v1.5.3

Here's where I've had success:

* PHP 5.6.36, memcache (no d) PHP extension 3.0.8, memcache server v1.5.3

So this seems to be a clear issue with the memcached (with a d) extension for PHP... both PHP 5.6 and PHP 7.x, at least in Acquia environment.

I can also reliably reproduce this simply by clearing cache via the performance page :(

What's frustrating is that I cannot reproduce it locally, even with the same version of memcached PHP ext, same version of memcache server, and similar version of PHP (7.2.8 local vs 7.2.6 on Acquia). I think I'll have to try and debug this on Acquia environment w/o having access to xdebug which will be rough!

Many of the patches above seem to try and fix it by just hiding the real problem, which is that for some reason multi-part cache data is not being saved properly. In some cases, all "parts" of the cache data don't exist, and in other cases, only the last part exists but the first parts don't.

Trying to debug this on Acquia using error_log statements, it's clear that large multipart data is not actually being saved to memcache. In some cases, the call to "set" on the memcached object returns just fine, indicating it worked. But checking the contents of memcached directly (telnet localhost 11211 and then run "get [cid]" indicates that it was not actually saved for some reason. In other cases, I was actually seeing that the memcached object returned result code "10" which is just mapped to "SERVER ERROR".

I was able to reproduce this more reliably by simply creating >1MiB of data and running a cache_set() with it. I was able to get it work reliably for this sample data when I decreased the size of the each "part" of the data (controlled via var "memcache_data_max_length") to a value like ~100KiB lower. But then that change didn't seem to make a difference when applied to my non-sample data :(

I think it would be incredibly helpful if anyone who was experiencing this provided more detailed about their environment:

1. Version of PHP
2. Version of libmemcached (check PHP info to get this)
3. Version of memcached server
4. Version of memcache/memcached PHP extension you're using

Another update:

I've isolated the problem further and it's not related to how the Memcached module is saving the data. I created a sample script where just the pure PHP Memcached extension function is used to save large data to the cache and it fails in the same way: Some of the cached items don't persist!

Attached is the script I used if anyone would like to test it as well.

The script works by just storing 10 items to the cache, where each item is about 1MiB. In my testing in Acquia environment w/ Memcached extension, only the last item is actually saved.

Saving 1048500 of data with cache CID 0622b: Success; Result Code: 0
Saving 1048500 of data with cache CID 37d2e: Success; Result Code: 0
Saving 1048500 of data with cache CID bf320: Success; Result Code: 0
Saving 1048500 of data with cache CID 3a993: Success; Result Code: 0
Saving 1048500 of data with cache CID 77b2e: Success; Result Code: 0
Saving 1048500 of data with cache CID 8d917: Success; Result Code: 0
Saving 1048500 of data with cache CID 03526: Success; Result Code: 0
Saving 1048500 of data with cache CID e65c6: Success; Result Code: 0
Saving 1048500 of data with cache CID 408c4: Success; Result Code: 0
Saving 1048500 of data with cache CID 18e02: Success; Result Code: 0
Fetching 0622b: No item found
Fetching 37d2e: No item found
Fetching bf320: No item found
Fetching 3a993: No item found
Fetching 77b2e: No item found
Fetching 8d917: No item found
Fetching 03526: No item found
Fetching e65c6: No item found
Fetching 408c4: No item found
Fetching 18e02: Received 1048500 bytes

But running the same script in an environment where the Memcache extension is used, it works as expected:

Saving 1048500 of data with cache CID bf68c: Success
Saving 1048500 of data with cache CID cea30: Success
Saving 1048500 of data with cache CID d7dd4: Success
Saving 1048500 of data with cache CID 71720: Success
Saving 1048500 of data with cache CID 8ccf8: Success
Saving 1048500 of data with cache CID 63793: Success
Saving 1048500 of data with cache CID 14949: Success
Saving 1048500 of data with cache CID b6f00: Success
Saving 1048500 of data with cache CID c7e3f: Success
Saving 1048500 of data with cache CID c12f0: Success
Fetching bf68c: Received 1048500 bytes
Fetching cea30: Received 1048500 bytes
Fetching d7dd4: Received 1048500 bytes
Fetching 71720: Received 1048500 bytes
Fetching 8ccf8: Received 1048500 bytes
Fetching 63793: Received 1048500 bytes
Fetching 14949: Received 1048500 bytes
Fetching b6f00: Received 1048500 bytes
Fetching c7e3f: Received 1048500 bytes
Fetching c12f0: Received 1048500 bytes

I've opened a ticket with Acquia to get some more attention on the issue. I think this is a big problem for sites as they are migrating to PHP 7, where ONLY the Memcached extension is available.

To be clear, there is indeed a bug with this module where it doesn't gracefully handle the situation where multi-part cache data is not complete. That needs to be fixed so that no PHP warnings are thrown. But the root of the problem is that the Memcached extension is not actually persisting the data properly in the first place.

Despite everything I've said, we still need to fix the bug in the module. I think the change in this patch is all that's needed and I can't imagine how this would cause any strange issues like people say other patches are doing. This just ensures that if any part of the multi-part cache data is missing, it will just return a cache miss like it should.

Subbing to this one; can see it happening in PHP 7.1.18 / memcached 3.0.4 / memcache server 1.5.3 on Acquia infrastructure. The patch in #22 seems to at least hide the message. Looking forward to finding out what's going on.

Confirmed that #22 seems to have at least solved the symptom. Following to see if there's any more info on what the root cause is. Could there be a problem with what is being written to the memcache?

Mike Lewis, can you please confirm what hosting environment you're in? Memcache vs Memcached library, PHP version, etc.

Confirming this issue on Acquia when switching PHP version from 5.6 to 7.1

Also confirming this problem on Acquia PHP 7.1.18 with memcached 3.0.4 and that #22 hides the messages.

I do think that the analysis on #21 should be posted on https://github.com/php-memcached-dev/php-memcached/issues for them to better debug this, but this fix should be commited soon, specially since Acquia will drop support to PHP 5.6 on October and memcache (without a d) is not supported on PHP 7

Any reason to not commit this patch?

I vote for RTBC

I hesitated to post this to the memcached library issue queue because I cannot reproduce it locally. That's the first thing the maintainers will ask for. I only observe the behavior on an Acquia server. If anyone can reproduce this issue in a local environment please let me know so I can duplicate that environment.

Indeed, I've managed to reproduce this problem only once on my local environment, and I don't know how exactly. And this replicates very often on Acquia servers. I have a docker image that resembles almost exactly an Acquia server configuration, but still no luck.

Could the number of client instances that access a single memcached daemon process play a role?

+++ b/dmemcache.inc
@@ -327,6 +327,12 @@ function _dmemcache_get_pieces($item, $key, $bin = 'cache', $mc = NULL) {
+    // The piece may be NULL if it didn't exist in memcache. If so,
+    // we have to just return false for the entire set because we won't
+    // be able to reconstruct the original data without all the pieces.
+    if (is_null($piece)) {
+      return FALSE;
+    }

I would prefer to use if (!$piece), but that is a large nit that can be fixed on commit.

However it means that dmemcache_get_multi lies to us as the piece_count does match, but the item is empty ...

RTBC +1 for this

However it means that dmemcache_get_multi lies to us as the piece_count does match, but the item is empty ...

This is true, but since dmemcache_get_multi is used in 2 other places, and is quite a complicated function, I didn't want to change something in there to correct. It could be refactored in a separate issue I think.

This does also happen with memcache extension, because we create it ourselves:

from dmemcache_get_multi():

      // Order is not guaranteed, map responses to order of requests.
      if (is_array($results)) {
        $keys = array_fill_keys($full_keys, NULL);
        $results = array_merge($keys, $results);
      }

See:

https://3v4l.org/em4Lr

and I bet if you specify Memcached::GET_PRESERVE_ORDER, that it then returns NULL for things not present.
as it needs to preserve the order, so cannot have missing keys.

So the main bug is this:

  // Retrieve all the pieces of data.
  $pieces = dmemcache_get_multi($keys, $bin, $mc);
  if (count($pieces) != $item->piece_count) {
    // Some of the pieces don't exist, so our data cannot be reconstructed.
    return FALSE;
  }

This check will _never_ be true, because keys will be filled.

A good check (or the patch I RTBC'ed) would be:

if (array_filter($pieces) != $item->piece_count) {
  return FALSE;
}

but as we loop anyway we can also do the check there.

Was just a wrong assumption on the code.

Putting to major, not critical.

There is a risk of unserialize() working even if piece data is missing and hence returning a corrupted cache item, but that is not that likely.

It can happen though and is a data consistency issue.

Found another bug in reviewing this however (which is what people ran in with the original patch) so posting here, because it is related in a way:

  // If $results is FALSE, convert it to an empty array.
  if (!$results) {
    $results = array();
    _dmemcache_write_debug('getMulti', $bin, implode(',', $full_keys), FALSE);
  }

This is wrong.

Needs to be:

$results = array();
$keys = array_fill_keys($full_keys, NULL);
$results = array_merge($keys, $results);

so that we always have the same behaviour for non-existing keys: An array keyed by keys with the value being NULL.

So we can fix this here as well.

And fixed by Jeremy above. Thanks all!

Re-opening to apply the same fix to the D6 codebase.

Re: Comment #21 from @bkosborne and how Memcache vs. Memcached works differently on Acquia.

On Acquia the Memcache extension (the one that worked on the tests) has compression on by default--therefore the script used is storing a repeating string into memcached, which then is compressed by the Memcache PHP extension into a much-smaller-sized item, and usually Memcache does not need to evict smaller items as frequently because there's "more room" available.

Otherwise, if no compression would be used (or, if the actual full contents of each cached item were indeed randomized instead of just repeating a single character), the fact that the Memcache daemon has usually very few Memcache "slots" of size 1MB available will of course cause almost-immediate eviction on sequential sets of the same-sized object (which is very possibly what is being observed by @bkosborne when using the Memcached Extension during the above test).

Doing some testing using https://github.com/memcached/memcached/blob/master/scripts/memcached-tool one can readily associate "number of evictions" to "number of items whose get() failed" when testing the script. This tool will also show how many "slots" of each slab size (up to 1024kB) are available, if they are full, the Max Age of the items in each slab, number of evictions, etc. For example, "Max age" should eventually report 0 if you run the script on Acquia with the Memcached PHP extension (or on any other environment which has few 1024kb-sized slots in the Memcache daemon).

@janusman, thank you! I think that explains everything!

I hadn't realized that the memcache extension was compressing the data. Once I disabled compression (by setting the INI directive memcache.compress_threshold to a very large number), I observed the same behavior as I was seeing with the "troublesome" memcached extension!

So, as you said, I guess it comes down to the small number of 1024KiB slabs available. When attempting to write multiple items of the same size, only the last few will persist because the previous ones are immediately purged, as there's not enough available large stabs to use.

This also explains why I had no problem reproducing this in a local testing environment. When starting my local environment, memcached has zero data in it. When I feed it many large items to store (~1MiB each), it will create as many pages of 1MiB slabs as it can, and in fact I can basically have it fill up all available memcached memory with these large slabs. But in Acquia where the memcache server already has tons of data in it, it refuses to allocate additional 1MiB slabs because there's no space for it.

These findings reinforce the importance of getting #2958403: enable compression by default with memcached extension committed. According to the changelog for the old "memcache" extension, compression has been enabled by default since version 3.0.3. So users that switch to PHP 7 (and thus the memcached extension, which does NOT enable compression by default) will suddenly be making far less efficient use of storage on their memcached storage.

@Jeremy - Is is possible to get a new 7.x release? There have been a number of commits now since the last one.

I plan to focus on a 7.x release after we get the first stable 8.x release out the door.

#40 Unless I miss something I think the "chunk_size" used by memcache module to split things is configurable.

Of course 512kB items will be way less effective than 1 MB items, but if you run out of slabs for 1 MB items, then maybe a lower threshold will work better.

But it indeed also explains why compression helps so much even if the bigger piece even compressed does not fit, because then the 1 MB chunked slices will be of different sizes and hence end up in different slabs and not all in the 1 MB piece slot.

A good way to put compression out of the picture is to use a truly random string with lots of entropy.

As of 2016, Drupal 6 is end of life and no longer supported, do we really need to leave the issue open?

Then I guess we can close it :)

Agree. I'll just mark it as Fixed so it can auto-close.

Maybe tag it for 7.x since it was not back-ported to 6.x