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

bug: Waku Store returns duplicate messages #1502

Closed
fryorcraken opened this issue Jan 20, 2023 · 7 comments · Fixed by #1511
Closed

bug: Waku Store returns duplicate messages #1502

fryorcraken opened this issue Jan 20, 2023 · 7 comments · Fixed by #1511
Assignees
@LNSD
Labels
bug Something isn't working critical This issue needs critical attention

Comments

@fryorcraken
Copy link
Collaborator

fryorcraken commented Jan 20, 2023 •
edited
Loading

Problem

js-waku interop test:

  1. Get nwaku to send 20 messages using post_waku_v2_relay_v1_message JSON RPC API
  2. Retrieve messages using page size 10, backward direction

Expected: 20 messages are returned
Actual: 44 messages are returned

Impact

Seems to be a critical bug until investigation is cleared.

To reproduce

From a js-waku clone:

git checkout chore/nwaku-0.14
npm run i
npm run build
cd packages/tests
DEBUG=waku* TS_NODE_PROJECT=./tsconfig.dev.json mocha tests/store.node.spec.ts --grep "^Waku Store Generator$"

nwaku logs will be present in ./log folder

Note nwaku is executed with the following arguments:

--listen-address=127.0.0.1 --rpc=true --relay=true --rpc-admin=true --websocket-support=true --log-level=TRACE --tcp-port=10840 --rpc-port=10839 --websocket-port=10841 --store=true --lightpush=true

and env var:

WAKUNODE2_STORE_MESSAGE_DB_URL = "";

Screenshots/logs

nwaku logs:
nwaku_Waku_Store_Generator.log

js-waku logs:

  waku:nwaku nwaku args: --listen-address=127.0.0.1 --rpc=true --relay=true --rpc-admin=true --websocket-support=true --log-level=TRACE --tcp-port=34097 --rpc-port=34096 --websocket-port=34098 --store=true --lightpush=true +0ms
  waku:nwaku nwaku 958844 started at 4:50:15 pm +57ms
  waku:nwaku Waiting to see 'Node setup complete' in nwaku logs +0ms
  waku:nwaku nwaku node has been started +4s
  waku:nwaku RPC Query:  post_waku_v2_relay_v1_message [
  '/waku/2/default-waku/proto',
  {
    payload: '00',
    contentTopic: '/test/1/waku-store/utf8',
    timestamp: 1674193819306000000n
  }
] +4ms
  waku:nwaku RPC Response:  {"jsonrpc":"2.0","id":1,"result":true} +44ms
  waku:nwaku RPC Query:  post_waku_v2_relay_v1_message [
  '/waku/2/default-waku/proto',
  {
    payload: '01',
    contentTopic: '/test/1/waku-store/utf8',
    timestamp: 1674193819351000000n
  }
] +1ms
  waku:nwaku RPC Response:  {"jsonrpc":"2.0","id":1,"result":true} +9ms
  waku:nwaku RPC Query:  post_waku_v2_relay_v1_message [
  '/waku/2/default-waku/proto',
  {
    payload: '02',
    contentTopic: '/test/1/waku-store/utf8',
    timestamp: 1674193819361000000n
  }
] +1ms
  waku:nwaku RPC Response:  {"jsonrpc":"2.0","id":1,"result":true} +9ms
  waku:nwaku RPC Query:  post_waku_v2_relay_v1_message [
  '/waku/2/default-waku/proto',
  {
    payload: '03',
    contentTopic: '/test/1/waku-store/utf8',
    timestamp: 1674193819370000000n
  }
] +0ms
  waku:nwaku RPC Response:  {"jsonrpc":"2.0","id":1,"result":true} +8ms
  waku:nwaku RPC Query:  post_waku_v2_relay_v1_message [
  '/waku/2/default-waku/proto',
  {
    payload: '04',
    contentTopic: '/test/1/waku-store/utf8',
    timestamp: 1674193819378000000n
  }
] +0ms
  waku:nwaku RPC Response:  {"jsonrpc":"2.0","id":1,"result":true} +7ms
  waku:nwaku RPC Query:  post_waku_v2_relay_v1_message [
  '/waku/2/default-waku/proto',
  {
    payload: '05',
    contentTopic: '/test/1/waku-store/utf8',
    timestamp: 1674193819386000000n
  }
] +1ms
  waku:nwaku RPC Response:  {"jsonrpc":"2.0","id":1,"result":true} +7ms
  waku:nwaku RPC Query:  post_waku_v2_relay_v1_message [
  '/waku/2/default-waku/proto',
  {
    payload: '06',
    contentTopic: '/test/1/waku-store/utf8',
    timestamp: 1674193819394000000n
  }
] +1ms
  waku:nwaku RPC Response:  {"jsonrpc":"2.0","id":1,"result":true} +7ms
  waku:nwaku RPC Query:  post_waku_v2_relay_v1_message [
  '/waku/2/default-waku/proto',
  {
    payload: '07',
    contentTopic: '/test/1/waku-store/utf8',
    timestamp: 1674193819401000000n
  }
] +0ms
  waku:nwaku RPC Response:  {"jsonrpc":"2.0","id":1,"result":true} +7ms
  waku:nwaku RPC Query:  post_waku_v2_relay_v1_message [
  '/waku/2/default-waku/proto',
  {
    payload: '08',
    contentTopic: '/test/1/waku-store/utf8',
    timestamp: 1674193819409000000n
  }
] +1ms
  waku:nwaku RPC Response:  {"jsonrpc":"2.0","id":1,"result":true} +7ms
  waku:nwaku RPC Query:  post_waku_v2_relay_v1_message [
  '/waku/2/default-waku/proto',
  {
    payload: '09',
    contentTopic: '/test/1/waku-store/utf8',
    timestamp: 1674193819417000000n
  }
] +1ms
  waku:nwaku RPC Response:  {"jsonrpc":"2.0","id":1,"result":true} +6ms
  waku:nwaku RPC Query:  post_waku_v2_relay_v1_message [
  '/waku/2/default-waku/proto',
  {
    payload: '0a',
    contentTopic: '/test/1/waku-store/utf8',
    timestamp: 1674193819424000000n
  }
] +1ms
  waku:nwaku RPC Response:  {"jsonrpc":"2.0","id":1,"result":true} +6ms
  waku:nwaku RPC Query:  post_waku_v2_relay_v1_message [
  '/waku/2/default-waku/proto',
  {
    payload: '0b',
    contentTopic: '/test/1/waku-store/utf8',
    timestamp: 1674193819431000000n
  }
] +1ms
  waku:nwaku RPC Response:  {"jsonrpc":"2.0","id":1,"result":true} +6ms
  waku:nwaku RPC Query:  post_waku_v2_relay_v1_message [
  '/waku/2/default-waku/proto',
  {
    payload: '0c',
    contentTopic: '/test/1/waku-store/utf8',
    timestamp: 1674193819438000000n
  }
] +1ms
  waku:nwaku RPC Response:  {"jsonrpc":"2.0","id":1,"result":true} +7ms
  waku:nwaku RPC Query:  post_waku_v2_relay_v1_message [
  '/waku/2/default-waku/proto',
  {
    payload: '0d',
    contentTopic: '/test/1/waku-store/utf8',
    timestamp: 1674193819445000000n
  }
] +0ms
  waku:nwaku RPC Response:  {"jsonrpc":"2.0","id":1,"result":true} +8ms
  waku:nwaku RPC Query:  post_waku_v2_relay_v1_message [
  '/waku/2/default-waku/proto',
  {
    payload: '0e',
    contentTopic: '/test/1/waku-store/utf8',
    timestamp: 1674193819453000000n
  }
] +0ms
  waku:nwaku RPC Response:  {"jsonrpc":"2.0","id":1,"result":true} +7ms
  waku:nwaku RPC Query:  post_waku_v2_relay_v1_message [
  '/waku/2/default-waku/proto',
  {
    payload: '0f',
    contentTopic: '/test/1/waku-store/utf8',
    timestamp: 1674193819461000000n
  }
] +1ms
  waku:nwaku RPC Response:  {"jsonrpc":"2.0","id":1,"result":true} +6ms
  waku:nwaku RPC Query:  post_waku_v2_relay_v1_message [
  '/waku/2/default-waku/proto',
  {
    payload: '10',
    contentTopic: '/test/1/waku-store/utf8',
    timestamp: 1674193819467000000n
  }
] +0ms
  waku:nwaku RPC Response:  {"jsonrpc":"2.0","id":1,"result":true} +7ms
  waku:nwaku RPC Query:  post_waku_v2_relay_v1_message [
  '/waku/2/default-waku/proto',
  {
    payload: '11',
    contentTopic: '/test/1/waku-store/utf8',
    timestamp: 1674193819475000000n
  }
] +1ms
  waku:nwaku RPC Response:  {"jsonrpc":"2.0","id":1,"result":true} +6ms
  waku:nwaku RPC Query:  post_waku_v2_relay_v1_message [
  '/waku/2/default-waku/proto',
  {
    payload: '12',
    contentTopic: '/test/1/waku-store/utf8',
    timestamp: 1674193819482000000n
  }
] +1ms
  waku:nwaku RPC Response:  {"jsonrpc":"2.0","id":1,"result":true} +7ms
  waku:nwaku RPC Query:  post_waku_v2_relay_v1_message [
  '/waku/2/default-waku/proto',
  {
    payload: '13',
    contentTopic: '/test/1/waku-store/utf8',
    timestamp: 1674193819489000000n
  }
] +0ms
  waku:nwaku RPC Response:  {"jsonrpc":"2.0","id":1,"result":true} +6ms
  waku:waku Waku node created 12D3KooWAsQqEPpwncpMS9MMDkshKHzZWLPd4Xh1C94JxywkWUA5 relay: false, store: true, light push: true, filter: true, peer exchange: true  +0ms
  waku:nwaku RPC Query:  get_waku_v2_debug_v1_info [] +406ms
  waku:nwaku RPC Response:  {"jsonrpc":"2.0","id":1,"result":{"listenAddresses":["/ip4/127.0.0.1/tcp/34097/p2p/16Uiu2HAm6pw3JzpCCJY8f6YPUgiur65R3Ze6vvnh5D5bjsEJFdmi","/ip4/127.0.0.1/tcp/34098/ws/p2p/16Uiu2HAm6pw3JzpCCJY8f6YPUgiur65R3Ze6vvnh5D5bjsEJFdmi"],"enrUri":"enr:-KO4QPJ54S-f-6rLtBWeE167Q-fmjqRpNQb6rmo0LQ8Vpj0NSVpC6bjHxvsVjKAlzAi8T9uiOQfZHwCVy6eUQFi74TUBgmlkgnY0gmlwhH8AAAGKbXVsdGlhZGRyc4wACgR_AAABBoUy3QOJc2VjcDI1NmsxoQKpZfGlPpAPEItcqIbIZoQGZVyWl4AnTV_y802TiyY0EYN0Y3CChTGFd2FrdTIL"}} +6ms
  waku:waku Dialing to /ip4/127.0.0.1/tcp/34098/ws/p2p/16Uiu2HAm6pw3JzpCCJY8f6YPUgiur65R3Ze6vvnh5D5bjsEJFdmi with protocols store,filter,lightpush,peer-exchange +147ms
  waku:wait-for-remote-peer /vac/waku/store/2.0.0-beta4 peer found:  16Uiu2HAm6pw3JzpCCJY8f6YPUgiur65R3Ze6vvnh5D5bjsEJFdmi +0ms
  waku:store Querying history with the following options { peerId: undefined } +0ms
  waku:libp2p-utils Using codec /vac/waku/store/2.0.0-beta4 +0ms
  waku:store Querying store peer /ip4/127.0.0.1/tcp/34098/ws/p2p/16Uiu2HAm6pw3JzpCCJY8f6YPUgiur65R3Ze6vvnh5D5bjsEJFdmi for (/waku/2/default-waku/proto) [ '/test/1/waku-store/utf8' ] +53ms
  waku:store 5 messages retrieved from store +28ms
  waku:store Querying store peer /ip4/127.0.0.1/tcp/34098/ws/p2p/16Uiu2HAm6pw3JzpCCJY8f6YPUgiur65R3Ze6vvnh5D5bjsEJFdmi for (/waku/2/default-waku/proto) [ '/test/1/waku-store/utf8' ] +57ms
  waku:store 5 messages retrieved from store +56ms
  waku:store Querying store peer /ip4/127.0.0.1/tcp/34098/ws/p2p/16Uiu2HAm6pw3JzpCCJY8f6YPUgiur65R3Ze6vvnh5D5bjsEJFdmi for (/waku/2/default-waku/proto) [ '/test/1/waku-store/utf8' ] +60ms
  waku:store 5 messages retrieved from store +57ms
  waku:store Querying store peer /ip4/127.0.0.1/tcp/34098/ws/p2p/16Uiu2HAm6pw3JzpCCJY8f6YPUgiur65R3Ze6vvnh5D5bjsEJFdmi for (/waku/2/default-waku/proto) [ '/test/1/waku-store/utf8' ] +61ms
  waku:store 5 messages retrieved from store +55ms
  waku:store Querying store peer /ip4/127.0.0.1/tcp/34098/ws/p2p/16Uiu2HAm6pw3JzpCCJY8f6YPUgiur65R3Ze6vvnh5D5bjsEJFdmi for (/waku/2/default-waku/proto) [ '/test/1/waku-store/utf8' ] +58ms
  waku:store 5 messages retrieved from store +54ms
  waku:store Querying store peer /ip4/127.0.0.1/tcp/34098/ws/p2p/16Uiu2HAm6pw3JzpCCJY8f6YPUgiur65R3Ze6vvnh5D5bjsEJFdmi for (/waku/2/default-waku/proto) [ '/test/1/waku-store/utf8' ] +56ms
  waku:store 5 messages retrieved from store +57ms
  waku:store Querying store peer /ip4/127.0.0.1/tcp/34098/ws/p2p/16Uiu2HAm6pw3JzpCCJY8f6YPUgiur65R3Ze6vvnh5D5bjsEJFdmi for (/waku/2/default-waku/proto) [ '/test/1/waku-store/utf8' ] +59ms
  waku:store 5 messages retrieved from store +56ms
  waku:store Querying store peer /ip4/127.0.0.1/tcp/34098/ws/p2p/16Uiu2HAm6pw3JzpCCJY8f6YPUgiur65R3Ze6vvnh5D5bjsEJFdmi for (/waku/2/default-waku/proto) [ '/test/1/waku-store/utf8' ] +56ms
  waku:store 5 messages retrieved from store +54ms
  waku:store Querying store peer /ip4/127.0.0.1/tcp/34098/ws/p2p/16Uiu2HAm6pw3JzpCCJY8f6YPUgiur65R3Ze6vvnh5D5bjsEJFdmi for (/waku/2/default-waku/proto) [ '/test/1/waku-store/utf8' ] +55ms
  waku:store 4 messages retrieved from store +60ms
  waku:store Stopping pagination due to `response.pagingInfo.cursor` missing from store response +0ms
[
  14, 15, 16, 17, 18, 12, 13, 14, 15, 16,
  10, 11, 12, 13, 14,  8,  9, 10, 11, 12,
   6,  7,  8,  9, 10,  4,  5,  6,  7,  8,
   2,  3,  4,  5,  6,  0,  1,  2,  3,  4,
   0,  1,  2,  3
]
  waku:nwaku nwaku 958844 getting SIGINT at 4:50:21 pm +1s
  waku:nwaku nwaku 958844 interrupted: true +0ms
  waku:nwaku nwaku 958844 process exited with 0 at 4:50:21 pm +24ms

AssertionError: expected 44 to equal 20
Expected :20
Actual   :44
<Click to see difference>

    at Context.<anonymous> (file:///home/fryorcraken/src/waku-org/js-waku/packages/tests/tests/store.node.spec.ts:93:30)
    at processTicksAndRejections (node:internal/process/task_queues:96:5)


[
  14, 15, 16, 17, 18, 12, 13, 14, 15, 16,
  10, 11, 12, 13, 14,  8,  9, 10, 11, 12,
   6,  7,  8,  9, 10,  4,  5,  6,  7,  8,
   2,  3,  4,  5,  6,  0,  1,  2,  3,  4,
   0,  1,  2,  3
]

Shows the dupe messages.

nwaku version/commit hash

  • e.g. v0.14.0
@fryorcraken fryorcraken added bug Something isn't working critical This issue needs critical attention track:maintenance labels Jan 20, 2023
@fryorcraken fryorcraken mentioned this issue Jan 20, 2023
Closed
@fryorcraken
Copy link
Collaborator Author

I expect the setup above to use the in-memory db. As nwaku uses sqlite by default, I have changed the js-waku test harness to also use sqlite. This resulted in the same behaviour.

commit that replaces the usage of in-memory db with sqlite: waku-org/js-waku@60b7912

nwaku logs:
nwaku_Waku_Store_Generator.log

js-waku logs:

  waku:nwaku nwaku args: --listen-address=127.0.0.1 --rpc=true --relay=true --rpc-admin=true --websocket-support=true --log-level=TRACE --tcp-port=48773 --rpc-port=48772 --websocket-port=48774 --store=true --lightpush=true --store-message-db-url=sqlite://ygyqj.sqlite3 +0ms
  waku:nwaku nwaku 1593672 started at 2:11:05 pm +129ms
  waku:nwaku Waiting to see 'Node setup complete' in nwaku logs +1ms
  waku:nwaku nwaku node has been started +4s
  waku:nwaku RPC Query:  post_waku_v2_relay_v1_message [
  '/waku/2/default-waku/proto',
  {
    payload: '00',
    contentTopic: '/test/1/waku-store/utf8',
    timestamp: 1674443469497000000n
  }
] +5ms
  waku:nwaku RPC Response:  {"jsonrpc":"2.0","id":1,"result":true} +63ms
  waku:nwaku RPC Query:  post_waku_v2_relay_v1_message [
  '/waku/2/default-waku/proto',
  {
    payload: '01',
    contentTopic: '/test/1/waku-store/utf8',
    timestamp: 1674443469561000000n
  }
] +1ms
  waku:nwaku RPC Response:  {"jsonrpc":"2.0","id":1,"result":true} +15ms
  waku:nwaku RPC Query:  post_waku_v2_relay_v1_message [
  '/waku/2/default-waku/proto',
  {
    payload: '02',
    contentTopic: '/test/1/waku-store/utf8',
    timestamp: 1674443469576000000n
  }
] +0ms
  waku:nwaku RPC Response:  {"jsonrpc":"2.0","id":1,"result":true} +11ms
  waku:nwaku RPC Query:  post_waku_v2_relay_v1_message [
  '/waku/2/default-waku/proto',
  {
    payload: '03',
    contentTopic: '/test/1/waku-store/utf8',
    timestamp: 1674443469588000000n
  }
] +1ms
  waku:nwaku RPC Response:  {"jsonrpc":"2.0","id":1,"result":true} +11ms
  waku:nwaku RPC Query:  post_waku_v2_relay_v1_message [
  '/waku/2/default-waku/proto',
  {
    payload: '04',
    contentTopic: '/test/1/waku-store/utf8',
    timestamp: 1674443469599000000n
  }
] +0ms
  waku:nwaku RPC Response:  {"jsonrpc":"2.0","id":1,"result":true} +11ms
  waku:nwaku RPC Query:  post_waku_v2_relay_v1_message [
  '/waku/2/default-waku/proto',
  {
    payload: '05',
    contentTopic: '/test/1/waku-store/utf8',
    timestamp: 1674443469610000000n
  }
] +0ms
  waku:nwaku RPC Response:  {"jsonrpc":"2.0","id":1,"result":true} +10ms
  waku:nwaku RPC Query:  post_waku_v2_relay_v1_message [
  '/waku/2/default-waku/proto',
  {
    payload: '06',
    contentTopic: '/test/1/waku-store/utf8',
    timestamp: 1674443469620000000n
  }
] +0ms
  waku:nwaku RPC Response:  {"jsonrpc":"2.0","id":1,"result":true} +10ms
  waku:nwaku RPC Query:  post_waku_v2_relay_v1_message [
  '/waku/2/default-waku/proto',
  {
    payload: '07',
    contentTopic: '/test/1/waku-store/utf8',
    timestamp: 1674443469630000000n
  }
] +0ms
  waku:nwaku RPC Response:  {"jsonrpc":"2.0","id":1,"result":true} +9ms
  waku:nwaku RPC Query:  post_waku_v2_relay_v1_message [
  '/waku/2/default-waku/proto',
  {
    payload: '08',
    contentTopic: '/test/1/waku-store/utf8',
    timestamp: 1674443469640000000n
  }
] +1ms
  waku:nwaku RPC Response:  {"jsonrpc":"2.0","id":1,"result":true} +11ms
  waku:nwaku RPC Query:  post_waku_v2_relay_v1_message [
  '/waku/2/default-waku/proto',
  {
    payload: '09',
    contentTopic: '/test/1/waku-store/utf8',
    timestamp: 1674443469652000000n
  }
] +1ms
  waku:nwaku RPC Response:  {"jsonrpc":"2.0","id":1,"result":true} +10ms
  waku:nwaku RPC Query:  post_waku_v2_relay_v1_message [
  '/waku/2/default-waku/proto',
  {
    payload: '0a',
    contentTopic: '/test/1/waku-store/utf8',
    timestamp: 1674443469662000000n
  }
] +0ms
  waku:nwaku RPC Response:  {"jsonrpc":"2.0","id":1,"result":true} +10ms
  waku:nwaku RPC Query:  post_waku_v2_relay_v1_message [
  '/waku/2/default-waku/proto',
  {
    payload: '0b',
    contentTopic: '/test/1/waku-store/utf8',
    timestamp: 1674443469673000000n
  }
] +1ms
  waku:nwaku RPC Response:  {"jsonrpc":"2.0","id":1,"result":true} +10ms
  waku:nwaku RPC Query:  post_waku_v2_relay_v1_message [
  '/waku/2/default-waku/proto',
  {
    payload: '0c',
    contentTopic: '/test/1/waku-store/utf8',
    timestamp: 1674443469683000000n
  }
] +0ms
  waku:nwaku RPC Response:  {"jsonrpc":"2.0","id":1,"result":true} +10ms
  waku:nwaku RPC Query:  post_waku_v2_relay_v1_message [
  '/waku/2/default-waku/proto',
  {
    payload: '0d',
    contentTopic: '/test/1/waku-store/utf8',
    timestamp: 1674443469694000000n
  }
] +1ms
  waku:nwaku RPC Response:  {"jsonrpc":"2.0","id":1,"result":true} +10ms
  waku:nwaku RPC Query:  post_waku_v2_relay_v1_message [
  '/waku/2/default-waku/proto',
  {
    payload: '0e',
    contentTopic: '/test/1/waku-store/utf8',
    timestamp: 1674443469704000000n
  }
] +0ms
  waku:nwaku RPC Response:  {"jsonrpc":"2.0","id":1,"result":true} +8ms
  waku:nwaku RPC Query:  post_waku_v2_relay_v1_message [
  '/waku/2/default-waku/proto',
  {
    payload: '0f',
    contentTopic: '/test/1/waku-store/utf8',
    timestamp: 1674443469712000000n
  }
] +0ms
  waku:nwaku RPC Response:  {"jsonrpc":"2.0","id":1,"result":true} +9ms
  waku:nwaku RPC Query:  post_waku_v2_relay_v1_message [
  '/waku/2/default-waku/proto',
  {
    payload: '10',
    contentTopic: '/test/1/waku-store/utf8',
    timestamp: 1674443469721000000n
  }
] +0ms
  waku:nwaku RPC Response:  {"jsonrpc":"2.0","id":1,"result":true} +10ms
  waku:nwaku RPC Query:  post_waku_v2_relay_v1_message [
  '/waku/2/default-waku/proto',
  {
    payload: '11',
    contentTopic: '/test/1/waku-store/utf8',
    timestamp: 1674443469732000000n
  }
] +1ms
  waku:nwaku RPC Response:  {"jsonrpc":"2.0","id":1,"result":true} +9ms
  waku:nwaku RPC Query:  post_waku_v2_relay_v1_message [
  '/waku/2/default-waku/proto',
  {
    payload: '12',
    contentTopic: '/test/1/waku-store/utf8',
    timestamp: 1674443469741000000n
  }
] +0ms
  waku:nwaku RPC Response:  {"jsonrpc":"2.0","id":1,"result":true} +10ms
  waku:nwaku RPC Query:  post_waku_v2_relay_v1_message [
  '/waku/2/default-waku/proto',
  {
    payload: '13',
    contentTopic: '/test/1/waku-store/utf8',
    timestamp: 1674443469751000000n
  }
] +0ms
  waku:nwaku RPC Response:  {"jsonrpc":"2.0","id":1,"result":true} +10ms
  waku:waku Waku node created 12D3KooWA31yXnwcrMa4xdQZXs6GwgdDUZjUyoBrN4TLoSHmJdsZ relay: false, store: true, light push: true, filter: true, peer exchange: true  +0ms
  waku:nwaku RPC Query:  get_waku_v2_debug_v1_info [] +477ms
  waku:nwaku RPC Response:  {"jsonrpc":"2.0","id":1,"result":{"listenAddresses":["/ip4/127.0.0.1/tcp/48773/p2p/16Uiu2HAky9TLTHneWMPEcsgxLH5XzwPxGyYnq7VR6JvGQ5r6siGs","/ip4/127.0.0.1/tcp/48774/ws/p2p/16Uiu2HAky9TLTHneWMPEcsgxLH5XzwPxGyYnq7VR6JvGQ5r6siGs"],"enrUri":"enr:-KO4QCf8bO0zdJNbmM4XrC9-1YmI410uhzxkluhyNrnfP8AvCeHsApydLetCGLNmLAF6_Dcim1Z6CHw3rhWZNfdg22EBgmlkgnY0gmlwhH8AAAGKbXVsdGlhZGRyc4wACgR_AAABBr6G3QOJc2VjcDI1NmsxoQI3RyiMKvo4ZVlO7vyVNuKzwQc4ON6ujhqvGUMVRqVmnIN0Y3CCvoWFd2FrdTIL"}} +8ms
  waku:waku Dialing to /ip4/127.0.0.1/tcp/48774/ws/p2p/16Uiu2HAky9TLTHneWMPEcsgxLH5XzwPxGyYnq7VR6JvGQ5r6siGs with protocols store,filter,lightpush,peer-exchange +154ms
  waku:wait-for-remote-peer /vac/waku/store/2.0.0-beta4 peer found:  16Uiu2HAky9TLTHneWMPEcsgxLH5XzwPxGyYnq7VR6JvGQ5r6siGs +0ms
  waku:store Querying history with the following options { peerId: undefined } +0ms
  waku:libp2p-utils Using codec /vac/waku/store/2.0.0-beta4 +0ms
  waku:store Querying store peer /ip4/127.0.0.1/tcp/48774/ws/p2p/16Uiu2HAky9TLTHneWMPEcsgxLH5XzwPxGyYnq7VR6JvGQ5r6siGs for (/waku/2/default-waku/proto) [ '/test/1/waku-store/utf8' ] +52ms
  waku:store 5 messages retrieved from store +42ms
  waku:store Querying store peer /ip4/127.0.0.1/tcp/48774/ws/p2p/16Uiu2HAky9TLTHneWMPEcsgxLH5XzwPxGyYnq7VR6JvGQ5r6siGs for (/waku/2/default-waku/proto) [ '/test/1/waku-store/utf8' ] +60ms
  waku:store 5 messages retrieved from store +58ms
  waku:store Querying store peer /ip4/127.0.0.1/tcp/48774/ws/p2p/16Uiu2HAky9TLTHneWMPEcsgxLH5XzwPxGyYnq7VR6JvGQ5r6siGs for (/waku/2/default-waku/proto) [ '/test/1/waku-store/utf8' ] +64ms
  waku:store 5 messages retrieved from store +56ms
  waku:store Querying store peer /ip4/127.0.0.1/tcp/48774/ws/p2p/16Uiu2HAky9TLTHneWMPEcsgxLH5XzwPxGyYnq7VR6JvGQ5r6siGs for (/waku/2/default-waku/proto) [ '/test/1/waku-store/utf8' ] +62ms
  waku:store 5 messages retrieved from store +56ms
  waku:store Querying store peer /ip4/127.0.0.1/tcp/48774/ws/p2p/16Uiu2HAky9TLTHneWMPEcsgxLH5XzwPxGyYnq7VR6JvGQ5r6siGs for (/waku/2/default-waku/proto) [ '/test/1/waku-store/utf8' ] +58ms
  waku:store 5 messages retrieved from store +54ms
  waku:store Querying store peer /ip4/127.0.0.1/tcp/48774/ws/p2p/16Uiu2HAky9TLTHneWMPEcsgxLH5XzwPxGyYnq7VR6JvGQ5r6siGs for (/waku/2/default-waku/proto) [ '/test/1/waku-store/utf8' ] +56ms
  waku:store 5 messages retrieved from store +55ms
  waku:store Querying store peer /ip4/127.0.0.1/tcp/48774/ws/p2p/16Uiu2HAky9TLTHneWMPEcsgxLH5XzwPxGyYnq7VR6JvGQ5r6siGs for (/waku/2/default-waku/proto) [ '/test/1/waku-store/utf8' ] +56ms
  waku:store 5 messages retrieved from store +53ms
  waku:store Querying store peer /ip4/127.0.0.1/tcp/48774/ws/p2p/16Uiu2HAky9TLTHneWMPEcsgxLH5XzwPxGyYnq7VR6JvGQ5r6siGs for (/waku/2/default-waku/proto) [ '/test/1/waku-store/utf8' ] +57ms
  waku:store 5 messages retrieved from store +54ms
  waku:store Querying store peer /ip4/127.0.0.1/tcp/48774/ws/p2p/16Uiu2HAky9TLTHneWMPEcsgxLH5XzwPxGyYnq7VR6JvGQ5r6siGs for (/waku/2/default-waku/proto) [ '/test/1/waku-store/utf8' ] +55ms
  waku:store 4 messages retrieved from store +55ms
  waku:store Stopping pagination due to `response.pagingInfo.cursor` missing from store response +0ms
[
  14, 15, 16, 17, 18, 12, 13, 14, 15, 16,
  10, 11, 12, 13, 14,  8,  9, 10, 11, 12,
   6,  7,  8,  9, 10,  4,  5,  6,  7,  8,
   2,  3,  4,  5,  6,  0,  1,  2,  3,  4,
   0,  1,  2,  3
]
  waku:nwaku nwaku 1593672 getting SIGINT at 2:11:11 pm +1s
  waku:nwaku nwaku 1593672 interrupted: true +0ms
  waku:nwaku Deleting db file ygyqj.sqlite3 +0ms
  waku:nwaku Failed to clean store file [Error: ENOENT: no such file or directory, stat 'ygyqj.sqlite3'] {
  errno: -2,
  code: 'ENOENT',
  syscall: 'stat',
  path: 'ygyqj.sqlite3'
} +25ms
  waku:nwaku nwaku 1593672 process exited with 0 at 2:11:11 pm +2ms

AssertionError: expected 44 to equal 20
Expected :20
Actual   :44
<Click to see difference>

    at Context.<anonymous> (file:///home/fryorcraken/src/waku-org/js-waku/packages/tests/tests/store.node.spec.ts:93:30)
    at processTicksAndRejections (node:internal/process/task_queues:96:5)

@LNSD
Copy link
Contributor

LNSD commented Jan 24, 2023 •
edited
Loading

So, if I understood correctly, the scenario is as follows:

Given a wakunode instance with "JSON-RPC API server", "Waku relay", "Waku store" and "Waku archive" capabilities enabled
When a js-waku client connects to this node's JSON-RPC API server
  And using the relay JSON-RPC API publishes 20 messages (via "post_waku_v2_relay_v1_message")
Then the 20 messages should be relayed to the network (pub-sub topic)
 And the 20 messages should be persisted in the node's Waku archive (in the DB)
 And the 20 messages stored in the Waku archive should be retrievable via the Waku store query protocol.

Is this correct?

@LNSD
Copy link
Contributor

LNSD commented Jan 24, 2023 •
edited
Loading

Based on the previous scenario, I did some tests:

  • The messages get published and inserted in the Waku archive database using the JSON-RPC API. I can confirm that the database file contains 20 messages ✅
  • With the 20 messages in the database, I query all the messages using the Waku store protocols with a page limit of 5 (so 4 queries are sent/received in total). The 20 messages are retrieved without duplicates ✅

@LNSD
Copy link
Contributor

LNSD commented Jan 24, 2023

Checking your logs I see something that looks suspicious:

  waku:store Querying store peer /ip4/127.0.0.1/tcp/48774/ws/p2p/16Uiu2HAky9TLTHneWMPEcsgxLH5XzwPxGyYnq7VR6JvGQ5r6siGs for (/waku/2/default-waku/proto) [ '/test/1/waku-store/utf8' ] +52ms
  waku:store 5 messages retrieved from store +42ms
  waku:store Querying store peer /ip4/127.0.0.1/tcp/48774/ws/p2p/16Uiu2HAky9TLTHneWMPEcsgxLH5XzwPxGyYnq7VR6JvGQ5r6siGs for (/waku/2/default-waku/proto) [ '/test/1/waku-store/utf8' ] +60ms
  waku:store 5 messages retrieved from store +58ms
  waku:store Querying store peer /ip4/127.0.0.1/tcp/48774/ws/p2p/16Uiu2HAky9TLTHneWMPEcsgxLH5XzwPxGyYnq7VR6JvGQ5r6siGs for (/waku/2/default-waku/proto) [ '/test/1/waku-store/utf8' ] +64ms
  waku:store 5 messages retrieved from store +56ms
  waku:store Querying store peer /ip4/127.0.0.1/tcp/48774/ws/p2p/16Uiu2HAky9TLTHneWMPEcsgxLH5XzwPxGyYnq7VR6JvGQ5r6siGs for (/waku/2/default-waku/proto) [ '/test/1/waku-store/utf8' ] +62ms
  waku:store 5 messages retrieved from store +56ms
  waku:store Querying store peer /ip4/127.0.0.1/tcp/48774/ws/p2p/16Uiu2HAky9TLTHneWMPEcsgxLH5XzwPxGyYnq7VR6JvGQ5r6siGs for (/waku/2/default-waku/proto) [ '/test/1/waku-store/utf8' ] +58ms
  waku:store 5 messages retrieved from store +54ms
  waku:store Querying store peer /ip4/127.0.0.1/tcp/48774/ws/p2p/16Uiu2HAky9TLTHneWMPEcsgxLH5XzwPxGyYnq7VR6JvGQ5r6siGs for (/waku/2/default-waku/proto) [ '/test/1/waku-store/utf8' ] +56ms
  waku:store 5 messages retrieved from store +55ms
  waku:store Querying store peer /ip4/127.0.0.1/tcp/48774/ws/p2p/16Uiu2HAky9TLTHneWMPEcsgxLH5XzwPxGyYnq7VR6JvGQ5r6siGs for (/waku/2/default-waku/proto) [ '/test/1/waku-store/utf8' ] +56ms
  waku:store 5 messages retrieved from store +53ms
  waku:store Querying store peer /ip4/127.0.0.1/tcp/48774/ws/p2p/16Uiu2HAky9TLTHneWMPEcsgxLH5XzwPxGyYnq7VR6JvGQ5r6siGs for (/waku/2/default-waku/proto) [ '/test/1/waku-store/utf8' ] +57ms
  waku:store 5 messages retrieved from store +54ms
  waku:store Querying store peer /ip4/127.0.0.1/tcp/48774/ws/p2p/16Uiu2HAky9TLTHneWMPEcsgxLH5XzwPxGyYnq7VR6JvGQ5r6siGs for (/waku/2/default-waku/proto) [ '/test/1/waku-store/utf8' ] +55ms
  waku:store 4 messages retrieved from store +55ms
  waku:store Stopping pagination due to `response.pagingInfo.cursor` missing from store response +0ms

I see that it performs 9 queries before receiving an empty cursor. If there are only 20 messages in the archive, the queries can't retrieve 44 items. I need to check the "query chain" criteria.

@LNSD
Copy link
Contributor

LNSD commented Jan 24, 2023 •
edited
Loading

Ok, the issue seems that is related to the "backwards" pagination. I managed to reproduce it with a backwards pagination query chain.

INF 2023-01-24 20:04:54.015+01:00 query response  topics="periscope" tid=1286629 iteration=1 batch=1 count=44 min_duration=2.334056 max_duration=271.192535
INF 2023-01-24 20:04:54.015+01:00 query response  topics="periscope" tid=1286629 payloads="@[15, 16, 17, 18, 19, 13, 14, 15, 16, 17, 11, 12, 13, 14, 15, 9, 10, 11, 12, 13, 7, 8, 9, 10, 11, 5, 6, 7, 8, 9, 3, 4, 5, 6, 7, 1, 2, 3, 4, 5, 1, 2, 3, 4]"

@fryorcraken @jm-clius I have one question:

Which use case are we trying to cover by supporting backwards pagination over the Waku store protocol?

@fryorcraken
Copy link
Collaborator Author

@fryorcraken @jm-clius I have one question:

Which use case are we trying to cover by supporting backwards pagination over the Waku store protocol?

In a scenario where the app is freshly loaded and hence does not have knowledge of any previous messages (can;t create a cursor), I'd expect backward pagination to be used to retrieve and display latest messages first.

Most likely (and contrary to the test), the pagination would stop on a user/app defined criteria which would likely be based on the number of messages retrieved.

Then moving forward, the app can store the oldest/earliest messages and do further queries based on user action/network state using a cursor.

@LNSD LNSD mentioned this issue Jan 25, 2023
Merged
3 tasks
@fryorcraken
Copy link
Collaborator Author

Confirmed fixed. Found new issue: #1514

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@LNSD LNSD

Labels
bug Something isn't working critical This issue needs critical attention
Projects
Waku
Archived in project
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

fix(archive): reverse the db query results in the waku archive front-end waku-org/nwaku
2 participants
@LNSD @fryorcraken