98 lines
18 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-23 00:01:43.809 INFO [tests.conftest] Fleet bootstrap inactive pass --fleet (or set FLEET_BOOTSTRAP=true) to connect local nodes to the waku.test fleet
2026-04-23 00:01:43.810 DEBUG [tests.conftest] Running fixture setup: test_id
2026-04-23 00:01:43.810 DEBUG [tests.conftest] Running test: test_publish_with_invalid_timestamps with id: 2026-04-23_00-01-43__e8c2b047-c635-4611-9c66-411e0363ed6f
2026-04-23 00:01:43.811 DEBUG [src.steps.common] Running fixture setup: common_setup
2026-04-23 00:01:43.811 DEBUG [src.steps.relay] Running fixture setup: relay_setup
2026-04-23 00:01:43.811 DEBUG [src.steps.relay] Running fixture setup: setup_main_relay_nodes
2026-04-23 00:01:43.821 DEBUG [src.node.docker_mananger] Docker client initialized with image wakuorg/nwaku:latest
2026-04-23 00:01:43.821 DEBUG [src.node.waku_node] WakuNode instance initialized with log path ./log/docker/node1_2026-04-23_00-01-43__e8c2b047-c635-4611-9c66-411e0363ed6f__wakuorg_nwaku:latest.log
2026-04-23 00:01:43.821 DEBUG [src.node.waku_node] Starting Node...
2026-04-23 00:01:43.822 DEBUG [src.node.docker_mananger] Attempting to create or retrieve network waku
2026-04-23 00:01:43.824 DEBUG [src.node.docker_mananger] Network waku already exists
2026-04-23 00:01:43.824 DEBUG [src.node.docker_mananger] Generated random external IP 172.18.111.43
2026-04-23 00:01:43.824 DEBUG [src.node.docker_mananger] Generated ports ['60943', '60944', '60945', '60946', '60947']
2026-04-23 00:01:43.824 DEBUG [src.node.waku_node] RLN credentials were not set
2026-04-23 00:01:43.824 INFO [src.node.waku_node] RLN credentials not set or credential store not available, starting without RLN
2026-04-23 00:01:43.825 DEBUG [src.node.waku_node] Using volumes []
2026-04-23 00:01:43.825 DEBUG [src.node.docker_mananger] docker run -i -t -p 60943:60943 -p 60944:60944 -p 60945:60945 -p 60946:60946 -p 60947:60947 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=60945 --rest-port=60943 --tcp-port=60944 --discv5-udp-port=60946 --rest-address=0.0.0.0 --nat=extip:172.18.111.43 --peer-exchange=true --discv5-discovery=true --cluster-id=198 --nodekey=eceb3d10faba8ca1f47fe1ec2cc62a5effee23f6fcde1ba3dea77b9c7e1cac6a --shard=0 --metrics-server=true --metrics-server-address=0.0.0.0 --metrics-server-port=60947 --metrics-logging=true --relay=true
2026-04-23 00:01:44.024 DEBUG [src.node.docker_mananger] docker network connect --ip 172.18.111.43 waku c36c1c1c2011a54dd5f1294cf2fef47ace8084192f3de8f461826cc9a42a85ca
2026-04-23 00:01:44.062 DEBUG [src.node.docker_mananger] Container started with ID c36c1c1c2011. Setting up logs at ./log/docker/node1_2026-04-23_00-01-43__e8c2b047-c635-4611-9c66-411e0363ed6f__wakuorg_nwaku:latest.log
2026-04-23 00:01:44.062 DEBUG [src.node.waku_node] Started container from image wakuorg/nwaku:latest. REST: 60943
2026-04-23 00:01:44.063 DEBUG [src.libs.common] Sleeping for 1 seconds
2026-04-23 00:01:44.125 ERROR [src.node.docker_mananger] Max retries reached for container 6ddec4a55a17. Exiting log stream.
2026-04-23 00:01:44.642 ERROR [src.node.docker_mananger] Max retries reached for container 5e4963ff4503. Exiting log stream.
2026-04-23 00:01:45.063 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:60943/health" -H "Content-Type: application/json" -d 'None'
2026-04-23 00:01:45.066 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-23 00:01:45.066 INFO [src.node.waku_node] Node protocols are initialized !!
2026-04-23 00:01:45.067 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:60943/debug/v1/info" -H "Content-Type: application/json" -d 'None'
2026-04-23 00:01:45.069 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"listenAddresses":["/ip4/172.18.111.43/tcp/60944/p2p/16Uiu2HAm6k7p2GLuTdxXs9mxxX3TTi1GscGacjVWU9sDeudLHfGb","/ip4/172.18.111.43/tcp/60945/ws/p2p/16Uiu2HAm6k7p2GLuTdxXs9mxxX3TTi1GscGacjVWU9sDeudLHfGb"],"enrUri":"enr:-L24QO-QOQuMXlsMQsFmXLwabxG2aLY4KfTbFvvbEhQ7NUblf7Ex0BLAdY6Qpb6VcR4baMIkdP_AH8_xhRvsWRHpMgoCgmlkgnY0gmlwhKwSbyuKbXVsdGlhZGRyc5YACASsEm8rBu4QAAoErBJvKwbuEd0DgnJzhQDGAQAAiXNlY3AyNTZrMaECqCo389WUP1NU4fek1FhqmbhcmQIX2CT0_ejsPo5nbZCDdGNwgu4Qg3VkcILuEoV3YWt1MgE"}'
2026-04-23 00:01:45.069 INFO [src.node.waku_node] REST service is ready !!
2026-04-23 00:01:45.076 DEBUG [src.node.docker_mananger] Docker client initialized with image wakuorg/nwaku:latest
2026-04-23 00:01:45.076 DEBUG [src.node.waku_node] WakuNode instance initialized with log path ./log/docker/node2_2026-04-23_00-01-43__e8c2b047-c635-4611-9c66-411e0363ed6f__wakuorg_nwaku:latest.log
2026-04-23 00:01:45.076 DEBUG [src.node.waku_node] Starting Node...
2026-04-23 00:01:45.076 DEBUG [src.node.docker_mananger] Attempting to create or retrieve network waku
2026-04-23 00:01:45.077 DEBUG [src.node.docker_mananger] Network waku already exists
2026-04-23 00:01:45.077 DEBUG [src.node.docker_mananger] Generated random external IP 172.18.106.118
2026-04-23 00:01:45.077 DEBUG [src.node.docker_mananger] Generated ports ['41427', '41428', '41429', '41430', '41431']
2026-04-23 00:01:45.078 DEBUG [src.node.waku_node] RLN credentials were not set
2026-04-23 00:01:45.078 INFO [src.node.waku_node] RLN credentials not set or credential store not available, starting without RLN
2026-04-23 00:01:45.078 DEBUG [src.node.waku_node] Using volumes []
2026-04-23 00:01:45.078 DEBUG [src.node.docker_mananger] docker run -i -t -p 41427:41427 -p 41428:41428 -p 41429:41429 -p 41430:41430 -p 41431:41431 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=41429 --rest-port=41427 --tcp-port=41428 --discv5-udp-port=41430 --rest-address=0.0.0.0 --nat=extip:172.18.106.118 --peer-exchange=true --discv5-discovery=true --cluster-id=198 --nodekey=daaf32c2bc5d54da092ebaef5b79cfee38369cd9fbaac17bbf06b918e61cd9c9 --shard=0 --metrics-server=true --metrics-server-address=0.0.0.0 --metrics-server-port=41431 --metrics-logging=true --relay=true --discv5-bootstrap-node=enr:-L24QO-QOQuMXlsMQsFmXLwabxG2aLY4KfTbFvvbEhQ7NUblf7Ex0BLAdY6Qpb6VcR4baMIkdP_AH8_xhRvsWRHpMgoCgmlkgnY0gmlwhKwSbyuKbXVsdGlhZGRyc5YACASsEm8rBu4QAAoErBJvKwbuEd0DgnJzhQDGAQAAiXNlY3AyNTZrMaECqCo389WUP1NU4fek1FhqmbhcmQIX2CT0_ejsPo5nbZCDdGNwgu4Qg3VkcILuEoV3YWt1MgE
2026-04-23 00:01:45.267 DEBUG [src.node.docker_mananger] docker network connect --ip 172.18.106.118 waku 487e91141d534ef7ecb90e9f1ebc37b285aedc45774950cf149827f5e247c2de
2026-04-23 00:01:45.300 DEBUG [src.node.docker_mananger] Container started with ID 487e91141d53. Setting up logs at ./log/docker/node2_2026-04-23_00-01-43__e8c2b047-c635-4611-9c66-411e0363ed6f__wakuorg_nwaku:latest.log
2026-04-23 00:01:45.300 DEBUG [src.node.waku_node] Started container from image wakuorg/nwaku:latest. REST: 41427
2026-04-23 00:01:45.300 DEBUG [src.libs.common] Sleeping for 1 seconds
2026-04-23 00:01:46.303 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:41427/health" -H "Content-Type: application/json" -d 'None'
2026-04-23 00:01:46.318 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-23 00:01:46.319 INFO [src.node.waku_node] Node protocols are initialized !!
2026-04-23 00:01:46.319 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:41427/debug/v1/info" -H "Content-Type: application/json" -d 'None'
2026-04-23 00:01:46.325 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"listenAddresses":["/ip4/172.18.106.118/tcp/41428/p2p/16Uiu2HAkztm8L8xAjJAZDyAFfHg6oavEuEXurRQ3ufyUR9ymYwW5","/ip4/172.18.106.118/tcp/41429/ws/p2p/16Uiu2HAkztm8L8xAjJAZDyAFfHg6oavEuEXurRQ3ufyUR9ymYwW5"],"enrUri":"enr:-L24QBexkS5GpSN139VAzURfhRWhzU_ByYu55p4a2kr4X9xUO9YVqI26e7opf8wKZgg3oYzDEPZxR7PCr6kPN_YwTwACgmlkgnY0gmlwhKwSanaKbXVsdGlhZGRyc5YACASsEmp2BqHUAAoErBJqdgah1d0DgnJzhQDGAQAAiXNlY3AyNTZrMaECUTrvubcpIldWEw7ig9rrV6SHMMLjHoYhfv0C4gsd4caDdGNwgqHUg3VkcIKh1oV3YWt1MgE"}'
2026-04-23 00:01:46.325 INFO [src.node.waku_node] REST service is ready !!
2026-04-23 00:01:46.326 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:41427/admin/v1/peers" -H "Content-Type: application/json" -d '["/ip4/172.18.111.43/tcp/60944/p2p/16Uiu2HAm6k7p2GLuTdxXs9mxxX3TTi1GscGacjVWU9sDeudLHfGb"]'
2026-04-23 00:01:46.328 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2026-04-23 00:01:46.329 DEBUG [src.steps.relay] Running fixture setup: subscribe_main_relay_nodes
2026-04-23 00:01:46.329 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:60943/relay/v1/subscriptions" -H "Content-Type: application/json" -d '["/waku/2/rs/198/1"]'
2026-04-23 00:01:46.332 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2026-04-23 00:01:46.333 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:41427/relay/v1/subscriptions" -H "Content-Type: application/json" -d '["/waku/2/rs/198/1"]'
2026-04-23 00:01:46.337 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2026-04-23 00:01:46.338 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:60943/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-23 00:01:46.345 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2026-04-23 00:01:46.345 DEBUG [src.libs.common] Sleeping for 0.1 seconds
2026-04-23 00:01:46.446 DEBUG [src.steps.relay] Checking that peer NODE_1:wakuorg/nwaku:latest can find the published message
2026-04-23 00:01:46.446 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:60943/relay/v1/messages/%2Fwaku%2F2%2Frs%2F198%2F1" -H "Content-Type: application/json" -d 'None'
2026-04-23 00:01:46.449 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":1776902506337928704,"ephemeral":false,"proof":""}]'
2026-04-23 00:01:46.473 DEBUG [src.steps.relay] Checking that peer NODE_2:wakuorg/nwaku:latest can find the published message
2026-04-23 00:01:46.473 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:41427/relay/v1/messages/%2Fwaku%2F2%2Frs%2F198%2F1" -H "Content-Type: application/json" -d 'None'
2026-04-23 00:01:46.476 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":1776902506337928704,"ephemeral":false,"proof":""}]'
2026-04-23 00:01:46.477 INFO [src.steps.relay] WARM UP successful!!
2026-04-23 00:01:46.478 DEBUG [tests.relay.test_publish] Running test with timestamp Timestamp as string number
2026-04-23 00:01:46.479 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:60943/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-23 00:01:46.481 ERROR [src.node.api_clients.base_client] HTTP error occurred: 400 Client Error: Bad Request for url: http://127.0.0.1:60943/relay/v1/messages/%2Fwaku%2F2%2Frs%2F198%2F1. Response content: b'Invalid content body, could not decode: Unable to deserialize data: '
2026-04-23 00:01:46.482 DEBUG [tests.relay.test_publish] Running test with timestamp Invalid large number
2026-04-23 00:01:46.483 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:60943/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-23 00:01:46.485 ERROR [src.node.api_clients.base_client] HTTP error occurred: 400 Client Error: Bad Request for url: http://127.0.0.1:60943/relay/v1/messages/%2Fwaku%2F2%2Frs%2F198%2F1. Response content: b'Invalid content body, could not decode: Unable to deserialize data: '
2026-04-23 00:01:46.486 DEBUG [tests.relay.test_publish] Running test with timestamp Float number
2026-04-23 00:01:46.487 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:60943/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-23 00:01:46.489 ERROR [src.node.api_clients.base_client] HTTP error occurred: 400 Client Error: Bad Request for url: http://127.0.0.1:60943/relay/v1/messages/%2Fwaku%2F2%2Frs%2F198%2F1. Response content: b'Invalid content body, could not decode: Unable to deserialize data: '
2026-04-23 00:01:46.490 DEBUG [tests.relay.test_publish] Running test with timestamp Array instead of timestamp
2026-04-23 00:01:46.490 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:60943/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-23 00:01:46.493 ERROR [src.node.api_clients.base_client] HTTP error occurred: 400 Client Error: Bad Request for url: http://127.0.0.1:60943/relay/v1/messages/%2Fwaku%2F2%2Frs%2F198%2F1. Response content: b'Invalid content body, could not decode: Unable to deserialize data: '
2026-04-23 00:01:46.494 DEBUG [tests.relay.test_publish] Running test with timestamp Object instead of timestamp
2026-04-23 00:01:46.494 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:60943/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-23 00:01:46.496 ERROR [src.node.api_clients.base_client] HTTP error occurred: 400 Client Error: Bad Request for url: http://127.0.0.1:60943/relay/v1/messages/%2Fwaku%2F2%2Frs%2F198%2F1. Response content: b'Invalid content body, could not decode: Unable to deserialize data: '
2026-04-23 00:01:46.497 DEBUG [tests.relay.test_publish] Running test with timestamp ISO 8601 timestamp
2026-04-23 00:01:46.498 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:60943/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-23 00:01:46.500 ERROR [src.node.api_clients.base_client] HTTP error occurred: 400 Client Error: Bad Request for url: http://127.0.0.1:60943/relay/v1/messages/%2Fwaku%2F2%2Frs%2F198%2F1. Response content: b'Invalid content body, could not decode: Unable to deserialize data: '
2026-04-23 00:01:46.501 DEBUG [tests.relay.test_publish] Running test with timestamp Missing
2026-04-23 00:01:46.501 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:60943/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-23 00:01:46.504 ERROR [src.node.api_clients.base_client] HTTP error occurred: 400 Client Error: Bad Request for url: http://127.0.0.1:60943/relay/v1/messages/%2Fwaku%2F2%2Frs%2F198%2F1. Response content: b'Invalid content body, could not decode: Unable to deserialize data: '
2026-04-23 00:01:46.506 DEBUG [tests.conftest] Running fixture teardown: test_setup
2026-04-23 00:01:46.508 DEBUG [tests.conftest] Running fixture teardown: close_open_nodes
2026-04-23 00:01:46.508 DEBUG [src.node.waku_node] Stopping container with id c36c1c1c2011
2026-04-23 00:01:46.951 DEBUG [src.node.waku_node] Container stopped.
2026-04-23 00:01:46.951 DEBUG [src.node.waku_node] Stopping container with id 487e91141d53
2026-04-23 00:01:47.407 DEBUG [src.node.waku_node] Container stopped.
2026-04-23 00:01:47.409 DEBUG [tests.conftest] Running fixture teardown: check_waku_log_errors
2026-04-23 00:01:47.417 DEBUG [src.node.docker_mananger] No errors found in the waku logs.
2026-04-23 00:01:47.425 DEBUG [src.node.docker_mananger] No errors found in the waku logs.