search

bitwalker / swarm

Easy clustering, registration, and distribution of worker processes for Erlang/Elixir
MIT License
1.19k stars 102 forks source link

Expected callbacks not received after network heals #89

Open markmeeus opened 6 years ago

markmeeus commented 6 years ago

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>
fredr commented 5 years ago

@markmeeus did you ever resolve this? and if so, what was the solution?

fredr commented 5 years ago

I've noticed that I have the same problem when running a cluster of 2 nodes, when I run 3 nodes the :begin_handoff and :resolve_conflict callbacks are called as expected.

x-ji commented 4 years ago

Same here. the processes are untracked but are never restarted on the other node for some reason. None of them events are called. Seems from some other issues that you may need to handle graceful shutdowns manually https://github.com/bitwalker/swarm/pull/83. But they're only talking about "handoffs" even though I just want to do a restart... So it's still confusing.