RAC – Clusterware Intermittently Fails to Start

While working on a new Grid Infrastructure installation on Red Hat V8.4, we had some issues testing a new cluster: The clusterware failed to come back up after a node reboot… but sometimes it worked.

We had the latest 19c software patched to 19.12 and were using ASMLib to configure the ASM disks.

When failing, the messages in the CRS alert.log stated that the clusterware was failing to find any voting disks—see the last line of the output:

2021-09-23 08:12:21.292 [OSYSMOND(28810)]CRS-8500: Oracle Clusterware OSYSMOND process is starting with operating system process ID 28810
2021-09-23 08:12:21.288 [CSSDMONITOR(28808)]CRS-8500: Oracle Clusterware CSSDMONITOR process is starting with operating system process ID 28808
2021-09-23 08:12:21.651 [CSSDAGENT(28847)]CRS-8500: Oracle Clusterware CSSDAGENT process is starting with operating system process ID 28847
2021-09-23 08:12:27.533 [OCSSD(28867)]CRS-8500: Oracle Clusterware OCSSD process is starting with operating system process ID 28867
2021-09-23 08:12:28.592 [OCSSD(28867)]CRS-1713: CSSD daemon is started in hub mode
2021-09-23 08:12:28.703 [OCSSD(28867)]CRS-1714: Unable to discover any voting files, retrying discovery in 15 seconds; Details at (:CSSNM00070:) in /racd01/app/oracle/diag/crs/l-04296-d5c/crs/trace/ocssd.trc

And in the ocssd.trc file:

2021-09-23 08:12:28.703 :   SKGFD:3462854400: ERROR: -14(asmlib /opt/oracle/extapi/64/asm/orcl/1/libasm.so version failed with 2
)
2021-09-23 08:12:28.703 :    CLSF:3462854400: Allocated CLSF context
2021-09-23 08:12:28.703 :    CSSD:3462854400: [     INFO] clssnmvDDiscThread: using discovery string ORCL:* for initial discovery
2021-09-23 08:12:28.703 :   SKGFD:3462854400: Discovery with str:ORCL:*:

2021-09-23 08:12:28.703 :   SKGFD:3462854400: UFS discovery with :ORCL:*:

2021-09-23 08:12:28.703 :   SKGFD:3462854400: Execute glob on the string /racd01/app/19.3.0.0.0/grid/dbs/ORCL:*

2021-09-23 08:12:28.703 :   SKGFD:3462854400: OSS discovery with :ORCL:*:

2021-09-23 08:12:28.703 :   SKGFD:3462854400: Discovery skipping bad asmlib :ASM::

2021-09-23 08:12:28.703 :    CSSD:3462854400: [     INFO] clssnmvDiskVerify: Successful discovery of 0 disks
2021-09-23 08:12:28.703 :    CSSD:3462854400: [     INFO] clssnmCompleteInitVFDiscovery: Completing initial voting file discovery
2021-09-23 08:12:28.703 :    CSSD:3462854400: [     INFO] clssnmvFindInitialConfigs: No voting files found
2021-09-23 08:12:28.703 :    CSSD:3462854400: [     INFO] (:CSSNM00070:)clssnmCompleteInitVFDiscovery: Voting file not found. Retrying discovery in 15 seconds

Note at line 1, the ‘libasm.so version failed with 2’.

We checked the disks using the discovery tool:

$ /usr/sbin/oracleasm-discover
Using ASMLib from /opt/oracle/extapi/64/asm/orcl/1/libasm.so
asm_version() failed with code 2

It gave the same error! We traced the discovery—strace /usr/sbin/oracleasm-discover—which shows clearly that we have no permissions:

write(1, "Using ASMLib from /opt/oracle/ex"..., 61) = 61
openat(AT_FDCWD, "/dev/oracleasm/.query_version", O_RDWR) = -1 EACCES (Permission denied)
openat(AT_FDCWD, "/dev/oracleasm/iid", O_RDONLY) = -1 EACCES (Permission denied)
write(2, "asm_version() failed with code 2"..., 33) = 33
exit_group(2)                           = ?
+++ exited with 2 +++

We checked the disks and indeed found that they have the wrong userid and group:

$ ls -lasi
total 0
18446638755664080616 0 drwxr-xr-x.  4 root root    0 Sep 23 06:50 .
                   3 0 drwxr-xr-x. 23 root root 5260 Sep 23 06:51 ..
18446638755664098920 0 -rwxrwx---.  1 root root    0 Sep 23 06:50 .check_iid
18446638755664086952 0 drwxr-xr-x.  1 root root    0 Sep 23 06:50 disks
18446638755664083432 0 -rwxrwx---.  1 root root    0 Sep 23 06:50 .get_iid
18446638755664094696 0 drwxrwx---.  1 root root    0 Sep 23 06:50 iid
18446638755664099624 0 -rwxrwx---.  1 root root    0 Sep 23 06:50 .query_disk
18446638755664071464 0 -rwxrwx---.  1 root root    0 Sep 23 06:50 .query_handle
18446638755664090472 0 -rwxrwx---.  1 root root    0 Sep 23 06:50 .query_version

They should be owned by the Oracle software owner and the DBA group. After checking the oracleasm log /var/log/oracleasm, we found the following error:

Thu Sep 23 08:12:28 Creating /dev/oracleasm mount point: /dev/oracleasm
Thu Sep 23 08:12:28 Creating /dev/oracleasm mount point: /dev/oracleasm
Thu Sep 23 08:12:28 Loading module "oracleasm": oracleasm
Thu Sep 23 08:12:28 Loading module "oracleasm": oracleasm
Thu Sep 23 08:12:28 Configuring "oracleasm" to use device physical block size
Thu Sep 23 08:12:28 Configuring "oracleasm" to use device physical block size
Thu Sep 23 08:12:28 chown: invalid user: 'oracle:dba'
Thu Sep 23 08:12:28 Mounting ASMlib driver filesystem: failed
Thu Sep 23 08:12:28 Mounting ASMlib driver filesystem: failed
Thu Sep 23 08:12:28 Unable to fix ASM driver permissions
Thu Sep 23 08:12:28 Unable to fix ASM driver permissions

Note line 7, so it seems like the username is not valid! But I am logged in as Oracle?

Checking the users, we see that oracle is not in the /etc/passwd file, so we must be getting it from somewhere else.

So we checked /etc/nsswitch.conf and found that we also get user information from System Security Services:

passwd:      files sss

Checking the services, we see that they started at around the same time:

# systemctl status sssd
- sssd.service - System Security Services Daemon
   Loaded: loaded (/usr/lib/systemd/system/sssd.service; enabled; vendor preset: enabled)
   Active: active (running) since Thu 2021-09-23 08:12:28 EDT; 46min ago
...

# systemctl status oracleasm
- oracleasm.service - Load oracleasm Modules
   Loaded: loaded (/usr/lib/systemd/system/oracleasm.service; enabled; vendor preset: disabled)
   Active: active (exited) since Thu 2021-09-23 08:12:28 EDT; 46min ago
...

This could be our cause and why the problem is intermittent. If oracleasm starts before the sssd service, then it will not be able to find any details for the oracle user when it tries to change the disk ownership, but if the oracleasm service is slower and starts after the sssd service, the user details will be available and the clusterware will start as normal.

So we added an After clause (line 3) to the /usr/lib/systemd/system/oracleasm.service file:

[Unit]
Description=Load oracleasm Modules
After=sssd.service

[Service]
Type=oneshot
RemainAfterExit=yes
ExecStart=/usr/sbin/oracleasm.init start_sysctl
ExecStop=/usr/sbin/oracleasm.init stop_sysctl
ExecReload=/usr/sbin/oracleasm.init restart_sysctl

[Install]
WantedBy=multi-user.target

This makes sure that the sssd service starts before oracleasm.

This resolved the issue and the clusterware comes up normally every time now.

The disks look like this:

$ ls -lasi
total 0
18446638755664080616 0 drwxr-xr-x.  4 root   root    0 Sep 23 09:50 .
                   3 0 drwxr-xr-x. 23 root   root 5260 Sep 23 09:51 ..
18446638755664098920 0 -rw-rw----.  1 oracle dba     0 Sep 23 09:50 .check_iid
18446638755664086952 0 drwxr-xr-x.  1 root   root    0 Sep 23 09:50 disks
18446638755664083432 0 -rw-rw----.  1 oracle dba     0 Sep 23 09:50 .get_iid
18446638755664094696 0 drwxrwx---.  1 oracle dba     0 Sep 23 09:50 iid
18446638755664099624 0 -rw-rw----.  1 oracle dba     0 Sep 23 09:50 .query_disk
18446638755664071464 0 -rw-rw----.  1 oracle dba     0 Sep 23 09:50 .query_handle
18446638755664090472 0 -rw-rw----.  1 oracle dba     0 Sep 23 09:50 .query_version

Thank you for reading my post! For more like this, please subscribe at the top of the page or here.