bug: filter not accepting more subscriptions under moderate usage

[Ivansete-status]

Problem

A service node with filter mounted may run out of available filter slots after a while, even though the node doesn't have any connection.

Impact

No other filter nodes can subscribe anymore to a service node.

To reproduce

We replicated this by using railgun infra but basically what we did was:

1. Start an nwaku node.
2. Open five js-waku clients, which perform filter subscriptions to the node started in 1.
3. Stop all five js-waku-clients after 30min working.
4. The next day, the nwaku node didn't accept further subscriptions and it printed the following log:

DBG 2024-12-03 11:52:57.977+00:00 starting sendNonPriorityTask               topics="libp2p pubsubpeer" tid=1 file=pubsubpeer.nim:515 p=12D*23fRdV
DBG 2024-12-03 11:52:57.977+00:00 created new pubsub peer                    topics="libp2p pubsub" tid=1 file=pubsub.nim:367 peerId=12D*23fRdV
DBG 2024-12-03 11:52:58.873+00:00 identify: decoded message                  topics="libp2p identify" tid=1 file=identify.nim:178 conn=12D*23fRdV:674ef1195df8b0a5dfa0cc7f pubkey=some(e...30D4)) addresses= protocols=/ipfs/id/1.0.0,/ipfs/ping/1.0.0,/vac/waku/filter-push/2.0.0-beta1,/vac/waku/metadata/1.0.0 observable_address=some(/dns4/railgun.ivansete.xyz/tcp/8000/wss/p2p/16Uiu2HAmExcXDvdCr2XxfCeQY1jhCoJ1HodgKauRatCngQ9Q1X61) proto_version=ipfs/0.1.0 agent_version=js-waku signedPeerRecord=None
NTC 2024-12-03 11:52:58.893+00:00 established connections with found peers   topics="waku node peer_manager" tid=1 file=peer_manager.nim:663 peerIds="@[\"12D*23fRdV\"]" origin=@[UnknownOrigin]
DBG 2024-12-03 11:52:58.897+00:00 filter subscribe request handler triggered topics="waku filter" tid=1 file=protocol.nim:283 peerId=12D*23fRdV
DBG 2024-12-03 11:52:59.001+00:00 filter subscribe request handler triggered topics="waku filter" tid=1 file=protocol.nim:283 peerId=12D*23fRdV
INF 2024-12-03 11:52:59.069+00:00 received filter subscribe request          topics="waku filter" tid=1 file=protocol.nim:125 peerId=12D*23fRdV request="FilterSubscribeRequest of req:ecf05f03-fe4e-4ae0-959c-8df44087b5ff [SUBSCRIBE] pubsubTopic:some(\"/waku/2/rs/0/1\") contentTopics:@[\"/railgun/v2/0-1-fees/json\", \"/railgun/v2/0-56-fees/json\", \"/railgun/v2/0-137-fees/json\", \"/railgun/v2/0-42161-fees/json\", \"/railgun/v2/0-421$1-transact-response/json\", \"/railgun/v2/encrypted-metrics-pong/json\"]"
DBG 2024-12-03 11:52:59.069+00:00 subscribing peer to filter criteria        topics="waku filter" tid=1 file=protocol.nim:66 peerId=12D*23fRdV filterCriteria="{(\"/waku/2/rs/0/1\", \"/railgun/v2/0-1-fees/json\"), (\"/waku/2/rs/0/1\", \"/railgun/v2/0-421$1-transact-response/json\"), (\"/waku/2/rs/0/1\", \"/railgun/v2/0-42161-fees/json\"), (\"/waku/2/rs/0/1\", \"/railgun/v2/0-137-fees/json\"), (\"/waku/2/rs/0/1\", \"/railgun/v2/0-56-fees/json\"), (\"/waku/2/rs/0/1\", \"/railgun/v2/encrypted-metrics-pong/json\")}"
ERR 2024-12-03 11:52:59.069+00:00 subscription request error                 topics="waku filter" tid=1 file=protocol.nim:154 peerId=12D*23fRdV request="FilterSubscribeRequest of req:ecf05f03-fe4e-4ae0-959c-8df44087b5ff [SUBSCRIBE] pubsubTopic:some(\"/waku/2/rs/0/1\") contentTopics:@[\"/railgun/v2/0-1-fees/json\", \"/railgun/v2/0-56-fees/json\", \"/railgun/v2/0-137-fees/json\", \"/railgun/v2/0-42161-fees/json\", \"/railgun/v2/0-421$1-transact-response/json\", \"/railgun/v2/encrypted-metrics-pong/json\"]"
DBG 2024-12-03 11:52:59.069+00:00 sending filter subscribe response          topics="waku filter" tid=1 file=protocol.nim:305 peer_id=12D*23fRdV response="FilterSubscribeResponse of req:ecf05f03-fe4e-4ae0-959c-8df44087b5ff [503] some(\"SERVICE_UNAVAILABLE: node has reached maximum number of subscriptions\")"
NTC 2024-12-03 11:53:09.385+00:00 handling lightpush request                 topics="waku lightpush" tid=1 file=protocol.nim:48 peer_id=12D*23fRdV requestId=bdae5d15-f473-43b7-8572-38ce3225a044 pubsubTopic=/waku/2/rs/0/1 msg_hash=0x5c8f213147f6fa30c0c43d285a450528bb89619aa8f88ba4c4bdf3f02c3776b2
ERR 2024-12-03 11:53:09.385+00:00 no subscribed peers found                  topics="waku filter" tid=1 file=protocol.nim:249 pubsubTopic=/waku/2/rs/0/1 contentTopic=/js-waku-subscription-ping/1/12D3KooWLbcBoJkang3N4PRhERfKs7VdojeRqUgzRGxHCR23fRdV/utf8 msg_hash=0x5c8f213147f6fa30c0c43d285a450528bb89619aa8f88ba4c4bdf3f02c3776b2

...

DBG 2024-12-03 12:04:09.894+00:00 filter subscribe request handler triggered topics="waku filter" tid=1 file=protocol.nim:283 peerId=12D*23fRdV
INF 2024-12-03 12:04:10.030+00:00 received filter subscribe request          topics="waku filter" tid=1 file=protocol.nim:125 peerId=12D*23fRdV request="FilterSubscribeRequest of req:87ba924f-3c60-4507-a7f5-0413e87a92c0 [SUBSCRIBER_PING] pubsubTopic:some(\"\") contentTopics:@[]"
DBG 2024-12-03 12:04:10.030+00:00 pinging subscriber                         topics="waku filter" tid=1 file=protocol.nim:33 peerId=12D*23fRdV
ERR 2024-12-03 12:04:10.030+00:00 pinging peer has no subscriptions          topics="waku filter" tid=1 file=protocol.nim:36 peerId=12D*23fRdV
ERR 2024-12-03 12:04:10.030+00:00 subscription request error                 topics="waku filter" tid=1 file=protocol.nim:154 peerId=12D*23fRdV request="FilterSubscribeRequest of req:87ba924f-3c60-4507-a7f5-0413e87a92c0 [SUBSCRIBER_PING] pubsubTopic:some(\"\") contentTopics:@[]"
DBG 2024-12-03 12:04:10.030+00:00 sending filter subscribe response          topics="waku filter" tid=1 file=protocol.nim:305 peer_id=12D*23fRdV response="FilterSubscribeResponse of req:87ba924f-3c60-4507-a7f5-0413e87a92c0 [404] some(\"NOT_FOUND: peer has no subscriptions\")"
DBG 2024-12-03 12:05:09.906+00:00 filter subscribe request handler triggered topics="waku filter" tid=1 file=protocol.nim:283 peerId=12D*23fRdV
INF 2024-12-03 12:05:10.054+00:00 received filter subscribe request          topics="waku filter" tid=1 file=protocol.nim:125 peerId=12D*23fRdV request="FilterSubscribeRequest of req:270fded7-6175-4588-86d2-b12ee4e68119 [SUBSCRIBER_PING] pubsubTopic:some(\"\") contentTopics:@[]"
DBG 2024-12-03 12:05:10.054+00:00 pinging subscriber                         topics="waku filter" tid=1 file=protocol.nim:33 peerId=12D*23fRdV
ERR 2024-12-03 12:05:10.058+00:00 pinging peer has no subscriptions          topics="waku filter" tid=1 file=protocol.nim:36 peerId=12D*23fRdV
ERR 2024-12-03 12:05:10.058+00:00 subscription request error                 topics="waku filter" tid=1 file=protocol.nim:154 peerId=12D*23fRdV request="FilterSubscribeRequest of req:270fded7-6175-4588-86d2-b12ee4e68119 [SUBSCRIBER_PING] pubsubTopic:some(\"\") contentTopics:@[]"
DBG 2024-12-03 12:05:10.058+00:00 sending filter subscribe response          topics="waku filter" tid=1 file=protocol.nim:305 peer_id=12D*23fRdV response="FilterSubscribeResponse of req:270fded7-6175-4588-86d2-b12ee4e68119 [404] some(\"NOT_FOUND: peer has no subscriptions\")"
DBG 2024-12-03 12:06:09.922+00:00 filter subscribe request handler triggered topics="waku filter" tid=1 file=protocol.nim:283 peerId=12D*23fRdV
INF 2024-12-03 12:06:10.146+00:00 received filter subscribe request          topics="waku filter" tid=1 file=protocol.nim:125 peerId=12D*23fRdV request="FilterSubscribeRequest of req:dfbefc62-eb35-4d73-a056-77516f2c75e9 [SUBSCRIBER_PING] pubsubTopic:some(\"\") contentTopics:@[]"
DBG 2024-12-03 12:06:10.146+00:00 pinging subscriber                         topics="waku filter" tid=1 file=protocol.nim:33 peerId=12D*23fRdV
ERR 2024-12-03 12:06:10.146+00:00 pinging peer has no subscriptions          topics="waku filter" tid=1 file=protocol.nim:36 peerId=12D*23fRdV
ERR 2024-12-03 12:06:10.146+00:00 subscription request error                 topics="waku filter" tid=1 file=protocol.nim:154 peerId=12D*23fRdV request="FilterSubscribeRequest of req:dfbefc62-eb35-4d73-a056-77516f2c75e9 [SUBSCRIBER_PING] pubsubTopic:some(\"\") contentTopics:@[]"

Expected behavior

The filter service node (wakunode2 app with filter mounted) should always allow incoming filter subscriptions under a moderate usage.

nwaku version/commit hash

Additional context

That is part of investigation performed with Railgun.

• The client apps used are: https://github.com/waku-org/lab.waku.org/tree/master/examples/experimental/railgun-repro (created by @danisharora099 🙌 )
• https://github.com/Railgun-Privacy/ux-metrics

In both cases, we connected against the following wakunode2/nwaku node: /dns4/railgun.ivansete.xyz/tcp/8000/wss/p2p/16Uiu2HAmExcXDvdCr2XxfCeQY1jhCoJ1HodgKauRatCngQ9Q1X61

[Ivansete-status]

If seems the "subscription maintainer" proc is not being called periodically.
The following gives zero lines: docker logs 5fd3dc729d75 --tail 1000000 | grep "maintaining subscriptions"
We'll keep investigating

[NagyZoltanPeter]

Is there any config used to set --filter-max-peers-to-serve?
If not I wonder how you reached 1000 peers subscribed at a time...
In nwaku filter has defaults of 1000 peers with 1000 criteria each to maintain at a time. Also there is a cleanup of the subscriptions with time threshold to check disconnected peers meanwhile.
Thus put me questioning how the respond SERVICE_UNAVAILABLE: node has reached maximum number of subscriptions come.

[Ivansete-status]

Is there any config used to set --filter-max-peers-to-serve?

Not, they use default values

---

If not I wonder how you reached 1000 peers subscribed at a time...

I guess being persistent ;P

[NagyZoltanPeter]

Is there any config used to set --filter-max-peers-to-serve?

Not, they use default values

If not I wonder how you reached 1000 peers subscribed at a time...

I guess being persistent ;P

Do you mean there are 1000 subscriber peer live in the same time on that particular service node.
Maybe we need to review that part handling unsubsribe/subscribe that if one does not call ping but make the same subscription second time, that should not result in new subscription in our register. I guess we have test case for that... but unsure atm.

[Ivansete-status]

Do you mean there are 1000 subscriber peer live in the same time on that particular service node.
Maybe we need to review that part handling unsubsribe/subscribe that if one does not call ping but make the same subscription second time, that should not result in new subscription in our register. I guess we have test case for that... but unsure atm.

Yes I'm reviewing that atm. So far I saw a tiny bug that prevented the subscription prune to happen. I'm willing to submit a PR shortly, hopefully next week.