96 lines
17 KiB
Plaintext

2026-01-31 04:32:38.447 DEBUG [tests.conftest] Running fixture setup: test_id
2026-01-31 04:32:38.447 DEBUG [tests.conftest] Running test: test_time_filter_end_time_now with id: 2026-01-31_04-32-38__de801962-4fb4-4fbe-ab8a-53b34c6de7c2
2026-01-31 04:32:38.447 DEBUG [src.steps.common] Running fixture setup: common_setup
2026-01-31 04:32:38.448 DEBUG [src.steps.store] Running fixture setup: store_setup
2026-01-31 04:32:38.448 DEBUG [src.steps.store] Running fixture setup: node_setup
2026-01-31 04:32:38.455 DEBUG [src.node.docker_mananger] Docker client initialized with image wakuorg/nwaku:latest
2026-01-31 04:32:38.455 DEBUG [src.node.waku_node] WakuNode instance initialized with log path ./log/docker/publishing_node1_2026-01-31_04-32-38__de801962-4fb4-4fbe-ab8a-53b34c6de7c2__wakuorg_nwaku:latest.log
2026-01-31 04:32:38.455 DEBUG [src.node.waku_node] Starting Node...
2026-01-31 04:32:38.455 DEBUG [src.node.docker_mananger] Attempting to create or retrieve network waku
2026-01-31 04:32:38.457 DEBUG [src.node.docker_mananger] Network waku already exists
2026-01-31 04:32:38.457 DEBUG [src.node.docker_mananger] Generated random external IP 172.18.227.165
2026-01-31 04:32:38.457 DEBUG [src.node.docker_mananger] Generated ports ['34342', '34343', '34344', '34345', '34346']
2026-01-31 04:32:38.457 DEBUG [src.node.waku_node] RLN credentials were not set
2026-01-31 04:32:38.457 INFO [src.node.waku_node] RLN credentials not set or credential store not available, starting without RLN
2026-01-31 04:32:38.457 DEBUG [src.node.waku_node] Using volumes []
2026-01-31 04:32:38.457 DEBUG [src.node.docker_mananger] docker run -i -t -p 34342:34342 -p 34343:34343 -p 34344:34344 -p 34345:34345 -p 34346:34346 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=34344 --rest-port=34342 --tcp-port=34343 --discv5-udp-port=34345 --rest-address=0.0.0.0 --nat=extip:172.18.227.165 --peer-exchange=true --discv5-discovery=true --cluster-id=3 --nodekey=5d74dbf2b4da749a7de3d3baeeee11d86274cd11eb59b66f99df7bfe4a3cb13e --shard=0 --metrics-server=true --metrics-server-address=0.0.0.0 --metrics-server-port=34346 --metrics-logging=true --store=true --relay=true
2026-01-31 04:32:38.650 DEBUG [src.node.docker_mananger] docker network connect --ip 172.18.227.165 waku 9e6d6bae23923aa3b822d706933201eb31f12f57e9588ecd8076dff693ae20ef
2026-01-31 04:32:38.680 DEBUG [src.node.docker_mananger] Container started with ID 9e6d6bae2392. Setting up logs at ./log/docker/publishing_node1_2026-01-31_04-32-38__de801962-4fb4-4fbe-ab8a-53b34c6de7c2__wakuorg_nwaku:latest.log
2026-01-31 04:32:38.680 DEBUG [src.node.waku_node] Started container from image wakuorg/nwaku:latest. REST: 34342
2026-01-31 04:32:38.681 DEBUG [src.libs.common] Sleeping for 1 seconds
2026-01-31 04:32:38.690 ERROR [src.node.docker_mananger] Max retries reached for container 43b77e174201. Exiting log stream.
2026-01-31 04:32:39.247 ERROR [src.node.docker_mananger] Max retries reached for container 0f6a0856f262. Exiting log stream.
2026-01-31 04:32:39.681 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:34342/health" -H "Content-Type: application/json" -d 'None'
2026-01-31 04:32:39.685 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"}]}'
2026-01-31 04:32:39.685 INFO [src.node.waku_node] Node protocols are initialized !!
2026-01-31 04:32:39.685 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:34342/debug/v1/info" -H "Content-Type: application/json" -d 'None'
2026-01-31 04:32:39.687 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"listenAddresses":["/ip4/172.18.227.165/tcp/34343/p2p/16Uiu2HAmDAQfyZ9zGd6byjcGzyeydcNFPQfXgTpU3Yp8uTZqcmH2","/ip4/172.18.227.165/tcp/34344/ws/p2p/16Uiu2HAmDAQfyZ9zGd6byjcGzyeydcNFPQfXgTpU3Yp8uTZqcmH2"],"enrUri":"enr:-L24QLpAi8FM1p0wBNlRLEMoJFhoOFx9TsMlxPDfu9V7E7_MTM6RA-D40raW9sAWQZP3PCHwSU3sCtv5KvQxiSxBpvcCgmlkgnY0gmlwhKwS46WKbXVsdGlhZGRyc5YACASsEuOlBoYnAAoErBLjpQaGKN0DgnJzhQADAQAAiXNlY3AyNTZrMaEDB4lYOcVbnhCvGGCZlIRw3g4hwco_OsKJZF2F61VdLcmDdGNwgoYng3VkcIKGKYV3YWt1MgM"}'
2026-01-31 04:32:39.688 INFO [src.node.waku_node] REST service is ready !!
2026-01-31 04:32:39.695 DEBUG [src.node.docker_mananger] Docker client initialized with image wakuorg/nwaku:latest
2026-01-31 04:32:39.696 DEBUG [src.node.waku_node] WakuNode instance initialized with log path ./log/docker/store_node1_2026-01-31_04-32-38__de801962-4fb4-4fbe-ab8a-53b34c6de7c2__wakuorg_nwaku:latest.log
2026-01-31 04:32:39.696 DEBUG [src.node.waku_node] Starting Node...
2026-01-31 04:32:39.696 DEBUG [src.node.docker_mananger] Attempting to create or retrieve network waku
2026-01-31 04:32:39.697 DEBUG [src.node.docker_mananger] Network waku already exists
2026-01-31 04:32:39.697 DEBUG [src.node.docker_mananger] Generated random external IP 172.18.111.24
2026-01-31 04:32:39.698 DEBUG [src.node.docker_mananger] Generated ports ['20149', '20150', '20151', '20152', '20153']
2026-01-31 04:32:39.698 DEBUG [src.node.waku_node] RLN credentials were not set
2026-01-31 04:32:39.698 INFO [src.node.waku_node] RLN credentials not set or credential store not available, starting without RLN
2026-01-31 04:32:39.698 DEBUG [src.node.waku_node] Using volumes []
2026-01-31 04:32:39.698 DEBUG [src.node.docker_mananger] docker run -i -t -p 20149:20149 -p 20150:20150 -p 20151:20151 -p 20152:20152 -p 20153:20153 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=20151 --rest-port=20149 --tcp-port=20150 --discv5-udp-port=20152 --rest-address=0.0.0.0 --nat=extip:172.18.111.24 --peer-exchange=true --discv5-discovery=true --cluster-id=3 --nodekey=3febf619ca2e1da7e8fabb2eaf5ac6f6b0b9d365e4f67953d73de2dccd3f10d5 --shard=0 --metrics-server=true --metrics-server-address=0.0.0.0 --metrics-server-port=20153 --metrics-logging=true --discv5-bootstrap-node=enr:-L24QLpAi8FM1p0wBNlRLEMoJFhoOFx9TsMlxPDfu9V7E7_MTM6RA-D40raW9sAWQZP3PCHwSU3sCtv5KvQxiSxBpvcCgmlkgnY0gmlwhKwS46WKbXVsdGlhZGRyc5YACASsEuOlBoYnAAoErBLjpQaGKN0DgnJzhQADAQAAiXNlY3AyNTZrMaEDB4lYOcVbnhCvGGCZlIRw3g4hwco_OsKJZF2F61VdLcmDdGNwgoYng3VkcIKGKYV3YWt1MgM --storenode=/ip4/172.18.227.165/tcp/34343/p2p/16Uiu2HAmDAQfyZ9zGd6byjcGzyeydcNFPQfXgTpU3Yp8uTZqcmH2 --store=true --relay=true
2026-01-31 04:32:39.903 DEBUG [src.node.docker_mananger] docker network connect --ip 172.18.111.24 waku 21cce50841e644da557d68bf1609b349555bef05c359abebc7a88336d55b0dc7
2026-01-31 04:32:39.936 DEBUG [src.node.docker_mananger] Container started with ID 21cce50841e6. Setting up logs at ./log/docker/store_node1_2026-01-31_04-32-38__de801962-4fb4-4fbe-ab8a-53b34c6de7c2__wakuorg_nwaku:latest.log
2026-01-31 04:32:39.937 DEBUG [src.node.waku_node] Started container from image wakuorg/nwaku:latest. REST: 20149
2026-01-31 04:32:39.937 DEBUG [src.libs.common] Sleeping for 1 seconds
2026-01-31 04:32:40.938 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:20149/health" -H "Content-Type: application/json" -d 'None'
2026-01-31 04:32:40.942 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"}]}'
2026-01-31 04:32:40.943 INFO [src.node.waku_node] Node protocols are initialized !!
2026-01-31 04:32:40.943 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:20149/debug/v1/info" -H "Content-Type: application/json" -d 'None'
2026-01-31 04:32:40.945 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"listenAddresses":["/ip4/172.18.111.24/tcp/20150/p2p/16Uiu2HAkwN82PxPDxn3BN2ZiGv1tXbXevG9t3EhNAMNs5BBepdQM","/ip4/172.18.111.24/tcp/20151/ws/p2p/16Uiu2HAkwN82PxPDxn3BN2ZiGv1tXbXevG9t3EhNAMNs5BBepdQM"],"enrUri":"enr:-L24QFc4mM4VP7p-A2NMrdETdcoCrPSxt1HFImUkAa-mBAusUSL3I7R7ZBEHbI4g8dJp_x4fzksBipx97fnMUkGZReMCgmlkgnY0gmlwhKwSbxiKbXVsdGlhZGRyc5YACASsEm8YBk62AAoErBJvGAZOt90DgnJzhQADAQAAiXNlY3AyNTZrMaECHM5_6YFFFDgr7L5YY0qTtayRLzpEOqbTuwif9FtIS8KDdGNwgk62g3VkcIJOuIV3YWt1MgM"}'
2026-01-31 04:32:40.946 INFO [src.node.waku_node] REST service is ready !!
2026-01-31 04:32:40.946 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:20149/admin/v1/peers" -H "Content-Type: application/json" -d '["/ip4/172.18.227.165/tcp/34343/p2p/16Uiu2HAmDAQfyZ9zGd6byjcGzyeydcNFPQfXgTpU3Yp8uTZqcmH2"]'
2026-01-31 04:32:40.949 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2026-01-31 04:32:40.949 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:34342/relay/v1/subscriptions" -H "Content-Type: application/json" -d '["/waku/2/rs/3/0"]'
2026-01-31 04:32:40.952 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2026-01-31 04:32:40.952 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:20149/relay/v1/subscriptions" -H "Content-Type: application/json" -d '["/waku/2/rs/3/0"]'
2026-01-31 04:32:40.954 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2026-01-31 04:32:40.956 DEBUG [src.steps.store] Relaying message
2026-01-31 04:32:40.956 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:34342/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)'}'
2026-01-31 04:32:40.961 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2026-01-31 04:32:40.961 DEBUG [src.libs.common] Sleeping for 0.2 seconds
2026-01-31 04:32:41.163 DEBUG [src.steps.store] Relaying message
2026-01-31 04:32:41.163 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:34342/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)'}'
2026-01-31 04:32:41.169 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2026-01-31 04:32:41.170 DEBUG [src.libs.common] Sleeping for 0.2 seconds
2026-01-31 04:32:41.370 DEBUG [src.steps.store] Relaying message
2026-01-31 04:32:41.371 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:34342/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)'}'
2026-01-31 04:32:41.376 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2026-01-31 04:32:41.377 DEBUG [src.libs.common] Sleeping for 0.2 seconds
2026-01-31 04:32:41.577 DEBUG [src.steps.store] Relaying message
2026-01-31 04:32:41.577 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:34342/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)'}'
2026-01-31 04:32:41.584 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2026-01-31 04:32:41.585 DEBUG [src.libs.common] Sleeping for 0.2 seconds
2026-01-31 04:32:41.785 DEBUG [src.steps.store] Relaying message
2026-01-31 04:32:41.785 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:34342/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)'}'
2026-01-31 04:32:41.791 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2026-01-31 04:32:41.791 DEBUG [src.libs.common] Sleeping for 0.2 seconds
2026-01-31 04:32:41.992 DEBUG [src.steps.store] Relaying message
2026-01-31 04:32:41.993 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:34342/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)'}'
2026-01-31 04:32:41.999 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2026-01-31 04:32:41.999 DEBUG [src.libs.common] Sleeping for 0.2 seconds
2026-01-31 04:32:42.200 DEBUG [tests.store.test_time_filter] inquering stored messages with start time 1769833957955888896 after end time 1769833962200216064
2026-01-31 04:32:42.200 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:34342/store/v3/messages?includeData=True&pubsubTopic=%2Fwaku%2F2%2Frs%2F3%2F0&startTime=1769833957955888896&endTime=1769833962200216064&pageSize=20&ascending=true" -H "Content-Type: application/json" -d 'None'
2026-01-31 04:32:42.204 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"requestId":"","statusCode":200,"statusDesc":"OK","messages":[{"messageHash":"0x9ca86aa8f36381a30076c1728c3e9700a0edd61f043de34943eb579fe9e7e910","message":{"payload":"U3RvcmUgd29ya3MhIQ==","contentTopic":"/myapp/1/latest/proto","version":0,"timestamp":1769833957955888896,"ephemeral":false},"pubsubTopic":"/waku/2/rs/3/0"},{"messageHash":"0xedc3ed7e769e012d48aba23c753bf30ce063ae78a7a84dad65abb97614b148c3","message":{"payload":"U3RvcmUgd29ya3MhIQ==","contentTopic":"/myapp/1/latest/proto","version":0,"timestamp":1769833959955895808,"ephemeral":false},"pubsubTopic":"/waku/2/rs/3/0"},{"messageHash":"0x43d907df8e937d1ead5d6275de44092ae468bc41f2a67c7814a0d11c46cfcc95","message":{"payload":"U3RvcmUgd29ya3MhIQ==","contentTopic":"/myapp/1/latest/proto","version":0,"timestamp":1769833960855897856,"ephemeral":false},"pubsubTopic":"/waku/2/rs/3/0"}]}'
2026-01-31 04:32:42.204 DEBUG [tests.store.test_time_filter] number of messages stored for start time 1769833957955888896 and end time = 1769833962200216064 is 3
2026-01-31 04:32:42.204 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:20149/store/v3/messages?includeData=True&pubsubTopic=%2Fwaku%2F2%2Frs%2F3%2F0&startTime=1769833957955888896&endTime=1769833962200216064&pageSize=20&ascending=true" -H "Content-Type: application/json" -d 'None'
2026-01-31 04:32:42.207 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"requestId":"","statusCode":200,"statusDesc":"OK","messages":[{"messageHash":"0x9ca86aa8f36381a30076c1728c3e9700a0edd61f043de34943eb579fe9e7e910","message":{"payload":"U3RvcmUgd29ya3MhIQ==","contentTopic":"/myapp/1/latest/proto","version":0,"timestamp":1769833957955888896,"ephemeral":false},"pubsubTopic":"/waku/2/rs/3/0"},{"messageHash":"0xedc3ed7e769e012d48aba23c753bf30ce063ae78a7a84dad65abb97614b148c3","message":{"payload":"U3RvcmUgd29ya3MhIQ==","contentTopic":"/myapp/1/latest/proto","version":0,"timestamp":1769833959955895808,"ephemeral":false},"pubsubTopic":"/waku/2/rs/3/0"},{"messageHash":"0x43d907df8e937d1ead5d6275de44092ae468bc41f2a67c7814a0d11c46cfcc95","message":{"payload":"U3RvcmUgd29ya3MhIQ==","contentTopic":"/myapp/1/latest/proto","version":0,"timestamp":1769833960855897856,"ephemeral":false},"pubsubTopic":"/waku/2/rs/3/0"}]}'
2026-01-31 04:32:42.207 DEBUG [tests.store.test_time_filter] number of messages stored for start time 1769833957955888896 and end time = 1769833962200216064 is 3
2026-01-31 04:32:42.209 DEBUG [tests.conftest] Running fixture teardown: test_setup
2026-01-31 04:32:42.210 DEBUG [tests.conftest] Running fixture teardown: close_open_nodes
2026-01-31 04:32:42.210 DEBUG [src.node.waku_node] Stopping container with id 9e6d6bae2392
2026-01-31 04:32:42.761 DEBUG [src.node.waku_node] Container stopped.
2026-01-31 04:32:42.761 DEBUG [src.node.waku_node] Stopping container with id 21cce50841e6
2026-01-31 04:32:43.329 DEBUG [src.node.waku_node] Container stopped.
2026-01-31 04:32:43.331 DEBUG [tests.conftest] Running fixture teardown: check_waku_log_errors
2026-01-31 04:32:43.338 DEBUG [src.node.docker_mananger] No errors found in the waku logs.
2026-01-31 04:32:43.345 DEBUG [src.node.docker_mananger] No errors found in the waku logs.