삽질 기록 (11) 로컬에서는 잘만 되는 WebSocket 채팅 EC2에서는 외않뒈?

 

위 캡처는 좀 작위적이지만 ㅎ..

실제로는 성공하자마자 비명 지르고 이빨 만개했었다.

성공한 기쁨에 심취해서 캡처하는 걸 깜빡하고 팀원분들한테 요청해서 다시 찍음..

 

https://7357.tistory.com/295?category=1092940 

(주절주절) 생애 첫 풀스택 팀 프로젝트를 마무리하며..

 

오늘은 2022년 10월 29일로 공부 목적으로 진행하던 팀 프로젝트를 마무리 지은지 4일 정도 된 시점이다. (예약글임 ㅎ)

 

저 때만 해도 그럭저럭 마무리 된 상태라고 생각해서 올렸었는데 생각보다 문제가 많았다.

근데 나는 이미 코드스테이츠에서 프리 프로젝트 기간이 시작된 상태라 시간이 없었고, 해결하지 못한 문제들 중 하나가 바로 WebSocket 채팅이였다.

 

로컬에서는 아주 잘만 돌아가던 녀석이 서버에 올라오자

계속 Connection Failed -> 401 -> 404 에러를 띄우는 것이 아니겠는가?

 

아쉽게도 재현하기는 귀찮고 캡쳐해놓은 게 없다. 아무튼 그랬다.

401 에러 때문에 처음에는 wss 핸드쉐이크 문제를 의심했으나 ELB에서 wss도 HTTPS와 마찬가지로 알아서 처리해준다고 해서 이건 패스.

 

토큰 관련해서 문제가 있었다면 로컬에서도 안됐을테니 패스.

당연히 이 정도로 포기하는 그런 한심한 사람은 아니다.

 

우선 바로 스프링 로그를 뒤져봤다.

 

org.springframework.dao.InvalidDataAccessApiUsageException: The given id must not be null!; nested exception is java.lang.IllegalArgumentException: The given id must not be null!
        at org.springframework.orm.jpa.EntityManagerFactoryUtils.convertJpaAccessExceptionIfPossible(EntityManagerFactoryUtils.java:374) ~[spring-orm-5.3.22.jar!/:5.3.22]
        at org.springframework.orm.jpa.vendor.HibernateJpaDialect.translateExceptionIfPossible(HibernateJpaDialect.java:235) ~[spring-orm-5.3.22.jar!/:5.3.22]
        at org.springframework.orm.jpa.AbstractEntityManagerFactoryBean.translateExceptionIfPossible(AbstractEntityManagerFactoryBean.java:551) ~[spring-orm-5.3.22.jar!/:5.3.22]
        at org.springframework.dao.support.ChainedPersistenceExceptionTranslator.translateExceptionIfPossible(ChainedPersistenceExceptionTranslator.java:61) ~[spring-tx-5.3.22.jar!/:5.3.22]
        at org.springframework.dao.support.DataAccessUtils.translateIfNecessary(DataAccessUtils.java:242) ~[spring-tx-5.3.22.jar!/:5.3.22]
        at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(PersistenceExceptionTranslationInterceptor.java:152) ~[spring-tx-5.3.22.jar!/:5.3.22]
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.3.22.jar!/:5.3.22]
        at org.springframework.data.jpa.repository.support.CrudMethodMetadataPostProcessor$CrudMethodMetadataPopulatingMethodInterceptor.invoke(CrudMethodMetadataPostProcessor.java:174) ~[spring-data-jpa-2.7.2.jar!/:2.7.2]
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.3.22.jar!/:5.3.22]
        at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:97) ~[spring-aop-5.3.22.jar!/:5.3.22]
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.3.22.jar!/:5.3.22]
        at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:215) ~[spring-aop-5.3.22.jar!/:5.3.22]
        at com.sun.proxy.$Proxy140.findById(Unknown Source) ~[na:na]
        at com.devillage.teamproject.service.user.UserServiceImpl.findVerifiedUser(UserServiceImpl.java:113) ~[classes!/:na]
        at com.devillage.teamproject.service.user.UserServiceImpl$$FastClassBySpringCGLIB$$95843ca2.invoke(<generated>) ~[classes!/:na]
        at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218) ~[spring-core-5.3.22.jar!/:5.3.22]
        at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:793) ~[spring-aop-5.3.22.jar!/:5.3.22]
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163) ~[spring-aop-5.3.22.jar!/:5.3.22]
        at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:763) ~[spring-aop-5.3.22.jar!/:5.3.22]
        at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:123) ~[spring-tx-5.3.22.jar!/:5.3.22]
        at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:388) ~[spring-tx-5.3.22.jar!/:5.3.22]
        at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:119) ~[spring-tx-5.3.22.jar!/:5.3.22]
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.3.22.jar!/:5.3.22]
        at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:763) ~[spring-aop-5.3.22.jar!/:5.3.22]
        at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:708) ~[spring-aop-5.3.22.jar!/:5.3.22]
        at com.devillage.teamproject.service.user.UserServiceImpl$$EnhancerBySpringCGLIB$$da46542f.findVerifiedUser(<generated>) ~[classes!/:na]
        at com.devillage.teamproject.config.WebSocketEventListener.handleWebSocketDisconnectListener(WebSocketEventListener.java:73) ~[classes!/:na]
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:na]
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:na]
        at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:na]
        at java.base/java.lang.reflect.Method.invoke(Method.java:566) ~[na:na]

 

The given id must not be null..?

찾아보니 식별자 문제라는데 아무리 머리를 싸매고 생각해봐도 식별자 문제일리가 없었다.

혹시 몰라 DB에 채팅방 등록이 안되었나 싶어서 확인해보니 아니다.

 

 

 

 

 

2022-10-29 03:23:22.652  INFO 27051 --- [MessageBroker-1] c.d.t.config.WebSocketEventListener      : Disconnect Check!
2022-10-29 03:23:22.654  WARN 27051 --- [http-nio-8080-exec-8] .w.s.m.s.DefaultHandlerExceptionResolver : Resolved [org.springframework.http.converter.HttpMessageNotWritableException: No converter for [class java.util.LinkedHashMap] with preset Content-Type 'text/event-stream;charset=UTF-8']
2022-10-29 03:23:22.663 ERROR 27051 --- [MessageBroker-1] o.s.w.s.m.StompSubProtocolHandler        : Error publishing SessionDisconnectEvent[sessionId=vy1wt3cy, CloseStatus[code=1011, reason=null]]

 

 

노 컨버터 어쩌고 저쩌고.. 저건 찾아봐도 주 원인은 아닌 것 같고,

CloseStatus[code=1011, reason=null]을 보고 단서가 될까 찾아보니 그냥 서버 문제로 접속 해제됐다는 뜻이다.

 

도저히 스프링 로그에서는 단서를 찾아낼 수 없었다.

그러면 어떡하나? nginx랑 ELB를 뒤져봐야지.

 

근데 이 글을 읽는 분들이 제 로그 하나하나 같이 읽을 필요는 없으니 생략하겠습니다.

아무튼 결론은 nginx에는 그냥 똑같이 401, 404 요청이 있었다는 정보 정도만 보였고, ELB에서도 별달리 눈에 띄는 로그를 찾을 수 없었다.

 

그리고 나는 이미 프리 프로젝트 때문에 이 문제만 주구장창 보고 있을 수도 없는 노릇이였으므로, 이 상태로 4일간 방치되었다.

 

그러다가 오늘 (1시간 전) 지푸라기라도 잡는 심정으로 다시 EC2의 스프링 로그를 실시간으로 갱신하며 뚫어져라 보고 있다가 이 문구를 발견한다.

 

2022-10-29 02:36:25.848 ERROR 27051 --- [http-nio-8080-exec-8] o.s.w.s.s.s.DefaultHandshakeHandler
: "Handshake failed due to invalid Upgrade header: null"

 

그렇다.. HTTP Header가 Upgrade되지 않고 있던 것이였다.

내가 평소 같았으면 "로그를 잘 읽었어야지!"라고 자책했겠지만 이번만큼은 억울한 것이 저 로그가 에러 로그랑 완전히 동떨어진 곳에 혼자 덩그러니 놓여있었다.

진짜 무념무상으로 로그를 한 글자 한 글자 읽어보다가 저걸 찾은 것이다.

 

 

 

여기가 에러가 시작되고 있는 부분인데 시작부터 끝까지 돌아봐도 저 로그가 없다.

다시 찾으려고 해도 저 로그 어디있는지 모르겠음, ctrl+f로 검색해도 안 나온다.

 

후.. 진짜 억울하다.

아무튼 변명은 그만두고 로컬에서 잘되던 웹 소켓 연결이 서버에서는 upgrade header 어디에 팔아먹고 안되는 것이냐?

 

1. ELB에서 유실되고 있을 수 있다.

: HTTP/2를 사용하거나 지연 시간 설정을 짧게 설정할 경우 여기서 요청이 유실될 수 있다고 한다.

 

2. EC2에서 Nginx로 리버스 프록시 기능을 사용하고 있을 경우 프록시로 보낼 때 upgrade header를 장착해서 보내야 한다.

 

나는 2번 문제였다..

클라이언트가 헤더 설정해서 보내도 EC2의 nginx에서 다시 그 요청을 분기해서 재요청하고 있으니 upgrade header 설정은 날아가버린다.

ELB도 문제가 될 수 있다고 하는데, 일단 나는 문제가 없었다.

리버스 프록시 과정에서 1.1로 전달하다보니 원래 문제가 있을 예정이였어도 문제가 없어질 수 밖에 없긴 하다.

 

혹시 리버스 프록시를 사용하지 않는데도 안되는 분들은 해당 설정을 한 번 확인해보자

 

 

location /ws {
        proxy_pass http://localhost:8080;
        proxy_set_header Upgrade $http_upgrade;
        proxy_set_header Connection "upgrade";
        proxy_http_version 1.1;
}

 

nginx의 기존 스프링 서버로 분기하는 부분에서 헤더에 upgrade를 장착해줬다.

그리고 결과는 ?

 

 

 

 

 

네 재탕~

아무튼 즐겁고 행복하다.

끝.