Add Instrumentation to Collect Missing HTTP Parameters

CHANGELOG.md

@@ -1,6 +1,11 @@
 # CHANGELOG
 
 ## Version 2.0.1
+- Fix issue when dependency start time wasn't being recorded correctly
+- Fixed #533 HTTP Dependency Telemetry now matches with .NET SDK
+- Introduced public method `httpMethodFinishedWithPath(String identifier, String method, String path, String correlationId, String uri, String target, int result, long delta)`
+  to support instrumentation of Path of URI in HTTP requests.
+- `httpMethodFinished(String identifier, String method, String correlationId, String uri, String target, int result, int delta)` is now marked as deprecated
 - Logger Messages now being pushed as custom dimension when reporting exceptions via Loggers. (#400)
 - Enhanced Log4j2 appender to support basic parameters including Filters, Layouts and includeException. (#348)
 - Fixed performance issue on SDK startup.

agent/src/main/java/com/microsoft/applicationinsights/agent/internal/agent/HttpClientMethodVisitor.java

@@ -32,8 +32,8 @@
  */
 public final class HttpClientMethodVisitor extends AbstractHttpMethodVisitor {
 
-    private final static String FINISH_DETECT_METHOD_NAME = "httpMethodFinished";
-    private final static String FINISH_METHOD_RETURN_SIGNATURE = "(Ljava/lang/String;Ljava/lang/String;Ljava/lang/String;Ljava/lang/String;Ljava/lang/String;IJ)V";
+    private final static String FINISH_DETECT_METHOD_NAME = "httpMethodFinishedWithPath";
+    private final static String FINISH_METHOD_RETURN_SIGNATURE = "(Ljava/lang/String;Ljava/lang/String;Ljava/lang/String;Ljava/lang/String;Ljava/lang/String;Ljava/lang/String;IJ)V";
 
     public HttpClientMethodVisitor(int access,
                                    String desc,
@@ -50,6 +50,8 @@ public HttpClientMethodVisitor(int access,
     private int childIdLocal;
     private int correlationContextLocal;
     private int appCorrelationId;
+    private int target;
+    private int path;
 
     @Override
     public void onMethodEnter() {
@@ -87,21 +89,37 @@ public void onMethodEnter() {
         mv.visitLdcInsn("Request-Context");
         mv.visitVarInsn(ALOAD, appCorrelationId);
         mv.visitMethodInsn(INVOKEINTERFACE, "org/apache/http/HttpRequest", "addHeader", "(Ljava/lang/String;Ljava/lang/String;)V", true);
-
+
+        //Load HttpUriRequest instance into Local Array. Contains information of Path and Host
         mv.visitVarInsn(ALOAD, 2);
-        mv.visitMethodInsn(INVOKEINTERFACE, "org/apache/http/HttpRequest", "getRequestLine", "()Lorg/apache/http/RequestLine;", true);
-        int requestLineLocal = this.newLocal(Type.getType(Object.class));
-        mv.visitVarInsn(ASTORE, requestLineLocal);
+        mv.visitMethodInsn(INVOKEINTERFACE, "org/apache/http/client/methods/HttpUriRequest", "getURI", "()Ljava/net/URI;", true);
+        int uri = this.newLocal(Type.getType(Object.class));
+        mv.visitVarInsn(ASTORE, uri);
 
-        mv.visitVarInsn(ALOAD, requestLineLocal);
-        mv.visitMethodInsn(INVOKEINTERFACE, "org/apache/http/RequestLine", "getMethod", "()Ljava/lang/String;", true);
+        //Get Method Name from HttpUriLRequest interface object
+        mv.visitVarInsn(ALOAD, 2);
+        mv.visitMethodInsn(INVOKEINTERFACE, "org/apache/http/client/methods/HttpUriRequest", "getMethod", "()Ljava/lang/String;", true);
         methodLocal = this.newLocal(Type.getType(Object.class));
         mv.visitVarInsn(ASTORE, methodLocal);
 
-        mv.visitVarInsn(ALOAD, requestLineLocal);
-        mv.visitMethodInsn(INVOKEINTERFACE, "org/apache/http/RequestLine", "getUri", "()Ljava/lang/String;", true);
+        //Use HttpUriRequest instance loaded to retrieve the target(aka host name) from java.net.URI class
+        mv.visitVarInsn(ALOAD, uri);
+        mv.visitMethodInsn(INVOKEVIRTUAL, "java/net/URI", "getHost", "()Ljava/lang/String;", false);
+        target = this.newLocal(Type.getType(Object.class));
+        mv.visitVarInsn(ASTORE, target);
+
+        //Get the URL String from URI object
+        mv.visitVarInsn(ALOAD, uri);
+        mv.visitMethodInsn(INVOKEVIRTUAL, "java/net/URI", "toString", "()Ljava/lang/String;", false);
         uriLocal = this.newLocal(Type.getType(Object.class));
         mv.visitVarInsn(ASTORE, uriLocal);
+
+        //Use HttpUriRequest instance loaded to retrieve the path(relative URL) from java.net.URI class
+        mv.visitVarInsn(ALOAD, uri);
+        mv.visitMethodInsn(INVOKEVIRTUAL, "java/net/URI", "getPath", "()Ljava/lang/String;", false);
+        path = this.newLocal(Type.getType(Object.class));
+        mv.visitVarInsn(ASTORE, path);
+
     }
 
     protected TempVar duplicateTopStackToTempVariable(Type typeOfTopElementInStack) {
@@ -157,11 +175,13 @@ protected void byteCodeForMethodExit(int opcode) {
                 mv.visitVarInsn(ASTORE, targetLocal);
 
                 mv.visitFieldInsn(Opcodes.GETSTATIC, internalName, "INSTANCE", "L" + internalName + ";");
+
                 mv.visitLdcInsn(getMethodName());
                 mv.visitVarInsn(ALOAD, methodLocal);
+                mv.visitVarInsn(ALOAD, path); //load path parameter
                 mv.visitVarInsn(ALOAD, childIdLocal);
                 mv.visitVarInsn(ALOAD, uriLocal);
-                mv.visitVarInsn(ALOAD, targetLocal);
+                mv.visitVarInsn(ALOAD, targetLocal); //using derived target
                 mv.visitVarInsn(ILOAD, statusCodeLocal);
                 mv.visitVarInsn(LLOAD, deltaInNS);
                 mv.visitMethodInsn(Opcodes.INVOKEVIRTUAL, internalName, FINISH_DETECT_METHOD_NAME, FINISH_METHOD_RETURN_SIGNATURE, false);
@@ -175,9 +195,10 @@ protected void byteCodeForMethodExit(int opcode) {
                 mv.visitFieldInsn(Opcodes.GETSTATIC, internalName, "INSTANCE", "L" + internalName + ";");
                 mv.visitLdcInsn(getMethodName());
                 mv.visitVarInsn(ALOAD, methodLocal);
+                mv.visitVarInsn(ALOAD, path); //load path parameter
                 mv.visitVarInsn(ALOAD, childIdLocal);
                 mv.visitVarInsn(ALOAD, uriLocal);
-                mv.visitInsn(ACONST_NULL);
+                mv.visitVarInsn(ALOAD, target); //using the derived target from java.net.URI
                 mv.visitVarInsn(ILOAD, statusCodeLocal);
                 mv.visitVarInsn(LLOAD, deltaInNS);
                 mv.visitMethodInsn(Opcodes.INVOKEVIRTUAL, internalName, FINISH_DETECT_METHOD_NAME, FINISH_METHOD_RETURN_SIGNATURE, false);

agent/src/main/java/com/microsoft/applicationinsights/agent/internal/coresync/AgentNotificationsHandler.java

@@ -53,6 +53,9 @@ public interface AgentNotificationsHandler {
     void httpMethodStarted(String classAndMethodNames, String url);
 
     /**
+     * @deprecated This method does not capture HTTP Parameters path and host name. Using this to instrument
+     * http client can lead to false information being captured and transmitted. </br>
+     * use {@link #httpMethodFinishedWithPath(String, String, String, String, String, String, int, long) instead </br>
      * A HTTP call that was ended
      * @param identifier - HTTP identifier, i.e. the callser
      * @param method - 'GET'/'PUT' etc.
@@ -62,8 +65,23 @@ public interface AgentNotificationsHandler {
      * @param result - The result
      * @param delta - Time it took to do the call
      */
+    @Deprecated
     void httpMethodFinished(String identifier, String method, String correlationId, String uri, String target, int result, long delta);
 
+    /**
+     *  A HTTP Call that was ended
+     * @param identifier - HTTP Identifier, i.e the caller
+     * @param method - 'GET'/'PUT'/'POST' etc
+     * @param path - The relative path of the URL
+     * @param correlationId - The correlation Id for the associated HTTP call
+     * @param uri - The URI executed
+     * @param target - The target resource of the HTTP call
+     * @param result - The result code generated by URL execution eg. 200, 404
+     * @param delta - The time it took to complete the call
+     */
+    void httpMethodFinishedWithPath(String identifier, String method, String path, String correlationId, String uri,
+                                    String target, int result, long delta);
+
     /**
      * Called when an java.sql.Statement concrete class is called
      * @param classAndMethodNames The name of the class and method separated by '.'

agent/src/main/java/com/microsoft/applicationinsights/agent/internal/coresync/impl/ImplementationsCoordinator.java

@@ -96,6 +96,19 @@ public void httpMethodFinished(String identifier, String method, String correlat
         }
     }
 
+    @Override
+    public void httpMethodFinishedWithPath(String identifier, String method, String path, String correlationId, String uri,
+                                           String target, int result, long delta) {
+        try {
+            AgentNotificationsHandler implementation = getImplementation();
+            if (implementation != null) {
+                implementation.httpMethodFinishedWithPath(identifier, method, path, correlationId, uri, target, result,
+                        delta);
+            }
+        } catch (Throwable t) {
+        }
+    }
+
     @Override
     public void exceptionCaught(String classAndMethodNames, Throwable throwable) {
         try {

core/src/main/java/com/microsoft/applicationinsights/internal/agent/CoreAgentNotificationsHandler.java

@@ -27,6 +27,7 @@
 import java.sql.DatabaseMetaData;
 import java.sql.ResultSet;
 import java.sql.SQLException;
+import java.util.Date;
 import java.util.LinkedList;
 
 import com.microsoft.applicationinsights.agent.internal.coresync.AgentNotificationsHandler;
@@ -163,6 +164,32 @@ public void httpMethodFinished(String identifier, String method, String correlat
         telemetryClient.track(telemetry);
     }
 
+    @Override
+    public void httpMethodFinishedWithPath(String identifier, String method, String path, String correlationId, String uri, String target, int result, long delta) {
+        if (!LocalStringsUtils.isNullOrEmpty(uri) && (uri.startsWith("https://dc.services.visualstudio.com") || uri.startsWith("https://rt.services.visualstudio.com"))) {
+            return;
+        }
+        long deltaInMS = nanoToMilliseconds(delta);
+        String name = method + " " + path;
+        RemoteDependencyTelemetry telemetry = new RemoteDependencyTelemetry(name, uri, new Duration(deltaInMS), true);
+        Date dependencyStartTime = new Date(System.currentTimeMillis() - deltaInMS);
+        telemetry.setTimestamp(dependencyStartTime);
+        telemetry.setId(correlationId);
+        telemetry.setResultCode(Integer.toString(result));
+        telemetry.setType("HTTP");
+        if (target != null && !target.isEmpty()) {
+            if (telemetry.getTarget() == null) {
+                telemetry.setTarget(target);
+            } else {
+                telemetry.setTarget(telemetry.getTarget() + " | " + target);
+            }
+        }
+
+        InternalLogger.INSTANCE.trace("'%s' sent an HTTP method: '%s', uri: '%s', duration=%s ms", identifier, method, uri, deltaInMS);
+        telemetryClient.track(telemetry);
+
+    }
+
     @Override
     public void jedisMethodStarted(String name) {
         int index = name.lastIndexOf('#');
@@ -211,7 +238,9 @@ public void methodFinished(String name, long thresholdInMS) {
     public void methodFinished(String classAndMethodNames, long deltaInNS, Object[] args, Throwable throwable) {
         long durationInMS = nanoToMilliseconds(deltaInNS);
         Duration duration = new Duration(durationInMS);
+        Date dependencyStartTime = new Date(System.currentTimeMillis() - durationInMS);
         RemoteDependencyTelemetry telemetry = new RemoteDependencyTelemetry(classAndMethodNames, null, duration, throwable == null);
+        telemetry.setTimestamp(dependencyStartTime);
         telemetry.setDependencyKind(DependencyKind.Other);
 
         if (args != null) {
@@ -359,10 +388,11 @@ private void report(MethodData methodData, Throwable throwable) {
     }
 
     private void sendInstrumentationTelemetry(MethodData methodData, Throwable throwable) {
-        Duration duration = new Duration(nanoToMilliseconds(methodData.interval));
-        RemoteDependencyTelemetry telemetry = new RemoteDependencyTelemetry(methodData.name, null, duration, throwable == null);
+        long durationInMilliSeconds = nanoToMilliseconds(methodData.interval);
+        RemoteDependencyTelemetry telemetry = new RemoteDependencyTelemetry(methodData.name, null, new Duration(durationInMilliSeconds), throwable == null);
         telemetry.setType(methodData.type);
-
+        Date dependencyStartDate = new Date(System.currentTimeMillis() - durationInMilliSeconds);
+        telemetry.setTimestamp(dependencyStartDate);
         InternalLogger.INSTANCE.trace("Sending RDD event for '%s'", methodData.name);
 
         telemetryClient.track(telemetry);
@@ -382,6 +412,8 @@ private void sendHTTPTelemetry(MethodData methodData, Throwable throwable) {
 
             RemoteDependencyTelemetry telemetry = new RemoteDependencyTelemetry(url, null, duration, throwable == null);
             telemetry.setDependencyKind(DependencyKind.Http);
+            Date dependencyStartDate = new Date(System.currentTimeMillis() - durationInMilliSeconds);
+            telemetry.setTimestamp(dependencyStartDate);
             telemetryClient.trackDependency(telemetry);
             if (throwable != null) {
                 ExceptionTelemetry exceptionTelemetry = new ExceptionTelemetry(throwable);
@@ -418,6 +450,8 @@ private void sendSQLTelemetry(MethodData methodData, Throwable throwable) {
                     duration,
                     throwable == null);
             telemetry.setDependencyKind(DependencyKind.SQL);
+            Date dependencyStartTime = new Date(System.currentTimeMillis() - durationInMilliSeconds);
+            telemetry.setTimestamp(dependencyStartTime);
 
             StringBuilder sb = null;
             if (methodData.arguments.length > 3) {
@@ -435,7 +469,7 @@ private void sendSQLTelemetry(MethodData methodData, Throwable throwable) {
             }
 
             InternalLogger.INSTANCE.trace("Sending Sql RDD event for '%s', command: '%s', duration=%s ms", dependencyName, commandName, durationInMilliSeconds);
-  
+
             telemetryClient.track(telemetry);
             if (throwable != null) {
                 InternalLogger.INSTANCE.trace("Sending Sql exception");

web/src/main/java/com/microsoft/applicationinsights/web/internal/correlation/TelemetryCorrelationUtils.java

@@ -180,6 +180,7 @@ public static String generateChildDependencyTarget(String requestContext) {
 
 		String target = generateSourceTargetCorrelation(instrumentationKey, requestContext);
 		if (target == null) {
+			InternalLogger.INSTANCE.warn("Target value is null and hence returning empty string");
 			return ""; // we want an empty string instead of null so it plays nicer with bytecode injection
 		}