search

Netflix / dynomite

A generic dynamo implementation for different k-v storage engines
Apache License 2.0
4.19k stars 531 forks source link

Some commands not going thru dynomite #611

Closed rcmorano closed 5 years ago

rcmorano commented 6 years ago

Aloha,

I'm facing some weird connectivity problems and maybe someone can bring some light to the problem or help me to debug further.

I'm currently running a dynomite cluster inside Docker containers and everything is working as expected.

I wanted to try the cluster behind a F5 BIG-IP LTM and I haven't been able, for example, to healthcheck the cluster using a simple "info" command. I have used the same healthcheck mechanism directly against the redis servers that back the dynomite cluster and it works without problem.

Since I didn't trust the F5 healthcheck, I logged in via SSH into it and since I have no 'redis-cli' in the F5 load balancer, I've been using telnet/netcat to test the connections myself.

What I found, is that if I send a 'ping' command, I do receive reply:

[dummy@dummy-ltm02:Active:Changes Pending] ~ # telnet 10.x.x.x 6379 Trying 10.x.x.x... Connected to 10.x.x.x. Escape character is '^]'. ping +PONG ping +PONG ...

[2018-10-01 11:37:46.475] client_unref_internal_try_put:97 <CONN_CLIENT 0x559a9a0ef730 -1 from '172.20.0.1:41302'> unref owner <POOL 0x559a9a0ce4f0 'dyn_o_mite'> [2018-10-01 11:37:49.918] msg_send_chain:1115 About to dump out the content of msg [2018-10-01 11:37:49.918] msg_dump:683 msg dump id 7 request 1 len 6 type 87 done 0 error 0 (err 0) [2018-10-01 11:37:49.918] mbuf_dump:156 mbuf 0x559a9a0f3c10 with 6 bytes of data 00000000 70 69 6e 67 0d 0a |ping..| [2018-10-01 11:37:49.918] msg_dump:688 ================================================= [2018-10-01 11:37:49.919] msg_send_chain:1115 About to dump out the content of msg [2018-10-01 11:37:49.919] msg_dump:683 msg dump id 8 request 0 len 7 type 140 done 0 error 0 (err 0) [2018-10-01 11:37:49.919] mbuf_dump:156 mbuf 0x559a9a0f7f10 with 7 bytes of data 00000000 2b 50 4f 4e 47 0d 0a |+PONG..| [2018-10-01 11:37:49.919] msg_dump:688 =================================================

  • dynomite's strace log for the connection:

[pid 10] <... epoll_wait resumed> [{EPOLLIN, {u32=2584672048, u64=94122497996592}}], 1024, 30000) = 1 [pid 10] read(20, "ping\r\n", 16320) = 6 [pid 10] gettimeofday({tv_sec=1538393492, tv_usec=773211}, NULL) = 0 [pid 10] gettimeofday({tv_sec=1538393492, tv_usec=773554}, NULL) = 0 [pid 10] gettimeofday({tv_sec=1538393492, tv_usec=773851}, NULL) = 0 [pid 10] epoll_ctl(9, EPOLL_CTL_MOD, 10, {EPOLLIN|EPOLLOUT, {u32=2584535680, u64=94122497860224}}) = 0 [pid 10] gettimeofday({tv_sec=1538393492, tv_usec=774513}, NULL) = 0 [pid 10] gettimeofday({tv_sec=1538393492, tv_usec=774913}, NULL) = 0 [pid 10] getrusage(RUSAGE_SELF, {ru_utime={tv_sec=0, tv_usec=40000}, ru_stime={tv_sec=0, tv_usec=30000}, ...}) = 0 [pid 10] gettimeofday({tv_sec=1538393492, tv_usec=775664}, NULL) = 0 [pid 10] epoll_wait(9, [{EPOLLOUT, {u32=2584535680, u64=94122497860224}}], 1024, 4999) = 1 [pid 10] gettimeofday({tv_sec=1538393492, tv_usec=776240}, NULL) = 0 [pid 10] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=127, ...}) = 0 [pid 10] write(2, "[2018-10-01 11:31:32.776] msg_se"..., 83) = 83 [pid 10] gettimeofday({tv_sec=1538393492, tv_usec=777467}, NULL) = 0 [pid 10] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=127, ...}) = 0 [pid 10] write(2, "[2018-10-01 11:31:32.777] msg_du"..., 100) = 100 [pid 10] gettimeofday({tv_sec=1538393492, tv_usec=778215}, NULL) = 0 [pid 10] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=127, ...}) = 0 [pid 10] write(2, "[2018-10-01 11:31:32.778] mbuf_d"..., 81) = 81 [pid 10] write(2, "00000000 70 69 6e 67 0d 0a "..., 70) = 70 [pid 10] gettimeofday({tv_sec=1538393492, tv_usec=779403}, NULL) = 0 [pid 10] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=127, ...}) = 0 [pid 10] write(2, "[2018-10-01 11:31:32.779] msg_du"..., 89) = 89 [pid 10] writev(10, [{iov_base="ping\r\n", iov_len=6}], 1) = 6 [pid 10] gettimeofday({tv_sec=1538393492, tv_usec=781172}, NULL) = 0 [pid 10] gettimeofday({tv_sec=1538393492, tv_usec=781536}, NULL) = 0 [pid 10] epoll_ctl(9, EPOLL_CTL_MOD, 10, {EPOLLIN|EPOLLET, {u32=2584535680, u64=94122497860224}}) = 0 [pid 10] gettimeofday({tv_sec=1538393492, tv_usec=782157}, NULL) = 0 [pid 10] epoll_wait(9, [{EPOLLIN, {u32=2584535680, u64=94122497860224}}], 1024, 4992) = 1 [pid 10] read(10, "+PONG\r\n", 16320) = 7 [pid 10] gettimeofday({tv_sec=1538393492, tv_usec=783191}, NULL) = 0 [pid 10] epoll_ctl(9, EPOLL_CTL_MOD, 20, {EPOLLIN|EPOLLOUT, {u32=2584672048, u64=94122497996592}}) = 0 [pid 10] epoll_wait(9, [{EPOLLOUT, {u32=2584672048, u64=94122497996592}}], 1024, 30000) = 1 [pid 10] gettimeofday({tv_sec=1538393492, tv_usec=784248}, NULL) = 0 [pid 10] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=127, ...}) = 0 [pid 10] write(2, "[2018-10-01 11:31:32.784] msg_se"..., 83) = 83 ... continues writing debug to stdout ...

But, in the case I send an 'info' command or any get, dynomite process unexpectedly closes the connection:

[dummy@dummy-ltm02:Active:Changes Pending] ~ # telnet 10.x.x.x 6379 Trying 10.x.x.x... Connected to 10.x.x.x. Escape character is '^]'. ping +PONG ping +PONG info Connection closed by foreign host. [dummy@dummy-ltm02:Active:Changes Pending] ~ #

[2018-10-01 11:43:03.057] client_unref_internal_try_put:97 <CONN_CLIENT 0x559a9a0ef730 -1 from '172.20.0.1:41348'> unref owner <POOL 0x559a9a0ce4f0 'dyn_o_mite'>

[pid 10] <... epoll_wait resumed> [{EPOLLIN, {u32=2584672048, u64=94122497996592}}], 1024, 30000) = 1 [pid 10] read(20, "info\r\n", 16320) = 6 [pid 10] epoll_ctl(9, EPOLL_CTL_DEL, 20, NULL) = 0 [pid 10] close(20) = 0 [pid 10] gettimeofday({tv_sec=1538393519, tv_usec=128808}, NULL) = 0 [pid 10] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=127, ...}) = 0 [pid 10] write(2, "[2018-10-01 11:31:59.128] client"..., 162) = 162 [pid 10] getrusage(RUSAGE_SELF, {ru_utime={tv_sec=0, tv_usec=70000}, ru_stime={tv_sec=0, tv_usec=70000}, ...}) = 0 [pid 10] epoll_wait(9, <unfinished ...>

Examining the TCP session, a FIN reply is immediately found from dynomite's side right after receiving the command.

I know it might be (it most probably is) a problem related to my network, and I've been reading "notes/socket.txt" about dynomite's TCP stack handling, but still couldn't figure what might be going on; that's why I'm opening this issue just in case someone could point me to... somewhere, any help would be so much appreciated :)

Thanks in advance!

rcmorano commented 6 years ago

I've just compiled dynomite with --enable-debug=full (I thought I read somewhere that verbosity=11 gives the same output but it seems it doesn't) and now I have some more insight.

I did a quick telnet test on localhost and I got the same results (connection drop), so I can discard any "outside world" network issue by the moment, as it remains the same if I telnet dynomite directly. Of course, using redis-cli works like a charm.

Here you can find the logs from dynomite on both (local) scenarios:

[2018-10-01 13:50:28.854] event_wait:264 epoll 0001 triggered on conn 0x55b0e150f150 [2018-10-01 13:50:28.854] core_core:510 event 00FF on <CONN_PROXY 0x55b0e150f150 12 listening on '0.0.0.0:8102'> [2018-10-01 13:50:28.854] _dn_alloc:259 malloc(88) at 0x55b0e1522080 @ dyn_dict.c:178 [2018-10-01 13:50:28.854] client_ref:83 <CONN_CLIENT 0x55b0e1521dd0 -1 from ''> ref owner 0x55b0e15004f0 into pool 'dyn_o_mite' [2018-10-01 13:50:28.854] conn_get:205 get conn 0x55b0e1521dd0 CONN_CLIENT [2018-10-01 13:50:28.854] event_add_conn:207 adding conn <CONN_CLIENT 0x55b0e1521dd0 20 from '172.21.0.1:55502'> to active [2018-10-01 13:50:28.854] proxy_accept:214 <CONN_PROXY 0x55b0e150f150 12 listening on '0.0.0.0:8102'> accepted <CONN_CLIENT 0x55b0e1521dd0 20 from '172.21.0.1:55502'> [2018-10-01 13:50:28.854] core_process_messages:617 length of C2G_OutQ : 0 [2018-10-01 13:50:28.854] event_wait:264 epoll 0005 triggered on conn 0x55b0e1521dd0 [2018-10-01 13:50:28.854] core_core:510 event FFFF on <CONN_CLIENT 0x55b0e1521dd0 20 from '172.21.0.1:55502'> [2018-10-01 13:50:28.854] _dn_alloc:259 malloc(32) at 0x55b0e1512ee0 @ ../dyn_array.c:34 [2018-10-01 13:50:28.854] _dn_alloc:259 malloc(32) at 0x55b0e1526460 @ ../dyn_array.c:39 [2018-10-01 13:50:28.854] msg_get:470 get msg 0x55b0e1522100 id 15 request 1 owner sd 20 [2018-10-01 13:50:28.854] mbuf_get:121 get mbuf 0x55b0e1526410 [2018-10-01 13:50:28.854] mbuf_insert:223 insert mbuf 0x55b0e1526410 len 0 [2018-10-01 13:50:28.854] conn_recv_data:396 <CONN_CLIENT 0x55b0e1521dd0 20 from '172.21.0.1:55502'> recv 6 of 16320 [2018-10-01 13:50:28.854] redis_parse_req:2033 parsed bad req 15 res 1 type 0 state 0 00000000 69 6e 66 6f 0d 0a |info..| [2018-10-01 13:50:28.854] core_recv:389 <CONN_CLIENT 0x55b0e1521dd0 20 from '172.21.0.1:55502'> recv failed: Invalid argument [2018-10-01 13:50:28.854] core_close:419 close <CONN_CLIENT 0x55b0e1521dd0 20 from '172.21.0.1:55502'> on event FFFF eof 0 done 0 rb 6 sb 0: Invalid argument [2018-10-01 13:50:28.854] event_del_conn:230 removing conn <CONN_CLIENT 0x55b0e1521dd0 20 from '172.21.0.1:55502'> from active [2018-10-01 13:50:28.854] client_close:202 <CONN_CLIENT 0x55b0e1521dd0 20 from '172.21.0.1:55502'> close, discarding pending <REQ 0x55b0e1522100 15:0::0 UNKNOWN, len:6> len 6 [2018-10-01 13:50:28.854] mbuf_remove:246 remove mbuf 0x55b0e1526410 len 6 [2018-10-01 13:50:28.854] mbuf_put:162 put mbuf 0x55b0e1526410 len 6 [2018-10-01 13:50:28.854] _dn_free:305 free(0x55b0e1526460) @ ../dyn_array.c:82 [2018-10-01 13:50:28.854] _dn_free:305 free(0x55b0e1512ee0) @ ../dyn_array.c:56 [2018-10-01 13:50:28.855] client_unref_internal_try_put:97 <CONN_CLIENT 0x55b0e1521dd0 -1 from '172.21.0.1:55502'> unref owner <POOL 0x55b0e15004f0 'dyn_o_mite'> [2018-10-01 13:50:28.855] _dn_free:305 free(0x55b0e1522080) @ dyn_dict.c:491 [2018-10-01 13:50:28.855] conn_put:215 putting <CONN_CLIENT 0x55b0e1521dd0 -1 from '172.21.0.1:55502'> [2018-10-01 13:50:28.855] core_process_messages:617 length of C2G_OutQ : 0

[2018-10-01 13:55:43.149] event_wait:264 epoll 0001 triggered on conn 0x55b0e150f150 [2018-10-01 13:55:43.150] core_core:510 event 00FF on <CONN_PROXY 0x55b0e150f150 12 listening on '0.0.0.0:8102'> [2018-10-01 13:55:43.150] _dn_alloc:259 malloc(88) at 0x55b0e1522080 @ dyn_dict.c:178 [2018-10-01 13:55:43.150] client_ref:83 <CONN_CLIENT 0x55b0e1521dd0 -1 from ''> ref owner 0x55b0e15004f0 into pool 'dyn_o_mite' [2018-10-01 13:55:43.150] conn_get:205 get conn 0x55b0e1521dd0 CONN_CLIENT [2018-10-01 13:55:43.150] event_add_conn:207 adding conn <CONN_CLIENT 0x55b0e1521dd0 20 from '172.21.0.1:59844'> to active [2018-10-01 13:55:43.150] proxy_accept:214 <CONN_PROXY 0x55b0e150f150 12 listening on '0.0.0.0:8102'> accepted <CONN_CLIENT 0x55b0e1521dd0 20 from '172.21.0.1:59844'> [2018-10-01 13:55:43.150] core_process_messages:617 length of C2G_OutQ : 0 [2018-10-01 13:55:43.150] event_wait:264 epoll 0005 triggered on conn 0x55b0e1521dd0 [2018-10-01 13:55:43.150] core_core:510 event FFFF on <CONN_CLIENT 0x55b0e1521dd0 20 from '172.21.0.1:59844'> [2018-10-01 13:55:43.150] _dn_alloc:259 malloc(32) at 0x55b0e1512e70 @ ../dyn_array.c:34 [2018-10-01 13:55:43.150] _dn_alloc:259 malloc(32) at 0x55b0e1512ee0 @ ../dyn_array.c:39 [2018-10-01 13:55:43.150] msg_get:470 get msg 0x55b0e1522100 id 19 request 1 owner sd 20 [2018-10-01 13:55:43.150] mbuf_get:121 get mbuf 0x55b0e1526410 [2018-10-01 13:55:43.150] mbuf_insert:223 insert mbuf 0x55b0e1526410 len 0 [2018-10-01 13:55:43.150] conn_recv_data:396 <CONN_CLIENT 0x55b0e1521dd0 20 from '172.21.0.1:59844'> recv 14 of 16320 [2018-10-01 13:55:43.150] redis_parse_req:1410 parsed command 'info' [2018-10-01 13:55:43.150] redis_parse_req:2015 parsed req 19 res 0 type 76 state 0 rpos 14 of 14 00000000 2a 31 0d 0a 24 34 0d 0a 69 6e 66 6f 0d 0a |1..$4..info..| [2018-10-01 13:55:43.150] server_get_dc:618 server_get_dc dc 'dc1' [2018-10-01 13:55:43.150] server_get_rack:652 server_get_rack 'rack1' [2018-10-01 13:55:43.150] req_forward:863 >>>>>>>>>>>>>>>>>>>>>>> <CONN_CLIENT 0x55b0e1521dd0 20 from '172.21.0.1:59844'> RECEIVED <REQ 0x55b0e1522100 19:0::0 REQ_REDIS_INFO, len:14> key '' tagged key '' [2018-10-01 13:55:43.150] _dn_alloc:259 malloc(32) at 0x55b0e1526460 @ dyn_dict.c:224 [2018-10-01 13:55:43.150] _dn_alloc:259 malloc(24) at 0x55b0e152a9d0 @ dyn_dict.c:359 [2018-10-01 13:55:43.150] server_get_dc:618 server_get_dc dc 'dc1' [2018-10-01 13:55:43.150] server_get_rack:652 server_get_rack 'rack1' [2018-10-01 13:55:43.150] req_client_enqueue_omsgq:1093 <CONN_CLIENT 0x55b0e1521dd0 20 from '172.21.0.1:59844'> enqueue outq <REQ 0x55b0e1522100 19:0::0 REQ_REDIS_INFO, len:14> [2018-10-01 13:55:43.150] local_req_forward:555 c_conn 0x55b0e1521dd0 got server conn 0x55b0e1501570 [2018-10-01 13:55:43.150] local_req_forward:562 <CONN_CLIENT 0x55b0e1521dd0 20 from '172.21.0.1:59844'> FORWARD <REQ 0x55b0e1522100 19:0::0 REQ_REDIS_INFO, len:14> to storage conn <CONN_SERVER 0x55b0e1501570 11 to 'dynomite-poc_redis_1_1:6379:1'> [2018-10-01 13:55:43.150] event_add_out:150 adding conn <CONN_SERVER 0x55b0e1501570 11 to 'dynomite-poc_redis_1_1:6379:1'> to active [2018-10-01 13:55:43.150] msg_tmo_insert:272 insert req 19 into tmo rbt with expiry of 5000 msec [2018-10-01 13:55:43.150] req_server_enqueue_imsgq:967 conn 0x55b0e1501570 enqueue inq 19:0 [2018-10-01 13:55:43.150] local_req_forward:608 <CONN_CLIENT 0x55b0e1521dd0 20 from '172.21.0.1:59844'> local forward <REQ 0x55b0e1522100 19:0::0 REQ_REDIS_INFO, len:14> to <CONN_SERVER 0x55b0e1501570 11 to 'dynomite-poc_redis_1_1:6379:1'> len 14 key '' [2018-10-01 13:55:43.150] event_del_out:181 removing conn <CONN_CLIENT 0x55b0e1521dd0 20 from '172.21.0.1:59844'> from active [2018-10-01 13:55:43.150] core_process_messages:617 length of C2G_OutQ : 0 [2018-10-01 13:55:43.150] event_wait:264 epoll 0004 triggered on conn 0x55b0e1501570 [2018-10-01 13:55:43.150] core_core:510 event FF00 on <CONN_SERVER 0x55b0e1501570 11 to 'dynomite-poc_redis_1_1:6379:1'> [2018-10-01 13:55:43.150] req_send_next:912 send next req 19 len 14 type 76 on s 11 [2018-10-01 13:55:43.150] msg_send_chain:1115 About to dump out the content of msg [2018-10-01 13:55:43.150] msg_dump:683 msg dump id 19 request 1 len 14 type 76 done 0 error 0 (err 0) [2018-10-01 13:55:43.150] mbuf_dump:156 mbuf 0x55b0e1526410 with 14 bytes of data 00000000 2a 31 0d 0a 24 34 0d 0a 69 6e 66 6f 0d 0a |1..$4..info..| [2018-10-01 13:55:43.150] msg_dump:688 ================================================= [2018-10-01 13:55:43.150] conn_sendv_data:447 sendv on sd 11 14 of 14 in 1 buffers [2018-10-01 13:55:43.150] req_send_done:929 send done req 19 len 14 type 76 on s 11 [2018-10-01 13:55:43.150] req_server_dequeue_imsgq:981 conn 0x55b0e1501570 dequeue inq 19:0 [2018-10-01 13:55:43.150] req_server_enqueue_omsgq:997 conn 0x55b0e1501570 enqueue outq 19:0 [2018-10-01 13:55:43.150] event_del_out:181 removing conn <CONN_SERVER 0x55b0e1501570 11 to 'dynomite-poc_redis_1_1:6379:1'> from active [2018-10-01 13:55:43.150] core_process_messages:617 length of C2G_OutQ : 0 [2018-10-01 13:55:43.150] event_wait:264 epoll 0001 triggered on conn 0x55b0e1501570 [2018-10-01 13:55:43.150] core_core:510 event 00FF on <CONN_SERVER 0x55b0e1501570 11 to 'dynomite-poc_redis_1_1:6379:1'> [2018-10-01 13:55:43.150] _dn_alloc:259 malloc(32) at 0x55b0e15267f0 @ ../dyn_array.c:34 [2018-10-01 13:55:43.150] _dn_alloc:259 malloc(32) at 0x55b0e1526820 @ ../dyn_array.c:39 [2018-10-01 13:55:43.150] msg_get:470 get msg 0x55b0e15264b0 id 20 request 0 owner sd 11 [2018-10-01 13:55:43.150] mbuf_get:121 get mbuf 0x55b0e152a820 [2018-10-01 13:55:43.150] mbuf_insert:223 insert mbuf 0x55b0e152a820 len 0 [2018-10-01 13:55:43.150] conn_recv_data:396 <CONN_SERVER 0x55b0e1501570 11 to 'dynomite-poc_redis_1_1:6379:1'> recv 2723 of 16320 [2018-10-01 13:55:43.150] redis_parse_rsp:2588 parsed rsp 20 res 0 type 142 state 0 rpos 2723 of 2723 00000000 24 32 37 31 34 0d 0a 23 20 53 65 72 76 65 72 0d |$2714..# Server.| 00000010 0a 72 65 64 69 73 5f 76 65 72 73 69 6f 6e 3a 34 |.redis_version:4| 00000020 2e 30 2e 31 31 0d 0a 72 65 64 69 73 5f 67 69 74 |.0.11..redis_git| 00000030 5f 73 68 61 31 3a 30 30 30 30 30 30 30 30 0d 0a |_sha1:00000000..| 00000040 72 65 64 69 73 5f 67 69 74 5f 64 69 72 74 79 3a |redis_git_dirty:| 00000050 30 0d 0a 72 65 64 69 73 5f 62 75 69 6c 64 5f 69 |0..redis_build_i| 00000060 64 3a 37 65 61 33 39 30 36 65 38 31 36 39 35 35 |d:7ea3906e816955| 00000070 30 62 0d 0a 72 65 64 69 73 5f 6d 6f 64 65 3a 73 |0b..redis_mode:s| 00000080 74 61 6e 64 61 6c 6f 6e 65 0d 0a 6f 73 3a 4c 69 |tandalone..os:Li| 00000090 6e 75 78 20 34 2e 39 2e 39 33 2d 6c 69 6e 75 78 |nux 4.9.93-linux| 000000a0 6b 69 74 2d 61 75 66 73 20 78 38 36 5f 36 34 0d |kit-aufs x86_64.| 000000b0 0a 61 72 63 68 5f 62 69 74 73 3a 36 34 0d 0a 6d |.arch_bits:64..m| 000000c0 75 6c 74 69 70 6c 65 78 69 6e 67 5f 61 70 69 3a |ultiplexing_api:| 000000d0 65 70 6f 6c 6c 0d 0a 61 74 6f 6d 69 63 76 61 72 |epoll..atomicvar| 000000e0 5f 61 70 69 3a 61 74 6f 6d 69 63 2d 62 75 69 6c |_api:atomic-buil| 000000f0 74 69 6e 0d 0a 67 63 63 5f 76 65 72 73 69 6f 6e |tin..gccversion| 00000100 3a 36 2e 33 2e 30 0d 0a 70 72 6f 63 65 73 73 5f |:6.3.0..process| 00000110 69 64 3a 31 0d 0a 72 75 6e 5f 69 64 3a 34 37 62 |id:1..run_id:47b| 00000120 64 31 61 33 39 35 32 62 37 36 65 33 35 63 34 33 |d1a3952b76e35c43| 00000130 39 30 31 33 31 36 62 37 64 37 32 35 36 62 33 35 |901316b7d7256b35| 00000140 37 30 63 38 33 0d 0a 74 63 70 5f 70 6f 72 74 3a |70c83..tcp_port:| 00000150 36 33 37 39 0d 0a 75 70 74 69 6d 65 5f 69 6e 5f |6379..uptimein| 00000160 73 65 63 6f 6e 64 73 3a 39 36 33 0d 0a 75 70 74 |seconds:963..upt| 00000170 69 6d 65 5f 69 6e 5f 64 61 79 73 3a 30 0d 0a 68 |ime_in_days:0..h| 00000180 7a 3a 31 30 0d 0a 6c 72 75 5f 63 6c 6f 63 6b 3a |z:10..lruclock:| 00000190 31 31 36 37 35 34 38 37 0d 0a 65 78 65 63 75 74 |11675487..execut| 000001a0 61 62 6c 65 3a 2f 64 61 74 61 2f 72 65 64 69 73 |able:/data/redis| 000001b0 2d 73 65 72 76 65 72 0d 0a 63 6f 6e 66 69 67 5f |-server..config| 000001c0 66 69 6c 65 3a 0d 0a 0d 0a 23 20 43 6c 69 65 6e |file:....# Clien| 000001d0 74 73 0d 0a 63 6f 6e 6e 65 63 74 65 64 5f 63 6c |ts..connectedcl| 000001e0 69 65 6e 74 73 3a 31 0d 0a 63 6c 69 65 6e 74 5f |ients:1..client| 000001f0 6c 6f 6e 67 65 73 74 5f 6f 75 74 70 75 74 5f 6c |longest_output_l| 00000200 69 73 74 3a 30 0d 0a 63 6c 69 65 6e 74 5f 62 69 |ist:0..client_bi| 00000210 67 67 65 73 74 5f 69 6e 70 75 74 5f 62 75 66 3a |ggest_input_buf:| 00000220 30 0d 0a 62 6c 6f 63 6b 65 64 5f 63 6c 69 65 6e |0..blocked_clien| 00000230 74 73 3a 30 0d 0a 0d 0a 23 20 4d 65 6d 6f 72 79 |ts:0....# Memory| 00000240 0d 0a 75 73 65 64 5f 6d 65 6d 6f 72 79 3a 38 34 |..used_memory:84| 00000250 38 32 39 36 0d 0a 75 73 65 64 5f 6d 65 6d 6f 72 |8296..used_memor| 00000260 79 5f 68 75 6d 61 6e 3a 38 32 38 2e 34 31 4b 0d |y_human:828.41K.| 00000270 0a 75 73 65 64 5f 6d 65 6d 6f 72 79 5f 72 73 73 |.used_memory_rss| 00000280 3a 33 35 33 30 37 35 32 0d 0a 75 73 65 64 5f 6d |:3530752..used_m| 00000290 65 6d 6f 72 79 5f 72 73 73 5f 68 75 6d 61 6e 3a |emory_rss_human:| 000002a0 33 2e 33 37 4d 0d 0a 75 73 65 64 5f 6d 65 6d 6f |3.37M..used_memo| 000002b0 72 79 5f 70 65 61 6b 3a 38 36 39 31 33 36 0d 0a |ry_peak:869136..| 000002c0 75 73 65 64 5f 6d 65 6d 6f 72 79 5f 70 65 61 6b |used_memory_peak| 000002d0 5f 68 75 6d 61 6e 3a 38 34 38 2e 37 37 4b 0d 0a |_human:848.77K..| 000002e0 75 73 65 64 5f 6d 65 6d 6f 72 79 5f 70 65 61 6b |used_memory_peak| 000002f0 5f 70 65 72 63 3a 39 37 2e 36 30 25 0d 0a 75 73 |_perc:97.60%..us| 00000300 65 64 5f 6d 65 6d 6f 72 79 5f 6f 76 65 72 68 65 |ed_memoryoverhe| 00000310 61 64 3a 38 33 36 30 38 36 0d 0a 75 73 65 64 5f |ad:836086..used| 00000320 6d 65 6d 6f 72 79 5f 73 74 61 72 74 75 70 3a 37 |memory_startup:7| 00000330 38 36[2018-10-01 13:55:43.151] server_ok:327 reset server 'dynomite-poc_redis_1_1:6379:1' failure count from 0 to 0 [2018-10-01 13:55:43.151] msg_tmo_delete:292 delete req 19 from tmo rbt [2018-10-01 13:55:43.151] req_server_dequeue_omsgq:1013 conn 0x55b0e1501570 dequeue outq 19:0 [2018-10-01 13:55:43.151] server_rsp_forward:838 <CONN_CLIENT 0x55b0e1521dd0 20 from '172.21.0.1:59844'> <REQ 0x55b0e1522100 19:0::0 REQ_REDIS_INFO, len:14> RECEIVED <RSP 0x55b0e15264b0 20:0 RSP_REDIS_BULK len:2723> [2018-10-01 13:55:43.151] msg_local_one_rsp_handler:1049 -514711280 SELECTED -514693952 [2018-10-01 13:55:43.151] event_add_out:150 adding conn <CONN_CLIENT 0x55b0e1521dd0 20 from '172.21.0.1:59844'> to active [2018-10-01 13:55:43.151] core_process_messages:617 length of C2G_OutQ : 0 [2018-10-01 13:55:43.151] event_wait:264 epoll 0004 triggered on conn 0x55b0e1521dd0 [2018-10-01 13:55:43.151] core_core:510 event FF00 on <CONN_CLIENT 0x55b0e1521dd0 20 from '172.21.0.1:59844'> [2018-10-01 13:55:43.151] rsp_send_next:160 send next rsp 20 on c 20 [2018-10-01 13:55:43.151] msg_send_chain:1115 About to dump out the content of msg [2018-10-01 13:55:43.151] msg_dump:683 msg dump id 20 request 0 len 2723 type 142 done 0 error 0 (err 0) [2018-10-01 13:55:43.151] mbuf_dump:156 mbuf 0x55b0e152a820 with 2723 bytes of data 00000000 24 32 37 31 34 0d 0a 23 20 53 65 72 76 65 72 0d |$2714..# Server.| 00000010 0a 72 65 64 69 73 5f 76 65 72 73 69 6f 6e 3a 34 |.redis_version:4| 00000020 2e 30 2e 31 31 0d 0a 72 65 64 69 73 5f 67 69 74 |.0.11..redis_git| 00000030 5f 73 68 61 31 3a 30 30 30 30 30 30 30 30 0d 0a |_sha1:00000000..| 00000040 72 65 64 69 73 5f 67 69 74 5f 64 69 72 74 79 3a |redis_git_dirty:| 00000050 30 0d 0a 72 65 64 69 73 5f 62 75 69 6c 64 5f 69 |0..redis_build_i| 00000060 64 3a 37 65 61 33 39 30 36 65 38 31 36 39 35 35 |d:7ea3906e816955| 00000070 30 62 0d 0a 72 65 64 69 73 5f 6d 6f 64 65 3a 73 |0b..redis_mode:s| 00000080 74 61 6e 64 61 6c 6f 6e 65 0d 0a 6f 73 3a 4c 69 |tandalone..os:Li| 00000090 6e 75 78 20 34 2e 39 2e 39 33 2d 6c 69 6e 75 78 |nux 4.9.93-linux| 000000a0 6b 69 74 2d 61 75 66 73 20 78 38 36 5f 36 34 0d |kit-aufs x86_64.| 000000b0 0a 61 72 63 68 5f 62 69 74 73 3a 36 34 0d 0a 6d |.arch_bits:64..m| 000000c0 75 6c 74 69 70 6c 65 78 69 6e 67 5f 61 70 69 3a |ultiplexing_api:| 000000d0 65 70 6f 6c 6c 0d 0a 61 74 6f 6d 69 63 76 61 72 |epoll..atomicvar| 000000e0 5f 61 70 69 3a 61 74 6f 6d 69 63 2d 62 75 69 6c |_api:atomic-buil| 000000f0 74 69 6e 0d 0a 67 63 63 5f 76 65 72 73 69 6f 6e |tin..gccversion| 00000100 3a 36 2e 33 2e 30 0d 0a 70 72 6f 63 65 73 73 5f |:6.3.0..process| 00000110 69 64 3a 31 0d 0a 72 75 6e 5f 69 64 3a 34 37 62 |id:1..run_id:47b| 00000120 64 31 61 33 39 35 32 62 37 36 65 33 35 63 34 33 |d1a3952b76e35c43| 00000130 39 30 31 33 31 36 62 37 64 37 32 35 36 62 33 35 |901316b7d7256b35| 00000140 37 30 63 38 33 0d 0a 74 63 70 5f 70 6f 72 74 3a |70c83..tcp_port:| 00000150 36 33 37 39 0d 0a 75 70 74 69 6d 65 5f 69 6e 5f |6379..uptimein| 00000160 73 65 63 6f 6e 64 73 3a 39 36 33 0d 0a 75 70 74 |seconds:963..upt| 00000170 69 6d 65 5f 69 6e 5f 64 61 79 73 3a 30 0d 0a 68 |ime_in_days:0..h| 00000180 7a 3a 31 30 0d 0a 6c 72 75 5f 63 6c 6f 63 6b 3a |z:10..lruclock:| 00000190 31 31 36 37 35 34 38 37 0d 0a 65 78 65 63 75 74 |11675487..execut| 000001a0 61 62 6c 65 3a 2f 64 61 74 61 2f 72 65 64 69 73 |able:/data/redis| 000001b0 2d 73 65 72 76 65 72 0d 0a 63 6f 6e 66 69 67 5f |-server..config| 000001c0 66 69 6c 65 3a 0d 0a 0d 0a 23 20 43 6c 69 65 6e |file:....# Clien| 000001d0 74 73 0d 0a 63 6f 6e 6e 65 63 74 65 64 5f 63 6c |ts..connectedcl| 000001e0 69 65 6e 74 73 3a 31 0d 0a 63 6c 69 65 6e 74 5f |ients:1..client| 000001f0 6c 6f 6e 67 65 73 74 5f 6f 75 74 70 75 74 5f 6c |longest_output_l| 00000200 69 73 74 3a 30 0d 0a 63 6c 69 65 6e 74 5f 62 69 |ist:0..client_bi| 00000210 67 67 65 73 74 5f 69 6e 70 75 74 5f 62 75 66 3a |ggest_input_buf:| 00000220 30 0d 0a 62 6c 6f 63 6b 65 64 5f 63 6c 69 65 6e |0..blocked_clien| 00000230 74 73 3a 30 0d 0a 0d 0a 23 20 4d 65 6d 6f 72 79 |ts:0....# Memory| 00000240 0d 0a 75 73 65 64 5f 6d 65 6d 6f 72 79 3a 38 34 |..used_memory:84| 00000250 38 32 39 36 0d 0a 75 73 65 64 5f 6d 65 6d 6f 72 |8296..used_memor| 00000260 79 5f 68 75 6d 61 6e 3a 38 32 38 2e 34 31 4b 0d |y_human:828.41K.| 00000270 0a 75 73 65 64 5f 6d 65 6d 6f 72 79 5f 72 73 73 |.used_memory_rss| 00000280 3a 33 35 33 30 37 35 32 0d 0a 75 73 65 64 5f 6d |:3530752..used_m| 00000290 65 6d 6f 72 79 5f 72 73 73 5f 68 75 6d 61 6e 3a |emory_rss_human:| 000002a0 33 2e 33 37 4d 0d 0a 75 73 65 64 5f 6d 65 6d 6f |3.37M..used_memo| 000002b0 72 79 5f 70 65 61 6b 3a 38 36 39 31 33 36 0d 0a |ry_peak:869136..| 000002c0 75 73 65 64 5f 6d 65 6d 6f 72 79 5f 70 65 61 6b |used_memory_peak| 000002d0 5f 68 75 6d 61 6e 3a 38 34 38 2e 37 37 4b 0d 0a |_human:848.77K..| 000002e0 75 73 65 64 5f 6d 65 6d 6f 72 79 5f 70 65 61 6b |used_memory_peak| 000002f0 5f 70 65 72 63 3a 39 37 2e 36 30 25 0d 0a 75 73 |_perc:97.60%..us| 00000300 65 64 5f 6d 65 6d 6f 72 79 5f 6f 76 65 72 68 65 |ed_memoryoverhe| 00000310 61 64 3a 38 33 36 30 38 36 0d 0a 75 73 65 64 5f |ad:836086..used| 00000320 6d 65 6d 6f 72 79 5f 73 74 61 72 74 75 70 3a 37 |memory_startup:7| 00000330 38 36[2018-10-01 13:55:43.151] msg_dump:688 ================================================= [2018-10-01 13:55:43.151] conn_sendv_data:447 sendv on sd 20 2723 of 2723 in 1 buffers [2018-10-01 13:55:43.151] rsp_send_done:174 send done rsp 20 on c 20 [2018-10-01 13:55:43.151] rsp_send_done:177 conn 0x55b0e1521dd0 rsp 0x55b0e15264b0 done [2018-10-01 13:55:43.151] req_client_dequeue_omsgq:1108 <CONN_CLIENT 0x55b0e1521dd0 20 from '172.21.0.1:59844'> dequeue outq <REQ 0x55b0e1522100 19:0::0 REQ_REDIS_INFO, len:14> [2018-10-01 13:55:43.151] rsp_send_done:192 conn 0x55b0e1521dd0 removing message 19:0 [2018-10-01 13:55:43.151] _dn_free:305 free(0x55b0e152a9d0) @ dyn_dict.c:433 [2018-10-01 13:55:43.151] mbuf_remove:246 remove mbuf 0x55b0e152a820 len 0 [2018-10-01 13:55:43.151] mbuf_put:162 put mbuf 0x55b0e152a820 len 0 [2018-10-01 13:55:43.151] _dn_free:305 free(0x55b0e1526820) @ ../dyn_array.c:82 [2018-10-01 13:55:43.151] _dn_free:305 free(0x55b0e15267f0) @ ../dyn_array.c:56 [2018-10-01 13:55:43.151] mbuf_remove:246 remove mbuf 0x55b0e1526410 len 0 [2018-10-01 13:55:43.151] mbuf_put:162 put mbuf 0x55b0e1526410 len 0 [2018-10-01 13:55:43.151] _dn_free:305 free(0x55b0e1512ee0) @ ../dyn_array.c:82 [2018-10-01 13:55:43.151] _dn_free:305 free(0x55b0e1512e70) @ ../dyn_array.c:56 [2018-10-01 13:55:43.151] event_del_out:181 removing conn <CONN_CLIENT 0x55b0e1521dd0 20 from '172.21.0.1:59844'> from active [2018-10-01 13:55:43.151] core_process_messages:617 length of C2G_OutQ : 0 [2018-10-01 13:55:43.155] event_wait:264 epoll 0001 triggered on conn 0x55b0e1521dd0 [2018-10-01 13:55:43.155] core_core:510 event 00FF on <CONN_CLIENT 0x55b0e1521dd0 20 from '172.21.0.1:59844'> [2018-10-01 13:55:43.155] _dn_alloc:259 malloc(32) at 0x55b0e1512e70 @ ../dyn_array.c:34 [2018-10-01 13:55:43.155] _dn_alloc:259 malloc(32) at 0x55b0e1512ee0 @ ../dyn_array.c:39 [2018-10-01 13:55:43.155] msg_get:470 get msg 0x55b0e1522100 id 21 request 1 owner sd 20 [2018-10-01 13:55:43.155] mbuf_get:121 get mbuf 0x55b0e1526410 [2018-10-01 13:55:43.155] mbuf_insert:223 insert mbuf 0x55b0e1526410 len 0 [2018-10-01 13:55:43.155] conn_recv_data:396 <CONN_CLIENT 0x55b0e1521dd0 20 from '172.21.0.1:59844'> recv 0 of 16320 [2018-10-01 13:55:43.155] conn_recv_data:410 <CONN_CLIENT 0x55b0e1521dd0 20 from '172.21.0.1:59844'> recv eof rb 14 sb 2723 [2018-10-01 13:55:43.155] req_filter:368 <CONN_CLIENT 0x55b0e1521dd0 20 from '172.21.0.1:59844'> filter empty <REQ 0x55b0e1522100 21:0::0 UNKNOWN, len:0> [2018-10-01 13:55:43.155] mbuf_remove:246 remove mbuf 0x55b0e1526410 len 0 [2018-10-01 13:55:43.155] mbuf_put:162 put mbuf 0x55b0e1526410 len 0 [2018-10-01 13:55:43.155] _dn_free:305 free(0x55b0e1512ee0) @ ../dyn_array.c:82 [2018-10-01 13:55:43.155] _dn_free:305 free(0x55b0e1512e70) @ ../dyn_array.c:56 [2018-10-01 13:55:43.155] client_active:147 <CONN_CLIENT 0x55b0e1521dd0 20 from '172.21.0.1:59844'> is inactive [2018-10-01 13:55:43.155] req_recv_next:337 <CONN_CLIENT 0x55b0e1521dd0 20 from '172.21.0.1:59844'> DONE [2018-10-01 13:55:43.155] core_close:419 close <CONN_CLIENT 0x55b0e1521dd0 20 from '172.21.0.1:59844'> on event 00FF eof 1 done 1 rb 14 sb 2723
[2018-10-01 13:55:43.155] event_del_conn:230 removing conn <CONN_CLIENT 0x55b0e1521dd0 20 from '172.21.0.1:59844'> from active [2018-10-01 13:55:43.155] client_unref_internal_try_put:97 <CONN_CLIENT 0x55b0e1521dd0 -1 from '172.21.0.1:59844'> unref owner <POOL 0x55b0e15004f0 'dyn_o_mite'> [2018-10-01 13:55:43.155] _dn_free:305 free(0x55b0e1526460) @ dyn_dict.c:479 [2018-10-01 13:55:43.155] _dn_free:305 free(0x55b0e1522080) @ dyn_dict.c:491 [2018-10-01 13:55:43.155] conn_put:215 putting <CONN_CLIENT 0x55b0e1521dd0 -1 from '172.21.0.1:59844'> [2018-10-01 13:55:43.155] core_process_messages:617 length of C2G_OutQ : 0

It seems the raw data sent by redis-cli is slightly different and I suppose that's somehow the problem.

I managed to send the exact same bytes (copy paste from dynomite's log) and got it working through telnet with this command:

echo -n "2a 31 0d 0a 24 34 0d 0a 69 6e 66 6f 0d 0a" | xxd -r -p | sed -e 's|\n||g' -e 's|\r||g' | telnet 10.x.x.x 6379

Just for the record, for my F5 use case, this send string did the job:

*1\r\n$4\r\ninfo\r\n

Anyway, shouldn't dynomite accept the very exact syntaxes redis itself does?

ipapapa commented 6 years ago

Yes, it should. What version of redis-cli are you using? In which part of the syntax have you observed a divergence?

rcmorano commented 5 years ago

Hi @ipapapa, thanks for your reply!

I'm, using "redis:4" docker image. It's version 4.0.11 to be exact [1].

The divergence I appreciate is that redis itself recognizes a raw "info" sent via telnet (without the extra bytes I explained in my last reply [2]), but when you try to send it to dynomite, it does not recognize the command.

ping command works, though.

[1]

root@cdbbed86b110:/data# redis-cli --version redis-cli 4.0.11 root@cdbbed86b110:/data#

[2]

[2018-10-01 13:55:43.150] redis_parse_req:1410 parsed command 'info' [2018-10-01 13:55:43.150] redis_parse_req:2015 parsed req 19 res 0 type 76 state 0 rpos 14 of 14 00000000 2a 31 0d 0a 24 34 0d 0a 69 6e 66 6f 0d 0a |*1..$4..info..|

ipapapa commented 5 years ago

Yeah, it may be some commands in the Redis cli. I feel I have seen that with somebody else. Please feel free to file a PR to fix this misalignment. It should not be a big change to support the extra strings. FWIW we are currently running Redis 3.2.x so we have not seen a lot this issue but we will upgrade to Redis 4.x soon.

smukil commented 5 years ago

@rcmorano Please feel free to send any patches our way.

Closing this, please reopen if you have further questions.