Present Perfect

After more than two years, I finally finished reading my second Spanish novel. This one was 'Zorro' by Isabel Allende. I assume it's different from her usual work. I obviously bit off more than I could chew, with a 380 page novel in small letters and very little whitespace. But I will persevere. Next!

After more than two years, I finally finished reading my second Spanish novel. This one was 'Zorro' by Isabel Allende. I assume it's different from her usual work. I obviously...

Yesterday, I was working some more on my jukebox code. It is now in the state where I can actually have it play a playlist and do the mixing properly. So I'm finally into dog food mode if you will, or in the mode where I can actually enjoy the result of the code I've written.

But I still had random failures that I couldn't make sense of that I thought were due to gnonlin. I was getting random backtraces on startup when setting up my gnl objects, like so:


Traceback (most recent call last):
File "examples/jukebox.py", line 123, in
main()
File "examples/jukebox.py", line 115, in main
main = Main(loop, tracks, playlist)
File "examples/jukebox.py", line 67, in __init__
self._jukebox.add_track(path, self._tracks[path][0])
File "/home/thomas/svn/src/dad/trunk/dad/gstreamer/jukebox.py", line 81, in add_track
self._process()
File "/home/thomas/svn/src/dad/trunk/dad/gstreamer/jukebox.py", line 137, in _process
operation.props.duration = mix.duration
TypeError: could not convert argument to correct param type


I had been noticing them before but always thought "I'll get to that later." But yesterday it was getting on my nerves.

The problem was, there was nothing wrong with the duration I was setting. 'duration' is an INT64 property on a gnloperation, and the duration I was setting was a normal long. I spent hours sprinkling debugging code and diving deeper into the stack to figure out where it was going wrong, but couldn't turn up anything.

I did see that in pygobject's gobject/pygtype.c code, it was checking PyErr_Occurred, and just resetting the error and the GValue. I added a PyErr_Print to see why the conversion was failing, and it told me:

TypeError: can't convert negative long to unsigned


This made even less sense - I wasn't setting a negative long, and I wasn't setting it to an unsigned property either. It's too bad the pygtype code wasn't bubbling up this clear error up, instead obfuscating it with the generic error, but it still didn't explain my bug.

We had invited friends over for dinner, so in the afternoon I was forced to take my mind off the keyboard, but as you all know that doesn't mean your mind is off the problem. I'm sure you all know that feeling where you have lots of different pieces of the puzzle lying in front of your mind's eye, and none of your theories made sense and you still see a bunch of different pieces.

Dinner was prepared, friends came, a good time was had by all, and my mind was off the problem. My only distraction was listening to the mixing points at the end of each song. And then when they left around 1 AM, Kristien and I sat on the couch, were watching some TV, it suddenly hit me. A classic bug pitfall.

What if the error was actually triggered before the line of code I was looking at ?

I'm sure you also all know that feeling where suddenly, a different way of looking at the problem makes all the pieces of the puzzle fall into place. It's probably the most gratifying moment when doing bug hunting - after hours of frustrating undirected prodding, suddenly you get that one theory that explains both the problem and the lack of result in the prodding.

That's when, instead of flying to the computer and trying it out, I prefer to savor the moment a bit. Because there's still the possibility that I might be wrong, and just uncover another layer of fur on the yak you're shaving. But no, everything seemed to add up, and I knew in my mind exactly the one line of code I needed to add to either prove or disprove your theory. And I also knew that this one line of code was the last thing I needed to try that day. Nothing else. Before, every 'just 2 more minutes' I asked for where valiant efforts borne from bug hunting optimism. Now, I see the problem crystal clear.

If the one line proves the theory, I can go to bed safely, be happy that I found the problem, that my stack ws unwound, and I was holding my juggling balls of my mental state in my hands. (Of course, if it disproved the theory, I was in for a night of bad sleep, going over the problem again and again in my head).

So, while Kristien got ready for bed, I moved back to the keyboard, and before the call that I thought was failing in the bindings, added another PyErr_Occurred check, and ran it. And there it went - and it confirmed that the error was actually generated before the line I was looking at, and coming from somewhere else.

So, off to bed, knowing that in the morning I knew exactly where to look.

After some futzing around, I realized that the call before was setting a negative value on a UINT64 property, and it was not erroring out. I was able to reproduce it from a python shell:


>>> import gst
>>> e = gst.element_factory_make('gnlsource')
>>> e.props.start = -1L
>>> import gobject
Traceback (most recent call last):
File "", line 1, in
TypeError: can't convert negative long to unsigned


And after digging through the history of that code, I found the revision where a change was made that removed the error checking for this particular case.

I filed a bug, and that was it. Hours of frustration boiling down to a simple commit labeled 'guint64 property fix'. The patch is trivial, so I'm sure they will do a better job at it than I would.

Of course, the actual bug is still in my code - I need to figure out why I'm setting a negative start value.

But again I am reminded of a fundamental bug fixing rule that I broke again this time: before trying to fix the bug where it appears to be, first make sure that the bug is where it appears to be. Sometimes the bug is created before where it is detected, and it's a lot easier to verify that first before anything else.

Yesterday, I was working some more on my jukebox code. It is now in the state where I can actually have it play a playlist and do the mixing properly....

Just noticed, while planning holidays with Kristien, that this year's GUADEC/Desktop Summit actually has its core days on the weekend. In the past I always remember them being during the week, in the center, with the fringe stuff before and after.

Bummer - I have two weddings, one on the starting weekend and one on the ending weekend, so while I was looking forward to going, maybe it doesn't make so much sense after all to go if I'll have to miss half of the core stuff already...

Just noticed, while planning holidays with Kristien, that this year's GUADEC/Desktop Summit actually has its core days on the weekend. In the past I always remember them being during the...

Yesterday Kristien was crossing over, with a bus stopping for her on the one side, and another car coming from the other direction. She was crossing over with her bike in her hand. While she was passing the bus, a motorcycle was racing past the bus, with no intention to stop. In a reflex, Kristien jumped forward, so the motorcycle only hit the back of her bike.

The back of her bike was completely squashed. The motorcycle slowed down a little, looked behind him, then raced away, even as other cars were trying to block him from fleeing.

The car that was stopped in the other direction originally pulled a U-turn and pursued the motorcycle. He was able to write down the cycle's license plate before the guy fled.

On the one hand I'm incredibly relieved Kristien's fine, beside a broken nail. On the other hand I want to make sure the guy that did this is taken off the streets. I have little hope of the police finding him, from what the police is saying, even if someone did give them the license plate.

If anyone knows how I can track down the owner of a Polish license plate, feel free to let me know. Irresponsible scum should be taken off the streets.

The witnesses, and the people that chased the bike to get the license plate, where all incredibly friendly and helpful. This kind of thing restores my faith in humanity. All of them where what people sometimes euphemistically call 'New Belgians'. Thank you all.

Yesterday Kristien was crossing over, with a bus stopping for her on the one side, and another car coming from the other direction. She was crossing over with her bike...

Using rsync on really large trees (> 1 million files) is really slow on the preparation stage. rsync creates a complete list of files on both sides. Especially if only a few files have changed between runs, the length of the preparation stage is much higher than the actual length of the synchronisation phase.

I thought that rsync had some options to take the mtime on directories into account, to not descend into directories that didn't have an mtime change, which would vastly reduce the amount of files it would have to look at. Apparently I made this option up though.

Or did I ? Is there any software that does what I describe ? Is there something wrong with the basic idea I'm thinking of ? Feel free to put me in my place!

Using rsync on really large trees (> 1 million files) is really slow on the preparation stage. rsync creates a complete list of files on both sides. Especially if only...