Modifying the HTTP header parser in Lusca

I've been slowly working towards a variety of medium-term goals in Lusca. I've resisted committing various bits of partially finished work partly because they're works in progress but partially because I'm not happy with how the code fits together.

One of these areas is the HTTP header parser and management routines. Among other things, the main issues I have with the parser and management code is listed below.

• Each header entry is represented by separate strings in memory;
• Each header entry has a small, separately allocated object (HttpHeaderEntry), one per header
• Parsing the header entries uses various stdio routines to iterate over characters, and these may be implemented slower (to handle unicode/wide/UTF/locale support) than what's needed here (7-bit ASCII);
• There's some sanity checks in the header parser - specifically, duplicate content-length - which is likely better once the headers have been parsed.

I've been working on the first two items in separate branches. One converts the HttpHeaderEntry items into a single allocated array, which is grown if needed. Another takes the current String API and turns it into fully reference-counted strings. Both of these work fine for me. But shoe-horning it into the current HTTP parser code - which expects individually allocated/created HttpHeaderEntry items which it can destroy on a whim before they're considered a part of the Http Header set - is overly hackish and prone to introduce bugs.

It's taking me quite a bit of time to slowly change the HTTP parser code to be ready for the new management code. Well, it's taken me about 6 months to slowly modify it in a way that doesn't require rewriting everything and potentially changing expected behaviour and/or introduce subtle bugs.

The upshoot? Things take time, but the code hopefully will be tidier, cleaner and easier to understand. Oh, and won't include bugs.

State of the Cygwin/Windows port!

A rather nice chap has been ploughing through the source and making it work under Windows/Cygwin. I've been committing bits and pieces of his work into LUSCA_HEAD as time permits.

You can find the main port details in Issue 94.

Thanks!

Hunting down method_t bugs..

It all started with Issue 99. There was a random crash in the logging code. It looked like bug in the method handling changes which made it into Squid-2.HEAD a year or two ago. I've been patching issues in the method handling - specifically with NULL and uninitialised method pointers appearing in places - but this time the method_t pointed to junk data.

A bit of digging found that the pointer value did point to a valid method_t structure instance - but something free'd it. Hm. A little further digging found what was going on:

1. A METHOD_OTHER appeared (an RTSP method) which resulted in a new method_t being malloc'ed;
2. The pointer was copied to the request_t structure;
3. The request was processed;
4. The initial method_t pointer was freed, but the request_t method pointer still pointed to it;
5. The logging code then logged the stuff said request_t method pointer pointed to - but it was already free'd. Sometimes it'd be junk, sometimes it'd be the original contents.

The original method code (and the "known" methods) all throw around pointers - and copies of pointers - to statically allocated structures which never go away. Unfortunately this logic wasn't changed when the dynamic "other" methods appeared.

So I've been quite busy tidying up the method handling code in preparation for the change in how they're handled. LUSCA_HEAD now has some code which logs potential memory leaks when handling the dynamic methods. I'm going to see if I can come up with a way (or two) to log potential risky situations when items are dereferenced after being free'd. But hopefully I can fix the issue without introducing any further bugs.

Today's fun bug: invalid swap metadata

One of the Lusca users has issues with swap file contents being invalid. It's linked to the length of the object URL - and fixing this is unfortunately more difficult than first thought.

In essence - the size of the URL, the size of the metadata and the size of the buffers being used for reading data don't match "right". The TLV encoding code doesn't put an upper limit on the size of the metadata. The TLV decoding code doesn't enforce a maximum buffer size - it tries reading the metadata until it finds the end of said metadata. All of this unfortunately results in stupid behaviour when overly long URLs are stored.

The current maximum URL is MAX_URL - 4096 bytes. Squid-3 may have redefined this to be longer. The reason I haven't done this is because the URL is included in the swap metadata - and this is only read in in SM_PAGE_SIZE chunks - again, 4096 bytes. So if the URL is say, 4000ish or so bytes long, the total length of the encoded metadata is > 4096 bytes. This is happily written out to the swapfile.

Reading the data in however is another story. An SM_PAGE_SIZE sized buffer is created and a read is issued. The incomplete metadata is read in. There's unfortunately no check to ensure the passed in buffer actually fully contains all of the metadata - so the code happily trumps in potentially uninitialised memory. The end result is at the very least an invalid object which is eventually deleted; it could be worse. I haven't yet investigated.

In any case - I'm now going to have to somehow enforce some sensible behaviour. I'd much prefer to make the code handle arbitrary (ie, configurable arbitrary) long URLs and read in the metadata as needed - but that's a bigger issue which will take some further refactoring and redesigning to solve.

This is all another example of how code works "by magic", rather than "by intent". :)

Lusca update: important bug fixes, portability work

I've finally found and fixed two annoying bugs in Lusca.

The first is that occasionally the rebuild processed failed to properly rebuild the cache contents and the proxy would start with an empty cache. This ended up being due to the undocumented IPC code in Lusca, inherited from Squid, which would "eat" a few bytes at the beginning of the child process lifetime to establish whether the child was active and ready. It would try to read a hello string ("hi there!\n\0") but it would read 32 bytes instead of the exact string length. If the child process started sending data straight away (as my store rebuild helpers do!) the initial part of their conversation could be eaten.

The real fix is to modify the helper IPC handshake so it's two way and fixed length rather than the hacky way it's done now. But the temporary workaround seems to work fine - just read the 11 bytes for the hello string, rather than up to 32 bytes.

The second was a weird situation involving the swap.state files in the UFS store dirs growing to enormous sizes, filling the cache_dir up. This was eventually traced back to the proxy being reconfigured once a minute on some deployments (in this case - pfsense!). The problem was quite simple in the end - a reconfigure would force the swap state logs to be closed and re-opened; but this didn't know whether the swap state logs were pointing at the live ones or the rebuilding ones. In the latter, the rebuild process was reading from swap.state and appending to swap.state.new; a reconfigure would close the swap.state.new file and append to swap.state. This meant that the rebuild process was reading from swap.state and appending to swap.state.new - thus never quite finishing the rebuild process.

Those have been fixed for *NIX ports and now the rebuild processe seems to be moving forward quite swimmingly!

I've also had a user pop up recently who is submitting portability fixes for cygwin (and under Windows 7, no less!) I've been committing fixes to the way header files are included so the code mostly compiles under both *NIX and Cygwin. Admittedly most of those portability fixes were my fault - I didn't really bother making my new code "autoconf/automake safe" but, thankfully, revisiting this choice isn't difficult. Thankyou for the continuous assistance with the Cygwin changes!

Finally, there's still 46 currently active issues in the issue tracker. Some are just placeholders for me to revisit certain bits of code (eg Issue #85 - figuring out how PURGE works!) but I'm still aiming to address, repair and close the majority of those issues - and release a few more stable snapshots! - before I begin including more development stuff into the main tree.

Not that the snapshots at the moment are unstable - far from it!

Lusca and HTTP parsing..

I've broken out most of the client-side request parsing code into a separate source file. There's now only a single entry and exit point (and one sideways jump for a comm timeout handler for now) from the client-side main code into the request handling code.

The main aim here is to eventually isolate and rework the whole process with which a HTTP request is parsed and constructed in memory. The process itself isn't all that CPU intensive these days compared to Squid-2.x and Squid-3.x but it is quite ugly. I won't go into the gory details - you can check it out for yourself if you like. Just cast your eyes over src/client_side_request_parser.c in LUSCA_HEAD.

I'm going to leave the request parsing code as it is for now. It's ugly but it works and its inefficiencies are dwarfed by the misuses of memory bandwidth/CPU cycles elsewhere.

I think I've left the codebase slightly easier to understand than before. I think I'm now at the point where I can document a large part of the client-side request and reply handling pipeline. The caching, vary and ETag processing is still very messy and too tightly integrated into the client-side code for my liking but as it also works fine for now I'll be leaving it well alone. There be dragons and all of that.

Lusca Logging, revisited

So the obvious thing to do is to not run the logging path at all, and to avoid evaluating the access control list(s) if there's no access control set defined for logging.

There are a couple of problems with this!

Firstly, the current behaviour is to not pass request/reply information through some of the statistics counters and the clientdb modules if the request doesn't match the logging ACL. If there's no logging ACL then all requests are kicked to the statistics/clientdb counters.

Secondly, there's also the ACLs used in the access_log directives which allow the administrator to filter which requests/replies are logged to which access log file(s). The current implementation will pass all requests which aren't denied by the top-level logging ACL through to each of the access_log entries, checking those for suitability.

The question is - can I mostly maintain the behaviour for the use cases. The main two are:

1. where logging is completely disabled (via "access_log none") but maintain client counters and the clientdb;
2. where logging is enabled to one access_log entry, maintaining client counters and the clientdb.

Hm, stuff to do, stuff to do..