Cache does not work!

[ziXet]

First of all, thanks for this awesome plugin!

My issue:

We would like to reduce the number of calls to our http auth backend by using cache. Particulary, we want to use the built-in "go-cache". However, it seems that the caching system does not work at all! no matter how we configure it.

Image: iegomez/mosquitto-go-auth:2.1.0-mosquitto_2.0.14

Config:

auth_plugin /mosquitto/go-auth.so

auth_opt_backends http

auth_opt_log_level warning
auth_opt_http_mode remote
auth_opt_http_host localhost
auth_opt_http_port 8000
auth_opt_http_getuser_uri /api/auth/mqtt/
auth_opt_http_aclcheck_uri /api/auth/mqtt/?check_acl=true
auth_opt_http_superuser_uri /api/auth/mqtt/?check_superuser=true
auth_opt_http_host_whitelist *
auth_opt_http_params_mode json

auth_opt_cache true
auth_opt_cache_type go-cache
auth_opt_cache_reset true
auth_opt_cache_refresh true

auth_opt_auth_cache_seconds 300
auth_opt_acl_cache_seconds 300
auth_opt_auth_jitter_seconds 5
auth_opt_acl_jitter_seconds 5

Related Logs:

....
mosquitto_1         | time="2023-05-05T16:15:40Z" level=info msg="Backend registered: HTTP"
mosquitto_1         | time="2023-05-05T16:15:40Z" level=info msg="registered acl checker: http"
mosquitto_1         | time="2023-05-05T16:15:40Z" level=info msg="registered user checker: http"
mosquitto_1         | time="2023-05-05T16:15:40Z" level=info msg="registered superuser checker: http"
mosquitto_1         | time="2023-05-05T16:15:40Z" level=info msg="redisCache activated"
mosquitto_1         | time="2023-05-05T16:15:40Z" level=info msg="started go-cache"
mosquitto_1         | time="2023-05-05T16:15:40Z" level=info msg="flushed go-cache"
.....

Not sure why this info msg shows up: "redisCache activated"!

We are still seeing acl requests to our HTTP backend.

Any help would be appreciated :-)

[ziXet]

Seems someone else also had this issue: https://stackoverflow.com/questions/76087851/why-is-mosquitto-go-auth-not-caching-auth-requests

[iegomez]

This might be a regression from the introduction of cache_refresh option.
As I mentioned in other issues, I 've had little time to check anything lately. I might take a look next week.

[ziXet]

This might be a regression from the introduction of cache_refresh option. As I mentioned in other issues, I 've had little time to check anything lately. I might take a look next week.

I can take a look and find the regression. Would you please give me the commit id that you guess cause this issue?

[iegomez]

Oh, wait, that was introduced back in late 2020, so this would've been utterly broken for a long time if it was related.
Tweaking the cache package tests might be a better way to find the problem.

[iegomez]

As for the redisCache activated message, it's just an oversight where whenever the cache option is set, it'll log that message regardless of the type of cache: https://github.com/iegomez/mosquitto-go-auth/blob/master/go-auth.go#L113

Good catch!

[iegomez]

If you set the log level to debug, you should be able to see if it's even attempting to hit the cache. For example, from authAclCheck:

	if authPlugin.useCache {
		log.Debugf("checking acl cache for %s", username)
		cached, granted = authPlugin.cache.CheckACLRecord(authPlugin.ctx, username, topic, clientid, acc)
		if cached {
			log.Debugf("found in cache: %s", username)
			return granted, nil
		}
	}

[iegomez]

Anyway, If I finish a couple of things in the next few minutes, I'll probably be able to take a quick look. Otherwise, next week it'll be.
If you do try to find the bug, happy hunting and let me know.

Cheers!

[ziXet]

Anyway, If I finish a couple of things in the next few minutes, I'll probably be able to take a quick look. Otherwise, next week it'll be. If you do try to find the bug, happy hunting and let me know.

Cheers!

go-cache test passed! I think I found the issue!

I realised that I have cache-miss because of the topic name change!

[ziXet]

Just one more thing. Doesn't it support superuser check?

[iegomez]

It should out of the box since setting the cache record is in the upper layer that doesn't care if the original check passed because of ACL rules or because of superuser abilities.
But I'll admit I'm rusty on these things, haven't used the plugin in years.

[ziXet]

It should out of the box since setting the cache record is in the upper layer that doesn't care if the original check passed because of ACL rules or because of superuser abilities. But I'll admit I'm rusty on these things, haven't used the plugin in years.

I'll try to submit a PR if I could make any improvements.

Thanks again.

[iegomez]

@ziXet I see you closed the issue. What was the actual resolution?
Was it that your app was changing topics and thus the cache always missed, or did you find a bug and are preparing a PR in favor of the issue?

[ziXet]

@ziXet I see you closed the issue. What was the actual resolution? Was it that your app was changing topics and thus the cache always missed, or did you find a bug and are preparing a PR in favor of the issue?

Yes, it was my app that was changing the topic! No issue on your code.

Thanks