100 lines
17 KiB
Plaintext

2026-03-28 04:41:12.929 DEBUG [tests.conftest] Running fixture setup: test_id
2026-03-28 04:41:12.930 DEBUG [tests.conftest] Running test: test_node_uses_both_auto_and_regular_apis with id: 2026-03-28_04-41-12__ebc3caee-bea8-494f-943b-dc72784bb022
2026-03-28 04:41:12.931 DEBUG [src.steps.common] Running fixture setup: common_setup
2026-03-28 04:41:12.932 DEBUG [src.steps.relay] Running fixture setup: relay_setup
2026-03-28 04:41:12.932 DEBUG [src.steps.sharding] Running fixture setup: sharding_setup
2026-03-28 04:41:12.946 DEBUG [src.node.docker_mananger] Docker client initialized with image wakuorg/nwaku:latest
2026-03-28 04:41:12.946 DEBUG [src.node.waku_node] WakuNode instance initialized with log path ./log/docker/node1_2026-03-28_04-41-12__ebc3caee-bea8-494f-943b-dc72784bb022__wakuorg_nwaku:latest.log
2026-03-28 04:41:12.947 DEBUG [src.node.waku_node] Starting Node...
2026-03-28 04:41:12.947 DEBUG [src.node.docker_mananger] Attempting to create or retrieve network waku
2026-03-28 04:41:12.951 DEBUG [src.node.docker_mananger] Network waku already exists
2026-03-28 04:41:12.952 DEBUG [src.node.docker_mananger] Generated random external IP 172.18.216.170
2026-03-28 04:41:12.952 DEBUG [src.node.docker_mananger] Generated ports ['13392', '13393', '13394', '13395', '13396']
2026-03-28 04:41:12.952 DEBUG [src.node.waku_node] Removing pubsub-topic from nwaku args
2026-03-28 04:41:12.952 DEBUG [src.node.waku_node] RLN credentials were not set
2026-03-28 04:41:12.952 INFO [src.node.waku_node] RLN credentials not set or credential store not available, starting without RLN
2026-03-28 04:41:12.952 DEBUG [src.node.waku_node] Using volumes []
2026-03-28 04:41:12.953 DEBUG [src.node.docker_mananger] docker run -i -t -p 13392:13392 -p 13393:13393 -p 13394:13394 -p 13395:13395 -p 13396:13396 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=13394 --rest-port=13392 --tcp-port=13393 --discv5-udp-port=13395 --rest-address=0.0.0.0 --nat=extip:172.18.216.170 --peer-exchange=true --discv5-discovery=true --cluster-id=2 --nodekey=fd8c2d90e5f1cd11c6c6b2daeb9f8d1ac128b2fd0a95e534cacdf14e7a7ebace --shard=0 --metrics-server=true --metrics-server-address=0.0.0.0 --metrics-server-port=13396 --metrics-logging=true --relay=true --filter=true
2026-03-28 04:41:13.154 DEBUG [src.node.docker_mananger] docker network connect --ip 172.18.216.170 waku 32e2ebd730859397b4a4b12262b0b48969eebdae3c375798ae23c9a744fbc3e7
2026-03-28 04:41:13.195 DEBUG [src.node.docker_mananger] Container started with ID 32e2ebd73085. Setting up logs at ./log/docker/node1_2026-03-28_04-41-12__ebc3caee-bea8-494f-943b-dc72784bb022__wakuorg_nwaku:latest.log
2026-03-28 04:41:13.195 DEBUG [src.node.waku_node] Started container from image wakuorg/nwaku:latest. REST: 13392
2026-03-28 04:41:13.195 DEBUG [src.libs.common] Sleeping for 1 seconds
2026-03-28 04:41:13.321 ERROR [src.node.docker_mananger] Max retries reached for container 6380b30546e0. Exiting log stream.
2026-03-28 04:41:13.812 ERROR [src.node.docker_mananger] Max retries reached for container 17e3ca5f792e. Exiting log stream.
2026-03-28 04:41:14.197 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:13392/health" -H "Content-Type: application/json" -d 'None'
2026-03-28 04:41:14.200 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"nodeHealth":"INITIALIZING","connectionStatus":"Disconnected","protocolsHealth":[]}'
2026-03-28 04:41:14.300 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:13392/health" -H "Content-Type: application/json" -d 'None'
2026-03-28 04:41:14.303 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"nodeHealth":"INITIALIZING","connectionStatus":"Disconnected","protocolsHealth":[]}'
2026-03-28 04:41:14.403 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:13392/health" -H "Content-Type: application/json" -d 'None'
2026-03-28 04:41:14.406 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"nodeHealth":"INITIALIZING","connectionStatus":"Disconnected","protocolsHealth":[]}'
2026-03-28 04:41:14.507 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:13392/health" -H "Content-Type: application/json" -d 'None'
2026-03-28 04:41:14.510 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"nodeHealth":"INITIALIZING","connectionStatus":"Disconnected","protocolsHealth":[]}'
2026-03-28 04:41:14.610 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:13392/health" -H "Content-Type: application/json" -d 'None'
2026-03-28 04:41:14.613 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"nodeHealth":"INITIALIZING","connectionStatus":"Disconnected","protocolsHealth":[]}'
2026-03-28 04:41:14.713 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:13392/health" -H "Content-Type: application/json" -d 'None'
2026-03-28 04:41:14.716 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":"READY"},{"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":"READY"},{"Legacy Lightpush Client":"READY"},{"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":"READY"},{"Rln Relay":"NOT_MOUNTED"}]}'
2026-03-28 04:41:14.717 INFO [src.node.waku_node] Node protocols are initialized !!
2026-03-28 04:41:14.717 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:13392/debug/v1/info" -H "Content-Type: application/json" -d 'None'
2026-03-28 04:41:14.719 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"listenAddresses":["/ip4/172.18.216.170/tcp/13393/p2p/16Uiu2HAmBoQdyNHvBzYtY6V8vWzVJnVVE83UamDgmsjx2MdKanqy","/ip4/172.18.216.170/tcp/13394/ws/p2p/16Uiu2HAmBoQdyNHvBzYtY6V8vWzVJnVVE83UamDgmsjx2MdKanqy"],"enrUri":"enr:-L24QPRrq6ddJk15RoGOTgyeacrQsvPjcXue2Aq8CjNgtH1wfdWEVbmZG4EEbd_Yd2SIeETaHWw7pNxA81Zkq4NPoJwCgmlkgnY0gmlwhKwS2KqKbXVsdGlhZGRyc5YACASsEtiqBjRRAAoErBLYqgY0Ut0DgnJzhQACAQAAiXNlY3AyNTZrMaEC80xr8gf5z09f4YcDMGbgRX3YNpyQB4yQr5JzKNk06bSDdGNwgjRRg3VkcII0U4V3YWt1MgU"}'
2026-03-28 04:41:14.719 INFO [src.node.waku_node] REST service is ready !!
2026-03-28 04:41:14.727 DEBUG [src.node.docker_mananger] Docker client initialized with image wakuorg/nwaku:latest
2026-03-28 04:41:14.727 DEBUG [src.node.waku_node] WakuNode instance initialized with log path ./log/docker/node2_2026-03-28_04-41-12__ebc3caee-bea8-494f-943b-dc72784bb022__wakuorg_nwaku:latest.log
2026-03-28 04:41:14.727 DEBUG [src.node.waku_node] Starting Node...
2026-03-28 04:41:14.727 DEBUG [src.node.docker_mananger] Attempting to create or retrieve network waku
2026-03-28 04:41:14.729 DEBUG [src.node.docker_mananger] Network waku already exists
2026-03-28 04:41:14.729 DEBUG [src.node.docker_mananger] Generated random external IP 172.18.17.121
2026-03-28 04:41:14.729 DEBUG [src.node.docker_mananger] Generated ports ['57836', '57837', '57838', '57839', '57840']
2026-03-28 04:41:14.729 DEBUG [src.node.waku_node] Removing pubsub-topic from nwaku args
2026-03-28 04:41:14.729 DEBUG [src.node.waku_node] RLN credentials were not set
2026-03-28 04:41:14.729 INFO [src.node.waku_node] RLN credentials not set or credential store not available, starting without RLN
2026-03-28 04:41:14.729 DEBUG [src.node.waku_node] Using volumes []
2026-03-28 04:41:14.730 DEBUG [src.node.docker_mananger] docker run -i -t -p 57836:57836 -p 57837:57837 -p 57838:57838 -p 57839:57839 -p 57840:57840 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=57838 --rest-port=57836 --tcp-port=57837 --discv5-udp-port=57839 --rest-address=0.0.0.0 --nat=extip:172.18.17.121 --peer-exchange=true --discv5-discovery=true --cluster-id=2 --nodekey=e7a8d5fffb08c7d799ac5c1349e8e8c02e4d5f3eabefbc9f44c5fabec23b3fff --shard=0 --metrics-server=true --metrics-server-address=0.0.0.0 --metrics-server-port=57840 --metrics-logging=true --relay=true --discv5-bootstrap-node=enr:-L24QPRrq6ddJk15RoGOTgyeacrQsvPjcXue2Aq8CjNgtH1wfdWEVbmZG4EEbd_Yd2SIeETaHWw7pNxA81Zkq4NPoJwCgmlkgnY0gmlwhKwS2KqKbXVsdGlhZGRyc5YACASsEtiqBjRRAAoErBLYqgY0Ut0DgnJzhQACAQAAiXNlY3AyNTZrMaEC80xr8gf5z09f4YcDMGbgRX3YNpyQB4yQr5JzKNk06bSDdGNwgjRRg3VkcII0U4V3YWt1MgU
2026-03-28 04:41:14.949 DEBUG [src.node.docker_mananger] docker network connect --ip 172.18.17.121 waku 992b123f28e65b9a108f2a23c2dbaef1c5ea77792e8c8ab557740133dcbdcbdd
2026-03-28 04:41:14.988 DEBUG [src.node.docker_mananger] Container started with ID 992b123f28e6. Setting up logs at ./log/docker/node2_2026-03-28_04-41-12__ebc3caee-bea8-494f-943b-dc72784bb022__wakuorg_nwaku:latest.log
2026-03-28 04:41:14.988 DEBUG [src.node.waku_node] Started container from image wakuorg/nwaku:latest. REST: 57836
2026-03-28 04:41:14.988 DEBUG [src.libs.common] Sleeping for 1 seconds
2026-03-28 04:41:15.988 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:57836/health" -H "Content-Type: application/json" -d 'None'
2026-03-28 04:41:15.991 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"},{"Legacy Store":"NOT_MOUNTED"},{"Peer Exchange":"READY"},{"Rendezvous":"NOT_READY","desc":"No Rendezvous peers are available yet"},{"Mix":"NOT_MOUNTED"},{"Lightpush Client":"READY"},{"Legacy Lightpush Client":"READY"},{"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":"READY"},{"Rln Relay":"NOT_MOUNTED"}]}'
2026-03-28 04:41:15.992 INFO [src.node.waku_node] Node protocols are initialized !!
2026-03-28 04:41:15.992 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:57836/debug/v1/info" -H "Content-Type: application/json" -d 'None'
2026-03-28 04:41:15.995 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"listenAddresses":["/ip4/172.18.17.121/tcp/57837/p2p/16Uiu2HAmAiLzaWBY1SNBcvvh8adazFVtLYXKa5PAN1Yh17mxtDEg","/ip4/172.18.17.121/tcp/57838/ws/p2p/16Uiu2HAmAiLzaWBY1SNBcvvh8adazFVtLYXKa5PAN1Yh17mxtDEg"],"enrUri":"enr:-L24QLIGzuC_0RyQ7y-5IQ9VZX4OYu7ozxsRvN13rU6zgHRtUCFsHp9L5nRcLXf4iIUF6YWjc-IaboOdC7PLXHMlqd8CgmlkgnY0gmlwhKwSEXmKbXVsdGlhZGRyc5YACASsEhF5BuHtAAoErBIReQbh7t0DgnJzhQACAQAAiXNlY3AyNTZrMaEC4yS1p0Gp7SGiSkrES7YxwmQdRdfNAPXzey9FGOruyDGDdGNwguHtg3VkcILh74V3YWt1MgE"}'
2026-03-28 04:41:15.995 INFO [src.node.waku_node] REST service is ready !!
2026-03-28 04:41:15.995 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:57836/admin/v1/peers" -H "Content-Type: application/json" -d '["/ip4/172.18.216.170/tcp/13393/p2p/16Uiu2HAmBoQdyNHvBzYtY6V8vWzVJnVVE83UamDgmsjx2MdKanqy"]'
2026-03-28 04:41:16.031 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2026-03-28 04:41:16.037 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:13392/relay/v1/auto/subscriptions" -H "Content-Type: application/json" -d '["/toychat/2/huilong/proto"]'
2026-03-28 04:41:16.041 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2026-03-28 04:41:16.042 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:57836/relay/v1/auto/subscriptions" -H "Content-Type: application/json" -d '["/toychat/2/huilong/proto"]'
2026-03-28 04:41:16.045 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2026-03-28 04:41:16.046 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:13392/relay/v1/auto/messages" -H "Content-Type: application/json" -d '{"payload": "U2hhcmRpbmcgd29ya3MhIQ==", "contentTopic": "/toychat/2/huilong/proto", "timestamp": '$(date +%s%N)'}'
2026-03-28 04:41:16.054 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2026-03-28 04:41:16.057 DEBUG [src.libs.common] Sleeping for 0.1 seconds
2026-03-28 04:41:16.157 DEBUG [src.steps.sharding] Checking that peer NODE_1:wakuorg/nwaku:latest can find the published message
2026-03-28 04:41:16.158 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:13392/relay/v1/auto/messages/%2Ftoychat%2F2%2Fhuilong%2Fproto" -H "Content-Type: application/json" -d 'None'
2026-03-28 04:41:16.161 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'[{"payload":"U2hhcmRpbmcgd29ya3MhIQ==","contentTopic":"/toychat/2/huilong/proto","version":0,"timestamp":1774672876046718878,"ephemeral":false,"proof":""}]'
2026-03-28 04:41:16.163 DEBUG [src.steps.sharding] Checking that peer NODE_2:wakuorg/nwaku:latest can find the published message
2026-03-28 04:41:16.164 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:57836/relay/v1/auto/messages/%2Ftoychat%2F2%2Fhuilong%2Fproto" -H "Content-Type: application/json" -d 'None'
2026-03-28 04:41:16.168 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'[{"payload":"U2hhcmRpbmcgd29ya3MhIQ==","contentTopic":"/toychat/2/huilong/proto","version":0,"timestamp":1774672876046718878,"ephemeral":false,"proof":""}]'
2026-03-28 04:41:16.169 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:13392/relay/v1/subscriptions" -H "Content-Type: application/json" -d '["/waku/2/rs/2/0"]'
2026-03-28 04:41:16.173 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2026-03-28 04:41:16.173 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:57836/relay/v1/subscriptions" -H "Content-Type: application/json" -d '["/waku/2/rs/2/0"]'
2026-03-28 04:41:16.175 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2026-03-28 04:41:16.176 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:13392/relay/v1/messages/%2Fwaku%2F2%2Frs%2F2%2F0" -H "Content-Type: application/json" -d '{"payload": "U2hhcmRpbmcgd29ya3MhIQ==", "contentTopic": "/myapp/1/latest/proto", "timestamp": '$(date +%s%N)'}'
2026-03-28 04:41:16.182 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2026-03-28 04:41:16.184 DEBUG [src.libs.common] Sleeping for 0.1 seconds
2026-03-28 04:41:16.284 DEBUG [src.steps.sharding] Checking that peer NODE_1:wakuorg/nwaku:latest can find the published message
2026-03-28 04:41:16.285 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:13392/relay/v1/messages/%2Fwaku%2F2%2Frs%2F2%2F0" -H "Content-Type: application/json" -d 'None'
2026-03-28 04:41:16.288 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'[{"payload":"U2hhcmRpbmcgd29ya3MhIQ==","contentTopic":"/myapp/1/latest/proto","version":0,"timestamp":1774672875809492148,"ephemeral":false,"proof":""},{"payload":"U2hhcmRpbmcgd29ya3MhIQ==","contentTopic":"/myapp/1/latest/proto","version":0,"timestamp":1774672876176355448,"ephemeral":false,"proof":""}]'
2026-03-28 04:41:16.327 DEBUG [tests.conftest] Running fixture teardown: test_setup
2026-03-28 04:41:16.328 DEBUG [tests.conftest] Running fixture teardown: close_open_nodes
2026-03-28 04:41:16.329 DEBUG [src.node.waku_node] Stopping container with id 32e2ebd73085
2026-03-28 04:41:16.817 DEBUG [src.node.waku_node] Container stopped.
2026-03-28 04:41:16.817 DEBUG [src.node.waku_node] Stopping container with id 992b123f28e6
2026-03-28 04:41:17.284 DEBUG [src.node.waku_node] Container stopped.
2026-03-28 04:41:17.287 DEBUG [tests.conftest] Running fixture teardown: check_waku_log_errors
2026-03-28 04:41:17.308 DEBUG [src.node.docker_mananger] No errors found in the waku logs.
2026-03-28 04:41:17.330 DEBUG [src.node.docker_mananger] No errors found in the waku logs.
2026-03-28 04:41:17.333 DEBUG [tests.conftest] Running fixture teardown: attach_logs_on_fail
2026-03-28 04:41:17.334 DEBUG [tests.conftest] Test failed, attempting to attach logs to the allure reports
2026-03-28 04:41:17.336 DEBUG [src.libs.common] Attaching file ./log/docker/node1_2026-03-28_04-41-12__ebc3caee-bea8-494f-943b-dc72784bb022__wakuorg_nwaku:latest.log
2026-03-28 04:41:17.344 DEBUG [src.libs.common] Attaching file ./log/docker/node2_2026-03-28_04-41-12__ebc3caee-bea8-494f-943b-dc72784bb022__wakuorg_nwaku:latest.log