[tracing] Structured logging based on Span events (#8583)

* [tracing] Update tracing.txt for Opentelemetry 0.6.0 version bump * [tracing] Add array value to span event attribute. Add span event logging. * [tracing] Add events to SpanHTTPHandler. Add events to TracedHTTPClient. * [tracing] Add log events to HandleSession, ReverseProxyHandler, JDBCBackedSession map and RedisBackedSessionMap. Additional changes include: - Disabling pretty printng in LoggingOptions for event JSON. * [tracing] Instrument DriverServiceSessionFactory and DockerSessionFactory with event logs. - Alphabetize EventAttributeValue Type enum - Alphabetize switch case in openTelemetrySpan - Breakdown TracerTest into multiple test methods for Span event testing - Add vargs to EventAttributeValue for array value types * [tracing] Remove AttributeKey enum method toString(). Add AttributeKey enum method getKey() * [tracing] Instrument event logs for LocalDistributor, LocalNode, GridStatusHandler, LocalSessionMap and ProtocolConverter. * [tracing] Fix indentation and conflict in JdbcBackedSessionMap [skip ci] Co-authored-by: David Burns <david.burns@theautomatedtester.co.uk> Co-authored-by: Diego Molina <diemol@users.noreply.github.com>
SeleniumHQ · Aug 18, 2020 · 738dd0e · 738dd0e
1 parent 49f2c2e
commit 738dd0e
Show file tree

Hide file tree

Showing 22 changed files with 1,154 additions and 250 deletions.
diff --git a/java/client/src/org/openqa/selenium/remote/RemoteTags.java b/java/client/src/org/openqa/selenium/remote/RemoteTags.java
@@ -18,8 +18,12 @@
 package org.openqa.selenium.remote;
 
 import org.openqa.selenium.Capabilities;
+import org.openqa.selenium.remote.tracing.AttributeKey;
+import org.openqa.selenium.remote.tracing.EventAttribute;
+import org.openqa.selenium.remote.tracing.EventAttributeValue;
 import org.openqa.selenium.remote.tracing.Span;
 
+import java.util.Map;
 import java.util.function.BiConsumer;
 
 public class RemoteTags {
@@ -28,12 +32,23 @@ private RemoteTags() {
     // Utility class
   }
 
-  public static final BiConsumer<Span, Capabilities> CAPABILITIES = (span, caps) -> {
-    span.setAttribute("session.capabilities", String.valueOf(caps));
-  };
+  public static final BiConsumer<Span, Capabilities>
+      CAPABILITIES =
+      (span, caps) -> span
+          .setAttribute(AttributeKey.SESSION_CAPABILITIES.getKey(), String.valueOf(caps));
 
-  public static final BiConsumer<Span, SessionId> SESSION_ID = (span, id) -> {
-    span.setAttribute("session.id", String.valueOf(id));
-  };
+  public static final BiConsumer<Span, SessionId> SESSION_ID = (span, id) ->
+      span.setAttribute(AttributeKey.SESSION_ID.getKey(), String.valueOf(id));
+
+  public static final BiConsumer<Map<String, EventAttributeValue>, Capabilities>
+      CAPABILITIES_EVENT =
+      (map, caps) ->
+          map.put(AttributeKey.SESSION_CAPABILITIES.getKey(),
+                  EventAttribute.setValue(String.valueOf(caps)));
+
+  public static final BiConsumer<Map<String, EventAttributeValue>, SessionId>
+      SESSION_ID_EVENT =
+      (map, id) ->
+          map.put(AttributeKey.SESSION_ID.getKey(), EventAttribute.setValue(String.valueOf(id)));
 
 }
diff --git a/java/client/src/org/openqa/selenium/remote/tracing/AttributeKey.java b/java/client/src/org/openqa/selenium/remote/tracing/AttributeKey.java
@@ -0,0 +1,62 @@
+// Licensed to the Software Freedom Conservancy (SFC) under one
+// or more contributor license agreements.  See the NOTICE file
+// distributed with this work for additional information
+// regarding copyright ownership.  The SFC licenses this file
+// to you 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.
+
+package org.openqa.selenium.remote.tracing;
+
+public enum AttributeKey {
+
+  EXCEPTION_EVENT("exception"),
+  EXCEPTION_TYPE("exception.type"),
+  EXCEPTION_MESSAGE("exception.message"),
+  EXCEPTION_STACKTRACE("exception.stacktrace"),
+
+  SPAN_KIND("span.kind"),
+
+  HTTP_METHOD("http.method"),
+  HTTP_URL("http.url"),
+  HTTP_STATUS_CODE("http.status_code"),
+  HTTP_TARGET_HOST("http.target_host"),
+  HTTP_CLIENT_CLASS("http.client_class"),
+  HTTP_HANDLER_CLASS("http.handler_class"),
+
+  LOGGER_CLASS("logger"),
+
+  DRIVER_RESPONSE("driver.response"),
+  DRIVER_URL("driver.url"),
+  DOWNSTREAM_DIALECT("downstream.dialect"),
+  UPSTREAM_DIALECT("upstream.dialect"),
+
+  SESSION_ID("session.id"),
+  SESSION_CAPABILITIES("session.capabilities"),
+  SESSION_URI("session.uri"),
+
+  DATABASE_STATEMENT ("db.statement"),
+  DATABASE_OPERATION ("db.operation"),
+  DATABASE_USER ("db.user"),
+  DATABASE_CONNECTION_STRING ("db.connection_string"),
+  DATABASE_SYSTEM("db.system");
+
+  private final String key;
+
+  AttributeKey(String key) {
+    this.key = key;
+  }
+
+  public String getKey() {
+    return this.key;
+  }
+}
diff --git a/java/client/src/org/openqa/selenium/remote/tracing/EventAttribute.java b/java/client/src/org/openqa/selenium/remote/tracing/EventAttribute.java
@@ -34,6 +34,22 @@ public static EventAttributeValue setValue(long value) {
     return new EventAttributeValue(value);
   }
 
+  public static EventAttributeValue setValue(String... value) {
+    return new EventAttributeValue(value);
+  }
+
+  public static EventAttributeValue setValue(Long... value) {
+    return new EventAttributeValue(value);
+  }
+
+  public static EventAttributeValue setValue(Double... value) {
+    return new EventAttributeValue(value);
+  }
+
+  public static EventAttributeValue setValue(Boolean... value) {
+    return new EventAttributeValue(value);
+  }
+
   public static EventAttributeValue setValue(double value) {
     return new EventAttributeValue(value);
   }

diff --git a/java/client/src/org/openqa/selenium/remote/tracing/EventAttributeValue.java b/java/client/src/org/openqa/selenium/remote/tracing/EventAttributeValue.java
@@ -23,6 +23,10 @@ public class EventAttributeValue {
   private String stringValue;
   private Number numberValue;
   private Boolean booleanValue;
+  private String[] stringArrayValue;
+  private Long[] longArrayValue;
+  private Double[] doubleArrayValue;
+  private Boolean[] booleanArrayValue;
 
   public EventAttributeValue(String value) {
     this.stringValue = value;
@@ -44,6 +48,26 @@ public EventAttributeValue(boolean value) {
     this.type = Type.BOOLEAN;
   }
 
+  public EventAttributeValue(String[] value) {
+    this.stringArrayValue = value;
+    this.type = Type.STRING_ARRAY;
+  }
+
+  public EventAttributeValue(Long[] value) {
+    this.longArrayValue = value;
+    this.type = Type.LONG_ARRAY;
+  }
+
+  public EventAttributeValue(Double[] value) {
+    this.doubleArrayValue = value;
+    this.type = Type.DOUBLE_ARRAY;
+  }
+
+  public EventAttributeValue(Boolean[] value) {
+    this.booleanArrayValue = value;
+    this.type = Type.BOOLEAN_ARRAY;
+  }
+
   public String getStringValue() {
     return stringValue;
   }
@@ -56,15 +80,27 @@ public Boolean getBooleanValue() {
     return booleanValue;
   }
 
+  public String[] getStringArrayValue() { return stringArrayValue; }
+
+  public Long[] getLongArrayValue() { return longArrayValue; }
+
+  public Double[] getDoubleArrayValue() { return doubleArrayValue; }
+
+  public Boolean[] getBooleanArrayValue() { return booleanArrayValue; }
+
   public Type getAttributeType() {
     return type;
   }
 
   public enum Type {
-    STRING,
     BOOLEAN,
+    BOOLEAN_ARRAY,
+    DOUBLE,
+    DOUBLE_ARRAY,
     LONG,
-    DOUBLE
+    LONG_ARRAY,
+    STRING,
+    STRING_ARRAY
   }
 
 }
diff --git a/java/client/src/org/openqa/selenium/remote/tracing/SpanWrappedHttpHandler.java b/java/client/src/org/openqa/selenium/remote/tracing/SpanWrappedHttpHandler.java
@@ -31,6 +31,9 @@
 import java.util.logging.Logger;
 
 import static org.openqa.selenium.remote.tracing.HttpTracing.newSpanAsChildOf;
+import static org.openqa.selenium.remote.tracing.Tags.EXCEPTION;
+import static org.openqa.selenium.remote.tracing.Tags.HTTP_REQUEST_EVENT;
+import static org.openqa.selenium.remote.tracing.Tags.HTTP_RESPONSE_EVENT;
 import static org.openqa.selenium.remote.tracing.Tags.HTTP_REQUEST;
 import static org.openqa.selenium.remote.tracing.Tags.HTTP_RESPONSE;
 import static org.openqa.selenium.remote.tracing.Tags.KIND;
@@ -52,6 +55,10 @@ public SpanWrappedHttpHandler(Tracer tracer, Function<HttpRequest, String> namer
   public HttpResponse execute(HttpRequest req) throws UncheckedIOException {
     // If there is already a span attached to this request, then do nothing.
     Object possibleSpan = req.getAttribute("selenium.tracing.span");
+    Map<String, EventAttributeValue> attributeMap = new HashMap<>();
+    attributeMap.put(AttributeKey.HTTP_HANDLER_CLASS.getKey(),
+                     EventAttribute.setValue(delegate.getClass().getName()));
+
     if (possibleSpan instanceof Span) {
       return delegate.execute(req);
     }
@@ -72,19 +79,26 @@ public HttpResponse execute(HttpRequest req) throws UncheckedIOException {
 
       KIND.accept(span, Span.Kind.SERVER);
       HTTP_REQUEST.accept(span, req);
+      HTTP_REQUEST_EVENT.accept(attributeMap, req);
+
       HttpTracing.inject(tracer, span, req);
 
       HttpResponse res = delegate.execute(req);
 
       HTTP_RESPONSE.accept(span, res);
+      HTTP_RESPONSE_EVENT.accept(attributeMap, res);
 
+      span.addEvent("HTTP request execution complete", attributeMap);
       return res;
     } catch (Throwable t) {
       span.setAttribute("error", true);
       span.setStatus(Status.UNKNOWN);
-      Map<String, EventAttributeValue> attributeValueMap = new HashMap<>();
-      attributeValueMap.put("Error message", EventAttribute.setValue(t.getMessage()));
-      span.addEvent("Error while executing server request", attributeValueMap);
+
+      EXCEPTION.accept(attributeMap, t);
+      attributeMap.put(AttributeKey.EXCEPTION_MESSAGE.getKey(),
+                       EventAttribute.setValue("Unable to execute request: " + t.getMessage()));
+      span.addEvent(AttributeKey.EXCEPTION_EVENT.getKey(), attributeMap);
+
       LOG.log(Level.WARNING, "Unable to execute request: " + t.getMessage(), t);
       throw t;
     } finally {

diff --git a/java/client/src/org/openqa/selenium/remote/tracing/Tags.java b/java/client/src/org/openqa/selenium/remote/tracing/Tags.java
@@ -20,12 +20,13 @@
 import org.openqa.selenium.remote.http.HttpRequest;
 import org.openqa.selenium.remote.http.HttpResponse;
 
+import java.io.PrintWriter;
+import java.io.StringWriter;
 import java.util.Map;
 import java.util.function.BiConsumer;
 
 public class Tags {
-
-  private final static Map<Integer, Status> STATUS_CODE_TO_TRACING_STATUS = Map.of(
+  private static final Map<Integer, Status> STATUS_CODE_TO_TRACING_STATUS = Map.of(
       401, Status.UNAUTHENTICATED,
       404, Status.NOT_FOUND,
       408, Status.DEADLINE_EXCEEDED,
@@ -40,20 +41,19 @@ private Tags() {
   }
 
   public static final BiConsumer<Span, Span.Kind> KIND =
-    (span, kind) -> span.setAttribute("span.kind", kind.toString());
+    (span, kind) -> span.setAttribute(AttributeKey.SPAN_KIND.getKey(), kind.toString());
 
   public static final BiConsumer<Span, HttpRequest> HTTP_REQUEST = (span, req) -> {
-    span.setAttribute("http.method", req.getMethod().toString());
-    span.setAttribute("http.url", req.getUri());
+    span.setAttribute(AttributeKey.HTTP_METHOD.getKey(), req.getMethod().toString());
+    span.setAttribute(AttributeKey.HTTP_URL.getKey(), req.getUri());
   };
 
   public static final BiConsumer<Span, HttpResponse> HTTP_RESPONSE = (span, res) -> {
     int statusCode = res.getStatus();
     if (res.getTargetHost() != null) {
-      span.setAttribute("http.target_host", res.getTargetHost());
+      span.setAttribute(AttributeKey.HTTP_TARGET_HOST.getKey(), res.getTargetHost());
     }
-    res.getTargetHost();
-    span.setAttribute("http.status_code", statusCode);
+    span.setAttribute(AttributeKey.HTTP_STATUS_CODE.getKey(), statusCode);
 
     if (statusCode > 99 && statusCode < 400) {
       span.setStatus(Status.OK);
@@ -65,4 +65,37 @@ private Tags() {
       span.setStatus(Status.UNKNOWN);
     }
   };
+
+  public static final BiConsumer<Map<String, EventAttributeValue>, HttpRequest>
+      HTTP_REQUEST_EVENT =
+      (map, req) -> {
+        map.put(AttributeKey.HTTP_METHOD.getKey(),
+                EventAttribute.setValue(req.getMethod().toString()));
+        map.put(AttributeKey.HTTP_URL.getKey(), EventAttribute.setValue(req.getUri()));
+      };
+
+  public static final BiConsumer<Map<String, EventAttributeValue>, HttpResponse>
+      HTTP_RESPONSE_EVENT =
+      (map, res) -> {
+        int statusCode = res.getStatus();
+        if (res.getTargetHost() != null) {
+          map.put(AttributeKey.HTTP_TARGET_HOST.getKey(),
+                  EventAttribute.setValue(res.getTargetHost()));
+        }
+        map.put(AttributeKey.HTTP_STATUS_CODE.getKey(), EventAttribute.setValue(statusCode));
+      };
+
+  public static final BiConsumer<Map<String, EventAttributeValue>, Throwable>
+      EXCEPTION =
+      (map, t) -> {
+        StringWriter sw = new StringWriter();
+        t.printStackTrace(new PrintWriter(sw));
+
+        map.put(AttributeKey.EXCEPTION_TYPE.getKey(),
+                EventAttribute.setValue(t.getClass().getName()));
+        map.put(AttributeKey.EXCEPTION_STACKTRACE.getKey(),
+                EventAttribute.setValue(sw.toString()));
+
+      };
+
 }
diff --git a/java/client/src/org/openqa/selenium/remote/tracing/TracedHttpClient.java b/java/client/src/org/openqa/selenium/remote/tracing/TracedHttpClient.java
@@ -18,8 +18,10 @@
 package org.openqa.selenium.remote.tracing;
 
 import static org.openqa.selenium.remote.tracing.Tags.HTTP_REQUEST;
+import static org.openqa.selenium.remote.tracing.Tags.HTTP_REQUEST_EVENT;
 import static org.openqa.selenium.remote.tracing.Tags.HTTP_RESPONSE;
 import static org.openqa.selenium.remote.tracing.HttpTracing.newSpanAsChildOf;
+import static org.openqa.selenium.remote.tracing.Tags.HTTP_RESPONSE_EVENT;
 import static org.openqa.selenium.remote.tracing.Tags.KIND;
 
 import org.openqa.selenium.internal.Require;
@@ -30,6 +32,8 @@
 import org.openqa.selenium.remote.http.WebSocket;
 
 import java.net.URL;
+import java.util.HashMap;
+import java.util.Map;
 
 public class TracedHttpClient implements HttpClient {
 
@@ -49,11 +53,18 @@ public WebSocket openSocket(HttpRequest request, WebSocket.Listener listener) {
   @Override
   public HttpResponse execute(HttpRequest req) {
     try (Span span = newSpanAsChildOf(tracer, req, "httpclient.execute")) {
+      Map<String, EventAttributeValue> attributeMap = new HashMap<>();
+      attributeMap.put(AttributeKey.HTTP_CLIENT_CLASS.getKey(),
+                       EventAttribute.setValue(delegate.getClass().getName()));
+
       KIND.accept(span, Span.Kind.CLIENT);
       HTTP_REQUEST.accept(span, req);
+      HTTP_REQUEST_EVENT.accept(attributeMap, req);
       tracer.getPropagator().inject(span, req, (r, key, value) -> r.setHeader(key, value));
       HttpResponse response = delegate.execute(req);
       HTTP_RESPONSE.accept(span, response);
+      HTTP_RESPONSE_EVENT.accept(attributeMap, response);
+      span.addEvent("HTTP request received response", attributeMap);
       return response;
     }
   }