Using the Right Debugging Tools

A while ago, we updated the MongoDB PHP driver's embedded C library to a new version. The C library handles most of the connection management and other low level tasks that the PHP driver needs to successfully talk to MongoDB deployments, especially in replicated environments where servers might disappear for maintenance or hardware failures.

After upgrading the C library from 1.12 to 1.13 we noticed that one of the PHP driver's tests was failing:

derick@singlemalt:~/dev/php/derickr-mongo-php-driver $ make test TESTS=tests/atlas.phpt
…
====================================================================
FAILED TEST SUMMARY
---------------------------------------------------------------------
Atlas Connectivity Tests [tests/atlas.phpt]
=====================================================================

When running the test manually, we get:

derick@singlemalt:~/dev/php/mongodb-mongo-php-driver $ php tests/atlas.phpt
--TEST--
Atlas Connectivity Tests
--SKIPIF--
skip Atlas tests not wanted
--FILE--
PASS
mongo-php-driver/src/libmongoc/src/libmongoc/src/mongoc/mongoc-cluster.c:1852 mongoc_cluster_fetch_stream_single():
        precondition failed: scanner_node && !scanner_node->retired
Aborted

That was not good news.

The atlas.phpt test tests whether the PHP driver (through the C driver) can connect to a set of different deployments of Atlas, MongoDB's Database as a Service platform. The test makes sure we can talk to an Atlas replica set, a sharded cluster, a free tier replica set, as well as TLS 1.1 and TLS 1.2 specific deployments. The test started failing when connecting to the second provided URI (the sharded cluster).

At first I thought this was caused by the upgrade from version 1.12 to 1.13 of the C driver, but that didn't end up being the case. Let's see how we got to finding and fixing this bug.

First of all, I started GDB to see where it was failing:

derick@singlemalt:~/dev/php/mongodb-mongo-php-driver $ gdb --args php tests/atlas.phpt
GNU gdb (Debian 8.1-4+b1) 8.1
…
Reading symbols from php...done.
(gdb) run
Starting program: /usr/local/php/7.3dev/bin/php tests/atlas.phpt
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
--TEST--
Atlas Connectivity Tests
--FILE--
PASS
mongo-php-driver/src/libmongoc/src/libmongoc/src/mongoc/mongoc-cluster.c:1852 mongoc_cluster_fetch_stream_single():
        precondition failed: scanner_node && !scanner_node->retired

Program received signal SIGABRT, Aborted.
__GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51
51      ../sysdeps/unix/sysv/linux/raise.c: No such file or directory.

This shows that the C driver bailed out due to a specific assertion on line 1852 of mongoc-cluster.c. This assertion reads:

BSON_ASSERT (scanner_node && !scanner_node->retired);

Which didn't really say a lot. The next thing to try is then to make a backtrace in GDB with the bt command. This revealed:

(gdb) bt
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51
#1  0x00007ffff41472f1 in __GI_abort () at abort.c:79
#2  0x00007ffff32cdcf1 in mongoc_cluster_fetch_stream_single (
        cluster=0x555556ba8e68, server_id=2, reconnect_ok=true, error=0x555556b95858)
        at mongo-php-driver/src/libmongoc/src/libmongoc/src/mongoc/mongoc-cluster.c:1852
#3  0x00007ffff32cd9df in _mongoc_cluster_stream_for_server (
        cluster=0x555556ba8e68, server_id=2, reconnect_ok=true, cs=0x0, reply=0x7fffffff9ee0, error=0x555556b95858)
        at mongo-php-driver/src/libmongoc/src/libmongoc/src/mongoc/mongoc-cluster.c:1762
#4  0x00007ffff32cdbe6 in mongoc_cluster_stream_for_server (
        cluster=0x555556ba8e68, server_id=2, reconnect_ok=true, cs=0x0, reply=0x7fffffff9ee0, error=0x555556b95858)
        at mongo-php-driver/src/libmongoc/src/libmongoc/src/mongoc/mongoc-cluster.c:1826
#5  0x00007ffff32ddb0a in _mongoc_cursor_fetch_stream (cursor=0x555556b95700)
        at mongo-php-driver/src/libmongoc/src/libmongoc/src/mongoc/mongoc-cursor.c:647
#6  0x00007ffff32e12a0 in _prime (cursor=0x555556b95700)
        at mongo-php-driver/src/libmongoc/src/libmongoc/src/mongoc/mongoc-cursor-find.c:40
#7  0x00007ffff32df22c in _call_transition (cursor=0x555556b95700)
        at mongo-php-driver/src/libmongoc/src/libmongoc/src/mongoc/mongoc-cursor.c:1146
#8  0x00007ffff32df54b in mongoc_cursor_next (cursor=0x555556b95700, bson=0x7fffffffa038)
        at mongo-php-driver/src/libmongoc/src/libmongoc/src/mongoc/mongoc-cursor.c:1214
#9  0x00007ffff332511c in phongo_cursor_advance_and_check_for_error (cursor=0x555556b95700)
        at mongo-php-driver/php_phongo.c:742
#10 0x00007ffff33253d9 in phongo_execute_query (
        client=0x555556ba8e60, namespace=0x7fffeaeb5d58 "test.test", zquery=0x7ffff38201c0, options=0x0,
        server_id=1, return_value=0x7ffff38200f0, return_value_used=1)
        at mongo-php-driver/php_phongo.c:810
#11 0x00007ffff3342cc3 in zim_Manager_executeQuery (execute_data=0x7ffff3820160, return_value=0x7ffff38200f0)
        at mongo-php-driver/src/MongoDB/Manager.c:492
#12 0x0000555555e41d16 in execute_internal (execute_data=0x7ffff3820160, return_value=0x7ffff38200f0)
        at /home/derick/dev/php/php-src.git/Zend/zend_execute.c:2328
…

At first glance, I couldn't really see anything wrong with this backtrace, and was still puzzled as to why it would abort. I decided to go for a lunch time walk and have a look at it again. I always find that walks are good for clearing my mind.

After the walk, and a cuppa tea, I looked at the backtrace again, and noticed the following curiosity:

#4  0x00007ffff32cdbe6 in mongoc_cluster_stream_for_server (
        cluster=0x555556ba8e68, server_id=2, reconnect_ok=true, cs=0x0, reply=0x7fffffff9ee0, error=0x555556b95858)
        at mongo-php-driver/src/libmongoc/src/libmongoc/src/mongoc/mongoc-cluster.c:1826

vs:

#10 0x00007ffff33253d9 in phongo_execute_query (
        client=0x555556ba8e60, namespace=0x7fffeaeb5d58 "test.test", zquery=0x7ffff38201c0, options=0x0,
        server_id=1, return_value=0x7ffff38200f0, return_value_used=1)
        at mongo-php-driver/php_phongo.c:810

In frame #10 the server_id variable is 1, whereas in frame #4 later on, the server_id variable is 2. These should have been the same.

The server ID is determined by the C driver when selecting a server to send a read or write operation to, and refers to a specific server's connection ID. The PHP driver uses this server ID when executing the query through the phongo_execute_query function, which calls the C driver's mongoc_collection_find_with_opts. The latter accepts as its 3rd argument a bson_t value with options to use while executing a query. These options include the pre-selected server ID, so that the C driver does not attempt to reselect a server:

cursor = mongoc_collection_find_with_opts(collection, query->filter, query->opts,
        phongo_read_preference_from_zval(zreadPreference TSRMLS_CC));

I decided to investigate which options the PHP driver was sending to mongoc_collection_find_with_opts. A while ago I developed a GDB helper function, about which I wrote in pretty-printing BSON. I sourced this helper within my GDB instance, and switched to frame #10 to inspect the value of the query options:

(gdb) source ~/dev/php/mongodb-mongo-php-driver/src/libmongoc/.gdbinit
(gdb) frame 10

The function call uses the options from the query struct query->opts, so I used the printbson helper function to display its contents:

(gdb) printbson query->opts

Which showed:

$11 = "!\000\000\000\020serverId\000\002\000\000\000\020serverId\000\001", '\000' <repeats 90 times>
INLINE (len=33)
{
        'serverId' : NumberInt("2"),
        'serverId' : NumberInt("1")
}

There are not supposed to be two conflicting serverId elements. Unlike PHP's arrays, bson_t values can have the same key appear multiple times. Although the C driver had selected server ID 1 for this query, server 2 was used because it was the first serverId element in the options struct. But why were there two values in the first place?

If you look at the PHP test, you see the following:

<?php
$urls = explode("\n", file_get_contents('.travis.scripts/atlas-uris.txt'));

…
$query = new \MongoDB\Driver\Query([]);

foreach ($urls as $url) {
        …

        try {
                $m = new \MongoDB\Driver\Manager($url);
                …
                iterator_to_array($m->executeQuery('test.test', $query));
                …
        } catch(Exception $e) {
                …
        }
}
?>

From this follows that we create the Query object, assign it to $query, and then use the same variable for each iteration. Somehow, we were not resetting the query options back to default before we used them, resulting in a duplicate serverId field. Once we figured out the problem, creating the fix was easy enough: Make sure we use a clean query->opts struct before we pass it to the mongoc_collection_find_with_opts function.

Debugging this issue was made a lot easier by having the right debugging tools, and this case shows that spending time on writing the GDB helper function printbson earlier in the year paid off. With this bug fixed, we could release a new patch version of the MongoDB Driver for PHP.

Happy hacking!

Shortlink

This article has a short URL available: https://drck.me/dbgtools-e7g

Comments

No comments yet

Downstream — Trip 5

On the previous trip I walked from Reading to Bourne End on the Thames Path, and on this trip I will progress to Staines. Getting to Bourne End wasn't as easy as getting to Reading, and a fair bit slower with a train to Maidenhead and then the branch line towards Marlow.

Day 7 — Bourne End to Staines

Downstream — Day 7

I set off from Bourne End (without going to the lovely craft beer place) fairly early in the morning, on a bright and sunny day. It was clearly regatta season as became apparent when I made my way to Cookham, where their yearly races were on. Not only were they preparing for the watery fun, there was also a good display of vintage cars being set-up. I think I was too early to see it in full flow. Unfortunately, it did mean diverting from the river for a while, first because of the regatta, and then because there are private things in the way.

When I got back to the river after about a mile, I could just about make out the outlines and hill of Cliveden House across the river. I had visited this National Trust property with family.

Just before reaching Maidenhead I came upon Boulter's Lock. An industrial looking lock that replaced earlier 16th and 18th century locks on the same place. It was quite busy around the lock, with apparently one or two tour buses having stopped to let their passengers having a look at it. I spend some time wandering around and relaxing, before continuing my walk.

Not far from Maidenhead lays Bray, famous for their large number of Michelin starred restaurants. There is the one star Hind's Head where I had eaten before, the three star Fat Duck, and the three start Waterside Inn, where I attended a wedding once. You can't see much of it from the other side of the Thames though, so just had to do with my memories of the tasty food.

Not far from Bray is the Dorney Lake, which was used in the 2012 Olympics as a rowing venue under the name "Eton Dorney". You can't see much of it from the North side, but once you've walked along it to the bottom end you can actually go up and have a look.

Immediately after rounding a bend in the river Thames, you see Windsor Castle, the Queen's "country home", towering over Windsor and the river. My plan was to have lunch in Windsor, but just after getting into Eton I noticed a nice looking pub, the Waterman's Arms. Their menu looked good, and they have a few nice draughts on so I decided to have lunch there instead. As a bonus, I also noticed the pub's ceiling had a painting of the whole length of the Thames on it!

After lunch, and perhaps half a pint too much, I continued my walk. On the bridge that connects Eton to Windsor, a guitar player was playing joyful tunes, to which I listened when taking some photos and video.

After walking for a while in between a railway and the river, there were plenty of signs saying that "no drones" could be flown in and near The Home Park. I bet the Queen doesn't like people snoop on her activities much. Beyond lovely Datchet, I was directed through a field with nettles to be "closer to the river", but I don't think that was specifically worth it. The 200 meter stretch along the road would probably be easier walking. The only real scenery were planes leaving Heathrow Airport anyway. The noise of planes overhead continued for the rest of the walk into Staines, or as it now is called "Staines-upon-Thames". Please note that Staines does not rhyme with Thames.

Just before Staines is Runnymede. Runnymede is an important site in British history, as this is the location where the Magna Carta was signed, all the way back in 1215. The Magna Carta is a charter of rights that is the first one to prevent from the King being above the law. Modifications were made in the following decades, and not many of its provisions are currently left, but it was very important on a journey to a constitutional monarchy.

The site itself is an open expanse of grassland, with a piece of art — "The Jurors", by Hew Locke. There is also a memorial created by the American Bar Association. Unfortunately I only found out about this after I had come home, and hence did not visit it.

Just beyond Runnymede the Thames Path passes under the M25, which means I have walked all the way from the source into Greater London. From there it was not much further to the end of my walk at St. Peter's Church in Staines.


Photos from my Adventure on the Thames Path are available on Flickr, and all videos on Vimeo. You can also see all the photos on a map.

Shortlink

This article has a short URL available: https://drck.me/downstream05-e76

Comments

No comments yet

Downstream — Trip 4

On the previous trip I walked from Shillingford to Reading on the Thames Path, and on this trip I was planning to walk to Marlow. For once, getting to the start was easy by a single and fast train ride into Reading.

Day 6 — Reading to Bourne End

Downstream — Day 6

With the Reading Festival over, there was little to see of hoardings and temporary holding pits when I started my walk towards Marlow. The first interesting thing along the path is Caversham Lock, which quite busy on the slightly hazy morning.

A little further along, I crossed, by means of a foot bridge, the River Kennet. Through the Kennet and Avon Canal, it connects the Thames at Reading with the River Avon at Bristol, with the canal section between Bath and Newbury. When recording the video section on this, I messed up so had to re-record the narration.

Continuing along the Thames Path I noticed that there are a significant number of posh schools located along this stretch of the river, which sometimes means you need to make a little detour. Another of these detours away from the river is at Shiplake, where the Thames Path brings you straight to the quaint village, with its Phone Box Book Exchange, and its lovely railway station.

My plan was to have lunch at Henley, at one of the pubs along the river. Just when I got to Henley however it started to rain, and all the pubs where absolutely packed, with lots of people wearing colourful clothes. I had no idea what was going on, and I was hungry, so I found a little cafe, Cafe Copia near the town hall to have lunch, and wait for the rain to pass.

After lunch I crossed the bridge and found the Thames Path clogged with these same people in colourful clothes. Due to the busyness it was quite slow going for a while, until I got to a massive festival site just North of Remenham. There was a reason for the funny dress sense after all, as this site was hosting the Rewind Festival, a big 80s festival.

After half an hour, the festival site was no longer visible and audible and the tranquillity of the walk returned, and I could listen to the podcast series Caliphate from the New York Times, once again, in the middle of the private deer park of Culham Court.

At Hurley it became busy along the Thames again as they were having their annual Regatta. As I was quite early, there was no racing going on yet, but as often with these river-side festivals they make you go around them, away from the Thames Path.

Near Bisham, you can spot the former grounds of Bisham Abbey across the river. Now it is sports centre, but when I passed by there was a wedding reception in progress.

As I was now approaching Marlow, I asked one of my coworkers, who is local, for a good recommendation for a post-walk beer. He came back with saying that Marlow is primarily food-orientated, and proceeded to recommend a pub in Bourne End, another three and a half miles walking. I decided to do that, as it was quite reasonably early, and I was going to miss the train at Marlow anyway. Just past the town, the Thames Path got diverted again, as repaving work was being done on a section — yay for shiny new paths!

The extra miles to Bourne End where worth it in the end as I settled for a half at KEG Craft Beer for a lovely sour. I also picked up a train beer for my trip back into London.


Photos from my Adventure on the Thames Path are available on Flickr, and all videos on Vimeo. You can also see all the photos on a map.

Shortlink

This article has a short URL available: https://drck.me/downstream04-e6w

Comments

No comments yet

Downstream — Trip 3

On the previous trip I walked from Oxford to Shillingford on the Thames Path, and on this trip I was planning to walk to Pangbourne. Getting to Shillingford requires a bit of planning as the buses aren't terribly frequent, so I got up early (07:00 on a Saturday!) for a 08:50 bus from Reading to Shillingford to continue downstream on my adventure.

Day 5 — Shillingford to Reading

Downstream — Day 5

Setting off from Shillingford I quickly came upon the river Thames again, where I was sharing the path with a (very slow) running group—I was keeping up while walking! The first activity on the river itself came at Benson Marina where early birds where getting their canoes in the water, avoiding a range of other motorised pleasure craft.

Wallingford wasn't very far away, and it is a quite picturesque old market town. The Thames Path doesn't go through the town itself, but I did catch some of it on the bus on the way to the start of this walk, and when returning from Shillingford on my previous walk.

Five kilometres beyond Wallingford the Thames Path dives under the Moulsford Railway Bridge before the path diverges from the river around a school. It was an unpleasant section up a hill, and then along a busy and narrow road before the path moves back towards the river, where it joins the tow path by going through a pub's garden. I hope that in the future this diversion would not be needed.

This walk featured six locks, from Benson Lock near the start, to Caversham Lock near Reading. I noticed that although the locks themselves are not getting much larger, the accompanying weirs most definitely do. I spent a little time at Goring Lock just before lunch.

I walked into the small village of Goring-on-Thames to have lunch in a "locals" pub where I had my first first-hand "Brexit Experience". I think I'll leave that story for a separate post though.

After lunch I walked back to the river, and noticed that the landscape was very different from most of the other landscapes along the Thames so far. Instead of it being flat, and wide open, near Goring, the landscape suddenly turned very hilly around me. I did some googling and found that this specific feature is called the Goring Gap. Apparently, about a hundred thousand years ago the Thames didn't flow through Oxford and London but instead went through St. Albans and Ipswitch. During the last ice age the route got diverted because there was a glacier in the way. The Goring Gap is the new route that the Thames cut out through the hills.

The feature became even more apparent when the Thames Path diverted slightly from the river and had me going right up a hill. Near the top I spoke with some other hikers which assured me this was the only location where the Thames Path would do that.

My original plan was to finish at Pangbourne, but it was still early and the weather was nice, so I decided to continue to Reading, with its much easier rail connections.

At Purley the path left the Thames for a while, as due to "access rights" the path can't follow the river closely. Annoyingly that meant up another bit of uphill. Although it wasn't particularly a long stretch, it was quite steep. When I got back to the river, a rain (drizzle) shower started, which kept showing its head all the way back to my finish in Reading.

The last three kilometres go past the normally quiet fields of Little John's farm, but with the Reading Festival only a week away, it was a busy business of setting up for the festival.

Just before Reading I crossed under the Caversham bridge, the last bridge on this part of the walk. Before boarding my train in Reading, I had a well deserved pint at The Three Guineas right in front of the station. Another 34km done!


Photos from my Adventure on the Thames Path are available on Flickr, and all videos on Vimeo. You can also see all the photos on a map.

Shortlink

This article has a short URL available: https://drck.me/downstream03-e62

Comments

No comments yet

Downstream — Trip 2

It had been a few weeks since the previous walk. It had been quite hot and therefore I left it a little to continue along the Thames Path. Today was a lot cooler to start with, with some scattered showers predicted. As this was another weekend day I suspected rail engineering works—and indeed, there were no trains from Paddington to Oxford. The rail replacement bus which took me from Didcot Parkway towards the start in Oxford was luckily will organised, and I only ended up being about 15 minutes later than I originally had hoped for.

Day 4 — Oxford to Shillingford

Downstream — Day 4

It was fairly windy, and a little chilly when I left Oxford along the river. There were lots of rowers out on the Thames, which didn't come as a big surprise as that's what Oxford's stretch on the Thames Isis is known for. Not only were there lots of rowing clubs out, but also plenty of amateurs.

After a while it started to become darker and darker, and I started to wonder whether I was going to keep it dry. I encountered a pair of hikers also doing the Thames Path having a break near one of the boat houses. After having a chat, and avoiding a tree branch being blown out of the tree, I decided to continue and mentioned that I would chance getting rained upon. Without surprise, 5 minutes later it was pelting it down. I found some shelter under a few trees to put on my rain coat, but by the time I managed to put on my coat it was already dry. The additional humidity wasn't that great though.

Just before Abingdon, and its lock, there is a complicated section on the Thames Path that isn't very well signed. OpenStreetMap has the Thames Path (near) perfectly mapped, so it was easy enough for me to find the route, but I did assist somebody going in the opposite direction and explained where she had to go.

In Abingdon I had lunch at the Nag's Head, which is situated on its own island, Nag's Head Island. I opted for a traditional fish & chips, and had a pint of the local brew, called Nag's Island. Just when I was finishing lunch it started to drizzle a little bit, but it had already stopped by the time I had finished my visit to the little coder's room.

Unfortunately the drizzle did come back a few times over the next hours, while I was getting closer to the big towers of the Didcot power stations, which were looming on the horizon. Just before Culham I stopped to have a look at the Swift Ditch, and old short cut for the river Thames ignoring Abingdon. It is no longer in use, and very overgrown, but it was the fastest route for nearly a thousand years.

During the next bit of the walk, there were a great many locks to go past and over, until I came upon the river Thame. From the source at Thames' Head to where the river Thames meats the river Thame, the Thames is also called the Isis. Especially in Oxford do make a big deal out of that. On some Ordnance Survey maps you will still see "River Thames or Isis" for the whole stretch from the source to the Thame.

About 20 minutes later I arrived at my finish today at Shillingford, where I took the bus into Reading, via a bus-replacement bus in Wallingford, and via Henley-on-Thames as the schedule worked better for that. Why wait 30 minutes for a fast route that gets me into Reading 3 minutes earlier while it was very clearly going to rain soon? In Reading, the trains into London were unsurprisingly delayed, as they are so often.


Photos from my Adventure on the Thames Path are available on Flickr, and all videos on Vimeo. You can also see all the photos on a map.

Shortlink

This article has a short URL available: https://drck.me/downstream02-e5i

Comments

No comments yet

Life Line