Отладка бага, который не воспроизводится

2018-12-07 в 14:19, admin, рубрики: react native, react-native-svg, ReactJS, Sentry, атомарность, многопоточность, отладка, потокобезопасность, разработка мобильных приложений, Разработка под android, состояние гонки, Тестирование мобильных приложений

10 октября 2018 года наша команда выпустила новую версию приложения React Native. Мы рады и гордимся этим.

Но ужас-то какой: через несколько часов внезапно увеличивается количество сбоев под Android.

Отладка бага, который не воспроизводится - 1
10 000 сбоев под Android

Наш инструмент мониторинга сбоев Sentry сходит с ума.

Во всех случаях мы видим ошибку типа JSApplicationIllegalArgumentException Error while updating property 'left' in shadow node of type: RCTView".

В React Native это обычно происходит, если задать свойство с неправильным типом. Но почему ошибка не проявилась при тестировании? У нас каждый разработчик тщательно тестирует новые релизы на нескольких устройствах.

Также ошибки кажутся довольно случайными, они как будто выпадают на любой комбинации свойств и типа shodow ноды. Например, вот первые три:

Error while updating property 'paddingTop' in shadow node of type: RCTView
Error while updating property 'height' in shadow node of type: RCTImageView
Error while updating property 'fill' of a view managed by: RNSVGPath

Похоже, ошибка происходит на любом устройстве и в любой версии Android, судя по отчету Sentry.

Отладка бага, который не воспроизводится - 2

Большинство сбоев под Android 8.0.0 падает, но это согласуется с нашей пользовательской базой

Давайте воспроизведём!

Итак, первый шаг перед исправлением бага — воспроизвести его, верно? К счастью, благодаря логам Sentry, мы можем узнать, что делают пользователи перед появлением сбоя.

Та-а-ак, посмотрим…

Отладка бага, который не воспроизводится - 3

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

Хорошо, попробуем повторить. Устанавливаем приложение на шести устройствах Android, открываем его и выходим несколько раз. Нет сбоя! Тем более невозможно воспроизвести его локально в dev-режиме.

Ладно, это кажется бессмысленным. Сбои всё равно довольно случайны и происходят в 10% случаев. Похоже, что у вас шанс 1 из 10, что приложение упадёт при запуске.

Анализ трассировки стека

Чтобы воспроизвести этот сбой, давайте попробуем понять, откуда он берётся…

Отладка бага, который не воспроизводится - 4

Как упоминалось ранее, у нас несколько различных ошибок. И у всех похожие, но немного разные трассировки.

Хорошо, возьмём первую из них:

java.lang.ArrayIndexOutOfBoundsException: length=10; index=-1
    at android.support.v4.util.Pools$SimplePool.release(Pools.java:116)
    at com.facebook.react.bridge.DynamicFromMap.recycle(DynamicFromMap.java:40)
    at com.facebook.react.uimanager.LayoutShadowNode.setHeight(LayoutShadowNode.java:168)
    at java.lang.reflect.Method.invoke(Method.java)
    ...

java.lang.reflect.InvocationTargetException: null
    at java.lang.reflect.Method.invoke(Method.java)
    ...

com.facebook.react.bridge.JSApplicationIllegalArgumentException: Error while updating property 'height' in shadow node of type: RNSVGSvgView
    at com.facebook.react.uimanager.ViewManagersPropertyCache$PropSetter.updateShadowNodeProp(ViewManagersPropertyCache.java:113)
    ...

Итак, проблема в android/support/v4/util/Pools.java.

Хм, мы очень глубоко в библиотеке поддержки Android, вряд ли тут можно извлечь какую-то пользу.

Найдём другой способ

Другой способ найти основную причину ошибки — проверить новые изменения, внесённые в последний релиз. Особенно те, которые влияют на нативный код Android. Возникают две гипотезы:

Мы обновили Native Navigation, где для каждого экрана используются нативные фрагменты под Android.
Мы обновили react-native-svg. Было несколько исключений, связанных с компонентами SVG, но вряд ли дело в этом.

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

Откатить обратно одну из двух библиотек.Выкатить её для 10% пользователей, что тривиально делается в Play Store.Проверить у нескольких пользователей, сохранился ли сбой. Таким образом мы подтвердим или опровергнем гипотезу.

Но как выбрать библиотеку для отката? Конечно, можно подбросить монетку, но разве это оптимальный вариант?

Добираемся до сути

Давайте более тщательно проанализируем предыдущую трассировку. Возможно, это поможет определиться с библиотекой.
```
/**
 * Simple (non-synchronized) pool of objects.
 *
 * @param  The pooled type.
 */
public static class SimplePool implements Pool {
    private final Object[] mPool;

    private int mPoolSize;

    ...

    @Override
    public boolean release(T instance) {
        if (isInPool(instance)) {
            throw new IllegalStateException("Already in the pool!");
        }
        if (mPoolSize < mPool.length) {
            mPool[mPoolSize] = instance;
            mPoolSize++;
            return true;
        }
        return false;
    }
```
Здесь произошёл сбой. Ошибка java.lang.ArrayIndexOutOfBoundsException: length=10; index=-1 означает, что mPool — массив размером 10, но mPoolSize=-1.

Ладно, как получился mPoolSize=-1? Кроме метода recycle выше, единственным местом изменения mPoolSize является метод acquire класса SimplePool:
```
public T acquire() {
    if (mPoolSize > 0) {
        final int lastPooledIndex = mPoolSize - 1;
        T instance = (T) mPool[lastPooledIndex];
        mPool[lastPooledIndex] = null;
        mPoolSize--;
        return instance;
    }
    return null;
}
```
Поэтому единственный способ получить отрицательное значение mPoolSize — это уменьшить его при mPoolSize=0. Но как это возможно с условием mPoolSize > 0?

Поставим точки останова в Android Studio и по шагам посмотрим, что происходит при запуске приложения. Я имею в виду, здесь условие if, этот код должен нормально работать!

Наконец, откровение!

Смотрите, в DynamicFromMap статическая ссылка на SimplePool.
```
private static final Pools.SimplePool<DynamicFromMap> sPool = new Pools.SimplePool<>(10);
```
После нескольких десятков нажатий кнопки Play с тщательно расставленными точками останова мы видим, что потоки mqt_native_modules обращаются к функциям SimplePool.acquire и SimplePool.release с помощью React Native для управления свойствами стиля компонента React (ниже свойство width компонента)

Но к ним также обращается основной поток main!

Выше мы видим, что они используются для обновления свойства fill в основном потоке, как правило, для компонента react-native-svg! И действительно, библиотека react-native-svg начала использовать DynamicFromMap только с седьмой версии для улучшения производительности нативных svg-анимаций.

И-и-и… функцию можно вызвать из двух потоков, но DynamicFromMap не использует SimplePool потокобезопасным способом. «Потокобезопасным», говорите?

Потокобезопасность, немного теории

В однопоточном JavaScript разработчикам обычно не нужно иметь дело с потокобезопасностью.

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

Возьмём простой пример: на изображении ниже показано, что потоки A и B параллельно:
- считывают целое число;
- увеличивают его значение;
- возвращают его.
Поток B потенциально может получить доступ к значению данных до того, как поток A его обновит. Мы ожидали, что два отдельных шага дадут конечное значение 19. Вместо этого мы можем получить 18. Такая ситуация, где конечное состояние данных зависит от относительного порядка операций потока, называется состоянием гонки. Проблема в том, что это состояние необязательно возникает всё время. Возможно, в приведённом выше случае у потока B есть другая работа, прежде чем приступить к увеличению значения, что даёт достаточно времени потоку A для обновления значения. Это объясняет случайность и невозможность воспроизвести сбой.

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

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

В нашем случае может произойти вот что:

Поскольку DynamicFromMap содержит статическую ссылку на SimplePool, несколько вызовов DynamicFromMap поступают из разных потоков, одновременно вызывая метод acquire в SimplePool.

На иллюстрации выше поток A вызывает метод, оценивая условие как true, но он ещё не успел уменьшить значение mPoolSize (которое используется совместно с потоком B), в то время как поток B тоже вызывает этот метод и тоже оценивает условие как true. Впоследствии каждый вызов уменьшит значение mPoolSize, в результате чего и получается «невозможное» значение.

Исправление

Изучая варианты исправления, мы обнаружили пул-реквест на react-native, который ещё не влился в ветку — и он обеспечивает потокобезопасность в данном случае.

Затем мы выкатили исправленную версию React Native для пользователей. Сбой наконец-то исправлен, ура!

Итак, благодаря помощи Дженика Дюплесси (контрибьютор в ядро React Native) и Микаэля Сэнда (мейнтейнер react-native-svg), патч включён в следующую минорную версию React Native 0.57.

Исправление этого бага потребовало некоторых усилий, но это была отличная возможность глубже покопаться в react-native и react-native-svg. Хороший отладчик и несколько хорошо расположенных точек останова имеют большое значение. Надеюсь, вы тоже вынесли из этой истории что-то полезное!