93 lines
16 KiB
Plaintext

2025-12-13 04:15:30.326 DEBUG [tests.conftest] Running fixture setup: test_id
2025-12-13 04:15:30.326 DEBUG [tests.conftest] Running test: test_relay_resubscribe_to_unsubscribed_pubsub_topic with id: 2025-12-13_04-15-30__95ef5f4c-2d0b-4288-9102-28b71aad1f18
2025-12-13 04:15:30.326 DEBUG [src.steps.common] Running fixture setup: common_setup
2025-12-13 04:15:30.327 DEBUG [src.steps.relay] Running fixture setup: relay_setup
2025-12-13 04:15:30.327 DEBUG [src.steps.relay] Running fixture setup: setup_main_relay_nodes
2025-12-13 04:15:30.333 DEBUG [src.node.docker_mananger] Docker client initialized with image wakuorg/nwaku:latest
2025-12-13 04:15:30.333 DEBUG [src.node.waku_node] WakuNode instance initialized with log path ./log/docker/node1_2025-12-13_04-15-30__95ef5f4c-2d0b-4288-9102-28b71aad1f18__wakuorg_nwaku:latest.log
2025-12-13 04:15:30.333 DEBUG [src.node.waku_node] Starting Node...
2025-12-13 04:15:30.334 DEBUG [src.node.docker_mananger] Attempting to create or retrieve network waku
2025-12-13 04:15:30.335 DEBUG [src.node.docker_mananger] Network waku already exists
2025-12-13 04:15:30.335 DEBUG [src.node.docker_mananger] Generated random external IP 172.18.77.42
2025-12-13 04:15:30.335 DEBUG [src.node.docker_mananger] Generated ports ['41991', '41992', '41993', '41994', '41995']
2025-12-13 04:15:30.335 DEBUG [src.node.waku_node] RLN credentials were not set
2025-12-13 04:15:30.335 INFO [src.node.waku_node] RLN credentials not set or credential store not available, starting without RLN
2025-12-13 04:15:30.336 DEBUG [src.node.waku_node] Using volumes []
2025-12-13 04:15:30.336 DEBUG [src.node.docker_mananger] docker run -i -t -p 41991:41991 -p 41992:41992 -p 41993:41993 -p 41994:41994 -p 41995:41995 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=41993 --rest-port=41991 --tcp-port=41992 --discv5-udp-port=41994 --rest-address=0.0.0.0 --nat=extip:172.18.77.42 --peer-exchange=true --discv5-discovery=true --cluster-id=3 --nodekey=ce8d3abe19b4aaf72f9fce8de53fdbad5644ea2bb5490a2d8bf22a576b1edacd --shard=0 --metrics-server=true --metrics-server-address=0.0.0.0 --metrics-server-port=41995 --metrics-logging=true --relay=true
2025-12-13 04:15:30.514 DEBUG [src.node.docker_mananger] docker network connect --ip 172.18.77.42 waku 012f62399d590c1083c56298b3eb00db348123f12caae715cf857262d9626109
2025-12-13 04:15:30.546 DEBUG [src.node.docker_mananger] Container started with ID 012f62399d59. Setting up logs at ./log/docker/node1_2025-12-13_04-15-30__95ef5f4c-2d0b-4288-9102-28b71aad1f18__wakuorg_nwaku:latest.log
2025-12-13 04:15:30.547 DEBUG [src.node.waku_node] Started container from image wakuorg/nwaku:latest. REST: 41991
2025-12-13 04:15:30.548 DEBUG [src.libs.common] Sleeping for 1 seconds
2025-12-13 04:15:30.628 ERROR [src.node.docker_mananger] Max retries reached for container bf3bd25cc15c. Exiting log stream.
2025-12-13 04:15:31.136 ERROR [src.node.docker_mananger] Max retries reached for container 343c913041f7. Exiting log stream.
2025-12-13 04:15:31.548 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:41991/health" -H "Content-Type: application/json" -d 'None'
2025-12-13 04:15:31.552 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":"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-13 04:15:31.552 INFO [src.node.waku_node] Node protocols are initialized !!
2025-12-13 04:15:31.552 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:41991/debug/v1/info" -H "Content-Type: application/json" -d 'None'
2025-12-13 04:15:31.554 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"listenAddresses":["/ip4/172.18.77.42/tcp/41992/p2p/16Uiu2HAmD7sb48sTQbLEqkPu48mTTQWoiGic25mdsqy3BiBKEzxs","/ip4/172.18.77.42/tcp/41993/ws/p2p/16Uiu2HAmD7sb48sTQbLEqkPu48mTTQWoiGic25mdsqy3BiBKEzxs"],"enrUri":"enr:-L24QNeN4n4jKAUVgljImFBl7v7iTmw0YWT2Cn8nNsJqc_ZaG4bFwbU8NmlKOx3SWclz5XIOSE7ErY7noq-6RL9P6YICgmlkgnY0gmlwhKwSTSqKbXVsdGlhZGRyc5YACASsEk0qBqQIAAoErBJNKgakCd0DgnJzhQADAQAAiXNlY3AyNTZrMaEDBuMJB0KIJOCXlgJWPnwgQl7s7FP9xul6vw3Z_ov7fFSDdGNwgqQIg3VkcIKkCoV3YWt1MgE"}'
2025-12-13 04:15:31.554 INFO [src.node.waku_node] REST service is ready !!
2025-12-13 04:15:31.561 DEBUG [src.node.docker_mananger] Docker client initialized with image wakuorg/nwaku:latest
2025-12-13 04:15:31.561 DEBUG [src.node.waku_node] WakuNode instance initialized with log path ./log/docker/node2_2025-12-13_04-15-30__95ef5f4c-2d0b-4288-9102-28b71aad1f18__wakuorg_nwaku:latest.log
2025-12-13 04:15:31.561 DEBUG [src.node.waku_node] Starting Node...
2025-12-13 04:15:31.561 DEBUG [src.node.docker_mananger] Attempting to create or retrieve network waku
2025-12-13 04:15:31.563 DEBUG [src.node.docker_mananger] Network waku already exists
2025-12-13 04:15:31.563 DEBUG [src.node.docker_mananger] Generated random external IP 172.18.30.198
2025-12-13 04:15:31.563 DEBUG [src.node.docker_mananger] Generated ports ['11477', '11478', '11479', '11480', '11481']
2025-12-13 04:15:31.563 DEBUG [src.node.waku_node] RLN credentials were not set
2025-12-13 04:15:31.563 INFO [src.node.waku_node] RLN credentials not set or credential store not available, starting without RLN
2025-12-13 04:15:31.563 DEBUG [src.node.waku_node] Using volumes []
2025-12-13 04:15:31.564 DEBUG [src.node.docker_mananger] docker run -i -t -p 11477:11477 -p 11478:11478 -p 11479:11479 -p 11480:11480 -p 11481:11481 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=11479 --rest-port=11477 --tcp-port=11478 --discv5-udp-port=11480 --rest-address=0.0.0.0 --nat=extip:172.18.30.198 --peer-exchange=true --discv5-discovery=true --cluster-id=3 --nodekey=754de75e280c6ef1e3c4f129ebedbc62eb823aff8a0fe82cec913bbb36f721bc --shard=0 --metrics-server=true --metrics-server-address=0.0.0.0 --metrics-server-port=11481 --metrics-logging=true --relay=true --discv5-bootstrap-node=enr:-L24QNeN4n4jKAUVgljImFBl7v7iTmw0YWT2Cn8nNsJqc_ZaG4bFwbU8NmlKOx3SWclz5XIOSE7ErY7noq-6RL9P6YICgmlkgnY0gmlwhKwSTSqKbXVsdGlhZGRyc5YACASsEk0qBqQIAAoErBJNKgakCd0DgnJzhQADAQAAiXNlY3AyNTZrMaEDBuMJB0KIJOCXlgJWPnwgQl7s7FP9xul6vw3Z_ov7fFSDdGNwgqQIg3VkcIKkCoV3YWt1MgE
2025-12-13 04:15:31.739 DEBUG [src.node.docker_mananger] docker network connect --ip 172.18.30.198 waku c583d8040e3dc34175a715dde55fc33bda51cab7f6442a80855f36edf864fce3
2025-12-13 04:15:31.769 DEBUG [src.node.docker_mananger] Container started with ID c583d8040e3d. Setting up logs at ./log/docker/node2_2025-12-13_04-15-30__95ef5f4c-2d0b-4288-9102-28b71aad1f18__wakuorg_nwaku:latest.log
2025-12-13 04:15:31.770 DEBUG [src.node.waku_node] Started container from image wakuorg/nwaku:latest. REST: 11477
2025-12-13 04:15:31.770 DEBUG [src.libs.common] Sleeping for 1 seconds
2025-12-13 04:15:32.771 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:11477/health" -H "Content-Type: application/json" -d 'None'
2025-12-13 04:15:32.783 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":"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-13 04:15:32.784 INFO [src.node.waku_node] Node protocols are initialized !!
2025-12-13 04:15:32.785 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:11477/debug/v1/info" -H "Content-Type: application/json" -d 'None'
2025-12-13 04:15:32.792 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"listenAddresses":["/ip4/172.18.30.198/tcp/11478/p2p/16Uiu2HAm1PM4aVD7a72z6THh5C85sLVWmp8aJ1EMT787YnUGH6zd","/ip4/172.18.30.198/tcp/11479/ws/p2p/16Uiu2HAm1PM4aVD7a72z6THh5C85sLVWmp8aJ1EMT787YnUGH6zd"],"enrUri":"enr:-L24QMxW4gdnyY3PW8KUCek0BDdcmD7YBs7wEmCsWiy6Q7wBAVE9YsfheHTImGXnyyHv2UaTf9A6DdqL1nw1f-udTdACgmlkgnY0gmlwhKwSHsaKbXVsdGlhZGRyc5YACASsEh7GBizWAAoErBIexgYs190DgnJzhQADAQAAiXNlY3AyNTZrMaECWI2R4YoNAuyRUwQZrX1bUAAIs2UwdcrliSdZ5BGk_9KDdGNwgizWg3VkcIIs2IV3YWt1MgE"}'
2025-12-13 04:15:32.793 INFO [src.node.waku_node] REST service is ready !!
2025-12-13 04:15:32.793 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:11477/admin/v1/peers" -H "Content-Type: application/json" -d '["/ip4/172.18.77.42/tcp/41992/p2p/16Uiu2HAmD7sb48sTQbLEqkPu48mTTQWoiGic25mdsqy3BiBKEzxs"]'
2025-12-13 04:15:32.797 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-13 04:15:32.798 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:41991/relay/v1/subscriptions" -H "Content-Type: application/json" -d '["/waku/2/rs/3/1"]'
2025-12-13 04:15:32.801 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-13 04:15:32.802 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:11477/relay/v1/subscriptions" -H "Content-Type: application/json" -d '["/waku/2/rs/3/1"]'
2025-12-13 04:15:32.806 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-13 04:15:32.807 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:41991/relay/v1/messages/%2Fwaku%2F2%2Frs%2F3%2F1" -H "Content-Type: application/json" -d '{"payload": "UmVsYXkgd29ya3MhIQ==", "contentTopic": "/test/1/waku-relay/proto", "timestamp": '$(date +%s%N)'}'
2025-12-13 04:15:32.812 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-13 04:15:32.812 DEBUG [src.libs.common] Sleeping for 0.1 seconds
2025-12-13 04:15:32.913 DEBUG [src.steps.relay] Checking that peer NODE_1:wakuorg/nwaku:latest can find the published message
2025-12-13 04:15:32.913 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:41991/relay/v1/messages/%2Fwaku%2F2%2Frs%2F3%2F1" -H "Content-Type: application/json" -d 'None'
2025-12-13 04:15:32.915 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'[{"payload":"UmVsYXkgd29ya3MhIQ==","contentTopic":"/test/1/waku-relay/proto","version":0,"timestamp":1765599332807407872,"ephemeral":false,"proof":""}]'
2025-12-13 04:15:32.917 DEBUG [src.steps.relay] Checking that peer NODE_2:wakuorg/nwaku:latest can find the published message
2025-12-13 04:15:32.917 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:11477/relay/v1/messages/%2Fwaku%2F2%2Frs%2F3%2F1" -H "Content-Type: application/json" -d 'None'
2025-12-13 04:15:32.919 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'[{"payload":"UmVsYXkgd29ya3MhIQ==","contentTopic":"/test/1/waku-relay/proto","version":0,"timestamp":1765599332807407872,"ephemeral":false,"proof":""}]'
2025-12-13 04:15:32.921 INFO [src.node.api_clients.base_client] curl -v -X DELETE "http://127.0.0.1:41991/relay/v1/subscriptions" -H "Content-Type: application/json" -d '["/waku/2/rs/3/1"]'
2025-12-13 04:15:32.926 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-13 04:15:32.927 INFO [src.node.api_clients.base_client] curl -v -X DELETE "http://127.0.0.1:11477/relay/v1/subscriptions" -H "Content-Type: application/json" -d '["/waku/2/rs/3/1"]'
2025-12-13 04:15:32.932 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-13 04:15:32.932 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:41991/relay/v1/messages/%2Fwaku%2F2%2Frs%2F3%2F1" -H "Content-Type: application/json" -d '{"payload": "UmVsYXkgd29ya3MhIQ==", "contentTopic": "/test/1/waku-relay/proto", "timestamp": '$(date +%s%N)'}'
2025-12-13 04:15:32.935 ERROR [src.node.api_clients.base_client] HTTP error occurred: 400 Client Error: Bad Request for url: http://127.0.0.1:41991/relay/v1/messages/%2Fwaku%2F2%2Frs%2F3%2F1. Response content: b'Failed to publish: Node not subscribed to topic: /waku/2/rs/3/1'
2025-12-13 04:15:32.935 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:41991/relay/v1/subscriptions" -H "Content-Type: application/json" -d '["/waku/2/rs/3/1"]'
2025-12-13 04:15:32.938 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-13 04:15:32.939 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:11477/relay/v1/subscriptions" -H "Content-Type: application/json" -d '["/waku/2/rs/3/1"]'
2025-12-13 04:15:32.943 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-13 04:15:32.943 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:41991/relay/v1/messages/%2Fwaku%2F2%2Frs%2F3%2F1" -H "Content-Type: application/json" -d '{"payload": "UmVsYXkgd29ya3MhIQ==", "contentTopic": "/test/1/waku-relay/proto", "timestamp": '$(date +%s%N)'}'
2025-12-13 04:15:32.948 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-13 04:15:32.948 DEBUG [src.libs.common] Sleeping for 0.1 seconds
2025-12-13 04:15:33.049 DEBUG [src.steps.relay] Checking that peer NODE_1:wakuorg/nwaku:latest can find the published message
2025-12-13 04:15:33.049 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:41991/relay/v1/messages/%2Fwaku%2F2%2Frs%2F3%2F1" -H "Content-Type: application/json" -d 'None'
2025-12-13 04:15:33.052 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'[{"payload":"UmVsYXkgd29ya3MhIQ==","contentTopic":"/test/1/waku-relay/proto","version":0,"timestamp":1765599332943867151,"ephemeral":false,"proof":""}]'
2025-12-13 04:15:33.053 DEBUG [src.steps.relay] Checking that peer NODE_2:wakuorg/nwaku:latest can find the published message
2025-12-13 04:15:33.053 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:11477/relay/v1/messages/%2Fwaku%2F2%2Frs%2F3%2F1" -H "Content-Type: application/json" -d 'None'
2025-12-13 04:15:33.056 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'[{"payload":"UmVsYXkgd29ya3MhIQ==","contentTopic":"/test/1/waku-relay/proto","version":0,"timestamp":1765599332943867151,"ephemeral":false,"proof":""}]'
2025-12-13 04:15:33.058 DEBUG [tests.conftest] Running fixture teardown: test_setup
2025-12-13 04:15:33.059 DEBUG [tests.conftest] Running fixture teardown: close_open_nodes
2025-12-13 04:15:33.059 DEBUG [src.node.waku_node] Stopping container with id 012f62399d59
2025-12-13 04:15:33.587 DEBUG [src.node.waku_node] Container stopped.
2025-12-13 04:15:33.587 DEBUG [src.node.waku_node] Stopping container with id c583d8040e3d
2025-12-13 04:15:34.085 DEBUG [src.node.waku_node] Container stopped.
2025-12-13 04:15:34.086 DEBUG [tests.conftest] Running fixture teardown: check_waku_log_errors
2025-12-13 04:15:34.097 DEBUG [src.node.docker_mananger] No errors found in the waku logs.
2025-12-13 04:15:34.104 DEBUG [src.node.docker_mananger] No errors found in the waku logs.