itest: make sure to not hit the natural ChannelUpdate rate limit #9567

ellemouton · 2025-02-28T11:31:57Z

Channel Updates have a natural rate limit of 1 update per second due to the fact that the timestamp carried in the update is only accurate to the second. So we need to ensure that the next update we send in the burst is at least 1 second after the last one.

This flake was appearing in the update channel policy itest in the part of the tests where we are testing
the burst rate limit logic of Carol. It's flaky at the moment though due to Carol sometimes rejecting a channel update
due to the natural 1-update-per-second rate limit. So we need to ensure that Alice waits at least a second between
sending updates for this logic to be tested properly. The log line that appears after the channel updates are sent too quickly after each there ie:
builder.go:1331: process network updates got: Ignoring outdated update (flags=00000001|00000000) for known chan_id=8015439768453121

As to why this is flake is appearing more often now, I think it may be due to this PR which removes the logic that would pass channel updates through the same channel before handling them in a goroutine - All that did was make it less likely for the flake to occur though cause it added a small artificial delay between the updates.

coderabbitai · 2025-02-28T11:32:04Z

Important

Review skipped

Auto reviews are limited to specific labels.

🏷️ Labels to auto review (1)

llm-review

Please check the settings in the CodeRabbit UI or the .coderabbit.yaml file in this repository. To trigger a single review, invoke the @coderabbitai review command.

You can disable this status message by setting the reviews.review_status to false in the CodeRabbit configuration file.

Thank you for using CodeRabbit. We offer it for free to the OSS community and would appreciate your support in helping us grow. If you find it useful, would you consider giving us a shout-out on your favorite social media?

❤️ Share

🪧 Tips

Chat

There are 3 ways to chat with CodeRabbit:

Review comments: Directly reply to a review comment made by CodeRabbit. Example:
- I pushed a fix in commit <commit_id>, please review it.
- Generate unit testing code for this file.
- Open a follow-up GitHub issue for this discussion.
Files and specific lines of code (under the "Files changed" tab): Tag @coderabbitai in a new review comment at the desired location with your query. Examples:
- @coderabbitai generate unit testing code for this file.
- @coderabbitai modularize this function.
PR comments: Tag @coderabbitai in a new PR comment to ask questions about the PR branch. For the best results, please provide a very specific query, as very limited context is provided in this mode. Examples:
- @coderabbitai gather interesting stats about this repository and render them as a table. Additionally, render a pie chart showing the language distribution in the codebase.
- @coderabbitai read src/utils.ts and generate unit testing code.
- @coderabbitai read the files in the src/scheduler package and generate a class diagram using mermaid and a README in the markdown format.
- @coderabbitai help me debug CodeRabbit configuration file.

Note: Be mindful of the bot's finite context window. It's strongly recommended to break down tasks such as reading entire modules into smaller chunks. For a focused discussion, use review comments to chat about specific files and their changes, instead of using the PR comments.

CodeRabbit Commands (Invoked using PR comments)

@coderabbitai pause to pause the reviews on a PR.
@coderabbitai resume to resume the paused reviews.
@coderabbitai review to trigger an incremental review. This is useful when automatic reviews are disabled for the repository.
@coderabbitai full review to do a full review from scratch and review all the files again.
@coderabbitai summary to regenerate the summary of the PR.
@coderabbitai generate docstrings to generate docstrings for this PR.
@coderabbitai resolve resolve all the CodeRabbit review comments.
@coderabbitai configuration to show the current CodeRabbit configuration for the repository.
@coderabbitai help to get help.

Other keywords and placeholders

Add @coderabbitai ignore anywhere in the PR description to prevent this PR from being reviewed.
Add @coderabbitai summary to generate the high-level summary at a specific location in the PR description.
Add @coderabbitai anywhere in the PR title to generate the title automatically.

CodeRabbit Configuration File (`.coderabbit.yaml`)

You can programmatically configure CodeRabbit by adding a .coderabbit.yaml file to the root of your repository.
Please see the configuration documentation for more information.
If your editor has YAML language server enabled, you can add the path at the top of this file to enable auto-completion and validation: # yaml-language-server: $schema=https://coderabbit.ai/integrations/schema.v2.json

Documentation and Community

Visit our Documentation for detailed information on how to use CodeRabbit.
Join our Discord Community to get help, request features, and share feedback.
Follow us on X/Twitter for updates and announcements.

Channel Updates have a natural rate limit of 1 update per second due to the fact that the timestamp carried in the update is only accurate to the second. So we need to ensure that the next update we send in the burst is at least 1 second after the last one.

bhandras

Nice catch! ⚔️

bhandras · 2025-03-03T05:34:50Z

itest/lnd_channel_policy_test.go

+	// per second due to the fact that the timestamp carried in the update
+	// is only accurate to the second. So we need to ensure that the next
+	// update we send in the burst is at least 1 second after the last one.
+	time.Sleep(time.Second)


nit: might make sense to rename assertAliceAndBob to updateAndAssertChanPolicy for clarity too.

good idea - will add a commit 🫡

yyforyongyu

I think there's a weird behavior, analyzed the logs from this build,

Channel open, not counted as rate limit.

2025-02-28 08:10:16.250 [DBG] PEER brontide.go:2412: Peer([Alice]): Received ChannelUpdate(chain_hash=0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206, short_chan_id=[SID: Alice=>Carol], mflags=00000001, cflags=00000001, update_time=2025-02-28 08:10:16 +0000 UTC) from [Alice]@127.0.0.1:39298
2025-02-28 08:10:16.257 [DBG] DISC gossiper.go:3145: Validating ChannelUpdate: channel=[SID: Alice=>Carol], for node=[Alice], has edge policy=false

Ignored channel updates, not counted as rate limit.

2025-02-28 08:10:21.426 [DBG] PEER brontide.go:2412: Peer([Alice]): Received ChannelUpdate(chain_hash=0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206, short_chan_id=[SID: Alice=>Carol], mflags=00000001, cflags=00000000, update_time=2025-02-28 08:10:16 +0000 UTC) from [Alice]@127.0.0.1:39298
2025-02-28 08:10:21.427 [DBG] PEER brontide.go:2412: Peer([Alice]): Received ChannelUpdate(chain_hash=0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206, short_chan_id=[SID: Alice=>Carol], mflags=00000001, cflags=00000001, update_time=2025-02-28 08:10:16 +0000 UTC) from [Alice]@127.0.0.1:39298
2025-02-28 08:10:21.433 [DBG] DISC gossiper.go:3004: Ignored stale edge policy for short_chan_id([SID: Alice=>Carol]): peer=[Alice]@127.0.0.1:39298, msg=ChannelUpdate, is_remote=true
2025-02-28 08:10:21.437 [DBG] DISC gossiper.go:3004: Ignored stale edge policy for short_chan_id([SID: Alice=>Carol]): peer=[Alice]@127.0.0.1:39298, msg=ChannelUpdate, is_remote=true

Rate limit once for each channel.

2025-02-28 08:10:22.580 [DBG] PEER brontide.go:2412: Peer([Alice]): Received ChannelUpdate(chain_hash=0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206, short_chan_id=[SID: Alice=>Bob], mflags=00000001, cflags=00000000, update_time=2025-02-28 08:10:22 +0000 UTC) from [Alice]@127.0.0.1:39298
2025-02-28 08:10:22.580 [DBG] PEER brontide.go:2412: Peer([Alice]): Received ChannelUpdate(chain_hash=0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206, short_chan_id=[SID: Alice=>Carol], mflags=00000001, cflags=00000001, update_time=2025-02-28 08:10:22 +0000 UTC) from [Alice]@127.0.0.1:39298
2025-02-28 08:10:22.586 [DBG] DISC gossiper.go:3145: Validating ChannelUpdate: channel=[SID: Alice=>Bob], for node=[Alice], has edge policy=true
2025-02-28 08:10:22.589 [DBG] DISC gossiper.go:3145: Validating ChannelUpdate: channel=[SID: Alice=>Carol], for node=[Alice], has edge policy=true

Rate limit twice for each channel, should pass, but the channel Alice=>Carol is limited. It's weird as ValidateChannelUpdateAnn has been called twice for the ChannelUpdate from the channel Alice=>Carol, which I think is the root cause.

2025-02-28 08:10:23.938 [DBG] PEER brontide.go:2412: Peer([Alice]): Received ChannelUpdate(chain_hash=0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206, short_chan_id=[SID: Alice=>Bob], mflags=00000001, cflags=00000000, update_time=2025-02-28 08:10:23 +0000 UTC) from [Alice]@127.0.0.1:39298
2025-02-28 08:10:23.938 [DBG] PEER brontide.go:2412: Peer([Alice]): Received ChannelUpdate(chain_hash=0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206, short_chan_id=[SID: Alice=>Carol], mflags=00000001, cflags=00000001, update_time=2025-02-28 08:10:23 +0000 UTC) from [Alice]@127.0.0.1:39298
2025-02-28 08:10:23.950 [DBG] DISC gossiper.go:3145: Validating ChannelUpdate: channel=[SID: Alice=>Bob], for node=[Alice], has edge policy=true
2025-02-28 08:10:23.952 [DBG] DISC gossiper.go:3145: Validating ChannelUpdate: channel=[SID: Alice=>Carol], for node=[Alice], has edge policy=true
2025-02-28 08:10:23.952 [DBG] DISC gossiper.go:3206: Rate limiting update for channel [SID: Alice=>Carol] from direction [Alice]
2025-02-28 08:10:23.976 [DBG] DISC gossiper.go:3334: Processed ChannelUpdate: peer=[Alice]@127.0.0.1:39298, short_chan_id=[SID: Alice=>Bob], timestamp=2025-02-28 08:10:23 +0000 UTC

# Why is the validation called again for Alice=>Carol?

2025-02-28 08:10:24.022 [DBG] DISC gossiper.go:3145: Validating ChannelUpdate: channel=[SID: Alice=>Carol], for node=[Alice], has edge policy=true
2025-02-28 08:10:24.022 [DBG] DISC gossiper.go:3206: Rate limiting update for channel [SID: Alice=>Carol] from direction [Alice]

yyforyongyu · 2025-03-03T07:20:42Z

itest/lnd_channel_policy_test.go

+	// per second due to the fact that the timestamp carried in the update
+	// is only accurate to the second. So we need to ensure that the next
+	// update we send in the burst is at least 1 second after the last one.
+	time.Sleep(time.Second)


What is the evidence showing this is the cause? Could you provide the logs?

see PR description of the log line

builder.go:1331: process network updates got: Ignoring outdated update (flags=00000001|00000000) for known chan_id=8015439768453121

gimme a sec to write up the exact order of ops. But pretty sure this reasoning was correct. basically, the global updates are applied very quickly after eachother and so the timestamp is the same.

Why is the validation called again for Alice=>Carol?

because 2 updates are getting sent very close together.
note that the issue is happening before the actual rate limit logic kicks in

We are sending a channel update on channel open, we then make a global update to base fee 800, then we make another one to 1600. All of these should be received just fine by Carol since the channel open one doesnt count towards rate limit and so the next 2 should be received just fine. But the 1600 is sent too quickly after the 800 one and so it has the same timestamp and so gets ignored as "outdated"

so we definitely do expect the Validation line twice in the normal case. I dont think anything else weird is happening here.

If that's the case, it should be caught here?

lnd/discovery/gossiper.go

Line 3000 in f744a54

if d.cfg.Graph.IsStaleEdgePolicy(

Also from the logs, the last two ChannelUpdate have different timestamps.

Channel open, not counted as rate limit. 2025-02-28 08:10:16.250 [DBG] PEER brontide.go:2412: Peer([Alice]): Received ChannelUpdate(chain_hash=0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206, short_chan_id=[SID: Alice=>Carol], mflags=00000001, cflags=00000001, update_time=2025-02-28 08:10:16 +0000 UTC) from [Alice]@127.0.0.1:39298 Ignored channel updates, not counted as rate limit. 2025-02-28 08:10:21.426 [DBG] PEER brontide.go:2412: Peer([Alice]): Received ChannelUpdate(chain_hash=0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206, short_chan_id=[SID: Alice=>Carol], mflags=00000001, cflags=00000000, update_time=2025-02-28 08:10:16 +0000 UTC) from [Alice]@127.0.0.1:39298 2025-02-28 08:10:21.427 [DBG] PEER brontide.go:2412: Peer([Alice]): Received ChannelUpdate(chain_hash=0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206, short_chan_id=[SID: Alice=>Carol], mflags=00000001, cflags=00000001, update_time=2025-02-28 08:10:16 +0000 UTC) from [Alice]@127.0.0.1:39298 Global update to base fee 800, rate limit once for each channel. 2025-02-28 08:10:22.580 [DBG] PEER brontide.go:2412: Peer([Alice]): Received ChannelUpdate(chain_hash=0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206, short_chan_id=[SID: Alice=>Carol], mflags=00000001, cflags=00000001, update_time=2025-02-28 08:10:22 +0000 UTC) from [Alice]@127.0.0.1:39298 Global update to base fee 1600, rate limit once for each channel. 2025-02-28 08:10:23.938 [DBG] PEER brontide.go:2412: Peer([Alice]): Received ChannelUpdate(chain_hash=0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206, short_chan_id=[SID: Alice=>Carol], mflags=00000001, cflags=00000001, update_time=2025-02-28 08:10:23 +0000 UTC) from [Alice]@127.0.0.1:39298

Looking closely, I think the Ignoring outdated... actually comes from processing the ChannelUpdate sent from Bob,

2025-02-28 08:10:22.580 [DBG] PEER brontide.go:2412: Peer([Alice]): Received ChannelUpdate(chain_hash=0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206, short_chan_id=[SID: Alice=>Carol], mflags=00000001, cflags=00000001, update_time=2025-02-28 08:10:22 +0000 UTC) from [Alice]@127.0.0.1:39298 ... It says the `ChannelUpdate` from Alice has been processed without error. 2025-02-28 08:10:22.605 [DBG] DISC gossiper.go:3334: Processed ChannelUpdate: peer=[Alice]@127.0.0.1:39298, short_chan_id=[SID: Alice=>Bob], timestamp=2025-02-28 08:10:22 +0000 UTC ... Then Carol received it from Bob. 2025-02-28 08:10:22.612 [DBG] PEER brontide.go:2412: Peer([Bob]): Received ChannelUpdate(chain_hash=0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206, short_chan_id=[SID: Alice=>Carol], mflags=00000001, cflags=00000001, update_time=2025-02-28 08:10:22 +0000 UTC) from [Bob]@127.0.0.1:11599 2025-02-28 08:10:22.612 [DBG] DISC gossiper.go:2942: Processing ChannelUpdate: peer=[Bob]@127.0.0.1:11599, short_chan_id=[SID: Alice=>Carol], This is now ignored because we already received it from Alice. 2025-02-28 08:10:22.627 [DBG] GRPH builder.go:1331: process network updates got: Ignoring outdated update (flags=00000001|00000001) for known chan_id=[SID: Alice=>Carol] 2025-02-28 08:10:22.627 [DBG] DISC gossiper.go:3242: Update edge for short_chan_id([SID: Alice=>Carol]) got: Ignoring outdated update (flags=00000001|00000001) for known chan_id=[SID: Alice=>Carol]

In addition if the error is from Alice's update I think the UpdateChannelPolicy would fail? And why would this affect the rate limiting?

ok yeah you're right. Looking

ellemouton added the flake fix label Feb 28, 2025

ellemouton self-assigned this Feb 28, 2025

ellemouton force-pushed the graph18 branch from b0dcded to 93a8d83 Compare February 28, 2025 11:32

ellemouton mentioned this pull request Feb 28, 2025

graph: move graph cache out of CRUD layer #9544

Draft

Crypt-iQ approved these changes Feb 28, 2025

View reviewed changes

ellemouton requested review from yyforyongyu and bhandras February 28, 2025 21:13

bhandras approved these changes Mar 3, 2025

View reviewed changes

ellemouton removed the request for review from yyforyongyu March 3, 2025 06:44

itest: rename closure for clarity

6047bef

ellemouton merged commit b7c5895 into lightningnetwork:elle-graphCacheBase Mar 3, 2025
30 checks passed

ellemouton deleted the graph18 branch March 3, 2025 06:47

yyforyongyu reviewed Mar 3, 2025

View reviewed changes

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

itest: make sure to not hit the natural ChannelUpdate rate limit #9567

itest: make sure to not hit the natural ChannelUpdate rate limit #9567

ellemouton commented Feb 28, 2025 •

edited

Loading

coderabbitai bot commented Feb 28, 2025

Review skipped

Chat

CodeRabbit Commands (Invoked using PR comments)

Other keywords and placeholders

CodeRabbit Configuration File (`.coderabbit.yaml`)

Documentation and Community

bhandras left a comment

bhandras Mar 3, 2025

ellemouton Mar 3, 2025

yyforyongyu left a comment

yyforyongyu Mar 3, 2025

ellemouton Mar 3, 2025 •

edited

Loading

ellemouton Mar 3, 2025 •

edited

Loading

ellemouton Mar 3, 2025 •

edited

Loading

ellemouton Mar 3, 2025

yyforyongyu Mar 3, 2025

ellemouton Mar 3, 2025

itest: make sure to not hit the natural ChannelUpdate rate limit #9567

itest: make sure to not hit the natural ChannelUpdate rate limit #9567

Conversation

ellemouton commented Feb 28, 2025 • edited Loading

coderabbitai bot commented Feb 28, 2025

Review skipped

Chat

CodeRabbit Commands (Invoked using PR comments)

Other keywords and placeholders

CodeRabbit Configuration File (.coderabbit.yaml)

Documentation and Community

bhandras left a comment

Choose a reason for hiding this comment

bhandras Mar 3, 2025

Choose a reason for hiding this comment

ellemouton Mar 3, 2025

Choose a reason for hiding this comment

yyforyongyu left a comment

Choose a reason for hiding this comment

yyforyongyu Mar 3, 2025

Choose a reason for hiding this comment

ellemouton Mar 3, 2025 • edited Loading

Choose a reason for hiding this comment

ellemouton Mar 3, 2025 • edited Loading

Choose a reason for hiding this comment

ellemouton Mar 3, 2025 • edited Loading

Choose a reason for hiding this comment

ellemouton Mar 3, 2025

Choose a reason for hiding this comment

yyforyongyu Mar 3, 2025

Choose a reason for hiding this comment

ellemouton Mar 3, 2025

Choose a reason for hiding this comment

ellemouton commented Feb 28, 2025 •

edited

Loading

CodeRabbit Configuration File (`.coderabbit.yaml`)

ellemouton Mar 3, 2025 •

edited

Loading

ellemouton Mar 3, 2025 •

edited

Loading

ellemouton Mar 3, 2025 •

edited

Loading