Author: Paul Tomblin

The ultimate Heisenbug?

We’ve got a problem that happens apparently at random times at a few customer sites, but which we’ve been unable to reproduce in the lab. I’m not sure if that means it’s a Heisenbug or just a really nasty Bohr-bug.

The part of the system that is affected are three programs:

  • One that generates events, called “tixd“
  • One that is responsible for collecting events from all the programs in the system (not just these three) and delivering them to subscribers, called the “EventBroker” or “eb“
  • One that subscribes to the events that the “tixd” generates, which we call the “scheduled“

What has been happening on these customer sites is that after days or weeks of proper operation, for no apparent reason, the “tixd” would say that it’s generating an event, but the “scheduled” wasn’t getting them any more. The customer would notice the problem, sometimes a day or two later, complain that things weren’t happening that were supposed to happen, our service people would restart the whole system, and everything would start working again.

This bug has been happening for ages now, and every time I get called in to look at their logs because I wrote the “scheduled” and all the fingers point to me. But I couldn’t find any reason why “scheduled” would stop responding to events, or would unsubscribe from events. A few builds ago, Tom put some debug into his “eb” that would log every event that came in and which subscribers it was being delivered to. He also logged subscribes and unsubscribes. And so we waited.

Today, it finally happened again. And this time, I’ve got the logs that show:

  • At 6am, an event is generated by the tixd, and the eb delivers it to the subscriber scheduled
  • Between 10am and 11am, there is a flurry of event subscribes and unsubscribes, all unrelated to scheduled. But some of these unsubscribes are caused when events are being delivered to subscribers that have exited without unsubscribing.
  • At about 1am, there is another event generated by the tixd, and the eb receives it but says there are no subscribers found.

At this point, because the eb log shows no unsubscribe coming from scheduled, I’d say it’s not my bug and pass it off to Tom, the author of the eb. But unfortunately, my employer declined to renew Tom’s contract at the end of last year, so he no longer works here. He dodged this bullet by only 5 days. And so I’ve got to figure out why this is happening. Lucky me.

Another damn failure on my colo box

Yesterday I had a panic attack – suddenly a certain repository of binary files was empty where it had been nearly 300Gb a few hours previously. I knew that Vicki was uploading some stuff to it today using an “ncftpput” command that I’d shown her but which I knew she didn’t understand what each command line argument meant. So I’m sorry to say my first reaction was “I bet she somehow wiped it”. But I looked in her ~/.ncftp/spool/log file and couldn’t see anything unusual. I guess I owe her an apology for that thought.

I looked on the domU, and “df” showed the partition still mounted, and still 91% full. But nothing showed up to “ls”. I unmounted it and shut off the nightly backups so that it doesn’t delete the backup. “fsck.ext3 /dev/hdb” gave an error about a zero length partition. Then I thought I should probably be doing this on the dom0, and so I logged into it and had the same error with “fsck.ext3 /dev/hdb1”. “fsck -l /dev/hdb” on that entire drive showed that it didn’t think the drive was there at all. Oh oh. Moment of panic time – one of the other domUs has some of its disk space on that drive as well, thanks to LVM. I wonder what’s screwing up on his domU if it can’t get to some of its disk space. Time to shut them all down and reboot.

I did an “xm console xen1” to connect to my domU and that’s where I saw the oh-so-familiar ext3 errors. But everything shut down relatively cleanly and rebooted. I saw one message in the log files about resetting the ide0 controller, which I’m not sure was caused by or the cause of the problem. And after the reboot, all 300Gb of files were back. Thank goodness, because the upload bandwidth I’ve got at home these days means it would have taken months to get that partition restored from my backup.

This partition that screwed up this time is a normal primary disk partition, not an LVM logical volume, and on a different physical drive than the other failures, so at least I’ve eliminated LVM and the disk hardware as a cause. But that leaves the IDE controller and Xen.

I can’t wait for my new 1U server to come. Still not sure whether I should try Xen again or VMWare. VMWare probably isn’t as fast and it’s a lot more difficult to manage without getting the for-pay version, but at least it’s “ready for prime time”.

Are you a pilot who blogs, or a blogger who flies?

I got an email today from “IFR Pilot” (who also signs off as Darrell) cc’ed to a bunch of other pilot-bloggers proposing that we all have a fly-in and get to know each other. After a few massively cc’ed exchanges where people seemed enthusiastic about the idea, I set up a mailing list so that other pilot-bloggers could find this list and sign up. If you are in that category, you can sign up at this link.

A lot of the people on “IFR Pilot”‘s list were people I’d never heard of, so I can see I’m going to be adding a whole bunch of new blogs to my RSS reader.

So how’d I do? (Aviation edition)

For 2006 I set myself a few goals for my flying. If I recall correctly, it was

  • Fly 50 hours this year.
  • Do some airwork and get more proficient at smooth flight, especially the use of the rudder.
  • Start work towards a Commercial or Float Plane rating.

Well, it didn’t quite work out that way. I only got 37.9 hours flying time (25.3 complex), although I would have been 5 or so hours closer to my goal if the Lance hadn’t been broken on the day we departed for Oshkosh, and maybe another 3 hours if we’d been able to fly to Albany on Thanksgiving weekend. Oh well. That’s still up for the 20-25 hours I normally put in a year. I also didn’t do much airwork, mostly cross country. So I still finding myself having to look at the ball and putting in rudder as an afterthought rather than feeling what needs be put in. However, I did get training in the Garmin 530, and I think I’m getting more precise in my approaches and IFR en-route flying. I also had a little adventure with ice avoidance and negotiating with ATC for what I needed on my way home from Pinckneyville. So while I didn’t meet my goals, I think I had a pretty satisfying flying year.

I’m not sure if I’m going to get to Oshkosh this year – this is our 10th anniversary and I think I’m going to be spending my vacation time on a cruise or something. So I probably won’t be heading down to Florida for Jack Brown’s Seaplane Base or up to Parry Sound for Georgian Bay Airways for a float rating either.

So my goals for this year remain

  • Become a more proficient yoke and rudder pilot.
  • Continue to fly more than I have been in the past.