93 lines
15 KiB
Plaintext

2025-12-10 04:12:38.016 DEBUG [tests.conftest] Running fixture setup: test_id
2025-12-10 04:12:38.017 DEBUG [tests.conftest] Running test: test_time_filter_invalid_start_time with id: 2025-12-10_04-12-38__5998370a-194f-484a-adbc-12b8be90d21a
2025-12-10 04:12:38.017 DEBUG [src.steps.common] Running fixture setup: common_setup
2025-12-10 04:12:38.017 DEBUG [src.steps.store] Running fixture setup: store_setup
2025-12-10 04:12:38.018 DEBUG [src.steps.store] Running fixture setup: node_setup
2025-12-10 04:12:38.025 DEBUG [src.node.docker_mananger] Docker client initialized with image wakuorg/nwaku:latest
2025-12-10 04:12:38.026 DEBUG [src.node.waku_node] WakuNode instance initialized with log path ./log/docker/publishing_node1_2025-12-10_04-12-38__5998370a-194f-484a-adbc-12b8be90d21a__wakuorg_nwaku:latest.log
2025-12-10 04:12:38.026 DEBUG [src.node.waku_node] Starting Node...
2025-12-10 04:12:38.026 DEBUG [src.node.docker_mananger] Attempting to create or retrieve network waku
2025-12-10 04:12:38.028 DEBUG [src.node.docker_mananger] Network waku already exists
2025-12-10 04:12:38.029 DEBUG [src.node.docker_mananger] Generated random external IP 172.18.202.13
2025-12-10 04:12:38.029 DEBUG [src.node.docker_mananger] Generated ports ['49818', '49819', '49820', '49821', '49822']
2025-12-10 04:12:38.029 DEBUG [src.node.waku_node] RLN credentials were not set
2025-12-10 04:12:38.029 INFO [src.node.waku_node] RLN credentials not set or credential store not available, starting without RLN
2025-12-10 04:12:38.029 DEBUG [src.node.waku_node] Using volumes []
2025-12-10 04:12:38.029 DEBUG [src.node.docker_mananger] docker run -i -t -p 49818:49818 -p 49819:49819 -p 49820:49820 -p 49821:49821 -p 49822:49822 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=49820 --rest-port=49818 --tcp-port=49819 --discv5-udp-port=49821 --rest-address=0.0.0.0 --nat=extip:172.18.202.13 --peer-exchange=true --discv5-discovery=true --cluster-id=3 --nodekey=dcc892f27ecfde7ec7c5e5bdcfffc960c7a90321fcdeed3cfa9e08092eae4bb4 --shard=0 --metrics-server=true --metrics-server-address=0.0.0.0 --metrics-server-port=49822 --metrics-logging=true --store=true --relay=true
2025-12-10 04:12:38.226 DEBUG [src.node.docker_mananger] docker network connect --ip 172.18.202.13 waku d36138563083ff5f821bcfd6298e87b1f71e480e70835e45555fbeff5e8ad12d
2025-12-10 04:12:38.262 DEBUG [src.node.docker_mananger] Container started with ID d36138563083. Setting up logs at ./log/docker/publishing_node1_2025-12-10_04-12-38__5998370a-194f-484a-adbc-12b8be90d21a__wakuorg_nwaku:latest.log
2025-12-10 04:12:38.262 ERROR [src.node.docker_mananger] Max retries reached for container 80250d17d904. Exiting log stream.
2025-12-10 04:12:38.263 DEBUG [src.node.waku_node] Started container from image wakuorg/nwaku:latest. REST: 49818
2025-12-10 04:12:38.264 DEBUG [src.libs.common] Sleeping for 1 seconds
2025-12-10 04:12:38.850 ERROR [src.node.docker_mananger] Max retries reached for container c745f8a37933. Exiting log stream.
2025-12-10 04:12:39.264 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:49818/health" -H "Content-Type: application/json" -d 'None'
2025-12-10 04:12:39.268 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":"READY"},{"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":"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":"NOT_READY","desc":"No Filter service peer available yet"}]}'
2025-12-10 04:12:39.268 INFO [src.node.waku_node] Node protocols are initialized !!
2025-12-10 04:12:39.268 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:49818/debug/v1/info" -H "Content-Type: application/json" -d 'None'
2025-12-10 04:12:39.270 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"listenAddresses":["/ip4/172.18.202.13/tcp/49819/p2p/16Uiu2HAmFFFhZSNMqP3yygih5yg5yGZvsBR7LmEjqz4jit7cUUd5","/ip4/172.18.202.13/tcp/49820/ws/p2p/16Uiu2HAmFFFhZSNMqP3yygih5yg5yGZvsBR7LmEjqz4jit7cUUd5"],"enrUri":"enr:-L24QIcMyvlnPDh1hQGCn0Vd-LfKMjv1c9eSNW90_K6sr2PuaWOn4b8CUV3tegOYwUiOJPEeopIQuaeoXqCjAP2z9pACgmlkgnY0gmlwhKwSyg2KbXVsdGlhZGRyc5YACASsEsoNBsKbAAoErBLKDQbCnN0DgnJzhQADAQAAiXNlY3AyNTZrMaEDJn56IfbMPUggS25FqUXxK8-i95ZO6xN9ZMyowxiSwWCDdGNwgsKbg3VkcILCnYV3YWt1MgM"}'
2025-12-10 04:12:39.270 INFO [src.node.waku_node] REST service is ready !!
2025-12-10 04:12:39.277 DEBUG [src.node.docker_mananger] Docker client initialized with image wakuorg/nwaku:latest
2025-12-10 04:12:39.277 DEBUG [src.node.waku_node] WakuNode instance initialized with log path ./log/docker/store_node1_2025-12-10_04-12-38__5998370a-194f-484a-adbc-12b8be90d21a__wakuorg_nwaku:latest.log
2025-12-10 04:12:39.278 DEBUG [src.node.waku_node] Starting Node...
2025-12-10 04:12:39.278 DEBUG [src.node.docker_mananger] Attempting to create or retrieve network waku
2025-12-10 04:12:39.279 DEBUG [src.node.docker_mananger] Network waku already exists
2025-12-10 04:12:39.279 DEBUG [src.node.docker_mananger] Generated random external IP 172.18.0.68
2025-12-10 04:12:39.279 DEBUG [src.node.docker_mananger] Generated ports ['46087', '46088', '46089', '46090', '46091']
2025-12-10 04:12:39.279 DEBUG [src.node.waku_node] RLN credentials were not set
2025-12-10 04:12:39.279 INFO [src.node.waku_node] RLN credentials not set or credential store not available, starting without RLN
2025-12-10 04:12:39.279 DEBUG [src.node.waku_node] Using volumes []
2025-12-10 04:12:39.280 DEBUG [src.node.docker_mananger] docker run -i -t -p 46087:46087 -p 46088:46088 -p 46089:46089 -p 46090:46090 -p 46091:46091 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=46089 --rest-port=46087 --tcp-port=46088 --discv5-udp-port=46090 --rest-address=0.0.0.0 --nat=extip:172.18.0.68 --peer-exchange=true --discv5-discovery=true --cluster-id=3 --nodekey=730dafeed64840440acfba6afefbcbf16e2f2dc48649db0669c41ffafbaea4ce --shard=0 --metrics-server=true --metrics-server-address=0.0.0.0 --metrics-server-port=46091 --metrics-logging=true --discv5-bootstrap-node=enr:-L24QIcMyvlnPDh1hQGCn0Vd-LfKMjv1c9eSNW90_K6sr2PuaWOn4b8CUV3tegOYwUiOJPEeopIQuaeoXqCjAP2z9pACgmlkgnY0gmlwhKwSyg2KbXVsdGlhZGRyc5YACASsEsoNBsKbAAoErBLKDQbCnN0DgnJzhQADAQAAiXNlY3AyNTZrMaEDJn56IfbMPUggS25FqUXxK8-i95ZO6xN9ZMyowxiSwWCDdGNwgsKbg3VkcILCnYV3YWt1MgM --storenode=/ip4/172.18.202.13/tcp/49819/p2p/16Uiu2HAmFFFhZSNMqP3yygih5yg5yGZvsBR7LmEjqz4jit7cUUd5 --store=true --relay=true
2025-12-10 04:12:39.460 DEBUG [src.node.docker_mananger] docker network connect --ip 172.18.0.68 waku cf841c998ab67bb57dd4c3f5132d06be04e12bc417b71a0f9c70370fc51c7392
2025-12-10 04:12:39.495 DEBUG [src.node.docker_mananger] Container started with ID cf841c998ab6. Setting up logs at ./log/docker/store_node1_2025-12-10_04-12-38__5998370a-194f-484a-adbc-12b8be90d21a__wakuorg_nwaku:latest.log
2025-12-10 04:12:39.496 DEBUG [src.node.waku_node] Started container from image wakuorg/nwaku:latest. REST: 46087
2025-12-10 04:12:39.496 DEBUG [src.libs.common] Sleeping for 1 seconds
2025-12-10 04:12:40.497 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:46087/health" -H "Content-Type: application/json" -d 'None'
2025-12-10 04:12:40.501 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"nodeHealth":"READY","protocolsHealth":[{"Relay":"READY"},{"Rln Relay":"NOT_MOUNTED"},{"Lightpush":"NOT_MOUNTED"},{"Legacy Lightpush":"NOT_MOUNTED"},{"Filter":"NOT_MOUNTED"},{"Store":"READY"},{"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":"READY"},{"Legacy Store Client":"READY"},{"Filter Client":"NOT_READY","desc":"No Filter service peer available yet"}]}'
2025-12-10 04:12:40.501 INFO [src.node.waku_node] Node protocols are initialized !!
2025-12-10 04:12:40.501 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:46087/debug/v1/info" -H "Content-Type: application/json" -d 'None'
2025-12-10 04:12:40.503 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"listenAddresses":["/ip4/172.18.0.68/tcp/46088/p2p/16Uiu2HAkw2eAeA6Nzzke5oaV5tqBgZdTut3jHqJUa3bwh71fMyTL","/ip4/172.18.0.68/tcp/46089/ws/p2p/16Uiu2HAkw2eAeA6Nzzke5oaV5tqBgZdTut3jHqJUa3bwh71fMyTL"],"enrUri":"enr:-L24QH6UVx-TR4RABBLsEKk6OlO9wQLA6l1SVK6X6iboU0qtQCrM_BloLH7TclHnlKvR6jRijIXelee-5xpD4zpwOnQCgmlkgnY0gmlwhKwSAESKbXVsdGlhZGRyc5YACASsEgBEBrQIAAoErBIARAa0Cd0DgnJzhQADAQAAiXNlY3AyNTZrMaECF9D3HvOc3JIx41FOfdML9aGGZ0YLzZPflgaWVOwNlNeDdGNwgrQIg3VkcIK0CoV3YWt1MgM"}'
2025-12-10 04:12:40.504 INFO [src.node.waku_node] REST service is ready !!
2025-12-10 04:12:40.504 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:46087/admin/v1/peers" -H "Content-Type: application/json" -d '["/ip4/172.18.202.13/tcp/49819/p2p/16Uiu2HAmFFFhZSNMqP3yygih5yg5yGZvsBR7LmEjqz4jit7cUUd5"]'
2025-12-10 04:12:40.506 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-10 04:12:40.507 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:49818/relay/v1/subscriptions" -H "Content-Type: application/json" -d '["/waku/2/rs/3/0"]'
2025-12-10 04:12:40.509 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-10 04:12:40.509 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:46087/relay/v1/subscriptions" -H "Content-Type: application/json" -d '["/waku/2/rs/3/0"]'
2025-12-10 04:12:40.512 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-10 04:12:40.513 DEBUG [src.steps.store] Relaying message
2025-12-10 04:12:40.513 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:49818/relay/v1/messages/%2Fwaku%2F2%2Frs%2F3%2F0" -H "Content-Type: application/json" -d '{"payload": "U3RvcmUgd29ya3MhIQ==", "contentTopic": "/myapp/1/latest/proto", "timestamp": '$(date +%s%N)'}'
2025-12-10 04:12:40.518 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-10 04:12:40.519 DEBUG [src.libs.common] Sleeping for 0.2 seconds
2025-12-10 04:12:40.720 DEBUG [src.steps.store] Relaying message
2025-12-10 04:12:40.720 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:49818/relay/v1/messages/%2Fwaku%2F2%2Frs%2F3%2F0" -H "Content-Type: application/json" -d '{"payload": "U3RvcmUgd29ya3MhIQ==", "contentTopic": "/myapp/1/latest/proto", "timestamp": '$(date +%s%N)'}'
2025-12-10 04:12:40.725 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-10 04:12:40.725 DEBUG [src.libs.common] Sleeping for 0.2 seconds
2025-12-10 04:12:40.926 DEBUG [src.steps.store] Relaying message
2025-12-10 04:12:40.927 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:49818/relay/v1/messages/%2Fwaku%2F2%2Frs%2F3%2F0" -H "Content-Type: application/json" -d '{"payload": "U3RvcmUgd29ya3MhIQ==", "contentTopic": "/myapp/1/latest/proto", "timestamp": '$(date +%s%N)'}'
2025-12-10 04:12:40.931 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-10 04:12:40.931 DEBUG [src.libs.common] Sleeping for 0.2 seconds
2025-12-10 04:12:41.132 DEBUG [src.steps.store] Relaying message
2025-12-10 04:12:41.132 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:49818/relay/v1/messages/%2Fwaku%2F2%2Frs%2F3%2F0" -H "Content-Type: application/json" -d '{"payload": "U3RvcmUgd29ya3MhIQ==", "contentTopic": "/myapp/1/latest/proto", "timestamp": '$(date +%s%N)'}'
2025-12-10 04:12:41.137 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-10 04:12:41.137 DEBUG [src.libs.common] Sleeping for 0.2 seconds
2025-12-10 04:12:41.338 DEBUG [src.steps.store] Relaying message
2025-12-10 04:12:41.338 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:49818/relay/v1/messages/%2Fwaku%2F2%2Frs%2F3%2F0" -H "Content-Type: application/json" -d '{"payload": "U3RvcmUgd29ya3MhIQ==", "contentTopic": "/myapp/1/latest/proto", "timestamp": '$(date +%s%N)'}'
2025-12-10 04:12:41.344 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-10 04:12:41.345 DEBUG [src.libs.common] Sleeping for 0.2 seconds
2025-12-10 04:12:41.545 DEBUG [src.steps.store] Relaying message
2025-12-10 04:12:41.546 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:49818/relay/v1/messages/%2Fwaku%2F2%2Frs%2F3%2F0" -H "Content-Type: application/json" -d '{"payload": "U3RvcmUgd29ya3MhIQ==", "contentTopic": "/myapp/1/latest/proto", "timestamp": '$(date +%s%N)'}'
2025-12-10 04:12:41.551 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-10 04:12:41.552 DEBUG [src.libs.common] Sleeping for 0.2 seconds
2025-12-10 04:12:41.752 DEBUG [tests.store.test_time_filter] inquering stored messages with start time abc
2025-12-10 04:12:41.753 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:49818/store/v3/messages?includeData=True&pubsubTopic=%2Fwaku%2F2%2Frs%2F3%2F0&startTime=abc&pageSize=20&ascending=true" -H "Content-Type: application/json" -d 'None'
2025-12-10 04:12:41.755 ERROR [src.node.api_clients.base_client] HTTP error occurred: 400 Client Error: Bad Request for url: http://127.0.0.1:49818/store/v3/messages?includeData=True&pubsubTopic=%2Fwaku%2F2%2Frs%2F3%2F0&startTime=abc&pageSize=20&ascending=true. Response content: b'time parsing error: invalid integer: abc'
2025-12-10 04:12:41.756 DEBUG [tests.store.test_time_filter] invalid start_time cause error Error: 400 Client Error: Bad Request for url: http://127.0.0.1:49818/store/v3/messages?includeData=True&pubsubTopic=%2Fwaku%2F2%2Frs%2F3%2F0&startTime=abc&pageSize=20&ascending=true with response: b'time parsing error: invalid integer: abc'
2025-12-10 04:12:41.758 DEBUG [tests.conftest] Running fixture teardown: test_setup
2025-12-10 04:12:41.759 DEBUG [tests.conftest] Running fixture teardown: close_open_nodes
2025-12-10 04:12:41.759 DEBUG [src.node.waku_node] Stopping container with id d36138563083
2025-12-10 04:12:42.299 DEBUG [src.node.waku_node] Container stopped.
2025-12-10 04:12:42.299 DEBUG [src.node.waku_node] Stopping container with id cf841c998ab6
2025-12-10 04:12:42.831 DEBUG [src.node.waku_node] Container stopped.
2025-12-10 04:12:42.833 DEBUG [tests.conftest] Running fixture teardown: check_waku_log_errors
2025-12-10 04:12:42.845 DEBUG [src.node.docker_mananger] No errors found in the waku logs.
2025-12-10 04:12:42.852 DEBUG [src.node.docker_mananger] No errors found in the waku logs.