Как читать лог до причины

1. Что такое лог

Тёма ну очень хочет написать агенту «в игре что-то со счётом, почини». Но тормозится сам — Лёха вбил дисциплину: мысль «что-то не так» — не данные для починки. Нужна улика. А улику по словам Лехи даёт лог. Слово знакомое, но что это конкретно, Тёма толком не знает — и ловит проходящего Олега.

— Дядь Олег, а лог — это вообще что? Та простыня, которую я всегда мотаю и закрываю?

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

— И где этот дневник посмотреть?

— А вот тут бывает по-разному, — Олег загибает пальцы. — Иногда программа пишет лог в файл на диск — тогда он лежит там и после, можно открыть хоть завтра. Помнишь свой ночной журнал, что сбой пережил? Вот это лог в файл. А иногда пишет в консоль — прямо в чёрное окно терминала, тут же на глазах. Тесты, например, орут в консоль: прогнал — сразу видишь, что вышло. Файл или консоль — суть одна: программа сама рассказывает, что с ней происходит.

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

2. Лог теста и лог падения — не путать

— Только держи в голове, — добавляет Олег, — сегодня у тебя два разных лога, и мешать их не надо.

Он показывает на пальцах.

— Первый — лог теста. Это когда твой проверяльщик отчитался: ждал три, получил тридцать, вот и FAIL. Это доклад контролёра — что он проверял и что не сошлось. Второй — лог падения, по-умному стектрейс, «след стека вызовов». Это когда сама программа споткнулась и записала, в каком месте кода рвануло. Контролёр говорит «результат неверный», а стектрейс — «рвануло вот на этой строке». Разные вещи: один про итог, другой про место.

— А мне какой нужен?

— Тебе сейчас — второй, который тычет в строку. Чтоб не гадать, где чинить. Хотя удобно, когда тест пишет их разом: и «неверный результат», и «вот где». Сейчас найду пару примеров у себя и покажу.

3. Стектрейс ведёт до конкретной строки

Пока Олег ищет подходящие примеры, Лёха вклинивается в разговор. Сначала воспроизводим баг, чтоб игра сама написала о проблеме. Гоняем тесты, ловим падение:

npm test

  ✖ три в ряд дают 3 очка (по 1 за совпадение)
    AssertionError [ERR_ASSERTION]: Expected values to be strictly equal:

    30 !== 3                                          ← получили 30, ждали 3

      at TestContext.<anonymous> (src/bonus-game/score.test.js:8:10)   ← строка теста, где не сошлось

— Смотри, тут обе штуки разом, о которых тебе Олег говорил, — Лёха намекает на вывод. — Верх, 30 !== 3 (получили тридцать, ждали три), — это лог теста: контролёр доложил, значения не сошлись. А низ, at … (src/bonus-game/score.test.js:8:10), — это след: точный адрес строки, где проверка не сошлась. src/bonus-game/score.test.js — файл. 8 — строка. 10 — символ. Иди туда и смотри, ЧТО именно проверялось.

Тёма открывает score.test.js, строка 8 — а там всё написано: assert.equal(calcScore(3), 3). Тест звал функцию calcScore и ждал от неё тройку.

— То есть лог мне и симптом дал, и адрес, — Тёма подаётся к экрану. — «Тридцать вместо трёх» — это контролёр, а строка теста называет виновника по имени: calcScore. Не стена текста, а лестница: лог ведёт в тест, тест ведёт в функцию.

Та самая «страшная простыня», которую он неделями мотал и закрывал не глядя, на глазах превращается в карту. Раньше смотрел на лог как на ругань, которую надо переждать. А сейчас читает как адрес: дом, этаж, квартира.

Тёма открывает src/bonus-game/score.js и мотает до calcScore — не наугад по всему проекту, а ровно туда, куда привела лестница. Палец на колёсике, строка 7, 8, 9.

Вот она.

Строка 9: каждое совпадение умножается на константу POINTS_PER_MATCH — и вот она, выше в файле: POINTS_PER_MATCH = 10. А должна быть 1. Одна цифра. Три совпадения вместо «плюс три очка» дают «три раза по десять» — вот откуда стабильная тридцатка, которую он всё утро ловил руками в игре.

— Да ты что, — выдыхает Тёма. — Вся эта наглая аркада, что улыбалась и врала, — это вот эта одна цифра?

Он даже немного разочарован, что так просто. Корень не угадан, не вымучен тыканьем по файлам — он нашёлся глазами по логу за минуту.

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

— А теперь фокус, — продолжает Лёха. — Этот самый лог ты не держишь в голове и не пересказываешь агенту своими словами. Ты отдаёшь ему саму улику. Смотри, в чем разница.

❌ так:  в игре очки считаются неправильно, посмотри почини
✅ так:  баг в calcScore (src/bonus-game/score.js:9): 3 совпадения дают 30 вместо 3,
         константа POINTS_PER_MATCH=10 вместо 1. Стектрейс: [вставлен лог].
         Почини причину, соседние зоны игры не трогай.

— Чувствуешь разницу исходных данных? — Лёха доволен. — В первом случае агент пойдёт тыкать наугад, может полезть чинить отрисовку или перепишет не тот модуль. Во втором — у него точная улика, и он чинит адресно. Дашь эмоцию — получишь догадки. Дашь улику — получишь работу по делу.

Тёма возвращается к своему ТЗ и переписывает строку дефекта. Утром он написал расплывчато: «логика счёта врёт». А теперь та же строчка ужалась до точной — файл, функция, строка, причина:

# было утром:
ДЕФЕКТ:  3 в ряд начисляет 30 очков вместо 3 (логика счёта врёт)

# стало после лога:
ДЕФЕКТ:  calcScore (src/bonus-game/score.js:9) — POINTS_PER_MATCH=10 вместо 1:
         3 совпадения → 30 очков вместо 3

Не «что-то со счётом», а файл-функция-строка-причина. Чем точнее вход, тем меньше шансов, что агент уйдёт лечить не ту болячку.

4. Проверку проектируют под конкретный баг

Перед тем как звать агента чинить, Лёха пишет вторую важную мысль — и она про то, КАК проверять.

— Смотри, — говорит он. — Тесты бывают разные. Их в проекте обычно куча — на разные случаи. И тут легко попасть в ловушку: «прогоню-ка я всё подряд, авось зелёное». Гоняешь весь ворох, глядишь на общее «всё прошло» — и вроде спокоен.

— А что не так? Прогнал всё — значит, всё проверено.

— Не значит. Среди этого вороха может вообще не быть теста на твой баг. Прогнал сотню чужих проверок, все зелёные — а твою тридцатку-вместо-трёх ни одна из них и не смотрела. Ты обрадовался зелёному, а оно про другое. Поэтому профессиональный подход другой: не «прогнать что есть», а сделать проверку конкретно под свой баг.

— То есть?

— А вот смотри, в чём разница. — Лёха разворачивает на пальцах. —По-детски было бы так: «ну прогоню тесты, гляну, зелёно ли». Абы какие, оптом. А по-взрослому ты сначала спрашиваешь себя: какой именно тест поймает ровно ЭТОТ сбой? У тебя баг — три в ряд даёт тридцать. Значит, тебе нужен тест, который проверяет ровно это: «дай счёту три в ряд, жди ровно три». Ты его назвал, ты знаешь, что он ловит. И если ОН зелёный — вот это уже про твой баг, а не про сто соседних.

Тёма кивает — теперь понятнее. Проверка не «прогнать наугад», а сделанная под цель: знаешь, что проверяешь, знаешь, какой ответ верный. Как ТЗ пишут под задачу, а не «сделай что-нибудь».

— Уложилось? — Лёха будто чувствует, что не до конца. — Ладно, слова словами. Сейчас увидишь сам, зачем это. Позовём агента чинить, он принесёт тебе зелёный тест, всё чин по чину. А я после покажу одну штуку, после которой ты на голое «зелёное» больше не купишься. Вот тогда и поймёшь, почему проверку надо строить с головой, а не прогонять оптом.

Тёма пожимает плечами и идёт звать агента. Что там за штука — поглядим.