История одного бага (#1653967)04.01.2017 18:48

Abstract: Реальная история из жизни реальных администраторов по отлову идиотского бага.
Поучительная часть: Никогда недооценивай зависимости зависимостей.

Вступление

Рядовой апгрейд в лаборатории с Openstack Mitaka до Openstack Newton (более новая версия). Несколько deprecated options в файлах конфигурации, keystone переехал с eventlet на WSGI и поломал существующую конфигурацию с haproxy; из-за типового «ipv6 listen» apache не стал конфликтовать с haproxy за одинаковые используемые порты на звезде (один слушал ipv6, другой ipv4 only), так что запросы уходили в haproxy вместо апача, где умирали с 503, т.к. апстрима не было… Впрочем, история не об этом.

После того, как основные проблемы были пофишкены, Nova (одна из компонент Openstack) при запуске начала падать с ошибкой: ConfigFileValueError: Value for option url is not valid: invalid URI: 'http://neutron-server.example.com:21345'.. Это было очень странно. С учётом, что в конфиге поменялось 100500 опций, возникло подозрение, что мы используем устаревшую опцию, которую больше не надо использовать. Однако, документация говорила, что пример опции — url = http://controller:9696.

Отладка

Очевидные шаги отладки:

Закомментировать опцию — не падает
Повторить опцию из примера — не падает
Заменить в опции порт на «наш» — возможно, нельзя использовать слишком большой номер порта — не падает
Заменить в опции url на наш — падает
Вернуть «controller» на место — не падает
Подозрение: не умеет fqdn: заменить controller на controller.dns — не падает
Подозрение: слишком много точек (у нас в реальном коде было 8 точек в url) — controller.dns1.dns2.dns3.dns4 — не падает
Оставить из нашего имени только первую часть: http://neutron-server:9696 — падает! гипотеза уже понятна.
Проверка1: http://neutronserver:9696 — не падает
Проверка2: http://with-dashes:9696 — падает!

Итого, бага: наличие дефиса в hostname вызывает ConfigFileValueError. Баг репортится: bugs.launchpad.net/ubuntu/+source/nova/+bug/1653967

Проверка, что это баг: RFC3986 утвержает, что:

unreserved    = ALPHA / DIGIT / "-" / "." / "_" / "~"
reg-name      = *( unreserved / pct-encoded / sub-delims ) 
host          = IP-literal / IPv4address / reg-name

(это такая bnf-нотация, когда говорит, что в host может быть »-»).

То есть дефис может быть в hostname при работе с доменными именами. Мы это все и так знаем, но всегда лучше перепроверить.

Изучение кода, который сообщает об ошибке:

            try:
                return convert(opt._get_from_namespace(namespace, group_name))
            except KeyError:  # nosec: Valid control flow instruction
                pass
            except ValueError as ve:
                raise ConfigFileValueError(
                    "Value for option %s is not valid: %s"
                    % (opt.name, str(ve)))

Ошибка возникала на двух опциях: url и novncproxy_base_url. Ошибка идентичная, хотя grep’ать удобнее по второму. Начинаем искать второе. Вот как она определяется в коде:

    cfg.URIOpt(
        'novncproxy_base_url',
        default='http://127.0.0.1:6080/vnc_auto.html',
        deprecated_group='DEFAULT',
        help="""

Ага. А cfg — это из from oslo_config import cfg. oslo.config — это библиотека Openstack для работы с конфигами. Смотрим сырцы.

Видим:

class URI(ConfigType):
...
    def __call__(self, value):
        if not rfc3986.is_valid_uri(value, require_scheme=True,
                                    require_authority=True):
            raise ValueError('invalid URI: %r' % value)

Внезапно:

>>> import rfc3986
>>> rfc3986.is_valid_uri('http://test.com')
True
>>> rfc3986.is_valid_uri('http://test-test.com')
False

Упс. Непорядок. Зато есть: github.com/sigmavirus24/rfc3986/issues/11
Бага давно пофикшена. В версии 0.2.2. А на хосте у нас:

apt-cache policy python-rfc3986
python-rfc3986:
  Installed: 0.2.0-2
  Candidate: 0.2.0-2
  Version table:
 *** 0.2.0-2 500
        500 http://archive.ubuntu.com/ubuntu xenial/main amd64 Packages
        100 /var/lib/dpkg/status

Зато в более свежей версии в zesty есть версия 0.3.1–2, которая такой проблемой не страдает.

Дальнейшее разбирательство

Давным-давно был сделан Баг. Он был некоторое время, потом его пофиксили. Но за это время запакетировали Код, в котором был Баг, и никто не обратил внимание на Фикс Бага, и версия с Багом оставалась в deb-репозитории годами. Она никого не волновала — пока не случились два коммита в oslo.config и nova:

commit 45ee2bed52a57b9801435b43ad45d8f50204580d
Author: Masaki Matsushita 
Date:   Mon Sep 28 20:28:28 2015 +0900

    Add URIOpt
    
    This change add URIOpt which validates string as URI.
    
    Closes-Bug: #1500398
    Change-Id: Ie8736b8654b9feb2a2b174159f08dbea03568d84

commit 6091de77eda12286786e28ae4f0779e7efc54634
Author: Maciej Szankin 
Date:   Thu Jul 28 10:30:59 2016 -0500

    Improve consistency in VNC opts
    
    * Updated header flags
    * Moved all vars to list
    * Removed possible values and related options sections where they were not
      needed
    * Changed IntOpt to PortOpt where needed
    
    Change-Id: I3255a867091f8e14c907c7fde9a2aa3abc249ae9
    Implements: Blueprint centralize-config-options-newton

Этот коммит сделал из StrOpt UriOpt и начал использовать (через oslo.conf) python-rfc3986. Из-за того, что была запакетирована старая опция, в программном ПО возникла неожиданная регрессия.

Бонусное: как мы это будем фиксить

Обычно в таких случаях, если апгрейд на более новую версию даётся легко (и не вызывает других проблем), то мы просто забираем пакет из более новой версии дистрибутива (в данном случае — ещё не вышедшей zesty, ака ubuntu-17.04). Мы положим его в наш приватный репозиторий под управлением aptly (как есть) и будем его использовать при установке/настройки сервером. Если бы такого пакета не было в природе — мы бы настроили на CI джобу на его пакетирование и публикацию (в репозиторий aptly). Если бы этот вариант не был доступен (например, несовместимые изменения), то мы бы добавили в наш patchqueue для nova ещё один патч, который бы делал StrOpt вместо UriOpt. Это подразумевает, что мы будем пересобирать nova из ubuntu-пакета с нашими собственными патчами. Этим занимается CI, который публикует пакеты в тот самый наш приватный репозиторий.

Немного флейма

И как бы эта проблема решалась в проприетарной среде? Ошибки допускают все (иначе бы у нас было ПО без багов). После того, как ошибка была зарепочена в саппорт первого уровня, и после боданий про установленные версии, обновления и контракты, оно дошло бы до саппорта второго уровня, третьего уровня, и так вплоть до человека с реальной квалификацией, он бы нашёл и исправил проблему. Какой estimate для того баг-фикса? Два часа на первый уровень, ещё час на второй, business day на исследование проблемы, ещё один business day на фикс, возможно ещё один день на релиз и тестирование. Это идеальный сценарий. На практике, мои самые оптимистичные оценки говорят про недели, превращающиеся в «следующем релизе через пол-года поправили».

Сколько это заняло у меня, в opensource проекте? ~14:30, сегодня проблема обнаружилась, и я зарепортил его на launchpad. В 15:20 уже было известно про проблему с зависимостью, в 15:30 было проверено, что с новой версией python-rfc3986 этой проблемы нет. В 16:50 (по кипрскому времени) я заканчиваю писать этот пост на Хабр.