Implement logging

[AmadeusW]

Sometimes things go wrong and we need a good way to know what exactly happens.
The following links illustrate how we can get logging:
http://azure.microsoft.com/en-us/documentation/articles/web-sites-enable-diagnostic-log/
http://azure.microsoft.com/en-us/documentation/articles/cloud-services-dotnet-diagnostics/#virtual-machine

This is another way of getting more information (not necessarily logs) through Application Insights: http://msdn.microsoft.com/en-us/library/dn481100.aspx

[MarcinJuraszek]

I looked around a bit and have some thoughts

Application Insights
You can sent logs, exceptions, performance measurements, etc. It's possible to use one of known logging frameworks with Application Insights as target. It works with Log4Net, NLog as well as TraceListener, but I don't know how that would work with different types of events (e.g. how to log perf measurement with NLog);

The API itself is really simple and easy to use. They released a new version late last year, with TelemetryClient being the entry point to do all sort of event logging.

You get nice way to browse the logs, aggregations on numeric data, etc. Seems nice and quite usable.

Session/Request information
I don't really know what kind of information you want to gather. From my personal experience the more detailed they are the better, up to some point. The most important think imo is to have a way to correlate all logged information on two levels: session level and request level. This way you can:

1. See what's user behavior between pages
2. See what's happening when application tries to handle particular request.

I didn't find anything about stuff like this that would be built into ASP.NET. Maybe there is some library that would do that? I think it's worth looking or even writing custom solution, e.g. based on IHttpModule events.

It would be nice to have a helper class that would let you simply log an event without worrying about all that stuff. I mean you just call Log/Trace and it figures out what's the SessionId, what's the RequestId, add that with your log information and sends it to Azure.

[AmadeusW]

Application Insights looks great so far! It already helped us figure out the cause of an annoying bug -> #77

I'm familiar with log4net, but if there is a built-in way to send logs (System.Diagnostics.Trace?), I'd rather use it as the simplest method.

Do you propose that we should write to log on BeginRequest event, so that we can correlate RequestId with URL, IP and other pieces of information?

Yes, the helper class should take care of string formatting, adding a timestamp (unless we can skip this?), and as you said: SessionId and RequestId.

[MarcinJuraszek]

Yes, BeginRequest is what I was thinking about. Seems like a good place to log request information (mentioned ID, URL, Headers, etc.) as well as initialize SessionId and RequestId.

Questions are:

• how to track the session. Just using HttpContext.Session to keep track of consecutive requests?
• how to track the RequestId. HttpContext.Items?

I'm not sure if you get TimeStamp for free. I'll set a dummy ASP.NET WebPage on Azure and see how it looks like in practice - what you get for free, etc.

[AmadeusW]

I couldn't find RequestID in HttpContext.Session, HttpContext.Request nor HttpContext.Items. What would we need RequestID for? If we log begin and end of each operation, we could just use SessionID.

Some people on the internet suggest attaching a unique value to the thread. Under (probably correct) assumption that one thread handles one request only, this can be used to track the request. But it will fail in multithreaded code. Is that what you meant by initializing the RequestID?

SessionID can be found in
HttpContext.Items["AspSession"].SessionID
HttpContext.Session.SessionID
HttpContext.Request.RequestContext.HttpContext.Session.SessionID

[MarcinJuraszek]

There is nothing like this on HttpContext. I was thinking about generating a new Guid at the beginning of request and using it throughout it.

Why do I think it had value? You can correlate multiple logs into a single request and see which code was executed to handle it, what were the parameters, etc. SessionId will be the same for multiple requests as long as they are made within certain timeframe. You could try using timestamps to sort them, but what if you have two requests at nearly the same time, because user is using multiple tabs, session cookie is shared and so SessionID is shared.

Attaching value to thread would work as long you don't do multithreading stuff (you'd have to rewrite that value to all the threads you create). Definitely doable, but a bit problematic.

[AmadeusW]

You have very good points about SessionId being the same for multiple requests. I agree that we should generate our own RequestId.

I've found HttpContext as a property on the Controller class. It won't be available in other classes, so do you think that persisting RequestId within a thread would be the best solution in this case?

[MarcinJuraszek]

You can get current HttpContext outside of Controller using HttpContext.Current.

Do you have any resources about attaching information into the thread?

[AmadeusW]

either Thread.SetData or System.Web.HttpContext.Current.Items.Add (link to SO)
Probably not ThreadStaticAttribute because it would be limited to the scope of the class

If you have any resources, please share :)
I'll get back to it tomorrow. Good night!

[AmadeusW]

Currently experimenting with logging at AmadeusW/SourceBrowser, on branch logging

How is requestId stored?

        [ThreadStatic]
        private static Guid _requestId;

How logging is done?

        public static void Error(string message,
            [System.Runtime.CompilerServices.CallerMemberName] string memberName = "",
            [System.Runtime.CompilerServices.CallerFilePath] string sourceFilePath = "",
            [System.Runtime.CompilerServices.CallerLineNumber] int sourceLineNumber = 0)
        {
            string requestId = RequestUtils.GetRequestId().ToString();
            Trace.WriteLine(String.Format("[{0}, {1}] at {2}:{3} ({4}); {5}", DateTime.UtcNow, requestId, sourceFilePath, sourceLineNumber, memberName, message), CATEGORY_ERROR);
        }

addition to <configuration> in Web.config:

  <system.diagnostics>
    <trace autoflush="false" indentsize="4">
      <listeners>
        <add name="myListener" type="System.Diagnostics.TextWriterTraceListener" initializeData="TextWriterOutput.log" />
        <remove name="Default" />
      </listeners>
    </trace>
  </system.diagnostics>

I've added ApplicationInsights to the project but haven't touched the TelemetryClient yet.
portal.azure.com doesn't report the traces, and one of the difficulties of working with ApplicationInsights is that SourceBrowser is not deployed as a Website, but it runs in Virtual Machine (because we need to install MSBuild and other extras)

[MarcinJuraszek]

I don't think the fact that you're running the app on VM matters. Did you try following steps from here? You should probably also Install Application Insights Status Monitor on your web server.

About RequestId:

• How are you going to work around async/await calls? Do we have any?
• Is there any parallel processing in the codebase?