19c RAC root.sh is failing in node1

Version 3
Visibility: Open to anyone

    Problem : ROOT.sh is failing in node1. 

     

    Environment

    Oracle Linux 7.6

    Grid Infrastructure 19.3.0

     

    Root.sh failing Analysis

     

    [root@racnode1 ~]# sh /u01/app/19.3.0/grid/root.sh

    Performing root user operation.

     

    The following environment variables are set as:

        ORACLE_OWNER= oracle

        ORACLE_HOME=  /u01/app/19.3.0/grid

     

    Enter the full pathname of the local bin directory: [/usr/local/bin]:

    The contents of "dbhome" have not changed. No need to overwrite.

    The contents of "oraenv" have not changed. No need to overwrite.

    The contents of "coraenv" have not changed. No need to overwrite.

     

    Entries will be added to the /etc/oratab file as needed by

    Database Configuration Assistant when a database is created

    Finished running generic part of root script.

    Now product-specific root actions will be performed.

    Relinking oracle with rac_on option

    Using configuration parameter file: /u01/app/19.3.0/grid/crs/install/crsconfig_params

    The log of current session can be found at:

      /u01/app/oracle/crsdata/racnode1/crsconfig/rootcrs_racnode1_2019-07-19_05-56-05PM.log

    2019/07/19 17:56:15 CLSRSC-594: Executing installation step 1 of 19: 'SetupTFA'.

    2019/07/19 17:56:15 CLSRSC-594: Executing installation step 2 of 19: 'ValidateEnv'.

    2019/07/19 17:56:15 CLSRSC-363: User ignored prerequisites during installation

    2019/07/19 17:56:15 CLSRSC-594: Executing installation step 3 of 19: 'CheckFirstNode'.

    2019/07/19 17:56:18 CLSRSC-594: Executing installation step 4 of 19: 'GenSiteGUIDs'.

    2019/07/19 17:56:19 CLSRSC-594: Executing installation step 5 of 19: 'SetupOSD'.

    2019/07/19 17:56:19 CLSRSC-594: Executing installation step 6 of 19: 'CheckCRSConfig'.

    2019/07/19 17:56:20 CLSRSC-594: Executing installation step 7 of 19: 'SetupLocalGPNP'.

    2019/07/19 17:57:00 CLSRSC-594: Executing installation step 8 of 19: 'CreateRootCert'.

    2019/07/19 17:57:01 CLSRSC-4002: Successfully installed Oracle Trace File Analyzer (TFA) Collector.

    2019/07/19 17:57:06 CLSRSC-594: Executing installation step 9 of 19: 'ConfigOLR'.

    2019/07/19 17:57:20 CLSRSC-594: Executing installation step 10 of 19: 'ConfigCHMOS'.

    2019/07/19 17:57:20 CLSRSC-594: Executing installation step 11 of 19: 'CreateOHASD'.

    2019/07/19 17:57:26 CLSRSC-594: Executing installation step 12 of 19: 'ConfigOHASD'.

    2019/07/19 17:57:26 CLSRSC-330: Adding Clusterware entries to file 'oracle-ohasd.service'

    2019/07/19 17:57:51 CLSRSC-594: Executing installation step 13 of 19: 'InstallAFD'.

    2019/07/19 17:57:56 CLSRSC-594: Executing installation step 14 of 19: 'InstallACFS'.

    2019/07/19 17:58:02 CLSRSC-594: Executing installation step 15 of 19: 'InstallKA'.

    2019/07/19 17:58:08 CLSRSC-594: Executing installation step 16 of 19: 'InitConfig'.

     

    ASM has been created and started successfully.

     

    [DBT-30001] Disk groups created successfully. Check /u01/app/oracle/cfgtoollogs/asmca/asmca-190719PM055843.log for details.

     

    2019/07/19 17:59:39 CLSRSC-482: Running command: '/u01/app/19.3.0/grid/bin/ocrconfig -upgrade oracle oinstall'

    CRS-4256: Updating the profile

    Successful addition of voting disk d54660a2e05d4fbebfd3581559b0e038.

    Successfully replaced voting disk group with +OVDATA.

    CRS-4256: Updating the profile

    CRS-4266: Voting file(s) successfully replaced

    ##  STATE    File Universal Id File Name Disk group

    --  ----- ----------------- --------- ---------

    1. ONLINE   d54660a2e05d4fbebfd3581559b0e038 (/dev/sdb1) [OVDATA]

    Located 1 voting disk(s).

    2019/07/19 18:01:17 CLSRSC-594: Executing installation step 17 of 19: 'StartCluster'.

    2019/07/19 18:02:56 CLSRSC-343: Successfully started Oracle Clusterware stack

    2019/07/19 18:02:56 CLSRSC-594: Executing installation step 18 of 19: 'ConfigNode'. <<<<==========================

    QoS Management Server could not be started.

     

    PRCR-1079 : Failed to start resource ora.qosmserver

     

    CRS-2674: Start of 'ora.qosmserver' on 'racnode1' failed

     

    CRS-2678: 'ora.qosmserver' on 'racnode1' has experienced an unrecoverable failure

     

    CRS-0267: Human intervention required to resume its availability.

     

    CRS-5802: Unable to start the agent process

     

    2019/07/19 18:11:16 CLSRSC-1102: failed to start resource 'qosmserver'

    2019/07/19 18:11:16 CLSRSC-287: FirstNode configuration failed

     

     

    cluster log

     

    2019-07-19 18:02:25.537 [CRSD(29815)]CRS-8500: Oracle Clusterware CRSD process is starting with operating system process ID 29815

    2019-07-19 18:02:28.168 [CRSD(29815)]CRS-1012: The OCR service started on node racnode1.

    2019-07-19 18:02:28.399 [CRSD(29815)]CRS-1201: CRSD started on node racnode1.

    2019-07-19 18:02:29.496 [CRSD(29815)]CRS-2772: Server 'racnode1' has been assigned to pool 'Free'.

    2019-07-19 18:03:50.961 [ORAROOTAGENT(31041)]CRS-8500: Oracle Clusterware ORAROOTAGENT process is starting with operating system process ID 31041

    2019-07-19 18:03:51.690 [ORAAGENT(31075)]CRS-8500: Oracle Clusterware ORAAGENT process is starting with operating system process ID 31075 <<<<<<<<<<<<<<<<<===============

    2019-07-19 18:05:13.086 [ORAAGENT(31075)]CRS-5016: Process "/u01/app/19.3.0/grid/opmn/bin/onsctli" spawned by agent "ORAAGENT" for action "check" failed: details at "(:CLSN00010:)" in "/u01/app/oracle/diag/crs/racnode1/crs/trace/crsd_oraagent_oracle.trc"

    2019-07-19 18:05:18.097 [ORAAGENT(31075)]CRS-5016: Process "/u01/app/19.3.0/grid/opmn/bin/onsctli" spawned by agent "ORAAGENT" for action "check" failed: details at "(:CLSN00010:)" in "/u01/app/oracle/diag/crs/racnode1/crs/trace/crsd_oraagent_oracle.trc"

    2019-07-19 18:05:28.069 [CRSD(29815)]CRS-2878: Failed to restart resource 'ora.ons'

    2019-07-19 18:05:28.080 [CRSD(29815)]CRS-2769: Unable to failover resource 'ora.ons'.

    2019-07-19 18:07:46.222 [CRSD(29815)]CRS-5828: Could not start agent '/u01/app/19.3.0/grid/bin/scriptagent_oracle'. Details at (:CRSAGF00130:) {1:47591:513} in /u01/app/oracle/diag/crs/racnode1/crs/trace/crsd.trc.

    2019-07-19 18:11:16.255 [CRSD(29815)]CRS-5828: Could not start agent '/u01/app/19.3.0/grid/bin/scriptagent_oracle'. Details at (:CRSAGF00130:) {1:47591:513} in /u01/app/oracle/diag/crs/racnode1/crs/trace/crsd.trc.

    2019-07-19 18:11:16.257 [CRSD(29815)]CRS-2758: Resource 'ora.qosmserver' is in an unknown state.

     

     

    crsd_oraagent_oracle.trc

     

    2019-07-19 18:05:13.037 : USRTHRD:3312244480: [     INFO] {1:47591:361} Thread:ASM DedicatedThread AsmCommonAgent::DedicatedThread::run  999 ASM Dedicated Thread } exit

    2019-07-19 18:05:13.038 : USRTHRD:3312244480: [     INFO] {1:47591:361} Thread:ASM DedicatedThread isRunning is reset to false here

    2019-07-19 18:05:13.038 : USRTHRD:3312244480: [     INFO] {1:47591:361} Thread:ASM DedicatedThread isFinished set to true

    2019-07-19 18:05:13.085 :CLSDYNAM:3342509824: [ ora.ons]{1:47591:431} [check] (:CLSN00010:)Communication error with the ONS server local port.

    2019-07-19 18:05:13.085 :CLSDYNAM:3342509824: [ ora.ons]{1:47591:431} [check] (:CLSN00010:)

    2019-07-19 18:05:13.085 :CLSDYNAM:3342509824: [ ora.ons]{1:47591:431} [check] (:CLSN00010:)Check the ONS log files

    2019-07-19 18:05:13.085 :CLSDYNAM:3342509824: [ ora.ons]{1:47591:431} [check] (:CLSN00010:)

    2019-07-19 18:05:13.085 :CLSDYNAM:3342509824: [ ora.ons]{1:47591:431} [check] (:CLSN00010:)ons is not running ...

    2019-07-19 18:05:13.085 :CLSDYNAM:3342509824: [ ora.ons]{1:47591:431} [check] (:CLSN00010:)

    2019-07-19 18:05:13.086 :CLSDYNAM:3342509824: [ ora.ons]{1:47591:431} [check] (:CLSN00010:)Utils:execCmd scls_process_join() uret 2

     

     

    [root@racnode1 ~]# cd /u01/app/19.3.0/grid/opmn/

    admin/ bin/   conf/  lib/ logs/  mesg/

    [root@racnode1 ~]# cd /u01/app/19.3.0/grid/opmn/logs/

    [root@racnode1 logs]# ls

    • ons.log.racnode1-vip  ons.out.racnode1-vip

    [root@racnode1 logs]# ls -ltr

    total 68

    -rw-r----- 1 oracle oinstall    76 Jul 19 18:04 ons.out.racnode1-vip

    -rw-r----- 1 oracle oinstall 58246 Jul 19 18:33 ons.log.racnode1-vip

     

    [root@racnode1 logs]# cat ons.out.racnode1-vip

    [2019-07-19T18:04:08+05:30] [ons] [TRACE:32] [] [internal] Server reloading

     

     

    [root@racnode1 logs]# vi ons.log.racnode1-vip

    [2019-07-19T18:04:03+05:30] [ons] [TRACE:32] [] [ons-local] Config file: /u01/app/19.3.0/grid/opmn/conf/ons.config.racnode1-vip

    [2019-07-19T18:04:03+05:30] [ons] [TRACE:32] [] [ons-local] Build: ONS_19.0.0.0.0_LINUX.X64_181205.1445 2018/12/6 0:16:24 UTC

    [2019-07-19T18:04:03+05:30] [ons] [TRACE:32] [] [ons-local] Host: racnode1-vip (192.168.56.14); Local Port: 6100; Remote Port: 6200; Pid: 31317

    [2019-07-19T18:04:03+05:30] [ons] [NOTIFICATION:1] [90] [ons-internal] ONS server initiated

    [2019-07-19T18:04:08+05:30] [ons] [TRACE:32] [] [ons-local] Reloading by request

    [2019-07-19T18:04:08+05:30] [ons] [TRACE:32] [] [ons-local] Config file: /u01/app/19.3.0/grid/opmn/conf/ons.config.racnode1-vip

    [2019-07-19T18:04:08+05:30] [ons] [TRACE:32] [] [ons-local] Build: ONS_19.0.0.0.0_LINUX.X64_181205.1445 2018/12/6 0:16:24 UTC

    [2019-07-19T18:04:08+05:30] [ons] [TRACE:32] [] [ons-local] Host: racnode1-vip (192.168.56.14); Local Port: 6100; Remote Port: 6200; Pid: 31394

    [2019-07-19T18:04:08+05:30] [ons] [NOTIFICATION:1] [90] [ons-internal] ONS server initiated

    [2019-07-19T18:04:12+05:30] [ons] [WARNING:1] [59] [ons-connect] Local connection 5;::1;16692 missing form factor [[

    Pid=31509; Home=/u01/app/19.3.0/grid

    ]]

    [2019-07-19T18:04:16+05:30] [ons] [WARNING:1] [59] [ons-connect] Local connection 6;::1;16694 missing form factor [[

    Pid=31509; Home=/u01/app/19.3.0/grid

    ]]

    [2019-07-19T18:04:21+05:30] [ons] [WARNING:1] [59] [ons-connect] Local connection 7;::1;16696 missing form factor [[

    Pid=31509; Home=/u01/app/19.3.0/grid

    ]]

    [2019-07-19T18:04:26+05:30] [ons] [WARNING:1] [59] [ons-connect] Local connection 8;::1;16702 missing form factor [[

    Pid=31509; Home=/u01/app/19.3.0/grid

    ]]

    [2019-07-19T18:04:31+05:30] [ons] [WARNING:1] [59] [ons-connect] Local connection 9;::1;16704 missing form factor [[

    Pid=31509; Home=/u01/app/19.3.0/grid

    ]]

    [2019-07-19T18:04:36+05:30] [ons] [WARNING:1] [59] [ons-connect] Local connection a;::1;16706 missing form factor [[

    Pid=31509; Home=/u01/app/19.3.0/grid

     

    • èPFA, Trace files.

     

     

    -bash-4.2$ /u01/app/19.3.0/grid/bin/srvctl config nodeapps

    Network 1 exists

    Subnet IPv4: 192.168.56.0/255.255.255.0/enp0s8, static

    Subnet IPv6:

    Ping Targets:

    Network is enabled

    Network is individually enabled on nodes:

    Network is individually disabled on nodes:

    VIP exists: network number 1, hosting node racnode1

    VIP Name: racnode1-vip

    VIP IPv4 Address: 192.168.56.14

    VIP IPv6 Address:

    VIP is enabled.

    VIP is individually enabled on nodes:

    VIP is individually disabled on nodes:

    ONS exists: Local port 6100, remote port 6200, EM port 2016, Uses SSL true

    ONS is enabled

    ONS is individually enabled on nodes:

    ONS is individually disabled on nodes:

     

     

    -bash-4.2$ /u01/app/19.3.0/grid/bin/crsctl stat res -t

    --------------------------------------------------------------------------------

    Name Target  State        Server State details

    --------------------------------------------------------------------------------

    Local Resources

    --------------------------------------------------------------------------------

    • ora.chad

    OFFLINE OFFLINE racnode1 STABLE

    • ora.net1.network

    ONLINE  ONLINE racnode1 STABLE

    • ora.ons

    ONLINE  OFFLINE racnode1 STABLE

    --------------------------------------------------------------------------------

    Cluster Resources

    --------------------------------------------------------------------------------

    • ora.ASMNET1LSNR_ASM.lsnr(ora.asmgroup)

    1        ONLINE ONLINE racnode1 STABLE

    2        OFFLINE OFFLINE STABLE

    3        OFFLINE OFFLINE STABLE

    • ora.LISTENER_SCAN1.lsnr

    1        ONLINE ONLINE racnode1 STABLE

    • ora.OVDATA.dg(ora.asmgroup)

    1        ONLINE ONLINE racnode1 STABLE

    2        OFFLINE OFFLINE STABLE

    3        OFFLINE OFFLINE STABLE

    • ora.asm(ora.asmgroup)

    1        ONLINE ONLINE       racnode1 Started,STABLE

    2        OFFLINE OFFLINE STABLE

    3        OFFLINE OFFLINE STABLE

    • ora.asmnet1.asmnetwork(ora.asmgroup)

    1        ONLINE ONLINE racnode1 STABLE

    2        OFFLINE OFFLINE STABLE

    3        OFFLINE OFFLINE STABLE

    • ora.cvu

    1        OFFLINE OFFLINE STABLE

    • ora.qosmserver

    1        ONLINE UNKNOWN racnode1 STABLE

    • ora.racnode1.vip

    1        ONLINE  INTERMEDIATE racnode1 FAILED OVER,STABLE

    • ora.scan1.vip

    1        ONLINE ONLINE racnode1 STABLE

    --------------------------------------------------------------------------------

     

     

    --------------------------------------------------------------------------------

    -bash-4.2$ /u01/app/19.3.0/grid/bin/crsctl stat res -t -init

    --------------------------------------------------------------------------------

    Name Target  State Server State details

    --------------------------------------------------------------------------------

    Cluster Resources

    --------------------------------------------------------------------------------

    • ora.asm

    1        ONLINE ONLINE racnode1 Started,STABLE

    • ora.cluster_interconnect.haip

    1        ONLINE ONLINE racnode1 STABLE

    • ora.crf

    1        ONLINE ONLINE racnode1 STABLE

    • ora.crsd

    1        ONLINE ONLINE racnode1 STABLE

    • ora.cssd

    1        ONLINE ONLINE racnode1 STABLE

    • ora.cssdmonitor

    1        ONLINE ONLINE racnode1 STABLE

    • ora.ctssd

    1        ONLINE ONLINE racnode1 OBSERVER,STABLE

    • ora.diskmon

    1        OFFLINE OFFLINE STABLE

    • ora.evmd

    1        ONLINE ONLINE racnode1 STABLE

    • ora.gipcd

    1        ONLINE ONLINE racnode1 STABLE

    • ora.gpnpd

    1        ONLINE ONLINE racnode1 STABLE

    • ora.mdnsd

    1        ONLINE ONLINE       racnode1 STABLE

    • ora.storage

    1        ONLINE ONLINE racnode1 STABLE

    --------------------------------------------------------------------------------

     

     

    [root@racnode1 logs]# cat /etc/hosts

    1. 127.0.0.1   localhost localhost.localdomain localhost4 localhost4.localdomain4

    ::1 localhost localhost.localdomain localhost6 localhost6.localdomain6

    1. 192.168.56.11 racnode1
    2. 192.168.56.12 racnode2

     

    1. 192.168.56.14 racnode1-vip
    2. 192.168.56.15 racnode2-vip

     

    1. 192.168.1.101 racnode1-priv
    2. 192.168.1.102 racnode2-priv

     

    1. 192.168.56.16 racscan

    [root@racnode1 logs]#

    [root@racnode1 logs]# cat /etc/networks

    default 0.0.0.0

    loopback 127.0.0.0

    link-local 169.254.0.0

    hostname=racnode1

    [root@racnode1 logs]#

    [root@racnode1 logs]# ifconfig -a

    enp0s3: flags=4163<UP,BROADCAST,RUNNING,MULTICAST>  mtu 1500

            ether 08:00:27:ef:57:da  txqueuelen 1000  (Ethernet)

            RX packets 0  bytes 0 (0.0 B)

            RX errors 0 dropped 0  overruns 0  frame 0

            TX packets 0  bytes 0 (0.0 B)

            TX errors 0 dropped 0 overruns 0  carrier 0  collisions 0

     

    enp0s8: flags=4163<UP,BROADCAST,RUNNING,MULTICAST>  mtu 1500

            inet 192.168.56.11  netmask 255.255.255.0  broadcast 192.168.56.255

            inet6 fe80::1437:e5f5:68a8:476c  prefixlen 64  scopeid 0x20<link>

            inet6 fe80::7a4f:f2e:ab6:c9cb  prefixlen 64  scopeid 0x20<link>

            ether 08:00:27:43:f2:9e  txqueuelen 1000  (Ethernet)

            RX packets 266155  bytes 21707659 (20.7 MiB)

            RX errors 0 dropped 0  overruns 0  frame 0

            TX packets 4818891  bytes 7643648799 (7.1 GiB)

            TX errors 0 dropped 0 overruns 0  carrier 0  collisions 0

     

    enp0s8:1: flags=4163<UP,BROADCAST,RUNNING,MULTICAST>  mtu 1500

            inet 192.168.56.14  netmask 255.255.255.0  broadcast 192.168.56.255

            ether 08:00:27:43:f2:9e  txqueuelen 1000  (Ethernet)

     

    enp0s8:2: flags=4163<UP,BROADCAST,RUNNING,MULTICAST>  mtu 1500

            inet 192.168.56.16  netmask 255.255.255.0  broadcast 192.168.56.255

            ether 08:00:27:43:f2:9e  txqueuelen 1000  (Ethernet)

     

    enp0s9: flags=4163<UP,BROADCAST,RUNNING,MULTICAST>  mtu 1500

            inet 192.168.1.101  netmask 255.255.255.0  broadcast 192.168.1.255

            inet6 fe80::74f0:ac0a:cbf2:f42  prefixlen 64  scopeid 0x20<link>

            inet6 fe80::8bb:d784:75e1:f27  prefixlen 64  scopeid 0x20<link>

            ether 08:00:27:09:07:cd  txqueuelen 1000  (Ethernet)

            RX packets 228  bytes 37444 (36.5 KiB)

            RX errors 0 dropped 0  overruns 0  frame 0

            TX packets 427  bytes 80058 (78.1 KiB)

            TX errors 0 dropped 0 overruns 0  carrier 0  collisions 0

     

    enp0s9:1: flags=4163<UP,BROADCAST,RUNNING,MULTICAST>  mtu 1500

            inet 169.254.3.96  netmask 255.255.224.0  broadcast 169.254.31.255

            ether 08:00:27:09:07:cd  txqueuelen 1000  (Ethernet)

     

    lo: flags=73<UP,LOOPBACK,RUNNING>  mtu 65536

            inet 127.0.0.1  netmask 255.0.0.0

            inet6 ::1 prefixlen 128  scopeid 0x10<host>

            loop txqueuelen 1000  (Local Loopback)

            RX packets 27745  bytes 139695024 (133.2 MiB)

            RX errors 0 dropped 0  overruns 0  frame 0

            TX packets 27745  bytes 139695024 (133.2 MiB)

            TX errors 0 dropped 0 overruns 0  carrier 0  collisions 0

     

    [root@racnode1 logs]# netstat -nr

    Kernel IP routing table

    Destination Gateway Genmask         Flags   MSS Window  irtt Iface

    1. 0.0.0.0 192.168.56.1 0.0.0.0 UG        0 0          0 enp0s8
    2. 169.254.0.0 0.0.0.0 255.255.224.0   U         0 0          0 enp0s9
    3. 192.168.1.0 0.0.0.0 255.255.255.0   U         0 0          0 enp0s9
    4. 192.168.56.0 0.0.0.0 255.255.255.0   U         0 0          0 enp0s8


    Workaround

     

    Workaround was to configure the hostname propertly in OL7 with hostnamectl command.

     

    hostnamectl command provides a proper API used to control Linux system hostname and change its related settings.

     

    Syntax:

    hostnamectl [OPTIONS...] COMMAND ....

    Where COMMAND can be any of the following:

    • status: Used to check current hostname settings.
    • set-hostname NAME: Used to set system hostname.

     

    Author:

    Hitesh Gondalia

    CloudDB