Controller action is getting called twice and IIS logs do not show that

Question

I'm having strange behaviour, that can not replicate on local machine and it is starting to drive me nuts.

Looks like ASP.NET MVC is trying to execute action, something timeouts, it fails without any exception and notice to ajax client, then tries to rerun action, ajax client gets response, but not from 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 for small orders it works fine, but for large orders two orders are created and reason seems to be processing time, the larger the order, the more time placing it to external webservice takes.

I've checked IIS logs, to make sure, that client script is not calling action twice - and IIS logs show only one call to particular action.

External service does not fail, there are no exceptions logged in event log/sql log.

To make sure, that ajax client gets response not from original call I've made 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 confirmed data, it returns "already placing order".

I've thought maybe action execution timeouts, but I've tried just for sake

<httpRuntime executionTimeout="600" />

didn't helped.

Any ideas where to search a reason, what additionally to check, to enable any additional logging?

Update: Interesting thing is, that original call is also completed.

Update 2: I've added action filter AjaxOnly to be sure, that it is called only 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 logs it is called only from javascript, so mystery continues...

Update 3:

I've isolated problem to simple Thread sleep in 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 ok on two independant dev machines (win 7) and staging machine in ec2 (win2008sp2), it is almost certainly problem with production server IIS settings (win 2008R2 x64 sp1).

Use async for long calls that can timeout. You can add a cancelation token. See my tutorial http://www.asp.net/mvc/tutorials/mvc-4/using-asynchronous-methods-in-aspnet-mvc-4 — RickAndMSFT, Jul 20 '12 at 15:24

score 0 · Answer 1 · edited May 23 '17 at 12:04

0

Here is the suggestion from a similar question:

"Is there any other markup that could be accidentally referencing the page? Script references, image references, css references, all could be mistakenly pointed at '.' or the current page."

MVC controller is being called twice

edited May 23 '17 at 12:04

Community

1
1

answered Jul 20 '12 at 13:44

Efe Kaptan

465
2
11

I've seen this, but it isn't the case because a) iis logs would still show 2 calls b) it would call twice for all orders, not only large ones c) i've added filter to allow action to be called from ajax – Giedrius Jul 20 '12 at 14:01

score 0 · Accepted Answer · answered Jul 24 '12 at 08:52

Found it.

As I've started to think, that IIS configuration is somehow involded to this, I've started a new test site on production IIS, simply default mvc site with 90 seconds thread sleep.
And it worked as supposed.
So I've copied whole production site to run on different port, thinking I'll be able to test ideas faster without affecting production site - and when it was running on different port there was no problem.

Turns out, that we were using Amazon Elastic balancer and it was the problem.

Moral is, that I would have wasted much less time, if I was aggressivly isolating problem from the very beginning.

Controller action is getting called twice and IIS logs do not show that

2 Answers2