Search code examples
c#asp.net-mvcrestlog4netelmah.mvc

JsonValueProviderFactory: System.ArgumentException: An item with the same key has already been added

I have a webhook api handler for Shopify which calls the below controller action with a json body. It is failing immediately because no log4net logging is being reached and logged except the one in the OnException method with the error below.

Question 1:

The Stack Trace in the Elmah log is not helpful in that it doesn't go down far enough to show which line in the code originated the error. Why is this? I've noticed this with async errors...they seem harder to determine the root cause line in the code. Maybe I should make it a synchronous method for now? Maybe I should just get rid of the OnException method as it could be obscuring more info?

Question 2:

What could possibly causing this error immediately upon hitting the controller action before any code is executed? This controller inherits the asp.net mvc Controller and the only code in the constructor is to create an instance of the DBContext and the log4net _logger.

Stack Trace:

Controllers.ShopWebhooksController.OnException(C:\inetpub\wwwroot\Controllers\ShopWebhooksController.cs:44)
System.ArgumentException: An item with the same key has already been added.
       at System.ThrowHelper.ThrowArgumentException(ExceptionResource resource)
       at System.Collections.Generic.Dictionary`2.Insert(TKey key, TValue value, Boolean add)
       at System.Web.Mvc.JsonValueProviderFactory.AddToBackingStore(EntryLimitedDictionary backingStore, String prefix, Object value)
       at System.Web.Mvc.JsonValueProviderFactory.AddToBackingStore(EntryLimitedDictionary backingStore, String prefix, Object value)
       at System.Web.Mvc.JsonValueProviderFactory.AddToBackingStore(EntryLimitedDictionary backingStore, String prefix, Object value)
       at System.Web.Mvc.JsonValueProviderFactory.AddToBackingStore(EntryLimitedDictionary backingStore, String prefix, Object value)
       at System.Web.Mvc.JsonValueProviderFactory.AddToBackingStore(EntryLimitedDictionary backingStore, String prefix, Object value)
       at System.Web.Mvc.JsonValueProviderFactory.AddToBackingStore(EntryLimitedDictionary backingStore, String prefix, Object value)
       at System.Web.Mvc.JsonValueProviderFactory.AddToBackingStore(EntryLimitedDictionary backingStore, String prefix, Object value)
       at System.Web.Mvc.JsonValueProviderFactory.GetValueProvider(ControllerContext controllerContext)
       at System.Web.Mvc.ValueProviderFactoryCollection.GetValueProvider(ControllerContext controllerContext)
       at System.Web.Mvc.ControllerBase.get_ValueProvider()
       at System.Web.Mvc.ControllerActionInvoker.GetParameterValue(ControllerContext controllerContext, ParameterDescriptor parameterDescriptor)
       at System.Web.Mvc.ControllerActionInvoker.GetParameterValues(ControllerContext controllerContext, ActionDescriptor actionDescriptor)
       at System.Web.Mvc.Async.AsyncControllerActionInvoker.<>c__DisplayClass3_1.<BeginInvokeAction>b__0(AsyncCallback asyncCallback, Object asyncState)
       at System.Web.Mvc.Async.AsyncResultWrapper.WrappedAsyncResultBase`1.Begin(AsyncCallback callback, Object state, Int32 timeout)
       at System.Web.Mvc.Async.AsyncControllerActionInvoker.BeginInvokeAction(ControllerContext controllerContext, String actionName, AsyncCallback callback, Object state)
       at System.Web.Mvc.Controller.<>c.<BeginExecuteCore>b__152_0(AsyncCallback asyncCallback, Object asyncState, ExecuteCoreState innerState)
       at System.Web.Mvc.Async.AsyncResultWrapper.WrappedAsyncVoid`1.CallBeginDelegate(AsyncCallback callback, Object callbackState)
       at System.Web.Mvc.Async.AsyncResultWrapper.WrappedAsyncResultBase`1.Begin(AsyncCallback callback, Object state, Int32 timeout)
       at System.Web.Mvc.Controller.BeginExecuteCore(AsyncCallback callback, Object state)
       at System.Web.Mvc.Async.AsyncResultWrapper.WrappedAsyncResultBase`1.Begin(AsyncCallback callback, Object state, Int32 timeout)
       at System.Web.Mvc.Controller.BeginExecute(RequestContext requestContext, AsyncCallback callback, Object state)
       at System.Web.Mvc.MvcHandler.<>c.<BeginProcessRequest>b__20_0(AsyncCallback asyncCallback, Object asyncState, ProcessRequestState innerState)
       at System.Web.Mvc.Async.AsyncResultWrapper.WrappedAsyncVoid`1.CallBeginDelegate(AsyncCallback callback, Object callbackState)
       at System.Web.Mvc.Async.AsyncResultWrapper.WrappedAsyncResultBase`1.Begin(AsyncCallback callback, Object state, Int32 timeout)
       at System.Web.Mvc.MvcHandler.BeginProcessRequest(HttpContextBase httpContext, AsyncCallback callback, Object state)
       at System.Web.HttpApplication.CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()
       at System.Web.HttpApplication.<>c__DisplayClass285_0.<ExecuteStepImpl>b__0()
       at System.Web.HttpApplication.ExecuteStepImpl(IExecutionStep step)
       at System.Web.HttpApplication.ExecuteStep(IExecutionStep step, Boolean& completedSynchronously)

Here's the Controller, the OrderUpdate is the Action being called:

public class ShopWebhooksController : Controller
{
private readonly ILog _logger;
private readonly InventoryMgmtContext _dbContext;

public ShopWebhooksController()
{
    _logger = LogManager.GetLogger(GetType());
    _dbContext = new InventoryMgmtContext();
}

protected override void OnException(ExceptionContext filterContext)
{
    Exception ex = filterContext.Exception;
    var action = filterContext.RouteData.Values["action"];
    // TODO: Log or report your exception.
    string msg = $"Exception in shopify webhook controller action: {action}. Message: {ex.Message}. Stack: {ex.StackTrace}.";
    _logger.Error(msg); **<---- this is being logged**

    filterContext.Result = new HttpStatusCodeResult(HttpStatusCode.OK, msg);

    //Let the base controller finish this execution
    base.OnException(filterContext);
}      


[HttpPost]
public async Task<ActionResult> OrderUpdated (int storefrontId)
{
    string msg = "Successfully submitted update request to Mozzo.";
    string webhook = "orders/updated";
    _logger.Debug($"Shopify {webhook} request received."); **<-- not being logged**

    try
    {
        var validationResult = await ValidateStorefrontWebhook(webhook, storefrontId);
        if (!validationResult.WasSuccessful) return new HttpStatusCodeResult(HttpStatusCode.OK, validationResult.Message);

        var orderSyncAppServ = new SyncErpWithPlacedOrdersTask();
        Hangfire.BackgroundJob.Enqueue(() => orderSyncAppServ.UpdateOrderFromWebhook(validationResult.Value, storefrontId));
    }
    catch (Exception e)
    {
        msg = $"Exception webhook: {webhook} for storefront Id: {storefrontId}. {e.Message}.";
        _logger.Error(msg);
    }
    return new HttpStatusCodeResult(HttpStatusCode.OK, msg);
}

#endregion

#region Private Methods


/// <summary>
/// Validates the webhook is authentic and returns the body of the request as a string
/// </summary>
/// <param name="webhook"></param>
/// <param name="storefrontId"></param>
/// <returns>request body (string version of an order, etc.</returns>
private async Task<ActionConfirmation<string>> ValidateStorefrontWebhook(string webhook, int storefrontId)
{
    string returnMessage = "";     

    //log request
    //get the request body (a json string of an order, product, etc coming from shopify.
    string jsonObject = await GetRequestBody();

    //wrap in brackets to make it an array of one because our import takes an array or orders
    jsonObject = $"[ {jsonObject} ]";

    //get storefront
    var storefront = await _dbContext.StoreFronts.Where(s => s.Id == storefrontId).SingleOrDefaultAsync();
    if (storefront == null) {
        returnMessage = $"Shopify {webhook} webhook request for Storefront Id: {storefront.Id} - storefront not found!";
        _logger.Error($"{LogHelper.GetCurrentMethodName()}: {returnMessage}");
        return ActionConfirmation<string>.CreateFailureConfirmation(returnMessage, "", false);
    }

    log4net.LogicalThreadContext.Properties["AccountId"] = storefront.Company.AccountId;
    log4net.LogicalThreadContext.Properties["CompanyId"] = storefront.CompanyId;
    log4net.LogicalThreadContext.Properties["FacilityId"] = null;
    log4net.LogicalThreadContext.Properties["UserId"] = null;

    string shopDomain = storefront.APIUrl;
    string shopSecretKey = storefront.StoreFrontTypeId == (int)StoreFront.StoreFrontTypes.ShopifyPrivate
        ? storefront.AccessToken
        : AppSettings.ShopifySecretKey;

    _logger.Debug("About to check if webhook is authentic");

    var isValidRequest = await AuthorizationService.IsAuthenticWebhook(
        Request.Headers.ToKvps(),
        Request.InputStream,
        shopSecretKey);

    if (!isValidRequest)
    {
        returnMessage = $"Shopify {webhook} webhook request for Storefront Id: {storefront.Id} is not authentic!";
        _logger.Error($"{LogHelper.GetCurrentMethodName()}: {returnMessage}"); 
        return ActionConfirmation<string>.CreateFailureConfirmation(returnMessage, "", false);
    }

    returnMessage = $"Shopify {webhook} webhook request for Storefront Id: {storefront.Id} is authentic!";
    _logger.Info($"{LogHelper.GetCurrentMethodName()}: {returnMessage}");            

    return ActionConfirmation<string>.CreateSuccessConfirmation(returnMessage, jsonObject, false);
}

private async Task<string> GetRequestBody()
{
    _logger.Debug($"{LogHelper.GetCurrentMethodName()}: Attempting to get request body.");

    //ShopifySharp has just read the input stream. We must always reset the inputstream
    //before reading it again.
    Request.InputStream.Position = 0;

    //Do not dispose the StreamReader or input stream. The controller will do that itself.
    string bodyText = await new StreamReader(Request.InputStream).ReadToEndAsync();

    _logger.Debug($"{LogHelper.GetCurrentMethodName()}: Request body: {bodyText}.");

    return bodyText;
}
#endregion

UPDATE - Problem and Solution

The issue was indeed that the Shopify Order webhook JSON object contained duplicate keys in that they has a lowercase and TitleCase version of 4 keys in the same object wrapper. enter image description here

The full path of these keys are:

order,refunds,0,transactions,0,receipt,version
order,refunds,0,transactions,0,receipt,timestamp
order,refunds,0,transactions,0,receipt,ack
order,refunds,0,transactions,0,receipt,build

And the exact code change I made was as below. I did follow the answer provided below on adding my own JsonValueProviderFactory class, but what was not provided, was the exact change to make...because it depends on how you want to handle it. In my case, this change results in any subsequent keys of the same name being thrown away. So if you want to handle it differently, you'd need to address as you desire:

/// <summary>
/// Modified this to handle duplicate keys
/// </summary>
/// <param name="key"></param>
/// <param name="value"></param>
public void Add(string key, object value)
{
    if (++_itemCount > _maximumDepth)
    {
        throw new InvalidOperationException("The JSON request was too large to be deserialized.");
    }

    // Add the following if block so if the key already exists, just return instead of trying to add it to the dictionary which will throw an error.
    if (_innerDictionary.ContainsKey(key))
    {
        return;
    }

    _innerDictionary.Add(key, value);
}
Solution

  • I think there is nothing wrong with your design, but one of your class may have duplicated property which will cause runtime exception.

    for example

    public int storefrontId {get; set;}
public int StorefrontId {get; set;}

    And you need to configure log4net to log your action calls. for ex:

    2021-02-16 10:24:17.5632|2|INFO|Microsoft.AspNetCore.Hosting.Diagnostics|Request finished in 141.7419ms 200  |url: http://myapp/OrderUpdated|action:

    EDIT Here is how you can do request log using DelegatingHandler

    public class RequestLogHandler : DelegatingHandler
{
    private static readonly ILog log = log4net.LogManager.GetLogger(System.Reflection.MethodBase.GetCurrentMethod().DeclaringType);
    
    protected override async Task<HttpResponseMessage> SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
    {
        if (request.Content != null)
        {
            string requestBody = await request.Content.ReadAsStringAsync();
            log.Info($"url {request.RequestUri} body = {requestBody}");
        }
        //// let other handlers process the request
        var result = await base.SendAsync(request, cancellationToken);

        return result;
    }
}

    Register handler in config

    config.MessageHandlers.Add(new RequestLogHandler());

    This will give you something like below. enter image description here

    Furthermore, I will tell steps to override JsonValueProviderFactory AddToBackingStore method. You use that for find what property causing this issue.

    1. Get source code from here.

    2. Add Class MyJsonValueProviderFactory.cs

    3. Register your new class before JsonValueProviderFactoruy in Global.asax.cs

      ValueProviderFactories.Factories.Insert(0, new MyJsonValueProviderFactory());

    or remove original first and use yours.

    ValueProviderFactories.Factories.Remove(ValueProviderFactories.Factories.OfType<JsonValueProviderFactory>().FirstOrDefault());
ValueProviderFactories.Factories.Add(new MyJsonValueProviderFactory());

    Play with this class with exception catching, you will be able to find where is the problem, you may start with Add method in EntryLimitedDictionary class.

    Again use below link to register error handling globally. https://learn.microsoft.com/en-us/aspnet/web-api/overview/error-handling/exception-handling