Browse By

Problemas na interface VIP do Oracle RAC

 

Fala pessoal, blz?
Estou iniciando meu primeiro post (e espero de muitos outros..rs) sobre uma experiência que passei em um ambiente que tirou um certo tempo na analise e que no final, foi mais um daqueles famosos comentarios, Nao acredito que era só isso, mas infelizmente ou felizmente nao podemos nos privar de sempre fazermos essas premissas basicas como analise de logs, backups e etc do ambiente antes de tomarmos qualquer ação.

Após implantação de um Oracle RAC 10gR2 na plataforma Windows 2008 server 64 Bits em 2 nodes onde na qual passei por alguns apertos mas que se resolviam com patchs da Oracle (Irei colocar em um outro post um How to com ações tomadas/instalações e etc…),  no dia seguinte estava eu tranquilo e sussegado fazendo outras atividades com aquela sensação de  ‘Implantação feita com sucesso, que bom… rs’  onde derrepente o telefone toca….

Nem preciso comentar quem era, certo ? … O cliente havia ligado dizendo que estava aparecendo algumas mensagens de erros na aplicação as vezes e etc…
Após conectar no ambiente e iniciar as dezenas de checagens foi notado que os serviços do rac1 estavam offlines por algum motivo.

Acima, assinalei em amarelo o VIP pq inicialmente ficou somente esse serviço offline e depois de um tempo o  restante ficou tbm pois um problema foi gerando outro e ass im vai, irei colocar somente o principal problema aqui.

Vamos aos logs do Cluster :

alertora-1.log:

2010-09-23 12:43:01.794
 [crsd(1996)]CRS-1201:CRSD started on node ora-1.
 2010-09-23 12:43:03.401
 [crsd(2556)]CRS-1205:Auto-start failed for the CRS resource . Details in ora-1.
 2010-09-23 12:43:03.479
 [crsd(2556)]CRS-1205:Auto-start failed for the CRS resource . Details in ora-1.
 2010-09-23 12:43:09.516
 [crsd(2552)]CRS-1205:Auto-start failed for the CRS resource . Details in ora-1.
 2010-09-23 12:43:11.810
 [crsd(2552)]CRS-1205:Auto-start failed for the CRS resource . Details in ora-1.
 2010-09-23 12:44:25.463
 [crsd(2956)]CRS-1205:Auto-start failed for the CRS resource . Details in ora-1.
 2010-09-23 12:44:25.525
 [crsd(2212)]CRS-1205:Auto-start failed for the CRS resource . Details in ora-1.
 2010-09-23 12:44:34.653
 [crsd(2840)]CRS-1205:Auto-start failed for the CRS resource . Details in ora-1.

O log acima, um dos primeiros que prefiro analisar quando ocorre algum problema na camada do cluster, nos mostra algumas informações como falhas para iniciar os serviços, até aí nao traz informações tão detalhadas, então vamos descendo mais um nivel de logs.

crsd.log:

2010-09-23 13:09:02.924: [  CRSRES][4432]32startRunnable: setting CLI values
 2010-09-23 13:09:03.111: [  CRSRES][4432]32Attempting to start `ora.ora-1.vip` on member `ora-1`
 2010-09-23 13:09:03.626: [  CRSAPP][4432]32StartResource error for ora.ora-1.vip error code = 1
 2010-09-23 13:09:04.094: [  CRSRES][4432]32Start of `ora.ora-1.vip` on member `ora-1` failed.
 2010-09-23 13:19:04.857: [  CRSRES][4608]32startRunnable: setting CLI values
 2010-09-23 13:19:04.935: [  CRSRES][4608]32Attempting to start `ora.ora-1.vip` on member `ora-1`
 2010-09-23 13:19:05.466: [  CRSAPP][4608]32StartResource error for ora.ora-1.vip error code = 1
 2010-09-23 13:19:05.856: [  CRSRES][4608]32Start of `ora.ora-1.vip` on member `ora-1` failed.
 2010-09-23 13:23:49.457: [  CRSRES][3152]32startRunnable: setting CLI values
 2010-09-23 13:23:49.629: [  CRSRES][3152]32Attempting to start `ora.ora-1.vip` on member `ora-1`
 2010-09-23 13:23:50.144: [  CRSAPP][3152]32StartResource error for ora.ora-1.vip error code = 1
 2010-09-23 13:23:50.596: [  CRSRES][3152]32Start of `ora.ora-1.vip` on member `ora-1` failed.
 2010-09-23 13:23:50.721: [  CRSRES][3152]32CRS-1006: No more members to consider
 2010-09-23 13:29:06.954: [  CRSRES][4664]32startRunnable: setting CLI values
 2010-09-23 13:29:07.235: [  CRSRES][4664]32Attempting to start `ora.ora-1.vip` on member `ora-1`
 2010-09-23 13:29:07.734: [  CRSAPP][4664]32StartResource error for ora.ora-1.vip error code = 1
 2010-09-23 13:29:08.233: [  CRSRES][4664]32Start of `ora.ora-1.vip` on member `ora-1` failed.
 2010-09-23 13:39:09.187: [  CRSRES][3984]32startRunnable: setting CLI values
 2010-09-23 13:39:09.281: [  CRSRES][3984]32Attempting to start `ora.ora-1.vip` on member `ora-1`
 2010-09-23 13:39:09.796: [  CRSAPP][3984]32StartResource error for ora.ora-1.vip error code = 1
 2010-09-23 13:39:10.295: [  CRSRES][3984]32Start of `ora.ora-1.vip` on member `ora-1` failed.
 2010-09-23 13:49:11.304: [  CRSRES][3560]32startRunnable: setting CLI values
 2010-09-23 13:49:11.444: [  CRSRES][3560]32Attempting to start `ora.ora-1.vip` on member `ora-1`
 2010-09-23 13:49:11.959: [  CRSAPP][3560]32StartResource error for ora.ora-1.vip error code = 1
 2010-09-23 13:49:12.443: [  CRSRES][3560]32Start of `ora.ora-1.vip` on member `ora-1` failed.
 2010-09-23 13:59:13.473: [  CRSRES][2256]32startRunnable: setting CLI values
 2010-09-23 13:59:13.504: [  CRSRES][2256]32Attempting to start `ora.ora-1.vip` on member `ora-1`
 2010-09-23 13:59:14.019: [  CRSAPP][2256]32StartResource error for ora.ora-1.vip error code = 1
 2010-09-23 13:59:14.487: [  CRSRES][2256]32Start of `ora.ora-1.vip` on member `ora-1` failed.
 2010-09-23 14:09:15.434: [  CRSRES][2604]32startRunnable: setting CLI values
 2010-09-23 14:09:15.559: [  CRSRES][2604]32Attempting to start `ora.ora-1.vip` on member `ora-1`
 2010-09-23 14:09:16.058: [  CRSAPP][2604]32StartResource error for ora.ora-1.vip error code = 1
 2010-09-23 14:09:16.542: [  CRSRES][2604]32Start of `ora.ora-1.vip` on member `ora-1` failed.
 2010-09-23 14:19:17.604: [  CRSRES][4612]32startRunnable: setting CLI values
 2010-09-23 14:19:17.729: [  CRSRES][4612]32Attempting to start `ora.ora-1.vip` on member `ora-1`
 2010-09-23 14:19:18.244: [  CRSAPP][4612]32StartResource error for ora.ora-1.vip error code = 1
 2010-09-23 14:19:18.681: [  CRSRES][4612]32Start of `ora.ora-1.vip` on member `ora-1` failed.
 2010-09-23 14:29:19.788: [  CRSRES][4628]32startRunnable: setting CLI values
 2010-09-23 14:29:19.928: [  CRSRES][4628]32Attempting to start `ora.ora-1.vip` on member `ora-1`
 2010-09-23 14:29:20.443: [  CRSAPP][4628]32StartResource error for ora.ora-1.vip error code = 1
 2010-09-23 14:29:20.989: [  CRSRES][4628]32Start of `ora.ora-1.vip` on member `ora-1` failed.
 2010-09-23 14:39:22.124: [  CRSRES][3092]32startRunnable: setting CLI values
 2010-09-23 14:39:22.311: [  CRSRES][3092]32Attempting to start `ora.ora-1.vip` on member `ora-1`
 2010-09-23 14:39:22.810: [  CRSAPP][3092]32StartResource error for ora.ora-1.vip error code = 1
 2010-09-23 14:39:23.310: [  CRSRES][3092]32Start of `ora.ora-1.vip` on member `ora-1` failed.
 2010-09-23 14:49:24.264: [  CRSRES][4324]32startRunnable: setting CLI values
 2010-09-23 14:49:24.342: [  CRSRES][4324]32Attempting to start `ora.ora-1.vip` on member `ora-1`
 2010-09-23 14:49:24.857: [  CRSAPP][4324]32StartResource error for ora.ora-1.vip error code = 1
 2010-09-23 14:49:25.262: [  CRSRES][4324]32Start of `ora.ora-1.vip` on member `ora-1` failed.
 2010-09-23 14:59:26.284: [  CRSRES][4880]32startRunnable: setting CLI values
 2010-09-23 14:59:26.362: [  CRSRES][4880]32Attempting to start `ora.ora-1.vip` on member `ora-1`
 2010-09-23 14:59:26.877: [  CRSAPP][4880]32StartResource error for ora.ora-1.vip error code = 1
 2010-09-23 14:59:27.360: [  CRSRES][4880]32Start of `ora.ora-1.vip` on member `ora-1` failed.
 2010-09-23 15:09:28.268: [  CRSRES][3120]32startRunnable: setting CLI values
 2010-09-23 15:09:28.393: [  CRSRES][3120]32Attempting to start `ora.ora-1.vip` on member `ora-1`
 2010-09-23 15:09:28.908: [  CRSAPP][3120]32StartResource error for ora.ora-1.vip error code = 1
 2010-09-23 15:09:29.360: [  CRSRES][3120]32Start of `ora.ora-1.vip` on member `ora-1` failed.
 2010-09-23 15:19:30.293: [  CRSRES][3352]32startRunnable: setting CLI values
 2010-09-23 15:19:30.386: [  CRSRES][3352]32Attempting to start `ora.ora-1.vip` on member `ora-1`
 2010-09-23 15:19:30.901: [  CRSAPP][3352]32StartResource error for ora.ora-1.vip error code = 1
 2010-09-23 15:19:31.400: [  CRSRES][3352]32Start of `ora.ora-1.vip` on member `ora-1` failed.
 2010-09-23 15:29:32.521: [  CRSRES][4580]32startRunnable: setting CLI values
 2010-09-23 15:29:32.631: [  CRSRES][4580]32Attempting to start `ora.ora-1.vip` on member `ora-1`
 2010-09-23 15:29:33.145: [  CRSAPP][4580]32StartResource error for ora.ora-1.vip error code = 1
 2010-09-23 15:29:33.629: [  CRSRES][4580]32Start of `ora.ora-1.vip` on member `ora-1` failed.
 2010-09-23 15:39:34.646: [  CRSRES][2132]32startRunnable: setting CLI values
Nesse log ( Um dos mais importantes junto com o ocssd.log em minha opinião)  podemos ver que o cluster em sua arquitetura tenta diversas vezes iniciar os serviços e sem exito, vamos para o proximo log.

ora_databasename.db.log:

Oracle Database 10g CRS Release 10.2.0.4.0 Production Copyright 1996, 2008 Oracle.  All rights reserved.
 2010-09-23 12:58:29.655: [    RACG][1816] [3052][1816][ora.mercury.db]: CLSR-0519: No instance found
 2010-09-23 12:58:29.655: [    RACG][1816] [3052][1816][ora.mercury.db]: end for resource = ora.mercury.db, action = check, status = 1, time = 0.031s

O log acima mostra que a instancia não foi encontrada na checagem automática do cluster.

ora.ora-1.ons.log:

2010-09-23 12:06:35.635: [    RACG][3236] [4416][3236][ora.ora-1.ons]: ONS signaled to shutdown . . .

 

Nesse log o nosso amigo ONS (Oracle Notification Service) um dos principais serviços (no Windows e daemon no linux, unix…)  passou sua informação que na qual seria uma sinalização para o shutdown.

ora.ora-1.vip.log:

2010-09-23 12:58:30.575: [    RACG][3168] [652][3168][ora.ora-1.vip]: clsrcexecut: env ORACLE_CONFIG_HOME=D:\oracle\product\10.2.0\crs
 2010-09-23 12:58:30.575: [    RACG][3168] [652][3168][ora.ora-1.vip]: clsrcexecut: cmd = D:\oracle\product\10.2.0\crs\bin\racgeut.exe -e _USR_ORA_DEBUG=0 54 D:\oracle\product\10.2.0\crs\bin\racgvip.exe start ora-1
 2010-09-23 12:58:30.575: [    RACG][3168] [652][3168][ora.ora-1.vip]: clsrcexecut: rc = 1, time = 0.220s
 2010-09-23 12:58:30.793: [    RACG][3168] [652][3168][ora.ora-1.vip]: clsrcexecut: env ORACLE_CONFIG_HOME=D:\oracle\product\10.2.0\crs
 2010-09-23 12:58:30.793: [    RACG][3168] [652][3168][ora.ora-1.vip]: clsrcexecut: cmd = D:\oracle\product\10.2.0\crs\bin\racgeut.exe -e _USR_ORA_DEBUG=0 54 D:\oracle\product\10.2.0\crs\bin\racgvip.exe check ora-1
 2010-09-23 12:58:30.793: [    RACG][3168] [652][3168][ora.ora-1.vip]: clsrcexecut: rc = 1, time = 0.217s
 2010-09-23 12:58:30.793: [    RACG][3168] [652][3168][ora.ora-1.vip]: end for resource = ora.ora-1.vip, action = start, status = 1, time = 0.624s
 2010-09-23 12:59:03.255: [    RACG][4772] [4768][4772][ora.ora-1.vip]: IP Address in use failed
 2010-09-23 12:59:03.255: [    RACG][4772] [4768][4772][ora.ora-1.vip]: clsrcexecut: env ORACLE_CONFIG_HOME=D:\oracle\product\10.2.0\crs
 2010-09-23 12:59:03.255: [    RACG][4772] [4768][4772][ora.ora-1.vip]: clsrcexecut: cmd = D:\oracle\product\10.2.0\crs\bin\racgeut.exe -e _USR_ORA_DEBUG=0 54 D:\oracle\product\10.2.0\crs\bin\racgvip.exe start ora-1
 2010-09-23 12:59:03.255: [    RACG][4772] [4768][4772][ora.ora-1.vip]: clsrcexecut: rc = 1, time = 0.222s
 2010-09-23 12:59:03.473: [    RACG][4772] [4768][4772][ora.ora-1.vip]: clsrcexecut: env ORACLE_CONFIG_HOME=D:\oracle\product\10.2.0\crs
 2010-09-23 12:59:03.473: [    RACG][4772] [4768][4772][ora.ora-1.vip]: clsrcexecut: cmd = D:\oracle\product\10.2.0\crs\bin\racgeut.exe -e _USR_ORA_DEBUG=0 54 D:\oracle\product\10.2.0\crs\bin\racgvip.exe check ora-1
 2010-09-23 12:59:03.473: [    RACG][4772] [4768][4772][ora.ora-1.vip]: clsrcexecut: rc = 1, time = 0.217s
 2010-09-23 12:59:03.473: [    RACG][4772] [4768][4772][ora.ora-1.vip]: end for resource = ora.ora-1.vip, action = start, status = 1, time = 0.467s
 2010-09-23 13:09:03.408: [    RACG][4604] [4824][4604][ora.ora-1.vip]: IP Address in use failed
 2010-09-23 13:09:03.408: [    RACG][4604] [4824][4604][ora.ora-1.vip]: clsrcexecut: env ORACLE_CONFIG_HOME=D:\oracle\product\10.2.0\crs
 2010-09-23 13:09:03.408: [    RACG][4604] [4824][4604][ora.ora-1.vip]: clsrcexecut: cmd = D:\oracle\product\10.2.0\crs\bin\racgeut.exe -e _USR_ORA_DEBUG=0 54 D:\oracle\product\10.2.0\crs\bin\racgvip.exe start ora-1
 2010-09-23 13:09:03.408: [    RACG][4604] [4824][4604][ora.ora-1.vip]: clsrcexecut: rc = 1, time = 0.227s
 2010-09-23 13:09:03.626: [    RACG][4604] [4824][4604][ora.ora-1.vip]: clsrcexecut: env ORACLE_CONFIG_HOME=D:\oracle\product\10.2.0\crs
 2010-09-23 13:09:03.626: [    RACG][4604] [4824][4604][ora.ora-1.vip]: clsrcexecut: cmd = D:\oracle\product\10.2.0\crs\bin\racgeut.exe -e _USR_ORA_DEBUG=0 54 D:\oracle\product\10.2.0\crs\bin\racgvip.exe check ora-1
 2010-09-23 13:09:03.626: [    RACG][4604] [4824][4604][ora.ora-1.vip]: clsrcexecut: rc = 1, time = 0.217s
 2010-09-23 13:09:03.626: [    RACG][4604] [4824][4604][ora.ora-1.vip]: end for resource = ora.ora-1.vip, action = start, status = 1, time = 0.473s
 2010-09-23 13:19:05.247: [    RACG][4200] [4988][4200][ora.ora-1.vip]: IP Address in use failed
 2010-09-23 13:19:05.247: [    RACG][4200] [4988][4200][ora.ora-1.vip]: clsrcexecut: env ORACLE_CONFIG_HOME=D:\oracle\product\10.2.0\crs
 2010-09-23 13:19:05.247: [    RACG][4200] [4988][4200][ora.ora-1.vip]: clsrcexecut: cmd = D:\oracle\product\10.2.0\crs\bin\racgeut.exe -e _USR_ORA_DEBUG=0 54 D:\oracle\product\10.2.0\crs\bin\racgvip.exe start ora-1
 2010-09-23 13:19:05.247: [    RACG][4200] [4988][4200][ora.ora-1.vip]: clsrcexecut: rc = 1, time = 0.225s
 2010-09-23 13:19:05.466: [    RACG][4200] [4988][4200][ora.ora-1.vip]: clsrcexecut: env ORACLE_CONFIG_HOME=D:\oracle\product\10.2.0\crs
 2010-09-23 13:19:05.466: [    RACG][4200] [4988][4200][ora.ora-1.vip]: clsrcexecut: cmd = D:\oracle\product\10.2.0\crs\bin\racgeut.exe -e _USR_ORA_DEBUG=0 54 D:\oracle\product\10.2.0\crs\bin\racgvip.exe check ora-1
 2010-09-23 13:19:05.466: [    RACG][4200] [4988][4200][ora.ora-1.vip]: clsrcexecut: rc = 1, time = 0.216s
 2010-09-23 13:19:05.466: [    RACG][4200] [4988][4200][ora.ora-1.vip]: end for resource = ora.ora-1.vip, action = start, status = 1, time = 0.468s
 2010-09-23 13:23:49.925: [    RACG][2548] [3692][2548][ora.ora-1.vip]: IP Address in use failed
 2010-09-23 13:23:49.925: [    RACG][2548] [3692][2548][ora.ora-1.vip]: clsrcexecut: env ORACLE_CONFIG_HOME=D:\oracle\product\10.2.0\crs
 2010-09-23 13:23:49.925: [    RACG][2548] [3692][2548][ora.ora-1.vip]: clsrcexecut: cmd = D:\oracle\product\10.2.0\crs\bin\racgeut.exe -e _USR_ORA_DEBUG=0 54 D:\oracle\product\10.2.0

O log acima do VIP mostra muito mais informações que ja deram uma sinalização a mais do que seria.

    No UNIX as informações mudam um pouco mas dizem o mesmo problema, segue um exemplo:

2010-09-30 10:55:12.080: [    RACG][1] [11402][1][ora.max01.vip]: Resource temporarily unavailable
 Could not open /dev/ipping: socket: Resource temporarily unavailable IP address already in use
 /usr/sbin/ifconfig lan0:802 172.30.200.71 netmask 255.255.255.0 broadcast 172.30.200.255 up failed (host=max01) Invalid para
 2010-09-30 10:55:12.098: [    RACG][1] [11402][1][ora.max01.vip]: meters, or failed to bring up VIP (host=max01)
 2010-09-30 10:55:12.098: [    RACG][1] [11402][1][ora.max01.vip]: clsrcexecut: env ORACLE_CONFIG_HOME=/u00/crs/oracle/product/10.2/crs
 2010-09-30 10:55:12.098: [    RACG][1] [11402][1][ora.max01.vip]: clsrcexecut: cmd = /u00/crs/oracle/product/10.2/crs/bin/racgeut -e _USR_ORA_DEBUG=0 54 /u00/crs/oracle/product/10.2/crs/bin/racgvip check max01
 2010-09-30 10:55:12.122: [    RACG][1] [11402][1][ora.max01.vip]: clsrcexecut: rc = 1, time = 2.982s
 2010-09-30 10:55:12.122: [    RACG][1] [11402][1][ora.max01.vip]: end for resource = ora.max01.vip, action = check, status = 1, time = 3.125s

Após essas e outras checagens, fomos a camada de rede iniciar alguns testes de comunicação.

Geralmente quando ocorre algum problema no cluster onde seus serviços no caso windows, param de funcionar, a interface do VIP do rac1 que é o nosso node com problema teria que migrar para o rac2, mas como podem ver na imagem no inicio do post o mesmo não migrou, então temos mais essa informação.

Testes de ping:

Esse ip que ‘pingamos’  seria o ip da interface do VIP do rac1 onde estranhamente esta respondendo, mas como poderia responder se a interface nao esta UP e nem migrada para segundo node ?

Pois é, iniciamos os traces pela rede entre varios testes, segue um simples comando chamado NSLOOKUP que qualquer pessoa pode executar no MS-DOS caso não tenha acesso a ferramentas de outros tipos no ambiente devido alguma hierarquia.

 

Com isso conseguimos identificar uma maquina client que obteve o ip do VIP do Rac1.
Após contactamos o administrador de rede, o mesmo efetuou as modificações tirando os ips do cluster do range do DHCP do parque e após isso reiniciamos os serviços e tudo voltou ao seu normal e como deveria ficar.

Por mais que o Oracle RAC seja um brutamonte de confiabilidade, alta disponibilidade e a melhor arquitetura de cluster em minha opinião, ele possui algumas características mais delicadas que em nosso caso foi uma maquina client que foi ligada, solicitou o mesmo ip da interface virtual onde o RAC cedeu sem maiores esforços, acarretando em alguns problemas.

Podemos ver que a comunicação entre o dba e as outras pessoas que estão no projeto precisam estar 100% em sintonia  (Por mais que seja passada todas as informações e prerequisitos) de tudo para eliminar problemas simples que não deveriam acontecer.

É isso aí, fica a dica….

Forte Abraço..

3 thoughts on “Problemas na interface VIP do Oracle RAC”

  1. Herbert says:

    da hora mano….curti mesmo….coloca mais ai que ajuda mtoooo….abraço mano

  2. André M says:

    Muito bom troubleshooting!

    Sei que poucas empresas implementam a rede privada em uma rede dedicada, separando da rede publica.

    Mas, desta forma consegue-se melhor desempenho e evita que este tipo de problema ocorra.

    Abraço.

    1. admin says:

      Fala André, blz!!!
      É muito importante mesmo ter essa separação da rede privada da publica.
      No meu caso foi problema da interface do VIP onde deve ficar na mesma subrede da rede publica mas realmente ja vimos em varios casos o pessoal criando VLAN’s, cabo cross (um absurdo) entre outras alternativas mais baratas para separar as redes fora as que encontramos na mesma subrede da publica/privada e isso influencia e muito realmente.

      Forte abraço

Leave a Reply to Herbert Cancel reply

Your email address will not be published. Required fields are marked *