I am having troubles using the tracer bullet in my...

# http4k

[Marco Garofalo]

I am having troubles using the tracer bullet in my tests, I have just 2 actors the "app" and the "player", the generated diagram has all the interactions i expect but the name of the "app" actor seems to be blank, any idea why? Here's the code I have added. https://github.com/th3n3rd/http4k-playground/commit/712d7f7da041c618dfbaa79c50bc5510e57d96af

[dave]

It looks ok on the surface - but I'm afraid it's impossible to run the tests on that branch as it doesn't compile and there are no instructions on how to make it generate the jooq classes. I suggest that you try to run the tests with events.and(::println) to see what is coming out in the metadata

[Marco Garofalo]

Interesting, the JOOQ classes are generated at compile time, a simple ./mvnw clean compile or even ./mvnw clean test just works.

[Marco Garofalo]

Btw the println doesn't seem to help, or maybe I put it in the wrong place:

object NameEvents {
    operator fun invoke(actorName: String, events: Events) = AddZipkinTraces()
        .then(AddServiceName(actorName))
        .then(events)
        .and(::println)
}

Is basically printing kind of raw events (Incoming, Outgoing)

Incoming(uri=/players, method=POST, status=201 Created, latency=160, xUriTemplate=players)
Outgoing(uri=/players, method=POST, status=201 , latency=194, xUriTemplate=players)
Incoming(uri=/games, method=POST, status=201 Created, latency=192, xUriTemplate=games)
Outgoing(uri=/games, method=POST, status=201 , latency=194, xUriTemplate=games)
...

[dave]

Try it inside the then

[Marco Garofalo]

object NameEvents {
    operator fun invoke(actorName: String, events: Events) = AddZipkinTraces()
        .then(AddServiceName(actorName))
        .then(events.and(::println))
}

Yeah that worked:

MetadataEvent(event=Incoming(uri=/players, method=POST, status=201 Created, latency=159, xUriTemplate=players), metadata={traces=ZipkinTraces(traceId=TraceId(value=aba9b99fd918c0a7), spanId=TraceId(value=f92f5ed8e9aa1232), parentSpanId=TraceId(value=04b0d2ca2574003b), samplingDecision=SamplingDecision(value=1)), service=app})
MetadataEvent(event=Outgoing(uri=/players, method=POST, status=201 , latency=192, xUriTemplate=players), metadata={traces=ZipkinTraces(traceId=TraceId(value=aba9b99fd918c0a7), spanId=TraceId(value=f92f5ed8e9aa1232), parentSpanId=TraceId(value=04b0d2ca2574003b), samplingDecision=SamplingDecision(value=1)), service=player})
MetadataEvent(event=Incoming(uri=/games, method=POST, status=201 Created, latency=192, xUriTemplate=games), metadata={traces=ZipkinTraces(traceId=TraceId(value=aba9b99fd918c0a7), spanId=TraceId(value=36418ad95a2f56d7), parentSpanId=TraceId(value=04b0d2ca2574003b), samplingDecision=SamplingDecision(value=1)), service=app})
MetadataEvent(event=Outgoing(uri=/games, method=POST, status=201 , latency=194, xUriTemplate=games), metadata={traces=ZipkinTraces(traceId=TraceId(value=aba9b99fd918c0a7), spanId=TraceId(value=36418ad95a2f56d7), parentSpanId=TraceId(value=04b0d2ca2574003b), samplingDecision=SamplingDecision(value=1)), service=player})
MetadataEvent(event=Incoming(uri=/games/f48f1650-adc5-4e19-8b77-1ba45f5bfcbc, method=GET, status=200 OK, latency=66, xUriTemplate=games/{id}), metadata={traces=ZipkinTraces(traceId=TraceId(value=aba9b99fd918c0a7), spanId=TraceId(value=4e229b1d4b84cd60), parentSpanId=TraceId(value=04b0d2ca2574003b), samplingDecision=SamplingDecision(value=1)), service=app})

[dave]

what does the diagram look like? you can export it from idea

[Marco Garofalo]

@startuml
title JourneyTests - winning gameplay
participant "player"
participant ""
"player" -> "": POST players
activate ""

"" -[#DarkGreen]> "player": <color:DarkGreen> 201 
deactivate ""
"player" -> "": POST games
activate ""

"" -[#DarkGreen]> "player": <color:DarkGreen> 201 
deactivate ""
"player" -> "": GET games/f48f1650-adc5-4e19-8b77-1ba45f5bfcbc
activate ""

"" -[#DarkGreen]> "player": <color:DarkGreen> 200 
deactivate ""
"player" -> "": POST games/f48f1650-adc5-4e19-8b77-1ba45f5bfcbc/guesses
activate ""

"" -[#DarkGreen]> "player": <color:DarkGreen> 201 
deactivate ""
"player" -> "": GET games/f48f1650-adc5-4e19-8b77-1ba45f5bfcbc
activate ""

"" -[#DarkGreen]> "player": <color:DarkGreen> 200 
deactivate ""
"player" -> "": POST games/f48f1650-adc5-4e19-8b77-1ba45f5bfcbc/guesses
activate ""

"" -[#DarkGreen]> "player": <color:DarkGreen> 201 
deactivate ""
"player" -> "": GET games/f48f1650-adc5-4e19-8b77-1ba45f5bfcbc
activate ""

"" -[#DarkGreen]> "player": <color:DarkGreen> 200 
deactivate ""
"player" -> "": POST games/f48f1650-adc5-4e19-8b77-1ba45f5bfcbc/guesses
activate ""

"" -[#DarkGreen]> "player": <color:DarkGreen> 201 
deactivate ""
"player" -> "": GET games/f48f1650-adc5-4e19-8b77-1ba45f5bfcbc
activate ""

"" -[#DarkGreen]> "player": <color:DarkGreen> 200 
deactivate ""
@enduml

[Marco Garofalo]

For some reason the "app" seems to stay empty.

[Marco Garofalo]

manually fixing the empty to "app" generates a valid diagram

[dave]

ok - the problem here is that you aren't calling http://app/players

[dave]

The service name only works for outbound traces

[dave]

because the tracer uses the outbound call (from the player) to thread together the traces

[dave]

the inbound calls aren't used at all which is why the actors are required

[Marco Garofalo]

But then what's the point of having traces?

[Marco Garofalo]

Meaning that the incoming should "match" the outgoing trace

[dave]

yes - the marrying up isn't currently done by matching up the inbound and outbound

[dave]

we could try and adjust the algorithm to match those up. We generally add both in order to just get an entire picture of what is going on

[Marco Garofalo]

I see that's why you have the internal reverse proxy in the website examples?

[dave]

The API gateway is there in order to just show how it could look, but yes - currently the host name in the URL needs to match the name of the service it is calling.

[dave]

The fix to the algorithm would need to be made in the Http Tracer code:

fun HttpTracer(actorFrom: ActorResolver) = Tracer { eventNode, tracer ->
    eventNode
        .takeIf { it.event.event is HttpEvent.Outgoing }
        ?.toTrace(actorFrom, tracer)
        ?.let(::listOf) ?: emptyList()
}

private fun EventNode.toTrace(actorFrom: ActorResolver, tracer: Tracer): Trace {
    val parentEvent = event.event as HttpEvent.Outgoing

    return RequestResponse(
        actorFrom(event),
        Actor(parentEvent.uri.host, System),
        parentEvent.method.name + " " + parentEvent.xUriTemplate,
        parentEvent.status.toString(),
        children.flatMap { tracer(it, tracer) }
    )
}

[dave]

specifically where the actor for the call is made:

Actor(parentEvent.uri.host, System)

[Ivan Pavlov]

Just to let you know, I've faced the similar problem in my playground and would love to get any news if/when the current approach is changed.
My desired outcome was different from what is shown in documentation and examples, so I adjusted client/server filters and tracer.

For Incoming filter (Server), I added a filter to ensure that incoming request leads to new span creation, so that each HttpHandler I want to treat as a separate service in test produces its own span:

fun InChildSpan(storage: ZipkinTracesStorage = ZipkinTracesStorage.THREAD_LOCAL) = Filter { next ->
    { req ->
        storage.inChildSpan { updated ->
            next(ZipkinTraces(updated, req))
        }
    }
}

For outgoing filter (Client), I actually reused org.http4k.filter.ServerFilters.RequestTracing instead of org.http4k.filter.ClientFilters#RequestTracing.
Then for matching requests and responses I modified EventNode.toTrace like this:

val matchingIncomingServiceActor = children
        .find { it.event.event is HttpEvent.Incoming }
        ?.let { actorFrom(it.event) }

    return RequestResponse(
        actorFrom(event),
        matchingIncomingServiceActor ?: Actor(parentEvent.uri.host, ActorType.System),

I suspect I might be doing something in the wrong direction, but in my case it worked well, so I decided to share it here

[dave]

@Ivan Pavlov this approach is actually the reverse of the design of distributed tracing AFAIK - spans are rolled on the outgoing instead of the incoming call. It will work for the diagrams for sure, but any instrumentation tooling might give you strange results

[dave]

The piece of code that needs to also be adjusted is the TracerBullet and how it recursively creates the tree of events. We'll gratefully accept contributions to fix it! 😉

[Ivan Pavlov]

I'll definitely take a look there and check if I can fix it 🙂

[dave]

I've managed to fix this so the tracing will be working as expected as soon as the new release 5.14.4.0 is available in maven central. We now take the service name from the matching incoming event. It was a little tricky because the incoming event shares the same traces as the outgoing (so technically it's not a "child" per se).

This means you can remove your hack @Ivan Pavlov. Also - note that there have been tweaks to the tracing example, so the RequestTracing filter is now applied before the transaction is reported. This is the proper ordering for these filters anyway in order to record the correct distributed tracing spans.

fun ClientStack(events: Events) = ClientFilters.RequestTracing()
    .then(ReportHttpTransaction { events(Outgoing(it)) })

Note that this change also means that we should now be able to reverse-engineer a set of traces from a collective log source (such as datadog or newrelic) and generate an entire trace diagram from it. I might look at adding something to the toolbox to cover this.

[Ivan Pavlov]

Thanks for letting me know @dave! I'll migrate my code to the latest version when it's available.
I had a chance to take a look at the source code yesterday and also noticed that official documentation provides a wrong example.
I understand that it could be actually tricky because EventNode concept is based on events relationship combined with spans relationship, so all events on the same level inherit the same children set and Incoming is not a child of Outgoing.

Also, I have a question regarding Span and Trace uniqueness. From what I could find in docs, spans are treated as a single piece of work within the trace. This test confused me a bit because different traces are connected via spans relationship org.http4k.tracing.TracerBulletExtraTest#traces can be grouped. If there is parentSpan from another trace, shouldn't it be considered as a different hierarchy in org.http4k.tracing.TracerBulletKt#buildTree?

[dave]

@Ivan Pavlov it's possible that that test isn't right. TBH, I use the TracerBulletTest as the benchmark and that's what I used to confirm the new behaviour

[dave]

Basically for every piece of work (aka line) that you want to represent on the diagram, you need a new trace (storage.inChildSpan {} )- be that a DB call an HTTP call or a sent message.

[Ivan Pavlov]

I get it, thanks. I suspect the test is not correct, but the tree building algorithm is not fully correct too because it does not respect different traces for events. Maybe it's worth fixing too 🙂

[dave]

agreed - it's not fully fully correct, but IRL the risk is small because of the generation of the random trace ids is known (and especially in the tests for which we are creating diagrams primarily). Feel free to PR a fix for it though - the tests will pick up the change correctly 🙂

[Ivan Pavlov]

I've opened a PR with a small change for grouping by traceId before building the tree https://github.com/http4k/http4k/pull/1086