Grouper Users - Open Discussion List

[Chris Hyzer <>]

I added this jira

https://bugs.internet2.edu/jira/browse/GRP-569

Thanks,
Chris

-----Original Message-----
From: 

 
[mailto:]
 On Behalf Of Colin Hudler
Sent: Wednesday, March 02, 2011 10:07 AM
To: 

Subject: Re: FW: [grouper-users] Grouper changelog/flatmembership error

I'm in the midst of some operational concerns at the moment. I hope to 
have time to investigate what happened to me. The sequence of events and 
immediate error suggested it would be easy to reproduce. I haven't tried 
yet, but the error hasn't happened again either. On this system, 
grouper-loader runs the SyncFlatTables job every minute. There was no 
upgrade. Perhaps I had accidentally started multiple grouper-loaders...again

On 3/2/11 8:59 AM, Shilen Patel wrote:
> I think this error can only happen if the change log daemon did not
> process the group creation that's the owner of the membership that's
> failing to get created in the flat table. And I think that should only
> happen if change log entries were removed from the change log before
> getting processed by the change log daemon or if the Grouper instance
> was upgraded from 1.5 (or before) and the SyncFlatTables script was not
> run. And actually, I'm not sure if xml-import adds change log entries.
> If it doesn't, then the SyncFlatTables script would need to run after an
> xml-import too and we should document that.
>
> So as long as you do an initial sync and you're running the change log
> daemon often (every minute is the default if the loader is running),
> then this shouldn't become a problem. Though I suppose if we wanted to,
> we could have the code verify that all the foreign keys exist, but that
> might get expensive.
>
> Thanks!
>
> -- Shilen
>
>
> On 3/1/11 9:53 PM, Tom Barton wrote:
>> Grouper developers,
>>
>> Is this a bug? If so, is there a jira issue for it?
>>
>> Thanks,
>> Tom
>>
>> On 2/23/2011 11:57 AM, Chris Hyzer wrote:
>>> Shilen can correct me if wrong, but I think a membership is trying to
>>> be inserted into the flat membership table where the group is not in
>>> the flat group table. I think if you run this in GSH it should fix it...
>>>
>>> new SyncFlatTables().sendNotifications(false).syncAllFlatTables();
>>>
>>> Thanks,
>>> Chris
>>>
>>>
>>> -----Original Message-----
>>> From: 
>>> 
>>> [mailto:]
>>>  On Behalf Of Colin Hudler
>>> Sent: Wednesday, February 23, 2011 12:45 PM
>>> To: 
>>> 
>>> Subject: [grouper-users] Grouper changelog/flatmembership error
>>>
>>> Greetings,
>>>
>>> Today I decided to toy around with grouper ESB things, and get
>>> notifications over XMPP. I'm running 1.6.3 with a large registry on
>>> Oracle 11g2. It is a purely development server. I setup
>>> grouper-loader.properties like this:
>>>
>>> changeLog.consumer.xmpp.class =
>>> edu.internet2.middleware.grouper.changeLog.esb.consumer.EsbConsumer
>>> changeLog.consumer.xmpp.quartzCron = 0 * * * * ?
>>> changeLog.consumer.xmpp.elfilter = event.eventType eq 'GROUP_DELETE'
>>> \|\| event.eventType eq 'GROUP_ADD' \|\| event.eventType eq
>>> 'MEMBERSHIP_DELETE' \|\| event.eventType eq 'MEMBERSHIP_ADD'
>>> changeLog.consumer.xmpp.publisher.class =
>>> edu.internet2.middleware.grouper.changeLog.esb.consumer.EsbXmppPublisher
>>> changeLog.consumer.xmpp.publisher.server = im.uchicago.edu
>>> changeLog.consumer.xmpp.publisher.port = 5222
>>> changeLog.consumer.xmpp.publisher.username = grouper_user
>>> changeLog.consumer.xmpp.publisher.password = sekret
>>> changeLog.consumer.xmpp.publisher.recipient = 
>>> 
>>> changeLog.consumer.xmpp.publisher.addSubjectAttributes = uid
>>>
>>> I took most of this from
>>> <https://spaces.internet2.edu/display/Grouper/Grouper+ESB+connector+configuration+examples>.
>>>
>>> I fired up gsh.sh -loader, and everything worked *really well*.. for a
>>> while. Every minute I got a huge batch (backlog?) of notification
>>> messages via jabber in json. Things went sour when some changes were
>>> made to grouper (via java API) while the consumer was running. The
>>> following was logged:
>>>
>>> 2011-02-23 11:19:54,077: [main] INFO EventLog.info(141) - -
>>> [70466727b03f4c4fb6e2799da6fa1da2,'GrouperSystem','application'] delete
>>> member: group='uc:Reference:email:routing:oncampus' list='members'
>>> subject='51884090U'/'person'/'ucmcdb
>>> ' (433ms)
>>> 2011-02-23 11:20:00,032: [DefaultQuartzScheduler_Worker-1] INFO
>>> EventLog.info(141) - -
>>> [2da2780ac728490a916b8ea833e24fc4,'GrouperSystem','application']
>>> session: start (3ms)
>>> 2011-02-23 11:20:14,720: [DefaultQuartzScheduler_Worker-2] WARN
>>> JDBCExceptionReporter.logExceptions(77) - - SQL Error: 2291, SQLState:
>>> 23000
>>> 2011-02-23 11:20:14,721: [DefaultQuartzScheduler_Worker-2] ERROR
>>> JDBCExceptionReporter.logExceptions(78) - - ORA-02291: integrity
>>> constraint (GROUPER.FK_FLAT_MSHIP_OWNER_GROUP_ID) violated - parent key
>>> not found
>>>
>>> 2011-02-23 11:20:14,721: [DefaultQuartzScheduler_Worker-2] WARN
>>> JDBCExceptionReporter.logExceptions(77) - - SQL Error: 2291, SQLState:
>>> 23000
>>> 2011-02-23 11:20:14,721: [DefaultQuartzScheduler_Worker-2] ERROR
>>> JDBCExceptionReporter.logExceptions(78) - - ORA-02291: integrity
>>> constraint (GROUPER.FK_FLAT_MSHIP_OWNER_GROUP_ID) violated - parent key
>>> not found
>>>
>>> 2011-02-23 11:20:14,722: [DefaultQuartzScheduler_Worker-2] ERROR
>>> AbstractFlushingEventListener.performExecutions(301) - - Could not
>>> synchronize database state with session
>>> org.hibernate.exception.ConstraintViolationException: could not insert:
>>> [edu.internet2.middleware.grouper.flat.FlatMembership]
>>> at
>>> org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:71)
>>>
>>> at
>>> org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:43)
>>>
>>> at
>>> org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:2272)
>>>
>>> at
>>> org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:2665)
>>>
>>> at
>>> org.hibernate.action.EntityInsertAction.execute(EntityInsertAction.java:60)
>>>
>>> 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:298)
>>>
>>> at
>>> org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:27)
>>>
>>> at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:1000)
>>> at
>>> edu.internet2.middleware.grouper.hibernate.ByObject.saveBatch(ByObject.java:254)
>>>
>>> at
>>> edu.internet2.middleware.grouper.hibernate.ByObjectStatic$8.callback(ByObjectStatic.java:518)
>>>
>>> at
>>> edu.internet2.middleware.grouper.hibernate.HibernateSession.callbackHibernateSession(HibernateSession.java:500)
>>>
>>> at
>>> edu.internet2.middleware.grouper.hibernate.ByObjectStatic.saveBatch(ByObjectStatic.java:505)
>>>
>>> at
>>> edu.internet2.middleware.grouper.internal.dao.hib3.Hib3FlatMembershipDAO.saveBatch(Hib3FlatMembershipDAO.java:49)
>>>
>>> at
>>> edu.internet2.middleware.grouper.changeLog.ChangeLogTempToEntity.processMembershipAdd(ChangeLogTempToEntity.java:581)
>>>
>>> at
>>> edu.internet2.middleware.grouper.changeLog.ChangeLogTempToEntity.processMembershipAdd(ChangeLogTempToEntity.java:622)
>>>
>>> at
>>> edu.internet2.middleware.grouper.changeLog.ChangeLogTempToEntity.access$800(ChangeLogTempToEntity.java:47)
>>>
>>> at
>>> edu.internet2.middleware.grouper.changeLog.ChangeLogTempToEntity$1.callback(ChangeLogTempToEntity.java:108)
>>>
>>> at
>>> edu.internet2.middleware.grouper.hibernate.HibernateSession.callbackHibernateSession(HibernateSession.java:500)
>>>
>>> at
>>> edu.internet2.middleware.grouper.changeLog.ChangeLogTempToEntity.convertRecords(ChangeLogTempToEntity.java:85)
>>>
>>> at
>>> edu.internet2.middleware.grouper.changeLog.ChangeLogTempToEntity.convertRecords(ChangeLogTempToEntity.java:153)
>>>
>>> at
>>> edu.internet2.middleware.grouper.changeLog.ChangeLogTempToEntity.convertRecords(ChangeLogTempToEntity.java:153)
>>>
>>> <...repeated many times...>
>>> at
>>> edu.internet2.middleware.grouper.changeLog.ChangeLogTempToEntity.convertRecords(ChangeLogTempToEntity.java:153)
>>>
>>> at
>>> edu.internet2.middleware.grouper.app.loader.GrouperLoaderType$4.runJob(GrouperLoaderType.java:755)
>>>
>>> at
>>> edu.internet2.middleware.grouper.app.loader.GrouperLoaderJob.runJob(GrouperLoaderJob.java:344)
>>>
>>> at
>>> edu.internet2.middleware.grouper.app.loader.GrouperLoaderJob.execute(GrouperLoaderJob.java:247)
>>>
>>> at org.quartz.core.JobRunShell.run(JobRunShell.java:202)
>>> at
>>> org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:529)
>>>
>>> Caused by: java.sql.BatchUpdateException: ORA-02291: integrity
>>> constraint (GROUPER.FK_FLAT_MSHIP_OWNER_GROUP_ID) violated - parent key
>>> not found
>>>
>>> at
>>> oracle.jdbc.driver.OraclePreparedStatement.executeBatch(OraclePreparedStatement.java:10055)
>>>
>>> at
>>> oracle.jdbc.driver.OracleStatementWrapper.executeBatch(OracleStatementWrapper.java:213)
>>>
>>> at
>>> com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeBatch(NewProxyPreparedStatement.java:1723)
>>>
>>> at
>>> org.hibernate.jdbc.BatchingBatcher.doExecuteBatch(BatchingBatcher.java:48)
>>>
>>> at
>>> org.hibernate.jdbc.BatchingBatcher.addToBatch(BatchingBatcher.java:34)
>>> at
>>> org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:2252)
>>>
>>> ... 63 more
>>> 2011-02-23 11:20:14,736: [DefaultQuartzScheduler_Worker-2] ERROR
>>> GrouperUtil.logErrorNextException(562) - - Next exception
>>> java.sql.SQLException: ORA-02291: integrity constraint
>>> (GROUPER.FK_FLAT_MSHIP_OWNER_GROUP_ID) violated - parent key not found
>>>
>>> This problem stays (the loader keeps logging it), and change
>>> notifications simply stopped coming through XMPP.
>