93 lines
16 KiB
Plaintext

2025-12-30 04:20:31.280 DEBUG [tests.conftest] Running fixture setup: test_id
2025-12-30 04:20:31.281 DEBUG [tests.conftest] Running test: test_relay_resubscribe_to_unsubscribed_pubsub_topic with id: 2025-12-30_04-20-31__dbf623ce-5e19-4c9d-95fc-b2071aa4fc2e
2025-12-30 04:20:31.281 DEBUG [src.steps.common] Running fixture setup: common_setup
2025-12-30 04:20:31.281 DEBUG [src.steps.relay] Running fixture setup: relay_setup
2025-12-30 04:20:31.281 DEBUG [src.steps.relay] Running fixture setup: setup_main_relay_nodes
2025-12-30 04:20:31.288 DEBUG [src.node.docker_mananger] Docker client initialized with image wakuorg/nwaku:latest
2025-12-30 04:20:31.288 DEBUG [src.node.waku_node] WakuNode instance initialized with log path ./log/docker/node1_2025-12-30_04-20-31__dbf623ce-5e19-4c9d-95fc-b2071aa4fc2e__wakuorg_nwaku:latest.log
2025-12-30 04:20:31.289 DEBUG [src.node.waku_node] Starting Node...
2025-12-30 04:20:31.289 DEBUG [src.node.docker_mananger] Attempting to create or retrieve network waku
2025-12-30 04:20:31.290 DEBUG [src.node.docker_mananger] Network waku already exists
2025-12-30 04:20:31.290 DEBUG [src.node.docker_mananger] Generated random external IP 172.18.174.237
2025-12-30 04:20:31.290 DEBUG [src.node.docker_mananger] Generated ports ['9120', '9121', '9122', '9123', '9124']
2025-12-30 04:20:31.291 DEBUG [src.node.waku_node] RLN credentials were not set
2025-12-30 04:20:31.291 INFO [src.node.waku_node] RLN credentials not set or credential store not available, starting without RLN
2025-12-30 04:20:31.291 DEBUG [src.node.waku_node] Using volumes []
2025-12-30 04:20:31.291 DEBUG [src.node.docker_mananger] docker run -i -t -p 9120:9120 -p 9121:9121 -p 9122:9122 -p 9123:9123 -p 9124:9124 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=9122 --rest-port=9120 --tcp-port=9121 --discv5-udp-port=9123 --rest-address=0.0.0.0 --nat=extip:172.18.174.237 --peer-exchange=true --discv5-discovery=true --cluster-id=3 --nodekey=2c181f192ce256dbead94bdee78ae8050f3a375ca9dcf562a5fd4d235bfc96ad --shard=0 --metrics-server=true --metrics-server-address=0.0.0.0 --metrics-server-port=9124 --metrics-logging=true --relay=true
2025-12-30 04:20:31.480 DEBUG [src.node.docker_mananger] docker network connect --ip 172.18.174.237 waku 69b69e07ada5524dabe2ffc7efc91a109f1f623b6a16a0c316d79a92ca477994
2025-12-30 04:20:31.511 DEBUG [src.node.docker_mananger] Container started with ID 69b69e07ada5. Setting up logs at ./log/docker/node1_2025-12-30_04-20-31__dbf623ce-5e19-4c9d-95fc-b2071aa4fc2e__wakuorg_nwaku:latest.log
2025-12-30 04:20:31.511 DEBUG [src.node.waku_node] Started container from image wakuorg/nwaku:latest. REST: 9120
2025-12-30 04:20:31.512 DEBUG [src.libs.common] Sleeping for 1 seconds
2025-12-30 04:20:31.575 ERROR [src.node.docker_mananger] Max retries reached for container 8fcf7c1cc605. Exiting log stream.
2025-12-30 04:20:32.072 ERROR [src.node.docker_mananger] Max retries reached for container d8c9beff0466. Exiting log stream.
2025-12-30 04:20:32.512 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:9120/health" -H "Content-Type: application/json" -d 'None'
2025-12-30 04:20:32.515 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-30 04:20:32.516 INFO [src.node.waku_node] Node protocols are initialized !!
2025-12-30 04:20:32.516 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:9120/debug/v1/info" -H "Content-Type: application/json" -d 'None'
2025-12-30 04:20:32.518 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"listenAddresses":["/ip4/172.18.174.237/tcp/9121/p2p/16Uiu2HAmT6iJpNBNjhwUnsUcESM7eca3CxHNSbxL9AfFkm4bDptY","/ip4/172.18.174.237/tcp/9122/ws/p2p/16Uiu2HAmT6iJpNBNjhwUnsUcESM7eca3CxHNSbxL9AfFkm4bDptY"],"enrUri":"enr:-L24QDVZ9Z4dWpRKpASU00rIlrPEaMdCppTtHd4vxm1I9-eNb-iorjhE81hOfJVB6k3MGc6_6zrMx-ldAqb299YtwRoCgmlkgnY0gmlwhKwSru2KbXVsdGlhZGRyc5YACASsEq7tBiOhAAoErBKu7QYjot0DgnJzhQADAQAAiXNlY3AyNTZrMaED1pqUG7M_PYZRPHXooNyc76FKU_kXKoE9MCM-lDcugKmDdGNwgiOhg3VkcIIjo4V3YWt1MgE"}'
2025-12-30 04:20:32.518 INFO [src.node.waku_node] REST service is ready !!
2025-12-30 04:20:32.525 DEBUG [src.node.docker_mananger] Docker client initialized with image wakuorg/nwaku:latest
2025-12-30 04:20:32.525 DEBUG [src.node.waku_node] WakuNode instance initialized with log path ./log/docker/node2_2025-12-30_04-20-31__dbf623ce-5e19-4c9d-95fc-b2071aa4fc2e__wakuorg_nwaku:latest.log
2025-12-30 04:20:32.525 DEBUG [src.node.waku_node] Starting Node...
2025-12-30 04:20:32.525 DEBUG [src.node.docker_mananger] Attempting to create or retrieve network waku
2025-12-30 04:20:32.527 DEBUG [src.node.docker_mananger] Network waku already exists
2025-12-30 04:20:32.527 DEBUG [src.node.docker_mananger] Generated random external IP 172.18.12.170
2025-12-30 04:20:32.527 DEBUG [src.node.docker_mananger] Generated ports ['48217', '48218', '48219', '48220', '48221']
2025-12-30 04:20:32.527 DEBUG [src.node.waku_node] RLN credentials were not set
2025-12-30 04:20:32.527 INFO [src.node.waku_node] RLN credentials not set or credential store not available, starting without RLN
2025-12-30 04:20:32.527 DEBUG [src.node.waku_node] Using volumes []
2025-12-30 04:20:32.528 DEBUG [src.node.docker_mananger] docker run -i -t -p 48217:48217 -p 48218:48218 -p 48219:48219 -p 48220:48220 -p 48221:48221 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=48219 --rest-port=48217 --tcp-port=48218 --discv5-udp-port=48220 --rest-address=0.0.0.0 --nat=extip:172.18.12.170 --peer-exchange=true --discv5-discovery=true --cluster-id=3 --nodekey=e49cd86e6b1c4a0fe8b88aeec6ce48cb9f09ff3fc5d70ed20b8fe7a17fd1cc7c --shard=0 --metrics-server=true --metrics-server-address=0.0.0.0 --metrics-server-port=48221 --metrics-logging=true --relay=true --discv5-bootstrap-node=enr:-L24QDVZ9Z4dWpRKpASU00rIlrPEaMdCppTtHd4vxm1I9-eNb-iorjhE81hOfJVB6k3MGc6_6zrMx-ldAqb299YtwRoCgmlkgnY0gmlwhKwSru2KbXVsdGlhZGRyc5YACASsEq7tBiOhAAoErBKu7QYjot0DgnJzhQADAQAAiXNlY3AyNTZrMaED1pqUG7M_PYZRPHXooNyc76FKU_kXKoE9MCM-lDcugKmDdGNwgiOhg3VkcIIjo4V3YWt1MgE
2025-12-30 04:20:32.718 DEBUG [src.node.docker_mananger] docker network connect --ip 172.18.12.170 waku 47e1484ef189be9b92ff413ba3fc85ff4d4c0e31a42f24d6ff1e79b4db1f8fcb
2025-12-30 04:20:32.755 DEBUG [src.node.docker_mananger] Container started with ID 47e1484ef189. Setting up logs at ./log/docker/node2_2025-12-30_04-20-31__dbf623ce-5e19-4c9d-95fc-b2071aa4fc2e__wakuorg_nwaku:latest.log
2025-12-30 04:20:32.755 DEBUG [src.node.waku_node] Started container from image wakuorg/nwaku:latest. REST: 48217
2025-12-30 04:20:32.755 DEBUG [src.libs.common] Sleeping for 1 seconds
2025-12-30 04:20:33.756 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:48217/health" -H "Content-Type: application/json" -d 'None'
2025-12-30 04:20:33.764 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-30 04:20:33.766 INFO [src.node.waku_node] Node protocols are initialized !!
2025-12-30 04:20:33.768 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:48217/debug/v1/info" -H "Content-Type: application/json" -d 'None'
2025-12-30 04:20:33.774 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"listenAddresses":["/ip4/172.18.12.170/tcp/48218/p2p/16Uiu2HAmPCWDUTHTmT3VoaGFd4gjBfSFMs3GQCwso7DaggeAk5QL","/ip4/172.18.12.170/tcp/48219/ws/p2p/16Uiu2HAmPCWDUTHTmT3VoaGFd4gjBfSFMs3GQCwso7DaggeAk5QL"],"enrUri":"enr:-L24QLUxw6rIgygTx_kZrBGofmV1EWPX5ly2u26tbZQutj4fVJtKZvx_uP_Bzpe2jTKuX6vGB8Dnfp8HFZmA18--lRsCgmlkgnY0gmlwhKwSDKqKbXVsdGlhZGRyc5YACASsEgyqBrxaAAoErBIMqga8W90DgnJzhQADAQAAiXNlY3AyNTZrMaEDnKekoUxUDidJIiHSYA659KKBic85YiELNc-IQ394goGDdGNwgrxag3VkcIK8XIV3YWt1MgE"}'
2025-12-30 04:20:33.774 INFO [src.node.waku_node] REST service is ready !!
2025-12-30 04:20:33.775 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:48217/admin/v1/peers" -H "Content-Type: application/json" -d '["/ip4/172.18.174.237/tcp/9121/p2p/16Uiu2HAmT6iJpNBNjhwUnsUcESM7eca3CxHNSbxL9AfFkm4bDptY"]'
2025-12-30 04:20:33.777 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-30 04:20:33.778 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:9120/relay/v1/subscriptions" -H "Content-Type: application/json" -d '["/waku/2/rs/3/1"]'
2025-12-30 04:20:33.782 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-30 04:20:33.782 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:48217/relay/v1/subscriptions" -H "Content-Type: application/json" -d '["/waku/2/rs/3/1"]'
2025-12-30 04:20:33.786 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-30 04:20:33.787 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:9120/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-30 04:20:33.792 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-30 04:20:33.792 DEBUG [src.libs.common] Sleeping for 0.1 seconds
2025-12-30 04:20:33.892 DEBUG [src.steps.relay] Checking that peer NODE_1:wakuorg/nwaku:latest can find the published message
2025-12-30 04:20:33.893 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:9120/relay/v1/messages/%2Fwaku%2F2%2Frs%2F3%2F1" -H "Content-Type: application/json" -d 'None'
2025-12-30 04:20:33.896 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":1767068433787353088,"ephemeral":false,"proof":""}]'
2025-12-30 04:20:33.898 DEBUG [src.steps.relay] Checking that peer NODE_2:wakuorg/nwaku:latest can find the published message
2025-12-30 04:20:33.898 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:48217/relay/v1/messages/%2Fwaku%2F2%2Frs%2F3%2F1" -H "Content-Type: application/json" -d 'None'
2025-12-30 04:20:33.900 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":1767068433787353088,"ephemeral":false,"proof":""}]'
2025-12-30 04:20:33.902 INFO [src.node.api_clients.base_client] curl -v -X DELETE "http://127.0.0.1:9120/relay/v1/subscriptions" -H "Content-Type: application/json" -d '["/waku/2/rs/3/1"]'
2025-12-30 04:20:33.906 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-30 04:20:33.906 INFO [src.node.api_clients.base_client] curl -v -X DELETE "http://127.0.0.1:48217/relay/v1/subscriptions" -H "Content-Type: application/json" -d '["/waku/2/rs/3/1"]'
2025-12-30 04:20:33.911 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-30 04:20:33.912 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:9120/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-30 04:20:33.914 ERROR [src.node.api_clients.base_client] HTTP error occurred: 400 Client Error: Bad Request for url: http://127.0.0.1:9120/relay/v1/messages/%2Fwaku%2F2%2Frs%2F3%2F1. Response content: b'Failed to publish: Node not subscribed to topic: /waku/2/rs/3/1'
2025-12-30 04:20:33.914 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:9120/relay/v1/subscriptions" -H "Content-Type: application/json" -d '["/waku/2/rs/3/1"]'
2025-12-30 04:20:33.918 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-30 04:20:33.918 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:48217/relay/v1/subscriptions" -H "Content-Type: application/json" -d '["/waku/2/rs/3/1"]'
2025-12-30 04:20:33.922 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-30 04:20:33.923 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:9120/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-30 04:20:33.926 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-30 04:20:33.927 DEBUG [src.libs.common] Sleeping for 0.1 seconds
2025-12-30 04:20:34.027 DEBUG [src.steps.relay] Checking that peer NODE_1:wakuorg/nwaku:latest can find the published message
2025-12-30 04:20:34.028 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:9120/relay/v1/messages/%2Fwaku%2F2%2Frs%2F3%2F1" -H "Content-Type: application/json" -d 'None'
2025-12-30 04:20:34.030 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":1767068433922990704,"ephemeral":false,"proof":""}]'
2025-12-30 04:20:34.032 DEBUG [src.steps.relay] Checking that peer NODE_2:wakuorg/nwaku:latest can find the published message
2025-12-30 04:20:34.032 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:48217/relay/v1/messages/%2Fwaku%2F2%2Frs%2F3%2F1" -H "Content-Type: application/json" -d 'None'
2025-12-30 04:20:34.034 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":1767068433922990704,"ephemeral":false,"proof":""}]'
2025-12-30 04:20:34.037 DEBUG [tests.conftest] Running fixture teardown: test_setup
2025-12-30 04:20:34.038 DEBUG [tests.conftest] Running fixture teardown: close_open_nodes
2025-12-30 04:20:34.038 DEBUG [src.node.waku_node] Stopping container with id 69b69e07ada5
2025-12-30 04:20:34.599 DEBUG [src.node.waku_node] Container stopped.
2025-12-30 04:20:34.599 DEBUG [src.node.waku_node] Stopping container with id 47e1484ef189
2025-12-30 04:20:35.132 DEBUG [src.node.waku_node] Container stopped.
2025-12-30 04:20:35.133 DEBUG [tests.conftest] Running fixture teardown: check_waku_log_errors
2025-12-30 04:20:35.139 DEBUG [src.node.docker_mananger] No errors found in the waku logs.
2025-12-30 04:20:35.145 DEBUG [src.node.docker_mananger] No errors found in the waku logs.