1С:Шина в продуктиве: что ломается на длинном аптайме и что мониторить

Вся Шина у нас стоит на одном узле: Docker на Linux, 4 ядра и 15 ГБ памяти. Этот узел гоняет между десятком систем порядка миллиона сообщений за сутки. Управляющий слой падал каждые день-два, и процессор ни разу не был причиной.

Разбираю, как живёт 1С:Шина версии 6.1.6 в продуктиве розничной сети. Центр связки - учётная система на УПП. К ней подключены бухгалтерия и зарплата, BPM и WMS, кассовый сервис и фронт-офис касс, CRM вместе с программой лояльности, а ещё сервисы инвентаризации и доставки.

Короткая версия этого разбора опубликована на Инфостарте. Здесь то же самое, но с добавленным разделом про мониторинг: какие метрики снимать, какими запросами и почему привычные пороги на такой нагрузке не работают.

Оговорок две. Наблюдаю Шину год, а замеры есть только за последние 30 суток: метрики у нас хранятся месяц, годовых рядов нет, и экстраполировать я не стану. И сколько весит типичное сообщение, не мерил, так что примерять наш “миллион в сутки” на свою систему не получится.

Словарь на три строки

В терминах Шины процесс означает одну интеграционную схему, у нас таких 18. Узел - шаг внутри схемы, на котором сообщение обрабатывают или передают дальше, узлов 173. Приложение - единица, которую Шина разворачивает целиком: запущено 15, и перезапускать их можно поодиночке. Канал описывает направление обмена со стороны 1С, каналов 62. Участник - учётная запись для входа в Шину, и сообщения достаются тому, кто под ней вошёл.

Брокеров два. Встроенный ActiveMQ Artemis живёт внутри Шины, внешний RabbitMQ стоит рядом. Отказы у них были разные.

Пять дефектов, которые копятся с аптаймом

Общее у всех пяти одно. Тестовый стенд пересоздают каждые сутки, а за такой срок ни один из них не успевает себя показать.

1. Дефолт Docker в десять секунд превращал баг брокера в отказ

Каждые сутки аптайма прибавляли журналу встроенного брокера по 10 ГБ, строго линейно. Хранится журнал в файлах-сегментах, и таких файлов набралось 3 956 на 38 ГБ. Диск растянули с 98 ГБ до 148, и всё равно упёрлись.

Параллельно в логе сыпалось Cannot find add info ... on compactor, это известная ошибка компактации в Artemis. В Шину встроена версия 2.14.0 выпуска 2020 года, внешнего broker.xml нет, крутить настройки брокера бесполезно.

Запускал эту цепочку не сам брокер. В docker-compose.yml не было stop_grace_period, и на остановку Docker давал дефолтные 10 секунд. Брокеру с большим журналом этого мало: он не успевает закрыться, прилетает SIGKILL, журнал портится, компактор ломается, рост продолжается.

stop_grace_period: 300s

С правкой прожили 8,5 суток аптайма. Сегментов в журнале 93, было 3 956, по объёму 930 МБ вместо прежних 38 ГБ.

Только записать успех на одну эту строку я не могу. В тот же заход мы отключили режим разработки (следующий пункт), который раз в двое суток валил управляющий слой. Меньше падений, значит реже рестарты и SIGKILL. Вклад каждой правки не разделить: выкатывали их в одно окно, а контрольной группы не было.

И ещё одно. Штатный рестарт запустил восстановление журнала, и от 38 ГБ после него осталось 270 МБ. Значит, 37,7 ГБ занимали мёртвые записи. Верно это при одном условии: recovery ничего не выбросил.

2. Управляющий слой умирал раз в двое суток

Выглядело это так: запрос до консоли или Console API доходит, а ответа нет. При этом брокер жив, на heartbeat возвращается 200, процессор отдыхает, а обмены стоят.

Все записи служебного лога о незакрытых ресурсах, сто процентов, вели в одну точку кода платформы. Там запрос к внутренней H2-базе консоли отдавал результат, и его никто не закрывал. Скорость около 6 в минуту, за сутки выходит примерно 8 600.

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

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

Для мониторинга вывод отсюда серьёзнее, чем про сам флаг: “я жив” сервер отвечал как раз в те часы, когда управление и обмены уже лежали. Наш watchdog стучался в корневой URL, и ему приходил 301. Та же ловушка встречается и без Шины: в ночной синхронизации с внешним сервисом чтение отвечало за доли секунды, пока запись уходила за 30 секунд, разбор таймаутов в обмене.

3. Диск свободен наполовину, а inode заканчиваются

По объёму диск заполнен на 84 %: 125 ГБ из 148, жить можно. С inode хуже: занято 85 %, это 8,27 миллиона, и до аварии остаются считаные дни.

Когда включено хранение доставленных, Шина раскладывает каждое сообщение на две части. Описание уходит в PostgreSQL, тело ложится на диск отдельным файлом. В базе ротация работает как надо, retention там сутки. А вот файлы с телами платформенный сборщик мусора не трогает вообще.

Вылечили ночным заданием в cron: оно удаляет файлы тел старше retention. Замер после: диск с 125 ГБ до 90, inode с 8,27 миллиона до 1,53.

Осторожно, совет разрушительный. Что эти файлы осиротели, я вывел логически, список имён с базой не сверял. Прежде чем ставить в cron удаление из хранилища платформы, убедитесь, что на отобранные файлы нет ссылок.

Набежал ровно месячный объём, и причина простая. В июне хранение доставленных включили точечно под расследование инцидента, разобрались, а выключить забыли. Через месяц хранилище от этого едва не легло.

4. Скрипт бэкапа, который тихо умер

Когда данные меняются на ходу, tar пишет file changed as we read it и выходит с кодом 1. А скрипт был с set -euo pipefail и на этой ошибке честно обрывался посреди работы.

Получилось так: строка в crontab стоит, а свежих копий нет. Старых нашлось больше пятидесяти снапшотов, в сумме 24,5 ГБ, значит когда-то скрипт работал, потом перестал. Когда это случилось, неизвестно: ротации не было, на даты файлов никто не смотрел.

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

5. Отвал потребителя от внешнего брокера

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

В общей сводке было 28 очередей и 26 потребителей. Отсюда ещё ничего не следует: часть наших очередей by design живёт без потребителя. Искать надо очередь, в которой одновременно ноль потребителей и лежит необработанный остаток.

Главное: отставание копится не в Шине, а в 1С

Каждый из пяти дефектов бил по самой Шине. А самый дорогой отказ года Шина не видела вовсе: с её стороны всё выглядело идеально.

Приёмник на 1С, прежде чем разбирать входящие сообщения, кладёт их в буфер. Физически буфер состоит из трёх регистров сведений.

Буфер	Максимальный возраст	Максимальная глубина
основной	111 698 с = 31,0 ч	2 863
фронт-офис касс	2 532 с = 0,7 ч	963
кассовый сервис	2 232 с = 0,6 ч	391

31 час, и это при пустых в тот момент очередях самой Шины.

Скорее всего, вы подумали не то. Услышав про “31 час отставания”, легко решить, что разбор остановился и буфер завален. Проверим арифметикой: в основной регистр-приёмник приходит 441 тысяча записей за сутки. За 31 час простоя разбора там скопилось бы около 570 тысяч.

Столько там не лежало. Вот почасовой замер в дни инцидента:

18.07 07:31   возраст  1,1 ч   в буфере   44
18.07 23:31   возраст 10,7 ч   в буфере  197
19.07 11:31   возраст 22,7 ч   в буфере  310
19.07 19:31   возраст 30,7 ч   в буфере  196   ← пик возраста

В буфере 44, потом 310, потом 196 сообщений, то есть разбор всё это время шёл нормально. Застряла голова очереди: одно сообщение никак не разбиралось, и его возраст рос вместе с часами.

И застрявших сообщений было как минимум два. От первого замера до второго 16 часов, а возраст за это время прибавил всего 9,6 часа. Выходит, первая голова каким-то образом ушла, и на её место встала другая.

Чего я не знаю, хотя хотел бы: какое сообщение застряло. Его тип, что его держало, чем кончился эпизод. В разборе ответа нет, и совет “мониторьте возраст” сводится к измерению симптома болезни, диагноз которой я не поставил.

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

Вас это тоже касается. В те двое суток любая проверка длины очереди светилась зелёным, а канал при этом простоял 31 час. Ловить такой класс отказов надо по возрасту самого старого необработанного сообщения. Остановку разбора видно по длине, застрявшую голову по возрасту. Отказы разные, и при нормальной глубине второй не заметишь.

Что мониторить: готовый набор

Раздел, которого нет в версии на Инфостарте. Свожу в одно место то, что у нас реально стоит и что стоило бы поставить раньше.

По каждому регистру-буферу на стороне 1С:

• возраст старейшего необработанного сообщения - главная метрика всей связки. Считать его по времени, которое пишет сама 1С, часам машины мониторинга не доверять: на их расхождение мы уже наступали;
• глубина буфера - ловит другой отказ, остановку разбора целиком;
• обе вместе, потому что порознь каждая пропускает свой класс аварий.

По Шине:

• длина очередей и число неподтверждённых;
• связка “ноль потребителей И в очереди лежит необработанный остаток” вместо простого “нет потребителей”: часть очередей пустует by design, и простой алерт будет фолзить;
• доступность именно управляющего слоя, а не корневого URL. Корень отдаёт 301 ровно тогда, когда обмены уже стоят.

По хосту:

• inode наравне с гигабайтами. Диск на 84 процентах выглядит спокойно, а inode на 85 означает дни до аварии;
• свежесть файла бэкапа, а не наличие строки в crontab.

Про пороги. Фиксированный порог на поток при такой нагрузке бесполезен. Самый тихий ночной час и самый загруженный дневной отличаются больше чем в 35 раз: 2,9 против 102,1 сообщения в секунду. К тому же у ночи свой пик, 47,5 в секунду, когда идёт пакетный обмен, то есть там, где ждёшь провал. Алерт у нас звенел каждую ночь, пока в условие не добавили наличие необработанного остатка.

Общий подход к наблюдаемости, из которого всё это выросло, разобран отдельно - “Наблюдаемость 1С: ошибок в проде в 23 раза меньше”, а конкретная сборка на Grafana и Prometheus - в статье про мониторинг 1С.

Когда соврал наш собственный мониторинг

Следующее мы нашли уже при подготовке статьи.

Счётчик “ошибок текстового лога брокера” стоял на 3 801 769, хотя в самих логах подобных строк не было ни одной.

Экспортёр делает две вещи подряд: получает inode файла, потом считает строки по шаблону. В выводе он ждёт две строки: первая идёт как inode, вторая как счётчик. Ротация лога у нас раз в девять минут. В момент ротации grep файла не видит и второй строки не выдаёт, а код спокойно принимает номер inode за количество совпадений.

Те самые 3 801 769 и есть номер inode файла лога. На этой метрике висел боевой алерт, и за месяцы он ни разу никого не поднял.

Нашлась и вторая. Максимальное время ответа консоли стояло ровно на 30,000 секунды. Это штрафная заглушка на случай, когда токен не получен, задержкой она не является. 95-й перцентиль на деле 23 мс.

Третий случай того же рода, и попался на нём я сам. Объём трафика я перепроверил по второму источнику: расхождение с Prometheus 0,16 процента. Выглядело отлично. Только Prometheus опрашивает те же адреса и берёт тот же счётчик. Одно число я прочитал дважды и едва не выдал это за независимую проверку.

Вывод шире Шины: свой мониторинг тоже надо проверять. Возьмите две самые пугающие метрики и сверьте руками с источником. Нам хватило получаса.

Оттуда же ещё подвох: правило алертинга, поправленное через sed -i, не применится. Проброшенный в контейнер поштучно файл держится за свой inode, а sed -i пишет новый. На хосте правку видно, контейнер читает прежний файл, перезагрузка конфигурации возвращает 200, а грузит старую версию.

Три инцидента с данными при статусе “доставлено”

Дефекты выше били по самой Шине. Следующие три хуже: страдали данные при статусе “доставлено” в журнале.

Часть потока уходила чужому потребителю. Продуктив и второй сеанс 1С одновременно читали одного и того же участника шины, и сообщения расходились между ними. Проверили 50 сообщений, в проде нашли 18, пропало 64 % выборки. Если распространить на всё окно, доверительный интервал получается от 51 % до 77 %.

Выручила идемпотентность приёмника. Повторы он отбрасывает, так что мы без раздумий отправили заново всё окно.

Самое важное отсюда: статус “доставлено” в журнале шины ещё не значит, что приёмник данные загрузил. Счётчик недоставленных такое не ловит в принципе, для Шины ведь всё штатно. Недоставленных у нас 61 на 26 миллионов, отличная цифра, только меряет она другое.

После рестарта Шины встают очереди в базе-приёмнике. Вставка падает с Cannot insert duplicate key на уникальном индексе входящей очереди канала. Номер позиции выдаёт Шина, после перезапуска она считает с меньшего значения, и новым сообщениям достаются номера, которые 1С уже встречала. Очереди строго FIFO, и одного конфликта в голове хватает, чтобы встал весь канал.

Лечит это у нас отдельный самописный сервис. Раз в минуту он проходит по очередям: за 30 дней сделал 48 833 прохода без единой ошибки и вмешался примерно 22 раза. Строку он удаляет только по жёсткому критерию, ошибка здесь стоит потерянного сообщения.

Сообщения ушли туда, где их никто не читает. Девять подтверждений получили ключ маршрутизации базовой очереди, а потребителей у неё ноль. Очередь без потребителя by design это тихая дыра: её либо явно вычёркивают из алертов, либо проверяют отдельно.

И общее условие для всех трёх. Тело сообщения шина хранит около шести часов, описание в базе живёт сутки, регистр 1С держит 14 дней. Спустя сутки после сбоя расследовать нечего.

Цифры и как они посчитаны

Начну с того, как считал: без этого таблицам верить не стоит.

Счётчик node_message_counter ведётся отдельно на каждом узле схемы. Если сложить все узлы, одно сообщение попадёт в сумму столько раз, сколько узлов оно прошло. На одном и том же окне разница у нас шестикратная: 147,5 миллиона по всем узлам и 26,1 миллиона сообщений.

sum(max by (process) (increase(node_message_counter[30d])))

Читается так: сообщения это сумма по процессам, где от каждого берётся наибольший счётчик среди его узлов. Сумма по всем узлам меряет объём работы, сообщений из неё не получить.

Скажу прямо: этот способ даёт заниженные цифры. В одном процессе бывает несколько независимых потоков навстречу друг другу. У нас в самом нагруженном процессе один поток дал 10,0 миллиона, обратный 9,8 миллиона, и максимум учёл только первый. По одному этому процессу недосчитано около 38 %, так что все числа ниже понимайте как “не менее”.

Поток

Показатель	Значение
Сообщений за 30 дней	не менее 26 092 008
Среднее по суткам	около 870 000
Медиана по суткам	830 547
Самые тяжёлые сутки	2 976 871
В среднем	около 10 сообщений в секунду
Пик пятиминутного окна	129,4 в секунду
Пик часового окна	102,6 в секунду

Между медианой и самыми тяжёлыми сутками разница в 3,6 раза.

На этой таблице я едва себя не обманул. Первая десятидневка окна дала в среднем по 722 788 сообщений в сутки, последняя уже по 958 108. Прирост 32,6 %, и я тут же набросал абзац про рост нагрузки. Его пришлось удалить. Управляющий слой в первые десять суток падал каждые день-два и обмены стояли, а за последние 8,5 суток не упал ни разу. Замер показал, как мы оправились после исправлений, рост нагрузки тут ни при чём.

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

Запас по ресурсам

Ресурс	Сейчас	Максимум за 30 дней
CPU хоста	24,7 %	59,7 %
Память контейнера Шины	5,5 ГБ	8,25 ГБ
load average (1 мин)	0,73	6,91

Процессора хватает с многократным запасом: миллион сообщений идёт при 22 % загрузки. С памятью запас меньше, контейнер доходил до 8,25 ГБ, а на весь хост её 15.

Пиковые 6,91 load average на четырёх ядрах настораживают. Я подозревал очередь на диск, но замер это не подтвердил: iowait в среднем составил 1,01 %, максимум 11,12 %. Другого объяснения у меня нет. Отчего подскакивал load average, я так и не выяснил. Пишу прямо, потому что гладкое объяснение само просится в текст и было бы придуманным.

Очереди самой Шины не копятся

Показатель	Значение
В очередях сейчас	56 сообщений
Максимум за 30 дней	422
95-й перцентиль	49
Максимум неподтверждённых	22

За месяц через Шину прошло 26 миллионов сообщений, а максимум очереди за это время 422. С июльским инцидентом это сходится: очередь в шине пустая, а канал при этом не движется.

Шина или прямой REST

Напрашивается вопрос, нужна ли шина вообще и не дешевле ли связать десять систем напрямую. Честно ответить не могу, покажу только, как устроен наш трафик.

Схемы смешанные: где-то HTTP-узлы, где-то очереди. За месяц HTTP пропустил 1 907 700 сообщений, почти все (1 891 016) пришлись на один обмен: CRM с программой лояльности. Архитектурной закономерности тут не видно.

Хочется написать, что команда сознательно развела задачи между HTTP и очередями по типу, но такой вывод я делать не стану: намерения из процентов не вычитаешь. Картину не хуже объясняет историческое наслоение.

Чек-лист эксплуатации

Развёртывание и рестарты

1. Задать stop_grace_period в Docker: брокеру с большим журналом дефолтных 10 секунд мало, у нас 300.
2. За рестарт Шины платят приёмники: позиции откатываются, входящие очереди в 1С могут встать.
3. После рестарта хранилище доставленных может оказаться пустым, а переотправлять больше неоткуда. Порядок такой: переотправляем, затем перезапускаем.
4. Штатный старт две минуты. Рекурсивный chown в entrypoint растягивает его примерно до четырёх с половиной, восстановление большого журнала брокером до девяти.
5. Нетерпеливый watchdog прибивает Шину посреди загрузки и крутит перезапуски по кругу.
6. Управляющий слой падает, если на проде включён development-mode.
7. Выключили режим разработки: приложение передеплоится, счётчики метрик обнулятся.

Мониторинг

8. Зонд проверяет управляющий слой, корневой URL не годится.
9. Следить за inode не меньше, чем за гигабайтами.
10. Кроме длины очереди, отслеживать возраст самого старого сообщения.
11. При суточных колебаниях потока в десятки раз пороговые алерты бесполезны.
12. Алерт на очередь без потребителя: срабатывать, только если потребителя нет И есть остаток.
13. Правило алертинга, смонтированное одним файлом (bind-mount), через sed -i не поправить.
14. Свои метрики тоже проверять.

Данные и доставка

15. Приёмник может не загрузить то, что шина считает доставленным. Сверка нужна сквозная, по идентификаторам.
16. Доставка at-least-once, значит приёмник обязан быть идемпотентным.
17. Сроки хранения на шине и в приёмнике отличаются на порядки.
18. Публичного метода для переотправки нет, только UI консоли.
19. Участник шины только для одного потребителя. Второй сеанс под ним тихо уведёт часть потока.
20. Включать хранение доставленных адресно и на время, с напоминанием выключить.

Что из этого следует

Тезис после года: в паре шины с 1С отказ чаще случается на приёмнике и выглядит как застревание, пропускной способности при этом хватает. Установка у нас одна, так что это наблюдение, на закономерность данных мало.

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

Готовые обработки по теме:

• Карта объёмов базы 1С - покажет регистры буфера обмена среди самых тяжёлых таблиц, хотя сами они растут незаметно.
• Чек-ап СУБД под 1С - Шина держит свои приложения на 24 базах PostgreSQL, и все они работают с настройками по умолчанию.

Настройка обменов и их наблюдаемости - часть нашей работы по обмену данными между базами 1С и мониторингу: ставим метрики, разбираем застревания и доводим до состояния, когда о сбое узнают раньше пользователей.