Hardly Stuck on Challange #YG$

ProgMastermind · July 30, 2024, 7:58pm

I’m doing the challenge 13 , I 've tried everything but my commands are not propogating from master to replica, but the redis-cli clients commands are going to replica , since the set commands are not travelling the state is not updating, the get commands are getting wrong response, can you tell me where i am going wrong

these are the logs

tester::#YG4] [handshake] master: Waiting for replica to initiate handshake with "PING" command
[your_program] Socket state before handshake: [recv_oct: 0, recv_cnt: 0, recv_max: 0, recv_avg: 0, recv_dvi: 0, send_oct: 0, send_cnt: 0, send_max: 0, send_avg: 0, send_pend: 0]
[tester::#YG4] [handshake] master: Received bytes: "*1\r\n$4\r\nPING\r\n"
[tester::#YG4] [handshake] master: Received RESP array: ["PING"]
[tester::#YG4] [handshake] Received ["PING"]
[tester::#YG4] [handshake] master: Sent "PONG"
[tester::#YG4] [handshake] master: Sent bytes: "+PONG\r\n"
[tester::#YG4] [handshake] master: Waiting for replica to send "REPLCONF listening-port 6380" command
[tester::#YG4] [handshake] master: Received bytes: "*3\r\n$8\r\nREPLCONF\r\n$14\r\nlistening-port\r\n$4\r\n6380\r\n"
[tester::#YG4] [handshake] master: Received RESP array: ["REPLCONF", "listening-port", "6380"]
[tester::#YG4] [handshake] Received ["REPLCONF", "listening-port", "6380"]
[tester::#YG4] [handshake] master: Sent "OK"
[tester::#YG4] [handshake] master: Sent bytes: "+OK\r\n"
[tester::#YG4] [handshake] master: Waiting for replica to send "REPLCONF capa" command
[tester::#YG4] [handshake] master: Received bytes: "*3\r\n$8\r\nREPLCONF\r\n$4\r\ncapa\r\n$6\r\npsync2\r\n"
[tester::#YG4] [handshake] master: Received RESP array: ["REPLCONF", "capa", "psync2"]
[tester::#YG4] [handshake] Received ["REPLCONF", "capa", "psync2"]
[tester::#YG4] [handshake] master: Sent "OK"
[tester::#YG4] [handshake] master: Sent bytes: "+OK\r\n"
[tester::#YG4] [handshake] master: Waiting for replica to send "PSYNC" command
[tester::#YG4] [handshake] master: Received bytes: "*3\r\n$5\r\nPSYNC\r\n$1\r\n?\r\n$2\r\n-1\r\n"
[tester::#YG4] [handshake] master: Received RESP array: ["PSYNC", "?", "-1"]
[tester::#YG4] [handshake] Received ["PSYNC", "?", "-1"]
[tester::#YG4] [handshake] master: Sent "FULLRESYNC 75cd7bc10c49047e0d163660f3b90625b1af31dc 0"
[tester::#YG4] [handshake] master: Sent bytes: "+FULLRESYNC 75cd7bc10c49047e0d163660f3b90625b1af31dc 0\r\n"
[tester::#YG4] [handshake] Sending RDB file...
[tester::#YG4] [handshake] master: Sent bytes: "$88\r\nREDIS0011\xfa\tredis-ver\x057.2.0\xfa\nredis-bits\xc0@\xfa\x05ctime\xc2m\b\xbce\xfa\bused-mem°\xc4\x10\x00\xfa\baof-base\xc0\x00\xff\xf0n;\xfe\xc0\xffZ\xa2"
[tester::#YG4] [handshake] Sent RDB file.
[tester::#YG4] [propagation] master: > SET foo 123
[tester::#YG4] [propagation] master: Sent bytes: "*3\r\n$3\r\nSET\r\n$3\r\nfoo\r\n$3\r\n123\r\n"
[tester::#YG4] [propagation] master: > SET bar 456
[tester::#YG4] [propagation] master: Sent bytes: "*3\r\n$3\r\nSET\r\n$3\r\nbar\r\n$3\r\n456\r\n"
[tester::#YG4] [propagation] master: > SET baz 789
[tester::#YG4] [propagation] master: Sent bytes: "*3\r\n$3\r\nSET\r\n$3\r\nbaz\r\n$3\r\n789\r\n"
[tester::#YG4] [test] Getting key foo
[tester::#YG4] [test] client: $ redis-cli GET foo
[tester::#YG4] [test] client: Sent bytes: "*2\r\n$3\r\nGET\r\n$3\r\nfoo\r\n"
[your_program] Connection check: {127, 0, 0, 1}:54276 - Is master? false
[your_program] Socket state after handshake: [recv_oct: 259, recv_cnt: 4, recv_max: 242, recv_avg: 64, recv_dvi: 43, send_oct: 133, send_cnt: 4, send_max: 49, send_avg: 33, send_pend: 0]
[your_program] Handling as client connection
[your_program] Handshake completed successfully
[your_program] Connection check: {127, 0, 0, 1}:6379 - Is master? true
[your_program] Handling as master connection
[your_program] Socket active mode: [active: true]
[your_program] Received command: "*2\r\n$3\r\nGET\r\n$3\r\nfoo\r\n"
[your_program] Started listening for master commands
[your_program] Parsed data: ["GET", "foo"]
[your_program] Executing GET command for key: foo
[tester::#YG4] [test] client: Received bytes: "$-1\r\n"
[tester::#YG4] [test] client: Received RESP null bulk string: "$-1\r\n"
[tester::#YG4] [test] Retrying... (1/5 attempts)
[tester::#YG4] [test] client: > GET foo
[tester::#YG4] [test] client: Sent bytes: "*2\r\n$3\r\nGET\r\n$3\r\nfoo\r\n"
[your_program] Received command: "*2\r\n$3\r\nGET\r\n$3\r\nfoo\r\n"
[your_program] Parsed data: ["GET", "foo"]
[your_program] Executing GET command for key: foo
[tester::#YG4] [test] client: Received bytes: "$-1\r\n"
[tester::#YG4] [test] client: Received RESP null bulk string: "$-1\r\n"
[tester::#YG4] [test] Retrying... (2/5 attempts)
[tester::#YG4] [test] client: > GET foo
[tester::#YG4] [test] client: Sent bytes: "*2\r\n$3\r\nGET\r\n$3\r\nfoo\r\n"
[your_program] Received command: "*2\r\n$3\r\nGET\r\n$3\r\nfoo\r\n"
[your_program] Parsed data: ["GET", "foo"]
[your_program] Executing GET command for key: foo
[tester::#YG4] [test] client: Received bytes: "$-1\r\n"
[tester::#YG4] [test] client: Received RESP null bulk string: "$-1\r\n"
[tester::#YG4] [test] Retrying... (3/5 attempts)
[tester::#YG4] [test] client: > GET foo
[tester::#YG4] [test] client: Sent bytes: "*2\r\n$3\r\nGET\r\n$3\r\nfoo\r\n"
[your_program] Received command: "*2\r\n$3\r\nGET\r\n$3\r\nfoo\r\n"
[your_program] Parsed data: ["GET", "foo"]
[your_program] Executing GET command for key: foo
[tester::#YG4] [test] client: Received bytes: "$-1\r\n"
[tester::#YG4] [test] client: Received RESP null bulk string: "$-1\r\n"
[tester::#YG4] [test] Retrying... (4/5 attempts)
[tester::#YG4] [test] client: > GET foo
[tester::#YG4] [test] client: Sent bytes: "*2\r\n$3\r\nGET\r\n$3\r\nfoo\r\n"
[your_program] Received command: "*2\r\n$3\r\nGET\r\n$3\r\nfoo\r\n"
[your_program] Parsed data: ["GET", "foo"]
[your_program] Executing GET command for key: foo
[tester::#YG4] [test] client: Received bytes: "$-1\r\n"
[tester::#YG4] [test] client: Received RESP null bulk string: "$-1\r\n"
[tester::#YG4] [test] Retrying... (5/5 attempts)
[tester::#YG4] [test] client: > GET foo
[tester::#YG4] [test] client: Sent bytes: "*2\r\n$3\r\nGET\r\n$3\r\nfoo\r\n"
[your_program] Received command: "*2\r\n$3\r\nGET\r\n$3\r\nfoo\r\n"
[your_program] Parsed data: ["GET", "foo"]
[your_program] Executing GET command for key: foo
[tester::#YG4] [test] client: Received bytes: "$-1\r\n"
[tester::#YG4] [test] client: Received RESP null bulk string: "$-1\r\n"
[tester::#YG4] Expected simple string or bulk string, got NIL
[tester::#YG4] Test failed
[tester::#YG4] Terminating program
[your_program] Received command: {:error, :closed}
[your_program] Connection to master closed
[your_program] 
[your_program] 19:57:43.354 [notice] SIGTERM received - shutting down
[your_program] 
[tester::#YG4] Program terminated successfully

can you just tell me where i am doing wrong ? and what should i do ?

rohitpaulk · July 30, 2024, 8:11pm

I think the issue here might be that the “Started listening for master commands” log appears after the SET commands have actually been sent? The SET commands are propagated on the replication connection (same one used for the handshake), so the replica must be ready to read soon after it reads the RDB file bytes.

@ProgMastermind Could you share your code too please? Hard to help without more info. Here’s how you can publish your code to GitHub: Publish to GitHub - CodeCrafters

ProgMastermind · July 31, 2024, 1:31am

This is my code rohit:- GitHub - ProgMastermind/Redis-Elixir

ProgMastermind · July 31, 2024, 1:37am

and i have one more doubt , we are sending the rdb_file from master right ? do we have to implement receive_rdb file though , i thought after receiving rdb file from master, master-connection will start sending commands and i have started implementing the receive_rdb , but i am getting a lot of errors while parsing, so i thought there is no need of that as it mentioned it is receiving an empty rdb file, replica will receive_rdb and it wil start listening from master-connection after master sends rdb_file ?
case perform_handshake(socket, replica_port) do
:ok →
IO.puts(“Handshake completed successfully”)
serve(socket, %{replica_of: {master_host, master_port}})
{:ok, socket}
{:error, reason} →
IO.puts(“Handshake failed: #{inspect(reason)}”)
{:error, reason}
end
if it’s a master connection, i am serving only after perfoming a handshake, but still the commands are not propogating, dont know why ?

ProgMastermind · July 31, 2024, 8:33am

Now i have made some changes to the code and when i am running codecrafters test
Waiting for replica to initiate handshake with “PING” command
[your_program] Socket state before handshake: [recv_oct: 0, recv_cnt: 0, recv_max: 0, recv_avg: 0, recv_dvi: 0, send_oct: 0, send_cnt: 0, send_max: 0, send_avg: 0, send_pend: 0]
[tester::#YG4] [handshake] master: Received bytes: “*1\r\n$4\r\nPING\r\n”
[tester::#YG4] [handshake] master: Received RESP array: [“PING”]
[tester::#YG4] [handshake] Received [“PING”]
[tester::#YG4] [handshake] master: Sent “PONG”
[tester::#YG4] [handshake] master: Sent bytes: “+PONG\r\n”
[tester::#YG4] [handshake] master: Waiting for replica to send “REPLCONF listening-port 6380” command
[tester::#YG4] [handshake] master: Received bytes: “*3\r\n$8\r\nREPLCONF\r\n$14\r\nlistening-port\r\n$4\r\n6380\r\n”
[tester::#YG4] [handshake] master: Received RESP array: [“REPLCONF”, “listening-port”, “6380”]
[tester::#YG4] [handshake] Received [“REPLCONF”, “listening-port”, “6380”]
[tester::#YG4] [handshake] master: Sent “OK”
[tester::#YG4] [handshake] master: Sent bytes: “+OK\r\n”
[tester::#YG4] [handshake] master: Waiting for replica to send “REPLCONF capa” command
[tester::#YG4] [handshake] master: Received bytes: “*3\r\n$8\r\nREPLCONF\r\n$4\r\ncapa\r\n$6\r\npsync2\r\n”
[tester::#YG4] [handshake] master: Received RESP array: [“REPLCONF”, “capa”, “psync2”]
[tester::#YG4] [handshake] Received [“REPLCONF”, “capa”, “psync2”]
[tester::#YG4] [handshake] master: Sent “OK”
[tester::#YG4] [handshake] master: Sent bytes: “+OK\r\n”
[tester::#YG4] [handshake] master: Waiting for replica to send “PSYNC” command
[tester::#YG4] [handshake] master: Received bytes: “*3\r\n$5\r\nPSYNC\r\n$1\r\n?\r\n$2\r\n-1\r\n”
[tester::#YG4] [handshake] master: Received RESP array: [“PSYNC”, “?”, “-1”]
[tester::#YG4] [handshake] Received [“PSYNC”, “?”, “-1”]
[tester::#YG4] [handshake] master: Sent “FULLRESYNC 75cd7bc10c49047e0d163660f3b90625b1af31dc 0”
[tester::#YG4] [handshake] master: Sent bytes: “+FULLRESYNC 75cd7bc10c49047e0d163660f3b90625b1af31dc 0\r\n”
[tester::#YG4] [handshake] Sending RDB file…
[tester::#YG4] [handshake] master: Sent bytes: “$88\r\nREDIS0011\xfa\tredis-ver\x057.2.0\xfa\nredis-bits\xc0@\xfa\x05ctime\xc2m\b\xbce\xfa\bused-mem°\xc4\x10\x00\xfa\baof-base\xc0\x00\xff\xf0n;\xfe\xc0\xffZ\xa2”
[tester::#YG4] [handshake] Sent RDB file.
[tester::#YG4] [propagation] master: > SET foo 123
[tester::#YG4] [propagation] master: Sent bytes: “*3\r\n$3\r\nSET\r\n$3\r\nfoo\r\n$3\r\n123\r\n”
[tester::#YG4] [propagation] master: > SET bar 456
[tester::#YG4] [propagation] master: Sent bytes: “*3\r\n$3\r\nSET\r\n$3\r\nbar\r\n$3\r\n456\r\n”
[tester::#YG4] [propagation] master: > SET baz 789
[tester::#YG4] [propagation] master: Sent bytes: “*3\r\n$3\r\nSET\r\n$3\r\nbaz\r\n$3\r\n789\r\n”
[tester::#YG4] [test] Getting key foo
[tester::#YG4] [test] client: $ redis-cli GET foo
[tester::#YG4] [test] client: Sent bytes: “*2\r\n$3\r\nGET\r\n$3\r\nfoo\r\n”
[your_program] Received command: “2\r\n$3\r\nGET\r\n$3\r\nfoo\r\n"
[your_program] Received data: "3\r\n$3\r\nSET\r\n$3\r\nfoo\r\n$3\r\n123\r\n3\r\n$3\r\nSET\r\n$3\r\nbar\r\n$3\r\n456\r\n3”…
[your_program] Parsed data: [“GET”, “foo”]
[your_program] Invalid RDB format: doesn’t start with $
[your_program] Executing GET command for key: foo
[tester::#YG4] [test] client: Received bytes: “$-1\r\n”
[tester::#YG4] [test] client: Received RESP null bulk string: “$-1\r\n”
[tester::#YG4] [test] Retrying… (1/5 attempts)
[tester::#YG4] [test] client: > GET foo
[tester::#YG4] [test] client: Sent bytes: “*2\r\n$3\r\nGET\r\n$3\r\nfoo\r\n”
[your_program] Received command: “*2\r\n$3\r\nGET\r\n$3\r\nfoo\r\n”
[your_program] Parsed data: [“GET”, “foo”]
[your_program] Executing GET command for key: foo
[tester::#YG4] [test] client: Received bytes: “$-1\r\n”
[tester::#YG4] [test] client: Received RESP null bulk string: “$-1\r\n”
[tester::#YG4] [test] Retrying… (2/5 attempts)
[tester::#YG4] [test] client: > GET foo
[tester::#YG4] [test] client: Sent bytes: “*2\r\n$3\r\nGET\r\n$3\r\nfoo\r\n”
[your_program] Received command: “*2\r\n$3\r\nGET\r\n$3\r\nfoo\r\n”
[your_program] Parsed data: [“GET”, “foo”]
[your_program] Executing GET command for key: foo
[tester::#YG4] [test] client: Received bytes: “$-1\r\n”
[tester::#YG4] [test] client: Received RESP null bulk string: “$-1\r\n”
[tester::#YG4] [test] Retrying… (3/5 attempts)
[tester::#YG4] [test] client: > GET foo
[tester::#YG4] [test] client: Sent bytes: “*2\r\n$3\r\nGET\r\n$3\r\nfoo\r\n”
[your_program] Received command: “*2\r\n$3\r\nGET\r\n$3\r\nfoo\r\n”
[your_program] Parsed data: [“GET”, “foo”]
[your_program] Executing GET command for key: foo
[tester::#YG4] [test] client: Received bytes: “$-1\r\n”
[tester::#YG4] [test] client: Received RESP null bulk string: “$-1\r\n”
[tester::#YG4] [test] Retrying… (4/5 attempts)
[tester::#YG4] [test] client: > GET foo
[tester::#YG4] [test] client: Sent bytes: “*2\r\n$3\r\nGET\r\n$3\r\nfoo\r\n”
[your_program] Received command: “*2\r\n$3\r\nGET\r\n$3\r\nfoo\r\n”
[your_program] Parsed data: [“GET”, “foo”]
[your_program] Executing GET command for key: foo
[tester::#YG4] [test] client: Received bytes: “$-1\r\n”
[tester::#YG4] [test] client: Received RESP null bulk string: “$-1\r\n”
[tester::#YG4] [test] Retrying… (5/5 attempts)
[tester::#YG4] [test] client: > GET foo
[tester::#YG4] [test] client: Sent bytes: “*2\r\n$3\r\nGET\r\n$3\r\nfoo\r\n”
[your_program] Received command: “*2\r\n$3\r\nGET\r\n$3\r\nfoo\r\n”
[your_program] Parsed data: [“GET”, “foo”]
[your_program] Executing GET command for key: foo
[tester::#YG4] [test] client: Received bytes: “$-1\r\n”
[tester::#YG4] [test] client: Received RESP null bulk string: “$-1\r\n”
[tester::#YG4] Expected simple string or bulk string, got NIL
[tester::#YG4] Test failed
[tester::#YG4] Terminating program
[your_program] Error receiving RDB file: :closed
[your_program] Handshake failed: :closed
[your_program] Handshake failed: :closed
[your_program] Received command: {:error, :closed}
[your_program]
[your_program] 08:26:34.505 [notice] SIGTERM received - shutting down
[your_program]
[tester::#YG4] Program terminated successfully

View our article on debugging test failures: How do I debug test failures? - CodeCrafters
prakash@prakash-Mi-NoteBook-Ultra:~/Desktop/codecrafters-redis-elixir$ codecrafters test

and when i am running another time
[tester::#YG4] [test] Getting key foo
[tester::#YG4] [test] client: $ redis-cli GET foo
[tester::#YG4] [test] client: Sent bytes: “*2\r\n$3\r\nGET\r\n$3\r\nfoo\r\n”
[your_program] Received command: “*2\r\n$3\r\nGET\r\n$3\r\nfoo\r\n”
[your_program] Received data: <<36, 56, 56, 13, 10, 82, 69, 68, 73, 83, 48, 48, 49, 49, 250, 9, 114, 101, 100, 105, 115, 45, 118, 101, 114, 5, 55, 46, 50, 46, 48, 250, 10, 114, 101, 100, 105, 115, 45, 98, 105, 116, 115, 192, 64, 250, 5, 99, 116, 105, …>>…

but if i am pushing them , once i am not getting any read data log and sometimes i am getting error logging the file ? can you just see what’s happening why am i getting inconsistent outputs ?

ProgMastermind · July 31, 2024, 1:43pm

Now i have made some progress and you can see the logs
remote: [tester::#YG4] [handshake] master: Received bytes: “*1\r\n$4\r\nPING\r\n”
remote: [tester::#YG4] [handshake] master: Received RESP array: [“PING”]
remote: [tester::#YG4] [handshake] Received [“PING”]
remote: [tester::#YG4] [handshake] master: Sent “PONG”
remote: [tester::#YG4] [handshake] master: Sent bytes: “+PONG\r\n”
remote: [tester::#YG4] [handshake] master: Waiting for replica to send “REPLCONF listening-port 6380” command
remote: [tester::#YG4] [handshake] master: Received bytes: “*3\r\n$8\r\nREPLCONF\r\n$14\r\nlistening-port\r\n$4\r\n6380\r\n”
remote: [tester::#YG4] [handshake] master: Received RESP array: [“REPLCONF”, “listening-port”, “6380”]
remote: [tester::#YG4] [handshake] Received [“REPLCONF”, “listening-port”, “6380”]
remote: [tester::#YG4] [handshake] master: Sent “OK”
remote: [tester::#YG4] [handshake] master: Sent bytes: “+OK\r\n”
remote: [tester::#YG4] [handshake] master: Waiting for replica to send “REPLCONF capa” command
remote: [tester::#YG4] [handshake] master: Received bytes: “*3\r\n$8\r\nREPLCONF\r\n$4\r\ncapa\r\n$6\r\npsync2\r\n”
remote: [tester::#YG4] [handshake] master: Received RESP array: [“REPLCONF”, “capa”, “psync2”]
remote: [tester::#YG4] [handshake] Received [“REPLCONF”, “capa”, “psync2”]
remote: [tester::#YG4] [handshake] master: Sent “OK”
remote: [tester::#YG4] [handshake] master: Sent bytes: “+OK\r\n”
remote: [tester::#YG4] [handshake] master: Waiting for replica to send “PSYNC” command
remote: [tester::#YG4] [handshake] master: Received bytes: “*3\r\n$5\r\nPSYNC\r\n$1\r\n?\r\n$2\r\n-1\r\n”
remote: [tester::#YG4] [handshake] master: Received RESP array: [“PSYNC”, “?”, “-1”]
remote: [tester::#YG4] [handshake] Received [“PSYNC”, “?”, “-1”]
remote: [tester::#YG4] [handshake] master: Sent “FULLRESYNC 75cd7bc10c49047e0d163660f3b90625b1af31dc 0”
remote: [tester::#YG4] [handshake] master: Sent bytes: “+FULLRESYNC 75cd7bc10c49047e0d163660f3b90625b1af31dc 0\r\n”
remote: [tester::#YG4] [handshake] Sending RDB file…
remote: [tester::#YG4] [handshake] master: Sent bytes: “$88\r\nREDIS0011\xfa\tredis-ver\x057.2.0\xfa\nredis-bits\xc0@\xfa\x05ctime\xc2m\b\xbce\xfa\bused-mem°\xc4\x10\x00\xfa\baof-base\xc0\x00\xff\xf0n;\xfe\xc0\xffZ\xa2”
remote: [tester::#YG4] [handshake] Sent RDB file.
remote: [tester::#YG4] [propagation] master: > SET foo 123
remote: [tester::#YG4] [propagation] master: Sent bytes: “*3\r\n$3\r\nSET\r\n$3\r\nfoo\r\n$3\r\n123\r\n”
remote: [tester::#YG4] [propagation] master: > SET bar 456
remote: [tester::#YG4] [propagation] master: Sent bytes: “*3\r\n$3\r\nSET\r\n$3\r\nbar\r\n$3\r\n456\r\n”
remote: [tester::#YG4] [propagation] master: > SET baz 789
remote: [tester::#YG4] [propagation] master: Sent bytes: “*3\r\n$3\r\nSET\r\n$3\r\nbaz\r\n$3\r\n789\r\n”
remote: [tester::#YG4] [test] Getting key foo
remote: [tester::#YG4] [test] client: $ redis-cli GET foo
remote: [tester::#YG4] [test] client: Sent bytes: “*2\r\n$3\r\nGET\r\n$3\r\nfoo\r\n”
remote: [your_program] Received command: “*2\r\n$3\r\nGET\r\n$3\r\nfoo\r\n”
remote: [your_program] Parsed data: [“GET”, “foo”]
remote: [your_program]
remote: [your_program] 13:35:04.425 [info] Starting to receive data from socket
remote: [your_program]
remote: [your_program] 13:35:04.427 [debug] Receiving data. Buffer size: 0, Expected length: 0
remote: [your_program] Expected Propagated Commands: [[“SET”, “foo”, “123”]]
remote: [your_program] Executing GET command for key: foo
remote: [your_program]
remote: [your_program] 13:35:04.428 [debug] Received chunk of size: 93 bytes
remote: [your_program] Socket state after handshake: [recv_oct: 259, recv_cnt: 5, recv_max: 149, recv_avg: 51, recv_dvi: 29, send_oct: 133, send_cnt: 4, send_max: 49, send_avg: 33, send_pend: 0]
remote: [your_program] Value found: 123
remote: [your_program]
remote: [your_program] 13:35:04.428 [debug] New buffer size: 93 bytes
remote: [your_program] Handshake completed successfully
remote: [your_program]
remote: [your_program] 13:35:04.428 [debug] Received enough data to potentially complete RDB or command
remote: [your_program]
remote: [your_program] 13:35:04.428 [info] RDB file complete, parsing remaining data as command
remote: [your_program]
remote: [your_program] 13:35:04.435 [debug] Attempting to parse command from data
remote: [your_program]
remote: [your_program] 13:35:04.435 [info] Successfully parsed command: [“SET”, “foo”, “123”]
remote: [your_program]
remote: [your_program] 13:35:04.435 [info] Received complete command: [“SET”, “foo”, “123”]
remote: [tester::#YG4] [test] client: Received bytes: “$3\r\n123\r\n”
remote: [tester::#YG4] [test] client: Received RESP bulk string: “123”
remote: [tester::#YG4] [test] Received “123”
remote: [tester::#YG4] [test] Getting key bar
remote: [tester::#YG4] [test] client: > GET bar
remote: [tester::#YG4] [test] client: Sent bytes: “*2\r\n$3\r\nGET\r\n$3\r\nbar\r\n”
remote: [your_program] Received command: “*2\r\n$3\r\nGET\r\n$3\r\nbar\r\n”
remote: [your_program] Parsed data: [“GET”, “bar”]
remote: [your_program] Executing GET command for key: bar
remote: [tester::#YG4] [test] client: Received bytes: “$-1\r\n”
remote: [tester::#YG4] [test] client: Received RESP null bulk string: “$-1\r\n”
remote: [tester::#YG4] [test] Retrying… (1/5 attempts)
remote: [tester::#YG4] [test] client: > GET bar
remote: [tester::#YG4] [test] client: Sent bytes: “*2\r\n$3\r\nGET\r\n$3\r\nbar\r\n”
remote: [your_program] Received command: “*2\r\n$3\r\nGET\r\n$3\r\nbar\r\n”
remote: [your_program] Parsed data: [“GET”, “bar”]
remote: [your_program] Executing GET command for key: bar
remote: [tester::#YG4] [test] client: Received bytes: “$-1\r\n”
remote: [tester::#YG4] [test] client: Received RESP null bulk string: “$-1\r\n”
remote: [tester::#YG4] [test] Retrying… (2/5 attempts)
remote: [tester::#YG4] [test] client: > GET bar
remote: [tester::#YG4] [test] client: Sent bytes: “*2\r\n$3\r\nGET\r\n$3\r\nbar\r\n”
remote: [your_program] Received command: “*2\r\n$3\r\nGET\r\n$3\r\nbar\r\n”
remote: [your_program] Parsed data: [“GET”, “bar”]
remote: [your_program] Executing GET command for key: bar
remote: [tester::#YG4] [test] client: Received bytes: “$-1\r\n”
remote: [tester::#YG4] [test] client: Received RESP null bulk string: “$-1\r\n”
remote: [tester::#YG4] [test] Retrying… (3/5 attempts)
remote: [tester::#YG4] [test] client: > GET bar
remote: [tester::#YG4] [test] client: Sent bytes: “*2\r\n$3\r\nGET\r\n$3\r\nbar\r\n”
remote: [your_program] Received command: “*2\r\n$3\r\nGET\r\n$3\r\nbar\r\n”
remote: [your_program] Parsed data: [“GET”, “bar”]
remote: [your_program] Executing GET command for key: bar
remote: [tester::#YG4] [test] client: Received bytes: “$-1\r\n”
remote: [tester::#YG4] [test] client: Received RESP null bulk string: “$-1\r\n”
remote: [tester::#YG4] [test] Retrying… (4/5 attempts)
remote: [tester::#YG4] [test] client: > GET bar
remote: [tester::#YG4] [test] client: Sent bytes: “*2\r\n$3\r\nGET\r\n$3\r\nbar\r\n”
remote: [your_program] Received command: “*2\r\n$3\r\nGET\r\n$3\r\nbar\r\n”
remote: [your_program] Parsed data: [“GET”, “bar”]
remote: [your_program] Executing GET command for key: bar
remote: [tester::#YG4] [test] client: Received bytes: “$-1\r\n”
remote: [tester::#YG4] [test] client: Received RESP null bulk string: “$-1\r\n”
remote: [tester::#YG4] [test] Retrying… (5/5 attempts)
remote: [tester::#YG4] [test] client: > GET bar
remote: [tester::#YG4] [test] client: Sent bytes: “*2\r\n$3\r\nGET\r\n$3\r\nbar\r\n”
remote: [your_program] Received command: “*2\r\n$3\r\nGET\r\n$3\r\nbar\r\n”
remote: [your_program] Parsed data: [“GET”, “bar”]
remote: [your_program] Executing GET command for key: bar
remote: [tester::#YG4] [test] client: Received bytes: “$-1\r\n”
remote: [tester::#YG4] [test] client: Received RESP null bulk string: “$-1\r\n”
remote: [tester::#YG4] Expected simple string or bulk string, got NIL
remote: [tester::#YG4] Test failed
remote: [tester::#YG4] Terminating program
remote: [your_program]
remote: [your_program] 13:35:07.455 [notice] SIGTERM received - shutting down
remote: [your_program]
remote: [your_program] Received command: {:error, :closed}
remote: [tester::#YG4] Program terminated successfully
remote:
remote: View our article on debugging test failures: How do I debug test failures? - CodeCrafters
remote:
To https://git.codecrafters.io/3c6d47f43b26ff8f

you can see i am able to parse only one command and setting the command ? but i am not receiving any data for the next two commands , and i am not getting data every time from the socket (receive_data) , once in a 3 attempts it is coming like this? can you look into it and tell where i am going wrong ?
and one more doubt at last of error i am getting
remote: [your_program] Received command: {:error, :closed}
remote: [tester::#YG4] Program terminated successfully
remote:
remote: View our article on debugging test failures: How do I debug test failures? - CodeCrafters
remote:
To https://git.codecrafters.io/3c6d47f43b26ff8f
f1b5147…49427b7 master → master
prakash@prakash-Mi-NoteBook-Ultra:~/Desktop/codecrafters-redis-
the log Received Command i have given for the process_command in my code , but when i am accepting commands from master and perfroming the operations, there is no need of that process_command, but i am getting that log , don’t know why ?

m-czernek · July 31, 2024, 5:36pm

The server can send one or multiple commands through the handshake socket.

So, for example, you must be able to parse three times *3\r\n$3\r\nSET\r\n$3\r\nfoo\r\n$3\r\n123\r\n, or just one time *3\r\n$3\r\nSET\r\n$3\r\nfoo\r\n$3\r\n123\r\n*3\r\n$3\r\nSET\r\n$3\r\nbar\r\n$3\r\n123\r\n*3\r\n$3\r\nSET\r\n$3\r\nbaz\r\n$3\r\n123\r\n, or anything in between.

Is it possible you’re only processing the first command and ignoring the rest from the socket? Or perhaps you’re reading only once and not getting the rest of the data.

ProgMastermind · July 31, 2024, 6:15pm

But sometimes i getting data from that connection and sometimes i am not getting anything, i am not receiving any data from connection , can you tell the reason for inconsistency ?

ProgMastermind · July 31, 2024, 9:07pm

I have solved the step, but still sometimes when i am receiving data , it is getting data sometimes and sometimes i am not getting , whenever the data is getting from connection it is passing the tests
[your_program] Socket state after handshake: [recv_oct: 166, recv_cnt: 4, recv_max: 149, recv_avg: 41, recv_dvi: 26, send_oct: 133, send_cnt: 4, send_max: 49, send_avg: 33, send_pend: 0]
[your_program] Received command: “2\r\n$3\r\nGET\r\n$3\r\nfoo\r\n"
[your_program] Parsed data: [“GET”, “foo”]
[your_program]
[your_program] 20:58:36.409 [info] Handshake completed successfully
[your_program] Process the received data carefully
[your_program]
[your_program] 20:58:36.414 [info] Starting to receive data from socket
[your_program]
[your_program] 20:58:36.414 [debug] Receiving data. Buffer size: 0, Expected length: 0
[your_program]
[your_program] 20:58:36.414 [debug] Received chunk of size: 93 bytes
[your_program]
[your_program] 20:58:36.414 [debug] New buffer size: 93 bytes
[your_program]
[your_program] 20:58:36.414 [debug] Received enough data to potentially complete RDB or command
[your_program]
[your_program] 20:58:36.414 [info] RDB file complete, parsing remaining data as command
[your_program]
[your_program] 20:58:36.414 [info] Received data: "3\r\n$3\r\nSET\r\n$3\r\nfoo\r\n$3\r\n123\r\n3\r\n$3\r\nSET\r\n$3\r\nbar\r\n$3\r\n456\r\n3\r\n$3\r\nSET\r\n$3\r\nbaz\r\n$3\r\n789\r\n”…
[your_program]
[your_program] 20:58:36.414 [debug] Attempting to parse commands from data
[your_program]
[your_program] 20:58:36.414 [debug] Parsing data: “3\r\n$3\r\nSET\r\n$3\r\nfoo\r\n$3\r\n123\r\n3\r\n$3\r\nSET\r\n$3\r\nbar\r\n$3\r\n456\r\n*3\r\n$3\r\nSET\r\n$3\r\nbaz\r\n$3\r\n789\r\n”
[your_program]
[your_program] 20:58:36.414 [debug] Parsed command: [“SET”, “foo”, “123”], remaining: “3\r\n$3\r\nSET\r\n$3\r\nbar\r\n$3\r\n456\r\n3\r\n$3\r\nSET\r\n$3\r\nbaz\r\n$3\r\n789\r\n”
[your_program]
[your_program] 20:58:36.414 [debug] Parsing data: “3\r\n$3\r\nSET\r\n$3\r\nbar\r\n$3\r\n456\r\n3\r\n$3\r\nSET\r\n$3\r\nbaz\r\n$3\r\n789\r\n”
[your_program]
[your_program] 20:58:36.414 [debug] Parsed command: [“SET”, “bar”, “456”], remaining: “*3\r\n$3\r\nSET\r\n$3\r\nbaz\r\n$3\r\n789\r\n”
[your_program]
[your_program] 20:58:36.414 [debug] Parsing data: “*3\r\n$3\r\nSET\r\n$3\r\nbaz\r\n$3\r\n789\r\n”
[your_program]
[your_program] 20:58:36.414 [debug] Parsed command: [“SET”, “baz”, “789”], remaining: “”
[your_program]
[your_program] 20:58:36.414 [debug] Finished parsing all commands: [[“SET”, “foo”, “123”], [“SET”, “bar”, “456”], [“SET”, “baz”, “789”]]
[your_program]
[your_program] 20:58:36.414 [info] Successfully parsed commands: [[“SET”, “foo”, “123”], [“SET”, “bar”, “456”], [“SET”, “baz”, “789”]]
[your_program]
[your_program] 20:58:36.414 [info] Received complete command: [[“SET”, “foo”, “123”], [“SET”, “bar”, “456”], [“SET”, “baz”, “789”]]
[your_program]
[your_program] 20:58:36.414 [info] Executing command: [“SET”, “foo”, “123”]
[your_program] Executing GET command for key: foo
[your_program]
[your_program] 20:58:36.423 [info] Executing command: [“SET”, “bar”, “456”]
[your_program] Value found: 123
[your_program]
[your_program] 20:58:36.423 [info] Executing command: [“SET”, “baz”, “789”]
[tester::#YG4] [test] client: Received bytes: “$3\r\n123\r\n”
[tester::#YG4] [test] client: Received RESP bulk string: “123”
[tester::#YG4] [test] Received “123”
[tester::#YG4] [test] Getting key bar
[tester::#YG4] [test] client: > GET bar
[tester::#YG4] [test] client: Sent bytes: “*2\r\n$3\r\nGET\r\n$3\r\nbar\r\n”
[your_program] Received command: “*2\r\n$3\r\nGET\r\n$3\r\nbar\r\n”
[your_program] Parsed data: [“GET”, “bar”]
[your_program] Executing GET command for key: bar
[your_program] Value found: 456
[tester::#YG4] [test] client: Received bytes: “$3\r\n456\r\n”
[tester::#YG4] [test] client: Received RESP bulk string: “456”
[tester::#YG4] [test] Received “456”
[tester::#YG4] [test] Getting key baz
[tester::#YG4] [test] client: > GET baz
[tester::#YG4] [test] client: Sent bytes: “*2\r\n$3\r\nGET\r\n$3\r\nbaz\r\n”
[your_program] Received command: “*2\r\n$3\r\nGET\r\n$3\r\nbaz\r\n”
[your_program] Parsed data: [“GET”, “baz”]
[your_program] Executing GET command for key: baz
[your_program] Value found: 789
[tester::#YG4] [test] client: Received bytes: “$3\r\n789\r\n”
[tester::#YG4] [test] client: Received RESP bulk string: “789”
[tester::#YG4] [test] Received “789”
[tester::#YG4] Test passed.
[tester::#YG4] Terminating program

#----------------------------------------------------------------------
but when i am not getting data I am receving this error
Socket state after handshake: [recv_oct: 259, recv_cnt: 4, recv_max: 242, recv_avg: 64, recv_dvi: 43, send_oct: 133, send_cnt: 4, send_max: 49, send_avg: 33, send_pend: 0]
[your_program] Received command: “*2\r\n$3\r\nGET\r\n$3\r\nfoo\r\n”
[your_program] Parsed data: [“GET”, “foo”]
[your_program] Process the received data carefully
[your_program]
[your_program] 21:05:15.706 [info] Handshake completed successfully
[your_program] Executing GET command for key: foo
[your_program]
[your_program] 21:05:15.712 [info] Starting to receive data from socket
[your_program]
[your_program] 21:05:15.712 [debug] Receiving data. Buffer size: 0, Expected length: 0
[tester::#YG4] [test] client: Received bytes: “$-1\r\n”
[tester::#YG4] [test] client: Received RESP null bulk string: “$-1\r\n”
[tester::#YG4] [test] Retrying… (1/5 attempts)
[tester::#YG4] [test] client: > GET foo
[tester::#YG4] [test] client: Sent bytes: “*2\r\n$3\r\nGET\r\n$3\r\nfoo\r\n”
[your_program] Received command: “*2\r\n$3\r\nGET\r\n$3\r\nfoo\r\n”
[your_program] Parsed data: [“GET”, “foo”]
[your_program] Executing GET command for key: foo
[tester::#YG4] [test] client: Received bytes: “$-1\r\n”
[tester::#YG4] [test] client: Received RESP null bulk string: “$-1\r\n”
[tester::#YG4] [test] Retrying… (2/5 attempts)
[tester::#YG4] [test] client: > GET foo
[tester::#YG4] [test] client: Sent bytes: “*2\r\n$3\r\nGET\r\n$3\r\nfoo\r\n”
[your_program] Received command: “*2\r\n$3\r\nGET\r\n$3\r\nfoo\r\n”
[your_program] Parsed data: [“GET”, “foo”]
[your_program] Executing GET command for key: foo
[tester::#YG4] [test] client: Received bytes: “$-1\r\n”
[tester::#YG4] [test] client: Received RESP null bulk string: “$-1\r\n”
[tester::#YG4] [test] Retrying… (3/5 attempts)
[tester::#YG4] [test] client: > GET foo
[tester::#YG4] [test] client: Sent bytes: “*2\r\n$3\r\nGET\r\n$3\r\nfoo\r\n”
[your_program] Received command: “*2\r\n$3\r\nGET\r\n$3\r\nfoo\r\n”
[your_program] Parsed data: [“GET”, “foo”]
[your_program] Executing GET command for key: foo
[tester::#YG4] [test] client: Received bytes: “$-1\r\n”
[tester::#YG4] [test] client: Received RESP null bulk string: “$-1\r\n”
[tester::#YG4] [test] Retrying… (4/5 attempts)
[tester::#YG4] [test] client: > GET foo
[tester::#YG4] [test] client: Sent bytes: “*2\r\n$3\r\nGET\r\n$3\r\nfoo\r\n”
[your_program] Received command: “*2\r\n$3\r\nGET\r\n$3\r\nfoo\r\n”
[your_program] Parsed data: [“GET”, “foo”]
[your_program] Executing GET command for key: foo
[tester::#YG4] [test] client: Received bytes: “$-1\r\n”
[tester::#YG4] [test] client: Received RESP null bulk string: “$-1\r\n”
[tester::#YG4] [test] Retrying… (5/5 attempts)
[tester::#YG4] [test] client: > GET foo
[tester::#YG4] [test] client: Sent bytes: “*2\r\n$3\r\nGET\r\n$3\r\nfoo\r\n”
[your_program] Received command: “*2\r\n$3\r\nGET\r\n$3\r\nfoo\r\n”
[your_program] Parsed data: [“GET”, “foo”]
[your_program] Executing GET command for key: foo
[tester::#YG4] [test] client: Received bytes: “$-1\r\n”
[tester::#YG4] [test] client: Received RESP null bulk string: “$-1\r\n”
[tester::#YG4] Expected simple string or bulk string, got NIL
[tester::#YG4] Test failed
[tester::#YG4] Terminating program
[your_program]
[your_program] 21:05:18.721 [notice] SIGTERM received - shutting down
[your_program]
[your_program] Received command: {:error, :closed}
[your_program]
[your_program] 21:05:18.726 [error] Error receiving data: :closed
[your_program]
[your_program] 21:05:18.726 [error] Failed to receive RDB file: :closed
[tester::#YG4] Program terminated successfully

My tests are failing, since i am not receiving any data, can you look into my code and tell me why it is happening like this and where i should rectify in my code, if i don’t rectify it wil become problem as for every push it will run all previous tests, if the data is not receiving consistently in this stage, the next stage will also fail.

@rohitpaulk can you look into this

rohitpaulk · August 1, 2024, 12:31pm

@ProgMastermind This most likely means that you’ve got a concurrency bug. The logs seem to mention that bytes were sent.

Swamped this week so can’t really take a look, but I’d recommend logging the raw bytes you receive on every TCP read - that should match what the logs emit.

ProgMastermind · August 1, 2024, 3:53pm

These log contains the raw bytes receiving on tcp read

[tester::#YG4] [handshake] master: Received bytes: "*1\r\n$4\r\nPING\r\n"
[tester::#YG4] [handshake] master: Received RESP array: ["PING"]
[tester::#YG4] [handshake] Received ["PING"]
[tester::#YG4] [handshake] master: Sent "PONG"
[tester::#YG4] [handshake] master: Sent bytes: "+PONG\r\n"
[tester::#YG4] [handshake] master: Waiting for replica to send "REPLCONF listening-port 6380" command
[tester::#YG4] [handshake] master: Received bytes: "*3\r\n$8\r\nREPLCONF\r\n$14\r\nlistening-port\r\n$4\r\n6380\r\n"
[tester::#YG4] [handshake] master: Received RESP array: ["REPLCONF", "listening-port", "6380"]
[tester::#YG4] [handshake] Received ["REPLCONF", "listening-port", "6380"]
[tester::#YG4] [handshake] master: Sent "OK"
[tester::#YG4] [handshake] master: Sent bytes: "+OK\r\n"
[tester::#YG4] [handshake] master: Waiting for replica to send "REPLCONF capa" command
[tester::#YG4] [handshake] master: Received bytes: "*3\r\n$8\r\nREPLCONF\r\n$4\r\ncapa\r\n$6\r\npsync2\r\n"
[tester::#YG4] [handshake] master: Received RESP array: ["REPLCONF", "capa", "psync2"]
[tester::#YG4] [handshake] Received ["REPLCONF", "capa", "psync2"]
[tester::#YG4] [handshake] master: Sent "OK"
[tester::#YG4] [handshake] master: Sent bytes: "+OK\r\n"
[tester::#YG4] [handshake] master: Waiting for replica to send "PSYNC" command
[tester::#YG4] [handshake] master: Received bytes: "*3\r\n$5\r\nPSYNC\r\n$1\r\n?\r\n$2\r\n-1\r\n"
[tester::#YG4] [handshake] master: Received RESP array: ["PSYNC", "?", "-1"]
[tester::#YG4] [handshake] Received ["PSYNC", "?", "-1"]
[tester::#YG4] [handshake] master: Sent "FULLRESYNC 75cd7bc10c49047e0d163660f3b90625b1af31dc 0"
[tester::#YG4] [handshake] master: Sent bytes: "+FULLRESYNC 75cd7bc10c49047e0d163660f3b90625b1af31dc 0\r\n"
[tester::#YG4] [handshake] Sending RDB file...
[tester::#YG4] [handshake] master: Sent bytes: "$88\r\nREDIS0011\xfa\tredis-ver\x057.2.0\xfa\nredis-bits\xc0@\xfa\x05ctime\xc2m\b\xbce\xfa\bused-mem°\xc4\x10\x00\xfa\baof-base\xc0\x00\xff\xf0n;\xfe\xc0\xffZ\xa2"
[tester::#YG4] [handshake] Sent RDB file.
[tester::#YG4] [propagation] master: > SET foo 123
[tester::#YG4] [propagation] master: Sent bytes: "*3\r\n$3\r\nSET\r\n$3\r\nfoo\r\n$3\r\n123\r\n"
[tester::#YG4] [propagation] master: > SET bar 456
[tester::#YG4] [propagation] master: Sent bytes: "*3\r\n$3\r\nSET\r\n$3\r\nbar\r\n$3\r\n456\r\n"
[tester::#YG4] [propagation] master: > SET baz 789
[tester::#YG4] [propagation] master: Sent bytes: "*3\r\n$3\r\nSET\r\n$3\r\nbaz\r\n$3\r\n789\r\n"
[tester::#YG4] [test] Getting key foo
[tester::#YG4] [test] client: $ redis-cli GET foo
[tester::#YG4] [test] client: Sent bytes: "*2\r\n$3\r\nGET\r\n$3\r\nfoo\r\n"
[your_program] Received command: "*2\r\n$3\r\nGET\r\n$3\r\nfoo\r\n"
[your_program] Parsed data: ["GET", "foo"]
[your_program] 
[your_program] 15:50:00.855 [info] Starting to receive data from socket
[your_program] 
[your_program] 15:50:00.857 [debug] Receiving data. Buffer size: 0, Expected length: 0
[your_program] 
[your_program] 15:50:00.857 [debug] Received raw bytes: <<42, 51, 13, 10, 36, 51, 13, 10, 83, 69, 84, 13, 10, 36, 51, 13, 10, 102, 111, 111, 13, 10, 36, 51, 13, 10, 49, 50, 51, 13, 10, 42, 51, 13, 10, 36, 51, 13, 10, 83, 69, 84, 13, 10, 36, 51, 13, 10, 98, 97, 114, 13, 10, 36, 51, 13, 10, 52, 53, 54, 13, 10, 42, 51, 13, 10, 36, 51, 13, 10, 83, 69, 84, 13, 10, 36, 51, 13, 10, 98, 97, 122, 13, 10, 36, 51, 13, 10, 55, 56, 57, 13, 10>>
[your_program] 
[your_program] 15:50:00.857 [debug] Received chunk of size: 93 bytes
[your_program] 
[your_program] 15:50:00.858 [debug] New buffer size: 93 bytes
[your_program] 
[your_program] 15:50:00.858 [debug] Received enough data to potentially complete RDB or command
[your_program] 
[your_program] 15:50:00.859 [info] RDB file complete, parsing remaining data as command
[your_program] 
[your_program] 15:50:00.859 [info] Received data: "*3\r\n$3\r\nSET\r\n$3\r\nfoo\r\n$3\r\n123\r\n*3\r\n$3\r\nSET\r\n$3\r\nbar\r\n$3\r\n456\r\n*3\r\n$3\r\nSET\r\n$3\r\nbaz\r\n$3\r\n789\r\n"...
[your_program] 
[your_program] 15:50:00.859 [debug] Attempting to parse commands from data
[your_program] 
[your_program] 15:50:00.859 [debug] Parsing data: "*3\r\n$3\r\nSET\r\n$3\r\nfoo\r\n$3\r\n123\r\n*3\r\n$3\r\nSET\r\n$3\r\nbar\r\n$3\r\n456\r\n*3\r\n$3\r\nSET\r\n$3\r\nbaz\r\n$3\r\n789\r\n"
[your_program] 
[your_program] 15:50:00.859 [debug] Parsed command: ["SET", "foo", "123"], remaining: "*3\r\n$3\r\nSET\r\n$3\r\nbar\r\n$3\r\n456\r\n*3\r\n$3\r\nSET\r\n$3\r\nbaz\r\n$3\r\n789\r\n"
[your_program] 
[your_program] 15:50:00.859 [debug] Parsing data: "*3\r\n$3\r\nSET\r\n$3\r\nbar\r\n$3\r\n456\r\n*3\r\n$3\r\nSET\r\n$3\r\nbaz\r\n$3\r\n789\r\n"
[your_program] 
[your_program] 15:50:00.859 [debug] Parsed command: ["SET", "bar", "456"], remaining: "*3\r\n$3\r\nSET\r\n$3\r\nbaz\r\n$3\r\n789\r\n"
[your_program] 
[your_program] 15:50:00.859 [debug] Parsing data: "*3\r\n$3\r\nSET\r\n$3\r\nbaz\r\n$3\r\n789\r\n"
[your_program] 
[your_program] 15:50:00.859 [debug] Parsed command: ["SET", "baz", "789"], remaining: ""
[your_program] 
[your_program] 15:50:00.859 [debug] Finished parsing all commands: [["SET", "foo", "123"], ["SET", "bar", "456"], ["SET", "baz", "789"]]
[your_program] 
[your_program] 15:50:00.859 [info] Successfully parsed commands: [["SET", "foo", "123"], ["SET", "bar", "456"], ["SET", "baz", "789"]]
[your_program] 
[your_program] 15:50:00.859 [info] Received complete command: [["SET", "foo", "123"], ["SET", "bar", "456"], ["SET", "baz", "789"]]
[your_program] 
[your_program] 15:50:00.859 [info] Executing command: ["SET", "foo", "123"]
[your_program] Executing GET command for key: foo
[your_program] 
[your_program] 15:50:00.866 [info] Executing command: ["SET", "bar", "456"]
[your_program] Value found: 123
[your_program] 
[your_program] 15:50:00.866 [info] Executing command: ["SET", "baz", "789"]
[your_program] Socket state after handshake: [recv_oct: 259, recv_cnt: 5, recv_max: 149, recv_avg: 51, recv_dvi: 29, send_oct: 133, send_cnt: 4, send_max: 49, send_avg: 33, send_pend: 0]
[your_program] Process the received data carefully
[your_program] 
[your_program] 15:50:00.867 [info] Handshake completed successfully
[tester::#YG4] [test] client: Received bytes: "$3\r\n123\r\n"
[tester::#YG4] [test] client: Received RESP bulk string: "123"
[tester::#YG4] [test] Received "123"
[tester::#YG4] [test] Getting key bar
[tester::#YG4] [test] client: > GET bar
[tester::#YG4] [test] client: Sent bytes: "*2\r\n$3\r\nGET\r\n$3\r\nbar\r\n"
[your_program] Received command: "*2\r\n$3\r\nGET\r\n$3\r\nbar\r\n"
[your_program] Parsed data: ["GET", "bar"]
[your_program] Executing GET command for key: bar
[your_program] Value found: 456
[tester::#YG4] [test] client: Received bytes: "$3\r\n456\r\n"
[tester::#YG4] [test] client: Received RESP bulk string: "456"
[tester::#YG4] [test] Received "456"
[tester::#YG4] [test] Getting key baz
[tester::#YG4] [test] client: > GET baz
[tester::#YG4] [test] client: Sent bytes: "*2\r\n$3\r\nGET\r\n$3\r\nbaz\r\n"
[your_program] Received command: "*2\r\n$3\r\nGET\r\n$3\r\nbaz\r\n"
[your_program] Parsed data: ["GET", "baz"]
[your_program] Executing GET command for key: baz
[your_program] Value found: 789
[tester::#YG4] [test] client: Received bytes: "$3\r\n789\r\n"
[tester::#YG4] [test] client: Received RESP bulk string: "789"
[tester::#YG4] [test] Received "789"
[tester::#YG4] Test passed.
[tester::#YG4] Terminating program
[your_program] 
[your_program] 15:50:00.893 [notice] SIGTERM received - shutting down
[your_program] 
[tester::#YG4] Program terminated successfully

@rohitpaulk as i have mentioned, sometimes when i am receiving data it is processing well , but sometimes i am not getting anything

[tester::#YG4] [handshake] Sent RDB file.
[tester::#YG4] [propagation] master: > SET foo 123
[tester::#YG4] [propagation] master: Sent bytes: "*3\r\n$3\r\nSET\r\n$3\r\nfoo\r\n$3\r\n123\r\n"
[tester::#YG4] [propagation] master: > SET bar 456
[tester::#YG4] [propagation] master: Sent bytes: "*3\r\n$3\r\nSET\r\n$3\r\nbar\r\n$3\r\n456\r\n"
[tester::#YG4] [propagation] master: > SET baz 789
[tester::#YG4] [propagation] master: Sent bytes: "*3\r\n$3\r\nSET\r\n$3\r\nbaz\r\n$3\r\n789\r\n"
[tester::#YG4] [test] Getting key foo
[tester::#YG4] [test] client: $ redis-cli GET foo
[tester::#YG4] [test] client: Sent bytes: "*2\r\n$3\r\nGET\r\n$3\r\nfoo\r\n"
[your_program] Received command: "*2\r\n$3\r\nGET\r\n$3\r\nfoo\r\n"
[your_program] Parsed data: ["GET", "foo"]
[your_program] 
[your_program] 15:46:57.402 [info] Starting to receive data from socket
[your_program] 
[your_program] 15:46:57.408 [debug] Receiving data. Buffer size: 0, Expected length: 0
[your_program] Executing GET command for key: foo

and it is failing, i have tried , everything but still can’t able to figure out

rohitpaulk · August 1, 2024, 4:10pm

Thanks for sharing logs from both success & failure cases!

In the first part of your message (tests passed), how come the handshake bytes aren’t logged? (PONG, OK etc.)

It seems like logging starts at a later point, and that you have bytes that are initially being read and processed (they aren’t logged)? Can you try logging all bytes received?

ProgMastermind · August 1, 2024, 4:16pm

I have just implemented logging in the receve_data function which happens after master sends the rdb file while processing request sent by replica(PSYNC) , since those functions are passing i have not implemented any logging there

rohitpaulk · August 1, 2024, 4:22pm

This is likely where the issue is @ProgMastermind - when the RDB file is received, maybe there are other bytes received along with it that are being discarded?

ProgMastermind · August 1, 2024, 4:28pm

But those are successfully handling right whatever commands hass been sent from the master , the replica is handling but after sending the rdb_file the issue is occuring , as you can see it is giving response upto PSYNC command.

rohitpaulk · August 1, 2024, 4:36pm

All I can do here is point you towards what could be wrong I think that logging out the bytes you receive as the RDB file is a good next step - it helps you verify that those bytes are indeed only the RDB file, and that they don’t include other SET commands inside which are being discarded.

ProgMastermind · August 1, 2024, 5:34pm

[tester::#YG4] Running tests for Stage #YG4 (Replication - Command Processing)
[tester::#YG4] Master is running on port 6379
[tester::#YG4] $ ./spawn_redis_server.sh --port 6380 --replicaof "localhost 6379"
[your_program]      warning: clauses with the same name and arity (number of arguments) should be grouped together, "defp execute_command/3" was previously defined (lib/server.ex:535)
[your_program]      │
[your_program]  572 │   defp execute_command("ECHO", [message], client) do
[your_program]      │        ~
[your_program]      │
[your_program]      └─ lib/server.ex:572:8
[your_program] 
[your_program] Server listening on port 6380
[tester::#YG4] [handshake] master: Waiting for replica to initiate handshake with "PING" command
[your_program] Socket state before handshake: [recv_oct: 0, recv_cnt: 0, recv_max: 0, recv_avg: 0, recv_dvi: 0, send_oct: 0, send_cnt: 0, send_max: 0, send_avg: 0, send_pend: 0]
[tester::#YG4] [handshake] master: Received bytes: "*1\r\n$4\r\nPING\r\n"
[tester::#YG4] [handshake] master: Received RESP array: ["PING"]
[tester::#YG4] [handshake] Received ["PING"]
[tester::#YG4] [handshake] master: Sent "PONG"
[tester::#YG4] [handshake] master: Sent bytes: "+PONG\r\n"
[tester::#YG4] [handshake] master: Waiting for replica to send "REPLCONF listening-port 6380" command
[your_program] 
[your_program] 16:55:22.237 [debug] Received raw bytes: <<43, 80, 79, 78, 71, 13, 10>>
[your_program] 
[your_program] 16:55:22.239 [debug] Received expected response
[tester::#YG4] [handshake] master: Received bytes: "*3\r\n$8\r\nREPLCONF\r\n$14\r\nlistening-port\r\n$4\r\n6380\r\n"
[tester::#YG4] [handshake] master: Received RESP array: ["REPLCONF", "listening-port", "6380"]
[tester::#YG4] [handshake] Received ["REPLCONF", "listening-port", "6380"]
[tester::#YG4] [handshake] master: Sent "OK"
[tester::#YG4] [handshake] master: Sent bytes: "+OK\r\n"
[tester::#YG4] [handshake] master: Waiting for replica to send "REPLCONF capa" command
[tester::#YG4] [handshake] master: Received bytes: "*3\r\n$8\r\nREPLCONF\r\n$4\r\ncapa\r\n$6\r\npsync2\r\n"
[tester::#YG4] [handshake] master: Received RESP array: ["REPLCONF", "capa", "psync2"]
[tester::#YG4] [handshake] Received ["REPLCONF", "capa", "psync2"]
[your_program] 
[your_program] 16:55:22.248 [debug] Received raw bytes: <<43, 79, 75, 13, 10>>
[your_program] 
[your_program] 16:55:22.248 [debug] Received expected response
[tester::#YG4] [handshake] master: Sent "OK"
[tester::#YG4] [handshake] master: Sent bytes: "+OK\r\n"
[tester::#YG4] [handshake] master: Waiting for replica to send "PSYNC" command
[tester::#YG4] [handshake] master: Received bytes: "*3\r\n$5\r\nPSYNC\r\n$1\r\n?\r\n$2\r\n-1\r\n"
[tester::#YG4] [handshake] master: Received RESP array: ["PSYNC", "?", "-1"]
[tester::#YG4] [handshake] Received ["PSYNC", "?", "-1"]
[your_program] 
[your_program] 16:55:22.249 [debug] Received raw bytes: <<43, 79, 75, 13, 10>>
[your_program] 
[your_program] 16:55:22.249 [debug] Received expected response
[tester::#YG4] [handshake] master: Sent "FULLRESYNC 75cd7bc10c49047e0d163660f3b90625b1af31dc 0"
[tester::#YG4] [handshake] master: Sent bytes: "+FULLRESYNC 75cd7bc10c49047e0d163660f3b90625b1af31dc 0\r\n"
[tester::#YG4] [handshake] Sending RDB file...
[tester::#YG4] [handshake] master: Sent bytes: "$88\r\nREDIS0011\xfa\tredis-ver\x057.2.0\xfa\nredis-bits\xc0@\xfa\x05ctime\xc2m\b\xbce\xfa\bused-mem°\xc4\x10\x00\xfa\baof-base\xc0\x00\xff\xf0n;\xfe\xc0\xffZ\xa2"
[tester::#YG4] [handshake] Sent RDB file.
[tester::#YG4] [propagation] master: > SET foo 123
[tester::#YG4] [propagation] master: Sent bytes: "*3\r\n$3\r\nSET\r\n$3\r\nfoo\r\n$3\r\n123\r\n"
[tester::#YG4] [propagation] master: > SET bar 456
[tester::#YG4] [propagation] master: Sent bytes: "*3\r\n$3\r\nSET\r\n$3\r\nbar\r\n$3\r\n456\r\n"
[tester::#YG4] [propagation] master: > SET baz 789
[tester::#YG4] [propagation] master: Sent bytes: "*3\r\n$3\r\nSET\r\n$3\r\nbaz\r\n$3\r\n789\r\n"
[tester::#YG4] [test] Getting key foo
[tester::#YG4] [test] client: $ redis-cli GET foo
[tester::#YG4] [test] client: Sent bytes: "*2\r\n$3\r\nGET\r\n$3\r\nfoo\r\n"
[your_program] 
[your_program] 16:55:22.251 [debug] Received PSYNC response: <<43, 70, 85, 76, 76, 82, 69, 83, 89, 78, 67, 32, 55, 53, 99, 100, 55, 98, 99, 49, 48, 99, 52, 57, 48, 52, 55, 101, 48, 100, 49, 54, 51, 54, 54, 48, 102, 51, 98, 57, 48, 54, 50, 53, 98, 49, 97, 102, 51, 49, 100, 99, 32, 48, 13, 10>>
[your_program] Received command: "*2\r\n$3\r\nGET\r\n$3\r\nfoo\r\n"
[your_program] Parsed data: ["GET", "foo"]
[your_program] 
[your_program] 16:55:22.255 [debug] PSYNC successful. Replication ID: 75cd7bc10c49047e0d163660f3b90625b1af31dc, Offset: 0
[your_program] 
[your_program] 16:55:22.255 [info] Starting to receive data from socket
[your_program] 
[your_program] 16:55:22.255 [debug] Receiving data. Buffer size: 0, Expected length: 0
[your_program] 
[your_program] 16:55:22.256 [debug] Received raw bytes: <<36, 56, 56, 13, 10, 82, 69, 68, 73, 83, 48, 48, 49, 49, 250, 9, 114, 101, 100, 105, 115, 45, 118, 101, 114, 5, 55, 46, 50, 46, 48, 250, 10, 114, 101, 100, 105, 115, 45, 98, 105, 116, 115, 192, 64, 250, 5, 99, 116, 105, 109, 101, 194, 109, 8, 188, 101, 250, 8, 117, 115, 101, 100, 45, 109, 101, 109, 194, 176, 196, 16, 0, 250, 8, 97, 111, 102, 45, 98, 97, 115, 101, 192, 0, 255, 240, 110, 59, 254, 192, 255, 90, 162, 42, 51, 13, 10, 36, 51, 13, 10, 83, 69, 84, 13, 10, 36, 51, 13, 10, 102, 111, 111, 13, 10, 36, 51, 13, 10, 49, 50, 51, 13, 10, 42, 51, 13, 10, 36, 51, 13, 10, 83, 69, 84, 13, 10, 36, 51, 13, 10, 98, 97, 114, 13, 10, 36, 51, 13, 10, 52, 53, 54, 13, 10, 42, 51, 13, 10, 36, 51, 13, 10, 83, 69, 84, 13, 10, 36, 51, 13, 10, 98, 97, 122, 13, 10, 36, 51, 13, 10, 55, 56, 57, 13, 10>>
[your_program] 
[your_program] 16:55:22.256 [debug] Received chunk of size: 186 bytes
[your_program] 
[your_program] 16:55:22.256 [debug] Received data (as string): <<36, 56, 56, 13, 10, 82, 69, 68, 73, 83, 48, 48, 49, 49, 250, 9, 114, 101, 100, 105, 115, 45, 118, 101, 114, 5, 55, 46, 50, 46, 48, 250, 10, 114, 101, 100, 105, 115, 45, 98, 105, 116, 115, 192, 64, 250, 5, 99, 116, 105, ...>>
[your_program] 
[your_program] 16:55:22.256 [debug] New buffer size: 186 bytes
[your_program] 
[your_program] 16:55:22.256 [debug] Parsing data starting with '$'
[your_program] 
[your_program] 16:55:22.256 [info] Found RDB length indicator: 88 bytes
[your_program] 
[your_program] 16:55:22.257 [debug] Received enough data to potentially complete RDB or command
[your_program] 
[your_program] 16:55:22.257 [info] RDB file complete, parsing remaining data as command
[your_program] 
[your_program] 16:55:22.257 [info] Received data: "*3\r\n$3\r\nSET\r\n$3\r\nfoo\r\n$3\r\n123\r\n*3\r\n$3\r\nSET\r\n$3\r\nbar\r\n$3\r\n456\r\n*3\r\n$3\r\nSET\r\n$3\r\nbaz\r\n$3\r\n789\r\n"...
[your_program] 
[your_program] 16:55:22.257 [debug] Attempting to parse commands from data
[your_program] 
[your_program] 16:55:22.257 [debug] Parsing data: "*3\r\n$3\r\nSET\r\n$3\r\nfoo\r\n$3\r\n123\r\n*3\r\n$3\r\nSET\r\n$3\r\nbar\r\n$3\r\n456\r\n*3\r\n$3\r\nSET\r\n$3\r\nbaz\r\n$3\r\n789\r\n"
[your_program] 
[your_program] 16:55:22.257 [debug] Parsed command: ["SET", "foo", "123"], remaining: "*3\r\n$3\r\nSET\r\n$3\r\nbar\r\n$3\r\n456\r\n*3\r\n$3\r\nSET\r\n$3\r\nbaz\r\n$3\r\n789\r\n"
[your_program] 
[your_program] 16:55:22.257 [debug] Parsing data: "*3\r\n$3\r\nSET\r\n$3\r\nbar\r\n$3\r\n456\r\n*3\r\n$3\r\nSET\r\n$3\r\nbaz\r\n$3\r\n789\r\n"
[your_program] 
[your_program] 16:55:22.257 [debug] Parsed command: ["SET", "bar", "456"], remaining: "*3\r\n$3\r\nSET\r\n$3\r\nbaz\r\n$3\r\n789\r\n"
[your_program] 
[your_program] 16:55:22.257 [debug] Parsing data: "*3\r\n$3\r\nSET\r\n$3\r\nbaz\r\n$3\r\n789\r\n"
[your_program] 
[your_program] 16:55:22.257 [debug] Parsed command: ["SET", "baz", "789"], remaining: ""
[your_program] 
[your_program] 16:55:22.257 [debug] Finished parsing all commands: [["SET", "foo", "123"], ["SET", "bar", "456"], ["SET", "baz", "789"]]
[your_program] 
[your_program] 16:55:22.257 [info] Successfully parsed commands: [["SET", "foo", "123"], ["SET", "bar", "456"], ["SET", "baz", "789"]]
[your_program] 
[your_program] 16:55:22.257 [info] Received complete command: [["SET", "foo", "123"], ["SET", "bar", "456"], ["SET", "baz", "789"]]
[your_program] 
[your_program] 16:55:22.257 [info] Executing command: ["SET", "foo", "123"]
[tester::#YG4] [test] client: Received bytes: "$3\r\n123\r\n"
[tester::#YG4] [test] client: Received RESP bulk string: "123"
[your_program] Executing GET command for key: foo
[your_program] Value found: 123
[your_program] 
[your_program] 16:55:22.264 [info] Executing command: ["SET", "bar", "456"]
[your_program] 
[your_program] 16:55:22.264 [info] Executing command: ["SET", "baz", "789"]
[your_program] Socket state after handshake: [recv_oct: 259, recv_cnt: 5, recv_max: 186, recv_avg: 51, recv_dvi: 34, send_oct: 133, send_cnt: 4, send_max: 49, send_avg: 33, send_pend: 0]
[your_program] Process the received data carefully
[your_program] 
[your_program] 16:55:22.264 [info] Handshake completed successfully
[tester::#YG4] [test] Received "123"
[tester::#YG4] [test] Getting key bar
[tester::#YG4] [test] client: > GET bar
[tester::#YG4] [test] client: Sent bytes: "*2\r\n$3\r\nGET\r\n$3\r\nbar\r\n"
[your_program] Received command: "*2\r\n$3\r\nGET\r\n$3\r\nbar\r\n"
[your_program] Parsed data: ["GET", "bar"]
[your_program] Executing GET command for key: bar
[your_program] Value found: 456
[tester::#YG4] [test] client: Received bytes: "$3\r\n456\r\n"
[tester::#YG4] [test] client: Received RESP bulk string: "456"
[tester::#YG4] [test] Received "456"
[tester::#YG4] [test] Getting key baz
[tester::#YG4] [test] client: > GET baz
[tester::#YG4] [test] client: Sent bytes: "*2\r\n$3\r\nGET\r\n$3\r\nbaz\r\n"
[your_program] Received command: "*2\r\n$3\r\nGET\r\n$3\r\nbaz\r\n"
[your_program] Parsed data: ["GET", "baz"]
[your_program] Executing GET command for key: baz
[your_program] Value found: 789
[tester::#YG4] [test] client: Received bytes: "$3\r\n789\r\n"
[tester::#YG4] [test] client: Received RESP bulk string: "789"
[tester::#YG4] [test] Received "789"
[tester::#YG4] Test passed.
[tester::#YG4] Terminating program
[your_program] 
[your_program] 16:55:22.270 [notice] SIGTERM received - shutting down
[your_program] 
[tester::#YG4] Program terminated successfully

and

#---------------------------------
but when the test is failing these are the logs

[tester::#YG4] [handshake] master: Waiting for replica to initiate handshake with "PING" command
[your_program] Socket state before handshake: [recv_oct: 0, recv_cnt: 0, recv_max: 0, recv_avg: 0, recv_dvi: 0, send_oct: 0, send_cnt: 0, send_max: 0, send_avg: 0, send_pend: 0]
[tester::#YG4] [handshake] master: Received bytes: "*1\r\n$4\r\nPING\r\n"
[tester::#YG4] [handshake] master: Received RESP array: ["PING"]
[tester::#YG4] [handshake] Received ["PING"]
[tester::#YG4] [handshake] master: Sent "PONG"
[tester::#YG4] [handshake] master: Sent bytes: "+PONG\r\n"
[tester::#YG4] [handshake] master: Waiting for replica to send "REPLCONF listening-port 6380" command
[your_program] 
[your_program] 17:32:17.177 [debug] Received raw bytes: <<43, 80, 79, 78, 71, 13, 10>>
[your_program] 
[your_program] 17:32:17.180 [debug] Received expected response
[tester::#YG4] [handshake] master: Received bytes: "*3\r\n$8\r\nREPLCONF\r\n$14\r\nlistening-port\r\n$4\r\n6380\r\n"
[tester::#YG4] [handshake] master: Received RESP array: ["REPLCONF", "listening-port", "6380"]
[tester::#YG4] [handshake] Received ["REPLCONF", "listening-port", "6380"]
[tester::#YG4] [handshake] master: Sent "OK"
[tester::#YG4] [handshake] master: Sent bytes: "+OK\r\n"
[tester::#YG4] [handshake] master: Waiting for replica to send "REPLCONF capa" command
[tester::#YG4] [handshake] master: Received bytes: "*3\r\n$8\r\nREPLCONF\r\n$4\r\ncapa\r\n$6\r\npsync2\r\n"
[tester::#YG4] [handshake] master: Received RESP array: ["REPLCONF", "capa", "psync2"]
[tester::#YG4] [handshake] Received ["REPLCONF", "capa", "psync2"]
[your_program] 
[your_program] 17:32:17.187 [debug] Received raw bytes: <<43, 79, 75, 13, 10>>
[your_program] 
[your_program] 17:32:17.187 [debug] Received expected response
[tester::#YG4] [handshake] master: Sent "OK"
[tester::#YG4] [handshake] master: Sent bytes: "+OK\r\n"
[tester::#YG4] [handshake] master: Waiting for replica to send "PSYNC" command
[tester::#YG4] [handshake] master: Received bytes: "*3\r\n$5\r\nPSYNC\r\n$1\r\n?\r\n$2\r\n-1\r\n"
[tester::#YG4] [handshake] master: Received RESP array: ["PSYNC", "?", "-1"]
[tester::#YG4] [handshake] Received ["PSYNC", "?", "-1"]
[your_program] 
[your_program] 17:32:17.189 [debug] Received raw bytes: <<43, 79, 75, 13, 10>>
[your_program] 
[your_program] 17:32:17.189 [debug] Received expected response
[tester::#YG4] [handshake] master: Sent "FULLRESYNC 75cd7bc10c49047e0d163660f3b90625b1af31dc 0"
[tester::#YG4] [handshake] master: Sent bytes: "+FULLRESYNC 75cd7bc10c49047e0d163660f3b90625b1af31dc 0\r\n"
[tester::#YG4] [handshake] Sending RDB file...
[tester::#YG4] [handshake] master: Sent bytes: "$88\r\nREDIS0011\xfa\tredis-ver\x057.2.0\xfa\nredis-bits\xc0@\xfa\x05ctime\xc2m\b\xbce\xfa\bused-mem°\xc4\x10\x00\xfa\baof-base\xc0\x00\xff\xf0n;\xfe\xc0\xffZ\xa2"
[tester::#YG4] [handshake] Sent RDB file.
[tester::#YG4] [propagation] master: > SET foo 123
[tester::#YG4] [propagation] master: Sent bytes: "*3\r\n$3\r\nSET\r\n$3\r\nfoo\r\n$3\r\n123\r\n"
[tester::#YG4] [propagation] master: > SET bar 456
[tester::#YG4] [propagation] master: Sent bytes: "*3\r\n$3\r\nSET\r\n$3\r\nbar\r\n$3\r\n456\r\n"
[tester::#YG4] [propagation] master: > SET baz 789
[tester::#YG4] [propagation] master: Sent bytes: "*3\r\n$3\r\nSET\r\n$3\r\nbaz\r\n$3\r\n789\r\n"
[tester::#YG4] [test] Getting key foo
[tester::#YG4] [test] client: $ redis-cli GET foo
[tester::#YG4] [test] client: Sent bytes: "*2\r\n$3\r\nGET\r\n$3\r\nfoo\r\n"
[your_program] 
[your_program] 17:32:17.191 [debug] Received PSYNC response: <<43, 70, 85, 76, 76, 82, 69, 83, 89, 78, 67, 32, 55, 53, 99, 100, 55, 98, 99, 49, 48, 99, 52, 57, 48, 52, 55, 101, 48, 100, 49, 54, 51, 54, 54, 48, 102, 51, 98, 57, 48, 54, 50, 53, 98, 49, 97, 102, 51, 49, ...>>
[your_program] Received command: "*2\r\n$3\r\nGET\r\n$3\r\nfoo\r\n"
[your_program] Parsed data: ["GET", "foo"]
[your_program] FORMATTER ERROR: bad return value
[your_program] 
[your_program] 17:32:17.196 [info] Starting to receive data from socket
[your_program] 
[your_program] 17:32:17.196 [debug] Receiving data. Buffer size: 0, Expected length: 0
[your_program] Executing GET command for key: foo
[tester::#YG4] [test] client: Received bytes: "$-1\r\n"
[tester::#YG4] [test] client: Received RESP null bulk string: "$-1\r\n"
[your_program] 
[your_program] 17:32:17.196 [debug] ** (RuntimeError) bad return value from Logger formatter Logger.Formatter, got [<<250, 9, 114, 101, 100, 105, 115, 45, 118, 101, 114, 5, 55, 46, 50, 46, 48, 250, 10, 114, 101, 100, 105, 115, 45, 98, 105, 116, 115, 192, 64, 250, 5, 99, 116, 105, 109, 101, 194, 109, 8, 188, 101, 250, 8, 117, 115, 101, 100, ...>>, "\n"] after "\n17:32:17.195 [debug] PSYNC successful. Replication ID: 75cd7bc10c49047e0d163660f3b90625b1af31dc, Offset: 0\r\n$88\r\nREDIS0011"
[your_program]     (kernel 9.2.4) logger_h_common.erl:430: :logger_h_common.string_to_binary/1
[your_program]     (kernel 9.2.4) logger_h_common.erl:396: :logger_h_common.do_log_to_binary/2
[your_program]     (kernel 9.2.4) logger_h_common.erl:177: :logger_h_common.log/2
[your_program]     (kernel 9.2.4) logger_backend.erl:51: :logger_backend.call_handlers/3
[your_program]     (redis 1.0.0) lib/server.ex:172: Server.receive_psync_response/1
[your_program]     (redis 1.0.0) lib/server.ex:100: Server.perform_handshake/2
[your_program]     (redis 1.0.0) lib/server.ex:59: Server.connect_to_master/2
[your_program] 
[tester::#YG4] [test] Retrying... (1/5 attempts)
[tester::#YG4] [test] client: > GET foo
[tester::#YG4] [test] client: Sent bytes: "*2\r\n$3\r\nGET\r\n$3\r\nfoo\r\n"
[your_program] Received command: "*2\r\n$3\r\nGET\r\n$3\r\nfoo\r\n"
[your_program] Parsed data: ["GET", "foo"]
[your_program] Executing GET command for key: foo
[tester::#YG4] [test] client: Received bytes: "$-1\r\n"
[tester::#YG4] [test] client: Received RESP null bulk string: "$-1\r\n"
[tester::#YG4] [test] Retrying... (2/5 attempts)
[tester::#YG4] [test] client: > GET foo
[tester::#YG4] [test] client: Sent bytes: "*2\r\n$3\r\nGET\r\n$3\r\nfoo\r\n"
[your_program] Received command: "*2\r\n$3\r\nGET\r\n$3\r\nfoo\r\n"
[your_program] Parsed data: ["GET", "foo"]
[your_program] Executing GET command for key: foo
[tester::#YG4] [test] client: Received bytes: "$-1\r\n"
[tester::#YG4] [test] client: Received RESP null bulk string: "$-1\r\n"
[tester::#YG4] [test] Retrying... (3/5 attempts)
[tester::#YG4] [test] client: > GET foo
[tester::#YG4] [test] client: Sent bytes: "*2\r\n$3\r\nGET\r\n$3\r\nfoo\r\n"
[your_program] Received command: "*2\r\n$3\r\nGET\r\n$3\r\nfoo\r\n"
[your_program] Parsed data: ["GET", "foo"]
[your_program] Executing GET command for key: foo
[tester::#YG4] [test] client: Received bytes: "$-1\r\n"
[tester::#YG4] [test] client: Received RESP null bulk string: "$-1\r\n"
[tester::#YG4] [test] Retrying... (4/5 attempts)
[tester::#YG4] [test] client: > GET foo
[tester::#YG4] [test] client: Sent bytes: "*2\r\n$3\r\nGET\r\n$3\r\nfoo\r\n"
[your_program] Received command: "*2\r\n$3\r\nGET\r\n$3\r\nfoo\r\n"
[your_program] Parsed data: ["GET", "foo"]
[your_program] Executing GET command for key: foo
[tester::#YG4] [test] client: Received bytes: "$-1\r\n"
[tester::#YG4] [test] client: Received RESP null bulk string: "$-1\r\n"
[tester::#YG4] [test] Retrying... (5/5 attempts)
[tester::#YG4] [test] client: > GET foo
[tester::#YG4] [test] client: Sent bytes: "*2\r\n$3\r\nGET\r\n$3\r\nfoo\r\n"
[your_program] Received command: "*2\r\n$3\r\nGET\r\n$3\r\nfoo\r\n"
[your_program] Parsed data: ["GET", "foo"]
[your_program] Executing GET command for key: foo
[tester::#YG4] [test] client: Received bytes: "$-1\r\n"
[tester::#YG4] [test] client: Received RESP null bulk string: "$-1\r\n"
[tester::#YG4] Expected simple string or bulk string, got NIL
[tester::#YG4] Test failed
[tester::#YG4] Terminating program
[your_program] 
[your_program] 17:32:20.266 [notice] SIGTERM received - shutting down
[your_program] 
[your_program] Socket state after handshake: [recv_oct: 259, recv_cnt: 4, recv_max: 242, recv_avg: 64, recv_dvi: 43, send_oct: 133, send_cnt: 4, send_max: 49, send_avg: 33, send_pend: 0]
[your_program] 
[your_program] 17:32:20.266 [error] Error receiving data: :closed
[your_program] 
[your_program] 17:32:20.266 [error] Failed to receive RDB file: :closed
[your_program] 
[your_program] 17:32:20.268 [info] Handshake completed successfully
[tester::#YG4] Program terminated successfully

m-czernek · August 1, 2024, 5:54pm

My problem was that sometimes, the replication data can come together with the rdb_file, so in case you think you parse rdb_file and then listen for more data, chances are that the replication data is mixed in with your “rdb_file” bytes.

rohitpaulk · August 1, 2024, 7:37pm

@ProgMastermind the logs seem to be truncated by your logging library, so it isn’t clear whether this contains extra bytes (other than the RDB) or not. Can you try logging the whole thing?

rohitpaulk · August 1, 2024, 7:38pm

And btw, you can use triple backticks to format your logs better (I did it for your messages above, thought I’d highlight in case you weren’t aware!)

Topic		Replies	Views
[Gleam] Stuck on Redis Challenge, Replication, Stage 13 Challenges challenge:redis	3	89	June 5, 2024
Redis Challenge: Stuck on Command Processing Challenges challenge:redis	6	159	October 4, 2024
[Redis][Python] Stuck on #YG4 - Command Processing Challenges challenge:redis	5	28	January 25, 2025
Redis Challenge Stage #YG4: only some set commands reach replica (Go) Challenges challenge:redis	8	200	October 4, 2024
Go trouble with replica processing commands Challenges challenge:redis	1	26	February 9, 2025

Hardly Stuck on Challange #YG$

Related topics