История одного бага в .NET 5

Как мы столкнулись с неожиданным багом в .NET 5, расследовали возникшую проблему, и что же из этого вышло.

Одним прекрасным днём было принято решение о переводе рабочего проекта с .NET Core 3.1 на .NET 5. Миграция оказалась проще, чем это было, например, при переходе с .NET Core 2.1 на .NET Core 3 из-за меньшего количества доработок. По сути потребовалось просто изменить TargetFramework на net5.0, обновить несколько библиотек и поправить пару мест в коде, которые стали deprecated, чтобы в будущем это было не так больно делать.

Команда тестирования проверила обновление вместе с другими задачами, а затем релиз был выкачен в прод. Но счастье было недолгим. Судя по метрикам, внезапно оказалось, что отвалилась одна из интеграций. По логам было видно, что несколько минут после выкатки релиза всё работало замечательно, но потом HTTPS-запросы к шине одного из клиентов по какой-то причине стали отваливаться с ошибкой авторизации (401). Выкатили релиз ещё раз, но это не помогло — проблема повторилась. Так как не удалось быстро понять, что именно пошло не так, пришлось выполнить даунгрейд обратно до .NET Core 3.1, а затем в фоновом режиме начать разбираться с проблемой, чтобы потом всё же переехать на .NET 5.

Да начнётся расследование

Сначала стоит изолированно воспроизвести проблему, чтобы исключить влияние других факторов. Для этого коллега написал консольное приложение, которое в цикле создаёт обработчик HTTP с боевым сертификатом в поле Certificates, клиент на основе этого обработчика, а затем стучится в API и выполняет одну из безобидных идемпотентных операций. Все запросы успешно выполнились, что довольно странно.

Возможно, что-то изменилось на стороне сервера, куда шлются запросы? На всякий случай выполняю аналогичные манипуляции при помощи curl, консольных приложений на Python и Go. Но и в этом случае проблема не воспроизводится.

Что же ещё может отличаться на проде и при локальном воспроизведении? Разработка ведётся на Windows, а прод крутится на Linux (опущу вопрос про то, почему при разработке не используется хотя бы Docker). Хорошо, попробую выполнить всё то же самое, но через Docker, и вуаля, первый запрос проходит успешно, а все остальные падают с ошибкой. Но на .NET Core 3.1 же всё работало, может что-то ещё поменяли? Запускаю то же консольное приложение, но меняю TargetFramework на netcoreapp3.1, и всё работает как на Windows, так и на Linux.

Возникает вопрос, а почему на проде ошибки начинаются не с первого запроса, а лишь спустя несколько минут? Ответ простой: используется HttpClientFactory, который кэширует HttpClientHandler для клиентов на некоторое время и переиспользует его для запросов, а когда приходит время создать новый обработчик, тут-то всё и ломается.

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

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

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

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

В итоге получается странная ситуация: вроде как ошибка связана с новой версией .NET, но уже вышло два минорных релиза (на момент возникновения проблемы актуальной была версия 5.0.2), а исправления всё нет. Если бы ошибка возникала при выполнении любого запроса с аутентификацией по сертификату, то проблему же уже наверняка заметили и починили. Значит, надо разбираться, чем же используемая в проекте конфигурация такая особенная, и в чём именно заключается ошибка.

В поисках бага

Внешняя отладка

Для повседневной разработки я пользуюсь Jetbrains Rider. В нём есть поддержка так называемой внешней отладки (External source debug). В этом режиме отладчик умеет проваливаться в кишки .NET, что позволит более детально изучить, что же происходит при выполнении проблемного HTTP-запроса, а затем попытаться самостоятельно найти ошибку.

Так как баг не воспроизводится на Windows, отладку нужно производить с использованием Linux-окружения, чего можно достичь двумя способами:

1. Установить Linux на рабочий компьютер;

2. Воспользоваться WSL 2 или Docker.

Во втором случае придётся подключаться отладчиком к работающему процессу через SSH, благо поддержка присутствует в обеих IDE. Однако, в Rider по какой-то причине при таком способе подключения отключается внешняя отладка, поэтому придётся для поиска ошибки воспользоваться Visual Studio, где есть аналогичный функционал.

В результате отладки находятся потенциальные жертвы: классы SecureChannel и SslStreamCertificateContext. Последний имеет разные имплементации для разных операционных систем, что достигается при помощи условной компиляции соответствующих partial классов: на Windows используется нативный модуль работы с сертификатами, в то время как на Linux — OpenSSL. После выполнения первого запроса происходит кэширование SSL-сессии в SslSessionsCache. При проблемном запросе сессия переиспользуется из кэша, и по какой-то причине отправляется массив данных меньшего размера, чем при нормальном запросе.

Если при помощи рефлексии очистить кэш SSL-сессий перед проблемным вызовом, то HTTP-запрос будет выполнен успешно:

var assembly = AppDomain.CurrentDomain.GetAssemblies()
	.First(x => x.FullName?.Contains("System.Net.Security") == true);
var cacheType = assembly.GetTypes().First(x => x.Name == "SslSessionsCache");
var field = cacheType.GetField("s_cachedCreds", BindingFlags.NonPublic | BindingFlags.Static);
if (field != null)
{
	var dic = (IDictionary?) field.GetValue(null);
	dic?.Clear();
}

(Не используйте этот код в своих проектах. Мало ли что может сломаться из-за такой чистки кэша.)

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

Анализ EventSource

Начиная с .NET Core 3.0, на Linux стало возможным использования EventSource — шины, куда отправляются разные внутренние логи, на которые можно подписаться. Сделать это можно двумя способами:

1. Создать свой EventListener, в котором подписаться на все события и выводить их в стандартный вывод консоли (или куда угодно, например, в csv-файл);

2. Воспользоваться утилитой dotnet-trace и натравить её на запущенный процесс.

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

1. .NET Core 3.1 на Windows 10

2. .NET Core 3.1 на Linux

3. .NET 5 на Windows 10

4. .NET 5 на Linux

Все полученные логи собрал в таблички, и попытался по ним понять, в чём же отличается внутренняя логика в тот момент, когда происходит ошибочное поведение:

Из этих данных удалось сделать следующие выводы:

• Обработка HTTP-запросов и формат логов сильно отличаются между 3.1 и 5.0. Это объясняется как минимум тем, что в пятой версии переехали на единую managed реализацию SocketsHttpHandler вместо разных реализаций с вызовом нативных библиотек (например, на Linux использовалась libcurl). Этот обработчик доступен и на 3.1, если включить соответствующую опцию через AppContext, но разница в логах всё равно колоссальная;

• Логи недостаточно подробные в интересующем месте;

• Также всё ещё есть сильные различия между версиями под Windows и Linux, поэтому их сравнение по сути невозможно.

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

Не время сдаваться

Ну что ж, раз самостоятельно исправить баг не получилось, попробуем обратиться к самым компетентным в этой области людям — разработчикам самого .NET. Разработка .NET уже несколько лет ведётся публично на Github, а значит есть возможность создать issue и даже отправить Pull Request.

Пробую найти issue с похожей или той же самой проблемой, чтобы посмотреть статус их решения и добавить туда дополнительную информацию.

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

• Подробно описать проблему: в каких случаях что-то работает, в каких — нет, и почему это важно;

• Предоставить пошаговую инструкцию по воспроизведению проблемы.

То есть нужно сделать баг воспроизводимым.

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

Создание сервера, идентичного натуральному

Доподлинно неизвестно, на каком языке написан сервер, при общении с которым возникают проблемы, и используется ли nginx или что-то ещё. Ошибка возникает при использовании клиента на .NET, да и проект пишется на нём же, поэтому попробую написать сервер на C#, где в качестве фреймворка будет использоваться ASP.NET Core вместе с Kestrel. При этом для аутентификации будет использоваться тот же боевой сертификат.

В документации есть довольно подробная статья по добавлению аутентификации по сертификату в проект на ASP.NET Core. Вкратце:

• Требуется добавить схему аутентификации с использованием сертификата, а в её настройках прописать логику проверки сертификата (например, сравнение слепка сертификата с исходным);

• Требуется настроить Kestrel, чтобы он проверял валидность сертификата.

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

func main() {
	caCert, err := ioutil.ReadFile("ca.cer")
	if err != nil {
		log.Fatal(err)
	}
	caCertPool := x509.NewCertPool()
	caCertPool.AppendCertsFromPEM(caCert)
	cfg := &tls.Config{
		ClientAuth: tls.RequireAndVerifyClientCert,
		//ClientCAs: caCertPool,
	}
	srv := &http.Server{
		Addr:      ":8443",
		Handler:   &handler{},
		TLSConfig: cfg,
	}
	log.Fatal(srv.ListenAndServeTLS("certificate.cer", "private.key"))
}

type handler struct{}

func (h *handler) ServeHTTP(w http.ResponseWriter, req *http.Request) {
	w.Write([]byte("PONG"))
}

Здесь создаётся простой обработчик HTTP-запросов, для которого требуется аутентификация по сертификату. В стандартной библиотеке Go для работы с сетью net/http PFX-файл нельзя применить в исходном виде, поэтому его нужно разбить на три составляющие, о которых чуть подробнее расскажу в следующей главе. Дополнительно создаётся хранилище клиентских сертификатов, куда вручную добавляется сертификат промежуточного удостоверяющего центра (CA). Обратите внимание, что в финальном коде использование этого хранилища закомментировано, это оказалось важной зацепкой в решении проблемы. Если раскомментировать эту строчку, то ошибок не возникает, что наводит на мысль, что искомый сервер может быть криво настроен.

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

http: TLS handshake error from 127.0.0.1:56082: tls: failed to verify client's certificate: x509: certificate signed by unknown authority

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

Вкратце про сертификаты

Цифровой сертификат — выпущенный удостоверяющим центром (CA) электронный или печатный документ, подтверждающий принадлежность владельцу открытого ключа или каких-либо атрибутов. Чтобы сертификату можно было доверять, он должен быть внесён в список доверенных или же быть подписан вышестоящим доверенным CA, и так до тех пор, пока в полученной цепочке доверия (Chain of Trust) не будет CA, который считается доверенным корневым сертификатом. Список доверенных удостоверяющих центров присутствует как в операционной системе, так и в браузерах, и постоянно обновляется. Более подробно про сертификаты и цепочку доверия можно узнать из неплохого видеоурока.

Аутентификация по сертификату используется как дополнительный этап проверки того, является ли клиент на той стороне доверенным. Она выполняется на этапе TLS-рукопожатия во время установки защищённого соединения на этапе Server hello, как можно увидеть на диаграмме, приведённой ниже:

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

В проекте сертификат хранится в виде PFX-файла. Обычный PFX-файл с сертификатом состоит из трёх составляющих:

1. Публичная часть клиентского сертификата (для вашего домена);

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

3. Приватный ключ, который используется для расшифровки запросов.

Получить эти составляющие из PFX-файла можно, например, при помощи следующих команд OpenSSL:

openssl pkcs12 -in certificate.pfx -clcerts -nokeys | sed -ne '/-BEGIN CERTIFICATE-/,/-END CERTIFICATE-/p' > certificate.cer
openssl pkcs12 -in certificate.pfx -cacerts -nokeys -chain | sed -ne '/-BEGIN CERTIFICATE-/,/-END CERTIFICATE-/p' > ca.cer
openssl pkcs12 -in certificate.pfx -nocerts -nodes | sed -ne '/-BEGIN PRIVATE KEY-/,/-END PRIVATE KEY-/p' > private.key

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

openssl pkcs12 -export -out certificate.pfx -in certificate.crt -certfile ca.crt -inkey privateKey.key

Как было описано ранее, серверу на Go требуется скормить эти файлы по отдельности, а вот для клиента на .NET проще использовать единый PFX-файл, поэтому и нужно понимать, в чём же заключается различие между форматами. К слову, в .NET 5 появилось больше перегрузок для работы с X509Certificate2, поэтому использование отдельных составляющих стало проще.

Создание сертификата, идентичного натуральному

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

Чуть более сложным способом будет сначала создать свой CA, потом создать сертификат, а затем подписать этот сертификат этим CA, предварительно создав свой CSR-ключ (Certificate Signing Request). У сертификатов есть ещё такая штука как расширения (extensions), которые позволяют изменить поведение. Например, можно разрешить проводить те или иные операции при помощи сертификата с расширением, а остальные запретить. Я попытался скопировать все расширения из исходного боевого сертификата, но для некоторых из них вроде адреса проверки отозванных сертификатов или включения SCT потребовалось бы приложить больше усилий, которые по итогу оказались бы потраченными впустую. К сожалению, полученный таким образом сертификат не позволил воспроизвести проблему.

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

• Взять один из ранее использованных просроченных сертификатов и попробовать его.
  Да, с ним проблема тоже воспроизводится (если перевести системное время назад), однако выставлять на публику такой сертификат — не лучшая идея. В теории злоумышленник каким-нибудь образом может расшифровать записанный ранее сетевой траффик, т.к. будет иметь доступ к приватному ключу;

• Приобрести платный сертификат. Но зачем спонсировать торговцев воздухом?

• Воспользоваться замечательным сервисом Let's Encrypt.
  С его помощью можно совершенно бесплатно выписать сертификат с наилучшими настройками безопасности, в котором будет содержаться цепочка сертификации, приводящая к доверенному корневому удостоверяющему центру.

Самым простым вариантом оказался вариант с Let's Encrypt.

Полученные с помощью Let's Encrypt три файла теперь необходимо запаковать в PFX-файл и скопировать его в папку с клиентом на .NET 5, а исходные три файла — в папку с сервером на Go, а затем попытаться воспроизвести проблему. Отлично! Она воспроизводится! И поведение такое же, как с исходным сервером и сертификатом!

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

В чём же причина бага?

Уже через день отписался Tomas Weinfurt, разработчик из Microsoft, который, судя по его активности в репозитории, как раз занимается сетевой частью .NET, в частности обработкой SSL. Ещё через несколько дней он подготовил Pull Request, в котором проблема была довольно просто устранена, а также написаны тесты, которые не позволят ей вернуться в дальнейшем (написать тесты оказалось сложнее, чем починить баг). Этот PR был влит в master-ветку (в которой на данный момент находится .NET 6), после чего бэкпортирован в ветку 5.0. Данное исправление вышло в составе минорного релиза 5.0.4.

Теперь можно собрать все детали головоломки воедино. Ошибка появилась после того, как в .NET 5 был добавлен упомянутый ранее SslStreamCertificateContext, причины добавления которого описаны в данном issue, поэтому проблемы не существовало в 3.1. Данный контекст не кэшируется вместе с SSL-сессиями, и поэтому после восстановления сессии из кэша в запросах отправлялся только конечный сертификат, без остальной цепочки, что объясняет то, почему размер проблемных запросов был меньше, чем обычных.

Некоторые сервера, такие как сервер одного из клиентов, по какой-то причине настроены так, что не могут восстановить цепочку доверия лишь по конечному сертификату, хотя возможность для этого есть, и поэтому отвергают такие соединения. В сервере на Go из примера для воспроизведения ошибки как раз указывается только конечный сертификат, и если не добавить в хранилище промежуточные сертификаты, то сервер не сможет восстановить и проверить цепочку. Соответственно если вы делаете свой сервер на Go с использованием net/http и аутентификации по сертификату, то не забудьте добавить промежуточные сертификаты в хранилище во избежание похожих проблем.

Заключение

Если при расследовании причин ошибки в программе вы обнаружили, что баг находится в сторонней библиотеке или более сложной системе вроде компилятора/рантайма языка, не стоит ждать с моря погоды, ведь можно:

• Изолировать проблему, попытаться её воспроизвести максимально простым способом;

• Выяснить, какой компонент системы и при каких условиях сбоит. Убедиться, что проблема именно в нём, а всё остальное работает как положено;

• Попробовать найти похожую проблему на Stack Overflow или в баг-трекере проекта, к которому относится ошибка;

• Если такой проблемы нет, то сделать баг стабильно воспроизводимым, а затем попытаться отладить и устранить его самостоятельно (чтобы было интереснее, можно поменять этот пункт и предыдущий местами);

• А если это не получилось или нет времени, то максимально подробно описать проблему и подготовить воспроизводимый пример, чтобы с этим могли помочь другие разработчики.

Обновлённая версия .NET с исправлением ошибки, описанной ранее, уже вышла, и проблема действительно больше не воспроизводится с использованием боевого сервера и сертификата (хотя был небольшой шанс, что поправили лишь похожую, но не исходную проблему). Поэтому теперь ничего не мешает снова обновить проект до .NET 5 с C# 9.0, где содержится много вкусностей вроде records и code generators.

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

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

Выражаю благодарность @tycheg за помощь с первоначальным воспроизведением и отладкой проблемы.