Grouper Users - Open Discussion List

["Black, Carey M." <>]

I am not sure what is going on.... but...

 

I found something odd in the grouper daemon service logs.

My loader job (singular) could be run from the UI(“Run loader process to sync group”), but when it ran from the daemon (daily@6,11) it returned this error:

 

"

2017-06-09 11:00:00,494: [DefaultQuartzScheduler_Worker-8] ERROR GrouperLoaderJob.execute(326) -  - Error running up job

java.lang.RuntimeException: Expecting type integer, but was: string, AttributeAssign[id=b673b5ca46664e14bbbcf8bfdf41d042,action="assign,attributeDefName=etc:attribute:loaderLdap:grouperLoaderLdapPriority,ownerAttributeAssignId=412d01103ee34a0bba851b5337451e3d]

        at edu.internet2.middleware.grouper.attr.value.AttributeAssignValueDelegate.convertToInteger(AttributeAssignValueDelegate.java:1523)

        at edu.internet2.middleware.grouper.attr.value.AttributeAssignValueDelegate.retrieveValueInteger(AttributeAssignValueDelegate.java:1507)

        at edu.internet2.middleware.grouper.attr.value.AttributeValueDelegate.retrieveValueInteger(AttributeValueDelegate.java:328)

        at edu.internet2.middleware.grouper.app.loader.GrouperLoaderJob.execute(GrouperLoaderJob.java:186)

        at org.quartz.core.JobRunShell.run(JobRunShell.java:202)

        at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573)

"

 

When that happens the log entry looks ... odd....

 

 

On a whim I removed the "priority value" from the loader config. ( It was set to “4” from the UI and removed the value).

Scheduled the job to run a few minutes later (11:16). Restarted the daemon.[ may not be needed, but why not? J ]

 

This time it ran from the daemon and produced a "Success log" entry. J better. J

 

 

 

 

=========== Part2 =================

Also not all of the groups are being loaded. ( REF: LDAP_GROUPS_FROM_ATTRIBUTES )

 

 

FWIW: The job should have loaded 113 groups (running from the UI or the daemon), but is not loading 3 of them for some reason. ( Still TBD as to why… )

  I am comparing the list of groups from the source with the list of groups in grouper after the job runs.

 

I also see another error in the logs too, but I have not convinced myself that this is the reason for the “missing three groups yet”, but maybe…

 

“

2017-06-09 11:16:48,223: [pool-1-thread-25] WARN  GrouperFuture.waitForJob(155) -  - Non fatal problem with callable.  Will try again not in thread

java.lang.RuntimeException: Problem with query in bysqlstatic: update grouper_groups set last_membership_change = ? where id  in (?),

Problem in HibernateSession: HibernateSession (97e1854): notNew, notReadonly, READ_WRITE_NEW, activeTransaction, session (66508c47),

Exception in delete: edu.internet2.middleware.grouper.Membership, edu.internet2.middleware.grouper.hibernate.ByObject@1f159461,

Problem in HibernateSession: HibernateSession (6cd7ed45): notNew, notReadonly, READ_WRITE_NEW, activeTransaction, session (66508c47),

Exception in delete: edu.internet2.middleware.grouper.Membership, ByObjectStatic, query: ', cacheable: null, cacheRegion: null, entityName: ImmediateMembershipEntry, tx type: null,

Problem in HibernateSession: HibernateSession (1d7338ae): notNew, notReadonly, READ_WRITE_NEW, activeTransaction, session (66508c47),

Problem in HibernateSession: HibernateSession (5657eadc): new, notReadonly, READ_WRITE_NEW, notActiveTransaction, session (66508c47),

Problem deleting member: edu.internet2.middleware.grouper.app.loader.LoaderMemberWrapper@6e7870ea, ,

Problem in job: syncOneMemberDeleteMemberLogic: <group_path>, <SUBJECTID_1>

        at edu.internet2.middleware.grouper.hibernate.BySqlStatic$1.callback(BySqlStatic.java:105)

        at edu.internet2.middleware.grouper.hibernate.HibernateSession.callbackHibernateSession(HibernateSession.java:700)

        at edu.internet2.middleware.grouper.hibernate.BySqlStatic.executeSql(BySqlStatic.java:80)

        at edu.internet2.middleware.grouper.internal.dao.hib3.Hib3GroupDAO.updateLastMembershipChangeIncludeAncestorGroups(Hib3GroupDAO.java:2494)

        at edu.internet2.middleware.grouper.Membership.updateLastMembershipChangeDuringMembersListUpdate(Membership.java:2221)

        at edu.internet2.middleware.grouper.Membership.processPostMembershipDelete(Membership.java:2101)

        at edu.internet2.middleware.grouper.Membership.onPostDelete(Membership.java:1963)

        at edu.internet2.middleware.grouper.hibernate.ByObject.delete(ByObject.java:125)

        at edu.internet2.middleware.grouper.hibernate.ByObjectStatic$10.callback(ByObjectStatic.java:675)

        at edu.internet2.middleware.grouper.hibernate.HibernateSession.callbackHibernateSession(HibernateSession.java:700)

        at edu.internet2.middleware.grouper.hibernate.ByObjectStatic.delete(ByObjectStatic.java:662)

        at edu.internet2.middleware.grouper.internal.dao.hib3.Hib3MembershipDAO.delete(Hib3MembershipDAO.java:2098)

        at edu.internet2.middleware.grouper.Membership$2.callback(Membership.java:542)

        at edu.internet2.middleware.grouper.hibernate.HibernateSession.callbackHibernateSession(HibernateSession.java:700)

        at edu.internet2.middleware.grouper.Membership.delete(Membership.java:530)

        at edu.internet2.middleware.grouper.Membership.internal_delImmediateMembership(Membership.java:1332)

        at edu.internet2.middleware.grouper.Group$9.callback(Group.java:2389)

        at edu.internet2.middleware.grouper.hibernate.HibernateSession.callbackHibernateSession(HibernateSession.java:700)

        at edu.internet2.middleware.grouper.Group.deleteMember(Group.java:2364)

        at edu.internet2.middleware.grouper.Group.deleteMember(Group.java:2281)

        at edu.internet2.middleware.grouper.app.loader.GrouperLoaderType.syncOneMemberDeleteMemberLogic(GrouperLoaderType.java:4236)

        at edu.internet2.middleware.grouper.app.loader.GrouperLoaderType.access$300(GrouperLoaderType.java:118)

        at edu.internet2.middleware.grouper.app.loader.GrouperLoaderType$13$1.callLogic(GrouperLoaderType.java:2747)

        at edu.internet2.middleware.grouper.app.loader.GrouperLoaderType$13$1.callLogic(GrouperLoaderType.java:2743)

        at edu.internet2.middleware.grouper.util.GrouperCallable$1.callback(GrouperCallable.java:191)

        at edu.internet2.middleware.grouper.GrouperSession.callbackGrouperSession(GrouperSession.java:974)

        at edu.internet2.middleware.grouper.util.GrouperCallable.callLogicWithSessionIfExists(GrouperCallable.java:188)

        at edu.internet2.middleware.grouper.util.GrouperCallable.call(GrouperCallable.java:154)

        at java.util.concurrent.FutureTask.run(FutureTask.java:266)

        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)

        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)

        at java.lang.Thread.run(Thread.java:748)

Caused by: com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction

        at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)

        at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)

        at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)

        at java.lang.reflect.Constructor.newInstance(Constructor.java:423)

        at com.mysql.jdbc.Util.handleNewInstance(Util.java:404)

        at com.mysql.jdbc.Util.getInstance(Util.java:387)

        at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:946)

        at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3878)

        at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3814)

        at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2478)

        at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2625)

        at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2551)

        at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1861)

        at com.mysql.jdbc.PreparedStatement.executeUpdateInternal(PreparedStatement.java:2073)

        at com.mysql.jdbc.PreparedStatement.executeUpdateInternal(PreparedStatement.java:2009)

        at com.mysql.jdbc.PreparedStatement.executeLargeUpdate(PreparedStatement.java:5094)

        at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1994)

        at com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeUpdate(NewProxyPreparedStatement.java:384)

        at edu.internet2.middleware.grouper.hibernate.BySqlStatic$1.callback(BySqlStatic.java:100)

        ... 31 more

2017-06-09 11:16:48,248: [pool-1-thread-25] INFO  EventLog.info(156) -  - [1854f1be9be540b1bc92b5141eaf9e04,'GrouperSystem','application'] delete member: group='<group_path>' list='members' subject='<SUBJECTID_2>'/'person'/'<source_ID>' (11ms)

2017-06-09 11:16:48,265: [pool-1-thread-25] DEBUG GrouperLoaderType.syncOneMemberDeleteMemberLogic(4237) -  - Group: <group_path> delete Subject id: <SUBJECTID_2>, sourceId: <source_ID>, alreadyDeleted? false

“

 

So it looks like the process “keeps going” and removes others users after the error on that one syncOneMemberDeleteMemberLogic error. ( Which seems correct.)

NOTE: I see no reference to the missing groups at all in the log either.

    It is as if the search just does not get the full list, and stops at 110 for some reason. ( any ideas on this mystery? )

 

Is there some additional logging I can turn on to find more information?

 

--

Carey Matthew