RHEVM is continously logging ERROR: java.sql.BatchUpdateException from BatchProcedureExecutionConnectionCallback

Solution Verified - Updated -

Environment

Red Hat Enterprise Virtualization (RHEV) 3.4

Issue

RHEVM and RHEV hypervisors are working fine, however logging of the batch exception occurs frequently - less than a minute apart.

ERROR [org.ovirt.engine.core.dal.dbbroker.BatchProcedureExecutionConnectionCallback] (DefaultQuartzScheduler_Worker-8) [2a7b5b9f] Can't execute batch: : java.sql.BatchUpdateException: Batch entry 0 select * from null.null() as result was aborted.  Call getNextException to see the cause.

ERROR [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (DefaultQuartzScheduler_Worker-83) BadSqlGrammarException: ConnectionCallback; bad SQL grammar []; nested exception is org.postgresql.util.PSQLException: ERROR: syntax error at or near "null"
  Position: 15: org.springframework.jdbc.BadSqlGrammarException: ConnectionCallback; bad SQL grammar []; nested exception is org.postgresql.util.PSQLException: ERROR: syntax error at or near "null"

Resolution

  1. Backup the RHEVM database

  2. Stop the Engine service to ensure that there are no connections to postgres backend calling any procedures:

    /etc/init.d/ovirt-engine stop
    
  3. Run the refreshStoredProcedures.sh script:

    source /etc/ovirt-engine/engine.conf.d/10-setup-database.conf 
    export PGPASSWORD=$ENGINE_DB_PASSWORD 
    cd /usr/share/ovirt-engine/dbscripts/ 
    ./refreshStoredProcedures.sh 
    
  4. Start the Engine service:

    /etc/init.d/ovirt-engine start
    
  5. Verify the engine logs to ensure the errors have stopped.

Root Cause

The following psql function was missing:
updatedisk_image_dynamic_by_disk_id

Diagnostic Steps

The syntax error at or near "null" seen in /var/lib/pgsql/data/pg_log/postgresql-Sun.log file matches to the error seen in the engine.log.

The following lines point to the problem:

    at org.ovirt.engine.core.dao.DiskImageDynamicDAODbFacadeImpl.updateAllDiskImageDynamicWithDiskId(DiskImageDynamicDAODbFacadeImpl.java:110) [dal.jar:]
    at org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo.saveDataToDb(VdsUpdateRunTimeInfo.java:170) [vdsbroker.jar:]

The /var/log/ovirt-engine-setup-20140610141034-8xxdh3.log shows upgrade activity on 2014-06-10.
It appears that the following sql functions are not included:

getiscsibondsbynetworkid
updatedisk_image_dynamic_by_disk_id

Exact error message seen in the engine.log file.

2014-11-17 09:20:04,866 ERROR [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (DefaultQuartzScheduler_Worker-83) ResourceManager::refreshVdsRunTimeInfo: Error: BadSqlGrammarException: ConnectionCallback; bad SQL grammar []; nested exception is org.postgresql.util.PSQLException: ERROR: syntax error at or near "null"
  Position: 15, vds = 08fbdb96-0d7f-11e2-89aa-525400ea8332 : rhevh02
2014-11-17 09:20:04,866 ERROR [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (DefaultQuartzScheduler_Worker-83) BadSqlGrammarException: ConnectionCallback; bad SQL grammar []; nested exception is org.postgresql.util.PSQLException: ERROR: syntax error at or near "null"
  Position: 15: org.springframework.jdbc.BadSqlGrammarException: ConnectionCallback; bad SQL grammar []; nested exception is org.postgresql.util.PSQLException: ERROR: syntax error at or near "null"
  Position: 15
    at org.springframework.jdbc.support.SQLErrorCodeSQLExceptionTranslator.doTranslate(SQLErrorCodeSQLExceptionTranslator.java:233) [spring-jdbc.jar:3.1.1.RELEASE]
    at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:72) [spring-jdbc.jar:3.1.1.RELEASE]
    at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:349) [spring-jdbc.jar:3.1.1.RELEASE]
    at org.ovirt.engine.core.dal.dbbroker.SimpleJdbcCallsHandler.executeStoredProcAsBatch(SimpleJdbcCallsHandler.java:52) [dal.jar:]
    at org.ovirt.engine.core.dal.dbbroker.SimpleJdbcCallsHandler.executeStoredProcAsBatch(SimpleJdbcCallsHandler.java:70) [dal.jar:]
    at org.ovirt.engine.core.dao.MassOperationsGenericDaoDbFacade.updateAllInBatch(MassOperationsGenericDaoDbFacade.java:60) [dal.jar:]
    at org.ovirt.engine.core.dao.DiskImageDynamicDAODbFacadeImpl.updateAllDiskImageDynamicWithDiskId(DiskImageDynamicDAODbFacadeImpl.java:110) [dal.jar:]
    at org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo.saveDataToDb(VdsUpdateRunTimeInfo.java:170) [vdsbroker.jar:]
    at org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo.refresh(VdsUpdateRunTimeInfo.java:358) [vdsbroker.jar:]
    at org.ovirt.engine.core.vdsbroker.VdsManager.onTimer(VdsManager.java:231) [vdsbroker.jar:]
    at sun.reflect.GeneratedMethodAccessor90.invoke(Unknown Source) [:1.7.0_71]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.7.0_71]
    at java.lang.reflect.Method.invoke(Method.java:606) [rt.jar:1.7.0_71]
    at org.ovirt.engine.core.utils.timer.JobWrapper.execute(JobWrapper.java:60) [scheduler.jar:]
    at org.quartz.core.JobRunShell.run(JobRunShell.java:213) [quartz.jar:]
    at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:557) [quartz.jar:]
Caused by: org.postgresql.util.PSQLException: ERROR: syntax error at or near "null"
  Position: 15
    at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2101)
    at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1834)
    at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:405)
    at org.postgresql.jdbc2.AbstractJdbc2Statement.executeBatch(AbstractJdbc2Statement.java:2752)
    at org.jboss.jca.adapters.jdbc.CachedPreparedStatement.executeBatch(CachedPreparedStatement.java:708)
    at org.jboss.jca.adapters.jdbc.WrappedStatement.executeBatch(WrappedStatement.java:1077)
    at org.ovirt.engine.core.dal.dbbroker.BatchProcedureExecutionConnectionCallback.doInConnection(BatchProcedureExecutionConnectionCallback.java:62) [dal.jar:]
    at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:342) [spring-jdbc.jar:3.1.1.RELEASE]
    ... 13 more

2014-11-17 09:20:06,604 ERROR [org.ovirt.engine.core.dal.dbbroker.BatchProcedureExecutionConnectionCallback] (DefaultQuartzScheduler_Worker-8) [2a7b5b9f] Can't execute batch: : java.sql.BatchUpdateException: Batch entry 0 select * from null.null() as result was aborted.  Call getNextException to see the cause.
    at org.postgresql.jdbc2.AbstractJdbc2Statement$CallableBatchResultHandler.handleError(AbstractJdbc2Statement.java:2689)
    at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1835)
    at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:405)
    at org.postgresql.jdbc2.AbstractJdbc2Statement.executeBatch(AbstractJdbc2Statement.java:2752)
    at org.jboss.jca.adapters.jdbc.CachedPreparedStatement.executeBatch(CachedPreparedStatement.java:708)
    at org.jboss.jca.adapters.jdbc.WrappedStatement.executeBatch(WrappedStatement.java:1077)
    at org.ovirt.engine.core.dal.dbbroker.BatchProcedureExecutionConnectionCallback.doInConnection(BatchProcedureExecutionConnectionCallback.java:62) [dal.jar:]
    at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:342) [spring-jdbc.jar:3.1.1.RELEASE]
    at org.ovirt.engine.core.dal.dbbroker.SimpleJdbcCallsHandler.executeStoredProcAsBatch(SimpleJdbcCallsHandler.java:52) [dal.jar:]
    at org.ovirt.engine.core.dal.dbbroker.SimpleJdbcCallsHandler.executeStoredProcAsBatch(SimpleJdbcCallsHandler.java:70) [dal.jar:]
    at org.ovirt.engine.core.dao.MassOperationsGenericDaoDbFacade.updateAllInBatch(MassOperationsGenericDaoDbFacade.java:60) [dal.jar:]
    at org.ovirt.engine.core.dao.DiskImageDynamicDAODbFacadeImpl.updateAllDiskImageDynamicWithDiskId(DiskImageDynamicDAODbFacadeImpl.java:110) [dal.jar:]
    at org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo.saveDataToDb(VdsUpdateRunTimeInfo.java:170) [vdsbroker.jar:]
    at org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo.refresh(VdsUpdateRunTimeInfo.java:358) [vdsbroker.jar:]
    at org.ovirt.engine.core.vdsbroker.VdsManager.onTimer(VdsManager.java:231) [vdsbroker.jar:]
    at sun.reflect.GeneratedMethodAccessor90.invoke(Unknown Source) [:1.7.0_71]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.7.0_71]
    at java.lang.reflect.Method.invoke(Method.java:606) [rt.jar:1.7.0_71]
    at org.ovirt.engine.core.utils.timer.JobWrapper.execute(JobWrapper.java:60) [scheduler.jar:]
    at org.quartz.core.JobRunShell.run(JobRunShell.java:213) [quartz.jar:]
    at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:557) [quartz.jar:]

2014-11-17 09:20:06,605 ERROR [org.ovirt.engine.core.dal.dbbroker.BatchProcedureExecutionConnectionCallback] (DefaultQuartzScheduler_Worker-8) [2a7b5b9f] Can't execute batch. Next exception is: : org.postgresql.util.PSQLException: ERROR: syntax error at or near "null"
  Position: 15
    at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2101)
    at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1834)
    at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:405)
    at org.postgresql.jdbc2.AbstractJdbc2Statement.executeBatch(AbstractJdbc2Statement.java:2752)
    at org.jboss.jca.adapters.jdbc.CachedPreparedStatement.executeBatch(CachedPreparedStatement.java:708)
    at org.jboss.jca.adapters.jdbc.WrappedStatement.executeBatch(WrappedStatement.java:1077)
    at org.ovirt.engine.core.dal.dbbroker.BatchProcedureExecutionConnectionCallback.doInConnection(BatchProcedureExecutionConnectionCallback.java:62) [dal.jar:]
    at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:342) [spring-jdbc.jar:3.1.1.RELEASE]
    at org.ovirt.engine.core.dal.dbbroker.SimpleJdbcCallsHandler.executeStoredProcAsBatch(SimpleJdbcCallsHandler.java:52) [dal.jar:]
    at org.ovirt.engine.core.dal.dbbroker.SimpleJdbcCallsHandler.executeStoredProcAsBatch(SimpleJdbcCallsHandler.java:70) [dal.jar:]
    at org.ovirt.engine.core.dao.MassOperationsGenericDaoDbFacade.updateAllInBatch(MassOperationsGenericDaoDbFacade.java:60) [dal.jar:]
    at org.ovirt.engine.core.dao.DiskImageDynamicDAODbFacadeImpl.updateAllDiskImageDynamicWithDiskId(DiskImageDynamicDAODbFacadeImpl.java:110) [dal.jar:]
    at org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo.saveDataToDb(VdsUpdateRunTimeInfo.java:170) [vdsbroker.jar:]
    at org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo.refresh(VdsUpdateRunTimeInfo.java:358) [vdsbroker.jar:]
    at org.ovirt.engine.core.vdsbroker.VdsManager.onTimer(VdsManager.java:231) [vdsbroker.jar:]
    at sun.reflect.GeneratedMethodAccessor90.invoke(Unknown Source) [:1.7.0_71]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.7.0_71]
    at java.lang.reflect.Method.invoke(Method.java:606) [rt.jar:1.7.0_71]
    at org.ovirt.engine.core.utils.timer.JobWrapper.execute(JobWrapper.java:60) [scheduler.jar:]
    at org.quartz.core.JobRunShell.run(JobRunShell.java:213) [quartz.jar:]
    at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:557) [quartz.jar:]

The /var/lib/pgsql/data/pg_log/postgresql-Sun.log reporting the syntax error

ERROR:  syntax error at or near "null" at character 15
STATEMENT:  select * from null.null() as result
ERROR:  syntax error at or near "null" at character 15
STATEMENT:  select * from null.null() as result
ERROR:  syntax error at or near "null" at character 15
STATEMENT:  select * from null.null() as result

This solution is part of Red Hat’s fast-track publication program, providing a huge library of solutions that Red Hat engineers have created while supporting our customers. To give you the knowledge you need the instant it becomes available, these articles may be presented in a raw and unedited form.

Comments