Fix blocking commands timeout is reset due to re-processing command #13004

enjoy-binbin · 2024-01-29T08:42:57Z

In #11012, we will reprocess command when client is unblocked on keys,
in some blocking commands, for example, in the XREADGROUP BLOCK scenario,
because of the re-processing command, we will recalculate the block timeout,
causing the blocking time to be reset.

This commit add a new CLIENT_REPROCESSING_COMMAND clent flag, explicitly
let the command know that it is being re-processed, later in blockForKeys
we will not reset the timeout.

Affected BLOCK cases:

list / zset / stream, added test cases for each.

Unaffected cases:

module (never re-process the commands).
WAIT / WAITAOF (never re-process the commands).

Fixes #12998.

In redis#11012, we will reprocess command when client is unblocked on keys, In the XREADGROUP BLOCK scenario, because of the re-processing command, we will recalculate the block timeout, causing the blocking time to be reset. This commit add a new CLIENT_REPROCESSING_COMMAND clent flag, explicitly let the command know that it is being re-processed, later in blockForKeys we will not reset the timeout. Fixes redis#12998.

enjoy-binbin · 2024-01-29T08:44:02Z

I'm considering adding a test, such as checking the time-consuming in redis-cli.tcl
I don't know if there is any other better way? We seem to have no way to check how long the client has been blocked?

oranagra · 2024-01-29T11:17:15Z

I'm considering adding a test, such as checking the time-consuming in redis-cli.tcl I don't know if there is any other better way? We seem to have no way to check how long the client has been blocked?

why is it hard to measure it in TCL with clock milliseconds (i.e. after rd read)?

oranagra

please check if other blocking commands were affected by this bug.
i.e. WAITAOF, modules, BLPOP.
i suppose at least the list blocking commands can get unblocked and re-blocked similarly to XREAD, so we should mention them in the release notes.

src/server.c

enjoy-binbin · 2024-01-29T16:49:21Z

BLPOP / BZPOPMIN have the same issue and i reproduce it in local.

i think modules also have the issue, but i haven't found a test case to reproduce yet, maybe you have a idea?

    c->bstate.timeout = 0;
    if (timeout_ms) {
        mstime_t now = mstime();
        if  (timeout_ms > LLONG_MAX - now) {
            c->bstate.module_blocked_handle = NULL;
            addReplyError(c, "timeout is out of range"); /* 'timeout_ms+now' would overflow */
            return bc;
        }
        c->bstate.timeout = timeout_ms + now;
    }

WAITAOF, i didn't think of a scenario where re-process would be triggered, do you have a idea?

I will continue to think about it tomorrow and push the first

oranagra · 2024-01-29T19:07:14Z

i don't think we have to test all of them.
just wanted to mention in the release notes which ones are affected.
please update the top comment and ping me when ready for merge

… a value to c->bstate.timeout

enjoy-binbin · 2024-01-30T07:44:52Z

There may be modules, but I haven't found any examples where we will re-process command (except blocking auth). Just in case, I also made a small change in the last commit, please take a look

wait and waitaof don't seem to re-process command

oranagra · 2024-01-30T09:14:49Z

i think that in modules we never re-process the commands, we left it out of scope in #11012 @ranshid please ack.
@enjoy-binbin please update the top comment with a list of what's impacted and what's not.

enjoy-binbin · 2024-01-30T09:22:42Z

i think that in modules we never re-process the commands, we left it out of scope in #11012 @ranshid please ack.

#11832

i updated the top comment

enjoy-binbin · 2024-01-30T09:53:23Z

https://github.com/redis/redis/actions/runs/7709050607/job/21009405189#step:5:683

i see i missed something, that the ci is fails.

        if (keys) {
            blockForKeys(c,BLOCKED_MODULE,keys,numkeys,timeout,flags&REDISMODULE_BLOCK_UNBLOCK_DELETED);
        } else {
+            c->bstate.timeout = timeout;
            blockClient(c,BLOCKED_MODULE);
        }

@oranagra
Do you need me to handle it this way? It feels like the code is a bit hidden. I guess it was just happen to passed PR CI and locally before, so i didn’t find that the Unblock by timer test case would fail.

oranagra · 2024-01-30T09:59:13Z

@enjoy-binbin yes, please fix it in this way.
p.s. i don't understand how come it lead to invalidFunctionWasCalled and why it would be flaky. (didn't bother to look at the test)

enjoy-binbin · 2024-01-30T10:00:49Z

p.s. i don't understand how come it lead to invalidFunctionWasCalled and why it would be flaky. (didn't bother to look at the test)

yes, now it is flaky, i'll try to get it to stabilize and then i will issue the fix.

This was introduced in redis#13004, missing this assignment. It causes timeout to be a random value (may be less than now), and then in `Unblock by timer` test, the client is unblocked and then it call timeout_callback, since the callback is NULL, the server will crash. The crash stack is: ``` beforesleep handleBlockedClientsTimeout checkBlockedClientTimeout unblockClientOnTimeout replyToBlockedClientTimedOut moduleBlockedClientTimedOut bc->timeout_callback(&ctx,(void**)c->argv,c->argc); ```

This was introduced in #13004, missing this assignment. It causes timeout to be a random value (may be less than now), and then in `Unblock by timer` test, the client is unblocked and then it call timeout_callback, since the callback is NULL, the server will crash. The crash stack is: ``` beforesleep handleBlockedClientsTimeout checkBlockedClientTimeout unblockClientOnTimeout replyToBlockedClientTimedOut moduleBlockedClientTimedOut -- the timeout_callback is NULL, invalidFunctionWasCalled bc->timeout_callback(&ctx,(void**)c->argv,c->argc); ```

…edis#13004) In redis#11012, we will reprocess command when client is unblocked on keys, in some blocking commands, for example, in the XREADGROUP BLOCK scenario, because of the re-processing command, we will recalculate the block timeout, causing the blocking time to be reset. This commit add a new CLIENT_REPROCESSING_COMMAND clent flag, explicitly let the command know that it is being re-processed, later in blockForKeys we will not reset the timeout. Affected BLOCK cases: - list / zset / stream, added test cases for each. Unaffected cases: - module (never re-process the commands). - WAIT / WAITAOF (never re-process the commands). Fixes redis#12998.

This was introduced in redis#13004, missing this assignment. It causes timeout to be a random value (may be less than now), and then in `Unblock by timer` test, the client is unblocked and then it call timeout_callback, since the callback is NULL, the server will crash. The crash stack is: ``` beforesleep handleBlockedClientsTimeout checkBlockedClientTimeout unblockClientOnTimeout replyToBlockedClientTimedOut moduleBlockedClientTimedOut -- the timeout_callback is NULL, invalidFunctionWasCalled bc->timeout_callback(&ctx,(void**)c->argv,c->argc); ```

These tests have all failed in daily CI: ``` *** [err]: Blocking XREADGROUP for stream key that has clients blocked on stream - reprocessing command in tests/unit/type/stream-cgroups.tcl Expected '1101' to be between to '1000' and '1100' (context: type eval line 23 cmd {assert_range [expr $end-$start] 1000 1100} proc ::test) *** [err]: BLPOP unblock but the key is expired and then block again - reprocessing command in tests/unit/type/list.tcl Expected '1101' to be between to '1000' and '1100' (context: type eval line 23 cmd {assert_range [expr $end-$start] 1000 1100} proc ::test) *** [err]: BZPOPMIN unblock but the key is expired and then block again - reprocessing command in tests/unit/type/zset.tcl Expected '1103' to be between to '1000' and '1100' (context: type eval line 23 cmd {assert_range [expr $end-$start] 1000 1100} proc ::test) ``` Increase the range to avoid failures, tests was introduced in redis#13004.

…ues (#13053) These tests have all failed in daily CI: ``` *** [err]: Blocking XREADGROUP for stream key that has clients blocked on stream - reprocessing command in tests/unit/type/stream-cgroups.tcl Expected '1101' to be between to '1000' and '1100' (context: type eval line 23 cmd {assert_range [expr $end-$start] 1000 1100} proc ::test) *** [err]: BLPOP unblock but the key is expired and then block again - reprocessing command in tests/unit/type/list.tcl Expected '1101' to be between to '1000' and '1100' (context: type eval line 23 cmd {assert_range [expr $end-$start] 1000 1100} proc ::test) *** [err]: BZPOPMIN unblock but the key is expired and then block again - reprocessing command in tests/unit/type/zset.tcl Expected '1103' to be between to '1000' and '1100' (context: type eval line 23 cmd {assert_range [expr $end-$start] 1000 1100} proc ::test) ``` Increase the range to avoid failures, and improve the comment to be clearer. tests was introduced in #13004.

…edis#13004) In redis#11012, we will reprocess command when client is unblocked on keys, in some blocking commands, for example, in the XREADGROUP BLOCK scenario, because of the re-processing command, we will recalculate the block timeout, causing the blocking time to be reset. This commit add a new CLIENT_REPROCESSING_COMMAND clent flag, explicitly let the command know that it is being re-processed, later in blockForKeys we will not reset the timeout. Affected BLOCK cases: - list / zset / stream, added test cases for each. Unaffected cases: - module (never re-process the commands). - WAIT / WAITAOF (never re-process the commands). Fixes redis#12998. (cherry picked from commit 492021d)

This was introduced in redis#13004, missing this assignment. It causes timeout to be a random value (may be less than now), and then in `Unblock by timer` test, the client is unblocked and then it call timeout_callback, since the callback is NULL, the server will crash. The crash stack is: ``` beforesleep handleBlockedClientsTimeout checkBlockedClientTimeout unblockClientOnTimeout replyToBlockedClientTimedOut moduleBlockedClientTimedOut -- the timeout_callback is NULL, invalidFunctionWasCalled bc->timeout_callback(&ctx,(void**)c->argv,c->argc); ``` (cherry picked from commit 45a35a7)

…ues (redis#13053) These tests have all failed in daily CI: ``` *** [err]: Blocking XREADGROUP for stream key that has clients blocked on stream - reprocessing command in tests/unit/type/stream-cgroups.tcl Expected '1101' to be between to '1000' and '1100' (context: type eval line 23 cmd {assert_range [expr $end-$start] 1000 1100} proc ::test) *** [err]: BLPOP unblock but the key is expired and then block again - reprocessing command in tests/unit/type/list.tcl Expected '1101' to be between to '1000' and '1100' (context: type eval line 23 cmd {assert_range [expr $end-$start] 1000 1100} proc ::test) *** [err]: BZPOPMIN unblock but the key is expired and then block again - reprocessing command in tests/unit/type/zset.tcl Expected '1103' to be between to '1000' and '1100' (context: type eval line 23 cmd {assert_range [expr $end-$start] 1000 1100} proc ::test) ``` Increase the range to avoid failures, and improve the comment to be clearer. tests was introduced in redis#13004. (cherry picked from commit 32f44da)

…13004) In #11012, we will reprocess command when client is unblocked on keys, in some blocking commands, for example, in the XREADGROUP BLOCK scenario, because of the re-processing command, we will recalculate the block timeout, causing the blocking time to be reset. This commit add a new CLIENT_REPROCESSING_COMMAND clent flag, explicitly let the command know that it is being re-processed, later in blockForKeys we will not reset the timeout. Affected BLOCK cases: - list / zset / stream, added test cases for each. Unaffected cases: - module (never re-process the commands). - WAIT / WAITAOF (never re-process the commands). Fixes #12998. (cherry picked from commit 492021d)

This was introduced in #13004, missing this assignment. It causes timeout to be a random value (may be less than now), and then in `Unblock by timer` test, the client is unblocked and then it call timeout_callback, since the callback is NULL, the server will crash. The crash stack is: ``` beforesleep handleBlockedClientsTimeout checkBlockedClientTimeout unblockClientOnTimeout replyToBlockedClientTimedOut moduleBlockedClientTimedOut -- the timeout_callback is NULL, invalidFunctionWasCalled bc->timeout_callback(&ctx,(void**)c->argv,c->argc); ``` (cherry picked from commit 45a35a7)

…ues (#13053) These tests have all failed in daily CI: ``` *** [err]: Blocking XREADGROUP for stream key that has clients blocked on stream - reprocessing command in tests/unit/type/stream-cgroups.tcl Expected '1101' to be between to '1000' and '1100' (context: type eval line 23 cmd {assert_range [expr $end-$start] 1000 1100} proc ::test) *** [err]: BLPOP unblock but the key is expired and then block again - reprocessing command in tests/unit/type/list.tcl Expected '1101' to be between to '1000' and '1100' (context: type eval line 23 cmd {assert_range [expr $end-$start] 1000 1100} proc ::test) *** [err]: BZPOPMIN unblock but the key is expired and then block again - reprocessing command in tests/unit/type/zset.tcl Expected '1103' to be between to '1000' and '1100' (context: type eval line 23 cmd {assert_range [expr $end-$start] 1000 1100} proc ::test) ``` Increase the range to avoid failures, and improve the comment to be clearer. tests was introduced in #13004. (cherry picked from commit 32f44da)

…edis#13004) In redis#11012, we will reprocess command when client is unblocked on keys, in some blocking commands, for example, in the XREADGROUP BLOCK scenario, because of the re-processing command, we will recalculate the block timeout, causing the blocking time to be reset. This commit add a new CLIENT_REPROCESSING_COMMAND clent flag, explicitly let the command know that it is being re-processed, later in blockForKeys we will not reset the timeout. Affected BLOCK cases: - list / zset / stream, added test cases for each. Unaffected cases: - module (never re-process the commands). - WAIT / WAITAOF (never re-process the commands). Fixes redis#12998.

This was introduced in redis#13004, missing this assignment. It causes timeout to be a random value (may be less than now), and then in `Unblock by timer` test, the client is unblocked and then it call timeout_callback, since the callback is NULL, the server will crash. The crash stack is: ``` beforesleep handleBlockedClientsTimeout checkBlockedClientTimeout unblockClientOnTimeout replyToBlockedClientTimedOut moduleBlockedClientTimedOut -- the timeout_callback is NULL, invalidFunctionWasCalled bc->timeout_callback(&ctx,(void**)c->argv,c->argc); ```

…ues (redis#13053) These tests have all failed in daily CI: ``` *** [err]: Blocking XREADGROUP for stream key that has clients blocked on stream - reprocessing command in tests/unit/type/stream-cgroups.tcl Expected '1101' to be between to '1000' and '1100' (context: type eval line 23 cmd {assert_range [expr $end-$start] 1000 1100} proc ::test) *** [err]: BLPOP unblock but the key is expired and then block again - reprocessing command in tests/unit/type/list.tcl Expected '1101' to be between to '1000' and '1100' (context: type eval line 23 cmd {assert_range [expr $end-$start] 1000 1100} proc ::test) *** [err]: BZPOPMIN unblock but the key is expired and then block again - reprocessing command in tests/unit/type/zset.tcl Expected '1103' to be between to '1000' and '1100' (context: type eval line 23 cmd {assert_range [expr $end-$start] 1000 1100} proc ::test) ``` Increase the range to avoid failures, and improve the comment to be clearer. tests was introduced in redis#13004.

enjoy-binbin requested a review from oranagra January 29, 2024 08:44

oranagra reviewed Jan 29, 2024

View reviewed changes

src/server.c Outdated Show resolved Hide resolved

code review

8da5453

enjoy-binbin changed the title ~~Fix XREADGROUP BLOCK timeout is reset due to re-processing command~~ Fix blocking commands timeout is reset due to re-processing command Jan 29, 2024

oranagra approved these changes Jan 29, 2024

View reviewed changes

Pass the timeout parameter to blockForKeys without directly assigning…

1013142

… a value to c->bstate.timeout

oranagra merged commit 492021d into redis:unstable Jan 30, 2024

oranagra added the release-notes indication that this issue needs to be mentioned in the release notes label Jan 30, 2024

enjoy-binbin deleted the fix_xreadgroup_reprocessing branch January 30, 2024 09:36

enjoy-binbin mentioned this pull request Jan 30, 2024

Fix timeout not being set in module blockClient case #13011

Merged

enjoy-binbin mentioned this pull request Feb 15, 2024

Increase tolerance range to block reprocess tests to avoid timing issues #13053

Merged

YaacovHazan mentioned this pull request May 16, 2024

Release Redis 7.2.5 #13272

Merged

alschastny mentioned this pull request Jul 19, 2024

XReadGroup sometimes returns an i/o timeout error when no message is read redis/go-redis#2963

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

Fix blocking commands timeout is reset due to re-processing command #13004

Fix blocking commands timeout is reset due to re-processing command #13004

Uh oh!

enjoy-binbin commented Jan 29, 2024 •

edited

Loading

Uh oh!

enjoy-binbin commented Jan 29, 2024

Uh oh!

oranagra commented Jan 29, 2024

Uh oh!

oranagra left a comment

Uh oh!

Uh oh!

enjoy-binbin commented Jan 29, 2024

Uh oh!

oranagra commented Jan 29, 2024

Uh oh!

enjoy-binbin commented Jan 30, 2024

Uh oh!

oranagra commented Jan 30, 2024

Uh oh!

enjoy-binbin commented Jan 30, 2024

Uh oh!

enjoy-binbin commented Jan 30, 2024 •

edited

Loading

Uh oh!

oranagra commented Jan 30, 2024

Uh oh!

enjoy-binbin commented Jan 30, 2024

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

2 participants

Fix blocking commands timeout is reset due to re-processing command #13004

Fix blocking commands timeout is reset due to re-processing command #13004

Uh oh!

Conversation

enjoy-binbin commented Jan 29, 2024 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

enjoy-binbin commented Jan 29, 2024

Uh oh!

oranagra commented Jan 29, 2024

Uh oh!

oranagra left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

enjoy-binbin commented Jan 29, 2024

Uh oh!

oranagra commented Jan 29, 2024

Uh oh!

enjoy-binbin commented Jan 30, 2024

Uh oh!

oranagra commented Jan 30, 2024

Uh oh!

enjoy-binbin commented Jan 30, 2024

Uh oh!

enjoy-binbin commented Jan 30, 2024 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

oranagra commented Jan 30, 2024

Uh oh!

enjoy-binbin commented Jan 30, 2024

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

2 participants

enjoy-binbin commented Jan 29, 2024 •

edited

Loading

enjoy-binbin commented Jan 30, 2024 •

edited

Loading