Bug 1102831

Summary:	modifying channel membership via SSM throws sql error ORA-20297: Call get_log_id need to follow set_log_auth
Product:	[Community] Spacewalk	Reporter:	Stephen Herr <sherr>
Component:	Server	Assignee:	Stephen Herr <sherr>
Status:	CLOSED CURRENTRELEASE	QA Contact:	Red Hat Satellite QA List <satqe-list>
Severity:	medium	Docs Contact:
Priority:	medium
Version:	2.2	CC:	cperry, saime, shughes, tpapaioa, xdmoon
Target Milestone:	---
Target Release:	---
Hardware:	Unspecified
OS:	Unspecified
Whiteboard:
Fixed In Version:	spacewalk-java-2.2.81	Doc Type:	Bug Fix
Doc Text:		Story Points:	---
Clone Of:	1073120	Environment:
Last Closed:	2014-07-17 08:41:37 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:
Embargoed:
Bug Depends On:	1073120
Bug Blocks:	1119298

Description Stephen Herr 2014-05-29 15:57:34 UTC

+++ This bug was initially created as a clone of Bug #1073120 +++

Description of problem:

Currently investigating a SSM issue where any action like modifying channel membership throws a sql error that is coming from the postgresql logging procs: 

com.redhat.rhn.common.db.WrappedSQLException: ORA-20297: Call get_log_id need to follow set_log_auth.
ORA-06512: at "RHNSAT.LOGGING", line 29
ORA-06512: at "RHNSAT.RHNSERVER_LOG_TRIG", line 5
ORA-04088: error during execution of trigger 'RHNSAT.RHNSERVER_LOG_TRIG'
ORA-06512: at "RHNSAT.RHN_CHANNEL", line 500
ORA-06512: at line 1

	at com.redhat.rhn.common.translation.SqlExceptionTranslator.oracleSQLException(SqlExceptionTranslator.java:82)
	at com.redhat.rhn.common.translation.SqlExceptionTranslator.sqlException(SqlExceptionTranslator.java:42)
	at com.redhat.rhn.common.db.datasource.CachedStatement.executeCallable(CachedStatement.java:543)
	at com.redhat.rhn.common.db.datasource.CallableMode.execute(CallableMode.java:35)
	at com.redhat.rhn.manager.ssm.SsmManager.unsubscribeChannel(SsmManager.java:213)
	at com.redhat.rhn.manager.ssm.SsmManager.performChannelActions(SsmManager.java:187)
	at com.redhat.rhn.frontend.events.SsmChangeChannelSubscriptionsAction.doExecute(SsmChangeChannelSubscriptionsAction.java:46)
	at com.redhat.rhn.frontend.events.AbstractDatabaseAction.execute(AbstractDatabaseAction.java:47)
	at com.redhat.rhn.common.messaging.ActionExecutor.run(ActionExecutor.java:69)
	at com.redhat.rhn.common.messaging.MessageDispatcher.run(MessageDispatcher.java:58)
	at java.lang.Thread.run(Thread.java:761)
Caused by: java.sql.SQLException: ORA-20297: Call get_log_id need to follow set_log_auth.
ORA-06512: at "RHNSAT.LOGGING", line 29
ORA-06512: at "RHNSAT.RHNSERVER_LOG_TRIG", line 5
ORA-04088: error during execution of trigger 'RHNSAT.RHNSERVER_LOG_TRIG'
ORA-06512: at "RHNSAT.RHN_CHANNEL", line 500
ORA-06512: at line 1

	at oracle.jdbc.driver.DatabaseError.throwSqlException(DatabaseError.java:112)
	at oracle.jdbc.driver.T2CConnection.checkError(T2CConnection.java:676)
	at oracle.jdbc.driver.T2CConnection.checkError(T2CConnection.java:602)
	at oracle.jdbc.driver.T2CCallableStatement.executeForDescribe(T2CCallableStatement.java:572)
	at oracle.jdbc.driver.T2CCallableStatement.executeForRows(T2CCallableStatement.java:765)
	at oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:1190)
	at oracle.jdbc.driver.OraclePreparedStatement.executeInternal(OraclePreparedStatement.java:3370)
	at oracle.jdbc.driver.OraclePreparedStatement.execute(OraclePreparedStatement.java:3476)
	at oracle.jdbc.driver.OracleCallableStatement.execute(OracleCallableStatement.java:4400)
	at com.mchange.v2.c3p0.impl.NewProxyCallableStatement.execute(NewProxyCallableStatement.java:2706)
	at com.redhat.rhn.common.db.NamedPreparedStatement.execute(NamedPreparedStatement.java:117)
	at com.redhat.rhn.common.db.datasource.CachedStatement.executeCallable(CachedStatement.java:528)
	... 8 more

Customer says restarting taskomatic and tomcat get the satellite working again but the tasks are still displayed as in progress. 

--- Additional comment from Tasos Papaioannou on 2014-05-08 11:17:43 EDT ---

A similar issue occurs when using embedded Postgresql:

1.) Add two RHEL 6 systems, both subscribed to the same Red Hat base channel, to SSM.
2.) Attempt to subscribe them to the RHN Tools child channel:

MANAGE > Manage systems' channel memberships
> select "Subscribe" for "RHN Tools for RHEL (v. 6 for 64-bit x86_64)"
> Alter Subscriptions > Change Subscriptions

3.) The "Channel Subscription Updates" SSM task remains "In Progress", and the following errors appear in the Tomcat and Postgres logs:

/var/log/tomcat6/catalina.out:

****
May 8, 2014 11:10:00 AM com.mchange.v2.c3p0.impl.NewPooledConnection handleThrowable
WARNING: [c3p0] A PooledConnection that has already signalled a Connection error is still in use!
May 8, 2014 11:10:00 AM com.mchange.v2.c3p0.impl.NewPooledConnection handleThrowable
WARNING: [c3p0] Another error has occurred [ org.postgresql.util.PSQLException: ERROR: current transaction is aborted, commands ignored until end of transaction block ] which will not be reported to listeners!
Throwable occurred: org.postgresql.util.PSQLException: ERROR: current transaction is aborted, commands ignored until end of transaction block
	at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2062)
	at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1795)
	at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:257)
	at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:479)
	at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:367)
	at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:360)
	at com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.execute(NewProxyPreparedStatement.java:651)
	at com.redhat.rhn.common.db.NamedPreparedStatement.execute(NamedPreparedStatement.java:140)
	at com.redhat.rhn.common.db.datasource.CachedStatement.execute(CachedStatement.java:467)
	at com.redhat.rhn.common.db.datasource.CachedStatement.execute(CachedStatement.java:443)
	at com.redhat.rhn.common.db.datasource.CachedStatement.executeUpdate(CachedStatement.java:276)
	at com.redhat.rhn.common.db.datasource.WriteMode.executeUpdate(WriteMode.java:33)
	at com.redhat.rhn.manager.ssm.SsmOperationManager.completeOperation(SsmOperationManager.java:217)
	at com.redhat.rhn.frontend.events.SsmChangeChannelSubscriptionsAction.doExecute(SsmChangeChannelSubscriptionsAction.java:50)
	at com.redhat.rhn.frontend.events.AbstractDatabaseAction.execute(AbstractDatabaseAction.java:47)
	at com.redhat.rhn.common.messaging.ActionExecutor.run(ActionExecutor.java:69)
	at com.redhat.rhn.common.messaging.MessageDispatcher.run(MessageDispatcher.java:58)
	at java.lang.Thread.run(Thread.java:761)
2014-05-08 11:10:00,161 [RHN Message Dispatcher] ERROR com.redhat.rhn.common.db.datasource.CachedStatement - Error while processing cached statement sql: UPDATE rhnSsmOperation
         SET status = ?,
             modified = current_timestamp
       WHERE id = ?
         AND user_id = ?
com.redhat.rhn.common.db.WrappedSQLException: ERROR: current transaction is aborted, commands ignored until end of transaction block
	at com.redhat.rhn.common.translation.SqlExceptionTranslator.postgreSqlException(SqlExceptionTranslator.java:54)
	at com.redhat.rhn.common.translation.SqlExceptionTranslator.sqlException(SqlExceptionTranslator.java:44)
	at com.redhat.rhn.common.db.NamedPreparedStatement.execute(NamedPreparedStatement.java:143)
	at com.redhat.rhn.common.db.datasource.CachedStatement.execute(CachedStatement.java:467)
	at com.redhat.rhn.common.db.datasource.CachedStatement.execute(CachedStatement.java:443)
	at com.redhat.rhn.common.db.datasource.CachedStatement.executeUpdate(CachedStatement.java:276)
	at com.redhat.rhn.common.db.datasource.WriteMode.executeUpdate(WriteMode.java:33)
	at com.redhat.rhn.manager.ssm.SsmOperationManager.completeOperation(SsmOperationManager.java:217)
	at com.redhat.rhn.frontend.events.SsmChangeChannelSubscriptionsAction.doExecute(SsmChangeChannelSubscriptionsAction.java:50)
	at com.redhat.rhn.frontend.events.AbstractDatabaseAction.execute(AbstractDatabaseAction.java:47)
	at com.redhat.rhn.common.messaging.ActionExecutor.run(ActionExecutor.java:69)
	at com.redhat.rhn.common.messaging.MessageDispatcher.run(MessageDispatcher.java:58)
	at java.lang.Thread.run(Thread.java:761)
Caused by: 
org.postgresql.util.PSQLException: ERROR: current transaction is aborted, commands ignored until end of transaction block
	at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2062)
	at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1795)
	at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:257)
	at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:479)
	at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:367)
	at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:360)
	at com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.execute(NewProxyPreparedStatement.java:651)
	at com.redhat.rhn.common.db.NamedPreparedStatement.execute(NamedPreparedStatement.java:140)
	... 10 more
com.redhat.rhn.common.db.WrappedSQLException: ERROR: current transaction is aborted, commands ignored until end of transaction block
	at com.redhat.rhn.common.translation.SqlExceptionTranslator.postgreSqlException(SqlExceptionTranslator.java:54)
	at com.redhat.rhn.common.translation.SqlExceptionTranslator.sqlException(SqlExceptionTranslator.java:44)
	at com.redhat.rhn.common.db.NamedPreparedStatement.execute(NamedPreparedStatement.java:143)
	at com.redhat.rhn.common.db.datasource.CachedStatement.execute(CachedStatement.java:467)
	at com.redhat.rhn.common.db.datasource.CachedStatement.execute(CachedStatement.java:443)
	at com.redhat.rhn.common.db.datasource.CachedStatement.executeUpdate(CachedStatement.java:276)
	at com.redhat.rhn.common.db.datasource.WriteMode.executeUpdate(WriteMode.java:33)
	at com.redhat.rhn.manager.ssm.SsmOperationManager.completeOperation(SsmOperationManager.java:217)
	at com.redhat.rhn.frontend.events.SsmChangeChannelSubscriptionsAction.doExecute(SsmChangeChannelSubscriptionsAction.java:50)
	at com.redhat.rhn.frontend.events.AbstractDatabaseAction.execute(AbstractDatabaseAction.java:47)
	at com.redhat.rhn.common.messaging.ActionExecutor.run(ActionExecutor.java:69)
	at com.redhat.rhn.common.messaging.MessageDispatcher.run(MessageDispatcher.java:58)
	at java.lang.Thread.run(Thread.java:761)
Caused by: org.postgresql.util.PSQLException: ERROR: current transaction is aborted, commands ignored until end of transaction block
	at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2062)
	at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1795)
	at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:257)
	at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:479)
	at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:367)
	at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:360)
	at com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.execute(NewProxyPreparedStatement.java:651)
	at com.redhat.rhn.common.db.NamedPreparedStatement.execute(NamedPreparedStatement.java:140)
	... 10 more
****

/var/lib/pgsql/data/pg_log/postgresql-Thu.log:

****
2014-05-08 11:10:00.158 EDT ERROR:  can't read "the_log_id": no such variable
2014-05-08 11:10:00.158 EDT CONTEXT:  can't read "the_log_id": no such variable
	    while executing
	"return $the_log_id"
	    (procedure "__PLTcl_proc_23717" line 4)
	    invoked from within
	"__PLTcl_proc_23717"
	in PL/Tcl function "_get_log_id"
	PL/pgSQL function "get_log_id" line 6 at assignment
	PL/pgSQL function "rhnserver_log_trig_fun" line 4 at assignment
	SQL statement "update rhnServer set channels_changed = current_timestamp where id =  $1 "
	PL/pgSQL function "subscribe_server" line 102 at SQL statement
2014-05-08 11:10:00.158 EDT STATEMENT:  select * from rhn_channel.subscribe_server($1, $2, 1, $3) as result
2014-05-08 11:10:00.159 EDT ERROR:  current transaction is aborted, commands ignored until end of transaction block
2014-05-08 11:10:00.159 EDT STATEMENT:  select 'c3p0 ping' from dual
2014-05-08 11:10:00.159 EDT ERROR:  current transaction is aborted, commands ignored until end of transaction block
2014-05-08 11:10:00.159 EDT STATEMENT:  UPDATE rhnSsmOperation
	         SET status = $1,
	             modified = current_timestamp
	       WHERE id = $2
	         AND user_id = $3
2014-05-08 11:10:00.159 EDT ERROR:  current transaction is aborted, commands ignored until end of transaction block
2014-05-08 11:10:00.159 EDT STATEMENT:  select 'c3p0 ping' from dual
****

As with external Oracle db, the log trigger on the rhnserver table appears to be the problem. Performing the same action with only one system in the SSM does not have this problem.

--- Additional comment from Stephen Herr on 2014-05-29 11:54:44 EDT ---

The reproducer in comment 8 does not produce the error if I only have two systems in the System Set, but does if I have 500 systems.

As you say the root problem here is that the logging triggers have not been initialized for this transaction. I will update the code to ensure that we always initialize logging for asynchronous user-initiated actions.

Even when I do though that will only prevent this from happening in the future, there is no way to fix the old "In Progress" tasks besides manually executing sql to clean them up. Perhaps something like:

update rhnSsmOperation set status='Completed' where status = 'In Progress';

Comment 1 Stephen Herr 2014-05-29 16:03:26 UTC

Committing to Spacewalk master:
b4d5705a8c6936b9b8edf477c66b3a2cc9e3f8a7

Comment 2 Stephen Herr 2014-05-29 17:37:34 UTC

And:
be94f2eef9ca1ebdbec67d1b6b9a60ce6447ec50

Comment 3 Milan Zázrivec 2014-07-17 08:41:37 UTC

Spacewalk 2.2 has been released:

    https://fedorahosted.org/spacewalk/wiki/ReleaseNotes22