Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Authentication error with Fedora API-M #32

Closed
whikloj opened this issue Apr 30, 2015 · 4 comments
Closed

Authentication error with Fedora API-M #32

whikloj opened this issue Apr 30, 2015 · 4 comments
Labels
bug

Comments

@whikloj
Copy link
Contributor

whikloj commented Apr 30, 2015

When I go to http://localhost:8080/fedora/objects/ I can see the object. But if I go to view a datastream, it asks for a username and password. When I enter the default fedoraAdmin:fedoraAdmin then I get a WSOD and the fedora log says

WARN 2015-04-30 00:09:43.716 [http-bio-8080-exec-4] (BaseRestResource) Authorization failed; unable to fulfill REST API request
org.fcrepo.server.errors.authorization.AuthzDeniedException:
        at org.fcrepo.server.security.impl.DefaultPolicyEnforcementPoint.enforce(DefaultPolicyEnforcementPoint.java:137) ~[fcrepo-server-3.8.0.jar:na]
        at org.fcrepo.server.security.DefaultAuthorization.enforceGetDatastream(DefaultAuthorization.java:370) ~[fcrepo-server-3.8.0.jar:na]
        at org.fcrepo.server.management.DefaultManagement.getDatastream(DefaultManagement.java:1145) ~[fcrepo-server-3.8.0.jar:na]

I verified that the fedoraAdmin:fedoraAdmin combo is defined in the fedora-users.xml file.
@ruebot
Copy link
Contributor

ruebot commented May 6, 2015

Confirmed. I'll turn the logging up, and investigate the filter.

@ruebot
Copy link
Contributor

ruebot commented May 6, 2015

More verbose stack trace of the error.

DEBUG 2015-05-06 19:15:19.209 [http-bio-8080-exec-12] (AttributeFinderModule) willService() org.fcrepo.server.security.ResourceAttributeFinderModule accept this known serviced attribute urn:fedora:names:fedora:2.1:resource:datastream:state
DEBUG 2015-05-06 19:15:19.243 [http-bio-8080-exec-12] (AttributeFinderModule) ++++++++++ AttributeFinder:findAttribute org.fcrepo.server.security.ResourceAttributeFinderModule designatorType=1
DEBUG 2015-05-06 19:15:19.311 [http-bio-8080-exec-12] (AttributeFinderModule) about to get temp org.fcrepo.server.security.ResourceAttributeFinderModule
DEBUG 2015-05-06 19:15:19.351 [http-bio-8080-exec-12] (ResourceAttributeFinderModule) getResourceAttribute urn:fedora:names:fedora:2.1:resource:datastream:state, pid=islandora:root
DEBUG 2015-05-06 19:15:19.360 [http-bio-8080-exec-12] (ResourceAttributeFinderModule) pid=islandora:root
DEBUG 2015-05-06 19:15:19.365 [http-bio-8080-exec-12] (DOReaderCache) cache hit for islandora:root
DEBUG 2015-05-06 19:15:19.371 [http-bio-8080-exec-12] (DefaultDOManager) Got DOReader (source=memory) for islandora:root in 5ms.
DEBUG 2015-05-06 19:15:19.383 [http-bio-8080-exec-12] (AttributeFinderModule) AttributeFinder:getAttributeFromEvaluationCtx org.fcrepo.server.security.ResourceAttributeFinderModule returning StringAttribute: "TN"
DEBUG 2015-05-06 19:15:19.384 [http-bio-8080-exec-12] (ResourceAttributeFinderModule) datastreamId=TN
DEBUG 2015-05-06 19:15:19.386 [http-bio-8080-exec-12] (ResourceAttributeFinderModule) Locally getting the 'urn:fedora:names:fedora:2.1:resource:datastream:state' attribute for this resource took 35ms.
DEBUG 2015-05-06 19:15:19.487 [http-bio-8080-exec-12] (AttributeFinderModule) org.fcrepo.server.security.ResourceAttributeFinderModule got temp=[A]
DEBUG 2015-05-06 19:15:19.550 [http-bio-8080-exec-12] (AttributeFinderModule) AttributeFinder:findAttribute will return a String[] org.fcrepo.server.security.ResourceAttributeFinderModule
DEBUG 2015-05-06 19:15:19.634 [http-bio-8080-exec-12] (BasicEvaluationCtx) Attribute not in request: fedoraRole ... querying AttributeFinder
DEBUG 2015-05-06 19:15:19.680 [http-bio-8080-exec-12] (AttributeFinderModule) getSupportedDesignatorTypes() will return org.fcrepo.server.security.ResourceAttributeFinderModule set of elements, n=1
DEBUG 2015-05-06 19:15:19.746 [http-bio-8080-exec-12] (BasicEvaluationCtx) Attribute not in request: fedoraRole ... querying AttributeFinder
DEBUG 2015-05-06 19:15:19.775 [http-bio-8080-exec-12] (AttributeFinderModule) getSupportedDesignatorTypes() will return org.fcrepo.server.security.ResourceAttributeFinderModule set of elements, n=1
DEBUG 2015-05-06 19:15:19.781 [http-bio-8080-exec-12] (BasicEvaluationCtx) Attribute not in request: fedoraRole ... querying AttributeFinder
DEBUG 2015-05-06 19:15:19.823 [http-bio-8080-exec-12] (AttributeFinderModule) getSupportedDesignatorTypes() will return org.fcrepo.server.security.ResourceAttributeFinderModule set of elements, n=1
DEBUG 2015-05-06 19:15:20.407 [http-bio-8080-exec-12] (DefaultPolicyEnforcementPoint) Policy evaluation took 3767 ms.
DEBUG 2015-05-06 19:15:20.410 [http-bio-8080-exec-12] (DefaultPolicyEnforcementPoint) in pep, after evaluate() called
DEBUG 2015-05-06 19:15:20.416 [http-bio-8080-exec-12] (DefaultPolicyEnforcementPoint) in pep, before denyBiasedAuthz() called
DEBUG 2015-05-06 19:15:20.452 [http-bio-8080-exec-12] (AbstractPolicyEnforcementPoint) AUTHZ:  permits=0 denies=1 indeterminates=0 notApplicables=0 unexpecteds=0
DEBUG 2015-05-06 19:15:20.459 [http-bio-8080-exec-12] (DefaultPolicyEnforcementPoint) <Response>
<Result ResourceId="islandora:root">
<Decision>Deny</Decision>
<Status>
<StatusCode Value="urn:oasis:names:tc:xacml:1.0:status:ok"/>
</Status>
</Result>
</Response>

DEBUG 2015-05-06 19:15:20.466 [http-bio-8080-exec-12] (DefaultPolicyEnforcementPoint) Policy enforcement took 3945 ms.
DEBUG 2015-05-06 19:15:20.472 [http-bio-8080-exec-12] (DefaultAuthorization) Exiting enforceGetDatastream
INFO 2015-05-06 19:15:20.494 [http-bio-8080-exec-12] (DefaultManagement) Completed getDatastream(pid: islandora:root, datastreamID: TN, asOfDateTime: null)
DEBUG 2015-05-06 19:15:20.537 [http-bio-8080-exec-12] (DefaultManagement) Exiting getDatastream
WARN 2015-05-06 19:15:20.619 [http-bio-8080-exec-12] (BaseRestResource) Authorization failed; unable to fulfill REST API request
org.fcrepo.server.errors.authorization.AuthzDeniedException: 
    at org.fcrepo.server.security.impl.DefaultPolicyEnforcementPoint.enforce(DefaultPolicyEnforcementPoint.java:137) ~[fcrepo-server-3.8.0.jar:na]
    at org.fcrepo.server.security.DefaultAuthorization.enforceGetDatastream(DefaultAuthorization.java:370) ~[fcrepo-server-3.8.0.jar:na]
    at org.fcrepo.server.management.DefaultManagement.getDatastream(DefaultManagement.java:1145) ~[fcrepo-server-3.8.0.jar:na]
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.7.0_80]
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) ~[na:1.7.0_80]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_80]
    at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_80]
    at org.fcrepo.server.messaging.NotificationInvocationHandler.invoke(NotificationInvocationHandler.java:71) ~[fcrepo-server-3.8.0.jar:na]
    at com.sun.proxy.$Proxy8.getDatastream(Unknown Source) ~[na:na]
    at org.fcrepo.server.management.ManagementModule.getDatastream(ManagementModule.java:299) ~[fcrepo-server-3.8.0.jar:na]
    at org.fcrepo.server.rest.DatastreamResource.getDatastreamProfile(DatastreamResource.java:152) ~[fcrepo-server-3.8.0.jar:na]
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.7.0_80]
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) ~[na:1.7.0_80]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_80]
    at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_80]
    at org.apache.cxf.service.invoker.AbstractInvoker.performInvocation(AbstractInvoker.java:180) [cxf-api-2.7.7.jar:2.7.7]
    at org.apache.cxf.service.invoker.AbstractInvoker.invoke(AbstractInvoker.java:96) [cxf-api-2.7.7.jar:2.7.7]
    at org.apache.cxf.jaxrs.JAXRSInvoker.invoke(JAXRSInvoker.java:192) [cxf-rt-frontend-jaxrs-2.7.7.jar:2.7.7]
    at org.apache.cxf.jaxrs.JAXRSInvoker.invoke(JAXRSInvoker.java:100) [cxf-rt-frontend-jaxrs-2.7.7.jar:2.7.7]
    at org.apache.cxf.interceptor.ServiceInvokerInterceptor$1.run(ServiceInvokerInterceptor.java:57) [cxf-api-2.7.7.jar:2.7.7]
    at org.apache.cxf.interceptor.ServiceInvokerInterceptor.handleMessage(ServiceInvokerInterceptor.java:93) [cxf-api-2.7.7.jar:2.7.7]
    at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:272) [cxf-api-2.7.7.jar:2.7.7]
    at org.apache.cxf.transport.ChainInitiationObserver.onMessage(ChainInitiationObserver.java:121) [cxf-api-2.7.7.jar:2.7.7]
    at org.apache.cxf.transport.http.AbstractHTTPDestination.invoke(AbstractHTTPDestination.java:239) [cxf-rt-transports-http-2.7.7.jar:2.7.7]
    at org.apache.cxf.transport.servlet.ServletController.invokeDestination(ServletController.java:248) [cxf-rt-transports-http-2.7.7.jar:2.7.7]
    at org.apache.cxf.transport.servlet.ServletController.invoke(ServletController.java:222) [cxf-rt-transports-http-2.7.7.jar:2.7.7]
    at org.apache.cxf.transport.servlet.ServletController.invoke(ServletController.java:153) [cxf-rt-transports-http-2.7.7.jar:2.7.7]
    at org.apache.cxf.transport.servlet.CXFNonSpringServlet.invoke(CXFNonSpringServlet.java:167) [cxf-rt-transports-http-2.7.7.jar:2.7.7]
    at org.apache.cxf.transport.servlet.AbstractHTTPServlet.handleRequest(AbstractHTTPServlet.java:286) [cxf-rt-transports-http-2.7.7.jar:2.7.7]
    at org.apache.cxf.transport.servlet.AbstractHTTPServlet.doGet(AbstractHTTPServlet.java:211) [cxf-rt-transports-http-2.7.7.jar:2.7.7]
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:620) [servlet-api.jar:na]
    at org.apache.cxf.transport.servlet.AbstractHTTPServlet.service(AbstractHTTPServlet.java:262) [cxf-rt-transports-http-2.7.7.jar:2.7.7]
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:303) [catalina.jar:7.0.55]
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208) [catalina.jar:7.0.55]
    at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52) [tomcat7-websocket.jar:7.0.55]
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241) [catalina.jar:7.0.55]
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208) [catalina.jar:7.0.55]
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:369) [spring-security-web-3.0.7.RELEASE.jar:3.0.7.RELEASE]
    at org.fcrepo.server.security.jaas.AuthFilterJAAS.doFilter(AuthFilterJAAS.java:329) [fcrepo-security-jaas-3.8.0.jar:na]
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:381) [spring-security-web-3.0.7.RELEASE.jar:3.0.7.RELEASE]
    at org.springframework.security.web.access.channel.ChannelProcessingFilter.doFilter(ChannelProcessingFilter.java:109) [spring-security-web-3.0.7.RELEASE.jar:3.0.7.RELEASE]
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:381) [spring-security-web-3.0.7.RELEASE.jar:3.0.7.RELEASE]
    at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:168) [spring-security-web-3.0.7.RELEASE.jar:3.0.7.RELEASE]
    at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:237) [spring-web-3.0.7.RELEASE.jar:3.0.7.RELEASE]
    at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:167) [spring-web-3.0.7.RELEASE.jar:3.0.7.RELEASE]
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241) [catalina.jar:7.0.55]
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208) [catalina.jar:7.0.55]
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:220) [catalina.jar:7.0.55]
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:122) [catalina.jar:7.0.55]
    at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:501) [catalina.jar:7.0.55]
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:171) [catalina.jar:7.0.55]
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103) [catalina.jar:7.0.55]
    at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:950) [catalina.jar:7.0.55]
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116) [catalina.jar:7.0.55]
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:408) [catalina.jar:7.0.55]
    at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1070) [tomcat-coyote.jar:7.0.55]
    at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:611) [tomcat-coyote.jar:7.0.55]
    at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:316) [tomcat-coyote.jar:7.0.55]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [na:1.7.0_80]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [na:1.7.0_80]
    at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) [tomcat-coyote.jar:7.0.55]
    at java.lang.Thread.run(Thread.java:745) [na:1.7.0_80]
DEBUG 2015-05-06 19:15:20.807 [http-bio-8080-exec-12] (AuthFilterJAAS) outgoing filter: org.fcrepo.server.security.jaas.AuthFilterJAAS
DEBUG 2015-05-06 19:15:25.311 [timerFactory] (DOReaderCache) removing entry islandora:root after 5929 milliseconds

We're getting a deny for urn:fedora:names:fedora:2.1:resource:datastream:state which is in deny-inactive-or-deleted-objects-or-datastreams-if-not-administrator.xml.

...also updated the filter to the 3.8.0 filter.

@ruebot
Copy link
Contributor

ruebot commented May 6, 2015 

DEBUG 2015-05-06 20:00:12.506 [http-bio-8080-exec-10] (DOReaderCache) cache miss for islandora:root
DEBUG 2015-05-06 20:00:12.516 [http-bio-8080-exec-10] (DOTranslatorImpl) Grabbing deserializer for: info:fedora/fedora-system:FOXML-1.1
DEBUG 2015-05-06 20:00:12.518 [http-bio-8080-exec-10] (FOXMLDODeserializer) Deserializing info:fedora/fedora-system:FOXML-1.1 for transContext: 0
DEBUG 2015-05-06 20:00:12.520 [http-bio-8080-exec-10] (FOXMLContentHandler) instantiate XML datastream: dsid = RELS-EXT checksumType = DISABLED checksum = none
DEBUG 2015-05-06 20:00:12.524 [http-bio-8080-exec-10] (FOXMLContentHandler) instantiate XML datastream: dsid = COLLECTION_POLICY checksumType = DISABLED checksum = none
DEBUG 2015-05-06 20:00:12.529 [http-bio-8080-exec-10] (FOXMLContentHandler) instantiate datastream: dsid = TN checksumType = DISABLED checksum = none
DEBUG 2015-05-06 20:00:12.534 [http-bio-8080-exec-10] (FOXMLContentHandler) instantiate XML datastream: dsid = DC checksumType = DISABLED checksum = none
DEBUG 2015-05-06 20:00:12.540 [http-bio-8080-exec-10] (FOXMLDODeserializer) Just finished parse.
DEBUG 2015-05-06 20:00:12.728 [http-bio-8080-exec-10] (DOReaderCache) adding islandora:root to cache
DEBUG 2015-05-06 20:00:12.732 [http-bio-8080-exec-10] (DefaultDOManager) Got DOReader (source=filesystem) for islandora:root in 230ms.
DEBUG 2015-05-06 20:00:12.733 [http-bio-8080-exec-10] (BasicEvaluationCtx) Attribute not in request: fedoraRole ... querying AttributeFinder
DEBUG 2015-05-06 20:00:12.735 [http-bio-8080-exec-10] (AttributeFinderModule) getSupportedDesignatorTypes() will return org.fcrepo.server.security.ResourceAttributeFinderModule set of elements, n=1
DEBUG 2015-05-06 20:00:12.739 [http-bio-8080-exec-10] (BasicEvaluationCtx) Attribute not in request: fedoraRole ... querying AttributeFinder
DEBUG 2015-05-06 20:00:12.743 [http-bio-8080-exec-10] (AttributeFinderModule) getSupportedDesignatorTypes() will return org.fcrepo.server.security.ResourceAttributeFinderModule set of elements, n=1
DEBUG 2015-05-06 20:00:12.765 [http-bio-8080-exec-10] (BasicEvaluationCtx) Attribute not in request: fedoraRole ... querying AttributeFinder
DEBUG 2015-05-06 20:00:12.765 [http-bio-8080-exec-10] (AttributeFinderModule) getSupportedDesignatorTypes() will return org.fcrepo.server.security.ResourceAttributeFinderModule set of elements, n=1
DEBUG 2015-05-06 20:00:12.766 [http-bio-8080-exec-10] (BasicEvaluationCtx) Attribute not in request: fedoraRole ... querying AttributeFinder
DEBUG 2015-05-06 20:00:12.782 [http-bio-8080-exec-10] (AttributeFinderModule) getSupportedDesignatorTypes() will return org.fcrepo.server.security.ResourceAttributeFinderModule set of elements, n=1
DEBUG 2015-05-06 20:00:12.884 [http-bio-8080-exec-10] (BasicEvaluationCtx) Attribute not in request: fedoraRole ... querying AttributeFinder
DEBUG 2015-05-06 20:00:12.886 [http-bio-8080-exec-10] (AttributeFinderModule) getSupportedDesignatorTypes() will return org.fcrepo.server.security.ResourceAttributeFinderModule set of elements, n=1
DEBUG 2015-05-06 20:00:12.887 [http-bio-8080-exec-10] (BasicEvaluationCtx) Attribute not in request: fedoraRole ... querying AttributeFinder
DEBUG 2015-05-06 20:00:12.888 [http-bio-8080-exec-10] (AttributeFinderModule) getSupportedDesignatorTypes() will return org.fcrepo.server.security.ResourceAttributeFinderModule set of elements, n=1
DEBUG 2015-05-06 20:00:12.953 [http-bio-8080-exec-10] (BasicEvaluationCtx) Attribute not in request: fedoraRole ... querying AttributeFinder
DEBUG 2015-05-06 20:00:12.960 [http-bio-8080-exec-10] (AttributeFinderModule) getSupportedDesignatorTypes() will return org.fcrepo.server.security.ResourceAttributeFinderModule set of elements, n=1
DEBUG 2015-05-06 20:00:12.961 [http-bio-8080-exec-10] (DefaultPolicyEnforcementPoint) Policy evaluation took 476 ms.
DEBUG 2015-05-06 20:00:12.995 [http-bio-8080-exec-10] (DefaultPolicyEnforcementPoint) in pep, after evaluate() called
DEBUG 2015-05-06 20:00:13.023 [http-bio-8080-exec-10] (DefaultPolicyEnforcementPoint) in pep, before denyBiasedAuthz() called
DEBUG 2015-05-06 20:00:13.080 [http-bio-8080-exec-10] (AbstractPolicyEnforcementPoint) AUTHZ:  permits=1 denies=0 indeterminates=0 notApplicables=0 unexpecteds=0
DEBUG 2015-05-06 20:00:13.083 [http-bio-8080-exec-10] (DefaultPolicyEnforcementPoint) Policy enforcement took 662 ms.
DEBUG 2015-05-06 20:00:13.084 [http-bio-8080-exec-10] (DefaultAuthorization) Exiting enforceGetDatastreamDissemination
DEBUG 2015-05-06 20:00:13.128 [http-bio-8080-exec-10] (DOReaderCache) cache hit for islandora:root
DEBUG 2015-05-06 20:00:13.130 [http-bio-8080-exec-10] (DefaultDOManager) Got DOReader (source=memory) for islandora:root in 3ms.
DEBUG 2015-05-06 20:00:13.623 [http-bio-8080-exec-10] (DefaultAccess) Roundtrip getDatastreamDissemination: 496 milliseconds.
DEBUG 2015-05-06 20:00:13.625 [http-bio-8080-exec-10] (DOReaderCache) cache hit for islandora:root
DEBUG 2015-05-06 20:00:13.627 [http-bio-8080-exec-10] (DefaultDOManager) Got DOReader (source=memory) for islandora:root in 2ms.
DEBUG 2015-05-06 20:00:13.629 [http-bio-8080-exec-10] (DOReaderCache) cache hit for islandora:root
DEBUG 2015-05-06 20:00:13.631 [http-bio-8080-exec-10] (DefaultDOManager) Got DOReader (source=memory) for islandora:root in 1ms.
DEBUG 2015-05-06 20:00:13.650 [http-bio-8080-exec-10] (AuthFilterJAAS) outgoing filter: org.fcrepo.server.security.jaas.AuthFilterJAAS
DEBUG 2015-05-06 20:00:19.516 [timerFactory] (DOReaderCache) removing entry islandora:root after 5886 milliseconds
DEBUG 2015-05-06 20:00:25.049 [http-bio-8080-exec-3] (AuthFilterJAAS) incoming filter: org.fcrepo.server.security.jaas.AuthFilterJAAS
DEBUG 2015-05-06 20:00:25.051 [http-bio-8080-exec-3] (AuthFilterJAAS) session-id: 49B1FC6153A8F5CB016BA71799051310
DEBUG 2015-05-06 20:00:25.053 [http-bio-8080-exec-3] (AuthFilterJAAS) found userPrincipal [org.fcrepo.server.security.jaas.auth.UserPrincipal]: fedoraAdmin
DEBUG 2015-05-06 20:00:25.055 [http-bio-8080-exec-3] (SubjectUtils) checking for attributes (class name): java.util.HashMap
DEBUG 2015-05-06 20:00:25.057 [http-bio-8080-exec-3] (SubjectUtils) checking for attributes (class name): java.util.HashMap
DEBUG 2015-05-06 20:00:25.060 [http-bio-8080-exec-3] (SubjectUtils) checking for attributes (class name): java.util.HashMap
DEBUG 2015-05-06 20:00:25.088 [http-bio-8080-exec-3] (ReadOnlyContext) Request Server IP Address is '10.0.2.15'
DEBUG 2015-05-06 20:00:25.107 [http-bio-8080-exec-3] (ReadOnlyContext) Request Client IP Address is '10.0.2.2'
DEBUG 2015-05-06 20:00:25.175 [http-bio-8080-exec-3] (ReadOnlyContext) NOOP_PARAMETER_NAME=noOp
DEBUG 2015-05-06 20:00:25.192 [http-bio-8080-exec-3] (ReadOnlyContext) request.getParameter(NOOP_PARAMETER_NAME)=null
DEBUG 2015-05-06 20:00:25.196 [http-bio-8080-exec-3] (ReadOnlyContext) noOp=false
DEBUG 2015-05-06 20:00:25.200 [http-bio-8080-exec-3] (ReadOnlyContext) IN CONTEXT processing auxSubjectRoles=={fedoraRole=[]}
DEBUG 2015-05-06 20:00:25.221 [http-bio-8080-exec-3] (ReadOnlyContext) IN CONTEXT processing auxSubjectRoles.keySet()==[fedoraRole]
DEBUG 2015-05-06 20:00:25.250 [http-bio-8080-exec-3] (ReadOnlyContext) IN CONTEXT processing auxSubjectRoles.keySet().isEmpty()==false
DEBUG 2015-05-06 20:00:25.304 [http-bio-8080-exec-3] (ReadOnlyContext) IN CONTEXT processing auxSubjectRoleKeys==java.util.HashMap$KeyIterator@266ce176
DEBUG 2015-05-06 20:00:25.326 [http-bio-8080-exec-3] (ReadOnlyContext) IN CONTEXT name==fedoraRole
DEBUG 2015-05-06 20:00:25.334 [http-bio-8080-exec-3] (ReadOnlyContext) IN CONTEXT name is string==fedoraRole
DEBUG 2015-05-06 20:00:25.336 [http-bio-8080-exec-3] (ReadOnlyContext) IN CONTEXT after while
DEBUG 2015-05-06 20:00:25.337 [http-bio-8080-exec-3] (ReadOnlyContext) subject attributes in readonlycontext constructor == urn:fedora:names:fedora:2.1:subject:loginId=[fedoraAdmin]
fedoraRole=[]

DEBUG 2015-05-06 20:00:25.340 [http-bio-8080-exec-3] (DefaultManagement) Entered getDatastream
DEBUG 2015-05-06 20:00:25.404 [http-bio-8080-exec-3] (DefaultAuthorization) Entered enforceGetDatastream
DEBUG 2015-05-06 20:00:25.408 [http-bio-8080-exec-3] (ReadOnlyContext) SINGLE SUBJECT VALUE from map == fedoraAdmin
DEBUG 2015-05-06 20:00:25.409 [http-bio-8080-exec-3] (AbstractPolicyEnforcementPoint) wrapSubjectIdAsSubjects(): fedoraAdmin
DEBUG 2015-05-06 20:00:25.411 [http-bio-8080-exec-3] (AbstractPolicyEnforcementPoint) wrapSubjectIdAsSubjects(): subjectAttribute, id=urn:oasis:names:tc:xacml:1.0:subject:subject-id, type=http://www.w3.org/2001/XMLSchema#string, value=StringAttribute: ""
DEBUG 2015-05-06 20:00:25.413 [http-bio-8080-exec-3] (AbstractPolicyEnforcementPoint) wrapSubjectIdAsSubjects(): subjectAttribute, id=urn:fedora:names:fedora:2.1:subject:loginId, type=http://www.w3.org/2001/XMLSchema#string, value=StringAttribute: "fedoraAdmin"
DEBUG 2015-05-06 20:00:25.414 [http-bio-8080-exec-3] (DefaultPolicyEnforcementPoint) request action has urn:oasis:names:tc:xacml:1.0:action:action-id=StringAttribute: ""
DEBUG 2015-05-06 20:00:25.418 [http-bio-8080-exec-3] (DefaultPolicyEnforcementPoint) request action has urn:fedora:names:fedora:2.1:action:id=StringAttribute: "urn:fedora:names:fedora:2.1:action:id-getDatastream"
DEBUG 2015-05-06 20:00:25.420 [http-bio-8080-exec-3] (DefaultPolicyEnforcementPoint) request action has urn:fedora:names:fedora:2.1:action:api=StringAttribute: "urn:fedora:names:fedora:2.1:action:api-m"
DEBUG 2015-05-06 20:00:25.422 [http-bio-8080-exec-3] (DOReaderCache) cache miss for islandora:root
DEBUG 2015-05-06 20:00:25.459 [http-bio-8080-exec-3] (DOTranslatorImpl) Grabbing deserializer for: info:fedora/fedora-system:FOXML-1.1
DEBUG 2015-05-06 20:00:25.489 [http-bio-8080-exec-3] (FOXMLDODeserializer) Deserializing info:fedora/fedora-system:FOXML-1.1 for transContext: 0
DEBUG 2015-05-06 20:00:25.554 [http-bio-8080-exec-3] (FOXMLContentHandler) instantiate XML datastream: dsid = RELS-EXT checksumType = DISABLED checksum = none
DEBUG 2015-05-06 20:00:25.622 [http-bio-8080-exec-3] (FOXMLContentHandler) instantiate XML datastream: dsid = COLLECTION_POLICY checksumType = DISABLED checksum = none
DEBUG 2015-05-06 20:00:25.627 [http-bio-8080-exec-3] (FOXMLContentHandler) instantiate datastream: dsid = TN checksumType = DISABLED checksum = none
DEBUG 2015-05-06 20:00:25.660 [http-bio-8080-exec-3] (FOXMLContentHandler) instantiate XML datastream: dsid = DC checksumType = DISABLED checksum = none
DEBUG 2015-05-06 20:00:25.693 [http-bio-8080-exec-3] (FOXMLDODeserializer) Just finished parse.
DEBUG 2015-05-06 20:00:25.770 [http-bio-8080-exec-3] (DOReaderCache) adding islandora:root to cache
DEBUG 2015-05-06 20:00:25.833 [http-bio-8080-exec-3] (DefaultDOManager) Got DOReader (source=filesystem) for islandora:root in 410ms.
DEBUG 2015-05-06 20:00:25.834 [http-bio-8080-exec-3] (BasicEvaluationCtx) Attribute not in request: fedoraRole ... querying AttributeFinder
DEBUG 2015-05-06 20:00:25.834 [http-bio-8080-exec-3] (AttributeFinderModule) getSupportedDesignatorTypes() will return org.fcrepo.server.security.ResourceAttributeFinderModule set of elements, n=1
DEBUG 2015-05-06 20:00:25.836 [http-bio-8080-exec-3] (BasicEvaluationCtx) Attribute not in request: fedoraRole ... querying AttributeFinder
DEBUG 2015-05-06 20:00:25.837 [http-bio-8080-exec-3] (AttributeFinderModule) getSupportedDesignatorTypes() will return org.fcrepo.server.security.ResourceAttributeFinderModule set of elements, n=1
DEBUG 2015-05-06 20:00:25.883 [http-bio-8080-exec-3] (BasicEvaluationCtx) Attribute not in request: fedoraRole ... querying AttributeFinder
DEBUG 2015-05-06 20:00:25.899 [http-bio-8080-exec-3] (AttributeFinderModule) getSupportedDesignatorTypes() will return org.fcrepo.server.security.ResourceAttributeFinderModule set of elements, n=1
DEBUG 2015-05-06 20:00:25.969 [http-bio-8080-exec-3] (BasicEvaluationCtx) Attribute not in request: fedoraRole ... querying AttributeFinder
DEBUG 2015-05-06 20:00:25.970 [http-bio-8080-exec-3] (AttributeFinderModule) getSupportedDesignatorTypes() will return org.fcrepo.server.security.ResourceAttributeFinderModule set of elements, n=1
DEBUG 2015-05-06 20:00:25.970 [http-bio-8080-exec-3] (BasicEvaluationCtx) Attribute not in request: fedoraRole ... querying AttributeFinder
DEBUG 2015-05-06 20:00:25.972 [http-bio-8080-exec-3] (AttributeFinderModule) getSupportedDesignatorTypes() will return org.fcrepo.server.security.ResourceAttributeFinderModule set of elements, n=1
DEBUG 2015-05-06 20:00:25.973 [http-bio-8080-exec-3] (BasicEvaluationCtx) Attribute not in request: fedoraRole ... querying AttributeFinder
DEBUG 2015-05-06 20:00:25.973 [http-bio-8080-exec-3] (AttributeFinderModule) getSupportedDesignatorTypes() will return org.fcrepo.server.security.ResourceAttributeFinderModule set of elements, n=1
DEBUG 2015-05-06 20:00:26.170 [http-bio-8080-exec-3] (DefaultPolicyEnforcementPoint) Policy evaluation took 749 ms.
DEBUG 2015-05-06 20:00:26.171 [http-bio-8080-exec-3] (DefaultPolicyEnforcementPoint) in pep, after evaluate() called
DEBUG 2015-05-06 20:00:26.173 [http-bio-8080-exec-3] (DefaultPolicyEnforcementPoint) in pep, before denyBiasedAuthz() called
DEBUG 2015-05-06 20:00:26.174 [http-bio-8080-exec-3] (AbstractPolicyEnforcementPoint) AUTHZ:  permits=0 denies=1 indeterminates=0 notApplicables=0 unexpecteds=0
DEBUG 2015-05-06 20:00:26.176 [http-bio-8080-exec-3] (DefaultPolicyEnforcementPoint) <Response>
<Result ResourceId="islandora:root">
<Decision>Deny</Decision>
<Status>
<StatusCode Value="urn:oasis:names:tc:xacml:1.0:status:ok"/>
</Status>
</Result>
</Response>

DEBUG 2015-05-06 20:00:26.233 [http-bio-8080-exec-3] (DefaultPolicyEnforcementPoint) Policy enforcement took 767 ms.
DEBUG 2015-05-06 20:00:26.253 [http-bio-8080-exec-3] (DefaultAuthorization) Exiting enforceGetDatastream
INFO 2015-05-06 20:00:26.253 [http-bio-8080-exec-3] (DefaultManagement) Completed getDatastream(pid: islandora:root, datastreamID: TN, asOfDateTime: null)
DEBUG 2015-05-06 20:00:26.254 [http-bio-8080-exec-3] (DefaultManagement) Exiting getDatastream
WARN 2015-05-06 20:00:26.428 [http-bio-8080-exec-3] (BaseRestResource) Authorization failed; unable to fulfill REST API request
org.fcrepo.server.errors.authorization.AuthzDeniedException: 
    at org.fcrepo.server.security.impl.DefaultPolicyEnforcementPoint.enforce(DefaultPolicyEnforcementPoint.java:137) ~[fcrepo-server-3.8.0.jar:na]
    at org.fcrepo.server.security.DefaultAuthorization.enforceGetDatastream(DefaultAuthorization.java:370) ~[fcrepo-server-3.8.0.jar:na]
    at org.fcrepo.server.management.DefaultManagement.getDatastream(DefaultManagement.java:1145) ~[fcrepo-server-3.8.0.jar:na]
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.7.0_80]
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) ~[na:1.7.0_80]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_80]
    at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_80]
    at org.fcrepo.server.messaging.NotificationInvocationHandler.invoke(NotificationInvocationHandler.java:71) ~[fcrepo-server-3.8.0.jar:na]
    at com.sun.proxy.$Proxy8.getDatastream(Unknown Source) ~[na:na]
    at org.fcrepo.server.management.ManagementModule.getDatastream(ManagementModule.java:299) ~[fcrepo-server-3.8.0.jar:na]
    at org.fcrepo.server.rest.DatastreamResource.getDatastreamProfile(DatastreamResource.java:152) ~[fcrepo-server-3.8.0.jar:na]
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.7.0_80]
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) ~[na:1.7.0_80]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_80]
    at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_80]
    at org.apache.cxf.service.invoker.AbstractInvoker.performInvocation(AbstractInvoker.java:180) [cxf-api-2.7.7.jar:2.7.7]
    at org.apache.cxf.service.invoker.AbstractInvoker.invoke(AbstractInvoker.java:96) [cxf-api-2.7.7.jar:2.7.7]
    at org.apache.cxf.jaxrs.JAXRSInvoker.invoke(JAXRSInvoker.java:192) [cxf-rt-frontend-jaxrs-2.7.7.jar:2.7.7]
    at org.apache.cxf.jaxrs.JAXRSInvoker.invoke(JAXRSInvoker.java:100) [cxf-rt-frontend-jaxrs-2.7.7.jar:2.7.7]
    at org.apache.cxf.interceptor.ServiceInvokerInterceptor$1.run(ServiceInvokerInterceptor.java:57) [cxf-api-2.7.7.jar:2.7.7]
    at org.apache.cxf.interceptor.ServiceInvokerInterceptor.handleMessage(ServiceInvokerInterceptor.java:93) [cxf-api-2.7.7.jar:2.7.7]
    at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:272) [cxf-api-2.7.7.jar:2.7.7]
    at org.apache.cxf.transport.ChainInitiationObserver.onMessage(ChainInitiationObserver.java:121) [cxf-api-2.7.7.jar:2.7.7]
    at org.apache.cxf.transport.http.AbstractHTTPDestination.invoke(AbstractHTTPDestination.java:239) [cxf-rt-transports-http-2.7.7.jar:2.7.7]
    at org.apache.cxf.transport.servlet.ServletController.invokeDestination(ServletController.java:248) [cxf-rt-transports-http-2.7.7.jar:2.7.7]
    at org.apache.cxf.transport.servlet.ServletController.invoke(ServletController.java:222) [cxf-rt-transports-http-2.7.7.jar:2.7.7]
    at org.apache.cxf.transport.servlet.ServletController.invoke(ServletController.java:153) [cxf-rt-transports-http-2.7.7.jar:2.7.7]
    at org.apache.cxf.transport.servlet.CXFNonSpringServlet.invoke(CXFNonSpringServlet.java:167) [cxf-rt-transports-http-2.7.7.jar:2.7.7]
    at org.apache.cxf.transport.servlet.AbstractHTTPServlet.handleRequest(AbstractHTTPServlet.java:286) [cxf-rt-transports-http-2.7.7.jar:2.7.7]
    at org.apache.cxf.transport.servlet.AbstractHTTPServlet.doGet(AbstractHTTPServlet.java:211) [cxf-rt-transports-http-2.7.7.jar:2.7.7]
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:620) [servlet-api.jar:na]
    at org.apache.cxf.transport.servlet.AbstractHTTPServlet.service(AbstractHTTPServlet.java:262) [cxf-rt-transports-http-2.7.7.jar:2.7.7]
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:303) [catalina.jar:7.0.55]
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208) [catalina.jar:7.0.55]
    at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52) [tomcat7-websocket.jar:7.0.55]
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241) [catalina.jar:7.0.55]
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208) [catalina.jar:7.0.55]
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:369) [spring-security-web-3.0.7.RELEASE.jar:3.0.7.RELEASE]
    at org.fcrepo.server.security.jaas.AuthFilterJAAS.doFilter(AuthFilterJAAS.java:329) [fcrepo-security-jaas-3.8.0.jar:na]
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:381) [spring-security-web-3.0.7.RELEASE.jar:3.0.7.RELEASE]
    at org.springframework.security.web.access.channel.ChannelProcessingFilter.doFilter(ChannelProcessingFilter.java:109) [spring-security-web-3.0.7.RELEASE.jar:3.0.7.RELEASE]
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:381) [spring-security-web-3.0.7.RELEASE.jar:3.0.7.RELEASE]
    at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:168) [spring-security-web-3.0.7.RELEASE.jar:3.0.7.RELEASE]
    at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:237) [spring-web-3.0.7.RELEASE.jar:3.0.7.RELEASE]
    at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:167) [spring-web-3.0.7.RELEASE.jar:3.0.7.RELEASE]
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241) [catalina.jar:7.0.55]
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208) [catalina.jar:7.0.55]
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:220) [catalina.jar:7.0.55]
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:122) [catalina.jar:7.0.55]
    at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:501) [catalina.jar:7.0.55]
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:171) [catalina.jar:7.0.55]
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103) [catalina.jar:7.0.55]
    at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:950) [catalina.jar:7.0.55]
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116) [catalina.jar:7.0.55]
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:408) [catalina.jar:7.0.55]
    at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1070) [tomcat-coyote.jar:7.0.55]
    at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:611) [tomcat-coyote.jar:7.0.55]
    at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:316) [tomcat-coyote.jar:7.0.55]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [na:1.7.0_80]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [na:1.7.0_80]
    at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) [tomcat-coyote.jar:7.0.55]
    at java.lang.Thread.run(Thread.java:745) [na:1.7.0_80]
DEBUG 2015-05-06 20:00:26.716 [http-bio-8080-exec-3] (AuthFilterJAAS) outgoing filter: org.fcrepo.server.security.jaas.AuthFilterJAAS
DEBUG 2015-05-06 20:00:30.612 [timerFactory] (DOReaderCache) removing entry islandora:root after 5190 milliseconds

Removed deny-inactive-or-deleted-objects-or-datastreams-if-not-administrator.xml. Looks like we're getting a deny for urn:fedora:names:fedora:2.1:action:id-getDatastream and
urn:fedora:names:fedora:2.1:action:api-m now.

$ grep -R "urn:fedora:names:fedora:2.1:action:id-getDatastream" .
./islandora/permit-getDatastreamHistory-unrestricted.xml:         <AttributeValue DataType="http://www.w3.org/2001/XMLSchema#string">urn:fedora:names:fedora:2.1:action:id-getDatastreamHistory</AttributeValue>
./islandora/permit-getDatastream-unrestricted.xml:         <AttributeValue DataType="http://www.w3.org/2001/XMLSchema#string">urn:fedora:names:fedora:2.1:action:id-getDatastream</AttributeValue>

$ grep -R "urn:fedora:names:fedora:2.1:action:id-getDatastream" .
./islandora/permit-getDatastreamHistory-unrestricted.xml:         <AttributeValue DataType="http://www.w3.org/2001/XMLSchema#string">urn:fedora:names:fedora:2.1:action:id-getDatastreamHistory</AttributeValue>
./islandora/permit-getDatastream-unrestricted.xml:         <AttributeValue DataType="http://www.w3.org/2001/XMLSchema#string">urn:fedora:names:fedora:2.1:action:id-getDatastream</AttributeValue>
vagrant@islandora:/usr/local/fedora/data/fedora-xacml-policies/repository-policies$ grep -R "urn:fedora:names:fedora:2.1:action:api-m" .
./islandora/permit-apim-to-anonymous-user.xml:                    <AttributeValue DataType="http://www.w3.org/2001/XMLSchema#string">urn:fedora:names:fedora:2.1:action:api-m</AttributeValue>
./islandora/permit-apim-to-authenticated-user.xml:          <AttributeValue DataType="http://www.w3.org/2001/XMLSchema#string">urn:fedora:names:fedora:2.1:action:api-m</AttributeValue>
./default/deny-apim-if-not-localhost.xml:          <AttributeValue DataType="http://www.w3.org/2001/XMLSchema#string">urn:fedora:names:fedora:2.1:action:api-m</AttributeValue>

@ruebot
Copy link
Contributor

ruebot commented May 6, 2015

...narrowed it down. Looks like it is default/deny-apim-if-not-localhost.xml. By wildcarding it like this, it solved the issue. This probably isn't ideal, and I'm not sure if this is just an issue of working from a local desktop to vagrant vm, or something else sinister.

ruebot added a commit that referenced this issue May 6, 2015
@ruebot
Use the correct filter. Maybe related to #32.
2d13863
@ruebot ruebot closed this as completed in 8badbe2 May 9, 2015
@ruebot ruebot added the bug label May 11, 2015
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@ruebot @whikloj