Infrequent and weird #<RuntimeError: NOAUTH Authentication required> in heroku/rediscloud environment

[chriso0710]

Hi guys,

ohm has been working great (still using version 2.3) in my Sinatra app for years.

But I'm seeing some weird periodic error in a heroku environment. I already opened a ticket with heroku, but they have no idea at the moment, other than switching to a different redis client.

My app uses the Redis Cloud heroku addon. The app does a redis fetch for every request it gets. Redis Cloud has also been working great for months. I have the REDIS config var set for heroku. The app reads it via ENV to get the redis config url. There is only a single place in the code where the redis config gets set:

Ohm.redis = Redic.new(ENV['REDIS'])

But I'm seeing daily errors from my app. The error occurs only after, before or during the heroku daily dyno restart. So only once per day!

NoMethodError: undefined method `each' for #<RuntimeError: NOAUTH Authentication required>
File "/app/vendor/bundle/ruby/2.3.0/gems/ohm-2.3.0/lib/ohm.rb" line 144 in block in fetch
File "/app/vendor/bundle/ruby/2.3.0/gems/ohm-2.3.0/lib/ohm.rb" line 699 in synchronize
File "/app/vendor/bundle/ruby/2.3.0/gems/ohm-2.3.0/lib/ohm.rb" line 699 in synchronize
File "/app/vendor/bundle/ruby/2.3.0/gems/ohm-2.3.0/lib/ohm.rb" line 143 in fetch
File "/app/vendor/bundle/ruby/2.3.0/gems/ohm-2.3.0/lib/ohm.rb" line 457 in sort
File "/app/vendor/bundle/ruby/2.3.0/gems/ohm-2.3.0/lib/ohm.rb" line 498 in first

I would appreciate any ideas or hints for debugging or resolving this issue. Thanks.

Christian

[soveran]

I know what's happening from the point of view of the server, and I think the client should retry. I'll check this and get back to you.

[soveran]

Is there a chance for you to try with the latest version?

[chriso0710]

Yeah, I know. I still have the update on my todo list, see #223. But ohm has been running smoothly most of the time, so I was delaying the update. Looks like I need to tackle this quite soon. Though it still might take some days until I find the time.

Do you have any ideas to mitigate the error for 2.3 in the meantime?

[soveran]

Can you tell me which version of Redic you have installed?

[chriso0710]

redic 1.5.0

[soveran]

What is stopping you from upgrading?

[chriso0710]

:-) No time, too much stuff going on. But will do it for our stage environment.

[soveran]

I had troubles yesterday installing msgpack, needed for Ohm 2.3.0. And I was thinking about just that: upgrading Ohm in staging to see how it goes. I wasn't able to reproduce it with the latest version, so that would be one idea. I can as try again with msgpack later if your experiment fails.

[chriso0710]

Thank you @soveran, I will keep you posted.

[chriso0710]

I did the gem update (ohm 3.1.1, redic 1.5.1) and a lot of my tests started to fail immediately.

The reason seems to be the following. I have this model:

class User < Ohm::Model

    attribute :uid
    attribute :name
    attribute :brand
    ...

    index :uid
    index :provider
    index :brand
...
end

In ohm 2.3 this worked

User.find(uid: "409590").first

and returned a valid user object.

In ohm 3.1 the same command fails

User.find(uid: "409590").first

and returns nil, which breaks my tests.

I have to do a

User.find(uid: "409590").to_a.first
#<User:0x007fb6ab933c30 @attributes={:uid=>"409590", :name=>"Christian Ott", ...>

to get a user object. Is this expected behaviour or am I missing something here?

[chriso0710]

Similar problem with ohm3:

My app uses

User.all.size
0

But correct size gets returned only with

User.all.to_a.size
3

[soveran]

Regarding User.find(uid: "409590").first, it may have to do with how nil values are handled when indexing and the changes between the two versions you are testing. You may need to iterate over all objects and save them so that the indices get updated.

[soveran]

(If that's not the case, let me know. I'm offline a lot these days and until February 6th, but I'm following up on this issue every morning.)

[chriso0710]

I do not have nil values for the field uid in my data. Nevertheless I saved all objects to rebuild the index. But the problem remains: The first method on the find always returns nil.

[soveran]

OK, I may need to see the definition of your model. If you want to keep it private, contact me by email.

[chriso0710]

Full ohm definition, without any methods:

class User < Ohm::Model

    attribute :uid
    attribute :name
    attribute :provider
    attribute :email
    attribute :image_url
    attribute :url
    attribute :lastlogin
    attribute :registered
    attribute :admin
    attribute :brand
    attribute :address
    attribute :locked
    attribute :locale
    attribute :stripeid
    attribute :stripecountrycode

    index :uid
    index :provider
    index :brand

    collection :projects, :Project
    reference :plan, :Plan

end

[soveran]

Cool. I created some instances and the result is what I expected. Can you create some instances that will allow me to reproduce the error?

[chriso0710]

This is what I get in irb:

> u = User.new(uid: "4711", provider: "github", name: "Chris", brand: "sosdev")
#<User:0x007fa1acd21310 @attributes={:uid=>"4711", :provider=>"github", :name=>"Chris", :brand=>"sosdev", :locale=>"en"}, @_memo={}>
> u.save
#<User:0x007fa1acd21310 @attributes={:uid=>"4711", :provider=>"github", :name=>"Chris", :brand=>"sosdev", :locale=>"en"}, @_memo={}, @id="43">
> u.inspect
"#<User:0x007fa1acd21310 @attributes={:uid=>\"4711\", :provider=>\"github\", :name=>\"Chris\", :brand=>\"sosdev\", :locale=>\"en\"}, @_memo={}, @id=\"43\">"
> User.all.size
0
> User.find(uid: "4711").first
nil
> User.find(uid: "4711").to_a.first
#<User:0x007fa1acf42180 @attributes={:uid=>"4711", :name=>"Chris", :provider=>"github", :brand=>"sosdev", :locale=>"en"}, @_memo={}, @id="43">

[soveran]

If I do exactly that, I get the right results. If you try that after running FLUSHDB, does it work?

[chriso0710]

No, sorry, now it gets weird. I have the same problems with a totally empty DB. I'm using redis 2.8 locally on a Mac. Have not changed anything on the server.

127.0.0.1:6379> flushdb
OK
127.0.0.1:6379> keys *
(empty list or set)

 > u = User.new(uid: "4711", provider: "github", name: "Chris", brand: "sosdev")
#<User:0x007ff284283bf0 @attributes={:uid=>"4711", :provider=>"github", :name=>"Chris", :brand=>"sosdev", :locale=>"en"}, @_memo={}>
> u.save
#<User:0x007ff284283bf0 @attributes={:uid=>"4711", :provider=>"github", :name=>"Chris", :brand=>"sosdev", :locale=>"en"}, @_memo={}, @id="1">
> User.all.size
0
> User.find(uid: "4711").first
nil
> User.all.to_a.size
1

# Server
redis_version:2.8.24
redis_git_sha1:00000000
redis_git_dirty:0
redis_build_id:2828360fe221885d
redis_mode:standalone
os:Darwin 17.3.0 x86_64
arch_bits:64
multiplexing_api:kqueue
gcc_version:4.2.1
process_id:57152
run_id:f6fed8973a89d3f1d24ac2564f24e60a60af6659
tcp_port:6379
uptime_in_seconds:4843
uptime_in_days:0
hz:10
lru_clock:5426057
config_file:/Users/co/.redis/redis.conf

Thanks for your help BTW!

[soveran]

I've just tried with that same version (2.8.24) and got the right results. Try to run this file:

require "ohm"

Ohm.redis.call("FLUSHDB")
Ohm.redis.call("SCRIPT", "FLUSH")

class Plan < Ohm::Model
  attribute :name
end

class User < Ohm::Model
  attribute :uid
  attribute :name
  attribute :provider
  attribute :email
  attribute :image_url
  attribute :url
  attribute :lastlogin
  attribute :registered
  attribute :admin
  attribute :brand
  attribute :address
  attribute :locked
  attribute :locale
  attribute :stripeid
  attribute :stripecountrycode

  index :uid
  index :provider
  index :brand

  collection :projects, :Project
  reference :plan, :Plan
end

p User.create(uid: "4711", provider: "github", name: "Chris", brand: "sosdev")
p User.all.size
p User.find(uid: "4711").first
p User.find(uid: "4711").to_a.first

[chriso0710]

Yep, this works!

#<User:0x007fb077b3f040 @attributes={:uid=>"4711", :provider=>"github", :name=>"Chris", :brand=>"sosdev"}, @_memo={}, @id="1">
1
#<User:0x007fb077b3cac0 @attributes={:uid=>"4711", :name=>"Chris", :provider=>"github", :brand=>"sosdev"}, @_memo={}, @id="1">
#<User:0x007fb077007c68 @attributes={:uid=>"4711", :name=>"Chris", :provider=>"github", :brand=>"sosdev"}, @_memo={}, @id="1">

Only difference seems the

Ohm.redis.call("SCRIPT", "FLUSH")

[chriso0710]

But back in my irb console the problem returns. Maybe it has something to do with json gems or model methods?

> User.all.to_a
[
    [0] #<User:0x007ff93b2f0ff8 @attributes={:uid=>"4711", :name=>"Chris", :provider=>"github", :brand=>"sosdev", :locale=>"en"}, @_memo={}, @id="1">
]
> User.find(uid: "4711").first
nil

This is my initialize method in the User class. Looks harmless to me:

    def initialize(data)
        super(data)
        @attributes[:locale] = "en" if !attributes[:locale]
    end

[soveran]

Can you try flushing the DB and the scripts when you enter IRB?

>> Ohm.redis.call("FLUSHDB")
>> Ohm.redis.call("SCRIPT", "FLUSH")

[chriso0710]

We are getting closer. I think I found the reason for the error. I am requiring

require 'active_support/all'

because I am using methods from active_support, although I am not using rails for this project. I think this must have something to do with JSON processing in active_support.

[soveran]

Ah, that could be the culprit. Let me know if it works fine without requiring active_support/all.

[chriso0710]

Yes, without active_support/all it all works! Thank you very much for your help so far. Unfortunately I need active_support. Do you have an idea how to prevent active_support interfering with JSON operations?

[soveran]

I guess it is overriding to_json, but we can track down the problem. Which version of activesupport are you using?

[soveran]

I remembered something similar that was fixed a while ago: https://github.com/soveran/nest/issues/7

[chriso0710]

Still using an old version: activesupport (3.2.22.5) 20+ comments later the original problem seems to turn into some kind of dependency hell... That's exactly the reason I was hesitant with updating ;-)

[chriso0710]

When doing this after requiring active_support it works again: https://stackoverflow.com/a/12324793/2520015

This might be a somewhat reasonable solution for me...

[soveran]

Try this, first locate Nest:

$ gem which nest

Then modify it and add this method:

def to_json(*args)
  @ns.to_json(*args)
end

Retry after that and let me know if it works.

[chriso0710]

Yes, patching nest works together with requiring active_supprt/all !

[soveran]

Great, I will check if that change doesn't interfere with anything else.

[chriso0710]

Thanks again @soveran for your help! That was fantastic.

I'm going to run my tests again and then push to the staging environment at heroku to see if this solves the original NOAUTH error.

[soveran]

I just pushed a new version of Nest with that change. I'm pesimistic about this change solving the NOAUTH error, but in any case it feels like we are making progress :-)

[chriso0710]

All tests are successful. I pushed the update to our stage env yesterday evening. NOAUTH error has not been seen yet.

[soveran]

Excellent! Keep me posted :-)

[soveran]

@chriso0710 Have you run into any issues yet? I suddendly remembered and was wondering about what happened.

[chriso0710]

Thank you for asking. No issues so far. Currently the ohm update is installed only in the stage environment. Not in production, which gets a lot more requests. Will probably take some weeks of testing before we move the update into production, though...

Do you have any idea what exactly could have caused the NOAUTH error in the 2.3 release?

[soveran]

I think we can close this for now. My guess is that the NOAUTH error was related to what we fixed. Feel free to reopen this issue if the problem returns. Thanks a lot for helping me out with this!

[chriso0710]

Yeah, ok. Thanks for your help!