Hello! I’ve been having some trouble with YG4 and XV6. The test occasionally passes, but often times it seems like the test never sends anything on the connection after I read out the RDB file
I read the RDB file here then start up a client handler for the master where I then expect to process more messages from the master, but most of the time the master never sends the next message and I’m not sure why. Occasionally these 2 tests will pass, but a majority of the time my replica never receives the message that the server is sending afterwards. I’ve tried placing in some log messages and the client handler for the master is stuck waiting on the conn.Read() even though the tester claims to have sent more message
[tester::#XV6] Running tests for Stage #XV6 (Replication - ACKs with no commands)
[tester::#XV6] Master is running on port 6379
[tester::#XV6] $ ./spawn_redis_server.sh --port 6380 --replicaof "localhost 6379"
[tester::#XV6] [handshake] master: Waiting for replica to initiate handshake with "PING" command
[tester::#XV6] [handshake] master: Received bytes: "*1\r\n$4\r\nping\r\n"
[tester::#XV6] [handshake] master: Received RESP array: ["ping"]
[tester::#XV6] [handshake] Received ["ping"]
[your_program] {"level":"info","ts":1734834647.78963,"caller":"server/handler.go:40","msg":"starting event loop","serverListenPort":6380,"nodeType":"slave"}
[your_program] {"level":"info","ts":1734834647.7900174,"caller":"server/handler.go:79","msg":"starting expiry loop","serverListenPort":6380,"nodeType":"slave"}
[your_program] {"level":"info","ts":1734834647.7900817,"caller":"server/handler.go:117","msg":"starting connection handler at %q","connectionAddr":"[::]:6380","serverListenPort":6380,"nodeType":"slave"}
[tester::#XV6] [handshake] master: Sent "PONG"
[tester::#XV6] [handshake] master: Sent bytes: "+PONG\r\n"
[tester::#XV6] [handshake] master: Waiting for replica to send "REPLCONF listening-port 6380" command
[tester::#XV6] [handshake] master: Received bytes: "*3\r\n$8\r\nreplconf\r\n$14\r\nlistening-port\r\n$4\r\n6380\r\n"
[tester::#XV6] [handshake] master: Received RESP array: ["replconf", "listening-port", "6380"]
[tester::#XV6] [handshake] Received ["replconf", "listening-port", "6380"]
[tester::#XV6] [handshake] master: Sent "OK"
[tester::#XV6] [handshake] master: Sent bytes: "+OK\r\n"
[tester::#XV6] [handshake] master: Waiting for replica to send "REPLCONF capa" command
[your_program] {"level":"info","ts":1734834647.7922037,"caller":"server/replica.go:176","msg":"successfully sent command to master node","masterAddress":"localhost:6379","command":"*1\r\n$4\r\nping\r\n","serverListenPort":6380,"nodeType":"slave"}
[your_program] {"level":"info","ts":1734834647.7928157,"caller":"server/replica.go:176","msg":"successfully sent command to master node","masterAddress":"localhost:6379","command":"*3\r\n$8\r\nreplconf\r\n$14\r\nlistening-port\r\n$4\r\n6380\r\n","serverListenPort":6380,"nodeType":"slave"}
[tester::#XV6] [handshake] master: Received bytes: "*3\r\n$8\r\nreplconf\r\n$4\r\ncapa\r\n$6\r\npsync2\r\n"
[tester::#XV6] [handshake] master: Received RESP array: ["replconf", "capa", "psync2"]
[tester::#XV6] [handshake] Received ["replconf", "capa", "psync2"]
[tester::#XV6] [handshake] master: Sent "OK"
[tester::#XV6] [handshake] master: Sent bytes: "+OK\r\n"
[tester::#XV6] [handshake] master: Waiting for replica to send "PSYNC" command
[your_program] {"level":"info","ts":1734834647.7949598,"caller":"server/replica.go:176","msg":"successfully sent command to master node","masterAddress":"localhost:6379","command":"*3\r\n$8\r\nreplconf\r\n$4\r\ncapa\r\n$6\r\npsync2\r\n","serverListenPort":6380,"nodeType":"slave"}
[tester::#XV6] [handshake] master: Received bytes: "*3\r\n$5\r\npsync\r\n$1\r\n?\r\n$2\r\n-1\r\n"
[tester::#XV6] [handshake] master: Received RESP array: ["psync", "?", "-1"]
[tester::#XV6] [handshake] Received ["psync", "?", "-1"]
[tester::#XV6] [handshake] master: Sent "FULLRESYNC 75cd7bc10c49047e0d163660f3b90625b1af31dc 0"
[tester::#XV6] [handshake] master: Sent bytes: "+FULLRESYNC 75cd7bc10c49047e0d163660f3b90625b1af31dc 0\r\n"
[tester::#XV6] [handshake] Sending RDB file...
[tester::#XV6] [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::#XV6] [handshake] Sent RDB file.
[tester::#XV6] [test] master: > REPLCONF GETACK *
[tester::#XV6] [test] master: Sent bytes: "*3\r\n$8\r\nREPLCONF\r\n$6\r\nGETACK\r\n$1\r\n*\r\n"
[your_program] {"level":"info","ts":1734834647.796829,"caller":"server/replica.go:113","msg":"received response to PSYNC command","response":"+FULLRESYNC 75cd7bc10c49047e0d163660f3b90625b1af31dc 0\r\n","serverListenPort":6380,"nodeType":"slave"}
[your_program] {"level":"info","ts":1734834647.7968588,"caller":"server/replica.go:117","msg":"received RDB file size string","data":"$88\r\n","serverListenPort":6380,"nodeType":"slave"}
[your_program] {"level":"info","ts":1734834647.796871,"caller":"server/replica.go:136","msg":"received RDB data","data":"REDIS0011\ufffd\tredis-ver\u00057.2.0\ufffd\nredis-bits\ufffd@\ufffd\u0005ctime\ufffdm\u0008\ufffde\ufffd\u0008used-mem°\ufffd\u0010\u0000\ufffd\u0008aof-base\ufffd\u0000\ufffd\ufffdn;\ufffd\ufffd\ufffdZ\ufffd","serverListenPort":6380,"nodeType":"slave"}
[your_program] {"level":"info","ts":1734834647.7979746,"caller":"server/handler.go:165","msg":"starting client handler","remoteAddress":"[::1]:6379","serverListenPort":6380,"nodeType":"slave"}
[tester::#XV6] Received: "" (no content received)
[tester::#XV6] ^ error
[tester::#XV6] Error: Expected start of a new RESP2 value (either +, -, :, $ or *)
[tester::#XV6] Test failed
[tester::#XV6] Terminating program
[your_program] {"level":"error","ts":1734834649.7980716,"caller":"server/handler.go:176","msg":"error reading from client connection","error":"EOF","serverListenPort":6380,"nodeType":"slave","stacktrace":"github.com/codecrafters-io/redis-starter-go/app/server.BaseServer.clientHandler\n\t/app/app/server/handler.go:176"}
[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"
[tester::#YG4] [handshake] master: Waiting for replica to initiate handshake with "PING" command
[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"]
[your_program] {"level":"info","ts":1734834883.348989,"caller":"server/handler.go:79","msg":"starting expiry loop","serverListenPort":6380,"nodeType":"slave"}
[your_program] {"level":"info","ts":1734834883.3490882,"caller":"server/handler.go:117","msg":"starting connection handler at %q","connectionAddr":"[::]:6380","serverListenPort":6380,"nodeType":"slave"}
[your_program] {"level":"info","ts":1734834883.3491163,"caller":"server/handler.go:40","msg":"starting event loop","serverListenPort":6380,"nodeType":"slave"}
[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] {"level":"info","ts":1734834883.3526483,"caller":"server/replica.go:176","msg":"successfully sent command to master node","masterAddress":"localhost:6379","command":"*1\r\n$4\r\nping\r\n","serverListenPort":6380,"nodeType":"slave"}
[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] {"level":"info","ts":1734834883.3633873,"caller":"server/replica.go:176","msg":"successfully sent command to master node","masterAddress":"localhost:6379","command":"*3\r\n$8\r\nreplconf\r\n$14\r\nlistening-port\r\n$4\r\n6380\r\n","serverListenPort":6380,"nodeType":"slave"}
[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] {"level":"info","ts":1734834883.3649983,"caller":"server/replica.go:176","msg":"successfully sent command to master node","masterAddress":"localhost:6379","command":"*3\r\n$8\r\nreplconf\r\n$4\r\ncapa\r\n$6\r\npsync2\r\n","serverListenPort":6380,"nodeType":"slave"}
[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.
[your_program] {"level":"info","ts":1734834883.366641,"caller":"server/replica.go:113","msg":"received response to PSYNC command","response":"+FULLRESYNC 75cd7bc10c49047e0d163660f3b90625b1af31dc 0\r\n","serverListenPort":6380,"nodeType":"slave"}
[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] {"level":"info","ts":1734834883.3676186,"caller":"server/replica.go:117","msg":"received RDB file size string","data":"$88\r\n","serverListenPort":6380,"nodeType":"slave"}
[your_program] {"level":"info","ts":1734834883.3676946,"caller":"server/replica.go:136","msg":"received RDB data","data":"REDIS0011\ufffd\tredis-ver\u00057.2.0\ufffd\nredis-bits\ufffd@\ufffd\u0005ctime\ufffdm\u0008\ufffde\ufffd\u0008used-mem°\ufffd\u0010\u0000\ufffd\u0008aof-base\ufffd\u0000\ufffd\ufffdn;\ufffd\ufffd\ufffdZ\ufffd","serverListenPort":6380,"nodeType":"slave"}
[your_program] {"level":"info","ts":1734834883.3678212,"caller":"server/handler.go:165","msg":"starting client handler","remoteAddress":"[::1]:6379","serverListenPort":6380,"nodeType":"slave"}
[tester::#YG4] [test] client: Received bytes: "$-1\r\n"
[tester::#YG4] [test] client: Received RESP null bulk string: "$-1\r\n"
[your_program] {"level":"info","ts":1734834883.3682907,"caller":"server/handler.go:132","msg":"accepted connection from client","remoteAddress":"[::1]:43662","serverListenPort":6380,"nodeType":"slave"}
[your_program] {"level":"info","ts":1734834883.368403,"caller":"server/handler.go:165","msg":"starting client handler","remoteAddress":"[::1]:43662","serverListenPort":6380,"nodeType":"slave"}
[your_program] {"level":"info","ts":1734834883.3684983,"caller":"server/handler.go:181","msg":"received command","command":"*2\r\n$3\r\nGET\r\n$3\r\nfoo\r\n","serverListenPort":6380,"nodeType":"slave"}
[your_program] {"level":"info","ts":1734834883.3685212,"caller":"server/handler.go:47","msg":"processing event","command":"*2\r\n$3\r\nGET\r\n$3\r\nfoo\r\n","remoteAddress":"[::1]:43662","serverListenPort":6380,"nodeType":"slave"}
[your_program] {"level":"info","ts":1734834883.3685806,"caller":"server/handler.go:65","msg":"executing commands","command":"GET: \"foo\"","serverListenPort":6380,"nodeType":"slave"}
[your_program] {"level":"info","ts":1734834883.3686075,"caller":"server/replica.go:148","msg":"replica executing command: GET: \"foo\"","serverListenPort":6380,"nodeType":"slave"}
[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"
[tester::#YG4] [test] client: Received bytes: "$-1\r\n"
[tester::#YG4] [test] client: Received RESP null bulk string: "$-1\r\n"
[your_program] {"level":"info","ts":1734834883.869071,"caller":"server/handler.go:181","msg":"received command","command":"*2\r\n$3\r\nGET\r\n$3\r\nfoo\r\n","serverListenPort":6380,"nodeType":"slave"}
[your_program] {"level":"info","ts":1734834883.8691168,"caller":"server/handler.go:47","msg":"processing event","command":"*2\r\n$3\r\nGET\r\n$3\r\nfoo\r\n","remoteAddress":"[::1]:43662","serverListenPort":6380,"nodeType":"slave"}
[your_program] {"level":"info","ts":1734834883.8691354,"caller":"server/handler.go:65","msg":"executing commands","command":"GET: \"foo\"","serverListenPort":6380,"nodeType":"slave"}
[your_program] {"level":"info","ts":1734834883.869152,"caller":"server/replica.go:148","msg":"replica executing command: GET: \"foo\"","serverListenPort":6380,"nodeType":"slave"}
[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"
[tester::#YG4] [test] client: Received bytes: "$-1\r\n"
[tester::#YG4] [test] client: Received RESP null bulk string: "$-1\r\n"
[your_program] {"level":"info","ts":1734834884.3699317,"caller":"server/handler.go:181","msg":"received command","command":"*2\r\n$3\r\nGET\r\n$3\r\nfoo\r\n","serverListenPort":6380,"nodeType":"slave"}
[your_program] {"level":"info","ts":1734834884.369991,"caller":"server/handler.go:47","msg":"processing event","command":"*2\r\n$3\r\nGET\r\n$3\r\nfoo\r\n","remoteAddress":"[::1]:43662","serverListenPort":6380,"nodeType":"slave"}
[your_program] {"level":"info","ts":1734834884.3700147,"caller":"server/handler.go:65","msg":"executing commands","command":"GET: \"foo\"","serverListenPort":6380,"nodeType":"slave"}
[your_program] {"level":"info","ts":1734834884.3700337,"caller":"server/replica.go:148","msg":"replica executing command: GET: \"foo\"","serverListenPort":6380,"nodeType":"slave"}
[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"
[tester::#YG4] [test] client: Received bytes: "$-1\r\n"
[tester::#YG4] [test] client: Received RESP null bulk string: "$-1\r\n"
[your_program] {"level":"info","ts":1734834884.8708334,"caller":"server/handler.go:181","msg":"received command","command":"*2\r\n$3\r\nGET\r\n$3\r\nfoo\r\n","serverListenPort":6380,"nodeType":"slave"}
[your_program] {"level":"info","ts":1734834884.8708932,"caller":"server/handler.go:47","msg":"processing event","command":"*2\r\n$3\r\nGET\r\n$3\r\nfoo\r\n","remoteAddress":"[::1]:43662","serverListenPort":6380,"nodeType":"slave"}
[your_program] {"level":"info","ts":1734834884.8709128,"caller":"server/handler.go:65","msg":"executing commands","command":"GET: \"foo\"","serverListenPort":6380,"nodeType":"slave"}
[your_program] {"level":"info","ts":1734834884.8709269,"caller":"server/replica.go:148","msg":"replica executing command: GET: \"foo\"","serverListenPort":6380,"nodeType":"slave"}
[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"
[tester::#YG4] [test] client: Received bytes: "$-1\r\n"
[tester::#YG4] [test] client: Received RESP null bulk string: "$-1\r\n"
[your_program] {"level":"info","ts":1734834885.3722668,"caller":"server/handler.go:181","msg":"received command","command":"*2\r\n$3\r\nGET\r\n$3\r\nfoo\r\n","serverListenPort":6380,"nodeType":"slave"}
[your_program] {"level":"info","ts":1734834885.372317,"caller":"server/handler.go:47","msg":"processing event","command":"*2\r\n$3\r\nGET\r\n$3\r\nfoo\r\n","remoteAddress":"[::1]:43662","serverListenPort":6380,"nodeType":"slave"}
[your_program] {"level":"info","ts":1734834885.3723376,"caller":"server/handler.go:65","msg":"executing commands","command":"GET: \"foo\"","serverListenPort":6380,"nodeType":"slave"}
[your_program] {"level":"info","ts":1734834885.3723528,"caller":"server/replica.go:148","msg":"replica executing command: GET: \"foo\"","serverListenPort":6380,"nodeType":"slave"}
[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"
[tester::#YG4] [test] client: Received bytes: "$-1\r\n"
[tester::#YG4] [test] client: Received RESP null bulk string: "$-1\r\n"
Wondering if anyone else has run into this or might have an idea why my replica occassionally fails to read
