vhost requests not cached

[BenTalagan]

Hi all,

Today I've been integrating a rabbitmq (3.7.12) with an HTTP authentication backend, with a backend cache. The http server is a rails server. I've noticed that everything seems to work well, every requests are cached except the vhost ones, strangely.

All four web services (user,vhost,resource,topic) just reply http status 200 and content 'allow' .

I use mosquitto_sub to connect to the rabbitmq server, and have enabled the mqtt plugin. This is actually my complete conf :

mqtt.vhost            = /
mqtt.exchange         = mqttexchange
# 24 hours by default
mqtt.subscription_ttl = 86400000
mqtt.prefetch         = 10

auth_backends.1 = internal
auth_backends.2 = cache

auth_cache.cached_backend = http
auth_cache.cache_ttl      = 120000
auth_cache.cache_refusals = true

auth_http.http_method   = post
auth_http.user_path     = http://rabbitmq:password@localhost:5000/rabbitmq_auth/user
auth_http.vhost_path    = http://rabbitmq:password@localhost:5000/rabbitmq_auth/vhost
auth_http.resource_path = http://rabbitmq:password@localhost:5000/rabbitmq_auth/resource
auth_http.topic_path    = http://rabbitmq:password@localhost:5000/rabbitmq_auth/topic

The parameters received on the vhost service look like :

{"username"=>"acfef9c2157f", "vhost"=>"/", "ip"=>"::ffff:127.0.0.1"}

When performing the connection, quite a number of requests are sent to the rails auth backend (user,vhost,resource,topic), all are correctly cached by the cache plugin - except the vhost ones.

I'm not familiar to the erlang language, so I don't have a clue about a potential bug. Any idea?

[lukebakken]

When performing the connection, quite a number of requests are sent to the rails auth backend (user,vhost,resource,topic), all are correctly cached by the cache plugin - except the vhost ones.

"except the vhost ones" - can you provide a couple complete HTTP request / responses for these non-cached requests? Please attach in a file. Thanks.

[BenTalagan]

Sure, this is a serie of vhost requests sniffed with wireshark between RMQ and the rails server. Please tell me if it suits your needs and if you want any other info. Thanks a lot for your very fast answer by the way!

uncached_requests.txt

[lukebakken]

Thanks, that helps a lot. I'll check it out.

[michaelklishin]

Is there a way for you to share the requests with timestamps? It should be possible to only export a range of frames in Wireshark.

[BenTalagan]

Okay, I'm not very familiar with wireshark, here's a complete capture of the flow (wireshark format).

vhost_capture.pcapng.zip

Requests are made repeatedly almost every second by mosquitto here (the connection is refused because I've denied the authorization at topic level, so mosquitto will retry over and over again, fully restarting the authentication/authorization process, on user / vhost / resource / topic services - the cache plugin does it job well for every service except for vhost, so the final result is that RMQ will only send the vhost requests, not the other ones, and as such, the flow is only made from vhost requests).

[michaelklishin]

This plugin performs caching within the context of a connection. If a client reconnects over and over, those are new connections and their operations will not be cached. Can you please share server logs, which will make it clear whether that's the case? I don't see any MQTT connections in the capture file above.

I don't see how authorization failure at topic level would refuse connection. The guide on Connections describes the flow. Before access to virtual host is allowed, a client cannot perform any operation, so topic authorization restrictions are not relevant. If virtual host access is allowed, and topic authorization fails, in case ofo MQTT the connection must be closed. If Mosquitto client reacts to that by reconnecting, we have the scenario above where caching is not meant to work because it's a new connection.

@BenTalagan please provide a way to reproduce. So far it seems to be that the plugin works as expected but the dump doesn't include any MQTT client activity so we are guessing.

[michaelklishin]

I wasn' completely correct in the comment above. There are more nuances: this plugin doesn't cache refused operations by default. auth_cache.cache_refusals can be set to true.

With ETS caching backend then cache results should be kept around for a while between connections, as long as all authentication context values are identical and cache invalidation hasn't happened.

I don't see any explicit cache invalidation for closing connections.

[BenTalagan]

@BenTalagan please provide a way to reproduce. So far it seems to be that the plugin works as expected but the dump doesn't include any MQTT client activity so we are guessing.

Ok, this is gonna be a bit long to reduce to a simple case. I think the best way would be for me to write a very small auth server with almost nothing inside, it'd be easier that way :) . It should take me a little while to provide it, but just let me react to your other answers.

I don't see how authorization failure at topic level would refuse connection. The guide on Connections describes the flow. Before access to virtual host is allowed, a client cannot perform any operation, so topic authorization restrictions are not relevant. If virtual host access is allowed, and topic authorization fails, in case ofo MQTT the connection must be closed. If Mosquitto client reacts to that by reconnecting, we have the scenario above where caching is not meant to work because it's a new connection.
I wasn't completely correct in the comment above. There are more nuances: this plugin doesn't cache refused operations by default. auth_cache.cache_refusals can be set to true.
With ETS caching backend then cache results should be kept around for a while between connections, as long as all authentication context values are identical and cache invalidation hasn't happened.
I don't see any explicit cache invalidation for closing connections.

cache_refusals is set to true in my configuration, so this is the context you are evoking in your second answer, and it looks more to what I've observed (your first answer was really surprising compared to what I'm observing : for example, when killing a mosquitto , and relaunching it, I can clearly see the cache involved). You're right, mosquitto does not 'disconnect' on topic denial, but the behaviour seen from the HTTP server is that the full cycle of authorizations will be done again (it can be seen when disabling the cache).

This is what's printed by mosquitto :

Client toto received CONNACK (0)
Client toto sending SUBSCRIBE (Mid: 698, Topic: /acfef9c217f/uplink/#, QoS: 1)
Client toto sending CONNECT
Client toto received CONNACK (0)
Client toto sending SUBSCRIBE (Mid: 699, Topic: /acfef9c217f/uplink/#, QoS: 1)
Client toto sending CONNECT
Client toto received CONNACK (0)
Client toto sending SUBSCRIBE (Mid: 700, Topic: /acfef9c217f/uplink/#, QoS: 1)

So, the flow I'm observing, and caching disabled :

• Mosquitto connects
• HTTP server receives user, answers allow
• HTTP server receives vhost, answers allow
• HTTP server receives resource, queue, configure, answers allow
• HTTP server receives resource, queue, read, answers allow
• HTTP server receives resource, queue, write, answers allow
• HTTP server receives topic, read, answers deny (my hack to 'kick out' the client)
• Mosquitto retries
• HTTP server receives user, answers allow
• HTTP server receives vhost, answers allow
• HTTP server receives resource, queue, configure, answers allow
• HTTP server receives resource, queue, read, answers allow
• HTTP server receives resource, queue, write, answers allow
• HTTP server receives topic, read, answers deny (my hack to 'kick out' the client)
• Mosquitto retries
• etc ...

And with caching enabled (with a clear cache) :

• Mosquitto connects
• HTTP server receives user, answers allow
• HTTP server receives vhost, answers allow
• HTTP server receives resource, queue, configure, answers allow
• HTTP server receives resource, queue, read, answers allow
• HTTP server receives resource, queue, write, answers allow
• HTTP server receives topic, read, answers deny (my hack to 'kick out' the client)
• Mosquitto retries
• HTTP server receives vhost, answers allow (all other requests are answered by the cache)
• Mosquitto retries
• HTTP server receives vhost, answers allow (all other requests are answered by the cache)
• etc ...

That's what I mean by all requests are cached, except vhost requests. Killing mosquitto and relaunching it will not change the cache behaviour.

@BenTalagan please provide a way to reproduce. So far it seems to be that the plugin works as expected but the dump doesn't include any MQTT client activity so we are guessing.

Sure, and now I have too much activity in my captures so it's almost unreadable. The best thing to do is probably to give me a little while to write a small server, cause it's even harder and harder for me to just write clear comments! :-)

[michaelklishin]

There's a bunch of example services that you can modify and share in a separate repo. We'll try to reproduce either way, thank you for the details.

[BenTalagan]

Yup, seen that already. No ruby example yet (sinatra or rails), could be a good occasion!

[BenTalagan]

Ok, I can reproduce it with a very small rails server. Here is the source :

rmq_auth_backend.zip

Here is my rabbitmq conf file :

rabbitmq.conf.zip

And here is the command to launch mosquitto :

mosquitto_sub -p 1883 -h 127.0.0.1 -u user -P password -i client_id -t topic -d -v -q 1

I hope you're a bit familiar with ruby/rvm ; with a recent install of ruby, you should be able to go to the server directory, and install the needed components with :

cd rmq_auth_backend
gem install bundler
bundle

Then launch the server like this :

rails s

As you can see the authentication controller is dead simple :

class RabbitmqAuthController < ApplicationController

  def user
    render status: :ok, html: 'allow'
  end
  
  def vhost
    render status: :ok, html: 'allow'
  end
  
  def resource
    render status: :ok, html: 'allow'
  end
  
  def topic
    render status: :ok, html: 'deny'
  end
    
end

With these elements you should be in the same configuration as I am. This produces the behavior I've tried to describe (with pain!). If you need anything, don't hesitate to ask!

[BenTalagan]

Oh, one more useful info I can add is that the problematic behavior remains the same if I change the cache module from auth_cache.cache_module = rabbit_auth_cache_ets to auth_cache.cache_module = rabbit_auth_cache_dict.

[lukebakken]

Hi @BenTalagan I finally had time to investigate and yes, I can reproduce this in my environment. I plan on starting my day tomorrow with this.

[BenTalagan]

Hi @lukebakken, awesome. Thanks a lot for the update, wish you good luck for your investigations!