Add logging of workflow and activity run failures

Author: Spikhalskiy

temporal-opentracing/src/main/java/io/temporal/opentracing/OpenTracingOptions.java

@@ -19,9 +19,9 @@
 
 package io.temporal.opentracing;
 
-import javax.annotation.Nonnull;
 import java.util.HashMap;
 import java.util.Map;
+import javax.annotation.Nonnull;
 
 public class OpenTracingOptions {
   private final Map<SpanOperationType, String> customSpanOperationNamePrefixes;

temporal-opentracing/src/main/java/io/temporal/opentracing/StandardLogNames.java

@@ -0,0 +1,25 @@
+/*
+ *  Copyright (C) 2020 Temporal Technologies, Inc. All Rights Reserved.
+ *
+ *  Copyright 2012-2016 Amazon.com, Inc. or its affiliates. All Rights Reserved.
+ *
+ *  Modifications copyright (C) 2017 Uber Technologies, Inc.
+ *
+ *  Licensed under the Apache License, Version 2.0 (the "License"). You may not
+ *  use this file except in compliance with the License. A copy of the License is
+ *  located at
+ *
+ *  http://aws.amazon.com/apache2.0
+ *
+ *  or in the "license" file accompanying this file. This file 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 io.temporal.opentracing;
+
+public class StandardLogNames {
+  public static final String FAILURE_MESSAGE = "failureMessage";
+  public static final String FAILURE_CAUSE = "failureCause";
+}

temporal-opentracing/src/main/java/io/temporal/opentracing/StandardTags.java renamed to temporal-opentracing/src/main/java/io/temporal/opentracing/StandardTagNames.java

@@ -19,9 +19,10 @@
 
 package io.temporal.opentracing;
 
-public class StandardTags {
+public class StandardTagNames {
   public static final String WORKFLOW_ID = "workflowId";
   public static final String RUN_ID = "runId";
   public static final String PARENT_WORKFLOW_ID = "parentWorkflowId";
   public static final String PARENT_RUN_ID = "parentRunId";
+  public static final String FAILED = "failed";
 }

temporal-opentracing/src/main/java/io/temporal/opentracing/internal/OpenTracingActivityInboundCallsInterceptor.java

@@ -71,6 +71,9 @@ public ActivityOutput execute(ActivityInput input) {
             .start();
     try (Scope scope = tracer.scopeManager().activate(activityRunSpan)) {
       return super.execute(input);
+    } catch (Throwable t) {
+      OpenTracingSpanUtils.logFail(activityRunSpan, t);
+      throw t;
     } finally {
       activityRunSpan.finish();
     }

temporal-opentracing/src/main/java/io/temporal/opentracing/internal/OpenTracingContextAccessor.java

@@ -27,9 +27,6 @@
 import io.temporal.api.common.v1.Payload;
 import io.temporal.common.converter.DataConverter;
 import io.temporal.common.interceptors.Header;
-import sun.reflect.generics.reflectiveObjects.NotImplementedException;
-
-import javax.annotation.Nonnull;
 import java.lang.reflect.Type;
 import java.util.HashMap;
 import java.util.Iterator;
@@ -39,7 +36,7 @@
 public class OpenTracingContextAccessor {
   private static final String TRACER_HEADER_KEY = "_tracer-data";
   private static final Type HASH_MAP_STRING_STRING_TYPE =
-          TypeToken.getParameterized(HashMap.class, String.class, String.class).getType();
+      TypeToken.getParameterized(HashMap.class, String.class, String.class).getType();
 
   public static void writeSpanContextToHeader(
       SpanContext spanContext, Header header, Tracer tracer) {
@@ -61,7 +58,8 @@ public static SpanContext readSpanContextFromHeader(Header header, Tracer tracer
       return null;
     }
     Map<String, String> serializedSpanContext =
-        DataConverter.getDefaultInstance().fromPayload(payload, HashMap.class, HASH_MAP_STRING_STRING_TYPE);
+        DataConverter.getDefaultInstance()
+            .fromPayload(payload, HashMap.class, HASH_MAP_STRING_STRING_TYPE);
     return deserializeSpanContextFromMap(serializedSpanContext, tracer);
   }
 

temporal-opentracing/src/main/java/io/temporal/opentracing/internal/OpenTracingSpanUtils.java

@@ -24,7 +24,8 @@
 import io.opentracing.Span;
 import io.opentracing.SpanContext;
 import io.opentracing.Tracer;
-import io.temporal.opentracing.StandardTags;
+import io.temporal.opentracing.StandardLogNames;
+import io.temporal.opentracing.StandardTagNames;
 import java.util.HashMap;
 import java.util.Map;
 import java.util.concurrent.TimeUnit;
@@ -36,7 +37,7 @@ public static Tracer.SpanBuilder createWorkflowStartSpan(
     Map<String, String> tags =
         new HashMap<String, String>() {
           {
-            put(StandardTags.WORKFLOW_ID, workflowId);
+            put(StandardTagNames.WORKFLOW_ID, workflowId);
           }
         };
     return createSpan(tracer, startTimeMs, operationName, tags, null, References.FOLLOWS_FROM);
@@ -52,9 +53,9 @@ public static Tracer.SpanBuilder createChildWorkflowStartSpan(
     Map<String, String> tags =
         new HashMap<String, String>() {
           {
-            put(StandardTags.WORKFLOW_ID, workflowId);
-            put(StandardTags.PARENT_WORKFLOW_ID, parentWorkflowId);
-            put(StandardTags.PARENT_RUN_ID, parentRunId);
+            put(StandardTagNames.WORKFLOW_ID, workflowId);
+            put(StandardTagNames.PARENT_WORKFLOW_ID, parentWorkflowId);
+            put(StandardTagNames.PARENT_RUN_ID, parentRunId);
           }
         };
     return createSpan(tracer, startTimeMs, operationName, tags, null, References.FOLLOWS_FROM);
@@ -70,8 +71,8 @@ public static Tracer.SpanBuilder createWorkflowRunSpan(
     Map<String, String> tags =
         new HashMap<String, String>() {
           {
-            put(StandardTags.WORKFLOW_ID, workflowId);
-            put(StandardTags.RUN_ID, runId);
+            put(StandardTagNames.WORKFLOW_ID, workflowId);
+            put(StandardTagNames.RUN_ID, runId);
           }
         };
     return createSpan(
@@ -88,8 +89,8 @@ public static Tracer.SpanBuilder createActivityStartSpan(
     Map<String, String> tags =
         new HashMap<String, String>() {
           {
-            put(StandardTags.WORKFLOW_ID, workflowId);
-            put(StandardTags.RUN_ID, runId);
+            put(StandardTagNames.WORKFLOW_ID, workflowId);
+            put(StandardTagNames.RUN_ID, runId);
           }
         };
     return createSpan(tracer, startTimeMs, operationName, tags, null, References.CHILD_OF);
@@ -105,14 +106,27 @@ public static Tracer.SpanBuilder createActivityRunSpan(
     Map<String, String> tags =
         new HashMap<String, String>() {
           {
-            put(StandardTags.WORKFLOW_ID, workflowId);
-            put(StandardTags.RUN_ID, runId);
+            put(StandardTagNames.WORKFLOW_ID, workflowId);
+            put(StandardTagNames.RUN_ID, runId);
           }
         };
     return createSpan(
         tracer, startTimeMs, operationName, tags, activityStartSpanContext, References.CHILD_OF);
   }
 
+  public static void logFail(Span toSpan, Throwable failReason) {
+    toSpan.setTag(StandardTagNames.FAILED, true);
+    Map<String, Object> logPayload =
+        new HashMap<String, Object>() {
+          {
+            put(StandardLogNames.FAILURE_MESSAGE, failReason.getMessage());
+            put(StandardLogNames.FAILURE_CAUSE, failReason);
+          }
+        };
+
+    toSpan.log(System.currentTimeMillis(), logPayload);
+  }
+
   private static Tracer.SpanBuilder createSpan(
       Tracer tracer,
       long startTimeMs,

temporal-opentracing/src/main/java/io/temporal/opentracing/internal/OpenTracingWorkflowInboundCallsInterceptor.java

@@ -64,6 +64,9 @@ public WorkflowOutput execute(WorkflowInput input) {
             .start();
     try (Scope scope = tracer.scopeManager().activate(workflowRunSpan)) {
       return super.execute(input);
+    } catch (Throwable t) {
+      OpenTracingSpanUtils.logFail(workflowRunSpan, t);
+      throw t;
     } finally {
       workflowRunSpan.finish();
     }

temporal-opentracing/src/test/java/io/temporal/opentracing/OpenTracingActivityFailureTest.java

@@ -165,6 +165,7 @@ public void testActivityFailureSpanStructure() {
     MockSpan activityFailRunSpan = activityRunSpans.get(0);
     assertEquals(activityStartSpan.context().spanId(), activityFailRunSpan.parentId());
     assertEquals("RunActivity-Activity1", activityFailRunSpan.operationName());
+    assertEquals(true, activityFailRunSpan.tags().get(StandardTagNames.FAILED));
 
     MockSpan activitySuccessfulRunSpan = activityRunSpans.get(1);
     assertEquals(activityStartSpan.context().spanId(), activitySuccessfulRunSpan.parentId());

temporal-opentracing/src/test/java/io/temporal/opentracing/OpenTracingWorkflowReplayTest.java

@@ -186,6 +186,7 @@ public void testWorkflowReplaySpanStructure() {
     MockSpan workflowFirstRunSpan = workflowRunSpans.get(0);
     assertEquals(workflowStartSpan.context().spanId(), workflowFirstRunSpan.parentId());
     assertEquals("RunWorkflow-TestWorkflow", workflowFirstRunSpan.operationName());
+    assertEquals(true, workflowFirstRunSpan.tags().get(StandardTagNames.FAILED));
 
     List<MockSpan> workflowFirstRunChildren = spansHelper.getByParentSpan(workflowFirstRunSpan);
     assertEquals(1, workflowFirstRunChildren.size());

temporal-opentracing/src/test/java/io/temporal/opentracing/OpenTracingWorkflowRetryTest.java

@@ -187,6 +187,7 @@ public void testWorkflowReplaySpanStructure() {
     MockSpan workflowFirstRunSpan = workflowRunSpans.get(0);
     assertEquals(workflowStartSpan.context().spanId(), workflowFirstRunSpan.parentId());
     assertEquals("RunWorkflow-TestWorkflow", workflowFirstRunSpan.operationName());
+    assertEquals(true, workflowFirstRunSpan.tags().get(StandardTagNames.FAILED));
 
     List<MockSpan> workflowFirstRunChildren = spansHelper.getByParentSpan(workflowFirstRunSpan);
     assertEquals(1, workflowFirstRunChildren.size());