Ok, I see. node-3
takes around 200ms to stop:
[2019-04-18T12:53:55,648][INFO ][o.e.n.Node ] [node-3] stopping ...
[2019-04-18T12:53:55,823][INFO ][o.e.n.Node ] [node-3] stopped
One of the first things it does is announce that it's shutting down, triggering another election:
[2019-04-18T12:53:55,659][INFO ][o.e.d.z.ZenDiscovery ] [node-1] master_left [{node-3}{8v1o1noDS5e_e7TAgI9K7A}{WCrG1STSQMWu6MCMRiHIqQ}{172.20.71.55}{172.20.71.55:9300}], reason [shut_down]
[2019-04-18T12:53:55,659][WARN ][o.e.d.z.ZenDiscovery ] [node-1] master left (reason = shut_down), current nodes: nodes:
{node-2}{nS8tF5PhTmau1Jc8mJhx_A}{Xw7nuJ5IS4uEgUulQEb3YQ}{172.20.71.33}{172.20.71.33:9300}
{node-3}{8v1o1noDS5e_e7TAgI9K7A}{WCrG1STSQMWu6MCMRiHIqQ}{172.20.71.55}{172.20.71.55:9300}, master
{node-1}{qtQ9zxHGS0yu8VyS_GDCuw}{a3ufzEfyQAubZvHWX9GXZg}{172.20.71.43}{172.20.71.43:9300}, local
[2019-04-18T12:53:55,659][DEBUG][o.e.d.z.MasterFaultDetection] [node-1] [master] stopping fault detection against master [{node-3}{8v1o1noDS5e_e7TAgI9K7A}{WCrG1STSQMWu6MCMRiHIqQ}{172.20.71.55}{172.20.71.55:9300}], reason [master left (reason = shut_down)]
[2019-04-18T12:53:55,659][TRACE][o.e.d.z.NodeJoinController] [node-1] starting an election context, will accumulate joins
However, node-1
reacts very quickly to the news, starts its discovery phase, and discovers node-3
within under 20ms:
[2019-04-18T12:53:55,659][TRACE][o.e.d.z.ZenDiscovery ] [node-1] starting to ping
[2019-04-18T12:53:55,660][TRACE][o.e.d.z.UnicastZenPing ] [node-1] resolved host [172.20.71.43] to [172.20.71.43:9300]
[2019-04-18T12:53:55,660][TRACE][o.e.d.z.UnicastZenPing ] [node-1] resolved host [172.20.71.33] to [172.20.71.33:9300]
[2019-04-18T12:53:55,660][TRACE][o.e.d.z.UnicastZenPing ] [node-1] resolved host [172.20.71.55] to [172.20.71.55:9300]
[2019-04-18T12:53:55,660][TRACE][o.e.d.z.UnicastZenPing ] [node-1] [3] sending to {node-3}{8v1o1noDS5e_e7TAgI9K7A}{WCrG1STSQMWu6MCMRiHIqQ}{172.20.71.55}{172.20.71.55:9300}
[2019-04-18T12:53:55,660][TRACE][o.e.d.z.UnicastZenPing ] [node-1] [3] sending to {node-1}{qtQ9zxHGS0yu8VyS_GDCuw}{a3ufzEfyQAubZvHWX9GXZg}{172.20.71.43}{172.20.71.43:9300}
[2019-04-18T12:53:55,660][TRACE][o.e.d.z.UnicastZenPing ] [node-1] [3] sending to {node-2}{nS8tF5PhTmau1Jc8mJhx_A}{Xw7nuJ5IS4uEgUulQEb3YQ}{172.20.71.33}{172.20.71.33:9300}
[2019-04-18T12:53:55,661][TRACE][o.e.d.z.UnicastZenPing ] [node-1] [3] received response from {node-1}{qtQ9zxHGS0yu8VyS_GDCuw}{a3ufzEfyQAubZvHWX9GXZg}{172.20.71.43}{172.20.71.43:9300}: [ping_response{node [{node-1}{qtQ9zxHGS0yu8VyS_GDCuw}{a3ufzEfyQAubZvHWX9GXZg}{172.20.71.43}{172.20.71.43:9300}], id[24], master [null],cluster_state_version [230], cluster_name[elastic-infinibox]}, ping_response{node [{node-1}{qtQ9zxHGS0yu8VyS_GDCuw}{a3ufzEfyQAubZvHWX9GXZg}{172.20.71.43}{172.20.71.43:9300}], id[25], master [null],cluster_state_version [230], cluster_name[elastic-infinibox]}]
[2019-04-18T12:53:55,661][TRACE][o.e.d.z.UnicastZenPing ] [node-1] [3] received response from {node-2}{nS8tF5PhTmau1Jc8mJhx_A}{Xw7nuJ5IS4uEgUulQEb3YQ}{172.20.71.33}{172.20.71.33:9300}: [ping_response{node [{node-1}{qtQ9zxHGS0yu8VyS_GDCuw}{a3ufzEfyQAubZvHWX9GXZg}{172.20.71.43}{172.20.71.43:9300}], id[24], master [null],cluster_state_version [230], cluster_name[elastic-infinibox]}, ping_response{node [{node-2}{nS8tF5PhTmau1Jc8mJhx_A}{Xw7nuJ5IS4uEgUulQEb3YQ}{172.20.71.33}{172.20.71.33:9300}], id[8], master [{node-3}{8v1o1noDS5e_e7TAgI9K7A}{WCrG1STSQMWu6MCMRiHIqQ}{172.20.71.55}{172.20.71.55:9300}],cluster_state_version [230], cluster_name[elastic-infinibox]}]
[2019-04-18T12:53:55,661][TRACE][o.e.d.z.UnicastZenPing ] [node-1] [3] received response from {node-3}{8v1o1noDS5e_e7TAgI9K7A}{WCrG1STSQMWu6MCMRiHIqQ}{172.20.71.55}{172.20.71.55:9300}: [ping_response{node [{node-1}{qtQ9zxHGS0yu8VyS_GDCuw}{a3ufzEfyQAubZvHWX9GXZg}{172.20.71.43}{172.20.71.43:9300}], id[24], master [null],cluster_state_version [230], cluster_name[elastic-infinibox]}, ping_response{node [{node-3}{8v1o1noDS5e_e7TAgI9K7A}{WCrG1STSQMWu6MCMRiHIqQ}{172.20.71.55}{172.20.71.55:9300}], id[27], master [{node-3}{8v1o1noDS5e_e7TAgI9K7A}{WCrG1STSQMWu6MCMRiHIqQ}{172.20.71.55}{172.20.71.55:9300}],cluster_state_version [230], cluster_name[elastic-infinibox]}]
I think we could call this a bug: node-3
arguably shouldn't respond to pings after it's announced that it's shutting down. The only maintained version with this bug is now 6.7 (it doesn't occur in 7.0 or later) and I don't think it's critical enough to warrant a fix there.
This means that what I said earlier isn't the case - it now looks like it can take ~7 seconds to elect a new master because sometimes there will be two elections, each taking 3 seconds. TIL.