TraceEnter is instrumented on async methods BEFORE the LogicalCallContext is updated

[ndrwrbgs]

https://github.com/csnemes/tracer/issues/43#issuecomment-289994952 ^ true that

If the instrumentation code is logically meant to be embedded at the { of async methods, it would be expected that the LogicalCallContext (like AsyncLocal in .NET 4.6) would have been scoped to that. However, it seems in the IL the instrumentation happens before the call off to the state machine, meaning that users who expect to be in a nested LogicalCallContext at time of { are still in the caller method's ExecutionContext.

I think the only way to achieve this is to not instrument async methods themselves, (let them do their state machine stuff) but add the TraceEnter call inside the generated state machine's MoveNext(), inside the main try, immediately after the locloc, brfalse, br.s commands that are 'restoring the state machine'.

Perhaps this makes sense given the work you recently did with #81? (I give a proposal above but I admittedly know very little about the Cecil interactions so I'm hoping the proposal makes more sense to you than it does to me :-) )

[csnemes]

I see the problem, managed to reproduce it, but fixing won't be easy. have to somehow figure out the link between the method's input argument and the generated state machine fields.

[ndrwrbgs]

Having realized that tracer essentially just becomes "full AOP in C#" once this is fixed, I found this other library. Unfortunately, they have the same problem :-P https://github.com/vescon/MethodBoundaryAspect.Fody/issues/5

[ndrwrbgs]

https://github.com/Fody/AsyncErrorHandler this may provide some help for this

[csnemes]

Thanks. I take a look on that.

[ndrwrbgs]

I worked on this this weekend and was able to get a POC working -- for async methods we want to instrument 'enter' on the first call to the MoveNext method of the generated state machine (when <>_state is -1), and for 'exit' the best I could do -- since sometimes the end of the state machine method is never actually hit (think where the SetResult() actually triggers the ending of the program) was to wrap the return value of the parent method (the Task) with a ContinueWith(() => ) kind of call -- in my solution I actually did this and left the 'exit' which was also instrumented in the MoveNext (but skipped over during normal state machine continuations except finish), I added the ContinueWith so that the end of the method WAS ALWAYS HIT, but I think that doing it purely in the ContinueWith would probably be a better solution.

Just some notes in case you look into this before I manage to ship anything.

[csnemes]

I came almost to the same conclusion. The exit part is already working (at least it supposed to), Fody piggybacks on the SetResult and SetException to find the logical return point (its in the AsyncmethodWeaver.cs). For the entry data the idea is the same as you mentioned at the beginning of the MoveNext add a state check and if its the first call log the data. Although the method entry parameters are reflected in the state machine's fields I'd rather inject them using my own fields. I hope I can finish the POC this week and see if it works.

[csnemes]

I've managed to add the trace enter logging into the state machine (start of MoveNext). I'm still fighting with a PEVerify error (although the rewritten assembly works, I'm more confident if there are no PEVerify errors around). One strange thing is that the order of entry and exit calls don't follow the expected logic if the first statement in a method is an await. Instead of External Enter, Internal Enter, Internal Leave, External Leave I get Internal Enter, Internal Leave, External Enter, External Leave.

[csnemes]

check out 3.2. It should now work as expected.

[ndrwrbgs]

Seems fixed! For some crazy reason I haven't saved a whole test suite to be used :-S but I'll reach back out if any edge cases are found!

BTW thank you so much! This is a great achievement in observability during local/console development!

[ndrwrbgs]

Wonderful, it even handles the case some other libraries missed of instrumenting the state machine when I put the TraceOn attribute on the method! <3