81 lines
14 KiB
Plaintext

2025-12-09 04:09:45.267 DEBUG [tests.conftest] Running fixture setup: test_id
2025-12-09 04:09:45.268 DEBUG [tests.conftest] Running test: test_filter_unsubscribe_with_very_large_request_id with id: 2025-12-09_04-09-45__c37a6f90-af12-4e72-a0b6-fd04eeea90cb
2025-12-09 04:09:45.268 DEBUG [src.steps.common] Running fixture setup: common_setup
2025-12-09 04:09:45.268 DEBUG [src.steps.filter] Running fixture setup: filter_setup
2025-12-09 04:09:45.268 DEBUG [src.steps.filter] Running fixture setup: setup_main_relay_node
2025-12-09 04:09:45.275 DEBUG [src.node.docker_mananger] Docker client initialized with image wakuorg/nwaku:latest
2025-12-09 04:09:45.275 DEBUG [src.node.waku_node] WakuNode instance initialized with log path ./log/docker/node1_2025-12-09_04-09-45__c37a6f90-af12-4e72-a0b6-fd04eeea90cb__wakuorg_nwaku:latest.log
2025-12-09 04:09:45.275 DEBUG [src.node.waku_node] Starting Node...
2025-12-09 04:09:45.276 DEBUG [src.node.docker_mananger] Attempting to create or retrieve network waku
2025-12-09 04:09:45.277 DEBUG [src.node.docker_mananger] Network waku already exists
2025-12-09 04:09:45.277 DEBUG [src.node.docker_mananger] Generated random external IP 172.18.145.72
2025-12-09 04:09:45.277 DEBUG [src.node.docker_mananger] Generated ports ['2249', '2250', '2251', '2252', '2253']
2025-12-09 04:09:45.277 DEBUG [src.node.waku_node] RLN credentials were not set
2025-12-09 04:09:45.277 INFO [src.node.waku_node] RLN credentials not set or credential store not available, starting without RLN
2025-12-09 04:09:45.278 DEBUG [src.node.waku_node] Using volumes []
2025-12-09 04:09:45.278 DEBUG [src.node.docker_mananger] docker run -i -t -p 2249:2249 -p 2250:2250 -p 2251:2251 -p 2252:2252 -p 2253:2253 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=2251 --rest-port=2249 --tcp-port=2250 --discv5-udp-port=2252 --rest-address=0.0.0.0 --nat=extip:172.18.145.72 --peer-exchange=true --discv5-discovery=true --cluster-id=3 --nodekey=aca5a55e107f93e0019edc46ab9887ec5f2a211c2fa513401d305cedda26e5ee --shard=0 --metrics-server=true --metrics-server-address=0.0.0.0 --metrics-server-port=2253 --metrics-logging=true --relay=true --filter=true
2025-12-09 04:09:45.462 DEBUG [src.node.docker_mananger] docker network connect --ip 172.18.145.72 waku 682a1c91cad397d5c3d77d051141415483584b79304de7e7195045d399dac1d0
2025-12-09 04:09:45.498 DEBUG [src.node.docker_mananger] Container started with ID 682a1c91cad3. Setting up logs at ./log/docker/node1_2025-12-09_04-09-45__c37a6f90-af12-4e72-a0b6-fd04eeea90cb__wakuorg_nwaku:latest.log
2025-12-09 04:09:45.499 DEBUG [src.node.waku_node] Started container from image wakuorg/nwaku:latest. REST: 2249
2025-12-09 04:09:45.500 DEBUG [src.libs.common] Sleeping for 1 seconds
2025-12-09 04:09:45.546 ERROR [src.node.docker_mananger] Max retries reached for container fe292fa46f6b. Exiting log stream.
2025-12-09 04:09:46.067 ERROR [src.node.docker_mananger] Max retries reached for container 310f6ab0059e. Exiting log stream.
2025-12-09 04:09:46.500 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:2249/health" -H "Content-Type: application/json" -d 'None'
2025-12-09 04:09:46.504 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"}]}'
2025-12-09 04:09:46.504 INFO [src.node.waku_node] Node protocols are initialized !!
2025-12-09 04:09:46.504 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:2249/debug/v1/info" -H "Content-Type: application/json" -d 'None'
2025-12-09 04:09:46.506 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"listenAddresses":["/ip4/172.18.145.72/tcp/2250/p2p/16Uiu2HAmJfFxTkH6cooWFUdb4obfTGcjw2ypVMv2nGjGDNijUvZm","/ip4/172.18.145.72/tcp/2251/ws/p2p/16Uiu2HAmJfFxTkH6cooWFUdb4obfTGcjw2ypVMv2nGjGDNijUvZm"],"enrUri":"enr:-L24QJPP93PBg3-vYDB6rwAv2372PNKN2lZoTVMImh3mcJTxFlSx5RjFFfBV2TOXqhtp7JN3RSh4N6y3VxgAQSOx1Q8CgmlkgnY0gmlwhKwSkUiKbXVsdGlhZGRyc5YACASsEpFIBgjKAAoErBKRSAYIy90DgnJzhQADAQAAiXNlY3AyNTZrMaEDWTfEjcGZhtIdRCK7wcRK8KQc3a8od2TaasQtH7EDhZiDdGNwggjKg3VkcIIIzIV3YWt1MgU"}'
2025-12-09 04:09:46.506 INFO [src.node.waku_node] REST service is ready !!
2025-12-09 04:09:46.507 DEBUG [src.steps.filter] Running fixture setup: setup_main_filter_node
2025-12-09 04:09:46.513 DEBUG [src.node.docker_mananger] Docker client initialized with image wakuorg/nwaku:latest
2025-12-09 04:09:46.513 DEBUG [src.node.waku_node] WakuNode instance initialized with log path ./log/docker/node2_2025-12-09_04-09-45__c37a6f90-af12-4e72-a0b6-fd04eeea90cb__wakuorg_nwaku:latest.log
2025-12-09 04:09:46.513 DEBUG [src.node.waku_node] Starting Node...
2025-12-09 04:09:46.513 DEBUG [src.node.docker_mananger] Attempting to create or retrieve network waku
2025-12-09 04:09:46.515 DEBUG [src.node.docker_mananger] Network waku already exists
2025-12-09 04:09:46.515 DEBUG [src.node.docker_mananger] Generated random external IP 172.18.55.205
2025-12-09 04:09:46.515 DEBUG [src.node.docker_mananger] Generated ports ['24691', '24692', '24693', '24694', '24695']
2025-12-09 04:09:46.515 DEBUG [src.node.waku_node] RLN credentials were not set
2025-12-09 04:09:46.515 INFO [src.node.waku_node] RLN credentials not set or credential store not available, starting without RLN
2025-12-09 04:09:46.515 DEBUG [src.node.waku_node] Using volumes []
2025-12-09 04:09:46.516 DEBUG [src.node.docker_mananger] docker run -i -t -p 24691:24691 -p 24692:24692 -p 24693:24693 -p 24694:24694 -p 24695:24695 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=24693 --rest-port=24691 --tcp-port=24692 --discv5-udp-port=24694 --rest-address=0.0.0.0 --nat=extip:172.18.55.205 --peer-exchange=true --discv5-discovery=true --cluster-id=3 --nodekey=21957debb8dbfd4bfa7eece7548ad089e9c9da79fc8f261fcca7805b2fb8123c --shard=0 --metrics-server=true --metrics-server-address=0.0.0.0 --metrics-server-port=24695 --metrics-logging=true --relay=false --discv5-bootstrap-node=enr:-L24QJPP93PBg3-vYDB6rwAv2372PNKN2lZoTVMImh3mcJTxFlSx5RjFFfBV2TOXqhtp7JN3RSh4N6y3VxgAQSOx1Q8CgmlkgnY0gmlwhKwSkUiKbXVsdGlhZGRyc5YACASsEpFIBgjKAAoErBKRSAYIy90DgnJzhQADAQAAiXNlY3AyNTZrMaEDWTfEjcGZhtIdRCK7wcRK8KQc3a8od2TaasQtH7EDhZiDdGNwggjKg3VkcIIIzIV3YWt1MgU --filternode=/ip4/172.18.145.72/tcp/2250/p2p/16Uiu2HAmJfFxTkH6cooWFUdb4obfTGcjw2ypVMv2nGjGDNijUvZm
2025-12-09 04:09:46.697 DEBUG [src.node.docker_mananger] docker network connect --ip 172.18.55.205 waku b9d606b1732dec3376110614dde1f93828daa79611275db8f4edf1945696f524
2025-12-09 04:09:46.731 DEBUG [src.node.docker_mananger] Container started with ID b9d606b1732d. Setting up logs at ./log/docker/node2_2025-12-09_04-09-45__c37a6f90-af12-4e72-a0b6-fd04eeea90cb__wakuorg_nwaku:latest.log
2025-12-09 04:09:46.731 DEBUG [src.node.waku_node] Started container from image wakuorg/nwaku:latest. REST: 24691
2025-12-09 04:09:46.732 DEBUG [src.libs.common] Sleeping for 1 seconds
2025-12-09 04:09:47.732 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:24691/health" -H "Content-Type: application/json" -d 'None'
2025-12-09 04:09:47.736 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"}]}'
2025-12-09 04:09:47.736 INFO [src.node.waku_node] Node protocols are initialized !!
2025-12-09 04:09:47.736 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:24691/debug/v1/info" -H "Content-Type: application/json" -d 'None'
2025-12-09 04:09:47.738 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"listenAddresses":["/ip4/172.18.55.205/tcp/24692/p2p/16Uiu2HAm6cN7aAzkyxBGRmeMkjFnBoeTrWFwSgzLNqUgXfpVvUEk","/ip4/172.18.55.205/tcp/24693/ws/p2p/16Uiu2HAm6cN7aAzkyxBGRmeMkjFnBoeTrWFwSgzLNqUgXfpVvUEk"],"enrUri":"enr:-L24QHjcDRGpVWc1mcR4qkmoCw1W0rFhBNodNmBM0D77SsfrDCQS4sx9Bo01Jyt557NSmozuXOWW01XcbyK1ve_Z5hQCgmlkgnY0gmlwhKwSN82KbXVsdGlhZGRyc5YACASsEjfNBmB0AAoErBI3zQZgdd0DgnJzhQADAQAAiXNlY3AyNTZrMaECpi2-fAm8iJFnVY6qEQQe3fgcRQBTqMUoKPiZexWOG9GDdGNwgmB0g3VkcIJgdoV3YWt1MgA"}'
2025-12-09 04:09:47.739 INFO [src.node.waku_node] REST service is ready !!
2025-12-09 04:09:47.739 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:24691/admin/v1/peers" -H "Content-Type: application/json" -d '["/ip4/172.18.145.72/tcp/2250/p2p/16Uiu2HAmJfFxTkH6cooWFUdb4obfTGcjw2ypVMv2nGjGDNijUvZm"]'
2025-12-09 04:09:47.768 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-09 04:09:47.770 DEBUG [src.steps.filter] Running fixture setup: subscribe_main_nodes
2025-12-09 04:09:47.771 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:2249/relay/v1/subscriptions" -H "Content-Type: application/json" -d '["/waku/2/rs/3/1"]'
2025-12-09 04:09:47.781 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-09 04:09:47.782 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:24691/filter/v2/subscriptions" -H "Content-Type: application/json" -d '{"requestId": "926eedcb-1518-4d61-abe6-7eea1c6da5b8", "contentFilters": ["/test/1/waku-filter/proto"], "pubsubTopic": "/waku/2/rs/3/1"}'
2025-12-09 04:09:47.794 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"requestId":"926eedcb-1518-4d61-abe6-7eea1c6da5b8","statusDesc":"OK"}'
2025-12-09 04:09:47.796 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:2249/relay/v1/messages/%2Fwaku%2F2%2Frs%2F3%2F1" -H "Content-Type: application/json" -d '{"payload": "RmlsdGVyIHdvcmtzISE=", "contentTopic": "/test/1/waku-filter/proto", "timestamp": '$(date +%s%N)'}'
2025-12-09 04:09:47.803 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-09 04:09:47.803 DEBUG [src.libs.common] Sleeping for 0.1 seconds
2025-12-09 04:09:47.903 DEBUG [src.steps.filter] Checking that peer NODE_2:wakuorg/nwaku:latest can find the published message
2025-12-09 04:09:47.904 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:24691/filter/v2/messages/%2Ftest%2F1%2Fwaku-filter%2Fproto" -H "Content-Type: application/json" -d 'None'
2025-12-09 04:09:47.908 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'[{"payload":"RmlsdGVyIHdvcmtzISE=","contentTopic":"/test/1/waku-filter/proto","version":0,"timestamp":1765253387796297832,"ephemeral":false}]'
2025-12-09 04:09:47.910 INFO [src.node.api_clients.base_client] curl -v -X DELETE "http://127.0.0.1:24691/filter/v2/subscriptions" -H "Content-Type: application/json" -d '{"requestId": "12345678901234567890123456789012345678901234567890", "contentFilters": ["/test/1/waku-filter/proto"], "pubsubTopic": "/waku/2/rs/3/1"}'
2025-12-09 04:09:47.918 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"requestId":"12345678901234567890123456789012345678901234567890","statusDesc":"OK"}'
2025-12-09 04:09:47.919 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:2249/relay/v1/messages/%2Fwaku%2F2%2Frs%2F3%2F1" -H "Content-Type: application/json" -d '{"payload": "RmlsdGVyIHdvcmtzISE=", "contentTopic": "/test/1/waku-filter/proto", "timestamp": '$(date +%s%N)'}'
2025-12-09 04:09:47.922 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-09 04:09:47.922 DEBUG [src.libs.common] Sleeping for 0.1 seconds
2025-12-09 04:09:48.023 DEBUG [src.steps.filter] Checking that peer NODE_2:wakuorg/nwaku:latest can find the published message
2025-12-09 04:09:48.023 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:24691/filter/v2/messages/%2Ftest%2F1%2Fwaku-filter%2Fproto" -H "Content-Type: application/json" -d 'None'
2025-12-09 04:09:48.026 ERROR [src.node.api_clients.base_client] HTTP error occurred: 400 Client Error: Bad Request for url: http://127.0.0.1:24691/filter/v2/messages/%2Ftest%2F1%2Fwaku-filter%2Fproto. Response content: b'Not subscribed to topic: /test/1/waku-filter/proto'
2025-12-09 04:09:48.029 DEBUG [tests.conftest] Running fixture teardown: test_setup
2025-12-09 04:09:48.030 DEBUG [tests.conftest] Running fixture teardown: close_open_nodes
2025-12-09 04:09:48.030 DEBUG [src.node.waku_node] Stopping container with id 682a1c91cad3
2025-12-09 04:09:48.566 DEBUG [src.node.waku_node] Container stopped.
2025-12-09 04:09:48.566 DEBUG [src.node.waku_node] Stopping container with id b9d606b1732d
2025-12-09 04:09:49.103 DEBUG [src.node.waku_node] Container stopped.
2025-12-09 04:09:49.106 DEBUG [tests.conftest] Running fixture teardown: check_waku_log_errors
2025-12-09 04:09:49.112 DEBUG [src.node.docker_mananger] No errors found in the waku logs.
2025-12-09 04:09:49.118 DEBUG [src.node.docker_mananger] No errors found in the waku logs.