Bug #14716: SecureRandom throwing an error in Ruby 2.5.1

• Status: Open
• Priority: Normal
• Assignee: -
• Target version: -
• ruby -v: 2.5.3
• Backport: 2.3: DONTNEED, 2.4: DONTNEED, 2.5: REQUIRED

[snehavas (sneha vasanth)]

Hi,

We recently upgraded from ruby 2.3.6 to 2.5.1.
We use SecureRandom.uuid to generate a random number for our session.
Post the upgrade we have been getting the following error intermittently

app error: failed to get urandom (RuntimeError)
E, [2018-04-27T04:55:08.741859 #16550] ERROR -- : /usr/lib/ruby/2.5.0/securerandom.rb:99:in `urandom'
E, [2018-04-27T04:55:08.741898 #16550] ERROR -- : /usr/lib/ruby/2.5.0/securerandom.rb:99:in `gen_random_urandom'
E, [2018-04-27T04:55:08.741932 #16550] ERROR -- : /usr/lib/ruby/2.5.0/securerandom.rb:129:in `random_bytes'
E, [2018-04-27T04:55:08.741965 #16550] ERROR -- : /usr/lib/ruby/2.5.0/securerandom.rb:219:in `uuid'
E, [2018-04-27T04:55:08.741997 #16550] ERROR -- : /usr/share/nginx/frontend/app/utilities/log.rb:74:in `create_session_info'
E, [2018-04-27T04:55:08.742036 #16550] ERROR -- : /usr/share/nginx/frontend/app/utilities/log.rb:11:in `context'

We understand that there was a change in ruby 2.5.1 where we now look at OS sources as the first point of contact to generate random numbers as opposed to OpenSSL.
Any idea why this could be happening?

[nobu (Nobuyoshi Nakada)]

• Related to Bug #9569: SecureRandom should try /dev/urandom first added

[nobu (Nobuyoshi Nakada)]

• Status changed from Open to Feedback
• Description updated (diff)

It depends on your OS.
What OS and the kernel version?

[snehavas (sneha vasanth)]

We are using Ubuntu 14.04.5 LTS

[snehavas (sneha vasanth)]

The Kernel version is 3.13.0-145-generic

[naruse (Yui NARUSE)]

• Backport changed from 2.3: UNKNOWN, 2.4: UNKNOWN, 2.5: UNKNOWN to 2.3: DONTNEED, 2.4: DONTNEED, 2.5: REQUIRED
• Status changed from Feedback to Open

r57307 changed to use __NR_getrandom (kernel header) from SYS_getrandom (glibc header).
But __NR_getrandom is from v3.17.
It needs to check both __NR_getrandom and SYS_getrandom for compatibility.

[naruse (Yui NARUSE)]

naruse (Yui NARUSE) wrote:

r57307 changed to use __NR_getrandom (kernel header) from SYS_getrandom (glibc header).
But __NR_getrandom is from v3.17.
It needs to check both __NR_getrandom and SYS_getrandom for compatibility.

genrandom(2) is introduced at v3.17.
On v3.13 kernel, it should fallback to /dev/urandom.
Maybe your environment doesn't have /dev/urandom?

[shyouhei (Shyouhei Urabe)]

I can reproduce the situation using this Dockerfile https://github.com/shyouhei/docker-library/blob/master/%2314716/Dockerfile

The key point is to delete /dev/urandom from the image.

2.3.6 used to try openssl first, so if it had enough entropy that was okay. 2.5.1 prefers /dev/urandom (or getrandom(2), for newer kernels).

[snehavas (sneha vasanth)]

We checked that by executing 'cat /dev/urandom' and we did see an output.
So dont think thats an issue.

We suspect that this issue occurs when there are many concurrent requests.

[patbl (Patrick Brinich-Langlois)]

We also got this error after upgrading to 2.5.1 (we had been on 2.4.2). We're also on a v3.13 kernel (3.13.0-24-generic). cat /dev/urandom produces output, and the errors are intermittent. Over the past day, failed to get urandom was our most common error, but there were several hours when we didn't get any such errors. So it seems possible that it occurs only when there are large numbers of requests, but I didn't try to see whether the request rate was correlated with the error rate.

[patbl (Patrick Brinich-Langlois)]

I worked around this problem by forcing SecureRandom to use the OpenSSL gem:

module SecureRandom
  if RUBY_VERSION == "2.5.1"
    class << self
      def gen_random(n)
        begin
          require 'openssl'
        rescue NoMethodError
          raise NotImplementedError, "No random device"
        else
          @rng_chooser.synchronize do
            class << self
              remove_method :gen_random
              alias gen_random gen_random_openssl
            end
          end
          return gen_random(n)
        end
      end
    end
  else
    raise "check whether this monkey patch is still correct"
  end
end

[bruno (Bruno Sutic)]

• ruby -v changed from 2.5.1 to 2.5.3

Hi,
we're on "Ubuntu 14.04.5 LTS", kernel version "3.13.0-165".

2019-03-03T05:00:00.798Z 12950 TID-ors73fmw2 WARN: RuntimeError: failed to get urandom
2019-03-03T05:00:00.798Z 12950 TID-ors73fmw2 WARN: /usr/lib/ruby/2.5.0/securerandom.rb:99:in `urandom'
/usr/lib/ruby/2.5.0/securerandom.rb:99:in `gen_random_urandom'
/usr/lib/ruby/2.5.0/securerandom.rb:129:in `random_bytes'
/usr/lib/ruby/2.5.0/securerandom.rb:148:in `hex'
/var/lib/gems/2.5.0/gems/activesupport-5.2.0/lib/active_support/notifications/instrumenter.rb:50:in `unique_id'
/var/lib/gems/2.5.0/gems/activesupport-5.2.0/lib/active_support/notifications/instrumenter.rb:12:in `initialize'
/var/lib/gems/2.5.0/gems/activesupport-5.2.0/lib/active_support/notifications.rb:210:in `new'
/var/lib/gems/2.5.0/gems/activesupport-5.2.0/lib/active_support/notifications.rb:210:in `instrumenter_for'
/var/lib/gems/2.5.0/gems/activesupport-5.2.0/lib/active_support/notifications.rb:190:in `instrumenter'
/var/lib/gems/2.5.0/gems/activerecord-5.2.0/lib/active_record/querying.rb:44:in `find_by_sql'
/var/lib/gems/2.5.0/gems/activerecord-5.2.0/lib/active_record/statement_cache.rb:108:in `execute'
/var/lib/gems/2.5.0/gems/activerecord-5.2.0/lib/active_record/core.rb:175:in `find'
/home/deployer/mios/current/app/workers/lock_status_update_worker.rb:17:in `perform'
/var/lib/gems/2.5.0/gems/sidekiq-5.2.3/lib/sidekiq/processor.rb:185:in `execute_job'
/var/lib/gems/2.5.0/gems/sidekiq-5.2.3/lib/sidekiq/processor.rb:167:in `block (2 levels) in process'
/var/lib/gems/2.5.0/gems/sidekiq-5.2.3/lib/sidekiq/middleware/chain.rb:128:in `block in invoke'
/var/lib/gems/2.5.0/gems/sentry-raven-2.7.4/lib/raven/integrations/sidekiq.rb:9:in `call'
/var/lib/gems/2.5.0/gems/sidekiq-5.2.3/lib/sidekiq/middleware/chain.rb:130:in `block in invoke'
/var/lib/gems/2.5.0/gems/sidekiq-pro-4.0.4/lib/sidekiq/batch/middleware.rb:29:in `call'
/var/lib/gems/2.5.0/gems/sidekiq-5.2.3/lib/sidekiq/middleware/chain.rb:130:in `block in invoke'
/var/lib/gems/2.5.0/gems/sidekiq-ent-1.7.2/lib/sidekiq-ent/unique.rb:143:in `call'
/var/lib/gems/2.5.0/gems/sidekiq-5.2.3/lib/sidekiq/middleware/chain.rb:130:in `block in invoke'
/var/lib/gems/2.5.0/gems/sidekiq-ent-1.7.2/lib/sidekiq-ent/limiter/middleware.rb:40:in `call'
/var/lib/gems/2.5.0/gems/sidekiq-5.2.3/lib/sidekiq/middleware/chain.rb:130:in `block in invoke'
/var/lib/gems/2.5.0/gems/sidekiq-5.2.3/lib/sidekiq/middleware/chain.rb:133:in `invoke'
/var/lib/gems/2.5.0/gems/sidekiq-5.2.3/lib/sidekiq/processor.rb:166:in `block in process'
/var/lib/gems/2.5.0/gems/sidekiq-5.2.3/lib/sidekiq/processor.rb:137:in `block (6 levels) in dispatch'
/var/lib/gems/2.5.0/gems/sidekiq-5.2.3/lib/sidekiq/job_retry.rb:108:in `local'
/var/lib/gems/2.5.0/gems/sidekiq-5.2.3/lib/sidekiq/processor.rb:136:in `block (5 levels) in dispatch'
/var/lib/gems/2.5.0/gems/sidekiq-5.2.3/lib/sidekiq/rails.rb:42:in `block in call'
/var/lib/gems/2.5.0/gems/activesupport-5.2.0/lib/active_support/execution_wrapper.rb:87:in `wrap'
/var/lib/gems/2.5.0/gems/activesupport-5.2.0/lib/active_support/reloader.rb:73:in `block in wrap'
/var/lib/gems/2.5.0/gems/activesupport-5.2.0/lib/active_support/execution_wrapper.rb:87:in `wrap'
/var/lib/gems/2.5.0/gems/activesupport-5.2.0/lib/active_support/reloader.rb:72:in `wrap'
/var/lib/gems/2.5.0/gems/sidekiq-5.2.3/lib/sidekiq/rails.rb:41:in `call'
/var/lib/gems/2.5.0/gems/sidekiq-5.2.3/lib/sidekiq/processor.rb:132:in `block (4 levels) in dispatch'
/var/lib/gems/2.5.0/gems/sidekiq-5.2.3/lib/sidekiq/processor.rb:243:in `stats'
/var/lib/gems/2.5.0/gems/sidekiq-5.2.3/lib/sidekiq/processor.rb:127:in `block (3 levels) in dispatch'
/var/lib/gems/2.5.0/gems/sidekiq-5.2.3/lib/sidekiq/job_logger.rb:8:in `call'
/var/lib/gems/2.5.0/gems/sidekiq-5.2.3/lib/sidekiq/processor.rb:126:in `block (2 levels) in dispatch'
/var/lib/gems/2.5.0/gems/sidekiq-5.2.3/lib/sidekiq/job_retry.rb:73:in `global'
/var/lib/gems/2.5.0/gems/sidekiq-5.2.3/lib/sidekiq/processor.rb:125:in `block in dispatch'
/var/lib/gems/2.5.0/gems/sidekiq-5.2.3/lib/sidekiq/logging.rb:48:in `with_context'
/var/lib/gems/2.5.0/gems/sidekiq-5.2.3/lib/sidekiq/logging.rb:42:in `with_job_hash_context'
/var/lib/gems/2.5.0/gems/sidekiq-5.2.3/lib/sidekiq/processor.rb:124:in `dispatch'
/var/lib/gems/2.5.0/gems/sidekiq-5.2.3/lib/sidekiq/processor.rb:165:in `process'
/var/lib/gems/2.5.0/gems/sidekiq-5.2.3/lib/sidekiq/processor.rb:83:in `process_one'
/var/lib/gems/2.5.0/gems/sidekiq-5.2.3/lib/sidekiq/processor.rb:71:in `run'

We're using Ruby 2.5.3 and we can see this issue happening intermittently for one of our applications.

• It doesn't happen for weeks, and then it suddenly starts happening.
• The process that this happens in is "sidekiq", it runs background jobs.
• Interestingly, our server runs our 4 other apps (ruby processes), and these apps don't get this error.
• Restarting a process seems to fix the issue from happening.