set silently fails for values with long expiration parameter (resolved)
I am having a strange problem on Membase 1.7.1 with spymemcached 2.7.3.
The write succeeds (status OK is returned), but the key is not inserted.
This happens only for some key/values - mostly it works fine.
I am querying the key using Moxi and telnet, and just get "END".
I've debugged spymemcached down to nio and there are no errors, it appears to legitimately receive OK response from the server.
My values are byte arrays, in this case it's about 4000 bytes long.
My expiration value is set to 52 days.
There are no errors in the membase web console.
Is there any logging that can be enabled on membase side to see what's going on with this set?
I am going to try setting up TAP to see if this key/value comes out on that end.
Thanks in advance!
I will try to create a runnable test case, but for now please consider the tap output using tap_example.py.
#the following is results of doing a set with 0 expiration and a fake value using telnet and moxi
CMD_TAP_MUTATION: ``79112:PDN:CP:CHIOK:04112:04412:1:91594::RACK'' (vb:297) -> ``12345'' (5 bytes from ('10.228.17.108', 11210))
CMD_TAP_MUTATION: ``79112:PDN:CP:CHIOK:04112:04412:1:91594::RACK'' (vb:297) -> ``12345'' (5 bytes from ('10.228.17.134', 11210))
#result of inserting the actual value using the app
CMD_TAP_MUTATION: ``79112:PDN:CP:CHIOK:04112:04412:1:91594::RACK'' (vb:297) -> ``??????&???
CMD_TAP_DELETE: ``79112:PDN:CP:CHIOK:04112:04412:1:91594::RACK'' (vb:297) -> ``'' (0 bytes from ('10.228.17.108', 11210))
CMD_TAP_DELETE: ``79112:PDN:CP:CHIOK:04112:04412:1:91594::RACK'' (vb:297) -> ``'' (0 bytes from ('10.228.17.134', 11210))Note that the mutation value when printed out somehow prevents the rest of the log entry from being printed (N bytes from ...).
All runs of tap_example.py use opts = {memcacheConstants.TAP_FLAG_BACKFILL: 0xffffffffffffffff} to indicate that only future changes are to be returned.
Some additional findings:
Curiously, the very first output is frequently some variation of a delete on one or both nodes.
When my app is calling set, it is:
CMD_TAP_MUTATION: ``79112:PDN:CP:CHIOK:04112:04412:1:91594::RACK'' (vb:297) -> (4012 bytes from ('10.228.17.108', 11210))
CMD_TAP_DELETE: ``79112:PDN:CP:CHIOK:04112:04412:1:91594::RACK'' (vb:297) -> (0 bytes from ('10.228.17.108', 11210))sometimes followed or preceeded by a mutation on 10.228.17.134 without a subsequent delete.
I've verified by debugging spymemcached that 10.228.17.108 is the master server for vbucket 297
I was able to track down the root cause.
The problem is caused by large values of the expiration time parameter.
Once i figured that out i found that memcache's protocol.txt specifies the following:
"Some commands involve a client sending some kind of expiration time
(relative to an item or to an operation requested by the client) to
the server. In all such cases, the actual value sent may either be
Unix time (number of seconds since January 1, 1970, as a 32-bit
value), or a number of seconds starting from current time. In the
latter case, this number of seconds may not exceed 60*60*24*30 (number
of seconds in 30 days); if the number sent by a client is larger than
that, the server will consider it to be real Unix time value rather
than an offset from current time."
Also, it is important to use UTC timezone to calculate the Unix time.
So, there is no membase bug here, yay :)
When I looked over your post I originally overlooked that you had such a high expiration time. Thanks for posting your findings, I'm sure someone else will run into this issue and find this post useful.
That is very strange, can you provide a test program that reproduces the behavior?