The controller action is called twice, and the IIS logs do not show that

Question

I have strange behavior that cannot be replicated on the local computer, and it starts to infuriate me.

It looks like ASP.NET MVC is trying to execute an action, something timeouts, it fails without any exceptions and notifies the ajax client, and then tries to repeat the action, the ajax client receives a response, but not from the original call.

I have a controller action:

[ValidateAntiForgeryToken] [ClientErrorHandler] public virtual ActionResult PlaceOrder(CheckoutDto checkoutDto) { LoadDataFromDatabase(); // this may take up to couple minutes var orderConfirmationData = PlaceOrderToExternalWebservice(); SaveConfirmationData(orderConfirmationData); return View(Transform(orderConfirmationData)) } 

And I call it using jquery ajax:

 $.ajax({ url: placeOrderActionUrl, type: "POST", async: true, dataType: "html", data: $('#checkoutForm').serialize(), success: function (data) { // show confirmation data }, error: function (request, status, error) { // show error message } }); 

And it works fine for small orders, but two orders are created for large orders, and the reason, apparently, is the processing time, the larger the order, the longer it takes its external web service.

I checked the IIS logs to make sure that the client script does not trigger the action twice - and the IIS logs show only one call to a specific action.

The external service is not interrupted, there are no exceptions in the event / sql logs.

To make sure that the ajax client does not receive a response from the original call, I made a kind of lock:

  [ValidateAntiForgeryToken] [ClientErrorHandler] public virtual ActionResult PlaceOrder(CheckoutDto checkoutDto) { try { if (OrderingLockedForCurrentUser()) { Log("Locked"); return View("Already placing order"); } LockOrderingForCurrentUser(); LoadDataFromDatabase(); // this may take up to couple minutes var orderConfirmationData = PlaceOrderToExternalWebservice(); SaveConfirmationData(orderConfirmationData); return View(Transform(orderConfirmationData)) } finally { RemoveOrderingLockForCurrentUser(); } } 

And instead of returning the confirmed data, it returns "already placing order".

I thought it might be a timeout for the action to complete, but I tried just for the sake of

 <httpRuntime executionTimeout="600" /> 

did not help.

Any ideas where to look for a reason, what to additionally check to include any additional entries?

Update: Interestingly, the original call is also completed.

Update 2: I added an AjaxOnly action filter to ensure that it is only called from javascript:

 public class AjaxOnlyAttribute : ActionFilterAttribute { public override void OnActionExecuting(ActionExecutingContext filterContext) { if (!filterContext.HttpContext.Request.IsAjaxRequest()) { throw new Exception("This action is intended to be called from Ajax only."); } } } 

And from the logs it is called only from javascript, so the mystery continues ...

Update 3:

I highlighted the problem for a simple thread sleep in a separate test controller:

 [ValidateAntiForgeryToken] [AjaxOnly] [ClientErrorHandler] public virtual ActionResult PlaceOrderAction(CheckoutDto checkoutDto) { try { if (CanPlaceOrder(Request.RequestContext.HttpContext)) { Thread.Sleep(TimeSpan.FromSeconds(90)); return Content("First time"); } return Content("Second time"); } finally { HttpContext.Cache.Remove(GetKey(userService.CurrentUser.UserId)); } } public bool CanPlaceOrder(HttpContextBase httpContext) { var userId = userService.CurrentUser.UserId; var key = GetKey(userId); if (httpContext.Cache[key] == null) { httpContext.Cache.Add(key, userId, null, DateTime.Now.AddMinutes(10), new TimeSpan(), CacheItemPriority.High, null); return true; } return false; } private static string GetKey(int userId) { return "PlacingOrder{0}".With(userId); } 

As long as it runs fine on two independent dev machines (win 7) and an intermediate machine in ec2 (win2008sp2), this is almost certainly a problem with the IIS settings of the production server (win 2008R2 x64 sp1).

Answer 1

Found.

As I started to think, this IIS configuration was somehow superimposed on it, I started a new test site for IIS production, just the default mvc site with 90 second sleep stream.
And it worked as intended. Therefore, I copied the entire production site to work on another port, thinking that I could test ideas faster without affecting the production site - and when it worked on another port, there were no problems.

Turns out we used the Amazon Elastic balancer, and that was the problem.

The moral is that I would have wasted much less time if I aggressively isolated the problem from the very beginning.

Answer 2

Here is a suggestion on a similar issue:

“Is there any other markup that might accidentally link to the page? Script links, image links, css links, all can be mistakenly pointed to '.' or current page. "

MVC controller is called twice