"Cache token has expired" error

[piotrpalarz]

Hi,

thank you for creating and maintaining this great driver. It's been really useful. I have one problem though.

I have configured automatic backup using laravel-backup and OVH Public Cloud Object Storage (it uses OpenStack Swift). It works just fine but after some time I get this error: "Cached token has expired on [date]".

I was about to open an issue here when I found out that you added laravel-cached-openstack and I was hoping that it would fix that issue. Unfortunately it didn't.

Is it anything I could change in my configuration or is it something that you have to fix in this driver?

Thanks

[mzur]

Which cache driver do you use? Maybe your cache doesn't handle the expiration date correctly.

[piotrpalarz]

I'm using Redis.

[mzur]

Maybe this is an issue with the time zone (i.e. your app has a different timezone than OVH servers, ref). Could this be the case?

To confirm this, you could add the following line here in your installed laravel-cached-openstack source:

logger('Token', ['original' => $token->expires, 'cached' => new DateTime($cachedToken['expires_at'])]);

Then clear the cache, perform some call to OpenStack and post the new lines added to your application logfile here.

[piotrpalarz]

I was just digging in the same code. Yes, my server is indeed in different timezone than the one returned from the OVH API call, but using DateTime eliminates the need to convert the date to the same timezone.

Output from the logger is:
Token {"original":"[object] (DateTimeImmutable: {\"date\":\"2019-01-16 13:48:05.000000\",\"timezone_type\":2,\"timezone\":\"Z\"})","cached":"2019-01-16 13:48:05"}
so it's the same.

If I use TTL app_cache:openstack-token-11c96b0ba5295a51e4db628298cb40de in Redis CLI, it returns 86117 (was 86400 which is 24h in seconds) so it's also correct and after that time that entry would be removed from the cache.

I run backups every hour so maybe when the token is generated and valid for the next 24 hours it exceeds that time right after my backup starts 24h later. I'll try to subtract 5 minutes from $cachedToken['expires_at'] and if I'm right it should fix that problem. I'll let you know tomorrow or within few days because that problem doesn't occur every 24 hour but once within few days.

[mzur]

using DateTime eliminates the need to convert the date to the same timezone

Yes but laravel-cached-openstack uses the string representation of the expiration date which does not include timezone information and probably is not converted. I see that your log entry contains "cached":"2019-01-16 13:48:05" instead of the dump of a DateTime object. Did you insert the exact code I posted above? With the dump of a DateTime object we would be able to compare the time (zones).

[piotrpalarz]

Yes, I pasted the code that you provided and that's the output. But given the correct TTL in Redis, it's all good. The token will be removed from cache excatly when expires_at from the API call says. Also, openstack does take the timezone into account (ref) and your code is not modifying expires_at date string returned from the API call.

I'm pretty sure right now that I run into this rare edge case because I run my backups regularly every hour. And given the fact that it's not happening every 24h but once within few days, it's probably it. I've added the code to subtract 5 minutes from that time and we'll see.

[mzur]

I'm not 100% convinced yet. And subtracting 5 min is a workaround at best. Please leave this issue open, I want to do a few tests myself when I have some time.

[piotrpalarz]

Ok, sure.

But what if the problem is between grabbing the token from the cache and calling $token->hasExpired()

Imagine a scenario like this (and that's what's happening on my server):

1. cron runs php artisan schedule:run command every minute
2. If it's round hour (e.g. 01:00) it runs php artisan backup:run --only-db
3. It dumps the database, creates a ZIP package
4. It uploads the package to the OVH using your driver so:
   4.1. If the token doesn't exist it creates one and stores it in the cache. Let's say its 01:00:11 so it will be removed from the cache at the exact time 24h later (I have confirmed that, Redis TTL is correct)
   4.2. If the token exists in the cache it's being deserialized and used. But here can be a problem. Let's say that the token is retrieved from the cache because its expires_at doesn't pass yet (e.g 01:00:11). [here that time passed and it's removed from the cache but it's in the PHP memory after retrieving it]. $token->hasExpired() is called and returns true because the token is not valid anymore (let's say it's 01:00:12).

Of course PHP runs that code very fast but I think this could be what's happening although it sounds unlikly. From a logical standpoint it's possible if we think about how much thought is being put into things like "atomic symlink" in Linux etc.

[mzur]

Ah, now I see what you mean. This is indeed an edge case when your backup interval matches exactly to the time the token is valid. This also explains why the error occurred only sometimes for you.

Now I'm convinced 😉 Then maybe it's best to always subtract a minute or so from the TTL in the cache. I'll see that I update laravel-cached-openstack accordingly.

[piotrpalarz]

Exactly. And that wouldn't be an issue for other users since your driver gives them ability not to call the API for the new token for 24h (or another time depending on the response) so if it will be 1 minute less it shouldn't be a problem.

Of course it's your call if you update the package but it would be awesome to have the ability to pull the newest version and forget about that problem which I'm almost sure we diagnosed here. If you want to wait, I'll be testing this out with -5 minutes for the next few days.

[mzur]

I intend to update the package but I won't have time for that in the next few days. Please report back if the change fixed the issue for you. Feel free to open a pull request to laravel-cached-openstack if it does.

[piotrpalarz]

Ok, will do. Thank you for your help.

[piotrpalarz]

Problem solved here: https://github.com/biigle/laravel-cached-openstack/releases/tag/v1.0.1