2026-02-04 17:29:28 +00:00

97 lines
15 KiB
Plaintext

2026-02-04 17:13:47.262 DEBUG [tests.conftest] Running fixture setup: test_id
2026-02-04 17:13:47.262 DEBUG [tests.conftest] Running test: test_metrics_after_filter_get with id: 2026-02-04_17-13-47__1035dd26-6aa2-43f5-82b4-0ddf16f4544d
2026-02-04 17:13:47.263 DEBUG [src.steps.common] Running fixture setup: common_setup
2026-02-04 17:13:47.263 DEBUG [src.steps.filter] Running fixture setup: filter_setup
2026-02-04 17:13:47.263 DEBUG [src.steps.light_push] Running fixture setup: light_push_setup
2026-02-04 17:13:47.264 DEBUG [src.steps.relay] Running fixture setup: relay_setup
2026-02-04 17:13:47.264 DEBUG [src.steps.store] Running fixture setup: store_setup
2026-02-04 17:13:47.264 DEBUG [src.steps.filter] Running fixture setup: setup_main_relay_node
2026-02-04 17:13:47.271 DEBUG [src.node.docker_mananger] Docker client initialized with image wakuorg/nwaku:latest
2026-02-04 17:13:47.271 DEBUG [src.node.waku_node] WakuNode instance initialized with log path ./log/docker/node1_2026-02-04_17-13-47__1035dd26-6aa2-43f5-82b4-0ddf16f4544d__wakuorg_nwaku:latest.log
2026-02-04 17:13:47.271 DEBUG [src.node.waku_node] Starting Node...
2026-02-04 17:13:47.271 DEBUG [src.node.docker_mananger] Attempting to create or retrieve network waku
2026-02-04 17:13:47.272 DEBUG [src.node.docker_mananger] Network waku already exists
2026-02-04 17:13:47.273 DEBUG [src.node.docker_mananger] Generated random external IP 172.18.55.47
2026-02-04 17:13:47.273 DEBUG [src.node.docker_mananger] Generated ports ['13864', '13865', '13866', '13867', '13868']
2026-02-04 17:13:47.273 DEBUG [src.node.waku_node] RLN credentials were not set
2026-02-04 17:13:47.273 INFO [src.node.waku_node] RLN credentials not set or credential store not available, starting without RLN
2026-02-04 17:13:47.273 DEBUG [src.node.waku_node] Using volumes []
2026-02-04 17:13:47.273 DEBUG [src.node.docker_mananger] docker run -i -t -p 13864:13864 -p 13865:13865 -p 13866:13866 -p 13867:13867 -p 13868:13868 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=13866 --rest-port=13864 --tcp-port=13865 --discv5-udp-port=13867 --rest-address=0.0.0.0 --nat=extip:172.18.55.47 --peer-exchange=true --discv5-discovery=true --cluster-id=3 --nodekey=28dc10ec1ccea9c0ea1f61eb681291be8cacfe1ca4bb1947b6eb3e32ccab41c8 --shard=0 --metrics-server=true --metrics-server-address=0.0.0.0 --metrics-server-port=13868 --metrics-logging=true --relay=true --filter=true
2026-02-04 17:13:47.458 DEBUG [src.node.docker_mananger] docker network connect --ip 172.18.55.47 waku 296a66ad7170873f4907daff0522b2b89d1193f863ebcb103b56c709526dd1fe
2026-02-04 17:13:47.491 DEBUG [src.node.docker_mananger] Container started with ID 296a66ad7170. Setting up logs at ./log/docker/node1_2026-02-04_17-13-47__1035dd26-6aa2-43f5-82b4-0ddf16f4544d__wakuorg_nwaku:latest.log
2026-02-04 17:13:47.492 DEBUG [src.node.waku_node] Started container from image wakuorg/nwaku:latest. REST: 13864
2026-02-04 17:13:47.492 DEBUG [src.libs.common] Sleeping for 1 seconds
2026-02-04 17:13:48.073 ERROR [src.node.docker_mananger] Max retries reached for container 1b80b76c9e31. Exiting log stream.
2026-02-04 17:13:48.494 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:13864/health" -H "Content-Type: application/json" -d 'None'
2026-02-04 17:13:48.497 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_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"}]}'
2026-02-04 17:13:48.497 INFO [src.node.waku_node] Node protocols are initialized !!
2026-02-04 17:13:48.497 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:13864/debug/v1/info" -H "Content-Type: application/json" -d 'None'
2026-02-04 17:13:48.500 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"listenAddresses":["/ip4/172.18.55.47/tcp/13865/p2p/16Uiu2HAmTi2o2KH4KTdmop8YfPeEeu1Hf1hurwfNFi6FqZXWy5N3","/ip4/172.18.55.47/tcp/13866/ws/p2p/16Uiu2HAmTi2o2KH4KTdmop8YfPeEeu1Hf1hurwfNFi6FqZXWy5N3"],"enrUri":"enr:-L24QAFw9C9svn77fegDa7A5mME3du8BEmsUQk1nKEVzP19_PjFESOV4j1kvZ3j2Vv-l8BS1dwcp9mziLWaCIwvFwRICgmlkgnY0gmlwhKwSNy-KbXVsdGlhZGRyc5YACASsEjcvBjYpAAoErBI3LwY2Kt0DgnJzhQADAQAAiXNlY3AyNTZrMaED36bPNRTDo1tjks8GRk8xbpJbnW0dMK7OskmNdwVWSaSDdGNwgjYpg3VkcII2K4V3YWt1MgU"}'
2026-02-04 17:13:48.500 INFO [src.node.waku_node] REST service is ready !!
2026-02-04 17:13:48.501 DEBUG [src.steps.filter] Running fixture setup: setup_main_filter_node
2026-02-04 17:13:48.507 DEBUG [src.node.docker_mananger] Docker client initialized with image wakuorg/nwaku:latest
2026-02-04 17:13:48.507 DEBUG [src.node.waku_node] WakuNode instance initialized with log path ./log/docker/node2_2026-02-04_17-13-47__1035dd26-6aa2-43f5-82b4-0ddf16f4544d__wakuorg_nwaku:latest.log
2026-02-04 17:13:48.508 DEBUG [src.node.waku_node] Starting Node...
2026-02-04 17:13:48.508 DEBUG [src.node.docker_mananger] Attempting to create or retrieve network waku
2026-02-04 17:13:48.509 DEBUG [src.node.docker_mananger] Network waku already exists
2026-02-04 17:13:48.509 DEBUG [src.node.docker_mananger] Generated random external IP 172.18.121.56
2026-02-04 17:13:48.510 DEBUG [src.node.docker_mananger] Generated ports ['33585', '33586', '33587', '33588', '33589']
2026-02-04 17:13:48.510 DEBUG [src.node.waku_node] RLN credentials were not set
2026-02-04 17:13:48.510 INFO [src.node.waku_node] RLN credentials not set or credential store not available, starting without RLN
2026-02-04 17:13:48.510 DEBUG [src.node.waku_node] Using volumes []
2026-02-04 17:13:48.510 DEBUG [src.node.docker_mananger] docker run -i -t -p 33585:33585 -p 33586:33586 -p 33587:33587 -p 33588:33588 -p 33589:33589 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=33587 --rest-port=33585 --tcp-port=33586 --discv5-udp-port=33588 --rest-address=0.0.0.0 --nat=extip:172.18.121.56 --peer-exchange=true --discv5-discovery=true --cluster-id=3 --nodekey=ecd1cc06d6c7dec59db931dc21dd2c1cbefb047835d9aa11e1a64d71ceeedbf5 --shard=0 --metrics-server=true --metrics-server-address=0.0.0.0 --metrics-server-port=33589 --metrics-logging=true --relay=false --discv5-bootstrap-node=enr:-L24QAFw9C9svn77fegDa7A5mME3du8BEmsUQk1nKEVzP19_PjFESOV4j1kvZ3j2Vv-l8BS1dwcp9mziLWaCIwvFwRICgmlkgnY0gmlwhKwSNy-KbXVsdGlhZGRyc5YACASsEjcvBjYpAAoErBI3LwY2Kt0DgnJzhQADAQAAiXNlY3AyNTZrMaED36bPNRTDo1tjks8GRk8xbpJbnW0dMK7OskmNdwVWSaSDdGNwgjYpg3VkcII2K4V3YWt1MgU --filternode=/ip4/172.18.55.47/tcp/13865/p2p/16Uiu2HAmTi2o2KH4KTdmop8YfPeEeu1Hf1hurwfNFi6FqZXWy5N3
2026-02-04 17:13:48.703 DEBUG [src.node.docker_mananger] docker network connect --ip 172.18.121.56 waku 916e9fb06d0b32a14b9d6b9eadfaccf77cea5aad89acba6b5ebe2960450ab401
2026-02-04 17:13:48.733 DEBUG [src.node.docker_mananger] Container started with ID 916e9fb06d0b. Setting up logs at ./log/docker/node2_2026-02-04_17-13-47__1035dd26-6aa2-43f5-82b4-0ddf16f4544d__wakuorg_nwaku:latest.log
2026-02-04 17:13:48.734 DEBUG [src.node.waku_node] Started container from image wakuorg/nwaku:latest. REST: 33585
2026-02-04 17:13:48.734 DEBUG [src.libs.common] Sleeping for 1 seconds
2026-02-04 17:13:49.734 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:33585/health" -H "Content-Type: application/json" -d 'None'
2026-02-04 17:13:49.739 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"nodeHealth":"READY","protocolsHealth":[{"Relay":"NOT_MOUNTED"},{"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":"READY"}]}'
2026-02-04 17:13:49.739 INFO [src.node.waku_node] Node protocols are initialized !!
2026-02-04 17:13:49.739 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:33585/debug/v1/info" -H "Content-Type: application/json" -d 'None'
2026-02-04 17:13:49.742 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"listenAddresses":["/ip4/172.18.121.56/tcp/33586/p2p/16Uiu2HAmJKcJM1SbmHrDXtdoeapi4mFKVMzTRpiPuTBftWubskyp","/ip4/172.18.121.56/tcp/33587/ws/p2p/16Uiu2HAmJKcJM1SbmHrDXtdoeapi4mFKVMzTRpiPuTBftWubskyp"],"enrUri":"enr:-L24QJv1bMzY0ntjjgxcEIpFwkz3_Jf6ZReeyx_30C7TziG5fdYjHdji6jibJQrOWk9_UT70CANg3sFd_gdIm20SM1ACgmlkgnY0gmlwhKwSeTiKbXVsdGlhZGRyc5YACASsEnk4BoMyAAoErBJ5OAaDM90DgnJzhQADAQAAiXNlY3AyNTZrMaEDVC8nP2uGRvw_oqhaDBrBsVjmzaYZ3dlCPXu6sKXofRuDdGNwgoMyg3VkcIKDNIV3YWt1MgA"}'
2026-02-04 17:13:49.742 INFO [src.node.waku_node] REST service is ready !!
2026-02-04 17:13:49.743 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:33585/admin/v1/peers" -H "Content-Type: application/json" -d '["/ip4/172.18.55.47/tcp/13865/p2p/16Uiu2HAmTi2o2KH4KTdmop8YfPeEeu1Hf1hurwfNFi6FqZXWy5N3"]'
2026-02-04 17:13:49.774 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2026-02-04 17:13:49.774 DEBUG [src.steps.filter] Running fixture setup: subscribe_main_nodes
2026-02-04 17:13:49.776 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:13864/relay/v1/subscriptions" -H "Content-Type: application/json" -d '["/waku/2/rs/3/1"]'
2026-02-04 17:13:49.791 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2026-02-04 17:13:49.792 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:33585/filter/v2/subscriptions" -H "Content-Type: application/json" -d '{"requestId": "7f1f8b88-d068-451a-b835-0382cab9dfe2", "contentFilters": ["/test/1/waku-relay/proto"], "pubsubTopic": "/waku/2/rs/3/1"}'
2026-02-04 17:13:49.804 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"requestId":"7f1f8b88-d068-451a-b835-0382cab9dfe2","statusDesc":"OK"}'
2026-02-04 17:13:49.805 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:13864/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-02-04 17:13:49.812 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2026-02-04 17:13:49.813 DEBUG [src.libs.common] Sleeping for 0.5 seconds
2026-02-04 17:13:50.313 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:33585/filter/v2/messages/%2Ftest%2F1%2Fwaku-relay%2Fproto" -H "Content-Type: application/json" -d 'None'
2026-02-04 17:13:50.316 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":1770225229805691263,"ephemeral":false}]'
2026-02-04 17:13:50.317 DEBUG [src.libs.common] Sleeping for 5 seconds
2026-02-04 17:13:55.317 DEBUG [src.steps.metrics] Checking metric: libp2p_peers has 1
2026-02-04 17:13:55.322 DEBUG [src.steps.metrics] Found metric: libp2p_peers with value 1.0
2026-02-04 17:13:55.322 DEBUG [src.steps.metrics] Checking metric: libp2p_pubsub_peers has 1
2026-02-04 17:13:55.326 DEBUG [src.steps.metrics] Found metric: libp2p_pubsub_peers with value 1.0
2026-02-04 17:13:55.326 DEBUG [src.steps.metrics] Checking metric: libp2p_pubsub_topics has 1
2026-02-04 17:13:55.330 DEBUG [src.steps.metrics] Found metric: libp2p_pubsub_topics with value 2.0
2026-02-04 17:13:55.330 DEBUG [src.steps.metrics] Checking metric: libp2p_pubsub_subscriptions_total has 1
2026-02-04 17:13:55.333 DEBUG [src.steps.metrics] Found metric: libp2p_pubsub_subscriptions_total with value 2.0
2026-02-04 17:13:55.334 DEBUG [src.steps.metrics] Checking metric: waku_peer_store_size has 1
2026-02-04 17:13:55.337 DEBUG [src.steps.metrics] Found metric: waku_peer_store_size with value 1.0
2026-02-04 17:13:55.338 DEBUG [src.steps.metrics] Checking metric: waku_histogram_message_size_count has 1
2026-02-04 17:13:55.341 DEBUG [src.steps.metrics] Found metric: waku_histogram_message_size_count with value 1.0
2026-02-04 17:13:55.341 DEBUG [src.steps.metrics] Checking metric: waku_node_messages_total{type="relay"} has 1
2026-02-04 17:13:55.345 DEBUG [src.steps.metrics] Found metric: waku_node_messages_total{type="relay"} with value 1.0
2026-02-04 17:13:55.345 DEBUG [src.steps.metrics] Checking metric: waku_service_peers{protocol="/vac/waku/filter-subscribe/2.0.0-beta1",peerId="/ip4/172.18.55.47/tcp/13865"} has 1
2026-02-04 17:13:55.349 DEBUG [src.steps.metrics] Found metric: waku_service_peers{protocol="/vac/waku/filter-subscribe/2.0.0-beta1",peerId="/ip4/172.18.55.47/tcp/13865"} with value 1.0
2026-02-04 17:13:55.349 DEBUG [src.steps.metrics] Checking metric: libp2p_peers has 1
2026-02-04 17:13:55.352 DEBUG [src.steps.metrics] Found metric: libp2p_peers with value 1.0
2026-02-04 17:13:55.353 DEBUG [src.steps.metrics] Checking metric: libp2p_total_dial_attempts_total has 1
2026-02-04 17:13:55.356 DEBUG [src.steps.metrics] Found metric: libp2p_total_dial_attempts_total with value 1.0
2026-02-04 17:13:55.356 DEBUG [src.steps.metrics] Checking metric: waku_peer_store_size has 1
2026-02-04 17:13:55.360 DEBUG [src.steps.metrics] Found metric: waku_peer_store_size with value 1.0
2026-02-04 17:13:55.362 DEBUG [tests.conftest] Running fixture teardown: test_setup
2026-02-04 17:13:55.363 DEBUG [tests.conftest] Running fixture teardown: close_open_nodes
2026-02-04 17:13:55.363 DEBUG [src.node.waku_node] Stopping container with id 296a66ad7170
2026-02-04 17:13:55.928 DEBUG [src.node.waku_node] Container stopped.
2026-02-04 17:13:55.930 DEBUG [src.node.waku_node] Stopping container with id 916e9fb06d0b
2026-02-04 17:13:56.497 DEBUG [src.node.waku_node] Container stopped.
2026-02-04 17:13:56.499 DEBUG [tests.conftest] Running fixture teardown: check_waku_log_errors
2026-02-04 17:13:56.509 DEBUG [src.node.docker_mananger] No errors found in the waku logs.
2026-02-04 17:13:56.513 DEBUG [src.node.docker_mananger] No errors found in the waku logs.