Unintentional side-effects - IPv4/IPv6 load balancing..

Here's a fun one:

1310397101.830 416 X TCP_MISS/200 700 GET http://www.freebsd.org/layout/images/front_get_back.png adrian DIRECT/[2001:4f8:fff6::22] image/png
1310397101.835 413 X TCP_MISS/200 851 GET http://www.freebsd.org/layout/images/front_get_tr.png adrian DIRECT/69.147.83.34 image/png

Since the ipcache code already balances outbound connections between multiple hosts, any IPv6 hosts get similarly load balanced.. between IPv4 hosts as well.

I may end up adding in logic to connect to "only v4" and "only v6" in forward.c...

Lusca update: IPv6 server work is now working

I'm now using the Lusca IPv6 branch for browsing both IPv4 and IPv6 sites.

There's a bunch of little things to update and test, including testing the neighbor selection, peer and ICP code. It's still not yet doing transparent interception or TPROXY - that'll be among the last thing to work on. Finally, there's a bunch of connection timeout handling code which currently is being ignored - there's no convenient place to attach a timeout handler now since the file descriptor isn't created up front; it's created only once the DNS resolution is complete.

My main focus at the moment is testing and verifying the peer, neighbor selection and ICP code out.

But yes, it is actually working!

Lusca development update - IPv6 is almost working

Now that I've (hopefully!) completely finished with university, I can get back into using my hard-earned money from Xenion to get more Lusca development done. (And yes, I'll also be doing wireless development too, fear not.)

The IPv6 branch is a bit messy at the moment, but it's almost able to handle IPv6 server requests.

The problem? The existing code which handles connecting to remote hosts (ie, src/comm.c) doesn't "know" about IPv6. It assumes all sockets are IPv4 and that all hostnames which are returned are also IPv4.

There's unfortunately a lot of dirty code in there - commReuseFD() is the main culprit and a good example of this. The 30 second version - since the commConnectStart() API assumes the socket is already created before the connect() occurs, any "connect retry" (for multiple hostnames and multiple attempts at the same end-host) requires the socket to be closed and recreated. But the FD has to stay the same. So commReuseFD() manually creates a new FD, makes it look like the old FD, then calls dup2() to get it into the same FD as the old one.

The "Correct" Fix is to modify the API to not take an FD, but to return an FD on successful connect() to the remote destination. There's some problems with this though, most notably in the request forwarding layer where the FD is created and comm close handlers are assigned before the connection is attempted. I need to make sure that there's no code which calls comm_close() on the active connection whilst connect() is going on - as said code expects the FD to be valid and assigned by this point.

The "Dirty" fix is to modify commConnectStart() and commReuseFD() to check the FD address family and destroy/create a "new" socket with the correct address family.

The "Problem" is that the code allows the outgoing address to be specified, both for transparent interception (source address spoofing) and to be set via an ACL match. Since IPv4 and IPv6 addresses are now possible, the API will have to be modified to handle this case.

What I'm likely going to do is something inspired by Squid-3. I'll teach the forwarding layer about "try v4 destinations" and "try v6 destinations". The administrator can then configure whether to try v4 or v6 destinations first. Only one outgoing address has to be provided - either "v4" or "v6"; and commConnectStart() will only try connecting to IP addresses that match the family of the outgoing address. That way if a host resolves to a mix of v4 and v6 addresses, they'll be tried in a "v4" group, then a "v6" group (or vice versa.) It's a bit dirty, but it's likely doable in the short-term.

In the long term, I'd like to fix the API up to be less messy and return an FD, rather than take an existing FD and abuse that. But that can come later.

LUSCA ipv6 - almost there (again!)

I've managed to now get the Lusca IPv6 code to perform IPv6 lookups, open a socket to the remote host and then try an IPv6 connection.

But this doesn't work - the legacy Squid-2 comm code does this:

• Create an AF_INET socket via comm_open();
• Pass that socket to commConnectStart() with the relevant hostname or IPv4 address to connect to.

If the host is an IPv6 host, the IPv4 socket won't connect to it.

So now I'll have to change the comm API slightly to make commConnectStart() return a FD on completion, rather than taking a socket to connect to. This will also fix a long-standing hatred of mine - where Squid/Lusca opens up a socket that just sits there until DNS lookups succeed. Ew.

Lusca and IPv6 - almost there

Today's task - tying together the bits of Lusca's IPv6 work to be able to do an IPv6 AAAA lookup, join it with an IPv4 A lookup, then try to connect to IPv6/IPv4 hosts.

The result:

IP Cache Contents:

Hostname Flg lstref TTL N
www.freebsd.org 4 21595 2( 1) [2001:4f8:fff6::22]-BAD 69.147.83.34-OK

So far, so good. I don't have it yet connecting to IPv6 destinations, but all the right bits are in play to be able to do so.

There's plenty of bits in the Squid-3 DNS code that work around potential bugs/gotchas in DNS vs EDNS handling when handling some of the larger IPv6 record replies seen in the real world. I'm going to commit what I have thus far and then look at leveraging what they've done.

Now that exams are over ..

My university exams are over for another semester. Remind me why I put myself through this? :-)

So now that they're over, my open source work plate now is rapidly filling up again:

FreeBSD 802.11n:

• 802.11n RX works!
• But now I need to grovel through ath9k and figure out how 802.11n TX works.
• I'm blissfully ignoring handling sending or receiving A-MPDU and A-MSDU frames for now. That can come (much) later once I have stable 802.11n TX/RX in station and hostap mode (which is enough of a challenge for now, thanks.)

Lusca:

• IPv6 client support! I need to finish merging in more stuff to test.
• Thread manager - this is an important one.
• Find my RPM build patches and include them in the subversion tree.

Who needs sleep?

LUSCA and IPv6

The IPv6 development branch (/playpen/LUSCA_HEAD_ipv6 in subversion) now handles IPv6 HTTP clients. It is still limited to IPv4 servers and other protocols (snmp, icmp, htcp, ftp) are all still IPv4.

But it's a (long overdue) start.

I'll look at next fleshing out IPv6-aware SNMP, ICP and HTCP as they're reasonably easy - I just need to change the socket handling to be IPv4/IPv6 agnostic.

I'll begin merging some of the simple framework changes back to mainline Lusca once I've committed that memory leak fix that I've been discussing.

More IPv6 hackery..

I've been spending a little time fleshing out some more of the IPv6 preparation work in Lusca. Since they're rather intrusive patches, I'm doing the work in a separate branch (/playpen/LUSCA_HEAD_ipv6) and will merge back bits and pieces as needed.

I've migrated the client db, external URL rewriters, access logging and the client-facing connection management code over to be IPv6 aware. I still have the request_t state, ACL lookups (which is luckily done - but sitting in a branch!), further DNS work and the protocol-facing stuff (HTTP, FTP.)

There isn't much more work involved in getting LUSCA_HEAD ready enough to serve IPv6-facing clients. That'll let me push out Cacheboy content over IPv6.

But for now, it's back to hacking on commercial, customer code.

Cacheboy: Firefox Release 3.6.4

Cacheboy is currently pushing a good 800-1200mbit of firefox 3.6.4 updates. It has about 6% of the total mozilla mirror weight so I predict that there's currently around 16 gigabits of total mozilla updates going out.

Lusca is holding up fine - a single process happily pushed ~ 400mbit on some hosts during the initial peak. I'd obviously like to be able to push a lot more than that but I'm still doing baby steps in the Lusca performance department.

HTTP parser/management changes

I've finally committed changes to Lusca which migrate the HTTP Header management routines away from individual malloc/free calls per HTTP Header entry to (hopefully!) one malloc/free for every N. (N being tunable, of course.)

A lot of incremental preparation work was required in the HTTP parser to tidy things up enough to (hopefully!) minimise any impact on stability and functionality.

There really isn't all that much noticable improvement unless you're working on small, embedded platforms with slow CPUs. It's more of a precursor to further optimisation and reorganisation work. The cumulative effect will be worthwhile.

I've released a tarball with the work - r14674 - which also includes a handful of ATF unit tests in the test-suite/atf/ subdirectory.

I'll likely next work on reorganising some more of the FTP and HTTP protocol specific code which can be migrated out of src/ . I'd like to then spend some more time writing unit tests before (hopefully!) finishing off the IPv6 related DNS changes in preparation for more IPv6 related tomfoolery.

Unit testing using ATF

I've been toying around with the NetBSD unit testing framework called "ATF". Unlike other well-known FOSS unit testing software, ATF seems to have relatively comprehensive support for writing unit tests in C - which is quite important for a piece of C software.

In fact, it seems quite a few popular bits of FOSS software handling unit tests, embedded/API documentation, etc all support C rather poorly. I wonder why.

I've not linked the ATF stubs into the main build tree just yet. The ATF code can be found in the source tree under /test-suite/atf/ . It works enough for me to use "make check" on my iBook (yes, that's a pre-intel, PPC G4 iBook) to check that the basic changes I'm making to the HTTP parser code don't introduce new bugs.

I would love some help writing more unit tests though!

The best news is sometimes no news..

Things have been quiet on the Lusca front lately. I poked some of the users who were reporting earlier issues and asked whether said issues were fixed. All of them responded "yes".

So sometimes no news is good news. But you have to sometimes make sure.

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

Improving the access logging code

The Squid/Lusca access logging logic is .. well, to be honest, it's quite dirty and inefficient. Yes, like most of Squid. But this is a somewhat bite-sized piece of the puzzle which I can tidy up in one corner without too many effects elsewhere.. or is it?

For high request rate, small object loads on slower FSB hardware, one of the largest CPU users is actually the client-side access log path. There's two culprits here:

1. memcpy() when copying the "hier" struct from the request struct to the access log entry struct (client_side.c:297; revision 14457); and
2. The ACL list setup in preparation for writing filtered access log entries to multiple files (client_side.c:314; revision 14457).

The memcpy() is of a 588 byte HierarchyLogEntry struct - it's this large because of two "SQUIDHOSTNAMELEN" (256 byte) long strings embedded in the struct itself. Annoying, but somewhat fixable with a little code refactoring and use of reference counted strings.

The ACL list setup is a bit more problematic. It sets up an ACL checklist using the http_access checklist before then checking log_access / acl_access. It then further may use this ACL checklist when evaluating various access_log lines to allow filtering certain access log entries to certain files.

Now, the latter bites because the really slow paths (setting up and destroying the ACL access stuff) is done even if the default logging configuration is used - one log file - and there's currently no easy way around that. Furthermore, if you disable logging entirely (access_log none) then the initial setup of the access log entry information is done, the ACL checklist is created, and then it's all tossed away without logging. A bit stupid, eh?

I'll cover what I'm doing in the codebase in a subsequent post (read; when I'm not running off to class.)