Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Warnings / Error from Netty in case of failures / suspensions #415

Closed
StephanEwen opened this issue Nov 27, 2024 · 4 comments · Fixed by #430
Closed

Warnings / Error from Netty in case of failures / suspensions #415

StephanEwen opened this issue Nov 27, 2024 · 4 comments · Fixed by #430

Comments

@StephanEwen
Copy link
Contributor

I see this happening in some examples where some operations (RPCs) cannot complete because the target service is not yet deployed, and the code suspends.

Steps to reproduce:

2024-11-27 12:04:48 INFO  [BookingWorkflow/run][inv_11UlL7aT9MLB5zSghFfnIimheCrjxZFQLD] dev.restate.sdk.core.InvocationStateMachine - Start invocation
2024-11-27 12:04:48 WARN  [BookingWorkflow/run][inv_11UlL7aT9MLB5zSghFfnIimheCrjxZFQLD] dev.restate.sdk.http.vertx.HttpResponseFlowAdapter - Error from wire
io.vertx.core.http.StreamResetException: Stream reset: 8
2024-11-27 12:04:48 INFO  [BookingWorkflow/run][inv_11UlL7aT9MLB5zSghFfnIimheCrjxZFQLD] dev.restate.sdk.core.InvocationStateMachine - End invocation
2024-11-27 12:04:48 ERROR [BookingWorkflow/run][inv_11UlL7aT9MLB5zSghFfnIimheCrjxZFQLD] io.vertx.core.impl.ContextImpl - Unhandled exception
java.lang.IllegalStateException: Response has already been written
	at io.vertx.core.http.impl.Http2ServerResponse.write(Http2ServerResponse.java:455) ~[vertx-core-4.5.11.jar:4.5.11]
	at io.vertx.core.http.impl.Http2ServerResponse.write(Http2ServerResponse.java:347) ~[vertx-core-4.5.11.jar:4.5.11]
	at io.vertx.core.http.impl.Http2ServerResponse.write(Http2ServerResponse.java:48) ~[vertx-core-4.5.11.jar:4.5.11]
	at dev.restate.sdk.http.vertx.HttpResponseFlowAdapter.onNext(HttpResponseFlowAdapter.java:49) ~[sdk-http-vertx-1.2.0.jar:?]
	at dev.restate.sdk.http.vertx.HttpResponseFlowAdapter.onNext(HttpResponseFlowAdapter.java:21) ~[sdk-http-vertx-1.2.0.jar:?]
	at dev.restate.sdk.core.MessageEncoder$1.onNext(MessageEncoder.java:37) ~[sdk-core-1.2.0.jar:?]
	at dev.restate.sdk.core.MessageEncoder$1.onNext(MessageEncoder.java:26) ~[sdk-core-1.2.0.jar:?]
	at dev.restate.sdk.core.InvocationStateMachine.closeWithMessage(InvocationStateMachine.java:302) ~[sdk-core-1.2.0.jar:?]
	at dev.restate.sdk.core.InvocationStateMachine.end(InvocationStateMachine.java:251) ~[sdk-core-1.2.0.jar:?]
	at dev.restate.sdk.core.InvocationStateMachine$1.cancel(InvocationStateMachine.java:131) ~[sdk-core-1.2.0.jar:?]
	at dev.restate.sdk.http.vertx.HttpResponseFlowAdapter.cancelSubscription(HttpResponseFlowAdapter.java:94) ~[sdk-http-vertx-1.2.0.jar:?]
	at dev.restate.sdk.http.vertx.HttpResponseFlowAdapter.endResponse(HttpResponseFlowAdapter.java:86) ~[sdk-http-vertx-1.2.0.jar:?]
	at dev.restate.sdk.http.vertx.HttpResponseFlowAdapter.propagateWireFailure(HttpResponseFlowAdapter.java:66) ~[sdk-http-vertx-1.2.0.jar:?]
	at io.vertx.core.http.impl.Http2ServerResponse.handleException(Http2ServerResponse.java:102) ~[vertx-core-4.5.11.jar:4.5.11]
	at io.vertx.core.http.impl.Http2ServerResponse.handleReset(Http2ServerResponse.java:90) ~[vertx-core-4.5.11.jar:4.5.11]
	at io.vertx.core.http.impl.Http2ServerRequest.handleReset(Http2ServerRequest.java:200) ~[vertx-core-4.5.11.jar:4.5.11]
	at io.vertx.core.http.impl.Http2ServerStream.handleReset(Http2ServerStream.java:185) ~[vertx-core-4.5.11.jar:4.5.11]
	at io.vertx.core.impl.ContextImpl.emit(ContextImpl.java:342) [vertx-core-4.5.11.jar:4.5.11]
	at io.vertx.core.impl.DuplicatedContext.emit(DuplicatedContext.java:163) [vertx-core-4.5.11.jar:4.5.11]
	at io.vertx.core.http.impl.VertxHttp2Stream.onReset(VertxHttp2Stream.java:99) [vertx-core-4.5.11.jar:4.5.11]
	at io.vertx.core.http.impl.Http2ConnectionBase.onRstStreamRead(Http2ConnectionBase.java:306) [vertx-core-4.5.11.jar:4.5.11]
	at io.vertx.core.http.impl.Http2ServerConnection.onRstStreamRead(Http2ServerConnection.java:38) [vertx-core-4.5.11.jar:4.5.11]
	at io.netty.handler.codec.http2.Http2FrameListenerDecorator.onRstStreamRead(Http2FrameListenerDecorator.java:57) [netty-codec-http2-4.1.115.Final.jar:4.1.115.Final]
	at io.netty.handler.codec.http2.Http2MaxRstFrameListener.onRstStreamRead(Http2MaxRstFrameListener.java:58) [netty-codec-http2-4.1.115.Final.jar:4.1.115.Final]
	at io.netty.handler.codec.http2.Http2FrameListenerDecorator.onRstStreamRead(Http2FrameListenerDecorator.java:57) [netty-codec-http2-4.1.115.Final.jar:4.1.115.Final]
	at io.netty.handler.codec.http2.DefaultHttp2ConnectionDecoder$FrameReadListener.onRstStreamRead(DefaultHttp2ConnectionDecoder.java:468) [netty-codec-http2-4.1.115.Final.jar:4.1.115.Final]
	at io.netty.handler.codec.http2.DefaultHttp2FrameReader.readRstStreamFrame(DefaultHttp2FrameReader.java:508) [netty-codec-http2-4.1.115.Final.jar:4.1.115.Final]
	at io.netty.handler.codec.http2.DefaultHttp2FrameReader.processPayloadState(DefaultHttp2FrameReader.java:253) [netty-codec-http2-4.1.115.Final.jar:4.1.115.Final]
	at io.netty.handler.codec.http2.DefaultHttp2FrameReader.readFrame(DefaultHttp2FrameReader.java:164) [netty-codec-http2-4.1.115.Final.jar:4.1.115.Final]
	at io.netty.handler.codec.http2.DefaultHttp2ConnectionDecoder.decodeFrame(DefaultHttp2ConnectionDecoder.java:186) [netty-codec-http2-4.1.115.Final.jar:4.1.115.Final]
	at io.netty.handler.codec.http2.DecoratingHttp2ConnectionDecoder.decodeFrame(DecoratingHttp2ConnectionDecoder.java:61) [netty-codec-http2-4.1.115.Final.jar:4.1.115.Final]
	at io.netty.handler.codec.http2.DecoratingHttp2ConnectionDecoder.decodeFrame(DecoratingHttp2ConnectionDecoder.java:61) [netty-codec-http2-4.1.115.Final.jar:4.1.115.Final]
	at io.netty.handler.codec.http2.Http2ConnectionHandler$FrameDecoder.decode(Http2ConnectionHandler.java:391) [netty-codec-http2-4.1.115.Final.jar:4.1.115.Final]
	at io.netty.handler.codec.http2.Http2ConnectionHandler.decode(Http2ConnectionHandler.java:451) [netty-codec-http2-4.1.115.Final.jar:4.1.115.Final]
	at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:530) [netty-codec-4.1.115.Final.jar:4.1.115.Final]
	at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:469) [netty-codec-4.1.115.Final.jar:4.1.115.Final]
	at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:290) [netty-codec-4.1.115.Final.jar:4.1.115.Final]
	at io.vertx.core.http.impl.VertxHttp2ConnectionHandler.channelRead(VertxHttp2ConnectionHandler.java:405) [vertx-core-4.5.11.jar:4.5.11]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444) [netty-transport-4.1.115.Final.jar:4.1.115.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420) [netty-transport-4.1.115.Final.jar:4.1.115.Final]
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412) [netty-transport-4.1.115.Final.jar:4.1.115.Final]
	at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1357) [netty-transport-4.1.115.Final.jar:4.1.115.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:440) [netty-transport-4.1.115.Final.jar:4.1.115.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420) [netty-transport-4.1.115.Final.jar:4.1.115.Final]
	at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:868) [netty-transport-4.1.115.Final.jar:4.1.115.Final]
	at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166) [netty-transport-4.1.115.Final.jar:4.1.115.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:788) [netty-transport-4.1.115.Final.jar:4.1.115.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:724) [netty-transport-4.1.115.Final.jar:4.1.115.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:650) [netty-transport-4.1.115.Final.jar:4.1.115.Final]
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:562) [netty-transport-4.1.115.Final.jar:4.1.115.Final]
	at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997) [netty-common-4.1.115.Final.jar:4.1.115.Final]
	at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) [netty-common-4.1.115.Final.jar:4.1.115.Final]
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [netty-common-4.1.115.Final.jar:4.1.115.Final]
	at java.base/java.lang.Thread.run(Thread.java:833) [?:?]
2024-11-27 12:04:48 INFO  [BookingWorkflow/run][inv_11UlL7aT9MLB5zSghFfnIimheCrjxZFQLD] dev.restate.sdk.core.InvocationStateMachine - Suspend invocation
@slinkydeveloper
Copy link
Contributor

slinkydeveloper commented Nov 28, 2024 •
edited
Loading

The thing is, this is completely valid exception, it's telling you that the response is already written because the stream was closed before (that's the Error from the wire you see in the second line), so I don't think we should simply hide that/ignore that. It is basically telling you we're dropping some data effectively.

Maybe we just need to lower down the level when we have these exceptions to DEBUG?

@StephanEwen
Copy link
Contributor Author

I don't quite understand - who closed the stream, the SDK or Restate server?

If the server closed the stream, than this is valid and expected and should probably just be on DEBUG, with an additional info that this can be because the server closed the stream.

If the SDK closed the stream and still tried to write, than this is a bit strange. Might be harmless (because of how committed journal is the only ground truth) but still strange that the SDK tries to write after it closed the stream itself. Some kind of accidental concurrency?

@slinkydeveloper
Copy link
Contributor

If the server closed the stream, than this is valid and expected and should probably just be on DEBUG, with an additional info that this can be because the server closed the stream.

This is the case here, you can see it here:

2024-11-27 12:04:48 WARN  [BookingWorkflow/run][inv_11UlL7aT9MLB5zSghFfnIimheCrjxZFQLD] dev.restate.sdk.http.vertx.HttpResponseFlowAdapter - Error from wire
io.vertx.core.http.StreamResetException: Stream reset: 8

I'll lower this down to debug

@StephanEwen
Copy link
Contributor Author

Can you add an error message that describes the situation, like "Restate Server closed the stream - this may be due to a request to suspend, or due to fencing off this invocation."

@slinkydeveloper slinkydeveloper mentioned this issue Nov 29, 2024
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Fix condition to drop messages in HttpResponseFlowAdapter restatedev/sdk-java
2 participants
@StephanEwen @slinkydeveloper