Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Incorrect Cluster Failover Behavior #59

Closed
neogenie opened this issue Aug 24, 2022 · 34 comments · Fixed by #94
Closed

Incorrect Cluster Failover Behavior #59

neogenie opened this issue Aug 24, 2022 · 34 comments · Fixed by #94

Comments

@neogenie
Copy link
Contributor

The library behaves incorrectly in a Redis cluster failover scenario.

Reproduce scenario:

  1. Run a Redis cluster in docker with failover
  2. Connect to the cluster
  3. Pause master container with data
  4. Wait for the cluster failover mechanism sync the nodes and rehash slots
  5. The library can no longer read and write data to the node, because reinitialization of slots and nodes does not occur. There is no way (public methods) to re-sync the cluster state and slots on the client side.

Problems:

  • There is no background monitoring of the cluster state on the client side. Cluster reconfiguration occurs only when the connection is explicitly disconnected or when the answer is "MOVED".
  • Timeout does not trigger reconnect.

Bottom line: If the connection to the master node of the cluster is lost, the library endlessly unsuccessfully tries to connect to it. This does not reconfigure the cluster and slots on the client side

@neogenie
Copy link
Contributor Author

neogenie commented Sep 6, 2022

Hi @aembke
Have a look, please
I've added the ability to manually internal cluster state re-sync and timeouts for basic operations

@aembke
Copy link
Owner

aembke commented Dec 12, 2022

Hey @neogenie, apologies on the late response. I just published 6.0.0-beta.1 to crates.io with a new implementation for pretty much this entire interface, as well as the underlying clustered connection logic. If you have any feedback please let me know.

@aembke
Copy link
Owner

aembke commented Dec 14, 2022

I was able to repro this issue with some tests prior to the changes in 6.0.0-beta.1 and 6.0.0, but now it seems to be working for me with the latest changes. I'm going to close this but feel free to reopen it if you see this issue again.

@aembke aembke closed this as completed Dec 14, 2022
@neogenie
Copy link
Contributor Author

@aembke
I need some more time to investigate but looks like failover behavior is still broken... :'(

@neogenie
Copy link
Contributor Author

neogenie commented Dec 15, 2022

Unfortunately the behavior is still not failsafe:
Cluster state:

Cluster state:

73357279c60314d199fb317de16ce672fd9e2754 192.168.160.10:6379@16379 master - 0 1671114887070 9 connected 10923-16383
67ddb06afe2c8fa7c3687c907be65c11937fc3da 192.168.160.6:6379@16379 master,fail - 1671114884055 1671114883050 1 connected
1805aa7cbb4cc676fc24c3472b2fd14d30694241 192.168.160.7:6379@16379 master - 0 1671114887271 7 connected 5461-10922
18eff7d5cf61b7a3c06134957120629ddd720b72 192.168.160.5:6379@16379 myself,master - 0 1671114887000 10 connected 0-5460
be9d34aee04a18415459db9fcab2cace92663e9b 192.168.160.8:6379@16379 slave 73357279c60314d199fb317de16ce672fd9e2754 0 1671114887372 9 connected
98db499d1ab3c59dbf202b713b97556ba468d4a2 192.168.160.9:6379@16379 slave 1805aa7cbb4cc676fc24c3472b2fd14d30694241 0 1671114887000 7 connected

Cluster status:
cluster_state:ok
cluster_slots_assigned:16384
cluster_slots_ok:16384
cluster_slots_pfail:0
cluster_slots_fail:0
cluster_known_nodes:6
cluster_size:3
cluster_current_epoch:10
cluster_my_epoch:10
cluster_stats_messages_ping_sent:1544
cluster_stats_messages_pong_sent:1538
cluster_stats_messages_meet_sent:1
cluster_stats_messages_fail_sent:5
cluster_stats_messages_auth-req_sent:4
cluster_stats_messages_update_sent:3
cluster_stats_messages_sent:3095
cluster_stats_messages_ping_received:1534
cluster_stats_messages_pong_received:1539
cluster_stats_messages_fail_received:6
cluster_stats_messages_auth-req_received:3
cluster_stats_messages_auth-ack_received:2
cluster_stats_messages_received:3084

2022-12-15T14:34:48.057860Z TRACE fred::interfaces: fred-QPUnsksb9q: Sending command SET (0) to multiplexer.
2022-12-15T14:34:48.057965Z TRACE fred::multiplexer::commands: fred-QPUnsksb9q: Recv command: MultiplexerCommand { kind: "Command", command: "SET" }    
2022-12-15T14:34:48.058013Z TRACE fred::protocol::command: fred-QPUnsksb9q: Pipeline check SET: true    
2022-12-15T14:34:48.058049Z TRACE fred::multiplexer: fred-QPUnsksb9q: Writing command 0    
2022-12-15T14:34:48.058095Z DEBUG fred::multiplexer::clustered: fred-QPUnsksb9q: Writing command `SET` to 192.168.160.6:6379    
2022-12-15T14:34:48.058127Z TRACE fred::multiplexer::utils: fred-QPUnsksb9q: Writing command 0. Timed out: false, Force flush: false    
2022-12-15T14:34:48.058168Z TRACE fred::multiplexer::utils: fred-QPUnsksb9q: Sending command SET to 192.168.160.6:6379, ID: 0    
2022-12-15T14:34:48.058212Z TRACE redis_protocol::utils: allocating more, len: 0, amt: 42    
2022-12-15T14:34:48.058255Z TRACE fred::protocol::codec: fred-QPUnsksb9q: Encoded 42 bytes to 192.168.160.6:6379. Buffer len: 42 (RESP2)    
2022-12-15T14:34:48.058276Z TRACE tokio_util::codec::framed_impl: flushing framed transport
2022-12-15T14:34:48.058291Z TRACE tokio_util::codec::framed_impl: writing; remaining=42
2022-12-15T14:34:48.058351Z TRACE tokio_util::codec::framed_impl: framed transport flushed
2022-12-15T14:34:48.058375Z TRACE fred::multiplexer::commands: fred-QPUnsksb9q: Sent command to 192.168.160.6:6379. Flushed: true    
2022-12-15T14:34:53.160753Z TRACE fred::interfaces: fred-qRm29SLs03: Sending command SET (0) to multiplexer.    
2022-12-15T14:34:53.161098Z TRACE fred::multiplexer::commands: fred-qRm29SLs03: Recv command: MultiplexerCommand { kind: "Command", command: "SET" }    
2022-12-15T14:34:53.161271Z TRACE fred::protocol::command: fred-qRm29SLs03: Pipeline check SET: true    
2022-12-15T14:34:53.161357Z TRACE fred::multiplexer: fred-qRm29SLs03: Writing command 0    
2022-12-15T14:34:53.161458Z DEBUG fred::multiplexer::clustered: fred-qRm29SLs03: Writing command `SET` to 192.168.160.6:6379    
2022-12-15T14:34:53.161542Z TRACE fred::multiplexer::utils: fred-qRm29SLs03: Writing command 0. Timed out: false, Force flush: false    
2022-12-15T14:34:53.161675Z TRACE fred::multiplexer::utils: fred-qRm29SLs03: Sending command SET to 192.168.160.6:6379, ID: 0    
2022-12-15T14:34:53.161799Z TRACE redis_protocol::utils: allocating more, len: 0, amt: 42    
2022-12-15T14:34:53.161917Z TRACE fred::protocol::codec: fred-qRm29SLs03: Encoded 42 bytes to 192.168.160.6:6379. Buffer len: 42 (RESP2)    
2022-12-15T14:34:53.162007Z TRACE tokio_util::codec::framed_impl: flushing framed transport
2022-12-15T14:34:53.162059Z TRACE tokio_util::codec::framed_impl: writing; remaining=42
2022-12-15T14:34:53.162272Z TRACE tokio_util::codec::framed_impl: framed transport flushed
2022-12-15T14:34:53.162386Z TRACE fred::multiplexer::commands: fred-qRm29SLs03: Sent command to 192.168.160.6:6379. Flushed: true    
2022-12-15T14:34:58.263499Z TRACE fred::interfaces: fred-1E2Opvw4vX: Sending command SET (0) to multiplexer.    
2022-12-15T14:34:58.263684Z TRACE fred::multiplexer::commands: fred-1E2Opvw4vX: Recv command: MultiplexerCommand { kind: "Command", command: "SET" }    
2022-12-15T14:34:58.263776Z TRACE fred::protocol::command: fred-1E2Opvw4vX: Pipeline check SET: true    
2022-12-15T14:34:58.263831Z TRACE fred::multiplexer: fred-1E2Opvw4vX: Writing command 0    
2022-12-15T14:34:58.263904Z DEBUG fred::multiplexer::clustered: fred-1E2Opvw4vX: Writing command `SET` to 192.168.160.6:6379    
2022-12-15T14:34:58.263963Z TRACE fred::multiplexer::utils: fred-1E2Opvw4vX: Writing command 0. Timed out: false, Force flush: false    
2022-12-15T14:34:58.264070Z TRACE fred::multiplexer::utils: fred-1E2Opvw4vX: Sending command SET to 192.168.160.6:6379, ID: 0    
2022-12-15T14:34:58.264187Z TRACE redis_protocol::utils: allocating more, len: 0, amt: 42    
2022-12-15T14:34:58.264277Z TRACE fred::protocol::codec: fred-1E2Opvw4vX: Encoded 42 bytes to 192.168.160.6:6379. Buffer len: 42 (RESP2)    
2022-12-15T14:34:58.264339Z TRACE tokio_util::codec::framed_impl: flushing framed transport
2022-12-15T14:34:58.264376Z TRACE tokio_util::codec::framed_impl: writing; remaining=42
2022-12-15T14:34:58.264533Z TRACE tokio_util::codec::framed_impl: framed transport flushed
2022-12-15T14:34:58.264612Z TRACE fred::multiplexer::commands: fred-1E2Opvw4vX: Sent command to 192.168.160.6:6379. Flushed: true    
2022-12-15T14:35:03.366003Z TRACE fred::interfaces: fred-Ky1aPe4iW7: Sending command SET (0) to multiplexer.    
2022-12-15T14:35:03.366120Z TRACE fred::multiplexer::commands: fred-Ky1aPe4iW7: Recv command: MultiplexerCommand { kind: "Command", command: "SET" }    
2022-12-15T14:35:03.366174Z TRACE fred::protocol::command: fred-Ky1aPe4iW7: Pipeline check SET: true    
2022-12-15T14:35:03.366201Z TRACE fred::multiplexer: fred-Ky1aPe4iW7: Writing command 0    
2022-12-15T14:35:03.366239Z DEBUG fred::multiplexer::clustered: fred-Ky1aPe4iW7: Writing command `SET` to 192.168.160.6:6379    
2022-12-15T14:35:03.366273Z TRACE fred::multiplexer::utils: fred-Ky1aPe4iW7: Writing command 0. Timed out: false, Force flush: false    
2022-12-15T14:35:03.366329Z TRACE fred::multiplexer::utils: fred-Ky1aPe4iW7: Sending command SET to 192.168.160.6:6379, ID: 0    
2022-12-15T14:35:03.366366Z TRACE redis_protocol::utils: allocating more, len: 0, amt: 42    
2022-12-15T14:35:03.366418Z TRACE fred::protocol::codec: fred-Ky1aPe4iW7: Encoded 42 bytes to 192.168.160.6:6379. Buffer len: 42 (RESP2)    
2022-12-15T14:35:03.366452Z TRACE tokio_util::codec::framed_impl: flushing framed transport
2022-12-15T14:35:03.366467Z TRACE tokio_util::codec::framed_impl: writing; remaining=42
2022-12-15T14:35:03.366537Z TRACE tokio_util::codec::framed_impl: framed transport flushed
2022-12-15T14:35:03.366572Z TRACE fred::multiplexer::commands: fred-Ky1aPe4iW7: Sent command to 192.168.160.6:6379. Flushed: true    
2022-12-15T14:35:08.468587Z TRACE fred::interfaces: fred-yxT6ev5KUY: Sending command SET (0) to multiplexer.    
2022-12-15T14:35:08.468858Z TRACE fred::multiplexer::commands: fred-yxT6ev5KUY: Recv command: MultiplexerCommand { kind: "Command", command: "SET" }    
2022-12-15T14:35:08.469012Z TRACE fred::protocol::command: fred-yxT6ev5KUY: Pipeline check SET: true    
2022-12-15T14:35:08.469092Z TRACE fred::multiplexer: fred-yxT6ev5KUY: Writing command 0    
2022-12-15T14:35:08.469206Z DEBUG fred::multiplexer::clustered: fred-yxT6ev5KUY: Writing command `SET` to 192.168.160.6:6379    
2022-12-15T14:35:08.469268Z TRACE fred::multiplexer::utils: fred-yxT6ev5KUY: Writing command 0. Timed out: false, Force flush: false    
2022-12-15T14:35:08.469379Z TRACE fred::multiplexer::utils: fred-yxT6ev5KUY: Sending command SET to 192.168.160.6:6379, ID: 0    
2022-12-15T14:35:08.469483Z TRACE redis_protocol::utils: allocating more, len: 0, amt: 42    
2022-12-15T14:35:08.469590Z TRACE fred::protocol::codec: fred-yxT6ev5KUY: Encoded 42 bytes to 192.168.160.6:6379. Buffer len: 42 (RESP2)    
2022-12-15T14:35:08.469664Z TRACE tokio_util::codec::framed_impl: flushing framed transport
2022-12-15T14:35:08.469716Z TRACE tokio_util::codec::framed_impl: writing; remaining=42
2022-12-15T14:35:08.469889Z TRACE tokio_util::codec::framed_impl: framed transport flushed
2022-12-15T14:35:08.469988Z TRACE fred::multiplexer::commands: fred-yxT6ev5KUY: Sent command to 192.168.160.6:6379. Flushed: true    
2022-12-15T14:35:13.571804Z TRACE fred::interfaces: fred-Z58ilx1fU0: Sending command SET (0) to multiplexer.    
2022-12-15T14:35:13.572021Z TRACE fred::multiplexer::commands: fred-Z58ilx1fU0: Recv command: MultiplexerCommand { kind: "Command", command: "SET" }    
2022-12-15T14:35:13.572137Z TRACE fred::protocol::command: fred-Z58ilx1fU0: Pipeline check SET: true    
2022-12-15T14:35:13.572215Z TRACE fred::multiplexer: fred-Z58ilx1fU0: Writing command 0    
2022-12-15T14:35:13.572293Z DEBUG fred::multiplexer::clustered: fred-Z58ilx1fU0: Writing command `SET` to 192.168.160.6:6379    
2022-12-15T14:35:13.572334Z TRACE fred::multiplexer::utils: fred-Z58ilx1fU0: Writing command 0. Timed out: false, Force flush: false    
2022-12-15T14:35:13.572406Z TRACE fred::multiplexer::utils: fred-Z58ilx1fU0: Sending command SET to 192.168.160.6:6379, ID: 0    
2022-12-15T14:35:13.572481Z TRACE redis_protocol::utils: allocating more, len: 0, amt: 42    
2022-12-15T14:35:13.572562Z TRACE fred::protocol::codec: fred-Z58ilx1fU0: Encoded 42 bytes to 192.168.160.6:6379. Buffer len: 42 (RESP2)    
2022-12-15T14:35:13.572615Z TRACE tokio_util::codec::framed_impl: flushing framed transport
2022-12-15T14:35:13.572641Z TRACE tokio_util::codec::framed_impl: writing; remaining=42
2022-12-15T14:35:13.572759Z TRACE tokio_util::codec::framed_impl: framed transport flushed
2022-12-15T14:35:13.572826Z TRACE fred::multiplexer::commands: fred-Z58ilx1fU0: Sent command to 192.168.160.6:6379. Flushed: true    
2022-12-15T14:35:18.574374Z TRACE fred::interfaces: fred-QPUnsksb9q: Sending command SET (0) to multiplexer.    
2022-12-15T14:35:18.574621Z TRACE fred::multiplexer::commands: fred-QPUnsksb9q: Recv command: MultiplexerCommand { kind: "Command", command: "SET" }    
2022-12-15T14:35:18.574772Z TRACE fred::protocol::command: fred-QPUnsksb9q: Pipeline check SET: true    
2022-12-15T14:35:18.574882Z TRACE fred::multiplexer: fred-QPUnsksb9q: Writing command 0    
2022-12-15T14:35:18.575017Z DEBUG fred::multiplexer::clustered: fred-QPUnsksb9q: Writing command `SET` to 192.168.160.6:6379    
2022-12-15T14:35:18.575118Z TRACE fred::multiplexer::utils: fred-QPUnsksb9q: Writing command 0. Timed out: false, Force flush: false    
2022-12-15T14:35:18.575236Z TRACE fred::multiplexer::utils: fred-QPUnsksb9q: Sending command SET to 192.168.160.6:6379, ID: 0    
2022-12-15T14:35:18.575334Z TRACE redis_protocol::utils: allocating more, len: 0, amt: 42    
2022-12-15T14:35:18.575473Z TRACE fred::protocol::codec: fred-QPUnsksb9q: Encoded 42 bytes to 192.168.160.6:6379. Buffer len: 42 (RESP2)    
2022-12-15T14:35:18.575566Z TRACE tokio_util::codec::framed_impl: flushing framed transport
2022-12-15T14:35:18.575623Z TRACE tokio_util::codec::framed_impl: writing; remaining=42
2022-12-15T14:35:18.575820Z TRACE tokio_util::codec::framed_impl: framed transport flushed
2022-12-15T14:35:18.575903Z TRACE fred::multiplexer::commands: fred-QPUnsksb9q: Sent command to 192.168.160.6:6379. Flushed: true    
2022-12-15T14:35:23.678168Z TRACE fred::interfaces: fred-qRm29SLs03: Sending command SET (0) to multiplexer.    
2022-12-15T14:35:23.678469Z TRACE fred::multiplexer::commands: fred-qRm29SLs03: Recv command: MultiplexerCommand { kind: "Command", command: "SET" }    
2022-12-15T14:35:23.678614Z TRACE fred::protocol::command: fred-qRm29SLs03: Pipeline check SET: true    
2022-12-15T14:35:23.678694Z TRACE fred::multiplexer: fred-qRm29SLs03: Writing command 0    
2022-12-15T14:35:23.678802Z DEBUG fred::multiplexer::clustered: fred-qRm29SLs03: Writing command `SET` to 192.168.160.6:6379    
2022-12-15T14:35:23.678876Z TRACE fred::multiplexer::utils: fred-qRm29SLs03: Writing command 0. Timed out: false, Force flush: false    
2022-12-15T14:35:23.678983Z TRACE fred::multiplexer::utils: fred-qRm29SLs03: Sending command SET to 192.168.160.6:6379, ID: 0    
2022-12-15T14:35:23.679091Z TRACE redis_protocol::utils: allocating more, len: 0, amt: 42    
2022-12-15T14:35:23.679208Z TRACE fred::protocol::codec: fred-qRm29SLs03: Encoded 42 bytes to 192.168.160.6:6379. Buffer len: 42 (RESP2)    
2022-12-15T14:35:23.679278Z TRACE tokio_util::codec::framed_impl: flushing framed transport
2022-12-15T14:35:23.679320Z TRACE tokio_util::codec::framed_impl: writing; remaining=42
2022-12-15T14:35:23.679499Z TRACE tokio_util::codec::framed_impl: framed transport flushed
2022-12-15T14:35:23.679592Z TRACE fred::multiplexer::commands: fred-qRm29SLs03: Sent command to 192.168.160.6:6379. Flushed: true    
2022-12-15T14:35:28.780671Z TRACE fred::interfaces: fred-1E2Opvw4vX: Sending command SET (0) to multiplexer.    
2022-12-15T14:35:28.781055Z TRACE fred::multiplexer::commands: fred-1E2Opvw4vX: Recv command: MultiplexerCommand { kind: "Command", command: "SET" }    
2022-12-15T14:35:28.781239Z TRACE fred::protocol::command: fred-1E2Opvw4vX: Pipeline check SET: true    
2022-12-15T14:35:28.781356Z TRACE fred::multiplexer: fred-1E2Opvw4vX: Writing command 0    
2022-12-15T14:35:28.781493Z DEBUG fred::multiplexer::clustered: fred-1E2Opvw4vX: Writing command `SET` to 192.168.160.6:6379    
2022-12-15T14:35:28.781584Z TRACE fred::multiplexer::utils: fred-1E2Opvw4vX: Writing command 0. Timed out: false, Force flush: false    
2022-12-15T14:35:28.781716Z TRACE fred::multiplexer::utils: fred-1E2Opvw4vX: Sending command SET to 192.168.160.6:6379, ID: 0    
2022-12-15T14:35:28.781839Z TRACE redis_protocol::utils: allocating more, len: 0, amt: 42    
2022-12-15T14:35:28.781991Z TRACE fred::protocol::codec: fred-1E2Opvw4vX: Encoded 42 bytes to 192.168.160.6:6379. Buffer len: 42 (RESP2)    
2022-12-15T14:35:28.782089Z TRACE tokio_util::codec::framed_impl: flushing framed transport
2022-12-15T14:35:28.782152Z TRACE tokio_util::codec::framed_impl: writing; remaining=42
2022-12-15T14:35:28.782378Z TRACE tokio_util::codec::framed_impl: framed transport flushed
2022-12-15T14:35:28.782498Z TRACE fred::multiplexer::commands: fred-1E2Opvw4vX: Sent command to 192.168.160.6:6379. Flushed: true    
2022-12-15T14:35:33.883254Z TRACE fred::interfaces: fred-Ky1aPe4iW7: Sending command SET (0) to multiplexer.    
2022-12-15T14:35:33.883594Z TRACE fred::multiplexer::commands: fred-Ky1aPe4iW7: Recv command: MultiplexerCommand { kind: "Command", command: "SET" }    
2022-12-15T14:35:33.883701Z TRACE fred::protocol::command: fred-Ky1aPe4iW7: Pipeline check SET: true    
2022-12-15T14:35:33.883771Z TRACE fred::multiplexer: fred-Ky1aPe4iW7: Writing command 0    
2022-12-15T14:35:33.883849Z DEBUG fred::multiplexer::clustered: fred-Ky1aPe4iW7: Writing command `SET` to 192.168.160.6:6379    
2022-12-15T14:35:33.883903Z TRACE fred::multiplexer::utils: fred-Ky1aPe4iW7: Writing command 0. Timed out: false, Force flush: false    
2022-12-15T14:35:33.883989Z TRACE fred::multiplexer::utils: fred-Ky1aPe4iW7: Sending command SET to 192.168.160.6:6379, ID: 0    
2022-12-15T14:35:33.884072Z TRACE redis_protocol::utils: allocating more, len: 0, amt: 42    
2022-12-15T14:35:33.884198Z TRACE fred::protocol::codec: fred-Ky1aPe4iW7: Encoded 42 bytes to 192.168.160.6:6379. Buffer len: 42 (RESP2)    
2022-12-15T14:35:33.884253Z TRACE tokio_util::codec::framed_impl: flushing framed transport
2022-12-15T14:35:33.884275Z TRACE tokio_util::codec::framed_impl: writing; remaining=42
2022-12-15T14:35:33.884436Z TRACE tokio_util::codec::framed_impl: framed transport flushed
2022-12-15T14:35:33.884509Z TRACE fred::multiplexer::commands: fred-Ky1aPe4iW7: Sent command to 192.168.160.6:6379. Flushed: true    
2022-12-15T14:35:38.985307Z TRACE fred::interfaces: fred-yxT6ev5KUY: Sending command SET (0) to multiplexer.    
2022-12-15T14:35:38.985535Z TRACE fred::multiplexer::commands: fred-yxT6ev5KUY: Recv command: MultiplexerCommand { kind: "Command", command: "SET" }    
2022-12-15T14:35:38.985634Z TRACE fred::protocol::command: fred-yxT6ev5KUY: Pipeline check SET: true    
2022-12-15T14:35:38.985703Z TRACE fred::multiplexer: fred-yxT6ev5KUY: Writing command 0    
2022-12-15T14:35:38.985781Z DEBUG fred::multiplexer::clustered: fred-yxT6ev5KUY: Writing command `SET` to 192.168.160.6:6379    
2022-12-15T14:35:38.985836Z TRACE fred::multiplexer::utils: fred-yxT6ev5KUY: Writing command 0. Timed out: false, Force flush: false    
2022-12-15T14:35:38.985900Z TRACE fred::multiplexer::utils: fred-yxT6ev5KUY: Sending command SET to 192.168.160.6:6379, ID: 0    
2022-12-15T14:35:38.985982Z TRACE redis_protocol::utils: allocating more, len: 0, amt: 42    
2022-12-15T14:35:38.986090Z TRACE fred::protocol::codec: fred-yxT6ev5KUY: Encoded 42 bytes to 192.168.160.6:6379. Buffer len: 42 (RESP2)    
2022-12-15T14:35:38.986151Z TRACE tokio_util::codec::framed_impl: flushing framed transport
2022-12-15T14:35:38.986177Z TRACE tokio_util::codec::framed_impl: writing; remaining=42
2022-12-15T14:35:38.986286Z TRACE tokio_util::codec::framed_impl: framed transport flushed
2022-12-15T14:35:38.986345Z TRACE fred::multiplexer::commands: fred-yxT6ev5KUY: Sent command to 192.168.160.6:6379. Flushed: true    
2022-12-15T14:35:44.088837Z TRACE fred::interfaces: fred-Z58ilx1fU0: Sending command SET (0) to multiplexer.    
2022-12-15T14:35:44.089121Z TRACE fred::multiplexer::commands: fred-Z58ilx1fU0: Recv command: MultiplexerCommand { kind: "Command", command: "SET" }    
2022-12-15T14:35:44.089226Z TRACE fred::protocol::command: fred-Z58ilx1fU0: Pipeline check SET: true    
2022-12-15T14:35:44.089283Z TRACE fred::multiplexer: fred-Z58ilx1fU0: Writing command 0    
2022-12-15T14:35:44.089384Z DEBUG fred::multiplexer::clustered: fred-Z58ilx1fU0: Writing command `SET` to 192.168.160.6:6379    
2022-12-15T14:35:44.089487Z TRACE fred::multiplexer::utils: fred-Z58ilx1fU0: Writing command 0. Timed out: false, Force flush: false    
2022-12-15T14:35:44.089606Z TRACE fred::multiplexer::utils: fred-Z58ilx1fU0: Sending command SET to 192.168.160.6:6379, ID: 0    
2022-12-15T14:35:44.089699Z TRACE redis_protocol::utils: allocating more, len: 0, amt: 42    
2022-12-15T14:35:44.089793Z TRACE fred::protocol::codec: fred-Z58ilx1fU0: Encoded 42 bytes to 192.168.160.6:6379. Buffer len: 42 (RESP2)    
2022-12-15T14:35:44.089866Z TRACE tokio_util::codec::framed_impl: flushing framed transport
2022-12-15T14:35:44.089904Z TRACE tokio_util::codec::framed_impl: writing; remaining=42
2022-12-15T14:35:44.090074Z TRACE tokio_util::codec::framed_impl: framed transport flushed
2022-12-15T14:35:44.090149Z TRACE fred::multiplexer::commands: fred-Z58ilx1fU0: Sent command to 192.168.160.6:6379. Flushed: true    

If the connection to the master node of the cluster is lost, the library endlessly unsuccessfully tries to connect to it. This does not reconfigure the cluster and slots on the client side

@aembke
Copy link
Owner

aembke commented Dec 15, 2022

Interesting ok, so in this scenario (if I'm reading this correctly) the unique thing is there's one node that thinks its a master but is in a fail state and has no cluster slots assigned. Does the cluster stay in this state for a long period of time or does 67ddb06afe2c8fa7c3687c907be65c11937fc3da ever switch back to a slave/replica?

I added a check in the recent version that runs CLUSTER INFO on all the primary nodes, and I'm curious if 67ddb06afe2c8fa7c3687c907be65c11937fc3da returns cluster_state:ok in response to CLUSTER INFO. In my failover tests the failed master node quickly switches back to a slave/replica, so that might be the key difference here.

@aembke
Copy link
Owner

aembke commented Dec 15, 2022

I'm a bit torn on how to handle this because in this scenario the master node 18eff7d5cf61b7a3c06134957120629ddd720b72 does not have a slave/replica associated with it, which could lead to a whole bunch of other issues if the cluster stays in this state for a long period of time. If I were operating this system and I saw that the cluster was stuck in a state where 1/3 master nodes couldn't replicate its dataset then I'd probably have to step in and do something to fix that, and loudly failing in the client might be the best approach to set off alarms so somebody looks at it.

On the other hand, all the hash slots are covered so it is still possible for the client to work. But 1/3 of the slots aren't replicated and certain failure modes could lead to data loss if that one master node were to go down before it had a chance to replicate the changes that occurred while in this state.

Or maybe I'm misinterpreting this. Looks like this will take some more investigation.

@neogenie
Copy link
Contributor Author

This is a fairly common scenario for a cluster: if the master fails, Redis switches the master to the replica. Thus, the original master remains in the cluster with a fail status. When it appears on the radar after some time, it does not at all guarantee that it will become a master again, it may remain a replica.

In the current version of the library, it does not update the configuration for the cluster, or uses the same connection to update it which is no longer available. This leads to the fact that if the connection to the node on which the requested data is lost, we can never get them again because the library continues to persistently but unsuccessfully knock on the node that is no longer available.
This is very clearly seen in the log above.

@aembke
Copy link
Owner

aembke commented Dec 15, 2022

Yeah that makes sense. I'm just trying to figure out why this doesn't repro in my test, but I think it's just because in mine the 67ddb06afe2c8fa7c3687c907be65c11937fc3da node almost immediately switches to a slave rather than staying as master,fail.

But like you said, it doesn't really matter, I can see how this would happen with a network partition and the client should be able to handle this. I'll take a look today and update here once it's fixed.

@aembke aembke reopened this Dec 15, 2022
@neogenie
Copy link
Contributor Author

You are absolutely right, the situation when there is only one replica and it becomes the master when the original master fails is not very good. Yes, in this case you should alert, write angry logs and call the duty dev-ops or sre :)
BUT:

  • It seems to me that the failover lies in this: if one node fails, the application can maintain its performance, continuing to serve customers. Actually, why are we making a replica and the possibility of moving to it?
  • There can be several replicas, in this case there will not be such a critical situation, but the master will still be unavailable.

In other words, as a redis client that handles this situation quite well while still serving users, we also expect similar behavior from the client library.

My solution proposed in the PR is still relevant, although perhaps not very elegant in terms of library architecture and needs to be adjusted.

@aembke aembke mentioned this issue Dec 16, 2022
@aembke
Copy link
Owner

aembke commented Dec 16, 2022

@neogenie would you mind trying your repro again with the latest changes in main?

@neogenie
Copy link
Contributor Author

2022-12-16T19:35:55.437704Z  INFO tests::redis::cluster: Cluster state: 

a6de1afd0a046c424c6ce1b9072ac40764784d12 172.28.0.6:6379@16379 slave 18a61616f85b720fc8666c6d7f723635b9207526 0 1671219354965 3 connected
931b6a4b8cdf55bab3c8069e8c9c3fe4ea5d0158 172.28.0.8:6379@16379 master,fail - 1671219351044 1671219350040 1 connected
18a61616f85b720fc8666c6d7f723635b9207526 172.28.0.7:6379@16379 myself,master - 0 1671219354000 3 connected 10923-16383
5d541d199a3ea43106ba59d6bc9d3cb7971c7485 172.28.0.5:6379@16379 slave ff30998fcb6118096cb1bbdec042d2b4dda75e78 0 1671219355066 2 connected
6928cf25ee199b2ed579ecc486b14d95e439faea 172.28.0.9:6379@16379 master - 0 1671219355000 7 connected 0-5460
ff30998fcb6118096cb1bbdec042d2b4dda75e78 172.28.0.10:6379@16379 master - 0 1671219354462 2 connected 5461-10922

2022-12-16T19:35:55.437791Z DEBUG tests::redis::cluster: Check cluster status...
2022-12-16T19:35:55.437870Z DEBUG bollard::docker: {"AttachStdin":null,"AttachStdout":true,"AttachStderr":null,"Tty":null,"DetachKeys":null,"Env":null,"Cmd":["redis-cli","-c","-a","qwerty","CLUSTER","INFO"],"Privileged":null,"User":null,"WorkingDir":null}    
2022-12-16T19:35:55.438001Z DEBUG bollard::uri: Parsing uri: unix://2f7661722f72756e2f646f636b65722e736f636b/containers/a43daf05d8cb257641d606dbbaa03aab185d180d948c508ee2779e70e7beae58/exec, client_type: Unix, socket: /var/run/docker.sock    
2022-12-16T19:35:55.438050Z DEBUG bollard::docker: unix://2f7661722f72756e2f646f636b65722e736f636b/containers/a43daf05d8cb257641d606dbbaa03aab185d180d948c508ee2779e70e7beae58/exec    
2022-12-16T19:35:55.438104Z DEBUG bollard::docker: request: Request { method: POST, uri: unix://2f7661722f72756e2f646f636b65722e736f636b/containers/a43daf05d8cb257641d606dbbaa03aab185d180d948c508ee2779e70e7beae58/exec, version: HTTP/1.1, headers: {"content-type": "application/json"}, body: Body(Full(b"{\"AttachStdin\":null,\"AttachStdout\":true,\"AttachStderr\":null,\"Tty\":null,\"DetachKeys\":null,\"Env\":null,\"Cmd\":[\"redis-cli\",\"-c\",\"-a\",\"qwerty\",\"CLUSTER\",\"INFO\"],\"Privileged\":null,\"User\":null,\"WorkingDir\":null}")) }    
2022-12-16T19:35:55.438272Z TRACE mio::poll: registering event source with poller: token=Token(687865882), interests=READABLE | WRITABLE    
2022-12-16T19:35:55.438329Z TRACE hyper::client::conn: client handshake Http1
2022-12-16T19:35:55.438381Z TRACE hyper::client::client: handshake complete, spawning background dispatcher task
2022-12-16T19:35:55.438494Z TRACE want: signal: Want    
2022-12-16T19:35:55.438525Z TRACE want: signal found waiting giver, notifying    
2022-12-16T19:35:55.438553Z TRACE hyper::proto::h1::conn: flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Busy }
2022-12-16T19:35:55.438566Z TRACE want: poll_want: taker wants!    
2022-12-16T19:35:55.438721Z TRACE encode_headers: hyper::proto::h1::role: Client::encode method=POST, body=Some(Known(204))
2022-12-16T19:35:55.438817Z TRACE hyper::proto::h1::io: buffer.flatten self.len=200 buf.len=204
2022-12-16T19:35:55.438858Z DEBUG hyper::proto::h1::io: flushed 404 bytes
2022-12-16T19:35:55.438874Z TRACE hyper::proto::h1::conn: flushed({role=client}): State { reading: Init, writing: KeepAlive, keep_alive: Busy }
2022-12-16T19:35:55.439161Z TRACE hyper::proto::h1::conn: Conn::read_head
2022-12-16T19:35:55.439200Z TRACE hyper::proto::h1::io: received 281 bytes
2022-12-16T19:35:55.439247Z TRACE parse_headers: hyper::proto::h1::role: Response.parse bytes=281
2022-12-16T19:35:55.439301Z TRACE parse_headers: hyper::proto::h1::role: Response.parse Complete(207)
2022-12-16T19:35:55.439404Z DEBUG hyper::proto::h1::io: parsed 7 headers
2022-12-16T19:35:55.439421Z DEBUG hyper::proto::h1::conn: incoming body is content-length (74 bytes)
2022-12-16T19:35:55.439461Z TRACE hyper::proto::h1::decode: decode; state=Length(74)
2022-12-16T19:35:55.439479Z DEBUG hyper::proto::h1::conn: incoming body completed
2022-12-16T19:35:55.439501Z TRACE hyper::proto::h1::conn: maybe_notify; read_from_io blocked
2022-12-16T19:35:55.439535Z TRACE hyper::proto::h1::dispatch: client tx closed
2022-12-16T19:35:55.439549Z TRACE hyper::proto::h1::conn: State::close_read()
2022-12-16T19:35:55.439547Z DEBUG bollard::docker: Decoded into string: {"Id":"b571d790770fd1484db8ae32c36ee23cf603f336b11eb7e6e9d08acda42e1ff3"}
2022-12-16T19:35:55.439560Z TRACE hyper::proto::h1::conn: State::close_write()
2022-12-16T19:35:55.439572Z TRACE hyper::proto::h1::conn: flushed({role=client}): State { reading: Closed, writing: Closed, keep_alive: Disabled }
2022-12-16T19:35:55.439585Z TRACE hyper::proto::h1::conn: flushed({role=client}): State { reading: Closed, writing: Closed, keep_alive: Disabled }
2022-12-16T19:35:55.439602Z TRACE hyper::proto::h1::conn: shut down IO complete
2022-12-16T19:35:55.439617Z DEBUG bollard::docker: {"Detach":false,"OutputCapacity":null}    
2022-12-16T19:35:55.439621Z TRACE mio::poll: deregistering event source from poller    
2022-12-16T19:35:55.439669Z TRACE want: signal: Closed    
2022-12-16T19:35:55.439755Z DEBUG bollard::uri: Parsing uri: unix://2f7661722f72756e2f646f636b65722e736f636b/exec/b571d790770fd1484db8ae32c36ee23cf603f336b11eb7e6e9d08acda42e1ff3/start, client_type: Unix, socket: /var/run/docker.sock    
2022-12-16T19:35:55.439792Z DEBUG bollard::docker: unix://2f7661722f72756e2f646f636b65722e736f636b/exec/b571d790770fd1484db8ae32c36ee23cf603f336b11eb7e6e9d08acda42e1ff3/start    
2022-12-16T19:35:55.439825Z DEBUG bollard::docker: request: Request { method: POST, uri: unix://2f7661722f72756e2f646f636b65722e736f636b/exec/b571d790770fd1484db8ae32c36ee23cf603f336b11eb7e6e9d08acda42e1ff3/start, version: HTTP/1.1, headers: {"connection": "Upgrade", "upgrade": "tcp", "content-type": "application/json"}, body: Body(Full(b"{\"Detach\":false,\"OutputCapacity\":null}")) }    
2022-12-16T19:35:55.439937Z TRACE mio::poll: registering event source with poller: token=Token(704643098), interests=READABLE | WRITABLE    
2022-12-16T19:35:55.440000Z TRACE hyper::client::conn: client handshake Http1
2022-12-16T19:35:55.440039Z TRACE hyper::client::client: handshake complete, spawning background dispatcher task
2022-12-16T19:35:55.440120Z TRACE want: signal: Want    
2022-12-16T19:35:55.440151Z TRACE want: signal found waiting giver, notifying    
2022-12-16T19:35:55.440179Z TRACE hyper::proto::h1::conn: flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Busy }
2022-12-16T19:35:55.440189Z TRACE want: poll_want: taker wants!    
2022-12-16T19:35:55.440296Z TRACE encode_headers: hyper::proto::h1::role: Client::encode method=POST, body=Some(Known(38))
2022-12-16T19:35:55.440367Z TRACE hyper::proto::h1::io: buffer.flatten self.len=229 buf.len=38
2022-12-16T19:35:55.440410Z DEBUG hyper::proto::h1::io: flushed 267 bytes
2022-12-16T19:35:55.440424Z TRACE hyper::proto::h1::conn: flushed({role=client}): State { reading: Init, writing: KeepAlive, keep_alive: Busy }
2022-12-16T19:35:55.440574Z TRACE hyper::proto::h1::conn: Conn::read_head
2022-12-16T19:35:55.440613Z TRACE hyper::proto::h1::io: received 203 bytes
2022-12-16T19:35:55.440654Z TRACE parse_headers: hyper::proto::h1::role: Response.parse bytes=203
2022-12-16T19:35:55.440700Z TRACE parse_headers: hyper::proto::h1::role: Response.parse Complete(203)
2022-12-16T19:35:55.440798Z DEBUG hyper::proto::h1::io: parsed 7 headers
2022-12-16T19:35:55.440815Z DEBUG hyper::proto::h1::conn: incoming body is empty
2022-12-16T19:35:55.440828Z TRACE hyper::proto::h1::conn: remote disabling keep-alive
2022-12-16T19:35:55.440842Z TRACE hyper::proto::h1::conn: try_keep_alive({role=client}): could keep-alive, but status = Disabled
2022-12-16T19:35:55.440855Z TRACE hyper::proto::h1::conn: State::close()
2022-12-16T19:35:55.440867Z TRACE hyper::proto::h1::conn: {role=client}: prepare possible HTTP upgrade
2022-12-16T19:35:55.440907Z TRACE hyper::proto::h1::conn: flushed({role=client}): State { reading: Closed, writing: Closed, keep_alive: Disabled }
2022-12-16T19:35:55.440939Z TRACE want: signal: Closed    
2022-12-16T19:35:55.440972Z TRACE hyper::upgrade: pending upgrade fulfill
2022-12-16T19:35:55.648075Z TRACE tokio_util::codec::framed_impl: attempting to decode a frame
2022-12-16T19:35:55.648153Z DEBUG bollard::read: NewlineLogOutputDecoder: read header, type = 1, length = 597    
2022-12-16T19:35:55.648177Z DEBUG bollard::read: NewlineLogOutputDecoder: Reading payload    
2022-12-16T19:35:55.648195Z TRACE tokio_util::codec::framed_impl: frame decoded from buffer
2022-12-16T19:35:55.648232Z TRACE tokio_util::codec::framed_impl: attempting to decode a frame
2022-12-16T19:35:55.648253Z DEBUG bollard::read: NewlineLogOutputDecoder: not enough data for read header    
2022-12-16T19:35:55.665922Z DEBUG bollard::read: NewlineLogOutputDecoder: not enough data for read header    
2022-12-16T19:35:55.665993Z TRACE mio::poll: deregistering event source from poller    
2022-12-16T19:35:55.666033Z DEBUG tests::redis::cluster: Cluster status: cluster_state:ok

cluster_slots_assigned:16384
cluster_slots_ok:16384
cluster_slots_pfail:0
cluster_slots_fail:0
cluster_known_nodes:6
cluster_size:3
cluster_current_epoch:7
cluster_my_epoch:3
cluster_stats_messages_ping_sent:1380
cluster_stats_messages_pong_sent:1377
cluster_stats_messages_meet_sent:1
cluster_stats_messages_auth-ack_sent:1
cluster_stats_messages_sent:2759
cluster_stats_messages_ping_received:1377
cluster_stats_messages_pong_received:1376
cluster_stats_messages_fail_received:2
cluster_stats_messages_auth-req_received:1
cluster_stats_messages_received:2756

2022-12-16T19:35:55.666095Z  INFO tests::redis::cluster: Cluster state parsed: ClusterInfo { is_ok: true, nodes: [NodeInfo { id: "a6de1afd0a046c424c6ce1b9072ac40764784d12", ip: "172.28.0.6", port: 6379, status: Slave, failed: false, slots: None, connected: true }, NodeInfo { id: "931b6a4b8cdf55bab3c8069e8c9c3fe4ea5d0158", ip: "172.28.0.8", port: 6379, status: Master, failed: true, slots: None, connected: true }, NodeInfo { id: "18a61616f85b720fc8666c6d7f723635b9207526", ip: "172.28.0.7", port: 6379, status: Master, failed: false, slots: Some((10923, 16383)), connected: true }, NodeInfo { id: "5d541d199a3ea43106ba59d6bc9d3cb7971c7485", ip: "172.28.0.5", port: 6379, status: Slave, failed: false, slots: None, connected: true }, NodeInfo { id: "6928cf25ee199b2ed579ecc486b14d95e439faea", ip: "172.28.0.9", port: 6379, status: Master, failed: false, slots: Some((0, 5460)), connected: true }, NodeInfo { id: "ff30998fcb6118096cb1bbdec042d2b4dda75e78", ip: "172.28.0.10", port: 6379, status: Master, failed: false, slots: Some((5461, 10922)), connected: true }] }
2022-12-16T19:35:55.666164Z  INFO tests::redis::cluster: Node failed, cluster synced.
2022-12-16T19:35:55.666185Z  INFO tests::redis::utils: Try write...
2022-12-16T19:35:55.666281Z TRACE fred::interfaces: fred-01nYjfrksh: Sending command SET (0) to multiplexer.    
2022-12-16T19:35:55.666381Z TRACE fred::multiplexer::commands: fred-01nYjfrksh: Recv command: MultiplexerCommand { kind: "Command", command: "SET" }    
2022-12-16T19:35:55.666423Z TRACE fred::protocol::command: fred-01nYjfrksh: Pipeline check SET: true    
2022-12-16T19:35:55.666445Z TRACE fred::multiplexer: fred-01nYjfrksh: Writing command 0    
2022-12-16T19:35:55.666477Z DEBUG fred::multiplexer::clustered: fred-01nYjfrksh: Writing command `SET` to 172.28.0.8:6379    
2022-12-16T19:35:55.666500Z TRACE fred::multiplexer::utils: fred-01nYjfrksh: Writing command 0. Timed out: false, Force flush: false    
2022-12-16T19:35:55.666527Z TRACE fred::multiplexer::utils: fred-01nYjfrksh: Sending command SET to 172.28.0.8:6379, ID: 0    
2022-12-16T19:35:55.666557Z TRACE redis_protocol::utils: allocating more, len: 0, amt: 42    
2022-12-16T19:35:55.666588Z TRACE fred::protocol::codec: fred-01nYjfrksh: Encoded 42 bytes to 172.28.0.8:6379. Buffer len: 42 (RESP2)    
2022-12-16T19:35:55.666607Z TRACE tokio_util::codec::framed_impl: flushing framed transport
2022-12-16T19:35:55.666615Z TRACE tokio_util::codec::framed_impl: writing; remaining=42
2022-12-16T19:35:55.666671Z TRACE tokio_util::codec::framed_impl: framed transport flushed
2022-12-16T19:35:55.666698Z TRACE fred::multiplexer::commands: fred-01nYjfrksh: Sent command to 172.28.0.8:6379. Flushed: true    
2022-12-16T19:36:00.769924Z TRACE fred::interfaces: fred-gmQBHrH6mg: Sending command SET (0) to multiplexer.    
2022-12-16T19:36:00.770273Z TRACE fred::multiplexer::commands: fred-gmQBHrH6mg: Recv command: MultiplexerCommand { kind: "Command", command: "SET" }    
2022-12-16T19:36:00.770431Z TRACE fred::protocol::command: fred-gmQBHrH6mg: Pipeline check SET: true    
2022-12-16T19:36:00.770531Z TRACE fred::multiplexer: fred-gmQBHrH6mg: Writing command 0    
2022-12-16T19:36:00.770664Z DEBUG fred::multiplexer::clustered: fred-gmQBHrH6mg: Writing command `SET` to 172.28.0.8:6379    
2022-12-16T19:36:00.770776Z TRACE fred::multiplexer::utils: fred-gmQBHrH6mg: Writing command 0. Timed out: false, Force flush: false    
2022-12-16T19:36:00.770902Z TRACE fred::multiplexer::utils: fred-gmQBHrH6mg: Sending command SET to 172.28.0.8:6379, ID: 0    
2022-12-16T19:36:00.771043Z TRACE redis_protocol::utils: allocating more, len: 0, amt: 42    
2022-12-16T19:36:00.771196Z TRACE fred::protocol::codec: fred-gmQBHrH6mg: Encoded 42 bytes to 172.28.0.8:6379. Buffer len: 42 (RESP2)    
2022-12-16T19:36:00.771282Z TRACE tokio_util::codec::framed_impl: flushing framed transport
2022-12-16T19:36:00.771343Z TRACE tokio_util::codec::framed_impl: writing; remaining=42
2022-12-16T19:36:00.771557Z TRACE tokio_util::codec::framed_impl: framed transport flushed
2022-12-16T19:36:00.771711Z TRACE fred::multiplexer::commands: fred-gmQBHrH6mg: Sent command to 172.28.0.8:6379. Flushed: true    
2022-12-16T19:36:05.873474Z TRACE fred::interfaces: fred-g9HeDABrKA: Sending command SET (0) to multiplexer.    
2022-12-16T19:36:05.873957Z TRACE fred::multiplexer::commands: fred-g9HeDABrKA: Recv command: MultiplexerCommand { kind: "Command", command: "SET" }    
2022-12-16T19:36:05.874169Z TRACE fred::protocol::command: fred-g9HeDABrKA: Pipeline check SET: true    
2022-12-16T19:36:05.874265Z TRACE fred::multiplexer: fred-g9HeDABrKA: Writing command 0    
2022-12-16T19:36:05.874416Z DEBUG fred::multiplexer::clustered: fred-g9HeDABrKA: Writing command `SET` to 172.28.0.8:6379    
2022-12-16T19:36:05.874542Z TRACE fred::multiplexer::utils: fred-g9HeDABrKA: Writing command 0. Timed out: false, Force flush: false    
2022-12-16T19:36:05.874701Z TRACE fred::multiplexer::utils: fred-g9HeDABrKA: Sending command SET to 172.28.0.8:6379, ID: 0    
2022-12-16T19:36:05.874858Z TRACE redis_protocol::utils: allocating more, len: 0, amt: 42    
2022-12-16T19:36:05.875072Z TRACE fred::protocol::codec: fred-g9HeDABrKA: Encoded 42 bytes to 172.28.0.8:6379. Buffer len: 42 (RESP2)    
2022-12-16T19:36:05.875189Z TRACE tokio_util::codec::framed_impl: flushing framed transport
2022-12-16T19:36:05.875262Z TRACE tokio_util::codec::framed_impl: writing; remaining=42
2022-12-16T19:36:05.875485Z TRACE tokio_util::codec::framed_impl: framed transport flushed
2022-12-16T19:36:05.875623Z TRACE fred::multiplexer::commands: fred-g9HeDABrKA: Sent command to 172.28.0.8:6379. Flushed: true    
2022-12-16T19:36:10.977373Z TRACE fred::interfaces: fred-RSX6byRk7w: Sending command SET (0) to multiplexer.    
2022-12-16T19:36:10.977751Z TRACE fred::multiplexer::commands: fred-RSX6byRk7w: Recv command: MultiplexerCommand { kind: "Command", command: "SET" }    
2022-12-16T19:36:10.977932Z TRACE fred::protocol::command: fred-RSX6byRk7w: Pipeline check SET: true    
2022-12-16T19:36:10.978041Z TRACE fred::multiplexer: fred-RSX6byRk7w: Writing command 0    
2022-12-16T19:36:10.978186Z DEBUG fred::multiplexer::clustered: fred-RSX6byRk7w: Writing command `SET` to 172.28.0.8:6379    
2022-12-16T19:36:10.978308Z TRACE fred::multiplexer::utils: fred-RSX6byRk7w: Writing command 0. Timed out: false, Force flush: false    
2022-12-16T19:36:10.978448Z TRACE fred::multiplexer::utils: fred-RSX6byRk7w: Sending command SET to 172.28.0.8:6379, ID: 0    
2022-12-16T19:36:10.978595Z TRACE redis_protocol::utils: allocating more, len: 0, amt: 42    
2022-12-16T19:36:10.978765Z TRACE fred::protocol::codec: fred-RSX6byRk7w: Encoded 42 bytes to 172.28.0.8:6379. Buffer len: 42 (RESP2)    
2022-12-16T19:36:10.978898Z TRACE tokio_util::codec::framed_impl: flushing framed transport
2022-12-16T19:36:10.978969Z TRACE tokio_util::codec::framed_impl: writing; remaining=42
2022-12-16T19:36:10.979216Z TRACE tokio_util::codec::framed_impl: framed transport flushed
2022-12-16T19:36:10.979332Z TRACE fred::multiplexer::commands: fred-RSX6byRk7w: Sent command to 172.28.0.8:6379. Flushed: true    
2022-12-16T19:36:16.081346Z TRACE fred::interfaces: fred-OW9vswalca: Sending command SET (0) to multiplexer.    
2022-12-16T19:36:16.081716Z TRACE fred::multiplexer::commands: fred-OW9vswalca: Recv command: MultiplexerCommand { kind: "Command", command: "SET" }    
2022-12-16T19:36:16.081884Z TRACE fred::protocol::command: fred-OW9vswalca: Pipeline check SET: true    
2022-12-16T19:36:16.081956Z TRACE fred::multiplexer: fred-OW9vswalca: Writing command 0    
2022-12-16T19:36:16.082068Z DEBUG fred::multiplexer::clustered: fred-OW9vswalca: Writing command `SET` to 172.28.0.8:6379    
2022-12-16T19:36:16.082200Z TRACE fred::multiplexer::utils: fred-OW9vswalca: Writing command 0. Timed out: false, Force flush: false    
2022-12-16T19:36:16.082326Z TRACE fred::multiplexer::utils: fred-OW9vswalca: Sending command SET to 172.28.0.8:6379, ID: 0    
2022-12-16T19:36:16.082459Z TRACE redis_protocol::utils: allocating more, len: 0, amt: 42    
2022-12-16T19:36:16.082655Z TRACE fred::protocol::codec: fred-OW9vswalca: Encoded 42 bytes to 172.28.0.8:6379. Buffer len: 42 (RESP2)    
2022-12-16T19:36:16.082762Z TRACE tokio_util::codec::framed_impl: flushing framed transport
2022-12-16T19:36:16.082836Z TRACE tokio_util::codec::framed_impl: writing; remaining=42
2022-12-16T19:36:16.083080Z TRACE tokio_util::codec::framed_impl: framed transport flushed
2022-12-16T19:36:16.083206Z TRACE fred::multiplexer::commands: fred-OW9vswalca: Sent command to 172.28.0.8:6379. Flushed: true    
2022-12-16T19:36:21.183998Z TRACE fred::interfaces: fred-iRGXoULh4I: Sending command SET (0) to multiplexer.    
2022-12-16T19:36:21.184777Z TRACE fred::multiplexer::commands: fred-iRGXoULh4I: Recv command: MultiplexerCommand { kind: "Command", command: "SET" }    
2022-12-16T19:36:21.184961Z TRACE fred::protocol::command: fred-iRGXoULh4I: Pipeline check SET: true    
2022-12-16T19:36:21.185035Z TRACE fred::multiplexer: fred-iRGXoULh4I: Writing command 0    
2022-12-16T19:36:21.185160Z DEBUG fred::multiplexer::clustered: fred-iRGXoULh4I: Writing command `SET` to 172.28.0.8:6379    
2022-12-16T19:36:21.185284Z TRACE fred::multiplexer::utils: fred-iRGXoULh4I: Writing command 0. Timed out: false, Force flush: false    
2022-12-16T19:36:21.185432Z TRACE fred::multiplexer::utils: fred-iRGXoULh4I: Sending command SET to 172.28.0.8:6379, ID: 0    
2022-12-16T19:36:21.185696Z TRACE redis_protocol::utils: allocating more, len: 0, amt: 42    
2022-12-16T19:36:21.185875Z TRACE fred::protocol::codec: fred-iRGXoULh4I: Encoded 42 bytes to 172.28.0.8:6379. Buffer len: 42 (RESP2)    
2022-12-16T19:36:21.185998Z TRACE tokio_util::codec::framed_impl: flushing framed transport
2022-12-16T19:36:21.186061Z TRACE tokio_util::codec::framed_impl: writing; remaining=42
2022-12-16T19:36:21.186262Z TRACE tokio_util::codec::framed_impl: framed transport flushed
2022-12-16T19:36:21.186405Z TRACE fred::multiplexer::commands: fred-iRGXoULh4I: Sent command to 172.28.0.8:6379. Flushed: true    
2022-12-16T19:36:26.186786Z TRACE fred::interfaces: fred-01nYjfrksh: Sending command SET (0) to multiplexer.    
2022-12-16T19:36:26.187177Z TRACE fred::multiplexer::commands: fred-01nYjfrksh: Recv command: MultiplexerCommand { kind: "Command", command: "SET" }    
2022-12-16T19:36:26.187375Z TRACE fred::protocol::command: fred-01nYjfrksh: Pipeline check SET: true    
2022-12-16T19:36:26.187501Z TRACE fred::multiplexer: fred-01nYjfrksh: Writing command 0    
2022-12-16T19:36:26.187644Z DEBUG fred::multiplexer::clustered: fred-01nYjfrksh: Writing command `SET` to 172.28.0.8:6379    
2022-12-16T19:36:26.187763Z TRACE fred::multiplexer::utils: fred-01nYjfrksh: Writing command 0. Timed out: false, Force flush: false    
2022-12-16T19:36:26.187894Z TRACE fred::multiplexer::utils: fred-01nYjfrksh: Sending command SET to 172.28.0.8:6379, ID: 0    
2022-12-16T19:36:26.188038Z TRACE redis_protocol::utils: allocating more, len: 0, amt: 42    
2022-12-16T19:36:26.188201Z TRACE fred::protocol::codec: fred-01nYjfrksh: Encoded 42 bytes to 172.28.0.8:6379. Buffer len: 42 (RESP2)    
2022-12-16T19:36:26.188308Z TRACE tokio_util::codec::framed_impl: flushing framed transport
2022-12-16T19:36:26.188370Z TRACE tokio_util::codec::framed_impl: writing; remaining=42
2022-12-16T19:36:26.188585Z TRACE tokio_util::codec::framed_impl: framed transport flushed
2022-12-16T19:36:26.188707Z TRACE fred::multiplexer::commands: fred-01nYjfrksh: Sent command to 172.28.0.8:6379. Flushed: true    
2022-12-16T19:36:31.290571Z TRACE fred::interfaces: fred-gmQBHrH6mg: Sending command SET (0) to multiplexer.    
2022-12-16T19:36:31.291154Z TRACE fred::multiplexer::commands: fred-gmQBHrH6mg: Recv command: MultiplexerCommand { kind: "Command", command: "SET" }    
2022-12-16T19:36:31.291343Z TRACE fred::protocol::command: fred-gmQBHrH6mg: Pipeline check SET: true    
2022-12-16T19:36:31.291447Z TRACE fred::multiplexer: fred-gmQBHrH6mg: Writing command 0    
2022-12-16T19:36:31.291614Z DEBUG fred::multiplexer::clustered: fred-gmQBHrH6mg: Writing command `SET` to 172.28.0.8:6379    
2022-12-16T19:36:31.291757Z TRACE fred::multiplexer::utils: fred-gmQBHrH6mg: Writing command 0. Timed out: false, Force flush: false    
2022-12-16T19:36:31.291907Z TRACE fred::multiplexer::utils: fred-gmQBHrH6mg: Sending command SET to 172.28.0.8:6379, ID: 0    
2022-12-16T19:36:31.292054Z TRACE redis_protocol::utils: allocating more, len: 0, amt: 42    
2022-12-16T19:36:31.292172Z TRACE fred::protocol::codec: fred-gmQBHrH6mg: Encoded 42 bytes to 172.28.0.8:6379. Buffer len: 42 (RESP2)    
2022-12-16T19:36:31.292279Z TRACE tokio_util::codec::framed_impl: flushing framed transport
2022-12-16T19:36:31.292321Z TRACE tokio_util::codec::framed_impl: writing; remaining=42
2022-12-16T19:36:31.292574Z TRACE tokio_util::codec::framed_impl: framed transport flushed
2022-12-16T19:36:31.292706Z TRACE fred::multiplexer::commands: fred-gmQBHrH6mg: Sent command to 172.28.0.8:6379. Flushed: true    
2022-12-16T19:36:36.393224Z TRACE fred::interfaces: fred-g9HeDABrKA: Sending command SET (0) to multiplexer.    
2022-12-16T19:36:36.393821Z TRACE fred::multiplexer::commands: fred-g9HeDABrKA: Recv command: MultiplexerCommand { kind: "Command", command: "SET" }    
2022-12-16T19:36:36.394011Z TRACE fred::protocol::command: fred-g9HeDABrKA: Pipeline check SET: true    
2022-12-16T19:36:36.394084Z TRACE fred::multiplexer: fred-g9HeDABrKA: Writing command 0    
2022-12-16T19:36:36.394195Z DEBUG fred::multiplexer::clustered: fred-g9HeDABrKA: Writing command `SET` to 172.28.0.8:6379    
2022-12-16T19:36:36.394311Z TRACE fred::multiplexer::utils: fred-g9HeDABrKA: Writing command 0. Timed out: false, Force flush: false    
2022-12-16T19:36:36.394447Z TRACE fred::multiplexer::utils: fred-g9HeDABrKA: Sending command SET to 172.28.0.8:6379, ID: 0    
2022-12-16T19:36:36.394594Z TRACE redis_protocol::utils: allocating more, len: 0, amt: 42    
2022-12-16T19:36:36.394768Z TRACE fred::protocol::codec: fred-g9HeDABrKA: Encoded 42 bytes to 172.28.0.8:6379. Buffer len: 42 (RESP2)    
2022-12-16T19:36:36.394864Z TRACE tokio_util::codec::framed_impl: flushing framed transport
2022-12-16T19:36:36.394906Z TRACE tokio_util::codec::framed_impl: writing; remaining=42
2022-12-16T19:36:36.395106Z TRACE tokio_util::codec::framed_impl: framed transport flushed
2022-12-16T19:36:36.395220Z TRACE fred::multiplexer::commands: fred-g9HeDABrKA: Sent command to 172.28.0.8:6379. Flushed: true    
2022-12-16T19:36:41.497368Z TRACE fred::interfaces: fred-RSX6byRk7w: Sending command SET (0) to multiplexer.    
2022-12-16T19:36:41.497746Z TRACE fred::multiplexer::commands: fred-RSX6byRk7w: Recv command: MultiplexerCommand { kind: "Command", command: "SET" }    
2022-12-16T19:36:41.497939Z TRACE fred::protocol::command: fred-RSX6byRk7w: Pipeline check SET: true    
2022-12-16T19:36:41.498074Z TRACE fred::multiplexer: fred-RSX6byRk7w: Writing command 0    
2022-12-16T19:36:41.498219Z DEBUG fred::multiplexer::clustered: fred-RSX6byRk7w: Writing command `SET` to 172.28.0.8:6379    
2022-12-16T19:36:41.498347Z TRACE fred::multiplexer::utils: fred-RSX6byRk7w: Writing command 0. Timed out: false, Force flush: false    
2022-12-16T19:36:41.498496Z TRACE fred::multiplexer::utils: fred-RSX6byRk7w: Sending command SET to 172.28.0.8:6379, ID: 0    
2022-12-16T19:36:41.498645Z TRACE redis_protocol::utils: allocating more, len: 0, amt: 42    
2022-12-16T19:36:41.498810Z TRACE fred::protocol::codec: fred-RSX6byRk7w: Encoded 42 bytes to 172.28.0.8:6379. Buffer len: 42 (RESP2)    
2022-12-16T19:36:41.498932Z TRACE tokio_util::codec::framed_impl: flushing framed transport
2022-12-16T19:36:41.498995Z TRACE tokio_util::codec::framed_impl: writing; remaining=42
2022-12-16T19:36:41.499244Z TRACE tokio_util::codec::framed_impl: framed transport flushed
2022-12-16T19:36:41.499358Z TRACE fred::multiplexer::commands: fred-RSX6byRk7w: Sent command to 172.28.0.8:6379. Flushed: true    
2022-12-16T19:36:46.601321Z TRACE fred::interfaces: fred-OW9vswalca: Sending command SET (0) to multiplexer.    
2022-12-16T19:36:46.601773Z TRACE fred::multiplexer::commands: fred-OW9vswalca: Recv command: MultiplexerCommand { kind: "Command", command: "SET" }    
2022-12-16T19:36:46.601954Z TRACE fred::protocol::command: fred-OW9vswalca: Pipeline check SET: true    
2022-12-16T19:36:46.602040Z TRACE fred::multiplexer: fred-OW9vswalca: Writing command 0    
2022-12-16T19:36:46.602178Z DEBUG fred::multiplexer::clustered: fred-OW9vswalca: Writing command `SET` to 172.28.0.8:6379    
2022-12-16T19:36:46.602316Z TRACE fred::multiplexer::utils: fred-OW9vswalca: Writing command 0. Timed out: false, Force flush: false    
2022-12-16T19:36:46.602454Z TRACE fred::multiplexer::utils: fred-OW9vswalca: Sending command SET to 172.28.0.8:6379, ID: 0    
2022-12-16T19:36:46.602618Z TRACE redis_protocol::utils: allocating more, len: 0, amt: 42    
2022-12-16T19:36:46.602784Z TRACE fred::protocol::codec: fred-OW9vswalca: Encoded 42 bytes to 172.28.0.8:6379. Buffer len: 42 (RESP2)    
2022-12-16T19:36:46.602898Z TRACE tokio_util::codec::framed_impl: flushing framed transport
2022-12-16T19:36:46.602975Z TRACE tokio_util::codec::framed_impl: writing; remaining=42
2022-12-16T19:36:46.603244Z TRACE tokio_util::codec::framed_impl: framed transport flushed
2022-12-16T19:36:46.603392Z TRACE fred::multiplexer::commands: fred-OW9vswalca: Sent command to 172.28.0.8:6379. Flushed: true    
2022-12-16T19:36:51.705466Z TRACE fred::interfaces: fred-iRGXoULh4I: Sending command SET (0) to multiplexer.    
2022-12-16T19:36:51.705890Z TRACE fred::multiplexer::commands: fred-iRGXoULh4I: Recv command: MultiplexerCommand { kind: "Command", command: "SET" }    
2022-12-16T19:36:51.706076Z TRACE fred::protocol::command: fred-iRGXoULh4I: Pipeline check SET: true    
2022-12-16T19:36:51.706179Z TRACE fred::multiplexer: fred-iRGXoULh4I: Writing command 0    
2022-12-16T19:36:51.706315Z DEBUG fred::multiplexer::clustered: fred-iRGXoULh4I: Writing command `SET` to 172.28.0.8:6379    
2022-12-16T19:36:51.706422Z TRACE fred::multiplexer::utils: fred-iRGXoULh4I: Writing command 0. Timed out: false, Force flush: false    
2022-12-16T19:36:51.706545Z TRACE fred::multiplexer::utils: fred-iRGXoULh4I: Sending command SET to 172.28.0.8:6379, ID: 0    
2022-12-16T19:36:51.706677Z TRACE redis_protocol::utils: allocating more, len: 0, amt: 42    
2022-12-16T19:36:51.706832Z TRACE fred::protocol::codec: fred-iRGXoULh4I: Encoded 42 bytes to 172.28.0.8:6379. Buffer len: 42 (RESP2)    
2022-12-16T19:36:51.706960Z TRACE tokio_util::codec::framed_impl: flushing framed transport
2022-12-16T19:36:51.707015Z TRACE tokio_util::codec::framed_impl: writing; remaining=42
2022-12-16T19:36:51.707239Z TRACE tokio_util::codec::framed_impl: framed transport flushed
2022-12-16T19:36:51.707363Z TRACE fred::multiplexer::commands: fred-iRGXoULh4I: Sent command to 172.28.0.8:6379. Flushed: true    

@neogenie
Copy link
Contributor Author

@aembke

Unfortunately, no changes so far...

It should be noted that my test script contains both cases

  • hard break of the connection - in this case everything was handled correctly in the previous version - the library detects that the connection is broken and rebuilds the cluster configuration. In this case, there is a physical break of the network connection.

  • soft break, when the network stack is unable to determine that the connection is down (I use docker container pause in my script) - only timeouts can help in this case. It was not by chance that I made a reference to my PR - there I added timeouts so that a staled connection could be determined. This script still doesn't work.

It seems to me that the problem now is that the library does not contain either active or even passive health-checks for the activity of network connections. It looks like there are two ways to solve the problem:

  • active health-checks - heartbeats running in the background (Redis supports them by the way)
  • passive health-checks - each command has a built-in timeout after which the connection must be checked for availability.

@aembke
Copy link
Owner

aembke commented Dec 16, 2022

Thanks for checking that, and that all makes sense. The PR this morning addresses a third scenario where node A is paused and the client sends a command to node B but node B responds with CLUSTERDOWN. Prior to the changes this morning that would result an error.

Appreciate the continued feedback and I'll update this when the second scenario you outline is handled.

@aembke
Copy link
Owner

aembke commented Dec 18, 2022

Quick update here:

The changes in #63 are written against the older major version so I had to update them for the 6.0.0, but those are merged in the latest PR (#85). This adds timeouts to all the connection initialization logic.

That will help with unresponsive connections if the server stops responding during connection initialization or a cluster sync operation, but won't detect connections that stop responding while waiting on other commands. I added a new FF check-unresponsive that adds additional active monitoring for unresponsive connections to handle this scenario. There are docs describing how to configure it here.

Hopefully this helps. If it doesn't fix your use case please let me know.

@neogenie
Copy link
Contributor Author

2022-12-18T21:44:31.419669Z  INFO tests::redis::cluster: Cluster state: 

77fcb21e16b5eeae900540f604a757caf9a78d88 172.26.0.5:6379@16379 master - 0 1671399870445 3 connected 10923-16383
085041de28919a5ae32b8f908027654fd8a6cdcc 172.26.0.10:6379@16379 master,fail - 1671399868035 1671399867000 1 connected
bae44cda74e2096d01df707c4ca2e26d3e65849c 172.26.0.7:6379@16379 master - 0 1671399871000 7 connected 0-5460
b6b0a631f0fbb0437c98cd7fa91e083d0db01e3d 172.26.0.9:6379@16379 myself,master - 0 1671399870000 2 connected 5461-10922
1a27c1a87101b661050e175487cf7124bb646201 172.26.0.8:6379@16379 slave 77fcb21e16b5eeae900540f604a757caf9a78d88 0 1671399871047 3 connected
b2d10c87600231d9e80f3a1dba1ea81e0a2c73f3 172.26.0.6:6379@16379 slave b6b0a631f0fbb0437c98cd7fa91e083d0db01e3d 0 1671399871047 2 connected

2022-12-18T21:44:31.419755Z DEBUG tests::redis::cluster: Check cluster status...
2022-12-18T21:44:31.419828Z DEBUG bollard::docker: {"AttachStdin":null,"AttachStdout":true,"AttachStderr":null,"Tty":null,"DetachKeys":null,"Env":null,"Cmd":["redis-cli","-c","-a","qwerty","CLUSTER","INFO"],"Privileged":null,"User":null,"WorkingDir":null}    
2022-12-18T21:44:31.419956Z DEBUG bollard::uri: Parsing uri: unix://2f7661722f72756e2f646f636b65722e736f636b/containers/8eda19a6f873f97022062cc1a4fe4489b4eaab26f49f97340ee3687e6dde29c5/exec, client_type: Unix, socket: /var/run/docker.sock    
2022-12-18T21:44:31.420000Z DEBUG bollard::docker: unix://2f7661722f72756e2f646f636b65722e736f636b/containers/8eda19a6f873f97022062cc1a4fe4489b4eaab26f49f97340ee3687e6dde29c5/exec    
2022-12-18T21:44:31.420042Z DEBUG bollard::docker: request: Request { method: POST, uri: unix://2f7661722f72756e2f646f636b65722e736f636b/containers/8eda19a6f873f97022062cc1a4fe4489b4eaab26f49f97340ee3687e6dde29c5/exec, version: HTTP/1.1, headers: {"content-type": "application/json"}, body: Body(Full(b"{\"AttachStdin\":null,\"AttachStdout\":true,\"AttachStderr\":null,\"Tty\":null,\"DetachKeys\":null,\"Env\":null,\"Cmd\":[\"redis-cli\",\"-c\",\"-a\",\"qwerty\",\"CLUSTER\",\"INFO\"],\"Privileged\":null,\"User\":null,\"WorkingDir\":null}")) }    
2022-12-18T21:44:31.420202Z TRACE mio::poll: registering event source with poller: token=Token(788529171), interests=READABLE | WRITABLE    
2022-12-18T21:44:31.420369Z TRACE hyper::client::conn: client handshake Http1
2022-12-18T21:44:31.420440Z TRACE hyper::client::client: handshake complete, spawning background dispatcher task
2022-12-18T21:44:31.420584Z TRACE want: signal: Want    
2022-12-18T21:44:31.420620Z TRACE want: signal found waiting giver, notifying    
2022-12-18T21:44:31.420649Z TRACE hyper::proto::h1::conn: flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Busy }
2022-12-18T21:44:31.420658Z TRACE want: poll_want: taker wants!    
2022-12-18T21:44:31.420800Z TRACE encode_headers: hyper::proto::h1::role: Client::encode method=POST, body=Some(Known(204))
2022-12-18T21:44:31.420892Z TRACE hyper::proto::h1::io: buffer.flatten self.len=200 buf.len=204
2022-12-18T21:44:31.420936Z DEBUG hyper::proto::h1::io: flushed 404 bytes
2022-12-18T21:44:31.420966Z TRACE hyper::proto::h1::conn: flushed({role=client}): State { reading: Init, writing: KeepAlive, keep_alive: Busy }
2022-12-18T21:44:31.421277Z TRACE hyper::proto::h1::conn: Conn::read_head
2022-12-18T21:44:31.421321Z TRACE hyper::proto::h1::io: received 281 bytes
2022-12-18T21:44:31.421364Z TRACE parse_headers: hyper::proto::h1::role: Response.parse bytes=281
2022-12-18T21:44:31.421428Z TRACE parse_headers: hyper::proto::h1::role: Response.parse Complete(207)
2022-12-18T21:44:31.421544Z DEBUG hyper::proto::h1::io: parsed 7 headers
2022-12-18T21:44:31.421567Z DEBUG hyper::proto::h1::conn: incoming body is content-length (74 bytes)
2022-12-18T21:44:31.421616Z TRACE hyper::proto::h1::decode: decode; state=Length(74)
2022-12-18T21:44:31.421642Z DEBUG hyper::proto::h1::conn: incoming body completed
2022-12-18T21:44:31.421659Z TRACE hyper::proto::h1::conn: maybe_notify; read_from_io blocked
2022-12-18T21:44:31.421700Z TRACE hyper::proto::h1::dispatch: client tx closed
2022-12-18T21:44:31.421718Z TRACE hyper::proto::h1::conn: State::close_read()
2022-12-18T21:44:31.421727Z TRACE hyper::proto::h1::conn: State::close_write()
2022-12-18T21:44:31.421740Z TRACE hyper::proto::h1::conn: flushed({role=client}): State { reading: Closed, writing: Closed, keep_alive: Disabled }
2022-12-18T21:44:31.421753Z TRACE hyper::proto::h1::conn: flushed({role=client}): State { reading: Closed, writing: Closed, keep_alive: Disabled }
2022-12-18T21:44:31.421773Z TRACE hyper::proto::h1::conn: shut down IO complete
2022-12-18T21:44:31.421801Z TRACE mio::poll: deregistering event source from poller    
2022-12-18T21:44:31.421850Z TRACE want: signal: Closed    
2022-12-18T21:44:31.421938Z DEBUG bollard::docker: Decoded into string: {"Id":"647bbfc32a031faf5d712ef8d56ef66434c3bb59b09fa4d2a252a1b9aee937db"}    
2022-12-18T21:44:31.422008Z DEBUG bollard::docker: {"Detach":false,"OutputCapacity":null}    
2022-12-18T21:44:31.422110Z DEBUG bollard::uri: Parsing uri: unix://2f7661722f72756e2f646f636b65722e736f636b/exec/647bbfc32a031faf5d712ef8d56ef66434c3bb59b09fa4d2a252a1b9aee937db/start, client_type: Unix, socket: /var/run/docker.sock    
2022-12-18T21:44:31.422143Z DEBUG bollard::docker: unix://2f7661722f72756e2f646f636b65722e736f636b/exec/647bbfc32a031faf5d712ef8d56ef66434c3bb59b09fa4d2a252a1b9aee937db/start    
2022-12-18T21:44:31.422171Z DEBUG bollard::docker: request: Request { method: POST, uri: unix://2f7661722f72756e2f646f636b65722e736f636b/exec/647bbfc32a031faf5d712ef8d56ef66434c3bb59b09fa4d2a252a1b9aee937db/start, version: HTTP/1.1, headers: {"connection": "Upgrade", "upgrade": "tcp", "content-type": "application/json"}, body: Body(Full(b"{\"Detach\":false,\"OutputCapacity\":null}")) }    
2022-12-18T21:44:31.422285Z TRACE mio::poll: registering event source with poller: token=Token(805306387), interests=READABLE | WRITABLE    
2022-12-18T21:44:31.422344Z TRACE hyper::client::conn: client handshake Http1
2022-12-18T21:44:31.422382Z TRACE hyper::client::client: handshake complete, spawning background dispatcher task
2022-12-18T21:44:31.422452Z TRACE want: signal: Want    
2022-12-18T21:44:31.422484Z TRACE want: signal found waiting giver, notifying    
2022-12-18T21:44:31.422513Z TRACE hyper::proto::h1::conn: flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Busy }
2022-12-18T21:44:31.422526Z TRACE want: poll_want: taker wants!    
2022-12-18T21:44:31.422640Z TRACE encode_headers: hyper::proto::h1::role: Client::encode method=POST, body=Some(Known(38))
2022-12-18T21:44:31.422712Z TRACE hyper::proto::h1::io: buffer.flatten self.len=229 buf.len=38
2022-12-18T21:44:31.422748Z DEBUG hyper::proto::h1::io: flushed 267 bytes
2022-12-18T21:44:31.422771Z TRACE hyper::proto::h1::conn: flushed({role=client}): State { reading: Init, writing: KeepAlive, keep_alive: Busy }
2022-12-18T21:44:31.422947Z TRACE hyper::proto::h1::conn: Conn::read_head
2022-12-18T21:44:31.423011Z TRACE hyper::proto::h1::io: received 203 bytes
2022-12-18T21:44:31.423060Z TRACE parse_headers: hyper::proto::h1::role: Response.parse bytes=203
2022-12-18T21:44:31.423123Z TRACE parse_headers: hyper::proto::h1::role: Response.parse Complete(203)
2022-12-18T21:44:31.423217Z DEBUG hyper::proto::h1::io: parsed 7 headers
2022-12-18T21:44:31.423236Z DEBUG hyper::proto::h1::conn: incoming body is empty
2022-12-18T21:44:31.423250Z TRACE hyper::proto::h1::conn: remote disabling keep-alive
2022-12-18T21:44:31.423264Z TRACE hyper::proto::h1::conn: try_keep_alive({role=client}): could keep-alive, but status = Disabled
2022-12-18T21:44:31.423276Z TRACE hyper::proto::h1::conn: State::close()
2022-12-18T21:44:31.423289Z TRACE hyper::proto::h1::conn: {role=client}: prepare possible HTTP upgrade
2022-12-18T21:44:31.423331Z TRACE hyper::proto::h1::conn: flushed({role=client}): State { reading: Closed, writing: Closed, keep_alive: Disabled }
2022-12-18T21:44:31.423365Z TRACE want: signal: Closed    
2022-12-18T21:44:31.423424Z TRACE hyper::upgrade: pending upgrade fulfill
2022-12-18T21:44:31.598156Z TRACE tokio_util::codec::framed_impl: attempting to decode a frame
2022-12-18T21:44:31.598238Z DEBUG bollard::read: NewlineLogOutputDecoder: read header, type = 1, length = 634    
2022-12-18T21:44:31.598266Z DEBUG bollard::read: NewlineLogOutputDecoder: Reading payload    
2022-12-18T21:44:31.598283Z TRACE tokio_util::codec::framed_impl: frame decoded from buffer
2022-12-18T21:44:31.598305Z TRACE tokio_util::codec::framed_impl: attempting to decode a frame
2022-12-18T21:44:31.598326Z DEBUG bollard::read: NewlineLogOutputDecoder: not enough data for read header    
2022-12-18T21:44:31.615371Z DEBUG bollard::read: NewlineLogOutputDecoder: not enough data for read header    
2022-12-18T21:44:31.615721Z TRACE mio::poll: deregistering event source from poller    
2022-12-18T21:44:31.615764Z DEBUG tests::redis::cluster: Cluster status: 
cluster_state:ok
cluster_slots_assigned:16384
cluster_slots_ok:16384
cluster_slots_pfail:0
cluster_slots_fail:0
cluster_known_nodes:6
cluster_size:3
cluster_current_epoch:7
cluster_my_epoch:2
cluster_stats_messages_ping_sent:1529
cluster_stats_messages_pong_sent:1526
cluster_stats_messages_meet_sent:1
cluster_stats_messages_fail_sent:10
cluster_stats_messages_auth-ack_sent:1
cluster_stats_messages_sent:3067
cluster_stats_messages_ping_received:1526
cluster_stats_messages_pong_received:1527
cluster_stats_messages_fail_received:1
cluster_stats_messages_auth-req_received:1
cluster_stats_messages_received:3055

2022-12-18T21:44:31.615793Z  INFO tests::redis::cluster: Cluster state parsed: ClusterInfo { is_ok: true, nodes: [NodeInfo { id: "77fcb21e16b5eeae900540f604a757caf9a78d88", ip: "172.26.0.5", port: 6379, status: Master, failed: false, slots: Some((10923, 16383)), connected: true }, NodeInfo { id: "085041de28919a5ae32b8f908027654fd8a6cdcc", ip: "172.26.0.10", port: 6379, status: Master, failed: true, slots: None, connected: true }, NodeInfo { id: "bae44cda74e2096d01df707c4ca2e26d3e65849c", ip: "172.26.0.7", port: 6379, status: Master, failed: false, slots: Some((0, 5460)), connected: true }, NodeInfo { id: "b6b0a631f0fbb0437c98cd7fa91e083d0db01e3d", ip: "172.26.0.9", port: 6379, status: Master, failed: false, slots: Some((5461, 10922)), connected: true }, NodeInfo { id: "1a27c1a87101b661050e175487cf7124bb646201", ip: "172.26.0.8", port: 6379, status: Slave, failed: false, slots: None, connected: true }, NodeInfo { id: "b2d10c87600231d9e80f3a1dba1ea81e0a2c73f3", ip: "172.26.0.6", port: 6379, status: Slave, failed: false, slots: None, connected: true }] }
2022-12-18T21:44:31.615966Z  INFO tests::redis::cluster: Node failed, cluster synced.
2022-12-18T21:44:31.615994Z  INFO tests::redis::utils: Try write...


2022-12-18T21:44:31.616096Z TRACE fred::interfaces: fred-9lCBe4loFM: Sending command SET (0) to multiplexer.    
2022-12-18T21:44:31.616246Z TRACE fred::multiplexer::commands: fred-9lCBe4loFM: Recv command: MultiplexerCommand { kind: "Command", command: "SET" }    
2022-12-18T21:44:31.616299Z TRACE fred::protocol::command: fred-9lCBe4loFM: Pipeline check SET: true    
2022-12-18T21:44:31.616329Z TRACE fred::multiplexer: fred-9lCBe4loFM: Writing command 0    
2022-12-18T21:44:31.616373Z DEBUG fred::multiplexer::clustered: fred-9lCBe4loFM: Writing command `SET` to 172.26.0.10:6379    
2022-12-18T21:44:31.616400Z TRACE fred::multiplexer::utils: fred-9lCBe4loFM: Writing command 0. Timed out: false, Force flush: false    
2022-12-18T21:44:31.616435Z TRACE fred::multiplexer::utils: fred-9lCBe4loFM: Sending command SET to 172.26.0.10:6379, ID: 0    
2022-12-18T21:44:31.616472Z TRACE fred::multiplexer::commands: fred-9lCBe4loFM: Sent command to 172.26.0.10:6379. Flushed: false    
2022-12-18T21:44:31.616498Z TRACE fred::multiplexer: fred-9lCBe4loFM: Checking and flushing sockets...    
2022-12-18T21:44:31.616534Z TRACE fred::protocol::connection: Flushing socket to 172.26.0.9:6379    
2022-12-18T21:44:31.616558Z TRACE tokio_util::codec::framed_impl: flushing framed transport
2022-12-18T21:44:31.616572Z TRACE tokio_util::codec::framed_impl: framed transport flushed
2022-12-18T21:44:31.616588Z TRACE fred::protocol::connection: Flushed socket to 172.26.0.9:6379    
2022-12-18T21:44:31.616607Z TRACE fred::protocol::connection: Flushing socket to 172.26.0.10:6379    
2022-12-18T21:44:31.616633Z TRACE redis_protocol::utils: allocating more, len: 0, amt: 42    
2022-12-18T21:44:31.616669Z TRACE fred::protocol::codec: fred-9lCBe4loFM: Encoded 42 bytes to 172.26.0.10:6379. Buffer len: 42 (RESP2)    
2022-12-18T21:44:31.616692Z TRACE tokio_util::codec::framed_impl: flushing framed transport
2022-12-18T21:44:31.616704Z TRACE tokio_util::codec::framed_impl: writing; remaining=42
2022-12-18T21:44:31.616781Z TRACE tokio_util::codec::framed_impl: framed transport flushed
2022-12-18T21:44:31.616806Z TRACE fred::protocol::connection: Flushed socket to 172.26.0.10:6379    
2022-12-18T21:44:31.616828Z TRACE fred::protocol::connection: Flushing socket to 172.26.0.5:6379    
2022-12-18T21:44:31.616848Z TRACE tokio_util::codec::framed_impl: flushing framed transport
2022-12-18T21:44:31.616861Z TRACE tokio_util::codec::framed_impl: framed transport flushed
2022-12-18T21:44:31.616875Z TRACE fred::protocol::connection: Flushed socket to 172.26.0.5:6379    
2022-12-18T21:44:33.305093Z DEBUG fred::multiplexer::types: fred-lZa2RW6GBf: Checking unresponsive connections...    
2022-12-18T21:44:33.305151Z TRACE fred::multiplexer::types: fred-lZa2RW6GBf: Using network timeout: 5000    
2022-12-18T21:44:33.307300Z DEBUG fred::multiplexer::types: fred-6Corg17GBH: Checking unresponsive connections...    
2022-12-18T21:44:33.307328Z TRACE fred::multiplexer::types: fred-6Corg17GBH: Using network timeout: 5000    
2022-12-18T21:44:33.308472Z DEBUG fred::multiplexer::types: fred-pm7n0saPJP: Checking unresponsive connections...    
2022-12-18T21:44:33.308501Z TRACE fred::multiplexer::types: fred-pm7n0saPJP: Using network timeout: 5000    
2022-12-18T21:44:33.309653Z DEBUG fred::multiplexer::types: fred-d3vAUmx97z: Checking unresponsive connections...    
2022-12-18T21:44:33.309681Z TRACE fred::multiplexer::types: fred-d3vAUmx97z: Using network timeout: 5000    
2022-12-18T21:44:33.311808Z DEBUG fred::multiplexer::types: fred-9lCBe4loFM: Checking unresponsive connections...    
2022-12-18T21:44:33.311837Z TRACE fred::multiplexer::types: fred-9lCBe4loFM: Using network timeout: 5000    
2022-12-18T21:44:33.311875Z DEBUG fred::multiplexer::types: fred-Aru1iU2Ekr: Checking unresponsive connections...    
2022-12-18T21:44:33.311913Z TRACE fred::multiplexer::types: fred-Aru1iU2Ekr: Using network timeout: 5000    
2022-12-18T21:44:38.306246Z DEBUG fred::multiplexer::types: fred-lZa2RW6GBf: Checking unresponsive connections...    
2022-12-18T21:44:38.306312Z TRACE fred::multiplexer::types: fred-lZa2RW6GBf: Using network timeout: 5000    
2022-12-18T21:44:38.308495Z DEBUG fred::multiplexer::types: fred-6Corg17GBH: Checking unresponsive connections...    
2022-12-18T21:44:38.308531Z TRACE fred::multiplexer::types: fred-6Corg17GBH: Using network timeout: 5000    
2022-12-18T21:44:38.309663Z DEBUG fred::multiplexer::types: fred-pm7n0saPJP: Checking unresponsive connections...    
2022-12-18T21:44:38.309707Z TRACE fred::multiplexer::types: fred-pm7n0saPJP: Using network timeout: 5000    
2022-12-18T21:44:38.310840Z DEBUG fred::multiplexer::types: fred-d3vAUmx97z: Checking unresponsive connections...    
2022-12-18T21:44:38.310883Z TRACE fred::multiplexer::types: fred-d3vAUmx97z: Using network timeout: 5000    
2022-12-18T21:44:38.313034Z DEBUG fred::multiplexer::types: fred-Aru1iU2Ekr: Checking unresponsive connections...    
2022-12-18T21:44:38.313048Z DEBUG fred::multiplexer::types: fred-9lCBe4loFM: Checking unresponsive connections...    
2022-12-18T21:44:38.313084Z TRACE fred::multiplexer::types: fred-Aru1iU2Ekr: Using network timeout: 5000    
2022-12-18T21:44:38.313085Z TRACE fred::multiplexer::types: fred-9lCBe4loFM: Using network timeout: 5000    
2022-12-18T21:44:38.313127Z  WARN fred::multiplexer::types: fred-9lCBe4loFM: Server 172.26.0.10:6379 unresponsive after 6696 ms    
2022-12-18T21:44:38.313173Z DEBUG fred::multiplexer::types: fred-9lCBe4loFM: Interrupting reader task for 172.26.0.10:6379    
2022-12-18T21:44:38.313296Z DEBUG fred::multiplexer::utils: fred-9lCBe4loFM: Recv interrupt on 172.26.0.10:6379    
2022-12-18T21:44:38.313332Z DEBUG fred::multiplexer::types: fred-9lCBe4loFM: Unsubscribe from interrupts for 172.26.0.10:6379    
2022-12-18T21:44:38.313443Z DEBUG fred::multiplexer::responses: fred-9lCBe4loFM: Ending reader task from 172.26.0.10:6379 due to Some(Redis Error - kind: IO, details: Unresponsive connection.)    
2022-12-18T21:44:38.313475Z DEBUG fred::modules::inner: fred-9lCBe4loFM: Sending reconnect message to multiplexer for Some(Server { host: "172.26.0.10", port: 6379, tls_server_name: None })    
2022-12-18T21:44:38.313531Z DEBUG fred::modules::inner: fred-9lCBe4loFM: No `on_error` listener.    
2022-12-18T21:44:38.313557Z DEBUG fred::multiplexer::clustered: fred-9lCBe4loFM: Ending reader task from 172.26.0.10:6379    
2022-12-18T21:44:38.313624Z TRACE fred::multiplexer::commands: fred-9lCBe4loFM: Recv command: MultiplexerCommand { kind: "Reconnect", server: Some(Server { host: "172.26.0.10", port: 6379, tls_server_name: None }), force: false }    
2022-12-18T21:44:38.313660Z DEBUG fred::multiplexer::commands: fred-9lCBe4loFM: Maybe reconnecting to Some(Server { host: "172.26.0.10", port: 6379, tls_server_name: None }) (force: false)    
2022-12-18T21:44:38.313687Z DEBUG fred::multiplexer::commands: fred-9lCBe4loFM: Has working connection: false    
2022-12-18T21:44:38.313713Z DEBUG fred::multiplexer::commands: fred-9lCBe4loFM: Starting reconnection loop...    
2022-12-18T21:44:38.313748Z DEBUG fred::multiplexer::utils: fred-9lCBe4loFM: Sleeping for 120 ms.    
2022-12-18T21:44:38.313771Z DEBUG fred::modules::inner: fred-9lCBe4loFM: Sleeping for 120 ms    
2022-12-18T21:44:38.435155Z DEBUG fred::multiplexer: fred-9lCBe4loFM: Disconnecting from 172.26.0.9:6379    
2022-12-18T21:44:38.435211Z TRACE tokio_util::codec::framed_impl: flushing framed transport
2022-12-18T21:44:38.435222Z TRACE tokio_util::codec::framed_impl: framed transport flushed
2022-12-18T21:44:38.435358Z TRACE fred::protocol::codec: fred-9lCBe4loFM: Recv 0 bytes from 172.26.0.9:6379 (RESP2).    
2022-12-18T21:44:38.435402Z DEBUG fred::multiplexer::types: fred-9lCBe4loFM: Unsubscribe from interrupts for 172.26.0.9:6379    
2022-12-18T21:44:38.435495Z DEBUG fred::multiplexer::responses: fred-9lCBe4loFM: Ending reader task from 172.26.0.9:6379 due to None    
2022-12-18T21:44:38.435525Z DEBUG fred::modules::inner: fred-9lCBe4loFM: Sending reconnect message to multiplexer for Some(Server { host: "172.26.0.9", port: 6379, tls_server_name: None })    
2022-12-18T21:44:38.435547Z DEBUG fred::modules::inner: fred-9lCBe4loFM: No `on_error` listener.    
2022-12-18T21:44:38.435570Z DEBUG fred::multiplexer::clustered: fred-9lCBe4loFM: Ending reader task from 172.26.0.9:6379    
2022-12-18T21:44:38.435631Z TRACE mio::poll: deregistering event source from poller    
2022-12-18T21:44:38.435689Z DEBUG fred::multiplexer: fred-9lCBe4loFM: Disconnecting from 172.26.0.10:6379    
2022-12-18T21:44:38.435713Z TRACE tokio_util::codec::framed_impl: flushing framed transport
2022-12-18T21:44:38.435722Z TRACE tokio_util::codec::framed_impl: framed transport flushed
2022-12-18T21:44:38.435768Z TRACE mio::poll: deregistering event source from poller    
2022-12-18T21:44:38.435823Z DEBUG fred::multiplexer: fred-9lCBe4loFM: Disconnecting from 172.26.0.5:6379    
2022-12-18T21:44:38.435854Z TRACE tokio_util::codec::framed_impl: flushing framed transport
2022-12-18T21:44:38.435867Z TRACE tokio_util::codec::framed_impl: framed transport flushed
2022-12-18T21:44:38.436010Z TRACE fred::protocol::codec: fred-9lCBe4loFM: Recv 0 bytes from 172.26.0.5:6379 (RESP2).    
2022-12-18T21:44:38.436050Z DEBUG fred::multiplexer::types: fred-9lCBe4loFM: Unsubscribe from interrupts for 172.26.0.5:6379    
2022-12-18T21:44:38.436114Z DEBUG fred::multiplexer::responses: fred-9lCBe4loFM: Ending reader task from 172.26.0.5:6379 due to None    
2022-12-18T21:44:38.436146Z DEBUG fred::modules::inner: fred-9lCBe4loFM: Sending reconnect message to multiplexer for Some(Server { host: "172.26.0.5", port: 6379, tls_server_name: None })    
2022-12-18T21:44:38.436182Z DEBUG fred::modules::inner: fred-9lCBe4loFM: No `on_error` listener.    
2022-12-18T21:44:38.436207Z DEBUG fred::multiplexer::clustered: fred-9lCBe4loFM: Ending reader task from 172.26.0.5:6379    
2022-12-18T21:44:38.436264Z TRACE mio::poll: deregistering event source from poller    
2022-12-18T21:44:38.436317Z TRACE fred::multiplexer: fred-9lCBe4loFM: Adding SET (0) command to retry buffer.    
2022-12-18T21:44:38.436352Z DEBUG fred::multiplexer::types: fred-9lCBe4loFM: Syncing connection state with unresponsive network task.    
2022-12-18T21:44:38.436402Z DEBUG fred::multiplexer::clustered: fred-9lCBe4loFM: Synchronizing cluster state.    
2022-12-18T21:44:38.436453Z TRACE redis_protocol::utils: allocating more, len: 0, amt: 28    
2022-12-18T21:44:38.436502Z TRACE fred::protocol::codec: fred-9lCBe4loFM: Encoded 28 bytes to redis-node-1:6379. Buffer len: 28 (RESP2)    
2022-12-18T21:44:38.436534Z TRACE tokio_util::codec::framed_impl: flushing framed transport
2022-12-18T21:44:38.436553Z TRACE tokio_util::codec::framed_impl: writing; remaining=28
2022-12-18T21:44:38.436598Z TRACE tokio_util::codec::framed_impl: framed transport flushed
2022-12-18T21:44:38.436623Z TRACE tokio_util::codec::framed_impl: attempting to decode a frame
2022-12-18T21:44:38.436637Z TRACE fred::protocol::codec: fred-9lCBe4loFM: Recv 0 bytes from redis-node-1:6379 (RESP2).    



2022-12-18T21:44:41.719195Z TRACE fred::interfaces: fred-lZa2RW6GBf: Sending command SET (0) to multiplexer.    
2022-12-18T21:44:41.719317Z TRACE fred::multiplexer::commands: fred-lZa2RW6GBf: Recv command: MultiplexerCommand { kind: "Command", command: "SET" }    
2022-12-18T21:44:41.719361Z TRACE fred::protocol::command: fred-lZa2RW6GBf: Pipeline check SET: true    
2022-12-18T21:44:41.719416Z TRACE fred::multiplexer: fred-lZa2RW6GBf: Writing command 0    
2022-12-18T21:44:41.719471Z DEBUG fred::multiplexer::clustered: fred-lZa2RW6GBf: Writing command `SET` to 172.26.0.10:6379    
2022-12-18T21:44:41.719501Z TRACE fred::multiplexer::utils: fred-lZa2RW6GBf: Writing command 0. Timed out: false, Force flush: false    
2022-12-18T21:44:41.719537Z TRACE fred::multiplexer::utils: fred-lZa2RW6GBf: Sending command SET to 172.26.0.10:6379, ID: 0    
2022-12-18T21:44:41.719578Z TRACE fred::multiplexer::commands: fred-lZa2RW6GBf: Sent command to 172.26.0.10:6379. Flushed: false    
2022-12-18T21:44:41.719606Z TRACE fred::multiplexer: fred-lZa2RW6GBf: Checking and flushing sockets...    
2022-12-18T21:44:41.719642Z TRACE fred::protocol::connection: Flushing socket to 172.26.0.10:6379    
2022-12-18T21:44:41.719673Z TRACE redis_protocol::utils: allocating more, len: 0, amt: 42    
2022-12-18T21:44:41.719713Z TRACE fred::protocol::codec: fred-lZa2RW6GBf: Encoded 42 bytes to 172.26.0.10:6379. Buffer len: 42 (RESP2)    
2022-12-18T21:44:41.719745Z TRACE tokio_util::codec::framed_impl: flushing framed transport
2022-12-18T21:44:41.719763Z TRACE tokio_util::codec::framed_impl: writing; remaining=42
2022-12-18T21:44:41.719826Z TRACE tokio_util::codec::framed_impl: framed transport flushed
2022-12-18T21:44:41.719857Z TRACE fred::protocol::connection: Flushed socket to 172.26.0.10:6379    
2022-12-18T21:44:41.719884Z TRACE fred::protocol::connection: Flushing socket to 172.26.0.5:6379    
2022-12-18T21:44:41.719903Z TRACE tokio_util::codec::framed_impl: flushing framed transport
2022-12-18T21:44:41.719915Z TRACE tokio_util::codec::framed_impl: framed transport flushed
2022-12-18T21:44:41.719930Z TRACE fred::protocol::connection: Flushed socket to 172.26.0.5:6379    
2022-12-18T21:44:41.719949Z TRACE fred::protocol::connection: Flushing socket to 172.26.0.9:6379    
2022-12-18T21:44:41.719967Z TRACE tokio_util::codec::framed_impl: flushing framed transport
2022-12-18T21:44:41.719978Z TRACE tokio_util::codec::framed_impl: framed transport flushed
2022-12-18T21:44:41.719991Z TRACE fred::protocol::connection: Flushed socket to 172.26.0.9:6379    
2022-12-18T21:44:43.307643Z DEBUG fred::multiplexer::types: fred-lZa2RW6GBf: Checking unresponsive connections...    
2022-12-18T21:44:43.307709Z TRACE fred::multiplexer::types: fred-lZa2RW6GBf: Using network timeout: 5000    
2022-12-18T21:44:43.309878Z DEBUG fred::multiplexer::types: fred-6Corg17GBH: Checking unresponsive connections...    
2022-12-18T21:44:43.309914Z TRACE fred::multiplexer::types: fred-6Corg17GBH: Using network timeout: 5000    
2022-12-18T21:44:43.311061Z DEBUG fred::multiplexer::types: fred-d3vAUmx97z: Checking unresponsive connections...    
2022-12-18T21:44:43.311077Z DEBUG fred::multiplexer::types: fred-pm7n0saPJP: Checking unresponsive connections...    
2022-12-18T21:44:43.311095Z TRACE fred::multiplexer::types: fred-d3vAUmx97z: Using network timeout: 5000    
2022-12-18T21:44:43.311116Z TRACE fred::multiplexer::types: fred-pm7n0saPJP: Using network timeout: 5000    
2022-12-18T21:44:43.314233Z DEBUG fred::multiplexer::types: fred-9lCBe4loFM: Checking unresponsive connections...    
2022-12-18T21:44:43.314260Z DEBUG fred::multiplexer::types: fred-Aru1iU2Ekr: Checking unresponsive connections...    
2022-12-18T21:44:43.314272Z TRACE fred::multiplexer::types: fred-9lCBe4loFM: Using network timeout: 5000    
2022-12-18T21:44:43.314294Z TRACE fred::multiplexer::types: fred-Aru1iU2Ekr: Using network timeout: 5000    
2022-12-18T21:44:48.308457Z DEBUG fred::multiplexer::types: fred-lZa2RW6GBf: Checking unresponsive connections...    
2022-12-18T21:44:48.308516Z TRACE fred::multiplexer::types: fred-lZa2RW6GBf: Using network timeout: 5000    
2022-12-18T21:44:48.308549Z  WARN fred::multiplexer::types: fred-lZa2RW6GBf: Server 172.26.0.10:6379 unresponsive after 6588 ms    
2022-12-18T21:44:48.308603Z DEBUG fred::multiplexer::types: fred-lZa2RW6GBf: Interrupting reader task for 172.26.0.10:6379    
2022-12-18T21:44:48.308657Z DEBUG fred::multiplexer::utils: fred-lZa2RW6GBf: Recv interrupt on 172.26.0.10:6379    
2022-12-18T21:44:48.308701Z DEBUG fred::multiplexer::types: fred-lZa2RW6GBf: Unsubscribe from interrupts for 172.26.0.10:6379    
2022-12-18T21:44:48.308788Z DEBUG fred::multiplexer::responses: fred-lZa2RW6GBf: Ending reader task from 172.26.0.10:6379 due to Some(Redis Error - kind: IO, details: Unresponsive connection.)    
2022-12-18T21:44:48.308849Z DEBUG fred::modules::inner: fred-lZa2RW6GBf: Sending reconnect message to multiplexer for Some(Server { host: "172.26.0.10", port: 6379, tls_server_name: None })    
2022-12-18T21:44:48.308889Z DEBUG fred::modules::inner: fred-lZa2RW6GBf: No `on_error` listener.    
2022-12-18T21:44:48.308919Z DEBUG fred::multiplexer::clustered: fred-lZa2RW6GBf: Ending reader task from 172.26.0.10:6379    
2022-12-18T21:44:48.308982Z TRACE fred::multiplexer::commands: fred-lZa2RW6GBf: Recv command: MultiplexerCommand { kind: "Reconnect", server: Some(Server { host: "172.26.0.10", port: 6379, tls_server_name: None }), force: false }    
2022-12-18T21:44:48.309020Z DEBUG fred::multiplexer::commands: fred-lZa2RW6GBf: Maybe reconnecting to Some(Server { host: "172.26.0.10", port: 6379, tls_server_name: None }) (force: false)    
2022-12-18T21:44:48.309042Z DEBUG fred::multiplexer::commands: fred-lZa2RW6GBf: Has working connection: false    
2022-12-18T21:44:48.309067Z DEBUG fred::multiplexer::commands: fred-lZa2RW6GBf: Starting reconnection loop...    
2022-12-18T21:44:48.309098Z DEBUG fred::multiplexer::utils: fred-lZa2RW6GBf: Sleeping for 110 ms.    
2022-12-18T21:44:48.309140Z DEBUG fred::modules::inner: fred-lZa2RW6GBf: Sleeping for 110 ms    
2022-12-18T21:44:48.310279Z DEBUG fred::multiplexer::types: fred-6Corg17GBH: Checking unresponsive connections...    
2022-12-18T21:44:48.310308Z TRACE fred::multiplexer::types: fred-6Corg17GBH: Using network timeout: 5000    
2022-12-18T21:44:48.312471Z DEBUG fred::multiplexer::types: fred-pm7n0saPJP: Checking unresponsive connections...    
2022-12-18T21:44:48.312500Z TRACE fred::multiplexer::types: fred-pm7n0saPJP: Using network timeout: 5000    
2022-12-18T21:44:48.312498Z DEBUG fred::multiplexer::types: fred-d3vAUmx97z: Checking unresponsive connections...    
2022-12-18T21:44:48.312535Z TRACE fred::multiplexer::types: fred-d3vAUmx97z: Using network timeout: 5000    
2022-12-18T21:44:48.315628Z DEBUG fred::multiplexer::types: fred-9lCBe4loFM: Checking unresponsive connections...    
2022-12-18T21:44:48.315622Z DEBUG fred::multiplexer::types: fred-Aru1iU2Ekr: Checking unresponsive connections...    
2022-12-18T21:44:48.315667Z TRACE fred::multiplexer::types: fred-9lCBe4loFM: Using network timeout: 5000    
2022-12-18T21:44:48.315672Z TRACE fred::multiplexer::types: fred-Aru1iU2Ekr: Using network timeout: 5000    
2022-12-18T21:44:48.420973Z DEBUG fred::multiplexer: fred-lZa2RW6GBf: Disconnecting from 172.26.0.10:6379    
2022-12-18T21:44:48.421080Z TRACE tokio_util::codec::framed_impl: flushing framed transport
2022-12-18T21:44:48.421091Z TRACE tokio_util::codec::framed_impl: framed transport flushed
2022-12-18T21:44:48.421217Z TRACE mio::poll: deregistering event source from poller    
2022-12-18T21:44:48.421329Z DEBUG fred::multiplexer: fred-lZa2RW6GBf: Disconnecting from 172.26.0.5:6379    
2022-12-18T21:44:48.421378Z TRACE tokio_util::codec::framed_impl: flushing framed transport
2022-12-18T21:44:48.421387Z TRACE tokio_util::codec::framed_impl: framed transport flushed
2022-12-18T21:44:48.421574Z TRACE fred::protocol::codec: fred-lZa2RW6GBf: Recv 0 bytes from 172.26.0.5:6379 (RESP2).    
2022-12-18T21:44:48.421630Z DEBUG fred::multiplexer::types: fred-lZa2RW6GBf: Unsubscribe from interrupts for 172.26.0.5:6379    
2022-12-18T21:44:48.421697Z DEBUG fred::multiplexer::responses: fred-lZa2RW6GBf: Ending reader task from 172.26.0.5:6379 due to None    
2022-12-18T21:44:48.421722Z DEBUG fred::modules::inner: fred-lZa2RW6GBf: Sending reconnect message to multiplexer for Some(Server { host: "172.26.0.5", port: 6379, tls_server_name: None })    
2022-12-18T21:44:48.421753Z DEBUG fred::modules::inner: fred-lZa2RW6GBf: No `on_error` listener.    
2022-12-18T21:44:48.421776Z DEBUG fred::multiplexer::clustered: fred-lZa2RW6GBf: Ending reader task from 172.26.0.5:6379    
2022-12-18T21:44:48.421832Z TRACE mio::poll: deregistering event source from poller    
2022-12-18T21:44:48.421882Z DEBUG fred::multiplexer: fred-lZa2RW6GBf: Disconnecting from 172.26.0.9:6379    
2022-12-18T21:44:48.421904Z TRACE tokio_util::codec::framed_impl: flushing framed transport
2022-12-18T21:44:48.421914Z TRACE tokio_util::codec::framed_impl: framed transport flushed
2022-12-18T21:44:48.422061Z TRACE fred::protocol::codec: fred-lZa2RW6GBf: Recv 0 bytes from 172.26.0.9:6379 (RESP2).    
2022-12-18T21:44:48.422093Z DEBUG fred::multiplexer::types: fred-lZa2RW6GBf: Unsubscribe from interrupts for 172.26.0.9:6379    
2022-12-18T21:44:48.422157Z DEBUG fred::multiplexer::responses: fred-lZa2RW6GBf: Ending reader task from 172.26.0.9:6379 due to None    
2022-12-18T21:44:48.422198Z DEBUG fred::modules::inner: fred-lZa2RW6GBf: Sending reconnect message to multiplexer for Some(Server { host: "172.26.0.9", port: 6379, tls_server_name: None })    
2022-12-18T21:44:48.422234Z DEBUG fred::modules::inner: fred-lZa2RW6GBf: No `on_error` listener.    
2022-12-18T21:44:48.422249Z DEBUG fred::multiplexer::clustered: fred-lZa2RW6GBf: Ending reader task from 172.26.0.9:6379    
2022-12-18T21:44:48.422290Z TRACE mio::poll: deregistering event source from poller    
2022-12-18T21:44:48.422337Z TRACE fred::multiplexer: fred-lZa2RW6GBf: Adding SET (0) command to retry buffer.    
2022-12-18T21:44:48.422361Z DEBUG fred::multiplexer::types: fred-lZa2RW6GBf: Syncing connection state with unresponsive network task.    
2022-12-18T21:44:48.422394Z DEBUG fred::multiplexer::clustered: fred-lZa2RW6GBf: Synchronizing cluster state.    
2022-12-18T21:44:48.422446Z TRACE redis_protocol::utils: allocating more, len: 0, amt: 28    
2022-12-18T21:44:48.422493Z TRACE fred::protocol::codec: fred-lZa2RW6GBf: Encoded 28 bytes to redis-node-1:6379. Buffer len: 28 (RESP2)    
2022-12-18T21:44:48.422516Z TRACE tokio_util::codec::framed_impl: flushing framed transport
2022-12-18T21:44:48.422530Z TRACE tokio_util::codec::framed_impl: writing; remaining=28
2022-12-18T21:44:48.422581Z TRACE tokio_util::codec::framed_impl: framed transport flushed
2022-12-18T21:44:48.422600Z TRACE tokio_util::codec::framed_impl: attempting to decode a frame
2022-12-18T21:44:48.422612Z TRACE fred::protocol::codec: fred-lZa2RW6GBf: Recv 0 bytes from redis-node-1:6379 (RESP2).    



2022-12-18T21:44:51.821830Z TRACE fred::interfaces: fred-6Corg17GBH: Sending command SET (0) to multiplexer.    
2022-12-18T21:44:51.821967Z TRACE fred::multiplexer::commands: fred-6Corg17GBH: Recv command: MultiplexerCommand { kind: "Command", command: "SET" }    
2022-12-18T21:44:51.822068Z TRACE fred::protocol::command: fred-6Corg17GBH: Pipeline check SET: true    
2022-12-18T21:44:51.822112Z TRACE fred::multiplexer: fred-6Corg17GBH: Writing command 0    
2022-12-18T21:44:51.822177Z DEBUG fred::multiplexer::clustered: fred-6Corg17GBH: Writing command `SET` to 172.26.0.10:6379    
2022-12-18T21:44:51.822208Z TRACE fred::multiplexer::utils: fred-6Corg17GBH: Writing command 0. Timed out: false, Force flush: false    
2022-12-18T21:44:51.822247Z TRACE fred::multiplexer::utils: fred-6Corg17GBH: Sending command SET to 172.26.0.10:6379, ID: 0    
2022-12-18T21:44:51.822285Z TRACE fred::multiplexer::commands: fred-6Corg17GBH: Sent command to 172.26.0.10:6379. Flushed: false    
2022-12-18T21:44:51.822314Z TRACE fred::multiplexer: fred-6Corg17GBH: Checking and flushing sockets...    
2022-12-18T21:44:51.822353Z TRACE fred::protocol::connection: Flushing socket to 172.26.0.5:6379    
2022-12-18T21:44:51.822382Z TRACE tokio_util::codec::framed_impl: flushing framed transport
2022-12-18T21:44:51.822399Z TRACE tokio_util::codec::framed_impl: framed transport flushed
2022-12-18T21:44:51.822421Z TRACE fred::protocol::connection: Flushed socket to 172.26.0.5:6379    
2022-12-18T21:44:51.822450Z TRACE fred::protocol::connection: Flushing socket to 172.26.0.10:6379    
2022-12-18T21:44:51.822483Z TRACE redis_protocol::utils: allocating more, len: 0, amt: 42    
2022-12-18T21:44:51.822524Z TRACE fred::protocol::codec: fred-6Corg17GBH: Encoded 42 bytes to 172.26.0.10:6379. Buffer len: 42 (RESP2)    
2022-12-18T21:44:51.822553Z TRACE tokio_util::codec::framed_impl: flushing framed transport
2022-12-18T21:44:51.822572Z TRACE tokio_util::codec::framed_impl: writing; remaining=42
2022-12-18T21:44:51.822658Z TRACE tokio_util::codec::framed_impl: framed transport flushed
2022-12-18T21:44:51.822686Z TRACE fred::protocol::connection: Flushed socket to 172.26.0.10:6379    
2022-12-18T21:44:51.822706Z TRACE fred::protocol::connection: Flushing socket to 172.26.0.9:6379    
2022-12-18T21:44:51.822726Z TRACE tokio_util::codec::framed_impl: flushing framed transport
2022-12-18T21:44:51.822742Z TRACE tokio_util::codec::framed_impl: framed transport flushed
2022-12-18T21:44:51.822756Z TRACE fred::protocol::connection: Flushed socket to 172.26.0.9:6379    
2022-12-18T21:44:53.309717Z DEBUG fred::multiplexer::types: fred-lZa2RW6GBf: Checking unresponsive connections...    
2022-12-18T21:44:53.309787Z TRACE fred::multiplexer::types: fred-lZa2RW6GBf: Using network timeout: 5000    
2022-12-18T21:44:53.312350Z DEBUG fred::multiplexer::types: fred-6Corg17GBH: Checking unresponsive connections...    
2022-12-18T21:44:53.312416Z TRACE fred::multiplexer::types: fred-6Corg17GBH: Using network timeout: 5000    
2022-12-18T21:44:53.313609Z DEBUG fred::multiplexer::types: fred-d3vAUmx97z: Checking unresponsive connections...    
2022-12-18T21:44:53.313624Z DEBUG fred::multiplexer::types: fred-pm7n0saPJP: Checking unresponsive connections...    
2022-12-18T21:44:53.313649Z TRACE fred::multiplexer::types: fred-d3vAUmx97z: Using network timeout: 5000    
2022-12-18T21:44:53.313663Z TRACE fred::multiplexer::types: fred-pm7n0saPJP: Using network timeout: 5000    
2022-12-18T21:44:53.316732Z DEBUG fred::multiplexer::types: fred-Aru1iU2Ekr: Checking unresponsive connections...    
2022-12-18T21:44:53.316789Z TRACE fred::multiplexer::types: fred-Aru1iU2Ekr: Using network timeout: 5000    
2022-12-18T21:44:53.316792Z DEBUG fred::multiplexer::types: fred-9lCBe4loFM: Checking unresponsive connections...    
2022-12-18T21:44:53.316821Z TRACE fred::multiplexer::types: fred-9lCBe4loFM: Using network timeout: 5000    
2022-12-18T21:44:58.310693Z DEBUG fred::multiplexer::types: fred-lZa2RW6GBf: Checking unresponsive connections...    
2022-12-18T21:44:58.310766Z TRACE fred::multiplexer::types: fred-lZa2RW6GBf: Using network timeout: 5000    
2022-12-18T21:44:58.313906Z DEBUG fred::multiplexer::types: fred-6Corg17GBH: Checking unresponsive connections...    
2022-12-18T21:44:58.313953Z TRACE fred::multiplexer::types: fred-6Corg17GBH: Using network timeout: 5000    
2022-12-18T21:44:58.313983Z  WARN fred::multiplexer::types: fred-6Corg17GBH: Server 172.26.0.10:6379 unresponsive after 6491 ms    
2022-12-18T21:44:58.314026Z DEBUG fred::multiplexer::types: fred-6Corg17GBH: Interrupting reader task for 172.26.0.10:6379    
2022-12-18T21:44:58.314111Z DEBUG fred::multiplexer::utils: fred-6Corg17GBH: Recv interrupt on 172.26.0.10:6379    
2022-12-18T21:44:58.314135Z DEBUG fred::multiplexer::types: fred-6Corg17GBH: Unsubscribe from interrupts for 172.26.0.10:6379    
2022-12-18T21:44:58.314198Z DEBUG fred::multiplexer::responses: fred-6Corg17GBH: Ending reader task from 172.26.0.10:6379 due to Some(Redis Error - kind: IO, details: Unresponsive connection.)    
2022-12-18T21:44:58.314223Z DEBUG fred::modules::inner: fred-6Corg17GBH: Sending reconnect message to multiplexer for Some(Server { host: "172.26.0.10", port: 6379, tls_server_name: None })    
2022-12-18T21:44:58.314254Z DEBUG fred::modules::inner: fred-6Corg17GBH: No `on_error` listener.    
2022-12-18T21:44:58.314292Z DEBUG fred::multiplexer::clustered: fred-6Corg17GBH: Ending reader task from 172.26.0.10:6379    
2022-12-18T21:44:58.314356Z TRACE fred::multiplexer::commands: fred-6Corg17GBH: Recv command: MultiplexerCommand { kind: "Reconnect", server: Some(Server { host: "172.26.0.10", port: 6379, tls_server_name: None }), force: false }    
2022-12-18T21:44:58.314390Z DEBUG fred::multiplexer::commands: fred-6Corg17GBH: Maybe reconnecting to Some(Server { host: "172.26.0.10", port: 6379, tls_server_name: None }) (force: false)    
2022-12-18T21:44:58.314418Z DEBUG fred::multiplexer::commands: fred-6Corg17GBH: Has working connection: false    
2022-12-18T21:44:58.314439Z DEBUG fred::multiplexer::commands: fred-6Corg17GBH: Starting reconnection loop...    
2022-12-18T21:44:58.314468Z DEBUG fred::multiplexer::utils: fred-6Corg17GBH: Sleeping for 104 ms.    
2022-12-18T21:44:58.314493Z DEBUG fred::modules::inner: fred-6Corg17GBH: Sleeping for 104 ms    
2022-12-18T21:44:58.314578Z DEBUG fred::multiplexer::types: fred-pm7n0saPJP: Checking unresponsive connections...    
2022-12-18T21:44:58.314596Z DEBUG fred::multiplexer::types: fred-d3vAUmx97z: Checking unresponsive connections...    
2022-12-18T21:44:58.314611Z TRACE fred::multiplexer::types: fred-pm7n0saPJP: Using network timeout: 5000    
2022-12-18T21:44:58.314622Z TRACE fred::multiplexer::types: fred-d3vAUmx97z: Using network timeout: 5000    
2022-12-18T21:44:58.317713Z DEBUG fred::multiplexer::types: fred-9lCBe4loFM: Checking unresponsive connections...    
2022-12-18T21:44:58.317738Z DEBUG fred::multiplexer::types: fred-Aru1iU2Ekr: Checking unresponsive connections...    
2022-12-18T21:44:58.317745Z TRACE fred::multiplexer::types: fred-9lCBe4loFM: Using network timeout: 5000    
2022-12-18T21:44:58.317762Z TRACE fred::multiplexer::types: fred-Aru1iU2Ekr: Using network timeout: 5000    
2022-12-18T21:44:58.420087Z DEBUG fred::multiplexer: fred-6Corg17GBH: Disconnecting from 172.26.0.5:6379    
2022-12-18T21:44:58.420144Z TRACE tokio_util::codec::framed_impl: flushing framed transport
2022-12-18T21:44:58.420154Z TRACE tokio_util::codec::framed_impl: framed transport flushed
2022-12-18T21:44:58.420395Z TRACE fred::protocol::codec: fred-6Corg17GBH: Recv 0 bytes from 172.26.0.5:6379 (RESP2).    
2022-12-18T21:44:58.420438Z DEBUG fred::multiplexer::types: fred-6Corg17GBH: Unsubscribe from interrupts for 172.26.0.5:6379    
2022-12-18T21:44:58.420521Z DEBUG fred::multiplexer::responses: fred-6Corg17GBH: Ending reader task from 172.26.0.5:6379 due to None    
2022-12-18T21:44:58.420584Z DEBUG fred::modules::inner: fred-6Corg17GBH: Sending reconnect message to multiplexer for Some(Server { host: "172.26.0.5", port: 6379, tls_server_name: None })    
2022-12-18T21:44:58.420623Z DEBUG fred::modules::inner: fred-6Corg17GBH: No `on_error` listener.    
2022-12-18T21:44:58.420652Z DEBUG fred::multiplexer::clustered: fred-6Corg17GBH: Ending reader task from 172.26.0.5:6379    
2022-12-18T21:44:58.420746Z TRACE mio::poll: deregistering event source from poller    
2022-12-18T21:44:58.420819Z DEBUG fred::multiplexer: fred-6Corg17GBH: Disconnecting from 172.26.0.10:6379    
2022-12-18T21:44:58.420848Z TRACE tokio_util::codec::framed_impl: flushing framed transport
2022-12-18T21:44:58.420867Z TRACE tokio_util::codec::framed_impl: framed transport flushed
2022-12-18T21:44:58.420925Z TRACE mio::poll: deregistering event source from poller    
2022-12-18T21:44:58.420982Z DEBUG fred::multiplexer: fred-6Corg17GBH: Disconnecting from 172.26.0.9:6379    
2022-12-18T21:44:58.421014Z TRACE tokio_util::codec::framed_impl: flushing framed transport
2022-12-18T21:44:58.421033Z TRACE tokio_util::codec::framed_impl: framed transport flushed
2022-12-18T21:44:58.421152Z TRACE fred::protocol::codec: fred-6Corg17GBH: Recv 0 bytes from 172.26.0.9:6379 (RESP2).    
2022-12-18T21:44:58.421194Z DEBUG fred::multiplexer::types: fred-6Corg17GBH: Unsubscribe from interrupts for 172.26.0.9:6379    
2022-12-18T21:44:58.421251Z DEBUG fred::multiplexer::responses: fred-6Corg17GBH: Ending reader task from 172.26.0.9:6379 due to None    
2022-12-18T21:44:58.421277Z DEBUG fred::modules::inner: fred-6Corg17GBH: Sending reconnect message to multiplexer for Some(Server { host: "172.26.0.9", port: 6379, tls_server_name: None })    
2022-12-18T21:44:58.421303Z DEBUG fred::modules::inner: fred-6Corg17GBH: No `on_error` listener.    
2022-12-18T21:44:58.421323Z DEBUG fred::multiplexer::clustered: fred-6Corg17GBH: Ending reader task from 172.26.0.9:6379    
2022-12-18T21:44:58.421369Z TRACE mio::poll: deregistering event source from poller    
2022-12-18T21:44:58.421414Z TRACE fred::multiplexer: fred-6Corg17GBH: Adding SET (0) command to retry buffer.    
2022-12-18T21:44:58.421441Z DEBUG fred::multiplexer::types: fred-6Corg17GBH: Syncing connection state with unresponsive network task.    
2022-12-18T21:44:58.421478Z DEBUG fred::multiplexer::clustered: fred-6Corg17GBH: Synchronizing cluster state.    
2022-12-18T21:44:58.421525Z TRACE redis_protocol::utils: allocating more, len: 0, amt: 28    
2022-12-18T21:44:58.421567Z TRACE fred::protocol::codec: fred-6Corg17GBH: Encoded 28 bytes to redis-node-1:6379. Buffer len: 28 (RESP2)    
2022-12-18T21:44:58.421586Z TRACE tokio_util::codec::framed_impl: flushing framed transport
2022-12-18T21:44:58.421594Z TRACE tokio_util::codec::framed_impl: writing; remaining=28
2022-12-18T21:44:58.421632Z TRACE tokio_util::codec::framed_impl: framed transport flushed
2022-12-18T21:44:58.421651Z TRACE tokio_util::codec::framed_impl: attempting to decode a frame
2022-12-18T21:44:58.421663Z TRACE fred::protocol::codec: fred-6Corg17GBH: Recv 0 bytes from redis-node-1:6379 (RESP2).    



2022-12-18T21:45:01.923863Z TRACE fred::interfaces: fred-pm7n0saPJP: Sending command SET (0) to multiplexer.    
2022-12-18T21:45:01.923960Z TRACE fred::multiplexer::commands: fred-pm7n0saPJP: Recv command: MultiplexerCommand { kind: "Command", command: "SET" }    
2022-12-18T21:45:01.924008Z TRACE fred::protocol::command: fred-pm7n0saPJP: Pipeline check SET: true    
2022-12-18T21:45:01.924036Z TRACE fred::multiplexer: fred-pm7n0saPJP: Writing command 0    
2022-12-18T21:45:01.924083Z DEBUG fred::multiplexer::clustered: fred-pm7n0saPJP: Writing command `SET` to 172.26.0.10:6379    
2022-12-18T21:45:01.924116Z TRACE fred::multiplexer::utils: fred-pm7n0saPJP: Writing command 0. Timed out: false, Force flush: false    
2022-12-18T21:45:01.924152Z TRACE fred::multiplexer::utils: fred-pm7n0saPJP: Sending command SET to 172.26.0.10:6379, ID: 0    
2022-12-18T21:45:01.924195Z TRACE fred::multiplexer::commands: fred-pm7n0saPJP: Sent command to 172.26.0.10:6379. Flushed: false    
2022-12-18T21:45:01.924217Z TRACE fred::multiplexer: fred-pm7n0saPJP: Checking and flushing sockets...    
2022-12-18T21:45:01.924255Z TRACE fred::protocol::connection: Flushing socket to 172.26.0.5:6379    
2022-12-18T21:45:01.924281Z TRACE tokio_util::codec::framed_impl: flushing framed transport
2022-12-18T21:45:01.924294Z TRACE tokio_util::codec::framed_impl: framed transport flushed
2022-12-18T21:45:01.924307Z TRACE fred::protocol::connection: Flushed socket to 172.26.0.5:6379    
2022-12-18T21:45:01.924330Z TRACE fred::protocol::connection: Flushing socket to 172.26.0.9:6379    
2022-12-18T21:45:01.924346Z TRACE tokio_util::codec::framed_impl: flushing framed transport
2022-12-18T21:45:01.924354Z TRACE tokio_util::codec::framed_impl: framed transport flushed
2022-12-18T21:45:01.924368Z TRACE fred::protocol::connection: Flushed socket to 172.26.0.9:6379    
2022-12-18T21:45:01.924384Z TRACE fred::protocol::connection: Flushing socket to 172.26.0.10:6379    
2022-12-18T21:45:01.924411Z TRACE redis_protocol::utils: allocating more, len: 0, amt: 42    
2022-12-18T21:45:01.924455Z TRACE fred::protocol::codec: fred-pm7n0saPJP: Encoded 42 bytes to 172.26.0.10:6379. Buffer len: 42 (RESP2)    
2022-12-18T21:45:01.924481Z TRACE tokio_util::codec::framed_impl: flushing framed transport
2022-12-18T21:45:01.924491Z TRACE tokio_util::codec::framed_impl: writing; remaining=42
2022-12-18T21:45:01.924553Z TRACE tokio_util::codec::framed_impl: framed transport flushed
2022-12-18T21:45:01.924577Z TRACE fred::protocol::connection: Flushed socket to 172.26.0.10:6379    
2022-12-18T21:45:03.311909Z DEBUG fred::multiplexer::types: fred-lZa2RW6GBf: Checking unresponsive connections...    
2022-12-18T21:45:03.311983Z TRACE fred::multiplexer::types: fred-lZa2RW6GBf: Using network timeout: 5000    
2022-12-18T21:45:03.315150Z DEBUG fred::multiplexer::types: fred-d3vAUmx97z: Checking unresponsive connections...    
2022-12-18T21:45:03.315159Z DEBUG fred::multiplexer::types: fred-6Corg17GBH: Checking unresponsive connections...    
2022-12-18T21:45:03.315188Z TRACE fred::multiplexer::types: fred-d3vAUmx97z: Using network timeout: 5000    
2022-12-18T21:45:03.315188Z TRACE fred::multiplexer::types: fred-6Corg17GBH: Using network timeout: 5000    
2022-12-18T21:45:03.315204Z DEBUG fred::multiplexer::types: fred-pm7n0saPJP: Checking unresponsive connections...    
2022-12-18T21:45:03.315237Z TRACE fred::multiplexer::types: fred-pm7n0saPJP: Using network timeout: 5000    
2022-12-18T21:45:03.318311Z DEBUG fred::multiplexer::types: fred-Aru1iU2Ekr: Checking unresponsive connections...    
2022-12-18T21:45:03.318324Z DEBUG fred::multiplexer::types: fred-9lCBe4loFM: Checking unresponsive connections...    
2022-12-18T21:45:03.318341Z TRACE fred::multiplexer::types: fred-Aru1iU2Ekr: Using network timeout: 5000    
2022-12-18T21:45:03.318384Z TRACE fred::multiplexer::types: fred-9lCBe4loFM: Using network timeout: 5000    
2022-12-18T21:45:08.312689Z DEBUG fred::multiplexer::types: fred-lZa2RW6GBf: Checking unresponsive connections...    
2022-12-18T21:45:08.312772Z TRACE fred::multiplexer::types: fred-lZa2RW6GBf: Using network timeout: 5000    
2022-12-18T21:45:08.316991Z DEBUG fred::multiplexer::types: fred-pm7n0saPJP: Checking unresponsive connections...    
2022-12-18T21:45:08.317042Z DEBUG fred::multiplexer::types: fred-6Corg17GBH: Checking unresponsive connections...    
2022-12-18T21:45:08.317046Z TRACE fred::multiplexer::types: fred-pm7n0saPJP: Using network timeout: 5000    
2022-12-18T21:45:08.317069Z TRACE fred::multiplexer::types: fred-6Corg17GBH: Using network timeout: 5000    
2022-12-18T21:45:08.317070Z DEBUG fred::multiplexer::types: fred-d3vAUmx97z: Checking unresponsive connections...    
2022-12-18T21:45:08.317079Z  WARN fred::multiplexer::types: fred-pm7n0saPJP: Server 172.26.0.10:6379 unresponsive after 6392 ms    
2022-12-18T21:45:08.317109Z TRACE fred::multiplexer::types: fred-d3vAUmx97z: Using network timeout: 5000    
2022-12-18T21:45:08.317113Z DEBUG fred::multiplexer::types: fred-pm7n0saPJP: Interrupting reader task for 172.26.0.10:6379    
2022-12-18T21:45:08.317174Z DEBUG fred::multiplexer::utils: fred-pm7n0saPJP: Recv interrupt on 172.26.0.10:6379    
2022-12-18T21:45:08.317199Z DEBUG fred::multiplexer::types: fred-pm7n0saPJP: Unsubscribe from interrupts for 172.26.0.10:6379    
2022-12-18T21:45:08.317261Z DEBUG fred::multiplexer::responses: fred-pm7n0saPJP: Ending reader task from 172.26.0.10:6379 due to Some(Redis Error - kind: IO, details: Unresponsive connection.)    
2022-12-18T21:45:08.317287Z DEBUG fred::modules::inner: fred-pm7n0saPJP: Sending reconnect message to multiplexer for Some(Server { host: "172.26.0.10", port: 6379, tls_server_name: None })    
2022-12-18T21:45:08.317320Z DEBUG fred::modules::inner: fred-pm7n0saPJP: No `on_error` listener.    
2022-12-18T21:45:08.317344Z DEBUG fred::multiplexer::clustered: fred-pm7n0saPJP: Ending reader task from 172.26.0.10:6379    
2022-12-18T21:45:08.317396Z TRACE fred::multiplexer::commands: fred-pm7n0saPJP: Recv command: MultiplexerCommand { kind: "Reconnect", server: Some(Server { host: "172.26.0.10", port: 6379, tls_server_name: None }), force: false }    
2022-12-18T21:45:08.317434Z DEBUG fred::multiplexer::commands: fred-pm7n0saPJP: Maybe reconnecting to Some(Server { host: "172.26.0.10", port: 6379, tls_server_name: None }) (force: false)    
2022-12-18T21:45:08.317468Z DEBUG fred::multiplexer::commands: fred-pm7n0saPJP: Has working connection: false    
2022-12-18T21:45:08.317488Z DEBUG fred::multiplexer::commands: fred-pm7n0saPJP: Starting reconnection loop...    
2022-12-18T21:45:08.317509Z DEBUG fred::multiplexer::utils: fred-pm7n0saPJP: Sleeping for 110 ms.    
2022-12-18T21:45:08.317532Z DEBUG fred::modules::inner: fred-pm7n0saPJP: Sleeping for 110 ms    
2022-12-18T21:45:08.319163Z DEBUG fred::multiplexer::types: fred-9lCBe4loFM: Checking unresponsive connections...    
2022-12-18T21:45:08.319178Z DEBUG fred::multiplexer::types: fred-Aru1iU2Ekr: Checking unresponsive connections...    
2022-12-18T21:45:08.319191Z TRACE fred::multiplexer::types: fred-9lCBe4loFM: Using network timeout: 5000    
2022-12-18T21:45:08.319203Z TRACE fred::multiplexer::types: fred-Aru1iU2Ekr: Using network timeout: 5000    
2022-12-18T21:45:08.428492Z DEBUG fred::multiplexer: fred-pm7n0saPJP: Disconnecting from 172.26.0.5:6379    
2022-12-18T21:45:08.428551Z TRACE tokio_util::codec::framed_impl: flushing framed transport
2022-12-18T21:45:08.428561Z TRACE tokio_util::codec::framed_impl: framed transport flushed
2022-12-18T21:45:08.428736Z TRACE fred::protocol::codec: fred-pm7n0saPJP: Recv 0 bytes from 172.26.0.5:6379 (RESP2).    
2022-12-18T21:45:08.428770Z DEBUG fred::multiplexer::types: fred-pm7n0saPJP: Unsubscribe from interrupts for 172.26.0.5:6379    
2022-12-18T21:45:08.428884Z DEBUG fred::multiplexer::responses: fred-pm7n0saPJP: Ending reader task from 172.26.0.5:6379 due to None    
2022-12-18T21:45:08.428914Z DEBUG fred::modules::inner: fred-pm7n0saPJP: Sending reconnect message to multiplexer for Some(Server { host: "172.26.0.5", port: 6379, tls_server_name: None })    
2022-12-18T21:45:08.428940Z DEBUG fred::modules::inner: fred-pm7n0saPJP: No `on_error` listener.    
2022-12-18T21:45:08.428964Z DEBUG fred::multiplexer::clustered: fred-pm7n0saPJP: Ending reader task from 172.26.0.5:6379    
2022-12-18T21:45:08.429028Z TRACE mio::poll: deregistering event source from poller    
2022-12-18T21:45:08.429091Z DEBUG fred::multiplexer: fred-pm7n0saPJP: Disconnecting from 172.26.0.9:6379    
2022-12-18T21:45:08.429114Z TRACE tokio_util::codec::framed_impl: flushing framed transport
2022-12-18T21:45:08.429127Z TRACE tokio_util::codec::framed_impl: framed transport flushed
2022-12-18T21:45:08.429284Z TRACE fred::protocol::codec: fred-pm7n0saPJP: Recv 0 bytes from 172.26.0.9:6379 (RESP2).    
2022-12-18T21:45:08.429323Z DEBUG fred::multiplexer::types: fred-pm7n0saPJP: Unsubscribe from interrupts for 172.26.0.9:6379    
2022-12-18T21:45:08.429374Z DEBUG fred::multiplexer::responses: fred-pm7n0saPJP: Ending reader task from 172.26.0.9:6379 due to None    
2022-12-18T21:45:08.429404Z DEBUG fred::modules::inner: fred-pm7n0saPJP: Sending reconnect message to multiplexer for Some(Server { host: "172.26.0.9", port: 6379, tls_server_name: None })    
2022-12-18T21:45:08.429436Z DEBUG fred::modules::inner: fred-pm7n0saPJP: No `on_error` listener.    
2022-12-18T21:45:08.429462Z DEBUG fred::multiplexer::clustered: fred-pm7n0saPJP: Ending reader task from 172.26.0.9:6379    
2022-12-18T21:45:08.429515Z TRACE mio::poll: deregistering event source from poller    
2022-12-18T21:45:08.429586Z DEBUG fred::multiplexer: fred-pm7n0saPJP: Disconnecting from 172.26.0.10:6379    
2022-12-18T21:45:08.429617Z TRACE tokio_util::codec::framed_impl: flushing framed transport
2022-12-18T21:45:08.429636Z TRACE tokio_util::codec::framed_impl: framed transport flushed
2022-12-18T21:45:08.429687Z TRACE mio::poll: deregistering event source from poller    
2022-12-18T21:45:08.429739Z TRACE fred::multiplexer: fred-pm7n0saPJP: Adding SET (0) command to retry buffer.    
2022-12-18T21:45:08.429766Z DEBUG fred::multiplexer::types: fred-pm7n0saPJP: Syncing connection state with unresponsive network task.    
2022-12-18T21:45:08.429806Z DEBUG fred::multiplexer::clustered: fred-pm7n0saPJP: Synchronizing cluster state.    
2022-12-18T21:45:08.429849Z TRACE redis_protocol::utils: allocating more, len: 0, amt: 28    
2022-12-18T21:45:08.429895Z TRACE fred::protocol::codec: fred-pm7n0saPJP: Encoded 28 bytes to redis-node-1:6379. Buffer len: 28 (RESP2)    
2022-12-18T21:45:08.429931Z TRACE tokio_util::codec::framed_impl: flushing framed transport
2022-12-18T21:45:08.429943Z TRACE tokio_util::codec::framed_impl: writing; remaining=28
2022-12-18T21:45:08.429976Z TRACE tokio_util::codec::framed_impl: framed transport flushed
2022-12-18T21:45:08.429995Z TRACE tokio_util::codec::framed_impl: attempting to decode a frame
2022-12-18T21:45:08.430013Z TRACE fred::protocol::codec: fred-pm7n0saPJP: Recv 0 bytes from redis-node-1:6379 (RESP2).    



2022-12-18T21:45:12.025459Z TRACE fred::interfaces: fred-d3vAUmx97z: Sending command SET (0) to multiplexer.    
2022-12-18T21:45:12.025583Z TRACE fred::multiplexer::commands: fred-d3vAUmx97z: Recv command: MultiplexerCommand { kind: "Command", command: "SET" }    
2022-12-18T21:45:12.025663Z TRACE fred::protocol::command: fred-d3vAUmx97z: Pipeline check SET: true    
2022-12-18T21:45:12.025697Z TRACE fred::multiplexer: fred-d3vAUmx97z: Writing command 0    
2022-12-18T21:45:12.025743Z DEBUG fred::multiplexer::clustered: fred-d3vAUmx97z: Writing command `SET` to 172.26.0.10:6379    
2022-12-18T21:45:12.025770Z TRACE fred::multiplexer::utils: fred-d3vAUmx97z: Writing command 0. Timed out: false, Force flush: false    
2022-12-18T21:45:12.025806Z TRACE fred::multiplexer::utils: fred-d3vAUmx97z: Sending command SET to 172.26.0.10:6379, ID: 0    
2022-12-18T21:45:12.025842Z TRACE fred::multiplexer::commands: fred-d3vAUmx97z: Sent command to 172.26.0.10:6379. Flushed: false    
2022-12-18T21:45:12.025869Z TRACE fred::multiplexer: fred-d3vAUmx97z: Checking and flushing sockets...    
2022-12-18T21:45:12.025904Z TRACE fred::protocol::connection: Flushing socket to 172.26.0.5:6379    
2022-12-18T21:45:12.025927Z TRACE tokio_util::codec::framed_impl: flushing framed transport
2022-12-18T21:45:12.025941Z TRACE tokio_util::codec::framed_impl: framed transport flushed
2022-12-18T21:45:12.025956Z TRACE fred::protocol::connection: Flushed socket to 172.26.0.5:6379    
2022-12-18T21:45:12.025977Z TRACE fred::protocol::connection: Flushing socket to 172.26.0.10:6379    
2022-12-18T21:45:12.026003Z TRACE redis_protocol::utils: allocating more, len: 0, amt: 42    
2022-12-18T21:45:12.026039Z TRACE fred::protocol::codec: fred-d3vAUmx97z: Encoded 42 bytes to 172.26.0.10:6379. Buffer len: 42 (RESP2)    
2022-12-18T21:45:12.026072Z TRACE tokio_util::codec::framed_impl: flushing framed transport
2022-12-18T21:45:12.026091Z TRACE tokio_util::codec::framed_impl: writing; remaining=42
2022-12-18T21:45:12.026156Z TRACE tokio_util::codec::framed_impl: framed transport flushed
2022-12-18T21:45:12.026180Z TRACE fred::protocol::connection: Flushed socket to 172.26.0.10:6379    
2022-12-18T21:45:12.026201Z TRACE fred::protocol::connection: Flushing socket to 172.26.0.9:6379    
2022-12-18T21:45:12.026219Z TRACE tokio_util::codec::framed_impl: flushing framed transport
2022-12-18T21:45:12.026230Z TRACE tokio_util::codec::framed_impl: framed transport flushed
2022-12-18T21:45:12.026244Z TRACE fred::protocol::connection: Flushed socket to 172.26.0.9:6379    
2022-12-18T21:45:13.314030Z DEBUG fred::multiplexer::types: fred-lZa2RW6GBf: Checking unresponsive connections...    
2022-12-18T21:45:13.314106Z TRACE fred::multiplexer::types: fred-lZa2RW6GBf: Using network timeout: 5000    
2022-12-18T21:45:13.318292Z DEBUG fred::multiplexer::types: fred-6Corg17GBH: Checking unresponsive connections...    
2022-12-18T21:45:13.318285Z DEBUG fred::multiplexer::types: fred-pm7n0saPJP: Checking unresponsive connections...    
2022-12-18T21:45:13.318322Z DEBUG fred::multiplexer::types: fred-d3vAUmx97z: Checking unresponsive connections...    
2022-12-18T21:45:13.318333Z TRACE fred::multiplexer::types: fred-6Corg17GBH: Using network timeout: 5000    
2022-12-18T21:45:13.318333Z TRACE fred::multiplexer::types: fred-pm7n0saPJP: Using network timeout: 5000    
2022-12-18T21:45:13.318349Z TRACE fred::multiplexer::types: fred-d3vAUmx97z: Using network timeout: 5000    
2022-12-18T21:45:13.320422Z DEBUG fred::multiplexer::types: fred-Aru1iU2Ekr: Checking unresponsive connections...    
2022-12-18T21:45:13.320434Z DEBUG fred::multiplexer::types: fred-9lCBe4loFM: Checking unresponsive connections...    
2022-12-18T21:45:13.320462Z TRACE fred::multiplexer::types: fred-Aru1iU2Ekr: Using network timeout: 5000    
2022-12-18T21:45:13.320459Z TRACE fred::multiplexer::types: fred-9lCBe4loFM: Using network timeout: 5000    
2022-12-18T21:45:18.315653Z DEBUG fred::multiplexer::types: fred-lZa2RW6GBf: Checking unresponsive connections...    
2022-12-18T21:45:18.315712Z TRACE fred::multiplexer::types: fred-lZa2RW6GBf: Using network timeout: 5000    
2022-12-18T21:45:18.319892Z DEBUG fred::multiplexer::types: fred-d3vAUmx97z: Checking unresponsive connections...    
2022-12-18T21:45:18.319945Z TRACE fred::multiplexer::types: fred-d3vAUmx97z: Using network timeout: 5000    
2022-12-18T21:45:18.319955Z DEBUG fred::multiplexer::types: fred-pm7n0saPJP: Checking unresponsive connections...    
2022-12-18T21:45:18.319978Z  WARN fred::multiplexer::types: fred-d3vAUmx97z: Server 172.26.0.10:6379 unresponsive after 6294 ms    
2022-12-18T21:45:18.319975Z DEBUG fred::multiplexer::types: fred-6Corg17GBH: Checking unresponsive connections...    
2022-12-18T21:45:18.319988Z TRACE fred::multiplexer::types: fred-pm7n0saPJP: Using network timeout: 5000    
2022-12-18T21:45:18.320004Z TRACE fred::multiplexer::types: fred-6Corg17GBH: Using network timeout: 5000    
2022-12-18T21:45:18.320009Z DEBUG fred::multiplexer::types: fred-d3vAUmx97z: Interrupting reader task for 172.26.0.10:6379    
2022-12-18T21:45:18.320061Z DEBUG fred::multiplexer::utils: fred-d3vAUmx97z: Recv interrupt on 172.26.0.10:6379    
2022-12-18T21:45:18.320090Z DEBUG fred::multiplexer::types: fred-d3vAUmx97z: Unsubscribe from interrupts for 172.26.0.10:6379    
2022-12-18T21:45:18.320151Z DEBUG fred::multiplexer::responses: fred-d3vAUmx97z: Ending reader task from 172.26.0.10:6379 due to Some(Redis Error - kind: IO, details: Unresponsive connection.)    
2022-12-18T21:45:18.320178Z DEBUG fred::modules::inner: fred-d3vAUmx97z: Sending reconnect message to multiplexer for Some(Server { host: "172.26.0.10", port: 6379, tls_server_name: None })    
2022-12-18T21:45:18.320215Z DEBUG fred::modules::inner: fred-d3vAUmx97z: No `on_error` listener.    
2022-12-18T21:45:18.320245Z DEBUG fred::multiplexer::clustered: fred-d3vAUmx97z: Ending reader task from 172.26.0.10:6379    
2022-12-18T21:45:18.320298Z TRACE fred::multiplexer::commands: fred-d3vAUmx97z: Recv command: MultiplexerCommand { kind: "Reconnect", server: Some(Server { host: "172.26.0.10", port: 6379, tls_server_name: None }), force: false }    
2022-12-18T21:45:18.320330Z DEBUG fred::multiplexer::commands: fred-d3vAUmx97z: Maybe reconnecting to Some(Server { host: "172.26.0.10", port: 6379, tls_server_name: None }) (force: false)    
2022-12-18T21:45:18.320357Z DEBUG fred::multiplexer::commands: fred-d3vAUmx97z: Has working connection: false    
2022-12-18T21:45:18.320374Z DEBUG fred::multiplexer::commands: fred-d3vAUmx97z: Starting reconnection loop...    
2022-12-18T21:45:18.320434Z DEBUG fred::multiplexer::utils: fred-d3vAUmx97z: Sleeping for 117 ms.    
2022-12-18T21:45:18.320458Z DEBUG fred::modules::inner: fred-d3vAUmx97z: Sleeping for 117 ms    
2022-12-18T21:45:18.322097Z DEBUG fred::multiplexer::types: fred-9lCBe4loFM: Checking unresponsive connections...    
2022-12-18T21:45:18.322105Z DEBUG fred::multiplexer::types: fred-Aru1iU2Ekr: Checking unresponsive connections...    
2022-12-18T21:45:18.322138Z TRACE fred::multiplexer::types: fred-Aru1iU2Ekr: Using network timeout: 5000    
2022-12-18T21:45:18.322141Z TRACE fred::multiplexer::types: fred-9lCBe4loFM: Using network timeout: 5000    
2022-12-18T21:45:18.438453Z DEBUG fred::multiplexer: fred-d3vAUmx97z: Disconnecting from 172.26.0.5:6379    
2022-12-18T21:45:18.438510Z TRACE tokio_util::codec::framed_impl: flushing framed transport
2022-12-18T21:45:18.438520Z TRACE tokio_util::codec::framed_impl: framed transport flushed
2022-12-18T21:45:18.438769Z TRACE fred::protocol::codec: fred-d3vAUmx97z: Recv 0 bytes from 172.26.0.5:6379 (RESP2).    
2022-12-18T21:45:18.438818Z DEBUG fred::multiplexer::types: fred-d3vAUmx97z: Unsubscribe from interrupts for 172.26.0.5:6379    
2022-12-18T21:45:18.438884Z DEBUG fred::multiplexer::responses: fred-d3vAUmx97z: Ending reader task from 172.26.0.5:6379 due to None    
2022-12-18T21:45:18.438910Z DEBUG fred::modules::inner: fred-d3vAUmx97z: Sending reconnect message to multiplexer for Some(Server { host: "172.26.0.5", port: 6379, tls_server_name: None })    
2022-12-18T21:45:18.438943Z DEBUG fred::modules::inner: fred-d3vAUmx97z: No `on_error` listener.    
2022-12-18T21:45:18.438977Z DEBUG fred::multiplexer::clustered: fred-d3vAUmx97z: Ending reader task from 172.26.0.5:6379    
2022-12-18T21:45:18.439044Z TRACE mio::poll: deregistering event source from poller    
2022-12-18T21:45:18.439115Z DEBUG fred::multiplexer: fred-d3vAUmx97z: Disconnecting from 172.26.0.10:6379    
2022-12-18T21:45:18.439137Z TRACE tokio_util::codec::framed_impl: flushing framed transport
2022-12-18T21:45:18.439151Z TRACE tokio_util::codec::framed_impl: framed transport flushed
2022-12-18T21:45:18.439208Z TRACE mio::poll: deregistering event source from poller    
2022-12-18T21:45:18.439275Z DEBUG fred::multiplexer: fred-d3vAUmx97z: Disconnecting from 172.26.0.9:6379    
2022-12-18T21:45:18.439299Z TRACE tokio_util::codec::framed_impl: flushing framed transport
2022-12-18T21:45:18.439308Z TRACE tokio_util::codec::framed_impl: framed transport flushed
2022-12-18T21:45:18.439449Z TRACE fred::protocol::codec: fred-d3vAUmx97z: Recv 0 bytes from 172.26.0.9:6379 (RESP2).    
2022-12-18T21:45:18.439477Z DEBUG fred::multiplexer::types: fred-d3vAUmx97z: Unsubscribe from interrupts for 172.26.0.9:6379    
2022-12-18T21:45:18.439524Z DEBUG fred::multiplexer::responses: fred-d3vAUmx97z: Ending reader task from 172.26.0.9:6379 due to None    
2022-12-18T21:45:18.439549Z DEBUG fred::modules::inner: fred-d3vAUmx97z: Sending reconnect message to multiplexer for Some(Server { host: "172.26.0.9", port: 6379, tls_server_name: None })    
2022-12-18T21:45:18.439579Z DEBUG fred::modules::inner: fred-d3vAUmx97z: No `on_error` listener.    
2022-12-18T21:45:18.439598Z DEBUG fred::multiplexer::clustered: fred-d3vAUmx97z: Ending reader task from 172.26.0.9:6379    
2022-12-18T21:45:18.439643Z TRACE mio::poll: deregistering event source from poller    
2022-12-18T21:45:18.439706Z TRACE fred::multiplexer: fred-d3vAUmx97z: Adding SET (0) command to retry buffer.    
2022-12-18T21:45:18.439742Z DEBUG fred::multiplexer::types: fred-d3vAUmx97z: Syncing connection state with unresponsive network task.    
2022-12-18T21:45:18.439790Z DEBUG fred::multiplexer::clustered: fred-d3vAUmx97z: Synchronizing cluster state.    
2022-12-18T21:45:18.439851Z TRACE redis_protocol::utils: allocating more, len: 0, amt: 28    
2022-12-18T21:45:18.439902Z TRACE fred::protocol::codec: fred-d3vAUmx97z: Encoded 28 bytes to redis-node-1:6379. Buffer len: 28 (RESP2)    
2022-12-18T21:45:18.439927Z TRACE tokio_util::codec::framed_impl: flushing framed transport
2022-12-18T21:45:18.439942Z TRACE tokio_util::codec::framed_impl: writing; remaining=28
2022-12-18T21:45:18.439990Z TRACE tokio_util::codec::framed_impl: framed transport flushed
2022-12-18T21:45:18.440017Z TRACE tokio_util::codec::framed_impl: attempting to decode a frame
2022-12-18T21:45:18.440040Z TRACE fred::protocol::codec: fred-d3vAUmx97z: Recv 0 bytes from redis-node-1:6379 (RESP2).    



2022-12-18T21:45:22.128239Z TRACE fred::interfaces: fred-Aru1iU2Ekr: Sending command SET (0) to multiplexer.    
2022-12-18T21:45:22.128337Z TRACE fred::multiplexer::commands: fred-Aru1iU2Ekr: Recv command: MultiplexerCommand { kind: "Command", command: "SET" }    
2022-12-18T21:45:22.128379Z TRACE fred::protocol::command: fred-Aru1iU2Ekr: Pipeline check SET: true    
2022-12-18T21:45:22.128407Z TRACE fred::multiplexer: fred-Aru1iU2Ekr: Writing command 0    
2022-12-18T21:45:22.128447Z DEBUG fred::multiplexer::clustered: fred-Aru1iU2Ekr: Writing command `SET` to 172.26.0.10:6379    
2022-12-18T21:45:22.128481Z TRACE fred::multiplexer::utils: fred-Aru1iU2Ekr: Writing command 0. Timed out: false, Force flush: false    
2022-12-18T21:45:22.128520Z TRACE fred::multiplexer::utils: fred-Aru1iU2Ekr: Sending command SET to 172.26.0.10:6379, ID: 0    
2022-12-18T21:45:22.128562Z TRACE fred::multiplexer::commands: fred-Aru1iU2Ekr: Sent command to 172.26.0.10:6379. Flushed: false    
2022-12-18T21:45:22.128594Z TRACE fred::multiplexer: fred-Aru1iU2Ekr: Checking and flushing sockets...    
2022-12-18T21:45:22.128627Z TRACE fred::protocol::connection: Flushing socket to 172.26.0.10:6379    
2022-12-18T21:45:22.128650Z TRACE redis_protocol::utils: allocating more, len: 0, amt: 42    
2022-12-18T21:45:22.128681Z TRACE fred::protocol::codec: fred-Aru1iU2Ekr: Encoded 42 bytes to 172.26.0.10:6379. Buffer len: 42 (RESP2)    
2022-12-18T21:45:22.128712Z TRACE tokio_util::codec::framed_impl: flushing framed transport
2022-12-18T21:45:22.128729Z TRACE tokio_util::codec::framed_impl: writing; remaining=42
2022-12-18T21:45:22.128795Z TRACE tokio_util::codec::framed_impl: framed transport flushed
2022-12-18T21:45:22.128819Z TRACE fred::protocol::connection: Flushed socket to 172.26.0.10:6379    
2022-12-18T21:45:22.128845Z TRACE fred::protocol::connection: Flushing socket to 172.26.0.9:6379    
2022-12-18T21:45:22.128868Z TRACE tokio_util::codec::framed_impl: flushing framed transport
2022-12-18T21:45:22.128884Z TRACE tokio_util::codec::framed_impl: framed transport flushed
2022-12-18T21:45:22.128901Z TRACE fred::protocol::connection: Flushed socket to 172.26.0.9:6379    
2022-12-18T21:45:22.128922Z TRACE fred::protocol::connection: Flushing socket to 172.26.0.5:6379    
2022-12-18T21:45:22.128939Z TRACE tokio_util::codec::framed_impl: flushing framed transport
2022-12-18T21:45:22.128950Z TRACE tokio_util::codec::framed_impl: framed transport flushed
2022-12-18T21:45:22.128965Z TRACE fred::protocol::connection: Flushed socket to 172.26.0.5:6379    
2022-12-18T21:45:23.316293Z DEBUG fred::multiplexer::types: fred-lZa2RW6GBf: Checking unresponsive connections...    
2022-12-18T21:45:23.316367Z TRACE fred::multiplexer::types: fred-lZa2RW6GBf: Using network timeout: 5000    
2022-12-18T21:45:23.320523Z DEBUG fred::multiplexer::types: fred-pm7n0saPJP: Checking unresponsive connections...    
2022-12-18T21:45:23.320554Z TRACE fred::multiplexer::types: fred-pm7n0saPJP: Using network timeout: 5000    
2022-12-18T21:45:23.321705Z DEBUG fred::multiplexer::types: fred-d3vAUmx97z: Checking unresponsive connections...    
2022-12-18T21:45:23.321748Z TRACE fred::multiplexer::types: fred-d3vAUmx97z: Using network timeout: 5000    
2022-12-18T21:45:23.321779Z DEBUG fred::multiplexer::types: fred-6Corg17GBH: Checking unresponsive connections...    
2022-12-18T21:45:23.321827Z TRACE fred::multiplexer::types: fred-6Corg17GBH: Using network timeout: 5000    
2022-12-18T21:45:23.323866Z DEBUG fred::multiplexer::types: fred-9lCBe4loFM: Checking unresponsive connections...    
2022-12-18T21:45:23.323913Z TRACE fred::multiplexer::types: fred-9lCBe4loFM: Using network timeout: 5000    
2022-12-18T21:45:23.323931Z DEBUG fred::multiplexer::types: fred-Aru1iU2Ekr: Checking unresponsive connections...    
2022-12-18T21:45:23.323967Z TRACE fred::multiplexer::types: fred-Aru1iU2Ekr: Using network timeout: 5000    
2022-12-18T21:45:28.317847Z DEBUG fred::multiplexer::types: fred-lZa2RW6GBf: Checking unresponsive connections...    
2022-12-18T21:45:28.317908Z TRACE fred::multiplexer::types: fred-lZa2RW6GBf: Using network timeout: 5000    
2022-12-18T21:45:28.322076Z DEBUG fred::multiplexer::types: fred-6Corg17GBH: Checking unresponsive connections...    
2022-12-18T21:45:28.322130Z TRACE fred::multiplexer::types: fred-6Corg17GBH: Using network timeout: 5000    
2022-12-18T21:45:28.322139Z DEBUG fred::multiplexer::types: fred-pm7n0saPJP: Checking unresponsive connections...    
2022-12-18T21:45:28.322160Z DEBUG fred::multiplexer::types: fred-d3vAUmx97z: Checking unresponsive connections...    
2022-12-18T21:45:28.322178Z TRACE fred::multiplexer::types: fred-pm7n0saPJP: Using network timeout: 5000    
2022-12-18T21:45:28.322192Z TRACE fred::multiplexer::types: fred-d3vAUmx97z: Using network timeout: 5000    
2022-12-18T21:45:28.324278Z DEBUG fred::multiplexer::types: fred-Aru1iU2Ekr: Checking unresponsive connections...    
2022-12-18T21:45:28.324297Z DEBUG fred::multiplexer::types: fred-9lCBe4loFM: Checking unresponsive connections...    
2022-12-18T21:45:28.324308Z TRACE fred::multiplexer::types: fred-Aru1iU2Ekr: Using network timeout: 5000    
2022-12-18T21:45:28.324330Z  WARN fred::multiplexer::types: fred-Aru1iU2Ekr: Server 172.26.0.10:6379 unresponsive after 6195 ms    
2022-12-18T21:45:28.324330Z TRACE fred::multiplexer::types: fred-9lCBe4loFM: Using network timeout: 5000    
2022-12-18T21:45:28.324368Z DEBUG fred::multiplexer::types: fred-Aru1iU2Ekr: Interrupting reader task for 172.26.0.10:6379    
2022-12-18T21:45:28.324425Z DEBUG fred::multiplexer::utils: fred-Aru1iU2Ekr: Recv interrupt on 172.26.0.10:6379    
2022-12-18T21:45:28.324453Z DEBUG fred::multiplexer::types: fred-Aru1iU2Ekr: Unsubscribe from interrupts for 172.26.0.10:6379    
2022-12-18T21:45:28.324516Z DEBUG fred::multiplexer::responses: fred-Aru1iU2Ekr: Ending reader task from 172.26.0.10:6379 due to Some(Redis Error - kind: IO, details: Unresponsive connection.)    
2022-12-18T21:45:28.324540Z DEBUG fred::modules::inner: fred-Aru1iU2Ekr: Sending reconnect message to multiplexer for Some(Server { host: "172.26.0.10", port: 6379, tls_server_name: None })    
2022-12-18T21:45:28.324572Z DEBUG fred::modules::inner: fred-Aru1iU2Ekr: No `on_error` listener.    
2022-12-18T21:45:28.324599Z DEBUG fred::multiplexer::clustered: fred-Aru1iU2Ekr: Ending reader task from 172.26.0.10:6379    
2022-12-18T21:45:28.324657Z TRACE fred::multiplexer::commands: fred-Aru1iU2Ekr: Recv command: MultiplexerCommand { kind: "Reconnect", server: Some(Server { host: "172.26.0.10", port: 6379, tls_server_name: None }), force: false }    
2022-12-18T21:45:28.324699Z DEBUG fred::multiplexer::commands: fred-Aru1iU2Ekr: Maybe reconnecting to Some(Server { host: "172.26.0.10", port: 6379, tls_server_name: None }) (force: false)    
2022-12-18T21:45:28.324734Z DEBUG fred::multiplexer::commands: fred-Aru1iU2Ekr: Has working connection: false    
2022-12-18T21:45:28.324764Z DEBUG fred::multiplexer::commands: fred-Aru1iU2Ekr: Starting reconnection loop...    
2022-12-18T21:45:28.324799Z DEBUG fred::multiplexer::utils: fred-Aru1iU2Ekr: Sleeping for 150 ms.    
2022-12-18T21:45:28.324817Z DEBUG fred::modules::inner: fred-Aru1iU2Ekr: Sleeping for 150 ms    
2022-12-18T21:45:28.475234Z DEBUG fred::multiplexer: fred-Aru1iU2Ekr: Disconnecting from 172.26.0.10:6379    
2022-12-18T21:45:28.475307Z TRACE tokio_util::codec::framed_impl: flushing framed transport
2022-12-18T21:45:28.475318Z TRACE tokio_util::codec::framed_impl: framed transport flushed
2022-12-18T21:45:28.475401Z TRACE mio::poll: deregistering event source from poller    
2022-12-18T21:45:28.475520Z DEBUG fred::multiplexer: fred-Aru1iU2Ekr: Disconnecting from 172.26.0.9:6379    
2022-12-18T21:45:28.475542Z TRACE tokio_util::codec::framed_impl: flushing framed transport
2022-12-18T21:45:28.475552Z TRACE tokio_util::codec::framed_impl: framed transport flushed
2022-12-18T21:45:28.475664Z TRACE fred::protocol::codec: fred-Aru1iU2Ekr: Recv 0 bytes from 172.26.0.9:6379 (RESP2).    
2022-12-18T21:45:28.475699Z DEBUG fred::multiplexer::types: fred-Aru1iU2Ekr: Unsubscribe from interrupts for 172.26.0.9:6379    
2022-12-18T21:45:28.475769Z DEBUG fred::multiplexer::responses: fred-Aru1iU2Ekr: Ending reader task from 172.26.0.9:6379 due to None    
2022-12-18T21:45:28.475795Z DEBUG fred::modules::inner: fred-Aru1iU2Ekr: Sending reconnect message to multiplexer for Some(Server { host: "172.26.0.9", port: 6379, tls_server_name: None })    
2022-12-18T21:45:28.475818Z DEBUG fred::modules::inner: fred-Aru1iU2Ekr: No `on_error` listener.    
2022-12-18T21:45:28.475843Z DEBUG fred::multiplexer::clustered: fred-Aru1iU2Ekr: Ending reader task from 172.26.0.9:6379    
2022-12-18T21:45:28.475903Z TRACE mio::poll: deregistering event source from poller    
2022-12-18T21:45:28.475966Z DEBUG fred::multiplexer: fred-Aru1iU2Ekr: Disconnecting from 172.26.0.5:6379    
2022-12-18T21:45:28.475988Z TRACE tokio_util::codec::framed_impl: flushing framed transport
2022-12-18T21:45:28.475997Z TRACE tokio_util::codec::framed_impl: framed transport flushed
2022-12-18T21:45:28.476097Z TRACE fred::protocol::codec: fred-Aru1iU2Ekr: Recv 0 bytes from 172.26.0.5:6379 (RESP2).    
2022-12-18T21:45:28.476126Z DEBUG fred::multiplexer::types: fred-Aru1iU2Ekr: Unsubscribe from interrupts for 172.26.0.5:6379    
2022-12-18T21:45:28.476163Z DEBUG fred::multiplexer::responses: fred-Aru1iU2Ekr: Ending reader task from 172.26.0.5:6379 due to None    
2022-12-18T21:45:28.476185Z DEBUG fred::modules::inner: fred-Aru1iU2Ekr: Sending reconnect message to multiplexer for Some(Server { host: "172.26.0.5", port: 6379, tls_server_name: None })    
2022-12-18T21:45:28.476206Z DEBUG fred::modules::inner: fred-Aru1iU2Ekr: No `on_error` listener.    
2022-12-18T21:45:28.476222Z DEBUG fred::multiplexer::clustered: fred-Aru1iU2Ekr: Ending reader task from 172.26.0.5:6379    
2022-12-18T21:45:28.476262Z TRACE mio::poll: deregistering event source from poller    
2022-12-18T21:45:28.476306Z TRACE fred::multiplexer: fred-Aru1iU2Ekr: Adding SET (0) command to retry buffer.    
2022-12-18T21:45:28.476333Z DEBUG fred::multiplexer::types: fred-Aru1iU2Ekr: Syncing connection state with unresponsive network task.    
2022-12-18T21:45:28.476366Z DEBUG fred::multiplexer::clustered: fred-Aru1iU2Ekr: Synchronizing cluster state.    
2022-12-18T21:45:28.476414Z TRACE redis_protocol::utils: allocating more, len: 0, amt: 28    
2022-12-18T21:45:28.476460Z TRACE fred::protocol::codec: fred-Aru1iU2Ekr: Encoded 28 bytes to redis-node-1:6379. Buffer len: 28 (RESP2)    
2022-12-18T21:45:28.476479Z TRACE tokio_util::codec::framed_impl: flushing framed transport
2022-12-18T21:45:28.476490Z TRACE tokio_util::codec::framed_impl: writing; remaining=28
2022-12-18T21:45:28.476526Z TRACE tokio_util::codec::framed_impl: framed transport flushed
2022-12-18T21:45:28.476545Z TRACE tokio_util::codec::framed_impl: attempting to decode a frame
2022-12-18T21:45:28.476564Z TRACE fred::protocol::codec: fred-Aru1iU2Ekr: Recv 0 bytes from redis-node-1:6379 (RESP2).    





2022-12-18T21:45:33.318707Z DEBUG fred::multiplexer::types: fred-lZa2RW6GBf: Checking unresponsive connections...    
2022-12-18T21:45:33.318768Z TRACE fred::multiplexer::types: fred-lZa2RW6GBf: Using network timeout: 5000    
2022-12-18T21:45:33.323955Z DEBUG fred::multiplexer::types: fred-d3vAUmx97z: Checking unresponsive connections...    
2022-12-18T21:45:33.324012Z TRACE fred::multiplexer::types: fred-d3vAUmx97z: Using network timeout: 5000    
2022-12-18T21:45:33.324007Z DEBUG fred::multiplexer::types: fred-6Corg17GBH: Checking unresponsive connections...    
2022-12-18T21:45:33.324041Z TRACE fred::multiplexer::types: fred-6Corg17GBH: Using network timeout: 5000    
2022-12-18T21:45:33.324039Z DEBUG fred::multiplexer::types: fred-pm7n0saPJP: Checking unresponsive connections...    
2022-12-18T21:45:33.324089Z TRACE fred::multiplexer::types: fred-pm7n0saPJP: Using network timeout: 5000    
2022-12-18T21:45:33.325132Z DEBUG fred::multiplexer::types: fred-Aru1iU2Ekr: Checking unresponsive connections...    
2022-12-18T21:45:33.325142Z DEBUG fred::multiplexer::types: fred-9lCBe4loFM: Checking unresponsive connections...    
2022-12-18T21:45:33.325185Z TRACE fred::multiplexer::types: fred-9lCBe4loFM: Using network timeout: 5000    
2022-12-18T21:45:33.325185Z TRACE fred::multiplexer::types: fred-Aru1iU2Ekr: Using network timeout: 5000    
2022-12-18T21:45:38.320008Z DEBUG fred::multiplexer::types: fred-lZa2RW6GBf: Checking unresponsive connections...    
2022-12-18T21:45:38.320085Z TRACE fred::multiplexer::types: fred-lZa2RW6GBf: Using network timeout: 5000    
2022-12-18T21:45:38.325266Z DEBUG fred::multiplexer::types: fred-pm7n0saPJP: Checking unresponsive connections...    
2022-12-18T21:45:38.325285Z DEBUG fred::multiplexer::types: fred-d3vAUmx97z: Checking unresponsive connections...    
2022-12-18T21:45:38.325295Z DEBUG fred::multiplexer::types: fred-6Corg17GBH: Checking unresponsive connections...    
2022-12-18T21:45:38.325329Z TRACE fred::multiplexer::types: fred-pm7n0saPJP: Using network timeout: 5000    
2022-12-18T21:45:38.325336Z TRACE fred::multiplexer::types: fred-d3vAUmx97z: Using network timeout: 5000    
2022-12-18T21:45:38.325338Z TRACE fred::multiplexer::types: fred-6Corg17GBH: Using network timeout: 5000    
2022-12-18T21:45:38.326450Z DEBUG fred::multiplexer::types: fred-9lCBe4loFM: Checking unresponsive connections...    
2022-12-18T21:45:38.326494Z TRACE fred::multiplexer::types: fred-9lCBe4loFM: Using network timeout: 5000    
2022-12-18T21:45:38.326505Z DEBUG fred::multiplexer::types: fred-Aru1iU2Ekr: Checking unresponsive connections...    
2022-12-18T21:45:38.326534Z TRACE fred::multiplexer::types: fred-Aru1iU2Ekr: Using network timeout: 5000    
2022-12-18T21:45:43.321629Z DEBUG fred::multiplexer::types: fred-lZa2RW6GBf: Checking unresponsive connections...    
2022-12-18T21:45:43.321697Z TRACE fred::multiplexer::types: fred-lZa2RW6GBf: Using network timeout: 5000    
2022-12-18T21:45:43.326948Z DEBUG fred::multiplexer::types: fred-6Corg17GBH: Checking unresponsive connections...    
2022-12-18T21:45:43.326970Z DEBUG fred::multiplexer::types: fred-pm7n0saPJP: Checking unresponsive connections...    
2022-12-18T21:45:43.326989Z TRACE fred::multiplexer::types: fred-6Corg17GBH: Using network timeout: 5000    
2022-12-18T21:45:43.326992Z DEBUG fred::multiplexer::types: fred-d3vAUmx97z: Checking unresponsive connections...    
2022-12-18T21:45:43.327003Z TRACE fred::multiplexer::types: fred-pm7n0saPJP: Using network timeout: 5000    
2022-12-18T21:45:43.327029Z TRACE fred::multiplexer::types: fred-d3vAUmx97z: Using network timeout: 5000    
2022-12-18T21:45:43.328089Z DEBUG fred::multiplexer::types: fred-Aru1iU2Ekr: Checking unresponsive connections...    
2022-12-18T21:45:43.328097Z DEBUG fred::multiplexer::types: fred-9lCBe4loFM: Checking unresponsive connections...    
2022-12-18T21:45:43.328124Z TRACE fred::multiplexer::types: fred-9lCBe4loFM: Using network timeout: 5000    
2022-12-18T21:45:43.328124Z TRACE fred::multiplexer::types: fred-Aru1iU2Ekr: Using network timeout: 5000    
2022-12-18T21:45:48.322635Z DEBUG fred::multiplexer::types: fred-lZa2RW6GBf: Checking unresponsive connections...    
2022-12-18T21:45:48.322708Z TRACE fred::multiplexer::types: fred-lZa2RW6GBf: Using network timeout: 5000    
2022-12-18T21:45:48.328922Z DEBUG fred::multiplexer::types: fred-d3vAUmx97z: Checking unresponsive connections...    
2022-12-18T21:45:48.328922Z DEBUG fred::multiplexer::types: fred-6Corg17GBH: Checking unresponsive connections...    
2022-12-18T21:45:48.328928Z DEBUG fred::multiplexer::types: fred-pm7n0saPJP: Checking unresponsive connections...    
2022-12-18T21:45:48.328983Z TRACE fred::multiplexer::types: fred-d3vAUmx97z: Using network timeout: 5000    
2022-12-18T21:45:48.328985Z TRACE fred::multiplexer::types: fred-pm7n0saPJP: Using network timeout: 5000    
2022-12-18T21:45:48.328985Z TRACE fred::multiplexer::types: fred-6Corg17GBH: Using network timeout: 5000    
2022-12-18T21:45:48.330025Z DEBUG fred::multiplexer::types: fred-Aru1iU2Ekr: Checking unresponsive connections...    
2022-12-18T21:45:48.330040Z DEBUG fred::multiplexer::types: fred-9lCBe4loFM: Checking unresponsive connections...    
2022-12-18T21:45:48.330061Z TRACE fred::multiplexer::types: fred-9lCBe4loFM: Using network timeout: 5000    
2022-12-18T21:45:48.330062Z TRACE fred::multiplexer::types: fred-Aru1iU2Ekr: Using network timeout: 5000    
2022-12-18T21:45:53.323923Z DEBUG fred::multiplexer::types: fred-lZa2RW6GBf: Checking unresponsive connections...    
2022-12-18T21:45:53.323983Z TRACE fred::multiplexer::types: fred-lZa2RW6GBf: Using network timeout: 5000    
2022-12-18T21:45:53.329251Z DEBUG fred::multiplexer::types: fred-pm7n0saPJP: Checking unresponsive connections...    
2022-12-18T21:45:53.329259Z DEBUG fred::multiplexer::types: fred-d3vAUmx97z: Checking unresponsive connections...    
2022-12-18T21:45:53.329283Z DEBUG fred::multiplexer::types: fred-6Corg17GBH: Checking unresponsive connections...    
2022-12-18T21:45:53.329320Z TRACE fred::multiplexer::types: fred-6Corg17GBH: Using network timeout: 5000    
2022-12-18T21:45:53.329321Z TRACE fred::multiplexer::types: fred-pm7n0saPJP: Using network timeout: 5000    
2022-12-18T21:45:53.329319Z TRACE fred::multiplexer::types: fred-d3vAUmx97z: Using network timeout: 5000    
2022-12-18T21:45:53.331463Z DEBUG fred::multiplexer::types: fred-Aru1iU2Ekr: Checking unresponsive connections...    
2022-12-18T21:45:53.331470Z DEBUG fred::multiplexer::types: fred-9lCBe4loFM: Checking unresponsive connections...    
2022-12-18T21:45:53.331536Z TRACE fred::multiplexer::types: fred-Aru1iU2Ekr: Using network timeout: 5000    
2022-12-18T21:45:53.331597Z TRACE fred::multiplexer::types: fred-9lCBe4loFM: Using network timeout: 5000    
2022-12-18T21:45:58.324979Z DEBUG fred::multiplexer::types: fred-lZa2RW6GBf: Checking unresponsive connections...    
2022-12-18T21:45:58.325039Z TRACE fred::multiplexer::types: fred-lZa2RW6GBf: Using network timeout: 5000    
2022-12-18T21:45:58.330229Z DEBUG fred::multiplexer::types: fred-d3vAUmx97z: Checking unresponsive connections...    
2022-12-18T21:45:58.330281Z TRACE fred::multiplexer::types: fred-d3vAUmx97z: Using network timeout: 5000    
2022-12-18T21:45:58.330285Z DEBUG fred::multiplexer::types: fred-6Corg17GBH: Checking unresponsive connections...    
2022-12-18T21:45:58.330313Z TRACE fred::multiplexer::types: fred-6Corg17GBH: Using network timeout: 5000    
2022-12-18T21:45:58.330318Z DEBUG fred::multiplexer::types: fred-pm7n0saPJP: Checking unresponsive connections...    
2022-12-18T21:45:58.330356Z TRACE fred::multiplexer::types: fred-pm7n0saPJP: Using network timeout: 5000    
2022-12-18T21:45:58.332409Z DEBUG fred::multiplexer::types: fred-9lCBe4loFM: Checking unresponsive connections...    
2022-12-18T21:45:58.332422Z DEBUG fred::multiplexer::types: fred-Aru1iU2Ekr: Checking unresponsive connections...    
2022-12-18T21:45:58.332459Z TRACE fred::multiplexer::types: fred-Aru1iU2Ekr: Using network timeout: 5000    
2022-12-18T21:45:58.332460Z TRACE fred::multiplexer::types: fred-9lCBe4loFM: Using network timeout: 5000    
2022-12-18T21:46:03.326604Z DEBUG fred::multiplexer::types: fred-lZa2RW6GBf: Checking unresponsive connections...    
2022-12-18T21:46:03.326665Z TRACE fred::multiplexer::types: fred-lZa2RW6GBf: Using network timeout: 5000    
2022-12-18T21:46:03.331854Z DEBUG fred::multiplexer::types: fred-pm7n0saPJP: Checking unresponsive connections...    
2022-12-18T21:46:03.331905Z TRACE fred::multiplexer::types: fred-pm7n0saPJP: Using network timeout: 5000    
2022-12-18T21:46:03.331916Z DEBUG fred::multiplexer::types: fred-d3vAUmx97z: Checking unresponsive connections...    
2022-12-18T21:46:03.331936Z DEBUG fred::multiplexer::types: fred-6Corg17GBH: Checking unresponsive connections...    
2022-12-18T21:46:03.331948Z TRACE fred::multiplexer::types: fred-d3vAUmx97z: Using network timeout: 5000    
2022-12-18T21:46:03.331973Z TRACE fred::multiplexer::types: fred-6Corg17GBH: Using network timeout: 5000    
2022-12-18T21:46:03.334035Z DEBUG fred::multiplexer::types: fred-9lCBe4loFM: Checking unresponsive connections...    
2022-12-18T21:46:03.334053Z DEBUG fred::multiplexer::types: fred-Aru1iU2Ekr: Checking unresponsive connections...    
2022-12-18T21:46:03.334065Z TRACE fred::multiplexer::types: fred-9lCBe4loFM: Using network timeout: 5000    
2022-12-18T21:46:03.334075Z TRACE fred::multiplexer::types: fred-Aru1iU2Ekr: Using network timeout: 5000    
2022-12-18T21:46:08.328108Z DEBUG fred::multiplexer::types: fred-lZa2RW6GBf: Checking unresponsive connections...    
2022-12-18T21:46:08.328175Z TRACE fred::multiplexer::types: fred-lZa2RW6GBf: Using network timeout: 5000    
2022-12-18T21:46:08.332333Z DEBUG fred::multiplexer::types: fred-pm7n0saPJP: Checking unresponsive connections...    
2022-12-18T21:46:08.332326Z DEBUG fred::multiplexer::types: fred-6Corg17GBH: Checking unresponsive connections...    
2022-12-18T21:46:08.332353Z DEBUG fred::multiplexer::types: fred-d3vAUmx97z: Checking unresponsive connections...    
2022-12-18T21:46:08.332384Z TRACE fred::multiplexer::types: fred-6Corg17GBH: Using network timeout: 5000    
2022-12-18T21:46:08.332386Z TRACE fred::multiplexer::types: fred-pm7n0saPJP: Using network timeout: 5000    
2022-12-18T21:46:08.332401Z TRACE fred::multiplexer::types: fred-d3vAUmx97z: Using network timeout: 5000    
2022-12-18T21:46:08.335442Z DEBUG fred::multiplexer::types: fred-Aru1iU2Ekr: Checking unresponsive connections...    
2022-12-18T21:46:08.335446Z DEBUG fred::multiplexer::types: fred-9lCBe4loFM: Checking unresponsive connections...    
2022-12-18T21:46:08.335482Z TRACE fred::multiplexer::types: fred-Aru1iU2Ekr: Using network timeout: 5000    
2022-12-18T21:46:08.335482Z TRACE fred::multiplexer::types: fred-9lCBe4loFM: Using network timeout: 5000    
2022-12-18T21:46:13.329752Z DEBUG fred::multiplexer::types: fred-lZa2RW6GBf: Checking unresponsive connections...    
2022-12-18T21:46:13.329813Z TRACE fred::multiplexer::types: fred-lZa2RW6GBf: Using network timeout: 5000    
2022-12-18T21:46:13.333991Z DEBUG fred::multiplexer::types: fred-d3vAUmx97z: Checking unresponsive connections...    
2022-12-18T21:46:13.334049Z TRACE fred::multiplexer::types: fred-d3vAUmx97z: Using network timeout: 5000    
2022-12-18T21:46:13.334049Z DEBUG fred::multiplexer::types: fred-pm7n0saPJP: Checking unresponsive connections...    
2022-12-18T21:46:13.334069Z DEBUG fred::multiplexer::types: fred-6Corg17GBH: Checking unresponsive connections...    
2022-12-18T21:46:13.334088Z TRACE fred::multiplexer::types: fred-pm7n0saPJP: Using network timeout: 5000    
2022-12-18T21:46:13.334097Z TRACE fred::multiplexer::types: fred-6Corg17GBH: Using network timeout: 5000    
2022-12-18T21:46:13.336199Z DEBUG fred::multiplexer::types: fred-9lCBe4loFM: Checking unresponsive connections...    
2022-12-18T21:46:13.336242Z TRACE fred::multiplexer::types: fred-9lCBe4loFM: Using network timeout: 5000    
2022-12-18T21:46:13.336264Z DEBUG fred::multiplexer::types: fred-Aru1iU2Ekr: Checking unresponsive connections...    
2022-12-18T21:46:13.336308Z TRACE fred::multiplexer::types: fred-Aru1iU2Ekr: Using network timeout: 5000    
2022-12-18T21:46:18.330573Z DEBUG fred::multiplexer::types: fred-lZa2RW6GBf: Checking unresponsive connections...    
2022-12-18T21:46:18.330653Z TRACE fred::multiplexer::types: fred-lZa2RW6GBf: Using network timeout: 5000    
2022-12-18T21:46:18.336102Z DEBUG fred::multiplexer::types: fred-pm7n0saPJP: Checking unresponsive connections...    
2022-12-18T21:46:18.336089Z DEBUG fred::multiplexer::types: fred-d3vAUmx97z: Checking unresponsive connections...    
2022-12-18T21:46:18.336088Z DEBUG fred::multiplexer::types: fred-6Corg17GBH: Checking unresponsive connections...    
2022-12-18T21:46:18.336187Z TRACE fred::multiplexer::types: fred-pm7n0saPJP: Using network timeout: 5000    
2022-12-18T21:46:18.336245Z TRACE fred::multiplexer::types: fred-6Corg17GBH: Using network timeout: 5000    
2022-12-18T21:46:18.336248Z TRACE fred::multiplexer::types: fred-d3vAUmx97z: Using network timeout: 5000    
2022-12-18T21:46:18.337339Z DEBUG fred::multiplexer::types: fred-Aru1iU2Ekr: Checking unresponsive connections...    
2022-12-18T21:46:18.337339Z DEBUG fred::multiplexer::types: fred-9lCBe4loFM: Checking unresponsive connections...    
2022-12-18T21:46:18.337444Z TRACE fred::multiplexer::types: fred-9lCBe4loFM: Using network timeout: 5000    
2022-12-18T21:46:18.337444Z TRACE fred::multiplexer::types: fred-Aru1iU2Ekr: Using network timeout: 5000    
2022-12-18T21:46:23.331422Z DEBUG fred::multiplexer::types: fred-lZa2RW6GBf: Checking unresponsive connections...    
2022-12-18T21:46:23.331483Z TRACE fred::multiplexer::types: fred-lZa2RW6GBf: Using network timeout: 5000    
2022-12-18T21:46:23.337666Z DEBUG fred::multiplexer::types: fred-d3vAUmx97z: Checking unresponsive connections...    
2022-12-18T21:46:23.337699Z TRACE fred::multiplexer::types: fred-d3vAUmx97z: Using network timeout: 5000    
2022-12-18T21:46:23.337696Z DEBUG fred::multiplexer::types: fred-pm7n0saPJP: Checking unresponsive connections...    
2022-12-18T21:46:23.337712Z DEBUG fred::multiplexer::types: fred-6Corg17GBH: Checking unresponsive connections...    
2022-12-18T21:46:23.337729Z TRACE fred::multiplexer::types: fred-pm7n0saPJP: Using network timeout: 5000    
2022-12-18T21:46:23.337740Z TRACE fred::multiplexer::types: fred-6Corg17GBH: Using network timeout: 5000    
2022-12-18T21:46:23.338814Z DEBUG fred::multiplexer::types: fred-9lCBe4loFM: Checking unresponsive connections...    
2022-12-18T21:46:23.338843Z TRACE fred::multiplexer::types: fred-9lCBe4loFM: Using network timeout: 5000    
2022-12-18T21:46:23.338832Z DEBUG fred::multiplexer::types: fred-Aru1iU2Ekr: Checking unresponsive connections...    
2022-12-18T21:46:23.338871Z TRACE fred::multiplexer::types: fred-Aru1iU2Ekr: Using network timeout: 5000    
2022-12-18T21:46:28.332610Z DEBUG fred::multiplexer::types: fred-lZa2RW6GBf: Checking unresponsive connections...    
2022-12-18T21:46:28.332670Z TRACE fred::multiplexer::types: fred-lZa2RW6GBf: Using network timeout: 5000    
2022-12-18T21:46:28.338880Z DEBUG fred::multiplexer::types: fred-6Corg17GBH: Checking unresponsive connections...    
2022-12-18T21:46:28.338911Z DEBUG fred::multiplexer::types: fred-d3vAUmx97z: Checking unresponsive connections...    
2022-12-18T21:46:28.338916Z TRACE fred::multiplexer::types: fred-6Corg17GBH: Using network timeout: 5000    
2022-12-18T21:46:28.338932Z DEBUG fred::multiplexer::types: fred-pm7n0saPJP: Checking unresponsive connections...    
2022-12-18T21:46:28.338941Z TRACE fred::multiplexer::types: fred-d3vAUmx97z: Using network timeout: 5000    
2022-12-18T21:46:28.338961Z TRACE fred::multiplexer::types: fred-pm7n0saPJP: Using network timeout: 5000    
2022-12-18T21:46:28.340055Z DEBUG fred::multiplexer::types: fred-Aru1iU2Ekr: Checking unresponsive connections...    
2022-12-18T21:46:28.340064Z DEBUG fred::multiplexer::types: fred-9lCBe4loFM: Checking unresponsive connections...    
2022-12-18T21:46:28.340107Z TRACE fred::multiplexer::types: fred-Aru1iU2Ekr: Using network timeout: 5000    
2022-12-18T21:46:28.340124Z TRACE fred::multiplexer::types: fred-9lCBe4loFM: Using network timeout: 5000    
2022-12-18T21:46:33.334127Z DEBUG fred::multiplexer::types: fred-lZa2RW6GBf: Checking unresponsive connections...    
2022-12-18T21:46:33.334187Z TRACE fred::multiplexer::types: fred-lZa2RW6GBf: Using network timeout: 5000    
2022-12-18T21:46:33.339367Z DEBUG fred::multiplexer::types: fred-pm7n0saPJP: Checking unresponsive connections...    
2022-12-18T21:46:33.339411Z DEBUG fred::multiplexer::types: fred-6Corg17GBH: Checking unresponsive connections...    
2022-12-18T21:46:33.339449Z TRACE fred::multiplexer::types: fred-pm7n0saPJP: Using network timeout: 5000    
2022-12-18T21:46:33.339449Z TRACE fred::multiplexer::types: fred-6Corg17GBH: Using network timeout: 5000    
2022-12-18T21:46:33.339477Z DEBUG fred::multiplexer::types: fred-d3vAUmx97z: Checking unresponsive connections...    
2022-12-18T21:46:33.339504Z TRACE fred::multiplexer::types: fred-d3vAUmx97z: Using network timeout: 5000    
2022-12-18T21:46:33.341580Z DEBUG fred::multiplexer::types: fred-Aru1iU2Ekr: Checking unresponsive connections...    
2022-12-18T21:46:33.341621Z TRACE fred::multiplexer::types: fred-Aru1iU2Ekr: Using network timeout: 5000    
2022-12-18T21:46:33.341624Z DEBUG fred::multiplexer::types: fred-9lCBe4loFM: Checking unresponsive connections...    

@neogenie
Copy link
Contributor Author

Unfortunately not working yet...
In my test scenario, everything got even worse: after a certain number of attempts, everything went into infinity loop.

let config = RedisConfig {
            server: ServerConfig::Clustered { hosts: nodes },
            password,
            fail_fast: true,
            ..Default::default()
        };

        let perf_config = PerformanceConfig {
            max_command_attempts: 1,
            default_command_timeout_ms: 10_000,
            network_timeout_ms: 5_000,
            backpressure: BackpressureConfig {
                max_in_flight_commands: 50_000_000,
                ..Default::default()
            },
            ..Default::default()
        };

@aembke

@aembke aembke mentioned this issue Jan 2, 2023
@aembke
Copy link
Owner

aembke commented Jan 2, 2023

@neogenie looks like the pipeline settings were different between our repros. I was able to repro something very similar to your logs and fixed it with the linked PR. If you have a moment would you mind trying your repro against that branch (fix/issue-59)?

@aembke aembke closed this as completed in #94 Jan 2, 2023
@aembke
Copy link
Owner

aembke commented Jan 2, 2023

Didn't mean to close this when merging the PR.

@aembke aembke reopened this Jan 2, 2023
@neogenie
Copy link
Contributor Author

@aembke

Unfortunately, everything is the same. I tried with

Checking fred v6.0.0 (https://github.com/aembke/fred.rs.git#32d81433)

@aembke
Copy link
Owner

aembke commented Feb 14, 2023

Hey @neogenie, some more info on this:

I'm not sure what we're doing differently in our repros. I can't seem to get an infinite loop to show up regardless of how I configure the client after the changes in #94.

I can repro an error with the config you provided above, though. If the max_command_attempts is 1 and any of the servers go unresponsive while a command is in flight then it'd make sense that the caller would get a Too many failed write attempts error. That's all I'm able to repro at the moment, however.

Here's my repro steps if you want to compare:

I'm using the code in the local inf_loop module with mostly default arguments.

cd path/to/fred/
source ./tests/environ
cd bin/inf_loop
RUST_LOG=fred=trace ./run.sh --cluster -h redis-cluster-1 -p 30001 -a bar -w 1000

And then in another bash session I'm using docker pause on whichever container is receiving the INCR commands (usually redis-cluster-3 on a fresh run).

From my reading of the logs it looks like the client detects the unresponsive connection after 5 seconds, reconnects 2-3 times until the cluster promotes one of the replicas to replace the paused container, then sends the failed INCR command again to the new primary hash slot owner. Depending on the value of max_command_attempts it either continues the outer loop or breaks at this point.

Are there any different or subsequent steps in your repro that I'm missing here? FWIW I made some small changes to the scripts in my working branch (fix/issue-59.1) for this as well.

@aembke
Copy link
Owner

aembke commented Apr 1, 2023

Closing this for now, but if anybody is able to help provide a repro for this please let me know and I'll reopen.

@aembke aembke closed this as completed Apr 1, 2023
@neogenie
Copy link
Contributor Author

@aembke hi!

Sorry for the delay!

Unfortunately, it doesn't work. Or am I doing something wrong or
I put together a minimal stand to reproduce the problem: https://github.com/neogenie/fred6_issues

It contains a minimal test that pauses the containers one by one and checks whether the key can be read/written. The test has all the necessary infrastructure to track the status of the cluster.

@neogenie
Copy link
Contributor Author

@aembke Up, pls !

@aembke aembke mentioned this issue May 1, 2023
@aembke
Copy link
Owner

aembke commented May 2, 2023

Hey @neogenie,

Thanks for taking the time to put this together, that was really helpful.

I was able to repro the issue and fix it with the changes in #129. It looks like some combination of what you said initially (some missing timeouts on backchannel operations) and maybe the change in #126 as well.

For what it's worth - to make your test pass I also had to reconfigure a few client settings. If your app code needs to handle this failure mode you may want to do something similar:

  • The max_command_attempts was changed from 1 to 2. It'll take one failure/timeout to detect the paused node since the connection doesn't close when the container is paused.
  • The repro uses a constant reconnect policy on a 1 sec interval so I changed default_command_timeout_ms from 1000 to 30_000 so the client had time to reconnect.
  • Added fred::globals::set_default_connection_timeout_ms(3_000) before initializing the client. The default is 60 sec, and in this case you'll want this to be less than the default_command_timeout_ms since the client may hit one of these timeouts while detecting the paused node. The name is a bit misleading, but that value is also used as the timeout on CLUSTER SLOTS commands.
  • It wasn't necessary here, but you can also use fred::globals::set_unresponsive_interval_ms to control how often the client checks for unresponsive connections.

I'll release 6.2.1 with these changes tonight or tomorrow and then most likely come back and adapt your repro into some integration tests. Thanks again.

@neogenie
Copy link
Contributor Author

neogenie commented May 2, 2023

@aembke Thanks a lot!
I'll go check

@neogenie
Copy link
Contributor Author

neogenie commented May 2, 2023

Unfortunately, it doesn't work. Or am I doing something wrong

@neogenie
Copy link
Contributor Author

neogenie commented May 2, 2023

@aembke
Copy link
Owner

aembke commented May 4, 2023

This is an interesting one. Try this #133.

I also had to set max_command_attempts to 3. There's a few race conditions with this that can result in the server returning a MOVED error to the client, and following that would mean another write attempt. Those two changes fixed it for me.

@neogenie
Copy link
Contributor Author

neogenie commented May 4, 2023

@aembke
Looks like it's working now! Thanks a lot. The only thing, it's not entirely obvious that the combination of configuration options matters - it would be great to describe the recommended proportions between them.

@aembke
Copy link
Owner

aembke commented May 5, 2023

Yeah I agree, this definitely highlighted the need for better docs and maybe even some "preset" functions on various config structs. Thanks for your patience on this too.

@neogenie
Copy link
Contributor Author

neogenie commented May 5, 2023

@aembke
The only thing is that the test still does not working correctly with .replicas() method.

@aembke
Copy link
Owner

aembke commented May 8, 2023

Yeah, that's from an unrelated issue. The fix for that will go up with: #134

@neogenie
Copy link
Contributor Author

neogenie commented May 8, 2023

Thanks! It works!!! @aembke

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging a pull request may close this issue.

2 participants