Bug 1374655

Summary: resource agent has trouble creating monitoring user when starting multi-tenant container DB "ORA-65140: invalid common profile name"
Product: Red Hat Enterprise Linux 6 Reporter: Oyvind Albrigtsen <oalbrigt>
Component: resource-agentsAssignee: Oyvind Albrigtsen <oalbrigt>
Status: CLOSED ERRATA QA Contact: cluster-qe <cluster-qe>
Severity: high Docs Contact:
Priority: high    
Version: 6.8CC: agk, cluster-maint, cluster-qe, fdinitto, lmiksik, mnovacek, pzimek
Target Milestone: rc   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: resource-agents-3.9.5-36.el6 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: 1328386 Environment:
Last Closed: 2017-03-21 09:28:17 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Bug Depends On: 1328386, 1358895    
Bug Blocks:    

Description Oyvind Albrigtsen 2016-09-09 10:45:43 UTC 
+++ This bug was initially created as a clone of Bug #1328386 +++

Description of problem:

If Oracle 12c DB is configured as multi-tenant container database, resource agent has trouble creating monitoring user when starting DB

Feb 24 13:13:28 rhelnode oracle(oracle12_baza)[5032]: ERROR: could not create OCFMONPROFILE oracle profile
Feb 24 13:13:28 rhelnode oracle(oracle12_baza)[5032]: ERROR: sqlplus output: create profile OCFMONPROFILE limit FAILED_LOGIN_ATTEMPTS UNLIMITED PASSWORD_LIFE_TIME UNLIMITED#012               *#012ERROR at line 1:#012ORA-65140: invalid common profile name

When trying to create profile by hand directly in database command that resource agent script uses fails.

SQL> create profile OCFMONPROFILE limit FAILED_LOGIN_ATTEMPTS UNLIMITED PASSWORD_LIFE_TIME UNLIMITED;
create profile OCFMONPROFILE limit FAILED_LOGIN_ATTEMPTS UNLIMITED PASSWORD_LIFE_TIME UNLIMITED
               *
ERROR at line 1:
ORA-65140: invalid common profile name

But when command is adjusted to comply with container DB it passes.

SQL> create profile C##OCFMONPROFILE limit FAILED_LOGIN_ATTEMPTS UNLIMITED PASSWORD_LIFE_TIME UNLIMITED;

Profile created.


When Oracle12c DB is not configured as container DB starts ok. So problem seems to be that resource agent doesn't check if the DB is multi-tenant and thus doesn't use the "C##" prefix in case it is multi-tenant container database.



Version-Release number of selected component (if applicable):
resource-agents-3.9.5-34.el6_8.2.x86_64


How reproducible:
always




Additional info:

https://www.oraexcel.com/oracle-12cR1-ORA-65140

Patches:
https://github.com/ClusterLabs/resource-agents/pull/790
https://github.com/ClusterLabs/resource-agents/pull/843
https://github.com/ClusterLabs/resource-agents/pull/844
Comment 2 Oyvind Albrigtsen 2016-09-12 12:21:12 UTC 
Tested and working as expected.
Comment 4 michal novacek 2016-12-12 14:51:22 UTC 
I have verified that it is possible to start oracle resource agent with prepended C## to monprofile and monuser parameter in resource-agents-3.9.5-40.el6.x86_64

----

common setup:

 * install oracle container database with cdb
    (https://www.redhat.com/en/files/resources/en-rhel-deploy-oracle-rac-database-12c-rhel-7.pdf,
    section 4.1.4 (page 73)

 * create resource agent and disable it

[root@duck-01 ~]# pcs resource show oracle
 Resource: oracle (class=ocf provider=heartbeat type=oracle)
>  Attributes: sid=cdb monprofile=mprofile monuser=OCFMON
  Meta Attrs: target-role=Stopped 
  Operations: start interval=0s timeout=120 (oracle-start-interval-0s)
              stop interval=0s timeout=120 (oracle-stop-interval-0s)
              monitor interval=30s (oracle-monitor-interval-30s)

  * check that oracle user can connect to database with sid 'cdb'

[root@duck-01 ~]# su - oracle
[oracle@duck-01 ~]$ export ORACLE_HOME=/u01/app/oracle/product/12.1.0/dbhome_1
>[oracle@duck-01 ~]$ export ORACLE_SID=cdb
[oracle@duck-01 ~]$  $ORACLE_HOME/bin/sqlplus / as sysdba

SQL*Plus: Release 12.1.0.2.0 Production on Mon Dec 12 14:54:39 2016

Copyright (c) 1982, 2014, Oracle.  All rights reserved.


Connected to:
Oracle Database 12c Enterprise Edition Release 12.1.0.2.0 - 64bit Production
With the Partitioning, OLAP, Advanced Analytics and Real Application Testing options

SQL> startup;
ORACLE instance started.

Total System Global Area 2.2884E+10 bytes
Fixed Size                  7655312 bytes
Variable Size            3959423088 bytes
Database Buffers         1.8858E+10 bytes
Redo Buffers               59453440 bytes
Database mounted.
Database opened.

SQL> shutdown immediate;
Database closed.
Database dismounted.
ORACLE instance shut down.

> before the fix (resource-agents-3.9.5-34.el6.x86_64)
======================================================
>> with profile not prepended with C## resource agent will not start (no useful
>> message given), incorrect sql command output

[root@duck-01 ~]# pcs resource enable oracle

[root@duck-01 ~]# pcs resource | grep oracle
     oracle     (ocf::heartbeat:oracle):        Stopped

[root@duck-01 ~]# grep oracle /var/log/messages | tail -n 50
Dec 12 15:04:00 duck-01 crmd[4966]:   notice: Result of start operation for oracle on duck-01.cluster-qe.lab.eng.brq.redhat.com: 0 (ok) | call=93 key=oracle_start_0 confirmed=true cib-update=160
Dec 12 15:04:00 duck-01 crmd[4966]:   notice: Initiating monitor operation oracle_monitor_30000 locally on duck-01.cluster-qe.lab.eng.brq.redhat.com | action 18
Dec 12 15:04:27 duck-01 pengine[4965]:   notice: Stop    oracle#011(duck-01.cluster-qe.lab.eng.brq.redhat.com)
Dec 12 15:04:27 duck-01 crmd[4966]:   notice: Initiating stop operation oracle_stop_0 locally on duck-01.cluster-qe.lab.eng.brq.redhat.com | action 18
Dec 12 15:04:36 duck-01 oracle(oracle)[4129]: INFO: Oracle instance cdb stopped: ORACLE instance shut down.
Dec 12 15:04:37 duck-01 oracle(oracle)[4129]: INFO: Cleaning up for cdb
Dec 12 15:04:37 duck-01 crmd[4966]:   notice: Result of stop operation for oracle on duck-01.cluster-qe.lab.eng.brq.redhat.com: 0 (ok) | call=96 key=oracle_stop_0 confirmed=true cib-update=163
Dec 12 15:05:02 duck-01 pengine[4965]:   notice: Start   oracle#011(duck-01.cluster-qe.lab.eng.brq.redhat.com)
Dec 12 15:05:02 duck-01 crmd[4966]:   notice: Initiating start operation oracle_start_0 locally on duck-01.cluster-qe.lab.eng.brq.redhat.com | action 17
>> Dec 12 15:05:15 duck-01 oracle(oracle)[4980]: ERROR: could not create OCFMONPROFILE oracle profile
>> Dec 12 15:05:15 duck-01 oracle(oracle)[4980]: ERROR: sqlplus output: create profile OCFMONPROFILE limit FAILED_LOGIN_ATTEMPTS UNLIMITED PASSWORD_LIFE_TIME UNLIMITED#012               *#012ERROR at line 1:#012ORA-65140: invalid common profile name
>> Dec 12 15:05:15 duck-01 crmd[4966]:   notice: Result of start operation for oracle on duck-01.cluster-qe.lab.eng.brq.redhat.com: 1 (unknown error) | call=97 key=oracle_start_0 confirmed=true cib-update=165
Dec 12 15:05:15 duck-01 crmd[4966]:  warning: Action 17 (oracle_start_0) on duck-01.cluster-qe.lab.eng.brq.redhat.com failed (target: 0 vs. rc: 1): Error
Dec 12 15:05:15 duck-01 crmd[4966]:   notice: Transition aborted by operation oracle_start_0 'modify' on duck-01.cluster-qe.lab.eng.brq.redhat.com: Event failed | magic=0:1;17:40:0:9d1066c4-c862-4f3d-b35f-cdf56494507b cib=0.23.1 source=match_graph_event:310 complete=false
Dec 12 15:05:15 duck-01 crmd[4966]:  warning: Action 17 (oracle_start_0) on duck-01.cluster-qe.lab.eng.brq.redhat.com failed (target: 0 vs. rc: 1): Error
Dec 12 15:05:15 duck-01 attrd[4964]:   notice: Sending flush op to all hosts for: fail-count-oracle (INFINITY)
Dec 12 15:05:15 duck-01 attrd[4964]:   notice: Sent update 53: fail-count-oracle=INFINITY
Dec 12 15:05:15 duck-01 attrd[4964]:   notice: Sending flush op to all hosts for: last-failure-oracle (1481551515)
Dec 12 15:05:15 duck-01 attrd[4964]:   notice: Sent update 55: last-failure-oracle=1481551515
Dec 12 15:05:15 duck-01 attrd[4964]:   notice: Sending flush op to all hosts for: fail-count-oracle (INFINITY)
Dec 12 15:05:15 duck-01 attrd[4964]:   notice: Sent update 57: fail-count-oracle=INFINITY
Dec 12 15:05:15 duck-01 attrd[4964]:   notice: Sending flush op to all hosts for: last-failure-oracle (1481551515)
Dec 12 15:05:15 duck-01 attrd[4964]:   notice: Sent update 59: last-failure-oracle=1481551515
...

>> correct the user the way oracle likes it (prepend C##), the resource does
>> not start anyway
[root@duck-01 ~]# pcs resource update oracle monprofile=C##mprofile
[root@duck-01 ~]# pcs resource | grep oracle
oracle-cdb     (ocf::heartbeat:oracle):        Stopped

> after the fix (resource-agents-3.9.5-40.el6.x86_64)
=====================================================
>> with profile and/or user not prepended with C## resource agent will not
>> start but it gives you clear reason why
[root@kiff-03 ~]# pcs resource enable oracle-cdb

[root@kiff-03 ~]# ps axf | grep cdb
24447 pts/3    S+     0:00          \_ grep --color=auto cdb

[root@kiff-03 ~]# pcs resource | grep oracle-cdb
 oracle-cdb     (ocf::heartbeat:oracle):        Stopped

[root@kiff-03 ~]# grep oracle-cdb /var/log/messages | tail -n 50
Dec 12 15:24:47 duck-01 crmd[4966]:   notice: Initiating stop operation oracle_stop_0 locally on duck-01.cluster-qe.lab.eng.brq.redhat.com | action 2
Dec 12 15:25:00 duck-01 oracle(oracle)[10114]: INFO: Oracle instance cdb stopped: ORACLE instance shut down.
Dec 12 15:25:01 duck-01 oracle(oracle)[10114]: INFO: Cleaning up for cdb
Dec 12 15:25:01 duck-01 crmd[4966]:   notice: Result of stop operation for oracle on duck-01.cluster-qe.lab.eng.brq.redhat.com: 0 (ok) | call=132 key=oracle_stop_0 confirmed=true cib-update=226
Dec 12 15:28:27 duck-01 pengine[4965]:  warning: Processing failed op start for oracle on duck-01.cluster-qe.lab.eng.brq.redhat.com: unknown error (1)
Dec 12 15:28:27 duck-01 pengine[4965]:  warning: Processing failed op start for oracle on duck-02.cluster-qe.lab.eng.brq.redhat.com: unknown error (1)
Dec 12 15:28:27 duck-01 pengine[4965]:  warning: Forcing oracle away from duck-01.cluster-qe.lab.eng.brq.redhat.com after 1000000 failures (max=1000000)
Dec 12 15:28:27 duck-01 pengine[4965]:  warning: Forcing oracle away from duck-02.cluster-qe.lab.eng.brq.redhat.com after 1000000 failures (max=1000000)
Dec 12 15:30:27 duck-01 pengine[4965]:  warning: Processing failed op start for oracle on duck-01.cluster-qe.lab.eng.brq.redhat.com: unknown error (1)
Dec 12 15:30:27 duck-01 pengine[4965]:  warning: Processing failed op start for oracle on duck-02.cluster-qe.lab.eng.brq.redhat.com: unknown error (1)
Dec 12 15:30:27 duck-01 attrd[4964]:   notice: Sending flush op to all hosts for: fail-count-oracle (<null>)
Dec 12 15:30:27 duck-01 attrd[4964]:   notice: Sent delete 89: node=duck-01.cluster-qe.lab.eng.brq.redhat.com, attr=fail-count-oracle, id=<n/a>, set=(null), section=status
Dec 12 15:30:27 duck-01 attrd[4964]:   notice: Sending flush op to all hosts for: last-failure-oracle (<null>)
Dec 12 15:30:27 duck-01 attrd[4964]:   notice: Sent delete 95: node=duck-01.cluster-qe.lab.eng.brq.redhat.com, attr=last-failure-oracle, id=<n/a>, set=(null), section=status
Dec 12 15:30:27 duck-01 pengine[4965]:  warning: Forcing oracle away from duck-01.cluster-qe.lab.eng.brq.redhat.com after 1000000 failures (max=1000000)
Dec 12 15:35:15 duck-01 pengine[4965]:   notice: Start   oracle#011(duck-01.cluster-qe.lab.eng.brq.redhat.com)
Dec 12 15:35:15 duck-01 crmd[4966]:   notice: Initiating start operation oracle_start_0 locally on duck-01.cluster-qe.lab.eng.brq.redhat.com | action 17
>> Dec 12 15:35:35 duck-01 oracle(oracle)[16058]: ERROR: monprofile must start with C## for container databases
Dec 12 15:35:35 duck-01 crmd[4966]:   notice: Result of start operation for oracle on duck-01.cluster-qe.lab.eng.brq.redhat.com: 1 (unknown error) | call=133 key=oracle_start_0 confirmed=true cib-update=237
Dec 12 15:35:35 duck-01 crmd[4966]:  warning: Action 17 (oracle_start_0) on duck-01.cluster-qe.lab.eng.brq.redhat.com failed (target: 0 vs. rc: 1): Error
Dec 12 15:35:35 duck-01 crmd[4966]:   notice: Transition aborted by operation oracle_start_0 'modify' on duck-01.cluster-qe.lab.eng.brq.redhat.com: Event failed | magic=0:1;17:62:0:9d1066c4-c862-4f3d-b35f-cdf56494507b cib=0.30.1 source=match_graph_event:310 complete=false
Dec 12 15:35:35 duck-01 crmd[4966]:  warning: Action 17 (oracle_start_0) on duck-01.cluster-qe.lab.eng.brq.redhat.com failed (target: 0 vs. rc: 1): Error
Dec 12 15:35:35 duck-01 attrd[4964]:   notice: Sending flush op to all hosts for: fail-count-oracle (INFINITY)
Dec 12 15:35:35 duck-01 attrd[4964]:   notice: Sent update 98: fail-count-oracle=INFINITY
Dec 12 15:35:35 duck-01 attrd[4964]:   notice: Sending flush op to all hosts for: last-failure-oracle (1481553335)
Dec 12 15:35:35 duck-01 attrd[4964]:   notice: Sent update 100: last-failure-oracle=1481553335
Dec 12 15:35:35 duck-01 attrd[4964]:   notice: Sending flush op to all hosts for: fail-count-oracle (INFINITY)
Dec 12 15:35:35 duck-01 attrd[4964]:   notice: Sent update 102: fail-count-oracle=INFINITY
Dec 12 15:35:35 duck-01 attrd[4964]:   notice: Sending flush op to all hosts for: last-failure-oracle (1481553335)
Dec 12 15:35:35 duck-01 attrd[4964]:   notice: Sent update 104: last-failure-oracle=1481553335
Dec 12 15:35:35 duck-01 pengine[4965]:  warning: Processing failed op start for oracle on duck-01.cluster-qe.lab.eng.brq.redhat.com: unknown error (1)
Dec 12 15:35:35 duck-01 pengine[4965]:  warning: Processing failed op start for oracle on duck-01.cluster-qe.lab.eng.brq.redhat.com: unknown error (1)
Dec 12 15:35:35 duck-01 pengine[4965]:   notice: Recover oracle#011(Started duck-01.cluster-qe.lab.eng.brq.redhat.com)
Dec 12 15:35:35 duck-01 pengine[4965]:  warning: Processing failed op start for oracle on duck-01.cluster-qe.lab.eng.brq.redhat.com: unknown error (1)
Dec 12 15:35:35 duck-01 pengine[4965]:  warning: Processing failed op start for oracle on duck-01.cluster-qe.lab.eng.brq.redhat.com: unknown error (1)
Dec 12 15:35:35 duck-01 pengine[4965]:  warning: Forcing oracle away from duck-01.cluster-qe.lab.eng.brq.redhat.com after 1000000 failures (max=1000000)
Dec 12 15:35:35 duck-01 pengine[4965]:   notice: Recover oracle#011(Started duck-01.cluster-qe.lab.eng.brq.redhat.com -> duck-02.cluster-qe.lab.eng.brq.redhat.com)
Dec 12 15:35:35 duck-01 crmd[4966]:   notice: Initiating stop operation oracle_stop_0 locally on duck-01.cluster-qe.lab.eng.brq.redhat.com | action 2
Dec 12 15:35:46 duck-01 oracle(oracle)[16914]: INFO: Oracle instance cdb stopped: ORACLE instance shut down.
Dec 12 15:35:47 duck-01 oracle(oracle)[16914]: INFO: Cleaning up for cdb
Dec 12 15:35:47 duck-01 crmd[4966]:   notice: Result of stop operation for oracle on duck-01.cluster-qe.lab.eng.brq.redhat.com: 0 (ok) | call=134 key=oracle_stop_0 confirmed=true cib-update=241
Dec 12 15:35:52 duck-01 crmd[4966]:   notice: Initiating start operation oracle_start_0 on duck-02.cluster-qe.lab.eng.brq.redhat.com | action 21

>> correct the monprofile by prepending it with C##

[root@duck-01 ~]# pcs resource update oracle monprofile=C##mprofile
[root@duck-01 ~]# pcs resource show oracle
 Resource: oracle (class=ocf provider=heartbeat type=oracle)
  Attributes: sid=cdb monprofile=C##mprofile monuser=OCFMON
  Operations: start interval=0s timeout=120 (oracle-start-interval-0s)
              stop interval=0s timeout=120 (oracle-stop-interval-0s)
              monitor interval=30s (oracle-monitor-interval-30s)

[root@duck-01 ~]# grep oracle /var/log/messages | tail -n 20
Dec 12 15:39:00 duck-01 pengine[4965]:  warning: Processing failed op start for oracle on duck-02.cluster-qe.lab.eng.brq.redhat.com: unknown error (1)
Dec 12 15:39:00 duck-01 pengine[4965]:  warning: Processing failed op start for oracle on duck-02.cluster-qe.lab.eng.brq.redhat.com: unknown error (1)
Dec 12 15:39:00 duck-01 pengine[4965]:   notice: Recover oracle#011(Started duck-02.cluster-qe.lab.eng.brq.redhat.com)
Dec 12 15:39:00 duck-01 pengine[4965]:  warning: Processing failed op start for oracle on duck-02.cluster-qe.lab.eng.brq.redhat.com: unknown error (1)
Dec 12 15:39:00 duck-01 pengine[4965]:  warning: Processing failed op start for oracle on duck-02.cluster-qe.lab.eng.brq.redhat.com: unknown error (1)
Dec 12 15:39:00 duck-01 pengine[4965]:  warning: Forcing oracle away from duck-02.cluster-qe.lab.eng.brq.redhat.com after 1000000 failures (max=1000000)
Dec 12 15:39:00 duck-01 pengine[4965]:   notice: Recover oracle#011(Started duck-02.cluster-qe.lab.eng.brq.redhat.com -> duck-01.cluster-qe.lab.eng.brq.redhat.com)
Dec 12 15:39:00 duck-01 crmd[4966]:   notice: Initiating stop operation oracle_stop_0 on duck-02.cluster-qe.lab.eng.brq.redhat.com | action 6
Dec 12 15:39:16 duck-01 crmd[4966]:   notice: Initiating start operation oracle_start_0 locally on duck-01.cluster-qe.lab.eng.brq.redhat.com | action 21
>> Dec 12 15:39:36 duck-01 oracle(oracle)[17874]: ERROR: monuser must start with C## for container databases
Dec 12 15:39:36 duck-01 crmd[4966]:   notice: Result of start operation for oracle on duck-01.cluster-qe.lab.eng.brq.redhat.com: 1 (unknown error) | call=147 key=oracle_start_0 confirmed=true cib-update=259
Dec 12 15:39:36 duck-01 crmd[4966]:  warning: Action 21 (oracle_start_0) on duck-01.cluster-qe.lab.eng.brq.redhat.com failed (target: 0 vs. rc: 1): Error
Dec 12 15:39:36 duck-01 crmd[4966]:   notice: Transition aborted by operation oracle_start_0 'modify' on duck-01.cluster-qe.lab.eng.brq.redhat.com: Event failed | magic=0:1;21:69:0:9d1066c4-c862-4f3d-b35f-cdf56494507b cib=0.31.20 source=match_graph_event:310 complete=false
Dec 12 15:39:36 duck-01 crmd[4966]:  warning: Action 21 (oracle_start_0) on duck-01.cluster-qe.lab.eng.brq.redhat.com failed (target: 0 vs. rc: 1): Error
Dec 12 15:39:36 duck-01 attrd[4964]:   notice: Sending flush op to all hosts for: fail-count-oracle (INFINITY)
Dec 12 15:39:36 duck-01 attrd[4964]:   notice: Sent update 127: fail-count-oracle=INFINITY
Dec 12 15:39:36 duck-01 attrd[4964]:   notice: Sending flush op to all hosts for: last-failure-oracle (1481553576)
Dec 12 15:39:36 duck-01 attrd[4964]:   notice: Sent update 129: last-failure-oracle=1481553576
Dec 12 15:39:36 duck-01 attrd[4964]:   notice: Sending flush op to all hosts for: fail-count-oracle (INFINITY)
Dec 12 15:39:36 duck-01 attrd[4964]:   notice: Sent update 131: fail-count-oracle=INFINITY

>> correct the monuser by prepending it with C##

[root@duck-01 ~]# pcs resource update oracle monuser=C##OCFMON

[root@duck-01 ~]# pcs resource show oracle
 Resource: oracle (class=ocf provider=heartbeat type=oracle)
  Attributes: sid=cdb monprofile=C##mprofile monuser=C##OCFMON
  Operations: start interval=0s timeout=120 (oracle-start-interval-0s)
              stop interval=0s timeout=120 (oracle-stop-interval-0s)
              monitor interval=30s (oracle-monitor-interval-30s)j

[root@duck-01 ~]# pcs resource | grep oracle
     oracle     (ocf::heartbeat:oracle):        Started duck-01.cluster-qe.lab.eng.brq.redhat.com

[root@duck-01 ~]# su - oracle
[oracle@duck-01 ~]$ export ORACLE_HOME=/u01/app/oracle/product/12.1.0/dbhome_1
[oracle@duck-01 ~]$ export ORACLE_SID=cdb
[oracle@duck-01 ~]$ $ORACLE_HOME/bin/sqlplus / as sysdba

SQL*Plus: Release 12.1.0.2.0 Production on Mon Dec 12 15:48:05 2016

Copyright (c) 1982, 2014, Oracle.  All rights reserved.


Connected to:
Oracle Database 12c Enterprise Edition Release 12.1.0.2.0 - 64bit Production
With the Partitioning, OLAP, Advanced Analytics and Real Application Testing options

SQL> startup
ORA-01081: cannot start already-running ORACLE - shut it down first
SQL>
Comment 6 errata-xmlrpc 2017-03-21 09:28:17 UTC 
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://rhn.redhat.com/errata/RHBA-2017-0602.html