写点什么

Eureka 实例注册状态保持 STARTING 的问题排查

用户头像
张晓辉
关注
发布于: 2020 年 05 月 28 日
Eureka 实例注册状态保持 STARTING 的问题排查

这是真实发生在生产环境的 case,实例启动后正常运行,而在注册中心的状态一直保持STARTING,而本地的状态为UP。导致服务的消费方无法发现可用实例。

这种情况的出现概率非常低,运行一年多未发现两个实例同时出现问题的情况,因此多实例运行可以避免。文末有问题的解决方案,不想花时间看分析过程可直接跳到最后。

环境说明:

eureka-client: 1.7.2 spring-boot: 1.5.12.RELEASE spring-cloud: Edgware.SR3

问题重现

借助Btrace重现, java -noverify -cp .:btrace-boot.jar -javaagent:btrace-agent.jar=script=<pre-compiled-btrace-script> <MainClass> <AppArguments>

思路

主线程更新实例本地状态(STARTING->UP)前, 等待心跳线程完成第一次心跳并尝试注册实例, 获取到当前的状态STARTING. 主线程更新状态后触发

Btrace 脚本

import com.sun.btrace.annotations.BTrace;import com.sun.btrace.annotations.Kind;import com.sun.btrace.annotations.Location;import com.sun.btrace.annotations.OnMethod;
import java.util.concurrent.atomic.AtomicBoolean;
import static com.sun.btrace.BTraceUtils.currentThread;import static com.sun.btrace.BTraceUtils.println;
/** * @author Addo.Zhang * @date 2019-07-31 */@BTrace(unsafe = true)public class EurekaRequest { public static final AtomicBoolean heartbeatThreadRegistrationStarted = new AtomicBoolean(false); public static final AtomicBoolean replicatorThreadRegistrationCompleted = new AtomicBoolean(false); public static final AtomicBoolean statusUP = new AtomicBoolean(false);
@OnMethod(clazz = "org.springframework.cloud.netflix.eureka.serviceregistry.EurekaServiceRegistry", location = @Location(value = Kind.LINE, line = 45)) public static void waitHeartbeatExecution() { println(currentThread() + " is waiting heartbeatThreadRegistrationStarted thread executing first"); while (!heartbeatThreadRegistrationStarted.get()) ; }
@OnMethod(clazz = "org.springframework.cloud.netflix.eureka.serviceregistry.EurekaServiceRegistry", location = @Location(value = Kind.LINE, line = 46)) public static void markStatusUp() { statusUP.set(true); println("Heartbeat thread executed and " + currentThread() + " continues procedure to change status to [UP]"); }
@OnMethod(clazz = "com.netflix.discovery.converters.EurekaJacksonCodec$InstanceInfoSerializer", location = @Location(value = Kind.LINE, line = 369)) public static void continueRegistrationExecution() { doExecution(); }
@OnMethod(clazz = "com.logancloud.forge.discovery.converters.LoganEurekaJacksonCodec$LoganInstanceInfoSerializer", location = @Location(value = Kind.LINE, line = 117)) public static void continueRegistrationExecution2() { doExecution(); }
private static void doExecution() { println(currentThread() + " started to proceed registration"); if (Thread.currentThread().getName().contains("HeartbeatExecutor")) { heartbeatThreadRegistrationStarted.set(true); while (!statusUP.get() || !replicatorThreadRegistrationCompleted.get()) { } try { Thread.sleep(500); //interval for replicator registration request completed. } catch (InterruptedException e) { Thread.currentThread().interrupt(); } } else if (Thread.currentThread().getName().contains("InstanceInfoReplicator")) { replicatorThreadRegistrationCompleted.set(true); } println(currentThread() + " thread registration completed"); }}
复制代码



  1. 心跳线程HeartbeatThread发送心跳请求(PUT), 注册中心返回 404.

  2. 实例信息同步线程InstanceInfoReplicator发送注册请求(POST): 状态为UPlastDirtyTimestampa

  3. 心跳线程发送实例注册请求(POST): 状态为STARTINGlastDirtyTimestampa

服务注册

先分析服务实例的注册逻辑.

InstanceInfo 初始化

通过InstanceInfoFactory#create()方法来初始化ApplicationInfoManager.instanceInfo实例时, 实例状态被设置为STARTING

服务实例注册

服务实例注册的真正逻辑是在DiscoveryClient#register()中完成的. 但是这个方法的调用却有两个入口, 在整个过程中可解释为主动注册和被动注册.

一. 主动注册

EurekaAutoServiceRegistration实现了SmartLifecycle接口, 在EurekaClientAutoConfiguration#eurekaAutoServiceRegistration()被实例化.

EurekaAutoServiceRegistration#start()方法将EurekaRegistration注册给EurekaServiceRegistry:

public void start() {    ...    if (!this.running.get() && this.registration.getNonSecurePort() > 0) {      //调用EurekaServiceRegistry进行注册    	this.serviceRegistry.register(this.registration);    	//发布实例注册的事件    	this.context.publishEvent(    			new InstanceRegisteredEvent<>(this, this.registration.getInstanceConfig()));    	this.running.set(true);    }}
复制代码



EurekaServiceRegistry#register(): 先将实例状态设置为初始状态 UP(可通过eureka.instance.initial-status修改, 默认为UP). 这里会触发StatusChangeListener#notify().


public void register(EurekaRegistration reg) { maybeInitializeClient(reg); if (log.isInfoEnabled()) { log.info("Registering application " + reg.getInstanceConfig().getAppname() + " with eureka with status " + reg.getInstanceConfig().getInitialStatus()); } //1 reg.getApplicationInfoManager() .setInstanceStatus(reg.getInstanceConfig().getInitialStatus()); if (reg.getHealthCheckHandler() != null) { //2 reg.getEurekaClient().registerHealthCheck(reg.getHealthCheckHandler()); }}
复制代码

DiscoveryClient内部匿名类提供了StatusChangeListener的实现, 调用InstanceInfoReplicator#onDemandUpdate()

statusChangeListener = new ApplicationInfoManager.StatusChangeListener() {    @Override    public String getId() {        return "statusChangeListener";    }    @Override    public void notify(StatusChangeEvent statusChangeEvent) {        if (InstanceStatus.DOWN == statusChangeEvent.getStatus() ||                InstanceStatus.DOWN == statusChangeEvent.getPreviousStatus()) {            // log at warn level if DOWN was involved            logger.warn("Saw local status change event {}", statusChangeEvent);        } else {            logger.info("Saw local status change event {}", statusChangeEvent);        }        instanceInfoReplicator.onDemandUpdate();    }};
复制代码

InstanceInfoReplicator是在DiscoveryClient#initScheduledTasks()中实例化的Runnable的实现, 实例化之后, 使用其内部的调度线程池调度一个线程. 而onDemandUpdate()也同样会使用调度线程池调度一个线程.

#run()方法会调用DiscoveryClient#refreshInstanceInfo()来更新状态. 状态的更新是通过HealthCheckHandler来实现的, 具体请看状态检查. 然后调用DiscoveryClient#register()方法进行注册.

二. 被动注册

上面提到了DiscoveryClient#initScheduledTasks(), 这里的 task 除了InstanceInfoReplicator之外还有其他的线程. 其中一个是线条线程HeartbeatThread. 这个线程会每隔一段时间向注册中心发送一个PUT类型的 HTTP 请求: 上报实例的状态(状态(status), 以及状态修改的时间(lastDirtyTimestamp)).

这个请求可能会有两种结果: 404200. 前者说明注册中心中还没有这个实例的注册信息; 后者说明状态上报成功.

假如是404, 便直接发起注册的动作, 即调用DiscoveryClient#register()方法进行注册.

状态检查



CloudEurekaClient通过HealthCheckHandler来检查实例的健康状态, 看下HealthCheckCallbackToHandlerBridge实现: callback 为空, 或者当前状态为STARTING或者OUT_OF_SERVICE时, 返回当前的状态. 我们没有设置 callback, 故而总是会返回当前的状态. 比如应用启动的初始状态为STARTING

public InstanceInfo.InstanceStatus getStatus(InstanceInfo.InstanceStatus currentStatus) {    if (null == callback || InstanceInfo.InstanceStatus.STARTING == currentStatus            || InstanceInfo.InstanceStatus.OUT_OF_SERVICE == currentStatus) { // Do not go to healthcheck handler if the status is starting or OOS.        return currentStatus;    }    return callback.isHealthy() ? InstanceInfo.InstanceStatus.UP : InstanceInfo.InstanceStatus.DOWN;}
复制代码

问题分析

现象

TCP 抓包

HeartBeat 请求和 Fetch 请求正常. status=UP&lastDirtyTimestamp=1545039481813



堆信息

本地状态为 UP, lastDirtyTimestamp为 1545039481813, lastUpdatedTimestamp为 1545039472888



注册中心里的实例信息

状态为 STARTING, lastDirtyTimestamp为 1545039481813, registrationTimestamp为 1545039481898, lastUpdatedTimestamp为 1545039481899

 <instance>      <instanceId>xp-xtower-webapp-boot-6-txcxb:xp-xtower-webapp-boot:10100</instanceId>      <hostName>10.128.41.74</hostName>      <app>XP-XTOWER-WEBAPP-BOOT</app>      <ipAddr>10.128.41.74</ipAddr>      <status>STARTING</status>      <overriddenstatus>UNKNOWN</overriddenstatus>      <port enabled="true">10100</port>      <securePort enabled="false">443</securePort>      <countryId>1</countryId>      <dataCenterInfo class="com.netflix.appinfo.InstanceInfo$DefaultDataCenterInfo">        <name>MyOwn</name>      </dataCenterInfo>      <leaseInfo>        <renewalIntervalInSecs>5</renewalIntervalInSecs>        <durationInSecs>20</durationInSecs>        <registrationTimestamp>1545039481898</registrationTimestamp>        <lastRenewalTimestamp>1545950719063</lastRenewalTimestamp>        <evictionTimestamp>0</evictionTimestamp>        <serviceUpTimestamp>0</serviceUpTimestamp>      </leaseInfo>      <metadata>        <forge>1.0.0</forge>        <management.port>10100</management.port>        <jmx.port>1099</jmx.port>        <group>innovation</group>      </metadata>      <homePageUrl>http://10.128.41.74:10100/</homePageUrl>      <statusPageUrl></statusPageUrl>      <healthCheckUrl>http://10.128.41.74:10100/health</healthCheckUrl>      <vipAddress>xp-xtower-webapp-boot</vipAddress>      <secureVipAddress>xp-xtower-webapp-boot</secureVipAddress>      <isCoordinatingDiscoveryServer>false</isCoordinatingDiscoveryServer>      <lastUpdatedTimestamp>1545039481899</lastUpdatedTimestamp>      <lastDirtyTimestamp>1545039481813</lastDirtyTimestamp>      <actionType>ADDED</actionType>    </instance>

复制代码

ScopeStatuslastDirtyTimestamplastUpdatedTimestampregistrationTimestampRequestUP1545039481813LocalUP15450394818131545039472888RemoteSTARTING154503948181315450394818991545039481898

结合起来看, 问题出在lastDirtyTimestamp未更新, 导致注册中心的状态未更新. 而lastUpdatedTimestamp的时间为 1545039481899, 与lastDirtyTimestamp相差86毫秒.

服务端InstanceResource#validateDirtyTimestamp()根据本地保存的实例的信息, 和心跳请求发送过来的请求做比较, 决定响应的状态码200404或者409

推理

注册中心里实例的状态为STARTING, 可以确定实例是[被动注册](#二. 被动注册)的.

这里有几个时间点:

  • 1545039472888InstanceInfo对象实例化的时间, 因为本地对象的#lastUpdatedTimestamp字段只有在实例化才会赋值, 此后不会被修改. 见堆信息

  • 1545039481813: 状态从STARTING变为UP的时间, 也是实例状态的最后一次更新时间. 此后的心跳请求都会带上实例的最新状态(UP)和状态的最后一次更新时间(1545039481813), 见TCP抓包.

  • 1545039481898: 注册中心收到实例的注册请求的时间. 见注册中心里的实例信息

  • 1545039481899: 注册中心中的实例信息被更新的时间. 这个时间只比注册的时间晚了 1 毫秒. 见注册中心里的实例信息

综上可见, 被动注册时发送请求, 拿到的实例的旧的状态STARTING, 修改时间确实最新的1545039481813. 后续的心跳上报实例状态为最新的UP, 修改时间也是最新的1545039481813. 但是由于最后修改时间与注册时的最后修改时间相同, 即使状态已经变为UP, 注册中心在收到心跳请求之后也不会将状态更新为UP.

服务端InstanceResource#renewLease() -> InstanceResource#validateDirtyTimestamp(): 如果请求中的lastDirtyTimestamp与当前保存的实例的相同, 则直接返回 OK, 不会更新注册中心中保存的实例的状态.

private Response validateDirtyTimestamp(Long lastDirtyTimestamp,                                        boolean isReplication) {    InstanceInfo appInfo = registry.getInstanceByAppAndId(app.getName(), id, false);    if (appInfo != null) {        if ((lastDirtyTimestamp != null) && (!lastDirtyTimestamp.equals(appInfo.getLastDirtyTimestamp()))) {            Object[] args = {id, appInfo.getLastDirtyTimestamp(), lastDirtyTimestamp, isReplication};            if (lastDirtyTimestamp > appInfo.getLastDirtyTimestamp()) {                logger.debug(                        "Time to sync, since the last dirty timestamp differs -"                                + " ReplicationInstance id : {},Registry : {} Incoming: {} Replication: {}",                        args);                return Response.status(Status.NOT_FOUND).build();            } else if (appInfo.getLastDirtyTimestamp() > lastDirtyTimestamp) {                // In the case of replication, send the current instance info in the registry for the                // replicating node to sync itself with this one.                if (isReplication) {                    logger.debug(                            "Time to sync, since the last dirty timestamp differs -"                                    + " ReplicationInstance id : {},Registry : {} Incoming: {} Replication: {}",                            args);                    return Response.status(Status.CONFLICT).entity(appInfo).build();                } else {                    return Response.ok().build();                }            }        }    }    return Response.ok().build();}
复制代码

为什么会出现这种情况?

应用启动过程中会有两个线程会触发注册的动作

  1. InstanceInfoReplicator线程: DiscoveryClient中的ApplicationInfoManager.StatusChangeListener监听到实例状态发生变化, 会新建一个线程将实例注册到注册中心

  2. DiscoveryClient$HeartbeatThread线程: 这个线程在DiscoveryClient实例初始化后延迟(与心跳间隔时间相同, 默认是30s, 中台为提高实例发现效率将其改为了5s)启动运行. 第一次发送心跳请求是如果注册中心返回 404(说明心跳线程提实例状态更新线程先启动), 则会先将实例注册到注册中心.

上面两个线程都通过调用AbstractJerseyEurekaHttpClient$register()方法并使用EurekaJacksonCodec$InstanceInfoSerializer将实例信息序列化. 序列化的过程中先记录实例的状态后记录实例状态的最后修改时间(lastDirtyTimestamp), 这两个操作不是一个原子操作.

非常极端的情况下(缩小心跳间隔增加了出现的概率, 但依然极地), 两个操作之间(心跳线程先拿到实例状态STARTING)主线程修改了实例状态为UP, 同时修改了lastDirtyTimestamp, 并触发了InstanceInfoReplicator线程的注册操作, 此时心跳线程获取到的实例的最后修改时间与STARTING状态并不一致. 之后同样注册动作覆盖了实例在注册中心的状态: UP -> STARTING.

后续的心跳请求带去的最新状态UPlastDirtyTimestamp, 并不会更新在注册中心的状态.

解决方案

EurekaJacksonCodec$InstanceInfoSerializer#serialize()方法中, 将#autoMarshalEligible() 的调用移到jgen.writeStartObject()后面. 这样就使得lastDirtyTimestamp的获取比status早, 就能保证即使注册时的lastDirtyTimestamp小于真正的, 但是状态是与实际相符. lastDirtyTimestamp会在后续的心跳请求中更新.


addInstance-info.getStatus(): UPaddInstance-info.getLastDirtyTimestamp(): 1565164484429
addInstance-info.getStatus(): STARTINGaddInstance-info.getLastDirtyTimestamp(): 1565164484415
renew-status-in-registry: UPrenew-lastDirtyTimestamp: 1565164484429renew-appInfo.getLastDirtyTimestamp(): 1565164484429
复制代码

PR 已经提交并合并完成,然而 1.7.x 的版本不知何时会发布修复版本

参考:


文章同步发送到公众号:云编码 (微信号:sevenfeet)。



发布于: 2020 年 05 月 28 日阅读数: 47
用户头像

张晓辉

关注

大胆尝试,小心求证 2018.04.09 加入

胡说八道

评论

发布
暂无评论
Eureka 实例注册状态保持 STARTING 的问题排查