Как предотвратить дублирование HTTP-запросов в Azure Web Role

Мы периодически видим повторяющийся HTTP-запрос, попадающий в наше приложение облачной службы Azure. Наше приложение использует Azure Traffic Manager для распределения трафика по двум регионам (для целей аварийного восстановления). У нас есть 3 крупных веб-роли в каждом регионе.

Кто-нибудь сталкивался (в идеале, решал) с подобной проблемой в Azure?

Более подробная информация ниже:

1. Регистрация трассировки:

Регистрация трассировки реализована в действии контроллера MVC, которое выглядит дублированным:

    [HttpPost]
    public JsonResult JsonPost(FormCollection formData)
    {
        Logger.Info(LogFormatter.FormatMessage(ToString(), "JsonPost", UserHelper.CustomerSession.CustomerId, "Begin JSON post."));
        var result = new DefaultJsonResult();
        try
        {
            #region Build and validate foo model
            var fooModel = BuildFooModel(formData);
            .
            .
            .
        }
        catch (Exception ex)
        {
            Logger.Error(LogFormatter.FormatException(ex, ToString(), "JsonPost",
                UserHelper.CustomerSession.CustomerId, "Error while proccessing Foo."));
            result.Success = false;
            result.Action = new JsonResultAction(JsonResultActionType.Display);
            result.Error = new JsonResultError();
            result.Error.Details.Add(new JsonResultErrorDetail
            {
                Type = "FooProcessing",
                Message = "Error while proccessing Foo."
            });
        }
        Logger.Info(LogFormatter.FormatMessage(ToString(), "JsonPost", UserHelper.CustomerSession.CustomerId, "End JSON post."));

        return Json(result);
    }

В журналах трассировки мы видим несколько случаев следующего:

Сообщение: счетный бар.
Метка времени: 22.01.2015 03:42:28
Имя контроллера: Com.Web.Controllers.FooController
Название действия: бар
Идентификатор пользователя: 85c5d33f-05b3-40d5-9e73-1219ca490e7e
RoleInstance = StoreWebApp_IN_0; WindowsIdentity.Name = NT AUTHORITY \ NETWORK SERVICE; ManagedThreadId = 15;

Сообщение: Начните JSON-пост.
Метка времени: 22.01.2015 03:43:22
Имя контроллера: Com.Web.Controllers.FooController
Название действия: JsonPost
Идентификатор пользователя: 85c5d33f-05b3-40d5-9e73-1219ca490e7e
RoleInstance = StoreWebApp_IN_0; WindowsIdentity.Name = NT AUTHORITY \ NETWORK SERVICE; ManagedThreadId = 28;

Сообщение: отправка уведомления Foo
Метка времени: 22.01.2015 03:43:28
Имя контроллера: Com.Web.Business.Modules.Foo.FooModule
Название действия: ProcessFoo
Идентификатор пользователя: 85c5d33f-05b3-40d5-9e73-1219ca490e7e
RoleInstance = StoreWebApp_IN_0; WindowsIdentity.Name = NT AUTHORITY \ NETWORK SERVICE; ManagedThreadId = 28;

Сообщение: Начните JSON-пост.
Метка времени: 22.01.2015 03:43:30
Имя контроллера: Com.Web.Controllers.FooController
Название действия: JsonPost
Идентификатор пользователя: 85c5d33f-05b3-40d5-9e73-1219ca490e7e
RoleInstance = StoreWebApp_IN_2; WindowsIdentity.Name = NT AUTHORITY \ NETWORK SERVICE; ManagedThreadId = 13;

Несколько примечаний:

  1. Вторая "Начать публикацию JSON" происходит до того, как первый запрос регистрирует свою "Концовку публикации JSON" (которая никогда не регистрируется, кстати)

  2. Вторая "Начать публикацию JSON" происходит в другом экземпляре веб-роли

2. Журналы IIS:

Соответствующие журналы IIS следующие:

2015-01-22 03:42:29 W3SVC1273337584 RD00155DE0F696 127.0.0.13 POST / foo / bar
- 443 johndoe@hotmail.com 128.0.0.28 HTTP / 1.1 Mozilla / 5.0 + (Macintosh; + Intel + Mac + OS + X + 10_8_2) + AppleWebKit / 536.26.17 + (KHTML, + like + Gecko) + Версия /6.0 0,2+ Сафари / 536.26.17

2015-01-22 03:43:30 W3SVC1273337584 RD00155DE0CAC8 127.0.0.54 POST / foo / jsonpost
- 443 johndoe@hotmail.com 128.0.0.28 HTTP / 1.1 Mozilla / 5.0 + (Macintosh; + Intel + Mac + OS + X + 10_8_2) + AppleWebKit / 536.26.17 + (KHTML, + like + Gecko) + Версия /6.0 0,2+ Сафари / 536.26.17

На данный момент вы, вероятно, спрашиваете себя, где находится запись журнала IIS для первого /foo/jsonpost запрос? Такое поведение согласуется с каждым экземпляром дублированного запроса, однако причина до сих пор остается загадкой.

Спасибо за прочтение. Любое понимание или даже предложения о том, как устранить неполадки, будет принята с благодарностью.

Поиск в Google "дублированных запросов Azure" дал следующие результаты:

Обновление 26.01.2015
Включено отслеживание ошибочного запроса в надежде захватить фантом (сначала /foo/jsonpost) запрос и изолировать, откуда это. К сожалению, все еще не повезло, отслеживание невыполненных запросов согласуется с журналами IIS.

Источник

1 ответ

Решение

Дело закрыто:

Отсутствующая запись в журнале была вызвана переполнением стека из-за некорректной логики взаимодействия сторонних API. При перезапуске IIS он возобновил / восстановил запрос, вызвавший переполнение стека. Поскольку соединение поддерживалось в течение всего цикла, клиент видел только ответ на второе выполнение. Причина, по которой переполнение стека не произошло со второй попыткой, заключается в том, что выполнение занимает другой путь кода, чем первое выполнение.

Как мы узнали, что было переполнение стека (помимо TODO комментарий, который читалprevent stack overflow"):

  • В журналах системных событий:A process serving application pool 'ASP.NET v4.0' suffered a fatal communication error with the Windows Process Activation Service. The process id was '5328'. The data field contains the error number."
  • В журналах HTTPERR (IIS) "Connection_Abandoned_By_ReqQueue"произошла ошибка, означающая, что рабочий процесс из пула приложений неожиданно завершил работу или потерял ожидающий запрос, закрыв его дескриптор
  • Журналы сбоев показывают 0x800703e9 - "Recursion too deep; the stack overflowed."

Надеюсь, что эти выводы полезны для других потерянных душ, пытающихся разгадать тайну пропавших журналов IIS...

Источник
Другие вопросы по тегам