Skip to content
This repository has been archived by the owner on Jan 22, 2025. It is now read-only.

Program account notifications are not sent for every confirmed block #18587

Closed
Arrowana opened this issue Jul 11, 2021 · 14 comments
Closed

Program account notifications are not sent for every confirmed block #18587

Arrowana opened this issue Jul 11, 2021 · 14 comments
Assignees
Milestone

Comments

@Arrowana
Copy link
Contributor

Arrowana commented Jul 11, 2021

Problem

It appears that programSubscribe often drops notifications.

Code snippet to reproduce: https://github.com/Arrowana/sol-rpc-race-example
It listens to the stake program for Authorized staker being the Keypair pubKey,
in a loop it sends a transaction to create a new stake account being the Authorized staker and withdrawer on a new account.

Example on mainnet-beta, it was notified "received" for a few created stake accounts but then dropped a few other:

received 1 BrXRZDA3acbRwYdve1T9sijhUmxNQ28GsZpx2aAio4EW
Sent 1
received 2 HFXDJQdJqovNxX5cA56A1XGPuiNTiUdyenstEfsAK6yF
Sent 2
Sent 3
received 4 2ztWtqFwoRVY2g6CjKUC63Yv7dtvMPxUu92CUPiQy3FG
Sent 4
Sent 5
received 6 2HvLYWYoXwYuzaeDKWXWr5ZUoC5vNXe6DcuEhjjwokPh
Sent 6

devnet: seems to notify of every single new program account without any problem
testnet: even more unreliable

Note: I tried removing the filter and it does not help, it still drops the expected transactions

Proposed Solution

TBD

@jstarry
Copy link
Contributor

jstarry commented Jul 17, 2021

This is probably not limited to program account subscriptions, but there are occasionally confirmed slots with program account changes which do not emit any notifications. I used a modified version of @Arrowana's demo which produced the below behavior on testnet and clearly shows that the confirmed slot 85270792 should have emitted notifications but didn't.

Received notifications:

received 3 FLDzc4FxDAZdLT1fFjDnxb9iW7x7XmDspnwi4EQXVmbj: 85270787
received 11 8GMYKN9K6tGazLbS2EYSRRTJr1kiwc4EzTa7aP3Dux5D: 85270793
received 12 7g3aWPmpW5e97rjrXsfDthj1Y3sJgsyyRvK8jqG2Eok5: 85270793
received 13 5LwXst2gCMWAPbcWuwCzgEsWAMVHnV7QiGkBbWxBGFCB: 85270794

Confirmed transactions:

Sent 3: (85270787) https://explorer.solana.com/tx/bAHtLSXDFsbG9U4L3ragPT1RPY4vGGZnQPkM9Ybf3JN2W7qpWwCBQ9p5wh3wMP5cGmuyZg7dvRN3QnpwwTinH2w?cluster=testnet
Sent 4: (85270792) https://explorer.solana.com/tx/3cjvJ9V5NZEQDjkB1vDbTpJNrZXeMcKJ23t3rbhUwnuG6qvh3tSomQUHwgob8sBNzYFN6TNy6SMk7uEfooknUgEv?cluster=testnet
Sent 5: (85270792) https://explorer.solana.com/tx/5X9x8c6x2xb3TMtvSrtSh8wMP3HSRZ7vfPUha5zn7mt92NtVX2CeSqnZ4WGZ8A13aZTPbSCEfhFPyhCmQXAPLvou?cluster=testnet
Sent 6: (85270792) https://explorer.solana.com/tx/gp4qh53e3gaeCozBAnbyfaZyRmn5Mpgth7TLwxHUzwfE6yKXRn4ZXDZdmg8qu51Lz3bUeoeqCvV5j9a9HgACLyC?cluster=testnet
Sent 7: (85270792) https://explorer.solana.com/tx/24BRdQG9B81iax2tFk8LiKKtAcfaQY5Xd7bbLSmjHa2yuJ8ksds7dWa3gFXMf61SYtkx136pBAvBgNg2T9GGR3xy?cluster=testnet
Sent 8: (85270792) https://explorer.solana.com/tx/5Z44T5RMS3zVHvmPvXDpqjaCnqMiapr4CJ3bu3qDbvomyx4PYkKxpyuVQX4Guhzd8tyV1gvpwn7N7Zt2JbbMoeKA?cluster=testnet
Sent 9: (85270792) https://explorer.solana.com/tx/3i33GwiLr4FBke4SZTE6ntVSEFXuiiUNpV4tGTjrCMe2pt3fm3XAwvxk6hHDM6MdABqn8MtyMV1Cj95rn8nCeUe8?cluster=testnet
Sent 10: (85270792) https://explorer.solana.com/tx/248ANSt71sd3H9VqSy39oQ88tbx9xyLHc9skY9hszckwQLsWkUeY1RQqVagWLM6dkNzJYFYn9gBffXbpGXVfWuFf?cluster=testnet
Sent 11: (85270793) https://explorer.solana.com/tx/26YpMBM3fx2vrfMg3kU1tavrwWjYnRXSiukxMf4wXsmtzRWobCqH12fD3gqvLPyeWbDmUboUvyCxLy4xGWcGk2MG?cluster=testnet
Sent 12: (85270793) https://explorer.solana.com/tx/3h9auJgFCb4kKRRNgDLHMmz6ipnzvc5HAwEWES9ED7b4m9ztSs2EP5Miui737h327eMSzZPdXRh1gYetXnWCx9Kk?cluster=testnet
Sent 13: (85270794) https://explorer.solana.com/tx/25MtQ5vNbyiRkoU9P1bqhQw2FJZ1dJLZAbeUrBQh3Wuht1XHdz5j12d1YUS9ocfAEMRQZ82ZRmqfMoFLuHKwbydB?cluster=testnet

@jstarry jstarry added this to the v1.7.4 milestone Jul 17, 2021
@jstarry
Copy link
Contributor

jstarry commented Jul 17, 2021

@CriesofCarrots do you have bandwidth to pick this up next week?

@jstarry jstarry changed the title web3.js or programSubscribe drops notifications Program account notifications are not sent for every confirmed block Jul 17, 2021
@jstarry
Copy link
Contributor

jstarry commented Jul 17, 2021

Thanks for the report and the helpful example @Arrowana!

@ghost
Copy link

ghost commented Jul 21, 2021

Chiming in to share that we're seeing the same, incredibly-unreliable events coming into our logsSubscribe subscriptions. I filed an issue for that here: #18827. But I suspect it is related. I'd consider this a pretty high priority issue.

@jstarry
Copy link
Contributor

jstarry commented Jul 22, 2021

@SkynetCapital if you can confirm whether the log events are unreliable in the same way as I described above, that would be really helpful! You could confirm by checking if all logs are received for some slots, but no logs are received for other slots. Thanks!

@ghost
Copy link

ghost commented Jul 22, 2021

@SkynetCapital if you can confirm whether the log events are unreliable in the same way as I described above, that would be really helpful! You could confirm by checking if all logs are received for some slots, but no logs are received for other slots. Thanks!

Sure thing, I'll need a little work to return the slot from the response in my code. In the mean time, I ran this test which listened to my recipient pubkey with logsSubscribe, and sent 100 lamports every 3 seconds. Only 4 events were returned out of 9 unique TXes. But I'll try to get a more scientific log, using the slots. After the 10 (9 unique) transfers were completed, the thread stayed open for another minute or two with no responses (in case the end of the log seems abrupt). Now I'm not fully ruling out an issue with the client implementation, but there is little explanation for why half would work, from the client-side. I breakpointed pretty deep and the websocket was getting no messages, leading me to believe it's not the client.

Also feel free to disregard the class/method names in the Logger, just re-used this test.

INFO: Websocket connection opened
Jul 21, 2021 9:19:33 PM MangoTest subscribeToLiquidations
INFO: Send 100 lamports, TXID = cRmoyX6cxDdKwBSdWoGKhbaQqDtibdi9ouPkzwWREcQt7jLnHkBn9eoMHFwaWivjtqGNJUcr7MqYYQViBRB5rbp
Jul 21, 2021 9:19:36 PM MangoTest subscribeToLiquidations
INFO: Send 100 lamports, TXID = 42zjEYPke19E3vb8CkkuPa9LjyVF7cyCAMGPCYRMTEdvyp2S9Zht6T5Wzx4xejuQo6gv8LWRAATyEADd1JzKnwVQ
Jul 21, 2021 9:19:37 PM ch.openserum.mango.listener.LiquidationListener onNotificationEvent
INFO: Event detected
Jul 21, 2021 9:19:37 PM ch.openserum.mango.listener.LiquidationListener onNotificationEvent
INFO: logsSubscribe received TXID = cRmoyX6cxDdKwBSdWoGKhbaQqDtibdi9ouPkzwWREcQt7jLnHkBn9eoMHFwaWivjtqGNJUcr7MqYYQViBRB5rbp
Jul 21, 2021 9:19:40 PM MangoTest subscribeToLiquidations
INFO: Send 100 lamports, TXID = 5Nj2NWLNmKfdbQhP8iFJNbgqxoynZ1JGjEmgQYbWpPfFvJb72YLhvAzx6UwPwB7YynhykvscTexwYGCkXSzAauhF
Jul 21, 2021 9:19:40 PM ch.openserum.mango.listener.LiquidationListener onNotificationEvent
INFO: Event detected
Jul 21, 2021 9:19:40 PM ch.openserum.mango.listener.LiquidationListener onNotificationEvent
INFO: logsSubscribe received TXID = 42zjEYPke19E3vb8CkkuPa9LjyVF7cyCAMGPCYRMTEdvyp2S9Zht6T5Wzx4xejuQo6gv8LWRAATyEADd1JzKnwVQ
Jul 21, 2021 9:19:43 PM MangoTest subscribeToLiquidations
INFO: Send 100 lamports, TXID = DsCPLTWzKcG85zJap9aNBzgmDhd8qHXPvD5aXpMCNsVxtAF98YgkFa2EzXuujnLTyEnU7KJFJ27N4Mx96zKAoKJ
Jul 21, 2021 9:19:46 PM MangoTest subscribeToLiquidations
INFO: Send 100 lamports, TXID = 21voiWjiSEgXhHQ7kD9Ps5bwGcSfcb6eSDmJFufeoN5ignz9zeogUEEGCQ1XbRWx3vCgbFnvN9FyqEaiwf7BL7Ut
Jul 21, 2021 9:19:49 PM MangoTest subscribeToLiquidations
INFO: Send 100 lamports, TXID = bQAxpe8Yf7a76vMsXPzyJ62GRuHTy2Bx45BVJ38V2DcTqcXDy35BvhreFaRKBqwDE5K7VszhJ9QZH7hpPZKLKBY
Jul 21, 2021 9:19:51 PM ch.openserum.mango.listener.LiquidationListener onNotificationEvent
INFO: Event detected
Jul 21, 2021 9:19:51 PM ch.openserum.mango.listener.LiquidationListener onNotificationEvent
INFO: logsSubscribe received TXID = 21voiWjiSEgXhHQ7kD9Ps5bwGcSfcb6eSDmJFufeoN5ignz9zeogUEEGCQ1XbRWx3vCgbFnvN9FyqEaiwf7BL7Ut
Jul 21, 2021 9:19:53 PM MangoTest subscribeToLiquidations
INFO: Send 100 lamports, TXID = bQAxpe8Yf7a76vMsXPzyJ62GRuHTy2Bx45BVJ38V2DcTqcXDy35BvhreFaRKBqwDE5K7VszhJ9QZH7hpPZKLKBY
Jul 21, 2021 9:19:56 PM MangoTest subscribeToLiquidations
INFO: Send 100 lamports, TXID = 2hzE9hMbZyxDoj4gbwoKQkmKjhK3zdZJct5XK8FASpedRJ7FTTLV4sAU49uQGykp2kjcLrZhBm3E6FZ9tNav6deZ
Jul 21, 2021 9:19:57 PM ch.openserum.mango.listener.LiquidationListener onNotificationEvent
INFO: Event detected
Jul 21, 2021 9:19:57 PM ch.openserum.mango.listener.LiquidationListener onNotificationEvent
INFO: logsSubscribe received TXID = bQAxpe8Yf7a76vMsXPzyJ62GRuHTy2Bx45BVJ38V2DcTqcXDy35BvhreFaRKBqwDE5K7VszhJ9QZH7hpPZKLKBY
Jul 21, 2021 9:19:59 PM MangoTest subscribeToLiquidations
INFO: Send 100 lamports, TXID = SZ574WjF1CVf4XkJ1voJoMNPioWwMLghTdDduxmKcDXHsGmG6MXTb5uADaHBBfiFJMSx1Qdh9jeCN5S23mUBdvx
Jul 21, 2021 9:20:03 PM MangoTest subscribeToLiquidations
INFO: Send 100 lamports, TXID = 5dH7rPcC1Pxu3y6xtC1dzQtfz3XedNtA3Xx9XZcveKaCMYSzNtf8Wjou2RCd5jQBEByAJaFgq1MnmYKRg4be1Vp

@sakridge
Copy link
Contributor

cc @lijunwangs

@lijunwangs lijunwangs self-assigned this Jul 28, 2021
@lijunwangs
Copy link
Contributor

Looking into this. @Arrowana for the missing notifications for your subscriptions, do you know if the validator was running during when you were expecting the notifications?

@jstarry
Copy link
Contributor

jstarry commented Jul 28, 2021

@lijunwangs I confirmed this behaviour and my validator was definitely running the whole time 😝

@lijunwangs
Copy link
Contributor

Thanks for confirming that. Runtime issue then.

@leofisG
Copy link

leofisG commented Jul 30, 2021

We have experienced similar issues when using the ProgramSubscribe end point via wss. We can reproduce the issue in both rust and js. AccountSubscribe seems to work fine. It will be great if you can provide an ETA to the fix.

@lijunwangs
Copy link
Contributor

Running against my validator with testnet -- I see the following:
Sent 1
received 2 EAkGGmHdngxtgY5nHAcyBc3cXB85qPStmWdnwH78Wyor
Sent 2
Sent 3
Sent 4
received 5 21kRqSk31N3id63D7yCboCJMQLJf6H8fon7HjZELBeq1
Sent 5

lijunwangs added a commit that referenced this issue Aug 10, 2021
…ribe (#19092)

#18587: programSubscribe is missing notifications randomly. The issue is because of two reasons

Not all rooted slots get OptimisticallyConfirmed notifications
The OptimisticallyConfirmed notifications can be out of order for slots: slot A and B with A < B can see notification for B first before A.
Summary of Changes

Changed OptimisticallyConfirmedBankTracker to send notifications for parent banks if they have not been notified yet. We use a new variable last_notified_slot to track that.

Tests:
With my validator running against testnet, before the fix, it was failing 75% of time, with the fix, it is passing consistently. Using the program mentioned in #18587.
mergify bot pushed a commit that referenced this issue Aug 12, 2021
…ribe (#19092)

#18587: programSubscribe is missing notifications randomly. The issue is because of two reasons

Not all rooted slots get OptimisticallyConfirmed notifications
The OptimisticallyConfirmed notifications can be out of order for slots: slot A and B with A < B can see notification for B first before A.
Summary of Changes

Changed OptimisticallyConfirmedBankTracker to send notifications for parent banks if they have not been notified yet. We use a new variable last_notified_slot to track that.

Tests:
With my validator running against testnet, before the fix, it was failing 75% of time, with the fix, it is passing consistently. Using the program mentioned in #18587.

(cherry picked from commit 1a372a7)
mergify bot added a commit that referenced this issue Aug 12, 2021
…ribe (backport #19092) (#19207)

* Fixing missing pubsub notification for programSubscribe and logsSubscribe (#19092)

#18587: programSubscribe is missing notifications randomly. The issue is because of two reasons

Not all rooted slots get OptimisticallyConfirmed notifications
The OptimisticallyConfirmed notifications can be out of order for slots: slot A and B with A < B can see notification for B first before A.
Summary of Changes

Changed OptimisticallyConfirmedBankTracker to send notifications for parent banks if they have not been notified yet. We use a new variable last_notified_slot to track that.

Tests:
With my validator running against testnet, before the fix, it was failing 75% of time, with the fix, it is passing consistently. Using the program mentioned in #18587.

(cherry picked from commit 1a372a7)

* Use v1.7 api

Co-authored-by: Lijun Wang <[email protected]>
Co-authored-by: Tyera Eulberg <[email protected]>
@lijunwangs
Copy link
Contributor

Fix merged into master.

CriesofCarrots pushed a commit to CriesofCarrots/solana that referenced this issue Aug 21, 2021
…ribe (solana-labs#19092)

Not all rooted slots get OptimisticallyConfirmed notifications
The OptimisticallyConfirmed notifications can be out of order for slots: slot A and B with A < B can see notification for B first before A.
Summary of Changes

Changed OptimisticallyConfirmedBankTracker to send notifications for parent banks if they have not been notified yet. We use a new variable last_notified_slot to track that.

Tests:
With my validator running against testnet, before the fix, it was failing 75% of time, with the fix, it is passing consistently. Using the program mentioned in solana-labs#18587.
CriesofCarrots pushed a commit to CriesofCarrots/solana that referenced this issue Aug 21, 2021
…ribe (solana-labs#19092)

Not all rooted slots get OptimisticallyConfirmed notifications
The OptimisticallyConfirmed notifications can be out of order for slots: slot A and B with A < B can see notification for B first before A.
Summary of Changes

Changed OptimisticallyConfirmedBankTracker to send notifications for parent banks if they have not been notified yet. We use a new variable last_notified_slot to track that.

Tests:
With my validator running against testnet, before the fix, it was failing 75% of time, with the fix, it is passing consistently. Using the program mentioned in solana-labs#18587.
mergify bot pushed a commit that referenced this issue Aug 26, 2021
…ribe (#19092)

#18587: programSubscribe is missing notifications randomly. The issue is because of two reasons

Not all rooted slots get OptimisticallyConfirmed notifications
The OptimisticallyConfirmed notifications can be out of order for slots: slot A and B with A < B can see notification for B first before A.
Summary of Changes

Changed OptimisticallyConfirmedBankTracker to send notifications for parent banks if they have not been notified yet. We use a new variable last_notified_slot to track that.

Tests:
With my validator running against testnet, before the fix, it was failing 75% of time, with the fix, it is passing consistently. Using the program mentioned in #18587.

(cherry picked from commit 1a372a7)

# Conflicts:
#	core/src/optimistically_confirmed_bank_tracker.rs
#	core/src/rpc_subscriptions.rs
mergify bot added a commit that referenced this issue Aug 27, 2021
…ribe (backport #19092) (#19455)

* Fixing missing pubsub notification for programSubscribe and logsSubscribe (#19092)

#18587: programSubscribe is missing notifications randomly. The issue is because of two reasons

Not all rooted slots get OptimisticallyConfirmed notifications
The OptimisticallyConfirmed notifications can be out of order for slots: slot A and B with A < B can see notification for B first before A.
Summary of Changes

Changed OptimisticallyConfirmedBankTracker to send notifications for parent banks if they have not been notified yet. We use a new variable last_notified_slot to track that.

Tests:
With my validator running against testnet, before the fix, it was failing 75% of time, with the fix, it is passing consistently. Using the program mentioned in #18587.

(cherry picked from commit 1a372a7)

# Conflicts:
#	core/src/optimistically_confirmed_bank_tracker.rs
#	core/src/rpc_subscriptions.rs

* Fix conflicts

Co-authored-by: Lijun Wang <[email protected]>
Co-authored-by: Tyera Eulberg <[email protected]>
@github-actions
Copy link
Contributor

github-actions bot commented Apr 1, 2022

This issue has been automatically locked since there has not been any activity in past 7 days after it was closed. Please open a new issue for related bugs.

@github-actions github-actions bot locked as resolved and limited conversation to collaborators Apr 1, 2022
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

No branches or pull requests

5 participants