Чиним баг в iOS Firebase RemoteConfig

Здравствуйте, меня зовут Артем Волков. Я iOS разработчик в компании AliExpress Россия.

В этой статье расскажу историю одного бага, который мы встретили, работая c подом Remote Config из SDK Google Firebase для iOS, а также о том, как мы внесли свой небольшой вклад в его исправление.

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

Жизнь и приключения одного бага

Вся история проблемы вращается вокруг файла

FirebaseRemoteConfig/Sources/RCNConfigContent.m

Что ожидаемо, в этом файле лежит реализация класса RCNConfigContent. Этот класс в целом предоставляет прямой синхронный (без переключения потоков) доступ к закешированным в память конфигам (_activeConfig, _fetchedConfig, _defaultConfig) и другим данным. Для этого RCNConfigContent работает с оберткой вокруг базы данных RCNConfigDBManager.

Взглянув на RCNConfigDBManager снаружи, легко увидеть, что он предоставляет несколько другой интерфейс — с колбэками. Заглянув же внутрь, можно увидеть, что работа с базой идет с синхронизацией обращений к ней через отдельную последовательную GCD-очередь.

_databaseOperationQueue = dispatch_queue_create(
  "com.google.GoogleConfigService.database", DISPATCH_QUEUE_SERIAL
);

Рождение бага

23 октября 2020 был сделан следующий коммит:

95cf1d3508ab2bfd412917722068ac10fe3979ae - пулл реквест 6692

Этим коммитом была добавлена поддержка новой функциональности. Назовем эту функциональность "Персонализация" (в коде "Personalization").

В плане интересующего нас кода это выглядит так:

1. Изменилось начальное значение семафора

2. К существовавшему ранее signal() (dispatch_semaphore_signal) добавилось ещё одно место, которое вызывает signal(). Приводить код смысла нет — там всё тривиально и не содержит проблем.

3. Код checkAndWaitForInitialDatabaseLoad, работающий с wait() (dispatch_semaphore_wait), не изменился.
   На самом деле у этого кода тоже есть подводный камень, но я пока не буду о нем говорить, вернусь к нему в дальнейшем.

Подводный камень тут...

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

Однако, здесь есть пара проблем. Первая проблема в том, что семафор в GCD работает не так, как ожидает разработчик, а согласно документации, то есть несколько иначе:

• signal() — повышает значение семафора

• wait() — понижает значение до нуля, а при значении, равном нулю, блокирует вызывающий код, до тех пор пока какой-то другой код, исполняющийся на другом потоке, не вызовет signal(). Когда последнее произойдет, wait() вернет управление, и ранее заблокированный поток продолжит свою работу.

Соответственно, новое начальное значение, равное 1, позволит первому же потоку, который обратится к checkAndWaitForInitialDatabaseLoad, пройти wait() без блокировки и установить флаг "загрузка из базы завершена" (_isConfigLoadFromDBCompleted), в результате чего все последующие потоки тоже пройдут checkAndWaitForInitialDatabaseLoad, не дождавшись загрузки из БД.

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

Слава бага

Данный коммит ушел в релиз Firebase iOS SDK 7.1.0 от 10 ноября 2020.

Состав релиза

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

Те из пользователей, кому не понравился свежий экспириенс, завели ишью 7424 с характерным для состояния гонки словом randomly в заголовке:

[Remote Config] Local conf randomly empty even with successful fetch #7424

Исцеление бага

Возникшую проблему девушки и парни из файрбейз оперативно исправили пулл реквестом 7975 от 28 апреля 2021, в описании которого сказано то, что мы уже рассмотрели выше:

_configLoadFromDBSemaphore = dispatch_semaphore_create(1) causes the later dispatch_semaphore_wait call in checkAndWaitForInitialDatabaseLoad() to never be blocked, so it's possible to return a config before we finish loading from the DB.

Это абсолютно верно. Другой вопрос, что данный ПР создавал новую, хотя и гораздо меньшую, чем предыдущая, проблему с отсутствием синхронизации для "Персонализации". Новая проблема заключалась теперь в том, что код, который обратился бы к checkAndWaitForInitialDatabaseLoad, не дожидался загрузки "Персонализации" и мог из-за этого получить пустой ответ, хотя данные в базе есть. Впрочем, вероятно, это было не очень страшно, потому что ишью на эту тему мне на глаза не попалась. Возможно, на тот момент пользователей "Персонализации" было мало (кажется, она была ещё в бете).

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

Итак, данный пулл реквест, спасающий загрузку конфигов (правда, ценой отстреливания "Персонализации") ушел в релизFirebase iOS SDK Version 8.0.0 от 11 мая 2021.

Спин-офф: баг и инкогнито-приключения в AliExpress Россия

Что же в это время происходило с приложением AliExpress Россия для iOS?

Примерно в марте 2021 года было принято решение добавить несколько новых подов из Firebase.

Среди них был и FirebaseRemoteConfig версии 7.4.0. Не самая последняя (на тот момент) версия была взята, из-за того что её было проще обеспечить зависимостями, при этом сохранив работоспособность других модулей, которые завязаны на такие же зависимости.

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

Как мы познакомились с этой проблемой? Тут, пожалуй, ничего необычного: время от времени наша обертка над FirebaseRemoteConfig возвращала дефолтные значения вместо загруженных с серверов Firebase. И это при условии, что консоль Firebase показывала 100% раскатку конфига, и активация конфига была проведена.

В список подозреваемых попали:

• корректно ли работает наша обертка? а всегда ли корректно?

• удалась ли передача по сети? а может, конфиг не раскатился, а консоль обманывает, показывая 100% раскатку?

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

• может, на воспроизведение влияет работа сети? мобильная/Wi-Fi/VPN?

• а может, мы неправильно работаем с Firebase iOS SDK?

• а может, какой-то наш код портит память Firebase-у?

Все эти варианты были "в молоко".

Грустнее всего, что (как обычно в состоянии гонки) проблема не воспроизводилась регулярно. Событие могло произойти и потом повториться несколько, а то и много раз, и после этого в течение трех(!) дней ежедневных(!) тестов не воспроизводиться.

В какой-то момент мы пришли к тому, что:

• на симуляторе проблему воспроизводить не получается;

• на устройстве проблема возникает редко;

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

Это навело меня на мысль, что всё-таки имеет место проблема с памятью, а частота возникает именно из-за memory pressure. Увы, снова промах. Проблема, как мы уже знаем, была в том, что возникало состояние гонки, а частота бага возрастала из-за загруженности процессора.

Разоблачение инкогнито

"На третий день Зоркий Глаз заметил, что в камере нет одной стены" (с)

На какой-то день Зоркий Глаз заметил, что если баг начал воспроизводиться, то он воспроизводится некоторое время. Значения из конфига не приходят, и всё. Впрочем, оказалось, что это состояние можно прервать удалением приложения.

А после удаления всё опять превращается в охоту за (не)удачей. Заметить, что удаление приложения прерывает воспроизведение бага, было не так просто, потому что воспроизводился баг нечасто, а когда воспроизводился, внимание тратилось на исследование одной из неверных гипотез. Кроме того (как потом оказалось), воспроизведение прерывалось публикацией нового конфига, что в большом проекте бывает довольно часто.

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

Дождавшись, когда баг наконец воспроизвелся, я стал последовательно погружаться в стек вместе с потоком исполнения. Первое же, что там обнаружилось — это то, что в файле FIRRemoteConfig.m в методе активации конфига

- (void)activateWithCompletion:(FIRRemoteConfigActivateChangeCompletion)completion```

есть следующий фрагмент:

В этом фрагменте задано условие:

if (strongSelf->_settings.lastETagUpdateTime == 0 ||
    strongSelf->_settings.lastETagUpdateTime <= strongSelf->_settings.lastApplyTimeInterval) 

И это условие приводило к возврату из метода с комплишен-замыканием completion(NO, nil); (нет изменений, нет ошибок). Дальнейшее чтение показало, что lastETagUpdateTime — это время, когда удалось получить последний изменившийся конфиг из сети (сохраняется в NSUserDefaults), а lastApplyTimeInterval — время последней успешной активации.

И раз уж RemoteConfig не возвращает значений (которые "якобы" уже раскатаны), возникла гипотеза, что какое-то из значений времени lastETagUpdateTime / lastApplyTimeInterval врёт. Более правдоподобным казалось, что врёт время активации, и это оказалась первая верная гипотеза с начала расследования :)

Стало интересно: а что если "зафорсить" проведение активации до конца? Что будет? И какой код будет при этом исполняться? И вот: после замены условия на NO и прогона активации до конца баг полечился даже без удаления приложения.

Это сулило удачу. Рабочей гипотезой было, что "врёт" время активации, при этом время активации выставлялось тут же, двумя строчками ниже:

strongSelf->_settings.lastApplyTimeInterval = [[NSDate date] timeIntervalSince1970];

Раз так, становилось ясно, что вызов, который расположен прямо перед выставлением времени активации — это и есть сама активация:

[strongSelf->_configContent copyFromDictionary:self->_configContent.fetchedConfig
                                      toSource:RCNDBSourceActive
                                  forNamespace:self->_FIRNamespace];

И она, похоже, не работает.

Колесо фортуны

Дальше начался поток удач. Внутри этого "странного" метода, который тогда для меня читался как "копируй-что-то-куда-то-для-чего-то", нашлось такое:

/// This function is for copying dictionary when user set up a default config or when user clicks
/// activate. For now the DBSource can only be Active or Default.
- (void)copyFromDictionary:(NSDictionary *)fromDict
                  toSource:(RCNDBSource)DBSource
              forNamespace:(NSString *)FIRNamespace {
  // Make sure database load has completed.
  [self checkAndWaitForInitialDatabaseLoad];
  // ...
}

Первый же вызов имел характерный комментарий: "Убеждаемся, что загрузка базы данных завершена". Это выглядело вполне подозрительно, а при взгляде внутрь там обнаружились семафоры и "вот это вот всё" (с). Гипотеза о том, что все проблемы вызваны неверной синхронизацией при работе с многопоточным кодом, родилась и тут же была подтверждена путем чтения кода, который приведен на иллюстрациях в начале статьи.

Естественно, это было поправлено сначала в форке, так как сходу не удалось выделить время на оформление ПР по всем правилам проекта.

В качестве метода достижения цели "дождаться завершения двух асинхронных задач" мной был выбран классический для iOS механизм dispatch_group. Аргументация приведена в моем ПР: на семафорах можно синхронизировать что угодно, но это зачастую будет нелегко прочесть, а на противоположной чаше весов — механизм dispatch_group, который позволяет элегантно достичь искомой цели.

В том числе, с помощью dispatch_group удалось легко поддержать синхронизацию упомянутой выше "Персонализации".

Обещанный секрет

С помощью dispatch_group также удалось убрать подводный камень в методе - (BOOL)checkAndWaitForInitialDatabaseLoad. Как и обещал в начале статьи, расскажу, в чем там была проблема.

Проблема была в том, что для ускорения проверки вводилась не закрытая семафором переменная _isConfigLoadFromDBCompleted. В целом, прятать семафор за незащищенным флагом — это всегда кривая дорожка, хоть и вымощенная благими намерениями.

Для пущей наглядности я добавил комментарии на русском:

- (BOOL)checkAndWaitForInitialDatabaseLoad {
  /// Wait on semaphore until done. This should be a no-op for subsequent calls.
  // То есть автор прячет семафор(!) за булевым флагом для ускорения.
  // Представим ситуацию, когда приложение начинает работать, и из разных точек входа,
  // например, 5 потоков вызывают checkAndWaitForInitialDatabaseLoad и попадают на точку (1)
  // (1)
  if (!_isConfigLoadFromDBCompleted) {
    // (2) все 5 потоков проверили переменную _isConfigLoadFromDBCompleted и находятся теперь здесь
    long result = dispatch_semaphore_wait( // все 5 потоков блокируются на семафоре, так как база (например) ещё не загружена
        _configLoadFromDBSemaphore,
        dispatch_time(DISPATCH_TIME_NOW, (int64_t)(kDatabaseLoadTimeoutSecs * NSEC_PER_SEC)));
    // в какой-то момент загрузка базы завершена, и по итогу вызван dispatch_semaphore_signal
    // благодаря этому один из 5 наших потоков освобождается и попадает ниже, в точку (3)
    if (result != 0) {
      FIRLogError(kFIRLoggerRemoteConfig, @"I-RCN000048",
                  @"Timed out waiting for fetched config to be loaded from DB");
      return false;
    }
    _isConfigLoadFromDBCompleted = true; // (3)
    // теперь все дальнейшие потоки "дешево" проверяют _isConfigLoadFromDBCompleted и не блокируются
    // но 4 из наших 5 гипотетических начальных потоков заблокированы навсегда
  }
  return true;
}

Конечно, и это можно было поправить семафорами. Но всё же реализация через dispatch_group_wait представляется более читабельной и масштабируемой.

Повторное исцеление

Чем закончилась эта история?

К концу августа нам удалось выделить время, чтобы заняться оформлением ПР в мастер. В процессе обнаружилось (внезапно, да), что ребята в Firebase поправили баг раньше, чем мы.

Что ж, это, пожалуй, учит: не отлаживай внешнюю зависимость бездумно, почитай сначала ишью в её гитхабе. Тем не менее, мы решили, что наш фикс более полно решает проблему, и поэтому к 6 сентября был оформлен наш ПР. И к 18 октября ребята из Firebase заапрувили и влили его.

После релиза мы перешли со своего форка на официальный под Firebase/RemoteConfig версии 8.8.0, в котором теперь есть и наш скромный вклад.