ASP .NET Web API: Trace Listeners: HTTP/1.1 500 Internal Server Error: What's wrong?

Question

I've been working with .NET for a little while now, but this is my first Web API 2 project. It has been a difficult struggle, so please go easy on me. There are may things about Web API that the articles out there assume to be either already known, obvious or apparent, but but are not really until you try and find out, for example, that that the "{id}" parameter is "magic" and should be used whenever possible.

Bearing that in mind, to help to troubleshoot our application further, I attempted to enable logging using Trace Listeners and NLog, using several excellent articles as guides, including the two that follow:

• Tracing in ASP.NET Web API 2
• Using NLog to provide custom tracing for your ASP.NET Web API

I am trying to get an ASP .NET Web API service to run using Trace Listeners and NLog to help us to log and timestamp critical points within the application where performance is slow.

However, when I test my controller from Fiddler, I get an exception that looks as follows:

HTTP/1.1 500 Internal Server Error
Cache-Control: no-cache
Pragma: no-cache
Content-Type: application/json; charset=utf-8
Expires: -1
Server: Microsoft-IIS/10.0
X-AspNet-Version: 4.0.30319
X-Powered-By: ASP.NET
Date: Fri, 04 Aug 2017 18:45:11 GMT
Content-Length: 3617

{"Message":"An error has occurred.",
"ExceptionMessage":"Value cannot be null.\r\nParameter name: traceWriter","ExceptionType":"System.ArgumentNullException","StackTrace":"   at System.Web.Http.Tracing.ITraceWriterExtensions.Trace(ITraceWriter traceWriter, HttpRequestMessage request, String category, TraceLevel level, String messageFormat, Object[] messageArguments)\r\n   at PURL_WebMarketing_API.Controllers.VisitorFormController.<GetFormInfo>d__3.MoveNext()\r\n--- End of stack trace from previous location where exception was thrown ---" }

I'm using Visual Studio 2015, .NET Framework 4.5, and the latest NuGet packages for NLog, ASP .NET Web API, and ASP .NET Web API Tracing.

Now for the code...

From App_Start/WebApiConfig.cs:

// Enable tracing
config.EnableSystemDiagnosticsTracing();

// Replace the default trace writer with my own custom handler
config.Services.Replace(typeof(System.Web.Http.Tracing.ITraceWriter), new Utilities.TraceHandler());

In VisitorFormController.cs:

public class VisitorFormController : ApiController
{
    private IDataAccessRepository _repository;
    private readonly ITraceWriter _tracer;


    public VisitorFormController(IDataAccessRepository repository): base()
    {
        _repository = repository;

        if (Request != null)
        {
            _tracer = Request.GetConfiguration().Services.GetTraceWriter();
        }
    }

[HttpGet]
        [Route("api/VisitorForm/{code}/{pageType}")]
        [EnableCors(origins: "*", headers: "*", methods: "options,get")]
        public async Task<IHttpActionResult> GetFormInfo(string code, string pageType)
        {
            DateTime startTime = DateTime.Now;

            if (string.IsNullOrEmpty(code))
                return BadRequest("Invitation code is required.");

            if (!IsValidPageType(pageType))
                return BadRequest("Valid page types may be 'post', 'info', 'No Code' or blank.");

            if (Request != null)
            {
                string startLogMessage = CustomLogMessageBuilder.GetLogMessage(CustomLogMessageBuilder.StandardStartEventNames.EVENT_TYPE_VISITOR_FORM_REQ_START);
                _tracer.Info(Request, this.ControllerContext.ControllerDescriptor.ControllerType.FullName, startLogMessage);
            }

            // *** Work happens here
            RecipientModel visitorFormInformation =  _repository.GetVisitorFormInformation(code, pageType);
            // ***

            if (visitorFormInformation == null)
                return NotFound();

            if (Request != null)
            {
                string endLogMessage = CustomLogMessageBuilder.GetLogMessage(CustomLogMessageBuilder.StandardEndEventNames.EVENT_TYPE_VISITOR_FORM_REQ_END, startTime);
                _tracer.Info(Request, this.ControllerContext.ControllerDescriptor.ControllerType.FullName, endLogMessage);
            }

            try
            {
                DateTime startLogActivityTime = DateTime.Now;

                if (Request != null)
                {
                    string startLogMessage = CustomLogMessageBuilder.GetLogMessage(CustomLogMessageBuilder.StandardStartEventNames.EVENT_TYPE_UPDATE_VISIT_LOG_FORM_VIEWED_START);
                    _tracer.Info(Request, this.ControllerContext.ControllerDescriptor.ControllerType.FullName, startLogMessage);
                }

                // Log visitor activity, asynchronously
                await _repository.LogActivity(visitorFormInformation.RecipientId, visitorFormInformation.IsCompleted);

                if (Request != null)
                {
                    string endLogMessage = CustomLogMessageBuilder.GetLogMessage(CustomLogMessageBuilder.StandardEndEventNames.EVENT_TYPE_UPDATE_VISIT_LOG_FORM_VIEWED_END, startLogActivityTime);
                    _tracer.Info(Request, this.ControllerContext.ControllerDescriptor.ControllerType.FullName, endLogMessage);
                }
            }
            catch
            {
                return BadRequest("Recipient ID#" + visitorFormInformation.RecipientId.ToString() + " not found.");
            }

            return Ok(visitorFormInformation);
        }

To see my custom trace handler, please see Filip Wojcieszyn's blog article posted above. My version is nearly identical, so I've omitted it for brevity.

If I'm doing everything by the book regarding the use of trace listeners, could it be something that I'm passing in? In its current state, the service works as long as the Trace Listeners are disabled.

Before anyone asks, I've tried this in various browsers. But I'm at wit's help and would be most grateful for any helpful comments and suggestions. Thanks!

Answer 1

The problem is the HttpContext is not yet available in the constructor of the controller, which is why the Request property is null, which causes the _tracer to be null, which causes any function call to _tracer to throw an ArgumentNullException.

I suggest you read a little bit more about the WebApi pipeline, for example here. It tells you how the controller is constructed and what happens at what point when a request is inbound.

In short: the solution is to not store the _tracer at controller level, but inside the action being executed, and get a 'new' tracer on every action call.

public class VisitorFormController : ApiController
{
    private IDataAccessRepository _repository;

    public VisitorFormController(IDataAccessRepository repository): base()
    {
        _repository = repository;
    }

    [HttpGet]
    [Route("api/VisitorForm/{code}/{pageType}")]
    [EnableCors(origins: "*", headers: "*", methods: "options,get")]
    public async Task<IHttpActionResult> GetFormInfo(string code, string pageType)
    {
       var tracer = Request.GetConfiguration().Services.GetTraceWriter();

       // Use tracer from here on...
    }
}