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:inetpubwwwrootControllersShopWebhooksController.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.
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);
}
3
Answers
I am not sure that I understand you correct, but try temporary wraps background call in additional method with logging and try catch:
And add this method to your controller:
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
And you need to configure log4net to log your action calls.
for ex:
EDIT
Here is how you can do request log using DelegatingHandler
Register handler in config
This will give you something like below.
Furthermore, I will tell steps to override JsonValueProviderFactory AddToBackingStore method. You use that for find what property causing this issue.
Get source code from here.
Add Class MyJsonValueProviderFactory.cs
Register your new class before JsonValueProviderFactoruy in Global.asax.cs
ValueProviderFactories.Factories.Insert(0, new MyJsonValueProviderFactory());
or remove original first and use yours.
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
It looks like
JsonValueProviderFactory.AddToBackingStore
is traversing the JSON input and putting each leaf value into a dictionary. The key for the dictionary is the path to the leaf node. That exception would occur if the traversal encounters two leaf nodes with the same path.I think you need to check the JSON input data – perhaps it has duplicate keys. E.g. this is valid JSON:
whereas this is not:
because the "id" key appears more than once. This might cause the error you’re seeing.