Redisson+sentinel race condition bug.
Обнаружение бага.
В результате тестирования связки redisson+redis+sentinel на кластере из трёх серверов с дропом одного из серверов по кругу по 5 минут скриптом. (дроп это простое выключение интерфейса на сервере) Через неопределенное время два часа или день я ловил ошибку “READONLY You can’t write against a read only replica..”. Выяснилось что если остановить дроп-скрипт в момент появления этой ошибки, то выбор нового мастер сервера redisson не происходит и ошибка остается навcегда. Я проверил redis сервера нативным клиентом, на чтение запись и на соответствие одному мастеру на всех, но оказалось что на редисе всё было без нареканий.
Первый репорт бага.
В надежде что разработчик решит мои проблемы, я зарепортил стэк трейс с ошибкой на гитхаб. Но как и оказалось чуда не произошло, и одно стэктрейса было мало чтобы найти и пофиксить это ошибку. Пришлось разбираться самому.
Отладка, изучение исходников.
Поизучав продолжительное время исходные коды redisson проекта, а в частности инициализацию и работу опроса sentinel серверов (это класс SentinelConnectionManager) решил попробывать посмотреть на ошибку в runtime. Для этого нужно было воссоздать ситуацию с багом и прицепица деббагером intellij.
jvm с параметрами отладки выглядит примерно так:
java -agentlib:jdwp=transport=dt_socket,server=y,suspend=n,address=*:8000 app.jar
Далее нужно было найти класс SentinelConnectionManager в тредах с задачами и проверить переменную SentinelConnectionManager.currentMaster указывающий на ip адрес текущего мастера для редис серверов. С адресом проблем не возникло он указывал на верный мастер, но соединение установленное redisson для мастер сервера которое лежит в SentinelConnectionManager.masterSlaveEntry.writeConnectionPool.entires{ClientConnectionsEntry} установленно на другой сервер, отличный от мастера.
Как же так могло получиться ? Так как по коду визуально баг я найти не могу, тогда я решил прибегнуть к лог-отладке, добавил свои отладочные маркеры в проект redisson и перекомпилил проект.
Отладка логированием.
Я добавил сообщения отладки и идентификатор для треда опроса sentinel серверов и вот что я увидел:
./app.log:6691:2023-03-06 02:14:59,036 INFO org.redisson.connection.SentinelConnectionManager [redisson-netty-2-9] MYMY scheduleChangeCheck run683
./app.log:6692:2023-03-06 02:14:59,036 INFO org.redisson.connection.SentinelConnectionManager [redisson-netty-2-9] MYMY checkState reqId = 683
./app.log:6693:2023-03-06 02:14:59,036 INFO org.redisson.connection.SentinelConnectionManager [redisson-netty-2-9] MYMY updateState reqId = 683
./app.log:6694:2023-03-06 02:14:59,036 INFO org.redisson.connection.SentinelConnectionManager [redisson-netty-2-9] MYMY checkMasterChange reqId = 683
./app.log:6696:2023-03-06 02:15:02,131 INFO org.redisson.connection.SentinelConnectionManager [redisson-timer-4-1] MYMY updateState reqId = 683 future.whenComplete
./app.log:6716:2023-03-06 02:15:02,132 INFO org.redisson.connection.SentinelConnectionManager [redisson-timer-4-1] MYMY scheduleChangeCheck 683
./app.log:6717:2023-03-06 02:15:03,133 INFO org.redisson.connection.SentinelConnectionManager [redisson-netty-2-10] MYMY scheduleChangeCheck run684
./app.log:6718:2023-03-06 02:15:03,133 INFO org.redisson.connection.SentinelConnectionManager [redisson-netty-2-10] MYMY checkState reqId = 684
./app.log:6719:2023-03-06 02:15:03,133 INFO org.redisson.connection.SentinelConnectionManager [redisson-netty-2-10] MYMY updateState reqId = 684
./app.log:6720:2023-03-06 02:15:03,133 INFO org.redisson.connection.SentinelConnectionManager [redisson-netty-2-10] MYMY checkMasterChange reqId = 684
./app.log:6721:2023-03-06 02:15:03,134 INFO org.redisson.connection.SentinelConnectionManager [redisson-netty-2-1] MYMY reqId = 684 checkMasterChange compareAndSet current = redis://172.18.20.168:6379 and newMaster = redis://172.18.20.166:6379
./app.log:6756:2023-03-06 02:15:03,137 INFO org.redisson.connection.SingleEntry [redisson-netty-2-1] MYMY 172.18.20.166/172.18.20.166:6379 setupMasterEntry futures wait.
./app.log:6758:2023-03-06 02:15:03,142 INFO org.redisson.connection.SentinelConnectionManager [redisson-netty-2-1] MYMY updateState reqId = 684 future.whenComplete
./app.log:6759:2023-03-06 02:15:03,142 INFO org.redisson.connection.SentinelConnectionManager [redisson-netty-2-1] MYMY scheduleChangeCheck 684
./app.log:6765:2023-03-06 02:15:03,145 INFO org.redisson.connection.SingleEntry [redisson-netty-2-16] MYMY 172.18.20.166/172.18.20.166:6379 setupMasterEntry thenApply - complete.
./app.log:6766:2023-03-06 02:15:03,147 INFO org.redisson.connection.SingleEntry [redisson-netty-2-16] MYMY 172.18.20.166/172.18.20.166:6379 changeMaster -> CHANGED to 172.18.20.166/172.18.20.166:6379
./app.log:6772:2023-03-06 02:15:04,144 INFO org.redisson.connection.SentinelConnectionManager [redisson-netty-2-14] MYMY scheduleChangeCheck run685
./app.log:6773:2023-03-06 02:15:04,144 INFO org.redisson.connection.SentinelConnectionManager [redisson-netty-2-14] MYMY checkState reqId = 685
./app.log:6774:2023-03-06 02:15:04,144 INFO org.redisson.connection.SentinelConnectionManager [redisson-netty-2-14] MYMY updateState reqId = 685
./app.log:6775:2023-03-06 02:15:04,144 INFO org.redisson.connection.SentinelConnectionManager [redisson-netty-2-14] MYMY checkMasterChange reqId = 685
./app.log:6776:2023-03-06 02:15:04,146 INFO org.redisson.connection.SentinelConnectionManager [redisson-netty-2-24] MYMY updateState reqId = 685 future.whenComplete
./app.log:6777:2023-03-06 02:15:04,146 INFO org.redisson.connection.SentinelConnectionManager [redisson-netty-2-24] MYMY scheduleChangeCheck 685
./app.log:6778:2023-03-06 02:15:05,147 INFO org.redisson.connection.SentinelConnectionManager [redisson-netty-2-30] MYMY scheduleChangeCheck run686
По строкам:
./app.log:6759:2023-03-06 02:15:03,142 INFO org.redisson.connection.SentinelConnectionManager [redisson-netty-2-1] MYMY scheduleChangeCheck 684
./app.log:6765:2023-03-06 02:15:03,145 INFO org.redisson.connection.SingleEntry [redisson-netty-2-16] MYMY 172.18.20.166/172.18.20.166:6379 setupMasterEntry thenApply - complete.
Можно понять что callback setup setupMasterEntry отрабатывает после запуска очередного цикла опроса scheduleChangeCheck, а должен отрабатывать до, т.к цикл(функция) должна дождаться всех колбэков и только потом перезапускаться. Скорее всего тут где то кроется race condition.
./app.log:12151:2023-03-06 02:24:58,094 INFO org.redisson.connection.SentinelConnectionManager [redisson-netty-2-1] MYMY scheduleChangeCheck run1265
./app.log:12152:2023-03-06 02:24:58,094 INFO org.redisson.connection.SentinelConnectionManager [redisson-netty-2-1] MYMY checkState reqId = 1265
./app.log:12168:2023-03-06 02:24:58,095 INFO org.redisson.connection.SentinelConnectionManager [redisson-netty-2-1] MYMY updateState reqId = 1265
./app.log:12169:2023-03-06 02:24:58,095 INFO org.redisson.connection.SentinelConnectionManager [redisson-netty-2-1] MYMY checkMasterChange reqId = 1265
./app.log:12170:2023-03-06 02:24:58,096 INFO org.redisson.connection.SentinelConnectionManager [redisson-netty-2-1] MYMY updateState reqId = 1265 future.whenComplete
./app.log:12171:2023-03-06 02:24:58,096 INFO org.redisson.connection.SentinelConnectionManager [redisson-netty-2-1] MYMY scheduleChangeCheck 1265
./app.log:12230:2023-03-06 02:24:59,097 INFO org.redisson.connection.SentinelConnectionManager [redisson-netty-2-5] MYMY scheduleChangeCheck run1266
./app.log:12231:2023-03-06 02:24:59,098 INFO org.redisson.connection.SentinelConnectionManager [redisson-netty-2-5] MYMY checkState reqId = 1266
./app.log:12247:2023-03-06 02:24:59,098 INFO org.redisson.connection.SentinelConnectionManager [redisson-netty-2-5] MYMY updateState reqId = 1266
./app.log:12248:2023-03-06 02:24:59,098 INFO org.redisson.connection.SentinelConnectionManager [redisson-netty-2-5] MYMY checkMasterChange reqId = 1266
./app.log:12249:2023-03-06 02:24:59,099 INFO org.redisson.connection.SentinelConnectionManager [redisson-netty-2-1] MYMY updateState reqId = 1266 future.whenComplete
./app.log:12250:2023-03-06 02:24:59,099 INFO org.redisson.connection.SentinelConnectionManager [redisson-netty-2-1] MYMY scheduleChangeCheck 1266
./app.log:12309:2023-03-06 02:25:00,071 INFO org.redisson.connection.SingleEntry [redisson-netty-2-8] MYMY 172.18.20.167/172.18.20.167:6379 setupMasterEntry -> exception = org.redisson.client.RedisConnectionException: Unable to connect to Redis server: 172.18.20.167/172.18.20.167:6379
./app.log:12310:2023-03-06 02:25:00,071 INFO org.redisson.connection.SingleEntry [redisson-netty-2-8] MYMY 172.18.20.167/172.18.20.167:6379 changeMaster -> exception = org.redisson.client.RedisConnectionException: Unable to connect to Redis server: 172.18.20.167/172.18.20.167:6379
./app.log:12353:2023-03-06 02:25:00,077 INFO org.redisson.connection.SentinelConnectionManager [redisson-netty-2-8] MYMY reqId = 1257 checkMasterChange -> exception = org.redisson.client.RedisConnectionException: Unable to connect to Redis server: 172.18.20.167/172.18.20.167:6379
./app.log:12354:2023-03-06 02:25:00,101 INFO org.redisson.connection.SentinelConnectionManager [redisson-netty-2-7] MYMY scheduleChangeCheck run1267
./app.log:12355:2023-03-06 02:25:00,101 INFO org.redisson.connection.SentinelConnectionManager [redisson-netty-2-7] MYMY checkState reqId = 1267
./app.log:12371:2023-03-06 02:25:00,101 INFO org.redisson.connection.SentinelConnectionManager [redisson-netty-2-7] MYMY updateState reqId = 1267
./app.log:12372:2023-03-06 02:25:00,101 INFO org.redisson.connection.SentinelConnectionManager [redisson-netty-2-7] MYMY checkMasterChange reqId = 1267
./app.log:12373:2023-03-06 02:25:00,102 INFO org.redisson.connection.SentinelConnectionManager [redisson-netty-2-1] MYMY reqId = 1267 checkMasterChange compareAndSet current = redis://172.18.20.166:6379 and newMaster = redis://172.18.20.167:6379
./app.log:12408:2023-03-06 02:25:00,103 INFO org.redisson.connection.SingleEntry [redisson-netty-2-1] MYMY 172.18.20.167/172.18.20.167:6379 setupMasterEntry futures wait.
./app.log:12411:2023-03-06 02:25:00,104 INFO org.redisson.connection.SentinelConnectionManager [redisson-netty-2-1] MYMY updateState reqId = 1267 future.whenComplete
./app.log:12412:2023-03-06 02:25:00,104 INFO org.redisson.connection.SentinelConnectionManager [redisson-netty-2-1] MYMY scheduleChangeCheck 1267
./app.log:12503:2023-03-06 02:25:01,105 INFO org.redisson.connection.SentinelConnectionManager [redisson-netty-2-16] MYMY scheduleChangeCheck run1268
./app.log:12504:2023-03-06 02:25:01,105 INFO org.redisson.connection.SentinelConnectionManager [redisson-netty-2-16] MYMY checkState reqId = 1268
./app.log:12520:2023-03-06 02:25:01,105 INFO org.redisson.connection.SentinelConnectionManager [redisson-netty-2-16] MYMY updateState reqId = 1268
./app.log:12521:2023-03-06 02:25:01,105 INFO org.redisson.connection.SentinelConnectionManager [redisson-netty-2-16] MYMY checkMasterChange reqId = 1268
./app.log:12522:2023-03-06 02:25:01,107 INFO org.redisson.connection.SentinelConnectionManager [redisson-netty-2-1] MYMY updateState reqId = 1268 future.whenComplete
./app.log:12523:2023-03-06 02:25:01,107 INFO org.redisson.connection.SentinelConnectionManager [redisson-netty-2-1] MYMY scheduleChangeCheck 1268
И в продолжении лога мы видим по строкам, что после таймаута соединения вызывается exception callback от треда с очень давним идентификатором reqId = 1257 т.к он ждал таймаут callback исключения не выполнялся, а текущий идентификатор треда опроса reqId = 1267 уже успел на десяток прибавиться(сделать 10 циклов).
./app.log:12353:2023-03-06 02:25:00,077 INFO org.redisson.connection.SentinelConnectionManager [redisson-netty-2-8] MYMY reqId = 1257 checkMasterChange -> exception = org.redisson.client.RedisConnectionException: Unable to connect to Redis server: 172.18.20.167/172.18.20.167:6379
./app.log:12354:2023-03-06 02:25:00,101 INFO org.redisson.connection.SentinelConnectionManager [redisson-netty-2-7] MYMY scheduleChangeCheck run1267
Когда exception callback от треда reqId = 1257 просыпаетца видит что соединение не удалось установить,
он восстанавливает setupMasterEntry(соединение) и currentMaster(адрес) на предыдущие значения.
Но при конкуренции с другим колбэком в другом потоке reqId = 1267,
это приводит к ситуации, когда exception callback восстанавливает соединение на уже неправильного мастера(на данный момент слейва).
В переменную currentMaster записывается адрес верного мастера конкурирующим колбэком.
В результате при новых презапусках треда проверки sentinel серверов т.к currentMaster адрес равен “правильному” мастеру,
система думает что она уже подключена к “правильному” серверу, а реально соединение установлено на другой сервер.
Но при записи получается что мы пишем не в мастер а в слейв, и ошибка становиться явной.
Код фунцкии без фикса:
private CompletionStage<RedisURI> checkMasterChange(SentinelServersConfig cfg, RedisConnection connection) {
RFuture<RedisURI> masterFuture = connection.async(StringCodec.INSTANCE, masterHostCommand, cfg.getMasterName());
return masterFuture.thenCompose(u -> serviceManager.resolveIP(scheme, u))
.whenComplete((newMaster, e) -> {
if (e != null) {
return;
}
RedisURI current = currentMaster.get();
if (!newMaster.equals(current)
&& currentMaster.compareAndSet(current, newMaster)) {
CompletableFuture<RedisClient> changeFuture = changeMaster(singleSlotRange.getStartSlot(), newMaster);
changeFuture.exceptionally(ex -> {
currentMaster.compareAndSet(newMaster, current);
return null;
});
}
});
}
Причина ошибки.
Проблема в том что функция checkMasterChange возвращает CompletionStage
Так выглядит пофиксенная функция от разработчика:
private CompletionStage<RedisClient> checkMasterChange(SentinelServersConfig cfg, RedisConnection connection) {
RFuture<RedisURI> masterFuture = connection.async(StringCodec.INSTANCE, masterHostCommand, cfg.getMasterName());
return masterFuture
.thenCompose(u -> serviceManager.resolveIP(scheme, u))
.thenCompose(newMaster -> {
RedisURI current = currentMaster.get();
if (!newMaster.equals(current)
&& currentMaster.compareAndSet(current, newMaster)) {
CompletableFuture<RedisClient> changeFuture = changeMaster(singleSlotRange.getStartSlot(), newMaster);
return changeFuture.exceptionally(ex -> {
currentMaster.compareAndSet(newMaster, current);
return null;
});
}
return CompletableFuture.completedFuture(null);
});
}
Всё остальное.
Стэк трейс ошибки, даже не намекает на race condition:
2023-03-06 02:24:52,037 INFO com.test.appclean.Application [main] Exception:READONLY You can't write against a read only replica.. channel: [id: 0xdc0ee8bd, L:/172.18.20.166:58492 - R:172.18.20.166/172.18.20.166:6379] command: (SET), promise: java.util.concurrent.CompletableFuture@54d0fcb4[Not completed, 1 dependents], params: [testvar, PooledUnsafeDirectByteBuf(ridx: 0, widx: 8, cap: 256)]org.redisson.client.RedisException: READONLY You can't write against a read only replica.. channel: [id: 0xdc0ee8bd, L:/172.18.20.166:58492 - R:172.18.20.166/172.18.20.166:6379] command: (SET), promise: java.util.concurrent.CompletableFuture@54d0fcb4[Not completed, 1 dependents], params: [testvar, PooledUnsafeDirectByteBuf(ridx: 0, widx: 8, cap: 256)]
at org.redisson.client.handler.CommandDecoder.decode(CommandDecoder.java:380)
at org.redisson.client.handler.CommandDecoder.decodeCommand(CommandDecoder.java:205)
at org.redisson.client.handler.CommandDecoder.decode(CommandDecoder.java:144)
at org.redisson.client.handler.CommandDecoder.decode(CommandDecoder.java:120)
at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:529)
at io.netty.handler.codec.ReplayingDecoder.callDecode(ReplayingDecoder.java:366)
at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:290)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:440)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166)
at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:788)
at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:724)
at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:650)
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:562)
at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)
at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at java.lang.Thread.run(Thread.java:748)
Пример программы для репродукции бага.
package com.test.appclean;
import org.redisson.Redisson;
import org.redisson.api.RedissonClient;
import org.redisson.config.Config;
import org.redisson.config.ReadMode;
import org.redisson.config.SentinelServersConfig;
import org.redisson.config.SubscriptionMode;
import org.redisson.connection.balancer.LoadBalancer;
import org.redisson.connection.balancer.RoundRobinLoadBalancer;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import java.io.PrintWriter;
import java.io.StringWriter;
import java.util.Arrays;
import java.util.List;
public class Application {
private static Logger logger = LoggerFactory.getLogger(Application.class);
/**
* Entry point.
*
* @param args agrs
*/
public static void main(final String[] args) throws InterruptedException {
logger.info("Hello world");
RedissonClient cache = createRedissonCache();
//RedissonClient database = createRedissonDatabase();
int i = 0;
while (true) {
try {
logger.info("\nPPPPPPPPPPP set testvar to val=" +i+"\n");
cache.getBucket("testvar").set("val=" + i);
} catch (Exception e) {
StringWriter sw = new StringWriter();
PrintWriter pw = new PrintWriter(sw);
e.printStackTrace(pw);
logger.info("Exception:"+e.getMessage()+sw.toString());
}
i++;
Thread.sleep( 1000);
}
//Thread.sleep(7 * 24 * 60 * 60 * 1000);
}
public static RedissonClient createRedissonCache() {
String redisDbName = "cacheMaster";
String redisAddresses = "redis://172.18.20.166:26379,redis://172.18.20.167:26379,redis://172.18.20.168:26379";
List<String> hosts = Arrays.asList(redisAddresses.split(","));
Config config = new Config();
SentinelServersConfig connect = config.useSentinelServers().setMasterName(redisDbName);
if (hosts.size() < 2) connect.setCheckSentinelsList(false);
LoadBalancer loadBalancer = new RoundRobinLoadBalancer();
connect.setLoadBalancer(loadBalancer);
connect.setSentinelAddresses(hosts);
connect.setMasterConnectionMinimumIdleSize(1);
connect.setSlaveConnectionMinimumIdleSize(1);
connect.setReadMode(ReadMode.MASTER);
connect.setSubscriptionMode(SubscriptionMode.MASTER);
RedissonClient client = Redisson.create(config);
return client;
}
}
dropscript.sh:
#!/bin/sh
trap ctrl_c INT
function ctrl_c() {
echo "Ctrl + C happened"
exit
}
HOSTS='172.18.20.166 172.18.20.167 172.18.20.168'
while [ 1 = 1 ]; do
for v in $HOSTS; do
echo "$(date +"%T") Go down host $v"
ssh root@$v 'ip link set eth0 down && sleep 5m && ip link set eth0 up'
echo "$(date +"%T") Go up host $v "
#sleep 1m
# exit
done
echo "Wait for next cycle 10s"
sleep 10s
done
Баг пофиксен в версии redisson 3.20.1, версия redis 6.2.6 которая использовалась при тестировании.