113 lines
17 KiB
Plaintext

2026-03-11 04:42:01.325 DEBUG [tests.conftest] Running fixture setup: test_id
2026-03-11 04:42:01.325 DEBUG [tests.conftest] Running test: test_metrics_after_store_get with id: 2026-03-11_04-42-01__26010bbd-e719-4aa9-aa4f-f3b0b1d69317
2026-03-11 04:42:01.325 DEBUG [src.steps.common] Running fixture setup: common_setup
2026-03-11 04:42:01.326 DEBUG [src.steps.filter] Running fixture setup: filter_setup
2026-03-11 04:42:01.326 DEBUG [src.steps.light_push] Running fixture setup: light_push_setup
2026-03-11 04:42:01.326 DEBUG [src.steps.relay] Running fixture setup: relay_setup
2026-03-11 04:42:01.326 DEBUG [src.steps.store] Running fixture setup: store_setup
2026-03-11 04:42:01.327 DEBUG [src.steps.store] Running fixture setup: node_setup
2026-03-11 04:42:01.334 DEBUG [src.node.docker_mananger] Docker client initialized with image wakuorg/nwaku:latest
2026-03-11 04:42:01.334 DEBUG [src.node.waku_node] WakuNode instance initialized with log path ./log/docker/publishing_node1_2026-03-11_04-42-01__26010bbd-e719-4aa9-aa4f-f3b0b1d69317__wakuorg_nwaku:latest.log
2026-03-11 04:42:01.334 DEBUG [src.node.waku_node] Starting Node...
2026-03-11 04:42:01.335 DEBUG [src.node.docker_mananger] Attempting to create or retrieve network waku
2026-03-11 04:42:01.336 DEBUG [src.node.docker_mananger] Network waku already exists
2026-03-11 04:42:01.336 DEBUG [src.node.docker_mananger] Generated random external IP 172.18.195.175
2026-03-11 04:42:01.336 DEBUG [src.node.docker_mananger] Generated ports ['58058', '58059', '58060', '58061', '58062']
2026-03-11 04:42:01.337 DEBUG [src.node.waku_node] RLN credentials were not set
2026-03-11 04:42:01.337 INFO [src.node.waku_node] RLN credentials not set or credential store not available, starting without RLN
2026-03-11 04:42:01.337 DEBUG [src.node.waku_node] Using volumes []
2026-03-11 04:42:01.337 DEBUG [src.node.docker_mananger] docker run -i -t -p 58058:58058 -p 58059:58059 -p 58060:58060 -p 58061:58061 -p 58062:58062 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=58060 --rest-port=58058 --tcp-port=58059 --discv5-udp-port=58061 --rest-address=0.0.0.0 --nat=extip:172.18.195.175 --peer-exchange=true --discv5-discovery=true --cluster-id=3 --nodekey=e20ccdf4227cd3877cdf9cc5e94ef89a0ec6b76abd3bdd647c6bc943059a8bef --shard=0 --metrics-server=true --metrics-server-address=0.0.0.0 --metrics-server-port=58062 --metrics-logging=true --store=true --relay=true
2026-03-11 04:42:01.523 ERROR [src.node.docker_mananger] Max retries reached for container 2512290ffc91. Exiting log stream.
2026-03-11 04:42:01.547 DEBUG [src.node.docker_mananger] docker network connect --ip 172.18.195.175 waku cead64482c80661e4f1cfef875345def3d39024bf11f51bcc48d071b6ab3dd6c
2026-03-11 04:42:01.585 DEBUG [src.node.docker_mananger] Container started with ID cead64482c80. Setting up logs at ./log/docker/publishing_node1_2026-03-11_04-42-01__26010bbd-e719-4aa9-aa4f-f3b0b1d69317__wakuorg_nwaku:latest.log
2026-03-11 04:42:01.586 DEBUG [src.node.waku_node] Started container from image wakuorg/nwaku:latest. REST: 58058
2026-03-11 04:42:01.586 DEBUG [src.libs.common] Sleeping for 1 seconds
2026-03-11 04:42:02.114 ERROR [src.node.docker_mananger] Max retries reached for container 432bf03794b1. Exiting log stream.
2026-03-11 04:42:02.586 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:58058/health" -H "Content-Type: application/json" -d 'None'
2026-03-11 04:42:02.589 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_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"},{"Rln Relay":"NOT_MOUNTED"}]}'
2026-03-11 04:42:02.590 INFO [src.node.waku_node] Node protocols are initialized !!
2026-03-11 04:42:02.590 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:58058/debug/v1/info" -H "Content-Type: application/json" -d 'None'
2026-03-11 04:42:02.592 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"listenAddresses":["/ip4/172.18.195.175/tcp/58059/p2p/16Uiu2HAm9hn5EJk64BnVdE9ba9uPQuW6Ww9tqBPWPQ3ySdqgkyDp","/ip4/172.18.195.175/tcp/58060/ws/p2p/16Uiu2HAm9hn5EJk64BnVdE9ba9uPQuW6Ww9tqBPWPQ3ySdqgkyDp"],"enrUri":"enr:-L24QGuCifbPnJc3Uuvhlhtwm4S063KoK0lQYXUmqFgnNthgBp20nGmc8fK8rtoe_rKZFbGPi-mB9gvkhYL05cvOk2gCgmlkgnY0gmlwhKwSw6-KbXVsdGlhZGRyc5YACASsEsOvBuLLAAoErBLDrwbizN0DgnJzhQADAQAAiXNlY3AyNTZrMaEC1CPM1OrD_44f-ZEBwceJ5tITagT3fLrFuWDfUXOEwm-DdGNwguLLg3VkcILizYV3YWt1MgM"}'
2026-03-11 04:42:02.593 INFO [src.node.waku_node] REST service is ready !!
2026-03-11 04:42:02.600 DEBUG [src.node.docker_mananger] Docker client initialized with image wakuorg/nwaku:latest
2026-03-11 04:42:02.601 DEBUG [src.node.waku_node] WakuNode instance initialized with log path ./log/docker/store_node1_2026-03-11_04-42-01__26010bbd-e719-4aa9-aa4f-f3b0b1d69317__wakuorg_nwaku:latest.log
2026-03-11 04:42:02.601 DEBUG [src.node.waku_node] Starting Node...
2026-03-11 04:42:02.601 DEBUG [src.node.docker_mananger] Attempting to create or retrieve network waku
2026-03-11 04:42:02.602 DEBUG [src.node.docker_mananger] Network waku already exists
2026-03-11 04:42:02.603 DEBUG [src.node.docker_mananger] Generated random external IP 172.18.94.228
2026-03-11 04:42:02.603 DEBUG [src.node.docker_mananger] Generated ports ['61238', '61239', '61240', '61241', '61242']
2026-03-11 04:42:02.603 DEBUG [src.node.waku_node] RLN credentials were not set
2026-03-11 04:42:02.603 INFO [src.node.waku_node] RLN credentials not set or credential store not available, starting without RLN
2026-03-11 04:42:02.603 DEBUG [src.node.waku_node] Using volumes []
2026-03-11 04:42:02.603 DEBUG [src.node.docker_mananger] docker run -i -t -p 61238:61238 -p 61239:61239 -p 61240:61240 -p 61241:61241 -p 61242:61242 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=61240 --rest-port=61238 --tcp-port=61239 --discv5-udp-port=61241 --rest-address=0.0.0.0 --nat=extip:172.18.94.228 --peer-exchange=true --discv5-discovery=true --cluster-id=3 --nodekey=a06dbd8aed954e21dacb9c2b1dbb03d412da03dbd745144c3aebcbb1ecb227e3 --shard=0 --metrics-server=true --metrics-server-address=0.0.0.0 --metrics-server-port=61242 --metrics-logging=true --discv5-bootstrap-node=enr:-L24QGuCifbPnJc3Uuvhlhtwm4S063KoK0lQYXUmqFgnNthgBp20nGmc8fK8rtoe_rKZFbGPi-mB9gvkhYL05cvOk2gCgmlkgnY0gmlwhKwSw6-KbXVsdGlhZGRyc5YACASsEsOvBuLLAAoErBLDrwbizN0DgnJzhQADAQAAiXNlY3AyNTZrMaEC1CPM1OrD_44f-ZEBwceJ5tITagT3fLrFuWDfUXOEwm-DdGNwguLLg3VkcILizYV3YWt1MgM --storenode=/ip4/172.18.195.175/tcp/58059/p2p/16Uiu2HAm9hn5EJk64BnVdE9ba9uPQuW6Ww9tqBPWPQ3ySdqgkyDp --store=true --relay=true
2026-03-11 04:42:02.825 DEBUG [src.node.docker_mananger] docker network connect --ip 172.18.94.228 waku 89ad56fe1774dbd8447b8eab15c7733c7bf8d72bf3b72ae60101da264c09ba86
2026-03-11 04:42:02.860 DEBUG [src.node.docker_mananger] Container started with ID 89ad56fe1774. Setting up logs at ./log/docker/store_node1_2026-03-11_04-42-01__26010bbd-e719-4aa9-aa4f-f3b0b1d69317__wakuorg_nwaku:latest.log
2026-03-11 04:42:02.861 DEBUG [src.node.waku_node] Started container from image wakuorg/nwaku:latest. REST: 61238
2026-03-11 04:42:02.861 DEBUG [src.libs.common] Sleeping for 1 seconds
2026-03-11 04:42:03.862 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:61238/health" -H "Content-Type: application/json" -d 'None'
2026-03-11 04:42:03.864 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"nodeHealth":"READY","connectionStatus":"PartiallyConnected","protocolsHealth":[{"Relay":"READY"},{"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"},{"Rln Relay":"NOT_MOUNTED"}]}'
2026-03-11 04:42:03.865 INFO [src.node.waku_node] Node protocols are initialized !!
2026-03-11 04:42:03.865 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:61238/debug/v1/info" -H "Content-Type: application/json" -d 'None'
2026-03-11 04:42:03.867 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"listenAddresses":["/ip4/172.18.94.228/tcp/61239/p2p/16Uiu2HAmNHvpdnKc6rxWk41haGWgDf2fMu8tAHHnHT9SJj496Lns","/ip4/172.18.94.228/tcp/61240/ws/p2p/16Uiu2HAmNHvpdnKc6rxWk41haGWgDf2fMu8tAHHnHT9SJj496Lns"],"enrUri":"enr:-L24QK67X3iSBzRfO2AnnAgLj5U1Ztb4OJfOKft1S4f6h6pIaWGkKwAdaKiFmQ-Vqdn9-_w2l3Ic0sVMR45FPsdCQGgCgmlkgnY0gmlwhKwSXuSKbXVsdGlhZGRyc5YACASsEl7kBu83AAoErBJe5AbvON0DgnJzhQADAQAAiXNlY3AyNTZrMaEDjy-uu3v6HnqXCD1l0ThiQ1OiuZUrfvwahQ-jt2wKijiDdGNwgu83g3VkcILvOYV3YWt1MgM"}'
2026-03-11 04:42:03.868 INFO [src.node.waku_node] REST service is ready !!
2026-03-11 04:42:03.868 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:61238/admin/v1/peers" -H "Content-Type: application/json" -d '["/ip4/172.18.195.175/tcp/58059/p2p/16Uiu2HAm9hn5EJk64BnVdE9ba9uPQuW6Ww9tqBPWPQ3ySdqgkyDp"]'
2026-03-11 04:42:03.871 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2026-03-11 04:42:03.871 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:58058/relay/v1/subscriptions" -H "Content-Type: application/json" -d '["/waku/2/rs/3/1"]'
2026-03-11 04:42:03.876 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2026-03-11 04:42:03.876 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:61238/relay/v1/subscriptions" -H "Content-Type: application/json" -d '["/waku/2/rs/3/1"]'
2026-03-11 04:42:03.882 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2026-03-11 04:42:03.885 DEBUG [src.steps.store] Relaying message
2026-03-11 04:42:03.886 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:58058/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-11 04:42:03.891 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2026-03-11 04:42:03.891 DEBUG [src.libs.common] Sleeping for 0.2 seconds
2026-03-11 04:42:04.092 DEBUG [src.steps.store] Checking that peer wakuorg/nwaku:latest can find the stored messages
2026-03-11 04:42:04.092 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:58058/store/v3/messages?pubsubTopic=%2Fwaku%2F2%2Frs%2F3%2F1&pageSize=50&ascending=true" -H "Content-Type: application/json" -d 'None'
2026-03-11 04:42:04.096 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"requestId":"","statusCode":200,"statusDesc":"OK","messages":[{"messageHash":"0x0a5df17c1bf00acc3d818e0874a86e892c24fc813ff08d3fb0175748b4b608a2"}]}'
2026-03-11 04:42:04.096 DEBUG [src.steps.store] messages length is 1
2026-03-11 04:42:04.097 DEBUG [src.steps.store] Checking that peer wakuorg/nwaku:latest can find the stored messages
2026-03-11 04:42:04.097 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:61238/store/v3/messages?pubsubTopic=%2Fwaku%2F2%2Frs%2F3%2F1&pageSize=50&ascending=true" -H "Content-Type: application/json" -d 'None'
2026-03-11 04:42:04.100 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"requestId":"","statusCode":200,"statusDesc":"OK","messages":[{"messageHash":"0x0a5df17c1bf00acc3d818e0874a86e892c24fc813ff08d3fb0175748b4b608a2"}]}'
2026-03-11 04:42:04.100 DEBUG [src.steps.store] messages length is 1
2026-03-11 04:42:04.101 DEBUG [src.libs.common] Sleeping for 5 seconds
2026-03-11 04:42:09.101 DEBUG [src.steps.metrics] Checking metric: libp2p_peers has 1
2026-03-11 04:42:09.106 DEBUG [src.steps.metrics] Found metric: libp2p_peers with value 1.0
2026-03-11 04:42:09.106 DEBUG [src.steps.metrics] Checking metric: libp2p_pubsub_peers has 1
2026-03-11 04:42:09.110 DEBUG [src.steps.metrics] Found metric: libp2p_pubsub_peers with value 1.0
2026-03-11 04:42:09.110 DEBUG [src.steps.metrics] Checking metric: libp2p_pubsub_topics has 1
2026-03-11 04:42:09.113 DEBUG [src.steps.metrics] Found metric: libp2p_pubsub_topics with value 2.0
2026-03-11 04:42:09.113 DEBUG [src.steps.metrics] Checking metric: libp2p_pubsub_subscriptions_total has 1
2026-03-11 04:42:09.116 DEBUG [src.steps.metrics] Found metric: libp2p_pubsub_subscriptions_total with value 2.0
2026-03-11 04:42:09.117 DEBUG [src.steps.metrics] Checking metric: waku_peer_store_size has 1
2026-03-11 04:42:09.120 DEBUG [src.steps.metrics] Found metric: waku_peer_store_size with value 1.0
2026-03-11 04:42:09.120 DEBUG [src.steps.metrics] Checking metric: waku_histogram_message_size_count has 1
2026-03-11 04:42:09.123 DEBUG [src.steps.metrics] Found metric: waku_histogram_message_size_count with value 1.0
2026-03-11 04:42:09.124 DEBUG [src.steps.metrics] Checking metric: waku_node_messages_total{type="relay"} has 1
2026-03-11 04:42:09.127 DEBUG [src.steps.metrics] Found metric: waku_node_messages_total{type="relay"} with value 1.0
2026-03-11 04:42:09.127 DEBUG [src.steps.metrics] Checking metric: waku_service_peers{protocol="/vac/waku/store/2.0.0-beta4",peerId="/ip4/172.18.195.175/tcp/58059"} has 1
2026-03-11 04:42:09.131 DEBUG [src.steps.metrics] Found metric: waku_service_peers{protocol="/vac/waku/store/2.0.0-beta4",peerId="/ip4/172.18.195.175/tcp/58059"} with value 1.0
2026-03-11 04:42:09.131 DEBUG [src.steps.metrics] Checking metric: waku_service_peers{protocol="/vac/waku/store-query/3.0.0",peerId="/ip4/172.18.195.175/tcp/58059"} has 1
2026-03-11 04:42:09.134 DEBUG [src.steps.metrics] Found metric: waku_service_peers{protocol="/vac/waku/store-query/3.0.0",peerId="/ip4/172.18.195.175/tcp/58059"} with value 1.0
2026-03-11 04:42:09.135 DEBUG [src.steps.metrics] Checking metric: libp2p_peers has 1
2026-03-11 04:42:09.138 DEBUG [src.steps.metrics] Found metric: libp2p_peers with value 1.0
2026-03-11 04:42:09.138 DEBUG [src.steps.metrics] Checking metric: libp2p_pubsub_peers has 1
2026-03-11 04:42:09.141 DEBUG [src.steps.metrics] Found metric: libp2p_pubsub_peers with value 1.0
2026-03-11 04:42:09.142 DEBUG [src.steps.metrics] Checking metric: libp2p_pubsub_topics has 1
2026-03-11 04:42:09.145 DEBUG [src.steps.metrics] Found metric: libp2p_pubsub_topics with value 2.0
2026-03-11 04:42:09.145 DEBUG [src.steps.metrics] Checking metric: libp2p_pubsub_subscriptions_total has 1
2026-03-11 04:42:09.149 DEBUG [src.steps.metrics] Found metric: libp2p_pubsub_subscriptions_total with value 2.0
2026-03-11 04:42:09.149 DEBUG [src.steps.metrics] Checking metric: waku_peer_store_size has 1
2026-03-11 04:42:09.152 DEBUG [src.steps.metrics] Found metric: waku_peer_store_size with value 1.0
2026-03-11 04:42:09.152 DEBUG [src.steps.metrics] Checking metric: waku_histogram_message_size_count has 1
2026-03-11 04:42:09.156 DEBUG [src.steps.metrics] Found metric: waku_histogram_message_size_count with value 1.0
2026-03-11 04:42:09.156 DEBUG [src.steps.metrics] Checking metric: waku_node_messages_total{type="relay"} has 1
2026-03-11 04:42:09.159 DEBUG [src.steps.metrics] Found metric: waku_node_messages_total{type="relay"} with value 1.0
2026-03-11 04:42:09.162 DEBUG [tests.conftest] Running fixture teardown: test_setup
2026-03-11 04:42:09.163 DEBUG [tests.conftest] Running fixture teardown: close_open_nodes
2026-03-11 04:42:09.163 DEBUG [src.node.waku_node] Stopping container with id cead64482c80
2026-03-11 04:42:09.749 DEBUG [src.node.waku_node] Container stopped.
2026-03-11 04:42:09.751 DEBUG [src.node.waku_node] Stopping container with id 89ad56fe1774
2026-03-11 04:42:10.331 DEBUG [src.node.waku_node] Container stopped.
2026-03-11 04:42:10.332 DEBUG [tests.conftest] Running fixture teardown: check_waku_log_errors
2026-03-11 04:42:10.341 DEBUG [src.node.docker_mananger] No errors found in the waku logs.
2026-03-11 04:42:10.347 DEBUG [src.node.docker_mananger] No errors found in the waku logs.