78 lines
14 KiB
Plaintext

2025-12-27 04:27:40.073 DEBUG [tests.conftest] Running fixture setup: test_id
2025-12-27 04:27:40.073 DEBUG [tests.conftest] Running test: test_publish_with_invalid_version with id: 2025-12-27_04-27-40__f9ef9384-50d4-4d1e-af7c-50691bd8b4d9
2025-12-27 04:27:40.073 DEBUG [src.steps.common] Running fixture setup: common_setup
2025-12-27 04:27:40.074 DEBUG [src.steps.relay] Running fixture setup: relay_setup
2025-12-27 04:27:40.074 DEBUG [src.steps.relay] Running fixture setup: setup_main_relay_nodes
2025-12-27 04:27:40.080 DEBUG [src.node.docker_mananger] Docker client initialized with image wakuorg/nwaku:latest
2025-12-27 04:27:40.080 DEBUG [src.node.waku_node] WakuNode instance initialized with log path ./log/docker/node1_2025-12-27_04-27-40__f9ef9384-50d4-4d1e-af7c-50691bd8b4d9__wakuorg_nwaku:latest.log
2025-12-27 04:27:40.080 DEBUG [src.node.waku_node] Starting Node...
2025-12-27 04:27:40.080 DEBUG [src.node.docker_mananger] Attempting to create or retrieve network waku
2025-12-27 04:27:40.082 DEBUG [src.node.docker_mananger] Network waku already exists
2025-12-27 04:27:40.082 DEBUG [src.node.docker_mananger] Generated random external IP 172.18.248.193
2025-12-27 04:27:40.082 DEBUG [src.node.docker_mananger] Generated ports ['39817', '39818', '39819', '39820', '39821']
2025-12-27 04:27:40.082 DEBUG [src.node.waku_node] RLN credentials were not set
2025-12-27 04:27:40.082 INFO [src.node.waku_node] RLN credentials not set or credential store not available, starting without RLN
2025-12-27 04:27:40.082 DEBUG [src.node.waku_node] Using volumes []
2025-12-27 04:27:40.082 DEBUG [src.node.docker_mananger] docker run -i -t -p 39817:39817 -p 39818:39818 -p 39819:39819 -p 39820:39820 -p 39821:39821 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=39819 --rest-port=39817 --tcp-port=39818 --discv5-udp-port=39820 --rest-address=0.0.0.0 --nat=extip:172.18.248.193 --peer-exchange=true --discv5-discovery=true --cluster-id=3 --nodekey=745373c0d7f7f289f1847def3be38b46e9b1ecaa6a2709cddeb94ba4ef38ef49 --shard=0 --metrics-server=true --metrics-server-address=0.0.0.0 --metrics-server-port=39821 --metrics-logging=true --relay=true
2025-12-27 04:27:40.255 DEBUG [src.node.docker_mananger] docker network connect --ip 172.18.248.193 waku 6a5532ef82b83a64bf4940fa3e716d9a23e8b0f211f4357e49b6054b6bdccfbe
2025-12-27 04:27:40.286 DEBUG [src.node.docker_mananger] Container started with ID 6a5532ef82b8. Setting up logs at ./log/docker/node1_2025-12-27_04-27-40__f9ef9384-50d4-4d1e-af7c-50691bd8b4d9__wakuorg_nwaku:latest.log
2025-12-27 04:27:40.286 DEBUG [src.node.waku_node] Started container from image wakuorg/nwaku:latest. REST: 39817
2025-12-27 04:27:40.286 DEBUG [src.libs.common] Sleeping for 1 seconds
2025-12-27 04:27:40.350 ERROR [src.node.docker_mananger] Max retries reached for container ac8855ad0999. Exiting log stream.
2025-12-27 04:27:40.878 ERROR [src.node.docker_mananger] Max retries reached for container 298ad62c9573. Exiting log stream.
2025-12-27 04:27:41.286 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:39817/health" -H "Content-Type: application/json" -d 'None'
2025-12-27 04:27:41.289 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_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"}]}'
2025-12-27 04:27:41.290 INFO [src.node.waku_node] Node protocols are initialized !!
2025-12-27 04:27:41.290 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:39817/debug/v1/info" -H "Content-Type: application/json" -d 'None'
2025-12-27 04:27:41.292 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"listenAddresses":["/ip4/172.18.248.193/tcp/39818/p2p/16Uiu2HAmGUHnK9r3GDVRKGfSNrwkagsqjWf6NKGqe4ccz4YbNdFB","/ip4/172.18.248.193/tcp/39819/ws/p2p/16Uiu2HAmGUHnK9r3GDVRKGfSNrwkagsqjWf6NKGqe4ccz4YbNdFB"],"enrUri":"enr:-L24QH6JlujU5CFSRcUJbnTd_CtTzO4FoFTx9vRUL4Szp77qYYmBXc-VaWV9dOKm-EoETtmUBim-4iCygfM6Vj8NZ0QCgmlkgnY0gmlwhKwS-MGKbXVsdGlhZGRyc5YACASsEvjBBpuKAAoErBL4wQabi90DgnJzhQADAQAAiXNlY3AyNTZrMaEDOLERkB5MAs_U9B-CIjyuRL_8tq_QpR_lGHI74CWtCk6DdGNwgpuKg3VkcIKbjIV3YWt1MgE"}'
2025-12-27 04:27:41.292 INFO [src.node.waku_node] REST service is ready !!
2025-12-27 04:27:41.299 DEBUG [src.node.docker_mananger] Docker client initialized with image wakuorg/nwaku:latest
2025-12-27 04:27:41.299 DEBUG [src.node.waku_node] WakuNode instance initialized with log path ./log/docker/node2_2025-12-27_04-27-40__f9ef9384-50d4-4d1e-af7c-50691bd8b4d9__wakuorg_nwaku:latest.log
2025-12-27 04:27:41.299 DEBUG [src.node.waku_node] Starting Node...
2025-12-27 04:27:41.299 DEBUG [src.node.docker_mananger] Attempting to create or retrieve network waku
2025-12-27 04:27:41.300 DEBUG [src.node.docker_mananger] Network waku already exists
2025-12-27 04:27:41.301 DEBUG [src.node.docker_mananger] Generated random external IP 172.18.60.37
2025-12-27 04:27:41.301 DEBUG [src.node.docker_mananger] Generated ports ['26933', '26934', '26935', '26936', '26937']
2025-12-27 04:27:41.301 DEBUG [src.node.waku_node] RLN credentials were not set
2025-12-27 04:27:41.301 INFO [src.node.waku_node] RLN credentials not set or credential store not available, starting without RLN
2025-12-27 04:27:41.301 DEBUG [src.node.waku_node] Using volumes []
2025-12-27 04:27:41.301 DEBUG [src.node.docker_mananger] docker run -i -t -p 26933:26933 -p 26934:26934 -p 26935:26935 -p 26936:26936 -p 26937:26937 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=26935 --rest-port=26933 --tcp-port=26934 --discv5-udp-port=26936 --rest-address=0.0.0.0 --nat=extip:172.18.60.37 --peer-exchange=true --discv5-discovery=true --cluster-id=3 --nodekey=37a5a2fb2b1ddac4cfe04ffe8c82f65c05521dffa61dd96fa0ce3ddabd1ddb4a --shard=0 --metrics-server=true --metrics-server-address=0.0.0.0 --metrics-server-port=26937 --metrics-logging=true --relay=true --discv5-bootstrap-node=enr:-L24QH6JlujU5CFSRcUJbnTd_CtTzO4FoFTx9vRUL4Szp77qYYmBXc-VaWV9dOKm-EoETtmUBim-4iCygfM6Vj8NZ0QCgmlkgnY0gmlwhKwS-MGKbXVsdGlhZGRyc5YACASsEvjBBpuKAAoErBL4wQabi90DgnJzhQADAQAAiXNlY3AyNTZrMaEDOLERkB5MAs_U9B-CIjyuRL_8tq_QpR_lGHI74CWtCk6DdGNwgpuKg3VkcIKbjIV3YWt1MgE
2025-12-27 04:27:41.479 DEBUG [src.node.docker_mananger] docker network connect --ip 172.18.60.37 waku 2395bb94a17e6f59c3af73643547ad99c20a4240dca91f81c2dc1b0e51a37421
2025-12-27 04:27:41.510 DEBUG [src.node.docker_mananger] Container started with ID 2395bb94a17e. Setting up logs at ./log/docker/node2_2025-12-27_04-27-40__f9ef9384-50d4-4d1e-af7c-50691bd8b4d9__wakuorg_nwaku:latest.log
2025-12-27 04:27:41.510 DEBUG [src.node.waku_node] Started container from image wakuorg/nwaku:latest. REST: 26933
2025-12-27 04:27:41.511 DEBUG [src.libs.common] Sleeping for 1 seconds
2025-12-27 04:27:42.511 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:26933/health" -H "Content-Type: application/json" -d 'None'
2025-12-27 04:27:42.523 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_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"}]}'
2025-12-27 04:27:42.526 INFO [src.node.waku_node] Node protocols are initialized !!
2025-12-27 04:27:42.527 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:26933/debug/v1/info" -H "Content-Type: application/json" -d 'None'
2025-12-27 04:27:42.530 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"listenAddresses":["/ip4/172.18.60.37/tcp/26934/p2p/16Uiu2HAmG5jWGLXdS7YhwVWFqrUdgV6DrU4KTTQU1szY1mw1ASQk","/ip4/172.18.60.37/tcp/26935/ws/p2p/16Uiu2HAmG5jWGLXdS7YhwVWFqrUdgV6DrU4KTTQU1szY1mw1ASQk"],"enrUri":"enr:-L24QGwzw3HtcH7AcrB2au0UQIEbwRQzwTy2mdcJcvlCPDTvajI9U0mRc0rvFJ7Ya6kCzvMw92VVYFH0oPJ6pMr6fW4CgmlkgnY0gmlwhKwSPCWKbXVsdGlhZGRyc5YACASsEjwlBmk2AAoErBI8JQZpN90DgnJzhQADAQAAiXNlY3AyNTZrMaEDMunLoQOrejljJC1Ap3h6FBdpFprxBl1CGUoC-HbKPQ2DdGNwgmk2g3VkcIJpOIV3YWt1MgE"}'
2025-12-27 04:27:42.531 INFO [src.node.waku_node] REST service is ready !!
2025-12-27 04:27:42.531 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:26933/admin/v1/peers" -H "Content-Type: application/json" -d '["/ip4/172.18.248.193/tcp/39818/p2p/16Uiu2HAmGUHnK9r3GDVRKGfSNrwkagsqjWf6NKGqe4ccz4YbNdFB"]'
2025-12-27 04:27:42.534 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-27 04:27:42.534 DEBUG [src.steps.relay] Running fixture setup: subscribe_main_relay_nodes
2025-12-27 04:27:42.534 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:39817/relay/v1/subscriptions" -H "Content-Type: application/json" -d '["/waku/2/rs/3/1"]'
2025-12-27 04:27:42.538 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-27 04:27:42.538 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:26933/relay/v1/subscriptions" -H "Content-Type: application/json" -d '["/waku/2/rs/3/1"]'
2025-12-27 04:27:42.542 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-27 04:27:42.544 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:39817/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)'}'
2025-12-27 04:27:42.549 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-27 04:27:42.550 DEBUG [src.libs.common] Sleeping for 0.1 seconds
2025-12-27 04:27:42.650 DEBUG [src.steps.relay] Checking that peer NODE_1:wakuorg/nwaku:latest can find the published message
2025-12-27 04:27:42.650 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:39817/relay/v1/messages/%2Fwaku%2F2%2Frs%2F3%2F1" -H "Content-Type: application/json" -d 'None'
2025-12-27 04:27:42.652 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":1766809662543939840,"ephemeral":false,"proof":""}]'
2025-12-27 04:27:42.654 DEBUG [src.steps.relay] Checking that peer NODE_2:wakuorg/nwaku:latest can find the published message
2025-12-27 04:27:42.654 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:26933/relay/v1/messages/%2Fwaku%2F2%2Frs%2F3%2F1" -H "Content-Type: application/json" -d 'None'
2025-12-27 04:27:42.656 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":1766809662543939840,"ephemeral":false,"proof":""}]'
2025-12-27 04:27:42.658 INFO [src.steps.relay] WARM UP successful!!
2025-12-27 04:27:42.659 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:39817/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)', "version": 2.1}'
2025-12-27 04:27:42.661 ERROR [src.node.api_clients.base_client] HTTP error occurred: 400 Client Error: Bad Request for url: http://127.0.0.1:39817/relay/v1/messages/%2Fwaku%2F2%2Frs%2F3%2F1. Response content: b'Invalid content body, could not decode: Unable to deserialize data: '
2025-12-27 04:27:42.663 DEBUG [tests.conftest] Running fixture teardown: test_setup
2025-12-27 04:27:42.665 DEBUG [tests.conftest] Running fixture teardown: close_open_nodes
2025-12-27 04:27:42.665 DEBUG [src.node.waku_node] Stopping container with id 6a5532ef82b8
2025-12-27 04:27:43.209 DEBUG [src.node.waku_node] Container stopped.
2025-12-27 04:27:43.209 DEBUG [src.node.waku_node] Stopping container with id 2395bb94a17e
2025-12-27 04:27:43.677 DEBUG [src.node.waku_node] Container stopped.
2025-12-27 04:27:43.679 DEBUG [tests.conftest] Running fixture teardown: check_waku_log_errors
2025-12-27 04:27:43.686 DEBUG [src.node.docker_mananger] No errors found in the waku logs.
2025-12-27 04:27:43.693 DEBUG [src.node.docker_mananger] No errors found in the waku logs.