Grouper Users - Open Discussion List

[Jim Fox <>]

I'm having cache issues with grouper 2.3
This is version 2.3 with patches to 100 or so.  I haven't edited the cache 
properties files.

I put a group, with admin info and etc

I try to read the group and get lookup the admins: by 
SubjectFinder.findByIdentifier('some_id')

The log shows we get to here quickly:

   2018-08-27 13:30:56,673: [ajp-nio-127.0.0.1-8009-exec-7] DEBUG 
SourcesXmlResolver$LogLabelCallable.call(174) -  - findByIdentifier on 
source: g:gsa, 'gws.cac.washington.edu', time in millis: 10
   2018-08-27 13:30:56,674: [ajp-nio-127.0.0.1-8009-exec-7] DEBUG 
SourcesXmlResolver$LogLabelCallable.call(174) -  - findByIdentifier on 
source: uwpds, 'gws.cac.washington.edu', time in millis: 1
   2018-08-27 13:30:56,675: [ajp-nio-127.0.0.1-8009-exec-7] DEBUG 
Hib3MemberDAO.membersFlashCacheRetrieveBySubjectId(1029) -  - retrieving from 
member flash cache by subjectId: uwpds, d9459cae21d011d4abd00004ac494ffe

Then this right away:

   2018-08-27 13:30:56,675: [ajp-nio-127.0.0.1-8009-exec-7] DEBUG 
HibernateSession.<init>(288) -  - HibernateSession.<init>() line 288, 
HibernateSession._internal_hibernateSession() line 468, 
HibernateSession.callbackHibernateSession() line 660, ByHqlStatic.list() line 407, 
ByHqlStatic.listSet() line 458, Hib3GroupDAO.findAllGroupsSecureHelper() line 3351, 
Hib3GroupDAO.getAllGroupsSecure() line 3895, GroupFinder.findGroups() line 1180, 
GrouperSourceAdapter.callback() line 288, GrouperSession.callbackGrouperSession() line 
974, GrouperSourceAdapter.getSubjectsByIdentifiers() line 272, 
GrouperSourceAdapter.getSubjectByIdentifier() line 378, SourcesXmlResolver.callLogic() 
line 387, SourcesXmlResolver.callLogic() line 384, SourcesXmlResolver.call() line 169, 
SourcesXmlResolver.executeCallables() line 230, SourcesXmlResolver.findByIdentifier() 
line 393, CachingResolver.findByIdentifier() line 191, 
ValidatingResolver.findByIdentifier() line 160, SubjectFinder.findByIdentifier() li!
ne 1088, SubjectFinder.findByIdentifier() line 697

and

   2018-08-27 13:30:56,676: [ajp-nio-127.0.0.1-8009-exec-7] DEBUG 
HibernateSession.<init>(289) -  - grouperTransactionType: 
READONLY_OR_USE_EXISTING, okToUseHibernate: true, readonlyMode: false, 
parentSessionExists: false, newHibernateSession: true, 
immediateGrouperTransactionTypeUsed: READONLY_NEW, 
immediateGrouperTransactionTypeReadonly: true, hibernateSession: HibernateSession 
(1e4e29ae): new, readonly, READONLY_NEW, notActiveTransaction, session (4fa2c92c)


Then, a full 20 seconds later:

   2018-08-27 13:31:16,608: [ajp-nio-127.0.0.1-8009-exec-7] DEBUG 
ByHql.list(446) -  - returnType: Group, hibernateSession: HibernateSession 
(1e4e29ae): new, readonly, READONLY_NEW, notActiveTransaction, session 
(4fa2c92c), foundSize: 0
   2018-08-27 13:31:16,610: [ajp-nio-127.0.0.1-8009-exec-7] DEBUG 
HibernateSession.callbackHibernateSession(716) -  - 
HibernateSession.callbackHibernateSession() line 716, ByHqlStatic.list() line 
407, ByHqlStatic.listSet() line 458, Hib3GroupDAO.findAllGroupsSecureHelper() 
line 3351, Hib3GroupDAO.getAllGroupsSecure() line 3895, 
GroupFinder.findGroups() line 1180, GrouperSourceAdapter.callback() line 288, 
GrouperSession.callbackGrouperSession() line 974, 
GrouperSourceAdapter.getSubjectsByIdentifiers() line 272, 
GrouperSourceAdapter.getSubjectByIdentifier() line 378, 
SourcesXmlResolver.callLogic() line 387, SourcesXmlResolver.callLogic() line 
384, SourcesXmlResolver.call() line 169, 
SourcesXmlResolver.executeCallables() line 230, 
SourcesXmlResolver.findByIdentifier() line 393, 
CachingResolver.findByIdentifier() line 191, 
ValidatingResolver.findByIdentifier() line 160, 
SubjectFinder.findByIdentifier() line 1088, SubjectFinder.findByIdentifier() 
line 697
   2018-08-27 13:31:16,611: [ajp-nio-127.0.0.1-8009-exec-7] DEBUG 
HibernateSession.callbackHibernateSession(717) -  - grouperTransactionType: 
READONLY_OR_USE_EXISTING, auditControl: WILL_NOT_AUDIT, hibernateSession: 
HibernateSession (1e4e29ae): new, readonly, READONLY_NEW, 
notActiveTransaction, session (4fa2c92c), hibernateSessionsInThreadLocal: 
1e4e29ae, willCreateAudit: false, createdContext: false, closedSession: true
   2018-08-27 13:31:16,611: [ajp-nio-127.0.0.1-8009-exec-7] DEBUG 
GrouperSession.callbackGrouperSession(986) -  - Stack: 
GrouperSession.callbackGrouperSession() line 986, 
GrouperSourceAdapter.getSubjectsByIdentifiers() line 272, 
GrouperSourceAdapter.getSubjectByIdentifier() line 378, 
SourcesXmlResolver.callLogic() line 387, SourcesXmlResolver.callLogic() line 
384, SourcesXmlResolver.call() line 169, 
SourcesXmlResolver.executeCallables() line 230, 
SourcesXmlResolver.findByIdentifier() line 393, 
CachingResolver.findByIdentifier() line 191, 
ValidatingResolver.findByIdentifier() line 160, 
SubjectFinder.findByIdentifier() line 1088, SubjectFinder.findByIdentifier() 
line 697
   2018-08-27 13:31:16,612: [ajp-nio-127.0.0.1-8009-exec-7] DEBUG 
GrouperSession.callbackGrouperSession(987) -  - 
{method=callbackGrouperSession(), hash=821691446, 
subject=d9459cae21d011d4abd00004ac494ffe, 
start_staticSession=d9459cae21d011d4abd00004ac494ffe, start_staticSessions=0, 
needsToBeRemoved=true, 
postAdd_staticSession=d9459cae21d011d4abd00004ac494ffe, 
postAdd_staticSessions_0=d9459cae21d011d4abd00004ac494ffe, 
end_staticSession=d9459cae21d011d4abd00004ac494ffe, end_staticSessions=0}
   2018-08-27 13:31:16,612: [ajp-nio-127.0.0.1-8009-exec-7] DEBUG 
SourcesXmlResolver$LogLabelCallable.call(174) -  - findByIdentifier on 
source: grouperEntities, 'gws.cac.washington.edu', time in millis: 19937

Note the 19937 milliseconds.

How can I stop this?
Can I disable cache while I'm trying to fix it?

Thanks,
Jim