Re: Memcached Binary protocol

[watul123]

I don't think its SASL, if I am following the memcached logs correctly then 
its failing while doing a read from FD(it gets zero bytes which results in 
READ_ERROR). Look at the following back to back fail and success. Read 
fails well before the SASL(auth and etc) comes into picture, *but 
surprisingly it fails only when SASL is enabled.* 

Interesting thing is, I tried the same thing on 5 different 
machines(RHEL6/5 VM), among which it works perfect on two machine(this is 
very confusing for me) and fails on 3 machines(VM). At tcp level I don't 
see any difference in the working and non working machines. Is there any 
tuning( at system level) which may needs to be done to make this 
Memcache-SASL combination to work?  

Just to go further, I was monitoring the FD's of the process memcached 
(under /proc/memcache_pid/fd), the thing I observed is whenever my app gets 
the MEMCACHED_TIMEOUT there are two new fds, and whenever my app gets 
"Success"  there is only one new FD (36 in my case), like below. (Note:- I 
tried with db handle open option and in that case I see one FD points to 
db, but still in every failure I see two new FDs apart from the db handle 
fd, and in case of success only one new FD which is 36)  


*lrwx-- 1 root root 64 May  2 15:39 37 -> socket:[39863]lrwx-- 1 
root root 64 May  2 15:39 36 -> socket:[39861]*


*Memcached Logs*<36 new binary client connection.
36: going from conn_new_cmd to conn_waiting
36: going from conn_waiting to conn_read
36: going from conn_read to conn_parse_cmd
<36 Read binary protocol data:
<360x80 0x20 0x00 0x00
<360x00 0x00 0x00 0x00
<360x00 0x00 0x00 0x00
<360x00 0x02 0x00 0x00
<360x00 0x00 0x00 0x00
<360x00 0x00 0x00 0x00
authenticated() in cmd 0x20 is true
>36 Writing bin response:
>36   0x81 0x20 0x00 0x00
>36   0x00 0x00 0x00 0x00
>36   0x00 0x00 0x00 0x05
>36   0x00 0x02 0x00 0x00
>36   0x00 0x00 0x00 0x00
>36   0x00 0x00 0x00 0x00
36: going from conn_parse_cmd to conn_mwrite
36: going from conn_mwrite to conn_new_cmd
36: going from conn_new_cmd to conn_waiting
36: going from conn_waiting to conn_read
36: going from conn_read to conn_parse_cmd
<36 Read binary protocol data:
<360x80 0x21 0x00 0x05
<360x00 0x00 0x00 0x00
<360x00 0x00 0x00 0x16
<360x00 0x02 0x00 0x00
<360x00 0x00 0x00 0x00
<360x00 0x00 0x00 0x00
authenticated() in cmd 0x21 is true
36: going from conn_parse_cmd to conn_nread
mech:  ``PLAIN'' with 17 bytes of data
sasl result code:  0
>36 Writing bin response:
>36   0x81 0x21 0x00 0x00
>36   0x00 0x00 0x00 0x00
>36   0x00 0x00 0x00 0x0d
>36   0x00 0x02 0x00 0x00
>36   0x00 0x00 0x00 0x00
>36   0x00 0x00 0x00 0x00
36: going from conn_nread to conn_mwrite
36: going from conn_mwrite to conn_new_cmd
36: going from conn_new_cmd to conn_waiting
36: going from conn_waiting to conn_read
36: going from conn_read to conn_parse_cmd
<36 Read binary protocol data:
<360x80 0x01 0x00 0x4d
<360x08 0x00 0x00 0x00
<360x00 0x00 0x00 0xa1
<360x00 0x01 0x00 0x00
<360x00 0x00 0x00 0x00
<360x00 0x00 0x00 0x00
authenticated() in cmd 0x01 is true
36: going from conn_parse_cmd to conn_nread
<36 SET 
abcdefghij999 
Value len is 76
> FOUND KEY 
abcdefghij999
>36 Writing bin response:
>36   0x81 0x01 0x00 0x00
>36   0x00 0x00 0x00 0x00
>36   0x00 0x00 0x00 0x00
>36   0x00 0x01 0x00 0x00
>36   0x00 0x00 0x00 0x00
>36   0x00 0x00 0x00 0x04
36: going from conn_nread to conn_mwrite
36: going from conn_mwrite to conn_new_cmd
36: going from conn_new_cmd to conn_waiting
36: going from conn_waiting to conn_read
36: going from conn_read to conn_parse_cmd
<36 Read binary protocol data:
<360x80 0x0c 0x00 0x4d
<360x00 0x00 0x00 0x00
<360x00 0x00 0x00 0x4d
<360x00 0x03 0x00 0x00
<360x00 0x00 0x00 0x00
<360x00 0x00 0x00 0x00
authenticated() in cmd 0x0c is true
36: going from conn_parse_cmd to conn_nread
<36 GET 
abcdefghij999
> FOUND KEY 
abcdefghij999
>36 Writing bin response:
>36   0x81 0x0c 0x00 0x4d
>36   0x04 0x00 0x00 0x00
>36   0x00 0x00 0x00 0x9d
>36   0x00 0x03 0x00 0x00
>36   0x00 0x00 0x00 0x00
>36   0x00 0x00 0x00 0x00
36: going from conn_nread to conn_mwrite
36: going from conn_mwrite to conn_new_cmd
36: going from conn_new_cmd to conn_waiting
36: going from conn_waiting to conn_read
36: going from conn_read to conn_parse_cmd
<36 Read binary protocol data:
<360x80 0x07 0x00 0x00
<360x00 0x00 0x00 0x00
<360x00 0x00 0x00 0x00
<360x00 0x04 0x00 0x00
<360x00 0x00 0x00 0x00
<360x00 0x00 0x00 0x00
authenticated() in cmd 0x07 is true
>36 Writing bin response:
>36   0x81 0x07 0x00 0x00
>36   0x00 0x00 0x00 0x00
>36   0x00 0x00 0x00 0x00
>36   0x00 0x04 0x00 0x00
>36   0x00 0x00 0x00 0x00
>36   0x00 

Re: Memcached Binary protocol

[dormando]

Sounds like the underlying SASL service is failing sometimes? I don't
think there's anything in the memcached code that would cause this.

On Sat, 29 Apr 2017, watul123 wrote:

> I am using same connection once the connection is established. What I see so 
> far is the inconsistency in the establishing the connection itself. As
> pasted above in the logs, for same password/user name, same setup, same test 
> program, same memcached bin, if I run the test program multiple times from
> command line,  memcached_set either returns success or the 
> timeout(MEMCACHED_TIMEOUT). The logs from the server side shows..
>
>  going from conn_read to conn_closing
> <36 connection closed.
> 36: going from conn_closing to conn_closed
>
> If the connection establishment is successful then I can set/get "n" number 
> of values without any issue.
>  
>
> On Wednesday, April 26, 2017 at 11:57:43 PM UTC-7, Dormando wrote:
>   Are you reusing connections, or re-SASL'ing every time? I wonder if the
>   underlying sasl daemon/mechanism is failing. SASL stuff is only ever
>   checked when the connection is first established. All requests after the
>   connection setup is fine.
>
>   On Wed, 26 Apr 2017, watul123 wrote:
>
>   > I think the binary protocol just works as expected, there is nothing 
> to do with length as well, it was my test program where I commented
>   out the below
>   > line
>   > "memcached_behavior_set(cache, MEMCACHED_BEHAVIOR_BINARY_PROTOCOL, 
> 1);"
>   >
>   > After fixing(un commenting) this line, no matter what length the 
> key/value are , it's success all the time.
>   >
>   > The actual issue is with SASL- connection gets closed all of sudden 
> like below, and the app gets Set Timeout, where as same thing gives
>   success some time
>   > Failed
>   > <36 new binary client connection.
>   > 36: going from conn_new_cmd to conn_waiting
>   > 36: going from conn_waiting to conn_read
>   > 36: going from conn_read to conn_parse_cmd
>   > <36 Read binary protocol data:
>   > <36    0x80 0x20 0x00 0x00
>   > <36    0x00 0x00 0x00 0x00
>   > <36    0x00 0x00 0x00 0x00
>   > <36    0x00 0x02 0x00 0x00
>   > <36    0x00 0x00 0x00 0x00
>   > <36    0x00 0x00 0x00 0x00
>   > authenticated() in cmd 0x20 is true
>   > >36 Writing bin response:
>   > >36   0x81 0x20 0x00 0x00
>   > >36   0x00 0x00 0x00 0x00
>   > >36   0x00 0x00 0x00 0x05
>   > >36   0x00 0x02 0x00 0x00
>   > >36   0x00 0x00 0x00 0x00
>   > >36   0x00 0x00 0x00 0x00
>   > 36: going from conn_parse_cmd to conn_mwrite
>   > 36: going from conn_mwrite to conn_new_cmd
>   > 36: going from conn_new_cmd to conn_waiting
>   > 36: going from conn_waiting to conn_read
>   > 36: going from conn_read to conn_closing
>   > <36 connection closed.
>   >
>   > Success:
>   > <36 new binary client connection.
>   > 36: going from conn_new_cmd to conn_waiting
>   > 36: going from conn_waiting to conn_read
>   > 36: going from conn_read to conn_parse_cmd
>   > <36 Read binary protocol data:
>   > <36    0x80 0x20 0x00 0x00
>   > <36    0x00 0x00 0x00 0x00
>   > <36    0x00 0x00 0x00 0x00
>   > <36    0x00 0x02 0x00 0x00
>   > <36    0x00 0x00 0x00 0x00
>   > <36    0x00 0x00 0x00 0x00
>   > authenticated() in cmd 0x20 is true
>   > >36 Writing bin response:
>   > >36   0x81 0x20 0x00 0x00
>   > >36   0x00 0x00 0x00 0x00
>   > >36   0x00 0x00 0x00 0x05
>   > >36   0x00 0x02 0x00 0x00
>   > >36   0x00 0x00 0x00 0x00
>   > >36   0x00 0x00 0x00 0x00
>   > 36: going from conn_parse_cmd to conn_mwrite
>   > 36: going from conn_mwrite to conn_new_cmd
>   > 36: going from conn_new_cmd to conn_waiting
>   > 36: going from conn_waiting to conn_read
>   > 36: going from conn_read to conn_parse_cmd
>   > <36 Read binary protocol data:
>   > <36    0x80 0x21 0x00 0x05
>   > <36    0x00 0x00 0x00 0x00
>   > <36    0x00 0x00 0x00 0x16
>   > <36    0x00 0x02 0x00 0x00
>   > <36    0x00 0x00 0x00 0x00
>   > <36    0x00 0x00 0x00 0x00
>   > authenticated() in cmd 0x21 is true
>   > 36: going from conn_parse_cmd to conn_nread
>   > mech:  ``PLAIN'' with 17 bytes of data
>   > INFO: User  failed to authenticate
>   > sasl result code:  0
>   > >36 Writing bin response:
>   > >36   0x81 0x21 0x00 0x00
>   > >36   0x00 0x00 0x00 0x00
>   > >36   0x00 0x00 0x00 0x0d
>   > >36   0x00 0x02 0x00 0x00
>   > >36   0x00 0x00 0x00 0x00
>   > >36   0x00 0x00 0x00 0x00
>   > 36: going from conn_nread to conn_mwrite
>   > 36: going from conn_mwrite to conn_new_cmd
>   > 36: going from conn_new_cmd to conn_waiting
>   > 36: going from conn_waiting to conn_read
>   > 36: going from conn_read to conn_parse_cmd
>   > 

Re: Memcached Binary protocol

[watul123]

I am using same connection once the connection is established. What I see 
so far is the inconsistency in the establishing the connection itself. As 
pasted above in the logs, for same password/user name, same setup, same 
test program, same memcached bin, if I run the test program multiple times 
from command line,  memcached_set either returns success or the 
timeout(MEMCACHED_TIMEOUT). The logs from the server side shows..

 going from conn_read to conn_closing
<36 connection closed.
36: going from conn_closing to conn_closed

If the connection establishment is successful then I can set/get "n" number 
of values without any issue. 
  

On Wednesday, April 26, 2017 at 11:57:43 PM UTC-7, Dormando wrote:
>
> Are you reusing connections, or re-SASL'ing every time? I wonder if the 
> underlying sasl daemon/mechanism is failing. SASL stuff is only ever 
> checked when the connection is first established. All requests after the 
> connection setup is fine. 
>
> On Wed, 26 Apr 2017, watul123 wrote: 
>
> > I think the binary protocol just works as expected, there is nothing to 
> do with length as well, it was my test program where I commented out the 
> below 
> > line 
> > "memcached_behavior_set(cache, MEMCACHED_BEHAVIOR_BINARY_PROTOCOL, 1);" 
> > 
> > After fixing(un commenting) this line, no matter what length the 
> key/value are , it's success all the time. 
> > 
> > The actual issue is with SASL- connection gets closed all of sudden like 
> below, and the app gets Set Timeout, where as same thing gives success some 
> time 
> > Failed 
> > <36 new binary client connection. 
> > 36: going from conn_new_cmd to conn_waiting 
> > 36: going from conn_waiting to conn_read 
> > 36: going from conn_read to conn_parse_cmd 
> > <36 Read binary protocol data: 
> > <360x80 0x20 0x00 0x00 
> > <360x00 0x00 0x00 0x00 
> > <360x00 0x00 0x00 0x00 
> > <360x00 0x02 0x00 0x00 
> > <360x00 0x00 0x00 0x00 
> > <360x00 0x00 0x00 0x00 
> > authenticated() in cmd 0x20 is true 
> > >36 Writing bin response: 
> > >36   0x81 0x20 0x00 0x00 
> > >36   0x00 0x00 0x00 0x00 
> > >36   0x00 0x00 0x00 0x05 
> > >36   0x00 0x02 0x00 0x00 
> > >36   0x00 0x00 0x00 0x00 
> > >36   0x00 0x00 0x00 0x00 
> > 36: going from conn_parse_cmd to conn_mwrite 
> > 36: going from conn_mwrite to conn_new_cmd 
> > 36: going from conn_new_cmd to conn_waiting 
> > 36: going from conn_waiting to conn_read 
> > 36: going from conn_read to conn_closing 
> > <36 connection closed. 
> > 
> > Success: 
> > <36 new binary client connection. 
> > 36: going from conn_new_cmd to conn_waiting 
> > 36: going from conn_waiting to conn_read 
> > 36: going from conn_read to conn_parse_cmd 
> > <36 Read binary protocol data: 
> > <360x80 0x20 0x00 0x00 
> > <360x00 0x00 0x00 0x00 
> > <360x00 0x00 0x00 0x00 
> > <360x00 0x02 0x00 0x00 
> > <360x00 0x00 0x00 0x00 
> > <360x00 0x00 0x00 0x00 
> > authenticated() in cmd 0x20 is true 
> > >36 Writing bin response: 
> > >36   0x81 0x20 0x00 0x00 
> > >36   0x00 0x00 0x00 0x00 
> > >36   0x00 0x00 0x00 0x05 
> > >36   0x00 0x02 0x00 0x00 
> > >36   0x00 0x00 0x00 0x00 
> > >36   0x00 0x00 0x00 0x00 
> > 36: going from conn_parse_cmd to conn_mwrite 
> > 36: going from conn_mwrite to conn_new_cmd 
> > 36: going from conn_new_cmd to conn_waiting 
> > 36: going from conn_waiting to conn_read 
> > 36: going from conn_read to conn_parse_cmd 
> > <36 Read binary protocol data: 
> > <360x80 0x21 0x00 0x05 
> > <360x00 0x00 0x00 0x00 
> > <360x00 0x00 0x00 0x16 
> > <360x00 0x02 0x00 0x00 
> > <360x00 0x00 0x00 0x00 
> > <360x00 0x00 0x00 0x00 
> > authenticated() in cmd 0x21 is true 
> > 36: going from conn_parse_cmd to conn_nread 
> > mech:  ``PLAIN'' with 17 bytes of data 
> > INFO: User  failed to authenticate 
> > sasl result code:  0 
> > >36 Writing bin response: 
> > >36   0x81 0x21 0x00 0x00 
> > >36   0x00 0x00 0x00 0x00 
> > >36   0x00 0x00 0x00 0x0d 
> > >36   0x00 0x02 0x00 0x00 
> > >36   0x00 0x00 0x00 0x00 
> > >36   0x00 0x00 0x00 0x00 
> > 36: going from conn_nread to conn_mwrite 
> > 36: going from conn_mwrite to conn_new_cmd 
> > 36: going from conn_new_cmd to conn_waiting 
> > 36: going from conn_waiting to conn_read 
> > 36: going from conn_read to conn_parse_cmd 
> > <36 Read binary protocol data: 
> > <360x80 0x01 0x00 0x17 
> > <360x08 0x00 0x00 0x00 
> > <360x00 0x00 0x00 0x39 
> > <360x00 0x01 0x00 0x00 
> > <360x00 0x00 0x00 0x00 
> > <360x00 0x00 0x00 0x00 
> > authenticated() in cmd 0x01 is true 
> > 36: going from conn_parse_cmd to conn_nread 
> > <36 SET abcefghjklmnopqrstvwxyz Value len is 26 
> > > NOT FOUND abcefghjklmnopqrstvwxyz 
> > >36 Writing bin response: 
> > >36   0x81 0x01 0x00 0x00 
> > >36   0x00 0x00 0x00 0x00 
> > >36   0x00 0x00 0x00 0x00 
> > >36   0x00 0x01 0x00 0x00 
> > >36   0x00 0x00 0x00 0x00 
> > >36   0x00 0x00 0x00 0x01 
> > 36: going from conn_nread to 

Re: Memcached Binary protocol

[dormando]

Are you reusing connections, or re-SASL'ing every time? I wonder if the
underlying sasl daemon/mechanism is failing. SASL stuff is only ever
checked when the connection is first established. All requests after the
connection setup is fine.

On Wed, 26 Apr 2017, watul123 wrote:

> I think the binary protocol just works as expected, there is nothing to do 
> with length as well, it was my test program where I commented out the below
> line
> "memcached_behavior_set(cache, MEMCACHED_BEHAVIOR_BINARY_PROTOCOL, 1);"
>
> After fixing(un commenting) this line, no matter what length the key/value 
> are , it's success all the time.
>
> The actual issue is with SASL- connection gets closed all of sudden like 
> below, and the app gets Set Timeout, where as same thing gives success some 
> time
> Failed
> <36 new binary client connection.
> 36: going from conn_new_cmd to conn_waiting
> 36: going from conn_waiting to conn_read
> 36: going from conn_read to conn_parse_cmd
> <36 Read binary protocol data:
> <36    0x80 0x20 0x00 0x00
> <36    0x00 0x00 0x00 0x00
> <36    0x00 0x00 0x00 0x00
> <36    0x00 0x02 0x00 0x00
> <36    0x00 0x00 0x00 0x00
> <36    0x00 0x00 0x00 0x00
> authenticated() in cmd 0x20 is true
> >36 Writing bin response:
> >36   0x81 0x20 0x00 0x00
> >36   0x00 0x00 0x00 0x00
> >36   0x00 0x00 0x00 0x05
> >36   0x00 0x02 0x00 0x00
> >36   0x00 0x00 0x00 0x00
> >36   0x00 0x00 0x00 0x00
> 36: going from conn_parse_cmd to conn_mwrite
> 36: going from conn_mwrite to conn_new_cmd
> 36: going from conn_new_cmd to conn_waiting
> 36: going from conn_waiting to conn_read
> 36: going from conn_read to conn_closing
> <36 connection closed.
>
> Success:
> <36 new binary client connection.
> 36: going from conn_new_cmd to conn_waiting
> 36: going from conn_waiting to conn_read
> 36: going from conn_read to conn_parse_cmd
> <36 Read binary protocol data:
> <36    0x80 0x20 0x00 0x00
> <36    0x00 0x00 0x00 0x00
> <36    0x00 0x00 0x00 0x00
> <36    0x00 0x02 0x00 0x00
> <36    0x00 0x00 0x00 0x00
> <36    0x00 0x00 0x00 0x00
> authenticated() in cmd 0x20 is true
> >36 Writing bin response:
> >36   0x81 0x20 0x00 0x00
> >36   0x00 0x00 0x00 0x00
> >36   0x00 0x00 0x00 0x05
> >36   0x00 0x02 0x00 0x00
> >36   0x00 0x00 0x00 0x00
> >36   0x00 0x00 0x00 0x00
> 36: going from conn_parse_cmd to conn_mwrite
> 36: going from conn_mwrite to conn_new_cmd
> 36: going from conn_new_cmd to conn_waiting
> 36: going from conn_waiting to conn_read
> 36: going from conn_read to conn_parse_cmd
> <36 Read binary protocol data:
> <36    0x80 0x21 0x00 0x05
> <36    0x00 0x00 0x00 0x00
> <36    0x00 0x00 0x00 0x16
> <36    0x00 0x02 0x00 0x00
> <36    0x00 0x00 0x00 0x00
> <36    0x00 0x00 0x00 0x00
> authenticated() in cmd 0x21 is true
> 36: going from conn_parse_cmd to conn_nread
> mech:  ``PLAIN'' with 17 bytes of data
> INFO: User  failed to authenticate
> sasl result code:  0
> >36 Writing bin response:
> >36   0x81 0x21 0x00 0x00
> >36   0x00 0x00 0x00 0x00
> >36   0x00 0x00 0x00 0x0d
> >36   0x00 0x02 0x00 0x00
> >36   0x00 0x00 0x00 0x00
> >36   0x00 0x00 0x00 0x00
> 36: going from conn_nread to conn_mwrite
> 36: going from conn_mwrite to conn_new_cmd
> 36: going from conn_new_cmd to conn_waiting
> 36: going from conn_waiting to conn_read
> 36: going from conn_read to conn_parse_cmd
> <36 Read binary protocol data:
> <36    0x80 0x01 0x00 0x17
> <36    0x08 0x00 0x00 0x00
> <36    0x00 0x00 0x00 0x39
> <36    0x00 0x01 0x00 0x00
> <36    0x00 0x00 0x00 0x00
> <36    0x00 0x00 0x00 0x00
> authenticated() in cmd 0x01 is true
> 36: going from conn_parse_cmd to conn_nread
> <36 SET abcefghjklmnopqrstvwxyz Value len is 26
> > NOT FOUND abcefghjklmnopqrstvwxyz
> >36 Writing bin response:
> >36   0x81 0x01 0x00 0x00
> >36   0x00 0x00 0x00 0x00
> >36   0x00 0x00 0x00 0x00
> >36   0x00 0x01 0x00 0x00
> >36   0x00 0x00 0x00 0x00
> >36   0x00 0x00 0x00 0x01
> 36: going from conn_nread to conn_mwrite
> 36: going from conn_mwrite to conn_new_cmd
> 36: going from conn_new_cmd to conn_waiting
> 36: going from conn_waiting to conn_read
> 36: going from conn_read to conn_parse_cmd
> <36 Read binary protocol data:
> <36    0x80 0x0c 0x00 0x17
> <36    0x00 0x00 0x00 0x00
> <36    0x00 0x00 0x00 0x17
> <36    0x00 0x03 0x00 0x00
> <36    0x00 0x00 0x00 0x00
> <36    0x00 0x00 0x00 0x00
> authenticated() in cmd 0x0c is true
> 36: going from conn_parse_cmd to conn_nread
> <36 GET abcefghjklmnopqrstvwxyz
> > FOUND KEY abcefghjklmnopqrstvwxyz
> >36 Writing bin response:
> >36   0x81 0x0c 0x00 0x17
> >36   0x04 0x00 0x00 0x00
> >36   0x00 0x00 0x00 0x35
> >36   0x00 0x03 0x00 0x00
> >36   0x00 0x00 0x00 0x00
> >36   0x00 0x00 0x00 0x00
> 36: going from conn_nread to conn_mwrite
> 36: going from conn_mwrite to conn_new_cmd
> 36: going from conn_new_cmd to conn_waiting
> 36: going from conn_waiting to conn_read
> 36: going from conn_read to conn_parse_cmd
> <36 Read binary protocol data:
> <36    0x80 0x07 0x00 0x00
> <36    0x00 

Re: Memcached Binary protocol

[watul123]

I think the binary protocol just works as expected, there is nothing to do 
with length as well, it was my test program where I commented out the below 
line
"memcached_behavior_set(cache, MEMCACHED_BEHAVIOR_BINARY_PROTOCOL, 1);" 

After fixing(un commenting) this line, no matter what length the key/value 
are , it's success all the time. 

*The actual issue is with SASL*- connection gets closed all of sudden like 
below, and the app gets Set Timeout, where as same thing gives success some 
time

*Failed*<36 new binary client connection.
36: going from conn_new_cmd to conn_waiting
36: going from conn_waiting to conn_read
36: going from conn_read to conn_parse_cmd
<36 Read binary protocol data:
<360x80 0x20 0x00 0x00
<360x00 0x00 0x00 0x00
<360x00 0x00 0x00 0x00
<360x00 0x02 0x00 0x00
<360x00 0x00 0x00 0x00
<360x00 0x00 0x00 0x00
authenticated() in cmd 0x20 is true
>36 Writing bin response:
>36   0x81 0x20 0x00 0x00
>36   0x00 0x00 0x00 0x00
>36   0x00 0x00 0x00 0x05
>36   0x00 0x02 0x00 0x00
>36   0x00 0x00 0x00 0x00
>36   0x00 0x00 0x00 0x00
36: going from conn_parse_cmd to conn_mwrite
36: going from conn_mwrite to conn_new_cmd
36: going from conn_new_cmd to conn_waiting
36: going from conn_waiting to conn_read
36: going from conn_read to conn_closing
<36 connection closed.


*Success:*<36 new binary client connection.
36: going from conn_new_cmd to conn_waiting
36: going from conn_waiting to conn_read
36: going from conn_read to conn_parse_cmd
<36 Read binary protocol data:
<360x80 0x20 0x00 0x00
<360x00 0x00 0x00 0x00
<360x00 0x00 0x00 0x00
<360x00 0x02 0x00 0x00
<360x00 0x00 0x00 0x00
<360x00 0x00 0x00 0x00
authenticated() in cmd 0x20 is true
>36 Writing bin response:
>36   0x81 0x20 0x00 0x00
>36   0x00 0x00 0x00 0x00
>36   0x00 0x00 0x00 0x05
>36   0x00 0x02 0x00 0x00
>36   0x00 0x00 0x00 0x00
>36   0x00 0x00 0x00 0x00
36: going from conn_parse_cmd to conn_mwrite
36: going from conn_mwrite to conn_new_cmd
36: going from conn_new_cmd to conn_waiting
36: going from conn_waiting to conn_read
36: going from conn_read to conn_parse_cmd
<36 Read binary protocol data:
<360x80 0x21 0x00 0x05
<360x00 0x00 0x00 0x00
<360x00 0x00 0x00 0x16
<360x00 0x02 0x00 0x00
<360x00 0x00 0x00 0x00
<360x00 0x00 0x00 0x00
authenticated() in cmd 0x21 is true
36: going from conn_parse_cmd to conn_nread
mech:  ``PLAIN'' with 17 bytes of data
INFO: User  failed to authenticate
sasl result code:  0
>36 Writing bin response:
>36   0x81 0x21 0x00 0x00
>36   0x00 0x00 0x00 0x00
>36   0x00 0x00 0x00 0x0d
>36   0x00 0x02 0x00 0x00
>36   0x00 0x00 0x00 0x00
>36   0x00 0x00 0x00 0x00
36: going from conn_nread to conn_mwrite
36: going from conn_mwrite to conn_new_cmd
36: going from conn_new_cmd to conn_waiting
36: going from conn_waiting to conn_read
36: going from conn_read to conn_parse_cmd
<36 Read binary protocol data:
<360x80 0x01 0x00 0x17
<360x08 0x00 0x00 0x00
<360x00 0x00 0x00 0x39
<360x00 0x01 0x00 0x00
<360x00 0x00 0x00 0x00
<360x00 0x00 0x00 0x00
authenticated() in cmd 0x01 is true
36: going from conn_parse_cmd to conn_nread
<36 SET abcefghjklmnopqrstvwxyz Value len is 26
> NOT FOUND abcefghjklmnopqrstvwxyz
>36 Writing bin response:
>36   0x81 0x01 0x00 0x00
>36   0x00 0x00 0x00 0x00
>36   0x00 0x00 0x00 0x00
>36   0x00 0x01 0x00 0x00
>36   0x00 0x00 0x00 0x00
>36   0x00 0x00 0x00 0x01
36: going from conn_nread to conn_mwrite
36: going from conn_mwrite to conn_new_cmd
36: going from conn_new_cmd to conn_waiting
36: going from conn_waiting to conn_read
36: going from conn_read to conn_parse_cmd
<36 Read binary protocol data:
<360x80 0x0c 0x00 0x17
<360x00 0x00 0x00 0x00
<360x00 0x00 0x00 0x17
<360x00 0x03 0x00 0x00
<360x00 0x00 0x00 0x00
<360x00 0x00 0x00 0x00
authenticated() in cmd 0x0c is true
36: going from conn_parse_cmd to conn_nread
<36 GET abcefghjklmnopqrstvwxyz
> FOUND KEY abcefghjklmnopqrstvwxyz
>36 Writing bin response:
>36   0x81 0x0c 0x00 0x17
>36   0x04 0x00 0x00 0x00
>36   0x00 0x00 0x00 0x35
>36   0x00 0x03 0x00 0x00
>36   0x00 0x00 0x00 0x00
>36   0x00 0x00 0x00 0x00
36: going from conn_nread to conn_mwrite
36: going from conn_mwrite to conn_new_cmd
36: going from conn_new_cmd to conn_waiting
36: going from conn_waiting to conn_read
36: going from conn_read to conn_parse_cmd
<36 Read binary protocol data:
<360x80 0x07 0x00 0x00
<360x00 0x00 0x00 0x00
<360x00 0x00 0x00 0x00
<360x00 0x04 0x00 0x00
<360x00 0x00 0x00 0x00
<360x00 0x00 0x00 0x00
authenticated() in cmd 0x07 is true
>36 Writing bin response:
>36   0x81 0x07 0x00 0x00
>36   0x00 0x00 0x00 0x00
>36   0x00 0x00 0x00 0x00
>36   0x00 0x04 0x00 0x00
>36   0x00 0x00 0x00 0x00
>36   0x00 0x00 0x00 0x00
36: going from conn_parse_cmd to conn_mwrite
36: going from conn_mwrite to conn_closing
<36 connection closed.
36: going from conn_closing to conn_closed






On Wednesday, April 26, 2017 at 

Re: Memcached Binary protocol

[watul123]

Never mind, while debugging I commented out some lines and forgot to 
un-comment those. After fixing it, I don't see the bad magic issue. 
Importantly, the increase in the length of key:value in test program 
returns the success. So the inconsistency of binary protocol is no issue 
anymore, now I need to move to SASL again. 

*Dormando, thank you so much for your help, really appreciate it. *

Thanks again,
Atul

On Wednesday, April 26, 2017 at 10:55:25 PM UTC-7, watul123 wrote:
>
> No, its just like below 
>
> const char* key = "abczadfg";
> const char* value = "valuetestapp";
>
> and 
>
> I am using the   this to ste the value "rc = memcached_set(cache, key, 
> strlen(key), value, strlen(value), (time_t)0, flags);"
>
> Thanks,
> Atul
>
> On Wednesday, April 26, 2017 at 10:50:33 PM UTC-7, Dormando wrote:
>>
>> Your key isn't over 256 bytes is it? 
>>
>> On Wed, 26 Apr 2017, watul123 wrote: 
>>
>> > Ok, thanks. Let me debug in that direction. I will update the thread 
>> with my findings. 
>> > 
>> > BTW, if I increase the length of key and value in my test program with 
>> binary protocol then I consistently get CONNECTION FAILURE with below 
>> output on 
>> > memcached side 
>> > <36 new binary client connection. 
>> > 36: going from conn_new_cmd to conn_waiting 
>> > 36: going from conn_waiting to conn_read 
>> > 36: going from conn_read to conn_parse_cmd 
>> > <36 Read binary protocol data: 
>> > <360x73 0x65 0x74 0x20 
>> > <360x61 0x62 0x63 0x7a 
>> > <360x20 0x30 0x20 0x30 
>> > <360x20 0x36 0x0d 0x0a 
>> > <360x76 0x61 0x6c 0x75 
>> > <360x65 0x65 0x0d 0x0a 
>> > Invalid magic:  73 
>> > 36: going from conn_parse_cmd to conn_closing 
>> > <36 connection closed. 
>> > 
>> > Thanks again, 
>> > Atul 
>> > 
>> > On Wednesday, April 26, 2017 at 10:30:14 PM UTC-7, Dormando wrote: 
>> >   Ok. 
>> > 
>> >   The binary protocol is tested pretty well so it's *probably* 
>> something in 
>> >   your program, but I won't rule out a bug on the server either. 
>> The binary 
>> >   protocol is in heavy usage in a bunch of places though. 
>> > 
>> >   On Wed, 26 Apr 2017, watul123 wrote: 
>> > 
>> >   > I can test with large string quickly. In the test app I may be 
>> sending fewer bytes, but in my real app I am sending way more bytes. 
>> >   > 
>> >   > FYI: I started with SASL auth, which was failing 
>> intermittently. After debugging I realized something is not right with 
>> binary protocol, 
>> >   then I disabled 
>> >   > the SASL to take it our of picture completely, and spawned the 
>> memcached with binary protocol and still I see the the intermittent 
>> >   behavior.  
>> >   > 
>> >   > On Wednesday, April 26, 2017 at 9:54:00 PM UTC-7, Dormando 
>> wrote: 
>> >   >   Looks like the protocol is getting out of sync somehow. 
>> >   > 
>> >   >   conn_waiting only means it's waiting to read more bytes 
>> from the socket 
>> >   >   from a set. Then it looks like the client doesn't send 
>> anymore bytes, 
>> >   >   times out, then closes the socket (-> conn_read -> 
>> conn_closing). 
>> >   > 
>> >   >   It's most likely a bug in how you're using the binary 
>> protocol, but it's 
>> >   >   hard to say from here. Somehow you're writing fewer bytes 
>> to the socket 
>> >   >   than you told the binary protocol to receive. 
>> >   > 
>> >   >   On Wed, 26 Apr 2017, watul123 wrote: 
>> >   > 
>> >   >   > Yes I am 100% sure. 
>> >   >   > When the binary protocol is in picture then only this 
>> happens, otherwise same test program with same argument runs perfect. I 
>> >   debugged a 
>> >   >   lot before 
>> >   >   > posting to this group. I am with you on the fact the 
>> binary protocol has nothing to do with the timeouts, but it is the one 
>> cause 
>> >   the 
>> >   >   failure while 
>> >   >   > reading from socket, then I guess the connection gets 
>> close, and at the application level I get MEMCACHED_TIMEOUT.  
>> >   >   > 
>> >   >   > This is what I see on memcached's log 
>> >   >   > 
>> >   >   > 36: going from conn_parse_cmd to conn_mwrite 
>> >   >   > 36: going from conn_mwrite to conn_new_cmd 
>> >   >   > 36: going from conn_new_cmd to conn_waiting 
>> >   >   > 36: going from conn_waiting to conn_read 
>> >   >   > 36: going from conn_read to conn_closing 
>> >   >   > <36 connection closed. 
>> >   >   > 36: going from conn_closing to conn_closed 
>> >   >   > 
>> >   >   > 
>> >   >   > 
>> >   >   > On Wednesday, April 26, 2017 at 5:02:04 PM UTC-7, 
>> Dormando wrote: 
>> >   >   >   Any way to get more information about the 
>> timeouts you're seeing? 
>> >   >   > 
>> >   >   >   There's nothing in the 

Re: Memcached Binary protocol

[watul123]

No, its just like below 

const char* key = "abczadfg";
const char* value = "valuetestapp";

and 

I am using the   this to ste the value "rc = memcached_set(cache, key, 
strlen(key), value, strlen(value), (time_t)0, flags);"

Thanks,
Atul

On Wednesday, April 26, 2017 at 10:50:33 PM UTC-7, Dormando wrote:
>
> Your key isn't over 256 bytes is it? 
>
> On Wed, 26 Apr 2017, watul123 wrote: 
>
> > Ok, thanks. Let me debug in that direction. I will update the thread 
> with my findings. 
> > 
> > BTW, if I increase the length of key and value in my test program with 
> binary protocol then I consistently get CONNECTION FAILURE with below 
> output on 
> > memcached side 
> > <36 new binary client connection. 
> > 36: going from conn_new_cmd to conn_waiting 
> > 36: going from conn_waiting to conn_read 
> > 36: going from conn_read to conn_parse_cmd 
> > <36 Read binary protocol data: 
> > <360x73 0x65 0x74 0x20 
> > <360x61 0x62 0x63 0x7a 
> > <360x20 0x30 0x20 0x30 
> > <360x20 0x36 0x0d 0x0a 
> > <360x76 0x61 0x6c 0x75 
> > <360x65 0x65 0x0d 0x0a 
> > Invalid magic:  73 
> > 36: going from conn_parse_cmd to conn_closing 
> > <36 connection closed. 
> > 
> > Thanks again, 
> > Atul 
> > 
> > On Wednesday, April 26, 2017 at 10:30:14 PM UTC-7, Dormando wrote: 
> >   Ok. 
> > 
> >   The binary protocol is tested pretty well so it's *probably* 
> something in 
> >   your program, but I won't rule out a bug on the server either. The 
> binary 
> >   protocol is in heavy usage in a bunch of places though. 
> > 
> >   On Wed, 26 Apr 2017, watul123 wrote: 
> > 
> >   > I can test with large string quickly. In the test app I may be 
> sending fewer bytes, but in my real app I am sending way more bytes. 
> >   > 
> >   > FYI: I started with SASL auth, which was failing intermittently. 
> After debugging I realized something is not right with binary protocol, 
> >   then I disabled 
> >   > the SASL to take it our of picture completely, and spawned the 
> memcached with binary protocol and still I see the the intermittent 
> >   behavior.  
> >   > 
> >   > On Wednesday, April 26, 2017 at 9:54:00 PM UTC-7, Dormando 
> wrote: 
> >   >   Looks like the protocol is getting out of sync somehow. 
> >   > 
> >   >   conn_waiting only means it's waiting to read more bytes 
> from the socket 
> >   >   from a set. Then it looks like the client doesn't send 
> anymore bytes, 
> >   >   times out, then closes the socket (-> conn_read -> 
> conn_closing). 
> >   > 
> >   >   It's most likely a bug in how you're using the binary 
> protocol, but it's 
> >   >   hard to say from here. Somehow you're writing fewer bytes 
> to the socket 
> >   >   than you told the binary protocol to receive. 
> >   > 
> >   >   On Wed, 26 Apr 2017, watul123 wrote: 
> >   > 
> >   >   > Yes I am 100% sure. 
> >   >   > When the binary protocol is in picture then only this 
> happens, otherwise same test program with same argument runs perfect. I 
> >   debugged a 
> >   >   lot before 
> >   >   > posting to this group. I am with you on the fact the 
> binary protocol has nothing to do with the timeouts, but it is the one 
> cause 
> >   the 
> >   >   failure while 
> >   >   > reading from socket, then I guess the connection gets 
> close, and at the application level I get MEMCACHED_TIMEOUT.  
> >   >   > 
> >   >   > This is what I see on memcached's log 
> >   >   > 
> >   >   > 36: going from conn_parse_cmd to conn_mwrite 
> >   >   > 36: going from conn_mwrite to conn_new_cmd 
> >   >   > 36: going from conn_new_cmd to conn_waiting 
> >   >   > 36: going from conn_waiting to conn_read 
> >   >   > 36: going from conn_read to conn_closing 
> >   >   > <36 connection closed. 
> >   >   > 36: going from conn_closing to conn_closed 
> >   >   > 
> >   >   > 
> >   >   > 
> >   >   > On Wednesday, April 26, 2017 at 5:02:04 PM UTC-7, 
> Dormando wrote: 
> >   >   >   Any way to get more information about the timeouts 
> you're seeing? 
> >   >   > 
> >   >   >   There's nothing in the protocol that would cause 
> "timeouts", but bugs 
> >   >   >   somewhere could cause clients to hang waiting on 
> more data I guess. 
> >   >   > 
> >   >   >   You're sure they're timeouts and not some other 
> kind of error? 
> >   >   > 
> >   >   >   On Wed, 26 Apr 2017, Atul Waghmare wrote: 
> >   >   > 
> >   >   >   > Hi there, 
> >   >   >   > 
> >   >   >   > I am facing one issue with memcached binary 
> protocol. Whenever I force the memcached to use the binary protocol, my 
> >   application get 
> >   

Re: Memcached Binary protocol

[dormando]

Your key isn't over 256 bytes is it?

On Wed, 26 Apr 2017, watul123 wrote:

> Ok, thanks. Let me debug in that direction. I will update the thread with my 
> findings.
>
> BTW, if I increase the length of key and value in my test program with binary 
> protocol then I consistently get CONNECTION FAILURE with below output on
> memcached side
> <36 new binary client connection.
> 36: going from conn_new_cmd to conn_waiting
> 36: going from conn_waiting to conn_read
> 36: going from conn_read to conn_parse_cmd
> <36 Read binary protocol data:
> <36    0x73 0x65 0x74 0x20
> <36    0x61 0x62 0x63 0x7a
> <36    0x20 0x30 0x20 0x30
> <36    0x20 0x36 0x0d 0x0a
> <36    0x76 0x61 0x6c 0x75
> <36    0x65 0x65 0x0d 0x0a
> Invalid magic:  73
> 36: going from conn_parse_cmd to conn_closing
> <36 connection closed.
>
> Thanks again,
> Atul
>
> On Wednesday, April 26, 2017 at 10:30:14 PM UTC-7, Dormando wrote:
>   Ok.
>
>   The binary protocol is tested pretty well so it's *probably* something 
> in
>   your program, but I won't rule out a bug on the server either. The 
> binary
>   protocol is in heavy usage in a bunch of places though.
>
>   On Wed, 26 Apr 2017, watul123 wrote:
>
>   > I can test with large string quickly. In the test app I may be 
> sending fewer bytes, but in my real app I am sending way more bytes.
>   >
>   > FYI: I started with SASL auth, which was failing intermittently. 
> After debugging I realized something is not right with binary protocol,
>   then I disabled
>   > the SASL to take it our of picture completely, and spawned the 
> memcached with binary protocol and still I see the the intermittent
>   behavior.     
>   >
>   > On Wednesday, April 26, 2017 at 9:54:00 PM UTC-7, Dormando wrote:
>   >       Looks like the protocol is getting out of sync somehow.
>   >
>   >       conn_waiting only means it's waiting to read more bytes from 
> the socket
>   >       from a set. Then it looks like the client doesn't send anymore 
> bytes,
>   >       times out, then closes the socket (-> conn_read -> 
> conn_closing).
>   >
>   >       It's most likely a bug in how you're using the binary protocol, 
> but it's
>   >       hard to say from here. Somehow you're writing fewer bytes to 
> the socket
>   >       than you told the binary protocol to receive.
>   >
>   >       On Wed, 26 Apr 2017, watul123 wrote:
>   >
>   >       > Yes I am 100% sure.
>   >       > When the binary protocol is in picture then only this 
> happens, otherwise same test program with same argument runs perfect. I
>   debugged a
>   >       lot before
>   >       > posting to this group. I am with you on the fact the binary 
> protocol has nothing to do with the timeouts, but it is the one cause
>   the
>   >       failure while
>   >       > reading from socket, then I guess the connection gets close, 
> and at the application level I get MEMCACHED_TIMEOUT. 
>   >       >
>   >       > This is what I see on memcached's log
>   >       >
>   >       > 36: going from conn_parse_cmd to conn_mwrite
>   >       > 36: going from conn_mwrite to conn_new_cmd
>   >       > 36: going from conn_new_cmd to conn_waiting
>   >       > 36: going from conn_waiting to conn_read
>   >       > 36: going from conn_read to conn_closing
>   >       > <36 connection closed.
>   >       > 36: going from conn_closing to conn_closed
>   >       >
>   >       >
>   >       >
>   >       > On Wednesday, April 26, 2017 at 5:02:04 PM UTC-7, Dormando 
> wrote:
>   >       >       Any way to get more information about the timeouts 
> you're seeing?
>   >       >
>   >       >       There's nothing in the protocol that would cause 
> "timeouts", but bugs
>   >       >       somewhere could cause clients to hang waiting on more 
> data I guess.
>   >       >
>   >       >       You're sure they're timeouts and not some other kind of 
> error?
>   >       >
>   >       >       On Wed, 26 Apr 2017, Atul Waghmare wrote:
>   >       >
>   >       >       > Hi there,
>   >       >       >
>   >       >       > I am facing one issue with memcached binary protocol. 
> Whenever I force the memcached to use the binary protocol, my
>   application get
>   >       >       occasional timeouts
>   >       >       > and occasional success. The percentage of failure(set 
> timeouts) is more than 80% when the memcached spawn with binary
>   protocol .
>   >       The moment
>   >       >       I remove the
>   >       >       > binary option, the success rate is 100%. 
>   >       >       >
>   >       >       > memcached - v1.4.36   
>   >       >       > libmemcached -v1.0.18
>   >       >       >
>   >       >       > Any idea what may be wrong?
>   >       >       >
>   >       >   

Re: Memcached Binary protocol

[watul123]

Ok, thanks. Let me debug in that direction. I will update the thread with 
my findings. 

BTW, if I increase the length of key and value in my test program with 
binary protocol then I consistently get CONNECTION FAILURE with below 
output on memcached side 
<36 new binary client connection.
36: going from conn_new_cmd to conn_waiting
36: going from conn_waiting to conn_read
36: going from conn_read to conn_parse_cmd
<36 Read binary protocol data:
<360x73 0x65 0x74 0x20
<360x61 0x62 0x63 0x7a
<360x20 0x30 0x20 0x30
<360x20 0x36 0x0d 0x0a
<360x76 0x61 0x6c 0x75
<360x65 0x65 0x0d 0x0a
Invalid magic:  73
36: going from conn_parse_cmd to conn_closing
<36 connection closed.

Thanks again,
Atul

On Wednesday, April 26, 2017 at 10:30:14 PM UTC-7, Dormando wrote:
>
> Ok. 
>
> The binary protocol is tested pretty well so it's *probably* something in 
> your program, but I won't rule out a bug on the server either. The binary 
> protocol is in heavy usage in a bunch of places though. 
>
> On Wed, 26 Apr 2017, watul123 wrote: 
>
> > I can test with large string quickly. In the test app I may be sending 
> fewer bytes, but in my real app I am sending way more bytes. 
> > 
> > FYI: I started with SASL auth, which was failing intermittently. After 
> debugging I realized something is not right with binary protocol, then I 
> disabled 
> > the SASL to take it our of picture completely, and spawned the memcached 
> with binary protocol and still I see the the intermittent behavior.  
> > 
> > On Wednesday, April 26, 2017 at 9:54:00 PM UTC-7, Dormando wrote: 
> >   Looks like the protocol is getting out of sync somehow. 
> > 
> >   conn_waiting only means it's waiting to read more bytes from the 
> socket 
> >   from a set. Then it looks like the client doesn't send anymore 
> bytes, 
> >   times out, then closes the socket (-> conn_read -> conn_closing). 
> > 
> >   It's most likely a bug in how you're using the binary protocol, 
> but it's 
> >   hard to say from here. Somehow you're writing fewer bytes to the 
> socket 
> >   than you told the binary protocol to receive. 
> > 
> >   On Wed, 26 Apr 2017, watul123 wrote: 
> > 
> >   > Yes I am 100% sure. 
> >   > When the binary protocol is in picture then only this happens, 
> otherwise same test program with same argument runs perfect. I debugged a 
> >   lot before 
> >   > posting to this group. I am with you on the fact the binary 
> protocol has nothing to do with the timeouts, but it is the one cause the 
> >   failure while 
> >   > reading from socket, then I guess the connection gets close, and 
> at the application level I get MEMCACHED_TIMEOUT.  
> >   > 
> >   > This is what I see on memcached's log 
> >   > 
> >   > 36: going from conn_parse_cmd to conn_mwrite 
> >   > 36: going from conn_mwrite to conn_new_cmd 
> >   > 36: going from conn_new_cmd to conn_waiting 
> >   > 36: going from conn_waiting to conn_read 
> >   > 36: going from conn_read to conn_closing 
> >   > <36 connection closed. 
> >   > 36: going from conn_closing to conn_closed 
> >   > 
> >   > 
> >   > 
> >   > On Wednesday, April 26, 2017 at 5:02:04 PM UTC-7, Dormando 
> wrote: 
> >   >   Any way to get more information about the timeouts you're 
> seeing? 
> >   > 
> >   >   There's nothing in the protocol that would cause 
> "timeouts", but bugs 
> >   >   somewhere could cause clients to hang waiting on more data 
> I guess. 
> >   > 
> >   >   You're sure they're timeouts and not some other kind of 
> error? 
> >   > 
> >   >   On Wed, 26 Apr 2017, Atul Waghmare wrote: 
> >   > 
> >   >   > Hi there, 
> >   >   > 
> >   >   > I am facing one issue with memcached binary protocol. 
> Whenever I force the memcached to use the binary protocol, my application 
> get 
> >   >   occasional timeouts 
> >   >   > and occasional success. The percentage of failure(set 
> timeouts) is more than 80% when the memcached spawn with binary protocol . 
> >   The moment 
> >   >   I remove the 
> >   >   > binary option, the success rate is 100%.  
> >   >   > 
> >   >   > memcached - v1.4.36
> >   >   > libmemcached -v1.0.18 
> >   >   > 
> >   >   > Any idea what may be wrong? 
> >   >   > 
> >   >   > Thanks, 
> >   >   > Atul 
> >   >   > 
> >   >   > -- 
> >   >   > 
> >   >   > --- 
> >   >   > You received this message because you are subscribed to 
> the Google Groups "memcached" group. 
> >   >   > To unsubscribe from this group and stop receiving emails 
> from it, send an email to memcached+...@googlegroups.com. 
> >   >   > For more options, visit 
> https://groups.google.com/d/optout. 
> >   >   > 
> >   > 

Re: Memcached Binary protocol

[dormando]

Ok.

The binary protocol is tested pretty well so it's *probably* something in
your program, but I won't rule out a bug on the server either. The binary
protocol is in heavy usage in a bunch of places though.

On Wed, 26 Apr 2017, watul123 wrote:

> I can test with large string quickly. In the test app I may be sending fewer 
> bytes, but in my real app I am sending way more bytes.
>
> FYI: I started with SASL auth, which was failing intermittently. After 
> debugging I realized something is not right with binary protocol, then I 
> disabled
> the SASL to take it our of picture completely, and spawned the memcached with 
> binary protocol and still I see the the intermittent behavior.     
>
> On Wednesday, April 26, 2017 at 9:54:00 PM UTC-7, Dormando wrote:
>   Looks like the protocol is getting out of sync somehow.
>
>   conn_waiting only means it's waiting to read more bytes from the socket
>   from a set. Then it looks like the client doesn't send anymore bytes,
>   times out, then closes the socket (-> conn_read -> conn_closing).
>
>   It's most likely a bug in how you're using the binary protocol, but it's
>   hard to say from here. Somehow you're writing fewer bytes to the socket
>   than you told the binary protocol to receive.
>
>   On Wed, 26 Apr 2017, watul123 wrote:
>
>   > Yes I am 100% sure.
>   > When the binary protocol is in picture then only this happens, 
> otherwise same test program with same argument runs perfect. I debugged a
>   lot before
>   > posting to this group. I am with you on the fact the binary protocol 
> has nothing to do with the timeouts, but it is the one cause the
>   failure while
>   > reading from socket, then I guess the connection gets close, and at 
> the application level I get MEMCACHED_TIMEOUT. 
>   >
>   > This is what I see on memcached's log
>   >
>   > 36: going from conn_parse_cmd to conn_mwrite
>   > 36: going from conn_mwrite to conn_new_cmd
>   > 36: going from conn_new_cmd to conn_waiting
>   > 36: going from conn_waiting to conn_read
>   > 36: going from conn_read to conn_closing
>   > <36 connection closed.
>   > 36: going from conn_closing to conn_closed
>   >
>   >
>   >
>   > On Wednesday, April 26, 2017 at 5:02:04 PM UTC-7, Dormando wrote:
>   >       Any way to get more information about the timeouts you're 
> seeing?
>   >
>   >       There's nothing in the protocol that would cause "timeouts", 
> but bugs
>   >       somewhere could cause clients to hang waiting on more data I 
> guess.
>   >
>   >       You're sure they're timeouts and not some other kind of error?
>   >
>   >       On Wed, 26 Apr 2017, Atul Waghmare wrote:
>   >
>   >       > Hi there,
>   >       >
>   >       > I am facing one issue with memcached binary protocol. 
> Whenever I force the memcached to use the binary protocol, my application get
>   >       occasional timeouts
>   >       > and occasional success. The percentage of failure(set 
> timeouts) is more than 80% when the memcached spawn with binary protocol .
>   The moment
>   >       I remove the
>   >       > binary option, the success rate is 100%. 
>   >       >
>   >       > memcached - v1.4.36   
>   >       > libmemcached -v1.0.18
>   >       >
>   >       > Any idea what may be wrong?
>   >       >
>   >       > Thanks,
>   >       > Atul
>   >       >
>   >       > --
>   >       >
>   >       > ---
>   >       > You received this message because you are subscribed to the 
> Google Groups "memcached" group.
>   >       > To unsubscribe from this group and stop receiving emails from 
> it, send an email to memcached+...@googlegroups.com.
>   >       > For more options, visit https://groups.google.com/d/optout.
>   >       >
>   >       >
>   >
>   > --
>   >
>   > ---
>   > You received this message because you are subscribed to the Google 
> Groups "memcached" group.
>   > To unsubscribe from this group and stop receiving emails from it, 
> send an email to memcached+...@googlegroups.com.
>   > For more options, visit https://groups.google.com/d/optout.
>   >
>   >
>
> --
>
> ---
> You received this message because you are subscribed to the Google Groups 
> "memcached" group.
> To unsubscribe from this group and stop receiving emails from it, send an 
> email to memcached+unsubscr...@googlegroups.com.
> For more options, visit https://groups.google.com/d/optout.
>
>

-- 

--- 
You received this message because you are subscribed to the Google Groups 
"memcached" group.
To unsubscribe from this group and stop receiving emails from it, send an email 
to memcached+unsubscr...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

Re: Memcached Binary protocol

[dormando]

Looks like the protocol is getting out of sync somehow.

conn_waiting only means it's waiting to read more bytes from the socket
from a set. Then it looks like the client doesn't send anymore bytes,
times out, then closes the socket (-> conn_read -> conn_closing).

It's most likely a bug in how you're using the binary protocol, but it's
hard to say from here. Somehow you're writing fewer bytes to the socket
than you told the binary protocol to receive.

On Wed, 26 Apr 2017, watul123 wrote:

> Yes I am 100% sure.
> When the binary protocol is in picture then only this happens, otherwise same 
> test program with same argument runs perfect. I debugged a lot before
> posting to this group. I am with you on the fact the binary protocol has 
> nothing to do with the timeouts, but it is the one cause the failure while
> reading from socket, then I guess the connection gets close, and at the 
> application level I get MEMCACHED_TIMEOUT. 
>
> This is what I see on memcached's log
>
> 36: going from conn_parse_cmd to conn_mwrite
> 36: going from conn_mwrite to conn_new_cmd
> 36: going from conn_new_cmd to conn_waiting
> 36: going from conn_waiting to conn_read
> 36: going from conn_read to conn_closing
> <36 connection closed.
> 36: going from conn_closing to conn_closed
>
>
>
> On Wednesday, April 26, 2017 at 5:02:04 PM UTC-7, Dormando wrote:
>   Any way to get more information about the timeouts you're seeing?
>
>   There's nothing in the protocol that would cause "timeouts", but bugs
>   somewhere could cause clients to hang waiting on more data I guess.
>
>   You're sure they're timeouts and not some other kind of error?
>
>   On Wed, 26 Apr 2017, Atul Waghmare wrote:
>
>   > Hi there,
>   >
>   > I am facing one issue with memcached binary protocol. Whenever I 
> force the memcached to use the binary protocol, my application get
>   occasional timeouts
>   > and occasional success. The percentage of failure(set timeouts) is 
> more than 80% when the memcached spawn with binary protocol . The moment
>   I remove the
>   > binary option, the success rate is 100%. 
>   >
>   > memcached - v1.4.36   
>   > libmemcached -v1.0.18
>   >
>   > Any idea what may be wrong?
>   >
>   > Thanks,
>   > Atul
>   >
>   > --
>   >
>   > ---
>   > You received this message because you are subscribed to the Google 
> Groups "memcached" group.
>   > To unsubscribe from this group and stop receiving emails from it, 
> send an email to memcached+...@googlegroups.com.
>   > For more options, visit https://groups.google.com/d/optout.
>   >
>   >
>
> --
>
> ---
> You received this message because you are subscribed to the Google Groups 
> "memcached" group.
> To unsubscribe from this group and stop receiving emails from it, send an 
> email to memcached+unsubscr...@googlegroups.com.
> For more options, visit https://groups.google.com/d/optout.
>
>

-- 

--- 
You received this message because you are subscribed to the Google Groups 
"memcached" group.
To unsubscribe from this group and stop receiving emails from it, send an email 
to memcached+unsubscr...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

Re: Memcached Binary protocol

[watul123]

Yes I am 100% sure. 
When the binary protocol is in picture then only this happens, otherwise 
same test program with same argument runs perfect. I debugged a lot before 
posting to this group. I am with you on the fact the binary protocol has 
nothing to do with the timeouts, but it is the one cause the failure while 
reading from socket, then I guess the connection gets close, and at the 
application level I get MEMCACHED_TIMEOUT.  

This is what I see on memcached's log

36: going from conn_parse_cmd to conn_mwrite
36: going from conn_mwrite to conn_new_cmd
36: going from conn_new_cmd to conn_waiting
36: going from conn_waiting to conn_read
36: going from conn_read to conn_closing
<36 connection closed.
36: going from conn_closing to conn_closed



On Wednesday, April 26, 2017 at 5:02:04 PM UTC-7, Dormando wrote:
>
> Any way to get more information about the timeouts you're seeing? 
>
> There's nothing in the protocol that would cause "timeouts", but bugs 
> somewhere could cause clients to hang waiting on more data I guess. 
>
> You're sure they're timeouts and not some other kind of error? 
>
> On Wed, 26 Apr 2017, Atul Waghmare wrote: 
>
> > Hi there, 
> > 
> > I am facing one issue with memcached binary protocol. Whenever I force 
> the memcached to use the binary protocol, my application get occasional 
> timeouts 
> > and occasional success. The percentage of failure(set timeouts) is more 
> than 80% when the memcached spawn with binary protocol . The moment I 
> remove the 
> > binary option, the success rate is 100%.  
> > 
> > memcached - v1.4.36
> > libmemcached -v1.0.18 
> > 
> > Any idea what may be wrong? 
> > 
> > Thanks, 
> > Atul 
> > 
> > -- 
> > 
> > --- 
> > You received this message because you are subscribed to the Google 
> Groups "memcached" group. 
> > To unsubscribe from this group and stop receiving emails from it, send 
> an email to memcached+...@googlegroups.com . 
> > For more options, visit https://groups.google.com/d/optout. 
> > 
> >

-- 

--- 
You received this message because you are subscribed to the Google Groups 
"memcached" group.
To unsubscribe from this group and stop receiving emails from it, send an email 
to memcached+unsubscr...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

Re: Memcached Binary protocol

[dormando]

Any way to get more information about the timeouts you're seeing?

There's nothing in the protocol that would cause "timeouts", but bugs
somewhere could cause clients to hang waiting on more data I guess.

You're sure they're timeouts and not some other kind of error?

On Wed, 26 Apr 2017, Atul Waghmare wrote:

> Hi there,
>
> I am facing one issue with memcached binary protocol. Whenever I force the 
> memcached to use the binary protocol, my application get occasional timeouts
> and occasional success. The percentage of failure(set timeouts) is more than 
> 80% when the memcached spawn with binary protocol . The moment I remove the
> binary option, the success rate is 100%. 
>
> memcached - v1.4.36   
> libmemcached -v1.0.18
>
> Any idea what may be wrong?
>
> Thanks,
> Atul
>
> --
>
> ---
> You received this message because you are subscribed to the Google Groups 
> "memcached" group.
> To unsubscribe from this group and stop receiving emails from it, send an 
> email to memcached+unsubscr...@googlegroups.com.
> For more options, visit https://groups.google.com/d/optout.
>
>

-- 

--- 
You received this message because you are subscribed to the Google Groups 
"memcached" group.
To unsubscribe from this group and stop receiving emails from it, send an email 
to memcached+unsubscr...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.