97 lines
18 KiB
Plaintext

2026-03-25 04:42:28.812 DEBUG [tests.conftest] Running fixture setup: test_id
2026-03-25 04:42:28.812 DEBUG [tests.conftest] Running test: test_publish_with_invalid_timestamps with id: 2026-03-25_04-42-28__1d8ff085-4b0f-45ff-b9bb-1978d0a23177
2026-03-25 04:42:28.812 DEBUG [src.steps.common] Running fixture setup: common_setup
2026-03-25 04:42:28.812 DEBUG [src.steps.relay] Running fixture setup: relay_setup
2026-03-25 04:42:28.813 DEBUG [src.steps.relay] Running fixture setup: setup_main_relay_nodes
2026-03-25 04:42:28.819 DEBUG [src.node.docker_mananger] Docker client initialized with image wakuorg/nwaku:latest
2026-03-25 04:42:28.819 DEBUG [src.node.waku_node] WakuNode instance initialized with log path ./log/docker/node1_2026-03-25_04-42-28__1d8ff085-4b0f-45ff-b9bb-1978d0a23177__wakuorg_nwaku:latest.log
2026-03-25 04:42:28.820 DEBUG [src.node.waku_node] Starting Node...
2026-03-25 04:42:28.820 DEBUG [src.node.docker_mananger] Attempting to create or retrieve network waku
2026-03-25 04:42:28.821 DEBUG [src.node.docker_mananger] Network waku already exists
2026-03-25 04:42:28.821 DEBUG [src.node.docker_mananger] Generated random external IP 172.18.151.32
2026-03-25 04:42:28.821 DEBUG [src.node.docker_mananger] Generated ports ['36092', '36093', '36094', '36095', '36096']
2026-03-25 04:42:28.822 DEBUG [src.node.waku_node] RLN credentials were not set
2026-03-25 04:42:28.822 INFO [src.node.waku_node] RLN credentials not set or credential store not available, starting without RLN
2026-03-25 04:42:28.822 DEBUG [src.node.waku_node] Using volumes []
2026-03-25 04:42:28.822 DEBUG [src.node.docker_mananger] docker run -i -t -p 36092:36092 -p 36093:36093 -p 36094:36094 -p 36095:36095 -p 36096:36096 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=36094 --rest-port=36092 --tcp-port=36093 --discv5-udp-port=36095 --rest-address=0.0.0.0 --nat=extip:172.18.151.32 --peer-exchange=true --discv5-discovery=true --cluster-id=3 --nodekey=d8241fcc5b7cf5c0ad68d7cabdfdbce94df7d3a55b2dccb3c40e4b704fb0bc62 --shard=0 --metrics-server=true --metrics-server-address=0.0.0.0 --metrics-server-port=36096 --metrics-logging=true --relay=true
2026-03-25 04:42:29.014 DEBUG [src.node.docker_mananger] docker network connect --ip 172.18.151.32 waku 4aa8df2e033348eaf21f9c96f11f24a401e99b238a2dde5a423a17b05c90d1b2
2026-03-25 04:42:29.038 ERROR [src.node.docker_mananger] Max retries reached for container 88bc35148a98. Exiting log stream.
2026-03-25 04:42:29.054 DEBUG [src.node.docker_mananger] Container started with ID 4aa8df2e0333. Setting up logs at ./log/docker/node1_2026-03-25_04-42-28__1d8ff085-4b0f-45ff-b9bb-1978d0a23177__wakuorg_nwaku:latest.log
2026-03-25 04:42:29.054 DEBUG [src.node.waku_node] Started container from image wakuorg/nwaku:latest. REST: 36092
2026-03-25 04:42:29.055 DEBUG [src.libs.common] Sleeping for 1 seconds
2026-03-25 04:42:29.555 ERROR [src.node.docker_mananger] Max retries reached for container 4cbcca94a65d. Exiting log stream.
2026-03-25 04:42:30.056 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:36092/health" -H "Content-Type: application/json" -d 'None'
2026-03-25 04:42:30.058 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"},{"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"},{"Rln Relay":"NOT_MOUNTED"}]}'
2026-03-25 04:42:30.059 INFO [src.node.waku_node] Node protocols are initialized !!
2026-03-25 04:42:30.059 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:36092/debug/v1/info" -H "Content-Type: application/json" -d 'None'
2026-03-25 04:42:30.061 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"listenAddresses":["/ip4/172.18.151.32/tcp/36093/p2p/16Uiu2HAmQeufns4eHJd4Y7EZdzJ6MgnDjxcp85qywb9wqBJuV8XE","/ip4/172.18.151.32/tcp/36094/ws/p2p/16Uiu2HAmQeufns4eHJd4Y7EZdzJ6MgnDjxcp85qywb9wqBJuV8XE"],"enrUri":"enr:-L24QD_G3kl--1JQGnQhh85LRrhv245NsOtLPXd0g3S8ILm3Q3ep76mnmGuEHY4UVEkmXPHfggJkayQmLZY2lobPIjUCgmlkgnY0gmlwhKwSlyCKbXVsdGlhZGRyc5YACASsEpcgBoz9AAoErBKXIAaM_t0DgnJzhQADAQAAiXNlY3AyNTZrMaEDskbzRfnkwYBk3ELP40lisQVLPLXjqf00teNkNeLT6pWDdGNwgoz9g3VkcIKM_4V3YWt1MgE"}'
2026-03-25 04:42:30.061 INFO [src.node.waku_node] REST service is ready !!
2026-03-25 04:42:30.068 DEBUG [src.node.docker_mananger] Docker client initialized with image wakuorg/nwaku:latest
2026-03-25 04:42:30.068 DEBUG [src.node.waku_node] WakuNode instance initialized with log path ./log/docker/node2_2026-03-25_04-42-28__1d8ff085-4b0f-45ff-b9bb-1978d0a23177__wakuorg_nwaku:latest.log
2026-03-25 04:42:30.068 DEBUG [src.node.waku_node] Starting Node...
2026-03-25 04:42:30.068 DEBUG [src.node.docker_mananger] Attempting to create or retrieve network waku
2026-03-25 04:42:30.070 DEBUG [src.node.docker_mananger] Network waku already exists
2026-03-25 04:42:30.070 DEBUG [src.node.docker_mananger] Generated random external IP 172.18.153.229
2026-03-25 04:42:30.070 DEBUG [src.node.docker_mananger] Generated ports ['59264', '59265', '59266', '59267', '59268']
2026-03-25 04:42:30.070 DEBUG [src.node.waku_node] RLN credentials were not set
2026-03-25 04:42:30.070 INFO [src.node.waku_node] RLN credentials not set or credential store not available, starting without RLN
2026-03-25 04:42:30.070 DEBUG [src.node.waku_node] Using volumes []
2026-03-25 04:42:30.070 DEBUG [src.node.docker_mananger] docker run -i -t -p 59264:59264 -p 59265:59265 -p 59266:59266 -p 59267:59267 -p 59268:59268 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=59266 --rest-port=59264 --tcp-port=59265 --discv5-udp-port=59267 --rest-address=0.0.0.0 --nat=extip:172.18.153.229 --peer-exchange=true --discv5-discovery=true --cluster-id=3 --nodekey=6cad327909235cf71afab6d8888ed08a181ceaae5cce8c8d52d025fffccddffb --shard=0 --metrics-server=true --metrics-server-address=0.0.0.0 --metrics-server-port=59268 --metrics-logging=true --relay=true --discv5-bootstrap-node=enr:-L24QD_G3kl--1JQGnQhh85LRrhv245NsOtLPXd0g3S8ILm3Q3ep76mnmGuEHY4UVEkmXPHfggJkayQmLZY2lobPIjUCgmlkgnY0gmlwhKwSlyCKbXVsdGlhZGRyc5YACASsEpcgBoz9AAoErBKXIAaM_t0DgnJzhQADAQAAiXNlY3AyNTZrMaEDskbzRfnkwYBk3ELP40lisQVLPLXjqf00teNkNeLT6pWDdGNwgoz9g3VkcIKM_4V3YWt1MgE
2026-03-25 04:42:30.265 DEBUG [src.node.docker_mananger] docker network connect --ip 172.18.153.229 waku 3660c7b58495f6622d26b584beb5082de06d8aef531735674c59996878d6b57a
2026-03-25 04:42:30.298 DEBUG [src.node.docker_mananger] Container started with ID 3660c7b58495. Setting up logs at ./log/docker/node2_2026-03-25_04-42-28__1d8ff085-4b0f-45ff-b9bb-1978d0a23177__wakuorg_nwaku:latest.log
2026-03-25 04:42:30.298 DEBUG [src.node.waku_node] Started container from image wakuorg/nwaku:latest. REST: 59264
2026-03-25 04:42:30.299 DEBUG [src.libs.common] Sleeping for 1 seconds
2026-03-25 04:42:31.299 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:59264/health" -H "Content-Type: application/json" -d 'None'
2026-03-25 04:42:31.327 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"},{"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"},{"Rln Relay":"NOT_MOUNTED"}]}'
2026-03-25 04:42:31.331 INFO [src.node.waku_node] Node protocols are initialized !!
2026-03-25 04:42:31.332 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:59264/debug/v1/info" -H "Content-Type: application/json" -d 'None'
2026-03-25 04:42:31.336 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"listenAddresses":["/ip4/172.18.153.229/tcp/59265/p2p/16Uiu2HAmPPS6ywWWgBaCCdTEpSBjhbpTYbAo9BaU8a8T6iVKWVGa","/ip4/172.18.153.229/tcp/59266/ws/p2p/16Uiu2HAmPPS6ywWWgBaCCdTEpSBjhbpTYbAo9BaU8a8T6iVKWVGa"],"enrUri":"enr:-L24QFiKD6A7Hevn2pWfrKZ4U8NtERuCCyHw4OJ2B3mWVgScS8HpC7t6Yh74AKiT86pCd4yytc76g422TgQVoP8O5A4CgmlkgnY0gmlwhKwSmeWKbXVsdGlhZGRyc5YACASsEpnlBueBAAoErBKZ5Qbngt0DgnJzhQADAQAAiXNlY3AyNTZrMaEDn3Rh80ekSQXkxpQyCdVa6JmbDQO62A6Yq4zAhMxKA1-DdGNwgueBg3VkcILng4V3YWt1MgE"}'
2026-03-25 04:42:31.337 INFO [src.node.waku_node] REST service is ready !!
2026-03-25 04:42:31.337 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:59264/admin/v1/peers" -H "Content-Type: application/json" -d '["/ip4/172.18.151.32/tcp/36093/p2p/16Uiu2HAmQeufns4eHJd4Y7EZdzJ6MgnDjxcp85qywb9wqBJuV8XE"]'
2026-03-25 04:42:31.341 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2026-03-25 04:42:31.341 DEBUG [src.steps.relay] Running fixture setup: subscribe_main_relay_nodes
2026-03-25 04:42:31.341 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:36092/relay/v1/subscriptions" -H "Content-Type: application/json" -d '["/waku/2/rs/3/1"]'
2026-03-25 04:42:31.345 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2026-03-25 04:42:31.345 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:59264/relay/v1/subscriptions" -H "Content-Type: application/json" -d '["/waku/2/rs/3/1"]'
2026-03-25 04:42:31.351 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2026-03-25 04:42:31.352 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:36092/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)'}'
2026-03-25 04:42:31.358 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2026-03-25 04:42:31.359 DEBUG [src.libs.common] Sleeping for 0.1 seconds
2026-03-25 04:42:31.460 DEBUG [src.steps.relay] Checking that peer NODE_1:wakuorg/nwaku:latest can find the published message
2026-03-25 04:42:31.460 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:36092/relay/v1/messages/%2Fwaku%2F2%2Frs%2F3%2F1" -H "Content-Type: application/json" -d 'None'
2026-03-25 04:42:31.462 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":1774413751352004096,"ephemeral":false,"proof":""}]'
2026-03-25 04:42:31.463 DEBUG [src.steps.relay] Checking that peer NODE_2:wakuorg/nwaku:latest can find the published message
2026-03-25 04:42:31.464 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:59264/relay/v1/messages/%2Fwaku%2F2%2Frs%2F3%2F1" -H "Content-Type: application/json" -d 'None'
2026-03-25 04:42:31.466 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":1774413751352004096,"ephemeral":false,"proof":""}]'
2026-03-25 04:42:31.467 INFO [src.steps.relay] WARM UP successful!!
2026-03-25 04:42:31.468 DEBUG [tests.relay.test_publish] Running test with timestamp Timestamp as string number
2026-03-25 04:42:31.468 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:36092/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)'}'
2026-03-25 04:42:31.471 ERROR [src.node.api_clients.base_client] HTTP error occurred: 400 Client Error: Bad Request for url: http://127.0.0.1:36092/relay/v1/messages/%2Fwaku%2F2%2Frs%2F3%2F1. Response content: b'Invalid content body, could not decode: Unable to deserialize data: '
2026-03-25 04:42:31.471 DEBUG [tests.relay.test_publish] Running test with timestamp Invalid large number
2026-03-25 04:42:31.472 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:36092/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)'}'
2026-03-25 04:42:31.474 ERROR [src.node.api_clients.base_client] HTTP error occurred: 400 Client Error: Bad Request for url: http://127.0.0.1:36092/relay/v1/messages/%2Fwaku%2F2%2Frs%2F3%2F1. Response content: b'Invalid content body, could not decode: Unable to deserialize data: '
2026-03-25 04:42:31.475 DEBUG [tests.relay.test_publish] Running test with timestamp Float number
2026-03-25 04:42:31.475 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:36092/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)'}'
2026-03-25 04:42:31.478 ERROR [src.node.api_clients.base_client] HTTP error occurred: 400 Client Error: Bad Request for url: http://127.0.0.1:36092/relay/v1/messages/%2Fwaku%2F2%2Frs%2F3%2F1. Response content: b'Invalid content body, could not decode: Unable to deserialize data: '
2026-03-25 04:42:31.478 DEBUG [tests.relay.test_publish] Running test with timestamp Array instead of timestamp
2026-03-25 04:42:31.479 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:36092/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)'}'
2026-03-25 04:42:31.481 ERROR [src.node.api_clients.base_client] HTTP error occurred: 400 Client Error: Bad Request for url: http://127.0.0.1:36092/relay/v1/messages/%2Fwaku%2F2%2Frs%2F3%2F1. Response content: b'Invalid content body, could not decode: Unable to deserialize data: '
2026-03-25 04:42:31.482 DEBUG [tests.relay.test_publish] Running test with timestamp Object instead of timestamp
2026-03-25 04:42:31.482 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:36092/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)'}'
2026-03-25 04:42:31.484 ERROR [src.node.api_clients.base_client] HTTP error occurred: 400 Client Error: Bad Request for url: http://127.0.0.1:36092/relay/v1/messages/%2Fwaku%2F2%2Frs%2F3%2F1. Response content: b'Invalid content body, could not decode: Unable to deserialize data: '
2026-03-25 04:42:31.485 DEBUG [tests.relay.test_publish] Running test with timestamp ISO 8601 timestamp
2026-03-25 04:42:31.486 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:36092/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)'}'
2026-03-25 04:42:31.488 ERROR [src.node.api_clients.base_client] HTTP error occurred: 400 Client Error: Bad Request for url: http://127.0.0.1:36092/relay/v1/messages/%2Fwaku%2F2%2Frs%2F3%2F1. Response content: b'Invalid content body, could not decode: Unable to deserialize data: '
2026-03-25 04:42:31.489 DEBUG [tests.relay.test_publish] Running test with timestamp Missing
2026-03-25 04:42:31.489 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:36092/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)'}'
2026-03-25 04:42:31.491 ERROR [src.node.api_clients.base_client] HTTP error occurred: 400 Client Error: Bad Request for url: http://127.0.0.1:36092/relay/v1/messages/%2Fwaku%2F2%2Frs%2F3%2F1. Response content: b'Invalid content body, could not decode: Unable to deserialize data: '
2026-03-25 04:42:31.494 DEBUG [tests.conftest] Running fixture teardown: test_setup
2026-03-25 04:42:31.495 DEBUG [tests.conftest] Running fixture teardown: close_open_nodes
2026-03-25 04:42:31.495 DEBUG [src.node.waku_node] Stopping container with id 4aa8df2e0333
2026-03-25 04:42:32.083 DEBUG [src.node.waku_node] Container stopped.
2026-03-25 04:42:32.084 DEBUG [src.node.waku_node] Stopping container with id 3660c7b58495
2026-03-25 04:42:32.637 DEBUG [src.node.waku_node] Container stopped.
2026-03-25 04:42:32.639 DEBUG [tests.conftest] Running fixture teardown: check_waku_log_errors
2026-03-25 04:42:32.646 DEBUG [src.node.docker_mananger] No errors found in the waku logs.
2026-03-25 04:42:32.651 DEBUG [src.node.docker_mananger] No errors found in the waku logs.