89 lines
17 KiB
Plaintext

2026-03-11 04:37:32.965 DEBUG [tests.conftest] Running fixture setup: test_id
2026-03-11 04:37:32.965 DEBUG [tests.conftest] Running test: test_message_relayed_while_store_node_is_stopped_without_removing with id: 2026-03-11_04-37-32__d703286d-f475-4bf1-b9bb-291726705374
2026-03-11 04:37:32.966 DEBUG [src.steps.common] Running fixture setup: common_setup
2026-03-11 04:37:32.966 DEBUG [src.steps.store] Running fixture setup: store_setup
2026-03-11 04:37:32.973 DEBUG [src.node.docker_mananger] Docker client initialized with image wakuorg/nwaku:latest
2026-03-11 04:37:32.973 DEBUG [src.node.waku_node] WakuNode instance initialized with log path ./log/docker/publishing_node1_2026-03-11_04-37-32__d703286d-f475-4bf1-b9bb-291726705374__wakuorg_nwaku:latest.log
2026-03-11 04:37:32.973 DEBUG [src.node.waku_node] Starting Node...
2026-03-11 04:37:32.973 DEBUG [src.node.docker_mananger] Attempting to create or retrieve network waku
2026-03-11 04:37:32.975 DEBUG [src.node.docker_mananger] Network waku already exists
2026-03-11 04:37:32.975 DEBUG [src.node.docker_mananger] Generated random external IP 172.18.231.250
2026-03-11 04:37:32.975 DEBUG [src.node.docker_mananger] Generated ports ['19716', '19717', '19718', '19719', '19720']
2026-03-11 04:37:32.975 DEBUG [src.node.waku_node] RLN credentials were not set
2026-03-11 04:37:32.975 INFO [src.node.waku_node] RLN credentials not set or credential store not available, starting without RLN
2026-03-11 04:37:32.975 DEBUG [src.node.waku_node] Using volumes []
2026-03-11 04:37:32.976 DEBUG [src.node.docker_mananger] docker run -i -t -p 19716:19716 -p 19717:19717 -p 19718:19718 -p 19719:19719 -p 19720:19720 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=19718 --rest-port=19716 --tcp-port=19717 --discv5-udp-port=19719 --rest-address=0.0.0.0 --nat=extip:172.18.231.250 --peer-exchange=true --discv5-discovery=true --cluster-id=3 --nodekey=916e5ef72bf4cefe34411dbec6c31db07faa2eacaa28deaebbe386e9d990e6ab --shard=0 --metrics-server=true --metrics-server-address=0.0.0.0 --metrics-server-port=19720 --metrics-logging=true --store=true --relay=true
2026-03-11 04:37:33.170 DEBUG [src.node.docker_mananger] docker network connect --ip 172.18.231.250 waku 06de6f61810cfc275fdee31810afa6aa96f1f0b15f632aca39edebf1b4ae2a01
2026-03-11 04:37:33.184 ERROR [src.node.docker_mananger] Max retries reached for container 0e04eda7eb93. Exiting log stream.
2026-03-11 04:37:33.206 DEBUG [src.node.docker_mananger] Container started with ID 06de6f61810c. Setting up logs at ./log/docker/publishing_node1_2026-03-11_04-37-32__d703286d-f475-4bf1-b9bb-291726705374__wakuorg_nwaku:latest.log
2026-03-11 04:37:33.207 DEBUG [src.node.waku_node] Started container from image wakuorg/nwaku:latest. REST: 19716
2026-03-11 04:37:33.207 DEBUG [src.libs.common] Sleeping for 1 seconds
2026-03-11 04:37:33.766 ERROR [src.node.docker_mananger] Max retries reached for container 6386237c164f. Exiting log stream.
2026-03-11 04:37:34.207 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:19716/health" -H "Content-Type: application/json" -d 'None'
2026-03-11 04:37:34.210 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_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"},{"Rln Relay":"NOT_MOUNTED"}]}'
2026-03-11 04:37:34.210 INFO [src.node.waku_node] Node protocols are initialized !!
2026-03-11 04:37:34.210 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:19716/debug/v1/info" -H "Content-Type: application/json" -d 'None'
2026-03-11 04:37:34.213 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"listenAddresses":["/ip4/172.18.231.250/tcp/19717/p2p/16Uiu2HAmEasTWYvvgjsxF5gr56UTGw8R24iVtesYSTffGiR5BSvd","/ip4/172.18.231.250/tcp/19718/ws/p2p/16Uiu2HAmEasTWYvvgjsxF5gr56UTGw8R24iVtesYSTffGiR5BSvd"],"enrUri":"enr:-L24QP35lqsQns6vSmgXqHsItb3XYpasDiazURKDq41Woc7AMQgVDG9d4dktes1Jimq79jVdRfjG8eYWXSORAb8gY-QCgmlkgnY0gmlwhKwS5_qKbXVsdGlhZGRyc5YACASsEuf6Bk0FAAoErBLn-gZNBt0DgnJzhQADAQAAiXNlY3AyNTZrMaEDHKlBx_yfyC5iPyRHx8Atpp_dzt6K5ofMqfr-GCGtdTqDdGNwgk0Fg3VkcIJNB4V3YWt1MgM"}'
2026-03-11 04:37:34.213 INFO [src.node.waku_node] REST service is ready !!
2026-03-11 04:37:34.220 DEBUG [src.node.docker_mananger] Docker client initialized with image wakuorg/nwaku:latest
2026-03-11 04:37:34.220 DEBUG [src.node.waku_node] WakuNode instance initialized with log path ./log/docker/store_node1_2026-03-11_04-37-32__d703286d-f475-4bf1-b9bb-291726705374__wakuorg_nwaku:latest.log
2026-03-11 04:37:34.221 DEBUG [src.node.waku_node] Starting Node...
2026-03-11 04:37:34.221 DEBUG [src.node.docker_mananger] Attempting to create or retrieve network waku
2026-03-11 04:37:34.222 DEBUG [src.node.docker_mananger] Network waku already exists
2026-03-11 04:37:34.222 DEBUG [src.node.docker_mananger] Generated random external IP 172.18.111.93
2026-03-11 04:37:34.222 DEBUG [src.node.docker_mananger] Generated ports ['18777', '18778', '18779', '18780', '18781']
2026-03-11 04:37:34.222 DEBUG [src.node.waku_node] RLN credentials were not set
2026-03-11 04:37:34.223 INFO [src.node.waku_node] RLN credentials not set or credential store not available, starting without RLN
2026-03-11 04:37:34.223 DEBUG [src.node.waku_node] Using volumes []
2026-03-11 04:37:34.223 DEBUG [src.node.docker_mananger] docker run -i -t -p 18777:18777 -p 18778:18778 -p 18779:18779 -p 18780:18780 -p 18781:18781 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=18779 --rest-port=18777 --tcp-port=18778 --discv5-udp-port=18780 --rest-address=0.0.0.0 --nat=extip:172.18.111.93 --peer-exchange=true --discv5-discovery=true --cluster-id=3 --nodekey=cdfc005fbd7bfce4372fbb5ef8ea392cba6cdb4b0e2f6becf3ce35fa76f7c53b --shard=0 --metrics-server=true --metrics-server-address=0.0.0.0 --metrics-server-port=18781 --metrics-logging=true --discv5-bootstrap-node=enr:-L24QP35lqsQns6vSmgXqHsItb3XYpasDiazURKDq41Woc7AMQgVDG9d4dktes1Jimq79jVdRfjG8eYWXSORAb8gY-QCgmlkgnY0gmlwhKwS5_qKbXVsdGlhZGRyc5YACASsEuf6Bk0FAAoErBLn-gZNBt0DgnJzhQADAQAAiXNlY3AyNTZrMaEDHKlBx_yfyC5iPyRHx8Atpp_dzt6K5ofMqfr-GCGtdTqDdGNwgk0Fg3VkcIJNB4V3YWt1MgM --storenode=/ip4/172.18.231.250/tcp/19717/p2p/16Uiu2HAmEasTWYvvgjsxF5gr56UTGw8R24iVtesYSTffGiR5BSvd --store=false --relay=false
2026-03-11 04:37:34.427 DEBUG [src.node.docker_mananger] docker network connect --ip 172.18.111.93 waku e99755cf96f86f8c6ee8f6d74dfa7878314aec56ef3c1771cbdcc94db1a776f1
2026-03-11 04:37:34.460 DEBUG [src.node.docker_mananger] Container started with ID e99755cf96f8. Setting up logs at ./log/docker/store_node1_2026-03-11_04-37-32__d703286d-f475-4bf1-b9bb-291726705374__wakuorg_nwaku:latest.log
2026-03-11 04:37:34.460 DEBUG [src.node.waku_node] Started container from image wakuorg/nwaku:latest. REST: 18777
2026-03-11 04:37:34.460 DEBUG [src.libs.common] Sleeping for 1 seconds
2026-03-11 04:37:35.461 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:18777/health" -H "Content-Type: application/json" -d 'None'
2026-03-11 04:37:35.464 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-11 04:37:35.464 INFO [src.node.waku_node] Node protocols are initialized !!
2026-03-11 04:37:35.464 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:18777/debug/v1/info" -H "Content-Type: application/json" -d 'None'
2026-03-11 04:37:35.466 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"listenAddresses":["/ip4/172.18.111.93/tcp/18778/p2p/16Uiu2HAm49CXz5kiNpxHZe9Vs3Ehnb5k2SKUpWYEK1472KBgEw2c","/ip4/172.18.111.93/tcp/18779/ws/p2p/16Uiu2HAm49CXz5kiNpxHZe9Vs3Ehnb5k2SKUpWYEK1472KBgEw2c"],"enrUri":"enr:-L24QF3AsIUeVUqzDmJHuTQgZFCRiVjSfsG0v4dGfE1z4gluAI-1wQ5GaZsqmy_cQv1JxgPRIthnaKpVbmBplRHWLHgCgmlkgnY0gmlwhKwSb12KbXVsdGlhZGRyc5YACASsEm9dBklaAAoErBJvXQZJW90DgnJzhQADAQAAiXNlY3AyNTZrMaECgYDbdWfWEC24EvDCY6mbHDQHAiakPoI80MeD3YEBPq2DdGNwgklag3VkcIJJXIV3YWt1MgA"}'
2026-03-11 04:37:35.467 INFO [src.node.waku_node] REST service is ready !!
2026-03-11 04:37:35.467 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:18777/admin/v1/peers" -H "Content-Type: application/json" -d '["/ip4/172.18.231.250/tcp/19717/p2p/16Uiu2HAmEasTWYvvgjsxF5gr56UTGw8R24iVtesYSTffGiR5BSvd"]'
2026-03-11 04:37:35.501 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2026-03-11 04:37:35.502 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:19716/relay/v1/subscriptions" -H "Content-Type: application/json" -d '["/waku/2/rs/3/0"]'
2026-03-11 04:37:35.516 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2026-03-11 04:37:35.518 DEBUG [src.steps.store] Relaying message
2026-03-11 04:37:35.519 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:19716/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-03-11 04:37:35.527 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2026-03-11 04:37:35.528 DEBUG [src.libs.common] Sleeping for 0.2 seconds
2026-03-11 04:37:35.729 DEBUG [src.steps.store] Checking that peer wakuorg/nwaku:latest can find the stored messages
2026-03-11 04:37:35.729 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:19716/store/v3/messages?pubsubTopic=%2Fwaku%2F2%2Frs%2F3%2F0&pageSize=5" -H "Content-Type: application/json" -d 'None'
2026-03-11 04:37:35.733 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"requestId":"","statusCode":200,"statusDesc":"OK","messages":[{"messageHash":"0xdc3107c2b7d16b5c54ba094bb665ca743e70a103868d7d9d5447194f080db47b"}]}'
2026-03-11 04:37:35.733 DEBUG [src.steps.store] messages length is 1
2026-03-11 04:37:35.733 DEBUG [src.steps.store] Checking that peer wakuorg/nwaku:latest can find the stored messages
2026-03-11 04:37:35.733 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:18777/store/v3/messages?pubsubTopic=%2Fwaku%2F2%2Frs%2F3%2F0&pageSize=5" -H "Content-Type: application/json" -d 'None'
2026-03-11 04:37:35.742 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"requestId":"0a03e4c4513fda1ee7d0","statusCode":200,"statusDesc":"OK","messages":[{"messageHash":"0xdc3107c2b7d16b5c54ba094bb665ca743e70a103868d7d9d5447194f080db47b"}]}'
2026-03-11 04:37:35.742 DEBUG [src.steps.store] messages length is 1
2026-03-11 04:37:36.279 DEBUG [src.steps.store] Relaying message
2026-03-11 04:37:36.280 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:19716/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-03-11 04:37:36.286 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2026-03-11 04:37:36.286 DEBUG [src.libs.common] Sleeping for 0.2 seconds
2026-03-11 04:37:36.983 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:18777/health" -H "Content-Type: application/json" -d 'None'
2026-03-11 04:37:37.086 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:18777/health" -H "Content-Type: application/json" -d 'None'
2026-03-11 04:37:37.089 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-11 04:37:37.089 INFO [src.node.waku_node] Node protocols are initialized !!
2026-03-11 04:37:37.089 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:18777/debug/v1/info" -H "Content-Type: application/json" -d 'None'
2026-03-11 04:37:37.091 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"listenAddresses":["/ip4/172.18.111.93/tcp/18778/p2p/16Uiu2HAm49CXz5kiNpxHZe9Vs3Ehnb5k2SKUpWYEK1472KBgEw2c","/ip4/172.18.111.93/tcp/18779/ws/p2p/16Uiu2HAm49CXz5kiNpxHZe9Vs3Ehnb5k2SKUpWYEK1472KBgEw2c"],"enrUri":"enr:-L24QF3AsIUeVUqzDmJHuTQgZFCRiVjSfsG0v4dGfE1z4gluAI-1wQ5GaZsqmy_cQv1JxgPRIthnaKpVbmBplRHWLHgCgmlkgnY0gmlwhKwSb12KbXVsdGlhZGRyc5YACASsEm9dBklaAAoErBJvXQZJW90DgnJzhQADAQAAiXNlY3AyNTZrMaECgYDbdWfWEC24EvDCY6mbHDQHAiakPoI80MeD3YEBPq2DdGNwgklag3VkcIJJXIV3YWt1MgA"}'
2026-03-11 04:37:37.092 INFO [src.node.waku_node] REST service is ready !!
2026-03-11 04:37:37.092 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:19716/store/v3/messages?pubsubTopic=%2Fwaku%2F2%2Frs%2F3%2F0&pageSize=5&ascending=true" -H "Content-Type: application/json" -d 'None'
2026-03-11 04:37:37.095 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"requestId":"","statusCode":200,"statusDesc":"OK","messages":[{"messageHash":"0xdc3107c2b7d16b5c54ba094bb665ca743e70a103868d7d9d5447194f080db47b"},{"messageHash":"0x8249dd60b8f371d6bf4554279eb298eeef193d1874fa348d04cd31ef48437238"}]}'
2026-03-11 04:37:37.095 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:18777/store/v3/messages?pubsubTopic=%2Fwaku%2F2%2Frs%2F3%2F0&pageSize=5&ascending=true" -H "Content-Type: application/json" -d 'None'
2026-03-11 04:37:37.139 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"requestId":"4a7806f2942dd275068e","statusCode":200,"statusDesc":"OK","messages":[{"messageHash":"0xdc3107c2b7d16b5c54ba094bb665ca743e70a103868d7d9d5447194f080db47b"},{"messageHash":"0x8249dd60b8f371d6bf4554279eb298eeef193d1874fa348d04cd31ef48437238"}]}'
2026-03-11 04:37:37.146 DEBUG [tests.conftest] Running fixture teardown: test_setup
2026-03-11 04:37:37.150 DEBUG [tests.conftest] Running fixture teardown: close_open_nodes
2026-03-11 04:37:37.150 DEBUG [src.node.waku_node] Stopping container with id 06de6f61810c
2026-03-11 04:37:37.715 DEBUG [src.node.waku_node] Container stopped.
2026-03-11 04:37:37.717 DEBUG [src.node.waku_node] Stopping container with id e99755cf96f8
2026-03-11 04:37:38.267 DEBUG [src.node.waku_node] Container stopped.
2026-03-11 04:37:38.269 DEBUG [tests.conftest] Running fixture teardown: check_waku_log_errors
2026-03-11 04:37:38.277 DEBUG [src.node.docker_mananger] No errors found in the waku logs.
2026-03-11 04:37:38.356 DEBUG [src.node.docker_mananger] No errors found in the waku logs.