109 lines
18 KiB
Plaintext

2025-12-11 04:14:24.786 DEBUG [tests.conftest] Running fixture setup: test_id
2025-12-11 04:14:24.787 DEBUG [tests.conftest] Running test: test_cursor_pointing_to_deleted_message with id: 2025-12-11_04-14-24__8980af62-6cea-41ad-9df8-581223084b6f
2025-12-11 04:14:24.787 DEBUG [src.steps.common] Running fixture setup: common_setup
2025-12-11 04:14:24.787 DEBUG [src.steps.store] Running fixture setup: store_setup
2025-12-11 04:14:24.787 DEBUG [src.steps.store] Running fixture setup: node_setup
2025-12-11 04:14:24.794 DEBUG [src.node.docker_mananger] Docker client initialized with image wakuorg/nwaku:latest
2025-12-11 04:14:24.794 DEBUG [src.node.waku_node] WakuNode instance initialized with log path ./log/docker/publishing_node1_2025-12-11_04-14-24__8980af62-6cea-41ad-9df8-581223084b6f__wakuorg_nwaku:latest.log
2025-12-11 04:14:24.794 DEBUG [src.node.waku_node] Starting Node...
2025-12-11 04:14:24.794 DEBUG [src.node.docker_mananger] Attempting to create or retrieve network waku
2025-12-11 04:14:24.796 DEBUG [src.node.docker_mananger] Network waku already exists
2025-12-11 04:14:24.796 DEBUG [src.node.docker_mananger] Generated random external IP 172.18.152.8
2025-12-11 04:14:24.796 DEBUG [src.node.docker_mananger] Generated ports ['44484', '44485', '44486', '44487', '44488']
2025-12-11 04:14:24.796 DEBUG [src.node.waku_node] RLN credentials were not set
2025-12-11 04:14:24.796 INFO [src.node.waku_node] RLN credentials not set or credential store not available, starting without RLN
2025-12-11 04:14:24.797 DEBUG [src.node.waku_node] Using volumes []
2025-12-11 04:14:24.797 DEBUG [src.node.docker_mananger] docker run -i -t -p 44484:44484 -p 44485:44485 -p 44486:44486 -p 44487:44487 -p 44488:44488 wakuorg/nwaku:latest --listen-address=0.0.0.0 --rest=true --rest-admin=true --websocket-support=true --log-level=TRACE --rest-relay-cache-capacity=100 --websocket-port=44486 --rest-port=44484 --tcp-port=44485 --discv5-udp-port=44487 --rest-address=0.0.0.0 --nat=extip:172.18.152.8 --peer-exchange=true --discv5-discovery=true --cluster-id=3 --nodekey=cc6dfccdb2fbcfea6e4e82b6d168df4a51692bdfdf1ac5b7fedfba68b510dadb --shard=0 --metrics-server=true --metrics-server-address=0.0.0.0 --metrics-server-port=44488 --metrics-logging=true --store=true --relay=true
2025-12-11 04:14:24.984 DEBUG [src.node.docker_mananger] docker network connect --ip 172.18.152.8 waku 11765908753ccd727e6cc222cfe340a864f1273b8084f35c60a8c7a0148bfc18
2025-12-11 04:14:25.015 DEBUG [src.node.docker_mananger] Container started with ID 11765908753c. Setting up logs at ./log/docker/publishing_node1_2025-12-11_04-14-24__8980af62-6cea-41ad-9df8-581223084b6f__wakuorg_nwaku:latest.log
2025-12-11 04:14:25.016 DEBUG [src.node.waku_node] Started container from image wakuorg/nwaku:latest. REST: 44484
2025-12-11 04:14:25.017 DEBUG [src.libs.common] Sleeping for 1 seconds
2025-12-11 04:14:25.024 ERROR [src.node.docker_mananger] Max retries reached for container 6c554ec60318. Exiting log stream.
2025-12-11 04:14:25.583 ERROR [src.node.docker_mananger] Max retries reached for container 1b5fb5f365dd. Exiting log stream.
2025-12-11 04:14:26.018 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:44484/health" -H "Content-Type: application/json" -d 'None'
2025-12-11 04:14:26.022 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"nodeHealth":"READY","protocolsHealth":[{"Relay":"NOT_READY","desc":"No connected peers"},{"Rln Relay":"NOT_MOUNTED"},{"Lightpush":"NOT_MOUNTED"},{"Legacy Lightpush":"NOT_MOUNTED"},{"Filter":"NOT_MOUNTED"},{"Store":"READY"},{"Legacy Store":"NOT_MOUNTED"},{"Peer Exchange":"READY"},{"Rendezvous":"NOT_READY","desc":"No Rendezvous peers are available yet"},{"Mix":"NOT_MOUNTED"},{"Lightpush Client":"NOT_READY","desc":"No Lightpush service peer available yet"},{"Legacy Lightpush Client":"NOT_READY","desc":"No Lightpush service peer available yet"},{"Store Client":"READY"},{"Legacy Store Client":"NOT_READY","desc":"No Legacy Store service peers are available yet, neither Store service set up for the node"},{"Filter Client":"NOT_READY","desc":"No Filter service peer available yet"}]}'
2025-12-11 04:14:26.022 INFO [src.node.waku_node] Node protocols are initialized !!
2025-12-11 04:14:26.022 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:44484/debug/v1/info" -H "Content-Type: application/json" -d 'None'
2025-12-11 04:14:26.024 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"listenAddresses":["/ip4/172.18.152.8/tcp/44485/p2p/16Uiu2HAm6ApY1MtUtC9etageT2NUkB6CQBQDkdXjz3FPTcXDhaEY","/ip4/172.18.152.8/tcp/44486/ws/p2p/16Uiu2HAm6ApY1MtUtC9etageT2NUkB6CQBQDkdXjz3FPTcXDhaEY"],"enrUri":"enr:-L24QP-Z6tInCtq4_g9wFZVuMWxXwUIKCs_4lGtcA_pQAnpnFlOWRvD9yOiBCRCj096xnp_d8RuuqIbOQphyPAi93eQCgmlkgnY0gmlwhKwSmAiKbXVsdGlhZGRyc5YACASsEpgIBq3FAAoErBKYCAatxt0DgnJzhQADAQAAiXNlY3AyNTZrMaECn6KEhsRrYPR8KjklrubNiv6XJxcpYHAJqDoyuIyBTjWDdGNwgq3Fg3VkcIKtx4V3YWt1MgM"}'
2025-12-11 04:14:26.024 INFO [src.node.waku_node] REST service is ready !!
2025-12-11 04:14:26.031 DEBUG [src.node.docker_mananger] Docker client initialized with image wakuorg/nwaku:latest
2025-12-11 04:14:26.031 DEBUG [src.node.waku_node] WakuNode instance initialized with log path ./log/docker/store_node1_2025-12-11_04-14-24__8980af62-6cea-41ad-9df8-581223084b6f__wakuorg_nwaku:latest.log
2025-12-11 04:14:26.031 DEBUG [src.node.waku_node] Starting Node...
2025-12-11 04:14:26.032 DEBUG [src.node.docker_mananger] Attempting to create or retrieve network waku
2025-12-11 04:14:26.033 DEBUG [src.node.docker_mananger] Network waku already exists
2025-12-11 04:14:26.033 DEBUG [src.node.docker_mananger] Generated random external IP 172.18.233.17
2025-12-11 04:14:26.033 DEBUG [src.node.docker_mananger] Generated ports ['62018', '62019', '62020', '62021', '62022']
2025-12-11 04:14:26.033 DEBUG [src.node.waku_node] RLN credentials were not set
2025-12-11 04:14:26.033 INFO [src.node.waku_node] RLN credentials not set or credential store not available, starting without RLN
2025-12-11 04:14:26.034 DEBUG [src.node.waku_node] Using volumes []
2025-12-11 04:14:26.034 DEBUG [src.node.docker_mananger] docker run -i -t -p 62018:62018 -p 62019:62019 -p 62020:62020 -p 62021:62021 -p 62022:62022 wakuorg/nwaku:latest --listen-address=0.0.0.0 --rest=true --rest-admin=true --websocket-support=true --log-level=TRACE --rest-relay-cache-capacity=100 --websocket-port=62020 --rest-port=62018 --tcp-port=62019 --discv5-udp-port=62021 --rest-address=0.0.0.0 --nat=extip:172.18.233.17 --peer-exchange=true --discv5-discovery=true --cluster-id=3 --nodekey=f7716b9d4cbadcd84dab066a95f76716be9b3fdf6bd9e3c35db24d80a8c4bedb --shard=0 --metrics-server=true --metrics-server-address=0.0.0.0 --metrics-server-port=62022 --metrics-logging=true --discv5-bootstrap-node=enr:-L24QP-Z6tInCtq4_g9wFZVuMWxXwUIKCs_4lGtcA_pQAnpnFlOWRvD9yOiBCRCj096xnp_d8RuuqIbOQphyPAi93eQCgmlkgnY0gmlwhKwSmAiKbXVsdGlhZGRyc5YACASsEpgIBq3FAAoErBKYCAatxt0DgnJzhQADAQAAiXNlY3AyNTZrMaECn6KEhsRrYPR8KjklrubNiv6XJxcpYHAJqDoyuIyBTjWDdGNwgq3Fg3VkcIKtx4V3YWt1MgM --storenode=/ip4/172.18.152.8/tcp/44485/p2p/16Uiu2HAm6ApY1MtUtC9etageT2NUkB6CQBQDkdXjz3FPTcXDhaEY --store=true --relay=true
2025-12-11 04:14:26.218 DEBUG [src.node.docker_mananger] docker network connect --ip 172.18.233.17 waku a6c35d144ea73da850d6d361b0c5a84ab96babb6616f641e432559bd635d22a8
2025-12-11 04:14:26.250 DEBUG [src.node.docker_mananger] Container started with ID a6c35d144ea7. Setting up logs at ./log/docker/store_node1_2025-12-11_04-14-24__8980af62-6cea-41ad-9df8-581223084b6f__wakuorg_nwaku:latest.log
2025-12-11 04:14:26.251 DEBUG [src.node.waku_node] Started container from image wakuorg/nwaku:latest. REST: 62018
2025-12-11 04:14:26.251 DEBUG [src.libs.common] Sleeping for 1 seconds
2025-12-11 04:14:27.251 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:62018/health" -H "Content-Type: application/json" -d 'None'
2025-12-11 04:14:27.256 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"nodeHealth":"READY","protocolsHealth":[{"Relay":"READY"},{"Rln Relay":"NOT_MOUNTED"},{"Lightpush":"NOT_MOUNTED"},{"Legacy Lightpush":"NOT_MOUNTED"},{"Filter":"NOT_MOUNTED"},{"Store":"READY"},{"Legacy Store":"NOT_MOUNTED"},{"Peer Exchange":"READY"},{"Rendezvous":"NOT_READY","desc":"No Rendezvous peers are available yet"},{"Mix":"NOT_MOUNTED"},{"Lightpush Client":"NOT_READY","desc":"No Lightpush service peer available yet"},{"Legacy Lightpush Client":"NOT_READY","desc":"No Lightpush service peer available yet"},{"Store Client":"READY"},{"Legacy Store Client":"READY"},{"Filter Client":"NOT_READY","desc":"No Filter service peer available yet"}]}'
2025-12-11 04:14:27.256 INFO [src.node.waku_node] Node protocols are initialized !!
2025-12-11 04:14:27.256 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:62018/debug/v1/info" -H "Content-Type: application/json" -d 'None'
2025-12-11 04:14:27.259 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"listenAddresses":["/ip4/172.18.233.17/tcp/62019/p2p/16Uiu2HAmRcf2jtjgXq59gGZyqpjiES2PXWFWCGXW1o52AL4NHRsH","/ip4/172.18.233.17/tcp/62020/ws/p2p/16Uiu2HAmRcf2jtjgXq59gGZyqpjiES2PXWFWCGXW1o52AL4NHRsH"],"enrUri":"enr:-L24QI3qgvpyisleq4nznO7fsa3xUqE0FhPIN8dh_yr5n7I2ZEUx8pqWCi8bf7UzGno0GytVaA865K9-Aqtvx2t1PK0CgmlkgnY0gmlwhKwS6RGKbXVsdGlhZGRyc5YACASsEukRBvJDAAoErBLpEQbyRN0DgnJzhQADAQAAiXNlY3AyNTZrMaEDwI7sZjaw0ZQWzL5-lz47VUH7l4c1jxfJjF19fUZvYrSDdGNwgvJDg3VkcILyRYV3YWt1MgM"}'
2025-12-11 04:14:27.259 INFO [src.node.waku_node] REST service is ready !!
2025-12-11 04:14:27.260 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:62018/admin/v1/peers" -H "Content-Type: application/json" -d '["/ip4/172.18.152.8/tcp/44485/p2p/16Uiu2HAm6ApY1MtUtC9etageT2NUkB6CQBQDkdXjz3FPTcXDhaEY"]'
2025-12-11 04:14:27.262 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-11 04:14:27.263 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:44484/relay/v1/subscriptions" -H "Content-Type: application/json" -d '["/waku/2/rs/3/0"]'
2025-12-11 04:14:27.265 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-11 04:14:27.265 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:62018/relay/v1/subscriptions" -H "Content-Type: application/json" -d '["/waku/2/rs/3/0"]'
2025-12-11 04:14:27.267 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-11 04:14:27.268 DEBUG [src.steps.store] Relaying message
2025-12-11 04:14:27.269 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:44484/relay/v1/messages/%2Fwaku%2F2%2Frs%2F3%2F0" -H "Content-Type: application/json" -d '{"payload": "TWVzc2FnZV8w", "contentTopic": "/myapp/1/latest/proto", "timestamp": '$(date +%s%N)'}'
2025-12-11 04:14:27.273 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-11 04:14:27.274 DEBUG [src.libs.common] Sleeping for 0.2 seconds
2025-12-11 04:14:27.474 DEBUG [src.steps.store] Relaying message
2025-12-11 04:14:27.475 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:44484/relay/v1/messages/%2Fwaku%2F2%2Frs%2F3%2F0" -H "Content-Type: application/json" -d '{"payload": "TWVzc2FnZV8x", "contentTopic": "/myapp/1/latest/proto", "timestamp": '$(date +%s%N)'}'
2025-12-11 04:14:27.480 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-11 04:14:27.480 DEBUG [src.libs.common] Sleeping for 0.2 seconds
2025-12-11 04:14:27.681 DEBUG [src.steps.store] Relaying message
2025-12-11 04:14:27.681 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:44484/relay/v1/messages/%2Fwaku%2F2%2Frs%2F3%2F0" -H "Content-Type: application/json" -d '{"payload": "TWVzc2FnZV8y", "contentTopic": "/myapp/1/latest/proto", "timestamp": '$(date +%s%N)'}'
2025-12-11 04:14:27.687 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-11 04:14:27.687 DEBUG [src.libs.common] Sleeping for 0.2 seconds
2025-12-11 04:14:27.889 DEBUG [src.steps.store] Relaying message
2025-12-11 04:14:27.889 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:44484/relay/v1/messages/%2Fwaku%2F2%2Frs%2F3%2F0" -H "Content-Type: application/json" -d '{"payload": "TWVzc2FnZV8z", "contentTopic": "/myapp/1/latest/proto", "timestamp": '$(date +%s%N)'}'
2025-12-11 04:14:27.893 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-11 04:14:27.894 DEBUG [src.libs.common] Sleeping for 0.2 seconds
2025-12-11 04:14:28.095 DEBUG [src.steps.store] Relaying message
2025-12-11 04:14:28.096 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:44484/relay/v1/messages/%2Fwaku%2F2%2Frs%2F3%2F0" -H "Content-Type: application/json" -d '{"payload": "TWVzc2FnZV80", "contentTopic": "/myapp/1/latest/proto", "timestamp": '$(date +%s%N)'}'
2025-12-11 04:14:28.101 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-11 04:14:28.101 DEBUG [src.libs.common] Sleeping for 0.2 seconds
2025-12-11 04:14:28.302 DEBUG [src.steps.store] Relaying message
2025-12-11 04:14:28.302 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:44484/relay/v1/messages/%2Fwaku%2F2%2Frs%2F3%2F0" -H "Content-Type: application/json" -d '{"payload": "TWVzc2FnZV81", "contentTopic": "/myapp/1/latest/proto", "timestamp": '$(date +%s%N)'}'
2025-12-11 04:14:28.308 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-11 04:14:28.308 DEBUG [src.libs.common] Sleeping for 0.2 seconds
2025-12-11 04:14:28.509 DEBUG [src.steps.store] Relaying message
2025-12-11 04:14:28.509 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:44484/relay/v1/messages/%2Fwaku%2F2%2Frs%2F3%2F0" -H "Content-Type: application/json" -d '{"payload": "TWVzc2FnZV82", "contentTopic": "/myapp/1/latest/proto", "timestamp": '$(date +%s%N)'}'
2025-12-11 04:14:28.514 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-11 04:14:28.515 DEBUG [src.libs.common] Sleeping for 0.2 seconds
2025-12-11 04:14:28.715 DEBUG [src.steps.store] Relaying message
2025-12-11 04:14:28.716 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:44484/relay/v1/messages/%2Fwaku%2F2%2Frs%2F3%2F0" -H "Content-Type: application/json" -d '{"payload": "TWVzc2FnZV83", "contentTopic": "/myapp/1/latest/proto", "timestamp": '$(date +%s%N)'}'
2025-12-11 04:14:28.721 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-11 04:14:28.721 DEBUG [src.libs.common] Sleeping for 0.2 seconds
2025-12-11 04:14:28.922 DEBUG [src.steps.store] Relaying message
2025-12-11 04:14:28.922 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:44484/relay/v1/messages/%2Fwaku%2F2%2Frs%2F3%2F0" -H "Content-Type: application/json" -d '{"payload": "TWVzc2FnZV84", "contentTopic": "/myapp/1/latest/proto", "timestamp": '$(date +%s%N)'}'
2025-12-11 04:14:28.927 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-11 04:14:28.928 DEBUG [src.libs.common] Sleeping for 0.2 seconds
2025-12-11 04:14:29.129 DEBUG [src.steps.store] Relaying message
2025-12-11 04:14:29.129 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:44484/relay/v1/messages/%2Fwaku%2F2%2Frs%2F3%2F0" -H "Content-Type: application/json" -d '{"payload": "TWVzc2FnZV85", "contentTopic": "/myapp/1/latest/proto", "timestamp": '$(date +%s%N)'}'
2025-12-11 04:14:29.135 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-11 04:14:29.135 DEBUG [src.libs.common] Sleeping for 0.2 seconds
2025-12-11 04:14:29.336 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:44484/store/v3/messages?pubsubTopic=%2Fwaku%2F2%2Frs%2F3%2F0&contentTopics=%2Fmyapp%2F1%2Flatest%2Fproto&cursor=0xd3e6c335f5cc43048f7ea95f1d726ad81cca4fba264312c8aee66ff3191c910d&pageSize=100&ascending=true" -H "Content-Type: application/json" -d 'None'
2025-12-11 04:14:29.339 ERROR [src.node.api_clients.base_client] HTTP error occurred: 500 Server Error: Internal Server Error for url: http://127.0.0.1:44484/store/v3/messages?pubsubTopic=%2Fwaku%2F2%2Frs%2F3%2F0&contentTopics=%2Fmyapp%2F1%2Flatest%2Fproto&cursor=0xd3e6c335f5cc43048f7ea95f1d726ad81cca4fba264312c8aee66ff3191c910d&pageSize=100&ascending=true. Response content: b'error in handleSelfStoreRequest: BAD_RESPONSE: archive error: DRIVER_ERROR: cursor not found'
2025-12-11 04:14:29.339 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:62018/store/v3/messages?pubsubTopic=%2Fwaku%2F2%2Frs%2F3%2F0&contentTopics=%2Fmyapp%2F1%2Flatest%2Fproto&cursor=0xd3e6c335f5cc43048f7ea95f1d726ad81cca4fba264312c8aee66ff3191c910d&pageSize=100&ascending=true" -H "Content-Type: application/json" -d 'None'
2025-12-11 04:14:29.342 ERROR [src.node.api_clients.base_client] HTTP error occurred: 500 Server Error: Internal Server Error for url: http://127.0.0.1:62018/store/v3/messages?pubsubTopic=%2Fwaku%2F2%2Frs%2F3%2F0&contentTopics=%2Fmyapp%2F1%2Flatest%2Fproto&cursor=0xd3e6c335f5cc43048f7ea95f1d726ad81cca4fba264312c8aee66ff3191c910d&pageSize=100&ascending=true. Response content: b'error in handleSelfStoreRequest: BAD_RESPONSE: archive error: DRIVER_ERROR: cursor not found'
2025-12-11 04:14:29.343 DEBUG [tests.conftest] Running fixture teardown: test_setup
2025-12-11 04:14:29.344 DEBUG [tests.conftest] Running fixture teardown: close_open_nodes
2025-12-11 04:14:29.345 DEBUG [src.node.waku_node] Stopping container with id 11765908753c
2025-12-11 04:14:29.922 DEBUG [src.node.waku_node] Container stopped.
2025-12-11 04:14:29.925 DEBUG [src.node.waku_node] Stopping container with id a6c35d144ea7
2025-12-11 04:14:30.467 DEBUG [src.node.waku_node] Container stopped.
2025-12-11 04:14:30.469 DEBUG [tests.conftest] Running fixture teardown: check_waku_log_errors
2025-12-11 04:14:30.476 DEBUG [src.node.docker_mananger] No errors found in the waku logs.
2025-12-11 04:14:30.484 DEBUG [src.node.docker_mananger] No errors found in the waku logs.