Grouper Users - Open Discussion List

[Shilen Patel <>]

FWIW, I don't think subject not found errors would result that way.  There's another exception in the logs that I believe would though.

2016-03-22 10:25:13,017: [pool-1-thread-12] ERROR GrouperLoaderType.syncOneGroupMembership(2395) -  - Problem with group: osu:ref:emp:eclass:UE

net.sf.ehcache.ObjectExistsException: Cache edu.internet2.middleware.grouper.internal.dao.hib3.Hib3GroupDAO.exists already exists,

Exception in save: edu.internet2.middleware.grouper.Membership, edu.internet2.middleware.grouper.hibernate.ByObject@2b3bb4b6,

Problem in HibernateSession: HibernateSession (2ffc0189): notNew, notReadonly, READ_WRITE_NEW, activeTransaction, session (51cb478c),

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

Problem in HibernateSession: HibernateSession (72bb2f59): new, notReadonly, READ_WRITE_NEW, notActiveTransaction, session (51cb478c)

        at net.sf.ehcache.CacheManager.addCacheNoCheck(CacheManager.java:1046)

        at net.sf.ehcache.CacheManager.addCache(CacheManager.java:988)

        at net.sf.ehcache.CacheManager.addCache(CacheManager.java:966)

        at edu.internet2.middleware.grouper.cache.EhcacheController.getCache(EhcacheController.java:201)

        at edu.internet2.middleware.grouper.cache.GrouperCache.<init>(GrouperCache.java:106)

        at edu.internet2.middleware.grouper.internal.dao.hib3.Hib3GroupDAO.getExistsCache(Hib3GroupDAO.java:110)

        at edu.internet2.middleware.grouper.internal.dao.hib3.Hib3GroupDAO.exists(Hib3GroupDAO.java:180)

        at edu.internet2.middleware.grouper.validator.MembershipValidator._doesOwnerExist(MembershipValidator.java:101)

        at edu.internet2.middleware.grouper.validator.MembershipValidator.validate(MembershipValidator.java:65)

        at edu.internet2.middleware.grouper.validator.ImmediateMembershipValidator.validate(ImmediateMembershipValidator.java:107)

        at edu.internet2.middleware.grouper.Membership.onPreSave(Membership.java:1738)

        at edu.internet2.middleware.grouper.hibernate.ByObject.save(ByObject.java:201)

        at edu.internet2.middleware.grouper.hibernate.ByObjectStatic$7.callback(ByObjectStatic.java:481)

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

        at edu.internet2.middleware.grouper.hibernate.ByObjectStatic.save(ByObjectStatic.java:468)

        at edu.internet2.middleware.grouper.internal.dao.hib3.Hib3MembershipDAO.save(Hib3MembershipDAO.java:2053)

        at edu.internet2.middleware.grouper.Membership.internal_addImmediateMembership(Membership.java:1246)

        at edu.internet2.middleware.grouper.privs.GrouperNonDbAccessAdapter$1.callback(GrouperNonDbAccessAdapter.java:307)

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

        at edu.internet2.middleware.grouper.privs.GrouperNonDbAccessAdapter.grantPriv(GrouperNonDbAccessAdapter.java:294)

        at edu.internet2.middleware.grouper.privs.AccessWrapper.grantPrivilege(AccessWrapper.java:168)

        at edu.internet2.middleware.grouper.privs.AccessResolverDecorator.grantPrivilege(AccessResolverDecorator.java:164)

        at edu.internet2.middleware.grouper.privs.AccessResolverDecorator.grantPrivilege(AccessResolverDecorator.java:164)

        at edu.internet2.middleware.grouper.privs.CachingAccessResolver.grantPrivilege(CachingAccessResolver.java:138)

        at edu.internet2.middleware.grouper.privs.AccessResolverDecorator.grantPrivilege(AccessResolverDecorator.java:164)

        at edu.internet2.middleware.grouper.privs.ValidatingAccessResolver.grantPrivilege(ValidatingAccessResolver.java:137)

        at edu.internet2.middleware.grouper.Group$12.callback(Group.java:4071)

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

        at edu.internet2.middleware.grouper.Group.internal_grantPriv(Group.java:4059)

        at edu.internet2.middleware.grouper.Group.grantPriv(Group.java:4023)

        at edu.internet2.middleware.grouper.app.loader.GrouperLoaderType.syncOneGroupMembership(GrouperLoaderType.java:2096)

        at edu.internet2.middleware.grouper.app.loader.GrouperLoaderType.syncGroupLogicForOneGroup(GrouperLoaderType.java:1462)

        at edu.internet2.middleware.grouper.app.loader.GrouperLoaderType.access$200(GrouperLoaderType.java:108)

        at edu.internet2.middleware.grouper.app.loader.GrouperLoaderType$10.callLogic(GrouperLoaderType.java:1382)

        at edu.internet2.middleware.grouper.app.loader.GrouperLoaderType$10.callLogic(GrouperLoaderType.java:1378)

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

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

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

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

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

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

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

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

Seems like two threads probably tried to create that cache at the same time.

  /**

   * lazy load

   * @return cache

   */

  private static GrouperCache<String, Boolean> getExistsCache() {

    if(existsCache==null) {

      existsCache=new GrouperCache<String, Boolean>("edu.internet2.middleware.grouper.internal.dao.hib3.Hib3GroupDAO.exists",

            1000, false, 30, 120, false);

    }

    return existsCache;

  }

Probably a very rare error and one that would be okay the next time it ran, but a little bit of locking could avoid it.  Seem reasonable?

Thanks!

- Shilen

On 3/24/16, 12:50 AM, "Hyzer, Chris" <> wrote:

You have some unresolvable subjects which would cause an error.  Grouper v2.3 soon to be released will be able to absorb some unresolvable subject errors without erroring out the job...

Thanks

Chris

-----Original Message-----

From: Andrew Morgan []

Sent: Wednesday, March 23, 2016 12:57 PM

To: Hyzer, Chris <>

Cc:

Subject: RE: [grouper-users] mysterious error in loader job

There are no other errors nearby in the logs.  There are some other errors

near the beginning of the job that I didn't notice until now, but I don't

understand them.

I have posted the logs for this job at:

   http://people.oregonstate.edu/~morgan/grouper-error.zip

Do you mind taking a quick look?

Thanks,

Andy

On Wed, 23 Mar 2016, Hyzer, Chris wrote:

There should have been more in the logs further up...  was there?  :)

Thanks

Chris

-----Original Message-----

From: [] On Behalf Of Andrew Morgan

Sent: Tuesday, March 22, 2016 3:23 PM

To:

Subject: [grouper-users] mysterious error in loader job

I ran a loader job manually using GSH this morning, and it died midway

through:

...

2016-03-22 10:26:13,095: [pool-1-thread-6] INFO  EventLog.info(156) -  - [c00000020c2143b0b57a4d8cbae471e3,'GrouperSystem','application'] add member: group='osu:ref:emp:eclass:XX' list='members' subject='hansenev'/'person'/'ldap' (29ms)

2016-03-22 10:26:13,097: [pool-1-thread-58] INFO  EventLog.info(156) -  - [91e6e752ca14487081522f05fbe8eb6d,'GrouperSystem','application'] add member: group='osu:ref:emp:eclass:XX' list='members' subject='fettigch'/'person'/'ldap' (32ms)

2016-03-22 10:26:13,169: [main] ERROR GrouperLoaderJob.runJob(433) -  - Error on job: SQL_GROUP_LIST__osu:ref:emp:loader:eclassGroups__6bee0641953641689ace2a06398a9fd2

java.lang.RuntimeException: Error in loader job: osu:ref:emp:loader:eclassGroups, check logs: null

         at edu.internet2.middleware.grouper.app.loader.GrouperLoaderJob.runJob(GrouperLoaderJob.java:422)

         at edu.internet2.middleware.grouper.app.loader.GrouperLoader.runJobOnceForGroup(GrouperLoader.java:1004)

         at edu.internet2.middleware.grouper.app.gsh.loaderRunOneJob.invoke(loaderRunOneJob.java:57)

         at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

         at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)

         at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)

         at java.lang.reflect.Method.invoke(Method.java:606)

         at bsh.Reflect.invokeMethod(Unknown Source)

         at bsh.Reflect.invokeStaticMethod(Unknown Source)

         at bsh.Reflect.invokeCompiledCommand(Unknown Source)

         at bsh.Name.invokeLocalMethod(Unknown Source)

         at bsh.Name.invokeMethod(Unknown Source)

         at bsh.BSHMethodInvocation.eval(Unknown Source)

         at bsh.BSHPrimaryExpression.eval(Unknown Source)

         at bsh.BSHPrimaryExpression.eval(Unknown Source)

         at bsh.Interpreter.eval(Unknown Source)

         at bsh.Interpreter.eval(Unknown Source)

         at bsh.Interpreter.eval(Unknown Source)

         at edu.internet2.middleware.grouper.app.gsh.ShellHelper.eval(ShellHelper.java:63)

         at edu.internet2.middleware.grouper.app.gsh.GrouperShell.run(GrouperShell.java:429)

         at edu.internet2.middleware.grouper.app.gsh.GrouperShell.grouperShellHelper(GrouperShell.java:232)

         at edu.internet2.middleware.grouper.app.gsh.GrouperShell.main(GrouperShell.java:162)

         at edu.internet2.middleware.grouper.app.gsh.GrouperShellWrapper.main(GrouperShellWrapper.java:31)

I ran it again, and it completed successfully.

"check logs: null" is not a lot to go on...  :)

Thanks,

Andy