Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

多个节点的数据不一致了 #8099

Closed
wangdongyun opened this issue Apr 7, 2022 · 23 comments · Fixed by #8693
Closed

多个节点的数据不一致了 #8099

wangdongyun opened this issue Apr 7, 2022 · 23 comments · Fixed by #8693

Comments

@wangdongyun
Copy link

wangdongyun commented Apr 7, 2022

Describe the bug
版本 2.0.3
生产环境部署了5节点,其中一个节点的raft状态有问题,通过前端 Nginix 将有问题的节点 摘除流量,然后删除raft 数据重启,raft状态恢复正常!但是导致一段时间内 多个节点的 临时实例的 个数不一致了,导致 推送给客户端大量的删除事件->故障#
image

一共5节点部署,其中两个实例 注册地实例数量 跌到了1/3到1/2

@wangdongyun
Copy link
Author

[sys_su@ip-10-21-40-240 logs]$ grep '2022-04-07 11:05' naming-server.log | grep 'disconnect, remove instances and subscribers' | wc -l
1129
出问题期间 有1千多个实例下线的log

@wangdongyun
Copy link
Author

wangdongyun commented Apr 7, 2022

进一步问题跟进:
在raft有异常的节点上,有这样的日志, 该节点我们使用 19标记,从该节点的视角来看 ,peer 节点是 90 和 212. 90 和 212 临时实例没有大批下线,大批下线的是另外两个
2022-04-07 11:02:53,421 WARN Node <naming_persistent_service_v2/10.21.42.19:7848> can't do preVote as it is not in conf <ConfigurationEntry [id=LogId [index=76, term=7], conf=10.21.42.90:7848,10.21.41.212:7848, oldConf=]>.

@wangdongyun
Copy link
Author

wangdongyun commented Apr 7, 2022

2022-04-07 00:00:02,186 WARN Node <naming_persistent_service_v2/10.21.42.19:7848> can't do preVote as it is not in conf <ConfigurationEntry [id=LogId [index=76, term=7], conf=10.21.42.90:7848,10.21.41.212:7848, oldConf=]>.
这个报错的原因,应该是恢复异常,前一天在 集群页面操作了 单节点199(某个节点) 下线! 当时199宕机了,导致集群的数据同步出现了拥堵(distro 同步队列pending 猜测是),出现了数据一致性告警,所以操作了集群下线!

集群下线是一个 “玩死” 操作,整个集群挂掉, 死循环下线,整个集群的状态 不断抖动 (ACTIVE\DOWN\XX),

这个时候整个集群问题不大(也不太健康,但是业务上没有大规模泛滥),可以正常对外提供服务!

当时进一步 “玩死”操作,1. 关闭了一个节点,此时集群变成了3节点 2. 下线剩余的两个节点(控制台操作)(高危)3.下线的两个节点仍然对外服务=> 当时害怕一个节点扛不住,以为这个时候只有新注册地实例才有可能不一致====》但是结果是致命的,下线的两个节点 大面积的临时实例下线(吐血)(故障) 4. 重新上线恢复的整个集群

从第二天的集群检查结果来看,集群恢复的还是有些问题,其中 19节点的raft 组显示异常,并且有上面地warn 日志
2022-04-07 11:02:53,421 WARN Node <naming_persistent_service_v2/10.21.42.19:7848> can't do preVote as it is not in conf <ConfigurationEntry [id=LogId [index=76, term=7], conf=10.21.42.90:7848,10.21.41.212:7848, oldConf=]>.

又一次 聪明的 敢死队 操作!自以为聪明的,先摘掉流量,然后删除数据重启,导致的两个实例大面积下线实例。 连续两天=> 被逼跑路~~

事后 看日志,发现是 19点在raft 组里面找不到自身,导致投票无法成功! 这里必然证明了 在控制台操作下线 是多么的危险和不靠谱!!!

@wangdongyun
Copy link
Author

wangdongyun commented Apr 7, 2022

19 节点 最后一次成员变更日志

2022-04-06 11:16:42,659 WARN [serverlist] updated to :
[Member{ip='10.21.41.199', port=8848, state=UP, extendInfo={raftPort=7848}},
Member{ip='10.21.40.240', port=8848, state=UP, extendInfo={raftPort=7848}},
Member{ip='10.21.42.19', port=8848, state=UP, extendInfo={lastRefreshTime=1649243272662, raftMetaData=com.alibaba.nacos.consistency.ProtocolMetaData@15fe8fcd, raftPort=7848, version=2.0.3}},
Member{ip='10.21.42.90', port=8848, state=UP, extendInfo={lastRefreshTime=1649243797570, raftMetaData={metaDataMap={naming_instance_metadata={leader=10.21.42.90:7848, raftGroupMember=[10.21.42.90:7848, 10.21.41.212:7848], term=7}, naming_persistent_service={leader=10.21.42.90:7848, raftGroupMember=[10.21.42.90:7848, 10.21.41.212:7848], term=8}, naming_persistent_service_v2={leader=10.21.42.90:7848, raftGroupMember=[10.21.42.90:7848, 10.21.41.212:7848], term=8}, naming_service_metadata={leader=10.21.42.90:7848, raftGroupMember=[10.21.42.90:7848, 10.21.41.212:7848], term=7}}}, raftPort=7848, version=2.0.3}},
Member{ip='10.21.41.212', port=8848, state=UP, extendInfo={lastRefreshTime=1649243794777, raftMetaData={metaDataMap={naming_instance_metadata={leader=10.21.42.90:7848, raftGroupMember=[10.21.42.90:7848, 10.21.41.212:7848], term=7}, naming_persistent_service={leader=10.21.42.90:7848, raftGroupMember=[10.21.42.90:7848, 10.21.41.212:7848], term=8}, naming_persistent_service_v2={leader=10.21.42.90:7848, raftGroupMember=[10.21.42.90:7848, 10.21.41.212:7848], term=8}, naming_service_metadata={leader=10.21.42.90:7848, raftGroupMember=[10.21.42.90:7848, 10.21.41.212:7848], term=7}}}, raftPort=7848, version=2.0.3}}]

@wangdongyun
Copy link
Author

wangdongyun commented Apr 7, 2022

我找了一个问题实例, 大规模下线实例的日志 ,下面的日志来自于240 grep 所有日志
naming-distro.log:2022-04-07 11:02:55,802 INFO client 1649329373866_10.2.95.178_36534 is invalid, get new client from 10.21.42.90
naming-distro.log:2022-04-07 11:02:56,261 INFO [Client-Add] Received distro client sync data 1649329373866_10.2.95.178_36534
naming-distro.log:2022-04-07 11:06:27,279 INFO client 1649329373866_10.2.95.178_36534 is invalid, get new client from 10.21.42.90
naming-distro.log:2022-04-07 11:06:28,621 INFO [Client-Add] Received distro client sync data 1649329373866_10.2.95.178_36534

从上面地日志可以看到,1649329373866_10.2.95.178_36534 来自90 这个实例,同时保存时间为3分钟左右,初步判定是90 在这几分钟内没有发送 心跳 verifydata事件=====> 进一步排查中~~~~

使用搜索Ip 命令 grep '10.2.95.178' *log
naming-distro.log:2022-04-07 06:18:00,096 INFO client 1649312277541_10.2.95.178_34562 is invalid, get new client from 10.21.42.19
naming-distro.log:2022-04-07 06:18:00,111 INFO [Client-Add] Received distro client sync data 1649312277541_10.2.95.178_34562
这个实例原本属于我们重启的19实例
当我们重启 19后,漂移到了 90

3分钟以后,两个client 都完成下线~
naming-server.log:2022-04-07 11:05:53,856 INFO Client connection 1649312277541_10.2.95.178_34562 disconnect, remove instances and subscribers
naming-server.log:2022-04-07 11:05:58,861 INFO Client connection 1649329373866_10.2.95.178_36534 disconnect, remove instances and subscribers
说明这段一直是没有 verify 事件的!

又发现了这样的日志
naming-distro.log:2022-04-07 11:06:27,279 INFO client 1648452155808_10.2.69.48_52524 is invalid, get new client from 10.21.42.90
naming-distro.log:2022-04-07 11:07:41,802 INFO client 1648452155808_10.2.69.48_52524 is invalid, get new client from 10.21.42.90
naming-distro.log:2022-04-07 11:07:41,873 INFO client 1648452155808_10.2.69.48_52524 is invalid, get new client from 10.21.42.90
naming-distro.log:2022-04-07 11:07:41,903 INFO client 1648452155808_10.2.69.48_52524 is invalid, get new client from 10.21.42.90
naming-distro.log:2022-04-07 11:07:42,036 INFO client 1648452155808_10.2.69.48_52524 is invalid, get new client from 10.21.42.90
naming-distro.log:2022-04-07 11:07:42,114 INFO client 1648452155808_10.2.69.48_52524 is invalid, get new client from 10.21.42.90
naming-distro.log:2022-04-07 11:07:42,124 INFO client 1648452155808_10.2.69.48_52524 is invalid, get new client from 10.21.42.90
naming-distro.log:2022-04-07 11:07:42,130 INFO client 1648452155808_10.2.69.48_52524 is invalid, get new client from 10.21.42.90
naming-distro.log:2022-04-07 11:07:42,327 INFO client 1648452155808_10.2.69.48_52524 is invalid, get new client from 10.21.42.90
naming-distro.log:2022-04-07 11:07:42,338 INFO client 1648452155808_10.2.69.48_52524 is invalid, get new client from 10.21.42.90
naming-distro.log:2022-04-07 11:07:42,737 INFO client 1648452155808_10.2.69.48_52524 is invalid, get new client from 10.21.42.90
naming-distro.log:2022-04-07 11:07:42,802 INFO client 1648452155808_10.2.69.48_52524 is invalid, get new client from 10.21.42.90
naming-distro.log:2022-04-07 11:07:42,810 INFO client 1648452155808_10.2.69.48_52524 is invalid, get new client from 10.21.42.90
naming-distro.log:2022-04-07 11:07:43,072 INFO client 1648452155808_10.2.69.48_52524 is invalid, get new client from 10.21.42.90
naming-distro.log:2022-04-07 11:07:43,089 INFO client 1648452155808_10.2.69.48_52524 is invalid, get new client from 10.21.42.90
naming-distro.log:2022-04-07 11:07:43,094 INFO client 1648452155808_10.2.69.48_52524 is invalid, get new client from 10.21.42.90
naming-distro.log:2022-04-07 11:07:43,278 INFO client 1648452155808_10.2.69.48_52524 is invalid, get new client from 10.21.42.90
naming-distro.log:2022-04-07 11:07:43,285 INFO client 1648452155808_10.2.69.48_52524 is invalid, get new client from 10.21.42.90
naming-distro.log:2022-04-07 11:07:43,984 INFO client 1648452155808_10.2.69.48_52524 is invalid, get new client from 10.21.42.90
naming-distro.log:2022-04-07 11:07:43,990 INFO client 1648452155808_10.2.69.48_52524 is invalid, get new client from 10.21.42.90
naming-distro.log:2022-04-07 11:07:44,747 INFO client 1648452155808_10.2.69.48_52524 is invalid, get new client from 10.21.42.90
naming-distro.log:2022-04-07 11:07:44,778 INFO client 1648452155808_10.2.69.48_52524 is invalid, get new client from 10.21.42.90
naming-distro.log:2022-04-07 11:07:44,788 INFO client 1648452155808_10.2.69.48_52524 is invalid, get new client from 10.21.42.90
naming-distro.log:2022-04-07 11:07:45,174 INFO client 1648452155808_10.2.69.48_52524 is invalid, get new client from 10.21.42.90
naming-distro.log:2022-04-07 11:07:45,180 INFO client 1648452155808_10.2.69.48_52524 is invalid, get new client from 10.21.42.90
naming-distro.log:2022-04-07 11:07:46,068 INFO client 1648452155808_10.2.69.48_52524 is invalid, get new client from 10.21.42.90
naming-distro.log:2022-04-07 11:07:46,068 INFO client 1648452155808_10.2.69.48_52524 is invalid, get new client from 10.21.42.90
naming-distro.log:2022-04-07 11:07:46,081 INFO client 1648452155808_10.2.69.48_52524 is invalid, get new client from 10.21.42.90
naming-distro.log:2022-04-07 11:07:47,552 INFO client 1648452155808_10.2.69.48_52524 is invalid, get new client from 10.21.42.90
naming-distro.log:2022-04-07 11:07:47,566 INFO client 1648452155808_10.2.69.48_52524 is invalid, get new client from 10.21.42.90

这个日志刷新了30次,怀疑是挤压了,正常5s搞一次,对应2分半,是不是堆积了2分半呢

通过 命令查看 线上集群 本身并不均匀, 客户端大部门连接的都是 90 这台机器,所以 90的同步压力会很大,
难道是因为宕机了某台机器导致的拥堵吗?

@wangdongyun
Copy link
Author

wangdongyun commented Apr 7, 2022

90 这个实例的最后一个 member 变更-> 5节点,表现正常

2022-04-06 11:16:09,216 WARN [serverlist] updated to : [Member{ip='10.21.41.199', port=8848, state=UP, extendInfo={raftPort=7848}}, Member{ip='10.21.42.19', port=8848, state=UP, extendInfo={raftPort=7848}}, Member{ip='10.21.42.90', port=8848, state=UP, extendInfo={lastRefreshTime=1649243582689, raftMetaData=com.alibaba.nacos.consistency.ProtocolMetaData@3d57bb9b, raftPort=7848, version=2.0.3}}, Member{ip='10.21.40.240', port=8848, state=UP, extendInfo={raftPort=7848}}, Member{ip='10.21.41.212', port=8848, state=UP, extendInfo={raftPort=7848}}]

@wangdongyun
Copy link
Author

wangdongyun commented Apr 7, 2022

难道结论是?: 重启一个节点 要控制在3min 内,理由,这段期间临时实例不会下线,即使同步有拥堵也不会有这个问题,
3min 内启动后,拥堵结束~~~~

@onewe
Copy link
Collaborator

onewe commented Apr 8, 2022

有点意思,mark 一下

@MajorHe1
Copy link
Collaborator

MajorHe1 commented Apr 8, 2022

跟我碰到的问题是一样的。

临时实例的注册和同步情况跟 raft没有关系 (nacos 的 raft协议感觉经常出问题),各种raft的错误日志是有节点不正常导致的。建议把重点放到distro协议上,关注一下protocol-distro日志,里面是否出现了大量的failed。

说一下我的复现步骤:
2.0.3版本,我们的集群目前6个节点,4个正常,2个主动停掉两天。
正常的节点中,不断的有大量客户端注册和注销,就会积累足够多的distroTask,这些task向停掉的节点进行同步,会一直失败然后不断重试。
到后面,向正常的节点再注册新的客户端,protocol-distro.log 里面根本就看不到 [DISTRO-START] 的日志了,也就是说新的distroTask没有被执行。
按照上述步骤应该很容易就能复现你说的场景了。

@wangdongyun
Copy link
Author

wangdongyun commented Apr 8, 2022

你的这个复现场景 属于典型的积压导致~
新注册的实例需要很长的时间才能同步到其他实例上~~
这个可以理解

线上遇到的问题是 重启单个节点(5分钟停歇) 导致了大规模的实例下线
现在生产环境完全不敢动弹了

@MajorHe1
Copy link
Collaborator

MajorHe1 commented Apr 8, 2022

正好在你开的另外一个issue也看到了,你的客户端是2.0.3的版本还是1.x的版本?

另外,积压跟实例下线是相伴相生的,因为verify的task得不到执行,节点就会把不是跟自己直接建立连接的客户端及其注册的服务和监听踢掉,这样集群内不同节点的服务数据不一致,也会出现你看到的大规模实例下线的状况了。

我猜这个时候下线的实例并不是在所有的节点注销了,而是只在自己建连得节点上能看到,是这个样子吗?

@YunWZ
Copy link
Contributor

YunWZ commented Apr 8, 2022

没记错的话,临时实例走distro协议(弱一致性),持久化实例才走raft协议.然后distro协议,同步信息给其他节点,如果同步失败,会进行重试,而同步时使用的服务实例地址则来自你的配置(address-server或者config-file)..

@wangdongyun
Copy link
Author

wangdongyun commented Apr 9, 2022

正好在你开的另外一个issue也看到了,你的客户端是2.0.3的版本还是1.x的版本?

另外,积压跟实例下线是相伴相生的,因为verify的task得不到执行,节点就会把不是跟自己直接建立连接的客户端及其注册的服务和监听踢掉,这样集群内不同节点的服务数据不一致,也会出现你看到的大规模实例下线的状况了。

我猜这个时候下线的实例并不是在所有的节点注销了,而是只在自己建连得节点上能看到,是这个样子吗?

  1. 目前客户端 大部分都是2.x
  2. 积压跟实例下线是相伴相生的,因为verify的task得不到执行,节点就会把不是跟自己直接建立连接的客户端及其注册的服务和监听踢掉,这样集群内不同节点的服务数据不一致,也会出现你看到的大规模实例下线的状况了 目前初步猜测是这种情况,还在排查中,目前没有找到核心指标 可以得到当时集群的运行状态,还在分析中。
  3. 停止 19节点->启动19节点前,集群是4个实例,其中两个实例的实例数量不受到影响,剩余两个实例 出现的大规模注册实例掉线情况。
  4. 目前还发现了一些Case:
    1)整个集群的恢复时间和我恢复19节点的时间点一致
    2)线上实例分布不均匀,大部门在90节点上(grpc)
    3)19节点一挂,就立刻出现拥堵(猜测),细节还在排查~~~

@wangdongyun
Copy link
Author

wangdongyun commented Apr 10, 2022

结论是对的! 的确是因为19宕机导致的拥堵
生产环境使用的4 core,默认开启了4个同步线程~
大规模掉线是 240 和 212, verify 线程池通过memeber+type 进行的分片!
对于90节点来说,宕机实例 19 和 240、199 对应了同一个线程
而对于 212来讲,是另外的线程~~
因为 只有 240、199 出现了大规模实例掉线情况~~

@wangdongyun
Copy link
Author

wangdongyun commented Apr 10, 2022

结论无raft状态无关~~
distro协议的拥堵是一个极其严重的问题,目前缺少指标,内部我们曾经加过,但是没想到 比想象中还要严重~~

protocol-distro.log.2022-04-06.0:2022-04-06 11:04:52,748 WARN task com.alibaba.nacos.core.distributed.distro.task.verify.DistroVerifyExecuteTask@71418d55 takes 41936ms
protocol-distro.log.2022-04-07.0:2022-04-07 11:06:20,939 WARN task com.alibaba.nacos.core.distributed.distro.task.verify.DistroVerifyExecuteTask@6df46312 takes 205153ms
protocol-distro.log.2022-04-07.0:2022-04-07 11:07:41,762 WARN task com.alibaba.nacos.core.distributed.distro.task.verify.DistroVerifyExecuteTask@117db6b6 takes 74495ms
这里显示了拥堵情况

@wangdongyun
Copy link
Author

为啥 单点宕机 这么立杆剪影了,整个集群立马跪~~~
对于verfiy 如果有单点故障,对应日志
2022-04-07 11:07:42,137 ERROR [Cluster-10.21.42.19:8848]Send request fail, request=DistroDataRequest{headers={}, requestId='null'}, retryTimes=1,errorMessage=Client not connected.

 if (waitReconnect) {
                    try {
                        //wait client to re connect.
                        Thread.sleep(Math.min(100, callback.getTimeout() / 3));
                    } catch (Exception exception) {
                        //Do nothing.
                    }
                }

这里一次阻塞100ms, 3次 重试,也就是300ms!

当时90有多少数据需要同步呢
最长一次花费了 205s, 超过了3分钟,这个应该是核心原因,205/0.3= 600+,
也就是说如果单个节点超过了600个实例,就会立马跪~~~~~~~~

@wangdongyun
Copy link
Author

wangdongyun commented Apr 10, 2022

如果某个节点宕机超过3分钟,就死~~
这个bug 我理解是十分严重的

@wangdongyun
Copy link
Author

wangdongyun commented Apr 10, 2022

目前nacos 没有找到指标 某个节点到底负责了多少了临时节点~
指标太少了,代码太多V1\V2

@MajorHe1
Copy link
Collaborator

目前nacos 没有找到指标 某个节点到底负责了多少了临时节点~ 指标太少了,代码太多V1\V2

这个指标是有的 #6572

@KomachiSion
Copy link
Collaborator

是否是使用了go-sdk-2.0.0版本?
这个版本sdk有bug
断链重连后不会重新注册和订阅服务。

@wangdongyun
Copy link
Author

目前nacos 没有找到指标 某个节点到底负责了多少了临时节点~ 指标太少了,代码太多V1\V2

这个指标是有的 #6572

OK~ 这个需要升级,内部使用的是 2021.07 的版本

@wangdongyun
Copy link
Author

是否是使用了go-sdk-2.0.0版本? 这个版本sdk有bug 断链重连后不会重新注册和订阅服务。

不是的,线上大部分服务使用的 都是 java 2.x的版本~

@wangdongyun
Copy link
Author

单节点宕机, 向宕机节点数据同步的时候单条需要300ms, 会卡主线程

我理解 这里需要解决阻塞的问题,因为nacos 内部代码很多使用了异步逻辑,本质上不会阻塞
妥协的解法 verifydata 是不是可以 每一个member 都使用单独的线程,避免因为某个member有问题,导致向其他member数据同步也卡主

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
5 participants