nil.unpack issue

[gauravbhatti]

I got this error The error occurred while evaluating nil.unpack I am using uuid-2.0.2 with rails2.3.4

[rumblinthebronx]

I got a similar issue while using UUID::generate on jruby-1.7.0-preview2 #<NoMethodError: undefined method unpack' for nil:NilClass> /home/developer/.rvm/gems/jruby-1.7.0.preview2/gems/uuid-2.3.6/lib/uuid.rb:376:inread_state' /home/developer/.rvm/gems/jruby-1.7.0.preview2/gems/uuid-2.3.6/lib/uuid.rb:332:in next_sequence' /home/developer/.rvm/gems/jruby-1.7.0.preview2/gems/uuid-2.3.6/lib/uuid.rb:366:inopen_lock' org/jruby/RubyIO.java:1180:in open' /home/developer/.rvm/gems/jruby-1.7.0.preview2/gems/uuid-2.3.6/lib/uuid.rb:363:inopen_lock' /home/developer/.rvm/gems/jruby-1.7.0.preview2/gems/uuid-2.3.6/lib/uuid.rb:331:in next_sequence' /home/developer/.rvm/gems/jruby-1.7.0.preview2/gems/uuid-2.3.6/lib/uuid.rb:313:ingenerate' org/jruby/ext/thread/Mutex.java:149:in synchronize' /home/developer/.rvm/gems/jruby-1.7.0.preview2/gems/uuid-2.3.6/lib/uuid.rb:297:ingenerate' /home/developer/.rvm/gems/jruby-1.7.0.preview2/gems/uuid-2.3.6/lib/uuid.rb:127:in `generate'

[langhorst]

I was unable to replicate this using jruby-1.7.2 (1.9.3p327), uuid-2.3.6, rails-3.2.11.

> rvm install jruby
> rvm use jruby
> rvm gemset create uuid
> rvm gemset use uuid
> git clone https://github.com/assaf/uuid.git
> cd uuid
> bundle install
> rake install
> rake test
> irb

Within irb:

> require 'uuid'
> UUID::generate
> require 'rails'
> UUID::generate
> 1000.times { puts UUID::generate }

No issues. I even tried requiring most of the gems available from gem list - no luck in replicating the issue. I wonder if this has something to do with the state file and your environment? Maybe try UUID::state_file = false to rule that out.

[udl]

I'm seeing the same issue with ruby ruby 1.9.3p385 when calling UUID.new.generate with gem version 2.3.6.

stacktrace:

.../shared/bundle/ruby/1.9.1/gems/uuid-2.3.6/lib/uuid.rb:376:in `read_state'
.../shared/bundle/ruby/1.9.1/gems/uuid-2.3.6/lib/uuid.rb:332:in `block in next_sequence'
.../shared/bundle/ruby/1.9.1/gems/uuid-2.3.6/lib/uuid.rb:366:in `block in open_lock'
.../shared/bundle/ruby/1.9.1/gems/uuid-2.3.6/lib/uuid.rb:363:in `open'
.../shared/bundle/ruby/1.9.1/gems/uuid-2.3.6/lib/uuid.rb:363:in `open_lock'
.../shared/bundle/ruby/1.9.1/gems/uuid-2.3.6/lib/uuid.rb:331:in `next_sequence'
.../shared/bundle/ruby/1.9.1/gems/uuid-2.3.6/lib/uuid.rb:262:in `initialize'

(replaced parts of the path by ...)

[zephyr-dev]

We are seeing this issue as well. We are using ruby 2.0.0-p0, rails 3.2.13. We encounter the error about once a day.

error: undefined method `unpack' for nil:NilClass stack trace:

"/home/user/.rvm/gems/ruby-2.0.0-p0/gems/uuid-2.3.7/lib/uuid.rb:377:in `read_state'"
"/home/user/.rvm/gems/ruby-2.0.0-p0/gems/uuid-2.3.7/lib/uuid.rb:333:in `block in next_sequence'"
"/home/user/.rvm/gems/ruby-2.0.0-p0/gems/uuid-2.3.7/lib/uuid.rb:367:in `block in open_lock'"
"/home/user/.rvm/gems/ruby-2.0.0-p0/gems/uuid-2.3.7/lib/uuid.rb:364:in `open'"
"/home/user/.rvm/gems/ruby-2.0.0-p0/gems/uuid-2.3.7/lib/uuid.rb:364:in `open_lock'"
"/home/user/.rvm/gems/ruby-2.0.0-p0/gems/uuid-2.3.7/lib/uuid.rb:332:in `next_sequence'"
"/home/user/.rvm/gems/ruby-2.0.0-p0/gems/uuid-2.3.7/lib/uuid.rb:263:in `initialize'"
"/home/user/.rvm/gems/ruby-2.0.0-p0/gems/uuid-2.3.7/lib/uuid.rb:127:in `new'"
"/home/user/.rvm/gems/ruby-2.0.0-p0/gems/uuid-2.3.7/lib/uuid.rb:127:in `generate'"

Note that we have about 50 separate processes hitting this code at once.

[oleander]

Same thing here.

[GEM_ROOT]/gems/uuid-2.3.7/lib/uuid.rb:377:in `read_state'
[GEM_ROOT]/gems/uuid-2.3.7/lib/uuid.rb:333:in `block in next_sequence'
[GEM_ROOT]/gems/uuid-2.3.7/lib/uuid.rb:367:in `block in open_lock'
[GEM_ROOT]/gems/uuid-2.3.7/lib/uuid.rb:364:in `open'
[GEM_ROOT]/gems/uuid-2.3.7/lib/uuid.rb:364:in `open_lock'
[GEM_ROOT]/gems/uuid-2.3.7/lib/uuid.rb:332:in `next_sequence'
[GEM_ROOT]/gems/uuid-2.3.7/lib/uuid.rb:263:in `initialize'
app/models/user.rb:26:in `new'
app/models/user.rb:26:in `block in <class
[GEM_ROOT]/gems/activesupport-4.0.0/lib/active_support/callbacks.rb:375:in `_run__2699327338686436562__initialize__callbacks'
[GEM_ROOT]/gems/activesupport-4.0.0/lib/active_support/callbacks.rb:80:in `run_callbacks'
[GEM_ROOT]/gems/protected_attributes-1.0.3/lib/active_record/mass_assignment_security/core.rb:19:in `initialize'
[GEM_ROOT]/gems/activerecord-4.0.0/lib/active_record/inheritance.rb:27:in `new'
[GEM_ROOT]/gems/activerecord-4.0.0/lib/active_record/inheritance.rb:27:in `new'
[GEM_ROOT]/gems/protected_attributes-1.0.3/lib/active_record/mass_assignment_security/persistence.rb:45:in `create'
[GEM_ROOT]/gems/activerecord-4.0.0/lib/active_record/relation.rb:121:in `block in create'
[GEM_ROOT]/gems/activerecord-4.0.0/lib/active_record/relation.rb:270:in `scoping'
[GEM_ROOT]/gems/activerecord-4.0.0/lib/active_record/relation.rb:121:in `create'
[GEM_ROOT]/gems/activerecord-4.0.0/lib/active_record/relation.rb:133:in `first_or_create'
app/controllers/application_controller.rb:217:in `block in current_user'
app/controllers/application_controller.rb:222:in `call'
app/controllers/application_controller.rb:222:in `current_user'
[GEM_ROOT]/bundler/gems/paper_trail-98848bb9b2db/lib/paper_trail/frameworks/rails.rb:20:in `user_for_paper_trail'
[GEM_ROOT]/bundler/gems/paper_trail-98848bb9b2db/lib/paper_trail/frameworks/rails.rb:62:in `set_paper_trail_whodunnit'
[GEM_ROOT]/gems/activesupport-4.0.0/lib/active_support/callbacks.rb:397:in `_run__1953005326139304363__process_action__callbacks'
[GEM_ROOT]/gems/activesupport-4.0.0/lib/active_support/callbacks.rb:80:in `run_callbacks'
[GEM_ROOT]/gems/actionpack-4.0.0/lib/abstract_controller/callbacks.rb:17:in `process_action'
[GEM_ROOT]/gems/actionpack-4.0.0/lib/action_controller/metal/rescue.rb:29:in `process_action'
[GEM_ROOT]/gems/actionpack-4.0.0/lib/action_controller/metal/instrumentation.rb:31:in `block in process_action'
[GEM_ROOT]/gems/activesupport-4.0.0/lib/active_support/notifications.rb:159:in `block in instrument'
[GEM_ROOT]/gems/activesupport-4.0.0/lib/active_support/notifications/instrumenter.rb:20:in `instrument'
[GEM_ROOT]/gems/activesupport-4.0.0/lib/active_support/notifications.rb:159:in `instrument'
[GEM_ROOT]/gems/actionpack-4.0.0/lib/action_controller/metal/instrumentation.rb:30:in `process_action'
[GEM_ROOT]/gems/actionpack-4.0.0/lib/action_controller/metal/params_wrapper.rb:245:in `process_action'
[GEM_ROOT]/gems/activerecord-4.0.0/lib/active_record/railties/controller_runtime.rb:18:in `process_action'
[GEM_ROOT]/gems/actionpack-4.0.0/lib/abstract_controller/base.rb:136:in `process'
[GEM_ROOT]/gems/actionpack-4.0.0/lib/abstract_controller/rendering.rb:44:in `process'
[GEM_ROOT]/gems/actionpack-4.0.0/lib/action_controller/metal.rb:195:in `dispatch'
[GEM_ROOT]/gems/actionpack-4.0.0/lib/action_controller/metal/rack_delegation.rb:13:in `dispatch'
[GEM_ROOT]/gems/actionpack-4.0.0/lib/action_controller/metal.rb:231:in `block in action'
[GEM_ROOT]/gems/actionpack-4.0.0/lib/action_dispatch/routing/route_set.rb:80:in `call'
[GEM_ROOT]/gems/actionpack-4.0.0/lib/action_dispatch/routing/route_set.rb:80:in `dispatch'
[GEM_ROOT]/gems/actionpack-4.0.0/lib/action_dispatch/routing/route_set.rb:48:in `call'
[GEM_ROOT]/gems/actionpack-4.0.0/lib/action_dispatch/journey/router.rb:71:in `block in call'
[GEM_ROOT]/gems/actionpack-4.0.0/lib/action_dispatch/journey/router.rb:59:in `each'
[GEM_ROOT]/gems/actionpack-4.0.0/lib/action_dispatch/journey/router.rb:59:in `call'
[GEM_ROOT]/gems/actionpack-4.0.0/lib/action_dispatch/routing/route_set.rb:655:in `call'
[GEM_ROOT]/gems/omniauth-1.0.3/lib/omniauth/strategy.rb:168:in `call!'
[GEM_ROOT]/gems/omniauth-1.0.3/lib/omniauth/strategy.rb:148:in `call'
[GEM_ROOT]/gems/omniauth-1.0.3/lib/omniauth/strategy.rb:168:in `call!'
[GEM_ROOT]/gems/omniauth-1.0.3/lib/omniauth/strategy.rb:148:in `call'
[GEM_ROOT]/gems/omniauth-1.0.3/lib/omniauth/builder.rb:42:in `call'
[GEM_ROOT]/gems/request_store-1.0.5/lib/request_store/middleware.rb:9:in `call'
[GEM_ROOT]/gems/warden-1.2.3/lib/warden/manager.rb:35:in `block in call'
[GEM_ROOT]/gems/warden-1.2.3/lib/warden/manager.rb:34:in `catch'
[GEM_ROOT]/gems/warden-1.2.3/lib/warden/manager.rb:34:in `call'
[GEM_ROOT]/gems/rack-1.5.2/lib/rack/etag.rb:23:in `call'
[GEM_ROOT]/gems/rack-1.5.2/lib/rack/conditionalget.rb:25:in `call'
[GEM_ROOT]/gems/rack-1.5.2/lib/rack/head.rb:11:in `call'
[GEM_ROOT]/gems/actionpack-4.0.0/lib/action_dispatch/middleware/params_parser.rb:27:in `call'
[GEM_ROOT]/gems/actionpack-4.0.0/lib/action_dispatch/middleware/flash.rb:241:in `call'
[GEM_ROOT]/gems/rack-1.5.2/lib/rack/session/abstract/id.rb:225:in `context'
[GEM_ROOT]/gems/rack-1.5.2/lib/rack/session/abstract/id.rb:220:in `call'
[GEM_ROOT]/gems/actionpack-4.0.0/lib/action_dispatch/middleware/cookies.rb:486:in `call'
[GEM_ROOT]/gems/activerecord-4.0.0/lib/active_record/query_cache.rb:36:in `call'
[GEM_ROOT]/gems/activerecord-4.0.0/lib/active_record/connection_adapters/abstract/connection_pool.rb:626:in `call'
[GEM_ROOT]/gems/actionpack-4.0.0/lib/action_dispatch/middleware/callbacks.rb:29:in `block in call'
[GEM_ROOT]/gems/activesupport-4.0.0/lib/active_support/callbacks.rb:373:in `_run__2828308976458894793__call__callbacks'
[GEM_ROOT]/gems/activesupport-4.0.0/lib/active_support/callbacks.rb:80:in `run_callbacks'
[GEM_ROOT]/gems/actionpack-4.0.0/lib/action_dispatch/middleware/callbacks.rb:27:in `call'
[GEM_ROOT]/gems/actionpack-4.0.0/lib/action_dispatch/middleware/remote_ip.rb:76:in `call'
[GEM_ROOT]/gems/actionpack-4.0.0/lib/action_dispatch/middleware/debug_exceptions.rb:17:in `call'
[GEM_ROOT]/gems/actionpack-4.0.0/lib/action_dispatch/middleware/show_exceptions.rb:30:in `call'
[GEM_ROOT]/gems/railties-4.0.0/lib/rails/rack/logger.rb:38:in `call_app'
[GEM_ROOT]/gems/railties-4.0.0/lib/rails/rack/logger.rb:21:in `block in call'
[GEM_ROOT]/gems/activesupport-4.0.0/lib/active_support/tagged_logging.rb:67:in `block in tagged'
[GEM_ROOT]/gems/activesupport-4.0.0/lib/active_support/tagged_logging.rb:25:in `tagged'
[GEM_ROOT]/gems/activesupport-4.0.0/lib/active_support/tagged_logging.rb:67:in `tagged'
[GEM_ROOT]/gems/railties-4.0.0/lib/rails/rack/logger.rb:21:in `call'
[GEM_ROOT]/gems/actionpack-4.0.0/lib/action_dispatch/middleware/request_id.rb:21:in `call'
[GEM_ROOT]/gems/rack-1.5.2/lib/rack/methodoverride.rb:21:in `call'
[GEM_ROOT]/gems/rack-1.5.2/lib/rack/runtime.rb:17:in `call'
[GEM_ROOT]/gems/rack-1.5.2/lib/rack/sendfile.rb:112:in `call'
[GEM_ROOT]/gems/railties-4.0.0/lib/rails/engine.rb:511:in `call'
[GEM_ROOT]/gems/railties-4.0.0/lib/rails/application.rb:97:in `call'
[GEM_ROOT]/gems/railties-4.0.0/lib/rails/railtie/configurable.rb:30:in `method_missing'
[GEM_ROOT]/gems/unicorn-4.6.3/lib/unicorn/http_server.rb:552:in `process_client'
[GEM_ROOT]/gems/unicorn-4.6.3/lib/unicorn/http_server.rb:632:in `worker_loop'
[GEM_ROOT]/gems/unicorn-4.6.3/lib/unicorn/http_server.rb:500:in `spawn_missing_workers'
[GEM_ROOT]/gems/unicorn-4.6.3/lib/unicorn/http_server.rb:511:in `maintain_worker_count'
[GEM_ROOT]/gems/unicorn-4.6.3/lib/unicorn/http_server.rb:277:in `join'
[GEM_ROOT]/gems/unicorn-4.6.3/bin/unicorn:126:in `<top (required)>'
[GEM_ROOT]/bin/unicorn:23:in `load'
[GEM_ROOT]/bin/unicorn:23:in `<main>'

I'm using Ruby 2.0.0

All other software versions can be seen above.

[Altonymous]

Any progress on this issue?

[mikelewis]

+1

[gtmax]

You can set state_file to false, but this might leave you with duplicated ids generated on the same machine, right?

Any drawbacks to simply retrying?

class UUID
  # Workaround for UUID gem failing sometimes on lock file access in a multiprocess environment
  # Which throws NoMethodError: undefined method `unpack' for nil:NilClass
  def generate_with_retry(*args)
    retries = 0
    begin
       generate_without_retry(*args)
    rescue StandardError => error
       retries += 1
       retry if retries < 3
       raise error, "[After trying #{retries} times] #{error.message}", error.backtrace
    end
  end
  alias_method_chain :generate, :retry # rails only, roll your own alias_method calls if outside rails
end

[slemiere]

I'm seeing this as well, @gtmax have you tried your code in a production environment ?

[gtmax]

@slemiere Yes, we are running with this code. However, from what I recall for some reason this still didn't solve the high-frequency concurrent multi-process UUID generation - and we realized that actually we didn't need a completely unique id there and switched to a cheaper SecureRandom.

[kazjote]

I can easily reproduce this problem on linux machine with:

require 'uuid'

20.times do
  fork { UUID.new while true }
end

Process.waitall

[oleander]

@kazjote I can confirm that's the case on OS X 10.10 as well.

[silasb]

Just hit this on production as well.

[Altonymous]

We switched to SecureRandom as well.

[larryzhao]

I also have it with ruby-2.3.0 on Ubuntu 12.04/14.04. I rarely occurs but I am having it like 10 times a day.

/gems/uuid-2.3.8/lib/uuid.rb:377 in read_state
/gems/uuid-2.3.8/lib/uuid.rb:333 in block in next_sequence
/gems/uuid-2.3.8/lib/uuid.rb:367 in block in open_lock
/gems/uuid-2.3.8/lib/uuid.rb:364 in open
/gems/uuid-2.3.8/lib/uuid.rb:364 in open_lock
/gems/uuid-2.3.8/lib/uuid.rb:332 in next_sequence
/gems/uuid-2.3.8/lib/uuid.rb:263 in initialize

[vineethvakeel]

We are seeing this issue when using uuid:2.3.9 with ruby 2.3.6 in our production environment. Has happened twice in the last 30 days.

Is the solution to use SecureRandom.uuid as shown in the commit above?

[silasb]

@vineethvakeel we moved to SecureRandom.uuid a long time ago and that fixed many of our issues that we saw with this library.