服务发现中的服务健康状态一直在波动，导致服务随机的不可用

[zzl221000]

版本：v0.5.23 helm部署，3副本集群 客户端是spring cloud nacos

[heqingpan]

服务实例健康状态大概率和实例心跳间隔有关，如果心跳间隔超过服务判断的心跳超期时长（目前服务默认是15秒）。

可以通过客户端或服务端日志确认实例心跳的间隔。

如果是间隔不匹配，需要把客户端心跳间隔调小（不同使用方式配置不同），或者把服务端检测间隔调大（目前暂不支持配置，后面版本考虑开放配置）。

可以提供一下这个case中客户端nacos-client的版本号还有对应的配置，我抽空去看看能不能复现。

另外可以试试使用单实例r-nacos看看是否是一样的问题，排除是集群同步引入的问题。

[zzl221000]

另外可以试试使用单实例r-nacos看看是否是一样的问题，排除是集群同步引入的问题。

不是心跳问题，两个页面同时打开有时会出现一个true一个false 和上次一样，机器突然断电了，后面就不太正常，看着是集群同步问题

[heqingpan]

这次也是机器空然断电引发的是吗？

控制台上面生效机器实例有几个？有之前一样只是2个？

用上次的方式恢复下有问题的节点再试试？

[zzl221000]

控制台上面生效机器实例有几个？有之前一样只是2个？

这次集群信息上面显示是3个节点，状态都是正常， 只有注册服务健康状态同步有问题，true、false来回变

[zzl221000]

用上次的方式恢复下有问题的节点再试试？ 不知道哪一个节点出现问题了，现在也不好重建数据

[heqingpan]

如果3个节点都显示的话，可能只是注册中心集群同步的问题。

只根据目前的描述信息，不太能直接判断原因，之后我再分析逻辑，同时也看看是不是可以增加必要的检测纠正手段规避这类问题。

先通过重启解决当前问题：可以分别对3个节点依次重启服务，这样应该能恢复服务。

[zzl221000]

可以分别对3个节点依次重启服务，这样应该能恢复服务。

节点重启后还是不正常，有没有什么调查的思路。 这个项目比较老，还是用的spring-cloud-alibaba 2.1.0.RELEASE 内置nacos版本是 java nacos-client: 1.1.1

[heqingpan]

如果重启之后还不正常，那就说明目前这个场景下有问题。

服务端日志有什么报错信息吗？

这个服务之前有正常过吗？

这个问题可能是一个节点认为这个服务归它管，但是超期没收到心跳。要么是集群多个节点划分不一致，要么是心跳请求转发不成功（可能性比较高）。

我晚点也用上面的版本试试看看是否能复现。

[heqingpan]

如果之前能正常运行，依次重启服务还不行的话，可以试试关掉整体集群再重新启动试试。

[zzl221000]

如果之前能正常运行，依次重启服务还不行的话，可以试试关掉整体集群再重新启动试试。

这块先临时切到原版nacos，等节后再测试下

[zzl221000]

https://github.com/user-attachments/assets/7784707c-bbd5-41e5-aa51-ad4b59b80e61

[heqingpan]

现象已确认，服务日志方便提供一下吗？ 3个节点的日志都提供一下？

[zzl221000]

现象已确认，服务日志方便提供一下吗？ 3个节点的日志都提供一下？

需要更改日志等级再提供下日志吗，现在日志是默认的等级 rnacos-0_rnacos.log rnacos-2_rnacos.log rnacos-1_rnacos.log

[heqingpan]

这个INFO级别的日志就可以了。

我先根据日志分析一下，看看能不能按日志进一步确认原因或者在我本地环境复现。 只要能复现，问题就相对好解决。

[heqingpan]

上面的日志只看到集群间的通信日志信息，没有看到客户端请求日志。

java nacos-client: 1.1.1 的话应该有间隔循环的服务实例心跳请求，是因为这个时间段集群没有服务实例注册吗？

如果方便的话，提供下出现上面问题现象时对应的集群日志。

[zzl221000]

@heqingpan 日志好像被滚动了，一会把服务切到rnacos再上传一份日志

[zzl221000]

@heqingpan 这份日志里面有心跳 rnacos-1_rnacos.log rnacos-0_rnacos.log rnacos-2_rnacos.log

[heqingpan]

收到，我这边再通过日志分析一下数据。

[heqingpan]

另外想确认一下，最新的日志数据，当时r-nacos上注册的服务实例其健康状态也是波动的现象吗？

前面的视频中，不是全部服务数有波动，只有部分服务波动，对应有波动的服务名称可以给一个吗？

确认上面的问题，有助于更好的分析数据。

[zzl221000]

另外想确认一下，最新的日志数据，当时r-nacos上注册的服务实例其健康状态也是波动的现象吗？

前面的视频中，不是全部服务数有波动，只有部分服务波动，对应有波动的服务名称可以给一个吗？

确认上面的问题，有助于更好的分析数据。

我这边观察是全部的服务都会出现这个问题，前面视频比较短，所以看到有些服务没有出现波动

[heqingpan]

了解。

那上面的日志数据那个时间段有发生波动现象吗？ 如果有波动当时波动的服务是哪些？

目前我这边暂时没能复现，我想借此在我本地复现问题。

[zzl221000]

那上面的日志数据那个时间段有发生波动现象吗？ 如果有波动当时波动的服务是哪些？

ruiling-client 这个服务在日志期间就是波动的

[heqingpan]

收到，我这边先通过日志分析，有进一步的进展会在issue回复。

准备上班了，估计要晚上才可能有结果。

[heqingpan]

昨晚和今早分别在本地尝试复现。

昨晚没有发现什么问题；

今天早上注册3个服务，其中有一个服务实例在一小段时间内状态变化: 健康 -> 不健康 -> 过期删除 -(过一小段时间)-> 重新注册 ；其它两个服务一直都正常。

初步推理判断：nacos-client: 1.1.1运行时，默认5秒发送一次心跳，长时间运行可能会偶发几次心跳没有发送成功；如果联系两次心跳没有发送成功，那么间隔达到15秒服务实例就会从健康变成不健康；如果联系5次心跳没有发送成功，那么服务实例就会被当做过期删除（早上的case是这个现象）。

上面的推段还需要结合日志再确认一遍。 目前心跳日志分散在3个节点中，不好直接判断；要准备上班了，晚上回来写个脚本把多个日志文件内容合并，并按时间排序后再确认一篇实际情况和我上面的推理是否一致。

如果上面的推理没有问题的话，后面开放服务实例健康时长为可配置，把它的时候调整长一些，应该能解决健康状态波动的大部分问题。

[zzl221000]

初步推理判断：nacos-client: 1.1.1运行时，默认5秒发送一次心跳，长时间运行可能会偶发几次心跳没有发送成功；如果联系两次心跳没有发送成功，那么间隔达到15秒服务实例就会从健康变成不健康；如果联系5次心跳没有发送成功，那么服务实例就会被当做过期删除（早上的case是这个现象）。

但是看我发的视频，以第六个服务为例，会出现5s内多次健康 -> 不健康 -> 健康 -> 不健康 -> 健康，这样的波动，这看上去，更像是集群之间数据不是同步的，请求不是统一给leader处理的

[heqingpan]

上面的现象用目前服务集群同步逻辑是可以解释的，和我上面的推理不冲突。

目前的注册中心集群处理规则如下： 1.根据服务哈希值与集群健康节点列表，确定服务对应的管理节点，服务实例的健康状态由管理节点维护，变更后会同步到其它节点。 2.服务实例变更后，管理节分0.5秒延时窗口同步给其它结点（就算忽略网络传输时间，同步也会有0.5秒左右的延时）

集群间服务数据同步期间，每次访问的控制台节点不同，查询到的状态就不同。

如果客户端发生两次没有同步成功，服务实例刚被标记为不健康再马上收到心跳，那波动的时间就更长。

---

上面推理没错的话，其根因就是客户端心跳有概率上报失败。

解决方式有： 1.服务端延长过期时间； 2.客户端从1.1.1升级到1.4.x（新版本应该会减少发心跳不成功的行为） 3.服务端开启不健康服务实例保护（健康数小于指定比例，可返回不健康实例给消费应用使用） 4.服务部署多个实例，降低同时健康状态为总数为0的机率。

目前问题还需要和日志对比确认，如果确定是这个问题，后面r-nacos会先支持第1点，支持设置延长实例过期时间。

[heqingpan]

昨天晚上通过脚本分析日志，我测试发现状态变化(健康 -> 不健康 -> 过期删除 -(过一小段时间)-> 重新注册)的实例确实是持续一小段时间没有收到客户端上传的心跳报文。

分析后的日志片段

2024-10-15 08:51:20 | 5.0 | n01.log
2024-10-15 08:51:25 | 5.0 | n03.log
2024-10-15 08:51:30 | 5.0 | n03.log
2024-10-15 08:52:30 | 60.0 | n02.log
2024-10-15 08:52:35 | 5.0 | n02.log
2024-10-15 08:52:40 | 5.0 | n01.log
2024-10-15 08:52:45 | 5.0 | n01.log

有一小段时间间隔60秒。

另外,昨天同时测试3个服务，发现服务刚启动前1分钟左右注册间隔都有波动（间隔超过5秒钟）：

服务1：

2024-10-15 08:37:13 | 0.0 | n02.log
2024-10-15 08:37:28 | 15.0 | n02.log
2024-10-15 08:37:38 | 10.0 | n02.log
2024-10-15 08:37:43 | 5.0 | n03.log
2024-10-15 08:37:48 | 5.0 | n03.log
2024-10-15 08:38:03 | 15.0 | n02.log
2024-10-15 08:38:08 | 5.0 | n02.log

服务2:

2024-10-15 08:37:18 | 0.0 | n02.log
2024-10-15 08:37:23 | 5.0 | n02.log
2024-10-15 08:37:38 | 15.0 | n02.log
2024-10-15 08:37:48 | 10.0 | n02.log
2024-10-15 08:37:53 | 5.0 | n02.log
2024-10-15 08:37:58 | 5.0 | n03.log
2024-10-15 08:38:03 | 5.0 | n03.log

服务3:

2024-10-15 08:37:08 | 0.0 | n02.log
2024-10-15 08:37:33 | 25.0 | n02.log
2024-10-15 08:37:43 | 10.0 | n02.log
2024-10-15 08:37:53 | 10.0 | n03.log
2024-10-15 08:37:58 | 5.0 | n02.log
2024-10-15 08:38:18 | 20.0 | n02.log
2024-10-15 08:38:23 | 5.0 | n03.log

---

我今天顺便用脚本分析你上面提供的日志，部分服务心跳的时间间隔也发现波动：

ruiling-client

2024-10-14 00:03:54 | 0.0 | rnacos-1_rnacos.log
2024-10-14 00:03:59 | 5.0 | rnacos-0_rnacos.log
2024-10-14 00:04:04 | 5.0 | rnacos-1_rnacos.log
2024-10-14 00:04:09 | 5.0 | rnacos-1_rnacos.log
2024-10-14 00:04:14 | 5.0 | rnacos-1_rnacos.log
2024-10-14 00:04:19 | 5.0 | rnacos-1_rnacos.log
2024-10-14 00:04:24 | 5.0 | rnacos-0_rnacos.log
2024-10-14 00:04:29 | 5.0 | rnacos-0_rnacos.log
2024-10-14 00:04:34 | 5.0 | rnacos-0_rnacos.log
2024-10-14 00:04:39 | 5.0 | rnacos-2_rnacos.log
2024-10-14 00:04:44 | 5.0 | rnacos-0_rnacos.log
2024-10-14 00:04:49 | 5.0 | rnacos-0_rnacos.log
2024-10-14 00:04:54 | 5.0 | rnacos-0_rnacos.log
2024-10-14 00:04:59 | 5.0 | rnacos-2_rnacos.log
2024-10-14 00:05:04 | 5.0 | rnacos-0_rnacos.log
2024-10-14 00:05:09 | 5.0 | rnacos-1_rnacos.log
2024-10-14 00:05:14 | 5.0 | rnacos-0_rnacos.log
2024-10-14 00:05:19 | 5.0 | rnacos-1_rnacos.log
2024-10-14 00:05:24 | 5.0 | rnacos-2_rnacos.log
2024-10-14 00:05:29 | 5.0 | rnacos-2_rnacos.log
2024-10-14 00:05:34 | 5.0 | rnacos-2_rnacos.log
2024-10-14 00:05:39 | 5.0 | rnacos-2_rnacos.log
2024-10-14 00:05:44 | 5.0 | rnacos-0_rnacos.log
2024-10-14 00:05:50 | 6.0 | rnacos-2_rnacos.log
2024-10-14 00:05:55 | 5.0 | rnacos-1_rnacos.log
2024-10-14 00:06:15 | 20.0 | rnacos-2_rnacos.log

ruiling-filesystem

2024-10-14 00:03:49 | 0.0 | rnacos-2_rnacos.log
2024-10-14 00:03:54 | 5.0 | rnacos-2_rnacos.log
2024-10-14 00:03:59 | 5.0 | rnacos-2_rnacos.log
2024-10-14 00:04:04 | 5.0 | rnacos-2_rnacos.log
2024-10-14 00:04:09 | 5.0 | rnacos-1_rnacos.log
2024-10-14 00:04:14 | 5.0 | rnacos-0_rnacos.log
2024-10-14 00:04:19 | 5.0 | rnacos-1_rnacos.log
2024-10-14 00:04:24 | 5.0 | rnacos-2_rnacos.log
2024-10-14 00:04:29 | 5.0 | rnacos-2_rnacos.log
2024-10-14 00:04:34 | 5.0 | rnacos-1_rnacos.log
2024-10-14 00:04:39 | 5.0 | rnacos-1_rnacos.log
2024-10-14 00:04:44 | 5.0 | rnacos-0_rnacos.log
2024-10-14 00:04:49 | 5.0 | rnacos-0_rnacos.log
2024-10-14 00:04:54 | 5.0 | rnacos-2_rnacos.log
2024-10-14 00:04:59 | 5.0 | rnacos-2_rnacos.log
2024-10-14 00:05:04 | 5.0 | rnacos-1_rnacos.log
2024-10-14 00:05:09 | 5.0 | rnacos-0_rnacos.log
2024-10-14 00:05:14 | 5.0 | rnacos-0_rnacos.log
2024-10-14 00:05:19 | 5.0 | rnacos-0_rnacos.log
2024-10-14 00:05:24 | 5.0 | rnacos-2_rnacos.log
2024-10-14 00:05:29 | 5.0 | rnacos-0_rnacos.log
2024-10-14 00:05:34 | 5.0 | rnacos-2_rnacos.log
2024-10-14 00:05:39 | 5.0 | rnacos-1_rnacos.log
2024-10-14 00:05:44 | 5.0 | rnacos-2_rnacos.log
2024-10-14 00:05:49 | 5.0 | rnacos-0_rnacos.log
2024-10-14 00:05:54 | 5.0 | rnacos-0_rnacos.log
2024-10-14 00:06:04 | 10.0 | rnacos-1_rnacos.log
2024-10-14 00:06:09 | 5.0 | rnacos-2_rnacos.log

---

附上分析python脚本，有兴趣的话也可以自己试试，看看和自己看到的波动现象时对应的心跳日志是不是有波动。

rnacos_log_merge_and_filter.py

#-*- coding: utf8 -*-

import re
import sys
from datetime import datetime

def get_log_infos(logs):
    log_infos = []
    for f in logs:
        fobj=open(f)
        txt=fobj.read()
        fobj.close()
        obj={'name':f,'value':txt}
        log_infos.append(obj)
    return log_infos

#在多个日志中获取指定实例上传心跳的间隔，间隔大于5秒增加标记
def merge_and_filter(logs,service_name):
    log_infos = get_log_infos(logs)
    reg=re.compile('^(\[(\d+-\d+-\d+ \d+:\d+:\d+).*PUT /nacos/v1/ns/instance/beat.*{}.*)$'.format(service_name),re.M)
    l=[]
    for item in log_infos:
        reg_items = reg.findall(item['value'])
        for sitem in reg_items:
            obj={"log_info":sitem[0],"time":sitem[1],"name":item['name']}
            l.append(obj)
    l.sort(key=lambda o:o['time'])
    if len(l)==0:
        return
    date_format = "%Y-%m-%d %H:%M:%S"
    p_time = datetime.strptime(l[0]['time'],date_format)
    for item in l:
        t = datetime.strptime(item['time'],date_format)
        #print("{} | {} | {} | {}".format(item['time'],(t-p_time).total_seconds(),item['name'],item['log_info']))
        print("{} | {} | {}".format(item['time'],(t-p_time).total_seconds(),item['name']))
        p_time = t

def main():
    if len(sys.argv)<3:
        print("cmd log1,log2 service_name")
        return
    logs = sys.argv[1].split(",")
    service_name= sys.argv[2]
    merge_and_filter(logs,service_name)

if __name__=="__main__":
    main()

执行命令： python rnacos_log_merge_and_filter.py rnacos-0_rnacos.log,rnacos-1_rnacos.log,rnacos-2_rnacos.log ruiling-client > ruiling-client.out

[heqingpan]

目前上面推理与日志吻合，初步确认问题是客户端心跳有概率没有成功上报引发的。

r-nacos侧后续处理方案：

1. r-nacos对服务实例健康心跳超时时间，与实例过期时间支持可配置（目前是定死的15秒和30秒）【主要方案】
2. 目前r-nacos集群中服务实例健康、过期管理是按规则划分由多个节点分别管理的；如果有必要可以支持启动主节点管理模式（主节点运算量会增大，集群吞吐量不能水平扩展，总体吞吐量会降低）【待定，前一项如果还不能解决问题后再考虑】
3. 增加短时间内状态频繁波动等对应异常场景补充告警日志，以方便快速发现定位问题点。

[heqingpan]

r-nacos v0.6.2 版本已尝试修复，@zzl221000 可以抽空使用v0.6.2试试。

附上本次增加两个参数： RNACOS_NAMING_HEALTH_TIMEOUT_SECOND : 健康过期时间，默认15秒 RNACOS_NAMING_INSTANCE_TIMEOUT_SECOND：实例过期时间，默认30秒

[zzl221000]

@heqingpan 我抽空部署测试一下

[zzl221000]

奇怪了，升级之后web页面登录不能跳转，能看config不能看service，请求都是200，但是会重定向到登陆页面

[heqingpan]

你升级到哪个版本？

登录不能跳转,能登陆成功吗？

能看config，不能看service,看时重定向到登陆页是吗？

这个看起来像是用户权限有问题，可以用管理员进入检查一下这个用户的角色确认一下。

[heqingpan]

我想到一种可能和这个现象相符合：升级后raft集群节点没有完全同步，导至raft不能写入，这时登陆后不能写缓存，不跳转；之前已经登陆的缓存请求到问题节点可能查不到登陆的缓存，然后认为没有登陆跳转到登陆页。

如果是这个问题，等集群恢复同步后，对应功能就会恢复。

[zzl221000]

我发现是有一个节点数据损坏了 0.6.3版本有办法快速修复吗 三个节点，每三次请求一次失败

[heqingpan]

把问题节点的nacos_db目录删除后重启节点应该就可以。

目前版本是支持导出全量数据的，也可以导出数据后，集群重建新集群，再导入数据。

[zzl221000]

r-nacos v0.6.2 版本已尝试修复，@zzl221000 可以抽空使用v0.6.2试试。

附上本次增加两个参数： RNACOS_NAMING_HEALTH_TIMEOUT_SECOND : 健康过期时间，默认15秒 RNACOS_NAMING_INSTANCE_TIMEOUT_SECOND：实例过期时间，默认30秒

服务注册正常了