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

Unexpected exception thrown for java.lang.NullPointerException #1713

Closed
q9f opened this issue May 2, 2020 · 3 comments · Fixed by #1734
Closed

Unexpected exception thrown for java.lang.NullPointerException #1713

q9f opened this issue May 2, 2020 · 3 comments · Fixed by #1734
Assignees
@mbaxter

Comments

@q9f
Copy link
Contributor

q9f commented May 2, 2020 •
edited
Loading

Description

On Schlesi, the client tells me to report the following exception after the sync seemingly completed:

13:36:24.118 FATAL - PLEASE FIX OR REPORT | Unexpected exception thrown for java.lang.NullPointerException: event 'interface tech.pegasys.artemis.validator.api.ValidatorApiChannel.getDuties' in handler 'tech.pegasys.artemis.validator.coordinator.ValidatorApiHandler'
java.lang.NullPointerException: null
	at tech.pegasys.artemis.storage.client.CombinedChainDataClient.getStateAtSlot(CombinedChainDataClient.java:204) ~[artemis-storage-0.11.0-SNAPSHOT.jar:0.11.0-dev-e8d96cf0]

Steps to Reproduce (Bug)

  1. Build Teku latest master
  2. Configure for Schlesi https://github.com/goerli/schlesi
  3. Connect to a local node
  4. Wait for a full sync to complete

Expected behavior:

Run Smoothly.

Actual behavior:

Runtime Exception:

13:35:48.116 INFO  - Sync Event *** Current slot: 36479, Head block: 35705, Connected peers: 2
13:36:00.116 INFO  - Sync Event *** Current slot: 36480, Head block: 35919, Connected peers: 2
13:36:12.116 INFO  - Sync Event *** Current slot: 36481, Head block: 36132, Connected peers: 2
13:36:24.118 FATAL - PLEASE FIX OR REPORT | Unexpected exception thrown for java.lang.NullPointerException: event 'interface tech.pegasys.artemis.validator.api.ValidatorApiChannel.getDuties' in handler 'tech.pegasys.artemis.validator.coordinator.ValidatorApiHandler'
java.lang.NullPointerException: null
	at tech.pegasys.artemis.storage.client.CombinedChainDataClient.getStateAtSlot(CombinedChainDataClient.java:204) ~[artemis-storage-0.11.0-SNAPSHOT.jar:0.11.0-dev-e8d96cf0]
	at tech.pegasys.artemis.storage.client.CombinedChainDataClient.lambda$getStateAtSlot$6(CombinedChainDataClient.java:180) ~[artemis-storage-0.11.0-SNAPSHOT.jar:0.11.0-dev-e8d96cf0]
	at java.util.Optional.map(Optional.java:258) ~[?:?]
	at tech.pegasys.artemis.storage.client.CombinedChainDataClient.getStateAtSlot(CombinedChainDataClient.java:180) ~[artemis-storage-0.11.0-SNAPSHOT.jar:0.11.0-dev-e8d96cf0]
	at tech.pegasys.artemis.validator.coordinator.ValidatorApiHandler.getDuties(ValidatorApiHandler.java:112) ~[artemis-validator-coordinator-0.11.0-SNAPSHOT.jar:0.11.0-dev-e8d96cf0]
	at jdk.internal.reflect.GeneratedMethodAccessor7.invoke(Unknown Source) ~[?:?]
	at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
	at java.lang.reflect.Method.invoke(Method.java:567) ~[?:?]
	at tech.pegasys.artemis.events.DirectEventDeliverer.executeMethod(DirectEventDeliverer.java:67) ~[artemis-events-0.11.0-SNAPSHOT.jar:0.11.0-dev-e8d96cf0]
	at tech.pegasys.artemis.events.DirectEventDeliverer.deliverToWithResponse(DirectEventDeliverer.java:60) ~[artemis-events-0.11.0-SNAPSHOT.jar:0.11.0-dev-e8d96cf0]
	at tech.pegasys.artemis.events.AsyncEventDeliverer.lambda$deliverToWithResponse$1(AsyncEventDeliverer.java:70) ~[artemis-events-0.11.0-SNAPSHOT.jar:0.11.0-dev-e8d96cf0]
	at tech.pegasys.artemis.events.AsyncEventDeliverer$QueueReader.deliverNextEvent(AsyncEventDeliverer.java:111) [artemis-events-0.11.0-SNAPSHOT.jar:0.11.0-dev-e8d96cf0]
	at tech.pegasys.artemis.events.AsyncEventDeliverer$QueueReader.run(AsyncEventDeliverer.java:103) [artemis-events-0.11.0-SNAPSHOT.jar:0.11.0-dev-e8d96cf0]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
	at java.lang.Thread.run(Thread.java:830) [?:?]
13:36:24.122 FATAL - PLEASE FIX OR REPORT | Unexpected exception thrown for java.lang.NullPointerException: event 'interface tech.pegasys.artemis.validator.api.ValidatorApiChannel.getDuties' in handler 'tech.pegasys.artemis.validator.coordinator.ValidatorApiHandler'
java.lang.NullPointerException: null
	at tech.pegasys.artemis.storage.client.CombinedChainDataClient.getStateAtSlot(CombinedChainDataClient.java:204) ~[artemis-storage-0.11.0-SNAPSHOT.jar:0.11.0-dev-e8d96cf0]
	at tech.pegasys.artemis.storage.client.CombinedChainDataClient.lambda$getStateAtSlot$6(CombinedChainDataClient.java:180) ~[artemis-storage-0.11.0-SNAPSHOT.jar:0.11.0-dev-e8d96cf0]
	at java.util.Optional.map(Optional.java:258) ~[?:?]
	at tech.pegasys.artemis.storage.client.CombinedChainDataClient.getStateAtSlot(CombinedChainDataClient.java:180) ~[artemis-storage-0.11.0-SNAPSHOT.jar:0.11.0-dev-e8d96cf0]
	at tech.pegasys.artemis.validator.coordinator.ValidatorApiHandler.getDuties(ValidatorApiHandler.java:112) ~[artemis-validator-coordinator-0.11.0-SNAPSHOT.jar:0.11.0-dev-e8d96cf0]
	at jdk.internal.reflect.GeneratedMethodAccessor7.invoke(Unknown Source) ~[?:?]
	at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
	at java.lang.reflect.Method.invoke(Method.java:567) ~[?:?]
	at tech.pegasys.artemis.events.DirectEventDeliverer.executeMethod(DirectEventDeliverer.java:67) ~[artemis-events-0.11.0-SNAPSHOT.jar:0.11.0-dev-e8d96cf0]
	at tech.pegasys.artemis.events.DirectEventDeliverer.deliverToWithResponse(DirectEventDeliverer.java:60) ~[artemis-events-0.11.0-SNAPSHOT.jar:0.11.0-dev-e8d96cf0]
	at tech.pegasys.artemis.events.AsyncEventDeliverer.lambda$deliverToWithResponse$1(AsyncEventDeliverer.java:70) ~[artemis-events-0.11.0-SNAPSHOT.jar:0.11.0-dev-e8d96cf0]
	at tech.pegasys.artemis.events.AsyncEventDeliverer$QueueReader.deliverNextEvent(AsyncEventDeliverer.java:111) [artemis-events-0.11.0-SNAPSHOT.jar:0.11.0-dev-e8d96cf0]
	at tech.pegasys.artemis.events.AsyncEventDeliverer$QueueReader.run(AsyncEventDeliverer.java:103) [artemis-events-0.11.0-SNAPSHOT.jar:0.11.0-dev-e8d96cf0]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
	at java.lang.Thread.run(Thread.java:830) [?:?]
13:36:27.262 FATAL - PLEASE FIX OR REPORT | Unexpected exception thrown for java.lang.NullPointerException: event 'interface tech.pegasys.artemis.validator.api.ValidatorApiChannel.getDuties' in handler 'tech.pegasys.artemis.validator.coordinator.ValidatorApiHandler'
java.lang.NullPointerException: null
	at tech.pegasys.artemis.storage.client.CombinedChainDataClient.getStateAtSlot(CombinedChainDataClient.java:204) ~[artemis-storage-0.11.0-SNAPSHOT.jar:0.11.0-dev-e8d96cf0]
	at tech.pegasys.artemis.storage.client.CombinedChainDataClient.lambda$getStateAtSlot$6(CombinedChainDataClient.java:180) ~[artemis-storage-0.11.0-SNAPSHOT.jar:0.11.0-dev-e8d96cf0]
	at java.util.Optional.map(Optional.java:258) ~[?:?]
	at tech.pegasys.artemis.storage.client.CombinedChainDataClient.getStateAtSlot(CombinedChainDataClient.java:180) ~[artemis-storage-0.11.0-SNAPSHOT.jar:0.11.0-dev-e8d96cf0]
	at tech.pegasys.artemis.validator.coordinator.ValidatorApiHandler.getDuties(ValidatorApiHandler.java:112) ~[artemis-validator-coordinator-0.11.0-SNAPSHOT.jar:0.11.0-dev-e8d96cf0]
	at jdk.internal.reflect.GeneratedMethodAccessor7.invoke(Unknown Source) ~[?:?]
	at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
	at java.lang.reflect.Method.invoke(Method.java:567) ~[?:?]
	at tech.pegasys.artemis.events.DirectEventDeliverer.executeMethod(DirectEventDeliverer.java:67) ~[artemis-events-0.11.0-SNAPSHOT.jar:0.11.0-dev-e8d96cf0]
	at tech.pegasys.artemis.events.DirectEventDeliverer.deliverToWithResponse(DirectEventDeliverer.java:60) ~[artemis-events-0.11.0-SNAPSHOT.jar:0.11.0-dev-e8d96cf0]
	at tech.pegasys.artemis.events.AsyncEventDeliverer.lambda$deliverToWithResponse$1(AsyncEventDeliverer.java:70) ~[artemis-events-0.11.0-SNAPSHOT.jar:0.11.0-dev-e8d96cf0]
	at tech.pegasys.artemis.events.AsyncEventDeliverer$QueueReader.deliverNextEvent(AsyncEventDeliverer.java:111) [artemis-events-0.11.0-SNAPSHOT.jar:0.11.0-dev-e8d96cf0]
	at tech.pegasys.artemis.events.AsyncEventDeliverer$QueueReader.run(AsyncEventDeliverer.java:103) [artemis-events-0.11.0-SNAPSHOT.jar:0.11.0-dev-e8d96cf0]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
	at java.lang.Thread.run(Thread.java:830) [?:?]
13:36:27.264 FATAL - PLEASE FIX OR REPORT | Unexpected exception thrown for java.lang.NullPointerException: event 'interface tech.pegasys.artemis.validator.api.ValidatorApiChannel.getDuties' in handler 'tech.pegasys.artemis.validator.coordinator.ValidatorApiHandler'
java.lang.NullPointerException: null
	at tech.pegasys.artemis.storage.client.CombinedChainDataClient.getStateAtSlot(CombinedChainDataClient.java:204) ~[artemis-storage-0.11.0-SNAPSHOT.jar:0.11.0-dev-e8d96cf0]
	at tech.pegasys.artemis.storage.client.CombinedChainDataClient.lambda$getStateAtSlot$6(CombinedChainDataClient.java:180) ~[artemis-storage-0.11.0-SNAPSHOT.jar:0.11.0-dev-e8d96cf0]
	at java.util.Optional.map(Optional.java:258) ~[?:?]
	at tech.pegasys.artemis.storage.client.CombinedChainDataClient.getStateAtSlot(CombinedChainDataClient.java:180) ~[artemis-storage-0.11.0-SNAPSHOT.jar:0.11.0-dev-e8d96cf0]
	at tech.pegasys.artemis.validator.coordinator.ValidatorApiHandler.getDuties(ValidatorApiHandler.java:112) ~[artemis-validator-coordinator-0.11.0-SNAPSHOT.jar:0.11.0-dev-e8d96cf0]
	at jdk.internal.reflect.GeneratedMethodAccessor7.invoke(Unknown Source) ~[?:?]
	at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
	at java.lang.reflect.Method.invoke(Method.java:567) ~[?:?]
	at tech.pegasys.artemis.events.DirectEventDeliverer.executeMethod(DirectEventDeliverer.java:67) ~[artemis-events-0.11.0-SNAPSHOT.jar:0.11.0-dev-e8d96cf0]
	at tech.pegasys.artemis.events.DirectEventDeliverer.deliverToWithResponse(DirectEventDeliverer.java:60) ~[artemis-events-0.11.0-SNAPSHOT.jar:0.11.0-dev-e8d96cf0]
	at tech.pegasys.artemis.events.AsyncEventDeliverer.lambda$deliverToWithResponse$1(AsyncEventDeliverer.java:70) ~[artemis-events-0.11.0-SNAPSHOT.jar:0.11.0-dev-e8d96cf0]
	at tech.pegasys.artemis.events.AsyncEventDeliverer$QueueReader.deliverNextEvent(AsyncEventDeliverer.java:111) [artemis-events-0.11.0-SNAPSHOT.jar:0.11.0-dev-e8d96cf0]
	at tech.pegasys.artemis.events.AsyncEventDeliverer$QueueReader.run(AsyncEventDeliverer.java:103) [artemis-events-0.11.0-SNAPSHOT.jar:0.11.0-dev-e8d96cf0]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
	at java.lang.Thread.run(Thread.java:830) [?:?]
13:36:28.116 INFO  - Slot Event *** Slot: 36482, Block:  x ... empty, Epoch: 1140, Finalized Epoch: 1133, Finalized Root: 0xa9b1..ca36
13:36:40.116 INFO  - Slot Event *** Slot: 36483, Block:  x ... empty, Epoch: 1140, Finalized Epoch: 1133, Finalized Root: 0xa9b1..ca36
13:36:52.116 INFO  - Slot Event *** Slot: 36484, Block:  x ... empty, Epoch: 1140, Finalized Epoch: 1133, Finalized Root: 0xa9b1..ca36

Note how finalized epoch is lacking behind (even though the chain is finalized at 1138) and the blocks are empty (even though they aren't).

Frequency:

1 - Only did one full sync so far.

Versions (Add all that apply)

  • Software version: teku/v0.11.0-dev-e8d96cf0/linux-x86_64/-na-openjdk64bitservervm-java-13
  • Java version: openjdk version "13.0.2" 2020-01-14
  • OS Name & Version: Arch Linux
  • Kernel Version: Linux intan 5.6.5-arch3-1 First commit. #1 SMP PREEMPT Sun, 19 Apr 2020 13:14:25 +0000 x86_64 GNU/Linux
@q9f q9f mentioned this issue May 3, 2020
Merged
@ajsutton
Copy link
Contributor

ajsutton commented May 6, 2020

Thanks for reporting this, sorry for the delay in getting back to you.

The sync will be "completing" early because Teku doesn't yet support snappy compression for gossip so isn't receiving any gossiped blocks. So we sync up to the status peers reported when they first connected and stop, thinking that we've got all the available blocks. #1722 will help with that, though there appears to be something else preventing us from getting gossip just yet.

If you're not running any validators, #1724 may wind up silencing the errors but the underlying issue appears to be that the head block root doesn't appear to have a matching state in the store. That shouldn't be possible and we're currently investigating how it happens.

@mbaxter mbaxter self-assigned this May 6, 2020
@mbaxter
Copy link
Contributor

mbaxter commented May 6, 2020

Looks like these errors are related to: #1730

Working on a comprehensive fix.

@mbaxter mbaxter mentioned this issue May 12, 2020
Merged
@mbaxter
Copy link
Contributor

mbaxter commented May 14, 2020

Fixed by: #1734

@mbaxter mbaxter closed this as completed May 14, 2020
@ajsutton ajsutton mentioned this issue May 27, 2020
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@mbaxter mbaxter

Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

[BC-415] Rework CombinedChainDataClient.getStateAtSlot() mbaxter/teku
3 participants
@ajsutton @mbaxter @q9f