Add timing CadiFilter

Issue-ID: AAF-468
Change-Id: I335a1106609ac99e12eeb0640a06c9eb969e9bbb
Signed-off-by: Instrumental <jonathan.gathman@att.com>

15 files changed, 189 insertions, 19 deletions

diff --git a/cadi/core/src/main/java/org/onap/aaf/cadi/CadiWrap.java b/cadi/core/src/main/java/org/onap/aaf/cadi/CadiWrap.java
index a2dfba37..6f4d5cc7 100644
--- a/cadi/core/src/main/java/org/onap/aaf/cadi/CadiWrap.java
+++ b/cadi/core/src/main/java/org/onap/aaf/cadi/CadiWrap.java
@@ -34,6 +34,7 @@ import org.onap.aaf.cadi.filter.PermConverter;
 import org.onap.aaf.cadi.lur.EpiLur;
 import org.onap.aaf.cadi.principal.TaggedPrincipal;
 import org.onap.aaf.cadi.taf.TafResp;
+import org.onap.aaf.cadi.util.Timing;
 
 
 
@@ -113,7 +114,7 @@ public class CadiWrap extends HttpServletRequestWrapper implements HttpServletRe
 	 */
 	@Override
 	public boolean isUserInRole(String perm) {
-		return perm==null?false:checkPerm(access,"(HttpRequest)",principal,pconv,lur,perm);
+		return perm==null?false:checkPerm(access,"isUserInRole",principal,pconv,lur,perm);
 	}
 	
 	public static boolean checkPerm(Access access, String caller, Principal principal, PermConverter pconv, Lur lur, String perm) {
@@ -121,12 +122,13 @@ public class CadiWrap extends HttpServletRequestWrapper implements HttpServletRe
 			access.log(Level.AUDIT,caller, "No Principal in Transaction");
 			return false;
 		} else { 
+			final long start = System.nanoTime();
 			perm = pconv.convert(perm);
 			if(lur.fish(principal,lur.createPerm(perm))) {
-				access.log(Level.DEBUG,caller, principal.getName(), "has", perm);
+				access.printf(Level.DEBUG,"%s: %s has %s, %f ms", caller, principal.getName(), perm, Timing.millis(start));
 				return true;
 			} else {
-				access.log(Level.DEBUG,caller, principal.getName(), "does not have", perm);
+				access.printf(Level.DEBUG,"%s: %s does not have %s, %f ms", caller, principal.getName(), perm, Timing.millis(start));
 				return false;
 			}
 		}
diff --git a/cadi/core/src/main/java/org/onap/aaf/cadi/filter/CadiFilter.java b/cadi/core/src/main/java/org/onap/aaf/cadi/filter/CadiFilter.java
index 237aa28d..29234ed7 100644
--- a/cadi/core/src/main/java/org/onap/aaf/cadi/filter/CadiFilter.java
+++ b/cadi/core/src/main/java/org/onap/aaf/cadi/filter/CadiFilter.java
@@ -36,6 +36,7 @@ import javax.servlet.http.HttpServletRequest;
 import javax.servlet.http.HttpServletResponse;
 
 import org.onap.aaf.cadi.Access;
+import org.onap.aaf.cadi.Access.Level;
 import org.onap.aaf.cadi.CadiException;
 import org.onap.aaf.cadi.CadiWrap;
 import org.onap.aaf.cadi.LocatorException;
@@ -43,11 +44,11 @@ import org.onap.aaf.cadi.Lur;
 import org.onap.aaf.cadi.PropAccess;
 import org.onap.aaf.cadi.ServletContextAccess;
 import org.onap.aaf.cadi.TrustChecker;
-import org.onap.aaf.cadi.Access.Level;
 import org.onap.aaf.cadi.config.Config;
 import org.onap.aaf.cadi.config.Get;
 import org.onap.aaf.cadi.taf.TafResp;
 import org.onap.aaf.cadi.taf.TafResp.RESP;
+import org.onap.aaf.cadi.util.Timing;
 
 /**
  * CadiFilter
@@ -264,22 +265,39 @@ public class CadiFilter implements Filter {
 	 */
 	//TODO Always validate changes against Tomcat AbsCadiValve and Jaspi CadiSAM functions
 	public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain) throws IOException, ServletException {
+		final long startAll = System.nanoTime();
+		long startCode, startValidate;
+		float code=0f, validate=0f;
+		String user = "n/a";
+		String tag = "";
 		try {
 			HttpServletRequest hreq = (HttpServletRequest)request;
 			if(noAuthn(hreq)) {
+				startCode=System.nanoTime();
 				chain.doFilter(request, response);
+				code = Timing.millis(startCode);
 			} else {
 				HttpServletResponse hresp = (HttpServletResponse)response;
+				startValidate=System.nanoTime();
 				TafResp tresp = httpChecker.validate(hreq, hresp, hreq);
+				validate = Timing.millis(startValidate);
 				if(tresp.isAuthenticated()==RESP.IS_AUTHENTICATED) {
+					user = tresp.getPrincipal().personalName();
+					tag = tresp.getPrincipal().tag();
 					CadiWrap cw = new CadiWrap(hreq, tresp, httpChecker.getLur(),getConverter(hreq));
 					if(httpChecker.notCadi(cw, hresp)) {
+						startCode=System.nanoTime();
 						oauthFilter.doFilter(cw,response,chain);
+						code = Timing.millis(startCode);
 					}
-				}						
+				}
 			}
 		} catch (ClassCastException e) {
 			throw new ServletException("CadiFilter expects Servlet to be an HTTP Servlet",e);
+		} finally {
+			access.printf(Level.WARN, "Trans: user=%s[%s],ip=%s,ms=%f,validate=%f,code=%f",
+				user,tag,request.getRemoteAddr(),
+				Timing.millis(startAll),validate,code);
 		}
 	}
 
diff --git a/cadi/core/src/main/java/org/onap/aaf/cadi/taf/AbsTafResp.java b/cadi/core/src/main/java/org/onap/aaf/cadi/taf/AbsTafResp.java
index c216fb57..fb54abdb 100644
--- a/cadi/core/src/main/java/org/onap/aaf/cadi/taf/AbsTafResp.java
+++ b/cadi/core/src/main/java/org/onap/aaf/cadi/taf/AbsTafResp.java
@@ -23,6 +23,7 @@ package org.onap.aaf.cadi.taf;
 
 import org.onap.aaf.cadi.Access;
 import org.onap.aaf.cadi.principal.TaggedPrincipal;
+import org.onap.aaf.cadi.util.Timing;
 
 /**
  * AbsTafResp
@@ -34,9 +35,11 @@ import org.onap.aaf.cadi.principal.TaggedPrincipal;
  */
 public abstract class AbsTafResp implements TafResp {
 
-	protected final String desc;
-	protected final TaggedPrincipal principal;
 	protected final Access access;
+	protected final String tafName;
+	protected final TaggedPrincipal principal;
+	protected final String desc;
+	private float timing;
 
 	/**
 	 * AbsTafResp
@@ -47,11 +50,13 @@ public abstract class AbsTafResp implements TafResp {
 	 * Access (for access to underlying container, i.e. for Logging, auditing, ClassLoaders, etc)
 	 *  
 	 * @param access
+	 * @param tafname 
 	 * @param principal
 	 * @param description
 	 */
-	public AbsTafResp(Access access, TaggedPrincipal principal, String description) {
+	public AbsTafResp(Access access, String tafname, TaggedPrincipal principal, String description) {
 		this.access = access;
+		this.tafName = tafname;
 		this.principal = principal;
 		this.desc = description;
 	}
@@ -113,4 +118,19 @@ public abstract class AbsTafResp implements TafResp {
 		return false;
 	}
 
+	@Override
+	public float timing() {
+		return timing;
+	}
+	
+	@Override
+	public void timing(final long start) {
+		timing = Timing.millis(start);
+	}
+
+	@Override
+	public String taf() {
+		return tafName;
+	}
+
 }
diff --git a/cadi/core/src/main/java/org/onap/aaf/cadi/taf/HttpEpiTaf.java b/cadi/core/src/main/java/org/onap/aaf/cadi/taf/HttpEpiTaf.java
index 5b51c111..1d7967e3 100644
--- a/cadi/core/src/main/java/org/onap/aaf/cadi/taf/HttpEpiTaf.java
+++ b/cadi/core/src/main/java/org/onap/aaf/cadi/taf/HttpEpiTaf.java
@@ -101,8 +101,9 @@ public class HttpEpiTaf implements HttpTaf {
 		}
 		try {
 			for (HttpTaf taf : tafs) {
+				final long start = System.nanoTime();
 				tresp = taf.validate(reading, req, resp);
-				addToLog(log, tresp);
+				addToLog(log, tresp, start);
 				switch(tresp.isAuthenticated()) {
 					case TRY_ANOTHER_TAF:
 						break; // and loop
@@ -181,10 +182,11 @@ public class HttpEpiTaf implements HttpTaf {
 		return Resp.NOT_MINE;
 	}
 	
-	private void addToLog(List<TafResp> log, TafResp tresp) {
+	private void addToLog(List<TafResp> log, final TafResp tresp, final long start) {
 		if (log == null) {
 			return;
 		}
+		tresp.timing(start);
 		log.add(tresp);
 	}
 	
@@ -193,7 +195,7 @@ public class HttpEpiTaf implements HttpTaf {
 			return;
 		}
 		for (TafResp tresp : log) {
-			access.log(Level.DEBUG, tresp.desc());
+			access.printf(Level.DEBUG, "%s: %s, ms=%f", tresp.taf(), tresp.desc(), tresp.timing());
 		}
 	}
 
diff --git a/cadi/core/src/main/java/org/onap/aaf/cadi/taf/LoginPageTafResp.java b/cadi/core/src/main/java/org/onap/aaf/cadi/taf/LoginPageTafResp.java
index 3f80170e..c8abec0a 100644
--- a/cadi/core/src/main/java/org/onap/aaf/cadi/taf/LoginPageTafResp.java
+++ b/cadi/core/src/main/java/org/onap/aaf/cadi/taf/LoginPageTafResp.java
@@ -37,7 +37,7 @@ public class LoginPageTafResp extends AbsTafResp {
 	private final String loginPageURL;
 
 	private LoginPageTafResp(Access access, final HttpServletResponse resp, String loginPageURL) {
-		super(access, null, "Multiple Possible HTTP Logins available.  Redirecting to Login Choice Page");
+		super(access, "LoginPage", null, "Multiple Possible HTTP Logins available.  Redirecting to Login Choice Page");
 		httpResp = resp;
 		this.loginPageURL = loginPageURL;
 	}
@@ -91,4 +91,10 @@ public class LoginPageTafResp extends AbsTafResp {
 
 		return NullTafResp.singleton();
 	}
+	
+	@Override
+	public String taf() {
+		return "LoginPage";
+	}
+
 }
diff --git a/cadi/core/src/main/java/org/onap/aaf/cadi/taf/NullTafResp.java b/cadi/core/src/main/java/org/onap/aaf/cadi/taf/NullTafResp.java
index 20fc944a..af6ef9cc 100644
--- a/cadi/core/src/main/java/org/onap/aaf/cadi/taf/NullTafResp.java
+++ b/cadi/core/src/main/java/org/onap/aaf/cadi/taf/NullTafResp.java
@@ -70,4 +70,19 @@ class NullTafResp implements TafResp {
 	public boolean isFailedAttempt() {
 		return true;
 	}
+
+	@Override
+	public float timing() {
+		return 0;
+	}
+
+	@Override
+	public void timing(long start) {
+	}
+	
+	@Override
+	public String taf() {
+		return "NULL";
+	}
+
 }
diff --git a/cadi/core/src/main/java/org/onap/aaf/cadi/taf/PuntTafResp.java b/cadi/core/src/main/java/org/onap/aaf/cadi/taf/PuntTafResp.java
index f496581b..a38c8532 100644
--- a/cadi/core/src/main/java/org/onap/aaf/cadi/taf/PuntTafResp.java
+++ b/cadi/core/src/main/java/org/onap/aaf/cadi/taf/PuntTafResp.java
@@ -25,6 +25,7 @@ import java.io.IOException;
 
 import org.onap.aaf.cadi.Access;
 import org.onap.aaf.cadi.principal.TaggedPrincipal;
+import org.onap.aaf.cadi.util.Timing;
 
 /**
  * A Punt Resp to make it fast and easy for a Taf to respond that it cannot handle a particular kind of
@@ -33,10 +34,13 @@ import org.onap.aaf.cadi.principal.TaggedPrincipal;
  *
  */
 public class PuntTafResp implements TafResp {
+	private final String name;
 	private final String desc;
+	private float timing;
 
 	public PuntTafResp(String name, String explanation) {
-		desc = name + " is not processing this transaction: " + explanation;
+		this.name = name;
+		desc = "Not processing this transaction: " + explanation;
 	}
 	
 	public boolean isValid() {
@@ -66,4 +70,20 @@ public class PuntTafResp implements TafResp {
 	public boolean isFailedAttempt() {
 		return false;
 	}
+
+	@Override
+	public float timing() {
+		return timing;
+	}
+
+	@Override
+	public void timing(long start) {
+		timing = Timing.millis(start);
+	}
+	
+	@Override
+	public String taf() {
+		return name;
+	}
+
 }
diff --git a/cadi/core/src/main/java/org/onap/aaf/cadi/taf/TafResp.java b/cadi/core/src/main/java/org/onap/aaf/cadi/taf/TafResp.java
index a679d994..acade37a 100644
--- a/cadi/core/src/main/java/org/onap/aaf/cadi/taf/TafResp.java
+++ b/cadi/core/src/main/java/org/onap/aaf/cadi/taf/TafResp.java
@@ -91,4 +91,21 @@ public interface TafResp {
 	 * Be able to check if part of a Failed attempt
 	 */
 	public boolean isFailedAttempt();
+	
+	/**
+	 * report how long this took
+	 * @return
+	 */
+	public float timing();
+
+	/**
+	 * Set end of timing in Millis, given Nanos
+	 * @param start
+	 */
+	void timing(long start);
+	
+	/**
+	 * Support Taf Name
+	 */
+	String taf();
 }
diff --git a/cadi/core/src/main/java/org/onap/aaf/cadi/taf/TrustNotTafResp.java b/cadi/core/src/main/java/org/onap/aaf/cadi/taf/TrustNotTafResp.java
index 24a79cf3..98ead3ca 100644
--- a/cadi/core/src/main/java/org/onap/aaf/cadi/taf/TrustNotTafResp.java
+++ b/cadi/core/src/main/java/org/onap/aaf/cadi/taf/TrustNotTafResp.java
@@ -25,10 +25,12 @@ import java.io.IOException;
 
 import org.onap.aaf.cadi.Access;
 import org.onap.aaf.cadi.principal.TaggedPrincipal;
+import org.onap.aaf.cadi.util.Timing;
 
 public class TrustNotTafResp implements TafResp {
 	private final TafResp delegate;
 	private final String desc;
+	private float timing;
 	
 	public TrustNotTafResp(final TafResp delegate, final String desc) {
 		this.delegate = delegate;
@@ -69,8 +71,24 @@ public class TrustNotTafResp implements TafResp {
 	public boolean isFailedAttempt() {
 		return true;
 	}
+	@Override
+	public float timing() {
+		return timing;
+	}
+
+	@Override
+	public void timing(long start) {
+		timing = Timing.millis(start);
+	}
 	
+	@Override
 	public String toString() {
 		return desc();
 	}
+	
+	@Override
+	public String taf() {
+		return "TrustNot";
+	}
+
 }
diff --git a/cadi/core/src/main/java/org/onap/aaf/cadi/taf/TrustTafResp.java b/cadi/core/src/main/java/org/onap/aaf/cadi/taf/TrustTafResp.java
index bc5e8db6..9d3b28ca 100644
--- a/cadi/core/src/main/java/org/onap/aaf/cadi/taf/TrustTafResp.java
+++ b/cadi/core/src/main/java/org/onap/aaf/cadi/taf/TrustTafResp.java
@@ -25,11 +25,13 @@ import java.io.IOException;
 
 import org.onap.aaf.cadi.Access;
 import org.onap.aaf.cadi.principal.TaggedPrincipal;
+import org.onap.aaf.cadi.util.Timing;
 
 public class TrustTafResp implements TafResp {
 	private final TafResp delegate;
 	private final TaggedPrincipal principal;
 	private final String desc;
+	private float timing;
 	
 	public TrustTafResp(final TafResp delegate, final TaggedPrincipal principal, final String desc) {
 		this.delegate = delegate;
@@ -71,8 +73,23 @@ public class TrustTafResp implements TafResp {
 	public boolean isFailedAttempt() {
 		return delegate.isFailedAttempt();
 	}
+	@Override
+	public float timing() {
+		return timing;
+	}
+
+	@Override
+	public void timing(long start) {
+		timing = Timing.millis(start);
+	}
 	
 	public String toString() {
 		return principal.getName() + " by trust of " + desc();
 	}
+	
+	@Override
+	public String taf() {
+		return "Trust";
+	}
+
 }
diff --git a/cadi/core/src/main/java/org/onap/aaf/cadi/taf/basic/BasicHttpTafResp.java b/cadi/core/src/main/java/org/onap/aaf/cadi/taf/basic/BasicHttpTafResp.java
index c17797b8..643cf29e 100644
--- a/cadi/core/src/main/java/org/onap/aaf/cadi/taf/basic/BasicHttpTafResp.java
+++ b/cadi/core/src/main/java/org/onap/aaf/cadi/taf/basic/BasicHttpTafResp.java
@@ -31,13 +31,14 @@ import org.onap.aaf.cadi.taf.AbsTafResp;
 import org.onap.aaf.cadi.taf.TafResp;
 
 public class BasicHttpTafResp extends AbsTafResp implements TafResp {
+	private static final String tafName = BasicHttpTaf.class.getSimpleName();
 	private HttpServletResponse httpResp;
 	private String realm;
 	private RESP status;
 	private final boolean wasFailed;
 	
 	public BasicHttpTafResp(Access access, TaggedPrincipal principal, String description, RESP status, HttpServletResponse resp, String realm, boolean wasFailed) {
-		super(access,principal, description);
+		super(access, tafName, principal, description);
 		httpResp = resp;
 		this.realm = realm;
 		this.status = status;
@@ -57,6 +58,4 @@ public class BasicHttpTafResp extends AbsTafResp implements TafResp {
 	public boolean isFailedAttempt() {
 		return wasFailed;
 	}
-
-
 }
diff --git a/cadi/core/src/main/java/org/onap/aaf/cadi/taf/cert/X509HttpTafResp.java b/cadi/core/src/main/java/org/onap/aaf/cadi/taf/cert/X509HttpTafResp.java
index b7f63b8e..c18f9036 100644
--- a/cadi/core/src/main/java/org/onap/aaf/cadi/taf/cert/X509HttpTafResp.java
+++ b/cadi/core/src/main/java/org/onap/aaf/cadi/taf/cert/X509HttpTafResp.java
@@ -29,10 +29,12 @@ import org.onap.aaf.cadi.taf.AbsTafResp;
 import org.onap.aaf.cadi.taf.TafResp;
 
 public class X509HttpTafResp extends AbsTafResp implements TafResp {
+	private static final String tafName = X509Taf.class.getSimpleName();
+
 	private RESP status;
 	
 	public X509HttpTafResp(Access access, TaggedPrincipal principal, String description, RESP status) {
-		super(access, principal, description);
+		super(access, tafName, principal, description);
  		this.status = status;
 	}
 
diff --git a/cadi/core/src/main/java/org/onap/aaf/cadi/taf/cert/X509Taf.java b/cadi/core/src/main/java/org/onap/aaf/cadi/taf/cert/X509Taf.java
index 7b7f2db0..77efa956 100644
--- a/cadi/core/src/main/java/org/onap/aaf/cadi/taf/cert/X509Taf.java
+++ b/cadi/core/src/main/java/org/onap/aaf/cadi/taf/cert/X509Taf.java
@@ -56,7 +56,6 @@ import org.onap.aaf.cadi.taf.basic.BasicHttpTaf;
 import org.onap.aaf.cadi.util.Split;
 
 public class X509Taf implements HttpTaf {
-	
 	private static final String CERTIFICATE_NOT_VALID_FOR_AUTHENTICATION = "Certificate NOT valid for Authentication";
 	public static final CertificateFactory certFactory;
 	public static final MessageDigest messageDigest;
diff --git a/cadi/core/src/main/java/org/onap/aaf/cadi/taf/dos/DenialOfServiceTafResp.java b/cadi/core/src/main/java/org/onap/aaf/cadi/taf/dos/DenialOfServiceTafResp.java
index b156392d..e5a336f7 100644
--- a/cadi/core/src/main/java/org/onap/aaf/cadi/taf/dos/DenialOfServiceTafResp.java
+++ b/cadi/core/src/main/java/org/onap/aaf/cadi/taf/dos/DenialOfServiceTafResp.java
@@ -27,10 +27,12 @@ import org.onap.aaf.cadi.Access;
 import org.onap.aaf.cadi.taf.AbsTafResp;
 
 public class DenialOfServiceTafResp extends AbsTafResp  {
+	private static final String tafName = DenialOfServiceTaf.class.getSimpleName();
+
 	private RESP ect;  // Homage to Arethra Franklin
 
 	public DenialOfServiceTafResp(Access access, RESP resp, String description ) {
-		super(access, null, description);
+		super(access, tafName, null, description);
 		ect = resp;
 	}
 
@@ -44,4 +46,10 @@ public class DenialOfServiceTafResp extends AbsTafResp  {
 	public RESP authenticate() throws IOException {
 		return ect;
 	}
+	
+	@Override
+	public String taf() {
+		return "DOS";
+	}
+
 }
diff --git a/cadi/core/src/main/java/org/onap/aaf/cadi/util/Timing.java b/cadi/core/src/main/java/org/onap/aaf/cadi/util/Timing.java
new file mode 100644
index 00000000..82bd389a
--- /dev/null
+++ b/cadi/core/src/main/java/org/onap/aaf/cadi/util/Timing.java
@@ -0,0 +1,27 @@
+/**
+ * ============LICENSE_START====================================================
+ * org.onap.aaf
+ * ===========================================================================
+ * Copyright (c) 2018 AT&T Intellectual Property. All rights reserved.
+ * ===========================================================================
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ * 
+ *      http://www.apache.org/licenses/LICENSE-2.0
+ * 
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ * ============LICENSE_END====================================================
+ *
+ */
+package org.onap.aaf.cadi.util;
+
+public class Timing {
+	public static float millis(final long start) {
+		return (System.nanoTime() - start) / 1000000f;
+	}
+}