uninitialized constant OpenSSL::KDF

[Jehops]

After upgrading to version 2.1.0, we are seeing the issue described in mastodon/mastodon#6059. Downgrading back to 2.0.6 fixes the issue.

[rhenium]

From mastodon/mastodon#6059:

Hi,

jrm (FreeBSD packager) reported on IRC that after updating to Mastodon v2.1.0, Sidekiq and Puma raise the following error:

uninitialized constant OpenSSL::KDF
/usr/local/lib/ruby/gems/2.3/gems/openssl-2.1.0/lib/openssl/pkcs5.rb:14:in `pbkdf2_hmac'
/usr/local/lib/ruby/gems/2.3/gems/openssl-2.1.0/lib/openssl/pkcs5.rb:19:in `pbkdf2_hmac_sha1'
/usr/local/lib/ruby/gems/2.3/gems/activesupport-5.1.4/lib/active_support/key_generator.rb:21:in `generate_key'
/usr/local/lib/ruby/gems/2.3/gems/activesupport-5.1.4/lib/active_support/key_generator.rb:36:in `generate_key'
/usr/local/lib/ruby/gems/2.3/gems/globalid-0.4.1/lib/global_id/railtie.rb:26:in `block (2 levels) in <class:Railtie>'
/usr/local/lib/ruby/gems/2.3/gems/activesupport-5.1.4/lib/active_support/lazy_load_hooks.rb:67:in `block in execute_hook'
/usr/local/lib/ruby/gems/2.3/gems/activesupport-5.1.4/lib/active_support/lazy_load_hooks.rb:60:in `with_execution_control'
/usr/local/lib/ruby/gems/2.3/gems/activesupport-5.1.4/lib/active_support/lazy_load_hooks.rb:65:in `execute_hook'
/usr/local/lib/ruby/gems/2.3/gems/activesupport-5.1.4/lib/active_support/lazy_load_hooks.rb:50:in `block in run_load_hooks'
/usr/local/lib/ruby/gems/2.3/gems/activesupport-5.1.4/lib/active_support/lazy_load_hooks.rb:49:in `each'
/usr/local/lib/ruby/gems/2.3/gems/activesupport-5.1.4/lib/active_support/lazy_load_hooks.rb:49:in `run_load_hooks'
/usr/local/lib/ruby/gems/2.3/gems/railties-5.1.4/lib/rails/application/finisher.rb:73:in `block in <module:Finisher>'
/usr/local/lib/ruby/gems/2.3/gems/railties-5.1.4/lib/rails/initializable.rb:30:in `instance_exec'
/usr/local/lib/ruby/gems/2.3/gems/railties-5.1.4/lib/rails/initializable.rb:30:in `run'
/usr/local/lib/ruby/gems/2.3/gems/railties-5.1.4/lib/rails/initializable.rb:59:in `block in run_initializers'
/usr/local/lib/ruby/2.3/tsort.rb:228:in `block in tsort_each'
/usr/local/lib/ruby/2.3/tsort.rb:350:in `block (2 levels) in each_strongly_connected_component'
/usr/local/lib/ruby/2.3/tsort.rb:431:in `each_strongly_connected_component_from'
/usr/local/lib/ruby/2.3/tsort.rb:349:in `block in each_strongly_connected_component'
/usr/local/lib/ruby/2.3/tsort.rb:347:in `each'
/usr/local/lib/ruby/2.3/tsort.rb:347:in `call'
/usr/local/lib/ruby/2.3/tsort.rb:347:in `each_strongly_connected_component'
/usr/local/lib/ruby/2.3/tsort.rb:226:in `tsort_each'
/usr/local/lib/ruby/2.3/tsort.rb:205:in `tsort_each'
/usr/local/lib/ruby/gems/2.3/gems/railties-5.1.4/lib/rails/initializable.rb:58:in `run_initializers'
/usr/local/lib/ruby/gems/2.3/gems/railties-5.1.4/lib/rails/application.rb:353:in `initialize!'
/usr/local/www/mastodon/config/environment.rb:5:in `<top (required)>'
/usr/local/lib/ruby/site_ruby/2.3/rubygems/core_ext/kernel_require.rb:55:in `require'
/usr/local/lib/ruby/site_ruby/2.3/rubygems/core_ext/kernel_require.rb:55:in `require'
/usr/local/lib/ruby/gems/2.3/gems/sidekiq-5.0.5/lib/sidekiq/cli.rb:257:in `boot_system'
/usr/local/lib/ruby/gems/2.3/gems/sidekiq-5.0.5/lib/sidekiq/cli.rb:54:in `run'
/usr/local/lib/ruby/gems/2.3/gems/sidekiq-5.0.5/bin/sidekiq:12:in `<top (required)>'
/usr/local/bin/sidekiq:23:in `load'
/usr/local/bin/sidekiq:23:in `<main>'

I believe this is because OpenSSL::KDF was added in Ruby 2.4.

Correction: it's new in openssl gem v2.1.0 which was released a few days ago.

This is still weird because the extension library (openssl.so), which should be loaded by require "openssl", must have defined OpenSSL::KDF module. Could you check what is inside $LOADED_FEATURES?

puts $LOADED_FEATURES.grep(/openssl/)

[Jehops]

$ irb
irb(main):001:0> puts $LOADED_FEATURES.grep(/openssl/)
=> nil
irb(main):002:0>

[Jehops]

Sorry, I think/hope you meant this.

$ irb
irb(main):001:0> require "openssl"
=> true
irb(main):002:0> puts $LOADED_FEATURES.grep(/openssl/)
/usr/local/lib/ruby/2.3/amd64-freebsd11/openssl.so
/usr/local/lib/ruby/2.3/openssl/bn.rb
/usr/local/lib/ruby/2.3/openssl/pkey.rb
/usr/local/lib/ruby/2.3/openssl/cipher.rb
/usr/local/lib/ruby/2.3/openssl/config.rb
/usr/local/lib/ruby/2.3/openssl/digest.rb
/usr/local/lib/ruby/2.3/openssl/x509.rb
/usr/local/lib/ruby/2.3/openssl/buffering.rb
/usr/local/lib/ruby/2.3/openssl/ssl.rb
/usr/local/lib/ruby/2.3/openssl.rb
=> nil
irb(main):003:0>

[rhenium]

Sorry that I wasn't clear enough. Please inject that into the code where the problem exists, say, into /usr/local/lib/ruby/gems/2.3/gems/openssl-2.1.0/lib/openssl/pkcs5.rb, just before line 14.

I suspect the openssl.so from Ruby 2.3 and lib/openssl/pkcs5.rb from openssl gem v2.1.0 are loaded at the same time.

[Jehops]

Here it is the output with the line added.

[71269] * Version 3.11.0 (ruby 2.3.6-p384), codename: Love Song
[71269] * Min threads: 5, max threads: 5
[71269] * Environment: production
[71269] * Process workers: 2
[71269] * Preloading application
/usr/local/lib/ruby/2.3/amd64-freebsd11/openssl.so
/usr/local/lib/ruby/2.3/openssl/bn.rb
/usr/local/lib/ruby/2.3/openssl/pkey.rb
/usr/local/lib/ruby/2.3/openssl/cipher.rb
/usr/local/lib/ruby/2.3/openssl/config.rb
/usr/local/lib/ruby/2.3/openssl/digest.rb
/usr/local/lib/ruby/2.3/openssl/x509.rb
/usr/local/lib/ruby/2.3/openssl/buffering.rb
/usr/local/lib/ruby/2.3/openssl/ssl.rb
/usr/local/lib/ruby/2.3/openssl.rb
/usr/local/lib/ruby/gems/2.3/gems/openssl-2.1.0/lib/openssl/pkcs5.rb
/usr/local/lib/ruby/gems/2.3/gems/openssl-2.1.0/lib/openssl.rb
[71269] ! Unable to load application: NameError: uninitialized constant OpenSSL::KDF
/usr/local/lib/ruby/gems/2.3/gems/openssl-2.1.0/lib/openssl/pkcs5.rb:15:in `pbkdf2_hmac': uninitialized constant OpenSSL::KDF (NameError)
        from /usr/local/lib/ruby/gems/2.3/gems/openssl-2.1.0/lib/openssl/pkcs5.rb:20:in `pbkdf2_hmac_sha1'
        from /usr/local/lib/ruby/gems/2.3/gems/activesupport-5.1.4/lib/active_support/key_generator.rb:21:in `generate_key'
        from /usr/local/lib/ruby/gems/2.3/gems/activesupport-5.1.4/lib/active_support/key_generator.rb:36:in `generate_key'
        from /usr/local/lib/ruby/gems/2.3/gems/globalid-0.4.1/lib/global_id/railtie.rb:26:in `block (2 levels) in <class:Railtie>'
        from /usr/local/lib/ruby/gems/2.3/gems/activesupport-5.1.4/lib/active_support/lazy_load_hooks.rb:67:in `block in execute_hook'
        from /usr/local/lib/ruby/gems/2.3/gems/activesupport-5.1.4/lib/active_support/lazy_load_hooks.rb:60:in `with_execution_control'
        from /usr/local/lib/ruby/gems/2.3/gems/activesupport-5.1.4/lib/active_support/lazy_load_hooks.rb:65:in `execute_hook'
        from /usr/local/lib/ruby/gems/2.3/gems/activesupport-5.1.4/lib/active_support/lazy_load_hooks.rb:50:in `block in run_load_hooks'
        from /usr/local/lib/ruby/gems/2.3/gems/activesupport-5.1.4/lib/active_support/lazy_load_hooks.rb:49:in `each'
        from /usr/local/lib/ruby/gems/2.3/gems/activesupport-5.1.4/lib/active_support/lazy_load_hooks.rb:49:in `run_load_hooks'
        from /usr/local/lib/ruby/gems/2.3/gems/railties-5.1.4/lib/rails/application/finisher.rb:73:in `block in <module:Finisher>'
        from /usr/local/lib/ruby/gems/2.3/gems/railties-5.1.4/lib/rails/initializable.rb:30:in `instance_exec'
        from /usr/local/lib/ruby/gems/2.3/gems/railties-5.1.4/lib/rails/initializable.rb:30:in `run'
        from /usr/local/lib/ruby/gems/2.3/gems/railties-5.1.4/lib/rails/initializable.rb:59:in `block in run_initializers'
        from /usr/local/lib/ruby/2.3/tsort.rb:228:in `block in tsort_each'
        from /usr/local/lib/ruby/2.3/tsort.rb:350:in `block (2 levels) in each_strongly_connected_component'
        from /usr/local/lib/ruby/2.3/tsort.rb:431:in `each_strongly_connected_component_from'
        from /usr/local/lib/ruby/2.3/tsort.rb:349:in `block in each_strongly_connected_component'
        from /usr/local/lib/ruby/2.3/tsort.rb:347:in `each'
        from /usr/local/lib/ruby/2.3/tsort.rb:347:in `call'
        from /usr/local/lib/ruby/2.3/tsort.rb:347:in `each_strongly_connected_component'
        from /usr/local/lib/ruby/2.3/tsort.rb:226:in `tsort_each'
        from /usr/local/lib/ruby/2.3/tsort.rb:205:in `tsort_each'
        from /usr/local/lib/ruby/gems/2.3/gems/railties-5.1.4/lib/rails/initializable.rb:58:in `run_initializers'
        from /usr/local/lib/ruby/gems/2.3/gems/railties-5.1.4/lib/rails/application.rb:353:in `initialize!'
        from /usr/local/www/mastodon/config/environment.rb:5:in `<top (required)>'
        from /usr/local/lib/ruby/site_ruby/2.3/rubygems/core_ext/kernel_require.rb:55:in `require'
        from /usr/local/lib/ruby/site_ruby/2.3/rubygems/core_ext/kernel_require.rb:55:in `require'
        from config.ru:4:in `block in <main>'
        from /usr/local/lib/ruby/gems/2.3/gems/rack-2.0.3/lib/rack/builder.rb:55:in `instance_eval'
        from /usr/local/lib/ruby/gems/2.3/gems/rack-2.0.3/lib/rack/builder.rb:55:in `initialize'
        from config.ru:in `new'
        from config.ru:in `<main>'
        from /usr/local/lib/ruby/gems/2.3/gems/rack-2.0.3/lib/rack/builder.rb:49:in `eval'
        from /usr/local/lib/ruby/gems/2.3/gems/rack-2.0.3/lib/rack/builder.rb:49:in `new_from_string'
        from /usr/local/lib/ruby/gems/2.3/gems/rack-2.0.3/lib/rack/builder.rb:40:in `parse_file'
        from /usr/local/lib/ruby/gems/2.3/gems/puma-3.11.0/lib/puma/configuration.rb:318:in `load_rackup'
        from /usr/local/lib/ruby/gems/2.3/gems/puma-3.11.0/lib/puma/configuration.rb:243:in `app'
        from /usr/local/lib/ruby/gems/2.3/gems/puma-3.11.0/lib/puma/runner.rb:138:in `load_and_bind'
        from /usr/local/lib/ruby/gems/2.3/gems/puma-3.11.0/lib/puma/cluster.rb:397:in `run'
        from /usr/local/lib/ruby/gems/2.3/gems/puma-3.11.0/lib/puma/launcher.rb:183:in `run'
        from /usr/local/lib/ruby/gems/2.3/gems/puma-3.11.0/lib/puma/cli.rb:77:in `run'
        from /usr/local/lib/ruby/gems/2.3/gems/puma-3.11.0/bin/puma:10:in `<top (required)>'
        from /usr/local/bin/puma:23:in `load'
        from /usr/local/bin/puma:23:in `<main>'

[rhenium]

/usr/local/lib/ruby/2.3/amd64-freebsd11/openssl.so
/usr/local/lib/ruby/2.3/openssl/bn.rb
/usr/local/lib/ruby/2.3/openssl/pkey.rb
/usr/local/lib/ruby/2.3/openssl/cipher.rb
/usr/local/lib/ruby/2.3/openssl/config.rb
/usr/local/lib/ruby/2.3/openssl/digest.rb
/usr/local/lib/ruby/2.3/openssl/x509.rb
/usr/local/lib/ruby/2.3/openssl/buffering.rb
/usr/local/lib/ruby/2.3/openssl/ssl.rb
/usr/local/lib/ruby/2.3/openssl.rb
/usr/local/lib/ruby/gems/2.3/gems/openssl-2.1.0/lib/openssl/pkcs5.rb
/usr/local/lib/ruby/gems/2.3/gems/openssl-2.1.0/lib/openssl.rb

Well, this is strange -- since (one of the dependencies of) mastodon has openssl as its runtime dependency, only files from the gem should have been loaded. This implies something is doing require "openssl" before Bundler activates the gem (with bundle exec or Bundler.setup), but I I wasn't able to reproduce on Travis CI.

https://travis-ci.org/rhenium/mastodon/jobs/318783772

[saper]

I have just replaced rubygem-openssl 2.0.6 with rubygem-openssl 2.1.0 in my existing mastodon 2.0.0_3 setup and that was enough to reproduce the issue.

It seems that puma does require 'openssl' and it does not care whether it's this gem or anything else.

Adding gem 'openssl' as the first line there fixes the error, but this is certainly no solution; and also it raises the question why did it work with rubygem-openssl 2.0.6 ? Why does it not complain about undefined OpenSSL::PKCS5 with 2.0.6?

[saper]

I just noticed that

OpenSSL::PKCS5.pbkdf2_hmac
OpenSSL::PKCS5.pbkdf2_hmac_sha1

are defined in the /usr/local/lib/ruby/2.4/amd64-freebsd10/openssl.so module shipped with ruby. So rubygem-openssl 2.1.0 tries to override them in Ruby but there is no guarantee that openssl.so provided via the gem is loaded.

This is very messy and is a consequence of a namespace clash between the built-in module and this gem.

[saper]

To reproduce this problem, try my test_kdf_repr branch of this project.

What is interesting, test_pkcs5.rb from v2.0.6 is fully working with a stock openssl.so

@Jehops we are also running into interesting FreeBSD-related problems additionally. Ruby links to the base system OpenSSL and the port will use one from ports if installed:

/usr/local/bin/ruby24 -I./lib -ropenssl -ve'puts OpenSSL::OPENSSL_VERSION, OpenSSL::OPENSSL_LIBRARY_VERSION'
ruby 2.4.3p205 (2017-12-14 revision 61247) [amd64-freebsd10]
OpenSSL 1.0.2n  7 Dec 2017
OpenSSL 1.0.2n  7 Dec 2017
Stock Ruby module:
/usr/local/bin/ruby24 -ropenssl -ve'puts OpenSSL::OPENSSL_VERSION, OpenSSL::OPENSSL_LIBRARY_VERSION'
ruby 2.4.3p205 (2017-12-14 revision 61247) [amd64-freebsd10]
OpenSSL 1.0.1s-freebsd  1 Mar 2016
OpenSSL 1.0.1u-freebsd  22 Sep 2016