XACK not removing from pending list

[kevinhatry]

Describe the bug
After calling XACK on a stream the message still shows up in the pending list.

Tested on keydb v5.3.3 and v6.0.16 with active replica.

edit: see updated test procedure in comment #238 (comment)

---

** Log Files **

127.0.0.1:6379> XPENDING reached_limits prov_reached_limits - + 10

1. 1. "1601371253314-0"
   2. "provreachedlimitsTask"
   3. (integer) 14288902
   4. (integer) 1
2. 1. "1601376154730-0"
   2. "provreachedlimitsTask"
   3. (integer) 9387420
   4. (integer) 1

127.0.0.1:6379> XACK reached_limits prov_reached_limits 1601371253314-0
(integer) 1

127.0.0.1:6379> XPENDING reached_limits prov_reached_limits - + 10

1. 1. "1601371253314-0"
   2. "provreachedlimitsTask"
   3. (integer) 15472971
   4. (integer) 1
2. 1. "1601376154730-0"
   2. "provreachedlimitsTask"
   3. (integer) 10571489
   4. (integer) 1

[kevinhatry]

Two additional info : the server is configured as a (active) replica of another server.

After restarting one of the replica (the least active one), the ACK started working again (from one server or the other).

[kevinhatry]

Another update : after a few minutes the problem appeared again : a pending message could not be acked (on either of the servers).
After a restart of the other replica the ACK worked (for how long though ???).

[kevinhatry]

If it can help, during the time when the ACK problem occurs these messages appears frequently (and are not present when it works) :
Sep 30 15:22:35 keydb-01b keydb-server[28210]: 28210:28215:S 30 Sep 2020 15:22:35.833 * Starting automatic rewriting of AOF on 100% growth
Sep 30 15:22:35 keydb-01b keydb-server[28210]: 28210:28215:S 30 Sep 2020 15:22:35.838 * Background append only file rewriting started by pid 25935
Sep 30 15:22:37 keydb-01b keydb-server[28210]: 28210:28215:S 30 Sep 2020 15:22:37.576 * AOF rewrite child asks to stop sending diffs.
Sep 30 15:22:37 keydb-01b keydb-server[28210]: 25935:28215:C 30 Sep 2020 15:22:37.576 * Parent agreed to stop sending diffs. Finalizing AOF...
Sep 30 15:22:37 keydb-01b keydb-server[28210]: 25935:28215:C 30 Sep 2020 15:22:37.576 * Concatenating 5.05 MB of AOF diff received from parent.
Sep 30 15:22:37 keydb-01b keydb-server[28210]: 25935:28215:C 30 Sep 2020 15:22:37.639 * SYNC append only file rewrite performed
Sep 30 15:22:37 keydb-01b keydb-server[28210]: 25935:28215:C 30 Sep 2020 15:22:37.644 * AOF rewrite: 11 MB of memory used by copy-on-write
Sep 30 15:22:37 keydb-01b keydb-server[28210]: 28210:28215:S 30 Sep 2020 15:22:37.739 * Background AOF rewrite terminated with success
Sep 30 15:22:37 keydb-01b keydb-server[28210]: 28210:28215:S 30 Sep 2020 15:22:37.739 * Residual parent diff successfully flushed to the rewritten AOF (0.69 MB)
Sep 30 15:22:37 keydb-01b keydb-server[28210]: 28210:28215:S 30 Sep 2020 15:22:37.739 * Background AOF rewrite finished successfully

[kevinhatry]

We reproduced the problem with a fresh setup and 2 versions of keydb :

1. install keydb v5.3.3 or v6.0.16 on one machine
2. install the same keydb version on a second machine
3. setup active replica between them (see configuration file keydb.conf.txt)
4. play the following command on the cli for either of the machine

XGROUP CREATE bug_test_stream bug_test_stream_group 0 MKSTREAM
XADD bug_test_stream * testing 123
XREADGROUP COUNT 1 GROUP bug_test_stream_group test_consumer STREAMS bug_test_stream >
XINFO CONSUMERS bug_test_stream bug_test_stream_group
XACK bug_test_stream bug_test_stream_group XXXX
XPENDING bug_test_stream bug_test_stream_group - + 10

where XXXX is the message id given by the XADD command.
The XINFO step shows one pending message which is normal at that stage.
The XPENDING step still shows the pending message which should have been acknowledged before.

The output from my test run is in output.txt
output.txt

---

keydb.conf.txt

[JohnSully]

Thanks for the specific repro @kevinhatry

I'm in the process of completing the Redis 6.0.8 merge, once that is complete I'll take a look. Its possible we inherited this from Redis since we haven't done any KeyDB specific changes to streams lately.

[JohnSully]

OK I see this is Active Replica specific and I can repro. I'll investigate further.

[JohnSully]

@kevinhatry Its worse than just a failure to remove the item, the servers are actually bouncing back XCLAIM commands in a loop.

[JohnSully]

Change a41366c is pushed to unstable which appears to resolve the issue. I would like to do a bit more testing, and I certainly would love your feedback if you have a chance to try it.

[kevinhatry]

@JohnSully thanks for providing a candidate fix this quickly.

I have tested the unstable branch and the problem is gone. ACKs are working as expected.
I even tried sending reads and acks to different servers and everything is replicated as expected on both servers.

I will test the v5.3.3 with only the commit a41366c applied to make sure it is sufficient in itself.

As a side note, in the README.md file :

• a dependency is missing: pkg-config.
• it could be clearer that the custom install command make PREFIX=/some/other/directory install will in fact install the binaries in a /some/other/directory/bin, so using make PREFIX=/usr/bin install in fact install the binaries in /usr/bin/bin

[kevinhatry]

v5.3.3 with a cherry-pick of commit a41366c also works as expected.

[JohnSully]

Closing as fixed. It will be out in the next version along with Redis 6.0.8 changes I merged.

Its a trivial backport so should work on any build it compiles with. Thats the safer way to go as unstable is under flux at the moment.