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 <real@awpcabm02> 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 0x00 0x00 0x00 > <36 0x00 0x00 0x00 0x00 > <36 0x00 0x04 0x00 0x00 > <36 0x00 0x00 0x00 0x00 > <36 0x00 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 11:08:45 PM UTC-7, Dormando wrote: > How long are they when you get connection failure? > > On Wed, 26 Apr 2017, 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: > > > <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? > > > > > > > > > > > > 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+...@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+...@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.
