Угнать за 1100 секунд – самый странный баг, который я видел

https://medium.com/confrere/gone-in-1100-seconds-hunting-bugs-on-the-edge-of-webrtc-132a186c45dd
  • Перевод

Два дня назад я получил странное сообщение от клиента: видеозвонок загадочно оборвался ровно через 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 <confrere.com> user <confrere:1520714985>: incoming packet message processed, error 438: Stale nonce


Когда звонок оборвался через 18 минут 20 секунд, мы снова просмотрели логи и нашли первое сообщение с упоминанием Stale nonce:

turnserver: 1053: session 000000000000000034: refreshed, realm=<confrere.com>, username=<redacted>, lifetime=600
turnserver: 1053: session 000000000000000034: realm <confrere.com> user <redacted>: incoming packet REFRESH processed, success
turnserver: 1053: handle_udp_packet: New UDP endpoint: local addr <redacted>:443, remote addr <redacted>:56031
turnserver: 1053: session 000000000000000061: realm <confrere.com> user <redacted>: incoming packet message processed, error 438: Wrong nonce
turnserver: 1053: session 000000000000000061: realm <confrere.com> user <redacted>: 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 в комментах!
Voximplant 119,58
Облачная телеком-платформа
Поделиться публикацией
Комментарии 27
  • +3
    Если вы, так же как и я, раньше не знали, что такое одноразовый код (nonce) [...] И если это число просрочено [...]

    Может добавите найденные знания в статью Википедии?
    • +21

      Безопасность мешает юзабилити. Отлично, отключаем ее и все работает.
      Nice job

      • +7
        Есть разные штуки для обеспечения безопасности. Не все из них разумно использовать в любой ситуации. К примеру, безопаснее всего выключенный компьютер :) Но работать мешает… Поэтому приходится понижать безопасность и его включать. Такая вот жизнь.
        • +1
          Некоторые люди не согласятся с вами, ведь когда компьютер выключен - антивирус не работает))
          Недавно пришлось устанавливать модем на машину одного очень хитрого юзера с о-о-очень большими звездами на погонах. Получив искомое, он вдруг забеспокоился:
          — А не могут ли по этой штуке ночью снять с моего компьютера информацию? Мы тут окружены шпионами!
          — Ваша информация в полной безопасности. Программа запрашивает пароль у всех, кто пожелает подключиться к машине. Кроме того, удаленному клиенту видны только нужные каталоги. Наконец, предусмотрена программная защита всех основных файлов…
          — Ты ничего не понял! — с торжеством возопил юзер. — Я же русским языком говорю, что ночью моя машина выключена — и ни одна защита на ней не работает. Как же обезопасить информацию на это время?!
          Хотите верьте, хотите нет, переубедить его оказалось мне не под силу. Его компьютер включен еженощно, чтобы все защиты работали.

          «КомпьютЕрики шутят» Владимира Шахиджаняна

          • +1

            После дыр во всяких IntelME, я бы на его месте вообще модем не подключал… И комп на ночь в сейф.

        • +3
          Все-таки осталось непонятным. Обычно nonce служит для разового обмена для получения сессионного ключа, далее он не нужен. Поэтому в нем и есть timestamp. Почему же у вас nonce используется и дальше в течение всей сессии, видимо как токен сессии? И почему, если он все-таки так нужен, нет процедуры его обновления?
          • +1
            ICE — это общий протокол «обхода NAT'ов», его использует не только WebRTC. Полагаю, текущая имплементация WebRTC не умеет обновлять nonce.
            • 0
              Упс, перевод же. Как-то я его не ожидал в корпоративном блоге.
          • +1
            Так вы реаутентификацию делать то будете в итоге? Или так оставите?
          • +1
            Если в сорцах coturn поискать число 500, то найдется кое-что интересное.

            Эм, usleep описан в man 3 usleep, и он просто усыпляет текущий thread на 500 микросекунд (а в контексте этой функции, похоже, это часть какой-то примитивной защиты или эмуляции DoS-атаки, судя по результатам поиска в репозитории, но это не точно), так что 500 секунд надо искать в другом месте.

            • 0
              Возможно, именно этот момент автор оригинальной статьи нашел неправильно, или сделал неправильную ссылку.
              • 0
                Оу, всё время забываю про переводы. Прошу прощения, да, это уже к источнику :)
                • +1
                  Кажется, это потому, что в конце статьи совсем нет никаких признаков того, что это перевод. Boomburum Продублируйте информацию про перевод в футере статей пожалуйста.
                  • 0
                    +1, с каждым переводом такое. Нужна лучшая индикация.
                    • 0
                      Можно в Stylebot отметить красненьким | желтеньким | мигающим элемент
                      элемент class=«post__type-label» (т.е. Перевод) и вуаля…
                      Типа так my.jetscreenshot.com/226/20180404-ze00-167kb.jpg
                      Яд конечно. Но уже не пропустишь ;)
                      • 0
                        Прежде чем принимать Яд, хочется попробовать что-нить выжать из UX'ера ТМ ^_^
                        • 0
                          Это всё равно вверху…
              • +1
                Интересно, сколько было итераций в попытках фикса и сколько вышло времени на поиск в человекочасах?
                • 0
                  Боюсь, этот вопрос придется задавать автору оригинальной статьи
                  • +1
                    Два дня назад я получил странное сообщение от клиента: видеозвонок загадочно оборвался ровно через 18 минут. А потом это случилось снова, также после 18-ой минуты. Совпадение?
                    Видимо максимум за два дня все решили
                    • 0
                      А как же
                      Пару месяцев спустя мы купили дешевый ноутбук с Windows...
                      • 0
                        Кривой перевод. В оригинале «few months ago» — пару месяцев назад.
                • 0
                  Спасибо. Интересно. Когда то немного подобную проблему починил в Астериске No audio on WebRTC caller side when answer waiting time is more than ~7sec
                  • +8
                    Ох уж эти стартапы… «Мы делаем видеоконференции через WebRTC, правда слабо понимаем, как работает софт в ключевых частях нашей системы». Логи начали читать в самом конце, в дампы трафика, судя по всему, даже не смотрели, хотя обе стороны были под контролем. Печально всё это.

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

                    Самое читаемое