Por Alessandro Goncalvez

Acabei de trabalhar em um incidente muito interessante em vários sentidos. Especialmente em relação que temos que olhar todos os aspectos e logs para encontrarmos a razão para certos comportamentos e não nos fixarmos tão profundamente na primeira impressão que temos.

Mas chega de conversa e vamos falar do incidente.

Cluster Exchange 2003 ( 3x1 ) , onde os 3 nós apresentavam a mesma falha logo após um unexpected shutdown , o recurso de System Attendant não incia com erro de timeout. Após aumentar o diagnostic logging de MSExchangeSA e MSExchangeMU apenas recebemos um erro :

1043 MSExchagneMU Error code is error 80070015 (The device is not ready.)

Com esse evento fixo na memória , e apresentando em todos os nós do cluster ao mesmo tempo rapidamente procurei por artigos relacionados a esse evento em específico com o mesmo código de erro , mas infelizmente o resultado foi pouco produtivo .

Pesquisei por esse evento e revi quase todos os artigos de suporte , mas nenhum resolvia esse evento específico.

Portanto , passei a me concentrar no ponto que temos mais informações , cluster log...

Ao verificar o cluster log achei o seguinte trecho ao iniciar o recurso:

 

000008dc.00000c98::2008/10/16-22:43:26.071 INFO [FM] FmpRmCreateResource: creating resource 43bc0450-9b47-4593-b1a2-0a76e491f02d in shared resource monitor

00000bd0.00000be8::2008/10/16-22:43:26.071 ERR Generic Service <Service Registry>: Service 'Another Service' is controlled by another resource. Error: 5010.

00000bd0.00000be8::2008/10/16-22:43:26.071 WARN [RM] RmpInsertResourceList failed, returned 5010

00000bd0.00000be8::2008/10/16-22:43:26.071 ERR [RM] Failed creating resource 43bc0450-9b47-4593-b1a2-0a76e491f02d, error 5010.

000008dc.00000c98::2008/10/16-22:43:26.071 INFO [FM] FmpRmCreateResource: unable to create resource 43bc0450-9b47-4593-b1a2-0a76e491f02d

00000bd0.00000af4::2008/10/16-22:44:10.235 INFO Microsoft Exchange System Attendant <EVS1 - Exchange System Attendant>: [EXRES] Reporting state 129 (OnlinePending).

00000bd0.00000af4::2008/10/16-22:45:39.651 INFO Microsoft Exchange System Attendant <EVS1 - Exchange System Attendant>: [EXRES] Reporting state 129 (OnlinePending).

...

00000bd0.00000af4::2008/10/16-22:47:09.278 ERR Microsoft Exchange System Attendant <EVS1 - Exchange System Attendant>: [EXRES] EventLogging: EVS1 - Exchange System Attendant: Failed to bring this resource online because of timeout. Error Code: 1460.

00000bd0.00000af4::2008/10/16-22:47:09.278 INFO Microsoft Exchange System Attendant <EVS1 - Exchange System Attendant>: [EXRES] Reporting state 4 (Failed).

00000bd0.00000af4::2008/10/16-22:47:09.278 INFO [RM] RmpSetResourceStatus, Posting state 4 notification for resource <EVS1 - Exchange System Attendant>

00000bd0.00000af4::2008/10/16-22:47:09.278 INFO Microsoft Exchange System Attendant <EVS1 - Exchange System Attendant>: [EXRES] State change: from 129 (OnlinePending) to 4 (Failed).

...

000008dc.00000998::2008/10/16-22:47:09.278 INFO [CP] CppResourceNotify for resource EVS1 - Exchange System Attendant

00000bd0.00000af4::2008/10/16-22:47:09.278 ERR Microsoft Exchange System Attendant <EVS1 - Exchange System Attendant>: [EXRES] EventLogging: EVS1 - Exchange System Attendant: Failed to bring the resource online. Error Code: 1460.

00000bd0.00000af4::2008/10/16-22:47:09.278 INFO Microsoft Exchange System Attendant <EVS1 - Exchange System Attendant>: [EXRES] Thread exited: DwOnlinePrimaryThread. Returning error 1460.

00000bd0.00000af4::2008/10/16-22:47:09.278 INFO Microsoft Exchange System Attendant <EVS1 - Exchange System Attendant>: [EXRES] DwResourceThread::decrement:: g_lThreadCount=1.

000008dc.00000998::2008/10/16-22:47:09.278 INFO [FM] FmpRmDoHandleCriticalResourceStateChange: call InterlockedDecrement on gdwQuoBlockingResources, Resource db7cbd8a-255a-4ff1-9ef4-a469112004d9

00000bd0.00000af4::2008/10/16-22:47:09.278 INFO Microsoft Exchange System Attendant <EVS1 - Exchange System Attendant>: [EXRES] EXCHANGE_RESOURCE::Release: Count=2.

 

O cluster log mostra o recurso de SA falhando com error code 1460 - ERROR_TIMEOUT.

Todavia isso não nos dá muita explicação do que está realmente acontecendo , apenas que o serviço não está respondendo em tempo hábil. Ainda temos que descobrir porque o serviço não inicia.

Ao olhar com mais atenção , antes de o cluster iniciar o recurso de MSExchangeSA temos uma falha de um recurso que está em modo compartilhado no resource monitor.

 

000008dc.00000c98::2008/10/16-22:43:26.071 INFO [FM] FmpRmCreateResource: creating resource 43bc0450-9b47-4593-b1a2-0a76e491f02d in shared resource monitor

00000bd0.00000be8::2008/10/16-22:43:26.071 ERR Generic Service <Service Registry>: Service 'Another Service' is controlled by another resource. Error: 5010.

 

O erro 5010 é traduzido para ERROR_OBJECT_ALREADY_EXISTS !?

O interessante é que essa falha acontece logo antes da tentativa de início do MSExchangeSA..

Um ponto importante é obeservar as secções do cluster log para termos uma visão geral do que acontece antes e depois de certos eventos. Um dos pontos de interesse é o mecanismo de Shared Locks e gdwQuoBlockingResources , que aponta recursos executando ações de "lock" no quorum. Mais informações sobre esse tema e outras técnicas de troubleshooting podem ser encontradas nesse link.

Observem que temos essa função chamando um decremento no mecanismo de locking dos recursos do quorum , o que também explica o porque dos recursos não conseguirem fazer failover , pois existam shared locks para o quorum e é necessário acesso ao quorum para fazer a operação de failover.

 

000008dc.00000998::2008/10/16-22:47:09.278 INFO [FM] FmpRmDoHandleCriticalResourceStateChange: call InterlockedDecrement on gdwQuoBlockingResources, Resource db7cbd8a-255a-4ff1-9ef4-a469112004d9

 

Mas isso nos dá uma pista do que pode estar causando isso , ao observar a seção entre InterlockedIncrement / InterlockedDecrement , pois nos mostra todos os recursos envolvidos.

Nessa seção logo antes da tentativa de início do MSExchangeSA temos uma falha na criação de um recurso , e mencionando que o recurso era controlado por outro recurso:

 

00000bd0.00000be8::2008/10/16-22:43:26.071 ERR Generic Service <Service Registry>: Service 'Another Service' is controlled by another resource. Error: 5010.

00000bd0.00000be8::2008/10/16-22:43:26.071 WARN [RM] RmpInsertResourceList failed, returned 5010

 

Isso me indicou o que faltava para inciar o recurso. Nesse caso decidimos por remover todos os recursos de cluster relacionados com Generic Service <Service Registry>: , após feito isso , o recurso de MSExchangeSA e outros entraram online normalmente.

Isso nos mostra que devemos sempre ter a mente aberta e procurar o máximo de informação possível para resolver um problema.

 

Obrigado e até a próxima