У меня в управлении и разработке сервис, который обрабатывает большой поток 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.