Grouper Users - Open Discussion List

["Hyzer, Chris" <>]

I missed this original email, sorry.

 

Fixed the priority issue in grouper api v2_3_0 patch #71

 

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

 

Note, your log message at end, is just a warning, it is expected and not a problem.  “Non fatal problem with callable.  Will try again not in thread”

 

You can change the things back in the grouper properties.

 

Do all your groups have members?

 

Thanks

Chris

 

 

 

From: [mailto:] On Behalf Of Black, Carey M.
Sent: Thursday, June 15, 2017 9:33 AM
To:
Subject: [grouper-users] RE: Maybe a daemon/loader bug report? Two parts: priority value, missing groups

 

Well, the plot thickens….

 

I can confirm that the process is not loading all of the members of the groups as well.

 

So not only is the loader job not loading all of the groups, but also not all of the members.

 

However, it looks like the deadlock is being caused by my attempt to use the “” feature.

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

 

 

So on a lark… I turned that off….

 

“

#####################################

## Settings to track last membership changes for groups and stems.

#####################################

 

# If true, when an immediate membership changes for a group (either a privilege or a list member),

# then an update will be made to the lastImmediateMembershipChange property for the group.

groups.updateLastImmediateMembershipTime = false

#groups.updateLastImmediateMembershipTime = true

 

# If true, when an immediate, composite, or effective membership changes for a group (either a privilege or a list member),

# then an update will be made to the lastMembershipChange property for the group.

groups.updateLastMembershipTime = false

#groups.updateLastMembershipTime = true

 

# If true, when an immediate or effective membership changes for a stem (this would be a naming privilege),

# then an update will be made to the lastMembershipChange property for the stem.

stems.updateLastMembershipTime = false

#stems.updateLastMembershipTime = true

“

 

However, the db deadlock problem continues. ( I think less frequently. However the member count in Grouper does not match the “member count” in the source system.)

 

Any ideas/guidance on how this can be investigated/resolved?

 

--

Carey Matthew

 

From: [] On Behalf Of Black, Carey M.
Sent: Friday, June 9, 2017 1:08 PM
To:
Subject: [grouper-users] Maybe a daemon/loader bug report? Two parts: priority value, missing groups

 

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, ,

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: , ,

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