Java Code Examples for com.nike.wingtips.Span#getSpanStartTimeEpochMicros()

private void verifyServerOverallSpanAnnotations(
    DtConfigAdjustments dtConfig,
    Span span,
    boolean endpointAnnotationsAlwaysMissing,
    boolean isDownstreamServerAndErrorOccurred
) {
    AtomicInteger expectedTotalNumAnnotations = new AtomicInteger(0);
    AtomicLong minAnnotationTimestamp = new AtomicLong(span.getSpanStartTimeEpochMicros());

    verifySpanAnnotation(
        span,
        dtConfig.wireReceiveStartAnnotationName,
        dtConfig.shouldAddWireReceiveStartAnnotation,
        expectedTotalNumAnnotations,
        minAnnotationTimestamp
    );

    verifySpanAnnotation(
        span,
        dtConfig.wireReceiveFinishAnnotationName,
        dtConfig.shouldAddWireReceiveFinishAnnotation,
        expectedTotalNumAnnotations,
        minAnnotationTimestamp
    );

    boolean expectEndpointStart = !endpointAnnotationsAlwaysMissing
                                  && dtConfig.shouldAddEndpointStartAnnotation;
    boolean expectEndpointFinish = !endpointAnnotationsAlwaysMissing
                                   && dtConfig.shouldAddEndpointFinishAnnotation;
    verifySpanAnnotation(
        span,
        dtConfig.endpointStartAnnotationName,
        expectEndpointStart,
        expectedTotalNumAnnotations,
        minAnnotationTimestamp
    );

    verifySpanAnnotation(
        span,
        dtConfig.endpointFinishAnnotationName,
        expectEndpointFinish,
        expectedTotalNumAnnotations,
        minAnnotationTimestamp
    );

    boolean expectErrorAnnotation = isDownstreamServerAndErrorOccurred && dtConfig.shouldAddErrorAnnotationForCaughtException;

    verifySpanAnnotation(
        span,
        dtConfig.errorAnnotationName,
        expectErrorAnnotation,
        expectedTotalNumAnnotations,
        minAnnotationTimestamp
    );

    verifySpanAnnotation(
        span,
        dtConfigAdjustments.wireSendStartAnnotationName,
        dtConfigAdjustments.shouldAddWireSendStartAnnotation,
        expectedTotalNumAnnotations,
        minAnnotationTimestamp
    );

    verifySpanAnnotation(
        span,
        dtConfig.wireSendFinishAnnotationName,
        dtConfig.shouldAddWireSendFinishAnnotation,
        expectedTotalNumAnnotations,
        minAnnotationTimestamp
    );

    // Connection start/finish annotations shouldn't exist for server overall spans.
    verifySpanAnnotation(
        span,
        dtConfig.connStartAnnotationName,
        false,
        expectedTotalNumAnnotations,
        minAnnotationTimestamp
    );

    verifySpanAnnotation(
        span,
        dtConfig.connFinishAnnotationName,
        false,
        expectedTotalNumAnnotations,
        minAnnotationTimestamp
    );

    assertThat(span.getTimestampedAnnotations()).hasSize(expectedTotalNumAnnotations.get());
}
 

@Test
public void startTrace_creates_trace_from_parent_if_available_and_sets_expected_span_name_and_tags_and_annotations() {
    // given
    String parentTraceId = UUID.randomUUID().toString();
    String parentParentSpanId = UUID.randomUUID().toString();
    String parentSpanId = UUID.randomUUID().toString();
    String parentSpanName = UUID.randomUUID().toString();
    String parentTraceEnabled = "true";
    String parentUserId = UUID.randomUUID().toString();
    httpRequest.headers().set(TraceHeaders.TRACE_ID, parentTraceId);
    httpRequest.headers().set(TraceHeaders.PARENT_SPAN_ID, parentParentSpanId);
    httpRequest.headers().set(TraceHeaders.SPAN_ID, parentSpanId);
    httpRequest.headers().set(TraceHeaders.SPAN_NAME, parentSpanName);
    httpRequest.headers().set(TraceHeaders.TRACE_SAMPLED, parentTraceEnabled);
    httpRequest.headers().set(USER_ID_HEADER_KEY, parentUserId);

    assertThat(Tracer.getInstance().getCurrentSpan(), nullValue());

    // when
    long nanosBefore = System.nanoTime();
    handler.startTrace(httpRequest, ctxMock);
    long nanosAfter = System.nanoTime();

    // then
    Span span = Tracer.getInstance().getCurrentSpan();
    assertThat(span.getTraceId(), is(parentTraceId));
    assertThat(span.getParentSpanId(), is(parentSpanId));
    assertThat(span.getSpanId(), notNullValue());
    assertThat(span.getSpanId(), not(parentSpanId));
    assertThat(span.getSpanName(), is(initialSpanNameFromStrategy.get()));
    assertThat(span.getUserId(), is(parentUserId));
    assertThat(span.isSampleable(), is(Boolean.valueOf(parentTraceEnabled)));

    strategyInitialSpanNameArgs.get().verifyArgs(requestInfoMock, tagAndNamingAdapterMock);
    strategyRequestTaggingArgs.get().verifyArgs(span, requestInfoMock, tagAndNamingAdapterMock);

    long expectedMaxWireReceiveStartTimestamp =
        span.getSpanStartTimeEpochMicros() + TimeUnit.NANOSECONDS.toMicros(nanosAfter - nanosBefore);
    TimestampedAnnotation wireReceiveStartAnnotation = findAnnotationInSpan(span, "wr.start");
    Assertions.assertThat(wireReceiveStartAnnotation.getTimestampEpochMicros())
              .isBetween(span.getSpanStartTimeEpochMicros(), expectedMaxWireReceiveStartTimestamp);
}
 

@DataProvider(value = {
    "true   |   true",
    "true   |   false",
    "false  |   true",
    "false  |   false"
}, splitBy = "\\|")
@Test
public void startTrace_creates_new_trace_if_no_parent_available_and_sets_expected_span_name_and_tags_and_annotations(
    boolean addWireReceiveStartAnnotation, boolean stateIsNull
) {
    // given
    assertThat(Tracer.getInstance().getCurrentSpan(), nullValue());
    shouldAddWireReceiveStartAnnotation = addWireReceiveStartAnnotation;
    if (stateIsNull) {
        doReturn(null).when(stateAttributeMock).get();
    }

    DTraceStartHandler handlerSpy = spy(handler);

    RiposteHandlerInternalUtil handlerUtilSpy = spy(new RiposteHandlerInternalUtil());
    Whitebox.setInternalState(handlerSpy, "handlerUtils", handlerUtilSpy);

    String fallbackSpanName = "fallback-span-name-" + UUID.randomUUID().toString();
    doReturn(fallbackSpanName).when(handlerUtilSpy).determineFallbackOverallRequestSpanName(any());

    String expectedSpanName = (stateIsNull) ? fallbackSpanName : initialSpanNameFromStrategy.get();

    // when
    long nanosBefore = System.nanoTime();
    handlerSpy.startTrace(httpRequest, ctxMock);
    long nanosAfter = System.nanoTime();

    // then
    Span span = Tracer.getInstance().getCurrentSpan();
    assertThat(span.getTraceId(), notNullValue());
    assertThat(span.getParentSpanId(), nullValue());
    assertThat(span.getSpanId(), notNullValue());
    assertThat(span.getSpanName(), is(expectedSpanName));
    assertThat(span.getUserId(), nullValue());

    if (!stateIsNull) {
        strategyInitialSpanNameArgs.get().verifyArgs(requestInfoMock, tagAndNamingAdapterMock);
        strategyRequestTaggingArgs.get().verifyArgs(span, requestInfoMock, tagAndNamingAdapterMock);
    }

    if (addWireReceiveStartAnnotation) {
        long expectedMaxWireReceiveStartTimestamp =
            span.getSpanStartTimeEpochMicros() + TimeUnit.NANOSECONDS.toMicros(nanosAfter - nanosBefore);
        TimestampedAnnotation wireReceiveStartAnnotation = findAnnotationInSpan(
            span, distributedTracingConfig.getServerSpanNamingAndTaggingStrategy().wireReceiveStartAnnotationName()
        );
        Assertions.assertThat(wireReceiveStartAnnotation.getTimestampEpochMicros())
                  .isBetween(span.getSpanStartTimeEpochMicros(), expectedMaxWireReceiveStartTimestamp);
    }
}
 

@Override
public void spanCompleted(Span wingtipsSpan) {
    try {
        String operationName = wingtipsSpan.getSpanName();
        long startTimeMicros = wingtipsSpan.getSpanStartTimeEpochMicros();

        // Given we should only be in this method on span completion, we are not going to wrap this conversion in a
        // try/catch. duration should be set on the Wingtips span.
        long durationMicros = TimeUnit.NANOSECONDS.toMicros(wingtipsSpan.getDurationNanos());
        long stopTimeMicros = startTimeMicros + durationMicros;

        // Sanitize the wingtips trace/span/parent IDs if necessary. This guarantees we can convert them to
        //      longs as required by LightStep.
        String wtSanitizedSpanId = sanitizeIdIfNecessary(wingtipsSpan.getSpanId(), false);
        String wtSanitizedTraceId = sanitizeIdIfNecessary(wingtipsSpan.getTraceId(), true);
        String wtSanitizedParentId = sanitizeIdIfNecessary(wingtipsSpan.getParentSpanId(), false);

        // Handle the common SpanBuilder settings.
        SpanBuilder lsSpanBuilder = (SpanBuilder) (
            tracer.buildSpan(operationName)
                  .withStartTimestamp(wingtipsSpan.getSpanStartTimeEpochMicros())
                  .ignoreActiveSpan()
                  .withTag("wingtips.span_id", wingtipsSpan.getSpanId())
                  .withTag("wingtips.trace_id", wingtipsSpan.getTraceId())
                  .withTag("wingtips.parent_id", String.valueOf(wingtipsSpan.getParentSpanId()))
                  .withTag("span.type", wingtipsSpan.getSpanPurpose().name())
        );

        // Force the LightStep span to have a Trace ID and Span ID matching the Wingtips span.
        //      NOTE: LightStep requires Ids to be longs, so we convert the sanitized wingtips trace/span IDs.
        long lsSpanId = TraceAndSpanIdGenerator.unsignedLowerHexStringToLong(wtSanitizedSpanId);
        long lsTraceId = TraceAndSpanIdGenerator.unsignedLowerHexStringToLong(wtSanitizedTraceId);
        lsSpanBuilder.withTraceIdAndSpanId(lsTraceId, lsSpanId);

        // Handle the parent ID / parent context SpanBuilder settings.
        if (wingtipsSpan.getParentSpanId() != null) {
            long lsParentId = TraceAndSpanIdGenerator.unsignedLowerHexStringToLong(wtSanitizedParentId);

            SpanContext lsSpanContext = new SpanContext(lsTraceId, lsParentId);

            lsSpanBuilder = (SpanBuilder)(lsSpanBuilder.asChildOf(lsSpanContext));
        }

        // Start the OT span and set logs and tags from the wingtips span.
        io.opentracing.Span lsSpan = lsSpanBuilder.start();

        for (Span.TimestampedAnnotation wingtipsAnnotation : wingtipsSpan.getTimestampedAnnotations()) {
            lsSpan.log(wingtipsAnnotation.getTimestampEpochMicros(), wingtipsAnnotation.getValue());
        }

        for (Map.Entry<String, String> wtTag : wingtipsSpan.getTags().entrySet()) {
            lsSpan.setTag(wtTag.getKey(), wtTag.getValue());
        }

        // Add some custom boolean tags if any of the IDs had to be sanitized. The raw unsanitized ID will be
        //      available via the wingtips.*_id tags.
        if (!wtSanitizedSpanId.equals(wingtipsSpan.getSpanId())) {
            lsSpan.setTag("wingtips.span_id.invalid", true);
            wingtipsSpan.putTag("sanitized_span_id", wtSanitizedSpanId);
        }
        if (!wtSanitizedTraceId.equals(wingtipsSpan.getTraceId())) {
            lsSpan.setTag("wingtips.trace_id.invalid", true);
            wingtipsSpan.putTag("sanitized_trace_id", wtSanitizedTraceId);
        }
        if (wtSanitizedParentId != null && !wtSanitizedParentId.equals(wingtipsSpan.getParentSpanId())) {
            lsSpan.setTag("wingtips.parent_id.invalid", true);
            wingtipsSpan.putTag("sanitized_parent_id", wtSanitizedParentId);
        }

        // on finish, the tracer library initialized on the creation of this listener will cache and transport the span
        // data to the LightStep Satellite.
        lsSpan.finish(stopTimeMicros);
    } catch (Exception ex) {
        long currentBadSpanCount = spanHandlingErrorCounter.incrementAndGet();
        // Adopted from WingtipsToZipkinLifecycleListener from Wingtips-Zipkin2 plugin.
        // Only log once every MIN_SPAN_HANDLING_ERROR_LOG_INTERVAL_MILLIS time interval to prevent log spam from a
        // malicious (or broken) caller.
        long currentTimeMillis = System.currentTimeMillis();
        long timeSinceLastLogMsgMillis = currentTimeMillis - lastSpanHandlingErrorLogTimeEpochMillis;

        if (timeSinceLastLogMsgMillis >= MIN_SPAN_HANDLING_ERROR_LOG_INTERVAL_MILLIS) {
            // We're not synchronizing the read and write to lastSpanHandlingErrorLogTimeEpochMillis, and that's ok.
            // If we get a few extra log messages due to a race condition it's not the end of the world - we're
            // still satisfying the goal of not allowing a malicious caller to endlessly spam the logs.
            lastSpanHandlingErrorLogTimeEpochMillis = currentTimeMillis;

            lightStepToWingtipsLogger.warn(
                    "There have been {} spans that were not LightStep compatible, or that experienced an error "
                    + "during span handling. Latest example: "
                    + "wingtips_span_with_error=\"{}\", conversion_or_handling_error=\"{}\"",
                    currentBadSpanCount, wingtipsSpan.toKeyValueString(), ex.toString()
            );
        }
    }
}