Memcached::touch() behaving weird and closing connection to daemon

[nadiamoe]

Hi,

I have the following code, which is run twice over the same persistent memcached connection, with binary protocol enabled:

    $user = $this->memcached->get($session);
    echo "Get: " . $this->memcached->getResultMessage() . "\n";
    //var_dump($user);
    if ($user) {
        $this->memcached->touch($session, time() + $this->config->memcached_expiration);
        echo "Touch: " . $this->memcached->getResultMessage() . "\n";
        $this->memcached->touch($user, time() + $this->config->memcached_expiration);
        echo "Touch: " . $this->memcached->getResultMessage() . "\n";
        return $user;
    } else {
        return null;
    }

(this code is whithin a function, hence the return calls)

Which produces the following output:

Get: SUCCESS
Touch: SERVER END
Touch: SUCCESS
Get: A TIMEOUT OCCURRED
Get: NOT FOUND

Or sometimes:

Get: SUCCESS
Touch: SERVER END
Touch: SUCCESS
Get: UNKNOWN READ FAILURE: Connection refused
Get: NOT FOUND

The server log (for the second output, precisely) is:

28: going from conn_new_cmd to conn_waiting
28: going from conn_waiting to conn_read
28: going from conn_read to conn_parse_cmd
28: Client using the binary protocol
<28 Read binary protocol data:
<28    0x80 0x07 0x00 0x00
<28    0x00 0x00 0x00 0x00
<28    0x00 0x00 0x00 0x00
<28    0x00 0x00 0x00 0x00
<28    0x00 0x00 0x00 0x00
<28    0x00 0x00 0x00 0x00
>28 Writing bin response:
>28   0x81 0x07 0x00 0x00
>28   0x00 0x00 0x00 0x00
>28   0x00 0x00 0x00 0x00
>28   0x00 0x00 0x00 0x00
>28   0x00 0x00 0x00 0x00
>28   0x00 0x00 0x00 0x00
28: going from conn_parse_cmd to conn_mwrite
28: going from conn_mwrite to conn_closing
<28 connection closed.
<30 new auto-negotiating client connection
<28 new auto-negotiating client connection
28: going from conn_new_cmd to conn_waiting
28: going from conn_waiting to conn_read
28: going from conn_read to conn_parse_cmd
28: Client using the binary protocol
<28 Read binary protocol data:
<28    0x80 0x0d 0x00 0x20
<28    0x00 0x00 0x00 0x00
<28    0x00 0x00 0x00 0x20
<28    0x00 0x00 0x00 0x00
<28    0x00 0x00 0x00 0x00
<28    0x00 0x00 0x00 0x00
28: going from conn_parse_cmd to conn_nread
<28 GET 8892ada1a13b7e0fb683352a5228ee1f
> FOUND KEY 8892ada1a13b7e0fb683352a5228ee1f
>28 Writing bin response:
>28   0x81 0x0d 0x00 0x20
>28   0x04 0x00 0x00 0x00
>28   0x00 0x00 0x00 0x2a
>28   0x00 0x00 0x00 0x00
>28   0x00 0x00 0x00 0x00
>28   0x00 0x00 0x00 0x00
28: going from conn_nread to conn_mwrite
28: going from conn_mwrite to conn_new_cmd
28: going from conn_new_cmd to conn_parse_cmd
<28 Read binary protocol data:
<28    0x80 0x0a 0x00 0x00
<28    0x00 0x00 0x00 0x00
<28    0x00 0x00 0x00 0x00
<28    0x00 0x00 0x00 0x00
<28    0x00 0x00 0x00 0x00
<28    0x00 0x00 0x00 0x00
>28 Writing bin response:
>28   0x81 0x0a 0x00 0x00
>28   0x00 0x00 0x00 0x00
>28   0x00 0x00 0x00 0x00
>28   0x00 0x00 0x00 0x00
>28   0x00 0x00 0x00 0x00
>28   0x00 0x00 0x00 0x00
28: going from conn_parse_cmd to conn_mwrite
28: going from conn_mwrite to conn_new_cmd
28: going from conn_new_cmd to conn_waiting
28: going from conn_waiting to conn_read
28: going from conn_read to conn_parse_cmd
<28 Read binary protocol data:
<28    0x80 0x1c 0x00 0x20
<28    0x04 0x00 0x00 0x00
<28    0x00 0x00 0x00 0x24
<28    0x00 0x00 0x00 0x00
<28    0x00 0x00 0x00 0x00
<28    0x00 0x00 0x00 0x00
28: going from conn_parse_cmd to conn_nread
<28 TOUCH 8892ada1a13b7e0fb683352a5228<31 new auto-negotiating client connection
ee1f
31: going from conn_new_cmd to conn_waiting
31: going from conn_waiting to conn_read
31: going from conn_read to conn_parse_cmd
31: Client using the binary protocol
<31 Read binary protocol data:
<31    0x80 0x1c> FOUND KEY 8892ada1a13b7e0fb683352a5 0x00 0x06
<31    0x04 0x00 0x00228ee1f
>28 Writing bin response:
>28   0x81 0x1c 0x00 0x00
>28   0x04 0x00 0x00 0x00
>28   0x00 0x00 0x00 0x04
>28   0x00 0x00 0x00 0x00
>28   0x00 0x00 0x00 0x00
>28   0x00 0x00 0x00 0x00
28: going from conn_nread to conn_mwrite
 0x00
<31    0x00 0x00 0x00 0x0a
<31    0x00 0x00 0x00 0x00
<31    0x00 0x00 0x00 0x00
<31    0x00 0x00 0x00 0x00
31: going from conn_parse_cmd to conn_nread
<31 TOUCH roobre
> FOUND KEY roobre
>31 Writing bin response:
>31   0x81 0x1c 0x00 0x00
>31   0x04 0x00 0x00 0x00
>31   0x00 0x00 0x00 0x04
>31   0x00 0x00 0x00 0x00
>31   0x00 0x00 0x00 0x00
>31   0x00 0x00 0x00 0x00
31: going from conn_nread to conn_mwrite
28: going from conn_mwrite to conn_new_cmd
28: going from conn_new_cmd to conn_waiting
28: going from conn_waiting to conn_read
31: going from conn_mwrite to conn_new_cmd
31: going from conn_new_cmd to conn_waiting
31: going from conn_waiting to conn_read
28: going from conn_read to conn_parse_cmd
<28 Read binary protocol data:
<28    0x80 0x0d 0x00 0x20
<28    0x00 0x00 0x00 0x00
<28    0x00 0x00 0x00 0x20
<28    0x00 0x00 0x00 0x00
<28    0x00 0x00 0x00 0x00
<28    0x00 0x00 0x00 0x00
28: going from conn_parse_cmd to conn_nread
<28 GET 8892ada1a13b7e0fb683352a5228ee1f
> FOUND KEY 8892ada1a13b7e0fb683352a5228ee1f
>28 Writing bin response:
>28   0x81 0x0d 0x00 0x20
>28   0x04 0x00 0x00 0x00
>28   0x00 0x00 0x00 0x2a
>28   0x00 0x00 0x00 0x00
>28   0x00 0x00 0x00 0x00
>28   0x00 0x00 0x00 0x00
28: going from conn_nread to conn_mwrite
28: going from conn_mwrite to conn_new_cmd
28: going from conn_new_cmd to conn_waiting
28: going from conn_waiting to conn_read
28: going from conn_read to conn_parse_cmd
<28 Read binary protocol data:
<28    0x80 0x0a 0x00 0x00
<28    0x00 0x00 0x00 0x00
<28    0x00 0x00 0x00 0x00
<28    0x00 0x00 0x00 0x00
<28    0x00 0x00 0x00 0x00
<28    0x00 0x00 0x00 0x00
>28 Writing bin response:
>28   0x81 0x0a 0x00 0x00
>28   0x00 0x00 0x00 0x00
>28   0x00 0x00 0x00 0x00
>28   0x00 0x00 0x00 0x00
>28   0x00 0x00 0x00 0x00
>28   0x00 0x00 0x00 0x00
28: going from conn_parse_cmd to conn_mwrite
28: going from conn_mwrite to conn_new_cmd
28: going from conn_new_cmd to conn_waiting
28: going from conn_waiting to conn_read
28: going from conn_read to conn_closing
<28 connection closed.
<28 new auto-negotiating client connection
31: going from conn_read to conn_closing
28: going from conn_new_cmd to conn_waiting
28: going from conn_waiting to conn_read
<31 connection closed.
28: going from conn_read to conn_parse_cmd
28: Client using the binary protocol
<28 Read binary protocol data:
<28    0x80 0x07 0x00 0x00
<28    0x00 0x00 0x00 0x00
<28    0x00 0x00 0x00 0x00
<28    0x00 0x00 0x00 0x00
<28    0x00 0x00 0x00 0x00
<28    0x00 0x00 0x00 0x00
>28 Writing bin response:
>28   0x81 0x07 0x00 0x00
>28   0x00 0x00 0x00 0x00
>28   0x00 0x00 0x00 0x00
>28   0x00 0x00 0x00 0x00
>28   0x00 0x00 0x00 0x00
>28  <31 new auto-negotiating client connection
 0x00 0x00 0x00 0x00
28: going from conn_parse_cmd to conn_mwrite
28: going from conn_mwrite to conn_closing
<28 connection closed.

Versions:

root@Tenshi:~# php -v
PHP 5.4.4-14+deb7u14 (cli) (built: Aug 21 2014 08:36:44) 
Copyright (c) 1997-2012 The PHP Group
Zend Engine v2.4.0, Copyright (c) 1998-2012 Zend Technologies
root@Tenshi:~# memcached -h
memcached 1.4.13
[...]
root@Tenshi:~# php --rextension memcached | head
Extension [ <persistent> extension #49 memcached version 2.0.1 ] {

[mkoppanen]

Which version of libmemcached and php-memcached are you using?

[nadiamoe]

Sorry, forgot to add that:

root@Tenshi:~# php --rextension memcached | head
Extension [ <persistent> extension #49 memcached version 2.0.1 ] {

How can I check the libmemcached version?

EDIT: Libmemcached files seem to be under /usr/share/doc/libmemcached10/. Is 10 enough detail?

[mkoppanen]

Testing with libmemcached 1.0.17 and current trunk version of PHP memcached extension. My test script looks like the following:

--TEST--
Test for bug 155
--SKIPIF--
<?php if (!extension_loaded("memcached")) print "skip"; ?>
--FILE--
<?php
include dirname (__FILE__) . '/config.inc';

$m = new Memcached ();

$m->setOption(Memcached::OPT_BINARY_PROTOCOL,true);
$m->addServer(MEMC_SERVER_HOST, MEMC_SERVER_PORT);

$key = 'bug_155_' . uniqid();

$m->set ($key, 'test', time() + 86400);

$m->get ($key);
echo "GET: " . $m->getResultMessage() . PHP_EOL;

$m->touch ($key, time() + 86400);
echo "TOUCH: " . $m->getResultMessage() . PHP_EOL;

$m->touch ($key, time() + 86400);
echo "TOUCH: " . $m->getResultMessage() . PHP_EOL;

$m->get ($key);
echo "GET: " . $m->getResultMessage() . PHP_EOL;

$m->get ($key);
echo "GET: " . $m->getResultMessage() . PHP_EOL;

echo "DONE" . PHP_EOL;

--EXPECT--
GET: SUCCESS
TOUCH: SUCCESS
TOUCH: SUCCESS
GET: SUCCESS
GET: SUCCESS
DONE

And the test passes. Can you provide your libmemcached version?

[nadiamoe]

Hi, thanks for the testing. Just note the key was added to the memcached server on a previous persistent connection, not sure if relevant tho. Also didn't commented it on the first post, but commenting out the touch lines fixes the problem entirely.

My libmemcached version is:

root@Tenshi:~# dpkg -l libmemcached10
Desired=Unknown/Install/Remove/Purge/Hold
| Status=Not/Inst/Conf-files/Unpacked/halF-conf/Half-inst/trig-aWait/Trig-pend
|/ Err?=(none)/Reinst-required (Status,Err: uppercase=bad)
||/ Name           Version      Architecture Description
+++-==============-============-============-==================================
ii  libmemcached10 1.0.8-1      amd64        C and C++ client library to the me

[mkoppanen]

Based on my tests this functionality seems to be broken on some versions of libmemcached. See failing versions here:

https://travis-ci.org/php-memcached-dev/php-memcached/builds/39128294

[nadiamoe]

It seems it's a libmemcached problem at the end. However, upgrading libmemcached it's not possible for me atm, so I'll need to workaround this somehow.

If you allow me a single side question, are any other operations which reset the timeout? Maybe overwriting the same key with Memcached::add()?

Regards.

[sodabrew]

Resolving with text in the README that recommends newer revisions of libmemcached.