New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

OpenSSL::Cipher#random_iv Regression in 9.1.14.0 #4857

Closed
HarlemSquirrel opened this Issue Nov 17, 2017 · 11 comments

Comments

Projects
None yet
4 participants
@HarlemSquirrel

HarlemSquirrel commented Nov 17, 2017

OpenSSL::Cipher#random_iv is about 12x slower for me on Ubuntu 16.04 with OpenJDK 1.8.0_151.

➤  java -version
openjdk version "1.8.0_151"
OpenJDK Runtime Environment (build 1.8.0_151-8u151-b12-0ubuntu0.16.04.2-b12)
OpenJDK 64-Bit Server VM (build 25.151-b12, mixed mode)

I have java set to use /dev/urandom instead of /dev/random.

➤  cat /usr/lib/jvm/java-8-openjdk-amd64/jre/lib/security/java.security | grep securerandom.source=
securerandom.source=file:/dev/urandom
➤  cat /usr/lib/jvm/java-8-openjdk-i386/jre/lib/security/java.security | grep securerandom.source= 
securerandom.source=file:/dev/urandom

JRuby 9.1.13.0

➤  JRUBY_OPTS='--profile' ruby -e "puts RUBY_VERSION, RUBY_ENGINE, RUBY_ENGINE_VERSION; require 'openssl'; OpenSSL::Cipher.new('AES-128-CBC').random_iv"
Profiling enabled; ^C shutdown will now dump profile info
2.3.3
jruby
9.1.13.0

main profile results:
Total time: 2.22

     total        self    children       calls  method
----------------------------------------------------------------
      1.87        0.04        1.83         221  Kernel.require
      1.42        0.00        1.41          91  Kernel.require
      0.86        0.11        0.75          35  Kernel.load
      0.78        0.77        0.01           1  Java::OrgJrubyExtOpenssl::OpenSSL.load
      0.38        0.00        0.38           2  Object#require_jar
      0.38        0.00        0.38           2  Jars.require_jar
      0.37        0.00        0.37           2  Jars.require_jar_with_block
      0.37        0.00        0.37           2  Jars.do_require
      0.37        0.00        0.37           2  Jars.home
      0.37        0.00        0.37           2  Jars.local_maven_repo
      0.36        0.00        0.36           1  Jars.maven_local_settings
      0.30        0.04        0.26          99  Array#each
      0.24        0.00        0.24           1  Gem::Specification.load_defaults
      0.24        0.00        0.24           1  Gem::Specification.each_spec
      0.24        0.00        0.24           1  Gem::Specification.each_gemspec
      0.21        0.05        0.16         285  Class#new
      0.16        0.00        0.16          16  Gem::Specification.load
      0.14        0.03        0.11          16  Kernel.eval
      0.13        0.00        0.13          28  Kernel.gem
      0.12        0.00        0.12           3  Gem::Dependency#to_spec
      0.11        0.00        0.11           3  Gem::Dependency#to_specs
      0.11        0.00        0.11           3  Gem::Dependency#matching_specs
      0.10        0.00        0.10          27  Kernel.send
      0.09        0.01        0.07          15  Gem::Specification#initialize
      0.08        0.00        0.08          12  Gem.register_default_spec
      0.07        0.00        0.07           3  Gem::Specification.stubs_for
      0.06        0.06        0.00          24  Java::JavaPackage#method_missing
      0.05        0.02        0.03          83  Array#map
      0.04        0.04        0.00        1424  String#sub
      0.03        0.02        0.01           2  Fixnum#times
      0.03        0.00        0.03           3  Gem::Specification.dirs
      0.03        0.01        0.02          44  Gem::Specification#add_dependency_with_type
      0.03        0.03        0.00         120  String#=~
      0.03        0.00        0.03          41  Gem::Specification#add_development_dependency
      0.03        0.00        0.03           9  Gem::Specification.gemspec_stubs_in
      0.03        0.00        0.02          86  Gem::Version.new
      0.02        0.00        0.02          99  Gem::Requirement#initialize
      0.02        0.00        0.02          25  Gem::Version#<=>
      0.02        0.00        0.02           4  Enumerable.find
      0.02        0.01        0.01          78  Array#map!
      0.02        0.00        0.02           1  Gem.win_platform?
      0.02        0.02        0.00           1  Time.now
      0.02        0.00        0.02          94  Gem::Requirement.create
      0.02        0.00        0.02           1  URI::RFC2396_Parser#initialize
      0.02        0.00        0.02          27  Gem.remove_unresolved_default_spec
      0.02        0.02        0.00          15  IO.read
      0.02        0.00        0.02          72  Gem::Dependency#initialize
      0.02        0.01        0.00           4  Hash#each
      0.02        0.00        0.02          50  Gem::Version#canonical_segments
      0.02        0.00        0.02           4  Gem::StubSpecification#to_spec

JRuby 9.1.14.0

➤  JRUBY_OPTS='--profile' ruby -e "puts RUBY_VERSION, RUBY_ENGINE, RUBY_ENGINE_VERSION; require 'openssl'; OpenSSL::Cipher.new('AES-128-CBC').random_iv"
Profiling enabled; ^C shutdown will now dump profile info
2.3.3
jruby
9.1.14.0

main profile results:
Total time: 27.28

     total        self    children       calls  method
----------------------------------------------------------------
     24.30       24.30        0.00           1  OpenSSL::Cipher#random_iv
      2.52        0.05        2.47         221  Kernel.require
      1.94        0.00        1.94          91  Kernel.require
      1.18        0.15        1.03          35  Kernel.load
      0.82        0.82        0.01           1  Java::OrgJrubyExtOpenssl::OpenSSL.load
      0.68        0.00        0.68           2  Object#require_jar
      0.68        0.00        0.68           2  Jars.require_jar
      0.66        0.00        0.66           2  Jars.require_jar_with_block
      0.66        0.00        0.65           2  Jars.do_require
      0.65        0.00        0.65           2  Jars.home
      0.65        0.00        0.65           2  Jars.local_maven_repo
      0.65        0.00        0.65           1  Jars.maven_local_settings
      0.47        0.08        0.39          97  Array#each
      0.33        0.00        0.33           1  Gem::Specification.load_defaults
      0.33        0.00        0.33           1  Gem::Specification.each_spec
      0.33        0.00        0.33           1  Gem::Specification.each_gemspec
      0.30        0.09        0.21         271  Class#new
      0.20        0.00        0.20          15  Gem::Specification.load
      0.19        0.00        0.18          28  Kernel.gem
      0.17        0.04        0.13          15  Kernel.eval
      0.17        0.00        0.16           3  Gem::Dependency#to_spec
      0.16        0.00        0.16           3  Gem::Dependency#to_specs
      0.16        0.00        0.16           3  Gem::Dependency#matching_specs
      0.15        0.00        0.14          12  Gem.register_default_spec
      0.14        0.00        0.14          27  Kernel.send
      0.10        0.00        0.10           3  Gem::Specification.stubs_for
      0.09        0.01        0.08          14  Gem::Specification#initialize
      0.09        0.08        0.00          24  Java::JavaPackage#method_missing
      0.08        0.08        0.00        1424  String#sub
      0.07        0.04        0.04          82  Array#map
      0.05        0.02        0.03           2  Fixnum#times
      0.05        0.00        0.05          27  Gem.remove_unresolved_default_spec
      0.05        0.00        0.05           1  URI::RFC2396_Parser#initialize
      0.05        0.00        0.05           3  Gem::Specification.dirs
      0.04        0.00        0.04           9  Gem::Specification.gemspec_stubs_in
      0.04        0.00        0.03          79  Gem::Version.new
      0.04        0.00        0.03           1  URI::RFC2396_Parser#initialize_regexp
      0.03        0.03        0.01           4  Hash#each
      0.03        0.03        0.00          29  Regexp#initialize
      0.03        0.00        0.03           2  Object#java_import
      0.03        0.03        0.00           1  Time.now
      0.03        0.00        0.03          41  Gem::Specification#add_dependency_with_type
      0.03        0.00        0.03          95  Gem::Requirement#initialize
      0.03        0.00        0.03          38  Gem::Specification#add_development_dependency
      0.03        0.03        0.00          14  IO.read
      0.03        0.01        0.02          73  Array#map!
      0.03        0.00        0.03           3  Gem::Specification.installed_stubs
      0.03        0.00        0.02          69  Gem::Dependency#initialize
      0.03        0.00        0.03           3  Gem::Specification.map_stubs
      0.03        0.00        0.03           3  Enumerable.flat_map
@HarlemSquirrel

This comment has been minimized.

Show comment
Hide comment
@HarlemSquirrel

HarlemSquirrel Nov 18, 2017

This seems to only occur when installing with RVM. When downloading and running from the included binary file it's working as expected. I'm puzzled as to why this would be the case.

➤  time bin/jruby -e "puts RUBY_ENGINE_VERSION; require 'openssl'; puts OpenSSL::Cipher.new('AES-128-CBC').random_iv"
9.1.14.0
�E��A14�zp�O�ϡ5
bin/jruby -e   2.81s user 0.14s system 155% cpu 1.895 total
➤  rvm install jruby-9.1.14.0 
Searching for binary rubies, this might take some time.
Found remote file /home/k/.rvm/archives/jruby-bin-9.1.14.0.tar.gz
Checking requirements for ubuntu.
Requirements installation successful.
jruby-9.1.14.0 - #configure
jruby-9.1.14.0 - #download
jruby-9.1.14.0 - #validate archive
jruby-9.1.14.0 - #extract
jruby-9.1.14.0 - #validate binary
jruby-9.1.14.0 - #setup
jruby-9.1.14.0 - #gemset created /home/k/.rvm/gems/jruby-9.1.14.0@global
jruby-9.1.14.0 - #importing gemset /home/k/.rvm/gemsets/jruby/global.gems..
jruby-9.1.14.0 - #generating global wrappers.......
jruby-9.1.14.0 - #gemset created /home/k/.rvm/gems/jruby-9.1.14.0
jruby-9.1.14.0 - #importing gemsetfile /home/k/.rvm/gemsets/default.gems evaluated to empty gem list
jruby-9.1.14.0 - #generating default wrappers.......

➤  time ruby -e "puts RUBY_ENGINE_VERSION; require 'openssl'; puts OpenSSL::Cipher.new('AES-128-CBC').random_iv"
9.1.14.0
\������}	�N�����
ruby -e   35.84s user 0.17s system 108% cpu 33.190 total

HarlemSquirrel commented Nov 18, 2017

This seems to only occur when installing with RVM. When downloading and running from the included binary file it's working as expected. I'm puzzled as to why this would be the case.

➤  time bin/jruby -e "puts RUBY_ENGINE_VERSION; require 'openssl'; puts OpenSSL::Cipher.new('AES-128-CBC').random_iv"
9.1.14.0
�E��A14�zp�O�ϡ5
bin/jruby -e   2.81s user 0.14s system 155% cpu 1.895 total
➤  rvm install jruby-9.1.14.0 
Searching for binary rubies, this might take some time.
Found remote file /home/k/.rvm/archives/jruby-bin-9.1.14.0.tar.gz
Checking requirements for ubuntu.
Requirements installation successful.
jruby-9.1.14.0 - #configure
jruby-9.1.14.0 - #download
jruby-9.1.14.0 - #validate archive
jruby-9.1.14.0 - #extract
jruby-9.1.14.0 - #validate binary
jruby-9.1.14.0 - #setup
jruby-9.1.14.0 - #gemset created /home/k/.rvm/gems/jruby-9.1.14.0@global
jruby-9.1.14.0 - #importing gemset /home/k/.rvm/gemsets/jruby/global.gems..
jruby-9.1.14.0 - #generating global wrappers.......
jruby-9.1.14.0 - #gemset created /home/k/.rvm/gems/jruby-9.1.14.0
jruby-9.1.14.0 - #importing gemsetfile /home/k/.rvm/gemsets/default.gems evaluated to empty gem list
jruby-9.1.14.0 - #generating default wrappers.......

➤  time ruby -e "puts RUBY_ENGINE_VERSION; require 'openssl'; puts OpenSSL::Cipher.new('AES-128-CBC').random_iv"
9.1.14.0
\������}	�N�����
ruby -e   35.84s user 0.17s system 108% cpu 33.190 total
@headius

This comment has been minimized.

Show comment
Hide comment
@headius

headius Nov 20, 2017

Member

Run the slow case with the following flag, so we can get some lower-level profiling: --sample

If it's running that long it should be pretty obvious what it's spending its time on.

The main differences I can think of when installing via RVM would be the default gem set and the jruby-launcher gem. The latter is our native executable; to be portable, the tarball does not normally include it. RVM installs it when installing JRuby, since there's some use cases that don't work with the bash script.

But this doesn't give me any idea why there's such a big difference.

Member

headius commented Nov 20, 2017

Run the slow case with the following flag, so we can get some lower-level profiling: --sample

If it's running that long it should be pretty obvious what it's spending its time on.

The main differences I can think of when installing via RVM would be the default gem set and the jruby-launcher gem. The latter is our native executable; to be portable, the tarball does not normally include it. RVM installs it when installing JRuby, since there's some use cases that don't work with the bash script.

But this doesn't give me any idea why there's such a big difference.

@kares

This comment has been minimized.

Show comment
Hide comment
@kares

kares Nov 20, 2017

Member

this seems like (yet another) depleting entropy issue. although you have java.security setup properly
... maybe from within RVM these are getting "lost" or maybe launching another JVM on your machine?
you could verify by connecting with jvisualvm that the time is being spent at Java's SecureRandom
... from there you would need to figure out whether any security related system properties were set ...

Member

kares commented Nov 20, 2017

this seems like (yet another) depleting entropy issue. although you have java.security setup properly
... maybe from within RVM these are getting "lost" or maybe launching another JVM on your machine?
you could verify by connecting with jvisualvm that the time is being spent at Java's SecureRandom
... from there you would need to figure out whether any security related system properties were set ...

@headius

This comment has been minimized.

Show comment
Hide comment
@headius

headius Nov 20, 2017

Member

@kares @HarlemSquirrel I discovered that the securerandom.source property and a couple others have a little quirk: they're hardcoded to force /dev/urandom back to /dev/random.

https://bugs.openjdk.java.net/browse/JDK-6202721

The workaround there is what I'm using for JRuby 9.1.15 in the launchers: specify the path in such a way that the JDK can't detect it, such as /dev/./urandom.

See 1a4f888 and 65a004f.

Member

headius commented Nov 20, 2017

@kares @HarlemSquirrel I discovered that the securerandom.source property and a couple others have a little quirk: they're hardcoded to force /dev/urandom back to /dev/random.

https://bugs.openjdk.java.net/browse/JDK-6202721

The workaround there is what I'm using for JRuby 9.1.15 in the launchers: specify the path in such a way that the JDK can't detect it, such as /dev/./urandom.

See 1a4f888 and 65a004f.

@kares

This comment has been minimized.

Show comment
Hide comment
@kares

kares Nov 20, 2017

Member

@headius EPIC find :) ... this must be it than, or not?

Member

kares commented Nov 20, 2017

@headius EPIC find :) ... this must be it than, or not?

@HarlemSquirrel

This comment has been minimized.

Show comment
Hide comment
@HarlemSquirrel

HarlemSquirrel Nov 20, 2017

I'm getting the following from visualvm

screenshot from 2017-11-20 13-47-47

I set securerandom.source=file:/dev/./urandom but that doesn't seem to help.

Here's the sample output when running

JRUBY_OPTS='--sample' rvm jruby-9.1.14.0 do ruby -e "puts RUBY_ENGINE_VERSION; require 'openssl'; puts OpenSSL::Cipher.new('AES-128-CBC').random_iv"

https://gist.github.com/HarlemSquirrel/112821bdf3fe2b9d6446867329daf4b4

HarlemSquirrel commented Nov 20, 2017

I'm getting the following from visualvm

screenshot from 2017-11-20 13-47-47

I set securerandom.source=file:/dev/./urandom but that doesn't seem to help.

Here's the sample output when running

JRUBY_OPTS='--sample' rvm jruby-9.1.14.0 do ruby -e "puts RUBY_ENGINE_VERSION; require 'openssl'; puts OpenSSL::Cipher.new('AES-128-CBC').random_iv"

https://gist.github.com/HarlemSquirrel/112821bdf3fe2b9d6446867329daf4b4

@headius

This comment has been minimized.

Show comment
Hide comment
@headius

headius Nov 21, 2017

Member

Ah-ha! All those SeedGenerator threads gave me something to search, and this looks very interesting: https://bz.apache.org/bugzilla/show_bug.cgi?id=56139

tldr: if /dev/urandom isn't readable, the random number generator will fall back on a threaded pseudo-random number generator.

This seems like it could be related, but I don't understand why it would work with our tarball and not with an RVM install.

Member

headius commented Nov 21, 2017

Ah-ha! All those SeedGenerator threads gave me something to search, and this looks very interesting: https://bz.apache.org/bugzilla/show_bug.cgi?id=56139

tldr: if /dev/urandom isn't readable, the random number generator will fall back on a threaded pseudo-random number generator.

This seems like it could be related, but I don't understand why it would work with our tarball and not with an RVM install.

@headius

This comment has been minimized.

Show comment
Hide comment
@headius

headius Nov 21, 2017

Member

Here's another interesting article that shows how to test whether entropy is being exhausted, along with other tips: https://liuzy163.wordpress.com/2015/03/20/tomcat-server-slow-due-to-blocked-seedgenerator-thread-on-insufficient-random-number-on-linux/

Member

headius commented Nov 21, 2017

Here's another interesting article that shows how to test whether entropy is being exhausted, along with other tips: https://liuzy163.wordpress.com/2015/03/20/tomcat-server-slow-due-to-blocked-seedgenerator-thread-on-insufficient-random-number-on-linux/

@headius

This comment has been minimized.

Show comment
Hide comment
@headius

headius Nov 21, 2017

Member

I think I know the connection!

You are not running 9.1.15.0, which includes the urandom change in the jruby bash script. However when you install from RVM, it installs jruby-launcher...which does have the urandom change.

So something about the way I'm setting security to use urandom is wrong. I confirmed I'm seeing these threads locally, and my local startup is also slower (I thought I just messed up my env).

I would recommend doing installing the 1.1.2 version of jruby-launcher gem, which should overwrite the one with the urandom tweak. I'll figure out what's wrong with it and spin a new release.

Member

headius commented Nov 21, 2017

I think I know the connection!

You are not running 9.1.15.0, which includes the urandom change in the jruby bash script. However when you install from RVM, it installs jruby-launcher...which does have the urandom change.

So something about the way I'm setting security to use urandom is wrong. I confirmed I'm seeing these threads locally, and my local startup is also slower (I thought I just messed up my env).

I would recommend doing installing the 1.1.2 version of jruby-launcher gem, which should overwrite the one with the urandom tweak. I'll figure out what's wrong with it and spin a new release.

headius added a commit that referenced this issue Nov 21, 2017

Improvement to Java security random source. Fixes #4857.
Apparently the JDK will fail to use the egd path without a file
URL. Stop the madness!

See https://bz.apache.org/bugzilla/show_bug.cgi?id=56139
@headius

This comment has been minimized.

Show comment
Hide comment
@headius

headius Nov 21, 2017

Member

I've fixed this in jruby-launcher 1.1.4. Please confirm it both works and doesn't run out of entropy (i.e. the urandom setting is still working).

Member

headius commented Nov 21, 2017

I've fixed this in jruby-launcher 1.1.4. Please confirm it both works and doesn't run out of entropy (i.e. the urandom setting is still working).

@HarlemSquirrel

This comment has been minimized.

Show comment
Hide comment
@HarlemSquirrel

HarlemSquirrel Nov 21, 2017

@headius you, sir, are the man! That seems to have done it.

➤  gem list jruby-launcher
 
*** LOCAL GEMS ***

jruby-launcher (1.1.3 java)
➤  time ruby -e "puts RUBY_ENGINE_VERSION; require 'openssl'; puts OpenSSL::Cipher.new('AES-128-CBC').random_iv"
9.1.14.0
=��d'q`)�/��_���
ruby -e   35.72s user 0.15s system 108% cpu 33.195 total
➤  gem install jruby-launcher                                                                              
Fetching: jruby-launcher-1.1.4-java.gem (100%)
Building native extensions. This could take a while...
Successfully installed jruby-launcher-1.1.4-java
1 gem installed
➤  time ruby -e "puts RUBY_ENGINE_VERSION; require 'openssl'; puts OpenSSL::Cipher.new('AES-128-CBC').random_iv"
9.1.14.0
�|_�x��G%�����
ruby -e   2.88s user 0.12s system 156% cpu 1.923 total

HarlemSquirrel commented Nov 21, 2017

@headius you, sir, are the man! That seems to have done it.

➤  gem list jruby-launcher
 
*** LOCAL GEMS ***

jruby-launcher (1.1.3 java)
➤  time ruby -e "puts RUBY_ENGINE_VERSION; require 'openssl'; puts OpenSSL::Cipher.new('AES-128-CBC').random_iv"
9.1.14.0
=��d'q`)�/��_���
ruby -e   35.72s user 0.15s system 108% cpu 33.195 total
➤  gem install jruby-launcher                                                                              
Fetching: jruby-launcher-1.1.4-java.gem (100%)
Building native extensions. This could take a while...
Successfully installed jruby-launcher-1.1.4-java
1 gem installed
➤  time ruby -e "puts RUBY_ENGINE_VERSION; require 'openssl'; puts OpenSSL::Cipher.new('AES-128-CBC').random_iv"
9.1.14.0
�|_�x��G%�����
ruby -e   2.88s user 0.12s system 156% cpu 1.923 total
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment