Перейти к содержимому
BXWiki

Обработчик срабатывает дважды - разбор причин

Письмо приходит дважды, запись создаётся в двух экземплярах, а обработчик написан один раз. Разбираем причины двойного срабатывания по убыванию частоты.

С чего начать

Смотрим, сколько обработчиков висит на событии:

$conn = \Bitrix\Main\Application::getConnection();
print_r($conn->query("SELECT FROM_MODULE_ID, MESSAGE_ID, TO_CLASS, TO_METHOD, SORT
    FROM b_module_to_module WHERE MESSAGE_ID = 'OnAfterIBlockElementAdd'")->fetchAll());
// две одинаковые строки означают двойную регистрацию одного обработчика

Одинаковые строки в таблице обработчиков видно сразу. Такое случается, когда обработчик регистрируют и при установке модуля, и повторно в файле инициализации проекта.

Записываем каждое срабатывание с меткой:

\Bitrix\Main\Diag\Debug::writeToFile([
    'id' => $fields['ID'] ?? null,
    'глубина' => count(debug_backtrace()),
    'скрипт' => $_SERVER['SCRIPT_NAME'] ?? 'cli',
], date('H:i:s.u'), 'handler.log');
// две записи с одинаковой миллисекундой - это один запрос, а не два разных

Журнал отвечает на главный вопрос разбора сразу. Два срабатывания в одном запросе - это код или регистрация, два в разных запросах - повторный вызов снаружи или фоновая задача.

Считаем срабатывания за один запрос:

static $count = 0;
$count++;
if ($count > 1) {
    \Bitrix\Main\Diag\Debug::writeToFile(debug_backtrace(0, 6), 'повтор', 'handler.log');
}
// стек второго срабатывания показывает, кто именно вызвал действие повторно

Стек второго срабатывания называет виновника прямым текстом. В нём видно и свой код, и штатный вызов платформы, и место, откуда пришла массовая операция.

Проверяем файл инициализации на повторное подключение:

Окно терминала
grep -rn "addEventHandler\|AddEventHandler" /home/bitrix/www/local/php_interface/ | head
grep -rn "require\|include" /home/bitrix/www/local/php_interface/init.php | head
# один и тот же файл, подключённый дважды, регистрирует обработчики дважды

Причины

  1. Обработчик зарегистрирован дважды примерно 30% случаев

    ПризнакДвойное срабатывание происходит в одном запросе, обе записи журнала с одной меткой времени.

    ПроверкаСмотрим таблицу обработчиков и ищем в ней две одинаковые строки для события.

    Что делатьОставляем одну регистрацию: либо при установке модуля, либо в файле инициализации.

  2. Код сохраняет запись дважды подряд примерно 25% случаев

    ПризнакПосле создания записи сразу идёт её обновление, и событие приходит на оба действия.

    ПроверкаСмотрим стек вызовов в журнале: он покажет, откуда пришло второе сохранение.

    Что делатьСобираем все поля до записи и сохраняем один раз, а не дописываем следом.

  3. Массовая операция поднимает событие на каждую запись примерно 20% случаев

    ПризнакСрабатываний столько же, сколько записей в пачке обмена или скрипта.

    ПроверкаСверяем число записей журнала с числом обработанных записей операции.

    Что делатьСтавим в обработчике проверку режима массовой операции либо отключаем его на время.

  4. Событие приходит и на сайте, и в фоновой задаче примерно 15% случаев

    ПризнакПервое срабатывание из запроса посетителя, второе - из скрипта по расписанию.

    ПроверкаСмотрим в журнале имя скрипта: у фоновой задачи оно другое или пустое.

    Что делатьРазводим обязанности: фоновая задача делает свою работу, а обработчик - только свою.

  5. Обработчик сам вызывает то же самое API примерно 10% случаев

    ПризнакГлубина стека во втором срабатывании заметно больше, чем в первом.

    ПроверкаПечатаем в журнале глубину стека вызовов при каждом срабатывании обработчика.

    Что делатьСтавим статический флаг блокировки и прерываем повторный вход в обработчик.

Частые вопросы

Как отличить двойную регистрацию от двойного вызова?

По метке времени в журнале: одинаковая миллисекунда означает один запрос и двойную регистрацию. Разные метки означают, что API вызвали дважды.

Почему обработчик срабатывает на каждую запись обмена?

Так и задумано: событие приходит на каждое изменение данных. На время массовых операций такие обработчики отключают или проверяют признак обмена.

Можно ли просто убрать вторую регистрацию?

Да, если она действительно лишняя, но сначала проверяют, откуда она берётся. Регистрация при установке модуля живёт в базе и переживает правку файла инициализации.

Как понять, что виноват мой обработчик?

По глубине стека вызовов: у вложенного срабатывания она больше. Это и есть признак того, что обработчик сам вызвал то же самое действие.

Что делать с уже отправленными дублями писем?

Извиниться перед покупателями и добавить защиту от повторной отправки по признаку записи. Признак хранят рядом с данными, а не в памяти запроса.

Смежное

Первоисточник