12 Replies Latest reply: Dec 27, 2012 12:51 PM by 981938 RSS

    Problem in the database at 10pm everyday

    974867
      Hi,
      I'm using Oracle 11gR2 (11.2.0.1.0) with default installation, running on SLES 11 SP2.
      Another SLES 11SP2 server hosts a web application with JBoss, it's using the corresponding JDBC connector (ojdbc6 11.2.0.1.0) to connect and update some tables of the database.
      The problem is that every day the jboss is unable to connect to the database for 1 hour exactly. This happens every day from 22:00 to 23:00 pm.

      The servers don't have any job scheduled at Linux level, JBboss, backup server or network infrastructure.
      For that reason I think the problem is in the database, I was looking for predefined jobs or maintenance tasks that may be running at 22 pm and making the database inaccessible, but still could not solve the problem.


      This is the error log from JBoss that i see every time that the JDBC driver want to connect to the database.
      After exactly one hour the connection returns automatically without problems.

      ---------------------------------------------------
      2012-11-13 22:00:26,847 WARN [org.jboss.resource.connectionmanager.TxConnectionManager] (Thread-45) Connection error occured: org.jboss.resource.connectionm
      anager.TxConnectionManager$TxConnectionEventListener@1ac1a45[state=NORMAL mc=org.jboss.resource.adapter.jdbc.local.LocalManagedConnection@563fa9 handles=1 la
      stUse=1352854823458 permit=true trackByTx=false mcp=org.jboss.resource.connectionmanager.JBossManagedConnectionPool$PoolBySubject@458eab context=org.jboss.re
      source.connectionmanager.InternalManagedConnectionPool@99b936 xaResource=org.jboss.resource.connectionmanager.TxConnectionManager$LocalXAResource@6d8e2a txSy
      nc=null]
      java.lang.RuntimeException: Assertion botch: negative time
      at oracle.jdbc.driver.DateCommonBinder.setOracleHMS(OraclePreparedStatement.java:18740)
      at oracle.jdbc.driver.TimestampBinder.bind(OraclePreparedStatement.java:19245)
      at oracle.jdbc.driver.OraclePreparedStatement.setupBindBuffers(OraclePreparedStatement.java:3014)
      at oracle.jdbc.driver.OraclePreparedStatement.executeBatch(OraclePreparedStatement.java:9973)
      at oracle.jdbc.driver.OracleStatementWrapper.executeBatch(OracleStatementWrapper.java:213)
      at org.jboss.resource.adapter.jdbc.WrappedStatement.executeBatch(WrappedStatement.java:774)
      at org.hibernate.jdbc.BatchingBatcher.doExecuteBatch(BatchingBatcher.java:70)
      at org.hibernate.jdbc.AbstractBatcher.executeBatch(AbstractBatcher.java:268)
      at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:268)
      at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:185)
      at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:321)
      at org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:51)
      at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:1216)
      at org.hibernate.impl.SessionImpl.managedFlush(SessionImpl.java:383)
      at org.hibernate.transaction.JDBCTransaction.commit(JDBCTransaction.java:133)
      at com.novell.soa.persist.HibernateUtil.commit(HibernateUtil.java:211)
      at com.novell.soa.persist.HibernateDAO.commit(HibernateDAO.java:450)
      at com.novell.soa.af.impl.persist.EngineStateDAO.updateHeartbeat(EngineStateDAO.java:151)
      at com.novell.soa.af.impl.core.EngineImpl$HeartbeatTimer.run(EngineImpl.java:1459)
      at java.lang.Thread.run(Unknown Source)
      2012-11-13 22:00:27,086 INFO [STDOUT] (Thread-45) ERROR [RBPM] [com.novell.soa.persist.HibernateUtil:rollback] Error rolling back transaction
      org.hibernate.TransactionException: JDBC rollback failed
      at org.hibernate.transaction.JDBCTransaction.rollback(JDBCTransaction.java:200)
      at com.novell.soa.persist.HibernateUtil.rollback(HibernateUtil.java:237)
      at com.novell.soa.persist.HibernateDAO.rollback(HibernateDAO.java:463)
      at com.novell.soa.af.impl.persist.EngineStateDAO.updateHeartbeat(EngineStateDAO.java:154)
      at com.novell.soa.af.impl.core.EngineImpl$HeartbeatTimer.run(EngineImpl.java:1459)
      at java.lang.Thread.run(Unknown Source)
      Caused by: java.sql.SQLException: You cannot rollback with autocommit set!
      at org.jboss.resource.adapter.jdbc.BaseWrapperManagedConnection.jdbcRollback(BaseWrapperManagedConnection.java:695)
      at org.jboss.resource.adapter.jdbc.WrappedConnection.rollback(WrappedConnection.java:500)
      at org.hibernate.transaction.JDBCTransaction.rollbackAndResetAutoCommit(JDBCTransaction.java:213)
      at org.hibernate.transaction.JDBCTransaction.rollback(JDBCTransaction.java:192)
      ... 5 more
      2012-11-13 22:00:27,088 INFO [STDOUT] (Thread-45) WARN [RBPM] [com.novell.soa.af.impl.core.EngineImpl:run] Failed to update heartbeat for engine: Engine01
      com.novell.soa.persist.PersistenceException: org.hibernate.exception.GenericJDBCException: Could not execute JDBC batch update
      at com.novell.soa.persist.HibernateUtil.commit(HibernateUtil.java:213)
      at com.novell.soa.persist.HibernateDAO.commit(HibernateDAO.java:450)
      at com.novell.soa.af.impl.persist.EngineStateDAO.updateHeartbeat(EngineStateDAO.java:151)
      at com.novell.soa.af.impl.core.EngineImpl$HeartbeatTimer.run(EngineImpl.java:1459)
      at java.lang.Thread.run(Unknown Source)
      Caused by: org.hibernate.exception.GenericJDBCException: Could not execute JDBC batch update
      at org.hibernate.exception.SQLStateConverter.handledNonSpecificException(SQLStateConverter.java:140)
      at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:128)
      at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:66)
      at org.hibernate.jdbc.AbstractBatcher.executeBatch(AbstractBatcher.java:275)
      at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:268)
      at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:185)
      at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:321)
      at org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:51)
      at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:1216)
      at org.hibernate.impl.SessionImpl.managedFlush(SessionImpl.java:383)
      at org.hibernate.transaction.JDBCTransaction.commit(JDBCTransaction.java:133)
      at com.novell.soa.persist.HibernateUtil.commit(HibernateUtil.java:211)
      ... 4 more
      Caused by: org.jboss.util.NestedSQLException: Error; - nested throwable: (java.lang.RuntimeException: Assertion botch: negative time)
      at org.jboss.resource.adapter.jdbc.WrappedConnection.checkException(WrappedConnection.java:873)
      at org.jboss.resource.adapter.jdbc.WrappedStatement.checkException(WrappedStatement.java:852)
      at org.jboss.resource.adapter.jdbc.WrappedStatement.executeBatch(WrappedStatement.java:778)
      at org.hibernate.jdbc.BatchingBatcher.doExecuteBatch(BatchingBatcher.java:70)
      at org.hibernate.jdbc.AbstractBatcher.executeBatch(AbstractBatcher.java:268)
      ... 12 more
      Caused by: java.lang.RuntimeException: Assertion botch: negative time
      at oracle.jdbc.driver.DateCommonBinder.setOracleHMS(OraclePreparedStatement.java:18740)
      at oracle.jdbc.driver.TimestampBinder.bind(OraclePreparedStatement.java:19245)
      at oracle.jdbc.driver.OraclePreparedStatement.setupBindBuffers(OraclePreparedStatement.java:3014)
      at oracle.jdbc.driver.OraclePreparedStatement.executeBatch(OraclePreparedStatement.java:9973)
      at oracle.jdbc.driver.OracleStatementWrapper.executeBatch(OracleStatementWrapper.java:213)
      at org.jboss.resource.adapter.jdbc.WrappedStatement.executeBatch(WrappedStatement.java:774)
      ... 14 more
      ---------------------------------------------------


      Any ideas?
      Thanks.

      Regards.
        • 1. Re: Problem in the database at 10pm everyday
          rp0428
          >
          The problem is that every day the jboss is unable to connect to the database for 1 hour exactly.
          >
          I don't see anything in the trace you posted that shows a 'connection' failure. Part of the trace shows other errors that would only appear if there already was a connection
          Error rolling back transaction
          . . .
          Could not execute JDBC batch update
          And there are references to prepared statements. I don't see how you could be rolling back a transaction if you aren't even connected to the database.

          You need to clarify the actual architecture and sequence of events. If a connection to the database is failing there should be a log or trace file somewhere that shows an Oracle exception or error or at least one from the app server or code that is 'connection' related.

          The database could certainly have been put in a mode that does not allow connections, or only allows restricted connections, for a time period.
          • 2. Re: Problem in the database at 10pm everyday
            974867
            Hi, thanks for the reply.

            >
            I don't see anything in the trace you posted that shows a 'connection' failure. Part of the trace shows other errors that would only appear if there already was a connection
            >

            i'll try to explain better the scenario:
            Every minute the web application server updates an attribute in the database, which is used like a heartbeat.
            This operation is successful throughout the day, except during the 22:00 pm and 23:00 pm, which is when I get the error posted previously, the error is repeated every minute (for each connection attempt)

            I found some logs in the oracle but none with information that can help me, same with scheduled jobs and maintenance task.
            Maybe i don't know where to look exactly.

            What do you think? Where I can see any log that can help or settings that may be the problem?
            • 3. Re: Problem in the database at 10pm everyday
              Fahd.Mirza
              Hello,
              In your error message, there is this following error:

              Assertion botch: negative time

              This normally appears when client time zone is different than the server's time zone.

              You may run following to check the time zones for any difference:

              SELECT SYSTIMESTAMP, CURRENT_TIMESTAMP, DBTIMEZONE, SESSIONTIMEZONE FROM DUAL;

              you may use alter session command to set your time_zone if above is different and try the operation again.

              If you think that your issue is related to database, then the first point to check is good old alert log. Are there any errors or warnings there?

              Thanks.

              Fahd Mirza
              fahdmirza.blogspot.com
              • 4. Re: Problem in the database at 10pm everyday
                974867
                Hi Fahd Mirza , thanks for the reply.

                Following the message "Assertion botch: negative time" I did check the time zone of the database and the web application.
                There was a difference in SESSIONTIMEZONE of 1 hour, use the command alter session to correct it but nothing changed.
                Also discard that approach because the problem occurs only for 1 hour per day, if the problem is generated by the time zone configuration should have more errors in the day. Am I right?


                Finally, I checked the following logs and I copied the data about one day where we had the problem:
                Do you see something strange?


                */diag/rdbms/orcl/orcl/alert/log.xml*
                >
                <msg time='2012-11-18T02:00:00.010-03:00' org_id='oracle' comp_id='rdbms'
                client_id='' type='UNKNOWN' level='16'
                host_id='arusflnx08' host_addr='127.0.0.2' module=''
                pid='4501'>
                <txt>Clearing Resource Manager plan via parameter
                </txt>
                </msg>
                <msg time='2012-11-18T06:00:00.014-03:00' org_id='oracle' comp_id='rdbms'
                client_id='' type='UNKNOWN' level='16'
                host_id='arusflnx08' host_addr='127.0.0.2' module=''
                pid='5074'>
                <txt>Setting Resource Manager plan SCHEDULER[0x3009]:DEFAULT_MAINTENANCE_PLAN via scheduler window
                </txt>
                </msg>
                <msg time='2012-11-18T06:00:00.014-03:00' org_id='oracle' comp_id='rdbms'
                client_id='' type='UNKNOWN' level='16'
                host_id='arusflnx08' host_addr='127.0.0.2' module=''
                pid='5074'>
                <txt>Setting Resource Manager plan DEFAULT_MAINTENANCE_PLAN via parameter
                </txt>
                </msg>
                <msg time='2012-11-18T06:00:00.014-03:00' org_id='oracle' comp_id='rdbms'
                msg_id='ksbs1p_real:2253:2371767696' client_id='' type='NOTIFICATION'
                group='process start' level='16' host_id='arusflnx08'
                host_addr='127.0.0.2' module='' pid='4501'>
                <txt>Starting background process VKRM
                </txt>
                </msg>
                <msg time='2012-11-18T06:00:00.030-03:00' org_id='oracle' comp_id='rdbms'
                msg_id='ksbrdp:3833:3697353022' type='NOTIFICATION' group='process start'
                level='16' host_id='arusflnx08' host_addr='127.0.0.2'
                pid='23304'>
                <txt>VKRM started with pid=27, OS id=23304
                </txt>
                </msg>
                <msg time='2012-11-18T06:00:02.125-03:00' org_id='oracle' comp_id='rdbms'
                msg_id='kesaiTuneSqlDrv:4553:2579917519' client_id='' type='NOTIFICATION'
                group='sqltune' level='16' host_id='arusflnx08'
                host_addr='127.0.0.2' module='DBMS_SCHEDULER' pid='23339'>
                <txt>Begin automatic SQL Tuning Advisor run for special tuning task &quot;SYS_AUTO_SQL_TUNING_TASK&quot;
                </txt>
                </msg>
                <msg time='2012-11-18T06:00:03.731-03:00' org_id='oracle' comp_id='rdbms'
                msg_id='kesaiTuneSqlDrv:5065:3456118459' client_id='' type='NOTIFICATION'
                group='sqltune' level='16' host_id='arusflnx08'
                host_addr='127.0.0.2' module='DBMS_SCHEDULER' pid='23339'>
                <txt>End automatic SQL Tuning Advisor run for special tuning task &quot;SYS_AUTO_SQL_TUNING_TASK&quot;
                </txt>
                </msg>
                <msg time='2012-11-18T06:00:15.648-03:00' org_id='oracle' comp_id='rdbms'
                client_id='' type='UNKNOWN' level='16'
                host_id='arusflnx08' host_addr='127.0.0.2' module=''
                pid='4511'>
                <txt>Thread 1 cannot allocate new log, sequence 101
                </txt>
                </msg>
                <msg time='2012-11-18T06:00:15.649-03:00' org_id='oracle' comp_id='rdbms'
                client_id='' type='UNKNOWN' level='16'
                host_id='arusflnx08' host_addr='127.0.0.2' module=''
                pid='4511'>
                <txt>Private strand flush not complete
                </txt>
                </msg>
                <msg time='2012-11-18T06:00:15.649-03:00' org_id='oracle' comp_id='rdbms'
                client_id='' type='UNKNOWN' level='16'
                host_id='arusflnx08' host_addr='127.0.0.2' module=''
                pid='4511'>
                <txt> Current log# 1 seq# 100 mem# 0: /opt/oracle/oradata/idmorcl/redo01.log
                </txt>
                </msg>
                <msg time='2012-11-18T06:00:18.680-03:00' org_id='oracle' comp_id='rdbms'
                client_id='' type='UNKNOWN' level='16'
                host_id='arusflnx08' host_addr='127.0.0.2' module=''
                pid='4511'>
                <txt>Thread 1 advanced to log sequence 101 (LGWR switch)
                </txt>
                </msg>
                <msg time='2012-11-18T06:00:18.680-03:00' org_id='oracle' comp_id='rdbms'
                client_id='' type='UNKNOWN' level='16'
                host_id='arusflnx08' host_addr='127.0.0.2' module=''
                pid='4511'>
                <txt> Current log# 2 seq# 101 mem# 0: /opt/oracle/oradata/idmorcl/redo02.log
                </txt>
                </msg>
                <msg time='2012-11-18T10:06:17.013-03:00' org_id='oracle' comp_id='rdbms'
                client_id='' type='UNKNOWN' level='16'
                host_id='arusflnx08' host_addr='127.0.0.2' module=''
                pid='4511'>
                <txt>Thread 1 cannot allocate new log, sequence 102
                </txt>
                </msg>
                <msg time='2012-11-18T10:06:17.013-03:00' org_id='oracle' comp_id='rdbms'
                client_id='' type='UNKNOWN' level='16'
                host_id='arusflnx08' host_addr='127.0.0.2' module=''
                pid='4511'>
                <txt>Private strand flush not complete
                </txt>
                </msg>
                <msg time='2012-11-18T10:06:17.013-03:00' org_id='oracle' comp_id='rdbms'
                client_id='' type='UNKNOWN' level='16'
                host_id='arusflnx08' host_addr='127.0.0.2' module=''
                pid='4511'>
                <txt> Current log# 2 seq# 101 mem# 0: /opt/oracle/oradata/idmorcl/redo02.log
                </txt>
                </msg>
                <msg time='2012-11-18T10:06:20.031-03:00' org_id='oracle' comp_id='rdbms'
                client_id='' type='UNKNOWN' level='16'
                host_id='arusflnx08' host_addr='127.0.0.2' module=''
                pid='4511'>
                <txt>Thread 1 advanced to log sequence 102 (LGWR switch)
                </txt>
                </msg>
                <msg time='2012-11-18T10:06:20.031-03:00' org_id='oracle' comp_id='rdbms'
                client_id='' type='UNKNOWN' level='16'
                host_id='arusflnx08' host_addr='127.0.0.2' module=''
                pid='4511'>
                <txt> Current log# 3 seq# 102 mem# 0: /opt/oracle/oradata/idmorcl/redo03.log
                </txt>
                </msg>
                <msg time='2012-11-18T18:38:38.244-03:00' org_id='oracle' comp_id='rdbms'
                client_id='' type='UNKNOWN' level='16'
                host_id='arusflnx08' host_addr='127.0.0.2' module=''
                pid='4511'>
                <txt>Thread 1 cannot allocate new log, sequence 103
                </txt>
                </msg>
                <msg time='2012-11-18T18:38:38.245-03:00' org_id='oracle' comp_id='rdbms'
                client_id='' type='UNKNOWN' level='16'
                host_id='arusflnx08' host_addr='127.0.0.2' module=''
                pid='4511'>
                <txt>Private strand flush not complete
                </txt>
                </msg>
                <msg time='2012-11-18T18:38:38.245-03:00' org_id='oracle' comp_id='rdbms'
                client_id='' type='UNKNOWN' level='16'
                host_id='arusflnx08' host_addr='127.0.0.2' module=''
                pid='4511'>
                <txt> Current log# 3 seq# 102 mem# 0: /opt/oracle/oradata/idmorcl/redo03.log
                </txt>
                </msg>
                <msg time='2012-11-18T18:38:41.260-03:00' org_id='oracle' comp_id='rdbms'
                client_id='' type='UNKNOWN' level='16'
                host_id='arusflnx08' host_addr='127.0.0.2' module=''
                pid='4511'>
                <txt>Thread 1 advanced to log sequence 103 (LGWR switch)
                </txt>
                </msg>
                <msg time='2012-11-18T18:38:41.260-03:00' org_id='oracle' comp_id='rdbms'
                client_id='' type='UNKNOWN' level='16'
                host_id='arusflnx08' host_addr='127.0.0.2' module=''
                pid='4511'>
                <txt> Current log# 1 seq# 103 mem# 0: /opt/oracle/oradata/idmorcl/redo01.log
                </txt>
                </msg>
                <msg time='2012-11-18T22:16:15.554-03:00' org_id='oracle' comp_id='rdbms'
                client_id='' type='UNKNOWN' level='16'
                host_id='arusflnx08' host_addr='127.0.0.2' module=''
                pid='4511'>
                <txt>Thread 1 advanced to log sequence 104 (LGWR switch)
                </txt>
                </msg>
                <msg time='2012-11-18T22:16:15.554-03:00' org_id='oracle' comp_id='rdbms'
                client_id='' type='UNKNOWN' level='16'
                host_id='arusflnx08' host_addr='127.0.0.2' module=''
                pid='4511'>
                <txt> Current log# 2 seq# 104 mem# 0: /opt/oracle/oradata/idmorcl/redo02.log
                </txt>
                </msg>
                >


                */diag/rdbms/orcl/orcl/trace/alert_orcl.log*
                >
                Sun Nov 18 02:00:00 2012
                Clearing Resource Manager plan via parameter
                Sun Nov 18 06:00:00 2012
                Setting Resource Manager plan SCHEDULER[0x3009]:DEFAULT_MAINTENANCE_PLAN via scheduler window
                Setting Resource Manager plan DEFAULT_MAINTENANCE_PLAN via parameter
                Sun Nov 18 06:00:00 2012
                Starting background process VKRM
                Sun Nov 18 06:00:00 2012
                VKRM started with pid=27, OS id=23304
                Sun Nov 18 06:00:02 2012
                Begin automatic SQL Tuning Advisor run for special tuning task "SYS_AUTO_SQL_TUNING_TASK"
                End automatic SQL Tuning Advisor run for special tuning task "SYS_AUTO_SQL_TUNING_TASK"
                Sun Nov 18 06:00:15 2012
                Thread 1 cannot allocate new log, sequence 101
                Private strand flush not complete
                Current log# 1 seq# 100 mem# 0: /opt/oracle/oradata/idmorcl/redo01.log
                Thread 1 advanced to log sequence 101 (LGWR switch)
                Current log# 2 seq# 101 mem# 0: /opt/oracle/oradata/idmorcl/redo02.log
                Sun Nov 18 10:06:17 2012
                Thread 1 cannot allocate new log, sequence 102
                Private strand flush not complete
                Current log# 2 seq# 101 mem# 0: /opt/oracle/oradata/idmorcl/redo02.log
                Thread 1 advanced to log sequence 102 (LGWR switch)
                Current log# 3 seq# 102 mem# 0: /opt/oracle/oradata/idmorcl/redo03.log
                Sun Nov 18 18:38:38 2012
                Thread 1 cannot allocate new log, sequence 103
                Private strand flush not complete
                Current log# 3 seq# 102 mem# 0: /opt/oracle/oradata/idmorcl/redo03.log
                Thread 1 advanced to log sequence 103 (LGWR switch)
                Current log# 1 seq# 103 mem# 0: /opt/oracle/oradata/idmorcl/redo01.log
                Sun Nov 18 22:16:15 2012
                Thread 1 advanced to log sequence 104 (LGWR switch)
                Current log# 2 seq# 104 mem# 0: /opt/oracle/oradata/idmorcl/redo02.log
                >


                */diag/tnslsnr/--/listener/alert/log.xml*
                >
                <msg time='2012-11-18T22:01:00.827-03:00' org_id='oracle' comp_id='tnslsnr'
                type='UNKNOWN' level='16' host_id='arusflnx08'
                host_addr='127.0.0.2'>
                <txt>18-NOV-2012 22:01:00 * service_update * idmorcl * 0
                </txt>
                </msg>
                <msg time='2012-11-18T22:01:08.613-03:00' org_id='oracle' comp_id='tnslsnr'
                type='UNKNOWN' level='16' host_id='arusflnx08'
                host_addr='127.0.0.2'>
                <txt>18-NOV-2012 22:01:08 * (CONNECT_DATA=(SID=idmorcl)(CID=(PROGRAM=JDBC Thin Client)(HOST=__jdbc__)(USER=root))) * (ADDRESS=(PROTOCOL=tcp)(HOST=10.30.10.2
                42)(PORT=39628)) * establish * idmorcl * 0
                </txt>
                </msg>
                <msg time='2012-11-18T22:01:08.634-03:00' org_id='oracle' comp_id='tnslsnr'
                type='UNKNOWN' level='16' host_id='arusflnx08'
                host_addr='127.0.0.2'>
                <txt>18-NOV-2012 22:01:08 * (CONNECT_DATA=(SID=idmorcl)(CID=(PROGRAM=JDBC Thin Client)(HOST=__jdbc__)(USER=root))) * (ADDRESS=(PROTOCOL=tcp)(HOST=10.30.10.2
                42)(PORT=39629)) * establish * idmorcl * 0
                </txt>
                </msg>
                <msg time='2012-11-18T22:01:18.848-03:00' org_id='oracle' comp_id='tnslsnr'
                type='UNKNOWN' level='16' host_id='arusflnx08'
                host_addr='127.0.0.2'>
                <txt>18-NOV-2012 22:01:18 * service_update * idmorcl * 0
                </txt>
                </msg>
                <msg time='2012-11-18T22:01:59.824-03:00' org_id='oracle' comp_id='tnslsnr'
                type='UNKNOWN' level='16' host_id='arusflnx08'
                host_addr='127.0.0.2'>
                <txt>18-NOV-2012 22:01:59 * (CONNECT_DATA=(SID=idmorcl)(CID=(PROGRAM=JDBC Thin Client)(HOST=__jdbc__)(USER=root))) * (ADDRESS=(PROTOCOL=tcp)(HOST=10.30.10.2
                43)(PORT=43443)) * establish * idmorcl * 0
                </txt>
                </msg>
                >


                */diag/tnslsnr/--/listener/trace/listener.log*
                >
                18-NOV-2012 22:00:09 * service_update * idmorcl * 0
                18-NOV-2012 22:00:18 * service_update * idmorcl * 0
                Sun Nov 18 22:00:48 2012
                18-NOV-2012 22:00:48 * service_update * idmorcl * 0
                Sun Nov 18 22:01:00 2012
                18-NOV-2012 22:01:00 * service_update * idmorcl * 0
                18-NOV-2012 22:01:08 * (CONNECT_DATA=(SID=idmorcl)(CID=(PROGRAM=JDBC Thin Client)(HOST=__jdbc__)(USER=root))) * (ADDRESS=(PROTOCOL=tcp)(HOST=10.30.10.242)(PO
                RT=39628)) * establish * idmorcl * 0
                18-NOV-2012 22:01:08 * (CONNECT_DATA=(SID=idmorcl)(CID=(PROGRAM=JDBC Thin Client)(HOST=__jdbc__)(USER=root))) * (ADDRESS=(PROTOCOL=tcp)(HOST=10.30.10.242)(PO
                RT=39629)) * establish * idmorcl * 0
                Sun Nov 18 22:01:18 2012
                18-NOV-2012 22:01:18 * service_update * idmorcl * 0
                Sun Nov 18 22:01:59 2012
                18-NOV-2012 22:01:59 * (CONNECT_DATA=(SID=idmorcl)(CID=(PROGRAM=JDBC Thin Client)(HOST=__jdbc__)(USER=root))) * (ADDRESS=(PROTOCOL=tcp)(HOST=10.30.10.243)(PO
                RT=43443)) * establish * idmorcl * 0
                Sun Nov 18 22:02:18 2012
                18-NOV-2012 22:02:18 * service_update * idmorcl * 0
                Sun Nov 18 22:02:48 2012
                18-NOV-2012 22:02:48 * service_update * idmorcl * 0
                >



                Thanks

                Edited by: 971864 on 20-nov-2012 10:53
                • 5. Re: Problem in the database at 10pm everyday
                  orafad
                  Considered running a test using the latest OJdbc driver?

                  Edited by: orafad on Nov 21, 2012 1:43 AM
                  • 6. Re: Problem in the database at 10pm everyday
                    rp0428
                    >
                    Every minute the web application server updates an attribute in the database, which is used like a heartbeat.
                    This operation is successful throughout the day, except during the 22:00 pm and 23:00 pm, which is when I get the error posted previously, the error is repeated every minute (for each connection attempt)
                    >
                    Post the code the server is trying to execute on the database. You said this code is failing with an error so there may be some clues in what the code is doing.
                    • 7. Re: Problem in the database at 10pm everyday
                      jgarry
                      Wild guess here, but look at https://confluence.atlassian.com/display/JIRAKB/%27Assertion+botch%3A+negative+time%27+Error+is+Thrown+When+Trying+to+Restore+Backup+Data

                      I'm thinking you have some kind of time synchronization error between the servers. This could have something to do with the environment one of the things starting up is wrong, perhaps the TZ or similar variable. Also, there were some bugs having to do with time zone in some versions of java, this could be the driver update orafad mentioned too.

                      Check that TZ is set explicitly in all environments, I've seen it where someone was starting up Oracle in csh, so it was defaulting to central time. Maybe one of the components somewhere has some maintenance job that starts up at 10PM, throwing a wrench into things. Maybe you should see if there are network issues, for that matter (some of our busiest times are backups in the middle of the night, I've seen things interfere just because some didn't honor end of dst).
                      • 8. Re: Problem in the database at 10pm everyday
                        orafad
                        971864 wrote:
                        Following the message "Assertion botch: negative time" I did check the time zone of the database and the web application.
                        There was a difference in SESSIONTIMEZONE of 1 hour, use the command alter session to correct it but nothing changed.
                        Also discard that approach because the problem occurs only for 1 hour per day, if the problem is generated by the time zone configuration should have more errors in the day. Am I right?
                        Why discard best lead so far so easily? Perhaps a time calculation involved only turns up negative (falsely, maybe) when hour is 22.
                        • 9. Re: Problem in the database at 10pm everyday
                          Dave Rabone
                          I'm with you on this one ... If there's a one hour difference then there's a one hour period when the two dates are different. Speculating wildly, perhaps there's then a daylight saving difference as well, which means it actually happens 10pm to 11pm (or is reported as such in the logs!)
                          • 10. Re: Problem in the database at 10pm everyday
                            974867
                            Thanks to all for the help, I worked on the problem and returned to check the timezone settings.

                            I run the query to get the HEARTBEAT time from the database (when it was working) and i see that the heartbeat is one hour ahead that the time of jboss and linux servers.
                            Like if the time zone of the heartbeat time is GMT-02 when the correct time zone must be GMT-03.

                            Post the code the server is trying to execute on the database. You said this code is failing with an error so there may be some clues in what the code is doing.
                            I checked the database's sessions and i captured the following code:
                            update AFENGINESTATE set HEARTBEAT=current_timestamp


                            I checked the TZ of Linux and Java, they are correct.
                            I read that the problem could be in the timezone of this particular session, to change the TZ for all sessions of all users should i set the linux environment variable ORA_SDTZ = '-03:00' in all servers (Oracle and Jboss) ?



                            Regards
                            • 11. Re: Problem in the database at 10pm everyday
                              974867
                              I set the the linux environment variable ORA_SDTZ='-03:00' in both servers and reboot them (Oracle and Jboss), but nothing happend...
                              The HEARTBEAT time still is one hour ahead.

                              What am I missing?
                              Thanks.
                              • 12. Re: Problem in the database at 10pm everyday
                                981938
                                Look at this [Assertion botch: negative time With 11.2 JDBC Drivers [ID 1206581.1]|https://support.oracle.com/epmos/faces/DocContentDisplay?_afrLoop=122896334453652&id=1206581.1&_afrWindowMode=0&_adf.ctrl-state=b0at1nm0f_92]