Skip to content
This repository has been archived by the owner on Aug 2, 2022. It is now read-only.

Encountered an error while processing subscription stream #435

Open
advanced4 opened this issue Sep 24, 2020 · 8 comments
Open

Encountered an error while processing subscription stream #435

advanced4 opened this issue Sep 24, 2020 · 8 comments
Assignees
@ktkrg

Comments

@advanced4
Copy link

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
Copy link
Contributor

sendkb commented Sep 24, 2020

Thanks for reporting. We will look into this issue. Possibly related to #363

@ktkrg ktkrg mentioned this issue Nov 20, 2020
Closed
@ktkrg
Copy link
Contributor

ktkrg commented Jan 15, 2021

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

@advanced4
Copy link
Author

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

@TheMeier
Copy link

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
Copy link

TheMeier commented Feb 12, 2021 •
edited
Loading

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
Copy link

ghost commented Apr 6, 2021

I'm also seeing these errors on 1.12.0

@gferrette
Copy link

Hello,

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

@sitler87
Copy link

Some info? Seeing that on latest version as well.

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees

@ktkrg ktkrg

Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
6 participants
@TheMeier @sendkb @advanced4 @gferrette @ktkrg @sitler87