Meditations on Crafting Software: Adventures In Native Extensions

It seemed like an innocent enough thing to do: install a gem. But woe to the developer who assumes simplicity in a minefield of complexity!

I've reached Chapter 7 in "Rebuilding Rails" and it's been a fabulous ride, so far! If you're an advanced beginning or competent Rails developer, going through Noah's guide is a wonderful way to deepen your understanding of what's really going on.

Anywho...

Attempt #1: gem install ... easy peazy! ... right?!

There I was, getting ready to start cutting code against the sqlite3 gem. The next step was simply installing the gem. Easy enough...

I simply added the gem to my project's gemspec:

<project-home>/rulers.gemspec:
# coding: utf-8
lib = File.expand_path('../lib', __FILE__)
$LOAD_PATH.unshift(lib) unless $LOAD_PATH.include?(lib)
require 'rulers/version'

Gem::Specification.new do |spec|
spec.name = "rulers"
spec.version = Rulers::VERSION
spec.authors = ["John S. Ryan"]

...

spec.add_runtime_dependency "sqlite3"
end

and ran bundle install...

john@Slick:ruby-on-rulers (master) [1345]$ bundle install
Fetching gem metadata from https://rubygems.org/..........
Fetching gem metadata from https://rubygems.org/..
Resolving dependencies...
Using rake (10.1.0)
Using bundler (1.3.5)
Using erubis (2.7.0)
Using multi_json (1.8.0)
Using rack (1.5.2)
Using rack-test (0.6.2)
Using require_all (1.3.1)
Installing sqlite3 (1.3.8)
Gem::Installer::ExtensionBuildError: ERROR: Failed to build gem native extension.

/Users/john/.rvm/rubies/ruby-1.9.2-p290/bin/ruby extconf.rb
checking for sqlite3.h... *** extconf.rb failed ***
Could not create Makefile due to some reason, probably lack of
necessary libraries and/or headers. Check the mkmf.log file for more
details. You may need configuration options.

Provided configuration options:
.
.
.
/Users/john/.rvm/rubies/ruby-1.9.2-p290/lib/ruby/1.9.1/mkmf.rb:368:in `try_do': The complier failed to generate an executable file. (RuntimeError)
You have to install development tools first.
from /Users/john/.rvm/rubies/ruby-1.9.2-p290/lib/ruby/1.9.1/mkmf.rb:452:in `try_cpp'
from /Users/john/.rvm/rubies/ruby-1.9.2-p290/lib/ruby/1.9.1/mkmf.rb:853:in `block in find_header'
from /Users/john/.rvm/rubies/ruby-1.9.2-p290/lib/ruby/1.9.1/mkmf.rb:693:in `block in checking_for'
from /Users/john/.rvm/rubies/ruby-1.9.2-p290/lib/ruby/1.9.1/mkmf.rb:280:in `block (2 levels) in postpone'
from /Users/john/.rvm/rubies/ruby-1.9.2-p290/lib/ruby/1.9.1/mkmf.rb:254:in `open'
from /Users/john/.rvm/rubies/ruby-1.9.2-p290/lib/ruby/1.9.1/mkmf.rb:280:in `block in postpone'
from /Users/john/.rvm/rubies/ruby-1.9.2-p290/lib/ruby/1.9.1/mkmf.rb:254:in `open'
from /Users/john/.rvm/rubies/ruby-1.9.2-p290/lib/ruby/1.9.1/mkmf.rb:276:in `postpone'
from /Users/john/.rvm/rubies/ruby-1.9.2-p290/lib/ruby/1.9.1/mkmf.rb:692:in `checking_for'
from /Users/john/.rvm/rubies/ruby-1.9.2-p290/lib/ruby/1.9.1/mkmf.rb:852:in `find_header'
from extconf.rb:34:in `<main>'

Gem files will remain installed in /Users/john/.rvm/gems/ruby-1.9.2-p290@rulers/gems/sqlite3-1.3.8 for inspection.
Results logged to /Users/john/.rvm/gems/ruby-1.9.2-p290@rulers/gems/sqlite3-1.3.8/ext/sqlite3/gem_make.out

An error occurred while installing sqlite3 (1.3.8), and Bundler cannot continue.
Make sure that `gem install sqlite3 -v '1.3.8'` succeeds before bundling.

Native Extensions

If you're new to the Ruby environment, you might not yet be familiar with the fact that Ruby has native extensions. Native extensions are pieces of code (written in C and compiled to shared libraries) that either need to run much faster than Ruby can be interpreted or needs access to OS resources not available directly through the Ruby VM.

For more details, find this gentle yet informative treatment here: http://patshaughnessy.net/2011/10/31/dont-be-terrified-of-building-native-extensions

What Happened?

Back to the output of our first attempt. When encountering this output for the first time, it can be rather hard to read. But I've highlighted some important elements for ya...

Three key clues:

there's an additional log file that might have the next level of details: mkmf.log
it's the extconf.rb script that failed (which, if you read that link in the previous section, you'd know that it's responsible for generating the Makefile) which means that some system dependency wasn't satisfied (e.g. a missing C header file or a build tool).
the causing symptom is "...install development tools first." (and "development tools" on Mac OS X, that's the Xcode command-line tools).

First, was somehow finding that mkmf.log. I searched from the root of the RVM ruby I'm using:

$ find /Users/john/.rvm/rubies/ruby-1.9.2-p290 -name mkmf.log

At first glance, I didn't see anything that jumped out at me as a problem.

Xcode / extconf.rb Out of Sync

But then I googled it and stumbled into what Dave Isaacs reported that in some versions of Xcode, the gcc compiler had a new prefix: llvm-gcc-4.2... and that the Ruby extensions configurator (extconf.rb) is using the old name gcc-4.2: http://stackoverflow.com/a/10458609/1190801 (who rightfully credited Michael Cohen: http://frozencanuck.wordpress.com/tag/extconf-rb/ ).

I added the symlink which resolved that problem...

$ sudo ln -s /usr/bin/{llvm-,}gcc-4.2

Sidebar: that's a fun little bit of globbing. it expands into:

$ sudo ln -s /usr/bin/llbm-gcc-4.2 gcc-4.2

Cool, eh? :)

Attempt #2: Missing Libraries

With the symlink in place, I tried again...

john@Slick:ruby-on-rulers (master) [1360]$ bundle install
Fetching gem metadata from https://rubygems.org/..........
Fetching gem metadata from https://rubygems.org/..
Resolving dependencies...
Using rake (10.1.0)
Using bundler (1.3.5)
Using erubis (2.7.0)
Using multi_json (1.8.0)
Using rack (1.5.2)
Using rack-test (0.6.2)
Using require_all (1.3.1)
Installing sqlite3 (1.3.8)
Gem::Installer::ExtensionBuildError: ERROR: Failed to build gem native extension.

/Users/john/.rvm/rubies/ruby-1.9.2-p290/bin/ruby extconf.rb
checking for sqlite3.h... yes
checking for sqlite3_libversion_number() in -lsqlite3... yes
checking for rb_proc_arity()... yes
checking for sqlite3_initialize()... yes
checking for sqlite3_backup_init()... yes
checking for sqlite3_column_database_name()... no
checking for sqlite3_enable_load_extension()... no
checking for sqlite3_load_extension()... no
checking for sqlite3_open_v2()... yes
checking for sqlite3_prepare_v2()... yes
checking for sqlite3_int64 in sqlite3.h... yes
checking for sqlite3_uint64 in sqlite3.h... yes
creating Makefile

make
/usr/bin/gcc-4.2 -I. -I/Users/john/.rvm/rubies/ruby-1.9.2-p290/include/ruby-1.9.1/x86_64-darwin10.8.0 -I/Users/john/.rvm/rubies/ruby-1.9.2-p290/include/ruby-1.9.1/ruby/backward -I/Users/john/.rvm/rubies/ruby-1.9.2-p290/include/ruby-1.9.1 -I. -DHAVE_RB_PROC_ARITY -DHAVE_SQLITE3_INITIALIZE -DHAVE_SQLITE3_BACKUP_INIT -DHAVE_SQLITE3_OPEN_V2 -DHAVE_SQLITE3_PREPARE_V2 -DHAVE_TYPE_SQLITE3_INT64 -DHAVE_TYPE_SQLITE3_UINT64 -I/Users/john/.rvm/usr/include -D_XOPEN_SOURCE -D_DARWIN_C_SOURCE -fno-common -O3 -ggdb -Wextra -Wno-unused-parameter -Wno-parentheses -Wpointer-arith -Wwrite-strings -Wno-missing-field-initializers -Wshorten-64-to-32 -Wno-long-long -fno-common -pipe -o backup.o -c backup.c
/usr/bin/gcc-4.2 -I. -I/Users/john/.rvm/rubies/ruby-1.9.2-p290/include/ruby-1.9.1/x86_64-darwin10.8.0 -I/Users/john/.rvm/rubies/ruby-1.9.2-p290/include/ruby-1.9.1/ruby/backward -I/Users/john/.rvm/rubies/ruby-1.9.2-p290/include/ruby-1.9.1 -I. -DHAVE_RB_PROC_ARITY -DHAVE_SQLITE3_INITIALIZE -DHAVE_SQLITE3_BACKUP_INIT -DHAVE_SQLITE3_OPEN_V2 -DHAVE_SQLITE3_PREPARE_V2 -DHAVE_TYPE_SQLITE3_INT64 -DHAVE_TYPE_SQLITE3_UINT64 -I/Users/john/.rvm/usr/include -D_XOPEN_SOURCE -D_DARWIN_C_SOURCE -fno-common -O3 -ggdb -Wextra -Wno-unused-parameter -Wno-parentheses -Wpointer-arith -Wwrite-strings -Wno-missing-field-initializers -Wshorten-64-to-32 -Wno-long-long -fno-common -pipe -o database.o -c database.c
/usr/bin/gcc-4.2 -I. -I/Users/john/.rvm/rubies/ruby-1.9.2-p290/include/ruby-1.9.1/x86_64-darwin10.8.0 -I/Users/john/.rvm/rubies/ruby-1.9.2-p290/include/ruby-1.9.1/ruby/backward -I/Users/john/.rvm/rubies/ruby-1.9.2-p290/include/ruby-1.9.1 -I. -DHAVE_RB_PROC_ARITY -DHAVE_SQLITE3_INITIALIZE -DHAVE_SQLITE3_BACKUP_INIT -DHAVE_SQLITE3_OPEN_V2 -DHAVE_SQLITE3_PREPARE_V2 -DHAVE_TYPE_SQLITE3_INT64 -DHAVE_TYPE_SQLITE3_UINT64 -I/Users/john/.rvm/usr/include -D_XOPEN_SOURCE -D_DARWIN_C_SOURCE -fno-common -O3 -ggdb -Wextra -Wno-unused-parameter -Wno-parentheses -Wpointer-arith -Wwrite-strings -Wno-missing-field-initializers -Wshorten-64-to-32 -Wno-long-long -fno-common -pipe -o exception.o -c exception.c
/usr/bin/gcc-4.2 -I. -I/Users/john/.rvm/rubies/ruby-1.9.2-p290/include/ruby-1.9.1/x86_64-darwin10.8.0 -I/Users/john/.rvm/rubies/ruby-1.9.2-p290/include/ruby-1.9.1/ruby/backward -I/Users/john/.rvm/rubies/ruby-1.9.2-p290/include/ruby-1.9.1 -I. -DHAVE_RB_PROC_ARITY -DHAVE_SQLITE3_INITIALIZE -DHAVE_SQLITE3_BACKUP_INIT -DHAVE_SQLITE3_OPEN_V2 -DHAVE_SQLITE3_PREPARE_V2 -DHAVE_TYPE_SQLITE3_INT64 -DHAVE_TYPE_SQLITE3_UINT64 -I/Users/john/.rvm/usr/include -D_XOPEN_SOURCE -D_DARWIN_C_SOURCE -fno-common -O3 -ggdb -Wextra -Wno-unused-parameter -Wno-parentheses -Wpointer-arith -Wwrite-strings -Wno-missing-field-initializers -Wshorten-64-to-32 -Wno-long-long -fno-common -pipe -o sqlite3.o -c sqlite3.c
/usr/bin/gcc-4.2 -I. -I/Users/john/.rvm/rubies/ruby-1.9.2-p290/include/ruby-1.9.1/x86_64-darwin10.8.0 -I/Users/john/.rvm/rubies/ruby-1.9.2-p290/include/ruby-1.9.1/ruby/backward -I/Users/john/.rvm/rubies/ruby-1.9.2-p290/include/ruby-1.9.1 -I. -DHAVE_RB_PROC_ARITY -DHAVE_SQLITE3_INITIALIZE -DHAVE_SQLITE3_BACKUP_INIT -DHAVE_SQLITE3_OPEN_V2 -DHAVE_SQLITE3_PREPARE_V2 -DHAVE_TYPE_SQLITE3_INT64 -DHAVE_TYPE_SQLITE3_UINT64 -I/Users/john/.rvm/usr/include -D_XOPEN_SOURCE -D_DARWIN_C_SOURCE -fno-common -O3 -ggdb -Wextra -Wno-unused-parameter -Wno-parentheses -Wpointer-arith -Wwrite-strings -Wno-missing-field-initializers -Wshorten-64-to-32 -Wno-long-long -fno-common -pipe -o statement.o -c statement.c
/usr/bin/gcc-4.2 -dynamic -bundle -o sqlite3_native.bundle backup.o database.o exception.o sqlite3.o statement.o -L. -L/Users/john/.rvm/rubies/ruby-1.9.2-p290/lib -L/Users/john/.rvm/usr/lib -L. -L/usr/local/lib -Wl,-undefined,dynamic_lookup -Wl,-multiply_defined,suppress -Wl,-flat_namespace -lruby.1.9.1 -lsqlite3 -lpthread -ldl -lobjc

make install
make: /opt/local/bin/gmkdir: No such file or directory
make: [/Users/john/.rvm/gems/ruby-1.9.2-p290@rulers/gems/sqlite3-1.3.8/lib/sqlite3/sqlite3_native.bundle] Error 1 (ignored)
/opt/local/bin/ginstall -c -m 0755 sqlite3_native.bundle /Users/john/.rvm/gems/ruby-1.9.2-p290@rulers/gems/sqlite3-1.3.8/lib/sqlite3
make: /opt/local/bin/ginstall: No such file or directory
make: *** [/Users/john/.rvm/gems/ruby-1.9.2-p290@rulers/gems/sqlite3-1.3.8/lib/sqlite3/sqlite3_native.bundle] Error 1

Gem files will remain installed in /Users/john/.rvm/gems/ruby-1.9.2-p290@rulers/gems/sqlite3-1.3.8 for inspection.
Results logged to /Users/john/.rvm/gems/ruby-1.9.2-p290@rulers/gems/sqlite3-1.3.8/ext/sqlite3/gem_make.out

An error occurred while installing sqlite3 (1.3.8), and Bundler cannot continue.
Make sure that `gem install sqlite3 -v '1.3.8'` succeeds before bundling.

Notice that extconf.rb succeeded, this time (green section). And that the compilation even succeeded (cyan section).

Things started going wrong during the install step. Specifically, two command-line tools are missing: /opt/local/bin/gmkdir and /opt/local/bin/ginstall. I checked and sure enough, those files didn't exist on my machine. What are they? Where would I get them?

More Googling...

Installing coreutils

...I learned that gmkdir and ginstall are part of a package called coreutils. Which turns out to be a pretty fundamental package that includes a whole bunch of GNU style tools for BSD-based Unix systems (and Darwin is a BSD variant).

http://thoughtsthatleakedout.blogspot.com/2011/10/problem-with-gmkdir-when-updating-gems.html

... and I took a wild guessed that this was the same package on MacPorts...

https://lists.macosforge.org/pipermail/macports-users/2010-September/022031.html

So, I installed coreutils...

john@Slick:.rvm [507]$ sudo port install coreutils
Password:
---> Computing dependencies for gettext
---> Fetching archive for gettext
---> Attempting to fetch gettext-0.18.3.1_1.darwin_11.x86_64.tbz2 from http://packages.macports.org/gettext
---> Attempting to fetch gettext-0.18.3.1_1.darwin_11.x86_64.tbz2.rmd160 from http://packages.macports.org/gettext
---> Installing gettext @0.18.3.1_1
---> Cleaning gettext
---> Computing dependencies for gettext
---> Deactivating gettext @0.18.3.1_0
---> Cleaning gettext
---> Activating gettext @0.18.3.1_1
---> Cleaning gettext
---> Fetching archive for gmp
---> Attempting to fetch gmp-5.1.2_0.darwin_11.x86_64.tbz2 from http://packages.macports.org/gmp
---> Attempting to fetch gmp-5.1.2_0.darwin_11.x86_64.tbz2.rmd160 from http://packages.macports.org/gmp
---> Installing gmp @5.1.2_0
---> Cleaning gmp
---> Deactivating gmp @5.0.5_0
---> Cleaning gmp
---> Activating gmp @5.1.2_0
---> Cleaning gmp
---> Computing dependencies for coreutils
---> Fetching archive for coreutils
---> Attempting to fetch coreutils-8.21_0.darwin_11.x86_64.tbz2 from http://packages.macports.org/coreutils
---> Attempting to fetch coreutils-8.21_0.darwin_11.x86_64.tbz2.rmd160 from http://packages.macports.org/coreutils
---> Installing coreutils @8.21_0
---> Activating coreutils @8.21_0

The tools provided by GNU coreutils are prefixed with the character 'g' by default to distinguish them from the BSD commands.
For example, cp becomes gcp and ls becomes gls.

If you want to use the GNU tools by default, add this directory to the front of your PATH environment variable:
/opt/local/libexec/gnubin/

---> Cleaning coreutils
---> Updating database of binaries: 100.0%
---> Scanning binaries for linking errors: 100.0%
---> No broken files found.
john@Slick:.rvm [508]$ which ginstall
/opt/local/bin/ginstall

Cool, thankfully that step worked. Now, to try again...

Attempt #3: Success!!!

With the symlink to gcc in place and the missing GNU tools installed, gave it one more go...

john@Slick:ruby-on-rulers (master) [1362]$ bundle install
Fetching gem metadata from https://rubygems.org/..........
Fetching gem metadata from https://rubygems.org/..
Resolving dependencies...
Using rake (10.1.0)
Using bundler (1.3.5)
Using erubis (2.7.0)
Using multi_json (1.8.0)
Using rack (1.5.2)
Using rack-test (0.6.2)
Using require_all (1.3.1)
Installing sqlite3 (1.3.8)
Using rulers (0.7.0) from source at .
Your bundle is complete!
Use `bundle show [gemname]` to see where a bundled gem is installed.

Hurray!!!

Retrospective

Here's a few things I learned about troubleshooting in this process:

gather all your forensics (i.e. read through all of the logging output you can get your hands on);
learn the process at hand (knowing what extconf.rb was doing was hugely helpful);
where you're given the gift of full command lines that were executed and failed, go run those manually to see if you get more information/context;
If at first you don't find it, google, google again.

Meditations on Crafting Software

Pages

04 October 2013

Adventures In Native Extensions