== CRITICAL ==

[Talkabout]

Hi guys,

I have checked the system log of both keydb servers I am running (active replica) and they are giving me the following error multiple times per minute:

== CRITICAL == This replica is sending an error to its master: 'unknown command 304769, with args beginning with: ' after processing the command ''

what exactly does that mean?

Thanks!

Bye

[JohnSully]

Odd,

Are you mixing KeyDB versions or replicating with Redis? Unfortunately the error message is not very illuminating, I’ll make it more verbose in a future version.

It would be helpful if you could give the output of the monitor command around the time you see this message. The missing piece is the command the replica is sending.

[Talkabout]

Hi @JohnSully ,

same KeyDB version, no Redis.

The error message is coming multiple times per minute, so shouldn't be a problem to get more information. What exact command do I need to execute? Simply "MONITOR" on keydb-cli?

Bye

[JohnSully]

You can run it like this:
./keydb-cli -h 127.0.0.1 -p 6379 monitor > out.txt
Change the IP and port as necessary, it should be of the replica showing the error.

once you have some data captured we can filter out uninteresting traffic with
grep "[IP of master]" out.txt > filter.txt
e.g.
grep "127.0.0.1" out.txt > filter.txt

Then it's just a matter of matching the timeframes. The monitor command outputs timestamps in unix time, while the KeyDB log will show time in normally. You can translate back and forth with this: https://www.unixtimestamp.com/index.php

e.g. 1582154414.789113 is 02/19/2020 @ 11:20pm (UTC)

[Antiarchitect]

Having similar issue:

1:S 02 Mar 2020 13:57:46.769 # == CRITICAL == This replica is sending an error to its master: 'EXEC without MULTI' after processing the command 'exec'
1:S 02 Mar 2020 13:57:46.827 # == CRITICAL == This replica is sending an error to its master: 'MULTI calls can not be nested' after processing the command 'multi'
1:S 02 Mar 2020 13:57:46.828 # == CRITICAL == This replica is sending an error to its master: 'EXEC without MULTI' after processing the command 'exec'
1:S 02 Mar 2020 13:57:48.801 # == CRITICAL == This replica is sending an error to its master: 'EXEC without MULTI' after processing the command 'exec'
1:S 02 Mar 2020 13:57:48.801 # == CRITICAL == This replica is sending an error to its master: 'MULTI calls can not be nested' after processing the command 'multi'
1:S 02 Mar 2020 13:57:48.853 # == CRITICAL == This replica is sending an error to its master: 'MULTI calls can not be nested' after processing the command 'multi'
1:S 02 Mar 2020 13:57:48.853 # == CRITICAL == This replica is sending an error to its master: 'EXEC without MULTI' after processing the command 'exec'
1:S 02 Mar 2020 13:58:08.462 # == CRITICAL == This replica is sending an error to its master: 'MULTI calls can not be nested' after processing the command 'multi'
1:S 02 Mar 2020 13:58:08.462 # == CRITICAL == This replica is sending an error to its master: 'EXEC without MULTI' after processing the command 'exec'
1:S 02 Mar 2020 13:58:08.563 # == CRITICAL == This replica is sending an error to its master: 'EXEC without MULTI' after processing the command 'exec'
1:S 02 Mar 2020 13:58:08.790 # == CRITICAL == This replica is sending an error to its master: 'MULTI calls can not be nested' after processing the command 'multi'
1:S 02 Mar 2020 13:58:08.791 # == CRITICAL == This replica is sending an error to its master: 'EXEC without MULTI' after processing the command 'exec'
1:S 02 Mar 2020 13:58:18.771 # == CRITICAL == This replica is sending an error to its master: 'MULTI calls can not be nested' after processing the command 'multi'
1:S 02 Mar 2020 13:58:18.771 # == CRITICAL == This replica is sending an error to its master: 'EXEC without MULTI' after processing the command 'exec'

[JohnSully]

Thank you! I've reworked the way transactions are handled during active replication in v5.3.2 (just released). It would be good if you could give that a try as I think it will resolve your issue.

[Talkabout]

Hi @JohnSully ,

both issues or only one of them? The error messages are similar but not same.

Bye

[JohnSully]

Hi @Talkabout

I'm less certain it will fix your issue (although it still may). If you get a chance to pass on the monitor output from around the time it repros that would be helpful in letting me better understand what's causing the error your seeing.

[Antiarchitect]

Thank you! I've reworked the way transactions are handled during active replication in v5.3.2 (just released). It would be good if you could give that a try as I think it will resolve your issue.

Actually I'm still experiencing this in eqalpha/keydb:x86_64_v5.3.2. When I've fixed my replication in the chart - there less records than before. But messages are still present. I'm using KeyDB multi-master in the Sentry chart (maybe bad code?). If I can help you with my logs or debug - please tell me what to do. With redis-ha chart (master-slave) - there were no errors of this kind - I've checked old logs.

[JohnSully]

@Antiarchitect @Talkabout

I appreciate your help with tracking this down. The best way forward will be for me to update the logging to give me more information. That way you won’t have to mess with monitor or other logs.

I will update this bug when the new logging is added.

[Antiarchitect]

Got it!

[JohnSully]

@Antiarchitect @Talkabout

I've added extra logging, primarily around what exactly is in the query buffer when the error occurs. The docker images have been updated and the v5.3.2 tag has also been modified to include this change. I did not bump the version as it's only a logging change and 5.3.2 was just released.

[Antiarchitect]

Will try to update today

[Antiarchitect]

7:S 05 Mar 2020 16:21:35.511 # == CRITICAL == This replica is sending an error to its master: 'EXEC without MULTI' after processing the command 'exec'
7:S 05 Mar 2020 16:21:35.511 #  querybuf: *1\r\n$4\r\nEXEC\r\n
7:S 05 Mar 2020 16:21:35.511 # == CRITICAL == This replica is sending an error to its master: 'Error in rreplay command, please check logs' after processing the command 'rreplay'
7:S 05 Mar 2020 16:21:35.511 #  querybuf: $1\r\n0\r\n$19\r\n1660341762582908496\r\n*5\r\n$7\r\nRREPLAY\r\n$36\r\n12f895d6-ed18-4acd-96fd-0f018402e3e0\r\n$14\r\n*1\r\n$4\r\nEXEC\r\n\r\n$1\r\n0\r\n$19\r\n1660341762582908497\r\n
7:S 05 Mar 2020 16:21:43.201 # == CRITICAL == This replica is sending an error to its master: 'EXEC without MULTI' after processing the command 'exec'
7:S 05 Mar 2020 16:21:43.201 #  querybuf: *1\r\n$4\r\nEXEC\r\n
7:S 05 Mar 2020 16:21:43.201 # == CRITICAL == This replica is sending an error to its master: 'Error in rreplay command, please check logs' after processing the command 'rreplay'
7:S 05 Mar 2020 16:21:43.201 #  querybuf: *5\r\n$7\r\nRREPLAY\r\n$36\r\n12f895d6-ed18-4acd-96fd-0f018402e3e0\r\n$15\r\n*1\r\n$5\r\nMULTI\r\n\r\n$1\r\n0\r\n$19\r\n1660341770705174999\r\n*5\r\n$7\r\nRREPLAY\r\n$36\r\n12f895d6-ed18-4acd-96fd-0f018402e3e0\r\n$77\r\n*3\r\n$4\r\nZREM\r\n$13\r\nunacked_index\r\n$36\r\n7a5a8d38-a30f-487e-9b39-5d9537ab195f\r\n\r\n$1\r\n0\r\n$19\r\n1660341770705175000\r\n*5\r\n$7\r\nRREPLAY\r\n$36\r\n12f895d6-ed18-4acd-96fd-0f018402e3e0\r\n$70\r\n*3\r\n$4\r\nHDEL\r\n$7\r\nunacked\r\n$36\r\n7a5a8d38-a30f-487e-9b39-5d9537ab195f\r\n\r\n$1\r\n0\r\n$19\r\n1660341770705175001\r\n*5\r\n$7\r\nRREPLAY\r\n$36\r\n12f895d6-ed18-4acd-96fd-0f018402e3e0\r\n$14\r\n*1\r\n$4\r\nEXEC\r\n\r\n$1\r\n0\r\n$19\r\n1660341770705175002\r\n*5\r\n$7\r\nRREPLAY\r\n$36\r\n12f895d6-ed18-4acd-96fd-0f018402e3e0\r\n$211\r\n*5\r\n$7\r\nRREPLAY\r\n$36\r\n9448dfc0-b041-4590-be50-452a66132f44\r\n$110\r\n*6\r\n$3\r\nSET\r\n$59\r\nl:b:k:sentry.grouptagvalue:df0c23da3fd89dd39342dfed00efd40d\r\n$1\r\n1\r\n$2\r\nEX\r\n$2\r\n10\r\n$2\r\nNX\r\n\r\n$1\r\n0\r\n$
7:S 05 Mar 2020 16:21:46.968 # == CRITICAL == This replica is sending an error to its master: 'EXEC without MULTI' after processing the command 'exec'
7:S 05 Mar 2020 16:21:46.968 #  querybuf: *1\r\n$4\r\nEXEC\r\n
7:S 05 Mar 2020 16:21:46.968 # == CRITICAL == This replica is sending an error to its master: 'Error in rreplay command, please check logs' after processing the command 'rreplay'
7:S 05 Mar 2020 16:21:46.968 #  querybuf: *5\r\n$7\r\nRREPLAY\r\n$36\r\n12f895d6-ed18-4acd-96fd-0f018402e3e0\r\n$15\r\n*1\r\n$5\r\nMULTI\r\n\r\n$1\r\n0\r\n$19\r\n1660341774621606332\r\n*5\r\n$7\r\nRREPLAY\r\n$36\r\n12f895d6-ed18-4acd-96fd-0f018402e3e0\r\n$101\r\n*4\r\n$4\r\nZADD\r\n$13\r\nunacked_index\r\n$17\r\n1583425306.965817\r\n$36\r\na270f227-aa34-46cd-805e-6cc462000058\r\n\r\n$1\r\n0\r\n$19\r\n1660341774621606333\r\n*5\r\n$7\r\nRREPLAY\r\n$36\r\n12f895d6-ed18-4acd-96fd-0f018402e3e0\r\n$10648\r\n*4\r\n$4\r\nHSET\r\n$7\r\nunacked\r\n$36\r\na270f227-aa34-46cd-805e-6cc462000058\r\n$10568\r\n[{"body": "gAJ9cQEoVQdleHBpcmVzcQJOVQN1dGNxA4hVBGFyZ3NxBF1xBVUFY2hvcmRxBk5VCWNhbGxiYWNrc3EHTlUIZXJyYmFja3NxCE5VB3Rhc2tzZXRxCU5VAmlkcQpVJGU3ZjJlODViLWI5NDItNGU2MC05ZmZjLWNmZmJhNmI5MTJmZnELVQdyZXRyaWVzcQxLAFUEdGFza3ENVSxzZW50cnkudGFza3MucG9zdF9wcm9jZXNzLnBvc3RfcHJvY2Vzc19ncm91cHEOVQl0aW1lbGltaXRxD05OhlUDZXRhcRBOVQZrd2FyZ3NxEX1xEihVGGlzX25ld19ncm91cF9lbnZpcm9ubWVudHETiVUGaXNfbmV3cRSJVQVldmVudHEVY2RqYW5nby5kYi5tb2RlbHMuYmFzZQptb2RlbF91bnBpY2tsZQpxFlUGc2

KeyDB is used by Sentry 9.1.2 as TSDB and cache in multi-master mode and consists of the 3 master nodes. I've turned off multithreading (server-threads 1) for more clear results.

[JohnSully]

Awesome that is super helpful! I’ll get back to you in a bit.

[ekexcello]

Hello.
Just got similar issue. We have a multimaster cluster of 3x KeyDB instances. After updating one node from 5.3.1 to 5.3.2 log on that node was flooded with error messages:

@400000005e6b6d1524a8162c 9854:S 13 Mar 2020 12:22:51.614 # == CRITICAL == This replica is sending an error to its master: 'Error in rreplay command, please check logs' after processing the command 'rreplay'
@400000005e6b6d1524a81a14 9854:S 13 Mar 2020 12:22:51.614 #     querybuf: *5\r\n$7\r\nRREPLAY\r\n$36\r\nc8326dfb-09b3-4dfa-84b0-d3dd998797f0\r\n$116\r\n*5\r\n$7\r\nRREPLAY\r\n$36\r\n710aaaf2-bf96-4293-b49c-c05a791d6953\r\n$15\r\n*1\r\n$5\r\nMULTI\r\n\r\n$2\r\n13\r\n$19\r\n1661047743783\r\n\r\n$2\r\n13\r\n$19\r\n1661047743729106983\r\n*5\r\n$7\r\nRREPLAY\r\n$36\r\nc8326dfb-09b3-4dfa-84b0-d3dd998797f0\r\n$220\r\n*5\r\n$7\r\nRREPLAY\r\n$36\r\n710aaaf2-bf96-4293-b49c-c05a791d6953\r\n$118\r\n*3\r\n$4\r\nSADD\r\n$24\r\nNette.Journal:10925:keys\r\n$66\r\nNette.Storage:collections.apiKeys:63ea0716ca***********ccb271e43161a5\r\n\r\n$2\r\n13\r\n$19\r\n1661047743783\r\n\r\n$2\r\n13\r\n$19\r\n1661047743729106985\r\n*5\r\n$7\r\nRREPLAY\r\n$36\r\nc8326dfb-09b3-4dfa-84b0-d3dd998797f0\r\n$219\r\n*5\r\n$7\r\nRREPLAY\r\n$36\r\n710aaaf2-bf96-4293-b49c-c05a791d6953\r\n$117\r\n*3\r\n$4\r\nSADD\r\n$85\r\nNette.Journal:Nette.Storage:collections.apiKeys:63ea0716ca***********ccb271e43161a5:tags\r\n$5\r\n10925\r\n\r\n$2\r\n13\r\n$19\r\n1661047743783\r\n\r\n$2\r\n13\r\n$19\r\n16610477
@400000005e6b6d1524a8450c 9854:S 13 Mar 2020 12:22:51.614 # == CRITICAL == This replica is sending an error to its master: 'Error in rreplay command, please check logs' after processing the command 'rreplay'
@400000005e6b6d1524a848f4 9854:S 13 Mar 2020 12:22:51.614 #     querybuf: *5\r\n$7\r\nRREPLAY\r\n$36\r\nc8326dfb-09b3-4dfa-84b0-d3dd998797f0\r\n$116\r\n*5\r\n$7\r\nRREPLAY\r\n$36\r\n710aaaf2-bf96-4293-b49c-c05a791d6953\r\n$15\r\n*1\r\n$5\r\nMULTI\r\n\r\n$2\r\n13\r\n$19\r\n1661047743783\r\n\r\n$2\r\n13\r\n$19\r\n1661047743729106983\r\n*5\r\n$7\r\nRREPLAY\r\n$36\r\nc8326dfb-09b3-4dfa-84b0-d3dd998797f0\r\n$220\r\n*5\r\n$7\r\nRREPLAY\r\n$36\r\n710aaaf2-bf96-4293-b49c-c05a791d6953\r\n$118\r\n*3\r\n$4\r\nSADD\r\n$24\r\nNette.Journal:10925:keys\r\n$66\r\nNette.Storage:collections.apiKeys:63ea0716ca***********ccb271e43161a5\r\n\r\n$2\r\n13\r\n$19\r\n1661047743783\r\n\r\n$2\r\n13\r\n$19\r\n1661047743729106985\r\n*5\r\n$7\r\nRREPLAY\r\n$36\r\nc8326dfb-09b3-4dfa-84b0-d3dd998797f0\r\n$219\r\n*5\r\n$7\r\nRREPLAY\r\n$36\r\n710aaaf2-bf96-4293-b49c-c05a791d6953\r\n$117\r\n*3\r\n$4\r\nSADD\r\n$85\r\nNette.Journal:Nette.Storage:collections.apiKeys:63ea0716ca***********ccb271e43161a5:tags\r\n$5\r\n10925\r\n\r\n$2\r\n13\r\n$19\r\n1661047743783\r\n\r\n$2\r\n13\r\n$19\r\n16610477
@400000005e6b6d1524a873ec 9854:S 13 Mar 2020 12:22:51.614 # == CRITICAL == This replica is sending an error to its master: 'Error in rreplay command, please check logs' after processing the command 'rreplay'
@400000005e6b6d1524a877d4 9854:S 13 Mar 2020 12:22:51.614 #     querybuf: *5\r\n$7\r\nRREPLAY\r\n$36\r\nc8326dfb-09b3-4dfa-84b0-d3dd998797f0\r\n$116\r\n*5\r\n$7\r\nRREPLAY\r\n$36\r\n710aaaf2-bf96-4293-b49c-c05a791d6953\r\n$15\r\n*1\r\n$5\r\nMULTI\r\n\r\n$2\r\n13\r\n$19\r\n1661047743783\r\n\r\n$2\r\n13\r\n$19\r\n1661047743729106983\r\n*5\r\n$7\r\nRREPLAY\r\n$36\r\nc8326dfb-09b3-4dfa-84b0-d3dd998797f0\r\n$220\r\n*5\r\n$7\r\nRREPLAY\r\n$36\r\n710aaaf2-bf96-4293-b49c-c05a791d6953\r\n$118\r\n*3\r\n$4\r\nSADD\r\n$24\r\nNette.Journal:10925:keys\r\n$66\r\nNette.Storage:collections.apiKeys:63ea0716ca***********ccb271e43161a5\r\n\r\n$2\r\n13\r\n$19\r\n1661047743783\r\n\r\n$2\r\n13\r\n$19\r\n1661047743729106985\r\n*5\r\n$7\r\nRREPLAY\r\n$36\r\nc8326dfb-09b3-4dfa-84b0-d3dd998797f0\r\n$219\r\n*5\r\n$7\r\nRREPLAY\r\n$36\r\n710aaaf2-bf96-4293-b49c-c05a791d6953\r\n$117\r\n*3\r\n$4\r\nSADD\r\n$85\r\nNette.Journal:Nette.Storage:collections.apiKeys:63ea0716ca***********ccb271e43161a5:tags\r\n$5\r\n10925\r\n\r\n$2\r\n13\r\n$19\r\n1661047743783\r\n\r\n$2\r\n13\r\n$19\r\n16610477
@400000005e6b6d1524a89714 9854:S 13 Mar 2020 12:22:51.614 # == CRITICAL == This replica is sending an error to its master: 'Error in rreplay command, please check logs' after processing the command 'rreplay'
@400000005e6b6d1524a89afc 9854:S 13 Mar 2020 12:22:51.614 #     querybuf: *5\r\n$7\r\nRREPLAY\r\n$36\r\nc8326dfb-09b3-4dfa-84b0-d3dd998797f0\r\n$991\r\n*5\r\n$7\r\nRREPLAY\r\n$36\r\n710aaaf2-bf96-4293-b49c-c05a791d6953\r\n$889\r\n*4\r\n$5\r\nSETEX\r\n$66\r\nNette.Storage:collections.apiKeys:63ea0716ca***********ccb271e43161a5\r\n$3\r\n600\r\n$784\r\n{"time":"0.60415300 1584098571","expire":1584099171,"serialized":true}

Attempt to upgrade second node rendered into same situation on two nodes.
An interesting option is that older version logged no issues and update of standalone instance also went well. However, we have had to roll back to 5.3.1 as it's not clear whether cluster of 5.3.2 will pick up dump of 5.3.1 and will be operational.