bug: Filter relay/v1/messages GET returns duplicate messages

[fbarbu15]

To reproduce

If you can reproduce the behavior, steps to reproduce:

1. Have a relay node (node1)
2. Connect a filter node (node2) to the relay node
3. Subscribe to some topics and verify that messages published via Relay reach the Filter nodes
4. Publish a message via Relay and verify that the filter node get's that message
5. Publish again the same message via Relay and verify if the filter node get's that message

Actual behavior

Filter message receives again the message

Expected behavior

I think this is a bug because:

• if the node2 is relay instead of filter, and we use relay/v1/messages instead the duplicate message will not be retrieved.
• if instead of nwaku I use gowaku for the exact scenario, the duplicate message will not be retrieved.

Screenshots/logs

If applicable, add screenshots or logs to help explain your problem.

nwaku version/commit hash

harbor.status.im/wakuorg/nwaku:latest

Docker logs

node2_2023-12-27_17-59-51__a326b384-8ecf-45e5-a65a-081f58c49657__harbor.status.im_wakuorg_nwakulatest.log
node1_2023-12-27_17-59-51__a326b384-8ecf-45e5-a65a-081f58c49657__harbor.status.im_wakuorg_nwakulatest.log

Test logs

17:59:51 src.node.docker_mananger DEBUG Starting container with image harbor.status.im/wakuorg/nwaku:latest
17:59:51 src.node.docker_mananger DEBUG Using args ['--listen-address=0.0.0.0', '--rpc=true', '--rpc-admin=true', '--rest=true', '--rest-admin=true', '--websocket-support=true', '--log-level=TRACE', '--rest-relay-cache-capacity=100', '--websocket-port=44660', '--rpc-port=44658', '--rest-port=44657', '--tcp-port=44659', '--discv5-udp-port=44661', '--rpc-address=0.0.0.0', '--rest-address=0.0.0.0', '--nat=extip:172.18.94.194', '--peer-exchange=true', '--discv5-discovery=true', '--cluster-id=0', '--metrics-server=true', '--metrics-server-address=0.0.0.0', '--metrics-server-port=44662', '--metrics-logging=true', '--relay=true', '--filter=true', '--nodekey=30348dd51465150e04a5d9d932c72864c8967f806cce60b5d26afeca1e77eb68']
17:59:52 src.node.docker_mananger DEBUG Container started with ID c1fe65c40472. Setting up logs at ./log/docker/node1_2023-12-27_17-59-51__a326b384-8ecf-45e5-a65a-081f58c49657__harbor.status.im_wakuorg_nwaku:latest.log
17:59:52 src.node.waku_node DEBUG Started container from image harbor.status.im/wakuorg/nwaku:latest. RPC: 44658 REST: 44657 WebSocket: 44660 TCP: 44659
17:59:52 src.libs.common DEBUG Sleeping for 1 seconds
17:59:53 src.node.api_clients.base_client INFO GET call: http://127.0.0.1:44657/debug/v1/info with payload: None
17:59:53 src.node.api_clients.base_client INFO Response status code: 200. Response content: b'{"listenAddresses":["/ip4/172.18.94.194/tcp/44659/p2p/16Uiu2HAmGNtM2rQ8abySFNhqPDFY4cmfAEpfo9Z9fD3NekoFR2ip","/ip4/172.18.94.194/tcp/44660/ws/p2p/16Uiu2HAmGNtM2rQ8abySFNhqPDFY4cmfAEpfo9Z9fD3NekoFR2ip"],"enrUri":"enr:-Kq4QGOifM6PYEcE460guogZZmU02OuKKPY26vXpn7h1rNUjYQpIcxUkUQNqKj2canKOCuBf_R2ax1TQfkt_ClNwIxYBgmlkgnY0gmlwhKwSXsKKbXVsdGlhZGRyc4wACgSsEl7CBq503QOJc2VjcDI1NmsxoQM3Tqpf5eFn4Jztm4gB0Y0JVSJyxyZsW8QR-QU5DZb-PYN0Y3CCrnODdWRwgq51hXdha3UyBQ"}'
17:59:53 src.node.waku_node INFO REST service is ready !!
17:59:53 src.steps.filter DEBUG Running fixture setup: setup_main_filter_node
17:59:53 src.node.docker_mananger DEBUG Docker client initialized with image harbor.status.im/wakuorg/nwaku:latest
17:59:53 src.node.waku_node DEBUG WakuNode instance initialized with log path ./log/docker/node2_2023-12-27_17-59-51__a326b384-8ecf-45e5-a65a-081f58c49657__harbor.status.im_wakuorg_nwaku:latest.log
17:59:53 src.node.waku_node DEBUG Starting Node...
17:59:53 src.node.docker_mananger DEBUG Attempting to create or retrieve network waku
17:59:53 src.node.docker_mananger DEBUG Network waku already exists
17:59:53 src.node.docker_mananger DEBUG Generated random external IP 172.18.225.164
17:59:53 src.node.docker_mananger DEBUG Generated ports [17456, 17457, 17458, 17459, 17460, 17461]
17:59:53 src.node.docker_mananger DEBUG Starting container with image harbor.status.im/wakuorg/nwaku:latest
17:59:53 src.node.docker_mananger DEBUG Using args ['--listen-address=0.0.0.0', '--rpc=true', '--rpc-admin=true', '--rest=true', '--rest-admin=true', '--websocket-support=true', '--log-level=TRACE', '--rest-relay-cache-capacity=100', '--websocket-port=17459', '--rpc-port=17457', '--rest-port=17456', '--tcp-port=17458', '--discv5-udp-port=17460', '--rpc-address=0.0.0.0', '--rest-address=0.0.0.0', '--nat=extip:172.18.225.164', '--peer-exchange=true', '--discv5-discovery=true', '--cluster-id=0', '--metrics-server=true', '--metrics-server-address=0.0.0.0', '--metrics-server-port=17461', '--metrics-logging=true', '--relay=false', '--filter=true', '--discv5-bootstrap-node=enr:-Kq4QGOifM6PYEcE460guogZZmU02OuKKPY26vXpn7h1rNUjYQpIcxUkUQNqKj2canKOCuBf_R2ax1TQfkt_ClNwIxYBgmlkgnY0gmlwhKwSXsKKbXVsdGlhZGRyc4wACgSsEl7CBq503QOJc2VjcDI1NmsxoQM3Tqpf5eFn4Jztm4gB0Y0JVSJyxyZsW8QR-QU5DZb-PYN0Y3CCrnODdWRwgq51hXdha3UyBQ', '--filternode=/ip4/172.18.94.194/tcp/44659/p2p/16Uiu2HAmGNtM2rQ8abySFNhqPDFY4cmfAEpfo9Z9fD3NekoFR2ip']
17:59:53 src.node.docker_mananger DEBUG Container started with ID 0050531e2af7. Setting up logs at ./log/docker/node2_2023-12-27_17-59-51__a326b384-8ecf-45e5-a65a-081f58c49657__harbor.status.im_wakuorg_nwaku:latest.log
17:59:53 src.node.waku_node DEBUG Started container from image harbor.status.im/wakuorg/nwaku:latest. RPC: 17457 REST: 17456 WebSocket: 17459 TCP: 17458
17:59:53 src.libs.common DEBUG Sleeping for 1 seconds
17:59:54 src.node.api_clients.base_client INFO GET call: http://127.0.0.1:17456/debug/v1/info with payload: None
17:59:54 src.node.api_clients.base_client INFO Response status code: 200. Response content: b'{"listenAddresses":["/ip4/172.18.225.164/tcp/17458/p2p/16Uiu2HAmH3yEtwB7D9gb8fBU6N7734FopFLxFHae3zkYRcDWhetS","/ip4/172.18.225.164/tcp/17459/ws/p2p/16Uiu2HAmH3yEtwB7D9gb8fBU6N7734FopFLxFHae3zkYRcDWhetS"],"enrUri":"enr:-Kq4QKoEkDYoDZlsW16QPFj5SjmnI7KDDvgxC2ti4MuCOTYbJH8TYZqTzAt_fwMT4PNbmItPKa1Ux7Fle_0nv4IHtD8BgmlkgnY0gmlwhKwS4aSKbXVsdGlhZGRyc4wACgSsEuGkBkQz3QOJc2VjcDI1NmsxoQNBUdnY-zsexRNeE7UR8bTGw9EtMkpBM0ZlFJwCBGEeK4N0Y3CCRDKDdWRwgkQ0hXdha3UyBA"}'
17:59:54 src.node.waku_node INFO REST service is ready !!
17:59:54 src.steps.filter DEBUG Running fixture setup: subscribe_main_nodes
17:59:54 src.node.api_clients.base_client INFO POST call: http://127.0.0.1:44657/relay/v1/subscriptions with payload: ["/waku/2/rs/0/0"]
17:59:54 src.node.api_clients.base_client INFO Response status code: 200. Response content: b'OK'
17:59:54 src.node.api_clients.base_client INFO POST call: http://127.0.0.1:17456/filter/v2/subscriptions with payload: {"requestId": "4a1437f6-03e6-4122-99d9-ed5e30c969c6", "contentFilters": ["/test/1/waku-filter/proto"], "pubsubTopic": "/waku/2/rs/0/0"}
17:59:54 src.node.api_clients.base_client INFO Response status code: 200. Response content: b'{"requestId":"4a1437f6-03e6-4122-99d9-ed5e30c969c6","statusCode":0,"statusDesc":""}'
------------------------------------------------------------------------------------------------ live log call ------------------------------------------------------------------------------------------------
17:59:55 src.node.api_clients.base_client INFO POST call: http://127.0.0.1:44657/relay/v1/messages/%2Fwaku%2F2%2Frs%2F0%2F0 with payload: {"payload": "RmlsdGVyIHdvcmtzISE=", "contentTopic": "/test/1/waku-filter/proto", "timestamp": 1703692795000859136}
17:59:55 src.node.api_clients.base_client INFO Response status code: 200. Response content: b'OK'
17:59:55 src.libs.common DEBUG Sleeping for 0.1 seconds
17:59:55 src.steps.filter DEBUG Checking that peer NODE_1:harbor.status.im/wakuorg/nwaku:latest can find the published message
17:59:55 src.node.api_clients.base_client INFO GET call: http://127.0.0.1:17456/filter/v2/messages/%2Ftest%2F1%2Fwaku-filter%2Fproto with payload: None
17:59:55 src.node.api_clients.base_client INFO Response status code: 200. Response content: b'[{"payload":"RmlsdGVyIHdvcmtzISE=","contentTopic":"/test/1/waku-filter/proto","version":0,"timestamp":1703692795000859136}]'
17:59:55 src.node.api_clients.base_client INFO POST call: http://127.0.0.1:44657/relay/v1/messages/%2Fwaku%2F2%2Frs%2F0%2F0 with payload: {"payload": "RmlsdGVyIHdvcmtzISE=", "contentTopic": "/test/1/waku-filter/proto", "timestamp": 1703692795000859136}
17:59:55 src.node.api_clients.base_client INFO Response status code: 200. Response content: b'OK'
17:59:55 src.libs.common DEBUG Sleeping for 0.1 seconds
17:59:55 src.steps.filter DEBUG Checking that peer NODE_1:harbor.status.im/wakuorg/nwaku:latest can find the published message
17:59:55 src.node.api_clients.base_client INFO GET call: http://127.0.0.1:17456/filter/v2/messages/%2Ftest%2F1%2Fwaku-filter%2Fproto with payload: None
17:59:55 src.node.api_clients.base_client INFO Response status code: 200. Response content: b'[{"payload":"RmlsdGVyIHdvcmtzISE=","contentTopic":"/test/1/waku-filter/proto","version":0,"timestamp":1703692795000859136}]'

[darshankabariya]

Hi @fbarbu15, could you clarify 'same message'? I sent the same payload with the same timestamp, and it wasn't received by the filter on node2. However, with the same payload but a different timestamp, it was received.

cc @Ivansete-status @gabrielmer @NagyZoltanPeter

[fbarbu15]

same message

Identical payload: same message test, topic and timestamp

[fbarbu15]

I just retried the test and it still fails. Here's the log maybe it could help

sending the message

curl -v -X POST "http://127.0.0.1:46420/relay/v1/messages/%2Fwaku%2F2%2Frs%2F0%2F1" -H "Content-Type: application/json" -d '{"payload": "RmlsdGVyIHdvcmtzISE=", "contentTopic": "/test/1/waku-filter/proto", "timestamp": 1718791765172475136}'

retrieving the message

curl -v -X GET "http://127.0.0.1:62946/filter/v2/messages/%2Ftest%2F1%2Fwaku-filter%2Fproto" -H "Content-Type: application/json" -d 'None'
Response content: b'[{"payload":"RmlsdGVyIHdvcmtzISE=","contentTopic":"/test/1/waku-filter/proto","version":0,"timestamp":1718791765172475136,"ephemeral":false}]'

retrieving the message again and checking that it's no longer retrieved a 2nd time, which is correct

curl -v -X GET "http://127.0.0.1:62946/filter/v2/messages/%2Ftest%2F1%2Fwaku-filter%2Fproto" -H "Content-Type: application/json" -d 'None'
Response content: b'[]'

sending the same message again

curl -v -X POST "http://127.0.0.1:46420/relay/v1/messages/%2Fwaku%2F2%2Frs%2F0%2F1" -H "Content-Type: application/json" -d '{"payload": "RmlsdGVyIHdvcmtzISE=", "contentTopic": "/test/1/waku-filter/proto", "timestamp": 1718791765172475136}'

retrieving the message and seeing the issue

curl -v -X GET "http://127.0.0.1:62946/filter/v2/messages/%2Ftest%2F1%2Fwaku-filter%2Fproto" -H "Content-Type: application/json" -d 'None'
Response content: b'[{"payload":"RmlsdGVyIHdvcmtzISE=","contentTopic":"/test/1/waku-filter/proto","version":0,"timestamp":1718791765172475136,"ephemeral":false}]'

[NagyZoltanPeter]

Hi @fbarbu15, could you clarify 'same message'? I sent the same payload with the same timestamp, and it wasn't received by the filter on node2. However, with the same payload but a different timestamp, it was received.

cc @Ivansete-status @gabrielmer @NagyZoltanPeter

Hi @darshankabariya, @fbarbu15,
I think I understand the issue here.

node1 is a relay node and a filter service.
node2 is a filter client

This way when node2 subscribes to node1 filter service it will instantly get (pushed) messages from node1 surrounding the relay which would probably filter out duplicate message on gossip-sub level. We have a filterHandler installed for relay, that is responsible to push filtered message to subscribers, which happens in this case.
So filter client gets the message twice, it does not check duplicates. So when using get filter messages it will naturally got served from the filter client cache.

Yeah, it is a good question on what level node shall check dups....

[darshankabariya]

Hi @fbarbu15 Could you plz check my config file? Maybe I missed something, it's not replicated locally.

Left side :- relay node (node1)
right side :- filter node (node2)

[fbarbu15]

on my side

• the relay node is also filter: --relay=true --filter=true
• the filter node is not relay and uses filternode instead of filter flag: --relay=false --filternode=/ip4/172.18.250.149/tcp/46421/p2p/16Uiu2HAmGNtM2rQ8abySFNhqPDFY4cmfAEpfo9Z9fD3NekoFR2ip

[NagyZoltanPeter]

on my side

• the relay node is also filter: --relay=true --filter=true
• the filter node is not relay and uses filternode instead of filter flag: --relay=false --filternode=/ip4/172.18.250.149/tcp/46421/p2p/16Uiu2HAmGNtM2rQ8abySFNhqPDFY4cmfAEpfo9Z9fD3NekoFR2ip

Yes this matches my assumption, the second node is a filter-client in other words. This way node1 is not relaying the message to node2 but "filter push" it upon filter subscription.