69 lines
12 KiB
Plaintext

2026-01-29 04:33:47.861 DEBUG [tests.conftest] Running fixture setup: test_id
2026-01-29 04:33:47.861 DEBUG [tests.conftest] Running test: test_filter_subscribe_with_extra_field with id: 2026-01-29_04-33-47__37516cdf-9f14-4947-96da-13b13b47ef25
2026-01-29 04:33:47.861 DEBUG [src.steps.common] Running fixture setup: common_setup
2026-01-29 04:33:47.861 DEBUG [src.steps.filter] Running fixture setup: filter_setup
2026-01-29 04:33:47.862 DEBUG [src.steps.filter] Running fixture setup: setup_main_relay_node
2026-01-29 04:33:47.868 DEBUG [src.node.docker_mananger] Docker client initialized with image wakuorg/nwaku:latest
2026-01-29 04:33:47.869 DEBUG [src.node.waku_node] WakuNode instance initialized with log path ./log/docker/node1_2026-01-29_04-33-47__37516cdf-9f14-4947-96da-13b13b47ef25__wakuorg_nwaku:latest.log
2026-01-29 04:33:47.869 DEBUG [src.node.waku_node] Starting Node...
2026-01-29 04:33:47.869 DEBUG [src.node.docker_mananger] Attempting to create or retrieve network waku
2026-01-29 04:33:47.870 DEBUG [src.node.docker_mananger] Network waku already exists
2026-01-29 04:33:47.870 DEBUG [src.node.docker_mananger] Generated random external IP 172.18.77.162
2026-01-29 04:33:47.871 DEBUG [src.node.docker_mananger] Generated ports ['30049', '30050', '30051', '30052', '30053']
2026-01-29 04:33:47.871 DEBUG [src.node.waku_node] RLN credentials were not set
2026-01-29 04:33:47.871 INFO [src.node.waku_node] RLN credentials not set or credential store not available, starting without RLN
2026-01-29 04:33:47.871 DEBUG [src.node.waku_node] Using volumes []
2026-01-29 04:33:47.871 DEBUG [src.node.docker_mananger] docker run -i -t -p 30049:30049 -p 30050:30050 -p 30051:30051 -p 30052:30052 -p 30053:30053 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=30051 --rest-port=30049 --tcp-port=30050 --discv5-udp-port=30052 --rest-address=0.0.0.0 --nat=extip:172.18.77.162 --peer-exchange=true --discv5-discovery=true --cluster-id=3 --nodekey=b07c0fcb5aa1ea4be06cf0b3084489c12e3bdcfce1d579c344ca3088ebbfeed7 --shard=0 --metrics-server=true --metrics-server-address=0.0.0.0 --metrics-server-port=30053 --metrics-logging=true --relay=true --filter=true
2026-01-29 04:33:48.048 DEBUG [src.node.docker_mananger] docker network connect --ip 172.18.77.162 waku 6890f3223a7ecf15b0792557daef79efde48fad7cfe3a7b296e8dd5dc0963e3c
2026-01-29 04:33:48.079 DEBUG [src.node.docker_mananger] Container started with ID 6890f3223a7e. Setting up logs at ./log/docker/node1_2026-01-29_04-33-47__37516cdf-9f14-4947-96da-13b13b47ef25__wakuorg_nwaku:latest.log
2026-01-29 04:33:48.079 DEBUG [src.node.waku_node] Started container from image wakuorg/nwaku:latest. REST: 30049
2026-01-29 04:33:48.080 DEBUG [src.libs.common] Sleeping for 1 seconds
2026-01-29 04:33:48.119 ERROR [src.node.docker_mananger] Max retries reached for container 3b2cc7425199. Exiting log stream.
2026-01-29 04:33:48.663 ERROR [src.node.docker_mananger] Max retries reached for container 2c71f69f272b. Exiting log stream.
2026-01-29 04:33:49.080 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:30049/health" -H "Content-Type: application/json" -d 'None'
2026-01-29 04:33:49.083 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_READY","desc":"Relay is not ready, filter will not be able to sort out messages"},{"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"}]}'
2026-01-29 04:33:49.084 INFO [src.node.waku_node] Node protocols are initialized !!
2026-01-29 04:33:49.084 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:30049/debug/v1/info" -H "Content-Type: application/json" -d 'None'
2026-01-29 04:33:49.087 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"listenAddresses":["/ip4/172.18.77.162/tcp/30050/p2p/16Uiu2HAmLUdu8qeVr4oLiMJQyRjMcNKFHqGXq7hK4Ey8AdeYhbiS","/ip4/172.18.77.162/tcp/30051/ws/p2p/16Uiu2HAmLUdu8qeVr4oLiMJQyRjMcNKFHqGXq7hK4Ey8AdeYhbiS"],"enrUri":"enr:-L24QEdf_AyAHed9PyYmq3e0623PFglg0TlTOzpWS6ptgDL1Skn3jDfAPZAm7Hx1bbA6lQatHNpqpy-GDjtla_mAziwCgmlkgnY0gmlwhKwSTaKKbXVsdGlhZGRyc5YACASsEk2iBnViAAoErBJNogZ1Y90DgnJzhQADAQAAiXNlY3AyNTZrMaEDdDaQObKp26vDiffcGvR-VtTdQEDk1aZolkhMTHgndfuDdGNwgnVig3VkcIJ1ZIV3YWt1MgU"}'
2026-01-29 04:33:49.087 INFO [src.node.waku_node] REST service is ready !!
2026-01-29 04:33:49.087 DEBUG [src.steps.filter] Running fixture setup: setup_main_filter_node
2026-01-29 04:33:49.094 DEBUG [src.node.docker_mananger] Docker client initialized with image wakuorg/nwaku:latest
2026-01-29 04:33:49.094 DEBUG [src.node.waku_node] WakuNode instance initialized with log path ./log/docker/node2_2026-01-29_04-33-47__37516cdf-9f14-4947-96da-13b13b47ef25__wakuorg_nwaku:latest.log
2026-01-29 04:33:49.094 DEBUG [src.node.waku_node] Starting Node...
2026-01-29 04:33:49.094 DEBUG [src.node.docker_mananger] Attempting to create or retrieve network waku
2026-01-29 04:33:49.096 DEBUG [src.node.docker_mananger] Network waku already exists
2026-01-29 04:33:49.096 DEBUG [src.node.docker_mananger] Generated random external IP 172.18.180.79
2026-01-29 04:33:49.096 DEBUG [src.node.docker_mananger] Generated ports ['21934', '21935', '21936', '21937', '21938']
2026-01-29 04:33:49.096 DEBUG [src.node.waku_node] RLN credentials were not set
2026-01-29 04:33:49.096 INFO [src.node.waku_node] RLN credentials not set or credential store not available, starting without RLN
2026-01-29 04:33:49.096 DEBUG [src.node.waku_node] Using volumes []
2026-01-29 04:33:49.097 DEBUG [src.node.docker_mananger] docker run -i -t -p 21934:21934 -p 21935:21935 -p 21936:21936 -p 21937:21937 -p 21938:21938 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=21936 --rest-port=21934 --tcp-port=21935 --discv5-udp-port=21937 --rest-address=0.0.0.0 --nat=extip:172.18.180.79 --peer-exchange=true --discv5-discovery=true --cluster-id=3 --nodekey=8ec7cfea8852c846a282eb7ecdbcae81d6dcb62d7c7f6f0def0f8df7ba46e3be --shard=0 --metrics-server=true --metrics-server-address=0.0.0.0 --metrics-server-port=21938 --metrics-logging=true --relay=false --discv5-bootstrap-node=enr:-L24QEdf_AyAHed9PyYmq3e0623PFglg0TlTOzpWS6ptgDL1Skn3jDfAPZAm7Hx1bbA6lQatHNpqpy-GDjtla_mAziwCgmlkgnY0gmlwhKwSTaKKbXVsdGlhZGRyc5YACASsEk2iBnViAAoErBJNogZ1Y90DgnJzhQADAQAAiXNlY3AyNTZrMaEDdDaQObKp26vDiffcGvR-VtTdQEDk1aZolkhMTHgndfuDdGNwgnVig3VkcIJ1ZIV3YWt1MgU --filternode=/ip4/172.18.77.162/tcp/30050/p2p/16Uiu2HAmLUdu8qeVr4oLiMJQyRjMcNKFHqGXq7hK4Ey8AdeYhbiS
2026-01-29 04:33:49.276 DEBUG [src.node.docker_mananger] docker network connect --ip 172.18.180.79 waku 1f329f5755b8a81d755c0957b1308669cb8fdf4838ebfd160ca99b58d3f21f75
2026-01-29 04:33:49.307 DEBUG [src.node.docker_mananger] Container started with ID 1f329f5755b8. Setting up logs at ./log/docker/node2_2026-01-29_04-33-47__37516cdf-9f14-4947-96da-13b13b47ef25__wakuorg_nwaku:latest.log
2026-01-29 04:33:49.308 DEBUG [src.node.waku_node] Started container from image wakuorg/nwaku:latest. REST: 21934
2026-01-29 04:33:49.308 DEBUG [src.libs.common] Sleeping for 1 seconds
2026-01-29 04:33:50.309 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:21934/health" -H "Content-Type: application/json" -d 'None'
2026-01-29 04:33:50.313 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"nodeHealth":"READY","protocolsHealth":[{"Relay":"NOT_MOUNTED"},{"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":"READY"}]}'
2026-01-29 04:33:50.313 INFO [src.node.waku_node] Node protocols are initialized !!
2026-01-29 04:33:50.313 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:21934/debug/v1/info" -H "Content-Type: application/json" -d 'None'
2026-01-29 04:33:50.316 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"listenAddresses":["/ip4/172.18.180.79/tcp/21935/p2p/16Uiu2HAmSJR3rVhZhFhtL8WiTmipFZ9U1eyvGwpUmto1ojeYh1iH","/ip4/172.18.180.79/tcp/21936/ws/p2p/16Uiu2HAmSJR3rVhZhFhtL8WiTmipFZ9U1eyvGwpUmto1ojeYh1iH"],"enrUri":"enr:-L24QGlJbwc--ppeOL-UB20yjvZCtCsta78LwsJeBW3F1nR4YoT6QImCf7eIn_IZw3zUDjICGFnl9JfkN7KN2QqpveICgmlkgnY0gmlwhKwStE-KbXVsdGlhZGRyc5YACASsErRPBlWvAAoErBK0TwZVsN0DgnJzhQADAQAAiXNlY3AyNTZrMaEDyr5ZAFadr2q0fvWMnfSVBOtqtbRYGwFMGKodScqBRiqDdGNwglWvg3VkcIJVsYV3YWt1MgA"}'
2026-01-29 04:33:50.316 INFO [src.node.waku_node] REST service is ready !!
2026-01-29 04:33:50.316 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:21934/admin/v1/peers" -H "Content-Type: application/json" -d '["/ip4/172.18.77.162/tcp/30050/p2p/16Uiu2HAmLUdu8qeVr4oLiMJQyRjMcNKFHqGXq7hK4Ey8AdeYhbiS"]'
2026-01-29 04:33:50.346 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2026-01-29 04:33:50.346 DEBUG [src.steps.filter] Running fixture setup: subscribe_main_nodes
2026-01-29 04:33:50.347 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:30049/relay/v1/subscriptions" -H "Content-Type: application/json" -d '["/waku/2/rs/3/1"]'
2026-01-29 04:33:50.361 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2026-01-29 04:33:50.363 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:21934/filter/v2/subscriptions" -H "Content-Type: application/json" -d '{"requestId": "453fe721-90b0-4e51-828f-5a2133834caa", "contentFilters": ["/test/1/waku-filter/proto"], "pubsubTopic": "/waku/2/rs/3/1"}'
2026-01-29 04:33:50.377 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"requestId":"453fe721-90b0-4e51-828f-5a2133834caa","statusDesc":"OK"}'
2026-01-29 04:33:50.378 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:21934/filter/v2/subscriptions" -H "Content-Type: application/json" -d '{"requestId": "1", "contentFilters": ["/test/1/waku-filter/proto"], "pubsubTopic": "/waku/2/rs/3/1", "extraField": "extraValue"}'
2026-01-29 04:33:50.381 ERROR [src.node.api_clients.base_client] HTTP error occurred: 400 Client Error: Bad Request for url: http://127.0.0.1:21934/filter/v2/subscriptions. Response content: b'{"requestId":"unknown","statusDesc":"BAD_REQUEST: Failed to decode request: (status: 400 Bad Request, headers: , kind: Error, errobj: (status: 400 Bad Request, message: \\"Invalid content body, could not decode. Unable to deserialize data: \\", contentType: \\"text/plain\\"))"}'
2026-01-29 04:33:50.384 DEBUG [tests.conftest] Running fixture teardown: test_setup
2026-01-29 04:33:50.385 DEBUG [tests.conftest] Running fixture teardown: close_open_nodes
2026-01-29 04:33:50.385 DEBUG [src.node.waku_node] Stopping container with id 6890f3223a7e
2026-01-29 04:33:50.893 DEBUG [src.node.waku_node] Container stopped.
2026-01-29 04:33:50.893 DEBUG [src.node.waku_node] Stopping container with id 1f329f5755b8
2026-01-29 04:33:51.446 DEBUG [src.node.waku_node] Container stopped.
2026-01-29 04:33:51.448 DEBUG [tests.conftest] Running fixture teardown: check_waku_log_errors
2026-01-29 04:33:51.453 DEBUG [src.node.docker_mananger] No errors found in the waku logs.
2026-01-29 04:33:51.457 DEBUG [src.node.docker_mananger] No errors found in the waku logs.