97 lines
18 KiB
Plaintext

2025-12-08 12:12:42.748 DEBUG [tests.conftest] Running fixture setup: test_id
2025-12-08 12:12:42.748 DEBUG [tests.conftest] Running test: test_publish_with_invalid_timestamps with id: 2025-12-08_12-12-42__80a5cfd6-92ab-43d2-8cd9-a824563c0e80
2025-12-08 12:12:42.749 DEBUG [src.steps.common] Running fixture setup: common_setup
2025-12-08 12:12:42.749 DEBUG [src.steps.relay] Running fixture setup: relay_setup
2025-12-08 12:12:42.749 DEBUG [src.steps.relay] Running fixture setup: setup_main_relay_nodes
2025-12-08 12:12:42.756 DEBUG [src.node.docker_mananger] Docker client initialized with image wakuorg/nwaku:latest
2025-12-08 12:12:42.756 DEBUG [src.node.waku_node] WakuNode instance initialized with log path ./log/docker/node1_2025-12-08_12-12-42__80a5cfd6-92ab-43d2-8cd9-a824563c0e80__wakuorg_nwaku:latest.log
2025-12-08 12:12:42.756 DEBUG [src.node.waku_node] Starting Node...
2025-12-08 12:12:42.756 DEBUG [src.node.docker_mananger] Attempting to create or retrieve network waku
2025-12-08 12:12:42.757 DEBUG [src.node.docker_mananger] Network waku already exists
2025-12-08 12:12:42.758 DEBUG [src.node.docker_mananger] Generated random external IP 172.18.216.110
2025-12-08 12:12:42.758 DEBUG [src.node.docker_mananger] Generated ports ['57137', '57138', '57139', '57140', '57141']
2025-12-08 12:12:42.758 DEBUG [src.node.waku_node] RLN credentials were not set
2025-12-08 12:12:42.758 INFO [src.node.waku_node] RLN credentials not set or credential store not available, starting without RLN
2025-12-08 12:12:42.758 DEBUG [src.node.waku_node] Using volumes []
2025-12-08 12:12:42.758 DEBUG [src.node.docker_mananger] docker run -i -t -p 57137:57137 -p 57138:57138 -p 57139:57139 -p 57140:57140 -p 57141:57141 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=57139 --rest-port=57137 --tcp-port=57138 --discv5-udp-port=57140 --rest-address=0.0.0.0 --nat=extip:172.18.216.110 --peer-exchange=true --discv5-discovery=true --cluster-id=3 --nodekey=ee0acdaeaf9bef5c409d6fba9adfdbdbaeef5dd67ddc9cadcb3aeb9c565774db --shard=0 --metrics-server=true --metrics-server-address=0.0.0.0 --metrics-server-port=57141 --metrics-logging=true --relay=true
2025-12-08 12:12:42.939 DEBUG [src.node.docker_mananger] docker network connect --ip 172.18.216.110 waku b8884d75983866224b6a898b55be45615f33fb1a3ee33b6314bc133788fc5422
2025-12-08 12:12:42.969 DEBUG [src.node.docker_mananger] Container started with ID b8884d759838. Setting up logs at ./log/docker/node1_2025-12-08_12-12-42__80a5cfd6-92ab-43d2-8cd9-a824563c0e80__wakuorg_nwaku:latest.log
2025-12-08 12:12:42.969 DEBUG [src.node.waku_node] Started container from image wakuorg/nwaku:latest. REST: 57137
2025-12-08 12:12:42.969 DEBUG [src.libs.common] Sleeping for 1 seconds
2025-12-08 12:12:42.997 ERROR [src.node.docker_mananger] Max retries reached for container 7bf20e532933. Exiting log stream.
2025-12-08 12:12:43.528 ERROR [src.node.docker_mananger] Max retries reached for container b87248698d8d. Exiting log stream.
2025-12-08 12:12:43.970 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:57137/health" -H "Content-Type: application/json" -d 'None'
2025-12-08 12:12:43.973 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-08 12:12:43.973 INFO [src.node.waku_node] Node protocols are initialized !!
2025-12-08 12:12:43.974 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:57137/debug/v1/info" -H "Content-Type: application/json" -d 'None'
2025-12-08 12:12:43.976 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"listenAddresses":["/ip4/172.18.216.110/tcp/57138/p2p/16Uiu2HAkvMwjNBuByUqPSZMgQoseTHkUE9tjKJjFbrfv4FxnMHGy","/ip4/172.18.216.110/tcp/57139/ws/p2p/16Uiu2HAkvMwjNBuByUqPSZMgQoseTHkUE9tjKJjFbrfv4FxnMHGy"],"enrUri":"enr:-L24QPxDp7xpCoXooIZV8ULNAcb3yeHkke6KaPRnfRDlY3EMLcqld10J4VSUU0uu_kD9eVXDjz9FETiYdl3jLlei6CECgmlkgnY0gmlwhKwS2G6KbXVsdGlhZGRyc5YACASsEthuBt8yAAoErBLYbgbfM90DgnJzhQADAQAAiXNlY3AyNTZrMaECDecsdsWzue1vGqb2YNUAW54AGgQ_D7tpdbAiecuU7i6DdGNwgt8yg3VkcILfNIV3YWt1MgE"}'
2025-12-08 12:12:43.976 INFO [src.node.waku_node] REST service is ready !!
2025-12-08 12:12:43.982 DEBUG [src.node.docker_mananger] Docker client initialized with image wakuorg/nwaku:latest
2025-12-08 12:12:43.982 DEBUG [src.node.waku_node] WakuNode instance initialized with log path ./log/docker/node2_2025-12-08_12-12-42__80a5cfd6-92ab-43d2-8cd9-a824563c0e80__wakuorg_nwaku:latest.log
2025-12-08 12:12:43.982 DEBUG [src.node.waku_node] Starting Node...
2025-12-08 12:12:43.982 DEBUG [src.node.docker_mananger] Attempting to create or retrieve network waku
2025-12-08 12:12:43.984 DEBUG [src.node.docker_mananger] Network waku already exists
2025-12-08 12:12:43.984 DEBUG [src.node.docker_mananger] Generated random external IP 172.18.0.246
2025-12-08 12:12:43.984 DEBUG [src.node.docker_mananger] Generated ports ['3208', '3209', '3210', '3211', '3212']
2025-12-08 12:12:43.984 DEBUG [src.node.waku_node] RLN credentials were not set
2025-12-08 12:12:43.984 INFO [src.node.waku_node] RLN credentials not set or credential store not available, starting without RLN
2025-12-08 12:12:43.984 DEBUG [src.node.waku_node] Using volumes []
2025-12-08 12:12:43.984 DEBUG [src.node.docker_mananger] docker run -i -t -p 3208:3208 -p 3209:3209 -p 3210:3210 -p 3211:3211 -p 3212:3212 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=3210 --rest-port=3208 --tcp-port=3209 --discv5-udp-port=3211 --rest-address=0.0.0.0 --nat=extip:172.18.0.246 --peer-exchange=true --discv5-discovery=true --cluster-id=3 --nodekey=54a700fd6d7f94deb0aae0ade5affac5edfd78617e6b7047bb7d0fab4672a925 --shard=0 --metrics-server=true --metrics-server-address=0.0.0.0 --metrics-server-port=3212 --metrics-logging=true --relay=true --discv5-bootstrap-node=enr:-L24QPxDp7xpCoXooIZV8ULNAcb3yeHkke6KaPRnfRDlY3EMLcqld10J4VSUU0uu_kD9eVXDjz9FETiYdl3jLlei6CECgmlkgnY0gmlwhKwS2G6KbXVsdGlhZGRyc5YACASsEthuBt8yAAoErBLYbgbfM90DgnJzhQADAQAAiXNlY3AyNTZrMaECDecsdsWzue1vGqb2YNUAW54AGgQ_D7tpdbAiecuU7i6DdGNwgt8yg3VkcILfNIV3YWt1MgE
2025-12-08 12:12:44.169 DEBUG [src.node.docker_mananger] docker network connect --ip 172.18.0.246 waku ad6fb0ce341ed616c3e5a923c30bb95a8f6a05161d1923db8e50c4f9222c8320
2025-12-08 12:12:44.198 DEBUG [src.node.docker_mananger] Container started with ID ad6fb0ce341e. Setting up logs at ./log/docker/node2_2025-12-08_12-12-42__80a5cfd6-92ab-43d2-8cd9-a824563c0e80__wakuorg_nwaku:latest.log
2025-12-08 12:12:44.199 DEBUG [src.node.waku_node] Started container from image wakuorg/nwaku:latest. REST: 3208
2025-12-08 12:12:44.199 DEBUG [src.libs.common] Sleeping for 1 seconds
2025-12-08 12:12:45.200 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:3208/health" -H "Content-Type: application/json" -d 'None'
2025-12-08 12:12:45.214 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-08 12:12:45.216 INFO [src.node.waku_node] Node protocols are initialized !!
2025-12-08 12:12:45.217 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:3208/debug/v1/info" -H "Content-Type: application/json" -d 'None'
2025-12-08 12:12:45.222 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"listenAddresses":["/ip4/172.18.0.246/tcp/3209/p2p/16Uiu2HAmV1dnY7ewyUics3izH5J6Tyt3PD3SmxVAvuUrUNHWKtJG","/ip4/172.18.0.246/tcp/3210/ws/p2p/16Uiu2HAmV1dnY7ewyUics3izH5J6Tyt3PD3SmxVAvuUrUNHWKtJG"],"enrUri":"enr:-L24QCbgChpDhb_DZ2_cThtFpxppLbZkKGEhnlpwMsCPuhK7Vd8a_cCo5xgP8-7J6gZvTkhLA4OXh5ohxcCXTNQ4hFYCgmlkgnY0gmlwhKwSAPaKbXVsdGlhZGRyc5YACASsEgD2BgyJAAoErBIA9gYMit0DgnJzhQADAQAAiXNlY3AyNTZrMaED8wTva1ozg_3kodmpRs-8mB0vg2VBl06DbcfEHdMkY3WDdGNwggyJg3VkcIIMi4V3YWt1MgE"}'
2025-12-08 12:12:45.222 INFO [src.node.waku_node] REST service is ready !!
2025-12-08 12:12:45.222 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:3208/admin/v1/peers" -H "Content-Type: application/json" -d '["/ip4/172.18.216.110/tcp/57138/p2p/16Uiu2HAkvMwjNBuByUqPSZMgQoseTHkUE9tjKJjFbrfv4FxnMHGy"]'
2025-12-08 12:12:45.225 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-08 12:12:45.226 DEBUG [src.steps.relay] Running fixture setup: subscribe_main_relay_nodes
2025-12-08 12:12:45.226 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:57137/relay/v1/subscriptions" -H "Content-Type: application/json" -d '["/waku/2/rs/3/1"]'
2025-12-08 12:12:45.230 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-08 12:12:45.230 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:3208/relay/v1/subscriptions" -H "Content-Type: application/json" -d '["/waku/2/rs/3/1"]'
2025-12-08 12:12:45.236 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-08 12:12:45.237 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:57137/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-08 12:12:45.240 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-08 12:12:45.240 DEBUG [src.libs.common] Sleeping for 0.1 seconds
2025-12-08 12:12:45.341 DEBUG [src.steps.relay] Checking that peer NODE_1:wakuorg/nwaku:latest can find the published message
2025-12-08 12:12:45.341 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:57137/relay/v1/messages/%2Fwaku%2F2%2Frs%2F3%2F1" -H "Content-Type: application/json" -d 'None'
2025-12-08 12:12:45.343 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":1765195965236971008,"ephemeral":false,"proof":""}]'
2025-12-08 12:12:45.345 DEBUG [src.steps.relay] Checking that peer NODE_2:wakuorg/nwaku:latest can find the published message
2025-12-08 12:12:45.345 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:3208/relay/v1/messages/%2Fwaku%2F2%2Frs%2F3%2F1" -H "Content-Type: application/json" -d 'None'
2025-12-08 12:12:45.347 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":1765195965236971008,"ephemeral":false,"proof":""}]'
2025-12-08 12:12:45.348 INFO [src.steps.relay] WARM UP successful!!
2025-12-08 12:12:45.349 DEBUG [tests.relay.test_publish] Running test with timestamp Timestamp as string number
2025-12-08 12:12:45.350 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:57137/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-08 12:12:45.352 ERROR [src.node.api_clients.base_client] HTTP error occurred: 400 Client Error: Bad Request for url: http://127.0.0.1:57137/relay/v1/messages/%2Fwaku%2F2%2Frs%2F3%2F1. Response content: b'Invalid content body, could not decode: Unable to deserialize data: '
2025-12-08 12:12:45.353 DEBUG [tests.relay.test_publish] Running test with timestamp Invalid large number
2025-12-08 12:12:45.353 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:57137/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-08 12:12:45.356 ERROR [src.node.api_clients.base_client] HTTP error occurred: 400 Client Error: Bad Request for url: http://127.0.0.1:57137/relay/v1/messages/%2Fwaku%2F2%2Frs%2F3%2F1. Response content: b'Invalid content body, could not decode: Unable to deserialize data: '
2025-12-08 12:12:45.356 DEBUG [tests.relay.test_publish] Running test with timestamp Float number
2025-12-08 12:12:45.357 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:57137/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-08 12:12:45.359 ERROR [src.node.api_clients.base_client] HTTP error occurred: 400 Client Error: Bad Request for url: http://127.0.0.1:57137/relay/v1/messages/%2Fwaku%2F2%2Frs%2F3%2F1. Response content: b'Invalid content body, could not decode: Unable to deserialize data: '
2025-12-08 12:12:45.360 DEBUG [tests.relay.test_publish] Running test with timestamp Array instead of timestamp
2025-12-08 12:12:45.360 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:57137/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-08 12:12:45.362 ERROR [src.node.api_clients.base_client] HTTP error occurred: 400 Client Error: Bad Request for url: http://127.0.0.1:57137/relay/v1/messages/%2Fwaku%2F2%2Frs%2F3%2F1. Response content: b'Invalid content body, could not decode: Unable to deserialize data: '
2025-12-08 12:12:45.363 DEBUG [tests.relay.test_publish] Running test with timestamp Object instead of timestamp
2025-12-08 12:12:45.363 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:57137/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-08 12:12:45.366 ERROR [src.node.api_clients.base_client] HTTP error occurred: 400 Client Error: Bad Request for url: http://127.0.0.1:57137/relay/v1/messages/%2Fwaku%2F2%2Frs%2F3%2F1. Response content: b'Invalid content body, could not decode: Unable to deserialize data: '
2025-12-08 12:12:45.366 DEBUG [tests.relay.test_publish] Running test with timestamp ISO 8601 timestamp
2025-12-08 12:12:45.367 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:57137/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-08 12:12:45.369 ERROR [src.node.api_clients.base_client] HTTP error occurred: 400 Client Error: Bad Request for url: http://127.0.0.1:57137/relay/v1/messages/%2Fwaku%2F2%2Frs%2F3%2F1. Response content: b'Invalid content body, could not decode: Unable to deserialize data: '
2025-12-08 12:12:45.370 DEBUG [tests.relay.test_publish] Running test with timestamp Missing
2025-12-08 12:12:45.370 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:57137/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-08 12:12:45.372 ERROR [src.node.api_clients.base_client] HTTP error occurred: 400 Client Error: Bad Request for url: http://127.0.0.1:57137/relay/v1/messages/%2Fwaku%2F2%2Frs%2F3%2F1. Response content: b'Invalid content body, could not decode: Unable to deserialize data: '
2025-12-08 12:12:45.375 DEBUG [tests.conftest] Running fixture teardown: test_setup
2025-12-08 12:12:45.376 DEBUG [tests.conftest] Running fixture teardown: close_open_nodes
2025-12-08 12:12:45.376 DEBUG [src.node.waku_node] Stopping container with id b8884d759838
2025-12-08 12:12:45.900 DEBUG [src.node.waku_node] Container stopped.
2025-12-08 12:12:45.900 DEBUG [src.node.waku_node] Stopping container with id ad6fb0ce341e
2025-12-08 12:12:46.466 DEBUG [src.node.waku_node] Container stopped.
2025-12-08 12:12:46.467 DEBUG [tests.conftest] Running fixture teardown: check_waku_log_errors
2025-12-08 12:12:46.472 DEBUG [src.node.docker_mananger] No errors found in the waku logs.
2025-12-08 12:12:46.478 DEBUG [src.node.docker_mananger] No errors found in the waku logs.