I’d like to take a moment to walk through the process of debugging this new system, because I built it, I added tests, I felt good about it, and it simply didn’t work with either PHP or Perl clients.
The first thing I decided to do was capture a packet trace. I wanted to see what was happening on the wire, so that I could understand how the server was really being used by these clients. This was full of surprises.
PHP failed immediately and noisily. There were a couple of unimplemented commands, and a validation exception from
botocorewhere PHP used
addwith a 0-length value. (This is a security feature added in 7.x, making sure the session ID it wants is not, through amazing bad luck, already in use.) Those were easy enough to build out, and a little tricky to test, but eventually, I got there.
Perl, though. It was weird. It seemed to be reading and writing fine, except that it rejected all the reads as invalid for some reason.
I couldn’t see what else to do, so I looked carefully over everything with a fine-toothed comb. This is the part of debugging where you just don’t know what’s happening.
(POST /login) > GET cgi-fab31… < VALUE cgi-fab31… 0 115 0 < END > SET cgi-5334f… 0 623 < STORED (GET /home) > GET cgi-5334f… < VALUE cgi-5334f… 0 623 0 < END > SET cgi-492ac… 0 115 < STORED
Here, length 115 corresponds to a logged-out session, and 623 to a logged-in one. What could be the problem?
If you, dear reader, want to do this as an exercise, look through the above trace. Compare with the protocol document that I used to implement the server.
Below, I’ll continue, describing what I tried and explaining why it didn’t work, before revealing the real issue.
I thought it unlikely, but the first thing I checked was the stored values vs. the returned values. They matched, bit-for-bit. Furthermore, the embedded expiration timestamps were accurate (session created 4 seconds ago, etc.) so the session should clearly not be rejected by the data itself.
I noticed the expiration timestamp is 0. Was that the issue? I wrote some more tests to simulate Perl’s calls on the wire, but with expiration of 0, they still passed. (As expected. The server just converts this to
86400because I need an expiration value, and that’s larger than our absolute session lifetime.)
memcache-dynamopacket trace with another trace from real
memcached, the other thing I saw was that
ENDwas being sent in a separate packet from
VALUEand the value contents. Surely, that wasn’t the issue? I worked a bit on packing my writes and not flushing the stream in between, and finally verified the result. It didn’t help.
Thank goodness, really. I’d worry about my sanity if a packet boundary affected the protocol.
I began to wonder if there was a problem in a Perl library. I checked out
CGI::Session::Driver::memcached, but none of them have had an update since 2012.
I started going through the packets byte-by-byte. The GET command had a trailing space on the line, but the server processes it with
line.rstrip(), so that wasn’t an issue.
But then I noticed something else. Real
memcachedwas returning the line as:
< VALUE cgi-9b992… 0 623
Should I leave off the CAS value when it’s 0? This didn’t make any sense, but I tried it, and it fixed Perl without harming PHP.
It also set the test suite on fire. Any time
aiomcachedid a get, it would throw an exception, because the CAS value was missing from the response. As it turns out, the library actually issues a
getscommand when the
get()method is called.
The difference between the
getscommands is not multiple-key support, but that
getsreturns CAS values, and
getdoes not. This is not indicated in the section about the commands in the protocol document; it’s mentioned in passing in the discussion of
<cas unique>. I took some notes on the protocol, and implemented from them, and missed this nuance.
The conspiracy was extended by Wireshark. It behaved a little oddly, not showing data values for those improper responses, but otherwise not issuing any warnings. (Unlike its “add must have a value” warning I had seen earlier.)
PHP also played into the conspiracy, either by sending
getscommands itself, or ignoring the extraneous CAS value in the response.
In retrospect, it might have been clever of me to capture a packet trace of the test suite. Assuming Wireshark would show a
getscommand or response differently, that would have helped narrow the problem down.
But in the end, that’s what debugging is: generating ideas, testing them, then looking for more if the test proves them wrong. I know “if you run out of ideas, then look harder” isn’t really great how-to advice? But that’s all I’ve got. Debugging is the most creative part of coding, and I don’t know how to teach creativity, either.
Post a Comment