У меня в управлении и разработке сервис, который обрабатывает большой поток PDF файлов, собранных различными генераторами. В начале июня произошел инцидент, в котором поды поднялись в пик количества по HPA и наглухо зависли на 30 минут. 100% CPU, обработка стоит, очередь копится, алерты летят пачками спустя 30 минут зависания.
Тогда было принято решение чинить не проблему, а симптом. Как по мне, лучшее решение в ситуации с инцидентом. Но недавно руки дошли выявить корень проблемы, и крылся он в используемом open source. Это история о том, как закомментированный panic превращается в бесконечный цикл, а санитайзер, не знающий полный алфавит, молча портит данные.
Действующие лица
Для Go экосистема PDF‑парсинга растет из одного корня:
rsc/pdf — библиотека Расса Кокса, которая заархивирована уже как 8 лет;
ledongthuc/pdf — самый живой наследник, 615 звезд, 358 импортов. Не обновляется с прошлого года;
dslipak/pdf — форк, который используется у меня на проде (достался с легаси‑частью проекта).
Все 3 — это, по сути, одна кодовая база с разными наборами патчей.
Инцидент
Симптомы: воркер берет из очереди PDF, уходит в page.Content() и не возвращается. 100% CPU на ядре. Нет ошибок, нет паник, тишина и несколько ретраев.
Файл это легальный документ, сгенерированный коммерческим генератором документов. Документ можно открыть любым просмотрщиком PDF‑документов. pdftotext разбирает его без каких либо проблем.
Первое, что бросилось в глаза, это стримы, закодированные /ASCII85Decode, что само по себе не самое частое явление, ведь большинство генераторов кладут бинарный flate. Первая гипотеза: проблема в ASCII85.
Спойлер
Забегая вперед, гипотеза оказалась ложной, но об этом чуть позже
Костыль, который пошел в прод
Когда прод лежит, не до красоты. Я сделал 2 слоя защиты.
Слой первый — жесткий таймаут вокруг распознавания. Библиотека синхронная, отменять ее изнутри нечем, поэтому пошел по классике:
var RecognizeTimeout = 30 * time.Second func RecognizeDataCtx(ctx context.Context, data []byte) (string, error) { ctx, cancel := context.WithTimeout(ctx, RecognizeTimeout) defer cancel() type result struct { text string err error } ch := make(chan result, 1) go func() { defer func() { if rec := recover(); rec != nil { ch <- result{err: fmt.Errorf("pdf recognize panic: %v", rec)} } }() text, err := NewRecognizer().RecognizeData(data) ch <- result{text: text, err: err} }() select { case <-ctx.Done(): return "", ErrRecognizeTimeout case res := <-ch: return res.text, res.err } }
Тут важно отметить, что по таймауту мы получаем ошибку, воркер продолжает работу. Решило ли это вопрос утечки рутин? Естественно нет. Но это позволило вернуться в строй за считанные минуты, держа при этом руку на пульсе жизни подов.
Затычка номер два — не пропускать подобные подозрительные файлы в Go парсер. Детектор, грэпающий байты. Подобные файлы теперь роутятся в сервис Python, который умеет обрабатывать ASCII85Decode.
Проблема решена? Нет. Симптом устранен? Да.
Дальше мы полезем в кишки библиотек: стектрейсы, построчный разбор чужого кода и прочие радости жизни. Если станет душно, просто листайте до выводов, там резюме всего расследования без подробностей.
Расследование, акт 1: где висим, чего грустим?
Готовим минимальный стенд, голый dslipak/pdf, файл убийца прода, GOTRACEBACK=all и SIGQUIT зависающему процессу. Видим стек рутины:
goroutine 7 [running]: github.com/dslipak/pdf.(*buffer).errorf(...) github.com/dslipak/pdf.(*buffer).reload(...) github.com/dslipak/pdf.(*buffer).readByte(...) github.com/dslipak/pdf.(*buffer).readToken(...) github.com/dslipak/pdf.Interpret(...) github.com/dslipak/pdf.Page.Content(...)
Смотрим в lex.go форка dslipak, нас интересует errorf:
func (b *buffer) errorf(format string, args ...interface{}) string { // panic(fmt.Errorf(format, args...)) - БУ! ИСПУГАЛСЯ? return fmt.Sprintf(format, args...) }
Панику закомментировали, видимо, было принято сильное решение в духе «чтобы не падало». Что интересно в оригинальной библиотеке rsc паника наступает и выше по стеку обрабатывается recover‑ом. Т.е. битая страница пропускается, жизнь продолжается.
Далее идет reload, который читает следующий кусок стрима:
func (b *buffer) reload() (bool, error) { n := cap(b.buf) - int(b.offset%int64(cap(b.buf))) n, err := b.r.Read(b.buf[:n]) if n == 0 && err != nil { b.buf = b.buf[:0] b.pos = 0 if b.allowEOF && err == io.EOF { b.eof = true return false, err } fmt.Sprint(b.errorf("malformed PDF: reading at offset %d: %v", b.offset, err)) return false, err } ... }
Внимательно «следим за руками». Если Read вернул не EOF ошибку, мы попадаем в ветку с errorf. В оригинальном репо здесь паника, явный выход наверх, в нашем случае, мертвый fmt.Sprint(...), который буквально ничего не делает. Итог: буфер обнулен, b.eof не выставлен, возвращаемся как ни в чем не бывало.
Теперь смотрим на readByte:
func (b *buffer) readByte() byte { if b.pos >= len(b.buf) { b.reload() if b.pos >= len(b.buf) { return '\n' } } ... }
Буфер, как мы уже знаем, пуст. Буфер пуст → reload → снова пуст → возвращаем \n. Осмысленный костыль в мире, где errorf паникует: до паники дело просто не дойдёт. В мире без паник, это генератор бесконечных переносов строки.
И финальный аккорд, readToken:
c := b.readByte() for { if isSpace(c) { if b.eof { return io.EOF } c = b.readByte() } ... }
\n это пробельный символ, b.eof никогда не выставится. Получаем вечный (ну или почти вечный) двигатель цикла пропуска пробелов. 100% CPU, ноль аллокаций, по профайлеру все ровно.
Расследование, акт 2: а при чем тут ASCII85?
А теперь самое интересное. Я полез смотреть, что за ошибку глотает reload(), и обнаружил, что у файла с прода четвертая страница вообще не имеет /Contents. Легально по спецификации, кстати. Это пустая страница, парсер пытается прочитать стрим содержимого, получает «stream not present», а дальше вы и так уже знаете.
Собираем PDF из четырех объектов, страницу без /Contents и ни одного байта ASCII85 по всем файле:
%PDF-1.4 1 0 obj << /Type /Catalog /Pages 2 0 R >> endobj 2 0 obj << /Type /Pages /Kids [3 0 R] /Count 1 >> endobj 3 0 obj << /Type /Page /Parent 2 0 R /MediaBox [0 0 612 792] >> endobj xref ...
Результат следующий: dslipak виснет намертво, а его родитель ledongthuc проходит по верному флоу (panic → recover → пропуск страницы). То есть ASCII был вообще не причем, просто конкретный генератор помимо ASCII85 так же оставлял пустые страницы без /Contents. Мой детектор 3 месяца работал по фактически косвенному признаку, который не имел отношения к реальной проблеме.
Что интересно, пока я копался в данной проблеме, я нашел второй баг, на этот раз уже в декодере.
Расследование, акт 3: реальный баг в ASCII85 декодере
Он живет уже в ledongthuc/pdf и унаследован в dslipak/pdf в файле ascii85.go (кстати один из последних апдейтов в репо). Там перед стандартным энкодером находится санитайзер alphaReader, который должен вычищать из потока все лишнее. Вот его код целиком:
func checkASCII85(r byte) byte { if r >= '!' && r <= 'u' { // 33 <= ascii85 <=117 return r } if r == '~' { return 1 // for marking possible end of data } return 0 // if non-ascii85 } func (a *alphaReader) Read(p []byte) (int, error) { n, err := a.reader.Read(p) if err == io.EOF { } if err != nil { return n, err } buf := make([]byte, n) tilda := false for i := 0; i < n; i++ { char := checkASCII85(p[i]) if char == '>' && tilda { // end of data break } if char > 1 { buf[i] = char } if char == 1 { tilda = true // possible end of data } } copy(p, buf) return n, nil }
Тут вопросы возникают ко многим вещам, начать хоть с пустого if err == io.EOF { }. Но лишь 2 дефекта критичны.
Дефект первый: буква z. В ASCII85 группа из четырех нулевых байтов имеет однобуквенное сокращение z, вместо пяти !. Это, кстати, не что‑то странное, это обычное поведение для Ghostscript, тулов Adobe и для гошного ascii85.Encode. Но, сам символ zэто 122 номер, что больше u (117), а значит функция checkASCII85(r byte) byte возвращает для него 0.
Дальше тонкий момент, санитайзер не сжимает буфер, он пишет по тем же индексам. Т.е. невалидные позиции остаются нулями и все это копируется обратно в buf. Почему это работает? Потому что encoding/ascii85 пропускает байты <= ' ', включая NULL. То есть все z в стриме будут просто проигнорированы из‑за условия r <= ‘u’.
Дефект второй: маркер конца ~>. Когда санитайзер натыкается на маркер он делает break и возвращает n, nil, а не io.EOF. Флаг ~ живет в локальной переменной, так что если ~ и > разъедутся по разным вызовам Read, маркер не распознается, а все, что лежит в секции после маркера, приедет следующим чанком и будет обработано как данные декодером.
Как это проявляется снаружи
Честно, зависит от цепочки фильтров.
Если стрим закодирован как [/ASCII85Decode /FlateDecode], то выпавшие 4 байта ломают zlib‑поток. А GetPlainText() возвращает malformed PDF: unexpected EOF. Page.Content() паникует, и эта паника улетает наружу, в вызывающий код. В таком случае решает оборачивание каждого вызова в recover.
Если фильтр чистый /ASCII85Decode, то ситуация хуже, ничего не падает. Контент молча теряет 4 байта на каждую z. Для текстовых стримов нуля зачастую не критичны, но порча от этого никуда не уходит. Такая ошибка годами остается не замеченной, а это самый неприятный класс багов.
Фикс
Прикладываю alphaReader целиком:
type alphaReader struct { reader io.Reader eod bool } func isASCII85(r byte) bool { return (r >= '!' && r <= 'u') || r == 'z' } func (a *alphaReader) Read(p []byte) (int, error) { if a.eod { return 0, io.EOF } n, err := a.reader.Read(p) out := 0 for i := 0; i < n; i++ { c := p[i] if c == '~' { a.eod = true return out, io.EOF } if isASCII85(c) { p[out] = c out++ } } return out, err }
Что изменилось:
z пропускается в декодер вместе с основным алфавитом;
буфер честно сжимается без NUL‑дырок;
на ~ возвращаем все накомпленое вместе с io.EOF;
состояние
eodпереехало в структуру, так что маркер на границе чанков перестает быть проблемой, а повторныйReadпосле конца данных отдает0, io.EOF.
Закономерный вопрос, почему по ~ мы сразу отдаем io.EOF, не дожидаясь комбинации маркеров окончания ~>. Дело в том, что ~ не входит в алфавит ASCII85 и не может встретиться в ином случае для легитимного документа.
Регрессия: вывод до и после фикса побайтово идентичен на всех файлах. Фикс ничего не сломал.
Какая дальнейшая судьба у этого фикса
Сейчас фикс уехал в апстрим: issue + PR в ledongthuc/pdf. Ссылки приложу в конце. Баг в dislipak я не репортил, так как репо выглядит заброшенным.
Касательно наблюдений за ledongthuc/pdf. Сейчас в нем 358 независимых пакета и один мейнтейнер, у которого весомая очередь из PR. Судя по всему владелец репо или выгорел, или не имеет достаточного количества времени для поддержания пакета. Я написал мейнтейнеру и предложил помощь: триаж, ревью, релизы. Если не сложится, то буду вести форк, как полноценный отдельный проект, разгребу накопившиеся репорты, волью их в репо с сохранением авторства. И буду поддерживать проект, пока на то будет хватать сил и времени.
Выводы или грабли
Закомментировать panic — не про надежность, а про потерю контроля и путь к неопределенному поведению функций.
Корреляция не причина, даже когда все указывает в ту сторону. Мой ACSII85 детектор 3 месяца отводил беду и это лучшее доказательство тому, что причина не была равна следствию.
Санитайзер, должен целиком соответствовать формату. Прежде чем вайтлистить что‑либо, лучше потратить полчаса‑час на чтение спецификации.
Таймаут, а лучше выделенный процесс, вокруг чужой библиотеки — обязательны.
Тихая порча данных страшнее падения. Паника видна сразу, тихая порча остается невидимой годами. И стреляет в спину, когда ты этого не ждешь.
Оффтоп: за один вечер расследования я узнал про внутренности PDF больше, чем за два года его парсинга. Не повторяйте моих ошибок, читайте чужой код до инцидента, а не после.
Ссылки:
issue github.com/ledongthuc/pdf/issues/83
PR с фиксом — github.com/ledongthuc/pdf/pull/84.
