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

Editing through Fedora's Flash admin client is broken #66

Closed
ksclarke opened this issue May 26, 2015 · 11 comments
Closed

Editing through Fedora's Flash admin client is broken #66

ksclarke opened this issue May 26, 2015 · 11 comments
Assignees
@ruebot
Labels
bug

Comments

@ksclarke
Copy link
Contributor

In need of a sanity check... I don't seem to be able to edit a MODS datastream through the Fedora web admin client on an islandora_vagrant instance. I just get a blank screen when I go to an object, select MODS, and then select "Edit Content".
@mjordan
Copy link
Contributor

mjordan commented May 26, 2015

I'm not getting a blank screen, but nothing happens when I click on Edit. Same thing regardless of ds. I'm at 694932f.

@ksclarke
Copy link
Contributor Author

You're right... it's not a blank screen (that must have just been my mind at the moment of testing)... it's just that nothing happens. Thanks for the confirmation.

@ksclarke
Copy link
Contributor Author

From @whikloj in the Islandora IRC channel: "seems to be a fedora xacml policy denial. Probably due to deny-apim-if-not-localhost.xml"

@whikloj
Copy link
Contributor

whikloj commented May 26, 2015

I was partially correct. Initially I wasn't seeing any data when I clicked on a datastream in the admin interface. Removing the policy allowed me to see and edit the data.
But clicking the "Save Changes" button says it works, but nothing changes and in the logs I see:

Completed modifyDatastreamByValue(pid: islandora:1, datastreamId: RELS-EXT, altIDs: '', dsLabel: Fedora Object to Object Relationship Metadata., mimeType: application/rdf+xml, formatURI: info:fedora/fedora-system:FedoraRELSExt-1.0, dsContent , checksumType: Disabled, checksum: null, logMessage: null)
WARN 2015-05-26 18:16:24.409 [http-bio-8080-exec-12] (DatastreamResource) 
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.enforceModifyDatastreamByValue(DefaultAuthorization.java:674) ~[fcrepo-server-3.8.0.jar:na]
    at org.fcrepo.server.management.DefaultManagement.modifyDatastreamByValue(DefaultManagement.java:855) ~[fcrepo-server-3.8.0.jar:na]

@ruebot
Copy link
Contributor

ruebot commented May 27, 2015

Full stack trace with DEBUG enabled for fcrepo.

DEBUG 2015-05-27 03:37:09.109 [http-bio-8080-exec-11] (ReadOnlyContext) Request Server IP Address is '10.0.2.15'
DEBUG 2015-05-27 03:37:09.109 [http-bio-8080-exec-11] (ReadOnlyContext) Request Client IP Address is '10.0.2.2'
DEBUG 2015-05-27 03:37:09.110 [http-bio-8080-exec-11] (ReadOnlyContext) NOOP_PARAMETER_NAME=noOp
DEBUG 2015-05-27 03:37:09.110 [http-bio-8080-exec-11] (ReadOnlyContext) request.getParameter(NOOP_PARAMETER_NAME)=null
DEBUG 2015-05-27 03:37:09.110 [http-bio-8080-exec-11] (ReadOnlyContext) noOp=false
DEBUG 2015-05-27 03:37:09.111 [http-bio-8080-exec-11] (ReadOnlyContext) IN CONTEXT processing auxSubjectRoles=={fedoraRole=[]}
DEBUG 2015-05-27 03:37:09.111 [http-bio-8080-exec-11] (ReadOnlyContext) IN CONTEXT processing auxSubjectRoles.keySet()==[fedoraRole]
DEBUG 2015-05-27 03:37:09.111 [http-bio-8080-exec-11] (ReadOnlyContext) IN CONTEXT processing auxSubjectRoles.keySet().isEmpty()==false
DEBUG 2015-05-27 03:37:09.111 [http-bio-8080-exec-11] (ReadOnlyContext) IN CONTEXT processing auxSubjectRoleKeys==java.util.HashMap$KeyIterator@60b2042a
DEBUG 2015-05-27 03:37:09.112 [http-bio-8080-exec-11] (ReadOnlyContext) IN CONTEXT name==fedoraRole
DEBUG 2015-05-27 03:37:09.112 [http-bio-8080-exec-11] (ReadOnlyContext) IN CONTEXT name is string==fedoraRole
DEBUG 2015-05-27 03:37:09.113 [http-bio-8080-exec-11] (ReadOnlyContext) IN CONTEXT after while
DEBUG 2015-05-27 03:37:09.113 [http-bio-8080-exec-11] (ReadOnlyContext) subject attributes in readonlycontext constructor == fedoraRole=[]
urn:fedora:names:fedora:2.1:subject:loginId=[fedoraAdmin]

DEBUG 2015-05-27 03:37:09.113 [http-bio-8080-exec-11] (DefaultManagement) Entered getDatastream
DEBUG 2015-05-27 03:37:09.113 [http-bio-8080-exec-11] (DefaultAuthorization) Entered enforceGetDatastream
DEBUG 2015-05-27 03:37:09.114 [http-bio-8080-exec-11] (ReadOnlyContext) SINGLE SUBJECT VALUE from map == fedoraAdmin
DEBUG 2015-05-27 03:37:09.114 [http-bio-8080-exec-11] (AbstractPolicyEnforcementPoint) wrapSubjectIdAsSubjects(): fedoraAdmin
DEBUG 2015-05-27 03:37:09.114 [http-bio-8080-exec-11] (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-27 03:37:09.114 [http-bio-8080-exec-11] (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-27 03:37:09.115 [http-bio-8080-exec-11] (DefaultPolicyEnforcementPoint) request action has urn:oasis:names:tc:xacml:1.0:action:action-id=StringAttribute: ""
DEBUG 2015-05-27 03:37:09.115 [http-bio-8080-exec-11] (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-27 03:37:09.115 [http-bio-8080-exec-11] (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-27 03:37:09.116 [http-bio-8080-exec-11] (DOReaderCache) cache hit for islandora:1
DEBUG 2015-05-27 03:37:09.116 [http-bio-8080-exec-11] (DefaultDOManager) Got DOReader (source=memory) for islandora:1 in 0ms.
DEBUG 2015-05-27 03:37:09.117 [http-bio-8080-exec-11] (BasicEvaluationCtx) Attribute not in request: fedoraRole ... querying AttributeFinder
DEBUG 2015-05-27 03:37:09.117 [http-bio-8080-exec-11] (AttributeFinderModule) getSupportedDesignatorTypes() will return org.fcrepo.server.security.ResourceAttributeFinderModule set of elements, n=1
DEBUG 2015-05-27 03:37:09.117 [http-bio-8080-exec-11] (BasicEvaluationCtx) Attribute not in request: fedoraRole ... querying AttributeFinder
DEBUG 2015-05-27 03:37:09.117 [http-bio-8080-exec-11] (AttributeFinderModule) getSupportedDesignatorTypes() will return org.fcrepo.server.security.ResourceAttributeFinderModule set of elements, n=1
DEBUG 2015-05-27 03:37:09.118 [http-bio-8080-exec-11] (BasicEvaluationCtx) Attribute not in request: fedoraRole ... querying AttributeFinder
DEBUG 2015-05-27 03:37:09.118 [http-bio-8080-exec-11] (AttributeFinderModule) getSupportedDesignatorTypes() will return org.fcrepo.server.security.ResourceAttributeFinderModule set of elements, n=1
DEBUG 2015-05-27 03:37:09.118 [http-bio-8080-exec-11] (BasicEvaluationCtx) Attribute not in request: fedoraRole ... querying AttributeFinder
DEBUG 2015-05-27 03:37:09.118 [http-bio-8080-exec-11] (AttributeFinderModule) getSupportedDesignatorTypes() will return org.fcrepo.server.security.ResourceAttributeFinderModule set of elements, n=1
DEBUG 2015-05-27 03:37:09.125 [http-bio-8080-exec-11] (DefaultPolicyEnforcementPoint) Policy evaluation took 9 ms.
DEBUG 2015-05-27 03:37:09.126 [http-bio-8080-exec-11] (DefaultPolicyEnforcementPoint) in pep, after evaluate() called
DEBUG 2015-05-27 03:37:09.126 [http-bio-8080-exec-11] (DefaultPolicyEnforcementPoint) in pep, before denyBiasedAuthz() called
DEBUG 2015-05-27 03:37:09.126 [http-bio-8080-exec-11] (AbstractPolicyEnforcementPoint) AUTHZ:  permits=0 denies=1 indeterminates=0 notApplicables=0 unexpecteds=0
DEBUG 2015-05-27 03:37:09.127 [http-bio-8080-exec-11] (DefaultPolicyEnforcementPoint) <Response>
<Result ResourceId="islandora:1">
<Decision>Deny</Decision>
<Status>
<StatusCode Value="urn:oasis:names:tc:xacml:1.0:status:ok"/>
</Status>
</Result>
</Response>

DEBUG 2015-05-27 03:37:09.128 [http-bio-8080-exec-11] (DefaultPolicyEnforcementPoint) Policy enforcement took 14 ms.
DEBUG 2015-05-27 03:37:09.129 [http-bio-8080-exec-11] (DefaultAuthorization) Exiting enforceGetDatastream
INFO 2015-05-27 03:37:09.130 [http-bio-8080-exec-11] (DefaultManagement) Completed getDatastream(pid: islandora:1, datastreamID: RELS-EXT, asOfDateTime: null)
DEBUG 2015-05-27 03:37:09.130 [http-bio-8080-exec-11] (DefaultManagement) Exiting getDatastream
WARN 2015-05-27 03:37:09.146 [http-bio-8080-exec-11] (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.8.0_45]
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_45]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_45]
    at java.lang.reflect.Method.invoke(Method.java:497) ~[na:1.8.0_45]
    at org.fcrepo.server.messaging.NotificationInvocationHandler.invoke(NotificationInvocationHandler.java:71) ~[fcrepo-server-3.8.0.jar:na]
    at com.sun.proxy.$Proxy9.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.8.0_45]
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_45]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_45]
    at java.lang.reflect.Method.invoke(Method.java:497) ~[na:1.8.0_45]
    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:1142) [na:1.8.0_45]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_45]
    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.8.0_45]
DEBUG 2015-05-27 03:37:09.161 [http-bio-8080-exec-11] (AuthFilterJAAS) outgoing filter: org.fcrepo.server.security.jaas.AuthFilterJAAS
DEBUG 2015-05-27 03:37:11.683 [http-bio-8080-exec-13] (AuthFilterJAAS) incoming filter: org.fcrepo.server.security.jaas.AuthFilterJAAS
DEBUG 2015-05-27 03:37:11.683 [http-bio-8080-exec-13] (AuthFilterJAAS) session-id: C2069089F80407BA1C936BFE25600366
DEBUG 2015-05-27 03:37:11.684 [http-bio-8080-exec-13] (AuthFilterJAAS) found userPrincipal [org.fcrepo.server.security.jaas.auth.UserPrincipal]: fedoraAdmin
DEBUG 2015-05-27 03:37:11.685 [http-bio-8080-exec-13] (SubjectUtils) checking for attributes (class name): java.util.HashMap
DEBUG 2015-05-27 03:37:11.687 [http-bio-8080-exec-13] (SubjectUtils) checking for attributes (class name): java.util.HashMap
DEBUG 2015-05-27 03:37:11.687 [http-bio-8080-exec-13] (SubjectUtils) checking for attributes (class name): java.util.HashMap
DEBUG 2015-05-27 03:37:11.690 [http-bio-8080-exec-13] (ReadOnlyContext) Request Server IP Address is '10.0.2.15'
DEBUG 2015-05-27 03:37:11.691 [http-bio-8080-exec-13] (ReadOnlyContext) Request Client IP Address is '10.0.2.2'
DEBUG 2015-05-27 03:37:11.691 [http-bio-8080-exec-13] (ReadOnlyContext) NOOP_PARAMETER_NAME=noOp
DEBUG 2015-05-27 03:37:11.691 [http-bio-8080-exec-13] (ReadOnlyContext) request.getParameter(NOOP_PARAMETER_NAME)=null
DEBUG 2015-05-27 03:37:11.691 [http-bio-8080-exec-13] (ReadOnlyContext) noOp=false
DEBUG 2015-05-27 03:37:11.691 [http-bio-8080-exec-13] (ReadOnlyContext) IN CONTEXT processing auxSubjectRoles=={fedoraRole=[]}
DEBUG 2015-05-27 03:37:11.692 [http-bio-8080-exec-13] (ReadOnlyContext) IN CONTEXT processing auxSubjectRoles.keySet()==[fedoraRole]
DEBUG 2015-05-27 03:37:11.692 [http-bio-8080-exec-13] (ReadOnlyContext) IN CONTEXT processing auxSubjectRoles.keySet().isEmpty()==false
DEBUG 2015-05-27 03:37:11.692 [http-bio-8080-exec-13] (ReadOnlyContext) IN CONTEXT processing auxSubjectRoleKeys==java.util.HashMap$KeyIterator@663dc6b6
DEBUG 2015-05-27 03:37:11.692 [http-bio-8080-exec-13] (ReadOnlyContext) IN CONTEXT name==fedoraRole
DEBUG 2015-05-27 03:37:11.692 [http-bio-8080-exec-13] (ReadOnlyContext) IN CONTEXT name is string==fedoraRole
DEBUG 2015-05-27 03:37:11.692 [http-bio-8080-exec-13] (ReadOnlyContext) IN CONTEXT after while
DEBUG 2015-05-27 03:37:11.692 [http-bio-8080-exec-13] (ReadOnlyContext) subject attributes in readonlycontext constructor == fedoraRole=[]
urn:fedora:names:fedora:2.1:subject:loginId=[fedoraAdmin]

DEBUG 2015-05-27 03:37:11.693 [http-bio-8080-exec-13] (DefaultManagement) Entered getDatastream
DEBUG 2015-05-27 03:37:11.693 [http-bio-8080-exec-13] (DefaultAuthorization) Entered enforceGetDatastream
DEBUG 2015-05-27 03:37:11.693 [http-bio-8080-exec-13] (ReadOnlyContext) SINGLE SUBJECT VALUE from map == fedoraAdmin
DEBUG 2015-05-27 03:37:11.693 [http-bio-8080-exec-13] (AbstractPolicyEnforcementPoint) wrapSubjectIdAsSubjects(): fedoraAdmin
DEBUG 2015-05-27 03:37:11.693 [http-bio-8080-exec-13] (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-27 03:37:11.693 [http-bio-8080-exec-13] (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-27 03:37:11.693 [http-bio-8080-exec-13] (DefaultPolicyEnforcementPoint) request action has urn:oasis:names:tc:xacml:1.0:action:action-id=StringAttribute: ""
DEBUG 2015-05-27 03:37:11.694 [http-bio-8080-exec-13] (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-27 03:37:11.694 [http-bio-8080-exec-13] (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-27 03:37:11.695 [http-bio-8080-exec-13] (DOReaderCache) cache hit for islandora:1
DEBUG 2015-05-27 03:37:11.695 [http-bio-8080-exec-13] (DefaultDOManager) Got DOReader (source=memory) for islandora:1 in 0ms.
DEBUG 2015-05-27 03:37:11.695 [http-bio-8080-exec-13] (BasicEvaluationCtx) Attribute not in request: fedoraRole ... querying AttributeFinder
DEBUG 2015-05-27 03:37:11.695 [http-bio-8080-exec-13] (AttributeFinderModule) getSupportedDesignatorTypes() will return org.fcrepo.server.security.ResourceAttributeFinderModule set of elements, n=1
DEBUG 2015-05-27 03:37:11.696 [http-bio-8080-exec-13] (BasicEvaluationCtx) Attribute not in request: fedoraRole ... querying AttributeFinder
DEBUG 2015-05-27 03:37:11.696 [http-bio-8080-exec-13] (AttributeFinderModule) getSupportedDesignatorTypes() will return org.fcrepo.server.security.ResourceAttributeFinderModule set of elements, n=1
DEBUG 2015-05-27 03:37:11.696 [http-bio-8080-exec-13] (BasicEvaluationCtx) Attribute not in request: fedoraRole ... querying AttributeFinder
DEBUG 2015-05-27 03:37:11.696 [http-bio-8080-exec-13] (AttributeFinderModule) getSupportedDesignatorTypes() will return org.fcrepo.server.security.ResourceAttributeFinderModule set of elements, n=1
DEBUG 2015-05-27 03:37:11.697 [http-bio-8080-exec-13] (BasicEvaluationCtx) Attribute not in request: fedoraRole ... querying AttributeFinder
DEBUG 2015-05-27 03:37:11.697 [http-bio-8080-exec-13] (AttributeFinderModule) getSupportedDesignatorTypes() will return org.fcrepo.server.security.ResourceAttributeFinderModule set of elements, n=1
DEBUG 2015-05-27 03:37:11.698 [http-bio-8080-exec-13] (DefaultPolicyEnforcementPoint) Policy evaluation took 4 ms.
DEBUG 2015-05-27 03:37:11.698 [http-bio-8080-exec-13] (DefaultPolicyEnforcementPoint) in pep, after evaluate() called
DEBUG 2015-05-27 03:37:11.698 [http-bio-8080-exec-13] (DefaultPolicyEnforcementPoint) in pep, before denyBiasedAuthz() called
DEBUG 2015-05-27 03:37:11.698 [http-bio-8080-exec-13] (AbstractPolicyEnforcementPoint) AUTHZ:  permits=0 denies=1 indeterminates=0 notApplicables=0 unexpecteds=0
DEBUG 2015-05-27 03:37:11.698 [http-bio-8080-exec-13] (DefaultPolicyEnforcementPoint) <Response>
<Result ResourceId="islandora:1">
<Decision>Deny</Decision>
<Status>
<StatusCode Value="urn:oasis:names:tc:xacml:1.0:status:ok"/>
</Status>
</Result>
</Response>

DEBUG 2015-05-27 03:37:11.699 [http-bio-8080-exec-13] (DefaultPolicyEnforcementPoint) Policy enforcement took 6 ms.
DEBUG 2015-05-27 03:37:11.699 [http-bio-8080-exec-13] (DefaultAuthorization) Exiting enforceGetDatastream
INFO 2015-05-27 03:37:11.699 [http-bio-8080-exec-13] (DefaultManagement) Completed getDatastream(pid: islandora:1, datastreamID: MODS, asOfDateTime: null)
DEBUG 2015-05-27 03:37:11.699 [http-bio-8080-exec-13] (DefaultManagement) Exiting getDatastream
WARN 2015-05-27 03:37:11.702 [http-bio-8080-exec-13] (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.8.0_45]
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_45]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_45]
    at java.lang.reflect.Method.invoke(Method.java:497) ~[na:1.8.0_45]
    at org.fcrepo.server.messaging.NotificationInvocationHandler.invoke(NotificationInvocationHandler.java:71) ~[fcrepo-server-3.8.0.jar:na]
    at com.sun.proxy.$Proxy9.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.8.0_45]
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_45]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_45]
    at java.lang.reflect.Method.invoke(Method.java:497) ~[na:1.8.0_45]
    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:1142) [na:1.8.0_45]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_45]
    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.8.0_45]
DEBUG 2015-05-27 03:37:11.705 [http-bio-8080-exec-13] (AuthFilterJAAS) outgoing filter: org.fcrepo.server.security.jaas.AuthFilterJAAS
DEBUG 2015-05-27 03:37:17.366 [timerFactory] (DOReaderCache) removing entry islandora:1 after 5671 milliseconds

I'll do some more troubleshooting later when I have some more time.

@ruebot
Copy link
Contributor

ruebot commented May 27, 2015

...and removing deny-apim-if-not-localhost.xml

DEBUG 2015-05-27 03:41:59.790 [http-bio-8080-exec-21] (DefaultManagement) Entered getDatastream
DEBUG 2015-05-27 03:41:59.790 [http-bio-8080-exec-21] (DefaultAuthorization) Entered enforceGetDatastream
DEBUG 2015-05-27 03:41:59.791 [http-bio-8080-exec-21] (ReadOnlyContext) SINGLE SUBJECT VALUE from map == fedoraAdmin
DEBUG 2015-05-27 03:41:59.791 [http-bio-8080-exec-21] (AbstractPolicyEnforcementPoint) wrapSubjectIdAsSubjects(): fedoraAdmin
DEBUG 2015-05-27 03:41:59.791 [http-bio-8080-exec-21] (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-27 03:41:59.791 [http-bio-8080-exec-21] (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-27 03:41:59.791 [http-bio-8080-exec-21] (DefaultPolicyEnforcementPoint) request action has urn:oasis:names:tc:xacml:1.0:action:action-id=StringAttribute: ""
DEBUG 2015-05-27 03:41:59.791 [http-bio-8080-exec-21] (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-27 03:41:59.791 [http-bio-8080-exec-21] (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-27 03:41:59.792 [http-bio-8080-exec-21] (DOReaderCache) cache miss for islandora:1
DEBUG 2015-05-27 03:41:59.792 [http-bio-8080-exec-21] (DOTranslatorImpl) Grabbing deserializer for: info:fedora/fedora-system:FOXML-1.1
DEBUG 2015-05-27 03:41:59.792 [http-bio-8080-exec-21] (FOXMLDODeserializer) Deserializing info:fedora/fedora-system:FOXML-1.1 for transContext: 0
DEBUG 2015-05-27 03:41:59.793 [http-bio-8080-exec-21] (FOXMLContentHandler) instantiate XML datastream: dsid = RELS-EXT checksumType = DISABLED checksum = none
DEBUG 2015-05-27 03:41:59.793 [http-bio-8080-exec-21] (FOXMLContentHandler) instantiate datastream: dsid = MODS checksumType = DISABLED checksum = none
DEBUG 2015-05-27 03:41:59.794 [http-bio-8080-exec-21] (FOXMLContentHandler) instantiate XML datastream: dsid = DC checksumType = DISABLED checksum = none
DEBUG 2015-05-27 03:41:59.794 [http-bio-8080-exec-21] (FOXMLContentHandler) instantiate datastream: dsid = OBJ checksumType = DISABLED checksum = none
DEBUG 2015-05-27 03:41:59.794 [http-bio-8080-exec-21] (FOXMLContentHandler) instantiate datastream: dsid = TECHMD checksumType = DISABLED checksum = none
DEBUG 2015-05-27 03:41:59.794 [http-bio-8080-exec-21] (FOXMLContentHandler) instantiate datastream: dsid = TN checksumType = DISABLED checksum = none
DEBUG 2015-05-27 03:41:59.795 [http-bio-8080-exec-21] (FOXMLContentHandler) instantiate datastream: dsid = MEDIUM_SIZE checksumType = DISABLED checksum = none
DEBUG 2015-05-27 03:41:59.795 [http-bio-8080-exec-21] (FOXMLDODeserializer) Just finished parse.
DEBUG 2015-05-27 03:41:59.797 [http-bio-8080-exec-21] (DOReaderCache) adding islandora:1 to cache
DEBUG 2015-05-27 03:41:59.797 [http-bio-8080-exec-21] (DefaultDOManager) Got DOReader (source=filesystem) for islandora:1 in 5ms.
DEBUG 2015-05-27 03:41:59.798 [http-bio-8080-exec-21] (BasicEvaluationCtx) Attribute not in request: fedoraRole ... querying AttributeFinder
DEBUG 2015-05-27 03:41:59.798 [http-bio-8080-exec-21] (AttributeFinderModule) getSupportedDesignatorTypes() will return org.fcrepo.server.security.ResourceAttributeFinderModule set of elements, n=1
DEBUG 2015-05-27 03:41:59.798 [http-bio-8080-exec-21] (BasicEvaluationCtx) Attribute not in request: fedoraRole ... querying AttributeFinder
DEBUG 2015-05-27 03:41:59.799 [http-bio-8080-exec-21] (AttributeFinderModule) getSupportedDesignatorTypes() will return org.fcrepo.server.security.ResourceAttributeFinderModule set of elements, n=1
DEBUG 2015-05-27 03:41:59.799 [http-bio-8080-exec-21] (BasicEvaluationCtx) Attribute not in request: fedoraRole ... querying AttributeFinder
DEBUG 2015-05-27 03:41:59.799 [http-bio-8080-exec-21] (AttributeFinderModule) getSupportedDesignatorTypes() will return org.fcrepo.server.security.ResourceAttributeFinderModule set of elements, n=1
DEBUG 2015-05-27 03:41:59.799 [http-bio-8080-exec-21] (BasicEvaluationCtx) Attribute not in request: fedoraRole ... querying AttributeFinder
DEBUG 2015-05-27 03:41:59.800 [http-bio-8080-exec-21] (AttributeFinderModule) getSupportedDesignatorTypes() will return org.fcrepo.server.security.ResourceAttributeFinderModule set of elements, n=1
DEBUG 2015-05-27 03:41:59.800 [http-bio-8080-exec-21] (BasicEvaluationCtx) Attribute not in request: fedoraRole ... querying AttributeFinder
DEBUG 2015-05-27 03:41:59.800 [http-bio-8080-exec-21] (AttributeFinderModule) getSupportedDesignatorTypes() will return org.fcrepo.server.security.ResourceAttributeFinderModule set of elements, n=1
DEBUG 2015-05-27 03:41:59.801 [http-bio-8080-exec-21] (DefaultPolicyEnforcementPoint) Policy evaluation took 10 ms.
DEBUG 2015-05-27 03:41:59.801 [http-bio-8080-exec-21] (DefaultPolicyEnforcementPoint) in pep, after evaluate() called
DEBUG 2015-05-27 03:41:59.801 [http-bio-8080-exec-21] (DefaultPolicyEnforcementPoint) in pep, before denyBiasedAuthz() called
DEBUG 2015-05-27 03:41:59.801 [http-bio-8080-exec-21] (AbstractPolicyEnforcementPoint) AUTHZ:  permits=1 denies=0 indeterminates=0 notApplicables=0 unexpecteds=0
DEBUG 2015-05-27 03:41:59.801 [http-bio-8080-exec-21] (DefaultPolicyEnforcementPoint) Policy enforcement took 10 ms.
DEBUG 2015-05-27 03:41:59.801 [http-bio-8080-exec-21] (DefaultAuthorization) Exiting enforceGetDatastream
DEBUG 2015-05-27 03:41:59.801 [http-bio-8080-exec-21] (DOReaderCache) cache hit for islandora:1
DEBUG 2015-05-27 03:41:59.802 [http-bio-8080-exec-21] (DefaultDOManager) Got DOReader (source=memory) for islandora:1 in 1ms.
INFO 2015-05-27 03:41:59.802 [http-bio-8080-exec-21] (DefaultManagement) Completed getDatastream(pid: islandora:1, datastreamID: MODS, asOfDateTime: null)
DEBUG 2015-05-27 03:41:59.802 [http-bio-8080-exec-21] (DefaultManagement) Exiting getDatastream
DEBUG 2015-05-27 03:41:59.802 [http-bio-8080-exec-21] (DefaultAuthorization) Entered enforceUpload
DEBUG 2015-05-27 03:41:59.802 [http-bio-8080-exec-21] (ReadOnlyContext) SINGLE SUBJECT VALUE from map == fedoraAdmin
DEBUG 2015-05-27 03:41:59.802 [http-bio-8080-exec-21] (AbstractPolicyEnforcementPoint) wrapSubjectIdAsSubjects(): fedoraAdmin
DEBUG 2015-05-27 03:41:59.803 [http-bio-8080-exec-21] (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-27 03:41:59.803 [http-bio-8080-exec-21] (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-27 03:41:59.803 [http-bio-8080-exec-21] (DefaultPolicyEnforcementPoint) request action has urn:oasis:names:tc:xacml:1.0:action:action-id=StringAttribute: ""
DEBUG 2015-05-27 03:41:59.803 [http-bio-8080-exec-21] (DefaultPolicyEnforcementPoint) request action has urn:fedora:names:fedora:2.1:action:id=StringAttribute: "urn:fedora:names:fedora:2.1:action:id-upload"
DEBUG 2015-05-27 03:41:59.803 [http-bio-8080-exec-21] (DefaultPolicyEnforcementPoint) request action has urn:fedora:names:fedora:2.1:action:api=StringAttribute: ""
DEBUG 2015-05-27 03:41:59.804 [pool-3-thread-1] (ReadOnlyContext) SINGLE SUBJECT VALUE from map == fedoraAdmin
DEBUG 2015-05-27 03:41:59.804 [http-bio-8080-exec-21] (BasicEvaluationCtx) Attribute not in request: fedoraRole ... querying AttributeFinder
DEBUG 2015-05-27 03:41:59.804 [http-bio-8080-exec-21] (AttributeFinderModule) getSupportedDesignatorTypes() will return org.fcrepo.server.security.ResourceAttributeFinderModule set of elements, n=1
DEBUG 2015-05-27 03:41:59.804 [http-bio-8080-exec-21] (BasicEvaluationCtx) Attribute not in request: fedoraRole ... querying AttributeFinder
DEBUG 2015-05-27 03:41:59.804 [http-bio-8080-exec-21] (AttributeFinderModule) getSupportedDesignatorTypes() will return org.fcrepo.server.security.ResourceAttributeFinderModule set of elements, n=1
DEBUG 2015-05-27 03:41:59.804 [http-bio-8080-exec-21] (BasicEvaluationCtx) Attribute not in request: fedoraRole ... querying AttributeFinder
DEBUG 2015-05-27 03:41:59.805 [http-bio-8080-exec-21] (AttributeFinderModule) getSupportedDesignatorTypes() will return org.fcrepo.server.security.ResourceAttributeFinderModule set of elements, n=1
DEBUG 2015-05-27 03:41:59.805 [http-bio-8080-exec-21] (BasicEvaluationCtx) Attribute not in request: fedoraRole ... querying AttributeFinder
DEBUG 2015-05-27 03:41:59.805 [http-bio-8080-exec-21] (AttributeFinderModule) getSupportedDesignatorTypes() will return org.fcrepo.server.security.ResourceAttributeFinderModule set of elements, n=1
DEBUG 2015-05-27 03:41:59.805 [http-bio-8080-exec-21] (BasicEvaluationCtx) Attribute not in request: fedoraRole ... querying AttributeFinder
DEBUG 2015-05-27 03:41:59.805 [http-bio-8080-exec-21] (AttributeFinderModule) getSupportedDesignatorTypes() will return org.fcrepo.server.security.ResourceAttributeFinderModule set of elements, n=1
DEBUG 2015-05-27 03:41:59.806 [http-bio-8080-exec-21] (DefaultPolicyEnforcementPoint) Policy evaluation took 3 ms.
DEBUG 2015-05-27 03:41:59.806 [http-bio-8080-exec-21] (DefaultPolicyEnforcementPoint) in pep, after evaluate() called
DEBUG 2015-05-27 03:41:59.806 [http-bio-8080-exec-21] (DefaultPolicyEnforcementPoint) in pep, before denyBiasedAuthz() called
DEBUG 2015-05-27 03:41:59.806 [http-bio-8080-exec-21] (AbstractPolicyEnforcementPoint) AUTHZ:  permits=0 denies=0 indeterminates=0 notApplicables=1 unexpecteds=0
DEBUG 2015-05-27 03:41:59.806 [http-bio-8080-exec-21] (DefaultPolicyEnforcementPoint) <Response>
<Result ResourceId="">
<Decision>NotApplicable</Decision>
<Status>
<StatusCode Value="urn:oasis:names:tc:xacml:1.0:status:ok"/>
</Status>
</Result>
</Response>

DEBUG 2015-05-27 03:41:59.806 [http-bio-8080-exec-21] (DefaultPolicyEnforcementPoint) Policy enforcement took 4 ms.
DEBUG 2015-05-27 03:41:59.806 [pool-3-thread-1] (AtomAPIMMessage) Silently dropping parameter not defined in the WSDL: context
DEBUG 2015-05-27 03:41:59.809 [pool-3-thread-1] (JMSManager) send() - message sent to destination fedora.apim.access
DEBUG 2015-05-27 03:41:59.810 [http-bio-8080-exec-21] (DefaultAuthorization) Exiting enforceUpload
WARN 2015-05-27 03:41:59.811 [http-bio-8080-exec-21] (DatastreamResource) 
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.enforceUpload(DefaultAuthorization.java:1172) ~[fcrepo-server-3.8.0.jar:na]
    at org.fcrepo.server.management.DefaultManagement.putTempStream(DefaultManagement.java:1289) ~[fcrepo-server-3.8.0.jar:na]
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_45]
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_45]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_45]
    at java.lang.reflect.Method.invoke(Method.java:497) ~[na:1.8.0_45]
    at org.fcrepo.server.messaging.NotificationInvocationHandler.invoke(NotificationInvocationHandler.java:71) ~[fcrepo-server-3.8.0.jar:na]
    at com.sun.proxy.$Proxy9.putTempStream(Unknown Source) ~[na:na]
    at org.fcrepo.server.management.ManagementModule.putTempStream(ManagementModule.java:522) ~[fcrepo-server-3.8.0.jar:na]
    at org.fcrepo.server.rest.DatastreamResource.addOrUpdateDatastream(DatastreamResource.java:571) [fcrepo-server-3.8.0.jar:na]
    at org.fcrepo.server.rest.DatastreamResource.modifyDatastream(DatastreamResource.java:351) [fcrepo-server-3.8.0.jar:na]
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_45]
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_45]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_45]
    at java.lang.reflect.Method.invoke(Method.java:497) ~[na:1.8.0_45]
    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.doPost(AbstractHTTPServlet.java:206) [cxf-rt-transports-http-2.7.7.jar:2.7.7]
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:646) [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:1142) [na:1.8.0_45]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_45]
    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.8.0_45]
WARN 2015-05-27 03:41:59.812 [http-bio-8080-exec-21] (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.enforceUpload(DefaultAuthorization.java:1172) ~[fcrepo-server-3.8.0.jar:na]
    at org.fcrepo.server.management.DefaultManagement.putTempStream(DefaultManagement.java:1289) ~[fcrepo-server-3.8.0.jar:na]
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_45]
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_45]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_45]
    at java.lang.reflect.Method.invoke(Method.java:497) ~[na:1.8.0_45]
    at org.fcrepo.server.messaging.NotificationInvocationHandler.invoke(NotificationInvocationHandler.java:71) ~[fcrepo-server-3.8.0.jar:na]
    at com.sun.proxy.$Proxy9.putTempStream(Unknown Source) ~[na:na]
    at org.fcrepo.server.management.ManagementModule.putTempStream(ManagementModule.java:522) ~[fcrepo-server-3.8.0.jar:na]
    at org.fcrepo.server.rest.DatastreamResource.addOrUpdateDatastream(DatastreamResource.java:571) [fcrepo-server-3.8.0.jar:na]
    at org.fcrepo.server.rest.DatastreamResource.modifyDatastream(DatastreamResource.java:351) [fcrepo-server-3.8.0.jar:na]
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_45]
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_45]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_45]
    at java.lang.reflect.Method.invoke(Method.java:497) ~[na:1.8.0_45]
    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.doPost(AbstractHTTPServlet.java:206) [cxf-rt-transports-http-2.7.7.jar:2.7.7]
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:646) [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:1142) [na:1.8.0_45]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_45]
    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.8.0_45]
DEBUG 2015-05-27 03:41:59.821 [http-bio-8080-exec-21] (AuthFilterJAAS) outgoing filter: org.fcrepo.server.security.jaas.AuthFilterJAAS
DEBUG 2015-05-27 03:41:59.883 [http-bio-8080-exec-22] (AuthFilterJAAS) incoming filter: org.fcrepo.server.security.jaas.AuthFilterJAAS
DEBUG 2015-05-27 03:41:59.883 [http-bio-8080-exec-22] (AuthFilterJAAS) session-id: C2069089F80407BA1C936BFE25600366
DEBUG 2015-05-27 03:41:59.883 [http-bio-8080-exec-22] (AuthFilterJAAS) found userPrincipal [org.fcrepo.server.security.jaas.auth.UserPrincipal]: fedoraAdmin
DEBUG 2015-05-27 03:41:59.883 [http-bio-8080-exec-22] (SubjectUtils) checking for attributes (class name): java.util.HashMap
DEBUG 2015-05-27 03:41:59.883 [http-bio-8080-exec-22] (SubjectUtils) checking for attributes (class name): java.util.HashMap
DEBUG 2015-05-27 03:41:59.883 [http-bio-8080-exec-22] (SubjectUtils) checking for attributes (class name): java.util.HashMap
DEBUG 2015-05-27 03:41:59.889 [http-bio-8080-exec-22] (ReadOnlyContext) Request Server IP Address is '10.0.2.15'
DEBUG 2015-05-27 03:41:59.890 [http-bio-8080-exec-22] (ReadOnlyContext) Request Client IP Address is '10.0.2.2'
DEBUG 2015-05-27 03:41:59.890 [http-bio-8080-exec-22] (ReadOnlyContext) NOOP_PARAMETER_NAME=noOp
DEBUG 2015-05-27 03:41:59.891 [http-bio-8080-exec-22] (ReadOnlyContext) request.getParameter(NOOP_PARAMETER_NAME)=null
DEBUG 2015-05-27 03:41:59.891 [http-bio-8080-exec-22] (ReadOnlyContext) noOp=false
DEBUG 2015-05-27 03:41:59.891 [http-bio-8080-exec-22] (ReadOnlyContext) IN CONTEXT processing auxSubjectRoles=={fedoraRole=[]}
DEBUG 2015-05-27 03:41:59.891 [http-bio-8080-exec-22] (ReadOnlyContext) IN CONTEXT processing auxSubjectRoles.keySet()==[fedoraRole]
DEBUG 2015-05-27 03:41:59.891 [http-bio-8080-exec-22] (ReadOnlyContext) IN CONTEXT processing auxSubjectRoles.keySet().isEmpty()==false
DEBUG 2015-05-27 03:41:59.891 [http-bio-8080-exec-22] (ReadOnlyContext) IN CONTEXT processing auxSubjectRoleKeys==java.util.HashMap$KeyIterator@672c3d87
DEBUG 2015-05-27 03:41:59.892 [http-bio-8080-exec-22] (ReadOnlyContext) IN CONTEXT name==fedoraRole
DEBUG 2015-05-27 03:41:59.892 [http-bio-8080-exec-22] (ReadOnlyContext) IN CONTEXT name is string==fedoraRole
DEBUG 2015-05-27 03:41:59.892 [http-bio-8080-exec-22] (ReadOnlyContext) IN CONTEXT after while
DEBUG 2015-05-27 03:41:59.892 [http-bio-8080-exec-22] (ReadOnlyContext) subject attributes in readonlycontext constructor == fedoraRole=[]
urn:fedora:names:fedora:2.1:subject:loginId=[fedoraAdmin]

DEBUG 2015-05-27 03:41:59.893 [http-bio-8080-exec-22] (DefaultManagement) Entered getDatastream
DEBUG 2015-05-27 03:41:59.893 [http-bio-8080-exec-22] (DefaultAuthorization) Entered enforceGetDatastream
DEBUG 2015-05-27 03:41:59.893 [http-bio-8080-exec-22] (ReadOnlyContext) SINGLE SUBJECT VALUE from map == fedoraAdmin
DEBUG 2015-05-27 03:41:59.893 [http-bio-8080-exec-22] (AbstractPolicyEnforcementPoint) wrapSubjectIdAsSubjects(): fedoraAdmin
DEBUG 2015-05-27 03:41:59.893 [http-bio-8080-exec-22] (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-27 03:41:59.894 [http-bio-8080-exec-22] (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-27 03:41:59.894 [http-bio-8080-exec-22] (DefaultPolicyEnforcementPoint) request action has urn:oasis:names:tc:xacml:1.0:action:action-id=StringAttribute: ""
DEBUG 2015-05-27 03:41:59.894 [http-bio-8080-exec-22] (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-27 03:41:59.894 [http-bio-8080-exec-22] (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-27 03:41:59.894 [http-bio-8080-exec-22] (DOReaderCache) cache hit for islandora:1
DEBUG 2015-05-27 03:41:59.895 [http-bio-8080-exec-22] (DefaultDOManager) Got DOReader (source=memory) for islandora:1 in 1ms.
DEBUG 2015-05-27 03:41:59.895 [http-bio-8080-exec-22] (BasicEvaluationCtx) Attribute not in request: fedoraRole ... querying AttributeFinder
DEBUG 2015-05-27 03:41:59.895 [http-bio-8080-exec-22] (AttributeFinderModule) getSupportedDesignatorTypes() will return org.fcrepo.server.security.ResourceAttributeFinderModule set of elements, n=1
DEBUG 2015-05-27 03:41:59.896 [http-bio-8080-exec-22] (BasicEvaluationCtx) Attribute not in request: fedoraRole ... querying AttributeFinder
DEBUG 2015-05-27 03:41:59.896 [http-bio-8080-exec-22] (AttributeFinderModule) getSupportedDesignatorTypes() will return org.fcrepo.server.security.ResourceAttributeFinderModule set of elements, n=1
DEBUG 2015-05-27 03:41:59.896 [http-bio-8080-exec-22] (BasicEvaluationCtx) Attribute not in request: fedoraRole ... querying AttributeFinder
DEBUG 2015-05-27 03:41:59.896 [http-bio-8080-exec-22] (AttributeFinderModule) getSupportedDesignatorTypes() will return org.fcrepo.server.security.ResourceAttributeFinderModule set of elements, n=1
DEBUG 2015-05-27 03:41:59.897 [http-bio-8080-exec-22] (BasicEvaluationCtx) Attribute not in request: fedoraRole ... querying AttributeFinder
DEBUG 2015-05-27 03:41:59.897 [http-bio-8080-exec-22] (AttributeFinderModule) getSupportedDesignatorTypes() will return org.fcrepo.server.security.ResourceAttributeFinderModule set of elements, n=1
DEBUG 2015-05-27 03:41:59.898 [http-bio-8080-exec-22] (BasicEvaluationCtx) Attribute not in request: fedoraRole ... querying AttributeFinder
DEBUG 2015-05-27 03:41:59.898 [http-bio-8080-exec-22] (AttributeFinderModule) getSupportedDesignatorTypes() will return org.fcrepo.server.security.ResourceAttributeFinderModule set of elements, n=1
DEBUG 2015-05-27 03:41:59.898 [http-bio-8080-exec-22] (DefaultPolicyEnforcementPoint) Policy evaluation took 4 ms.
DEBUG 2015-05-27 03:41:59.898 [http-bio-8080-exec-22] (DefaultPolicyEnforcementPoint) in pep, after evaluate() called
DEBUG 2015-05-27 03:41:59.898 [http-bio-8080-exec-22] (DefaultPolicyEnforcementPoint) in pep, before denyBiasedAuthz() called
DEBUG 2015-05-27 03:41:59.898 [http-bio-8080-exec-22] (AbstractPolicyEnforcementPoint) AUTHZ:  permits=1 denies=0 indeterminates=0 notApplicables=0 unexpecteds=0
DEBUG 2015-05-27 03:41:59.899 [http-bio-8080-exec-22] (DefaultPolicyEnforcementPoint) Policy enforcement took 6 ms.
DEBUG 2015-05-27 03:41:59.899 [http-bio-8080-exec-22] (DefaultAuthorization) Exiting enforceGetDatastream
DEBUG 2015-05-27 03:41:59.899 [http-bio-8080-exec-22] (DOReaderCache) cache hit for islandora:1
DEBUG 2015-05-27 03:41:59.899 [http-bio-8080-exec-22] (DefaultDOManager) Got DOReader (source=memory) for islandora:1 in 0ms.
INFO 2015-05-27 03:41:59.899 [http-bio-8080-exec-22] (DefaultManagement) Completed getDatastream(pid: islandora:1, datastreamID: MODS, asOfDateTime: null)
DEBUG 2015-05-27 03:41:59.900 [http-bio-8080-exec-22] (DefaultManagement) Exiting getDatastream
DEBUG 2015-05-27 03:41:59.900 [pool-3-thread-1] (ReadOnlyContext) SINGLE SUBJECT VALUE from map == fedoraAdmin
DEBUG 2015-05-27 03:41:59.902 [pool-3-thread-1] (AtomAPIMMessage) Silently dropping parameter not defined in the WSDL: context
DEBUG 2015-05-27 03:41:59.907 [http-bio-8080-exec-23] (AuthFilterJAAS) incoming filter: org.fcrepo.server.security.jaas.AuthFilterJAAS
DEBUG 2015-05-27 03:41:59.907 [http-bio-8080-exec-23] (AuthFilterJAAS) session-id: C2069089F80407BA1C936BFE25600366
DEBUG 2015-05-27 03:41:59.908 [http-bio-8080-exec-22] (AuthFilterJAAS) outgoing filter: org.fcrepo.server.security.jaas.AuthFilterJAAS
DEBUG 2015-05-27 03:41:59.909 [pool-3-thread-1] (JMSManager) send() - message sent to destination fedora.apim.access
DEBUG 2015-05-27 03:41:59.913 [http-bio-8080-exec-23] (ReadOnlyContext) Request Server IP Address is '10.0.2.15'
DEBUG 2015-05-27 03:41:59.913 [http-bio-8080-exec-23] (ReadOnlyContext) Request Client IP Address is '10.0.2.2'
DEBUG 2015-05-27 03:41:59.943 [http-bio-8080-exec-23] (ReadOnlyContext) NOOP_PARAMETER_NAME=noOp
DEBUG 2015-05-27 03:41:59.943 [http-bio-8080-exec-23] (ReadOnlyContext) request.getParameter(NOOP_PARAMETER_NAME)=null
DEBUG 2015-05-27 03:41:59.943 [http-bio-8080-exec-23] (ReadOnlyContext) noOp=false
DEBUG 2015-05-27 03:41:59.943 [http-bio-8080-exec-23] (ReadOnlyContext) IN CONTEXT auxSubjectRoles == null
DEBUG 2015-05-27 03:41:59.943 [http-bio-8080-exec-23] (ReadOnlyContext) subject attributes in readonlycontext constructor == urn:fedora:names:fedora:2.1:subject:loginId=[]

DEBUG 2015-05-27 03:41:59.944 [http-bio-8080-exec-23] (DefaultAuthorization) Entered enforceListDatastreams
DEBUG 2015-05-27 03:41:59.944 [http-bio-8080-exec-23] (ReadOnlyContext) SINGLE SUBJECT VALUE from map == 
DEBUG 2015-05-27 03:41:59.944 [http-bio-8080-exec-23] (AbstractPolicyEnforcementPoint) wrapSubjectIdAsSubjects(): 
DEBUG 2015-05-27 03:41:59.944 [http-bio-8080-exec-23] (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-27 03:41:59.945 [http-bio-8080-exec-23] (DefaultPolicyEnforcementPoint) request action has urn:oasis:names:tc:xacml:1.0:action:action-id=StringAttribute: ""
DEBUG 2015-05-27 03:41:59.945 [http-bio-8080-exec-23] (DefaultPolicyEnforcementPoint) request action has urn:fedora:names:fedora:2.1:action:id=StringAttribute: "urn:fedora:names:fedora:2.1:action:id-listDatastreams"
DEBUG 2015-05-27 03:41:59.945 [http-bio-8080-exec-23] (DefaultPolicyEnforcementPoint) request action has urn:fedora:names:fedora:2.1:action:api=StringAttribute: "urn:fedora:names:fedora:2.1:action:api-a"
DEBUG 2015-05-27 03:41:59.946 [http-bio-8080-exec-23] (DOReaderCache) cache hit for islandora:1
DEBUG 2015-05-27 03:41:59.946 [http-bio-8080-exec-23] (DefaultDOManager) Got DOReader (source=memory) for islandora:1 in 0ms.
DEBUG 2015-05-27 03:41:59.947 [http-bio-8080-exec-23] (BasicEvaluationCtx) Attribute not in request: fedoraRole ... querying AttributeFinder
DEBUG 2015-05-27 03:41:59.948 [http-bio-8080-exec-23] (AttributeFinderModule) getSupportedDesignatorTypes() will return org.fcrepo.server.security.ResourceAttributeFinderModule set of elements, n=1
DEBUG 2015-05-27 03:41:59.951 [http-bio-8080-exec-23] (BasicEvaluationCtx) Attribute not in request: fedoraRole ... querying AttributeFinder
DEBUG 2015-05-27 03:41:59.951 [http-bio-8080-exec-23] (AttributeFinderModule) getSupportedDesignatorTypes() will return org.fcrepo.server.security.ResourceAttributeFinderModule set of elements, n=1
DEBUG 2015-05-27 03:41:59.951 [http-bio-8080-exec-23] (BasicEvaluationCtx) Attribute not in request: fedoraRole ... querying AttributeFinder
DEBUG 2015-05-27 03:41:59.951 [http-bio-8080-exec-23] (AttributeFinderModule) getSupportedDesignatorTypes() will return org.fcrepo.server.security.ResourceAttributeFinderModule set of elements, n=1
DEBUG 2015-05-27 03:41:59.952 [http-bio-8080-exec-23] (BasicEvaluationCtx) Attribute not in request: fedoraRole ... querying AttributeFinder
DEBUG 2015-05-27 03:41:59.952 [http-bio-8080-exec-23] (AttributeFinderModule) getSupportedDesignatorTypes() will return org.fcrepo.server.security.ResourceAttributeFinderModule set of elements, n=1
DEBUG 2015-05-27 03:41:59.952 [http-bio-8080-exec-23] (BasicEvaluationCtx) Attribute not in request: fedoraRole ... querying AttributeFinder
DEBUG 2015-05-27 03:41:59.953 [http-bio-8080-exec-23] (AttributeFinderModule) getSupportedDesignatorTypes() will return org.fcrepo.server.security.ResourceAttributeFinderModule set of elements, n=1
DEBUG 2015-05-27 03:41:59.953 [http-bio-8080-exec-23] (DefaultPolicyEnforcementPoint) Policy evaluation took 8 ms.
DEBUG 2015-05-27 03:41:59.953 [http-bio-8080-exec-23] (DefaultPolicyEnforcementPoint) in pep, after evaluate() called
DEBUG 2015-05-27 03:41:59.953 [http-bio-8080-exec-23] (DefaultPolicyEnforcementPoint) in pep, before denyBiasedAuthz() called
DEBUG 2015-05-27 03:41:59.953 [http-bio-8080-exec-23] (AbstractPolicyEnforcementPoint) AUTHZ:  permits=1 denies=0 indeterminates=0 notApplicables=0 unexpecteds=0
DEBUG 2015-05-27 03:41:59.954 [http-bio-8080-exec-23] (DefaultPolicyEnforcementPoint) Policy enforcement took 10 ms.
DEBUG 2015-05-27 03:41:59.954 [http-bio-8080-exec-23] (DefaultAuthorization) Exiting enforceListDatastreams
DEBUG 2015-05-27 03:41:59.954 [http-bio-8080-exec-23] (DOReaderCache) cache hit for islandora:1
DEBUG 2015-05-27 03:41:59.955 [http-bio-8080-exec-23] (DefaultDOManager) Got DOReader (source=memory) for islandora:1 in 1ms.
DEBUG 2015-05-27 03:41:59.956 [http-bio-8080-exec-23] (DefaultAccess) Roundtrip listDatastreams: 11 milliseconds.
DEBUG 2015-05-27 03:42:05.198 [timerFactory] (DOReaderCache) removing entry islandora:1 after 5243 milliseconds

notApplicables=1 is essentially a deny. That's why the 'save' isn't taking effect.

@ruebot
Copy link
Contributor

ruebot commented May 27, 2015

Looks like my regex is bad. It should be \d{1,3}\.\d{1,3}\.\d{1,3}\.\d{1,3} not d{1,3}.d{1,3}.d{1,3}.d{1,3}. I'll just make this a config file in the configs dir.

@ruebot ruebot self-assigned this May 27, 2015
@ruebot ruebot added the bug label May 27, 2015
@ruebot
Copy link
Contributor

ruebot commented May 27, 2015

Anybody want to test: https://github.com/Islandora-Labs/islandora_vagrant/tree/issue-66?

ruebot added a commit that referenced this issue May 27, 2015
@ruebot
Address #66
16f045a
@whikloj
Copy link
Contributor

whikloj commented May 27, 2015

I'll build it today and see if it works.

@whikloj
Copy link
Contributor

whikloj commented May 27, 2015

Looks good to me, able to edit and save XML in Fedora admin. See changes reflected immediately including new versions. Closed with 16f045a

@whikloj whikloj closed this as completed May 27, 2015
@ruebot
Copy link
Contributor

ruebot commented May 28, 2015

Cool. I'll merge it into master, and push. Thanks @whikloj!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@ruebot ruebot

Labels
bug
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@ksclarke @ruebot @mjordan @whikloj