Preventing serialization errors in the nodes stats API by masseyke · Pull Request #90319 · elastic/elasticsearch

masseyke · 2022-09-23T20:17:48Z

On a few occasions we have seen the nodes stats API fail with this (this stack is from 7.14.0, but we have also seen it on higher 7.x versions and 8.x):

[es/i-38/es.log] [2022-08-24T13:32:54,997][WARN ][org.elasticsearch.transport.OutboundHandler] [instance-0000000038] failed to serialize outbound message [Response{46294885}{false}{false}{false}{class org.elasticsearch.action.admin.cluster.stats.ClusterStatsNodeResponse}]
java.lang.IllegalStateException: Negative longs unsupported, use writeLong or writeZLong for negative numbers [-1]
	at org.elasticsearch.common.io.stream.StreamOutput.writeVLong(StreamOutput.java:289) ~[elasticsearch-7.17.5.jar:7.17.5]
	at org.elasticsearch.ingest.IngestStats$Stats.writeTo(IngestStats.java:186) ~[elasticsearch-7.17.5.jar:7.17.5]
	at org.elasticsearch.ingest.IngestStats.writeTo(IngestStats.java:76) ~[elasticsearch-7.17.5.jar:7.17.5]
	at org.elasticsearch.common.io.stream.StreamOutput.writeOptionalWriteable(StreamOutput.java:978) ~[elasticsearch-7.17.5.jar:7.17.5]
	at org.elasticsearch.action.admin.cluster.node.stats.NodeStats.writeTo(NodeStats.java:288) ~[elasticsearch-7.17.5.jar:7.17.5]
	at org.elasticsearch.action.admin.cluster.stats.ClusterStatsNodeResponse.writeTo(ClusterStatsNodeResponse.java:89) ~[elasticsearch-7.17.5.jar:7.17.5]
	at org.elasticsearch.transport.OutboundMessage.serialize(OutboundMessage.java:75) ~[elasticsearch-7.17.5.jar:7.17.5]
	at org.elasticsearch.transport.OutboundHandler.sendMessage(OutboundHandler.java:180) [elasticsearch-7.17.5.jar:7.17.5]
	at org.elasticsearch.transport.OutboundHandler.sendResponse(OutboundHandler.java:145) [elasticsearch-7.17.5.jar:7.17.5]
	at org.elasticsearch.transport.TcpTransportChannel.sendResponse(TcpTransportChannel.java:61) [elasticsearch-7.17.5.jar:7.17.5]
	at org.elasticsearch.transport.TaskTransportChannel.sendResponse(TaskTransportChannel.java:41) [elasticsearch-7.17.5.jar:7.17.5]
	at org.elasticsearch.action.support.nodes.TransportNodesAction$NodeTransportHandler.messageReceived(TransportNodesAction.java:305) [elasticsearch-7.17.5.jar:7.17.5]
	at org.elasticsearch.action.support.nodes.TransportNodesAction$NodeTransportHandler.messageReceived(TransportNodesAction.java:299) [elasticsearch-7.17.5.jar:7.17.5]
	at org.elasticsearch.xpack.security.transport.SecurityServerTransportInterceptor$ProfileSecuredRequestHandler$1.doRun(SecurityServerTransportInterceptor.java:341) [x-pack-security-7.17.5.jar:7.17.5]
	at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:26) [elasticsearch-7.17.5.jar:7.17.5]
	at org.elasticsearch.xpack.security.transport.SecurityServerTransportInterceptor$ProfileSecuredRequestHandler$3.onResponse(SecurityServerTransportInterceptor.java:404) [x-pack-security-7.17.5.jar:7.17.5]
	at org.elasticsearch.xpack.security.transport.SecurityServerTransportInterceptor$ProfileSecuredRequestHandler$3.onResponse(SecurityServerTransportInterceptor.java:394) [x-pack-security-7.17.5.jar:7.17.5]
	at org.elasticsearch.xpack.security.authz.AuthorizationService.authorizeSystemUser(AuthorizationService.java:620) [x-pack-security-7.17.5.jar:7.17.5]
	at org.elasticsearch.xpack.security.authz.AuthorizationService.authorize(AuthorizationService.java:250) [x-pack-security-7.17.5.jar:7.17.5]
	at org.elasticsearch.xpack.security.transport.ServerTransportFilter$NodeProfile.lambda$inbound$1(ServerTransportFilter.java:136) [x-pack-security-7.17.5.jar:7.17.5]
	at org.elasticsearch.action.ActionListener$1.onResponse(ActionListener.java:136) [elasticsearch-7.17.5.jar:7.17.5]
	at org.elasticsearch.action.ActionListener$MappedActionListener.onResponse(ActionListener.java:101) [elasticsearch-7.17.5.jar:7.17.5]
	at org.elasticsearch.xpack.security.authc.AuthenticatorChain.authenticateAsync(AuthenticatorChain.java:102) [x-pack-security-7.17.5.jar:7.17.5]
	at org.elasticsearch.xpack.security.authc.AuthenticationService.authenticate(AuthenticationService.java:199) [x-pack-security-7.17.5.jar:7.17.5]
	at org.elasticsearch.xpack.security.transport.ServerTransportFilter$NodeProfile.inbound(ServerTransportFilter.java:128) [x-pack-security-7.17.5.jar:7.17.5]
	at org.elasticsearch.xpack.security.transport.SecurityServerTransportInterceptor$ProfileSecuredRequestHandler.messageReceived(SecurityServerTransportInterceptor.java:415) [x-pack-security-7.17.5.jar:7.17.5]
	at org.elasticsearch.transport.RequestHandlerRegistry.processMessageReceived(RequestHandlerRegistry.java:67) [elasticsearch-7.17.5.jar:7.17.5]
	at org.elasticsearch.transport.InboundHandler$1.doRun(InboundHandler.java:260) [elasticsearch-7.17.5.jar:7.17.5]
	at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingAbstractRunnable.doRun(ThreadContext.java:777) [elasticsearch-7.17.5.jar:7.17.5]
	at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:26) [elasticsearch-7.17.5.jar:7.17.5]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) [?:?]
	at java.lang.Thread.run(Thread.java:833) [?:?]

The cause is that the ingestCurrent counter has gone below 0, and writeVLong cannot handle negative numbers. The ingestCurrent counter ought to never be below 0. I have not been able to reproduce this despite trying a lot of things. I believe that the only way that this could happen (before 7.17.2 anyway) is if a processor's listener is called more than once, since the counter is always incremented before the processor is run, and then decremented once in the processor's listener. Unfortunately I have not been able to find any place where a listener is called more than once, and there are hundreds of listener uses we would need to go through. Since I have not found the root cause, this PR is meant to detect and prevent the serialization problem, and to log the stack trace when it is found (so that we can potentially find the root cause(s)).
Closes #77973
Related #84838

elasticsearchmachine · 2022-09-23T20:18:12Z

Pinging @elastic/es-data-management (Team:Data Management)

elasticsearchmachine · 2022-09-23T20:18:13Z

Hi @masseyke, I've created a changelog YAML for you.

elasticsearchmachine · 2022-09-23T20:22:14Z

Hi @masseyke, I've updated the changelog YAML for you.

masseyke · 2022-09-23T21:47:14Z

@elasticmachine run elasticsearch-ci/part-1

server/src/main/java/org/elasticsearch/ingest/IngestMetric.java

masseyke · 2022-09-26T16:52:49Z

@elasticmachine run elasticsearch-ci/bwc

masseyke · 2022-09-26T17:17:52Z

@elasticmachine update branch

joegallo · 2022-09-27T14:39:30Z

Anything else you'd like to see here @DaveCTurner? It LGTM, but I don't want to front run your ✅ if there's something else you'd like to see.

DaveCTurner

No, nothing more from me, I was just passing through 😁

Preventing serialization errors in the nodes stats API, and adding logging to the ingest counter code so that we can find the root cause of the problem in the future.

elasticsearchmachine · 2022-09-27T20:41:49Z

💔 Backport failed

Status	Branch	Result
✅	8.5
❌	7.17	Commit could not be cherrypicked due to conflicts
✅	8.4

You can use sqren/backport to manually backport by running backport --upstream elastic/elasticsearch --pr 90319

Preventing serialization errors in the nodes stats API, and adding logging to the ingest counter code so that we can find the root cause of the problem in the future.

Preventing serialization errors in the nodes stats API, and adding logging to the ingest counter code so that we can find the root cause of the problem in the future. Co-authored-by: Elastic Machine <elasticmachine@users.noreply.github.com>

…c#90319)

#90466)

* Update docs for v8.4.3 release * Update release highlights for 8.4.3 version. * Update docs/reference/release-notes/8.4.3.asciidoc Co-authored-by: Adam Locke <adam.locke@elastic.co> * Update docs/reference/release-notes/8.4.3.asciidoc Co-authored-by: Adam Locke <adam.locke@elastic.co> * Update docs/reference/release-notes/highlights.asciidoc Co-authored-by: Adam Locke <adam.locke@elastic.co> * Make link external type * Update release notes to include #90319 PR after creating BC2. * Remove release note for #90302 * Minor grammar fix Co-authored-by: Adam Locke <adam.locke@elastic.co>

* Update docs for v8.4.3 release * Update release highlights for 8.4.3 version. * Update docs/reference/release-notes/8.4.3.asciidoc Co-authored-by: Adam Locke <adam.locke@elastic.co> * Update docs/reference/release-notes/8.4.3.asciidoc Co-authored-by: Adam Locke <adam.locke@elastic.co> * Update docs/reference/release-notes/highlights.asciidoc Co-authored-by: Adam Locke <adam.locke@elastic.co> * Make link external type * Update release notes to include elastic#90319 PR after creating BC2. * Remove release note for elastic#90302 * Minor grammar fix Co-authored-by: Adam Locke <adam.locke@elastic.co> (cherry picked from commit 25a196f) # Conflicts: # docs/reference/release-notes.asciidoc # docs/reference/release-notes/highlights.asciidoc

* Update docs for v8.4.3 release * Update release highlights for 8.4.3 version. * Update docs/reference/release-notes/8.4.3.asciidoc Co-authored-by: Adam Locke <adam.locke@elastic.co> * Update docs/reference/release-notes/8.4.3.asciidoc Co-authored-by: Adam Locke <adam.locke@elastic.co> * Update docs/reference/release-notes/highlights.asciidoc Co-authored-by: Adam Locke <adam.locke@elastic.co> * Make link external type * Update release notes to include #90319 PR after creating BC2. * Remove release note for #90302 * Minor grammar fix Co-authored-by: Adam Locke <adam.locke@elastic.co> (cherry picked from commit 25a196f) # Conflicts: # docs/reference/release-notes.asciidoc # docs/reference/release-notes/highlights.asciidoc Co-authored-by: Slobodan Adamović <slobodanadamovic@users.noreply.github.com>

Preventing serialization errors in the nodes stats API, and adding logging to the ingest counter code so that we can find the root cause of the problem in the future.

Preventing serialization errors in the nodes stats API

7920024

masseyke added >bug :Distributed/Ingest Node Execution or management of Ingest Pipelines v8.5.0 v7.17.7 v8.6.0 labels Sep 23, 2022

elasticsearchmachine added the Team:Data Management (obsolete) DO NOT USE. This team no longer exists. label Sep 23, 2022

Update docs/changelog/90319.yaml

30c9d83

Update docs/changelog/90319.yaml

b0ce826

masseyke requested a review from joegallo September 23, 2022 20:23

DaveCTurner reviewed Sep 24, 2022

View reviewed changes

server/src/main/java/org/elasticsearch/ingest/IngestMetric.java Show resolved Hide resolved

Never reporting a negative ingest current

58f84bd

masseyke requested a review from DaveCTurner September 26, 2022 13:34

Merge branch 'main' into fix/prevent-serialization-error

11cee2f

DaveCTurner approved these changes Sep 27, 2022

View reviewed changes

masseyke added auto-backport-and-merge v8.4.3 labels Sep 27, 2022

masseyke merged commit e21be6e into elastic:main Sep 27, 2022

masseyke deleted the fix/prevent-serialization-error branch September 27, 2022 20:40

masseyke mentioned this pull request Sep 27, 2022

[8.5] Preventing serialization errors in the nodes stats API (#90319) #90429

Merged

masseyke mentioned this pull request Sep 27, 2022

[8.4] Preventing serialization errors in the nodes stats API (#90319) #90430

Merged

masseyke added a commit to masseyke/elasticsearch that referenced this pull request Sep 28, 2022

[7.17] Preventing serialization errors in the nodes stats API (elasti…

b1bbba1

…c#90319)

masseyke mentioned this pull request Sep 28, 2022

[7.17] Preventing serialization errors in the nodes stats API (#90319) #90466

Merged

elasticsearchmachine pushed a commit that referenced this pull request Sep 28, 2022

[7.17] Preventing serialization errors in the nodes stats API (#90319) (

2e24da1

#90466)

slobodanadamovic added a commit to slobodanadamovic/elasticsearch that referenced this pull request Sep 29, 2022

Update release notes to include elastic#90319 PR after creating BC2.

6ffb31f

slobodanadamovic mentioned this pull request Sep 29, 2022

[Doc] Release notes for v8.4.3 #90443

Merged

This was referenced Nov 8, 2022

Improving logging to troubleshoot pipeline metrics problem #91439

Merged

Catching exceptions to prevent ingest listeners from being called multiple times #91475

Closed

masseyke mentioned this pull request Nov 16, 2022

Improving logging to troubelshoot pipeline metrics problem (#91439) #91627

Merged

joegallo mentioned this pull request Nov 29, 2022

Drop the ingest listener call count tracking #92003

Merged

BBQigniter mentioned this pull request Dec 7, 2022

Nodes stats API CPU usage value is -1 #91940

Closed

predogma mentioned this pull request Sep 7, 2023

Node is unable to join the cluster due to negative version in composable index template #98652

Open

joegallo mentioned this pull request Jan 30, 2024

Tighten up exception handling around markItemAsDropped/markItemAsFailed #104931

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Preventing serialization errors in the nodes stats API#90319

Preventing serialization errors in the nodes stats API#90319
masseyke merged 5 commits intoelastic:mainfrom
masseyke:fix/prevent-serialization-error

masseyke commented Sep 23, 2022 •

edited

Loading

Uh oh!

elasticsearchmachine commented Sep 23, 2022

Uh oh!

elasticsearchmachine commented Sep 23, 2022

Uh oh!

elasticsearchmachine commented Sep 23, 2022

Uh oh!

masseyke commented Sep 23, 2022

Uh oh!

Uh oh!

masseyke commented Sep 26, 2022

Uh oh!

masseyke commented Sep 26, 2022

Uh oh!

joegallo commented Sep 27, 2022

Uh oh!

DaveCTurner left a comment

Uh oh!

elasticsearchmachine commented Sep 27, 2022

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

5 participants

Conversation

masseyke commented Sep 23, 2022 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

elasticsearchmachine commented Sep 23, 2022

Uh oh!

elasticsearchmachine commented Sep 23, 2022

Uh oh!

elasticsearchmachine commented Sep 23, 2022

Uh oh!

masseyke commented Sep 23, 2022

Uh oh!

Uh oh!

masseyke commented Sep 26, 2022

Uh oh!

masseyke commented Sep 26, 2022

Uh oh!

joegallo commented Sep 27, 2022

Uh oh!

DaveCTurner left a comment

Choose a reason for hiding this comment

Uh oh!

elasticsearchmachine commented Sep 27, 2022

💔 Backport failed

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

5 participants

masseyke commented Sep 23, 2022 •

edited

Loading