linkd needs to "upsert" entries in the ipRouteInterface, atinterface, vlan tables

I've changed the Hibernate code behind these updates to do the right thing now. For some reason, most of the code was properly upserting, just the vlan and iprouteinterface DAOs were overlooked somehow. :/ But it's fixed now!

commit e2658478a61cb9adceaa15c9bbf795553e7a2470

I dare you to a fresh log from a run including your commit:

org.springframework.dao.DataIntegrityViolationException: could not insert: [org.opennms.netmgt.model.OnmsVlan]; SQL [insert into vlan (lastPollTime, nodeId, status, vlanId, vlanName, vlanStatus, vlanType, id) values (?, ?, ?, ?, ?, ?, ?, ?)]; constraint [pk_vlan]; nested exception is org.hibernate.exception.ConstraintViolationException: could not insert: [org.opennms.netmgt.model.OnmsVlan]
at org.springframework.orm.hibernate3.SessionFactoryUtils.convertHibernateAccessException(SessionFactoryUtils.java:637)
at org.springframework.orm.hibernate3.HibernateAccessor.convertHibernateAccessException(HibernateAccessor.java:412)
at org.springframework.orm.hibernate3.HibernateTemplate.doExecute(HibernateTemplate.java:411)
at org.springframework.orm.hibernate3.HibernateTemplate.executeWithNativeSession(HibernateTemplate.java:374)
at org.springframework.orm.hibernate3.HibernateTemplate.saveOrUpdate(HibernateTemplate.java:737)
at org.opennms.netmgt.dao.hibernate.AbstractDaoHibernate.saveOrUpdate(AbstractDaoHibernate.java:425)
at org.opennms.netmgt.linkd.HibernateEventWriter.saveVlan(HibernateEventWriter.java:538)
at org.opennms.netmgt.linkd.AbstractQueryManager.processVlanTable(AbstractQueryManager.java:493)
at org.opennms.netmgt.linkd.HibernateEventWriter.storeSnmpCollection(HibernateEventWriter.java:205)
at org.opennms.netmgt.linkd.Linkd.updateNodeSnmpCollection(Linkd.java:570)
at org.opennms.netmgt.linkd.SnmpCollection.run(SnmpCollection.java:516)
at org.opennms.netmgt.linkd.scheduler.Scheduler$1.run(Scheduler.java:301)
at org.opennms.core.concurrent.RunnableConsumerThreadPool$FiberThreadImpl.run(RunnableConsumerThreadPool.java:420)
at java.lang.Thread.run(Thread.java:662)
Caused by: org.hibernate.exception.ConstraintViolationException: could not insert: [org.opennms.netmgt.model.OnmsVlan]
at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:94)
at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:66)
at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:2295)
at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:2688)
at org.hibernate.action.EntityInsertAction.execute(EntityInsertAction.java:79)
at org.hibernate.engine.ActionQueue.execute(ActionQueue.java:279)
at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:263)
at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:167)
at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:321)
at org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:50)
at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:1027)
at org.springframework.orm.hibernate3.HibernateAccessor.flushIfNecessary(HibernateAccessor.java:390)
at org.springframework.orm.hibernate3.HibernateTemplate.doExecute(HibernateTemplate.java:407)
... 11 more

-A

Grrr, I'm going to try and improve the logging for this issue and add some unit tests for the DAO code. Let me know if you see any similar stack traces for the iprouteinterface table. Thanks for the testing!!

Hi Alex, can you try this patch out on your system? It uses Matt's new UpsertTemplate code to perform the database update which may solve this issue. I need to check with him to make sure I'm using it properly but try it out and see if there's any improvement in the meantime. Thanks!

Build du jour, with your patch, gives:

2011-11-03 08:56:08,678 DEBUG [LinkdScheduler-1 Pool-fiber0] HibernateEventWriter: processVlanTable: Saving VLAN entry: org.opennms.netmgt.model.OnmsVlan@8dba6b[dbId=<null>,node=[OnmsNode@1ea2b4b id = 2, label = 'boxed-home-sw-1.boxed.no', parent.id = 'null', createTime = 2011-11-03 08:51:14.756, sysObjectId = '.1.3.6.1.4.1.9.1.799', sysName = 'boxed-home-sw-1.boxed.no', sysDescription = 'Cisco IOS Software, C2960 Software (C2960-LANBASEK9-M), Version 12.2(40)SE, RELEASE SOFTWARE (fc3)..Copyright (c) 1986-2007 by Cisco Systems, Inc...Compiled Fri 24-Aug-07 01:55 by myl', sysLocation = [null], sysContact = [null], type = 'A', operatingSystem = [null]],id=1,name=default,type=1,status=1,dbStatus=A,lastPollTime=2011-11-03 08:56:08.15]
2011-11-03 08:56:08,681 DEBUG [LinkdScheduler-1 Pool-fiber0] RunnableConsumerThreadPool$FiberThreadImpl: run: an unexpected error occured during fiber run, calling error liseners
2011-11-03 08:56:08,681 ERROR [LinkdScheduler-1 Pool-fiber0] RunnableConsumerThreadPool$FiberThreadImpl: No error listeners defined for unexpected error: org.springframework.dao.InvalidDataAccessApiUsageException: The given object has a null identifier: org.opennms.netmgt.model.OnmsVlan; nested exception is org.hibernate.TransientObjectException: The given object has a null identifier: org.opennms.netmgt.model.OnmsVlan
org.springframework.dao.InvalidDataAccessApiUsageException: The given object has a null identifier: org.opennms.netmgt.model.OnmsVlan; nested exception is org.hibernate.TransientObjectException: The given object has a null identifier: org.opennms.netmgt.model.OnmsVlan
at org.springframework.orm.hibernate3.SessionFactoryUtils.convertHibernateAccessException(SessionFactoryUtils.java:654)
at org.springframework.orm.hibernate3.HibernateAccessor.convertHibernateAccessException(HibernateAccessor.java:412)
at org.springframework.orm.hibernate3.HibernateTemplate.doExecute(HibernateTemplate.java:411)
at org.springframework.orm.hibernate3.HibernateTemplate.executeWithNativeSession(HibernateTemplate.java:374)
at org.springframework.orm.hibernate3.HibernateTemplate.update(HibernateTemplate.java:705)
at org.springframework.orm.hibernate3.HibernateTemplate.update(HibernateTemplate.java:701)
at org.opennms.netmgt.dao.hibernate.AbstractDaoHibernate.update(AbstractDaoHibernate.java:435)
at org.opennms.netmgt.linkd.HibernateEventWriter$2.doUpdate(HibernateEventWriter.java:560)
at org.opennms.netmgt.linkd.HibernateEventWriter$2.doUpdate(HibernateEventWriter.java:545)
at org.opennms.netmgt.dao.support.UpsertTemplate.update(UpsertTemplate.java:183)
at org.opennms.netmgt.dao.support.UpsertTemplate.doUpsert(UpsertTemplate.java:161)
at org.opennms.netmgt.dao.support.UpsertTemplate.access$000(UpsertTemplate.java:124)
at org.opennms.netmgt.dao.support.UpsertTemplate$1.doInTransaction(UpsertTemplate.java:148)
at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:130)
at org.opennms.netmgt.dao.support.UpsertTemplate.execute(UpsertTemplate.java:144)
at org.opennms.netmgt.linkd.HibernateEventWriter.saveVlan(HibernateEventWriter.java:545)
at org.opennms.netmgt.linkd.AbstractQueryManager.processVlanTable(AbstractQueryManager.java:493)
at org.opennms.netmgt.linkd.HibernateEventWriter.storeSnmpCollection(HibernateEventWriter.java:210)
at org.opennms.netmgt.linkd.Linkd.updateNodeSnmpCollection(Linkd.java:570)
at org.opennms.netmgt.linkd.SnmpCollection.run(SnmpCollection.java:516)
at org.opennms.netmgt.linkd.scheduler.Scheduler$1.run(Scheduler.java:301)
at org.opennms.core.concurrent.RunnableConsumerThreadPool$FiberThreadImpl.run(RunnableConsumerThreadPool.java:420)
at java.lang.Thread.run(Thread.java:662)
Caused by: org.hibernate.TransientObjectException: The given object has a null identifier: org.opennms.netmgt.model.OnmsVlan
at org.hibernate.event.def.DefaultSaveOrUpdateEventListener.getUpdateId(DefaultSaveOrUpdateEventListener.java:272)
at org.hibernate.event.def.DefaultUpdateEventListener.getUpdateId(DefaultUpdateEventListener.java:69)
at org.hibernate.event.def.DefaultSaveOrUpdateEventListener.entityIsDetached(DefaultSaveOrUpdateEventListener.java:240)
at org.hibernate.event.def.DefaultUpdateEventListener.performSaveOrUpdate(DefaultUpdateEventListener.java:56)
at org.hibernate.event.def.DefaultSaveOrUpdateEventListener.onSaveOrUpdate(DefaultSaveOrUpdateEventListener.java:93)
at org.hibernate.impl.SessionImpl.fireUpdate(SessionImpl.java:591)
at org.hibernate.impl.SessionImpl.update(SessionImpl.java:579)
at org.hibernate.impl.SessionImpl.update(SessionImpl.java:571)
at org.springframework.orm.hibernate3.HibernateTemplate$14.doInHibernate(HibernateTemplate.java:708)
at org.springframework.orm.hibernate3.HibernateTemplate.doExecute(HibernateTemplate.java:406)
... 20 more

I'm also seeing this issue on the atinterface table on a new test system:

2011-11-14 11:17:26,938 WARN [LinkdScheduler-5 Pool-fiber3] HibernateEventWriter: processIpNetToMediaTable: no node found for IP address 64.0.0.9.
2011-11-14 11:17:26,939 WARN [LinkdScheduler-5 Pool-fiber3] HibernateEventWriter: processIpNetToMediaTable: no node found for IP address 64.0.0.12.
2011-11-14 11:17:26,943 WARN [LinkdScheduler-5 Pool-fiber3] HibernateEventWriter: processIpNetToMediaTable: Setting MAC address to 000f24562b80 but it used to be '' (IP Address = 64.119.133.225, ifIndex = 16)
2011-11-14 11:17:26,943 WARN [LinkdScheduler-5 Pool-fiber3] HibernateEventWriter: processIpNetToMediaTable: Setting ifIndex to 16 but it used to be '-1' (IP Address = 64.119.133.225, MAC = 000f24562b80)
2011-11-14 11:17:26,945 WARN [LinkdScheduler-5 Pool-fiber1] HibernateEventWriter: processIpNetToMediaTable: Setting MAC address to 001e4afc1f76 but it used to be '' (IP Address = 64.119.133.226, ifIndex = 16)
2011-11-14 11:17:26,945 WARN [LinkdScheduler-5 Pool-fiber1] HibernateEventWriter: processIpNetToMediaTable: Setting ifIndex to 16 but it used to be '-1' (IP Address = 64.119.133.226, MAC = 001e4afc1f76)
2011-11-14 11:17:26,956 WARN [LinkdScheduler-5 Pool-fiber1] HibernateEventWriter: processRouteTable: interface has an invalid ifType (-1). Skipping.
2011-11-14 11:17:26,961 WARN [LinkdScheduler-5 Pool-fiber1] HibernateEventWriter: processRouteTable: No node ID found for next hop IP address 0.0.0.0. Not adding the IP route interface to the linkable SNMP node.
2011-11-14 11:17:26,964 WARN [LinkdScheduler-5 Pool-fiber1] HibernateEventWriter: processRouteTable: No node ID found for next hop IP address 0.0.0.0. Not adding the IP route interface to the linkable SNMP node.
2011-11-14 11:17:26,982 ERROR [LinkdScheduler-5 Pool-fiber3] RunnableConsumerThreadPool$FiberThreadImpl: No error listeners defined for unexpected error: org.springframework.dao.DataIntegrityViolationException: could not insert: [org.opennms.netmgt.model.OnmsAtInterface]; SQL [insert into atInterface (ifIndex, ipAddr, lastPollTime, atPhysAddr, nodeId, sourceNodeId, status, id) values (?, ?, ?, ?, ?, ?, ?, ?)]; constraint [pk_atinterface]; nested exception is org.hiberna
te.exception.ConstraintViolationException: could not insert: [org.opennms.netmgt.model.OnmsAtInterface]
org.springframework.dao.DataIntegrityViolationException: could not insert: [org.opennms.netmgt.model.OnmsAtInterface]; SQL [insert into atInterface (ifIndex, ipAddr, lastPollTime, atPhysAddr, nodeId, sourceNodeId, status, id) values (?, ?, ?, ?, ?, ?, ?, ?)]; constraint [pk_atinterface]; nested exception is org.hibernate.exception.ConstraintViolationException: could not insert: [org.opennms.netmgt.model.OnmsAtInterface]
at org.springframework.orm.hibernate3.SessionFactoryUtils.convertHibernateAccessException(SessionFactoryUtils.java:637)
at org.springframework.orm.hibernate3.HibernateAccessor.convertHibernateAccessException(HibernateAccessor.java:412)
at org.springframework.orm.hibernate3.HibernateTemplate.doExecute(HibernateTemplate.java:411)
at org.springframework.orm.hibernate3.HibernateTemplate.executeWithNativeSession(HibernateTemplate.java:374)
at org.springframework.orm.hibernate3.HibernateTemplate.saveOrUpdate(HibernateTemplate.java:737)
at org.opennms.netmgt.dao.hibernate.AbstractDaoHibernate.saveOrUpdate(AbstractDaoHibernate.java:425)
at org.opennms.netmgt.linkd.HibernateEventWriter.saveAtInterface(HibernateEventWriter.java:509)
at org.opennms.netmgt.linkd.AbstractQueryManager.processIpNetToMediaTable(AbstractQueryManager.java:184)
at org.opennms.netmgt.linkd.HibernateEventWriter.storeSnmpCollection(HibernateEventWriter.java:194)
at org.opennms.netmgt.linkd.Linkd.updateNodeSnmpCollection(Linkd.java:572)
at org.opennms.netmgt.linkd.SnmpCollection.run(SnmpCollection.java:522)
at org.opennms.netmgt.linkd.scheduler.Scheduler$1.run(Scheduler.java:301)
at org.opennms.core.concurrent.RunnableConsumerThreadPool$FiberThreadImpl.run(RunnableConsumerThreadPool.java:420)
at java.lang.Thread.run(Thread.java:662)
Caused by: org.hibernate.exception.ConstraintViolationException: could not insert: [org.opennms.netmgt.model.OnmsAtInterface]
at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:94)
at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:66)
at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:2295)
at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:2688)
at org.hibernate.action.EntityInsertAction.execute(EntityInsertAction.java:79)
at org.hibernate.engine.ActionQueue.execute(ActionQueue.java:279)
at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:263)
at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:167)
at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:321)
at org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:50)
at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:1027)
at org.springframework.orm.hibernate3.HibernateAccessor.flushIfNecessary(HibernateAccessor.java:390)
at org.springframework.orm.hibernate3.HibernateTemplate.doExecute(HibernateTemplate.java:407)
... 11 more
Caused by: org.postgresql.util.PSQLException: ERROR: duplicate key value violates unique constraint "pk_atinterface"
at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2102)
at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1835)
at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:257)
at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:500)
at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:388)
at org.postgresql.jdbc2.AbstractJdbc2Statement.executeUpdate(AbstractJdbc2Statement.java:334)
at com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeUpdate(NewProxyPreparedStatement.java:105)
at org.hibernate.jdbc.NonBatchingBatcher.addToBatch(NonBatchingBatcher.java:46)
at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:2275)
... 21 more

From your latest commit:
+ if (m_bridgeNodes.size() > 0)

Run a s/found/find/g.

There, now I can have claimed to have found a fault in the linkd source code!

-A

Fresh logs:

2011-11-16 00:18:26,999 DEBUG [LinkdScheduler-1 Pool-fiber0] HibernateEventWriter: processVlanTable: Saving VLAN entry: org.opennms.netmgt.model.OnmsVlan@89eaa9[dbId=<null>,node=[OnmsNode@76911d id = 2, label = 'boxed-home-sw-1.boxed.no', parent.id = 'null', createTime = 2011-11-16 00:14:05.445, sysObjectId = '.1.3.6.1.4.1.9.1.799', sysName = 'boxed-home-sw-1.boxed.no', sysDescription = 'Cisco IOS Software, C2960 Software (C2960-LANBASEK9-M), Version 12.2(40)SE, RELEASE SOFTWARE (fc3)..Copyright (c) 1986-2007 by Cisco Systems, Inc...Compiled Fri 24-Aug-07 01:55 by myl', sysLocation = [null], sysContact = [null], type = 'A', operatingSystem = [null]],id=1,name=default,type=1,status=1,dbStatus=A,lastPollTime=2011-11-16 00:18:26.977]
2011-11-16 00:18:27,002 DEBUG [LinkdScheduler-1 Pool-fiber0] RunnableConsumerThreadPool$FiberThreadImpl: run: an unexpected error occured during fiber run, calling error liseners
2011-11-16 00:18:27,002 ERROR [LinkdScheduler-1 Pool-fiber0] RunnableConsumerThreadPool$FiberThreadImpl: No error listeners defined for unexpected error: org.springframework.dao.InvalidDataAccessApiUsageException: The given object has a null identifier: org.opennms.netmgt.model.OnmsVlan; nested exception is org.hibernate.TransientObjectException: The given object has a null identifier: org.opennms.netmgt.model.OnmsVlan
org.springframework.dao.InvalidDataAccessApiUsageException: The given object has a null identifier: org.opennms.netmgt.model.OnmsVlan; nested exception is org.hibernate.TransientObjectException: The given object has a null identifier: org.opennms.netmgt.model.OnmsVlan
at org.springframework.orm.hibernate3.SessionFactoryUtils.convertHibernateAccessException(SessionFactoryUtils.java:654)
at org.springframework.orm.hibernate3.HibernateAccessor.convertHibernateAccessException(HibernateAccessor.java:412)
at org.springframework.orm.hibernate3.HibernateTemplate.doExecute(HibernateTemplate.java:411)
at org.springframework.orm.hibernate3.HibernateTemplate.executeWithNativeSession(HibernateTemplate.java:374)
at org.springframework.orm.hibernate3.HibernateTemplate.update(HibernateTemplate.java:705)
at org.springframework.orm.hibernate3.HibernateTemplate.update(HibernateTemplate.java:701)
at org.opennms.netmgt.dao.hibernate.AbstractDaoHibernate.update(AbstractDaoHibernate.java:435)
at org.opennms.netmgt.linkd.HibernateEventWriter$2.doUpdate(HibernateEventWriter.java:560)
at org.opennms.netmgt.linkd.HibernateEventWriter$2.doUpdate(HibernateEventWriter.java:545)
at org.opennms.netmgt.dao.support.UpsertTemplate.update(UpsertTemplate.java:183)
at org.opennms.netmgt.dao.support.UpsertTemplate.doUpsert(UpsertTemplate.java:161)
at org.opennms.netmgt.dao.support.UpsertTemplate.access$000(UpsertTemplate.java:124)
at org.opennms.netmgt.dao.support.UpsertTemplate$1.doInTransaction(UpsertTemplate.java:148)
at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:130)
at org.opennms.netmgt.dao.support.UpsertTemplate.execute(UpsertTemplate.java:144)
at org.opennms.netmgt.linkd.HibernateEventWriter.saveVlan(HibernateEventWriter.java:545)
at org.opennms.netmgt.linkd.AbstractQueryManager.processVlanTable(AbstractQueryManager.java:493)
at org.opennms.netmgt.linkd.HibernateEventWriter.storeSnmpCollection(HibernateEventWriter.java:210)
at org.opennms.netmgt.linkd.Linkd.updateNodeSnmpCollection(Linkd.java:570)
at org.opennms.netmgt.linkd.SnmpCollection.run(SnmpCollection.java:516)
at org.opennms.netmgt.linkd.scheduler.Scheduler$1.run(Scheduler.java:301)
at org.opennms.core.concurrent.RunnableConsumerThreadPool$FiberThreadImpl.run(RunnableConsumerThreadPool.java:420)
at java.lang.Thread.run(Thread.java:662)
Caused by: org.hibernate.TransientObjectException: The given object has a null identifier: org.opennms.netmgt.model.OnmsVlan
at org.hibernate.event.def.DefaultSaveOrUpdateEventListener.getUpdateId(DefaultSaveOrUpdateEventListener.java:272)
at org.hibernate.event.def.DefaultUpdateEventListener.getUpdateId(DefaultUpdateEventListener.java:69)
at org.hibernate.event.def.DefaultSaveOrUpdateEventListener.entityIsDetached(DefaultSaveOrUpdateEventListener.java:240)
at org.hibernate.event.def.DefaultUpdateEventListener.performSaveOrUpdate(DefaultUpdateEventListener.java:56)
at org.hibernate.event.def.DefaultSaveOrUpdateEventListener.onSaveOrUpdate(DefaultSaveOrUpdateEventListener.java:93)
at org.hibernate.impl.SessionImpl.fireUpdate(SessionImpl.java:591)
at org.hibernate.impl.SessionImpl.update(SessionImpl.java:579)
at org.hibernate.impl.SessionImpl.update(SessionImpl.java:571)
at org.springframework.orm.hibernate3.HibernateTemplate$14.doInHibernate(HibernateTemplate.java:708)
at org.springframework.orm.hibernate3.HibernateTemplate.doExecute(HibernateTemplate.java:406)
... 20 more

This error with the UpsertTemplate code makes me think there is something wrong with the Hibernate mappings. This is not too surprising, the Hibernate impl of linkd's data access is brand new. I'm not looking at this right now but if anyone else wants to comb over the Hibernate annotations on OnmsVlan, OnmsIpRouteInterface, and OnmsAtInterface, that is probably a good place to look for the source of this problem.

And I fixed the s/found/find/g problems!

I just committed a fix (commit 04dad982af86bfb7e0103b4977d1ed020d6c7525) that should log additional information when these exceptions occur. Can you please try the new code out to see what the output is? The log messages should give you the value of the Hibernate identifier property. Also, if you could query the database for this value (if it is printed properly) it would also help to see the contents of the database alongside the log messages for the thread.

Will do. Building now.

Looks very similar; I'll get postgres to output a query log.

2011-11-17 00:03:58,088 ERROR [LinkdScheduler-1 Pool-fiber0] RunnableConsumerThreadPool$FiberThreadImpl: No error listeners defined for unexpected error: org.springframework.dao.InvalidDataAccessApiUsageException: The given object has a null identifier: org.opennms.netmgt.model.OnmsVlan; nested exception is org.hibernate.TransientObjectException: The given object has a null identifier: org.opennms.netmgt.model.OnmsVlan
org.springframework.dao.InvalidDataAccessApiUsageException: The given object has a null identifier: org.opennms.netmgt.model.OnmsVlan; nested exception is org.hibernate.TransientObjectException: The given object has a null identifier: org.opennms.netmgt.model.OnmsVlan
at org.springframework.orm.hibernate3.SessionFactoryUtils.convertHibernateAccessException(SessionFactoryUtils.java:654)
at org.springframework.orm.hibernate3.HibernateAccessor.convertHibernateAccessException(HibernateAccessor.java:412)
at org.springframework.orm.hibernate3.HibernateTemplate.doExecute(HibernateTemplate.java:411)
at org.springframework.orm.hibernate3.HibernateTemplate.executeWithNativeSession(HibernateTemplate.java:374)
at org.springframework.orm.hibernate3.HibernateTemplate.update(HibernateTemplate.java:705)
at org.springframework.orm.hibernate3.HibernateTemplate.update(HibernateTemplate.java:701)
at org.opennms.netmgt.dao.hibernate.AbstractDaoHibernate.update(AbstractDaoHibernate.java:445)
at org.opennms.netmgt.linkd.HibernateEventWriter$2.doUpdate(HibernateEventWriter.java:560)
at org.opennms.netmgt.linkd.HibernateEventWriter$2.doUpdate(HibernateEventWriter.java:545)
at org.opennms.netmgt.dao.support.UpsertTemplate.update(UpsertTemplate.java:183)
at org.opennms.netmgt.dao.support.UpsertTemplate.doUpsert(UpsertTemplate.java:161)
at org.opennms.netmgt.dao.support.UpsertTemplate.access$000(UpsertTemplate.java:124)
at org.opennms.netmgt.dao.support.UpsertTemplate$1.doInTransaction(UpsertTemplate.java:148)
at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:130)
at org.opennms.netmgt.dao.support.UpsertTemplate.execute(UpsertTemplate.java:144)
at org.opennms.netmgt.linkd.HibernateEventWriter.saveVlan(HibernateEventWriter.java:545)
at org.opennms.netmgt.linkd.AbstractQueryManager.processVlanTable(AbstractQueryManager.java:490)
at org.opennms.netmgt.linkd.HibernateEventWriter.storeSnmpCollection(HibernateEventWriter.java:210)
at org.opennms.netmgt.linkd.Linkd.updateNodeSnmpCollection(Linkd.java:576)
at org.opennms.netmgt.linkd.SnmpCollection.run(SnmpCollection.java:527)
at org.opennms.netmgt.linkd.scheduler.Scheduler$1.run(Scheduler.java:301)
at org.opennms.core.concurrent.RunnableConsumerThreadPool$FiberThreadImpl.run(RunnableConsumerThreadPool.java:420)
at java.lang.Thread.run(Thread.java:662)
at org.hibernate.event.def.DefaultSaveOrUpdateEventListener.getUpdateId(DefaultSaveOrUpdateEventListener.java:272)
at org.hibernate.event.def.DefaultUpdateEventListener.getUpdateId(DefaultUpdateEventListener.java:69)
at org.hibernate.event.def.DefaultSaveOrUpdateEventListener.entityIsDetached(DefaultSaveOrUpdateEventListener.java:240)
at org.hibernate.event.def.DefaultUpdateEventListener.performSaveOrUpdate(DefaultUpdateEventListener.java:56)
at org.hibernate.event.def.DefaultSaveOrUpdateEventListener.onSaveOrUpdate(DefaultSaveOrUpdateEventListener.java:93)
at org.hibernate.impl.SessionImpl.fireUpdate(SessionImpl.java:591)
at org.hibernate.impl.SessionImpl.update(SessionImpl.java:579)
at org.hibernate.impl.SessionImpl.update(SessionImpl.java:571)
at org.springframework.orm.hibernate3.HibernateTemplate$14.doInHibernate(HibernateTemplate.java:708)
at org.springframework.orm.hibernate3.HibernateTemplate.doExecute(HibernateTemplate.java:406)
... 20 more
2011-11-17 00:04:54,664 INFO [OpenNMS.Lin

There should be an additional log message printed before the stack trace that looks like:

Null identifier on object, class: OnmsVlan: ...

and I'm interested in the content at the end of the log message.

Ah, here we go:

2011-11-17 00:11:36,775 WARN [LinkdScheduler-1 Pool-fiber0] VlanDaoHibernate: Null identifier on object, class: org.opennms.netmgt.model.OnmsVlan: org.opennms.netmgt.model.OnmsVlan@1ad0070[dbId=<null>,node=[OnmsNode@a88b1c id = 2, label = 'boxed-home-sw-1.boxed.no', parent.id = 'null', createTime = 2011-11-16 23:59:39.88, sysObjectId = '.1.3.6.1.4.1.9.1.799', sysName = 'boxed-home-sw-1.boxed.no', sysDescription = 'Cisco IOS Software, C2960 Software (C2960-LANBASEK9-M), Version 12.2(40)SE, RELEASE SOFTWARE (fc3)..Copyright (c) 1986-2007 by Cisco Systems, Inc...Compiled Fri 24-Aug-07 01:55 by myl', sysLocation = [null], sysContact = [null], type = 'A', operatingSystem = [null]],id=1,name=default,type=1,status=1,dbStatus=A,lastPollTime=2011-11-17 00:11:36.706]

Here's the same from the query log, with a ROLLBACK:

Nov 17 00:26:28 linkd postgres[9570]: [215-1] 2011-11-17 00:26:28 CET 4ec44542.2562 opennms LOG: execute S_1: BEGIN
Nov 17 00:26:28 linkd postgres[9570]: [216-1] 2011-11-17 00:26:28 CET 4ec44542.2562 opennms LOG: execute <unnamed>: select onmsnode0_.nodeId as nodeId1_0_, onmsnode0_.nodeCreateTime as nodeCrea2_1_0_, onmsnode0_.dpName as dpName1_0_, onmsnode0_.foreignId as foreignId1_0_, onmsnode0_.foreignSource as foreignS4_1_0_, onmsnode0_.nodeLabel as nodeLabel1_0_, onmsnode0_.nodeLabelSource as nodeLabe6_1_0_, onmsnode0_.lastCapsdPoll as lastCaps7_1_0_, onmsnode0_.nodeDomainName as nodeDoma8_1_0_, onmsnode0_.nodeNetBIOSName as nodeNetB9_1_0_, onmsnode0_.operatingSystem as operati10_1_0_, onmsnode0_.nodeParentID as nodePar18_1_0_, onmsnode0_.nodeSysContact as nodeSys11_1_0_, onmsnode0_.nodeSysDescription as nodeSys12_1_0_, onmsnode0_.nodeSysLocation as nodeSys13_1_0_, onmsnode0_.nodeSysName as nodeSys14_1_0_, onmsnode0_.nodeSysOID as nodeSysOID1_0_, onmsnode0_.nodeType as nodeType1_0_, onmsnode0_1_.criticalPathIp as critical1_2_0_, onmsnode0_1_.criticalPathServiceName as critical2_2_0_ from node onmsnode0_ left outer jo
Nov 17 00:26:28 linkd postgres[9570]: [216-3] 2011-11-17 00:26:28 CET 4ec44542.2562 opennms DETAIL: parameters: $1 = '2'
Nov 17 00:26:28 linkd postgres[9570]: [217-1] 2011-11-17 00:26:28 CET 4ec44542.2562 opennms LOG: execute <unnamed>: select onmsassetr0_.id as id4_0_, onmsassetr0_.additionalhardware as addition2_4_0_, onmsassetr0_.address1 as address3_4_0_, onmsassetr0_.address2 as address4_4_0_, onmsassetr0_.admin as admin4_0_, onmsassetr0_.assetNumber as assetNum6_4_0_, onmsassetr0_.autoenable as autoenable4_0_, onmsassetr0_.building as building4_0_, onmsassetr0_.category as category4_0_, onmsassetr0_.circuitId as circuitId4_0_, onmsassetr0_.city as city4_0_, onmsassetr0_.comment as comment4_0_, onmsassetr0_.connection as connection4_0_, onmsassetr0_.cpu as cpu4_0_, onmsassetr0_.dateInstalled as dateIns15_4_0_, onmsassetr0_.department as department4_0_, onmsassetr0_.description as descrip17_4_0_, onmsassetr0_.displayCategory as display18_4_0_, onmsassetr0_.division as division4_0_, onmsassetr0_.enable as enable4_0_, onmsassetr0_.floor as floor4_0_, onmsassetr0_.hdd1 as hdd22_4_0_, onmsassetr0_.hdd2 as hdd23_4_0_, onmsasse
Nov 17 00:26:28 linkd postgres[9570]: [217-4] 2011-11-17 00:26:28 CET 4ec44542.2562 opennms DETAIL: parameters: $1 = '2'
Nov 17 00:26:28 linkd postgres[9570]: [218-1] 2011-11-17 00:26:28 CET 4ec44542.2562 opennms LOG: execute <unnamed>: select ipinterfac0_.nodeId as nodeId1_, ipinterfac0_.id as id1_, ipinterfac0_.id as id0_0_, ipinterfac0_.ipAddr as ipAddr0_0_, ipinterfac0_.ipHostName as ipHostName0_0_, ipinterfac0_.ipLastCapsdPoll as ipLastCa4_0_0_, ipinterfac0_.isManaged as isManaged0_0_, ipinterfac0_.isSnmpPrimary as isSnmpPr6_0_0_, ipinterfac0_.nodeId as nodeId0_0_, ipinterfac0_.snmpInterfaceId as snmpInte8_0_0_ from ipInterface ipinterfac0_ where ipinterfac0_.nodeId=$1
Nov 17 00:26:28 linkd postgres[9570]: [218-2] 2011-11-17 00:26:28 CET 4ec44542.2562 opennms DETAIL: parameters: $1 = '2'
Nov 17 00:26:28 linkd postgres[9570]: [219-1] 2011-11-17 00:26:28 CET 4ec44542.2562 opennms LOG: execute S_3: ROLLBACK

I just committed some changes to the Hibernate mappings for a lot of the DAO objects, please try them out to see if they make a difference. Note that the changes are in the opennms-model JAR.

From the log above, we can see that the @Id field of OnmsVlan is null (dbId=<null>) and this is causing Hibernate to refuse to update the row. Also from the stack trace, we can see that it's trying to update an existing row... maybe the ID of the existing object isn't being pulled from the database properly?? I'm still investigating.

Pulled git and cooking up build du jour. I build the whole thing with a clean first, so everything gets built.

Still going strong:

2011-11-17 17:58:43,381 DEBUG [LinkdScheduler-1 Pool-fiber0] HibernateEventWriter: processVlanTable: Saving VLAN entry: org.opennms.netmgt.model.OnmsVlan@1aa246e[dbId=<null>,node=[OnmsNode@1c90b1 id = 2, label = 'boxed-home-sw-1.boxed.no', parent.id = 'null', createTime = 2011-11-17 17:54:19.096, sysObjectId = '.1.3.6.1.4.1.9.1.799', sysName = 'boxed-home-sw-1.boxed.no', sysDescription = 'Cisco IOS Software, C2960 Software (C2960-LANBASEK9-M), Version 12.2(40)SE, RELEASE SOFTWARE (fc3)..Copyright (c) 1986-2007 by Cisco Systems, Inc...Compiled Fri 24-Aug-07 01:55 by myl', sysLocation = [null], sysContact = [null], type = 'A', operatingSystem = [null]],id=1,name=default,type=1,status=1,dbStatus=A,lastPollTime=2011-11-17 17:58:43.33]
2011-11-17 17:58:43,390 WARN [LinkdScheduler-1 Pool-fiber0] VlanDaoHibernate: Null identifier on object, class: org.opennms.netmgt.model.OnmsVlan: org.opennms.netmgt.model.OnmsVlan@1aa246e[dbId=<null>,node=[OnmsNode@1c90b1 id = 2, label = 'boxed-home-sw-1.boxed.no', parent.id = 'null', createTime = 2011-11-17 17:54:19.096, sysObjectId = '.1.3.6.1.4.1.9.1.799', sysName = 'boxed-home-sw-1.boxed.no', sysDescription = 'Cisco IOS Software, C2960 Software (C2960-LANBASEK9-M), Version 12.2(40)SE, RELEASE SOFTWARE (fc3)..Copyright (c) 1986-2007 by Cisco Systems, Inc...Compiled Fri 24-Aug-07 01:55 by myl', sysLocation = [null], sysContact = [null], type = 'A', operatingSystem = [null]],id=1,name=default,type=1,status=1,dbStatus=A,lastPollTime=2011-11-17 17:58:43.33]
2011-11-17 17:58:43,391 DEBUG [LinkdScheduler-1 Pool-fiber0] RunnableConsumerThreadPool$FiberThreadImpl: run: an unexpected error occured during fiber run, calling error liseners
2011-11-17 17:58:43,391 ERROR [LinkdScheduler-1 Pool-fiber0] RunnableConsumerThreadPool$FiberThreadImpl: No error listeners defined for unexpected error: org.springframework.dao.InvalidDataAccessApiUsageException: The given object has a null identifier: org.opennms.netmgt.model.OnmsVlan; nested exception is org.hibernate.TransientObjectException: The given object has a null identifier: org.opennms.netmgt.model.OnmsVlan
org.springframework.dao.InvalidDataAccessApiUsageException: The given object has a null identifier: org.opennms.netmgt.model.OnmsVlan; nested exception is org.hibernate.TransientObjectException: The given object has a null identifier: org.opennms.netmgt.model.OnmsVlan
at org.springframework.orm.hibernate3.SessionFactoryUtils.convertHibernateAccessException(SessionFactoryUtils.java:654)
at org.springframework.orm.hibernate3.HibernateAccessor.convertHibernateAccessException(HibernateAccessor.java:412)
at org.springframework.orm.hibernate3.HibernateTemplate.doExecute(HibernateTemplate.java:411)
at org.springframework.orm.hibernate3.HibernateTemplate.executeWithNativeSession(HibernateTemplate.java:374)
at org.springframework.orm.hibernate3.HibernateTemplate.update(HibernateTemplate.java:705)
at org.springframework.orm.hibernate3.HibernateTemplate.update(HibernateTemplate.java:701)
at org.opennms.netmgt.dao.hibernate.AbstractDaoHibernate.update(AbstractDaoHibernate.java:445)
at org.opennms.netmgt.linkd.HibernateEventWriter$2.doUpdate(HibernateEventWriter.java:560)
at org.opennms.netmgt.linkd.HibernateEventWriter$2.doUpdate(HibernateEventWriter.java:545)
at org.opennms.netmgt.dao.support.UpsertTemplate.update(UpsertTemplate.java:183)
at org.opennms.netmgt.dao.support.UpsertTemplate.doUpsert(UpsertTemplate.java:161)
at org.opennms.netmgt.dao.support.UpsertTemplate.access$000(UpsertTemplate.java:124)
at org.opennms.netmgt.dao.support.UpsertTemplate$1.doInTransaction(UpsertTemplate.java:148)
at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:130)
at org.opennms.netmgt.dao.support.UpsertTemplate.execute(UpsertTemplate.java:144)
at org.opennms.netmgt.linkd.HibernateEventWriter.saveVlan(HibernateEventWriter.java:545)
at org.opennms.netmgt.linkd.AbstractQueryManager.processVlanTable(AbstractQueryManager.java:490)
at org.opennms.netmgt.linkd.HibernateEventWriter.storeSnmpCollection(HibernateEventWriter.java:210)
at org.opennms.netmgt.linkd.Linkd.updateNodeSnmpCollection(Linkd.java:576)
at org.opennms.netmgt.linkd.SnmpCollection.run(SnmpCollection.java:527)
at org.opennms.netmgt.linkd.scheduler.Scheduler$1.run(Scheduler.java:301)
at org.opennms.core.concurrent.RunnableConsumerThreadPool$FiberThreadImpl.run(RunnableConsumerThreadPool.java:420)
at java.lang.Thread.run(Thread.java:662)

One more:

2011-11-17 21:35:16,119 WARN [LinkdScheduler-1 Pool-fiber0] VlanDaoHibernate: Null identifier on object, class: org.opennms.netmgt.model.OnmsVlan: org.opennms.netmgt.model.OnmsVlan@10362d0[dbId=<null>,node=[OnmsNode@897063 id = 2, label = 'boxed-home-sw-1.boxed.no', parent.id = 'null', createTime = 2011-11-17 21:30:50.931, sysObjectId = '.1.3.6.1.4.1.9.1.799', sysName = 'boxed-home-sw-1.boxed.no', sysDescription = 'Cisco IOS Software, C2960 Software (C2960-LANBASEK9-M), Version 12.2(40)SE, RELEASE SOFTWARE (fc3)..Copyright (c) 1986-2007 by Cisco Systems, Inc...Compiled Fri 24-Aug-07 01:55 by myl', sysLocation = [null], sysContact = [null], type = 'A', operatingSystem = [null]],id=1,name=default,type=1,status=1,dbStatus=A,lastPollTime=2011-11-17 21:35:16.055]
2011-11-17 21:35:16,120 DEBUG [LinkdScheduler-1 Pool-fiber0] RunnableConsumerThreadPool$FiberThreadImpl: run: an unexpected error occured during fiber run, calling error liseners
2011-11-17 21:35:16,120 ERROR [LinkdScheduler-1 Pool-fiber0] RunnableConsumerThreadPool$FiberThreadImpl: No error listeners defined for unexpected error: org.springframework.dao.InvalidDataAccessApiUsageException: The given object has a null identifier: org.opennms.netmgt.model.OnmsVlan; nested exception is org.hibernate.TransientObjectException: The given object has a null identifier: org.opennms.netmgt.model.OnmsVlan
org.springframework.dao.InvalidDataAccessApiUsageException: The given object has a null identifier: org.opennms.netmgt.model.OnmsVlan; nested exception is org.hibernate.TransientObjectException: The given object has a null identifier: org.opennms.netmgt.model.OnmsVlan
at org.springframework.orm.hibernate3.SessionFactoryUtils.convertHibernateAccessException(SessionFactoryUtils.java:654)
at org.springframework.orm.hibernate3.HibernateAccessor.convertHibernateAccessException(HibernateAccessor.java:412)
at org.springframework.orm.hibernate3.HibernateTemplate.doExecute(HibernateTemplate.java:411)
at org.springframework.orm.hibernate3.HibernateTemplate.executeWithNativeSession(HibernateTemplate.java:374)
at org.springframework.orm.hibernate3.HibernateTemplate.update(HibernateTemplate.java:705)
at org.springframework.orm.hibernate3.HibernateTemplate.update(HibernateTemplate.java:701)
at org.opennms.netmgt.dao.hibernate.AbstractDaoHibernate.update(AbstractDaoHibernate.java:445)
at org.opennms.netmgt.linkd.HibernateEventWriter$2.doUpdate(HibernateEventWriter.java:560)
at org.opennms.netmgt.linkd.HibernateEventWriter$2.doUpdate(HibernateEventWriter.java:545)
at org.opennms.netmgt.dao.support.UpsertTemplate.update(UpsertTemplate.java:183)
at org.opennms.netmgt.dao.support.UpsertTemplate.doUpsert(UpsertTemplate.java:161)
at org.opennms.netmgt.dao.support.UpsertTemplate.access$000(UpsertTemplate.java:124)
at org.opennms.netmgt.dao.support.UpsertTemplate$1.doInTransaction(UpsertTemplate.java:148)
at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:130)
at org.opennms.netmgt.dao.support.UpsertTemplate.execute(UpsertTemplate.java:144)
at org.opennms.netmgt.linkd.HibernateEventWriter.saveVlan(HibernateEventWriter.java:545)
at org.opennms.netmgt.linkd.AbstractQueryManager.processVlanTable(AbstractQueryManager.java:490)
at org.opennms.netmgt.linkd.HibernateEventWriter.storeSnmpCollection(HibernateEventWriter.java:210)
at org.opennms.netmgt.linkd.Linkd.updateNodeSnmpCollection(Linkd.java:576)
at org.opennms.netmgt.linkd.SnmpCollection.run(SnmpCollection.java:527)
at org.opennms.netmgt.linkd.scheduler.Scheduler$1.run(Scheduler.java:301)
at org.opennms.core.concurrent.RunnableConsumerThreadPool$FiberThreadImpl.run(RunnableConsumerThreadPool.java:420)
at java.lang.Thread.run(Thread.java:662)
Caused by: org.hibernate.TransientObjectException: The given object has a null identifier: org.opennms.netmgt.model.OnmsVlan
at org.hibernate.event.def.DefaultSaveOrUpdateEventListener.getUpdateId(DefaultSaveOrUpdateEventListener.java:272)
at org.hibernate.event.def.DefaultUpdateEventListener.getUpdateId(DefaultUpdateEventListener.java:69)
at org.hibernate.event.def.DefaultSaveOrUpdateEventListener.entityIsDetached(DefaultSaveOrUpdateEventListener.java:240)
at org.hibernate.event.def.DefaultUpdateEventListener.performSaveOrUpdate(DefaultUpdateEventListener.java:56)
at org.hibernate.event.def.DefaultSaveOrUpdateEventListener.onSaveOrUpdate(DefaultSaveOrUpdateEventListener.java:93)
at org.hibernate.impl.SessionImpl.fireUpdate(SessionImpl.java:591)
at org.hibernate.impl.SessionImpl.update(SessionImpl.java:579)
at org.hibernate.impl.SessionImpl.update(SessionImpl.java:571)
at org.springframework.orm.hibernate3.HibernateTemplate$14.doInHibernate(HibernateTemplate.java:708)
at org.springframework.orm.hibernate3.HibernateTemplate.doExecute(HibernateTemplate.java:406)

Relevant section of the query log:

Nov 17 21:35:11 linkd postgres[18089]: [559-1] 2011-11-17 21:35:11 CET 4ec56ec5.46a9 opennms LOG: execute S_1: BEGIN
Nov 17 21:35:11 linkd postgres[18089]: [560-1] 2011-11-17 21:35:11 CET 4ec56ec5.46a9 opennms LOG: execute <unnamed>: select this_.id as id21_1_, this_.lastPollTime as lastPoll2
21_1, this_.nodeId as nodeId21_1_, this_.status as status21_1_, this_.vlanId as vlanId21_1_, this_.vlanName as vlanName21_1_, this_.vlanStatus as vlanStatus21_1_, this_.vlanTy
pe as vlanType21_1_, node1_.nodeId as nodeId2_0_, node1_.nodeCreateTime as nodeCrea2_2_0_, node1_.dpName as dpName2_0_, node1_.foreignId as foreignId2_0_, node1_.foreignSource a
s foreignS4_2_0_, node1_.nodeLabel as nodeLabel2_0_, node1_.nodeLabelSource as nodeLabe6_2_0_, node1_.lastCapsdPoll as lastCaps7_2_0_, node1_.nodeDomainName as nodeDoma8_2_0_, n
ode1_.nodeNetBIOSName as nodeNetB9_2_0_, node1_.operatingSystem as operati10_2_0_, node1_.nodeParentID as nodePar18_2_0_, node1_.nodeSysContact as nodeSys11_2_0_, node1_.nodeSys
Description as nodeSys12_2_0_, node1_.nodeSysLocation as nodeSys13_2_0_, node1_.nodeSysName as nodeSys14_2_0_, node1_.nodeSysOID as nodeSy
Nov 17 21:35:11 linkd postgres[18089]: [560-2] node1_1_.criticalPathIp as critical1_3_0_, node1_1_.criticalPathServiceName as critical2_3_0_ from vlan this_ left outer join nod
e node1_ on this_.nodeId=node1_.nodeId left outer join pathOutage node1_1_ on node1_.nodeId=node1_1_.nodeId where node1_.nodeId=$1 and this_.vlanId=$2
Nov 17 21:35:11 linkd postgres[18089]: [560-3] 2011-11-17 21:35:11 CET 4ec56ec5.46a9 opennms DETAIL: parameters: $1 = '2', $2 = '1'
Nov 17 21:35:11 linkd postgres[18089]: [561-1] 2011-11-17 21:35:11 CET 4ec56ec5.46a9 opennms LOG: execute <unnamed>: select onmsassetr0_.id as id5_0_, onmsassetr0_.additionalha
rdware as addition2_5_0_, onmsassetr0_.address1 as address3_5_0_, onmsassetr0_.address2 as address4_5_0_, onmsassetr0_.admin as admin5_0_, onmsassetr0_.assetNumber as assetNum6_
5_0_, onmsassetr0_.autoenable as autoenable5_0_, onmsassetr0_.building as building5_0_, onmsassetr0_.category as category5_0_, onmsassetr0_.circuitId as circuitId5_0_, onmsasset
r0_.city as city5_0_, onmsassetr0_.comment as comment5_0_, onmsassetr0_.connection as connection5_0_, onmsassetr0_.cpu as cpu5_0_, onmsassetr0_.dateInstalled as dateIns15_5_0_,
onmsassetr0_.department as department5_0_, onmsassetr0_.description as descrip17_5_0_, onmsassetr0_.displayCategory as display18_5_0_, onmsassetr0_.division as division5_0_, onm
sassetr0_.enable as enable5_0_, onmsassetr0_.floor as floor5_0_, onmsassetr0_.hdd1 as hdd22_5_0_, onmsassetr0_.hdd2 as hdd23_5_0_, onmsass
Nov 17 21:35:11 linkd postgres[18089]: [561-2] hdd25_5_0_, onmsassetr0_.hdd5 as hdd26_5_0_, onmsassetr0_.hdd6 as hdd27_5_0_, onmsassetr0_.inputpower as inputpower5_0_, onmsasse
tr0_.userLastModified as userLas29_5_0_, onmsassetr0_.lastModifiedDate as lastMod30_5_0_, onmsassetr0_.lease as lease5_0_, onmsassetr0_.leaseExpires as leaseEx32_5_0_, onmsasset
r0_.maintContractExpires as maintCo33_5_0_, onmsassetr0_.maintcontract as maintco34_5_0_, onmsassetr0_.managedObjectInstance as managed35_5_0_, onmsassetr0_.managedObjectType as
managed36_5_0_, onmsassetr0_.manufacturer as manufac37_5_0_, onmsassetr0_.modelNumber as modelNu38_5_0_, onmsassetr0_.nodeId as nodeId5_0_, onmsassetr0_.notifyCategory as notif
yC39_5_0_, onmsassetr0_.numpowersupplies as numpowe40_5_0_, onmsassetr0_.operatingSystem as operati41_5_0_, onmsassetr0_.password as password5_0_, onmsassetr0_.pollerCategory as
pollerC43_5_0_, onmsassetr0_.port as port5_0_, onmsassetr0_.rack as rack5_0_, onmsassetr0_.rackunitheight as rackuni46_5_0_, onmsassetr0_
Nov 17 21:35:11 linkd postgres[18089]: [561-3] region5_0_, onmsassetr0_.room as room5_0_, onmsassetr0_.serialNumber as serialN50_5_0_, onmsassetr0_.slot as slot5_0_, onmsassetr
0_.snmpcommunity as snmpcom52_5_0_, onmsassetr0_.state as state5_0_, onmsassetr0_.storagectrl as storage54_5_0_, onmsassetr0_.supportPhone as support55_5_0_, onmsassetr0_.thresholdCategory as thresho56_5_0_, onmsassetr0_.username as username5_0_, onmsassetr0_.vendor as vendor5_0_, onmsassetr0_.vendorAssetNumber as vendorA59_5_0_, onmsassetr0_.vendorFax as vendorFax5_0_, onmsassetr0_.vendorPhone as vendorP61_5_0_, onmsassetr0_.zip as zip5_0_ from assets onmsassetr0_ where onmsassetr0_.nodeId=$1
Nov 17 21:35:11 linkd postgres[18089]: [561-4] 2011-11-17 21:35:11 CET 4ec56ec5.46a9 opennms DETAIL: parameters: $1 = '2'
Nov 17 21:35:11 linkd postgres[18089]: [562-1] 2011-11-17 21:35:11 CET 4ec56ec5.46a9 opennms LOG: execute S_15: ROLLBACK

OK, I've tracked down some concrete problems in the linkd (at last). First, the @Transactional annotations were not placed properly so I don't think any database transactions were working properly. There are also more upsert issues that I'm encountering once the transactions are in place. But basically I've been able to reproduce the primary key collisions (in atinterface anyway) that are in this bug inside a unit test. Now I just need to finish fixing the problems...

while seth.comment() do;
git pull
build
test
post.logs()
done

Less glorious NPEs this time:

2011-11-22 20:35:13,459 DEBUG [LinkdScheduler-1 Pool-fiber0] SnmpCollection: run: saving collection into database for 172.31.255.3
2011-11-22 20:35:13,459 DEBUG [LinkdScheduler-1 Pool-fiber0] Linkd: Updating SNMP collection for 172.31.255.3
2011-11-22 20:35:13,459 DEBUG [LinkdScheduler-1 Pool-fiber0] HibernateEventWriter: processIpNetToMediaTable: Starting ipNetToMedia table processing for 2/172.31.255.3
2011-11-22 20:35:13,459 DEBUG [LinkdScheduler-1 Pool-fiber0] HibernateEventWriter: processIpNetToMediaTable: trying save ipNetToMedia info: IP address 172.31.255.1, MAC address 000c29a4a5b2, ifIndex 100
2011-11-22 20:35:13,463 DEBUG [LinkdScheduler-1 Pool-fiber0] HibernateEventWriter: processIpNetToMediaTable: no node found for IP address 172.31.255.1.
2011-11-22 20:35:13,463 DEBUG [LinkdScheduler-1 Pool-fiber0] RunnableConsumerThreadPool$FiberThreadImpl: run: an unexpected error occured during fiber run, calling error liseners
2011-11-22 20:35:13,463 ERROR [LinkdScheduler-1 Pool-fiber0] RunnableConsumerThreadPool$FiberThreadImpl: No error listeners defined for unexpected error: java.lang.NullPointerException
java.lang.NullPointerException
at org.opennms.netmgt.linkd.AbstractQueryManager.sendNewSuspectEvent(AbstractQueryManager.java:80)
at org.opennms.netmgt.linkd.AbstractQueryManager.processIpNetToMediaTable(AbstractQueryManager.java:157)
at org.opennms.netmgt.linkd.HibernateEventWriter.storeSnmpCollection(HibernateEventWriter.java:192)
at org.opennms.netmgt.linkd.Linkd.updateNodeSnmpCollection(Linkd.java:580)
at org.opennms.netmgt.linkd.SnmpCollection.run(SnmpCollection.java:527)
at org.opennms.netmgt.linkd.scheduler.Scheduler$1.run(Scheduler.java:301)
at org.opennms.core.concurrent.RunnableConsumerThreadPool$FiberThreadImpl.run(RunnableConsumerThreadPool.java:420)
at java.lang.Thread.run(Thread.java:662)

Another thing I see that is more curious than causing porblems (right now):
grep "Sending tracker pdu of size" /var/log/opennms/daemon/link.log:
2011-11-22 20:35:11,502 DEBUG [LinkdScheduler-1 Pool-fiber0] SnmpWalker: Sending tracker pdu of size 10
2011-11-22 20:35:11,539 DEBUG [DefaultUDPTransportMapping_213.166.170.87/0] SnmpWalker: Sending tracker pdu of size 10
2011-11-22 20:35:11,570 DEBUG [DefaultUDPTransportMapping_213.166.170.87/0] SnmpWalker: Sending tracker pdu of size 10
2011-11-22 20:35:11,607 DEBUG [DefaultUDPTransportMapping_213.166.170.87/0] SnmpWalker: Sending tracker pdu of size 10
2011-11-22 20:35:11,640 DEBUG [DefaultUDPTransportMapping_213.166.170.87/0] SnmpWalker: Sending tracker pdu of size 10
2011-11-22 20:35:11,678 DEBUG [DefaultUDPTransportMapping_213.166.170.87/0] SnmpWalker: Sending tracker pdu of size 10
2011-11-22 20:35:11,717 DEBUG [DefaultUDPTransportMapping_213.166.170.87/0] SnmpWalker: Sending tracker pdu of size 10
2011-11-22 20:35:11,761 DEBUG [DefaultUDPTransportMapping_213.166.170.87/0] SnmpWalker: Sending tracker pdu of size 9
2011-11-22 20:35:11,795 DEBUG [DefaultUDPTransportMapping_213.166.170.87/0] SnmpWalker: Sending tracker pdu of size 6
2011-11-22 20:35:11,856 DEBUG [DefaultUDPTransportMapping_213.166.170.87/0] SnmpWalker: Sending tracker pdu of size 3
2011-11-22 20:35:11,915 DEBUG [DefaultUDPTransportMapping_213.166.170.87/0] SnmpWalker: Sending tracker pdu of size 2
2011-11-22 20:35:11,994 DEBUG [DefaultUDPTransportMapping_213.166.170.87/0] SnmpWalker: Sending tracker pdu of size 2

It keeps decreasing the size of the transfers.

Also, the NPE is obviously fixed by correcting "lisners" to "listeners".

-A

Fresh run with today's checkin does not get off the ground:

Caused by: org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'linkdContext' defined in URL [jar:file:/opt/opennms/lib/opennms-services-1.9.94-SNAPSHOT.jar!/beanRefContext.xml]: Instantiation of bean failed; nested exception is org.springframework.beans.BeanInstantiationException: Could not instantiate bean class [org.springframework.context.support.ClassPathXmlApplicationContext]: Constructor threw exception; nested exception is org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'queryManager': Injection of autowired dependencies failed; nested exception is org.springframework.beans.factory.BeanCreationException: Could not autowire field: protected org.opennms.netmgt.linkd.Linkd org.opennms.netmgt.linkd.AbstractQueryManager.m_linkd; nested exception is org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'daemon' defined in class path resource [META-INF/opennms/applicationContext-linkd.xml]: Invocation of init method failed; nested exception is java.lang.NullPointerException
at org.springframework.beans.factory.support.ConstructorResolver.autowireConstructor(ConstructorResolver.java:288)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.autowireConstructor(AbstractAutowireCapableBeanFactory.java:1003)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBeanInstance(AbstractAutowireCapableBeanFactory.java:907)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:485)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:456)
at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:291)
at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:222)
at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:288)
at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:194)
at org.springframework.context.support.AbstractApplicationContext.getBean(AbstractApplicationContext.java:1079)
at org.springframework.beans.factory.access.SingletonBeanFactoryLocator.useBeanFactory(SingletonBeanFactoryLocator.java:397)
... 25 more
Caused by: org.springframework.beans.BeanInstantiationException: Could not instantiate bean class [org.springframework.context.support.ClassPathXmlApplicationContext]: Constructor threw exception; nested exception is org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'queryManager': Injection of autowired dependencies failed; nested exception is org.springframework.beans.factory.BeanCreationException: Could not autowire field: protected org.opennms.netmgt.linkd.Linkd org.opennms.netmgt.linkd.AbstractQueryManager.m_linkd; nested exception is org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'daemon' defined in class path resource [META-INF/opennms/applicationContext-linkd.xml]: Invocation of init method failed; nested exception is java.lang.NullPointerException
at org.springframework.beans.BeanUtils.instantiateClass(BeanUtils.java:141)
at org.springframework.beans.factory.support.SimpleInstantiationStrategy.instantiate(SimpleInstantiationStrategy.java:108)
at org.springframework.beans.factory.support.ConstructorResolver.autowireConstructor(ConstructorResolver.java:280)
... 35 more
Caused by: org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'queryManager': Injection of autowired dependencies failed; nested exception is org.springframework.beans.factory.BeanCreationException: Could not autowire field: protected org.opennms.netmgt.linkd.Linkd org.opennms.netmgt.linkd.AbstractQueryManager.m_linkd; nested exception is org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'daemon' defined in class path resource [META-INF/opennms/applicationContext-linkd.xml]: Invocation of init method failed; nested exception is java.lang.NullPointerException
at org.springframework.beans.factory.annotation.AutowiredAnnotationBeanPostProcessor.postProcessPropertyValues(AutowiredAnnotationBeanPostProcessor.java:285)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.populateBean(AbstractAutowireCapableBeanFactory.java:1074)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:517)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:456)
at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:291)
at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:222)
at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:288)
at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:190)
at org.springframework.beans.factory.support.DefaultListableBeanFactory.preInstantiateSingletons(DefaultListableBeanFactory.java:580)
at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:895)
at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:425)
at org.springframework.context.support.ClassPathXmlApplicationContext.<init>(ClassPathXmlApplicationContext.java:139)
at org.springframework.context.support.ClassPathXmlApplicationContext.<init>(ClassPathXmlApplicationContext.java:105)
at sun.reflect.GeneratedConstructorAccessor100.newInstance(Unknown Source)
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27)
at java.lang.reflect.Constructor.newInstance(Constructor.java:513)
at org.springframework.beans.BeanUtils.instantiateClass(BeanUtils.java:126)
... 37 more
Caused by: org.springframework.beans.factory.BeanCreationException: Could not autowire field: protected org.opennms.netmgt.linkd.Linkd org.opennms.netmgt.linkd.AbstractQueryManager.m_linkd; nested exception is org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'daemon' defined in class path resource [META-INF/opennms/applicationContext-linkd.xml]: Invocation of init method failed; nested exception is java.lang.NullPointerException
at org.springframework.beans.factory.annotation.AutowiredAnnotationBeanPostProcessor$AutowiredFieldElement.inject(AutowiredAnnotationBeanPostProcessor.java:502)
at org.springframework.beans.factory.annotation.InjectionMetadata.inject(InjectionMetadata.java:84)
at org.springframework.beans.factory.annotation.AutowiredAnnotationBeanPostProcessor.postProcessPropertyValues(AutowiredAnnotationBeanPostProcessor.java:282)
... 53 more
Caused by: org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'daemon' defined in class path resource [META-INF/opennms/applicationContext-linkd.xml]: Invocation of init method failed; nested exception is java.lang.NullPointerException
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1420)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:519)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:456)
at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:291)
at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:222)
at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:288)
at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:190)
at org.springframework.beans.factory.support.DefaultListableBeanFactory.findAutowireCandidates(DefaultListableBeanFactory.java:844)
at org.springframework.beans.factory.support.DefaultListableBeanFactory.doResolveDependency(DefaultListableBeanFactory.java:786)
at org.springframework.beans.factory.support.DefaultListableBeanFactory.resolveDependency(DefaultListableBeanFactory.java:703)
at org.springframework.beans.factory.annotation.AutowiredAnnotationBeanPostProcessor$AutowiredFieldElement.inject(AutowiredAnnotationBeanPostProcessor.java:474)
... 55 more
Caused by: java.lang.NullPointerException
at org.opennms.netmgt.linkd.HibernateEventWriter.getSnmpNodeList(HibernateEventWriter.java:111)
at org.opennms.netmgt.linkd.Linkd.onInit(Linkd.java:137)
at org.opennms.netmgt.daemon.AbstractServiceDaemon.init(AbstractServiceDaemon.java:349)
at org.opennms.netmgt.daemon.AbstractServiceDaemon.afterPropertiesSet(AbstractServiceDaemon.java:51)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1477)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1417)
... 65 more

Latest commit allows it to build clean, now it won't find links, not even links found earlier (swtich to switch). It doesn't give any NPE's at least.

Node ID 3 is 172.31.255.6, which certainly seems to be in the DB, but is not SNMP managed; but it should find the other node (172.31.255.3, which is the other switch), but seems it dumps out and exists when it fails to get a node.

Ignore the last two comments. We now have the right part in the log:

2011-11-30 00:17:02,475 DEBUG [LinkdScheduler-1 Pool-fiber0] HibernateEventWriter: processVlanTable: Starting VLAN table processing for 2/172.31.255.3
2011-11-30 00:17:02,481 DEBUG [LinkdScheduler-1 Pool-fiber0] HibernateEventWriter: processVlanTable: Saving VLAN entry: org.opennms.netmgt.model.OnmsVlan@1f1a90a[dbId=<null>,node=[OnmsNode@145cac5 id = 2, label = 'boxed-home-sw-1.boxed.no', parent.id = 'null', createTime = 2011-11-30 00:09:49.315, sysObjectId = '.1.3.6.1.4.1.9.1.799', sysName = 'boxed-home-sw-1.boxed.no', sysDescription = 'Cisco IOS Software, C2960 Software (C2960-LANBASEK9-M), Version 12.2(40)SE, RELEASE SOFTWARE (fc3)..Copyright (c) 1986-2007 by Cisco Systems, Inc...Compiled Fri 24-Aug-07 01:55 by myl', sysLocation = [null], sysContact = [null], type = 'A', operatingSystem = [null]],id=1,name=default,type=1,status=1,dbStatus=A,lastPollTime=2011-11-30 00:17:02.378]
2011-11-30 00:17:02,490 DEBUG [LinkdScheduler-1 Pool-fiber0] RunnableConsumerThreadPool$FiberThreadImpl: run: an unexpected error occured during fiber run, calling error liseners
2011-11-30 00:17:02,490 ERROR [LinkdScheduler-1 Pool-fiber0] RunnableConsumerThreadPool$FiberThreadImpl: No error listeners defined for unexpected error: java.lang.IllegalArgumentException: [Assertion failed] - this expression must be true
java.lang.IllegalArgumentException: [Assertion failed] - this expression must be true
at org.springframework.util.Assert.isTrue(Assert.java:65)
at org.springframework.util.Assert.isTrue(Assert.java:77)
at org.opennms.netmgt.linkd.HibernateEventWriter$2.doUpdate(HibernateEventWriter.java:499)
at org.opennms.netmgt.linkd.HibernateEventWriter$2.doUpdate(HibernateEventWriter.java:489)
at org.opennms.netmgt.dao.support.UpsertTemplate.update(UpsertTemplate.java:183)
at org.opennms.netmgt.dao.support.UpsertTemplate.doUpsert(UpsertTemplate.java:161)
at org.opennms.netmgt.dao.support.UpsertTemplate.access$000(UpsertTemplate.java:124)
at org.opennms.netmgt.dao.support.UpsertTemplate$1.doInTransaction(UpsertTemplate.java:148)
at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:130)
at org.opennms.netmgt.dao.support.UpsertTemplate.execute(UpsertTemplate.java:144)
at org.opennms.netmgt.linkd.HibernateEventWriter.saveVlan(HibernateEventWriter.java:489)
at org.opennms.netmgt.linkd.AbstractQueryManager.processVlanTable(AbstractQueryManager.java:474)
at org.opennms.netmgt.linkd.HibernateEventWriter.storeSnmpCollection(HibernateEventWriter.java:209)
at org.opennms.netmgt.linkd.Linkd.updateNodeSnmpCollection(Linkd.java:583)
at org.opennms.netmgt.linkd.SnmpCollection.run(SnmpCollection.java:527)
at org.opennms.netmgt.linkd.scheduler.Scheduler$1.run(Scheduler.java:301)
at org.opennms.core.concurrent.RunnableConsumerThreadPool$FiberThreadImpl.run(RunnableConsumerThreadPool.java:420)
at java.lang.Thread.run(Thread.java:662)

With today's commits:

2011-12-01 19:11:39,342 DEBUG [LinkdScheduler-1 Pool-fiber0] Linkd: Updating SNMP collection for 172.31.255.2
2011-12-01 19:11:39,342 DEBUG [LinkdScheduler-1 Pool-fiber0] HibernateEventWriter: processIpNetToMediaTable: Starting ipNetToMedia table processing for 1/172.31.255.2
2011-12-01 19:11:39,342 DEBUG [LinkdScheduler-1 Pool-fiber0] HibernateEventWriter: processIpNetToMediaTable: trying save ipNetToMedia info: IP address 172.31.255.1, MAC address
000c29a4a5b2, ifIndex 100
2011-12-01 19:11:39,355 DEBUG [LinkdScheduler-1 Pool-fiber0] HibernateEventWriter: processIpNetToMediaTable: trying save ipNetToMedia info: IP address 172.31.255.2, MAC address
001ae3719541, ifIndex 100
2011-12-01 19:11:39,372 DEBUG [LinkdScheduler-1 Pool-fiber0] HibernateEventWriter: processCdpCacheTable: Starting CDP cache table processing for 1/172.31.255.2
2011-12-01 19:11:39,372 DEBUG [LinkdScheduler-1 Pool-fiber0] HibernateEventWriter: processCdpCacheTable: IP address found: 172.31.255.3
2011-12-01 19:11:39,372 DEBUG [LinkdScheduler-1 Pool-fiber0] HibernateEventWriter: processCdpCacheTable: ifIndex found: 10106
2011-12-01 19:11:39,372 DEBUG [LinkdScheduler-1 Pool-fiber0] HibernateEventWriter: processCdpCacheTable: Target device port name found: GigabitEthernet0/8
2011-12-01 19:11:39,372 WARN [LinkdScheduler-1 Pool-fiber0] HibernateEventWriter: processCdpCacheTable: No node ID found: interface not added to linkable SNMP node. Skipping.
2011-12-01 19:11:39,372 DEBUG [LinkdScheduler-1 Pool-fiber0] HibernateEventWriter: processRouteTable: Zero route table entries for 1/172.31.255.2
2011-12-01 19:11:39,372 DEBUG [LinkdScheduler-1 Pool-fiber0] HibernateEventWriter: processVlanTable: Starting VLAN table processing for 1/172.31.255.2
2011-12-01 19:11:39,378 DEBUG [LinkdScheduler-1 Pool-fiber0] HibernateEventWriter: processVlanTable: Saving VLAN entry: org.opennms.netmgt.model.OnmsVlan@1025044[dbId=<null>,nod
e=[OnmsNode@890e74 id = 1, label = 'boxed-home-off-sw.boxed.no', parent.id = 'null', createTime = 2011-12-01 19:07:33.244, sysObjectId = '.1.3.6.1.4.1.9.1.799', sysName = 'boxed
-home-off-sw.boxed.no', sysDescription = 'Cisco IOS Software, C2960 Software (C2960-LANBASEK9-M), Version 12.2(40)SE, RELEASE SOFTWARE (fc3)..Copyright (c) 1986-2007 by Cisco Sy
stems, Inc...Compiled Fri 24-Aug-07 01:55 by myl', sysLocation = 'Kontoret, Bergen', sysContact = [null], type = 'A', operatingSystem = [null]],id=1,name=default,type=1,status=1
,dbStatus=A,lastPollTime=2011-12-01 19:11:39.342]
2011-12-01 19:11:39,386 WARN [LinkdScheduler-1 Pool-fiber0] VlanDaoHibernate: Null identifier on object, class: org.opennms.netmgt.model.OnmsVlan: org.opennms.netmgt.model.Onms
Vlan@1025044[dbId=<null>,node=[OnmsNode@890e74 id = 1, label = 'boxed-home-off-sw.boxed.no', parent.id = 'null', createTime = 2011-12-01 19:07:33.244, sysObjectId = '.1.3.6.1.4.1.9.1.799', sysName = 'boxed-home-off-sw.boxed.no', sysDescription = 'Cisco IOS Software, C2960 Software (C2960-LANBASEK9-M), Version 12.2(40)SE, RELEASE SOFTWARE (fc3)..Copyright (c) 1986-2007 by Cisco Systems, Inc...Compiled Fri 24-Aug-07 01:55 by myl', sysLocation = 'Kontoret, Bergen', sysContact = [null], type = 'A', operatingSystem = [null]],id=1,name=default,type=1,status=1,dbStatus=A,lastPollTime=2011-12-01 19:11:39.342]
2011-12-01 19:11:39,387 DEBUG [LinkdScheduler-1 Pool-fiber0] RunnableConsumerThreadPool$FiberThreadImpl: run: an unexpected error occured during fiber run, calling error liseners

2011-12-01 19:11:39,387 ERROR [LinkdScheduler-1 Pool-fiber0] RunnableConsumerThreadPool$FiberThreadImpl: No error listeners defined for unexpected error: org.springframework.dao.InvalidDataAccessApiUsageException: The given object has a null identifier: org.opennms.netmgt.model.OnmsVlan; nested exception is org.hibernate.TransientObjectException: The given object has a null identifier: org.opennms.netmgt.model.OnmsVlan
org.springframework.dao.InvalidDataAccessApiUsageException: The given object has a null identifier: org.opennms.netmgt.model.OnmsVlan; nested exception is org.hibernate.TransientObjectException: The given object has a null identifier: org.opennms.netmgt.model.OnmsVlan
at org.springframework.orm.hibernate3.SessionFactoryUtils.convertHibernateAccessException(SessionFactoryUtils.java:654)
at org.springframework.orm.hibernate3.HibernateAccessor.convertHibernateAccessException(HibernateAccessor.java:412)
at org.springframework.orm.hibernate3.HibernateTemplate.doExecute(HibernateTemplate.java:411)
at org.springframework.orm.hibernate3.HibernateTemplate.executeWithNativeSession(HibernateTemplate.java:374)
at org.springframework.orm.hibernate3.HibernateTemplate.update(HibernateTemplate.java:705)
at org.springframework.orm.hibernate3.HibernateTemplate.update(HibernateTemplate.java:701)
at org.opennms.netmgt.dao.hibernate.AbstractDaoHibernate.update(AbstractDaoHibernate.java:445)
at org.opennms.netmgt.linkd.HibernateEventWriter$2.doUpdate(HibernateEventWriter.java:510)
at org.opennms.netmgt.linkd.HibernateEventWriter$2.doUpdate(HibernateEventWriter.java:489)
at org.opennms.netmgt.dao.support.UpsertTemplate.update(UpsertTemplate.java:183)
at org.opennms.netmgt.dao.support.UpsertTemplate.doUpsert(UpsertTemplate.java:161)
at org.opennms.netmgt.dao.support.UpsertTemplate.access$000(UpsertTemplate.java:124)
at org.opennms.netmgt.dao.support.UpsertTemplate$1.doInTransaction(UpsertTemplate.java:148)
at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:130)
at org.opennms.netmgt.dao.support.UpsertTemplate.execute(UpsertTemplate.java:144)
at org.opennms.netmgt.linkd.HibernateEventWriter.saveVlan(HibernateEventWriter.java:489)
at org.opennms.netmgt.linkd.AbstractQueryManager.processVlanTable(AbstractQueryManager.java:474)
at org.opennms.netmgt.linkd.HibernateEventWriter.storeSnmpCollection(HibernateEventWriter.java:209)
at org.opennms.netmgt.linkd.Linkd.updateNodeSnmpCollection(Linkd.java:583)
at org.opennms.netmgt.linkd.SnmpCollection.run(SnmpCollection.java:527)
at org.opennms.netmgt.linkd.scheduler.Scheduler$1.run(Scheduler.java:301)
at org.opennms.core.concurrent.RunnableConsumerThreadPool$FiberThreadImpl.run(RunnableConsumerThreadPool.java:420)
at java.lang.Thread.run(Thread.java:662)
Caused by: org.hibernate.TransientObjectException: The given object has a null identifier: org.opennms.netmgt.model.OnmsVlan
at org.hibernate.event.def.DefaultSaveOrUpdateEventListener.getUpdateId(DefaultSaveOrUpdateEventListener.java:272)
at org.hibernate.event.def.DefaultUpdateEventListener.getUpdateId(DefaultUpdateEventListener.java:69)
at org.hibernate.event.def.DefaultSaveOrUpdateEventListener.entityIsDetached(DefaultSaveOrUpdateEventListener.java:240)
at org.hibernate.event.def.DefaultUpdateEventListener.performSaveOrUpdate(DefaultUpdateEventListener.java:56)
at org.hibernate.event.def.DefaultSaveOrUpdateEventListener.onSaveOrUpdate(DefaultSaveOrUpdateEventListener.java:93)
at org.hibernate.impl.SessionImpl.fireUpdate(SessionImpl.java:591)
at org.hibernate.impl.SessionImpl.update(SessionImpl.java:579)
at org.hibernate.impl.SessionImpl.update(SessionImpl.java:571)
at org.springframework.orm.hibernate3.HibernateTemplate$14.doInHibernate(HibernateTemplate.java:708)
at org.springframework.orm.hibernate3.HibernateTemplate.doExecute(HibernateTemplate.java:406)
... 20 more

and no links between the switches.

-A

OK, Linkd.updateNodeSnmpCollection() had package-private visibility which means that @Transactional didn't work on it (hence the lack of a transaction in the stack trace). I just changed this.

commit aaeb4646a5e549a2a382305513e2f55a0f598efe

And with your last few commits, current as of 15 minute ago:

2011-12-01 23:50:02,026 DEBUG [LinkdScheduler-1 Pool-fiber0] HibernateEventWriter: processRouteTable: Zero route table entries for 2/172.31.255.3
2011-12-01 23:50:02,026 DEBUG [LinkdScheduler-1 Pool-fiber0] HibernateEventWriter: processVlanTable: Starting VLAN table processing for 2/172.31.255.3
2011-12-01 23:50:02,033 DEBUG [LinkdScheduler-1 Pool-fiber0] HibernateEventWriter: processVlanTable: Saving VLAN entry: org.opennms.netmgt.model.OnmsVlan@15fff9c[dbId=<null>,nod
e=[OnmsNode@3800b5 id = 2, label = 'boxed-home-sw-1.boxed.no', parent.id = 'null', createTime = 2011-12-01 23:45:26.736, sysObjectId = '.1.3.6.1.4.1.9.1.799', sysName = 'boxed-home-sw-1.boxed.no', sysDescription = 'Cisco IOS Software, C2960 Software (C2960-LANBASEK9-M), Version 12.2(40)SE, RELEASE SOFTWARE (fc3)..Copyright (c) 1986-2007 by Cisco Systems, Inc...Compiled Fri 24-Aug-07 01:55 by myl', sysLocation = [null], sysContact = [null], type = 'A', operatingSystem = [null]],id=1,name=default,type=1,status=1,dbStatus=A,lastPollTime=2011-12-01 23:50:01.899]
2011-12-01 23:50:02,041 WARN [LinkdScheduler-1 Pool-fiber0] VlanDaoHibernate: Null identifier on object, class: org.opennms.netmgt.model.OnmsVlan: org.opennms.netmgt.model.OnmsVlan@15fff9c[dbId=<null>,node=[OnmsNode@3800b5 id = 2, label = 'boxed-home-sw-1.boxed.no', parent.id = 'null', createTime = 2011-12-01 23:45:26.736, sysObjectId = '.1.3.6.1.4.1.9.1.799', sysName = 'boxed-home-sw-1.boxed.no', sysDescription = 'Cisco IOS Software, C2960 Software (C2960-LANBASEK9-M), Version 12.2(40)SE, RELEASE SOFTWARE (fc3)..Copyright (c) 1986-2007 by Cisco Systems, Inc...Compiled Fri 24-Aug-07 01:55 by myl', sysLocation = [null], sysContact = [null], type = 'A', operatingSystem = [null]],id=1,name=default,type=1,status=1,dbStatus=A,lastPollTime=2011-12-01 23:50:01.899]
2011-12-01 23:50:02,041 DEBUG [LinkdScheduler-1 Pool-fiber0] RunnableConsumerThreadPool$FiberThreadImpl: run: an unexpected error occured during fiber run, calling error liseners
2011-12-01 23:50:02,041 ERROR [LinkdScheduler-1 Pool-fiber0] RunnableConsumerThreadPool$FiberThreadImpl: No error listeners defined for unexpected error: org.springframework.dao.InvalidDataAccessApiUsageException: The given object has a null identifier: org.opennms.netmgt.model.OnmsVlan; nested exception is org.hibernate.TransientObjectException: The given object has a null identifier: org.opennms.netmgt.model.OnmsVlan
org.springframework.dao.InvalidDataAccessApiUsageException: The given object has a null identifier: org.opennms.netmgt.model.OnmsVlan; nested exception is org.hibernate.TransientObjectException: The given object has a null identifier: org.opennms.netmgt.model.OnmsVlan
at org.springframework.orm.hibernate3.SessionFactoryUtils.convertHibernateAccessException(SessionFactoryUtils.java:654)
at org.springframework.orm.hibernate3.HibernateAccessor.convertHibernateAccessException(HibernateAccessor.java:412)
at org.springframework.orm.hibernate3.HibernateTemplate.doExecute(HibernateTemplate.java:411)
at org.springframework.orm.hibernate3.HibernateTemplate.executeWithNativeSession(HibernateTemplate.java:374)
at org.springframework.orm.hibernate3.HibernateTemplate.update(HibernateTemplate.java:705)
at org.springframework.orm.hibernate3.HibernateTemplate.update(HibernateTemplate.java:701)
at org.opennms.netmgt.dao.hibernate.AbstractDaoHibernate.update(AbstractDaoHibernate.java:445)
at org.opennms.netmgt.linkd.HibernateEventWriter$2.doUpdate(HibernateEventWriter.java:510)
at org.opennms.netmgt.linkd.HibernateEventWriter$2.doUpdate(HibernateEventWriter.java:489)
at org.opennms.netmgt.dao.support.UpsertTemplate.update(UpsertTemplate.java:183)
at org.opennms.netmgt.dao.support.UpsertTemplate.doUpsert(UpsertTemplate.java:161)
at org.opennms.netmgt.dao.support.UpsertTemplate.access$000(UpsertTemplate.java:124)
at org.opennms.netmgt.dao.support.UpsertTemplate$1.doInTransaction(UpsertTemplate.java:148)
at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:130)
at org.opennms.netmgt.dao.support.UpsertTemplate.execute(UpsertTemplate.java:144)
at org.opennms.netmgt.linkd.HibernateEventWriter.saveVlan(HibernateEventWriter.java:489)
at org.opennms.netmgt.linkd.AbstractQueryManager.processVlanTable(AbstractQueryManager.java:474)
at org.opennms.netmgt.linkd.HibernateEventWriter.storeSnmpCollection(HibernateEventWriter.java:209)
at org.opennms.netmgt.linkd.Linkd.updateNodeSnmpCollection(Linkd.java:583)
at org.opennms.netmgt.linkd.SnmpCollection.run(SnmpCollection.java:527)
at org.opennms.netmgt.linkd.scheduler.Scheduler$1.run(Scheduler.java:301)
at org.opennms.core.concurrent.RunnableConsumerThreadPool$FiberThreadImpl.run(RunnableConsumerThreadPool.java:420)
at java.lang.Thread.run(Thread.java:662)
Caused by: org.hibernate.TransientObjectException: The given object has a null identifier: org.opennms.netmgt.model.OnmsVlan
at org.hibernate.event.def.DefaultSaveOrUpdateEventListener.getUpdateId(DefaultSaveOrUpdateEventListener.java:272)
at org.hibernate.event.def.DefaultUpdateEventListener.getUpdateId(DefaultUpdateEventListener.java:69)
at org.hibernate.event.def.DefaultSaveOrUpdateEventListener.entityIsDetached(DefaultSaveOrUpdateEventListener.java:240)
at org.hibernate.event.def.DefaultUpdateEventListener.performSaveOrUpdate(DefaultUpdateEventListener.java:56)
at org.hibernate.event.def.DefaultSaveOrUpdateEventListener.onSaveOrUpdate(DefaultSaveOrUpdateEventListener.java:93)
at org.hibernate.impl.SessionImpl.fireUpdate(SessionImpl.java:591)
at org.hibernate.impl.SessionImpl.update(SessionImpl.java:579)
at org.hibernate.impl.SessionImpl.update(SessionImpl.java:571)
at org.springframework.orm.hibernate3.HibernateTemplate$14.doInHibernate(HibernateTemplate.java:708)
at org.springframework.orm.hibernate3.HibernateTemplate.doExecute(HibernateTemplate.java:406)
... 20 more

and no links.

-A

I don't think you have the most up-to-date code... the line:

org.opennms.netmgt.linkd.HibernateEventWriter.saveVlan(HibernateEventWriter.java:489)

doesn't line up with my code from the 1.10 branch. saveVlan() starts at line 498.

That list little one snuck into git just as I had startd building. My apologies. I see links galore and will put the test build out to a place it should find lots of fun. A run on the test rigs produces the expected links, and not a single exception in the logs. Yay!

OK, it sounds like the transaction and database issues inside linkd are finally resolved. Hallelujah! I combed through the entire codebase for more potential @Transactional problems and I didn't see anything major like the systemic problems that were in the linkd code. I'm going to go ahead and close this bug. If people encounter further issues, please open new issues (with stack traces).

Unfort. I see the same problem in 1.10.0 for cisco catalyst 3750 Trunks via cdp only;

see at first the switch show cdp;

stack-eg2versatel#show run int vlan642
Building configuration...

Current configuration : 95 bytes
!
interface Vlan642
ip address 10.2.64.138 255.255.255.240
no logging event link-status
end

stack-eg2versatel#show cdp nei
Capability Codes: R - Router, T - Trans Bridge, B - Source Route Bridge
S - Switch, H - Host, I - IGMP, r - Repeater, P - Phone,
D - Remote, C - CVTA, M - Two-port Mac Relay

Device ID Local Intrfce Holdtme Capability Platform Port ID
tic-switch.domain.de
Gig 4/0/1 124 R S I WS-C3750G Gig 1/0/24
tic-switch.domain.de
Gig 5/0/1 124 R S I WS-C3750G Gig 2/0/23
stack-kg2versatel.domain.de
Gig 1/0/2 170 R S I WS-C3750G Gig 2/0/24
stack-kg2versatel.domain.de
Gig 2/0/2 170 R S I WS-C3750G Gig 2/0/23
stack-kg2versatel.domain.de
Gig 1/0/1 126 R S I WS-C3750G Gig 1/0/24
stack-kg2versatel.domain.de
Gig 2/0/4 141 R S I WS-C3750G Gig 1/0/13
BTS3.01 Gig 3/0/4 169 T AIR-LAP12 Gig 0.1
BTS4.01 Gig 3/0/3 164 T AIR-LAP12 Gig 0
ras.domain.int
Fas 3/0/48 154 R S I 3660 Fas 5/1
ras.domain.int
Fas 3/0/36 143 R S I 3660 Fas 0/0
stack-eg2versatel#ping tic-switch.domain.de

Translating "tic-switch.domain.de"...domain server (10.2.9.27) [OK]

Type escape sequence to abort.
Sending 5, 100-byte ICMP Echos to 10.2.64.141, timeout is 2 seconds:
!!!!!
Success rate is 100 percent (5/5), round-trip min/avg/max = 1/2/9 ms
stack-eg2versatel#ping stack-kg2versatel.domain.de

Translating "stack-kg2versatel.biotronik-erlangen.de"...domain server (10.2.9.27) [OK]

Type escape sequence to abort.
Sending 5, 100-byte ICMP Echos to 10.2.64.137, timeout is 2 seconds:
!!!!!
Success rate is 100 percent (5/5), round-trip min/avg/max = 1/4/9 ms
===========================================================
debugging output of linkd:

BasePortTable@770a7b24,dot1dStp=org.opennms.netmgt.linkd.snmp.Dot1dStpGroup@511ab58a,dot1dStpTable=org.opennms.netmgt.linkd.snmp.Dot1dStpPortTable@3084a09f,dot1dTpFdbTable=org.opennms.netmgt.linkd.snmp.Dot1dTpFdbTable@534d3f9b,dot1qTpFdbTable=<null>]
2012-03-23 23:51:27,899 DEBUG [LinkdScheduler-5 Pool-fiber4] SnmpCollection: run: saving collection into database for 10.2.64.138
2012-03-23 23:51:27,899 DEBUG [LinkdScheduler-5 Pool-fiber4] Linkd: Updating SNMP collection for 10.2.64.138

::::
some VLAN's I not need
::::

Than vlan 642 woth portschannel and several Gi Interfaces to switch 10.2.64.137 stack-kg2versatel.domain.de

2012-03-23 23:51:29,690 DEBUG [LinkdScheduler-5 Pool-fiber4] HibernateEventWriter: processIpNetToMediaTable: trying save ipNetToMedia info: IP address 10.2.64.137, MAC address 0012d9053ac1, ifIndex 642
2012-03-23 23:51:29,702 DEBUG [LinkdScheduler-5 Pool-fiber4] AtInterfaceDaoHibernate$2: getAtInterfaceForAddress: More than one AtInterface matched address 10.2.64.137!
2012-03-23 23:51:29,707 DEBUG [LinkdScheduler-5 Pool-fiber4] RunnableConsumerThreadPool$FiberThreadImpl: run: an unexpected error occured during fiber run, calling error liseners
n: could not insert: [org.opennms.netmgt.model.OnmsAtInterface]
]; constraint [pk_atinterface]; nested exception is org.hibernate.exception.ConstraintViolationException: could not insert: [org.opennms.netmgt.model.OnmsAtInterface]
at org.springframework.orm.hibernate3.SessionFactoryUtils.convertHibernateAccessException(SessionFactoryUtils.java:637)
at org.springframework.orm.hibernate3.HibernateTransactionManager.convertHibernateAccessException(HibernateTransactionManager.java:793)
at org.springframework.orm.hibernate3.HibernateTransactionManager.doCommit(HibernateTransactionManager.java:664)
at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:754)
at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:723)
at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:147)
at org.opennms.netmgt.dao.support.UpsertTemplate.execute(UpsertTemplate.java:144)
at org.opennms.netmgt.dao.hibernate.AtInterfaceDaoHibernate.getAtInterfaceForAddress(AtInterfaceDaoHibernate.java:217)
at org.opennms.netmgt.linkd.AbstractQueryManager.processIpNetToMediaTable(AbstractQueryManager.java:153)
at org.opennms.netmgt.linkd.HibernateEventWriter.storeSnmpCollection(HibernateEventWriter.java:191)
at org.opennms.netmgt.linkd.Linkd.updateNodeSnmpCollection(Linkd.java:583)
at org.opennms.netmgt.linkd.SnmpCollection.run(SnmpCollection.java:527)
at org.opennms.netmgt.linkd.scheduler.Scheduler$1.run(Scheduler.java:301)
at org.opennms.core.concurrent.RunnableConsumerThreadPool$FiberThreadImpl.run(RunnableConsumerThreadPool.java:420)
at java.lang.Thread.run(Thread.java:722)
Caused by: org.hibernate.exception.ConstraintViolationException: could not insert: [org.opennms.netmgt.model.OnmsAtInterface]
at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:94)
at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:66)
at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:2295)
at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:2688)
at org.hibernate.action.EntityInsertAction.execute(EntityInsertAction.java:79)
at org.hibernate.engine.ActionQueue.execute(ActionQueue.java:279)
at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:263)
at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:167)
at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:321)
at org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:50)
at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:1027)
at org.hibernate.impl.SessionImpl.managedFlush(SessionImpl.java:365)
at org.hibernate.transaction.JDBCTransaction.commit(JDBCTransaction.java:137)
at org.springframework.orm.hibernate3.HibernateTransactionManager.doCommit(HibernateTransactionManager.java:656)
... 12 more
Caused by: org.postgresql.util.PSQLException: ERROR: duplicate key value violates unique constraint "pk_atinterface"
at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2102)
at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1835)
at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:257)
at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:500)
at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:388)
at org.postgresql.jdbc2.AbstractJdbc2Statement.executeUpdate(AbstractJdbc2Statement.java:334)
at com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeUpdate(NewProxyPreparedStatement.java:105)
at org.hibernate.jdbc.NonBatchingBatcher.addToBatch(NonBatchingBatcher.java:46)
at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:2275)
... 23 more

Changing fix version from 1.10.0 to 1.11 since it seems like there are more issues here to fix based on the last comment.

This has been resolved in master 11.2-SNAPSHOT