Help Troubleshooting significant delay in processing in SP

Thu Feb 24 14:11:58 UTC 2022

I’m trying to figure out where some 8-10 seconds are being spent on some requests in shibboleth sp 3.3.0. Apache mpm-worker, version 2.4.52. This is deployed in Kubernetes in two containers in a pod sharing, amongst other things, the /var/run/shibboleth socket. Most SAML requests are very fast. But then every 15 minutes there’s a spike of activity and I see requests taking many seconds to complete.

Every 15 minutes or so, some tests kick off, and ‘flood’ (maybe 5-8 simultaneous, so nothing too strenuous) login tests from the same IP (checkAddress is Off). I do see this on some non-test logins periodically too; I have yet to be able to tell if there’s a pattern other than the “every 15 minutes test” that also causes a small spike in CPU usage.

Some logs from the tail end of the processing, with most everything in shibd.logger set to DEBUG, specifically
log4j.rootCategory=DEBUG, shibd_log
log4j.category.XMLTooling.XMLObject=DEBUG
log4j.category.XMLTooling.KeyDEBUGResolver=DEBUG
log4j.category.Shibboleth.IPRange=DEBUG
log4j.category.Shibboleth.PropertySet=DEBUG
log4j.category.XMLTooling.libcurl=DEBUG
log4j.category.Shibboleth.SessionCache=DEBUG
log4j.category.XMLTooling.StorageService=DEBUG
log4j.category.XMLTooling.Signature.Debugger=WARN, sig_log
log4j.additivity.XMLTooling.Signature.Debugger=false
log4j.category.Shibboleth-TRANSACTION=INFO, tran_log
log4j.additivity.Shibboleth-TRANSACTION=false
(etc)

In the apache log I see:
x.x.x.x [2022-02-24T13:34:27.957014Z] "POST /Shibboleth.sso/SAML2/POST HTTP/1.1" 302 1647 8812ms xff=- ua="Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/98.0.4758.102 Safari/537.36" gw=10.42.20.0 traceparent=-  inBytes=21599 OutBytes=1647

Shibd.log, starting with
time=2022-02-24T13:34:27.957Z level=DEBUG ndc="[9] [dds-auth-gateway]" class=Shibboleth.Listener message=dispatching message (dds-auth-gateway/SAML2/POST)
time=2022-02-24T13:34:27.958Z level=DEBUG ndc="[9] [dds-auth-gateway]" class=OpenSAML.MessageDecoder.SAML2POST message=validating input
etc, and cutting towards the end of the sequence:
time=2022-02-24T13:34:27.976Z level=DEBUG ndc="[9] [dds-auth-gateway]" class=Shibboleth.SSO.SAML2 message=resolving attributes...
time=2022-02-24T13:34:27.976Z level=DEBUG ndc="[9] [dds-auth-gateway]" class=Shibboleth.AttributeResolver.Query message=found AttributeStatement in input to new session, skipping query
time=2022-02-24T13:34:27.976Z level=DEBUG ndc="[9] [dds-auth-gateway]" class=Shibboleth.SessionCache message=creating new session
time=2022-02-24T13:34:27.976Z level=DEBUG ndc="[9] [dds-auth-gateway]" class=XMLTooling.StorageService.MEMCACHE message=readString ctx: Logout - key: foo at example.com
time=2022-02-24T13:34:27.976Z level=DEBUG ndc="[9] [dds-auth-gateway]" class=XMLTooling.StorageService.MEMCACHE message=Key Logout:foo at example.com not found in memcache...
time=2022-02-24T13:34:27.976Z level=DEBUG ndc="[9] [dds-auth-gateway]" class=XMLTooling.XMLObject message=starting to marshal saml:NameID
time=2022-02-24T13:34:27.976Z level=DEBUG ndc="[9] [dds-auth-gateway]" class=XMLTooling.XMLObject message=XMLObject has a usable cached DOM, reusing it
time=2022-02-24T13:34:27.976Z level=DEBUG ndc="[9] [dds-auth-gateway]" class=XMLTooling.XMLObject message=releasing cached DOM representation for parent object with propagation set to true
time=2022-02-24T13:34:27.976Z level=DEBUG ndc="[9] [dds-auth-gateway]" class=XMLTooling.XMLObject message=releasing cached DOM representation for (saml:Subject)
time=2022-02-24T13:34:27.976Z level=DEBUG ndc="[9] [dds-auth-gateway]" class=XMLTooling.XMLObject message=releasing cached DOM representation for parent object with propagation set to true
time=2022-02-24T13:34:27.976Z level=DEBUG ndc="[9] [dds-auth-gateway]" class=XMLTooling.XMLObject message=releasing cached DOM representation for (saml:Assertion)
time=2022-02-24T13:34:27.976Z level=DEBUG ndc="[9] [dds-auth-gateway]" class=Shibboleth.SessionCache message=storing new session...
time=2022-02-24T13:34:27.976Z level=DEBUG ndc="[9] [dds-auth-gateway]" class=XMLTooling.StorageService.MEMCACHE message=createString ctx: _0cff98c534aed6f61f3024b237048004 - key: session
time=2022-02-24T13:34:27.977Z level=DEBUG ndc="[9] [dds-auth-gateway]" class=XMLTooling.StorageService.MEMCACHE message=Got result, updating map
time=2022-02-24T13:34:27.978Z level=DEBUG ndc="[9] [dds-auth-gateway]" class=XMLTooling.StorageService.MEMCACHE message=Key _0cff98c534aed6f61f3024b237048004 not found in memcache...
time=2022-02-24T13:34:27.978Z level=DEBUG ndc="[9] [dds-auth-gateway]" class=XMLTooling.StorageService.MEMCACHE message=New context: _0cff98c534aed6f61f3024b237048004
time=2022-02-24T13:34:27.979Z level=DEBUG ndc="[9] [dds-auth-gateway]" class=XMLTooling.StorageService.MEMCACHE message=readString ctx: NameID - key: foo at example.com

then a while nothing, then on the same ndc 9:
time=2022-02-24T13:34:36.748Z level=DEBUG ndc="[9] [dds-auth-gateway]" class=XMLTooling.StorageService.MEMCACHE message=updateString ctx: NameID - key: foo at example.com
time=2022-02-24T13:34:36.748Z level=DEBUG ndc="[9] [dds-auth-gateway]" class=XMLTooling.StorageService.MEMCACHE message=readString ctx: NameID - key: foo at example.com
time=2022-02-24T13:34:36.766Z level=INFO ndc="[9] [dds-auth-gateway]" class=Shibboleth.SessionCache message=new session created: ID (_0cff98c534aed6f61f3024b237048004) IdP (MyIDP) Protocol(urn:oasis:names:tc:SAML:2.0:protocol) Address (x.x.x.x)
time=2022-02-24T13:34:36.768Z level=DEBUG ndc="[9] [dds-auth-gateway]" class=XMLTooling.StorageService.MEMCACHE message=readString ctx: RelayState - key: 77861fb69b5ae065dc5fe0b9601ada45e4a850746a12812a696c2b7cd97f0264

And in transaction.log:

time=2022-02-24T13:34:36.767Z level=INFO ndc="[9] [dds-auth-gateway]" class=Shibboleth-TRANSACTION.Login message=IDP= MyIDP |SP=MySP|AuthTime=2022-02-24T13:34:27|AssertTime=2022-02-24T13:34:27|ProtoTime=2022-02-24T13:34:27|Status=urn:oasis:names:tc:SAML:2.0:status:Success|SubStatus=|SessionId=_0cff98c534aed6f61f3024b237048004|AssertionId=_2f144390-c175-471b-ba43-3aecd9d89bd1|MsgId=_bd66a138-a368-4bc6-a9f8-5a03e9acad40|ReqId=_0a45d4da4cf6d4321aadbcbe325dd256|SAMLSessId=_2f144390-c175-471b-ba43-3aecd9d89bd1|SAMLAuthCtx=urn:oasis:names:tc:SAML:2.0:ac:classes:unspecified|Attributes=MY_SHIB_NameID_Email(1),MY_SHIB_User_IsAbsIDPUser(1)|Binding=urn:oasis:names:tc:SAML:2.0:bindings:HTTP-POST|Exception=|LogoutResult=|UA=Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/98.0.4758.102 Safari/537.36|ClientIp=x.x.x.x

Any place I can look or debugs I can enable to determine what’s happening between 2022-02-24T13:34:27.979Z and 2022-02-24T13:34:36.748Z? Or any other suggestions how I can figure out how this request took 8+ seconds?

Regards,
Jan

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://shibboleth.net/pipermail/users/attachments/20220224/9a007c82/attachment.htm>