Encountered an error while processing subscription stream

[advanced4]

While setting up a dev environment for Open Distro, one of my nodes has substantial log spam of the following:

Sep 24 12:16:15 masternode1 performance-analyzer-agent-cli[26382]: 12:16:15.689 [grpc-default-executor-21] ERROR com.amazon.opendistro.elasticsearch.performanceanalyzer.rca.net.SubscribeResponseHandler - Encountered an error while processing subscription stream
Sep 24 12:16:15 masternode1 performance-analyzer-agent-cli[26382]: io.grpc.StatusRuntimeException: UNKNOWN
Sep 24 12:16:15 masternode1 performance-analyzer-agent-cli[26382]: #011at io.grpc.Status.asRuntimeException(Status.java:533) ~[grpc-api-1.25.0.jar:1.25.0]
Sep 24 12:16:15 masternode1 performance-analyzer-agent-cli[26382]: #011at io.grpc.stub.ClientCalls$StreamObserverToCallListenerAdapter.onClose(ClientCalls.java:447) [grpc-stub-1.25.0.jar:1.25.0]
Sep 24 12:16:15 masternode1 performance-analyzer-agent-cli[26382]: #011at io.grpc.PartialForwardingClientCallListener.onClose(PartialForwardingClientCallListener.java:39) [grpc-api-1.25.0.jar:1.25.0]
Sep 24 12:16:15 masternode1 performance-analyzer-agent-cli[26382]: #011at io.grpc.ForwardingClientCallListener.onClose(ForwardingClientCallListener.java:23) [grpc-api-1.25.0.jar:1.25.0]
Sep 24 12:16:15 masternode1 performance-analyzer-agent-cli[26382]: #011at io.grpc.ForwardingClientCallListener$SimpleForwardingClientCallListener.onClose(ForwardingClientCallListener.java:40) [grpc-api-1.25.0.jar:1.25.0]
Sep 24 12:16:15 masternode1 performance-analyzer-agent-cli[26382]: #011at io.grpc.internal.CensusStatsModule$StatsClientInterceptor$1$1.onClose(CensusStatsModule.java:700) [grpc-core-1.25.0.jar:1.25.0]
Sep 24 12:16:15 masternode1 performance-analyzer-agent-cli[26382]: #011at io.grpc.PartialForwardingClientCallListener.onClose(PartialForwardingClientCallListener.java:39) [grpc-api-1.25.0.jar:1.25.0]
Sep 24 12:16:15 masternode1 performance-analyzer-agent-cli[26382]: #011at io.grpc.ForwardingClientCallListener.onClose(ForwardingClientCallListener.java:23) [grpc-api-1.25.0.jar:1.25.0]
Sep 24 12:16:15 masternode1 performance-analyzer-agent-cli[26382]: #011at io.grpc.ForwardingClientCallListener$SimpleForwardingClientCallListener.onClose(ForwardingClientCallListener.java:40) [grpc-api-1.25.0.jar:1.25.0]
Sep 24 12:16:15 masternode1 performance-analyzer-agent-cli[26382]: #011at io.grpc.internal.CensusTracingModule$TracingClientInterceptor$1$1.onClose(CensusTracingModule.java:399) [grpc-core-1.25.0.jar:1.25.0]
Sep 24 12:16:15 masternode1 performance-analyzer-agent-cli[26382]: #011at io.grpc.internal.ClientCallImpl.closeObserver(ClientCallImpl.java:510) [grpc-core-1.25.0.jar:1.25.0]
Sep 24 12:16:15 masternode1 performance-analyzer-agent-cli[26382]: #011at io.grpc.internal.ClientCallImpl.access$300(ClientCallImpl.java:66) [grpc-core-1.25.0.jar:1.25.0]
Sep 24 12:16:15 masternode1 performance-analyzer-agent-cli[26382]: #011at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl.close(ClientCallImpl.java:630) [grpc-core-1.25.0.jar:1.25.0]
Sep 24 12:16:15 masternode1 performance-analyzer-agent-cli[26382]: #011at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl.access$700(ClientCallImpl.java:518) [grpc-core-1.25.0.jar:1.25.0]
Sep 24 12:16:15 masternode1 performance-analyzer-agent-cli[26382]: #011at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1StreamClosed.runInternal(ClientCallImpl.java:692) [grpc-core-1.25.0.jar:1.25.0]
Sep 24 12:16:15 masternode1 performance-analyzer-agent-cli[26382]: #011at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1StreamClosed.runInContext(ClientCallImpl.java:681) [grpc-core-1.25.0.jar:1.25.0]
Sep 24 12:16:15 masternode1 performance-analyzer-agent-cli[26382]: #011at io.grpc.internal.ContextRunnable.run(ContextRunnable.java:37) [grpc-core-1.25.0.jar:1.25.0]
Sep 24 12:16:15 masternode1 performance-analyzer-agent-cli[26382]: #011at io.grpc.internal.SerializingExecutor.run(SerializingExecutor.java:123) [grpc-core-1.25.0.jar:1.25.0]
Sep 24 12:16:15 masternode1 performance-analyzer-agent-cli[26382]: #011at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130) [?:?]
Sep 24 12:16:15 masternode1 performance-analyzer-agent-cli[26382]: #011at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630) [?:?]
Sep 24 12:16:15 masternode1 performance-analyzer-agent-cli[26382]: #011at java.lang.Thread.run(Thread.java:832) [?:?]

My current environment consists of 5 data nodes and 1 master node. The master node emits the above error 10's of times per minute. The data nodes emit a smaller message, at a similar rate:

Sep 24 06:29:21 datanode3 performance-analyzer-agent-cli[14936]: INFO: Single batch             : No bind variables have been provided with a single statement batch execution. This may be due to accidental API misuse
Sep 24 06:29:21 datanode3 performance-analyzer-agent-cli[14936]: Sep 24, 2020 6:29:21 AM org.jooq.tools.JooqLogger info
Sep 24 06:29:21 datanode3 performance-analyzer-agent-cli[14936]: INFO: Single batch             : No bind variables have been provided with a single statement batch execution. This may be due to accidental API misuse
Sep 24 06:29:22 datanode3 performance-analyzer-agent-cli[14936]: 06:29:22.785 [pool-6-thread-1] ERROR com.amazon.opendistro.elasticsearch.performanceanalyzer.net.NetServer - Subscribe request received before handler is set.
Sep 24 06:29:22 datanode3 performance-analyzer-agent-cli[14936]: 06:29:22.785 [pool-6-thread-1] ERROR com.amazon.opendistro.elasticsearch.performanceanalyzer.net.NetServer - Subscribe request received before handler is set.
Sep 24 06:29:22 datanode3 performance-analyzer-agent-cli[14936]: 06:29:22.786 [pool-6-thread-1] ERROR com.amazon.opendistro.elasticsearch.performanceanalyzer.net.NetServer - Subscribe request received before handler is set.

This very well may be a configuration error or something I did wrong, but as the error messages are unhelpful, and there are zero helpful results on Google or in the Issues that I can find, this is still a valid error to me, as these error messages can be improved. This may be related to #39

[sendkb]

Thanks for reporting. We will look into this issue. Possibly related to https://github.com/opendistro-for-elasticsearch/performance-analyzer-rca/issues/363

[ktkrg]

@advanced4 Can you please check if the issue is resolved in the latest version of ODFE?

[advanced4]

@ktkrg Yes, this appears to have been resolved, I don't see these messages on master or data nodes. Thanks!

[TheMeier]

I still have these exceptions on opendistroforelasticsearch-1.12.0-1.noarch

io.grpc.StatusRuntimeException: UNKNOWN
	at io.grpc.Status.asRuntimeException(Status.java:533) ~[grpc-api-1.28.0.jar:1.28.0]
	at io.grpc.stub.ClientCalls$StreamObserverToCallListenerAdapter.onClose(ClientCalls.java:449) [grpc-stub-1.28.0.jar:1.28.0]
	at io.grpc.internal.ClientCallImpl.closeObserver(ClientCallImpl.java:426) [grpc-core-1.28.0.jar:1.28.0]
	at io.grpc.internal.ClientCallImpl.access$500(ClientCallImpl.java:66) [grpc-core-1.28.0.jar:1.28.0]
	at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl.close(ClientCallImpl.java:689) [grpc-core-1.28.0.jar:1.28.0]
	at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl.access$900(ClientCallImpl.java:577) [grpc-core-1.28.0.jar:1.28.0]
	at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1StreamClosed.runInternal(ClientCallImpl.java:751) [grpc-core-1.28.0.jar:1.28.0]
	at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1StreamClosed.runInContext(ClientCallImpl.java:740) [grpc-core-1.28.0.jar:1.28.0]
	at io.grpc.internal.ContextRunnable.run(ContextRunnable.java:37) [grpc-core-1.28.0.jar:1.28.0]
	at io.grpc.internal.SerializingExecutor.run(SerializingExecutor.java:123) [grpc-core-1.28.0.jar:1.28.0]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630) [?:?]
	at java.lang.Thread.run(Thread.java:832) [?:?]

[TheMeier]

On a an eligeble master node I see these errors that might be related

2021-02-12 08:44:36.863 [PA:Reader] [pool-6-thread-1] ERROR com.amazon.opendistro.elasticsearch.performanceanalyzer.net.NetServer - Subscribe request received before handler is set.

[ghost]

I'm also seeing these errors on 1.12.0

[gferrette]

Hello,

I'm seeing these errors on last version too (1.13.2)

[sitler87]

Some info? Seeing that on latest version as well.