<html xmlns:o="urn:schemas-microsoft-com:office:office" xmlns:w="urn:schemas-microsoft-com:office:word" xmlns:m="http://schemas.microsoft.com/office/2004/12/omml" xmlns="http://www.w3.org/TR/REC-html40">
<head>
<meta http-equiv="Content-Type" content="text/html; charset=Windows-1252">
<meta name="Generator" content="Microsoft Word 15 (filtered medium)">
<style><!--
/* Font Definitions */
@font-face
{font-family:"Cambria Math";
panose-1:2 4 5 3 5 4 6 3 2 4;}
@font-face
{font-family:Calibri;
panose-1:2 15 5 2 2 2 4 3 2 4;}
/* Style Definitions */
p.MsoNormal, li.MsoNormal, div.MsoNormal
{margin:0cm;
font-size:11.0pt;
font-family:"Calibri",sans-serif;}
.MsoChpDefault
{mso-style-type:export-only;
font-size:10.0pt;}
@page WordSection1
{size:612.0pt 792.0pt;
margin:72.0pt 72.0pt 72.0pt 72.0pt;}
div.WordSection1
{page:WordSection1;}
--></style>
</head>
<body lang="en-VN" link="#0563C1" vlink="#954F72" style="word-wrap:break-word">
<div class="WordSection1">
<p class="MsoNormal">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.<span lang="EN-US"> 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.<o:p></o:p></span></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal">Every 15 minutes or so, some tests kick off, and ‘flood’ (maybe 5-8 simultaneous<span lang="EN-US">, so nothing too strenuous</span>) login tests from the same IP (checkAddress is Off). I do see this on some non-test logins periodically
too<span lang="EN-US">; </span>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.</p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal">Some logs from the tail end of the processing, with<span lang="EN-US"> most everything in shibd.logger set to DEBUG, specifically
<o:p></o:p></span></p>
<p class="MsoNormal">log4j.rootCategory=DEBUG, shibd_log<o:p></o:p></p>
<p class="MsoNormal">log4j.category.XMLTooling.XMLObject=DEBUG<o:p></o:p></p>
<p class="MsoNormal">log4j.category.XMLTooling.KeyDEBUGResolver=DEBUG<o:p></o:p></p>
<p class="MsoNormal">log4j.category.Shibboleth.IPRange=DEBUG<o:p></o:p></p>
<p class="MsoNormal">log4j.category.Shibboleth.PropertySet=DEBUG<o:p></o:p></p>
<p class="MsoNormal">log4j.category.XMLTooling.libcurl=DEBUG<o:p></o:p></p>
<p class="MsoNormal">log4j.category.Shibboleth.SessionCache=DEBUG<o:p></o:p></p>
<p class="MsoNormal">log4j.category.XMLTooling.StorageService=DEBUG<o:p></o:p></p>
<p class="MsoNormal">log4j.category.XMLTooling.Signature.Debugger=WARN, sig_log<o:p></o:p></p>
<p class="MsoNormal">log4j.additivity.XMLTooling.Signature.Debugger=false<o:p></o:p></p>
<p class="MsoNormal">log4j.category.Shibboleth-TRANSACTION=INFO, tran_log<o:p></o:p></p>
<p class="MsoNormal">log4j.additivity.Shibboleth-TRANSACTION=false</p>
<p class="MsoNormal"><span lang="EN-US">(etc)<o:p></o:p></span></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal"><span lang="EN-US">In the apache log I see:<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">x.x.x.x</span> [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<o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal">Shibd.log<span lang="EN-US">, starting with <o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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)<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">time=2022-02-24T13:34:27.958Z level=DEBUG ndc="[9] [dds-auth-gateway]" class=OpenSAML.MessageDecoder.SAML2POST message=validating input<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">etc, and cutting towards the end of the sequence:<o:p></o:p></span></p>
<p class="MsoNormal">time=2022-02-24T13:34:27.976Z level=DEBUG ndc="[9] [dds-auth-gateway]" class=Shibboleth.SSO.SAML2 message=resolving attributes...<o:p></o:p></p>
<p class="MsoNormal">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<o:p></o:p></p>
<p class="MsoNormal">time=2022-02-24T13:34:27.976Z level=DEBUG ndc="[9] [dds-auth-gateway]" class=Shibboleth.SessionCache message=creating new session<o:p></o:p></p>
<p class="MsoNormal">time=2022-02-24T13:34:27.976Z level=DEBUG ndc="[9] [dds-auth-gateway]" class=XMLTooling.StorageService.MEMCACHE message=readString ctx: Logout - key:
<span lang="EN-US">foo@example.com</span><o:p></o:p></p>
<p class="MsoNormal">time=2022-02-24T13:34:27.976Z level=DEBUG ndc="[9] [dds-auth-gateway]" class=XMLTooling.StorageService.MEMCACHE message=Key Logout:<span lang="EN-US">foo@example.com</span><span lang="EN-US">
</span>not found in memcache...<o:p></o:p></p>
<p class="MsoNormal">time=2022-02-24T13:34:27.976Z level=DEBUG ndc="[9] [dds-auth-gateway]" class=XMLTooling.XMLObject message=starting to marshal saml:NameID<o:p></o:p></p>
<p class="MsoNormal">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<o:p></o:p></p>
<p class="MsoNormal">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<o:p></o:p></p>
<p class="MsoNormal">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)<o:p></o:p></p>
<p class="MsoNormal">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<o:p></o:p></p>
<p class="MsoNormal">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)<o:p></o:p></p>
<p class="MsoNormal">time=2022-02-24T13:34:27.976Z level=DEBUG ndc="[9] [dds-auth-gateway]" class=Shibboleth.SessionCache message=storing new session...<o:p></o:p></p>
<p class="MsoNormal">time=2022-02-24T13:34:27.976Z level=DEBUG ndc="[9] [dds-auth-gateway]" class=XMLTooling.StorageService.MEMCACHE message=createString ctx: _0cff98c534aed6f61f3024b237048004 - key: session<o:p></o:p></p>
<p class="MsoNormal">time=2022-02-24T13:34:27.977Z level=DEBUG ndc="[9] [dds-auth-gateway]" class=XMLTooling.StorageService.MEMCACHE message=Got result, updating map<o:p></o:p></p>
<p class="MsoNormal">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...<o:p></o:p></p>
<p class="MsoNormal">time=2022-02-24T13:34:27.978Z level=DEBUG ndc="[9] [dds-auth-gateway]" class=XMLTooling.StorageService.MEMCACHE message=New context: _0cff98c534aed6f61f3024b237048004<o:p></o:p></p>
<p class="MsoNormal">time=2022-02-24T13:34:27.979Z level=DEBUG ndc="[9] [dds-auth-gateway]" class=XMLTooling.StorageService.MEMCACHE message=readString ctx: NameID - key:
<span lang="EN-US">foo@example.com</span></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal"><span lang="EN-US">then a while nothing, then on the same ndc 9:<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">time=2022-02-24T13:34:36.748Z level=DEBUG ndc="[9] [dds-auth-gateway]" class=XMLTooling.StorageService.MEMCACHE message=updateString ctx: NameID - key: foo@example.com<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">time=2022-02-24T13:34:36.748Z level=DEBUG ndc="[9] [dds-auth-gateway]" class=XMLTooling.StorageService.MEMCACHE message=readString ctx: NameID - key: foo@example.com<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">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)<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">time=2022-02-24T13:34:36.768Z level=DEBUG ndc="[9] [dds-auth-gateway]" class=XMLTooling.StorageService.MEMCACHE message=readString ctx: RelayState - key: 77861fb69b5ae065dc5fe0b9601ada45e4a850746a12812a696c2b7cd97f0264<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US"><o:p> </o:p></span></p>
<p class="MsoNormal">And in transaction.log:</p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal">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</p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal"><span lang="EN-US">Any place I can look or debugs I can enable to determine what’s happening between
</span>2022-02-24T13:34:27.979Z <span lang="EN-US">and 2022-02-24T13:34:36.748Z? Or any other suggestions how I can figure out how this request took 8+ seconds?<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US"><o:p> </o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">Regards,<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">Jan<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US"><o:p> </o:p></span></p>
</div>
</body>
</html>