Falha ao Iniciar o Serviço de Cluster

Por: Yuri Diógenes

1. Introdução

A duas semanas atrás trabalhei em um caso de Cluster que a princípio parecia apontar para tudo, menos para o que foi a resolução final. Este artigo apesar de ser bem específico para um determinado cenário ele traz uma visão sobre dois assuntos que muitas empresas tem alta visibilidade: Segurança e Alta Disponibilidade.

2. Cenário

Neste caso o cliente tinha dois nós de cluster, tudo funcionava muito bem em ambos, o cliente em particular não recordava qual tinha sido a última mudança realizada para que isso ocorresse. O fato é que ao reiniciar um dos nós do cluster o serviço de cluster (clussvc.exe) não iniciava. A seqüência de erros era a seguinte:

Event Type: Error

Event Source: ClusSvc

Event Category: Startup/Shutdown

Event ID: 1009

Date: 10/4/2006

Time: 5:12:43 AM

User: N/A

Computer: CNODE1

Description:

Cluster service could not join an existing server cluster and could not form a new server cluster. Cluster service has terminated.

Event Type: Error

Event Source: Service Control Manager

Event Category: None

Event ID: 7034

Date: 10/4/2006

Time: 5:12:51 AM

User: N/A

Computer: CNODE1

Description:

The Cluster Service service terminated unexpectedly. It has done this 1 time(s).

Conforme podemos verificar o nó CNODE1 falhou primeiramente ao tentar juntar-se ao cluster. E logo em seguida houve a parada do serviço.

Primeira coisa a fazer neste caso é entender o que houve na perspectiva deste nó (CNODE1) para ele não conseguir fazer o “join” no cluster. Para isso revisei o arquivo de log do cluster e nele pude observar as seguintes entradas:

Primeira Parte – Falha no Join

2006/10/03-08:31:50.878 INFO [CS] Service Domain Account = CTEST\usrcluster

2006/10/03-08:31:50.878 INFO [CS] Initializing RPC server.

2006/10/03-08:31:50.888 INFO [INIT] CspRegisterDynamicLRPCEndpoint: Successfully registered LRPC endpoint with EP mapper

2006/10/03-08:31:51.028 INFO [INIT] Attempting to join cluster VPCCLUSTER

2006/10/03-08:31:51.078 INFO [JOIN] Spawning thread to connect to sponsor 10.0.0.2

2006/10/03-08:31:51.078 INFO [JOIN] Spawning thread to connect to sponsor 192.168.0.2

2006/10/03-08:31:51.078 INFO [JOIN] Spawning thread to connect to sponsor CNODE2

2006/10/03-08:31:51.078 INFO [JOIN] Spawning thread to connect to sponsor 192.168.0.219

006/10/03-08:31:51.078 INFO [JOIN] Asking 10.0.0.2 to sponsor us after delay of 0 milliseconds.

2006/10/03-08:31:52.079 INFO [JOIN] Asking 192.168.0.2 to sponsor us after delay of 1000 milliseconds.

2006/10/03-08:31:52.079 INFO [JOIN] Asking CNODE2 to sponsor us after delay of 1000 milliseconds.

2006/10/03-08:31:53.081 INFO [JOIN] Asking 192.168.0.219 to sponsor us after delay of 2000 milliseconds.

2006/10/03-21:32:25.850 INFO [JOIN] Sponsor 192.168.0.219 is not available (JoinVersion), status=1722.

2006/10/03-21:32:25.850 WARN [JOIN] JoinVersion data for sponsor 192.168.0.219 is invalid, status 1722.

006/10/03-21:32:54.674 WARN [JOIN] Unable to resolve JoinVersion endpoint for sponsor 10.0.0.2, status 1726.

006/10/03-21:32:54.674 WARN [JOIN] JoinVersion data for sponsor 10.0.0.2 is invalid, status 1726.

2006/10/03-21:32:55.673 WARN [JOIN] Unable to resolve JoinVersion endpoint for sponsor 192.168.0.2, status 1726.

2006/10/03-21:32:55.673 WARN [JOIN] JoinVersion data for sponsor 192.168.0.2 is invalid, status 1726.

2006/10/03-21:32:55.673 WARN [JOIN] Unable to resolve JoinVersion endpoint for sponsor CNODE2, status 1726.

2006/10/03-21:32:55.673 WARN [JOIN] JoinVersion data for sponsor CNODE2 is invalid, status 1726.

2006/10/03-21:32:55.673 INFO [JOIN] Got out of the join wait, CsJoinThreadCount = 1.

2006/10/03-21:32:55.673 ERR [JOIN] Unable to connect to any sponsor node.

2006/10/03-21:32:55.673 WARN [INIT] Failed to join cluster, status 53

Como você pode ver no log, toda a seqüência inicial está funcionando corretamente, mas podemos observar que logo ao tentar localizar o outro nó temos o erro 1722 (RPC UNAVAILABLE), em seguida temos os o erro 53 mostrando que houve a falha ao juntar-se com o cluster.

Bem, até aí tudo bem, porém o serviço do cluster para no momento em que o nó tenta formar um cluster por conta própria (isso é normal, pois como ele não conseguiu se juntar ao outro nó ele pensa que o outro nó está desligado) e não consegue subir os recursos de disco devido aos recursos já estarem alocados para o outro nó. Vejamos isso no log de cluster:

Segunda Parte – A falha

2006/10/03-21:33:29.337 INFO Physical Disk <Disk R:>: [DiskArb] Successful read (sector 12) [CNODE2:1028] (0,a65431a0:01c6e6c2).

2006/10/03-21:33:29.337 INFO Physical Disk <Disk R:>: [DiskArb] No reservation found. Read'n'wait.

2006/10/03-21:33:36.539 INFO Physical Disk <Disk R:>: [DiskArb] Successful read (sector 12) [CNODE2:1032] (0,a65431a0:01c6e6c2).

2006/10/03-21:33:36.539 INFO Physical Disk <Disk R:>: [DiskArb] Arbitrate returned status 5034.

2006/10/03-21:33:36.539 INFO [MM] MmSetQuorumOwner(0,0), old owner 1.

2006/10/03-21:33:36.539 ERR [FM] FmGetQuorumResource failed, error 5034.

2006/10/03-21:33:36.539 ERR [INIT] ClusterForm: Could not get quorum resource. No fixup attempted. Status = 5086

2006/10/03-21:33:36.539 INFO [INIT] Cleaning up failed form attempt.

2006/10/03-21:33:36.539 ERR [INIT] Failed to form cluster, status 5086.

2006/10/03-21:33:36.539 ERR [CS] ClusterInitialize failed 5086

2006/10/03-21:33:36.539 WARN [INIT] The cluster service is shutting down.

2006/10/03-21:33:36.539 INFO [EVT] EvShutdown

2006/10/03-21:33:36.539 WARN [FM] Shutdown: Failover Manager requested to shutdown groups.

2006/10/03-21:33:36.539 INFO [FM] FmpCleanupGroups: Entry

2006/10/03-21:33:36.539 INFO [FM] FmpCleanupGroups: Exit

2006/10/03-21:33:36.539 INFO [Dm] DmShutdown

2006/10/03-21:33:36.539 INFO [DM] DmpShutdownFlusher: Entry

2006/10/03-21:33:36.539 INFO [DM] DmpShutdownFlusher: Setting event

2006/10/03-21:33:36.539 INFO [DM] DmpRegistryFlusher: got 0

2006/10/03-21:33:36.539 INFO [DM] DmpRegistryFlusher: exiting

2006/10/03-21:33:36.549 WARN [MM] MMLeave is called when rgp=NULL.

2006/10/03-21:33:36.549 ERR [CS] Service Stopped. exit code = 5086

Bem o log é maior, mas resolve pegar este trecho no final do problema pois ele mostra exatamente o que está ocorrendo para que a falha aconteça, em especial as linhas em vermelho.

Primeiramente há uma falha na arbitração do disco R: e o erro retornado é o 5034, que significa que o dono do recurso de quorum está ligado (ERROR_QUORUM_OWNER_ALIVE), com isso este nó não consegue subir este recurso. Logo em seguida temos a falha para formar o cluster com o erro 5086, que significa que o disco de quorum não foi encontrado (ERROR_QUORUM_DISK_NOT_FOUND). O Gerenciador de Falha (Failover Manager) requisita então que todos grupos sejam desligados e no fim o serviço de cluster para com o mesmo erro 5086.

Agora entendemos porque o serviço de cluster está parando durante o boot. Mas a pergunta é: porque o este nó falha ao juntar-se ao cluster?

3. A Causa Raiz

Após realizar alguns testes vi que o seguinte comportamento acontecia: caso você tentasse iniciar o serviço de cluster após a máquina iniciar por completo aí o serviço iniciava sem problemas. Ou seja, o problema só ocorria durante o boot.

Esse é um ponto importantíssimo, pois se você pensar bem, o que poderia está causando este nó não encontrar o outro nó durante o boot? Poderíamos desconfiar da rede por exemplo, pois como neste momento o acesso a rede é fundamental então com certeza esse seria um ponto a ser investigado. Mas, resolvi olhar de uma outra forma, resolvi comparar os serviços que existiam em um nó do cluster cujo o problema não ocorria e comparar com o que o problema ocorria.

Bingo!! No nó cujo problema ocorria tínhamos o Windows Firewall habilitado e isso faz total sentido, pois o que acontece durante a inicialização de um computador que tem o serviço do Windows Firewall marcado para iniciar automaticamente é o que chamamos de “Startup Protection”. Durante o período em que o sistema operacional é carregado e os serviços ainda estão iniciando o Windows Firewall para proteger o computador de ataques vindo pela rede naquele momento ele já começa a uma filtragem de pacotes, esta filtragem de pacotes mais restritiva é feita até que o serviço Windows Firewall/Internet Connection Sharing inicie por complete, mesmo que existam exceções configuradas, durante o “startup protection” não é permitido o envio destes tipos de pacotes. Para mais informações sobre o serviço Windows Firewall veja o artigo “How Windows Firewall Works”.

Devido a termos essa proteção o cluster não pode se comunicar com o outro nó durante o momento em que o serviço clussvc.exe está iniciando. Durante este início o serviço de cluster tenta comunicar-se com o controlador de domínio e com o nó que contém os recursos.

4. A Solução

A melhor forma de configurar o Windows Firewall em um cluster é através da utilização do SCW (Security Configuration Wizard), pois ele vai criar as exceções necessárias e para evitar este problema durante o boot o que será feito é configurar as ações do serviço caso ele não inicie. Essa opção pode ser encontrada na guia “Recovery”, quando se entra nas propriedades do serviço, escolhendo a opção “restart the service” vai fazer com que o serviço de cluster tente iniciar novamente e com isso seja possível fazer o “join” com o cluster.

Este procedimento é descrito com detalhes no artigo “How to Use Windows Firewall with a Server Cluster”.

Lembre-se: a solução não é desativar o Firewall, e sim configurá-lo de forma correta e para isso o uso do SCW é muito importante.