82 lines
14 KiB
Plaintext
Raw Blame History

This file contains ambiguous Unicode characters

This file contains Unicode characters that might be confused with other characters. If you think that this is intentional, you can safely ignore this warning. Use the Escape button to reveal them.

2026-04-22 23:59:22.159 INFO [tests.conftest] Fleet bootstrap inactive pass --fleet (or set FLEET_BOOTSTRAP=true) to connect local nodes to the waku.test fleet
2026-04-22 23:59:22.159 DEBUG [tests.conftest] Running fixture setup: test_id
2026-04-22 23:59:22.160 DEBUG [tests.conftest] Running test: test_relay_with_latency_between_two_nodes with id: 2026-04-22_23-59-22__be87bfeb-9526-41d8-8190-95a1ba9d6367
2026-04-22 23:59:22.160 DEBUG [src.steps.common] Running fixture setup: common_setup
2026-04-22 23:59:22.160 DEBUG [src.steps.relay] Running fixture setup: relay_setup
2026-04-22 23:59:22.166 DEBUG [src.node.docker_mananger] Docker client initialized with image wakuorg/nwaku:latest
2026-04-22 23:59:22.166 DEBUG [src.node.waku_node] WakuNode instance initialized with log path ./log/docker/node1_2026-04-22_23-59-22__be87bfeb-9526-41d8-8190-95a1ba9d6367__wakuorg_nwaku:latest.log
2026-04-22 23:59:22.171 DEBUG [src.node.docker_mananger] Docker client initialized with image wakuorg/nwaku:latest
2026-04-22 23:59:22.171 DEBUG [src.node.waku_node] WakuNode instance initialized with log path ./log/docker/node2_2026-04-22_23-59-22__be87bfeb-9526-41d8-8190-95a1ba9d6367__wakuorg_nwaku:latest.log
2026-04-22 23:59:22.171 INFO [tests.e2e.test_network_conditions] Starting node1 and node2 with relay enabled
2026-04-22 23:59:22.171 DEBUG [src.node.waku_node] Starting Node...
2026-04-22 23:59:22.172 DEBUG [src.node.docker_mananger] Attempting to create or retrieve network waku
2026-04-22 23:59:22.173 DEBUG [src.node.docker_mananger] Network waku already exists
2026-04-22 23:59:22.173 DEBUG [src.node.docker_mananger] Generated random external IP 172.18.113.19
2026-04-22 23:59:22.173 DEBUG [src.node.docker_mananger] Generated ports ['54634', '54635', '54636', '54637', '54638']
2026-04-22 23:59:22.173 DEBUG [src.node.waku_node] RLN credentials were not set
2026-04-22 23:59:22.173 INFO [src.node.waku_node] RLN credentials not set or credential store not available, starting without RLN
2026-04-22 23:59:22.173 DEBUG [src.node.waku_node] Using volumes []
2026-04-22 23:59:22.173 DEBUG [src.node.docker_mananger] docker run -i -t -p 54634:54634 -p 54635:54635 -p 54636:54636 -p 54637:54637 -p 54638:54638 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=54636 --rest-port=54634 --tcp-port=54635 --discv5-udp-port=54637 --rest-address=0.0.0.0 --nat=extip:172.18.113.19 --peer-exchange=true --discv5-discovery=true --cluster-id=198 --nodekey=9b7a1dbc1660b60c6cdbebfaa18ac7534ba7ecdc2bb29b5afdd19e12e3ed1d99 --shard=0 --metrics-server=true --metrics-server-address=0.0.0.0 --metrics-server-port=54638 --metrics-logging=true --relay=true
2026-04-22 23:59:22.334 ERROR [src.node.docker_mananger] Max retries reached for container 5e3578d55b32. Exiting log stream.
2026-04-22 23:59:22.501 DEBUG [src.node.docker_mananger] docker network connect --ip 172.18.113.19 waku a9702c0e2d23bcf11958271a0a9dd6dee52292af6e1097d2835f9674eec726bb
2026-04-22 23:59:22.686 DEBUG [src.node.docker_mananger] Container started with ID a9702c0e2d23. Setting up logs at ./log/docker/node1_2026-04-22_23-59-22__be87bfeb-9526-41d8-8190-95a1ba9d6367__wakuorg_nwaku:latest.log
2026-04-22 23:59:22.687 DEBUG [src.node.waku_node] Started container from image wakuorg/nwaku:latest. REST: 54634
2026-04-22 23:59:22.687 DEBUG [src.libs.common] Sleeping for 1 seconds
2026-04-22 23:59:22.864 ERROR [src.node.docker_mananger] Max retries reached for container 782806bf2ff1. Exiting log stream.
2026-04-22 23:59:23.688 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:54634/health" -H "Content-Type: application/json" -d 'None'
2026-04-22 23:59:23.690 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":"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"},{"Filter Client":"NOT_READY","desc":"No Filter service peer available yet"},{"Rln Relay":"NOT_MOUNTED"}]}'
2026-04-22 23:59:23.691 INFO [src.node.waku_node] Node protocols are initialized !!
2026-04-22 23:59:23.691 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:54634/debug/v1/info" -H "Content-Type: application/json" -d 'None'
2026-04-22 23:59:23.693 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"listenAddresses":["/ip4/172.18.113.19/tcp/54635/p2p/16Uiu2HAmQt9AqBpCjuaivfbo4YZBB9ZZKf2KAtxzZ3fUZucx6epe","/ip4/172.18.113.19/tcp/54636/ws/p2p/16Uiu2HAmQt9AqBpCjuaivfbo4YZBB9ZZKf2KAtxzZ3fUZucx6epe"],"enrUri":"enr:-L24QKVtybeSb4C25F_VV09Qf-e-16m8Miz55m77A99ALGCKMrx7GmTQKuuw_cN-yZgk0LjnhtaaJjWPheGMnLEG55kCgmlkgnY0gmlwhKwScROKbXVsdGlhZGRyc5YACASsEnETBtVrAAoErBJxEwbVbN0DgnJzhQDGAQAAiXNlY3AyNTZrMaEDtarEHhV4kGkrTqYzx_fi7MtL-Ti3d7nNbTN8DfVZ-xeDdGNwgtVrg3VkcILVbYV3YWt1MgE"}'
2026-04-22 23:59:23.693 INFO [src.node.waku_node] REST service is ready !!
2026-04-22 23:59:23.693 DEBUG [src.node.waku_node] Starting Node...
2026-04-22 23:59:23.693 DEBUG [src.node.docker_mananger] Attempting to create or retrieve network waku
2026-04-22 23:59:23.694 DEBUG [src.node.docker_mananger] Network waku already exists
2026-04-22 23:59:23.694 DEBUG [src.node.docker_mananger] Generated random external IP 172.18.54.229
2026-04-22 23:59:23.695 DEBUG [src.node.docker_mananger] Generated ports ['14056', '14057', '14058', '14059', '14060']
2026-04-22 23:59:23.695 DEBUG [src.node.waku_node] RLN credentials were not set
2026-04-22 23:59:23.695 INFO [src.node.waku_node] RLN credentials not set or credential store not available, starting without RLN
2026-04-22 23:59:23.695 DEBUG [src.node.waku_node] Using volumes []
2026-04-22 23:59:23.695 DEBUG [src.node.docker_mananger] docker run -i -t -p 14056:14056 -p 14057:14057 -p 14058:14058 -p 14059:14059 -p 14060:14060 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=14058 --rest-port=14056 --tcp-port=14057 --discv5-udp-port=14059 --rest-address=0.0.0.0 --nat=extip:172.18.54.229 --peer-exchange=true --discv5-discovery=true --cluster-id=198 --nodekey=f4a5975696f2df520e1b7cba8f8db77f68a9c3fbd41ceabe7c50bde47206a4c7 --shard=0 --metrics-server=true --metrics-server-address=0.0.0.0 --metrics-server-port=14060 --metrics-logging=true --relay=true --discv5-bootstrap-node=enr:-L24QKVtybeSb4C25F_VV09Qf-e-16m8Miz55m77A99ALGCKMrx7GmTQKuuw_cN-yZgk0LjnhtaaJjWPheGMnLEG55kCgmlkgnY0gmlwhKwScROKbXVsdGlhZGRyc5YACASsEnETBtVrAAoErBJxEwbVbN0DgnJzhQDGAQAAiXNlY3AyNTZrMaEDtarEHhV4kGkrTqYzx_fi7MtL-Ti3d7nNbTN8DfVZ-xeDdGNwgtVrg3VkcILVbYV3YWt1MgE
2026-04-22 23:59:24.564 DEBUG [src.node.docker_mananger] docker network connect --ip 172.18.54.229 waku 843ed2b4022e83cbc6be659b93d240e2b2e88807a0c3ae931ab01cb30bd59599
2026-04-22 23:59:25.222 DEBUG [src.node.docker_mananger] Container started with ID 843ed2b4022e. Setting up logs at ./log/docker/node2_2026-04-22_23-59-22__be87bfeb-9526-41d8-8190-95a1ba9d6367__wakuorg_nwaku:latest.log
2026-04-22 23:59:25.222 DEBUG [src.node.waku_node] Started container from image wakuorg/nwaku:latest. REST: 14056
2026-04-22 23:59:25.223 DEBUG [src.libs.common] Sleeping for 1 seconds
2026-04-22 23:59:26.223 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:14056/health" -H "Content-Type: application/json" -d 'None'
2026-04-22 23:59:26.226 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":"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"},{"Filter Client":"NOT_READY","desc":"No Filter service peer available yet"},{"Rln Relay":"NOT_MOUNTED"}]}'
2026-04-22 23:59:26.226 INFO [src.node.waku_node] Node protocols are initialized !!
2026-04-22 23:59:26.226 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:14056/debug/v1/info" -H "Content-Type: application/json" -d 'None'
2026-04-22 23:59:26.228 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"listenAddresses":["/ip4/172.18.54.229/tcp/14057/p2p/16Uiu2HAmPiy3pyLpYDRBimdhSfUFrFxrVJzDFSJuzJ8Mg8n3tETy","/ip4/172.18.54.229/tcp/14058/ws/p2p/16Uiu2HAmPiy3pyLpYDRBimdhSfUFrFxrVJzDFSJuzJ8Mg8n3tETy"],"enrUri":"enr:-L24QOurhLhCtXyyhLDHzrVqXDeIm3fKA14av6JC7Krrz-tyABAQOCrgrQS9YFk71sGVwphQ3OM3cqbhOw_6ZrCKzRkCgmlkgnY0gmlwhKwSNuWKbXVsdGlhZGRyc5YACASsEjblBjbpAAoErBI25QY26t0DgnJzhQDGAQAAiXNlY3AyNTZrMaEDpHVohpNhdXHDQMc5pjIIC4-JSamd1XNsywQ_ZpdxKWiDdGNwgjbpg3VkcII264V3YWt1MgE"}'
2026-04-22 23:59:26.228 INFO [src.node.waku_node] REST service is ready !!
2026-04-22 23:59:26.228 INFO [tests.e2e.test_network_conditions] Subscribing both nodes to relay topic
2026-04-22 23:59:26.228 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:54634/relay/v1/subscriptions" -H "Content-Type: application/json" -d '["/waku/2/rs/198/1"]'
2026-04-22 23:59:26.231 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2026-04-22 23:59:26.231 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:14056/relay/v1/subscriptions" -H "Content-Type: application/json" -d '["/waku/2/rs/198/1"]'
2026-04-22 23:59:26.235 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2026-04-22 23:59:26.235 INFO [tests.e2e.test_network_conditions] Waiting for autoconnection
2026-04-22 23:59:26.236 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:54634/admin/v1/peers" -H "Content-Type: application/json" -d 'None'
2026-04-22 23:59:26.238 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'[{"multiaddr":"/ip4/172.18.54.229/tcp/56182/p2p/16Uiu2HAmPiy3pyLpYDRBimdhSfUFrFxrVJzDFSJuzJ8Mg8n3tETy","protocols":["/ipfs/id/1.0.0","/libp2p/autonat/1.0.0","/libp2p/circuit/relay/0.2.0/hop","/vac/waku/metadata/1.0.0","/vac/waku/relay/2.0.0","/vac/waku/rendezvous/1.0.0","/ipfs/ping/1.0.0","/vac/waku/filter-push/2.0.0-beta1","/vac/waku/peer-exchange/2.0.0-alpha1"],"shards":[0],"connected":"Connected","agent":"logos-delivery-\\"v0.38.0-18-gbb8a7e\\"","origin":"UnknownOrigin"}]'
2026-04-22 23:59:26.238 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:14056/admin/v1/peers" -H "Content-Type: application/json" -d 'None'
2026-04-22 23:59:26.241 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'[{"multiaddr":"/ip4/172.18.113.19/tcp/54635/p2p/16Uiu2HAmQt9AqBpCjuaivfbo4YZBB9ZZKf2KAtxzZ3fUZucx6epe","protocols":["/ipfs/id/1.0.0","/libp2p/autonat/1.0.0","/libp2p/circuit/relay/0.2.0/hop","/vac/waku/metadata/1.0.0","/vac/waku/relay/2.0.0","/vac/waku/rendezvous/1.0.0","/ipfs/ping/1.0.0","/vac/waku/filter-push/2.0.0-beta1","/vac/waku/peer-exchange/2.0.0-alpha1"],"shards":[0],"connected":"Connected","agent":"logos-delivery-\\"v0.38.0-18-gbb8a7e\\"","origin":"Discv5"}]'
2026-04-22 23:59:26.241 DEBUG [src.libs.common] Sleeping for 10 seconds
2026-04-22 23:59:36.241 DEBUG [tests.e2e.test_network_conditions] Applying 5000ms latency to node2
2026-04-22 23:59:36.243 INFO [src.steps.network_conditions] TC exec: ['sudo', '-n', 'nsenter', '-t', '23959', '-n', 'tc', 'qdisc', 'del', 'dev', 'eth0', 'root']
2026-04-22 23:59:36.394 INFO [src.steps.network_conditions] TC exec: ['sudo', '-n', 'nsenter', '-t', '23959', '-n', 'tc', 'qdisc', 'add', 'dev', 'eth0', 'root', 'netem', 'delay', '5000ms']
2026-04-22 23:59:36.406 DEBUG [tests.e2e.test_network_conditions] Publishing message from node1
2026-04-22 23:59:36.406 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:54634/relay/v1/messages/%2Fwaku%2F2%2Frs%2F198%2F1" -H "Content-Type: application/json" -d '{"payload": "UmVsYXkgd29ya3MhIQ==", "contentTopic": "/test/1/waku-relay/proto", "timestamp": '$(date +%s%N)'}'
2026-04-22 23:59:36.410 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2026-04-22 23:59:36.410 DEBUG [tests.e2e.test_network_conditions] Fetching relay messages on node2
2026-04-22 23:59:36.411 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:14056/relay/v1/messages/%2Fwaku%2F2%2Frs%2F198%2F1" -H "Content-Type: application/json" -d 'None'
2026-04-22 23:59:46.413 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":1776902376406033179,"ephemeral":false,"proof":""}]'
2026-04-22 23:59:46.415 INFO [src.steps.network_conditions] TC exec: ['sudo', '-n', 'nsenter', '-t', '23959', '-n', 'tc', 'qdisc', 'del', 'dev', 'eth0', 'root']
2026-04-22 23:59:46.424 DEBUG [tests.conftest] Running fixture teardown: test_setup
2026-04-22 23:59:46.425 DEBUG [tests.conftest] Running fixture teardown: close_open_nodes
2026-04-22 23:59:46.425 DEBUG [src.node.waku_node] Stopping container with id a9702c0e2d23
2026-04-22 23:59:47.158 DEBUG [src.node.waku_node] Container stopped.
2026-04-22 23:59:47.159 DEBUG [src.node.waku_node] Stopping container with id 843ed2b4022e
2026-04-22 23:59:47.969 ERROR [src.node.docker_mananger] Max retries reached for container a9702c0e2d23. Exiting log stream.
2026-04-22 23:59:48.270 DEBUG [src.node.waku_node] Container stopped.
2026-04-22 23:59:48.271 DEBUG [tests.conftest] Running fixture teardown: check_waku_log_errors
2026-04-22 23:59:48.284 DEBUG [src.node.docker_mananger] No errors found in the waku logs.
2026-04-22 23:59:48.297 DEBUG [src.node.docker_mananger] No errors found in the waku logs.