Ben,
I'm actually back on 3.4.2 at the moment. Once the problem showed up, I figured
I'd roll back so at least I've had fewer unknown areas of possible failure.
Anyway, I have a ruby gem in my app that sends requests to api-a for metadata,
etc. I don't have a clean url to give you, but I do see that the API methods
are processing quickly both in the logs and in browser (listDatastreams, for
example).
I see now from the logs that the lag I pasted earlier is occurring during what
looks like authorization, before any api-a methods are called. When they are
called, they process immediately as expected. I've pasted a portion in below.
Does that looks like some policy configuration I've mangled? I've temporarily
set xacml to permit-all-requests just to make the logs more readable.
Thanks,
Tyler
DEBUG 2013-02-12 12:36:41.728 [http-8080-2] (AuthFilterJAAS) incoming filter:
org.fcrepo.server.security.jaas.AuthFilterJAAS
DEBUG 2013-02-12 12:36:41.728 [http-8080-2] (AuthFilterJAAS) session-id:
CEE9677414B2880AEB923B8F8B56242D
DEBUG 2013-02-12 12:36:41.728 [http-8080-2] (AuthFilterJAAS) auth username:
fedoraAdmin
DEBUG 2013-02-12 12:36:41.728 [http-8080-2] (XmlUsersFileModule) using
FEDORA_HOME: E:\fedora
DEBUG 2013-02-12 12:36:41.728 [http-8080-2] (XmlUsersFileModule) login module
initialised: org.fcrepo.server.security.jaas.auth.module.XmlUsersFileModule
DEBUG 2013-02-12 12:36:41.728 [http-8080-2] (XmlUsersFileModule)
org.fcrepo.server.security.jaas.auth.module.XmlUsersFileModule login called.
DEBUG 2013-02-12 12:36:41.728 [http-8080-2] (AuthFilterJAAS) found
userPrincipal [org.fcrepo.server.security.jaas.auth.UserPrincipal]: fedoraAdmin
DEBUG 2013-02-12 12:36:41.728 [http-8080-2] (SubjectUtils) checking for
attributes (class name): java.util.HashMap
DEBUG 2013-02-12 12:36:41.728 [http-8080-2] (SubjectUtils) checking for
attributes (key object name): java.lang.String
DEBUG 2013-02-12 12:36:41.728 [http-8080-2] (SubjectUtils) checking for
attributes (value object name): java.util.HashSet
DEBUG 2013-02-12 12:36:41.728 [http-8080-2] (AuthFilterJAAS) found role:
administrator
DEBUG 2013-02-12 12:36:41.728 [http-8080-2] (SubjectUtils) checking for
attributes (class name): java.util.HashMap
DEBUG 2013-02-12 12:36:41.728 [http-8080-2] (SubjectUtils) checking for
attributes (key object name): java.lang.String
DEBUG 2013-02-12 12:36:41.728 [http-8080-2] (SubjectUtils) checking for
attributes (value object name): java.util.HashSet
DEBUG 2013-02-12 12:36:41.728 [http-8080-2] (AuthFilterJAAS) added role:
administrator
DEBUG 2013-02-12 12:36:41.728 [http-8080-2] (SubjectUtils) checking for
attributes (class name): java.util.HashMap
DEBUG 2013-02-12 12:36:41.728 [http-8080-2] (SubjectUtils) checking for
attributes (key object name): java.lang.String
DEBUG 2013-02-12 12:36:41.728 [http-8080-2] (SubjectUtils) checking for
attributes (value object name): java.util.HashSet
DEBUG 2013-02-12 12:36:41.728 [http-8080-2] (FilterRestApiFlash) Entering
FilterRestApiFlash.doThisSubclass()
DEBUG 2013-02-12 12:36:41.728 [http-8080-2] (ReadOnlyContext) Request Server IP
Address is '153.9.241.51'
DEBUG 2013-02-12 12:36:41.728 [http-8080-2] (ReadOnlyContext) Request Client IP
Address is '153.9.241.55'
DEBUG 2013-02-12 12:36:46.268 [http-8080-2] (ReadOnlyContext)
NOOP_PARAMETER_NAME=noOp
DEBUG 2013-02-12 12:36:46.268 [http-8080-2] (ReadOnlyContext)
request.getParameter(NOOP_PARAMETER_NAME)=null
DEBUG 2013-02-12 12:36:46.268 [http-8080-2] (ReadOnlyContext) noOp=false
DEBUG 2013-02-12 12:36:46.268 [http-8080-2] (ReadOnlyContext) IN CONTEXT
processing auxSubjectRoles=={role=[administrator], fedoraRole=[administrator]}
DEBUG 2013-02-12 12:36:46.268 [http-8080-2] (ReadOnlyContext) IN CONTEXT
processing auxSubjectRoles.keySet()==[role, fedoraRole]
DEBUG 2013-02-12 12:36:46.268 [http-8080-2] (ReadOnlyContext) IN CONTEXT
processing auxSubjectRoles.keySet().isEmpty()==false
DEBUG 2013-02-12 12:36:46.268 [http-8080-2] (ReadOnlyContext) IN CONTEXT
processing auxSubjectRoleKeys==java.util.HashMap$KeyIterator@1085e92
DEBUG 2013-02-12 12:36:46.268 [http-8080-2] (ReadOnlyContext) IN CONTEXT
name==role
DEBUG 2013-02-12 12:36:46.268 [http-8080-2] (ReadOnlyContext) IN CONTEXT name
is string==role
DEBUG 2013-02-12 12:36:46.268 [http-8080-2] (ReadOnlyContext) IN CONTEXT
singleValue is string==administrator
DEBUG 2013-02-12 12:36:46.268 [http-8080-2] (ReadOnlyContext) IN CONTEXT
name==fedoraRole
DEBUG 2013-02-12 12:36:46.268 [http-8080-2] (ReadOnlyContext) IN CONTEXT name
is string==fedoraRole
DEBUG 2013-02-12 12:36:46.268 [http-8080-2] (ReadOnlyContext) IN CONTEXT
singleValue is string==administrator
DEBUG 2013-02-12 12:36:46.268 [http-8080-2] (ReadOnlyContext) IN CONTEXT after
while
DEBUG 2013-02-12 12:36:46.268 [http-8080-2] (ReadOnlyContext) subject
attributes in readonlycontext constructor ==
urn:fedora:names:fedora:2.1:subject:loginId=[fedoraAdmin]
role=[administrator]
fedoraRole=[administrator]
DEBUG 2013-02-12 12:36:46.268 [http-8080-2] (DefaultAuthorization) Entered
enforceGetDatastreamDissemination
DEBUG 2013-02-12 12:36:46.268 [http-8080-2] (ReadOnlyContext) SINGLE SUBJECT
VALUE from map == fedoraAdmin
DEBUG 2013-02-12 12:36:46.268 [http-8080-2] (PolicyEnforcementPoint) permitting
request because enforceMode==ENFORCE_MODE_PERMIT_ALL_REQUESTS
DEBUG 2013-02-12 12:36:46.268 [http-8080-2] (PolicyEnforcementPoint) Policy
enforcement took 0ms.
DEBUG 2013-02-12 12:36:46.268 [http-8080-2] (DefaultAuthorization) Exiting
enforceGetDatastreamDissemination
DEBUG 2013-02-12 12:36:46.268 [http-8080-2] (DefaultDOManager) Got DOReader
(source=memory) for lcdl:5530 in 0ms.
DEBUG 2013-02-12 12:36:46.268 [http-8080-2] (DefaultAccess) Roundtrip
getDatastreamDissemination: 0 milliseconds.
DEBUG 2013-02-12 12:36:46.268 [http-8080-2] (DefaultAuthorization) Entered
enforceGetDatastreamDissemination
DEBUG 2013-02-12 12:36:46.268 [http-8080-2] (ReadOnlyContext) SINGLE SUBJECT
VALUE from map == fedoraAdmin
DEBUG 2013-02-12 12:36:46.268 [http-8080-2] (PolicyEnforcementPoint) permitting
request because enforceMode==ENFORCE_MODE_PERMIT_ALL_REQUESTS
DEBUG 2013-02-12 12:36:46.268 [http-8080-2] (PolicyEnforcementPoint) Policy
enforcement took 0ms.
DEBUG 2013-02-12 12:36:46.268 [http-8080-2] (DefaultAuthorization) Exiting
enforceGetDatastreamDissemination
DEBUG 2013-02-12 12:36:46.268 [http-8080-2] (DefaultDOManager) Got DOReader
(source=memory) for lcdl:5530 in 0ms.
DEBUG 2013-02-12 12:36:46.268 [http-8080-2] (DefaultAccess) Roundtrip
getDatastreamDissemination: 0 milliseconds.
DEBUG 2013-02-12 12:36:46.284 [http-8080-2] (DefaultAuthorization) Entered
enforceListDatastreams
DEBUG 2013-02-12 12:36:46.284 [http-8080-2] (ReadOnlyContext) SINGLE SUBJECT
VALUE from map == fedoraAdmin
DEBUG 2013-02-12 12:36:46.284 [http-8080-2] (PolicyEnforcementPoint) permitting
request because enforceMode==ENFORCE_MODE_PERMIT_ALL_REQUESTS
DEBUG 2013-02-12 12:36:46.284 [http-8080-2] (PolicyEnforcementPoint) Policy
enforcement took 0ms.
DEBUG 2013-02-12 12:36:46.284 [http-8080-2] (DefaultAuthorization) Exiting
enforceListDatastreams
DEBUG 2013-02-12 12:36:46.284 [http-8080-2] (DefaultDOManager) Got DOReader
(source=memory) for lcdl:5530 in 0ms.
DEBUG 2013-02-12 12:36:46.284 [http-8080-2] (DefaultAccess) Roundtrip
listDatastreams: 0 milliseconds.
DEBUG 2013-02-12 12:36:46.284 [http-8080-2] (AuthFilterJAAS) outgoing filter:
org.fcrepo.server.security.jaas.AuthFilterJAAS
Tyler
Tyler Mobley
Digital Services Librarian
College of Charleston Libraries
(843)953-6671
From: Benjamin Armintor <armin...@gmail.com<mailto:armin...@gmail.com>>
Reply-To: "Support and info exchange list for Fedora users."
<fedora-commons-users@lists.sourceforge.net<mailto:fedora-commons-users@lists.sourceforge.net>>
Date: Tuesday, February 12, 2013 10:19 AM
To: "Support and info exchange list for Fedora users."
<fedora-commons-users@lists.sourceforge.net<mailto:fedora-commons-users@lists.sourceforge.net>>
Subject: Re: [fcrepo-user] [SPAM] Large lag in response time post upgrade
Hey Tyler-
This doesn't ring a bell, but it has been a while since I worked on the 3.5
codebase. Could you attach a sample URL for the requests that are seeing this
behavior?
- Ben
On Tue, Feb 12, 2013 at 9:42 AM, mobleyt
<mobl...@cofc.edu<mailto:mobl...@cofc.edu>> wrote:
So late last week I completed an upgrade from 3.4.2 to 3.5. However, upon
upgrade, I noticed an intense lag between requests made by my client
application and the Fedora server. Just to get everything back on track, I
rolled back to my 3.4.2 version, but the speed issue remains. I'm not
receiving any errors, but everything takes its time to respond to my client
server.
On the client side my app has a method that pulls metadata from datastreams.
It usually makes a number of requests in addition to the image file for
display. Nothing has changed on that end. What I'm seeing in the fedora log,
however, is a consistent lag at the following point:
DEBUG 2013-02-12 09:10:54.063 [http-8080-3] (FilterRestApiFlash) Entering
FilterRestApiFlash.doThisSubclass()
DEBUG 2013-02-12 09:10:54.063 [http-8080-3] (ReadOnlyContext) Request Server
IP Address is '153.9.241.51'
DEBUG 2013-02-12 09:10:54.063 [http-8080-3] (ReadOnlyContext) Request Client
IP Address is '153.9.241.55'
DEBUG 2013-02-12 09:10:58.603 [http-8080-3] (ReadOnlyContext)
NOOP_PARAMETER_NAME=noOp
DEBUG 2013-02-12 09:10:58.603 [http-8080-3] (ReadOnlyContext)
request.getParameter(NOOP_PARAMETER_NAME)=null
DEBUG 2013-02-12 09:10:58.603 [http-8080-3] (ReadOnlyContext) noOp=false
This point lags consistently about 4 to 5 seconds and happens a few times
per request. Is there any setting or configuration that, in the process of
upgrade or downgrade, would cause this to slow down? Nothing has changed on
my client application, and I believe I have rolled back all my previous
settings in Fedora. Any ideas?
Thanks,
Tyler
--
View this message in context:
http://fedora-commons.1317035.n2.nabble.com/Large-lag-in-response-time-post-upgrade-tp7578769.html
Sent from the Fedora Commons Users mailing list archive at Nabble.com.
------------------------------------------------------------------------------
Free Next-Gen Firewall Hardware Offer
Buy your Sophos next-gen firewall before the end March 2013
and get the hardware for free! Learn more.
http://p.sf.net/sfu/sophos-d2d-feb
_______________________________________________
Fedora-commons-users mailing list
Fedora-commons-users@lists.sourceforge.net<mailto:Fedora-commons-users@lists.sourceforge.net>
https://lists.sourceforge.net/lists/listinfo/fedora-commons-users
------------------------------------------------------------------------------
Free Next-Gen Firewall Hardware Offer
Buy your Sophos next-gen firewall before the end March 2013
and get the hardware for free! Learn more.
http://p.sf.net/sfu/sophos-d2d-feb
_______________________________________________
Fedora-commons-users mailing list
Fedora-commons-users@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/fedora-commons-users
