[ERROR] System.exit(0)시 SpringBootApplication이 종료되지 않는다?

겔로그·2022년 7월 15일
SpringSpring booterror
0
post-thumbnail

개요

오늘도 당연하다는 듯 발생하는 에러.... 오늘의 이슈는 다음과 같다.
에러를 발견한건 사내 서비스 관련 유지보수 작업을 진행하면서이다. 사내 오픈소스 중 Condition Checker라는 외부 시스템 의존성에 대한 연결 확인을 진행하는 라이브러리가 있다.

해당 라이브러리의 옵션에는 only-validation이라는 옵션이 있는데, 해당 옵션을 사용할 경우, 외부 시스템 의존성 연결이 정상적으로 됐는지 확인하고 어플리케이션을 종료하는 특징이 있다.

최근 서버 증설 관련 작업을 진행하여 어플리케이션을 배포하고 외부 시스템과의 의존성을 확인하기 위해 only-validation 옵션을 켰는데 다음과 같은 문제가 발생했다.

                               ..? 프로세스를 못 끈다고요..?

서버의 상태를 확인한 결과 서비스는 의도한 대로 종료된 상태이나 프로세스는 살아있는 아이러니한 상황이었다.

도대체 왜 이런 문제가 발생했는지 알아보는 시간을 가지겠다.

문제 해결 과정

앞서, 역시 종료가 정상적으로 되지 않는 것이기 때문에 코드를 보았다. 코드를 뜯어보니 다음과 같은 로직이 나왔다. 회사 코드이기 때문에 대략적인 문제 부분만 보여주고 다른 것은 임의로 변경하겠다.

public void shutdown() {
    switch (type) {
        case RUN:
        case OFF:
            break;
        default:
            log.info("[CONDITION_CHECKER] Applicaiton shutdown by conditionChecker module. mode: {}", mode);
            System.exit(0);
    }
    mode = OFF;

대충 봐도 문제는 단 한 곳 뿐이었다. System.exit(0);
도대체 이 놈이 어떤 동작을 하길래 슬프게도 프로세스만 살아남고 어플리케이션은 종료되는 것일까? 빠르게 구글링을 해보자

StackOverflow에도 나와 같은 문제 상황을 겪은 사람이 있었다. 이제 한 번 확인해보자.
쭉 읽다보면 리뷰어 중 한 분이 spring boot issue 링크를 남겨 놓았다. 링크에 들어가면 다음과 같은 이야기를 한다.
참고 : https://github.com/spring-projects/spring-boot/issues/27049

The key difference is that the context has already been closed before calling System.exit. In 2.4 that works. In 2.5 it hangs as our shutdown hook tries to close the context before waiting for it to become inactive. The close can't proceed as the monitor's held by the main thread which has called System.exit() in the middle of a refresh. We can avoid the problem by only calling close on contexts that are active.

주요 차이점은 System.exit을 호출하기 이전에 컨텍스트가 이미 닫혔는가의 여부이다.
2.4 버전에서는 동작했지만, 2.5 버전부터는 shutdown hook이 비활성화 하기 이전에 컨텍스트를 먼저 닫는다. System.exit() 새로 고침 중에 호출한 주 스레드가 모니터를 보유하고 있으므로 닫기를 진행할 수 없다. 이 문제는 컨텍스트가 활성화 상태일 때 종료를 호출하기만 하면 해결된다.

여기서 System.exit()에서 호출한 main thread가 monitor를 보유하고 있어 닫는게 불가능하다는 의미가 정확히 어떤 내용인지 이해가 가질 않는다. 이해가 되지 않는 부분은 넘어가고 JVM의 thread dump 내용을 보면 보다 더 구체적으로 원인을 파악할 수 있다니 한번 확인해보자

Thread Dump

main

   "main" #1 prio=5 os_prio=31 cpu=933.21ms elapsed=9.94s tid=0x00007f8d0f809800 nid=0x2703 in Object.wait()  [0x0000700004e3a000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(java.base@11.0.10/Native Method)
	- waiting on <0x000000061dcc4a38> (a java.lang.Thread)
	at java.lang.Thread.join(java.base@11.0.10/Thread.java:1305)
	- waiting to re-lock in wait() <0x000000061dcc4a38> (a java.lang.Thread)
	at java.lang.Thread.join(java.base@11.0.10/Thread.java:1380)
	at java.lang.ApplicationShutdownHooks.runHooks(java.base@11.0.10/ApplicationShutdownHooks.java:107)
	at java.lang.ApplicationShutdownHooks$1.run(java.base@11.0.10/ApplicationShutdownHooks.java:46)
	at java.lang.Shutdown.runHooks(java.base@11.0.10/Shutdown.java:130)
	at java.lang.Shutdown.exit(java.base@11.0.10/Shutdown.java:174)
	- locked <0x000000061dcc3c68> (a java.lang.Class for java.lang.Shutdown)
	at java.lang.Runtime.exit(java.base@11.0.10/Runtime.java:116)
	at java.lang.System.exit(java.base@11.0.10/System.java:1752)
	at com.example.demo.So68099330Application.shutdown(So68099330Application.java:13)
	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(java.base@11.0.10/Native Method)
	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(java.base@11.0.10/NativeMethodAccessorImpl.java:62)
	at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(java.base@11.0.10/DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(java.base@11.0.10/Method.java:566)
	at org.springframework.beans.factory.annotation.InitDestroyAnnotationBeanPostProcessor$LifecycleElement.invoke(InitDestroyAnnotationBeanPostProcessor.java:389)
	at org.springframework.beans.factory.annotation.InitDestroyAnnotationBeanPostProcessor$LifecycleMetadata.invokeInitMethods(InitDestroyAnnotationBeanPostProcessor.java:333)
	at org.springframework.beans.factory.annotation.InitDestroyAnnotationBeanPostProcessor.postProcessBeforeInitialization(InitDestroyAnnotationBeanPostProcessor.java:157)
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.applyBeanPostProcessorsBeforeInitialization(AbstractAutowireCapableBeanFactory.java:422)
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1778)
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:602)
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:524)
	at org.springframework.beans.factory.support.AbstractBeanFactory.lambda$doGetBean$0(AbstractBeanFactory.java:335)
	at org.springframework.beans.factory.support.AbstractBeanFactory$$Lambda$206/0x0000000800201040.getObject(Unknown Source)
	at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:234)
	- locked <0x000000061dff1048> (a java.util.concurrent.ConcurrentHashMap)
	at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:333)
	at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:208)
	at org.springframework.beans.factory.support.DefaultListableBeanFactory.preInstantiateSingletons(DefaultListableBeanFactory.java:944)
	at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:918)
	at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:583)
	- locked <0x000000061dd09be0> (a java.lang.Object)
	at org.springframework.boot.SpringApplication.refresh(SpringApplication.java:754)
	at org.springframework.boot.SpringApplication.refreshContext(SpringApplication.java:434)
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:338)
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:1343)
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:1332)
	at com.example.demo.So68099330Application.main(So68099330Application.java:17)

shutdown

 "SpringApplicationShutdownHook" #20 prio=5 os_prio=31 cpu=3.09ms elapsed=8.90s tid=0x00007f8d0eaa3000 nid=0x8503 waiting for monitor entry  [0x00007000072aa000]
   java.lang.Thread.State: BLOCKED (on object monitor)
	at org.springframework.context.support.AbstractApplicationContext.close(AbstractApplicationContext.java:1021)
	- waiting to lock <0x000000061dd09be0> (a java.lang.Object)
	at org.springframework.boot.SpringApplicationShutdownHook.closeAndWait(SpringApplicationShutdownHook.java:128)
	at org.springframework.boot.SpringApplicationShutdownHook$$Lambda$294/0x000000080027e040.accept(Unknown Source)
	at java.lang.Iterable.forEach(java.base@11.0.10/Iterable.java:75)
	at org.springframework.boot.SpringApplicationShutdownHook.run(SpringApplicationShutdownHook.java:100)
	at java.lang.Thread.run(java.base@11.0.10/Thread.java:834)

뭐 다 보기도 힘들고 무슨 소리인지도 이해가 잘 안될 것이니 핵심만 설명하겠다. 0x000000061dd09be0로 앞서 보여준 로그에서 검색을 해보자.검색을 진행할 경우 AbstractApplicationContext.close()와 AbstractApplicationContext.refresh()가 하나의 쓰레드를 가지고 락을 잡고 안 놓아주는 상태가 된다. 결국 빈까지 다 삭제하고 마무리로 종료를 하려고 할 때 두 개의 메소드에서 동일한 자원을 가지고 lock을 걸기 때문에 프로세스는 꺼지지 않고 살아있게 되는 것이다.

이제 원인이 된 부분을 확인했으니 코드를 다시 확인해보자

원인 발생 코드

참고 이슈: https://github.com/spring-projects/spring-boot/issues/23625

2.2.x 버전에서는 Application context의 refreshContext 코드가 다음과 같았다.

2.2.x 버전 refreshContext 메소드(refresh가 아래로 이동) 

private boolean registShutdownHook = true;

private void refreshContext(ConfigurableApplicationContext context) {
	refresh(context)
    if(this.registShutdownHook) {
    	try {
        	context.registerShutdownHook();
        	//Not allowed some environments.
        }
    }
}

코드를 볼 경우, refresh 이후 shutdownhook이 true일 경우 context.registerShutdownHook()을 진행한다. refresh 메소드는 다음과 같은 로직으로 동작한다.

/** Synchronization monitor for the "refresh" and "destroy". */
	private final Object startupShutdownMonitor = new Object();
    
@Override
	public void refresh() throws BeansException, IllegalStateException {
		synchronized (this.startupShutdownMonitor) {
        ...
        }

startupShutdownMonitor가 동기화 된 상태로 자원을 lock하고 있다. 다음은 context.registerShutdownHook()의 로직을 확인해보자.

@Override
	public void registerShutdownHook() {
		if (this.shutdownHook == null) {
			// No shutdown hook registered yet.
			this.shutdownHook = new Thread(SHUTDOWN_HOOK_THREAD_NAME) {
				@Override
				public void run() {
					synchronized (startupShutdownMonitor) {
						doClose();
					}
				}
			};
			Runtime.getRuntime().addShutdownHook(this.shutdownHook);
		}
	}

실행시 동일하게 startupShutdownMonitor가 동기화된 상태로 doClose() 메소드를 동작시킨다.

앞서 본 이슈에서는 refresh가 동작하는 동안 JVM이 종료될 경우 registerShutdownHook 메소드가 정상적으로 컨텍스트가 종료되지 않아 2.2.11 버전부터는 로직이 다음과 같이 변경되었다.

2.2.11부터 변경된 refreshContext 메소드(refresh가 아래로 이동)

private boolean registShutdownHook = true;

private void refreshContext(ConfigurableApplicationContext context) {
   if(this.registShutdownHook) {
   	try {
       	context.registerShutdownHook();
       	//Not allowed some environments.
       }
   }
   refresh(context);
}

다음과 같이 registerShutdownHook()을 진행하고 refresh()가 동작하도록 순서가 변경되었다. 하지만 이로 인해 registerShutdownHook이 Shutdown hook을 생성하고 lock을 획득하는 과정에서 System.exit(0)과의 deadlock이 발생하게 된 것이다.

해결 방법

해결 방법은 여러가지가 있다.

1. 2.6.0 이상 버전에 적용한다.

가장 쉬운 방법은 wilkinsona 아재가 Merge한 2.6.0 이상 버전을 사용하면 된다. 또한, spring.main.register-shutdown-hook 설정을 false로 둠으로서 shutdown hook이 동작하지 못하게 한다면 deadlock 상황이 발생하지 않아 정상적으로 종료된다.

2.6.0 이상 버전에는 그럼 어떻게 해결하셨는지 보자.

참고 : https://github.com/spring-projects/spring-boot/commit/5a9fa3c8f1d40095c5521e107854d2a5dc0ce2df

Previously, SpringApplicationShutdownHook would call close() on any
registered application context even if it wasn't active as it had
already been closed. This could lead to deadlock if the context was
closed and System.exit was called during application context refresh.
This commit updates SpringApplicationShutdownHook so that it only
calls close() on active contexts.

application context를 언제나 close() 되도록 호출했었는데 이게 context가 닫힐 때와 시스템이 종료될 때 application context가 새로고침 될 때 호출되어 데드락이 발생하는 상황이 생겼다.
따라서 해당 문제를 해결하기 위해 SpringApplicationShutdownHook은 오로지 활성화된 context에서만 close()가 동작하도록 구현을 변경했다. 

private void closeAndWait(ConfigurableApplicationContext context) {
		if (!context.isActive()) {
			return;
		}
		context.close();
		try {
			int waited = 0;

closeAndWait에 context가 활성화 되지 않은 경우에는 return을 해줌으로서 deadlock 상태를 회피하는 방어로직을 추가하였다.
이를 통해 context가 활성화 되어있을 경우에만 lock을 잡고 어플리케이션을 종료하도록 해결하였다.

2. Shutdown hook을 끈다.

private boolean registShutdownHook = true;이 true였기 때문에 ShutdownHook이 동작하는 것이므로 System.exit(0)을 사용하고 싶고 버전 업그레이드를 희망하지 않을 경우 spring.main.register-shutdown-hook을 false로 설정하면 된다.

spring.main.register-shutdown-hook: false

결론

Spring Boot 버전이 업그레이드 되면서 Spring Boot 오픈소스에 기여하는 형님들 조차 예상하지 못한 사이드 이펙트였던 것 같다.

문제 해결 과정

  1. 2.2.x 버전에서 발생한 JVM 종료시 정상적으로 컨텍스트가 종료되지 않는 이슈 발생
  2. 2.2.11 버전부터 refresh() 와 registerShutdownHook() 로직 순서가 변경됨
  3. 변경됨에 따른 사이드 이펙트 발생(System.exit(0)시 deadlock 발생)
  4. 2.6.0_M1 이상에서는 context가 활성화 되어있을 경우에만 실행되도록 로직 수정

System.exit()시 호출되는 로직과 System shudown hook 로직 중 한놈이 context를 껐으면 그냥 종료되어야 되는데 그 상태에서 lock을 잡아 deadlock 상황을 만드니 어플리케이션은 꺼지지만 프로세스는 종료되지 않았던 것이다.

따라서 컨텍스트가 살아있을 경우에만 락을 잡도록 변경되었으니 System.exit을 사용하고 싶은 개발자는 2.6.0 버전 이후의 Spring boot를 이용하면 되겠다.

개인의 생각

생각보다 다양한 부분에서 오류가 있다는 것을 느끼게 되었다. 모든 내용이 표준 라이브러리라 할지라도 에러는 있을 수 있으니 오류가 발견할 경우 좀 더 넓게 바라볼 필요가 있을 것 같다.(물론 내가 틀릴 확률은 99.99999%)

추가로, Spring의 동작 과정을 알면 보다 더 스프링 개발을 잘 할 수 있을 것 같다는 생각이 들었다. 이번 기회를 통해 Spring 내부 코드 동작 과정을 조금이나마 볼 수 있게 되었는데 동작 과정을 아는 것이 앞으로 개발에 있어서 큰 도움이 될 것 같다는 생각을 하게 되었다.

마지막으로는 Spring boot도 버전별로 이슈가 천차만별이니 주의해서 업그레이드/사용 하길 바란다. Spring Boot뿐만 아니라 DB, 라이브러리를 넘어 어플리케이션까지 버전 업그레이드 또는 도입시 고려할 사이드 이펙트가 생각지 못한 곳에 존재한다.

그러기 때문에 도입 이전에 최대한 릴리즈 docs를 보거나 최소한 변경 사항이라도 읽어보는 습관을 길러야겠다는 결심을 하며 글을 마무리하겠다.

profile
겔로그
Gelog 나쁜 것만 드려요~
이전 포스트

[ERROR] Form 태그에 input=text가 하나일 때 엔터를 치면 새로고침이 된다?

다음 포스트

일정 공유

0개의 댓글