Logging?

[findchris]

Hi there.

I'm switching to readthis from redis_store, and am seeing unexpected cache keys being written. In trying to debug this, I was looking for logging of some sort: Observing which keys and values are being written or read per operation. Am I overlooking existing functionality, or might this be something you'd support?

Cheers.

[findchris]

Note that I'm sure that the issue is in my code, but having logs would help with debugging my issue.

[sorentwo]

You can make use of ActiveSupport::Notifications for logging and debugging. Something like this should do it:

ActiveSupport::Notifications.subscribe(/cache*+active_support/) do |name, start, finish, id, payload|
  Rails.logger.debug ['cache:', name, finish - start, id, payload].join(' ')
end

[findchris]

Thanks for that tip.

I dug into the issue a bit more, and I think I found a bug in how namespace is handled.

I construct my cache like so:

@cache_store = Readthis::Cache.new(
  redis: { url: ENV['REDIS_CACHE_URL'], driver: :hiredis },
  marshal: Oj
)
@cache_store.options[:namespace] = "Admin::Campaign"

I know the namespace could be passed in to the initializer, but according to existing ActiveSupport implementations, it doesn't need to be. I see that the namespace gets cached here, after which point the :namespace key doesn't appear to be fetched from the options hash.

So even though the options hash contains a namespace key, @namespace is nil:

@cache_store 
=> #<Readthis::Cache:0x00000111325458
 @entity=#<Readthis::Entity:0x000001113247b0 @compression=false, @marshal=Oj, @threshold=1024>,
 @expires_in=nil,
 @namespace=nil,
 @options={:redis=>{:url=>"redis://redacted:1234", :driver=>:hiredis}, :marshal=>Oj, :namespace=>Admin::Campaign},
 @pool=...

@cache_store.instance_variable_get :@namespace
=> nil

See how ActiveSupport::Cache::Store#namespaced_key checks the options hash every time.

I can see why you'd want to omit this for the sake of performance (in which case I'd recommend freezeing options), but it isn't exactly ActiveSupport cache "compliant" if you go this route.

[sorentwo]

Good find. The options hash was only recently exposed for the sake of compatibility, which would explain this oversight. I'll investigate the difference between fetching namespace from options on each call vs using the attr_accessor. I imagine it is negligible, and I'd rather prevent this kind of gotcha.

[sorentwo]

It turns out that this makes it faster for some operations.

Calculating -------------------------------------
      readthis:write   550.000  i/100ms
       readthis:read   719.000  i/100ms
 readthis:read_multi   727.000  i/100ms
-------------------------------------------------
      readthis:write      5.631k (± 1.2%) i/s -     28.600k
       readthis:read      7.317k (± 1.3%) i/s -     36.669k
 readthis:read_multi      7.383k (± 1.6%) i/s -     37.077k

With merge:

Calculating -------------------------------------
      readthis:write   548.000  i/100ms
       readthis:read   720.000  i/100ms
 readthis:read_multi   766.000  i/100ms
-------------------------------------------------
      readthis:write      5.619k (± 1.5%) i/s -     28.496k
       readthis:read      7.339k (± 1.1%) i/s -     36.720k
 readthis:read_multi      7.831k (± 0.9%) i/s -     39.832k

[findchris]

Thanks for the fast turnaround. Can you issue a patch-level gem version bump?

[sorentwo]

I'd prefer to wait and get some usage from master before I bump the patch version. If you've given it a run please report back here.

[findchris]

I just encountered a different (unrelated error):

r = Readthis::Cache.new(
  redis: { url: ENV['REDIS_CACHE_URL'], driver: :hiredis },
  marshal: Oj
)
r.options[:namespace] = "Admin::Campaigns"
r.write :all, []

# =>
TypeError: no implicit conversion of nil into Integer
from /Users/chris/.rvm/gems/ruby-2.1.3@the_app/bundler/gems/readthis-84aaaf569337/lib/readthis/entity.rb:95:in `pack'

Can you reproduce?

[sorentwo]

If you are using master with Oj you will need to configure Oj as one of the possible loaders. That can probably use a better error though, I'll set something up.

[findchris]

Thanks for the responsiveness.

I think I have another issue for you (sorry), or at least my understanding is lacking: Configuring the cache as per my previous example (added Readthis.serializers << Oj and include marshal: Oj in options), I'm seeing what looks like double-serialization (first Oj, and then Marshal) being applied. The resultant cache entry:

"\u0004{\"^o\":\"Admin::Campaign\",\"id\":\"1\"}"

Compare that to just Oj.dumping the object and writing it to the cache directly (using store.set):

"{\"^o\":\"Admin::Campaign\",\"id\":\"1\"}"

This difference is obviously the \u0004 part, which I have seen previously when using Marshal.dump.

Upon further investigation, I'm probably wrong, since doing Marshal.dump(Oj.dump(value)) yields a different result. Nonetheless, the \u0004 part confuses me /shrug.

Unrelated issue:

Readthis.serializers << Oj
=> #<Readthis::Serializers:0x007f8c70a2a518 @inverted={1=>Marshal, 2=>Readthis::Passthrough, 3=>JSON, 5=>Oj}, @serializers={Marshal=>1, Readthis::Passthrough=>2, JSON=>3, Oj=>5}>

# try to read from cache =>
Readthis::UnknownSerializerError: '0' doesn't match any serializers
from .../lib/readthis/serializers.rb:95:in `rassoc'

[sorentwo]

The \u0004 prefix you are seeing is from the new flagging mechanism. It allows multiple serializers to be used at the same time and accurately records compression info. Unfortunately it also breaks backward compatibility, but for good reason. There are more details in the CHANGELOG entry

[findchris]

@sorentwo I appreciate your support throughout this, and I'm sorry to pester you with another issue, but I'm seeing incorrect deserialization on read:

# using pry within #write_entity
> store.set(namespaced, dumped)
=> "OK"
> value = store.get(namespaced_key(key, merged_options(options)))
=> "\u0004{\"^o\":\"Admin::Campaign\",\"id\":\"1\"}"
> entity.load(value)
=> "\u0004{\"^o\":\"Admin::Campaign\",\"id\":\"1\"}"

I would expect this to be deserialized back into a Admin::Campaign. Is this assumption wrong?

[findchris]

To add to my above comment, I dug further, and it looks as though within Entity#decompose:

> marshal  = serializers.rassoc(flags & MARSHAL_FLAG)  # flags => 4
=> nil

Therefore, back in Entity#load, marshal.load(inflate(value, compress)) would be equivalent to calling nil.load(inflate(value, compress)), which raises NoMethodError, which just returns the unmodified string:

...
rescue TypeError, NoMethodError
  string
end

Can you have a look when you have a moment?

[sorentwo]

@findchris Thanks for digging around. I broke the build in a crucial spot earlier today, which you also happened to discover. I've removed the strict error that was triggered within the load method and things should be better.

[findchris]

Hi again @sorentwo - The issue as described in the comment above (#22 (comment)) is still occurring (and I'm running on the latest from master [61c969c]).

[findchris]

Another follow up on my investigation @sorentwo...

The setup (pry session in Readthis::Entity#decompose):

> flags
=> 4
> serializers.instance_variable_get :@inverted
=> {1=>Marshal, 2=>Readthis::Passthrough, 3=>JSON, 4=>Oj}

It seems that within Readthis::Entity#decompose, if we change:

> marshal  = serializers.rassoc(flags & MARSHAL_FLAG)
=>  nil # because flags & MARSHAL_FLAG returns 0 

to

> marshal  = serializers.rassoc(flags)
=> Oj

All works as planned.

Any insight here?

[findchris]

Could it be an inconsistency between:

  BASE_SERIALIZERS = {
      Marshal     => 0x1,
      Passthrough => 0x2,
      JSON        => 0x3
    }.freeze

and

MARSHAL_FLAG    = 0x3

?
Just trying to figure this out.
Cheers.

[sorentwo]

@findchris: Thanks for putting so much effort into tracking this down! Your discovery about the MARSHAL_FLAG value was the ticket. That's been fixed up in master and I've released a new version, 1.0.0-rc.1 with all of these fixes included.

[findchris]

Cool; I'll check it out. Regenerate gemspec?

[findchris]

I've tested this out, and all is working for me now 👍

[findchris]

FYI, I deployed this to production earlier today, and I am noticing a small decrease in CPU/latency, most likely due to leveraging Oj instead of Marshal, as I'm not doing any multi requests to Redis.

Anyway, nice work on the gem, and please do continue your support of it 👍

[sorentwo]

Thanks @findchris! You really helped drive these latest releases to a stable place.

[findchris]

@sorentwo 👌 I'm locked to the current commit, so I'll look forward to a gem release.