Eureka Server 내장한 어플리케이션의 로그와 Eureka Client가 구현되어있는 어플리케이션 로그를 보면서 유레카의 동작방식을 이해해 보자.

어플리케이션 로그

Eureka 서버

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
2019-11-29 13:11:20.165  INFO 1 --- [main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat initialized with port(s): 8761 (http)
2019-11-29 13:11:20.325  INFO 1 --- [main] o.apache.catalina.core.StandardService   : Starting service [Tomcat]
2019-11-29 13:11:20.326  INFO 1 --- [main] org.apache.catalina.core.StandardEngine  : Starting Servlet engine: [Apache Tomcat/9.0.22]
2019-11-29 13:11:20.651  INFO 1 --- [main] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring embedded WebApplicationContext
2019-11-29 13:11:20.652  INFO 1 --- [main] o.s.web.context.ContextLoader            : Root WebApplicationContext: initialization completed in 6067 ms
...
2019-11-29 13:11:29.470  INFO 1 --- [main] o.s.b.a.e.web.EndpointLinksResolver      : Exposing 20 endpoint(s) beneath base path '/actuator'
2019-11-29 13:11:29.974  INFO 1 --- [main] o.s.c.n.eureka.InstanceInfoFactory       : Setting initial instance status as: STARTING
2019-11-29 13:11:30.113  INFO 1 --- [main] com.netflix.discovery.DiscoveryClient    : Initializing Eureka in region us-east-1
2019-11-29 13:11:30.124  INFO 1 --- [main] com.netflix.discovery.DiscoveryClient    : Client configured to neither register nor query for data.
2019-11-29 13:11:30.158  INFO 1 --- [main] com.netflix.discovery.DiscoveryClient    : Discovery Client initialized at timestamp 1575000690156 with initial instances count: 0
2019-11-29 13:11:30.330  INFO 1 --- [main] c.n.eureka.DefaultEurekaServerContext    : Initializing ...
2019-11-29 13:11:30.337  INFO 1 --- [main] c.n.eureka.cluster.PeerEurekaNodes       : Adding new peer nodes [http://registry:8761/eureka/]
2019-11-29 13:11:31.081  INFO 1 --- [main] c.n.d.provider.DiscoveryJerseyProvider   : Using JSON encoding codec LegacyJacksonJson
2019-11-29 13:11:31.083  INFO 1 --- [main] c.n.d.provider.DiscoveryJerseyProvider   : Using JSON decoding codec LegacyJacksonJson
2019-11-29 13:11:31.084  INFO 1 --- [main] c.n.d.provider.DiscoveryJerseyProvider   : Using XML encoding codec XStreamXml
2019-11-29 13:11:31.089  INFO 1 --- [main] c.n.d.provider.DiscoveryJerseyProvider   : Using XML decoding codec XStreamXml
2019-11-29 13:11:31.570  INFO 1 --- [main] c.n.eureka.cluster.PeerEurekaNodes       : Replica node URL:  http://registry:8761/eureka/
2019-11-29 13:11:31.613  INFO 1 --- [main] c.n.e.registry.AbstractInstanceRegistry  : Finished initializing remote region registries. All known remote regions: []
2019-11-29 13:11:31.614  INFO 1 --- [main] c.n.eureka.DefaultEurekaServerContext    : Initialized
2019-11-29 13:11:31.902  INFO 1 --- [main] o.s.c.n.e.s.EurekaServiceRegistry        : Registering application REGISTRY with eureka with status UP
2019-11-29 13:11:31.980  INFO 1 --- [Thread-11] o.s.c.n.e.server.EurekaServerBootstrap   : Setting the eureka configuration..
2019-11-29 13:11:31.981  INFO 1 --- [Thread-11] o.s.c.n.e.server.EurekaServerBootstrap   : Eureka data center value eureka.datacenter is not set, defaulting to default
2019-11-29 13:11:31.981  INFO 1 --- [Thread-11] o.s.c.n.e.server.EurekaServerBootstrap   : Eureka environment value eureka.environment is not set, defaulting to test
2019-11-29 13:11:32.092  INFO 1 --- [Thread-11] o.s.c.n.e.server.EurekaServerBootstrap   : isAws returned false
2019-11-29 13:11:32.099  INFO 1 --- [Thread-11] o.s.c.n.e.server.EurekaServerBootstrap   : Initialized server context
2019-11-29 13:11:32.100  INFO 1 --- [Thread-11] c.n.e.r.PeerAwareInstanceRegistryImpl    : Got 1 instances from neighboring DS node
2019-11-29 13:11:32.100  INFO 1 --- [Thread-11] c.n.e.r.PeerAwareInstanceRegistryImpl    : Renew threshold is: 1
2019-11-29 13:11:32.100  INFO 1 --- [Thread-11] c.n.e.r.PeerAwareInstanceRegistryImpl    : Changing status to UP
2019-11-29 13:11:32.163  INFO 1 --- [Thread-11] e.s.EurekaServerInitializerConfiguration : Started Eureka Server
2019-11-29 13:11:32.289  INFO 1 --- [main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat started on port(s): 8761 (http) with context path ''
2019-11-29 13:11:32.310  INFO 1 --- [main] .s.c.n.e.s.EurekaAutoServiceRegistration : Updating port to 8761
2019-11-29 13:11:32.312  INFO 1 --- [main] k.c.s.e.e.EurekaServerApplication        : Started EurekaServerApplication in 20.454 seconds (JVM running for 21.053)
2019-11-29 13:11:33.010  INFO 1 --- [nio-8761-exec-1] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring DispatcherServlet 'dispatcherServlet'
2019-11-29 13:11:33.010  INFO 1 --- [nio-8761-exec-1] o.s.web.servlet.DispatcherServlet        : Initializing Servlet 'dispatcherServlet'
2019-11-29 13:11:33.019  INFO 1 --- [nio-8761-exec-1] o.s.web.servlet.DispatcherServlet        : Completed initialization in 9 ms
2019-11-29 13:11:34.244  INFO 1 --- [nio-8761-exec-2] c.n.e.registry.AbstractInstanceRegistry  : Registered instance TEST-SERVICE/53614fa559ab:test-service:9300 with status UP (replication=false)
2019-11-29 13:11:36.253  INFO 1 --- [nio-8761-exec-4] c.n.e.registry.AbstractInstanceRegistry  : Registered instance ZUUL-GATEWAY/7cf3a25fe7e2:zuul-gateway:8080 with status UP (replication=false)
2019-11-29 13:11:47.191  INFO 1 --- [nio-8761-exec-3] c.n.e.registry.AbstractInstanceRegistry  : Registered instance TEST-SERVICE/382f8bf1dfec:test-service:20180 with status UP (replication=false)
2019-11-29 13:12:32.157  INFO 1 --- [a-EvictionTimer] c.n.e.registry.AbstractInstanceRegistry  : Running the evict task with compensationTime 0ms
2019-11-29 13:13:32.157  INFO 1 --- [a-EvictionTimer] c.n.e.registry.AbstractInstanceRegistry  : Running the evict task with compensationTime 0ms
2019-11-29 13:14:32.156  INFO 1 --- [a-EvictionTimer] c.n.e.registry.AbstractInstanceRegistry  : Running the evict task with compensationTime 0ms
2019-11-29 13:15:32.156  INFO 1 --- [a-EvictionTimer] c.n.e.registry.AbstractInstanceRegistry  : Running the evict task with compensationTime 0ms
2019-11-29 13:16:32.156  INFO 1 --- [a-EvictionTimer] c.n.e.registry.AbstractInstanceRegistry  : Running the evict task with compensationTime 0ms

Eureka의 인스턴스 상태

관련 로그
1
2
3
4
5
6
2019-11-29 13:11:29.974  INFO 1 --- [main] o.s.c.n.eureka.InstanceInfoFactory       : Setting initial instance status as: STARTING
...
2019-11-29 13:11:34.244  INFO 1 --- [nio-8761-exec-2] c.n.e.registry.AbstractInstanceRegistry  : Registered instance TEST-SERVICE/53614fa559ab:test-service:9300 with status UP (replication=false)
...
2019-11-29 13:12:32.157  INFO 1 --- [a-EvictionTimer] c.n.e.registry.AbstractInstanceRegistry  : Running the evict task with compensationTime 0ms
2019-11-29 13:13:32.157  INFO 1 --- [a-EvictionTimer] c.n.e.registry.AbstractInstanceRegistry  : Running the evict task with compensationTime 0ms

서비스 레지스트리의 initial instance status는 STARTING 으로 설정 함.
TEST-SERVICE/53614fa559ab:test-service:9300 (appID/instanceId)
appID는 Application Name 이고, instanceId는 ${spring.cloud.hostname}:${spring.application.name}:${server.port} 의 조합이다.

일반적인 서비스 레지스트리의 Instance Lifecycle

Netflix Eureka와 같은 대부분의 서비스 레지스트리는 인스턴스를 조회하고, 등록하는 인터페이스를 제공한다. (REST API) 그리고 인스턴스 생명주기는 3가지 단계로 표현된다.

  1. Register

    서비스 레지스트리에 microservice instance를 등록 함.

  2. Heartbeat

    등록된 instance는 사전 정의된 interval에 따라 레지스트리에 heartbeat을 보낸다.

    레지스트리가 특정시간동안 heartbeat을 받지 못하면 인스턴스는 down 상태로 판단하고, 레지스트리에서 삭제한다.

  3. Deregister/Down

    instance가 삭제되었을 경우에 서비스 레지스트리에 등록해제(deregister) 해주는 과정이 필요하다.

    deregister 요청을 받으면 instance는 down 상태가 되고, 레지스트리에서 삭제된다.

Eureka의 Instance Lifecycle 및 Instance의 상태

Instance의 Lifecycle 단계 별로 유레카 Instance Status 값의 변화를 알아보자.

  1. STARTING

    유레카 서버에 서비스가 등록되면서 STARTING 상태가 됨.

  2. UP

    서비스 어플리케이션이 요청을 받을 수 있는 상태가 되면 STARTING 에서 UP 상태로 변경 됨.

  3. HEARTBEAT

    사전에 정의된 interval(eureka.instance.lease-renewal-interval-in-seconds default:30)에 따라 유레카 서버에 heartbeat을 보내고, 특정시간(eureka.instance.lease-expiration-duration-in-seconds default: 90)동안 유레카 서버가 heartbeat를 받지 못하면 레지스트리에서 해당 인스턴스를 제거한다.

  4. DOWN

    인스턴스가 종료되면 DOWN 상태로 변경 한다.

참고

Eureka-REST-operations

https://dzone.com/articles/service-registration-with-go-lang-and-eureka

Eureka Server Peer Node 구성

관련로그
1
2019-11-29 13:11:30.337  INFO 1 --- [main] c.n.eureka.cluster.PeerEurekaNodes       : Adding new peer nodes [http://registry:8761/eureka/]
참고

Understanding Eureka Peer to Peer Communication

Eureka Client - 서비스

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
...
com.netflix.discovery.DiscoveryClient    : Disable delta property : true
2019-11-29 13:42:21.296  INFO 1 --- [           main] com.netflix.discovery.DiscoveryClient    : Single vip registry refresh property : null
2019-11-29 13:42:21.296  INFO 1 --- [           main] com.netflix.discovery.DiscoveryClient    : Force full registry fetch : false
2019-11-29 13:42:21.296  INFO 1 --- [           main] com.netflix.discovery.DiscoveryClient    : Application is null : false
2019-11-29 13:42:21.297  INFO 1 --- [           main] com.netflix.discovery.DiscoveryClient    : Registered Applications size is zero : true
2019-11-29 13:42:21.297  INFO 1 --- [           main] com.netflix.discovery.DiscoveryClient    : Application version is -1: true
2019-11-29 13:42:21.297  INFO 1 --- [           main] com.netflix.discovery.DiscoveryClient    : Getting all instance registry info from the eureka server
2019-11-29 13:42:21.524  INFO 1 --- [           main] com.netflix.discovery.DiscoveryClient    : The response status is 200
...
2019-11-29 13:42:21.546  INFO 1 --- [           main] com.netflix.discovery.DiscoveryClient    : Discovery Client initialized at timestamp 1575002541545 with initial instances count: 2
2019-11-29 13:42:21.548  INFO 1 --- [           main] o.s.c.n.e.s.EurekaServiceRegistry        : Registering application TEST-SERVICE with eureka with status UP
2019-11-29 13:42:21.549  INFO 1 --- [           main] com.netflix.discovery.DiscoveryClient    : Saw local status change event StatusChangeEvent [timestamp=1575002541549, current=UP, previous=STARTING]
2019-11-29 13:42:21.554  INFO 1 --- [nfoReplicator-0] com.netflix.discovery.DiscoveryClient    : DiscoveryClient_TEST-SERVICE/364b4deadbc7:test-service:20233: registering service...
2019-11-29 13:42:21.632  INFO 1 --- [nfoReplicator-0] com.netflix.discovery.DiscoveryClient    : DiscoveryClient_TEST-SERVICE/364b4deadbc7:test-service:20233 - registration status: 204
2019-11-29 13:42:21.640  INFO 1 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat started on port(s): 20233 (http) with context path ''
2019-11-29 13:42:21.645  INFO 1 --- [           main] .s.c.n.e.s.EurekaAutoServiceRegistration : Updating port to 20233
2019-11-29 13:42:21.648  INFO 1 --- [           main] k.c.s.e.e.TestServiceApplication         : Started TestServiceApplication in 6.367 seconds (JVM running for 7.332)
2019-11-29 13:42:24.538  INFO 1 --- [freshExecutor-0] com.netflix.discovery.DiscoveryClient    : Disable delta property : true
2019-11-29 13:42:24.539  INFO 1 --- [freshExecutor-0] com.netflix.discovery.DiscoveryClient    : Single vip registry refresh property : null
2019-11-29 13:42:24.540  INFO 1 --- [freshExecutor-0] com.netflix.discovery.DiscoveryClient    : Force full registry fetch : false
2019-11-29 13:42:24.540  INFO 1 --- [freshExecutor-0] com.netflix.discovery.DiscoveryClient    : Application is null : false
2019-11-29 13:42:24.540  INFO 1 --- [freshExecutor-0] com.netflix.discovery.DiscoveryClient    : Registered Applications size is zero : false
2019-11-29 13:42:24.540  INFO 1 --- [freshExecutor-0] com.netflix.discovery.DiscoveryClient    : Application version is -1: false
2019-11-29 13:42:24.540  INFO 1 --- [freshExecutor-0] com.netflix.discovery.DiscoveryClient    : Getting all instance registry info from the eureka server

유레카 클라이언트는 유레카 서버로 부터 registry를 fetch해서 캐싱한다.

서비스 목록을 3초마다 캐싱하도록 설정된 경우의 로그다.

2019-11-29 13:42:21.297 Getting all instance registry info from the eureka server 로그가 출력된 이후 3초가 지난 2019-11-29 13:42:24.540 에 또 fetch해 오는 것을 확인 할 수 있다.

관련 설정
1
2
3
4
5
6
eureka:
  client:
    registerWithEureka: true
    fetchRegistry: true
    registry-fetch-interval-seconds: 3
    disable-delta: true

registry-fetch-interval-seconds 서버로부터 레지스트리 정보를 읽어와 로컬에 캐시하게 되는데 이때 레지스트리 fetch 간격 (초)

disable-delta 레지스트리 정보의 변경된 부분만 fetch 함.

Indicates whether the eureka client should disable fetching of delta and should rather resort to getting the full registry information. Note that the delta fetches can reduce the traffic tremendously, because the rate of change with the eureka server is normally much lower than the rate of fetches. The changes are effective at runtime at the next registry fetch cycle as specified by registryFetchIntervalSeconds

참고

Eureka configuration_properties

Instance Scale Out 상황에서의 로그 확인

TEST-SERVICE가 레지스트리에 등록되어 있는 상황에서 TEST-SEVICE 의 Instance가 1개 더 생성되었을 때의 로그를 확인해보자.

Eureka Server

1
2
3
4
...
2019-11-29 13:42:21.627  INFO 1 --- [nio-8761-exec-3] c.n.e.registry.AbstractInstanceRegistry  : Registered instance TEST-SERVICE/364b4deadbc7:test-service:20233 with status UP (replication=false)
2019-11-29 13:42:32.160  INFO 1 --- [a-EvictionTimer] c.n.e.registry.AbstractInstanceRegistry  : Running the evict task with compensationTime 0ms
...

Eureka Client

1
2
3
4
5
2019-11-29 13:42:21.546  INFO 1 --- [           main] com.netflix.discovery.DiscoveryClient    : Discovery Client initialized at timestamp 1575002541545 with initial instances count: 2
2019-11-29 13:42:21.548  INFO 1 --- [           main] o.s.c.n.e.s.EurekaServiceRegistry        : Registering application TEST-SERVICE with eureka with status UP
2019-11-29 13:42:21.549  INFO 1 --- [           main] com.netflix.discovery.DiscoveryClient    : Saw local status change event StatusChangeEvent [timestamp=1575002541549, current=UP, previous=STARTING]
2019-11-29 13:42:21.554  INFO 1 --- [nfoReplicator-0] com.netflix.discovery.DiscoveryClient    : DiscoveryClient_TEST-SERVICE/364b4deadbc7:test-service:20233: registering service...
2019-11-29 13:42:21.632  INFO 1 --- [nfoReplicator-0] com.netflix.discovery.DiscoveryClient    : DiscoveryClient_TEST-SERVICE/364b4deadbc7:test-service:20233 - registration status: 204
서버로그와 클라이언트 로그를 대조해 보면..

클라이언트 - 2019-11-29 13:42:21.554 registering service ...

서버 - 2019-11-29 13:42:21.627 Registered instance ...

클라이언트 - 2019-11-29 13:42:21.632 registration status: 204

Operation HTTP action Description
Register new application instance POST /eureka/v2/apps/appID Input: JSON/XML payload HTTP Code: 204 on success
  1. 서비스 등록요청
  2. 유레카 레지스트리 인스턴스 등록
  3. 등록완료

Instance Scale In 상황에서의 로그 확인

Eureka Server

1
2
2019-12-07 11:18:25.478  INFO 1 --- [a-EvictionTimer] c.n.e.registry.AbstractInstanceRegistry  : Running the evict task with compensationTime 0ms
2019-12-07 11:18:28.611  INFO 1 --- [nio-8761-exec-5] c.n.e.registry.AbstractInstanceRegistry  : Cancelled instance TEST-SERVICE/291358de0d8d:test-service:9300 (replication=false)
Operation HTTP action Description
De-register application instance DELETE /eureka/v2/apps/appID/instanceID HTTP Code: 200 on success

끝

eureka-server-client