What's it all about, Alfie?

I was pulled in this morning to a problem with trade committals using a Python server that interfaces to a certain vendor's application. The python server is pretty nice - uses the built-in XMLRPC server and it's as clean and easy as pie to work on. Python - Good. The system it feeds - not so much.

I was getting an exception in committing a new trade to the system. I was getting a very unhelpful exception message, and as a result I had to run this guy several times with the same inputs and different levels of logging statements to see where in the code this was throwing the exception. It's python 2.3, so the really nice exception stack trace printing wasn't available to me, and the custom logging package in use wasn't my pick and I had no idea if it re-directed stdout/stderr.

What followed was about 30 mins of print debugging and about 5 mins of input data conditioning to make sure that none of the incoming data values were illegal and causing the problem. Good stuff to do, but given that this is all system-to-system interaction, this shouldn't have been strictly necessary. Nevertheless...

So I kept looking and finally got it down to the one field that was causing the problem. It was a string that was 23 characters long and the data description in the vendor's docs said it was limited to 20. OK, that's understandable in some systems like old-style client/server stuff. But in this day and age why are we limiting ourselves to 20 chars when we know any decent database has varchar fields and by their very nature, they are variable in length up to a point. Make that point 256 chars, or even 1k - what's the harm? Yes, it might not all fetch back in one packet, but given gigabit ethernet, is this still really a concern?

But even if it is, how about giving me a really useful exception like "Data value out of range" or something like that. Then you can use that for integers that are too big, strings, etc. It is pretty universal and then you are really helping out the guy trying to debug the problem.

As it was, I was forced to check "Why?" by searching around and finding in the docs the limit. But wait... there's more.

This vendor publishes a limit of n, but the limit is really n-1. Why? Good question. If the limit is 20, make the field in the database 21 or something. In fact, most varchar fields can hold up to their maximum, so why the offset? I can only imagine it's something from the designers/developers that is so silly as to be laughable.

I'm not laughing. I'm shaking my head.

So I finally put in the code to clean up the limits on the strings and log that data was getting truncated. Then I passed it off to the guys that were supposed to have figured this out, and they ran the tests and things worked. But we're still not done because with this truncation they have to make sure that it's not going to break anything moving forward. At this point, I don't know and don't really care. It's a messed-up system with horrible exception messages, pitiful documentation, and tech support that's virtually non-existant. I don't like it, and hope soon to be rid of it.

This morning I was looking at the logs of one of my price injectors and I got an exception on the CKStopwatch saying that the number of time events and time structs didn't match, which is a serious data integrity problem. I'm never gotten this before, and so I had to dig into it right away.

When I looked at the code, I saw something I knew was there, but it hadn't hit me in all the months this thing had been running. You see, in this injector, I need to have a few (configurable, based on load and number of processors) threads that take the prices and send them to the destination - inject them into the message stream. In these threads, I need to have an idea of the elapsed time they have been running so that I can print out statistics on their operation. Nothing big, but I need to have the number of prices they have injected over the time interval they have been working. Ticks per sec.

Since I needed to have this persistent over several loops of this thread's main processing method, I decided to declare it static at the top of the run loop:

  int SPPoller::process()
  {
      bool        error = false;
 
      static int         totalSent = 0;
      static CKStopwatch interval;

and then it checked to see if this was the first time through and reset the stopwatch. But all this was a horrible mistake waiting to bite me.

The static reference is going to give me one and only one value for this guy regardless of the number of threads using this code. The fact that the int was thread-safe was lucky for me, but the CKStopwatch wasn't. That's where I got the exception from the other day, and a different one this morning.

The reason I did this was to try and keep the variables close to their location of use. And had I gone with thread-local storage, I'd have been in good shape. But I didn't. I debugged this with a single injector and it was fine. I only have two in most configurations, so it's a little more dangerous, but still not as bad as if I had 50 threads.

The solution was easy - make the total sent count and the interval timer instance variables of the class and then in the constructor, reset the timer and zero out the count and everything will be just fine. This was only effecting my logging, and so it's not a horrible problem, but the exception caused the poller to die, and that was a serious issue. Had to be fixed. Easy to do.

Whew! That one caught me by surprise.

In joining the Mac OS X open source graphing package (CorePlot) group on Google Groups today I ran into something I've hit a few times before - people invite me based on my email address, which makes sense, but most of the time that's my "transient" email account - currently Comcast. What I ended up with was an invitation on my Comcast email account and not on my Gmail account where all my Google Groups are registered.

The problem is, I want them all on the same Gmail account. What I've had to do in the past was manually join the group, or have the owner send a new invitation to my Gmail account. While I sent an email to the group owner, I decided to try and fix this once and for all - by creating an account for my Comcast email account.

It wasn't all that hard - I basically did it in about 15 mins and in the end, I had my Comcast email as one account, and I'd unsubscribed to the CorePlot group. I'd then put all my other email addresses on my main Gmail account, so that should a new invitation come in, it's possible to have all them routed to the one main Gmail account. At least that's how I'm guessing it works. If not, I'll create another and then deal with that.

While it was a pain to have to go through all this, I have to say that the UI for the Google Groups is pretty nice. It's about as good as I could expect for a web-based app - even Google. There are a lot of screens, and it's easy to get lost in the maze of forms to set up the account and profile. It's something to get used to, but once you get the idea of where things are, it's a decent interface and gets the job done.

I'm glad to have cleared this up, anyway. Going forward, I shouldn't have any more issues of getting invitations under one email address and not having an account on Google Groups.

UPDATE: I will say that the support for Safari in Google Groups was far better than Camino and Firefox. I'm not sure why that is, maybe it's just because they have more Safari guys and they wanted to be supported well, or maybe it's the feature set in WebKit - hard to know. But things are much nicer in terms of uploading images and such in Safari. Gotta love that!

Last night on the way home I was thinking about the locking problem I had battling during the day and was just rolling it around in my mind. As so often happens, the solution came to me in a little question leading to a little insight, and then as I ran it through in my mind I was convinced that I had figured it out.

The problem was that I wasn't considering a hidden thread and a hidden mutex. Had it been one or the other, I might have seen it sooner, but the fact was it took me that long to have my mind "fan out" from the initial problem and see what else was happening in the system.

The message broker API is not thread-safe. So in order to make sure we don't mess it up, we have a global mutex on it. One one thing can be going through it - in or out. Seems very reasonable. Since we need to receive messages we have a polling thread in the API wrapper classes that uses poll() to see if there's anything at the socket, and if there is, it locks the API and then processes the incoming message, and unlocks the mutex.

We also have the sending thread. That guy is based on the fact that a price comes from the ticker plant and there may be several instruments that this price matches, so I have to lock the list of instruments, get all those that are driven by this price, and then send each one in turn. Finally, I unlock the list of instruments.

These would all be OK if it weren't for a few facts:

• the incoming messages can cause me to add a new instrument
• the locking on the instrument list on the sending thread encompasses the entire loop

What would happen is that I'd be sending an instrument with price to the message broker and an incoming message would arrive. That incoming message would block until the sending was done and then it would obtain the mutex on the API and start the processing of the incoming message.

If that message ended up requesting me to add a new instrument to the list by calling addInstrument() then I'd try to get the lock on the instrument list. Bingo! The sending thread is not done, and can't send again because the incoming thread had the API mutex locked, and the incoming message can't add the instrument because the sending thread has the lock on the instrument list. Deadlock.

The solution was simple: Never leave anything locked when sending a message. Simple. When I copied the instruments to a temp list in a thread-safe manner, and then processed the copy without a lock on the instrument list everything worked.

I have to say, this is one of the fun times to write code. The best debugger is the one between your ears. You have to understand what is happening and then think about the parts. To have figured this out with a debugger would have been very lucky to say the least. Timing was critical to the deadlock. I'm really surprised that it happened as often as it did.

Anyway... that was the biggie for the day. I'll track the code for the rest of the day and make sure I'm right, but it's gotta be the problem.

I had another lock-up in my tick injector that uses the Vendor library that I've had so much trouble with in the past. It appeared that it was in my code this time, and that surprised me quite a bit because I was convinced that there was no way I could have a deadlock because there was no section of code that had both locks in place at one time. If you don't have a thread that holds two locks then there's no way you can have a deadlock. Delay, sure, but no deadlock.

So I started going through all the code and checking to see if I missed anything. Well... sure enough, I had a little section where I had a stack locker active and then called a method that grabbed the other lock for a bit. I was able to clean this up, and I'm hoping this had to be it, but in truth, I'd have to have another section with two locks to have a deadlock. And I didn't find that section section.

I did, however, find a few places where I thought that encapsulation was a better plan, and so I made methods that were, themselves, thread-safe, and then put those into the code where I had originally had the locks. These should be essentially "no-ops", but in fact the locking will be slightly different and in that I may have helped myself even though I hadn't seen a section of code with two active locks.

I've also added in some more logging into my addInstrument() call - where it appears the lock-up was, just to see what happens next time. I'll run with this and we'll see if and when it fails what the logs tell us.

Today I did a little coding on my fast tick server because it was giving one user in London the head fake, and rather than ask them to understand that it was just that, I decided to fix the problem so it didn't misrepresent the data to the data maintenance team.

The problem was really that I worked hard to make sure the data in the server was maintained properly, and didn't spend any time thinking about making sure it was visually updated properly when it corrected itself. So if the user made the change, everything was fine, but if the system corrected itself, the user might think it hadn't. And then think that it was wrong when it really was just fine.

The code change was minor - maybe 10 lines, and the same code was used in at least one other place, but re-factoring it wasn't really necessary due to the locking constraints, so I just updated the code and it worked like a charm. I didn't have the heart to tell the user that they changed nothing, so I let them believe that I had found a bug in the way the data was moved around, and I did, but the effect is solely for the human's benefit.

But hey... it's always fun to code. Right?

I'm still on the trail of the problems in the message bus API. I stayed a little late last night to try a few things while my price injector wasn't injecting ticks. Turns out, I learned a bit, but then this morning I learned quite a bit more. It's getting downright interesting.

First, last night, when I wasn't injecting prices, I would see the poll() working as it should. This morning, I noticed that as soon as I started sending price messages, I started getting tons of poll() hits on the incoming message socket. Why on earth are they doing that?

More to the point, the poll() loop was working perfectly and I could cross that off my list. It was certainly a possibility that the polling loop was just stopping - an error, an exception, something could have stopped it and that would explain it. However, this morning, I saw the polling loop running like a champ, but the messages I sent this morning were not getting delivered to my code.

Interesting fact #2: the act of sending a message in this API causes the system poll() to return true even when there's no data waiting at the socket. I can imagine a few reasons why this might be the case, but all of them are pretty bad. The criteria for a positive result from poll() should always mean that there's data there on the socket waiting to be read. But clearly, this is not the case with this API.

So one good, one bad. What I'm left with is that I needed to add in more logging on the processing of the message data stream and hope that it's a trap-able error in the code I can control. If not, then there's no hope for a solution on my end, and I'll have to football all this information back to the vendor and hope that they can figure this out with the data I provide them.

I'm not holding my breath.

Today I got an email from a tech support guy for a vendor we use, asking if I'd tried their latest version to see if it fixed the problem I was having. Basically, it's a proprietary message bus that's very simple, and at the same time, fast. The problem is, it's not really fast enough to warrant being on it's own, but it's so old, that when it was new, it was probably something pretty useful - in the context of their system.

He asked a bunch of questions, all things I'd gone over with the last guy that contacted me on the 18 month old bug, but I wrote back a detailed message saying what I'd tried and what I believed to be the issue. However, because of the way they wrote their library, there's really no way I can know what's happening under the covers.

I suspect that it's in the socket handling - specifically the use of the poll() system call, and what it returns in different conditions. I know from experience that it can be tricky on linux if the socket gets in a weird state. My friend who wrote our C++ wrapper to the C API from the vendor did the simple poll() system call to see if there was a pending message on the socket, and if so, he'd call their handling method. But he used the simple poll() system call.

I decided that I'd see if the improved poll() I had written for CKit would help. It's got a lot better error handling and maybe the issue is with that. Certainly a good place to start. So I added that code, and we'll see what happens.

If that's not the case, then I'm going to start logging the activity around the poll() call to see if the vendor's handler function is hanging, or if there's even data at the socket to read. I'm not sure what's going to come of this, but it's an interesting diversion. Maybe I can come up with a work-around and fix this horrible problem.

Today I was trying to clean up a script we use at the Shop for equalizing perl on the different platforms around the place. We all need some variable of perl 5.8, but if it's 5.8.3 versus 5.8.8, it's not that big a deal. However, all perl implementations need to be able to have CPAN, plus database access which means that they have been linked against the right libraries for each version.

The problem is that this sounds easy, but in reality, there's a disconnect and not every build of perl available on the network mounts is built similarly. Some have database access, others don't. It's a bit of hit-n-miss.

Yesterday I was working on a perl script to monitor one of my tick injectors, and realized that in order to get perl working on these new boxes I had to enumerate all the hostnames. That is just far too brittle, and I didn't like it - but I couldn't see a nice pattern in the basic machine set-up to decide which one to use.

Today I decided to find out, so I made a matrix of all the machines, their architecture, OS version, and name, and then looked at the perl builds available to them. Turns out that there is a pattern, but it was obscured by the fact that not all versions of perl were available on all machines. I was able to create a solid filter based on the machine architecture (x86_64 or not) and then have a primary and a back-up.

It wasn't rocket science, but then again, very few things are. But this was a fun little excursion into what was there and what pattern fit. Interesting stuff.

The Shop is a heavy user of chat - be it IRC-based (as it was for so many years) or the 'secure' chat that we now use, it's chat. It's very useful as a conduit to the users for all kinds of information - especially the monitoring of servers and processes. This morning I did a little 5 min job to convert back one of the server monitoring bots from the 'secure' chat back to IRC chat as we have one of the latter, and the global messaging group which controls the former is still not allowing bots back on their network after a particularly bad server meltdown caused by a few bad bots.

I wanted to move this one guy back to straight IRC because it's a very nice example of a perl-based bot that can monitor all kinds of interesting things. I then spent a few hours crafting a monitoring bot out of this starting point to replace the java-based monitoring tools that had caused me so much trouble yesterday. I asked the guy that created them to turn them off - save one development box (his choice), until such time as we can be assured that there's no conflict in the communications.

His response was that these monitors are providing vital data on the status of the ticks flowing from my injectors into the system(s). I told him I totally understood his position, and if he'd just let me know what the processes were monitoring, I'd be glad to give him that same functionality, quickly, in a less intrusive monitoring framework.

I didn't hear from him, but I started one anyway with the likely candidates. I also talked to the head support guy and he had a simple little monitor as well. I included his test in with my code and started banging on it.

The first cut was nice, but I also wanted to add a little additional chatting when a stalled log restarted so that the users monitoring the chat channel would know that the problem corrected itself and they didn't have to worry about restarting anything. In this particular system, it's common for an updating process to get stalled and then restart without any intervention. I wanted to make sure that this was being passed on to the operators so they didn't worry about a problem that's corrected itself.

I sent out an email explaining it, and how to stop/start/restart it along with where it chats, and what it chats about. Basic information. I haven't heard from the group that put the other monitoring tool, but I'm guessing they are not going to be happy about what I've done. Not in the least. I hope I'm wrong, but in the past there has been more than a little animosity between my group here, and the group that did the other tool. Sad, but there's nothing that would have kept them from writing the same thing. Nothing at all.