Memcached not actual deleting? #233

Open
pfischermx opened this Issue Dec 15, 2016 · 10 comments

Projects

None yet

2 participants

@pfischermx
pfischermx commented Dec 15, 2016 edited

Howdy!

So we have session locking and use memcached for it (for the record, this is all done via php session management with its internal support for memcache), by going through the memcache flow the process is:

  1. A new request is done to our service.
  2. A session starts, this triggers an 'ADD' to verify that a lock key associated with the session does not exists, if it exists then it keeps checking if the lock is gone.
  3. Once the request of 1) is completed a SET is done where the session is saved to memcache (a SET).
  4. And followed by DELETE the lock key.

The problem that I'm trying to fix is: there are some cases where the session would stay in memcache even after the DELETE, to look for the root cause the I looked at maybe PHP had a bug or memcached was unreliable (connection timeout) and the DELETE never happened, so I added metrics to monitor this and it was always 1-2ms, what I'd expect from memcache.

So then I looked with tcpdump on the memcached host and waited and waited for a lock to happen and bingo, I could see:

req> add session.lock.abcdefg
reply> STORED
req> get session.lock.abcdefg
reply> VALUE session.lock.abcdefg 0 N
req> set session.lock.abdefg
reply> STORED
req> delete session.lock.abdefg
reply> DELETED
...
req> add session.lock.abcdefg
reply> STORED
req> get session.lock.abcdefg
reply> VALUE session.lock.abcdefg 0 N
req> set session.lock.abdefg
reply> STORED
req> delete session.lock.abdefg
reply> DELETED
...
req> add session.lock.abcdefg
reply> NOT_STORED

So I'm wondering:

a) Is it a known bug?
b) Any other things that I can look? It is clear that memcached replied with DELETE but the key existed (verified by in another terminal then doing a get to it, the key existed).

screen shot 2016-12-14 at 7 07 58 pm

The memcached version is: 1.4.25 (ubuntu, 1.4.25-2ubuntu1.2)

@dormando
Member
dormando commented Dec 15, 2016 edited

Not a known bug, but your version is kind of old and may be vendor patched.

        item_unlink(it);
        item_remove(it);      /* release our reference */
        out_string(c, "DELETED");

It's not really possible for those functions to fail. The DELETE is printed after the item has been removed from the hash table, so it can't even fail asynchronously.

Is it possible you're double add'ing the lock somewhere? Or add'ing at the same time as the delete's happening? Items are independently globally locked so simultaneous or near simultaneous actions could fail (ie; thread A gets the DELETE first, but is descheduled by the OS for a millisecond for some reason. Thread B handles the ADD).

That's far fetched though. The problem is likely simpler. Any chance you could try a newer version? possibly use the new logging to get a synchronizeable log of actions (it has GID's)

@pfischermx

Thanks for the reply, @dormando.

Initially (after opening this bug) had the suspicion that maybe the session id was not really unique and that entropy wasn't enough (which would be very weird and bad) so today we added logging to our systems to track how the session is moving across requests and sadly the answer is that the session is unique and that there are no other requests that could be double-adding.

Upgrading is going to be a bit problematic but we will need to do it, specially since our pool for sessions is hashed so taking a host out would need all those session could get lost.

@dormando
Member

Sorry :/ That's 8 versions old and if this is a real bug it'll be hard to find.

Getting logging out of your current version requires restarting it anyway (unless you're already redirecting stdout/stderr somewhere). Under newer versions logging is done at runtime, at least.

I doubt it's a bug on the server but lets work through it to figure out what's going on anyway.

@dormando
Member

(also; if possible output from the various stats commands (stats, items, slabs, settings) is super useful. you can send to me privately if posting here isn't possible)

@dormando
Member

poke :)

@pfischermx

Sorry, the weekend crossed.

Here is the output of stats:

STAT pid 4082
STAT uptime 4025819
STAT time 1482178857
STAT version 1.4.25 Ubuntu
STAT libevent 2.0.21-stable
STAT pointer_size 64
STAT rusage_user 44765.088000
STAT rusage_system 69118.400000
STAT curr_connections 57
STAT total_connections 240726
STAT connection_structures 108
STAT reserved_fds 10
STAT cmd_get 1002616208
STAT cmd_set 2585363349
STAT cmd_flush 0
STAT cmd_touch 0
STAT get_hits 916629890
STAT get_misses 85986318
STAT delete_misses 162427
STAT delete_hits 994537811
STAT incr_misses 0
STAT incr_hits 7
STAT decr_misses 0
STAT decr_hits 0
STAT cas_misses 0
STAT cas_hits 0
STAT cas_badval 0
STAT touch_hits 0
STAT touch_misses 0
STAT auth_cmds 0
STAT auth_errors 0
STAT bytes_read 1002620268934
STAT bytes_written 825120378149
STAT limit_maxbytes 7114588160
STAT accepting_conns 1
STAT listen_disabled_num 0
STAT time_in_listen_disabled_us 0
STAT threads 2
STAT conn_yields 0
STAT hash_power_level 25
STAT hash_bytes 268435456
STAT hash_is_expanding 0
STAT malloc_fails 0
STAT bytes 4321749344
STAT curr_items 27296480
STAT total_items 1994523717
STAT expired_unfetched 54585787
STAT evicted_unfetched 0
STAT evictions 0
STAT reclaimed 55503129
STAT crawler_reclaimed 0
STAT crawler_items_checked 0
STAT lrutail_reflocked 0
END

the stats items output is a little bit bigger so I pasted it on gist: https://gist.github.com/pfischermx/fe1e05f1e24f6d05be727f2da1a115bb

for slabs: https://gist.github.com/pfischermx/dcbe194529ef78b99a1f2095ec2ab0e8

And as for settings:

STAT maxbytes 7114588160
STAT maxconns 8192
STAT tcpport 11211
STAT udpport 11211
STAT inter 0.0.0.0
STAT verbosity 1
STAT oldest 0
STAT evictions on
STAT domain_socket NULL
STAT umask 700
STAT growth_factor 1.25
STAT chunk_size 48
STAT num_threads 2
STAT num_threads_per_udp 2
STAT stat_key_prefix :
STAT detail_enabled no
STAT reqs_per_event 75
STAT cas_enabled yes
STAT tcp_backlog 1024
STAT binding_protocol auto-negotiate
STAT auth_enabled_sasl no
STAT item_size_max 1048576
STAT maxconns_fast no
STAT hashpower_init 0
STAT slab_reassign no
STAT slab_automove 0
STAT lru_crawler no
STAT lru_crawler_sleep 100
STAT lru_crawler_tocrawl 0
STAT tail_repair_time 0
STAT flush_enabled yes
STAT hash_algorithm jenkins
STAT lru_maintainer_thread no
STAT hot_lru_pct 32
STAT warm_lru_pct 32
STAT expirezero_does_not_evict no
END
@dormando
Member

Nothing looks obviously wrong.

@dormando
Member

Hey,

Looking at your output more closely; can you confirm there aren't typos in it?

req> add session.lock.abcdefg
reply> STORED
req> get session.lock.abcdefg
reply> VALUE session.lock.abcdefg 0 N

This section is operating on effectively key abcdefg. Key presently exists.

req> set session.lock.abdefg
reply> STORED
req> delete session.lock.abdefg
reply> DELETED

Now key abdefg. Key did exist, is now deleted.

...
req> add session.lock.abcdefg
reply> STORED
req> get session.lock.abcdefg
reply> VALUE session.lock.abcdefg 0 N

Now abcdefg again. Key did not exist, now exists. (There's an elipses; not sure what was missing)

req> set session.lock.abdefg
reply> STORED
req> delete session.lock.abdefg
reply> DELETED

Now abdefg again. Key was set, and deleted again.

...
req> add session.lock.abcdefg
reply> NOT_STORED

Elipses, and now abcdefg fails to add. Most recent known state of abcdefg is that it did exist. So the NOT_STORED here is correct. The output's been switching between two distinct values, with memcached operating properly.

@dormando
Member

It's also possible that while looking at tcpdump you'll be getting prints out of order. So that's why I'm recommending the logger under newer versions; it includes GIDs which you can serialize the order of operations with.

@dormando
Member
dormando commented Jan 5, 2017

Poking again.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment