woowacourse-teams / 2021-zzimkkong

✅ 공간을 한 눈에, 예약은 한 번에!
https://zzimkkong.com
164 stars 20 forks source link

[BE] 슬랙 메세지 발송 간헐적으로 실패하는 이슈 #985

Closed sakjung closed 7 months ago

sakjung commented 8 months ago

버그 기능

버그 상황 재연

기대 동작

현재 동작

stacktrace 를 봤을 때, 타이밍 이슈일 확률이 높음. 현재 tcpdump 걸어 놓은 상태 (since 2023/03/20). 에러 다시 잡히는 순간 덤프파일 통해서 함께 파악 예정.

i.e. slack message 발송 request 로직 start -> 도중에 fireChannelInactive -> connection prematurely closed

sakjung commented 8 months ago

LOG

2024-03-20 11:16:34.772 |  INFO | http-nio-8080-exec-161 |  5d6855b309d9 | [WebClientConfig:26] - REQUEST: POST https://hooks.slack.com/services/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 
2024-03-20 11:16:34.773 |  INFO | http-nio-8080-exec-161 |  5d6855b309d9 | [RequestLoggingFilter:100] - [15ms] [201][HTTP METHOD: POST] [PATH INFO: /api/guests/maps/3/spaces/10/reservations] [REQUEST HEADER: x-forwarded-for:218.39.176.142, host:127.0.0.1:8080, connection:close, content-length:125, sec-ch-ua:"Chromium";v="122", "Not(A:Brand";v="24", "Google Chrome";v="122", content-type:application/json, sec-ch-ua-mobile:?0, authorization:Bearer eyJhbGciOiJIUzI1NiJ9.eyJzdWIiOiJkcGNrczA1MDlAZ21haWwuY29tIiwiaWF0IjoxNzEwODIxMDMxLCJleHAiOjE3MTA5MDc0MzF9.vHSILq2E3jORRxUBgtUVomV1ikEhizP-6S1fMPYX0Z4, user-agent:Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/122.0.0.0 Safari/537.36, sec-ch-ua-platform:"macOS", accept:*/*, origin:https://zzimkkong.com, sec-fetch-site:same-site, sec-fetch-mode:cors, sec-fetch-dest:empty, referer:https://zzimkkong.com/, accept-encoding:gzip, deflate, br, zstd, accept-language:ko-KR,ko;q=0.9,en-US;q=0.8,en;q=0.7] [REQUEST BODY: {"startDateTime":"2024-03-20T19:30:00+09:00","endDateTime":"2024-03-20T20:30:00+09:00","description":"페어프로그래밍"}] [REMOTE ADDRESS: 218.39.176.142]  
2024-03-20 11:16:35.034 |  WARN | reactor-http-epoll-3 |   | [HttpClientConnect:294] - [id:f1bb6174-5, L:/192.168.0.180:34368 ! R:hooks.slack.com/52.196.128.139:443] The connection observed an error 
reactor.netty.http.client.PrematureCloseException: Connection prematurely closed BEFORE response
2024-03-20 11:16:35.035 | ERROR | reactor-http-epoll-3 |   | [Operators:314] - Operator called default onErrorDropped 
reactor.core.Exceptions$ErrorCallbackNotImplemented: org.springframework.web.reactive.function.client.WebClientRequestException: Connection prematurely closed BEFORE response; nested exception is reactor.netty.http.client.PrematureCloseException: Connection prematurely closed BEFORE response
Caused by: org.springframework.web.reactive.function.client.WebClientRequestException: Connection prematurely closed BEFORE response; nested exception is reactor.netty.http.client.PrematureCloseException: Connection prematurely closed BEFORE response
    at org.springframework.web.reactive.function.client.ExchangeFunctions$DefaultExchangeFunction.lambda$wrapException$9(ExchangeFunctions.java:141)
    Suppressed: reactor.core.publisher.FluxOnAssembly$OnAssemblyException: 
Error has been observed at the following site(s):
    |_ checkpoint ⇢ Request to POST null [DefaultWebClient]
Stack trace:
        at org.springframework.web.reactive.function.client.ExchangeFunctions$DefaultExchangeFunction.lambda$wrapException$9(ExchangeFunctions.java:141)
        at reactor.core.publisher.MonoErrorSupplied.subscribe(MonoErrorSupplied.java:70)
        at reactor.core.publisher.Mono.subscribe(Mono.java:4150)
        at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onError(FluxOnErrorResume.java:103)
        at reactor.core.publisher.FluxPeek$PeekSubscriber.onError(FluxPeek.java:221)
        at reactor.core.publisher.FluxPeek$PeekSubscriber.onError(FluxPeek.java:221)
        at reactor.core.publisher.FluxPeek$PeekSubscriber.onError(FluxPeek.java:221)
        at reactor.core.publisher.MonoNext$NextSubscriber.onError(MonoNext.java:93)
        at reactor.core.publisher.MonoFlatMapMany$FlatMapManyMain.onError(MonoFlatMapMany.java:204)
        at reactor.core.publisher.SerializedSubscriber.onError(SerializedSubscriber.java:124)
        at reactor.core.publisher.FluxRetryWhen$RetryWhenMainSubscriber.whenError(FluxRetryWhen.java:224)
        at reactor.core.publisher.FluxRetryWhen$RetryWhenOtherSubscriber.onError(FluxRetryWhen.java:273)
        at reactor.core.publisher.FluxConcatMap$ConcatMapImmediate.drain(FluxConcatMap.java:413)
        at reactor.core.publisher.FluxConcatMap$ConcatMapImmediate.onNext(FluxConcatMap.java:250)
        at reactor.core.publisher.EmitterProcessor.drain(EmitterProcessor.java:491)
        at reactor.core.publisher.EmitterProcessor.tryEmitNext(EmitterProcessor.java:299)
        at reactor.core.publisher.SinkManySerialized.tryEmitNext(SinkManySerialized.java:97)
        at reactor.core.publisher.InternalManySink.emitNext(InternalManySink.java:27)
        at reactor.core.publisher.FluxRetryWhen$RetryWhenMainSubscriber.onError(FluxRetryWhen.java:189)
        at reactor.core.publisher.MonoCreate$DefaultMonoSink.error(MonoCreate.java:189)
        at reactor.netty.http.client.HttpClientConnect$HttpObserver.onUncaughtException(HttpClientConnect.java:385)
        at reactor.netty.ReactorNetty$CompositeConnectionObserver.onUncaughtException(ReactorNetty.java:647)
        at reactor.netty.resources.DefaultPooledConnectionProvider$DisposableAcquire.onUncaughtException(DefaultPooledConnectionProvider.java:220)
        at reactor.netty.resources.DefaultPooledConnectionProvider$PooledConnection.onUncaughtException(DefaultPooledConnectionProvider.java:468)
        at reactor.netty.http.client.HttpClientOperations.onInboundClose(HttpClientOperations.java:290)
        at reactor.netty.channel.ChannelOperationsHandler.channelInactive(ChannelOperationsHandler.java:74)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:262)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:248)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:241)
        at io.netty.channel.ChannelInboundHandlerAdapter.channelInactive(ChannelInboundHandlerAdapter.java:81)
        at io.netty.handler.codec.http.HttpContentDecoder.channelInactive(HttpContentDecoder.java:235)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:262)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:248)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:241)
        at io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireChannelInactive(CombinedChannelDuplexHandler.java:418)
        at io.netty.handler.codec.ByteToMessageDecoder.channelInputClosed(ByteToMessageDecoder.java:389)
        at io.netty.handler.codec.ByteToMessageDecoder.channelInactive(ByteToMessageDecoder.java:354)
        at io.netty.handler.codec.http.HttpClientCodec$Decoder.channelInactive(HttpClientCodec.java:311)
        at io.netty.channel.CombinedChannelDuplexHandler.channelInactive(CombinedChannelDuplexHandler.java:221)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:262)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:248)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:241)
        at io.netty.handler.codec.ByteToMessageDecoder.channelInputClosed(ByteToMessageDecoder.java:389)
        at io.netty.handler.codec.ByteToMessageDecoder.channelInactive(ByteToMessageDecoder.java:354)
        at io.netty.handler.ssl.SslHandler.channelInactive(SslHandler.java:1073)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:262)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:248)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:241)
        at io.netty.channel.DefaultChannelPipeline$HeadContext.channelInactive(DefaultChannelPipeline.java:1405)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:262)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:248)
        at io.netty.channel.DefaultChannelPipeline.fireChannelInactive(DefaultChannelPipeline.java:901)
        at io.netty.channel.AbstractChannel$AbstractUnsafe$8.run(AbstractChannel.java:831)
        at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164)
        at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:472)
        at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:384)
        at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
        at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
        at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
        at java.base/java.lang.Thread.run(Thread.java:829)
Caused by: reactor.netty.http.client.PrematureCloseException: Connection prematurely closed BEFORE response