Помните аварию с потерей провайдера услуг dubbo, вызванную сбоем в сети zookeeper.

Java

задний план

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

несколько вопросов

После возникновения этой проблемы у нашей команды возникло несколько вопросов,

  1. После восстановления zookeeper сервис dubbo будет перерегистрирован.
  2. Почему со ссылкой на оплату проблема, а все остальные ссылки в норме?
  3. Производственная среда представляет собой развертывание с несколькими узлами, почему все узлы платежного звена не зарегистрированы нормально, а все узлы других приложений звена в норме.

Устранение неполадок

Предварительное расследование

В ходе первоначального исследования были обнаружены следующие проблемы:

  1. В течение этого периода зоопарку не удалось подключиться и переизбраться, что длилось от 3 до 4 минут.
  2. У одного из трех узлов zookeeper в производственной среде есть проблема с конфигурацией.Предполагая, что это три узла zk1, zk2 и zk3, тогда zk1 настраивает кластер как zk1, zk1 и zk2, а две другие конфигурации являются нормальными.
  3. Есть приложение, которое генерирует около 1000 потребителей из-за проблем с кодом

Но интуитивно наша команда согласилась, что хотя пункты 2 и 3 проблемные, они не должны иметь никакого отношения к этой аварии.

вопрос первый

Первое, что нас смущает, — это первый вопрос, поэтому я планирую сначала проигнорировать второй вопрос и третий вопрос, а сначала выяснить причину первого вопроса.

догадка

По вопросу 1, так как я не особо знаком с zookeeper и dubbo, я провел много экспериментов и в итоге выяснил, что когда мы будем активно удалять узел провайдера через zkCli, dubbo не будет перерегистрирован.

Поэтому я проверил журнал операций транзакций zookeeper и обнаружил, что в течение этого периода не было записи об удалении узла провайдера. Тогда догадываться можно только об автоматическом удалении zookeeper.

Поэтому я сделал предположение,Dubbo был фактически перерегистрирован, но позже был удален зоопарком..

Повторение проблемы

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

  1. Запустите zk1, zk2, zk3 и разверните службу dubbo. Регистрация службы прошла успешно
  2. Отключите сеть между zk1, zk2 и zk3, кластер zk недоступен, а служба dubbo сообщает об ошибке тайм-аута соединения zk
  3. подождите 4 минуты
  4. Восстановите сеть между zk1, zk2 и zk3, переподключите сервис dubbo и зарегистрируйте сервис
  5. Проверьте узел zookeeper, узел провайдера в норме.
  6. подождите 1 минуту
  7. узел провайдера исчезает

Откройте журнал zk следующим образом:

zk日志

Журнал службы dubbo выглядит следующим образом:

dubbo服务日志

Видно, что dubbo был перерегистрирован после восстановления zookeeper, но на стороне zookeeper видно, что результатом перерегистрации является NodeExists и возникает исключение. Сторона dubbo игнорирует это исключение. Через некоторое время произошло большое количество таймаутов сеанса на стороне zookeeper, при этом нода провайдера была удалена.

На этом этапе мы можем в основном объяснить первый вопрос:

1. Сначала все нормально работает с dubbo и zk и подключается через sessionA
2. Далее сеть zk кластера отключается, и условие доступности более половины узлов не может быть выполнено, zk кластер находится в недоступном состоянии, а dubbo отключен от zk.
3. Зк приходит в норму, а сервис даббо думает, что сессия А была отключена, поэтому инициирует новую сессию Б и регистрирует ноду провайдера. В настоящее время из-за локального сохранения zk использует исходные данные для восстановления до нормального состояния, считает, что сеанс A является нормальным, и не удаляет узел провайдера, зарегистрированный сеансом A. Таким образом, регистрация sessionB не удалась, и dubbo проигнорировал это исключение и подумал, что все в порядке.
4. Через некоторое время, поскольку сеанс A фактически был отключен, нормальное сердцебиение не может поддерживаться, поэтому по истечении периода ожидания zk отключает сеанс A и очищает узел провайдера, соответствующий сеансу A.

В этот момент моделируется процесс потери всего узла провайдера.

Далее мы можем проверить некоторые догадки в описанном выше процессе через исходный код:

О. Служба dubbo игнорирует исключения NodeExists.

package com.helijia.dubbox.remoting.zookeeper.curator;

public class CuratorZookeeperClient extends AbstractZookeeperClient<CuratorWatcher> {
  
    ... ...
  
    public void createEphemeral(String path) {
        try {
            client.create().withMode(CreateMode.EPHEMERAL).forPath(path);
        } catch (NodeExistsException ignored) {
        } catch (Exception e) {
            throw new IllegalStateException(e.getMessage(), e);
        }
    }
}

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

B. обработка сеанса zkA

package org.apache.zookeeper.server;

public class SessionTrackerImpl extends ZooKeeperCriticalThread implements SessionTracker {
  
    ... ...
  
    @Override
    synchronized public void run() {
        try {
            while (running) {
                currentTime = Time.currentElapsedTime();
                if (nextExpirationTime > currentTime) {
                    this.wait(nextExpirationTime - currentTime);
                    continue;
                }
                SessionSet set;
                set = sessionSets.remove(nextExpirationTime);
                if (set != null) {
                    for (SessionImpl s : set.sessions) {
                        setSessionClosing(s.sessionId);
                        expirer.expire(s);
                    }
                }
                nextExpirationTime += expirationInterval;
            }
        } catch (InterruptedException e) {
            handleException(this.getName(), e);
        }
        LOG.info("SessionTrackerImpl exited loop!");
    }
}

Этот код используется для работы с сеансами с истекшим сроком действия.Когда вы видите это, вы можете спросить, если это так, сеанс будет убит во время выборов zk.На самом деле это не так.Как только кластер zk недоступен,runningпеременная становится ложной, иsessionSetsОн будет сохранен в базе данных zk (этот код не будет опубликован). Этот цикл завершится, подождите, пока zk вернется в нормальное состояние, а затем возобновите исходный сеанс.

Далее мы можем посмотреть,SessionTrackerImplЧто такое nextExpirationTime, когда он только что создан,

package org.apache.zookeeper.server;

public class SessionTrackerImpl extends ZooKeeperCriticalThread implements SessionTracker {
    public SessionTrackerImpl(SessionExpirer expirer,
            ConcurrentHashMap<Long, Integer> sessionsWithTimeout, int tickTime,
            long sid, ZooKeeperServerListener listener)
    {
        super("SessionTracker", listener);
        this.expirer = expirer;
        this.expirationInterval = tickTime;
        this.sessionsWithTimeout = sessionsWithTimeout;
        nextExpirationTime = roundToInterval(Time.currentElapsedTime());
        this.nextSessionId = initializeNextSession(sid);
        for (Entry<Long, Integer> e : sessionsWithTimeout.entrySet()) {
            addSession(e.getKey(), e.getValue());
        }
    }
    
    private long roundToInterval(long time) {
        // We give a one interval grace period
        return (time / expirationInterval + 1) * expirationInterval;
    }
}

Как видно из приведенного выше кода, начальныйnextExpirationTimeСравниватьcurrentTimeЕще один период тайм-аута, то есть после того, как zk вернется в нормальное состояние, ему нужно подождать в течение периода тайм-аута, прежде чем очистить исходный недействительный сеанс.

Что касается упомянутой выше проблемы персистентности старой сессии, мы можем подтвердить это из процесса создания сессии.Таким образом, из переданного второго параметра мы можем знать, что данные сессии изначально получены из базы данных zk. (Конечно, доказательства здесь недостаточно, можно попробовать создать временную ноду через zkCli, затем быстро остановить zk, а затем запустить zk, тогда мы сможем обнаружить, что предыдущая временная нода все еще существует в течение некоторого периода времени после запуска )

package org.apache.zookeeper.server;

public class ZooKeeperServer implements SessionExpirer, ServerStats.Provider {
    
    ... ...
    
    protected void createSessionTracker() {
        // 第二个参数可以看出session数据初始时会从zk的数据库中进行获取
        sessionTracker = new SessionTrackerImpl(this, zkDb.getSessionWithTimeOuts(),
                tickTime, 1, getZooKeeperServerListener());
    }
}

На этом этапе мы можем полностью объяснить первый вопрос.

вопрос второй, вопрос третий

По вопросам два и три в принципе можно сделать вывод, что это не случайное событие, а неизбежное. Поскольку все приложения используют один и тот же zk, эта проблема не должна иметь ничего общего с zk, это должна быть проблема на стороне сервиса dubbo. Тогда наверное можно догадаться, что это связано с версиями сторонних библиотек типа dubbo, zkCli, dubbox и curator.

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

Анализ на основе логов

На этот раз расследование все же ведется путем воспроизведения сцены, на этот раз я выбрал для наблюдения обычный даббо-сервис и проблемный даббо-сервис, и соответственно выбрал одну из сессий их провайдера для отслеживания. Такая же операция выполняется для отключения сети между зк, и время отключения составляет около 2 минут.

Журнал нормального сервиса dubbo выглядит следующим образом:

2020-03-11 10:23:56,975 [org.apache.zookeeper.ClientCnxn]-[localhost-startStop-1-SendThread(10.3.6.39:12181)]-[onConnected]-[1299]-[INFO] Session establishment complete on server 10.3.6.39/10.3.6.39:12181, sessionid = 0x170c26cf67a0011, negotiated timeout = 40000
2020-03-11 11:40:33,357 [org.apache.zookeeper.ClientCnxn]-[localhost-startStop-1-SendThread(10.3.6.39:12181)]-[run]-[1158]-[INFO] Unable to read additional data from server sessionid 0x170c26cf67a0011, likely server has closed socket, closing socket connection and attempting reconnect
2020-03-11 11:40:35,009 [org.apache.zookeeper.ClientCnxn]-[localhost-startStop-1-SendThread(10.3.6.39:12181)]-[run]-[1158]-[INFO] Unable to read additional data from server sessionid 0x170c26cf67a0011, likely server has closed socket, closing socket connection and attempting reconnect
... ...
2020-03-11 11:42:39,282 [org.apache.zookeeper.ClientCnxn]-[localhost-startStop-1-SendThread(10.3.6.39:12181)]-[run]-[1158]-[INFO] Unable to read additional data from server sessionid 0x170c26cf67a0011, likely server has closed socket, closing socket connection and attempting reconnect
2020-03-11 11:42:40,502 [org.apache.zookeeper.ClientCnxn]-[localhost-startStop-1-SendThread(10.3.6.39:12181)]-[run]-[1158]-[INFO] Unable to read additional data from server sessionid 0x170c26cf67a0011, likely server has closed socket, closing socket connection and attempting reconnect
2020-03-11 11:42:42,117 [org.apache.zookeeper.ClientCnxn]-[localhost-startStop-1-SendThread(10.3.6.39:12181)]-[onConnected]-[1299]-[INFO] Session establishment complete on server 10.3.6.39/10.3.6.39:12181, sessionid = 0x170c26cf67a0011, negotiated timeout = 40000

Журнал проблемного сервиса dubbo выглядит следующим образом:

2020-03-11 10:24:42,548 [org.apache.zookeeper.ClientCnxn]-[Curator-Framework-0-SendThread(10.3.6.39:12181)]-[onConnected]-[1299]-[INFO] Session establishment complete on server 10.3.6.39/10.3.6.39:12181, sessionid = 0x170c7688bbc0001, negotiated timeout = 40000
2020-03-11 11:41:24,733 [org.apache.zookeeper.ClientCnxn]-[Curator-Framework-0-SendThread(10.3.8.118:12181)]-[run]-[1158]-[INFO] Unable to read additional data from server sessionid 0x170c7688bbc0001, likely server has closed socket, closing socket connection and attempting reconnect
2020-03-11 11:41:25,400 [org.apache.zookeeper.ClientCnxn]-[Curator-Framework-0-SendThread(10.3.8.117:12181)]-[run]-[1158]-[INFO] Unable to read additional data from server sessionid 0x170c7688bbc0001, likely server has closed socket, closing socket connection and attempting reconnect
... ...
2020-03-11 11:42:23,802 [org.apache.zookeeper.ClientCnxn]-[Curator-Framework-0-SendThread(10.3.8.117:12181)]-[run]-[1158]-[INFO] Unable to read additional data from server sessionid 0x170c7688bbc0001, likely server has closed socket, closing socket connection and attempting reconnect
2020-03-11 11:42:23,972 [org.apache.zookeeper.ClientCnxn]-[Curator-Framework-0-SendThread(10.3.6.39:12181)]-[run]-[1158]-[INFO] Unable to read additional data from server sessionid 0x170c7688bbc0001, likely server has closed socket, closing socket connection and attempting reconnect
2020-03-11 11:42:24,841 [org.apache.curator.ConnectionState]-[DubboRegistryFailedRetryTimer-thread-1]-[checkTimeouts]-[191]-[WARN] Connection attempt unsuccessful after 60007 (greater than max timeout of 60000). Resetting connection and trying again with a new connection.
2020-03-11 11:42:25,277 [org.apache.zookeeper.ZooKeeper]-[DubboRegistryFailedRetryTimer-thread-1]-[close]-[684]-[INFO] Session: 0x170c7688bbc0001 closed
2020-03-11 11:42:25,277 [org.apache.zookeeper.ClientCnxn]-[Curator-Framework-0-EventThread]-[run]-[519]-[INFO] EventThread shut down for session: 0x170c7688bbc0001

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

Глядя на логи рабочей среды, выясняется, что проблемы есть не только у 6 dubbo-сервисов платежного звена, а всего затронуто более 20 приложений, но только 6 приложений платежного звена предоставляют провайдеры, а все остальные приложения имеют только потребителей.

Эту проблему можно объяснить феноменом лога, а потом нам еще нужно найти настоящую причину из исходного кода.

Найдите причину в исходном коде

найди первымConnection attempt unsuccessful after 60007 (greater than max timeout of 60000). Resetting connection and trying again with a new connection.Место кода, где находится этот журнал,

package org.apache.curator;

class ConnectionState implements Watcher, Closeable {
    
    ... ...
    
    private synchronized void checkTimeouts() throws Exception
    {
        int minTimeout = Math.min(sessionTimeoutMs, connectionTimeoutMs);
        long elapsed = System.currentTimeMillis() - connectionStartMs;
        if ( elapsed >= minTimeout )
        {
            if ( zooKeeper.hasNewConnectionString() )
            {
                handleNewConnectionString();
            }
            else
            {
                int maxTimeout = Math.max(sessionTimeoutMs, connectionTimeoutMs);
                if ( elapsed > maxTimeout )
                {
                    if ( !Boolean.getBoolean(DebugUtils.PROPERTY_DONT_LOG_CONNECTION_ISSUES) )
                    {
                        log.warn(String.format("Connection attempt unsuccessful after %d (greater than max timeout of %d). Resetting connection and trying again with a new connection.", elapsed, maxTimeout));
                    }
                    reset();
                }
                else
                {
                    KeeperException.ConnectionLossException connectionLossException = new CuratorConnectionLossException();
                    if ( !Boolean.getBoolean(DebugUtils.PROPERTY_DONT_LOG_CONNECTION_ISSUES) )
                    {
                        log.error(String.format("Connection timed out for connection string (%s) and timeout (%d) / elapsed (%d)", zooKeeper.getConnectionString(), connectionTimeoutMs, elapsed), connectionLossException);
                    }
                    new EventTrace("connections-timed-out", tracer.get(), getSessionId()).commit();
                    throw connectionLossException;
                }
            }
        }
    }
}

После некоторой отладки я обнаружил, что разница между обычным приложением и проблемным приложением здесь. Как показано на рисунке ниже, обычное приложение будетelapsed>connectionTimeoutMsОно заблокировано в красной части рисунка ниже, и проблемное приложение будет продолжать работать до тех пор, покаelapsed > maxTimeoutЗатем сбросьте сеанс.

image-20200311163446869

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

image-20200311165058123

Затем следующее, что привлекает внимание, это условие суждения.Код следующий, коды обоих одинаковы,

image-20200311165600268

Отладка показала, что обаclient.getRetryPolicy()Возвращаемая стратегия повтора отличается, нормальное приложение возвращает n=1, проблемное приложение возвращает n=Integer.MAX_VALUE. Затем давайте посмотрим на процесс инициализации retryPolicy из двух.

Отладка, чтобы найти метод инъекции retryPolicy

проблемное приложение

Для проблемного приложения, как показано на рисунке ниже, поскольку это старое приложение, CuratorZookeeperClient использует dubbox-1.0.4, а число повторных попыток по умолчанию равно бесконечности (Integer.MAX_VALUE).

image-20200311161008906

обычное приложение

Для обычных приложений, как показано на рисунке ниже, CuratorZookeeperClient загружает dubbo-2.6.7, а количество попыток по умолчанию равно 1.

image-20200311160525435

Проверьте здесь, вы можете получить заключение,В этом разница между версиями dubbo, используемыми двумя: Dubbo-2.6.7 не будет иметь этой проблемы, но dubbox-1.0.4 (dubbo-2.5.3) будет иметь эту проблему..

То же, что и версия dubbo (2.5.3), одна нормальная, а другая неисправная

Но на этом история не заканчивается. Дело обстоит сложнее, чем предполагалось, на самом деле все рассматриваемые приложения используют dubbo2.5.3, но не все приложения dubbo2.5.3 имеют проблемы, а некоторые приложения dubbo2.5.3 действительно работают нормально.

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

<dubbo:registry protocol="zookeeper" address="${user.dubbo.zk.servers}" client="curatorx" />

Обычное применение конфигурации dubbo выглядит следующим образом:

<dubbo:registry protocol="zookeeper" address="${dubbo.registry.address}" check="true" />

Для версии dubbo2.5.3 по умолчанию используется zkclient, как показано ниже.Так обычное приложение не загружает клиент куратора, а проблемное приложение указывает использование куратора в качестве клиента.

dubbo-2.5.3

Само собой для dubbo2.6.7 в качестве zk клиента по умолчанию используется куратор

dubbo-2.6.7

В заключение

В моем случае задействованы только dubbo2.5.3 и dubbo2.6.7, другие версии dubbo проверяйте сами

До сих пор все три вышеуказанных вопроса были объяснены.

Подводя итог, при использовании версии dubbo 2.5.3 (другие более низкие версии dubbo могут иметь аналогичные проблемы) и назначении клиента куратором будет явление исчезновения провайдера после недоступности zookeeper более определенного времени период времени.

Категории