105 lines
18 KiB
Plaintext

2025-12-24 04:24:48.271 DEBUG [tests.conftest] Running fixture setup: test_id
2025-12-24 04:24:48.271 DEBUG [tests.conftest] Running test: test_relay_subscribe_with_multiple_overlapping_pubsub_topics with id: 2025-12-24_04-24-48__46216361-e1b3-4e4c-898d-706b0088d23c
2025-12-24 04:24:48.272 DEBUG [src.steps.common] Running fixture setup: common_setup
2025-12-24 04:24:48.272 DEBUG [src.steps.relay] Running fixture setup: relay_setup
2025-12-24 04:24:48.272 DEBUG [src.steps.relay] Running fixture setup: setup_main_relay_nodes
2025-12-24 04:24:48.278 DEBUG [src.node.docker_mananger] Docker client initialized with image wakuorg/nwaku:latest
2025-12-24 04:24:48.279 DEBUG [src.node.waku_node] WakuNode instance initialized with log path ./log/docker/node1_2025-12-24_04-24-48__46216361-e1b3-4e4c-898d-706b0088d23c__wakuorg_nwaku:latest.log
2025-12-24 04:24:48.279 DEBUG [src.node.waku_node] Starting Node...
2025-12-24 04:24:48.279 DEBUG [src.node.docker_mananger] Attempting to create or retrieve network waku
2025-12-24 04:24:48.280 DEBUG [src.node.docker_mananger] Network waku already exists
2025-12-24 04:24:48.281 DEBUG [src.node.docker_mananger] Generated random external IP 172.18.217.10
2025-12-24 04:24:48.281 DEBUG [src.node.docker_mananger] Generated ports ['5661', '5662', '5663', '5664', '5665']
2025-12-24 04:24:48.281 DEBUG [src.node.waku_node] RLN credentials were not set
2025-12-24 04:24:48.281 INFO [src.node.waku_node] RLN credentials not set or credential store not available, starting without RLN
2025-12-24 04:24:48.281 DEBUG [src.node.waku_node] Using volumes []
2025-12-24 04:24:48.281 DEBUG [src.node.docker_mananger] docker run -i -t -p 5661:5661 -p 5662:5662 -p 5663:5663 -p 5664:5664 -p 5665:5665 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=5663 --rest-port=5661 --tcp-port=5662 --discv5-udp-port=5664 --rest-address=0.0.0.0 --nat=extip:172.18.217.10 --peer-exchange=true --discv5-discovery=true --cluster-id=3 --nodekey=daed6533f805f31561fe8ed96aabacfd453d9bfd9d14d022fcaf57fda400d1af --shard=0 --metrics-server=true --metrics-server-address=0.0.0.0 --metrics-server-port=5665 --metrics-logging=true --relay=true
2025-12-24 04:24:48.460 DEBUG [src.node.docker_mananger] docker network connect --ip 172.18.217.10 waku 6c3de82b601bdeded66fbab37483b7b41986f8bdfcc568ed14ed02f8c84e92ac
2025-12-24 04:24:48.495 DEBUG [src.node.docker_mananger] Container started with ID 6c3de82b601b. Setting up logs at ./log/docker/node1_2025-12-24_04-24-48__46216361-e1b3-4e4c-898d-706b0088d23c__wakuorg_nwaku:latest.log
2025-12-24 04:24:48.496 DEBUG [src.node.waku_node] Started container from image wakuorg/nwaku:latest. REST: 5661
2025-12-24 04:24:48.497 DEBUG [src.libs.common] Sleeping for 1 seconds
2025-12-24 04:24:48.514 ERROR [src.node.docker_mananger] Max retries reached for container 906e6c76f00e. Exiting log stream.
2025-12-24 04:24:49.078 ERROR [src.node.docker_mananger] Max retries reached for container ba3d7fb8b266. Exiting log stream.
2025-12-24 04:24:49.497 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:5661/health" -H "Content-Type: application/json" -d 'None'
2025-12-24 04:24:49.500 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":"NOT_MOUNTED"},{"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":"NOT_READY","desc":"No Store service peer available yet, neither Store service set up for the node"},{"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-24 04:24:49.500 INFO [src.node.waku_node] Node protocols are initialized !!
2025-12-24 04:24:49.501 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:5661/debug/v1/info" -H "Content-Type: application/json" -d 'None'
2025-12-24 04:24:49.503 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"listenAddresses":["/ip4/172.18.217.10/tcp/5662/p2p/16Uiu2HAmJ9GM9D656q8HFKWLfoEmhQKm21UF9L8fwjSiTKqHr9Zj","/ip4/172.18.217.10/tcp/5663/ws/p2p/16Uiu2HAmJ9GM9D656q8HFKWLfoEmhQKm21UF9L8fwjSiTKqHr9Zj"],"enrUri":"enr:-L24QEgNhjxF6N5wCvMn6hTxPhiPflgdbm6AgqWYOs-dPnaaE1CNLNZmTs7JEqnQIHDqfkI2I2OXTkqOFWwcFcHUZ2MCgmlkgnY0gmlwhKwS2QqKbXVsdGlhZGRyc5YACASsEtkKBhYeAAoErBLZCgYWH90DgnJzhQADAQAAiXNlY3AyNTZrMaEDUYjJIX7dqvxu7jOKVw4jX31WKFQPwemFXVe8arzUvbKDdGNwghYeg3VkcIIWIIV3YWt1MgE"}'
2025-12-24 04:24:49.503 INFO [src.node.waku_node] REST service is ready !!
2025-12-24 04:24:49.510 DEBUG [src.node.docker_mananger] Docker client initialized with image wakuorg/nwaku:latest
2025-12-24 04:24:49.510 DEBUG [src.node.waku_node] WakuNode instance initialized with log path ./log/docker/node2_2025-12-24_04-24-48__46216361-e1b3-4e4c-898d-706b0088d23c__wakuorg_nwaku:latest.log
2025-12-24 04:24:49.510 DEBUG [src.node.waku_node] Starting Node...
2025-12-24 04:24:49.510 DEBUG [src.node.docker_mananger] Attempting to create or retrieve network waku
2025-12-24 04:24:49.512 DEBUG [src.node.docker_mananger] Network waku already exists
2025-12-24 04:24:49.512 DEBUG [src.node.docker_mananger] Generated random external IP 172.18.55.209
2025-12-24 04:24:49.512 DEBUG [src.node.docker_mananger] Generated ports ['31637', '31638', '31639', '31640', '31641']
2025-12-24 04:24:49.512 DEBUG [src.node.waku_node] RLN credentials were not set
2025-12-24 04:24:49.512 INFO [src.node.waku_node] RLN credentials not set or credential store not available, starting without RLN
2025-12-24 04:24:49.512 DEBUG [src.node.waku_node] Using volumes []
2025-12-24 04:24:49.513 DEBUG [src.node.docker_mananger] docker run -i -t -p 31637:31637 -p 31638:31638 -p 31639:31639 -p 31640:31640 -p 31641:31641 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=31639 --rest-port=31637 --tcp-port=31638 --discv5-udp-port=31640 --rest-address=0.0.0.0 --nat=extip:172.18.55.209 --peer-exchange=true --discv5-discovery=true --cluster-id=3 --nodekey=6dba7e18d5096a64f169fdcd5ece363cada51faaced6154f1eeacf2dd117232c --shard=0 --metrics-server=true --metrics-server-address=0.0.0.0 --metrics-server-port=31641 --metrics-logging=true --relay=true --discv5-bootstrap-node=enr:-L24QEgNhjxF6N5wCvMn6hTxPhiPflgdbm6AgqWYOs-dPnaaE1CNLNZmTs7JEqnQIHDqfkI2I2OXTkqOFWwcFcHUZ2MCgmlkgnY0gmlwhKwS2QqKbXVsdGlhZGRyc5YACASsEtkKBhYeAAoErBLZCgYWH90DgnJzhQADAQAAiXNlY3AyNTZrMaEDUYjJIX7dqvxu7jOKVw4jX31WKFQPwemFXVe8arzUvbKDdGNwghYeg3VkcIIWIIV3YWt1MgE
2025-12-24 04:24:49.689 DEBUG [src.node.docker_mananger] docker network connect --ip 172.18.55.209 waku a379e501d1227cde23396913f93495141888b1489ea1ce7951adfe3540f08f5f
2025-12-24 04:24:49.724 DEBUG [src.node.docker_mananger] Container started with ID a379e501d122. Setting up logs at ./log/docker/node2_2025-12-24_04-24-48__46216361-e1b3-4e4c-898d-706b0088d23c__wakuorg_nwaku:latest.log
2025-12-24 04:24:49.725 DEBUG [src.node.waku_node] Started container from image wakuorg/nwaku:latest. REST: 31637
2025-12-24 04:24:49.725 DEBUG [src.libs.common] Sleeping for 1 seconds
2025-12-24 04:24:50.726 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:31637/health" -H "Content-Type: application/json" -d 'None'
2025-12-24 04:24:50.731 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":"NOT_MOUNTED"},{"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":"NOT_READY","desc":"No Store service peer available yet, neither Store service set up for the node"},{"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-24 04:24:50.732 INFO [src.node.waku_node] Node protocols are initialized !!
2025-12-24 04:24:50.733 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:31637/debug/v1/info" -H "Content-Type: application/json" -d 'None'
2025-12-24 04:24:50.737 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"listenAddresses":["/ip4/172.18.55.209/tcp/31638/p2p/16Uiu2HAm1CT32hz4E7bXXYJEiWDpK1WkocEXnwuqwwAbPtKmzZSC","/ip4/172.18.55.209/tcp/31639/ws/p2p/16Uiu2HAm1CT32hz4E7bXXYJEiWDpK1WkocEXnwuqwwAbPtKmzZSC"],"enrUri":"enr:-L24QO_eAcgjA96AfE5Qlp7VRZgy251fL_wDUYmvZotNSmiXK-LkoWEOQh8yz1Vpvnkgd6lJVHt5zLO8-dTWsmiOa_gCgmlkgnY0gmlwhKwSN9GKbXVsdGlhZGRyc5YACASsEjfRBnuWAAoErBI30QZ7l90DgnJzhQADAQAAiXNlY3AyNTZrMaECVcLvW7ECLs5zXupcRX47VZ1hEcnusJOSuuXN7ZWxWt2DdGNwgnuWg3VkcIJ7mIV3YWt1MgE"}'
2025-12-24 04:24:50.739 INFO [src.node.waku_node] REST service is ready !!
2025-12-24 04:24:50.739 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:31637/admin/v1/peers" -H "Content-Type: application/json" -d '["/ip4/172.18.217.10/tcp/5662/p2p/16Uiu2HAmJ9GM9D656q8HFKWLfoEmhQKm21UF9L8fwjSiTKqHr9Zj"]'
2025-12-24 04:24:50.743 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-24 04:24:50.744 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:5661/relay/v1/subscriptions" -H "Content-Type: application/json" -d '["/waku/2/rs/3/0", "/waku/2/rs/3/1", "/waku/2/rs/3/9"]'
2025-12-24 04:24:50.748 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-24 04:24:50.748 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:31637/relay/v1/subscriptions" -H "Content-Type: application/json" -d '["/waku/2/rs/3/0", "/waku/2/rs/3/1", "/waku/2/rs/3/9"]'
2025-12-24 04:24:50.756 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-24 04:24:50.757 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:5661/relay/v1/subscriptions" -H "Content-Type: application/json" -d '["/waku/2/rs/3/1", "/waku/2/rs/3/9", "/waku/2/rs/3/25"]'
2025-12-24 04:24:50.762 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-24 04:24:50.762 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:31637/relay/v1/subscriptions" -H "Content-Type: application/json" -d '["/waku/2/rs/3/1", "/waku/2/rs/3/9", "/waku/2/rs/3/25"]'
2025-12-24 04:24:50.766 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-24 04:24:50.768 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:5661/relay/v1/messages/%2Fwaku%2F2%2Frs%2F3%2F0" -H "Content-Type: application/json" -d '{"payload": "UmVsYXkgd29ya3MhIQ==", "contentTopic": "/test/1/waku-relay/proto", "timestamp": '$(date +%s%N)'}'
2025-12-24 04:24:50.774 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-24 04:24:50.774 DEBUG [src.libs.common] Sleeping for 0.1 seconds
2025-12-24 04:24:50.874 DEBUG [src.steps.relay] Checking that peer NODE_1:wakuorg/nwaku:latest can find the published message
2025-12-24 04:24:50.874 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:5661/relay/v1/messages/%2Fwaku%2F2%2Frs%2F3%2F0" -H "Content-Type: application/json" -d 'None'
2025-12-24 04:24:50.877 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'[{"payload":"UmVsYXkgd29ya3MhIQ==","contentTopic":"/test/1/waku-relay/proto","version":0,"timestamp":1766550290768006912,"ephemeral":false,"proof":""}]'
2025-12-24 04:24:50.878 DEBUG [src.steps.relay] Checking that peer NODE_2:wakuorg/nwaku:latest can find the published message
2025-12-24 04:24:50.878 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:31637/relay/v1/messages/%2Fwaku%2F2%2Frs%2F3%2F0" -H "Content-Type: application/json" -d 'None'
2025-12-24 04:24:50.880 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'[{"payload":"UmVsYXkgd29ya3MhIQ==","contentTopic":"/test/1/waku-relay/proto","version":0,"timestamp":1766550290768006912,"ephemeral":false,"proof":""}]'
2025-12-24 04:24:50.882 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:5661/relay/v1/messages/%2Fwaku%2F2%2Frs%2F3%2F1" -H "Content-Type: application/json" -d '{"payload": "UmVsYXkgd29ya3MhIQ==", "contentTopic": "/test/1/waku-relay/proto", "timestamp": '$(date +%s%N)'}'
2025-12-24 04:24:50.886 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-24 04:24:50.886 DEBUG [src.libs.common] Sleeping for 0.1 seconds
2025-12-24 04:24:50.987 DEBUG [src.steps.relay] Checking that peer NODE_1:wakuorg/nwaku:latest can find the published message
2025-12-24 04:24:50.987 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:5661/relay/v1/messages/%2Fwaku%2F2%2Frs%2F3%2F1" -H "Content-Type: application/json" -d 'None'
2025-12-24 04:24:50.989 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'[{"payload":"UmVsYXkgd29ya3MhIQ==","contentTopic":"/test/1/waku-relay/proto","version":0,"timestamp":1766550290882443008,"ephemeral":false,"proof":""}]'
2025-12-24 04:24:50.991 DEBUG [src.steps.relay] Checking that peer NODE_2:wakuorg/nwaku:latest can find the published message
2025-12-24 04:24:50.991 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:31637/relay/v1/messages/%2Fwaku%2F2%2Frs%2F3%2F1" -H "Content-Type: application/json" -d 'None'
2025-12-24 04:24:50.993 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'[{"payload":"UmVsYXkgd29ya3MhIQ==","contentTopic":"/test/1/waku-relay/proto","version":0,"timestamp":1766550290882443008,"ephemeral":false,"proof":""}]'
2025-12-24 04:24:50.994 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:5661/relay/v1/messages/%2Fwaku%2F2%2Frs%2F3%2F9" -H "Content-Type: application/json" -d '{"payload": "UmVsYXkgd29ya3MhIQ==", "contentTopic": "/test/1/waku-relay/proto", "timestamp": '$(date +%s%N)'}'
2025-12-24 04:24:50.999 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-24 04:24:50.999 DEBUG [src.libs.common] Sleeping for 0.1 seconds
2025-12-24 04:24:51.100 DEBUG [src.steps.relay] Checking that peer NODE_1:wakuorg/nwaku:latest can find the published message
2025-12-24 04:24:51.100 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:5661/relay/v1/messages/%2Fwaku%2F2%2Frs%2F3%2F9" -H "Content-Type: application/json" -d 'None'
2025-12-24 04:24:51.102 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'[{"payload":"UmVsYXkgd29ya3MhIQ==","contentTopic":"/test/1/waku-relay/proto","version":0,"timestamp":1766550290994865152,"ephemeral":false,"proof":""}]'
2025-12-24 04:24:51.103 DEBUG [src.steps.relay] Checking that peer NODE_2:wakuorg/nwaku:latest can find the published message
2025-12-24 04:24:51.104 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:31637/relay/v1/messages/%2Fwaku%2F2%2Frs%2F3%2F9" -H "Content-Type: application/json" -d 'None'
2025-12-24 04:24:51.106 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'[{"payload":"UmVsYXkgd29ya3MhIQ==","contentTopic":"/test/1/waku-relay/proto","version":0,"timestamp":1766550290994865152,"ephemeral":false,"proof":""}]'
2025-12-24 04:24:51.107 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:5661/relay/v1/messages/%2Fwaku%2F2%2Frs%2F3%2F25" -H "Content-Type: application/json" -d '{"payload": "UmVsYXkgd29ya3MhIQ==", "contentTopic": "/test/1/waku-relay/proto", "timestamp": '$(date +%s%N)'}'
2025-12-24 04:24:51.111 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-24 04:24:51.111 DEBUG [src.libs.common] Sleeping for 0.1 seconds
2025-12-24 04:24:51.212 DEBUG [src.steps.relay] Checking that peer NODE_1:wakuorg/nwaku:latest can find the published message
2025-12-24 04:24:51.212 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:5661/relay/v1/messages/%2Fwaku%2F2%2Frs%2F3%2F25" -H "Content-Type: application/json" -d 'None'
2025-12-24 04:24:51.215 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'[{"payload":"UmVsYXkgd29ya3MhIQ==","contentTopic":"/test/1/waku-relay/proto","version":0,"timestamp":1766550291107583744,"ephemeral":false,"proof":""}]'
2025-12-24 04:24:51.216 DEBUG [src.steps.relay] Checking that peer NODE_2:wakuorg/nwaku:latest can find the published message
2025-12-24 04:24:51.216 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:31637/relay/v1/messages/%2Fwaku%2F2%2Frs%2F3%2F25" -H "Content-Type: application/json" -d 'None'
2025-12-24 04:24:51.218 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'[{"payload":"UmVsYXkgd29ya3MhIQ==","contentTopic":"/test/1/waku-relay/proto","version":0,"timestamp":1766550291107583744,"ephemeral":false,"proof":""}]'
2025-12-24 04:24:51.221 DEBUG [tests.conftest] Running fixture teardown: test_setup
2025-12-24 04:24:51.222 DEBUG [tests.conftest] Running fixture teardown: close_open_nodes
2025-12-24 04:24:51.222 DEBUG [src.node.waku_node] Stopping container with id 6c3de82b601b
2025-12-24 04:24:51.797 DEBUG [src.node.waku_node] Container stopped.
2025-12-24 04:24:51.798 DEBUG [src.node.waku_node] Stopping container with id a379e501d122
2025-12-24 04:24:52.318 DEBUG [src.node.waku_node] Container stopped.
2025-12-24 04:24:52.319 DEBUG [tests.conftest] Running fixture teardown: check_waku_log_errors
2025-12-24 04:24:52.326 DEBUG [src.node.docker_mananger] No errors found in the waku logs.
2025-12-24 04:24:52.334 DEBUG [src.node.docker_mananger] No errors found in the waku logs.