Redis [BUG] invalidation messages received before ACK of SUBSCRIBE __redis__:invalidate

Tried with 6, 7 and 8 on Docker.

I use a connection pair where I do on A:

CLIENT TRACKING ON REDIRECT <B id> prefix <...> BCAST NOLOOP

And on B:

SUBSCRIBE __redis__:invalidate

In answer to this I get ">3\r\n$9\r\nsubscribe\r\n$20\r\n__redis__:invalidate\r\n:1\r\n" as expected and then the invalidation messages can follow, eg:

>3\r\n$9\r\nsubscribe\r\n$20\r\n__redis__:invalidate\r\n:1\r\n
>2\r\n$10\r\ninvalidate\r\n*1\r\n$23\r\nb:05aabbccddeeff:Cmd111\r\n
>2\r\n$10\r\ninvalidate\r\n*1\r\n$23\r\nb:05aabbccddeeff:Cmd112\r\n
>2\r\n$10\r\ninvalidate\r\n*1\r\n$23\r\nb:05aabbccddeeff:Cmd113\r\n
>2\r\n$10\r\ninvalidate\r\n*1\r\n$23\r\nb:05aabbccddeeff:Cmd114\r\n

BUT if when I issue the SUBSCRIBE while already settings keys externally at a high rate I have cases where I see:

>2\r\n$10\r\ninvalidate\r\n*1\r\n$23\r\nb:05aabbccddeeff:Cmd111\r\n
>2\r\n$10\r\ninvalidate\r\n*1\r\n$23\r\nb:05aabbccddeeff:Cmd112\r\n
>3\r\n$9\r\nsubscribe\r\n$20\r\n__redis__:invalidate\r\n:1\r\n
>2\r\n$10\r\ninvalidate\r\n*1\r\n$23\r\nb:05aabbccddeeff:Cmd113\r\n
>2\r\n$10\r\ninvalidate\r\n*1\r\n$23\r\nb:05aabbccddeeff:Cmd114\r\n

Is it allowed to receive the subscribe ACK out of order or is this a bug?

Comment From: sundb

In theory >3\r\n$9\r\nsubscribe\r\n$20\r\n__redis__:invalidate\r\n:1\r\n will arrive faster than the invalid message. Is it possible that the client executes SUBSCRIBE __redis__:invalidate twice?

Comment From: nunojpg

I only execute it once, and this only happens if I am writing at a very high rate (from another connection), while subscribing.

Comment From: sundb

can you provide your reproducible steps? it would be better if any code.

Comment From: nunojpg

I have failed to reproduce this outside of my custom C++ client, which I can't make a small reproducible example, but I see a similar instance of this issue:

Set one process to always busy write:

while true; do redis-cli -s /run/redis/redis.sock set $(date +"%T.%N") a > /dev/null; done

In console A:

➜  ~ ncat -U /run/redis/redis.sock
HELLO 3
%7
$6
server
$5
redis
$7
version
$5
7.4.1
$5
proto
:3
$2
id
:222023
$4
mode
$10
standalone
$4
role
$6
master
$7
modules
*0
CLIENT ID
:222023

In console B:

~ ncat -U /run/redis/redis.sock
CLIENT TRACKING ON REDIRECT 222023 PREFIX 1 BCAST NOLOOP
+OK

At this point console A immediatly starts to get invalidate messages:

>2
$10
invalidate
*1
$18
10:25:30.744447157
>2
$10
invalidate
*1
$18
10:25:30.756668897

Without I ever issuing a subscribe command!

More interesting, if I ommit HELLO 3, then it doesn't start until I issue a subscribe.

So I could in this case reproduce getting invalidate messages before the subscribe, but only if HELLO 3 is used.

Comment From: sundb

@nunojpg thanks, i'll have a try.