Weird phenomenon when using CAS transaction in dedicated connection

[dntam00]

Hello everyone, I'm facing unexplainable problem when using CAS transaction, the redis transaction fails and return null message, but when I used MONITOR command and capture packet by wireshark, I didn't see any others updating in watched key.
Here is the log of MONITOR command:

2024-06-15 14:27:12.811820 [0 172.24.0.1:58706] "ZADD" "watched_key" "INCR" "-1" "127.0.0.1"
2024-06-15 14:27:12.816681 [0 172.24.0.1:58654] "ZREM" "another_key" "127.0.0.1-d9cace95-2a26-4d94-aa24-1a1d2c381a82"
2024-06-15 14:27:12.823212 [0 172.24.0.1:58674] "ZSCORE" "watched_key" "127.0.0.1"
2024-06-15 14:27:12.831299 [0 172.24.0.1:38920] "EVALSHA" "7726c7be95e2a0ed082ec1da1e26b562f5c8903f" "1" "2:127.0.0.1-d9cace95-2a26-4d94-aa24-1a1d2c381a82" "\x84\xa2\x9f\x13\x85\x1c\xe9\\\xcc\a\x82D\xa4\x8a\xd7B\xa8\xbfK\xfd\xe2\x13\xaaX" "1718461637799"
2024-06-15 14:27:12.831648 [0 lua] "GET" "2:127.0.0.1-d9cace95-2a26-4d94-aa24-1a1d2c381a82"
2024-06-15 14:27:12.831702 [0 lua] "DEL" "2:127.0.0.1-d9cace95-2a26-4d94-aa24-1a1d2c381a82"
2024-06-15 14:27:12.831804 [0 172.24.0.1:58650] "EVALSHA" "7726c7be95e2a0ed082ec1da1e26b562f5c8903f" "1" "0:127.0.0.1-d9cace95-2a26-4d94-aa24-1a1d2c381a82" "\x84\xa2\x9f\x13\x85\x1c\xe9\\\xcc\a\x82D\xa4\x8a\xd7B\xa8\xbfK\xfd\xe2\x13\xaaX" "1718461637799"
2024-06-15 14:27:12.831908 [0 lua] "GET" "0:127.0.0.1-d9cace95-2a26-4d94-aa24-1a1d2c381a82"
2024-06-15 14:27:12.831932 [0 lua] "DEL" "0:127.0.0.1-d9cace95-2a26-4d94-aa24-1a1d2c381a82"
2024-06-15 14:27:12.831993 [0 172.24.0.1:58650] "EVALSHA" "7726c7be95e2a0ed082ec1da1e26b562f5c8903f" "1" "1:127.0.0.1-d9cace95-2a26-4d94-aa24-1a1d2c381a82" "\x84\xa2\x9f\x13\x85\x1c\xe9\\\xcc\a\x82D\xa4\x8a\xd7B\xa8\xbfK\xfd\xe2\x13\xaaX" "1718461637799"
2024-06-15 14:27:12.832003 [0 lua] "GET" "1:127.0.0.1-d9cace95-2a26-4d94-aa24-1a1d2c381a82"
2024-06-15 14:27:12.832006 [0 lua] "DEL" "1:127.0.0.1-d9cace95-2a26-4d94-aa24-1a1d2c381a82"
2024-06-15 14:27:12.904419 [0 172.24.0.1:38900] "ZSCORE" "watched_key" "127.0.0.1"
2024-06-15 14:27:12.905439 [0 172.24.0.1:38900] "WATCH" "watched_key"
2024-06-15 14:27:12.906484 [0 172.24.0.1:38900] "ZRANGEBYSCORE" "watched_key" "-inf" "9" "LIMIT" "0" "1"
2024-06-15 14:27:12.907474 [0 172.24.0.1:38900] "ZSCORE" "watched_key" "127.0.0.1"
2024-06-15 14:27:12.908419 [0 172.24.0.1:38900] "MULTI"
2024-06-15 14:27:12.909881 [0 172.24.0.1:38900] "EXEC"
2024-06-15 14:27:12.910860 [0 172.24.0.1:38900] "ZSCORE" "watched_key" "127.0.0.1"
2024-06-15 14:27:13.244464 [0 172.24.0.1:35638] "keys" "turn/origin/*"
2024-06-15 14:27:13.244489 [0 172.24.0.1:35620] "keys" "turn/origin/*"
2024-06-15 14:27:13.244900 [0 172.24.0.1:35634] "keys" "turn/origin/*"
2024-06-15 14:27:13.244920 [0 172.24.0.1:35636] "keys" "turn/origin/*"
2024-06-15 14:27:13.245474 [0 172.24.0.1:35630] "keys" "turn/origin/*"
2024-06-15 14:27:13.804457 [0 172.24.0.1:58674] "ZRANGEBYSCORE" "another_key" "-inf" "1718461633" "LIMIT" "0" "100"

please focus on MULTI and EXEC and there is no command between them.
the wireshark shows that command is QUEUED successfully.

Even when I use ZSCORE to get data in transaction, it's still same as expected.
I'm implementing this function as follow (example):

_ = redis.Dedicated(func(c rueidis.DedicatedClient) error {
		// watch key
		c.Do(ctx, c.B().Watch().Key(queueName).Build())
		// get instance
		redisResult := c.Do(ctx, c.B().Zrangebyscore().Key(queueName).Min("-inf").
			Max(strconv.Itoa(9)).Limit(0, 1).Build())
		c.Do(ctx, c.B().Multi().Build())
		c.Do(ctx, c.B().Zadd().Key(queueName).Incr().ScoreMember().ScoreMember(1, "127.0.0.1").Build()
		_, err := c.Do(ctx, c.B().Exec().Build()).ToArray()
		if err != nil {
			fmt.Println(fmt.Errorf("error while increasing request count: %v", err))
		}
		return err
	})

In my application, there is another goroutine which updates this value, but if this is the case, I think MONITOR command or wireshark must shows it.

Thank you. 🙏🙏🙏

[rueian]

Hi @dangngoctam00,

In my application, there is another goroutine which updates this value, but if this is the case, I think MONITOR command or wireshark must shows it.

That is exactly the reason why you got a nil response from the EXEC. MONITOR will only log commands that have been successfully executed. So you will not see any commands between MULTI and EXEC from the logs of an aborted transaction.

In terms of wireshark, it should show those aborted commands, and according to your screenshot, it did:

The QUEUED is the response of the ZADD.

[rueian]

I see. Actually, we could also do UNWATCH or DISCARD in rueidis here:

rueidis/pipe.go

Lines 751 to 759 in 5fe0175

	func (p *pipe) CleanSubscriptions() {
	if atomic.LoadInt32(&p.state) == 1 {
	if p.version >= 7 {
	p.DoMulti(context.Background(), cmds.UnsubscribeCmd, cmds.PUnsubscribeCmd, cmds.SUnsubscribeCmd)
	} else {
	p.DoMulti(context.Background(), cmds.UnsubscribeCmd, cmds.PUnsubscribeCmd)
	}
	}
	}

[rueian]

This function will be called when a dedicated connection is recycled to reset the connection state.

[dntam00]

@rueian thank you for your support.

[dntam00]

To summarize: UNWATCH if we don't EXEC transaction after WATCH any key.