В рамках обмена разумом довелось на днях протянуть руку помощи в Грецию — помочь тамошнему инженеру Exchange ответить на вопрос заказчика, почему его 4-нодовый отказоустойчивый растянутый в облако DAG-кластер вдруг развалился, как пирамидка из кубиков.
Дано: две ноды кластера (node 1, node 2) размещены на площадке заказчика (on-premise), ещё две (node 3, node 4) где-то «в облаке», File share witness (на отдельном сервере, но тоже у заказчика), ОС Windows 2008 R2.
Проблема: всё пропало, кластер развалился, Exchange, соответственно, потерял базу и впал в прострацию.
Задача: понять почему, и сделать так, чтоб больше такого не было. Никогда. Хе-хе…
System Event Log показал, что примерно в 4 утра без объявления войны начала «моргать» сеть между нодами on-premise и «облачными».
04:33:31 Cluster node ‘CLOUDMBX2’ was removed from the active failover cluster membership. The Cluster service on this node may have stopped. This could also be due to the node having lost communication with other active nodes in the failover cluster. Run the Validate a Configuration wizard to check your network configuration. If the condition persists, check for hardware or software errors related to the network adapters on this node. Also check for failures in any other network components to which the node is connected such as hubs, switches, or bridges.
04:21:09 Cluster node ‘CLOUDMBX1’ was removed from the active failover cluster membership. The Cluster service on this node may have stopped. This could also be due to the node having lost communication with other active nodes in the failover cluster. Run the Validate a Configuration wizard to check your network configuration. If the condition persists, check for hardware or software errors related to the network adapters on this node. Also check for failures in any other network components to which the node is connected such as hubs, switches, or bridges.
В кластерном логе с этого момента можно наблюдать активную возню в попытке вернуть потерянных «облачных» товарищей обратно в группу. Безуспешную, потому что проблемы с сетью продолжаются.
3892 00001908.00001fc4::2016/09/23-03:44:50.408 INFO [NODE] Node 1: n3 node object adding stream
3903 00001908.0000131c::2016/09/23-03:44:50.486 ERR [NODE] Node 1: Error processing message from n3, starting Regroup.
4525 00001908.00000854::2016/09/23-04:00:28.795 INFO [RGP] Node 1: upgrading 301(1 2) => 404(1 2 4) in stage Stable_0(1)
5510 00001908.00000854::2016/09/23-04:01:20.680 ERR [NODE] Node 1: Connection to Node 4 is broken. Reason Closed(1236)’ because of ‘channel to remote endpoint fe80::517e:ac92:9e24:fa25%16:~3343~ has failed with status WSAECONNRESET(10054)’
5511 00001908.00000854::2016/09/23-04:01:20.680 WARN [NODE] Node 1: Initiating reconnect with n4.
5958 00001908.00001b18::2016/09/23-04:05:39.781 ERR [NODE] Node 1: Connection to Node 4 is broken. Reason Closed(1236)’ because of ‘channel to remote endpoint fe80::517e:ac92:9e24:fa25%16:~3343~ has failed with status WSAECONNRESET(10054)’
7244 00001908.00000e10::2016/09/23-04:08:53.782 ERR [NODE] Node 1: Connection to Node 3 is broken. Reason GracefulClose(1226)’ because of ‘channel to remote endpoint fe80::dcf8:c3c2:c9b8:b250%16:~3343~ is closed’
В один прекрасный момент им почти удалось воссоединиться всем четырём.
7815 00001908.00002094::2016/09/23-04:08:59.398 INFO [RGP] Node 1: incoming node 2 is in stage Closing2(1 2 3 4) oldView:503(1 2 3 4) proposed:601(1 2 3 4)
7816 00001908.00002094::2016/09/23-04:08:59.398 INFO [RGP] Node 1: merging inStage (1 2 3 4) + (1 2 3 4) = (1 2 3 4) (sender 2 in stage Closing2)
Но внезапно выяснилось, что нет связи между первой и третьей нодами.
7817 00001908.00002094::2016/09/23-04:08:59.398 INFO [RGP] Node 1: connectivity matrix is not complete (waiting: <ConnectivityMatrix>
7818 00001908.00002094::2016/09/23-04:08:59.398 INFO <row id=’0’00000000000000000000000000000000/>
7819 00001908.00002094::2016/09/23-04:08:59.398 INFO <row id=’1′00000000000000000000000000010110/>
7820 00001908.00002094::2016/09/23-04:08:59.398 INFO <row id=’2′00000000000000000000000000011110/>
7821 00001908.00002094::2016/09/23-04:08:59.398 INFO <row id=’3′00000000000000000000000000011100/>
7822 00001908.00002094::2016/09/23-04:08:59.398 INFO <row id=’4′00000000000000000000000000011110/>
7823 00001908.00002094::2016/09/23-04:08:59.398 INFO </ConnectivityMatrix>
Тут надо понимать, что механизм реализации кластера требует наличия связи каждой ноды с каждой другой нодой в кластере. И если это правило не выполняется, выбирается наиболее связный между собой набор (surviving subset) участников, а остальные принудительно выпиливаются нафиг (trim) до устранения проблем. Во избежание split-brain.
И вот что мы видим в кластерном логе:
7824 00001908.00000c88::2016/09/23-04:08:59.710 INFO [RGP] Node 1: Timer Tick Started
7825 00001908.00000c88::2016/09/23-04:08:59.710 INFO [RGP] Node 1: best surviving subset is (2 3 4), will be pruned after PruneAck
7826 00001908.00000c88::2016/09/23-04:08:59.710 INFO [RGP] Node 1: Closing2 => Pruning3
3(1) oldView:503(1 2 3 4) proposed:601(2 3 4)
7851 00001908.000028e0::2016/09/23-04:08:59.710 INFO [RGP] Node 1: incoming node 1 is in stage Pruning
7852 00001908.000028e0::2016/09/23-04:08:59.710 WARN [RGP] Node 1: node 1 was trimmed out during regroup (1)
Не очень понятно, почему система решила выкинуть node 1 (лидера кластера на тот момент), а не node 3, но случилось так. Node 2 подхватила кластерный ресурс и Witness, но почти в этот же момент снова пропала связь между ней и нодами в облаке и потеряв кворум (необходимое для работы кластера большинство участников) node 2 тоже остановила свою деятельность.
10121 00001e88.00002360::2016/09/23-04:09:07.830 ERR [QUORUM] Node 2: Lost quorum (0 2)
10122 00001e88.00002360::2016/09/23-04:09:07.830 ERR lost quorum (status = 5925)
10124 00001e88.00002360::2016/09/23-04:09:07.830 INFO [DM]: Shutting down, so unloading the cluster database.
10127 000013ac.0000230c::2016/09/23-04:09:07.939 WARN [RHS] Cluster service has terminated.
Ну а так как Witness остался отрезан от облачных участников, последние тоже не дотянули до кворума и кластер прекратил свою деятельность.
Get-Cluster <cluster name> | fl *
показал в числе прочего следующие параметры:
CrossSubnetDelay : 1000
CrossSubnetThreshold : 5
SameSubnetDelay : 1000
SameSubnetThreshold : 5
Delay — это задержка между heardbeat’ами, а Threshold — допустимое количество пропущенных хартбитов, после которого нода будет считаться потерянной. Так вот, указанные значения являются значениями по умолчанию вплоть до Windows 2012 R2. А потом вдруг осознали, что такие настройки слишком агрессивны. Подробно об этом хорошо написано тут: Tuning Failover Cluster Network Thresholds (табличка оттуда же).
Parameter | Win2012 R2 | Win2016 | Maximum |
SameSubnetDelay | 1 second | 1 second | 2 seconds |
SameSubnetThreshold | 5 heartbeats | 10 heartbeats | 120 heartbeats |
CrossSubnetDelay | 1 second | 1 seconds | 4 seconds |
CrossSubnetThreshold | 5 heartbeats | 20 heartbeats | 120 heartbeats |
CrossSiteDelay | NA | 1 second | 4 seconds |
CrossSiteThreshold | NA | 20 heartbeats | 120 heartbeats |
И даже выпустили патч, который и на Windows 2012 R2 меняет дефолтные значения на принятые в Windows 2016. Он входит в June 2016 update rollup for Windows RT 8.1, Windows 8.1, and Windows Server 2012 R2
В 2008 R2, похоже, придётся менять руками
Мораль: дефолтные значения могут быть не только неоптимальными, но и вредными.