97 lines
15 KiB
Plaintext

2026-03-13 04:36:09.170 DEBUG [tests.conftest] Running fixture setup: test_id
2026-03-13 04:36:09.170 DEBUG [tests.conftest] Running test: test_metrics_after_filter_get with id: 2026-03-13_04-36-09__6f2f8f0d-a711-4f13-b151-426b2fa8175d
2026-03-13 04:36:09.171 DEBUG [src.steps.common] Running fixture setup: common_setup
2026-03-13 04:36:09.171 DEBUG [src.steps.filter] Running fixture setup: filter_setup
2026-03-13 04:36:09.171 DEBUG [src.steps.light_push] Running fixture setup: light_push_setup
2026-03-13 04:36:09.171 DEBUG [src.steps.relay] Running fixture setup: relay_setup
2026-03-13 04:36:09.172 DEBUG [src.steps.store] Running fixture setup: store_setup
2026-03-13 04:36:09.172 DEBUG [src.steps.filter] Running fixture setup: setup_main_relay_node
2026-03-13 04:36:09.180 DEBUG [src.node.docker_mananger] Docker client initialized with image wakuorg/nwaku:latest
2026-03-13 04:36:09.180 DEBUG [src.node.waku_node] WakuNode instance initialized with log path ./log/docker/node1_2026-03-13_04-36-09__6f2f8f0d-a711-4f13-b151-426b2fa8175d__wakuorg_nwaku:latest.log
2026-03-13 04:36:09.180 DEBUG [src.node.waku_node] Starting Node...
2026-03-13 04:36:09.180 DEBUG [src.node.docker_mananger] Attempting to create or retrieve network waku
2026-03-13 04:36:09.182 DEBUG [src.node.docker_mananger] Network waku already exists
2026-03-13 04:36:09.182 DEBUG [src.node.docker_mananger] Generated random external IP 172.18.156.229
2026-03-13 04:36:09.182 DEBUG [src.node.docker_mananger] Generated ports ['48654', '48655', '48656', '48657', '48658']
2026-03-13 04:36:09.182 DEBUG [src.node.waku_node] RLN credentials were not set
2026-03-13 04:36:09.183 INFO [src.node.waku_node] RLN credentials not set or credential store not available, starting without RLN
2026-03-13 04:36:09.183 DEBUG [src.node.waku_node] Using volumes []
2026-03-13 04:36:09.183 DEBUG [src.node.docker_mananger] docker run -i -t -p 48654:48654 -p 48655:48655 -p 48656:48656 -p 48657:48657 -p 48658:48658 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=48656 --rest-port=48654 --tcp-port=48655 --discv5-udp-port=48657 --rest-address=0.0.0.0 --nat=extip:172.18.156.229 --peer-exchange=true --discv5-discovery=true --cluster-id=3 --nodekey=df8f44af0a1ae5acbbeeabb19edebc8ddbc4c01ccdb0cbc3a83f12a2cfceb483 --shard=0 --metrics-server=true --metrics-server-address=0.0.0.0 --metrics-server-port=48658 --metrics-logging=true --relay=true --filter=true
2026-03-13 04:36:09.383 DEBUG [src.node.docker_mananger] docker network connect --ip 172.18.156.229 waku 8c4366acf6d06dc60c477afc3f65e72499d9c4fa5f9da6e144536b944cc86a44
2026-03-13 04:36:09.418 DEBUG [src.node.docker_mananger] Container started with ID 8c4366acf6d0. Setting up logs at ./log/docker/node1_2026-03-13_04-36-09__6f2f8f0d-a711-4f13-b151-426b2fa8175d__wakuorg_nwaku:latest.log
2026-03-13 04:36:09.419 DEBUG [src.node.waku_node] Started container from image wakuorg/nwaku:latest. REST: 48654
2026-03-13 04:36:09.419 DEBUG [src.libs.common] Sleeping for 1 seconds
2026-03-13 04:36:09.974 ERROR [src.node.docker_mananger] Max retries reached for container 94eb4cbc29b8. Exiting log stream.
2026-03-13 04:36:10.420 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:48654/health" -H "Content-Type: application/json" -d 'None'
2026-03-13 04:36:10.423 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"nodeHealth":"READY","connectionStatus":"Disconnected","protocolsHealth":[{"Relay":"NOT_READY","desc":"No connected peers"},{"Lightpush":"NOT_MOUNTED"},{"Legacy Lightpush":"NOT_MOUNTED"},{"Filter":"NOT_READY","desc":"Relay is not ready, filter will not be able to sort out messages"},{"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"},{"Rln Relay":"NOT_MOUNTED"}]}'
2026-03-13 04:36:10.423 INFO [src.node.waku_node] Node protocols are initialized !!
2026-03-13 04:36:10.423 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:48654/debug/v1/info" -H "Content-Type: application/json" -d 'None'
2026-03-13 04:36:10.426 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"listenAddresses":["/ip4/172.18.156.229/tcp/48655/p2p/16Uiu2HAmQxShwKGTmmBTFRedDEjS7oncm5uMoiRPHS4DPVwYFbZA","/ip4/172.18.156.229/tcp/48656/ws/p2p/16Uiu2HAmQxShwKGTmmBTFRedDEjS7oncm5uMoiRPHS4DPVwYFbZA"],"enrUri":"enr:-L24QMNoVBvsBXu-tQEo3rLEu3W3_OVVPREpXyoHSHXxdaLjauon-Vt15E5IWLOmLkrdWPvIQ42v-TjF2LW5oEA330YCgmlkgnY0gmlwhKwSnOWKbXVsdGlhZGRyc5YACASsEpzlBr4PAAoErBKc5Qa-EN0DgnJzhQADAQAAiXNlY3AyNTZrMaEDtsTq7Ue7cBF7bKIYOwmkFO3l76sbZBGGqJ9UYVNsrPGDdGNwgr4Pg3VkcIK-EYV3YWt1MgU"}'
2026-03-13 04:36:10.426 INFO [src.node.waku_node] REST service is ready !!
2026-03-13 04:36:10.426 DEBUG [src.steps.filter] Running fixture setup: setup_main_filter_node
2026-03-13 04:36:10.434 DEBUG [src.node.docker_mananger] Docker client initialized with image wakuorg/nwaku:latest
2026-03-13 04:36:10.434 DEBUG [src.node.waku_node] WakuNode instance initialized with log path ./log/docker/node2_2026-03-13_04-36-09__6f2f8f0d-a711-4f13-b151-426b2fa8175d__wakuorg_nwaku:latest.log
2026-03-13 04:36:10.434 DEBUG [src.node.waku_node] Starting Node...
2026-03-13 04:36:10.434 DEBUG [src.node.docker_mananger] Attempting to create or retrieve network waku
2026-03-13 04:36:10.436 DEBUG [src.node.docker_mananger] Network waku already exists
2026-03-13 04:36:10.436 DEBUG [src.node.docker_mananger] Generated random external IP 172.18.114.119
2026-03-13 04:36:10.436 DEBUG [src.node.docker_mananger] Generated ports ['25460', '25461', '25462', '25463', '25464']
2026-03-13 04:36:10.436 DEBUG [src.node.waku_node] RLN credentials were not set
2026-03-13 04:36:10.436 INFO [src.node.waku_node] RLN credentials not set or credential store not available, starting without RLN
2026-03-13 04:36:10.436 DEBUG [src.node.waku_node] Using volumes []
2026-03-13 04:36:10.436 DEBUG [src.node.docker_mananger] docker run -i -t -p 25460:25460 -p 25461:25461 -p 25462:25462 -p 25463:25463 -p 25464:25464 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=25462 --rest-port=25460 --tcp-port=25461 --discv5-udp-port=25463 --rest-address=0.0.0.0 --nat=extip:172.18.114.119 --peer-exchange=true --discv5-discovery=true --cluster-id=3 --nodekey=e6b714d26db4641bea5d0b0adf51be06bffcf7bc9ade368f0af6eabf23f6b26b --shard=0 --metrics-server=true --metrics-server-address=0.0.0.0 --metrics-server-port=25464 --metrics-logging=true --relay=false --discv5-bootstrap-node=enr:-L24QMNoVBvsBXu-tQEo3rLEu3W3_OVVPREpXyoHSHXxdaLjauon-Vt15E5IWLOmLkrdWPvIQ42v-TjF2LW5oEA330YCgmlkgnY0gmlwhKwSnOWKbXVsdGlhZGRyc5YACASsEpzlBr4PAAoErBKc5Qa-EN0DgnJzhQADAQAAiXNlY3AyNTZrMaEDtsTq7Ue7cBF7bKIYOwmkFO3l76sbZBGGqJ9UYVNsrPGDdGNwgr4Pg3VkcIK-EYV3YWt1MgU --filternode=/ip4/172.18.156.229/tcp/48655/p2p/16Uiu2HAmQxShwKGTmmBTFRedDEjS7oncm5uMoiRPHS4DPVwYFbZA
2026-03-13 04:36:10.633 DEBUG [src.node.docker_mananger] docker network connect --ip 172.18.114.119 waku 2988e1eb945882b3b0160af464355d1e74436e6cf987f7b30301cdc624613551
2026-03-13 04:36:10.667 DEBUG [src.node.docker_mananger] Container started with ID 2988e1eb9458. Setting up logs at ./log/docker/node2_2026-03-13_04-36-09__6f2f8f0d-a711-4f13-b151-426b2fa8175d__wakuorg_nwaku:latest.log
2026-03-13 04:36:10.667 DEBUG [src.node.waku_node] Started container from image wakuorg/nwaku:latest. REST: 25460
2026-03-13 04:36:10.668 DEBUG [src.libs.common] Sleeping for 1 seconds
2026-03-13 04:36:11.668 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:25460/health" -H "Content-Type: application/json" -d 'None'
2026-03-13 04:36:11.671 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"nodeHealth":"READY","connectionStatus":"Disconnected","protocolsHealth":[{"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"},{"Rln Relay":"NOT_MOUNTED"}]}'
2026-03-13 04:36:11.671 INFO [src.node.waku_node] Node protocols are initialized !!
2026-03-13 04:36:11.672 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:25460/debug/v1/info" -H "Content-Type: application/json" -d 'None'
2026-03-13 04:36:11.674 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"listenAddresses":["/ip4/172.18.114.119/tcp/25461/p2p/16Uiu2HAm12cHhgTSFaepYFbGPCTpY9ZcqFBUGMfkMmqNimVgEQTp","/ip4/172.18.114.119/tcp/25462/ws/p2p/16Uiu2HAm12cHhgTSFaepYFbGPCTpY9ZcqFBUGMfkMmqNimVgEQTp"],"enrUri":"enr:-L24QBHG907wFEGOvmfXDs5gfoqd-W5zjcLD9jt_N8eyj7VZN-r9FsbVDFAjHUFjn-msnv-kOhswUhw-cQfEIdEnvHwCgmlkgnY0gmlwhKwScneKbXVsdGlhZGRyc5YACASsEnJ3BmN1AAoErBJydwZjdt0DgnJzhQADAQAAiXNlY3AyNTZrMaECUz2W2ezkNwO20BrD7DO56ukEDtwnTb2xlzUa91wuWceDdGNwgmN1g3VkcIJjd4V3YWt1MgA"}'
2026-03-13 04:36:11.674 INFO [src.node.waku_node] REST service is ready !!
2026-03-13 04:36:11.674 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:25460/admin/v1/peers" -H "Content-Type: application/json" -d '["/ip4/172.18.156.229/tcp/48655/p2p/16Uiu2HAmQxShwKGTmmBTFRedDEjS7oncm5uMoiRPHS4DPVwYFbZA"]'
2026-03-13 04:36:11.710 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2026-03-13 04:36:11.712 DEBUG [src.steps.filter] Running fixture setup: subscribe_main_nodes
2026-03-13 04:36:11.712 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:48654/relay/v1/subscriptions" -H "Content-Type: application/json" -d '["/waku/2/rs/3/1"]'
2026-03-13 04:36:11.730 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2026-03-13 04:36:11.732 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:25460/filter/v2/subscriptions" -H "Content-Type: application/json" -d '{"requestId": "5d56570b-5932-4ae9-b4d5-96418041ae03", "contentFilters": ["/test/1/waku-relay/proto"], "pubsubTopic": "/waku/2/rs/3/1"}'
2026-03-13 04:36:11.746 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"requestId":"5d56570b-5932-4ae9-b4d5-96418041ae03","statusDesc":"OK"}'
2026-03-13 04:36:11.747 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:48654/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)'}'
2026-03-13 04:36:11.755 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2026-03-13 04:36:11.755 DEBUG [src.libs.common] Sleeping for 0.5 seconds
2026-03-13 04:36:12.256 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:25460/filter/v2/messages/%2Ftest%2F1%2Fwaku-relay%2Fproto" -H "Content-Type: application/json" -d 'None'
2026-03-13 04:36:12.259 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":1773376571747867712,"ephemeral":false}]'
2026-03-13 04:36:12.259 DEBUG [src.libs.common] Sleeping for 5 seconds
2026-03-13 04:36:17.260 DEBUG [src.steps.metrics] Checking metric: libp2p_peers has 1
2026-03-13 04:36:17.265 DEBUG [src.steps.metrics] Found metric: libp2p_peers with value 1.0
2026-03-13 04:36:17.265 DEBUG [src.steps.metrics] Checking metric: libp2p_pubsub_peers has 1
2026-03-13 04:36:17.269 DEBUG [src.steps.metrics] Found metric: libp2p_pubsub_peers with value 1.0
2026-03-13 04:36:17.269 DEBUG [src.steps.metrics] Checking metric: libp2p_pubsub_topics has 1
2026-03-13 04:36:17.272 DEBUG [src.steps.metrics] Found metric: libp2p_pubsub_topics with value 2.0
2026-03-13 04:36:17.273 DEBUG [src.steps.metrics] Checking metric: libp2p_pubsub_subscriptions_total has 1
2026-03-13 04:36:17.276 DEBUG [src.steps.metrics] Found metric: libp2p_pubsub_subscriptions_total with value 2.0
2026-03-13 04:36:17.277 DEBUG [src.steps.metrics] Checking metric: waku_peer_store_size has 1
2026-03-13 04:36:17.280 DEBUG [src.steps.metrics] Found metric: waku_peer_store_size with value 1.0
2026-03-13 04:36:17.280 DEBUG [src.steps.metrics] Checking metric: waku_histogram_message_size_count has 1
2026-03-13 04:36:17.284 DEBUG [src.steps.metrics] Found metric: waku_histogram_message_size_count with value 1.0
2026-03-13 04:36:17.284 DEBUG [src.steps.metrics] Checking metric: waku_node_messages_total{type="relay"} has 1
2026-03-13 04:36:17.287 DEBUG [src.steps.metrics] Found metric: waku_node_messages_total{type="relay"} with value 1.0
2026-03-13 04:36:17.287 DEBUG [src.steps.metrics] Checking metric: waku_service_peers{protocol="/vac/waku/filter-subscribe/2.0.0-beta1",peerId="/ip4/172.18.156.229/tcp/48655"} has 1
2026-03-13 04:36:17.291 DEBUG [src.steps.metrics] Found metric: waku_service_peers{protocol="/vac/waku/filter-subscribe/2.0.0-beta1",peerId="/ip4/172.18.156.229/tcp/48655"} with value 1.0
2026-03-13 04:36:17.291 DEBUG [src.steps.metrics] Checking metric: libp2p_peers has 1
2026-03-13 04:36:17.294 DEBUG [src.steps.metrics] Found metric: libp2p_peers with value 1.0
2026-03-13 04:36:17.295 DEBUG [src.steps.metrics] Checking metric: libp2p_total_dial_attempts_total has 1
2026-03-13 04:36:17.298 DEBUG [src.steps.metrics] Found metric: libp2p_total_dial_attempts_total with value 1.0
2026-03-13 04:36:17.298 DEBUG [src.steps.metrics] Checking metric: waku_peer_store_size has 1
2026-03-13 04:36:17.302 DEBUG [src.steps.metrics] Found metric: waku_peer_store_size with value 1.0
2026-03-13 04:36:17.304 DEBUG [tests.conftest] Running fixture teardown: test_setup
2026-03-13 04:36:17.305 DEBUG [tests.conftest] Running fixture teardown: close_open_nodes
2026-03-13 04:36:17.305 DEBUG [src.node.waku_node] Stopping container with id 8c4366acf6d0
2026-03-13 04:36:17.857 DEBUG [src.node.waku_node] Container stopped.
2026-03-13 04:36:17.858 DEBUG [src.node.waku_node] Stopping container with id 2988e1eb9458
2026-03-13 04:36:18.430 DEBUG [src.node.waku_node] Container stopped.
2026-03-13 04:36:18.432 DEBUG [tests.conftest] Running fixture teardown: check_waku_log_errors
2026-03-13 04:36:18.438 DEBUG [src.node.docker_mananger] No errors found in the waku logs.
2026-03-13 04:36:18.444 DEBUG [src.node.docker_mananger] No errors found in the waku logs.