Recurso de Cluster MSExchangeSA falha - MSExchangeMU 1043 (0x80070015)
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