Выгрузка данных не запускалась полтора месяца. Все запуски отчитались успехом

Цепочка из пяти шагов, каждый по расписанию. Планировщик показывает выполнение без ошибок. Файлы на месте, даты обновляются, претензий нет ни у кого.

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

Дальше разбор трёх независимых механизмов, каждый из которых превращал провал в успех. Ни один не был сложным. Втроём они продержались до самого аудита.

Что показал аудит

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

Период с середины июня по двадцатое июля, шесть прогонов, раз в пять-шесть дней. Матрица по пяти шагам получилась такая:

Обратите внимание на форму отказа. Это не "иногда падало" и не "стало хуже под нагрузкой". Ровно ноль на двух конкретных позициях при шести из шести на остальных.

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

Практический вывод. Прежде чем искать причину, посмотрите на форму отказа. Ноль из шести и четыре из шести - разные поломки, и лежат они в разных местах.

Почему два шага не выполнялись

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

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

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

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

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

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

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

Шаг, который "работал"

Теперь про механизм, из-за которого история и стала интересной.

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

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

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

Все внешние признаки при этом идеальные. Задание отработало. Файл создан. Дата файла свежая. Размер правдоподобный. Ошибок нет.

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

Это худший вид зелёного из всех. Молчащий отказ хотя бы молчит, и рано или поздно кто-то заметит тишину. Здесь механизм активно подтверждает, что всё в порядке: вот запуск, вот результат, вот дата. Чем аккуратнее сделан такой шаг, тем убедительнее он врёт.

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

Коды возврата были инвертированы

Третий механизм самый обидный: он ломал единственный оставшийся способ понять, что происходит.

Проверили, что именно возвращают исполняемые файлы цепочки. Все три врали, причём по-разному:

• один возвращал ненулевой код при успешном завершении;
• два возвращали ноль при провале.

У первого нашлась конкретная причина: неэкранированные скобки в выводе внутри условного блока. Файл делал работу целиком, а на выходе сообщал об ошибке, которой не было. Два других глотали код ошибки: падение внутри до внешнего результата просто не доезжало.

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

Практическое следствие для мониторинга оказалось убийственным. Если бы кто-то настроил оповещения по кодам возврата, красное горело бы там, где всё хорошо, а там, где тридцать пять дней ничего не происходит, было бы тихо. Такой мониторинг увёл бы разбор в противоположную сторону, и увёл бы уверенно.

Обратите внимание на счёт: три файла из трёх. Это не совпадение. Причина у всех трёх общая: код возврата в них не проверяли ни разу с момента написания. Никто не портил его нарочно, просто эта величина никогда никого не интересовала и свободно дрейфовала куда угодно.

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

Проверочный шаг тоже врал

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

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

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

Отдельное задание и один файл, сделанный руками

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

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

Из-за этого файла задание выглядело живым. Файл есть, дата есть, всё в порядке.

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

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

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

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

Что общего у трёх механизмов

Соберём вместе. Три независимых способа обмануться:

1. шаг не запускался, но соседи запускались, и цепочка целиком выглядела рабочей;
2. шаг запускался и работал, но по срезу от десятого июня;
3. коды возврата инвертированы, поэтому любой контроль поверх них показал бы обратное.

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

Здесь стоит развести три утверждения, которые в разговоре сливаются в одно.

"Задание запустилось" - планировщик его вызвал. "Задание отработало" - процесс завершился и не сообщил об ошибке. "Работа сделана" - результат существует и построен на актуальных данных.

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

Что мониторить вместо запуска

Практическая часть, переносимая на что угодно.

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

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

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

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

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

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

Границы применимости

Механизм описан для пакетных сценариев под планировщиком. Инвертированные коды возврата - специфика этой конкретной реализации, и утверждать, что так у всех, я не буду. Проверять надо своё.

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

Опечатка с переносом строки воспроизводится только в среде запуска. В интерактивном режиме конструкция отрабатывает корректно, поэтому обычная проверка руками её пропускает.

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

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

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

Сколько ещё заданий в том же планировщике болеют тем же, не проверено. Посмотрели три файла одной цепочки, все три оказались с дефектом. Соседние задания никто не открывал, хотя после такой находки это первое, что напрашивается.

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

Открытый вопрос

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