bitwalker / bitwalker/swarm

Expected callbacks not received after network heals

Open
#89 3 comments 0 reactions 0 assignees View on GitHub
Dominant language
Elixir
Stars
1.3k
Forks
110
PR merge metrics
No merged PRs in 30d

Description

Hi,

Thanks for the great lib, awesome work!

We are building a system where we have to process a stream of messages from a remote system. To be more precise, the stream of data are update messages for a specific resources.

So we are using Swarm to manage worker processes for these resources. We create the process when the first message arrives, and let it die from a genserver timeout after a set interval.

We are now in the process of testing the app for a network split situation, and it looks like something is a bit off, or at least, we are a bit confused :-)

First of all, we are using the Distribution.Ring since we will be deploying on an OpenShift instance (Kubernetes)
We are testing this by simply connecting 2 iex nodes running our app with `Node.connect/1` and `Node.disconnect/1`

What happens is the following
-> When the 2 nodes are connected, a new message for a new resource creates a process on one of the 2 nodes, perfect
-> When the 2 nodes are disconnected, all processes that existed before the disconnect are started (if the were not already running) on both machines, still makes sense.
-> When the 2 are connected again, the processes keep running on one of the nodes and the processes on the other node receive a {:swarm, :die}, strange, we were actually expecting them to be relocated, the Ring uses a consistent hash?

While the nodes were disconnected, both processes could have processed messages and they maybe in a conflicting state. We have way to actually resolve these conflicts and we were counting on the :resolve_conflict message to inform us about this situation.

However none of the `:begin_handoff`, `:end_handoff` or `:resolve_conflict` messages are received on either Node.

our begin_handoff returns a :resume tuple, but since it is not called ...

Could you help us out?

Here are some debug logs of the disconnect/connect:
### Node A "attila" => disconnect
```
iex(attila@10.68.38.221)2> Node.disconnect :"mark@10.68.38.221"
*DBG* 'Elixir.Swarm.Tracker' receive info {'DOWN',#Ref<0.2529274800.2416967684.136847>,process,<22512.560.0>,
noconnection} in state tracking
true
iex(attila@10.68.38.221)3> *DBG* 'Elixir.Swarm.Tracker' consume info {'DOWN',#Ref<0.2529274800.2416967684.136847>,process,<22512.560.0>,
noconnection} in state tracking
*DBG* 'Elixir.Swarm.Tracker' receive info {nodedown,'mark@10.68.38.221',[{node_type,visible}]} in state tracking
*DBG* 'Elixir.Swarm.Tracker' consume info {nodedown,'mark@10.68.38.221',[{node_type,visible}]} in state tracking
[debug] [swarm on attila@10.68.38.221] [tracker:handle_monitor] lost connection to "RESOURCE401" (#PID<22512.560.0>) on mark@10.68.38.221, node is down
[info] [swarm on attila@10.68.38.221] [tracker:nodedown] nodedown mark@10.68.38.221
[debug] [swarm on attila@10.68.38.221] [tracker:handle_topology_change] topology change (nodedown for mark@10.68.38.221)
[debug] [swarm on attila@10.68.38.221] [tracker:handle_topology_change] restarting "RESOURCE400" on attila@10.68.38.221
[debug] [swarm on attila@10.68.38.221] [tracker:do_track] starting "RESOURCE400" on attila@10.68.38.221
[debug] [swarm on attila@10.68.38.221] [tracker:do_track] started "RESOURCE400" on attila@10.68.38.221
[debug] [swarm on attila@10.68.38.221] [tracker:handle_topology_change] restarting "RESOURCE401" on attila@10.68.38.221
[debug] [swarm on attila@10.68.38.221] [tracker:do_track] starting "RESOURCE401" on attila@10.68.38.221
[debug] [swarm on attila@10.68.38.221] [tracker:do_track] started "RESOURCE401" on attila@10.68.38.221
[info] [swarm on attila@10.68.38.221] [tracker:handle_topology_change] topology change complete
````
### Node B "mark" => received disconnect
````
*DBG* 'Elixir.Swarm.Tracker' receive info {'DOWN',#Ref<0.899263733.806354945.65248>,process,<24381.547.0>,
noconnection} in state tracking
*DBG* 'Elixir.Swarm.Tracker' consume info {'DOWN',#Ref<0.899263733.806354945.65248>,process,<24381.547.0>,
noconnection} in state tracking
*DBG* 'Elixir.Swarm.Tracker' receive info {nodedown,'attila@10.68.38.221',[{node_type,visible}]} in state tracking
*DBG* 'Elixir.Swarm.Tracker' consume info {nodedown,'attila@10.68.38.221',[{node_type,visible}]} in state tracking
[debug] [swarm on mark@10.68.38.221] [tracker:handle_monitor] lost connection to "RESOURCE402" (#PID<24381.547.0>) on attila@10.68.38.221, node is down
[info] [swarm on mark@10.68.38.221] [tracker:nodedown] nodedown attila@10.68.38.221
[debug] [swarm on mark@10.68.38.221] [tracker:handle_topology_change] topology change (nodedown for attila@10.68.38.221)
[debug] [swarm on mark@10.68.38.221] [tracker:handle_topology_change] restarting "RESOURCE402" on mark@10.68.38.221
[debug] [swarm on mark@10.68.38.221] [tracker:do_track] starting "RESOURCE402" on mark@10.68.38.221
[debug] [swarm on mark@10.68.38.221] [tracker:do_track] started "RESOURCE402" on mark@10.68.38.221
[info] [swarm on mark@10.68.38.221] [tracker:handle_topology_change] topology change complete
````

... Some processing going on while nodes are disconnected ...

### Node A "attila" => connect with Node B
````
iex(attila@10.68.38.221)3> Node.connect :"mark@10.68.38.221"
*DBG* 'Elixir.Swarm.Tracker' receive info {nodeup,'mark@10.68.38.221',[{node_type,visible}]} in state tracking
true
iex(attila@10.68.38.221)4> *DBG* 'Elixir.Swarm.Tracker' consume info {nodeup,'mark@10.68.38.221',[{node_type,visible}]} in state tracking
*DBG* 'Elixir.Swarm.Tracker' receive cast {sync,<22512.358.0>,{1,0}} in state syncing
*DBG* 'Elixir.Swarm.Tracker' consume cast {sync,<22512.358.0>,{1,0}} in state syncing
[info] [swarm on attila@10.68.38.221] [tracker:ensure_swarm_started_on_remote_node] nodeup mark@10.68.38.221
*DBG* 'Elixir.Swarm.Tracker' receive cast {sync_recv,<22512.358.0>,
{{0,1},0},
[{entry,<<"RESOURCE402">>,<22512.568.0>,
#Ref<22512.899263733.806354946.64013>,
#{all_workers => true,
mfa =>
{'Elixir.Cadex.Swarm.Supervisor',start_unit_processor,
[<<"RESOURCE402">>]}},
{{0,{0,10,0}},{{1,0},{0,10,0}}}},
{entry,<<"RESOURCE401">>,<22512.560.0>,
#Ref<22512.899263733.806354949.65462>,
#{all_workers => true,
mfa =>
{'Elixir.Cadex.Swarm.Supervisor',start_unit_processor,
[<<"RESOURCE401">>]}},
{{0,{0,4,0}},{{1,0},{0,4,0}}}},
{entry,<<"RESOURCE400">>,<22512.557.0>,
#Ref<22512.899263733.806354949.64803>,
#{all_workers => true,
mfa =>
{'Elixir.Cadex.Swarm.Supervisor',start_unit_processor,
[<<"RESOURCE400">>]}},
{{0,{0,2,0}},{{1,0},{0,2,0}}}}]} in state syncing
"{:swarm, :die} RESOURCE402"
"{:swarm, :die} RESOURCE401"
"{:swarm, :die} RESOURCE400"
[info] [swarm on attila@10.68.38.221] [tracker:cluster_wait] joining cluster..
[info] [swarm on attila@10.68.38.221] [tracker:cluster_wait] found connected nodes: [:"mark@10.68.38.221"]
[info] [swarm on attila@10.68.38.221] [tracker:cluster_wait] selected sync node: mark@10.68.38.221
[info] [swarm on attila@10.68.38.221] [tracker:syncing] syncing from mark@10.68.38.221 based on node precedence
*DBG* 'Elixir.Swarm.Tracker' consume cast {sync_recv,<22512.358.0>,
{{0,1},0},
[{entry,<<"RESOURCE402">>,<22512.568.0>,
#Ref<22512.899263733.806354946.64013>,
#{all_workers => true,
mfa =>
{'Elixir.Cadex.Swarm.Supervisor',start_unit_processor,
[<<"RESOURCE402">>]}},
{{0,{0,10,0}},{{1,0},{0,10,0}}}},
{entry,<<"RESOURCE401">>,<22512.560.0>,
#Ref<22512.899263733.806354949.65462>,
#{all_workers => true,
mfa =>
{'Elixir.Cadex.Swarm.Supervisor',start_unit_processor,
[<<"RESOURCE401">>]}},
{{0,{0,4,0}},{{1,0},{0,4,0}}}},
{entry,<<"RESOURCE400">>,<22512.557.0>,
#Ref<22512.899263733.806354949.64803>,
#{all_workers => true,
mfa =>
{'Elixir.Cadex.Swarm.Supervisor',start_unit_processor,
[<<"RESOURCE400">>]}},
{{0,{0,2,0}},{{1,0},{0,2,0}}}}]} in state syncing
[info] [swarm on attila@10.68.38.221] [tracker:syncing] received registry from mark@10.68.38.221, merging..
[info] [swarm on attila@10.68.38.221] [tracker:syncing] local synchronization with mark@10.68.38.221 complete!
[info] [swarm on attila@10.68.38.221] [tracker:resolve_pending_sync_requests] pending sync requests cleared

````

### Node B "mark" => receive 2nd connect

````
*DBG* 'Elixir.Swarm.Tracker' receive info {nodeup,'attila@10.68.38.221',[{node_type,visible}]} in state tracking
*DBG* 'Elixir.Swarm.Tracker' consume info {nodeup,'attila@10.68.38.221',[{node_type,visible}]} in state tracking
*DBG* 'Elixir.Swarm.Tracker' receive cast {sync,<24381.349.0>,{1,0}} in state syncing
*DBG* 'Elixir.Swarm.Tracker' consume cast {sync,<24381.349.0>,{1,0}} in state syncing
[info] [swarm on mark@10.68.38.221] [tracker:ensure_swarm_started_on_remote_node] nodeup attila@10.68.38.221
*DBG* 'Elixir.Swarm.Tracker' receive info {event,<24381.349.0>,{{0,1},{1,1}},{untrack,<24381.547.0>}} in state awaiting_sync_ack
*DBG* 'Elixir.Swarm.Tracker' postpone info {event,<24381.349.0>,{{0,1},{1,1}},{untrack,<24381.547.0>}} in state awaiting_sync_ack
*DBG* 'Elixir.Swarm.Tracker' receive info {event,<24381.349.0>,{{0,2},{1,2}},{untrack,<24381.550.0>}} in state awaiting_sync_ack
*DBG* 'Elixir.Swarm.Tracker' postpone info {event,<24381.349.0>,{{0,2},{1,2}},{untrack,<24381.550.0>}} in state awaiting_sync_ack
*DBG* 'Elixir.Swarm.Tracker' receive info {event,<24381.349.0>,{{0,3},{1,3}},{untrack,<24381.549.0>}} in state awaiting_sync_ack
*DBG* 'Elixir.Swarm.Tracker' postpone info {event,<24381.349.0>,{{0,3},{1,3}},{untrack,<24381.549.0>}} in state awaiting_sync_ack
*DBG* 'Elixir.Swarm.Tracker' receive cast {sync_ack,<24381.349.0>,
{1,3},
[{entry,<<"RESOURCE402">>,<0.568.0>,
#Ref<24381.2529274800.2416967683.128726>,
#{all_workers => true,
mfa =>
{'Elixir.Cadex.Swarm.Supervisor',start_unit_processor,
[<<"RESOURCE402">>]}},
{{0,{0,10,0}},{{1,0},{0,10,0}}}},
{entry,<<"RESOURCE401">>,<0.560.0>,
#Ref<24381.2529274800.2416967683.128729>,
#{all_workers => true,
mfa =>
{'Elixir.Cadex.Swarm.Supervisor',start_unit_processor,
[<<"RESOURCE401">>]}},
{{0,{0,4,0}},{{1,0},{0,4,0}}}},
{entry,<<"RESOURCE400">>,<0.557.0>,
#Ref<24381.2529274800.2416967683.128731>,
#{all_workers => true,
mfa =>
{'Elixir.Cadex.Swarm.Supervisor',start_unit_processor,
[<<"RESOURCE400">>]}},
{{0,{0,2,0}},{{1,0},{0,2,0}}}}]} in state awaiting_sync_ack
[info] [swarm on mark@10.68.38.221] [tracker:cluster_wait] joining cluster..
[info] [swarm on mark@10.68.38.221] [tracker:cluster_wait] found connected nodes: [:"attila@10.68.38.221"]
[info] [swarm on mark@10.68.38.221] [tracker:cluster_wait] selected sync node: attila@10.68.38.221
[info] [swarm on mark@10.68.38.221] [tracker:syncing] syncing to attila@10.68.38.221 based on node precedence
*DBG* 'Elixir.Swarm.Tracker' consume cast {sync_ack,<24381.349.0>,
{1,3},
[{entry,<<"RESOURCE402">>,<0.568.0>,
#Ref<24381.2529274800.2416967683.128726>,
#{all_workers => true,
mfa =>
{'Elixir.Cadex.Swarm.Supervisor',start_unit_processor,
[<<"RESOURCE402">>]}},
{{0,{0,10,0}},{{1,0},{0,10,0}}}},
{entry,<<"RESOURCE401">>,<0.560.0>,
#Ref<24381.2529274800.2416967683.128729>,
#{all_workers => true,
mfa =>
{'Elixir.Cadex.Swarm.Supervisor',start_unit_processor,
[<<"RESOURCE401">>]}},
{{0,{0,4,0}},{{1,0},{0,4,0}}}},
{entry,<<"RESOURCE400">>,<0.557.0>,
#Ref<24381.2529274800.2416967683.128731>,
#{all_workers => true,
mfa =>
{'Elixir.Cadex.Swarm.Supervisor',start_unit_processor,
[<<"RESOURCE400">>]}},
{{0,{0,2,0}},{{1,0},{0,2,0}}}}]} in state awaiting_sync_ack
*DBG* 'Elixir.Swarm.Tracker' consume info {event,<24381.349.0>,{{0,1},{1,1}},{untrack,<24381.547.0>}} in state tracking
*DBG* 'Elixir.Swarm.Tracker' consume info {event,<24381.349.0>,{{0,2},{1,2}},{untrack,<24381.550.0>}} in state tracking
*DBG* 'Elixir.Swarm.Tracker' consume info {event,<24381.349.0>,{{0,3},{1,3}},{untrack,<24381.549.0>}} in state tracking
[info] [swarm on mark@10.68.38.221] [tracker:awaiting_sync_ack] received sync acknowledgement from attila@10.68.38.221, syncing with remote registry
[info] [swarm on mark@10.68.38.221] [tracker:awaiting_sync_ack] local synchronization with attila@10.68.38.221 complete!
[info] [swarm on mark@10.68.38.221] [tracker:resolve_pending_sync_requests] pending sync requests cleared
[debug] [swarm on mark@10.68.38.221] [tracker:handle_replica_event] replica event: untrack #PID<24381.547.0>
[debug] [swarm on mark@10.68.38.221] [tracker:handle_replica_event] replica event: untrack #PID<24381.550.0>
[debug] [swarm on mark@10.68.38.221] [tracker:handle_replica_event] replica event: untrack #PID<24381.549.0>
````

Contributor guide

No contributing guide indexed for this repository

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.