첫 번째 Spring Boot 이슈 및 후기

개요 Link to heading

사이드 프로젝트로 진행하던 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 로 설치한 프로그램 버전 업그레이드 밖에 없었다.

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

원인 분석 Link to heading

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 실행한 결과 Link to heading

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

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

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

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

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

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

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 를 붙이면 된다는 내용을 확인했고, 로컬에서 원하는 값으로 가져오는 것을 확인했다.

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

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