<html xmlns:v="urn:schemas-microsoft-com:vml" 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=us-ascii">
<meta name="Generator" content="Microsoft Word 15 (filtered medium)">
<!--[if !mso]><style>v\:* {behavior:url(#default#VML);}
o\:* {behavior:url(#default#VML);}
w\:* {behavior:url(#default#VML);}
.shape {behavior:url(#default#VML);}
</style><![endif]--><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;}
@font-face
{font-family:Consolas;
panose-1:2 11 6 9 2 2 4 3 2 4;}
/* Style Definitions */
p.MsoNormal, li.MsoNormal, div.MsoNormal
{margin:0cm;
margin-bottom:.0001pt;
font-size:11.0pt;
font-family:"Calibri","sans-serif";
mso-fareast-language:EN-US;}
a:link, span.MsoHyperlink
{mso-style-priority:99;
color:#0563C1;
text-decoration:underline;}
a:visited, span.MsoHyperlinkFollowed
{mso-style-priority:99;
color:#954F72;
text-decoration:underline;}
span.EmailStyle17
{mso-style-type:personal-compose;
font-family:"Calibri","sans-serif";
color:windowtext;}
.MsoChpDefault
{mso-style-type:export-only;
mso-fareast-language:EN-US;}
@page WordSection1
{size:612.0pt 792.0pt;
margin:72.0pt 72.0pt 72.0pt 72.0pt;}
div.WordSection1
{page:WordSection1;}
--></style><!--[if gte mso 9]><xml>
<o:shapedefaults v:ext="edit" spidmax="1026" />
</xml><![endif]--><!--[if gte mso 9]><xml>
<o:shapelayout v:ext="edit">
<o:idmap v:ext="edit" data="1" />
</o:shapelayout></xml><![endif]-->
</head>
<body lang="EN-NZ" link="#0563C1" vlink="#954F72">
<div class="WordSection1">
<p class="MsoNormal">Hi all,<o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal">We’ve been running our IdP successfully now for at least a year, and are beginning to expand the number of services that use it, with our first big application recently launched, and the client is really happy with how that has gone. So
first off, thank you so very much for such a wonderful product to work with, it’s been a real pleasure. The implementation and documentation are both excellent examples of how to make a product worth supporting.<o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal">Recently I’ve been developing some further service reporting graphs (based around rrdtool and custom Python scripts). One of the enhancements I have hade was to change the Apache access logging to include the service time. My logging format
is quite different, and illustrated below:<o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal">(Apache 2.2 on RHEL 6)<o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal" style="margin-left:36.0pt"><span style="font-size:10.0pt;font-family:Consolas"># Unfortunately, the name of the module that generated the request is unavailable in RHEL5's Apache "[handler %R]\t"<o:p></o:p></span></p>
<p class="MsoNormal" style="margin-left:36.0pt"><span style="font-size:10.0pt;font-family:Consolas"># Note also that httpd will escape " to \", plus various others... (see the docs)<o:p></o:p></span></p>
<p class="MsoNormal" style="margin-left:36.0pt"><span style="font-size:10.0pt;font-family:Consolas">#<o:p></o:p></span></p>
<p class="MsoNormal" style="margin-left:36.0pt"><span style="font-size:10.0pt;font-family:Consolas">LogFormat "[time %{%FT%T%z}t]\t[addr %h]\t[xff %{X-Forwarded-For}i]\t[user %u]\t[sso %{OAM_REMOTE_USER}i]\t[pid %P]\t[vhost %{Host}i]\t[port %p]\t[prot %H]\t[meth
%m]\t[path %U]\t[qs %q]\t[ref %{Referer}i]\t[agent %{User-agent}i]\t[handler %R]\t[resp %>s]\t[redir %{Location}o]\t[serv %D us]\t[bin %I]\t[bout %O]\t[cnx %X]\t" ott<o:p></o:p></span></p>
<p class="MsoNormal" style="margin-left:36.0pt"><span style="font-size:10.0pt;font-family:Consolas">
<o:p></o:p></span></p>
<p class="MsoNormal" style="margin-left:36.0pt"><span style="font-size:10.0pt;font-family:Consolas"># Let's not log (specifically archive) the noise...<o:p></o:p></span></p>
<p class="MsoNormal" style="margin-left:36.0pt"><span style="font-size:10.0pt;font-family:Consolas">SetEnvIf Remote_Addr ^(load-balancer-health-checker-ip)$ noise<o:p></o:p></span></p>
<p class="MsoNormal" style="margin-left:36.0pt"><span style="font-size:10.0pt;font-family:Consolas">SetEnvIf Request_URI ^/statistics/ noise<o:p></o:p></span></p>
<p class="MsoNormal" style="margin-left:36.0pt"><span style="font-size:10.0pt;font-family:Consolas">SetEnvIf Request_URI ^/idp/profile/Status$ noise<o:p></o:p></span></p>
<p class="MsoNormal" style="margin-left:36.0pt"><span style="font-size:10.0pt;font-family:Consolas">SetEnvIf Request_URI ^/favicon.ico$ noise<o:p></o:p></span></p>
<p class="MsoNormal" style="margin-left:36.0pt"><span style="font-size:10.0pt;font-family:Consolas"><o:p> </o:p></span></p>
<p class="MsoNormal" style="margin-left:36.0pt"><span style="font-size:10.0pt;font-family:Consolas">CustomLog logs/access_log ott env=!noise<o:p></o:p></span></p>
<p class="MsoNormal" style="margin-left:36.0pt"><span style="font-size:10.0pt;font-family:Consolas">CustomLog logs/access_noise_log common env=noise<o:p></o:p></span></p>
<p class="MsoNormal" style="margin-left:36.0pt"><span style="font-size:10.0pt;font-family:Consolas"><o:p> </o:p></span></p>
<p class="MsoNormal" style="margin-left:36.0pt"><span style="font-size:10.0pt;font-family:Consolas"># and in the SSL configuration<o:p></o:p></span></p>
<p class="MsoNormal" style="margin-left:36.0pt"><span style="font-size:10.0pt;font-family:Consolas">ErrorLog logs/ssl_error_log<o:p></o:p></span></p>
<p class="MsoNormal" style="margin-left:36.0pt"><span style="font-size:10.0pt;font-family:Consolas">CustomLog logs/ssl_access_log ott env=!noise<o:p></o:p></span></p>
<p class="MsoNormal" style="margin-left:36.0pt"><span style="font-size:10.0pt;font-family:Consolas">CustomLog logs/ssl_access_noise_log common env=noise<o:p></o:p></span></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal">‘ott’ refers to ‘over-the-top’, meaning something that does more than required… I find it pretty useful though, in this case because it tells me the service time (%D), as documented at
<a href="http://httpd.apache.org/docs/2.2/mod/mod_log_config.html#formats">http://httpd.apache.org/docs/2.2/mod/mod_log_config.html#formats</a>
<o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal" style="margin-left:36.0pt">%D The time taken to serve the request, in microseconds.<o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal">What I have found potentially concerning is that the service time for some requests seem inordinately longer than I would have expected, though I don’t know what is normal for these particular requests, so I’d like to know what others have
found.<o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal">Taking the logs and processing them lightly, I threw them into a PivotChart to explore possible correlations, and found some things of potential concern. The graph is shown below. Note that the SSO handlers (/idp/profile/SAML2/POST/SSO
and /idp/profile/SAML2/Redirect/SSO – but not when a ?SAMLRequest=… is present) have a high standard deviation of response time<o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal">I’m not so concerned about the minimum times (well, not for this discussion), as they are likely due to our LDAP infrastructure; and the time for this corresponds well to the time between connection set up and tear-down when communicating
with said LDAP server. We use LDAP authentication for UserPassword authentication, and LDAP also back-ends our attribute resolution. We don’t operate this IdP in a clustered configuration, and we use uApprove.<o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal">What is more of concern are those entries with a high average (and a high standard deviation), such as the GET of /idp/profile/SAML2/Redirect/SSO with no query string, that produces a 200 response.<o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal">What would be happening when the IdP is evaluating such a request? My first thought was that entropy might be getting starved, but having looked at that for quite some time, it seems that it is quite buoyant and consistently between 2000
and 3000 bits, so I don’t think its blocking on entropy.<o:p></o:p></p>
<p class="MsoNormal">
<o:p></o:p></p>
<p class="MsoNormal">I wonder if its MySQL related (used for uApprove as well as storing shared tokens). And there is a bit of an outlier with /idp/uApprove/AttributeRelease. Might enable the slow query log…<o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal">Look forward to hearing about other’s experiences.<o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal">Thanks for reading,<o:p></o:p></p>
<p class="MsoNormal">Cameron<o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal"><span style="mso-fareast-language:EN-NZ"><img border="0" width="943" height="797" id="Chart_x0020_1" src="cid:image002.png@01CF1DB9.BA275990"></span><o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal"><span style="mso-fareast-language:EN-NZ">-- <o:p></o:p></span></p>
<p class="MsoNormal"><b><span style="mso-fareast-language:EN-NZ">Cameron Kerr</span></b><span style="mso-fareast-language:EN-NZ">
<span style="color:#767171"><cameron.kerr@otago.ac.nz></span><br>
<b>Systems Engineer</b><span style="color:#767171">. Systems Services Team; Infrastructure & Applications; ITS;
</span><b>University of Otago</b><span style="color:#767171"><o:p></o:p></span></span></p>
<p class="MsoNormal"><span style="color:#767171;mso-fareast-language:EN-NZ">Ph. +64 (03) 479 8191. Cell: +6421479527<o:p></o:p></span></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
</div>
</body>
</html>