첫 번째 Spring Boot 이슈 및 후기

Created: 2023-11-03 | Last modified: 2023-11-03

개요

사이드 프로젝트로 진행하던 zammanvoca-server 프로젝트를 로컬에서 테스트 진행하던 중 아래와 같은 에러를 발견했다.

.   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::                (v3.1.5)

2023-10-21T00:05:19.654+09:00  INFO 4906 --- [           main] m.z.ServerApplicationKt        : Starting ServerApplicationKt using Java 17.0.9 with PID 4906
2023-10-21T00:05:19.656+09:00  INFO 4906 --- [           main] m.z.ServerApplicationKt        : The following 1 profile is active: "local"
2023-10-21T00:05:19.694+09:00  INFO 4906 --- [           main] .s.b.d.c.l.DockerComposeLifecycleManager : Using Docker Compose file 'some/path/compose.yaml'
2023-10-21T00:11:45.208+09:00 ERROR 4906 --- [           main] o.s.boot.SpringApplication               : Application run failed

java.lang.NullPointerException: Cannot invoke "org.springframework.boot.docker.compose.core.DockerCliInspectResponse.hostConfig()" because "inspectResponse" is null
    at org.springframework.boot.docker.compose.core.DefaultConnectionPorts.isHostNetworkMode(DefaultConnectionPorts.java:56) ~[spring-boot-docker-compose-3.1.5.jar:3.1.5]
    at org.springframework.boot.docker.compose.core.DefaultConnectionPorts.<init>(DefaultConnectionPorts.java:47) ~[spring-boot-docker-compose-3.1.5.jar:3.1.5]
    at org.springframework.boot.docker.compose.core.DefaultRunningService.<init>(DefaultRunningService.java:55) ~[spring-boot-docker-compose-3.1.5.jar:3.1.5]
    at org.springframework.boot.docker.compose.core.DefaultDockerCompose.getRunningServices(DefaultDockerCompose.java:83) ~[spring-boot-docker-compose-3.1.5.jar:3.1.5]
    at org.springframework.boot.docker.compose.lifecycle.DockerComposeLifecycleManager.start(DockerComposeLifecycleManager.java:120) ~[spring-boot-docker-compose-3.1.5.jar:3.1.5]
    at org.springframework.boot.docker.compose.lifecycle.DockerComposeListener.onApplicationEvent(DockerComposeListener.java:53) ~[spring-boot-docker-compose-3.1.5.jar:3.1.5]
    at org.springframework.boot.docker.compose.lifecycle.DockerComposeListener.onApplicationEvent(DockerComposeListener.java:35) ~[spring-boot-docker-compose-3.1.5.jar:3.1.5]
    at org.springframework.context.event.SimpleApplicationEventMulticaster.doInvokeListener(SimpleApplicationEventMulticaster.java:174) ~[spring-context-6.0.13.jar:6.0.13]
    at org.springframework.context.event.SimpleApplicationEventMulticaster.invokeListener(SimpleApplicationEventMulticaster.java:167) ~[spring-context-6.0.13.jar:6.0.13]
    at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:145) ~[spring-context-6.0.13.jar:6.0.13]
    at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:133) ~[spring-context-6.0.13.jar:6.0.13]
    at org.springframework.boot.context.event.EventPublishingRunListener.multicastInitialEvent(EventPublishingRunListener.java:136) ~[spring-boot-3.1.5.jar:3.1.5]
    at org.springframework.boot.context.event.EventPublishingRunListener.contextLoaded(EventPublishingRunListener.java:98) ~[spring-boot-3.1.5.jar:3.1.5]
    at org.springframework.boot.SpringApplicationRunListeners.lambda$contextLoaded$4(SpringApplicationRunListeners.java:72) ~[spring-boot-3.1.5.jar:3.1.5]
    at java.base/java.lang.Iterable.forEach(Iterable.java:75) ~[na:na]
    at org.springframework.boot.SpringApplicationRunListeners.doWithListeners(SpringApplicationRunListeners.java:118) ~[spring-boot-3.1.5.jar:3.1.5]
    at org.springframework.boot.SpringApplicationRunListeners.doWithListeners(SpringApplicationRunListeners.java:112) ~[spring-boot-3.1.5.jar:3.1.5]
    at org.springframework.boot.SpringApplicationRunListeners.contextLoaded(SpringApplicationRunListeners.java:72) ~[spring-boot-3.1.5.jar:3.1.5]
    at org.springframework.boot.SpringApplication.prepareContext(SpringApplication.java:420) ~[spring-boot-3.1.5.jar:3.1.5]
    at org.springframework.boot.SpringApplication.run(SpringApplication.java:315) ~[spring-boot-3.1.5.jar:3.1.5]
    at org.springframework.boot.SpringApplication.run(SpringApplication.java:1306) ~[spring-boot-3.1.5.jar:3.1.5]
    at org.springframework.boot.SpringApplication.run(SpringApplication.java:1295) ~[spring-boot-3.1.5.jar:3.1.5]

분명 이전까지는 잘 동작했는데, 그 사이에 영향을 미칠 수 있는건… brew 로 설치한 프로그램 버전 업그레이드 밖에 없었다.

그래서 구체적으로 어떤 원인이 발생한건지 확인해보았다.

원인 분석

NPE가 발생한 원인은 DefaultDockerCompose Class 내의 getRunningServices 메서드에서 에러 발생한 것이었고,

디버깅 결과는 다음과 같았다.

    @Override
    public List<RunningService> getRunningServices() {
        List<DockerCliComposePsResponse> runningPsResponses = runComposePs().stream().filter(this::isRunning).toList();
        if (runningPsResponses.isEmpty()) {
            return Collections.emptyList();
        }
        DockerComposeFile dockerComposeFile = this.cli.getDockerComposeFile();
        List<RunningService> result = new ArrayList<>();
        Map<String, DockerCliInspectResponse> inspected = inspect(runningPsResponses);
        for (DockerCliComposePsResponse psResponse : runningPsResponses) {
            DockerCliInspectResponse inspectResponse = inspected.get(psResponse.id()); // <-- psResponse.id() 가 inspected 의 Key 의 앞 부분만 할당되었다.
            result.add(new DefaultRunningService(this.hostname, dockerComposeFile, psResponse, inspectResponse));
        }
        return Collections.unmodifiableList(result);
    }

DockerCliInspectResponse inspectResponse = inspected.get(psResponse.id()); 라인에서

psResponse.id() 는 4634e75ac669 이런 값이지만,

inspected 는 4634e75ac66930fbce37ec146669182dabfa2f7b254a5f6afaa34d1cf15dbb65 값이다.

길이 차이라고 보면 된다.

Docker 실행한 결과

실제 저 값은 코드에서 docker 를 실행해서 가져온 값인 것을 확인할 수 있다.

그래서 로컬에서 실행해보았다.

에러 발생 시점에서 docker compose 의 버전은 최신 버전인 2.23.0 이었다.

$ docker compose ps --format=json
{...,"ID":"4634e75ac669","Image":"postgres:latest",...}

$ docker inspect --format='{{ json . }}' 4634e75ac669
{"Id":"4634e75ac66930fbce37ec146669182dabfa2f7b254a5f6afaa34d1cf15dbb65",...}

그럼 왜 이전에는 제대로 동작을 했던 것일까?

docker compose 를 업데이트해서 발생했을 것이라 이미 지레짐작을 하고 있어, release를 보러 갔고, 원인이 되는 부분을 찾게 되었다.

https://github.com/docker/compose/releases/tag/v2.23.0

release note

https://github.com/docker/compose/pull/11038

https://github.com/docker/compose/pull/10918

안내되는 내용을 보니, --no-trunc flag 를 붙이면 된다는 내용을 확인했고, 로컬에서 원하는 값으로 가져오는 것을 확인했다.

1
2

$ docker compose ps --format=json --no-trunc
{...,"ID":"4634e75ac66930fbce37ec146669182dabfa2f7b254a5f6afaa34d1cf15dbb65","Image":"postgres:latest",...}

해결책도 어느정도 확인한 것 같다.