В моей старой системе учёта валютной позиции больше двадцати лет стоял коммерческий инструмент трассировки от конторы, которая делала SoftICE. Он работал исправно, о каждой ошибке присылал письмо со стеком вызовов — и не помог мне ни разу. Недавно я наконец понял, почему так вышло, и ответ оказался до обидного простым.
Кто это писал
В 1999 году я пришёл дилером в казначейство небольшого банка. Систему учёта позиции писал себе сам, вечерами, потому что писать её было больше некому: я не программист, я просто хотел, чтобы утро начиналось не с ручной сверки. Про то, как в этой системе жили остатки, я уже рассказывал. Теперь про то, как в ней жила отладка.
Сразу главное, чтобы дальше читалось правильно. Стек вызовов отвечает на вопрос «где упало». А мне нужен был ответ на вопрос «что к этому привело у пользователя?». Это разные вопросы, и на то, чтобы увидеть между ними разницу, у меня ушла заметная часть жизни.
Инструмент верхней полки с палёного диска
VB6 компилируется, и у скомпилированной программы есть неприятное свойство: когда она падает у пользователя, ты узнаёшь номер ошибки и её текст, но не строку. Функция Erl возвращает номер строки только там, где строки пронумерованы, а нумеровать руками десятки тысяч строк никто, разумеется, не будет.
Для этого существовал FailSafe. Не самоделка: продукт Marquis Computing, чьи активы в 1995 году выкупила NuMega Technologies — та самая, что делала SoftICE и BoundsChecker. Дальше судьба у него была такая:
Когда | Что |
|---|---|
до 1995 | Marquis Computing, продукты VB/CodeReview и VB/FailSafe |
1995 | активы выкупает NuMega Technologies |
1997 | NuMega покупает Compuware, инструмент входит в пакет DevPartner Studio |
2009 | Compuware продаёт портфель NuMega британской Micro Focus |
Четыре владельца, потом тишина: продукта давно нет, а проблема, которую он решал, жива и сегодня, просто теперь стектрейс дают из коробки.
Мне FailSafe достался на компакт-диске, из тех, что тогда ходили по рукам. Лицензии у меня, разумеется, не было. Сколько он стоил в магазине, я даже не выяснял.
Работал он так: проходил по всему проекту, нумеровал строки и оборачивал каждую процедуру обвязкой. На входе fsPUSH с именем модуля, процедуры и склеенными в строку аргументами, на выходе fsPOP:
fsPUSH "frmMain.frm", "Sub cli_edit_Click", "(" & ")"
В одном только frmMain.frm таких обёрток 141, а пронумерованных строк — 2913. Сам модуль FAILSAFE.BAS — 2787 строк, и в нём есть всё, что положено взрослому инструменту: журнал, ассерты, отправка отчёта об ошибке письмом через MAPI с приложенным логом, даже профайлер. Открывается модуль строкой «YOU ARE ADVISED NOT TO TAMPER WITH THIS CODE», и я не тамперил.
И надо отдать ему должное: инструмент был по-настоящему бескомпромиссным. Скомпилированная программа — это просто exe, установленный у пользователя, и когда она спотыкается, понять, на какой строке, вообще не через что: не ставить же каждому бухгалтеру Visual Studio, чтобы гонять учётную систему из-под отладчика. А с FailSafe я видел модуль, процедуру, строку, стек и значения аргументов. Другого способа получить это не существовало.
Почему это не помогало
Письма с трассировками просто приходили. Я не понимал, что из этого можно извлечь.
Долго думал, что дело во мне. Потом — что в инструменте. На самом деле ни то, ни другое: настоящие беды моей системы не были падениями, а были балансом, который утром не поправился, переоценкой с убытком, которого никто не ждал, сделкой по дикому курсу, взявшейся непонятно откуда. Программа во всех этих случаях не падала, она спокойно работала и показывала не те цифры, а инструмент, который умеет отвечать только на «где упало», молчит ровно тогда, когда ничего не упало.
Таких сигналов, которые приходили и не работали, у меня за годы накопилось несколько: письма о коррекции остатков, поле USERNAME в служебной метке, слово really в названии проверки внутри утилиты сверки, которую я сам же написал и забыл, и, наконец, письма с трассировками. Общее у них одно. Каждый честно отвечал на вопрос, который задал ему автор его кода, — и ни один не отвечал на вопрос, который возникал у меня утром: что вообще случилось этой ночью с вот этой цифрой и почему?
Инструмент отвечает на свой вопрос, а не на твой. Вот и вся разгадка, на которую ушло столько лет.
Что я сделал во второй системе
Новую систему я начал не с инструмента, а с вопроса. Вопрос звучит так: «что случилось с этим конкретным обращением?» — где обращение это запрос пользователя, прогон импорта, работа фонового воркера. Ответом стал код обращения, он же trace ID, механика известная.
Устроено просто. На входе стоит middleware. Если запрос пришёл от вышестоящего сервиса с валидным заголовком X-Trace-Id, код берётся как есть — тогда у сервиса и у бэкенда один код на всю цепочку. Если заголовка нет (браузер его не шлёт), код генерируется: uuid4().hex, 32 символа. Дальше код никогда не меняется, только передаётся.
А теперь то, ради чего всё затевалось — куда этот код доходит:
в каждую строку лога, через фильтр логирования. Вне запроса в колонке стоит
-, а не пустота, чтобы формат не схлопывался и греп по коду не цеплял чужие строки;в заголовок любого ответа, успешного и ошибочного;
в тело ошибки: пятисотка отдаёт
{"detail": "internal_error", "trace_id": ...};в журнал аудита, отдельной колонкой на экране;
в логи фоновых воркеров, у которых свои коды на каждый цикл, и в журнал прогонов импорта, где рядом живёт код прогона: там прослеживается уже не запрос, а вся ночная загрузка целиком.
Первые пользователи у системы еще только скоро появятся, так что первым клиентом собственной поддержки оказался я сам. Меня не пускал логин. Симптом «не пускает» гонит проверять пароль, токен, права — я и погнался было. Потом взял номер из тела ошибки, грепнул по логам и через секунду читал строку с причиной: пользователь не сохранился, и аутентификация была вообще ни при чём. Симптом показывал в одну сторону, причина сидела в другой — ровно тот случай, на котором старая система держала меня годами.
Чем ключ отличается от стека
Стек описывает место падения. Ключ связывает цепочку: заголовок, строки лога, тело ошибки, запись в журнале — всё это теперь один сюжет, который поднимается одним грепом. Но главное свойство ключа даже не это. Его может назвать человек, который не видит ни логов, ни кода, ни стека: «у меня ошибка, вот номер». Стек вызовов по телефону не продиктуешь.
А дальше — то, ради чего это всё затевалось. По номеру поднимается вся цепочка: что пришло, через что прошло, на чём сломалось, — и проблему можно воспроизвести у себя, не отрывая человека от работы. Вопрос, с которого десятилетиями начинается любой разбор — «а как вы получили эту ошибку?» — задавать больше незачем: ответ уже записан.
Одна деталь для тех, кто пойдёт делать то же самое на FastAPI. Первый соблазн — взять BaseHTTPMiddleware, и это ошибка: он исполняет приложение в отдельной задаче со своим контекстом, и contextvars, выставленный на входе, виден на пути ответа не везде. Пришлось писать чистый ASGI-middleware: один контекст на весь запрос, set на входе, reset в finally. Вторая засада — синхронные эндпоинты, которых у меня 210: они исполняются в threadpool и получают копию контекста, так что читать код оттуда можно, а изменить его так, чтобы увидел middleware, нельзя.
Проверить всё это на настоящих пользователях мне пока не на ком. Возможно, первый же живой человек вместо номера скажет мне «там какие-то буквы красным». Посмотрим.
Возражения
«Это же обычный correlation ID, OpenTelemetry даёт его из коробки». Даёт, и механика описана сто раз. Я и не претендую на открытие. Интересно здесь другое: десятилетиями рядом со мной жил инструмент, который собирал куда больше данных — и не отвечал на мой вопрос. И ещё последний метр: в типовой связке trace ID живёт в логах и APM, куда пользователь не заглянет. До тела ошибки, которое человек видит на экране и может процитировать, его доводят почему-то редко.
«VB6, легаси, на дворе 2026-й». Язык здесь ни при чём. Инструмент, отвечающий не на тот вопрос, прекрасно заводится в любом стеке — сколько сейчас систем, где OpenTelemetry стоит, потому что положено, а на вопрос «что случилось с этой цифрой» по-прежнему отвечают перекладыванием логов руками?
«Почему не Sentry, не готовый APM». Контур банковский, наружу нельзя ничего. Но причина глубже: со сбором данных прекрасно справлялся и FailSafe. Не хватало не данных, а ключа, по которому их можно связать и найти.
«68 файлов ради request ID — оверинжиниринг». Задевающих код файлов действительно 68, только точек всего две: middleware, который код рождает, и фильтр лога, который его подмешивает. Остальное — места, где код читается или показывается человеку. Дорого стоит не механика, а дисциплина «код доходит до всех, кому он нужен».
Что я из этого вынес
Сначала называю вопрос, потом ставлю инструмент. «Где упало» и «что случилось с этим обращением» — два разных вопроса, и отвечают на них разные вещи.
Ключ рождается один раз в начале цепочки и дальше не меняется. Чужой валидный берём как есть, свой генерируем только когда мы первые.
Ключ обязан доходить до человека: в тело ошибки, на экран. Ключ, живущий только в логах, отвечает инженеру, а спрашивает обычно не инженер.
По ключу цепочка не только ищется, но и воспроизводится. Вопрос «как вы получили эту ошибку» исчезает из разговора с пользователем совсем.
Пустое значение хуже заглушки:
-в колонке лога держит формат и не даёт поиску цеплять чужие строки. Мелочь, а сэкономила мне уже не один греп.
А палёный диск с FailSafe от NuMega, наверное, до сих пор лежит в какой-нибудь коробке. Выбрасывать было жалко: инструмент-то был хороший.
