Describe the bug
I have a lua script with:
redis.call("EXPIREAT", KEYS[1], tonumber(ARGV[1]));
And somehow when running redis-cli monitor I see it print 1649939655.077101 [2 lua] "pexpireat" "mykey" "1650024000"
So it seems to be calling pexpireat but with my non-millisecond-precision timestamp, which is completely broken.
Expected behavior
I'd expect expireat to be called.
Additional information
I run this on AWS Elasticache with redis compatibility version 6.2.5. I am not sure if this could be a bug of their redis port or not.
As workaround I switched to call PEXPIREAT and multiply my timestamp by 1000.
Comment From: Seldaek
Found a minimal repro script.. it seems to have something to do with the key existence.
redis-cli eval 'redis.call("expireat", "testkey", 1650024000); redis.call("set", "testkey", "1"); redis.call("expireat", "testkey", 1650024000); redis.call("del", "testkey"); redis.call("expireat", "testkey", 1650024000);' 0
Monitor output:
1649945585.540959 [5 10.10.1.10:33782] "eval" "redis.call(\"expireat\", \"testkey\", 1650024000); redis.call(\"set\", \"testkey\", \"1\"); redis.call(\"expireat\", \"testkey\", 1650024000); redis.call(\"del\", \"testkey\"); redis.call(\"expireat\", \"testkey\", 1650024000);" "0"
1649945585.541002 [5 lua] "expireat" "testkey" "1650024000"
1649945585.541011 [5 lua] "set" "testkey" "1"
1649945585.541019 [5 lua] "pexpireat" "testkey" "1650024000"
1649945585.541026 [5 lua] "del" "testkey"
1649945585.541030 [5 lua] "expireat" "testkey" "1650024000"
As you can see, out of the 3 calls to expireat only 2 really call expireat (when the key does not exist), but when it does exist it somehow calls pexpireat.
It does appear like the TTL of the key is set correctly though, so it may be just a bug in the monitor output somehow.
It also appears like the lua scripting is not in cause, as doing it without lua also has the same outcome.
Comment From: Seldaek
I also cannot reproduce this with my local redis, but that is version 6.0.6. I don't have a way of getting 6.2.5 easily so cannot confirm if it's a new regression or an AWS-specific bug sorry.
Comment From: hwware
I tried this on redis 6.2.5 but I am not able to replicate this on my end. Maybe this is a AWS specific bug like you said. Can you share the config file you are using for this?
Comment From: Seldaek
@hwware sorry what config file are you referring to here? I'm using default parameters from AWS, so no config per se.
Comment From: madolson
@Seldaek Hello, I'm from AWS elasticache :) If you have a support ticket, can you send it to me at matolson@amazon.com.
I'm taking a looking to see if I can repro it on some internal versions. I didn't think we had any custom code here, just using the OSS implementation, but I'll check.
Comment From: Seldaek
@madolson thanks for checking, I have not opened a support ticket yet as I was hoping to first confirm it's really AWS specific.
Comment From: madolson
@Seldaek So I can confirm it's an AWS bug, and it is only a bug when the key exists because we have an early exit in the code for the case the key does not exist. When the key does exist, we "rewrite" the command to higher precision for replication, and we for some reason always print the 'real' name of the currently executed command instead of the rewritten variant.
Just to make it clear, this is just a visual bug, we're not actually executing the listed command on any node.
Fun fact, this bug has existed since the launch of our service back in 2012, so kudos to you for being the first to find it :)
Comment From: madolson
Ok, resolving this for now, if you have more questions feel free to follow up with me at the email I provided. We'll work to get this fixed in our service.
Comment From: Seldaek
Great, thanks for jumping on this so quickly (even tho it's been there for 10 years;). That matches my findings so I can definitely go back to using expireat now.