З початку 2026 року у клієнта спостерігалась нестабільна робота системи передачі даних на маркувальне обладнання Dibal. Помилка довгий час вважалась наслідком дій операторів — поки детальний аналіз не вказав на приховану логічну колізію у СУБД MySQL 5.0.
Вступ і постановка задачі
Проблема проявлялась хаотично: при відправці товарів через RGI частина текстових полів (з 12 по 30), що містили інформацію для етикетки різними мовами, інколи не передавалась на обладнання — хоча дані коректно потрапляли у DIS. Через неповну передачу інформації на лінію виходили упаковки з некоректними або неповними етикетками.
Після аналізу логів та виїзної діагностики вдалось підтвердити, що проблема відтворюється на стороні програмного забезпечення Dibal DIS версії 1.11W.
Особливість інциденту полягала в тому, що помилка виникала непередбачувано: один і той же набір даних міг бути переданий коректно або частково — лише при зміні коду товару. За результатами тестування, ймовірність виникнення проблеми складала близько 30% відправлень.
Вихідні дані архітектури
- Операційна система: Windows 10.
- Керуюче ПЗ: Служба
RGI_i.exe— компонент інтеграційного пакету Dibal DIS. Моніторить директоріюC:/DibalExport. При появі файлуimportas2.xlsxпарсить його, транслює дані по протоколу TCP пакетами-регістрами на LS4000 та виконує запис до локальної СУБД MySQL. Після завершення циклу файл переміщується доC:\Program Files (x86)\Dibal\DIS\RGI\Processed filesз додаванням часового штампуYYYYMMDDHHmmss_Importas2.xlsx. - СУБД: MySQL Server 5.0.19-nt (база даних
sys_datos_dis, рушій таблицьInnoDB). - Обладнання: Ваговимірювальний комплекс Dibal LS4000 (порт
3000). - Еталонний показник: При штатному циклі імпорту ПЗ повідомляє в консоль: «Передано 38 записів».
Постановка проблеми
В певний момент часу поведінка комплексу змінилась. При відправці файлу з певним ідентифікатором товару (ID=5) утиліта RGI_i.exe відправляла на ваги лише 15 записів, після чого коректно (без падіння процесу) завершувала цикл і переміщувала файл до архіву.
RGI_i.exe та повне перезавантаження ОС сервера не усували аномалію. Якщо в тому ж файлі Excel змінити значення комірки ID з 5 на 1 — утиліта миттєво відпрацьовувала штатно, передаючи всі 38 записів.
Чому стандартні логи не показували проблему?
Застосунок RGI_i.exe не логує кількість рядків, повернених MySQL-запитом — лише результат відправки. Якщо MySQL повернув 15 рядків, застосунок чесно відправив 15 пакетів і написав «Передано 15 записів». З точки зору застосунку — все штатно.
Хронологія розслідування та етапи локалізації
Етап 1: Розгортання лабораторного стенду та перевірка первинних гіпотез
Оскільки з подібною містичною поведінкою системи за 6 років експлуатації ми зіткнулись вперше, проведення тестів на «живому» сервері клієнта було неприпустимо. Прийнято рішення ізолювати проблему у контрольованому середовищі.
Дія: З об'єкту клієнта було вилучено: резервну копію бази даних MySQL, оригінальні лог-файли та файли імпорту importas2.xlsx. У лабораторії розгорнуто два ідентичних незалежних стенди, що повністю дублювали бойове оточення: серверна частина (MySQL 5.0 + DIS Suite + RGI_i.exe) та апаратна частина (фізичні машини Dibal LS4000).
Результат: Ми методично гоняли імпорт файлів, намагаючись зловити момент, коли система спіткнеться. Удача посміхнулась на одному зі стендів: як тільки у файлі імпорту ID товару змінено на 5, конвеєр завантаження зламався — ваги прийняли лише 15 записів (регістрів) замість належних 38. Стабільний баг спійманий у контрольованому середовищі.
ID=5 трансляція обривалась на 15 пакетах. Висновок: Проблема має персистентний (постійний) характер і жорстко зафіксована у структурі даних СУБД.
Етап 2: Мережевий аналіз та дешифровка TCP-трафіку
Гіпотеза №2: Апаратний збій ваг або спотворення пакетів на фізичному рівні. Передбачалось, що ваги Dibal LS4000 нативно відбраковують специфічну послідовність байт, що генерується при обробці ID=5, або мережевий стек ОС некоректно обробляє сокет.
Дія: Між процесом RGI_i.exe та вагами включено сніфер трафіку Packet Sender, налаштований на прослуховування порту 3000. Перехоплено байтові потоки для обох сценаріїв.
Результат: Аналіз сирого трафіку показав, що мережа працює ідеально. Формат команд Dibal DIS повністю відповідав специфікації. Пакети летіли у абсолютно правильному порядку, підтвердження (ACK) від ваг приходили без затримок. Сніфер зафіксував:
- Для
ID=1: Успішні транзакціїTCP Send, після чого ініціалізувавсяTCP Disconnect. - Для
ID=5: Успішні транзакціїTCP Send, після чого з боку сервера летів пакет закриття сесіїFIN/ACK.
RGI_i.exe сам, за власною ініціативою, приймає рішення закрити сокет після відправки 15 записів. Мережевий слід привів назад всередину сервера.
Етап 3: Порядковий аналіз системних журналів (Process Monitor)
Оскільки ПЗ працювало і не генерувало виключень (Exception), потребувалось дослідити його взаємодію з ОС та СУБД на рівні ядра.
Дія: Запущено Process Monitor. У диспетчері фільтрів встановлено правила: Process Name IS RGI_i.exe та Process Name IS mysqld-nt.exe.
- Запуск файлу з
ID=5(збій) → Експорт уLogfile.CSV. - Запуск файлу з
ID=1(норма) → Експорт уLogfileGood.CSV.
Знято два трейси: Logfile.CSV (12 373 рядки) та LogfileGood.CSV (14 906 рядків).
Аналіз трейсів: що показав Process Monitor
Кількість TCP-пакетів до ваг — підтвердження
"16:14:26,6170903","RGI_i.exe","13840","TCP Send", "IGPRESTADO3.deriods.local:57652 -> 192.168.150.144:3000", "SUCCESS","Length: 130, startime: 2614704, ..."
"16:27:34,6402458","RGI_i.exe","13840","TCP Send", "IGPRESTADO3.deriods.local:57782 -> 192.168.150.144:3000", "SUCCESS","Length: 130, startime: 2693506, ..."
Обидва пакети ідентичні за структурою: 130 байт, одне з'єднання. BAD відправив рівно 15 таких пакетів та зупинився. GOOD — 38.
Перша відмінність: звернення до файлів схеми MySQL (.frm)
Це і є ключова аномалія:
| Метрика | BAD | GOOD |
|---|---|---|
Звернень до .frm-файлів | 282 | 2 |
| Таблиць з повним читанням схеми | 26 | 0 |
Звернень до dat_articulo_t_b.frm | 9 | 0 |
В MySQL 5.0 файл .frm містить схему таблиці. В нормі схема кешується у table_cache. Якщо MySQL вимушений повторно читати .frm з диску — це може означати, що кеш було скинуто. Причина скидання: виконання запиту, який зажадав тимчасової перебудови структури — наприклад, складний JOIN з великою кількістю рядків в одній із таблиць.
З трейса BAD, вікно підготовки даних (між виявленням файлу та першим TCP-пакетом до ваг):
"16:14:26,2334247","mysqld-nt.exe","1980","CreateFile",
"...sys_datos_dis\dat_articulo_t_b.frm",
"SUCCESS","Desired Access: Generic Read, Disposition: Open..."
"16:14:26,2334766","mysqld-nt.exe","1980","ReadFile",
"...dat_articulo_t_b.frm",
"SUCCESS","Offset: 0, Length: 64, Priority: Normal"
"16:14:26,2335120","mysqld-nt.exe","1980","ReadFile",
"...dat_articulo_t_b.frm","SUCCESS","Offset: 64, Length: 7"
"16:14:26,2335241","mysqld-nt.exe","1980","ReadFile",
"...dat_articulo_t_b.frm","SUCCESS","Offset: 4096, Length: 104"
"16:14:26,2335866","mysqld-nt.exe","1980","CloseFile",
"...dat_articulo_t_b.frm","SUCCESS",""
"16:14:26,2341394","mysqld-nt.exe","1980","CreateFile",
"...dat_articulo_t_b.TRG","NAME NOT FOUND",
"Desired Access: Read Attributes, Disposition: Open..."
MySQL читає схему dat_articulo_t_b повністю з диску (5 послідовних ReadFile по всіх секціях .frm-файлу), потім намагається знайти тригер .TRG — і не знаходить його (NAME NOT FOUND). У GOOD-сценарії цих операцій немає взагалі: схема була у кеші.
Повна часова шкала інциденту
16:14:26,0897 RGI виявляє Importas2.xlsx 16:14:26,1825 MySQL створює тимчасову таблицю — початок JOIN-запиту 16:14:26,2334 MySQL читає dat_articulo_t_b.frm з диску (НЕ з кешу!) 16:14:26,6171 RGI відправляє ПЕРШИЙ регістр (130 байт) → ваги :3000 16:14:27,0705 RGI відправляє ОСТАННІЙ регістр — підсумок: 15 відправлено 16:14:27,0778 RGI пише в EnvioModificaciones_log — сесія завершена
16:27:34,1800 RGI виявляє Importas2.xlsx
16:27:34,2683 MySQL створює тимчасову таблицю — початок JOIN-запиту
[.frm файли НЕ читаються — схема у кеші]
16:27:34,6402 RGI відправляє ПЕРШИЙ регістр (130 байт) → ваги :3000
16:27:35,4631 RGI відправляє ОСТАННІЙ регістр — підсумок: 38 відправлено
16:27:35,4705 RGI пише в EnvioModificaciones_log — сесія завершена
Характеристики передачі
| Метрика | BAD | GOOD |
|---|---|---|
| Пакетів відправлено | 15 | 38 |
| Байт відправлено | 1 950 | 4 420 |
| Тривалість передачі | 0,453 сек | 0,823 сек |
| Час на пакет | 30,2 мс | 24,2 мс |
| Розмір кожного пакету | 130 байт | 130 байт |
Корінна причина: дублікати у dat_articulo_t_b
Process Monitor вказав на dat_articulo_t_b як на аномальну точку. Наступний крок — аналіз вмісту таблиці напряму.
Структура таблиці
CREATE TABLE `dat_articulo_t_b` ( `IdArticulo` int(11) NOT NULL, `IdEmpresa` int(11) NOT NULL DEFAULT '1', `IdTienda` int(11) NOT NULL DEFAULT '1', `IdBalanza` int(11) NOT NULL DEFAULT '0', -- ... поля стану ... PRIMARY KEY (`IdEmpresa`, `IdTienda`, `IdBalanza`, `IdArticulo`), KEY BusquedaArticulos (`IdEmpresa`, `IdArticulo`) ) ENGINE=InnoDB ROW_FORMAT=DYNAMIC;
Таблиця є зв'язковою: вона зберігає, які артикули (IdArticulo) призначено на які ваги (IdBalanza). Саме по ній RGI будує список регістрів для відправки.
Дублікати у даних
У таблиці були присутні записи з однаковим IdArticulo=5 для однакових IdTienda/IdBalanza, що неможливо при дотриманні PRIMARY KEY. Це могло статись через прямий імпорт даних в обхід обмежень або при використанні INSERT IGNORE / REPLACE INTO.
-- Коректні записи (різні IdBalanza) (5,1,1,1, 0,0,0,0,0,0,'M','usuario','2024-07-05 08:36:29'), (5,1,1,2, 0,0,0,0,0,0,'M','usuario','2024-07-05 08:36:29'),
При наявності дублів MySQL змушений виконувати запит без використання індексу на частині шляху — еквівалент повного сканування з дедуплікацією. Це призводить до:
- Скидання
table_cache(звідси — читання.frmз диску). - Повернення непередбачуваної підмножини рядків замість повного результату.
- Відсутності будь-яких помилок у логах — MySQL технічно виконав запит успішно.
Чому залежить від значення ID?
RGI_i.exe будує список відправки, запитуючи dat_articulo_t_b з фільтром по IdArticulo. При ID=5 (з дублями) — запит потрапляв у деградований шлях виконання. При іншому ID — використовувався нормальний індексний шлях, що повертав усі 38 рядків.
Реалізовані рішення та ліквідація наслідків
Оскільки проблема полягала у пошкодженні логічних зв'язків конкретних рядків, стандартні утиліти відновлення таблиць (REPAIR TABLE неприйнятний для InnoDB, а OPTIMIZE TABLE перебудовував фізичну структуру файлів, не видаляючи логічні колізії даних всередині рядків) виявились неефективними.
Очищення пошкоджених сутностей у СУБД
Для повної ліквідації заклинілих індексів прийнято рішення примусово очистити всі дані з таблиці dat_articulo_t_b, змусивши ПЗ відтворити її структуру з чистого аркушу.
На тестовому стенді (а потім і на бойовому сервері) зупинено службу RGI_i.exe та виконано наступний SQL-скрипт:
-- Перемикання на цільову БД USE `sys_datos_dis`; -- Видалення заклинілих записів артикула з ключових таблиць DELETE FROM `dat_articulo_t_b` WHERE `IdArticulo` > 0; -- Відтворення таблиці з повною перебудовою даних і індексів ALTER TABLE `dat_articulo_t_b` ENGINE=InnoDB; -- Скидання глобального кешу запитів СУБД RESET QUERY CACHE; FLUSH TABLES;
RGI_i.exe та повторної подачі файлу з ID=5 утиліта ініціалізувала запис у СУБД «з нуля». Конвеєр успішно пройшов усі стадії, і на ваги LS4000 полетіли штатні 38 записів. Проблему повністю усунуто.
Висновки та Post-Mortem
Цей інцидент — класичний приклад того, як специфіка обробки помилок у ПЗ може маскувати проблеми у СУБД. Програма не видавала статус ERROR або CRITICAL, вона виконувала логічно легітимний (з її точки зору) цикл роботи, ґрунтуючись на спотворених даних, що повертались MySQL.
Ключові висновки
SUCCESS або штатне завершення роботи, але результат не відповідає еталону — спускайтесь на рівень нижче (до системних викликів ядра ОС).