Uploaded image for project: 'OpenNMS'
  1. OpenNMS
  2. NMS-10473

duplicate key exceptions in alarmd

    XMLWordPrintable

    Details

    • Sprint:
      Horizon - November 28th 2018, Horizon - December 5th 2018

      Description

      Here's an excerpt from the log showing the alarm being created, and the duplicate key except that follows:

      2018-11-23 18:00:18,881 DEBUG [alarmd-Thread-4-of-4] o.o.n.e.EventIpcManagerDefaultImpl: run: calling onEvent on alarmd for event {"uei":"uei.opennms.org/vendor/cisco/syslog/ifUp","time":"2018-11-23 17:54:51,000-0600","dbid":19431251,"source":"syslogd","nodeid":1673,"parms":[{"hostname":"7.192.16.6"}, {"syslogmessage":"%ETHPORT-5-IF_UP: Interface Ethernet111/1/41 is up in mode access"}, {"severity":"Notice"}, {"timestamp":"Nov 23 23:54:51"}, {"service":"local7"}, {"group1":"Ethernet111/1/41"}, {"ifDescr":"Ethernet111/1/41"}]}
      2018-11-23 18:00:18,881 DEBUG [alarmd-Thread-4-of-4] o.o.n.a.AlarmPersisterImpl: process: uei.opennms.org/vendor/cisco/syslog/ifUp; nodeid: 1673; ipaddr: 7.192.16.6; serviceid: null
      2018-11-23 18:00:18,881 DEBUG [alarmd-Thread-4-of-4] o.o.n.a.AlarmPersisterImpl: addOrReduceEventAsAlarm: looking for existing reduction key: uei.opennms.org/vendor/cisco/syslog/ifUp:00000000-0000-0000-0000-000000000000:1673:Ethernet111/1/41
      2018-11-23 18:00:18,882 DEBUG [alarmd-Thread-4-of-4] o.o.n.a.AlarmPersisterImpl: addOrReduceEventAsAlarm: reductionKey:uei.opennms.org/vendor/cisco/syslog/ifUp:00000000-0000-0000-0000-000000000000:1673:Ethernet111/1/41 not found, instantiating new alarm
      2018-11-23 18:00:18,889 DEBUG [alarmd-Thread-3-of-4] o.o.n.e.EventIpcManagerDefaultImpl: run: calling onEvent on alarmd for event {"uei":"uei.opennms.org/generic/traps/SNMP_Link_Up","time":"2018-11-23 17:59:03,554-0600","dbid":19431252,"source":"trapd","nodeid":1673,"parms":[{".1.3.6.1.2.1.2.2.1.1.527305216":"527305216"}, {".1.3.6.1.2.1.2.2.1.7.527305216":"1"}, {".1.3.6.1.2.1.2.2.1.8.527305216":"1"}, {".1.3.6.1.2.1.2.2.1.2.527305216":"Ethernet111/1/41"}, {".1.3.6.1.2.1.31.1.1.1.18.527305216":"LS2E31-AZ1-1017"}, {".1.3.6.1.6.3.1.1.4.3.0":".1.3.6.1.6.3.1.1.5.4"}, {"ifIndex":"527305216"}]}
      2018-11-23 18:00:18,889 DEBUG [alarmd-Thread-3-of-4] o.o.n.a.AlarmPersisterImpl: process: uei.opennms.org/generic/traps/SNMP_Link_Up; nodeid: 1673; ipaddr: 7.192.16.6; serviceid: null
      2018-11-23 18:00:18,891 DEBUG [alarmd-Thread-3-of-4] o.o.n.a.AlarmPersisterImpl: addOrReduceEventAsAlarm: looking for existing reduction key: uei.opennms.org/generic/traps/SNMP_Link_Up:00000000-0000-0000-0000-000000000000:1673:527305216
      2018-11-23 18:00:18,895 DEBUG [alarmd-Thread-3-of-4] o.o.n.a.AlarmPersisterImpl: addOrReduceEventAsAlarm: reductionKey:uei.opennms.org/generic/traps/SNMP_Link_Up:00000000-0000-0000-0000-000000000000:1673:527305216 found, reducing event to existing alarm: /7.192.16.6
      2018-11-23 18:00:18,907 DEBUG [alarmd-Thread-4-of-4] o.o.n.a.d.DroolsAlarmContext: Inserting alarm into session: OnmsAlarm{alarmid=1470370, distPoller=OnmsDistPoller{id=00000000-0000-0000-0000-000000000000, label=localhost, location=Default, type=OpenNMS}, uei=uei.opennms.org/vendor/cisco/syslog/ifUp, severity=CLEARED, lastEventTime=2018-11-23 17:54:51.0}
      2018-11-23 18:00:18,908 DEBUG [alarmd-Thread-4-of-4] o.o.n.d.h.AbstractDaoHibernate: criteria = Criteria [class=class org.opennms.netmgt.model.OnmsAcknowledgment,orders=[Order [attribute=ackTime, ascending=false], Order [attribute=id, ascending=false]],restrictions=[EqRestriction [attribute=refId, value=1470370]],distinct=false,limit=1]
      2018-11-23 18:00:18,914 DEBUG [alarmd-Thread-4-of-4] o.o.n.a.d.DroolsAlarmContext: Inserting first alarm acknowledgement into session: Acknowledgment ID:0 User:admin Time:2018-11-23 17:54:51.0 AckType:Alarm AckAction:Unacknowledge Acknowledable ID:1470370
      2018-11-23 18:00:18,914 DEBUG [alarmd-Thread-4-of-4] o.o.n.b.d.Bsmd: Handling alarm with id: 1470370, reduction key: uei.opennms.org/vendor/cisco/syslog/ifUp:00000000-0000-0000-0000-000000000000:1673:Ethernet111/1/41 and severity: CLEARED and status: Indeterminate
      2018-11-23 18:00:18,924 DEBUG [alarmd-Thread-3-of-4] o.o.n.d.h.AbstractDaoHibernate: criteria = Criteria [class=class org.opennms.netmgt.model.OnmsAcknowledgment,orders=[Order [attribute=ackTime, ascending=false], Order [attribute=id, ascending=false]],restrictions=[EqRestriction [attribute=refId, value=1470337]],distinct=false,limit=1]
      2018-11-23 18:00:18,931 DEBUG [alarmd-Thread-3-of-4] o.o.n.b.d.Bsmd: Handling alarm with id: 1470337, reduction key: uei.opennms.org/generic/traps/SNMP_Link_Down:00000000-0000-0000-0000-000000000000:1673:527305216 and severity: CLEARED and status: Indeterminate
      2018-11-23 18:00:18,942 DEBUG [alarmd-Thread-1-of-4] o.o.n.e.EventIpcManagerDefaultImpl: run: calling onEvent on alarmd for event {"uei":"uei.opennms.org/vendor/cisco/syslog/ifUp","time":"2018-11-23 17:54:51,000-0600","dbid":19431253,"source":"syslogd","nodeid":1673,"parms":[{"hostname":"7.192.16.6"}, {"syslogmessage":"%ETHPORT-5-IF_UP: Interface Ethernet111/1/41 is up in mode access"}, {"severity":"Notice"}, {"timestamp":"Nov 23 23:54:51"}, {"service":"local7"}, {"group1":"Ethernet111/1/41"}, {"ifDescr":"Ethernet111/1/41"}]}
      2018-11-23 18:00:18,942 DEBUG [alarmd-Thread-1-of-4] o.o.n.a.AlarmPersisterImpl: process: uei.opennms.org/vendor/cisco/syslog/ifUp; nodeid: 1673; ipaddr: 7.192.16.6; serviceid: null
      2018-11-23 18:00:18,943 DEBUG [alarmd-Thread-1-of-4] o.o.n.a.AlarmPersisterImpl: addOrReduceEventAsAlarm: looking for existing reduction key: uei.opennms.org/vendor/cisco/syslog/ifUp:00000000-0000-0000-0000-000000000000:1673:Ethernet111/1/41
      2018-11-23 18:00:18,943 DEBUG [alarmd-Thread-1-of-4] o.o.n.a.AlarmPersisterImpl: addOrReduceEventAsAlarm: reductionKey:uei.opennms.org/vendor/cisco/syslog/ifUp:00000000-0000-0000-0000-000000000000:1673:Ethernet111/1/41 not found, instantiating new alarm
      2018-11-23 18:00:18,966 DEBUG [alarmd-Thread-1-of-4] o.o.n.a.d.DroolsAlarmContext: Inserting alarm into session: OnmsAlarm{alarmid=1470371, distPoller=OnmsDistPoller{id=00000000-0000-0000-0000-000000000000, label=localhost, location=Default, type=OpenNMS}, uei=uei.opennms.org/vendor/cisco/syslog/ifUp, severity=CLEARED, lastEventTime=2018-11-23 17:54:51.0}
      2018-11-23 18:00:18,966 DEBUG [alarmd-Thread-1-of-4] o.o.n.d.h.AbstractDaoHibernate: criteria = Criteria [class=class org.opennms.netmgt.model.OnmsAcknowledgment,orders=[Order [attribute=ackTime, ascending=false], Order [attribute=id, ascending=false]],restrictions=[EqRestriction [attribute=refId, value=1470371]],distinct=false,limit=1]
      2018-11-23 18:00:18,971 DEBUG [alarmd-Thread-1-of-4] o.o.n.a.d.DroolsAlarmContext: Inserting first alarm acknowledgement into session: Acknowledgment ID:0 User:admin Time:2018-11-23 17:54:51.0 AckType:Alarm AckAction:Unacknowledge Acknowledable ID:1470371
      2018-11-23 18:00:18,971 DEBUG [alarmd-Thread-1-of-4] o.o.n.b.d.Bsmd: Handling alarm with id: 1470371, reduction key: uei.opennms.org/vendor/cisco/syslog/ifUp:00000000-0000-0000-0000-000000000000:1673:Ethernet111/1/41 and severity: CLEARED and status: Indeterminate
      2018-11-23 18:00:18,984 WARN  [alarmd-Thread-1-of-4] o.h.u.JDBCExceptionReporter: SQL Error: 0, SQLState: 23505
      2018-11-23 18:00:18,984 ERROR [alarmd-Thread-1-of-4] o.h.u.JDBCExceptionReporter: ERROR: duplicate key value violates unique constraint "alarm_reductionkey_idx"
        Detail: Key (reductionkey)=(uei.opennms.org/vendor/cisco/syslog/ifUp:00000000-0000-0000-0000-000000000000:1673:Ethernet111/1/41) already exists.
      2018-11-23 18:00:18,987 DEBUG [alarmd-Thread-1-of-4] o.o.n.e.a.AnnotationBasedEventListenerAdapter: Caught an unhandled exception while processing event uei.opennms.org/vendor/cisco/syslog/ifUp, for listener org.opennms.netmgt.alarmd.Alarmd@3f250786. Add EventExceptionHandler annotation to the listener
      org.springframework.dao.DataIntegrityViolationException: could not insert: [org.opennms.netmgt.model.OnmsAlarm]; SQL [insert into alarms (tticketId, tticketState, alarmAckTime, alarmAckUser, alarmType, applicationDN, clearKey, counter, description, systemId, firstAutomationTime, firstEventTime, ifIndex, ipAddr, lastAutomationTime, lastEventId, lastEventTime, logmsg, managedObjectInstance, managedObjectType, mouseOverText, nodeId, operinstruct, ossPrimaryKey, qosAlarmState, reductionKey, serviceid, severity, stickymemo, suppressedTime, suppressedUntil, suppressedUser, eventUEI, x733AlarmType, x733ProbableCause, alarmId) values (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)]; constraint [alarm_reductionkey_idx]; nested exception is org.hibernate.exception.ConstraintViolationException: could not insert: [org.opennms.netmgt.model.OnmsAlarm]
              at org.springframework.orm.hibernate3.SessionFactoryUtils.convertHibernateAccessException(SessionFactoryUtils.java:659) ~[org.apache.servicemix.bundles.spring-orm-4.2.9.RELEASE_1.jar:?]
              at org.springframework.orm.hibernate3.HibernateTransactionManager.convertHibernateAccessException(HibernateTransactionManager.java:800) ~[org.apache.servicemix.bundles.spring-orm-4.2.9.RELEASE_1.jar:?]
              at org.springframework.orm.hibernate3.HibernateTransactionManager.doCommit(HibernateTransactionManager.java:670) ~[org.apache.servicemix.bundles.spring-orm-4.2.9.RELEASE_1.jar:?]
              at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:761) ~[org.apache.servicemix.bundles.spring-tx-4.2.9.RELEASE_1.jar:?]
              at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:730) ~[org.apache.servicemix.bundles.spring-tx-4.2.9.RELEASE_1.jar:?]
              at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:150) ~[org.apache.servicemix.bundles.spring-tx-4.2.9.RELEASE_1.jar:?]
              at org.opennms.netmgt.alarmd.AlarmPersisterImpl.persist(AlarmPersisterImpl.java:120) ~[opennms-alarmd-24.0.0-SNAPSHOT.jar:?]
              at org.opennms.netmgt.alarmd.Alarmd.onEvent(Alarmd.java:85) ~[opennms-alarmd-24.0.0-SNAPSHOT.jar:?]
              at sun.reflect.GeneratedMethodAccessor496.invoke(Unknown Source) ~[?:?]
              at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_112]
              at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_112]
              at org.opennms.netmgt.events.api.AnnotationBasedEventListenerAdapter.processEvent(AnnotationBasedEventListenerAdapter.java:221) [org.opennms.features.events.api-24.0.0-SNAPSHOT.jar:?]
              at org.opennms.netmgt.events.api.AnnotationBasedEventListenerAdapter$1.run(AnnotationBasedEventListenerAdapter.java:182) [org.opennms.features.events.api-24.0.0-SNAPSHOT.jar:?]
              at org.opennms.core.logging.Logging.withPrefix(Logging.java:71) [org.opennms.core.logging-24.0.0-SNAPSHOT.jar:?]
              at org.opennms.netmgt.events.api.AnnotationBasedEventListenerAdapter.onEvent(AnnotationBasedEventListenerAdapter.java:175) [org.opennms.features.events.api-24.0.0-SNAPSHOT.jar:?]
              at org.opennms.netmgt.eventd.EventIpcManagerDefaultImpl$EventListenerExecutor$2.run(EventIpcManagerDefaultImpl.java:189) [org.opennms.features.events.daemon-24.0.0-SNAPSHOT.jar:?]
              at java.util.concurrent.CompletableFuture$AsyncRun.run(CompletableFuture.java:1626) [?:1.8.0_112]
              at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [?:1.8.0_112]
              at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:1.8.0_112]
              at org.opennms.core.concurrent.LogPreservingThreadFactory$3.run(LogPreservingThreadFactory.java:124) [opennms-util-24.0.0-SNAPSHOT.jar:?]
              at java.lang.Thread.run(Thread.java:745) [?:1.8.0_112]
      Caused by: org.hibernate.exception.ConstraintViolationException: could not insert: [org.opennms.netmgt.model.OnmsAlarm]
              at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:96) ~[hibernate-core-3.6.10.Final.jar:3.6.10.Final]
              at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:66) ~[hibernate-core-3.6.10.Final.jar:3.6.10.Final]
              at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:2455) ~[hibernate-core-3.6.10.Final.jar:3.6.10.Final]
              at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:2875) ~[hibernate-core-3.6.10.Final.jar:3.6.10.Final]
              at org.hibernate.action.EntityInsertAction.execute(EntityInsertAction.java:79) ~[hibernate-core-3.6.10.Final.jar:3.6.10.Final]
              at org.hibernate.engine.ActionQueue.execute(ActionQueue.java:273) ~[hibernate-core-3.6.10.Final.jar:3.6.10.Final]
              at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:265) ~[hibernate-core-3.6.10.Final.jar:3.6.10.Final]
              at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:184) ~[hibernate-core-3.6.10.Final.jar:3.6.10.Final]
              at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:321) ~[hibernate-core-3.6.10.Final.jar:3.6.10.Final]
              at org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:51) ~[hibernate-core-3.6.10.Final.jar:3.6.10.Final]
              at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:1216) ~[hibernate-core-3.6.10.Final.jar:3.6.10.Final]
              at org.hibernate.impl.SessionImpl.managedFlush(SessionImpl.java:383) ~[hibernate-core-3.6.10.Final.jar:3.6.10.Final]
              at org.hibernate.transaction.JDBCTransaction.commit(JDBCTransaction.java:133) ~[hibernate-core-3.6.10.Final.jar:3.6.10.Final]
              at org.springframework.orm.hibernate3.HibernateTransactionManager.doCommit(HibernateTransactionManager.java:662) ~[org.apache.servicemix.bundles.spring-orm-4.2.9.RELEASE_1.jar:?]
              ... 18 more
      Caused by: org.postgresql.util.PSQLException: ERROR: duplicate key value violates unique constraint "alarm_reductionkey_idx"
        Detail: Key (reductionkey)=(uei.opennms.org/vendor/cisco/syslog/ifUp:00000000-0000-0000-0000-000000000000:1673:Ethernet111/1/41) already exists.
              at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2458) ~[postgresql-9.4.1211.jar:9.4.1211]
              at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2158) ~[postgresql-9.4.1211.jar:9.4.1211]
              at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:291) ~[postgresql-9.4.1211.jar:9.4.1211]
              at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:432) ~[postgresql-9.4.1211.jar:9.4.1211]
              at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:358) ~[postgresql-9.4.1211.jar:9.4.1211]
              at org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:171) ~[postgresql-9.4.1211.jar:9.4.1211]
              at org.postgresql.jdbc.PgPreparedStatement.executeUpdate(PgPreparedStatement.java:138) ~[postgresql-9.4.1211.jar:9.4.1211]
              at com.zaxxer.hikari.pool.ProxyPreparedStatement.executeUpdate(ProxyPreparedStatement.java:61) ~[HikariCP-2.5.1.jar:?]
              at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeUpdate(HikariProxyPreparedStatement.java) ~[HikariCP-2.5.1.jar:?]
              at org.hibernate.jdbc.NonBatchingBatcher.addToBatch(NonBatchingBatcher.java:46) ~[hibernate-core-3.6.10.Final.jar:3.6.10.Final]
              at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:2435) ~[hibernate-core-3.6.10.Final.jar:3.6.10.Final]
              at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:2875) ~[hibernate-core-3.6.10.Final.jar:3.6.10.Final]
              at org.hibernate.action.EntityInsertAction.execute(EntityInsertAction.java:79) ~[hibernate-core-3.6.10.Final.jar:3.6.10.Final]
              at org.hibernate.engine.ActionQueue.execute(ActionQueue.java:273) ~[hibernate-core-3.6.10.Final.jar:3.6.10.Final]
              at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:265) ~[hibernate-core-3.6.10.Final.jar:3.6.10.Final]
              at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:184) ~[hibernate-core-3.6.10.Final.jar:3.6.10.Final]
              at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:321) ~[hibernate-core-3.6.10.Final.jar:3.6.10.Final]
              at org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:51) ~[hibernate-core-3.6.10.Final.jar:3.6.10.Final]
              at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:1216) ~[hibernate-core-3.6.10.Final.jar:3.6.10.Final]
              at org.hibernate.impl.SessionImpl.managedFlush(SessionImpl.java:383) ~[hibernate-core-3.6.10.Final.jar:3.6.10.Final]
              at org.hibernate.transaction.JDBCTransaction.commit(JDBCTransaction.java:133) ~[hibernate-core-3.6.10.Final.jar:3.6.10.Final]
              at org.springframework.orm.hibernate3.HibernateTransactionManager.doCommit(HibernateTransactionManager.java:662) ~[org.apache.servicemix.bundles.spring-orm-4.2.9.RELEASE_1.jar:?]
              ... 18 more
      2018-11-23 18:00:19,793 DEBUG [Timer-1] o.o.n.a.d.DroolsAlarmContext: Firing rules.
      

        Attachments

          Issue Links

            Activity

              People

              • Assignee:
                smith David Smith
                Reporter:
                j-white Jesse White
              • Votes:
                0 Vote for this issue
                Watchers:
                2 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: