after await in an async MVC action ActivityId is not restored

[ailn]

    public async Task<ActionResult> TestProxyAsync()
    {
        var log = EventSourceImplementer.GetEventSourceAs<IAlternateEventSource>();
        using (var scope = new EventSourceProxy.EventActivityScope())
        {
            log.LogSmth("TestProxyAsync starting");

            var logic = new TheMainLogic();
            await logic.DoStuffAsync();

            log.LogSmth("TestProxyAsync finished");

            return View((object)"Very cool!!!");
        }
    }

after await the activityId will be ovewritten by 'somebody'.

[jonwagner]

Cool. Thanks for the test case. .NET is a mess with handling activity ids.

[ailn]

Yup )

[jonwagner]

The following test case passes for me. Are you using v2.0.2? If so, can you spot the difference between your code and mine?

    #region Async Tests
    public interface ILogForAsync
    {
        void Log();
    }

    public async Task TestActivityIDAsync()
    {
        var log = EventSourceImplementer.GetEventSourceAs<ILogForAsync>();

        using (var scope = new EventSourceProxy.EventActivityScope())
        {
            var before = EventActivityScope.CurrentActivityId;

            log.Log();

            await Task.Factory.StartNew(() => {});

            Assert.AreEqual(before, EventActivityScope.CurrentActivityId);
            Assert.AreEqual(before, scope.ActivityId);
        }
    }

    [Test]
    public void ActivityIDShouldRestoreAfterAwait()
    {
        TestActivityIDAsync().Wait();
    }
    #endregion

[ailn]

Try to run it from asp.net MVC controller.

[ailn]

My guess is that Trace.CorrelationManager.ActivityId is used by ASP.NET MVC and definetly by WCF infrastructure for E2E tracing, so we cannot rely on it. Instead we could directly use CallContext.LogicalSetData("EventSourceProxy.ActivityID", activityId) and CallContext.LogicalGetData("EventSourceProxy.ActivityID")

[jonwagner]

I think it would be useful if it worked with E2E tracing. By default, it would be great if the MVC/WCF Activity ID would flow through all of the logs so that you could always correlate activities.

I'd like to get a better handle on why the change to the activity id isn't captured before the await.

I think that in the worst case, I'll switch it to use a new slot, but if it's null, log Trace.CorrelationManager.ActivityId instead.

[jonwagner]

Interesting... if you add

.ConfigureAwait(false)

then the task resumes on a different thread than the original, and everything works fine. Of course, you'd lose your ASP.NET context, but it gives a good lead as to what is happening.

[jonwagner]

Alright - I checked in some changes that:

1. Keep a separate CallContext slot for the activity ID, so the framework doesn't alter it.
2. In PrepareForWriteEvent, it sets the ETW activity ID to the ESP activity, and if there isn't one, uses the Trace.CorrelationManager one.
3. When cleaning up the scope, it restores the previous ESP activity, and if there isn't one, it restores the Trace.CorrelationManager one.

I think this keeps things pretty compatible.

Please try it out.

[ailn]

Hi Jon! Thank you! I cannot try out - I'm on my vacation up to 23 of January

Regards, Andrey

Îòïðàâëåíî ñ iPhone

01 ÿíâ. 2014 ã., â 0:29, Jon Wagner notifications@github.com íàïèñàë(à):

Alright - I checked in some changes that:

Keep a separate CallContext slot for the activity ID, so the framework doesn't alter it. In PrepareForWriteEvent, it sets the ETW activity ID to the ESP activity, and if there isn't one, uses the Trace.CorrelationManager one. When cleaning up the scope, it restores the previous ESP activity, and if there isn't one, it restores the Trace.CorrelationManager one. I think this keeps things pretty compatible.

Please try it out.

— Reply to this email directly or view it on GitHub.