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 <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+...@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.
