Grouper Users - Open Discussion List

["Black, Carey M." <>]

All,

Yesterday I was alerted to an odd behavior of our grouper install. While 
investigating the condition the "odd behavior" resolved itself and returned 
to normal. 
        ( I changed nothing. I did not even restart anything. I was still 
looking at logs and testing myself when it fixed itself. )
        BTW: Grouper 2.3 

I have my suspicions about what it might have been, but I want to describe 
the behavior and see if someone can tell me what the logs are really saying. 
( Or as I suspect, not saying.)


When a user logged in to the UI ( it may have affected existing users, I 
don't know for sure ) they were given an error page informing them that they 
are not in the group that allows them access to the UI. ( AKA: 
require.group.for.logins setting )

The users that reported the behavior were existing members of that group 
prior to the event. ( And had been members for months. )
Even my account was effected. [ Gulp.... Uh..... WT? ]

It may be of note that for our install:
        " Subject id: XXXX " is the users "username" , and " login subject: 
"YYYY-for XXXX"," is a unique identifier supplied by our IDM system 
(available to Grouper via the Subject API )


This is the only thing that found the logs that looked related ( sanitized ) :
"
2018-07-18 15:56:57,175: [ajp-nio-8009-exec-1] ERROR 
GrouperUiFilter.ensureUserAllowedInSection(446) -  - Error, user Subject id: 
XXXX, sourceId: SSSS needs to be in one of the following groups: < 
require.group.for.logins >
2018-07-18 15:56:57,176: [ajp-nio-8009-exec-1] ERROR 
GrouperUiFilter.initRequest(898) -  - Cant find login subject: "YYYY-for 
XXXX", ADMIN_UI
java.lang.RuntimeException: Error, user Subject id: XXXX, sourceId: SSSS 
needs to be in one of the following groups: < require.group.for.logins >
        at 
edu.internet2.middleware.grouper.ui.GrouperUiFilter.ensureUserAllowedInSection(GrouperUiFilter.java:457)
        at 
edu.internet2.middleware.grouper.ui.GrouperUiFilter.retrieveSubjectLoggedIn(GrouperUiFilter.java:306)
        at 
edu.internet2.middleware.grouper.ui.GrouperUiFilter.retrieveSubjectLoggedIn(GrouperUiFilter.java:292)
        at 
edu.internet2.middleware.grouper.ui.GrouperUiFilter.initRequest(GrouperUiFilter.java:893)
        at 
edu.internet2.middleware.grouper.ui.GrouperUiFilter.doFilter(GrouperUiFilter.java:993)
        at 
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:192)
        at 
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:165)
        at 
org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:198)
        at 
org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96)
        at 
org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:478)
        at 
org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:140)
        at 
org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:80)
        at 
org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:624)
        at 
org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87)
        at 
org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:341)
        at org.apache.coyote.ajp.AjpProcessor.service(AjpProcessor.java:478)
        at 
org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)
        at 
org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:798)
        at 
org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1441)
        at 
org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
        at 
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at 
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at 
org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
        at java.lang.Thread.run(Thread.java:748)
2018-07-18 15:56:57,178: [ajp-nio-8009-exec-1] ERROR 
GrouperUiFilter.initRequest(942) -  - error in init
edu.internet2.middleware.grouper.ui.exceptions.ControllerDone
        at 
edu.internet2.middleware.grouper.ui.GrouperUiFilter.initRequest(GrouperUiFilter.java:905)
        at 
edu.internet2.middleware.grouper.ui.GrouperUiFilter.doFilter(GrouperUiFilter.java:993)
        at 
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:192)
        at 
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:165)
        at 
org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:198)
        at 
org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96)
        at 
org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:478)
        at 
org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:140)
        at 
org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:80)
        at 
org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:624)
        at 
org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87)
        at 
org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:341)
        at org.apache.coyote.ajp.AjpProcessor.service(AjpProcessor.java:478)
        at 
org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)
        at 
org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:798)
        at 
org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1441)
        at 
org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
        at 
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at 
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at 
org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
        at java.lang.Thread.run(Thread.java:748)
"



OK. Now to color your thoughts with my guess....

During the login process I suspect that the SubjectAPI failed to return a 
result for REMOTE_USER. And the values that were logged were sourced from a 
grouper cache for that "REMOTE_USER" (AKA " Subject id: XXXX " ) value. That 
failure may have prevented the lookup of the membership for the user. Which 
was surfaced to the logs and UI as "you are not a member of the group" error. 

So, my guess, is that the real error was masked and a "downstream error" was 
surfaced.


Can anyone:
  Confirm that makes sense? (or is possible)
      Or
 Suggest an alternate explanation?
     And (please)
 Identify any log setting I could enable to catch/identify this condition in 
the future?


Thanks in advance.

-- 
Carey Matthew