69 lines
13 KiB
Plaintext

2026-03-05 04:33:58.409 DEBUG [tests.conftest] Running fixture setup: test_id
2026-03-05 04:33:58.409 DEBUG [tests.conftest] Running test: test_filter_unsubscribe_with_invalid_request_id with id: 2026-03-05_04-33-58__6b73bdbf-f0c2-41c1-bfa7-a9bf10a890a3
2026-03-05 04:33:58.409 DEBUG [src.steps.common] Running fixture setup: common_setup
2026-03-05 04:33:58.409 DEBUG [src.steps.filter] Running fixture setup: filter_setup
2026-03-05 04:33:58.410 DEBUG [src.steps.filter] Running fixture setup: setup_main_relay_node
2026-03-05 04:33:58.417 DEBUG [src.node.docker_mananger] Docker client initialized with image wakuorg/nwaku:latest
2026-03-05 04:33:58.417 DEBUG [src.node.waku_node] WakuNode instance initialized with log path ./log/docker/node1_2026-03-05_04-33-58__6b73bdbf-f0c2-41c1-bfa7-a9bf10a890a3__wakuorg_nwaku:latest.log
2026-03-05 04:33:58.417 DEBUG [src.node.waku_node] Starting Node...
2026-03-05 04:33:58.417 DEBUG [src.node.docker_mananger] Attempting to create or retrieve network waku
2026-03-05 04:33:58.418 DEBUG [src.node.docker_mananger] Network waku already exists
2026-03-05 04:33:58.419 DEBUG [src.node.docker_mananger] Generated random external IP 172.18.251.103
2026-03-05 04:33:58.419 DEBUG [src.node.docker_mananger] Generated ports ['4715', '4716', '4717', '4718', '4719']
2026-03-05 04:33:58.419 DEBUG [src.node.waku_node] RLN credentials were not set
2026-03-05 04:33:58.419 INFO [src.node.waku_node] RLN credentials not set or credential store not available, starting without RLN
2026-03-05 04:33:58.419 DEBUG [src.node.waku_node] Using volumes []
2026-03-05 04:33:58.419 DEBUG [src.node.docker_mananger] docker run -i -t -p 4715:4715 -p 4716:4716 -p 4717:4717 -p 4718:4718 -p 4719:4719 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=4717 --rest-port=4715 --tcp-port=4716 --discv5-udp-port=4718 --rest-address=0.0.0.0 --nat=extip:172.18.251.103 --peer-exchange=true --discv5-discovery=true --cluster-id=3 --nodekey=4496b9cafb911df58aabc4c759d40801eccf5d74fc9197aabc4b6b6e6dacb7f8 --shard=0 --metrics-server=true --metrics-server-address=0.0.0.0 --metrics-server-port=4719 --metrics-logging=true --relay=true --filter=true
2026-03-05 04:33:58.617 DEBUG [src.node.docker_mananger] docker network connect --ip 172.18.251.103 waku f50c208625508afe33265f45fca0752995f79bbadcffb881dcc8a7a5fa2f19b8
2026-03-05 04:33:58.652 ERROR [src.node.docker_mananger] Max retries reached for container d5ffb0257f73. Exiting log stream.
2026-03-05 04:33:58.653 DEBUG [src.node.docker_mananger] Container started with ID f50c20862550. Setting up logs at ./log/docker/node1_2026-03-05_04-33-58__6b73bdbf-f0c2-41c1-bfa7-a9bf10a890a3__wakuorg_nwaku:latest.log
2026-03-05 04:33:58.654 DEBUG [src.node.waku_node] Started container from image wakuorg/nwaku:latest. REST: 4715
2026-03-05 04:33:58.654 DEBUG [src.libs.common] Sleeping for 1 seconds
2026-03-05 04:33:59.211 ERROR [src.node.docker_mananger] Max retries reached for container a1d3d38df020. Exiting log stream.
2026-03-05 04:33:59.654 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:4715/health" -H "Content-Type: application/json" -d 'None'
2026-03-05 04:33:59.657 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_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"},{"Rln Relay":"NOT_MOUNTED"}]}'
2026-03-05 04:33:59.657 INFO [src.node.waku_node] Node protocols are initialized !!
2026-03-05 04:33:59.657 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:4715/debug/v1/info" -H "Content-Type: application/json" -d 'None'
2026-03-05 04:33:59.660 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"listenAddresses":["/ip4/172.18.251.103/tcp/4716/p2p/16Uiu2HAkwpR4d6DS3QvhdUNGdCNZ4SFGRKYqMiefYp6zCsvF8UFi","/ip4/172.18.251.103/tcp/4717/ws/p2p/16Uiu2HAkwpR4d6DS3QvhdUNGdCNZ4SFGRKYqMiefYp6zCsvF8UFi"],"enrUri":"enr:-L24QAnkD8brARkUQHtTHR2RKDnkQVkn8frVkhqRO1XoIyg-RB7dVmvhwhimBVAyOcie9SAhPE3sQyfTqNVm8tWQFZUCgmlkgnY0gmlwhKwS-2eKbXVsdGlhZGRyc5YACASsEvtnBhJsAAoErBL7ZwYSbd0DgnJzhQADAQAAiXNlY3AyNTZrMaECI4rdtgW7HSTdlv0Svh6QUkgAbYLlsTHEOGgSk32GiTmDdGNwghJsg3VkcIISboV3YWt1MgU"}'
2026-03-05 04:33:59.660 INFO [src.node.waku_node] REST service is ready !!
2026-03-05 04:33:59.660 DEBUG [src.steps.filter] Running fixture setup: setup_main_filter_node
2026-03-05 04:33:59.667 DEBUG [src.node.docker_mananger] Docker client initialized with image wakuorg/nwaku:latest
2026-03-05 04:33:59.667 DEBUG [src.node.waku_node] WakuNode instance initialized with log path ./log/docker/node2_2026-03-05_04-33-58__6b73bdbf-f0c2-41c1-bfa7-a9bf10a890a3__wakuorg_nwaku:latest.log
2026-03-05 04:33:59.668 DEBUG [src.node.waku_node] Starting Node...
2026-03-05 04:33:59.668 DEBUG [src.node.docker_mananger] Attempting to create or retrieve network waku
2026-03-05 04:33:59.669 DEBUG [src.node.docker_mananger] Network waku already exists
2026-03-05 04:33:59.669 DEBUG [src.node.docker_mananger] Generated random external IP 172.18.62.78
2026-03-05 04:33:59.669 DEBUG [src.node.docker_mananger] Generated ports ['17368', '17369', '17370', '17371', '17372']
2026-03-05 04:33:59.670 DEBUG [src.node.waku_node] RLN credentials were not set
2026-03-05 04:33:59.670 INFO [src.node.waku_node] RLN credentials not set or credential store not available, starting without RLN
2026-03-05 04:33:59.670 DEBUG [src.node.waku_node] Using volumes []
2026-03-05 04:33:59.670 DEBUG [src.node.docker_mananger] docker run -i -t -p 17368:17368 -p 17369:17369 -p 17370:17370 -p 17371:17371 -p 17372:17372 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=17370 --rest-port=17368 --tcp-port=17369 --discv5-udp-port=17371 --rest-address=0.0.0.0 --nat=extip:172.18.62.78 --peer-exchange=true --discv5-discovery=true --cluster-id=3 --nodekey=c35b3dbdb1d18233604cc321f0bb4cfbacbe1a14aabb519b36bdd26b05ea4ade --shard=0 --metrics-server=true --metrics-server-address=0.0.0.0 --metrics-server-port=17372 --metrics-logging=true --relay=false --discv5-bootstrap-node=enr:-L24QAnkD8brARkUQHtTHR2RKDnkQVkn8frVkhqRO1XoIyg-RB7dVmvhwhimBVAyOcie9SAhPE3sQyfTqNVm8tWQFZUCgmlkgnY0gmlwhKwS-2eKbXVsdGlhZGRyc5YACASsEvtnBhJsAAoErBL7ZwYSbd0DgnJzhQADAQAAiXNlY3AyNTZrMaECI4rdtgW7HSTdlv0Svh6QUkgAbYLlsTHEOGgSk32GiTmDdGNwghJsg3VkcIISboV3YWt1MgU --filternode=/ip4/172.18.251.103/tcp/4716/p2p/16Uiu2HAkwpR4d6DS3QvhdUNGdCNZ4SFGRKYqMiefYp6zCsvF8UFi
2026-03-05 04:33:59.874 DEBUG [src.node.docker_mananger] docker network connect --ip 172.18.62.78 waku 87941bbf0a97b764f127579efe3300740e122a3f02b6b7a42dc074c73ff7f1c8
2026-03-05 04:33:59.907 DEBUG [src.node.docker_mananger] Container started with ID 87941bbf0a97. Setting up logs at ./log/docker/node2_2026-03-05_04-33-58__6b73bdbf-f0c2-41c1-bfa7-a9bf10a890a3__wakuorg_nwaku:latest.log
2026-03-05 04:33:59.908 DEBUG [src.node.waku_node] Started container from image wakuorg/nwaku:latest. REST: 17368
2026-03-05 04:33:59.908 DEBUG [src.libs.common] Sleeping for 1 seconds
2026-03-05 04:34:00.908 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:17368/health" -H "Content-Type: application/json" -d 'None'
2026-03-05 04:34:00.911 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"nodeHealth":"READY","connectionStatus":"Disconnected","protocolsHealth":[{"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"},{"Rln Relay":"NOT_MOUNTED"}]}'
2026-03-05 04:34:00.912 INFO [src.node.waku_node] Node protocols are initialized !!
2026-03-05 04:34:00.912 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:17368/debug/v1/info" -H "Content-Type: application/json" -d 'None'
2026-03-05 04:34:00.914 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"listenAddresses":["/ip4/172.18.62.78/tcp/17369/p2p/16Uiu2HAm1pLaMVA9dLeLtUtHDwYj6n6ZaVxtzrtxNGJtFexrRaFZ","/ip4/172.18.62.78/tcp/17370/ws/p2p/16Uiu2HAm1pLaMVA9dLeLtUtHDwYj6n6ZaVxtzrtxNGJtFexrRaFZ"],"enrUri":"enr:-L24QMYjhOfYngZR_C4y0_XUPLir2YnSVSRIjU0QUlScOv32aBrxGpUQeSntPJpSYH98g1arAXJzi6mgLfp_eaFePdECgmlkgnY0gmlwhKwSPk6KbXVsdGlhZGRyc5YACASsEj5OBkPZAAoErBI-TgZD2t0DgnJzhQADAQAAiXNlY3AyNTZrMaECXvSKM3eiHZCMVZDa9Udbl1eigiL-GcDY1MNjUEjfyWCDdGNwgkPZg3VkcIJD24V3YWt1MgA"}'
2026-03-05 04:34:00.914 INFO [src.node.waku_node] REST service is ready !!
2026-03-05 04:34:00.915 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:17368/admin/v1/peers" -H "Content-Type: application/json" -d '["/ip4/172.18.251.103/tcp/4716/p2p/16Uiu2HAkwpR4d6DS3QvhdUNGdCNZ4SFGRKYqMiefYp6zCsvF8UFi"]'
2026-03-05 04:34:00.947 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2026-03-05 04:34:00.948 DEBUG [src.steps.filter] Running fixture setup: subscribe_main_nodes
2026-03-05 04:34:00.949 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:4715/relay/v1/subscriptions" -H "Content-Type: application/json" -d '["/waku/2/rs/3/1"]'
2026-03-05 04:34:00.966 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2026-03-05 04:34:00.967 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:17368/filter/v2/subscriptions" -H "Content-Type: application/json" -d '{"requestId": "5dd5b1bf-247e-4758-b314-f999bc86c614", "contentFilters": ["/test/1/waku-filter/proto"], "pubsubTopic": "/waku/2/rs/3/1"}'
2026-03-05 04:34:00.978 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"requestId":"5dd5b1bf-247e-4758-b314-f999bc86c614","statusDesc":"OK"}'
2026-03-05 04:34:00.979 INFO [src.node.api_clients.base_client] curl -v -X DELETE "http://127.0.0.1:17368/filter/v2/subscriptions" -H "Content-Type: application/json" -d '{"requestId": 1, "contentFilters": ["/test/1/waku-filter/proto"], "pubsubTopic": "/waku/2/rs/3/1"}'
2026-03-05 04:34:00.982 ERROR [src.node.api_clients.base_client] HTTP error occurred: 400 Client Error: Bad Request for url: http://127.0.0.1:17368/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-03-05 04:34:00.984 DEBUG [tests.conftest] Running fixture teardown: test_setup
2026-03-05 04:34:00.985 DEBUG [tests.conftest] Running fixture teardown: close_open_nodes
2026-03-05 04:34:00.985 DEBUG [src.node.waku_node] Stopping container with id f50c20862550
2026-03-05 04:34:01.565 DEBUG [src.node.waku_node] Container stopped.
2026-03-05 04:34:01.567 DEBUG [src.node.waku_node] Stopping container with id 87941bbf0a97
2026-03-05 04:34:02.137 DEBUG [src.node.waku_node] Container stopped.
2026-03-05 04:34:02.139 DEBUG [tests.conftest] Running fixture teardown: check_waku_log_errors
2026-03-05 04:34:02.149 DEBUG [src.node.docker_mananger] No errors found in the waku logs.
2026-03-05 04:34:02.153 DEBUG [src.node.docker_mananger] No errors found in the waku logs.