[Перевод] Угнать за 1100 секунд – самый странный баг, который я видел
Два дня назад я получил странное сообщение от клиента: видеозвонок загадочно оборвался ровно через 18 минут. А потом это случилось снова, также после 18-ой минуты. Совпадение?
Этот баг был не только странный, но и страшно неловкий. Наша цель — делать настолько простой инструмент для видеозвонков, чтобы условный доктор или психолог захотел бы пользоваться нашим сервисом. Надо ли говорить, что постоянный разрыв через 18 минут не согласуется с такой целью?
WebRTC — это когда вы всегда имеете дело с багами
Баги — это не какой-то феномен для нас. Наш продукт основан на WebRTC, довольно новом веб-стандарте, который позволяет двум браузерам напрямую обмениваться данными (например, видео и аудио в реальном времени).
В сентябре 2017, WebRTC наконец стал поддерживаться во всех основных браузерах. За последние месяцы мы урвали свою честную долю багов, пока заставляли WebRTC работать для всех. (Работа с передовыми технологиями — это хороший способ познакомиться с тем, как писать баг-репорты производителям браузеров).
Однако этот последний баг был самым странным за мои 5 лет работы с WebRTC.
Инструменты для отлова багов WebRTC
К счастью, у нас есть много инструментов для отлова багов (спасибо некоторым крутым контрибьюторам). Наивно думать, что некто сделает дамп chrome://webrtc-internals и пришлет его вам вместе со сценарием, который легко воспроизвести.
Пример вывода на основе дампа WebRTC. Зеленые линии обозначают успешное соединение, красная линия — сбой соединения.
Один из лучших инструментов — это rtcstats, который дает вывод из getStats и хранит его в обычных файлах (наряду с другим полезными фишками).
Подтверждение бага
Мы быстро нашли искомые файлы из двух сбойных звонков. Это были видеозвонки между Chrome 64 и Edge 16. Chrome упал на 18 минуте 20 секунде. Последующий рестарт ICE тоже не удался, что автоматически закрыло RTCPeerConnection.
Загадка в том, что Edge не согласился с Chrome — на стороне Edge iceConnectionState оставался подключенным вплоть до рестарта ICE, браузер разорвал соединение только провалился рестарт ICE. Что это было?
Скрин из Edge, посмотрите на временные метки connected и получения описания iceRestart, между ними примерно 18 минут 20 секунд. Причем iceConnectionStateChange даже не изменился на failed!
Воспроизвести баг: магическое число »18 минут 20 секунд»
Пару месяцев спустя мы купили дешевый ноутбук с Windows, чтобы запускать Edge 16 и видеть баги в действии. Мы делали видеозвонок между этим ноутбуком и Макбуком с Chrome 64.
А потом мы ждали. И разумеется, ровно после 18 минут 20 секунд статус ICE меняется на failed, рестарт ICE не удается и соединение рвется. Мы никогда не видели ничего подобного, это был шок.
Что же делать дальше? С чего начать? В нашем коде не было магического таймера, который бы рвал соединения после 18 минут 20 секунд в некоторых браузерах. Все это казалось непреодолимым, но мы могли сделать только одно.
Команда в блаженном неведении о багах, которые ее ожидают. Фото сделано в Олесунне, Норвегия, во время рабочей поездки.
Один шаг за раз — методичная локализация бага
Мы нашли воспроизводимый сценарий, но все еще надо было уменьшить область поиска. Серия тестов должна была проверить наши предположения.
Во-первых, случится ли подобное между двумя браузерами Chrome, в которых обычно меньше всего проблем с WebRTC? На тех же ноутбуках, с теми же начальными условиями мы проверили звонок из Chrome в Chrome. Через 18 минут 20 секунд звонок все еще был активен, состояние соединения ICE оставалось стабильным. То есть баг не случился.
Тем не менее, при тесте из Firefox в Edge, звонок опять сорвался.
Главный вопрос: это баг в Edge или баг в нашем коде? Сервис appear.in тоже построен на WebRTC и в нашем продукте многое сделано так же, потому что половина нашей команды раньше работала в appear.in. Мы решили протестировать звонок из Chrome в Edge через эту платформу в режиме peer-to-peer (бесплатно), все на тех же машинах. Ни единого разрыва!
Мы не знали, плакать или смеяться. Область поиска сузилась и указывала на ошибку в нашем коде. Confrere не мог работать для связки Chrome-Edge.
Когда ожидания рушатся
Так как каждый тест занимал 20 минут, мы решили, что надо приостановиться и продолжить уже из дома.
Ради лишней проверки, мы протестировали Chrome-Edge из дома. Каково же было удивление, когда после 40 минут теста звонок все еще был активен. Что?!
Мы проверяли всё снова и снова. Chrome логировал, что соединение в офисе делало так: relay <-> stun. Это значит, что одно плечо звонка должно идти через наши сервера (relayed), а вот второе плечо может отправлять данные напрямую (STUN). Это не редкость для современных сетевых конфигураций.
Дамп RTCStats показывает статус соединения каждый пары ICE-кандидатов. Посмотрите на самый верх: локальный адрес в статусе relay, а удаленный — в статусе stun.
Из-за специфической конфигурации сети в нашем офисе, моя машина, запускающая Chrome, была подключена через кабель, чтобы позволить прямые соединения. Ноутбук с Edge цеплялся по очень нестабильному Wi-Fi, и использовал relay-сервер. Однако в домашней сети, стороны звонка соединялись через локальных кандидатов, то есть не покидали домашнюю сеть.
IceTransportPolicy спешит на помощь!
Следующий шаг — определить, почему в офисе тест был неудачным, но теперь вдруг заработал. Могла ли причина быть в stun- или relay-кандидатах? К счастью, мы можем заставить PeerConnection использовать только relay-кандидатов — надо проставить соответствующее значение у iceTransportPolicy, когда создается PeerConnection. И разумеется, через 18 минут 20 секунд звонок обрывается.
Были ли это совпадение, что связка Chrome-Edge работала в appear.in? Может быть, наше соединение через appear.in использовало STUN, но в нашем сервисе победил TURN? Быстрый тест показал, что дело в нашей ошибке, так как принудительный relay (TURN) для appear.in не вызвал багов.
Наконец, мы попробовали еще кое-что. Мы собрали особую версию Confrere и с разрешения appear.in использовали их TURN-серверы для одного теста. Спустя 25 минут мы сделали вывод, что код в нашем клиентском приложении был в порядке (потому что этот код не провоцировал баг при использовании других TURN-серверов).
Когда каждый тест занимает минимум 18 минут, то это требует терпения. Слева я, справа — Свейн (CEO)
Логи спешат на помощь!
Когда мы локализовали проблему — виновата наша конфигурация TURN-серверов — мы могли все починить? Нет. Мы до сих пор не знали, что именно вызывало этот баг. Наша TURN-инфраструктура по большей части основана на том, что мы узнали за 4 года работы в appear.in, она использует те же опенсорсные компоненты, работает в том же облаке и с той же конфигурацией.
Когда вы в полной растерянности и не знаете, куда двигаться дальше, вы всегда можете обратиться к логам. Логирование было для нас главным инструментом в поиске бага, потому что оно позволяет в реальном времени следить за работающей системой. Запустив новый видеозвонок, мы пристально следили за логами.
Где-то на 10-минутной отметке стали учащаться сообщения вида:
turnserver: 1054: session 000000000000000061: realm user : incoming packet message processed, error 438: Stale nonce
Когда звонок оборвался через 18 минут 20 секунд, мы снова просмотрели логи и нашли первое сообщение с упоминанием Stale nonce:
turnserver: 1053: session 000000000000000034: refreshed, realm=, username=, lifetime=600
turnserver: 1053: session 000000000000000034: realm user : incoming packet REFRESH processed, success
turnserver: 1053: handle_udp_packet: New UDP endpoint: local addr :443, remote addr :56031
turnserver: 1053: session 000000000000000061: realm user : incoming packet message processed, error 438: Wrong nonce
turnserver: 1053: session 000000000000000061: realm user : incoming packet message processed, error 438: Stale nonce
Почему так много сообщений про Stale nonce? Что это вообще за одноразовый код (nonce) и как он может быть просроченным (stale)?
Понять баг: Привет, «stale nonce»
Если вы, так же как и я, раньше не знали, что такое одноразовый код (nonce):
Nonce (от англ. nonce — «number that can only be used once» — число, которое может быть использовано один раз) в криптографии — одноразовый код, выбранный случайным или псевдослучайным образом, который используется для безопасной передачи основного пароля, предотвращая атаку повторного воспроизведения.
— Wikipedia
И если это число просрочено:
Stale nonce это больше предупреждение, чем ошибка. Для SIP ваши авторизационные данные зашифрованы в SIP-заголовках. Чтобы эти данные не могли перехватить другие люди и делать звонки за ваш счет, используется одноразовый код (nonce).
Стандарт SIP RFC требует, чтобы nonce периодически менялся. Если клиент использует старый nonce, то это «stale nonce». В этом случае клиент обязан использовать текущий nonce вместо старого. Такое сообщение означает, что клиент пытается использовать stale nonce, то есть либо происходит атака повторного воспроизведения, либо клиент не смог получить новый nonce
— с просторов интернета
В Confrere используется опенсорсное ПО coturn, оно управляет TURN-серверами. Если вы внимательно прочтете документацию, то увидите, что в конфигурации есть параметр для stale nonce:
# Uncomment if extra security is desired,
# with nonce value having limited lifetime.
# By default, the nonce value is unique for a session,
# and has unlimited lifetime.
# Set this option to limit the nonce lifetime.
# It defaults to 600 secs (10 min) if no value is provided. After that delay,
# the client will get 438 error and will have to re-authenticate itself.
#
#stale-nonce=600
В своей конфигурации мы включили stale-nonce и все безупречно работало, пока база клиентов с браузером Edge не начала расти.
Логи stale nonce были знакомы Филиппу Ханке, он же и помог нам понять, что к чему. Шиджун Сун сообщал в appear.in о похожей проблеме в мае 2017-го, что позволило appear.in избежать проблем.
У нас была возможность изменить конфигурацию TURN-сервера и убрать флаг stale-nonce, чтобы nonce не имел ограничений по времени.
50 минут в тестовом окружении — и мы наконец смогли сказать: «Мы нашли баг!»
И все-таки, почему 18 минут 20 секунд?
Должно быть, вы заметили заголовок этого поста. Угнать за 1100 секунд. В этом тексте я писал »18 минут 20 секунд», а знаете, сколько это в секундах? 1100.
Мы знаем, что через 600 секунд от начала разговора начальный nonce становится невалидным. Возникает сообщение stale nonce и еще через 500 секунд соединение рвется. Откуда берутся еще 500 секунд?
Если в сорцах coturn поискать число 500, то найдется кое-что интересное.
Выглядит как встроенный таймер сна через 500 секунд после какой-то проверки соединения. Я не слишком знаком с внутренним устройством coturn, но судя по всему, если nonce становится невалидным, то через 500 секунд после этого coturn прекратит передачу пакетов другому участнику. Конечно же, другой участник при этом увидит, что соединение разорвано (ведь он больше не получает пакеты).
Это объясняет происходящее со стороны Chrome, так как ему перестают приходить пакеты. Но почему Edge не замечает этого?
История о двух пакетах
Соединения в WebRTC могут быть двух видов: UDP и TCP. Для пакетов UDP не требуется подтверждение о получении, не гарантируется доставка и они могут приходить не в том порядке. В коммуникациях реального времени это не большая проблема, так как кодеки довольно хорошо справляются с потерей пакетов.
У TCP все по-другому. TCP очень полезен, когда нужно доставить все данные другой стороне, в правильном порядке и с подтверждением доставки. Большая часть трафика WebRTC — это UDP.
В нашей истории Edge отправлял UDP-пакеты через TURN-сервер другой стороне. Когда сервер WebRTC прекращал передавать пакеты, Edge никак не мог знать, получал ли Chrome пакеты или нет, поэтому Edge продолжал радостно слать данные. С другой стороны, Chrome вел себя правильно и отправлял пакеты через STUN. Так что когда происходил iceRestart, Edge не знал, что делать и просто по-тихому падал.
Итоги
Выводы такие: мы отправим баг-репорт в баг-трекер Edge и на некоторое время развернем новые TURN-сервера без флага stale-nonce. Новые серверы должны гарантировать, что в будущем не будет сбоев, и наши пользователи получат долгие и качественные видеозвонки в нашем сервисе.
Также я невероятно рад быть частью сообщества людей, которые охотно делятся знаниями и помогают друг другу. От разработчиков браузеров, которые отвечали на наши баг-репорты и фиксили баги, до отдельных контрибьюторов, которые делают превосходный и бесплатный инструментарий для сообщества WebRTC.
Отдельное спасибо Филиппу Ханке за то, что указал нам на флаг stale-nonce и терпел мои бесконечные причитания, когда все это казалось бессмыслицей. Кроме того, выражаю признательность Шиджун Суну за то, что открыл эту проблему в мае 2017-го.
Надеемся, эта история была полезна для вас. С автором оригинальной статьи можно связаться через Твиттер или почту, а я готов поделиться нашим опытом использования WebRTC в комментах!
