Custom span creation with Phobos 2.0.3-beta1

[object]

I created a small repo to demonstrate the issues I am desciribing below: https://github.com/object/AkkaWinTailWithPhobos

The repo is using WinTail sample from Akka.NET Bootcamp.

On start the root actor (ConsoleReader) receives a message "start" followed by user input.

User input in all tests consist of 4 strings: 123 456 7890 exit

1. Default span creation (create-trace-upon-receive = on)

Total spans: 7

akka.msg.recv start
    akka.msg.recv 123
    akka.msg.recv continue
        akka.msg.recv 456
        akka.msg.recv continue
        akka.msg.recv 7890
            akka.msg.recv continue

This behavior is by design and can be replaced with manual span creation feature introduced in Phobos 2.0.3.

2. No span creation (create-trace-upon-receive = off)

ConsoleReader: No StartActiveSpan ConsoleWriter: No StartActiveSpan

Total spans: 1

akka.msg.recv start Issues:

• Why is the root span still created? Shouldn't all span creation be controlles by the application code?

3. Manual span creation (create-trace-upon-receive = off)

ConsoleReader: StartActiveSpan("ReadText", SpanKind.Consumer, Context.GetInstrumentation().UsableContext ?? default) ConsoleWriter: StartActiveSpan("WriteText", SpanKind.Consumer, Context.GetInstrumentation().UsableContext ?? default)

Total spans: 7

akka.msg.recv start
    ReadText 123
    WriteText 123
    ReadText 456
    WriteText 456
    ReadText 7890
    WriteText 7890

Issues:

• Same as previous one. Why is the root span still created?

In addition I would like to create ConsoleWriter spans as child spans for ConsoleReader, this is attempted in the next test.

4. Manual span creation (create-trace-upon-receive = off)

ConsoleReader: StartActiveSpan("ReadText", SpanKind.Consumer, Context.GetInstrumentation().UsableContext ?? default) ConsoleWriter: StartActiveSpan("WriteText", SpanKind.Consumer, Context.GetInstrumentation().ActiveSpan)

Total spans: 4 Total spans: 1 Total spans: 1 Total spans: 1

akka.msg.recv start
    ReadText 123
    ReadText 456
    ReadText 7890
WriteText 123
WriteText 456
WriteText 7890

Issues:

• Even though I try to set explicitly parent span for ConsoleWriter, all its spans are created as root spans.

[Aaronontheweb]

• Why is the root span still created? Shouldn't all span creation be controlles by the application code?

ah, I think I know why this is - actor lifecycle tracing is still on. Guess I need to have that implicitly disabled when automatic span creation is turned off.

[Aaronontheweb]

either that or instruct users to turn both off at the same time.

[object]

@Aaronontheweb No, I disable actor lifecycle tracing in this example:

trace-actor-lifecycle = off

Also, the root span that is still created doesn't trace lifecycle, it it created for incoming message (akka.msg.recv), so apparently it is something else.

[Aaronontheweb]

That's a relief - in this case, this is still a bug in our implementation then. We're about to push a 2.0.3 that addresses https://github.com/petabridge/phobos-issues/issues/57 - I'll take another stab at fixing this once that's pushed.

[object]

@Aaronontheweb Do you have an ETA for this fix? Let me know if you need to validate the fix candidate.

[Aaronontheweb]

No ETA yet, been bogged down on a very weird Akka.Cluster.Sharding issue but I'll start looking into this tonight.

[Aaronontheweb]

Thanks @object - I've run your sample and there are definitely some bugs in Phobos here. I'll get cracking on those. Should have an ETA soon.

[Aaronontheweb]

• Same as previous one. Why is the root span still created?

This is fixed - forgot to add an if statement to check to see if create-trace-upon-receive = on when an actor receives a message that has no active trace associated with it.

[Aaronontheweb]

This is what I get now using the following C#

public sealed class WriterActor : ReceiveActor
{
private IActorRef _testActor;
public IPhobosActorContext Instrumentation => Context.GetInstrumentation();

public WriterActor(IActorRef testActor)
{
    _testActor = testActor;

    Receive<string>(str =>
    {
        using var mySpan = Instrumentation.Tracer.StartActiveSpan("WriteText", SpanKind.Consumer, Instrumentation.UsableContext ?? default);
        mySpan.SetAttribute("myText", str);
        _testActor.Tell(str);
    });
}
}

public sealed class ReaderActor : ReceiveActor
{
public IPhobosActorContext Instrumentation => Context.GetInstrumentation();
private readonly IActorRef _writerActor;

public ReaderActor(Stack<string> inputs, IActorRef writerActor)
{
    Inputs = inputs;
    _writerActor = writerActor;

    Receive<StartLoop>(_ =>
    {
        using var mySpan = Instrumentation.Tracer.StartActiveSpan("StartLoop", SpanKind.Consumer, Instrumentation.UsableContext ?? default);
        while(Inputs.TryPop(out var result))
            Self.Tell(result);
    });

    Receive<string>(str =>
    {
        using var mySpan = Instrumentation.Tracer.StartActiveSpan("ReadText", SpanKind.Consumer, Instrumentation.UsableContext ?? default);
        mySpan.SetAttribute("myText", str);

        _writerActor.Tell(str);
    });
}

protected override void PreStart()
{
    Self.Tell(StartLoop.Instance);
}

public Stack<string> Inputs { get; }

public sealed class StartLoop
{
    public static readonly StartLoop Instance = new StartLoop();
    private StartLoop(){}
}
}

sequenceDiagram
Nobody->>Nobody: StartLoop
Note over Nobody,Nobody: SpanIndex: 0<br/>ParentIndex: none<br/>
Nobody->>Nobody: ReadText
Note over Nobody,Nobody: SpanIndex: 1<br/>ParentIndex: 0<br/>Tags: <br/>&nbsp;&nbsp;myText: 4<br/>
Nobody->>Nobody: ReadText
Note over Nobody,Nobody: SpanIndex: 2<br/>ParentIndex: 0<br/>Tags: <br/>&nbsp;&nbsp;myText: 3<br/>
Nobody->>Nobody: ReadText
Note over Nobody,Nobody: SpanIndex: 3<br/>ParentIndex: 0<br/>Tags: <br/>&nbsp;&nbsp;myText: 2<br/>
Nobody->>Nobody: ReadText
Note over Nobody,Nobody: SpanIndex: 4<br/>ParentIndex: 0<br/>Tags: <br/>&nbsp;&nbsp;myText: 1<br/>
Nobody->>Nobody: WriteText
Note over Nobody,Nobody: SpanIndex: 5<br/>ParentIndex: 1<br/>Tags: <br/>&nbsp;&nbsp;myText: 4<br/>
Nobody->>Nobody: WriteText
Note over Nobody,Nobody: SpanIndex: 6<br/>ParentIndex: 2<br/>Tags: <br/>&nbsp;&nbsp;myText: 3<br/>
Nobody->>Nobody: WriteText
Note over Nobody,Nobody: SpanIndex: 7<br/>ParentIndex: 3<br/>Tags: <br/>&nbsp;&nbsp;myText: 2<br/>
Nobody->>Nobody: WriteText
Note over Nobody,Nobody: SpanIndex: 8<br/>ParentIndex: 4<br/>Tags: <br/>&nbsp;&nbsp;myText: 1<br/>

[Aaronontheweb]

All write operations are correlated with reads here using method 2 on your chart, which is the right way to do this. Would that approach work for you @object ?

[object]

@Aaronontheweb Looks promising. Can you push a prerelease of 2.0.4 version of Phobos so I can also run some tests?

[Aaronontheweb]

I'm going to push 2.0.4 for real later today once I have a fix in-place for https://github.com/petabridge/phobos-issues/issues/59

[Aaronontheweb]

Phobos 2.0.4 is now live and should help resolve this issue: https://phobos.petabridge.com/articles/releases/RELEASE_NOTES.html#204httpssdkbincompublisherpetabridgeproductphobospackagesphobosactorversions204-june-02-2022

Give that a try and let us know if that solution works better for you.

[object]

@Aaronontheweb yes, this seems to work much better, perhaps this is what we need. But I need to run more complicated scenarios to conclude.

Just to clarify how to create a child span. I noticed that if I try to create a new span as a child of a current span, like this:

var parentSpan = Context.GetInstrumentation().ActiveSpan;
using var mySpan = Context.GetInstrumentation().Tracer.StartActiveSpan("WriteText", SpanKind.Consumer, parentSpan);

it's a root span that gets created, because if I inspect Context.GetInstrumentation().ActiveSpan I can see that its ID is null. That means that if I choose to use UsableContext, I can no longer rely on OpenTelemetry ActiveSpan API, right? So UsableContext becomes an active span. We can live with it though it makes the API experience somewhat weird: certain OTel API methods are replaced with custom Phobos calls. I want to mention this because if there are others who will also prefer our way of creating trace spans in Akka, it might be worth to offer an OpenTelemetry compliant API for such usage so calling instrumentation.ActiveSpan will work as expected. Of course I don't know how feasible is this.

[Aaronontheweb]

hi @object ,

so you need to use UsableContext because there is no TelemetrySpan transmitted via message to the actors - only the SpanContext. This is done for primarily for location transparency so remote and local spans are handled identically. Tracer.ActiveSpan worked inside actors before because we automatically created that span ;), but now that you're doing it by hand you have to use the OTel APIs the same way we do internally - by passing in the SpanContext.

You can probably write an extension method that will do this more succinctly for all actor types (doing this in GitHub, not Rider, so pardon anything that doesn't compile):

public static TelemetrySpan GetOrCreateActiveSpan(this IActorContext context, string operationName){
  var instrumentedContext = context.GetInstrumentation();
  if(instrumentedContext.ActiveSpan == default(TelemetrySpan)
    return instrumentedContext.Tracer.StartActiveSpan("WriteText", SpanKind.Consumer, instrumentedContext.UsableContext ?? default);
 return instrumentedContext.ActiveSpan;
}

You can call that from any of your actors where you want to manually control tracing output and it should simplify things quite a bit.

[object]

Thanks @Aaronontheweb. Yes, I am writing some helper methods so the code will look more succinct, similar to what you suggested. I was at first confused that there is no TelemetrySpan - because in the output trace it looks like it is. But of course this is because I am now constructing it by hand from the context. So I can fully shape span topology. Makes sense.