89 lines
16 KiB
Plaintext

2025-12-15 04:23:39.731 DEBUG [tests.conftest] Running fixture setup: test_id
2025-12-15 04:23:39.732 DEBUG [tests.conftest] Running test: test_message_relayed_while_store_node_is_stopped_without_removing with id: 2025-12-15_04-23-39__4a918d4f-f59d-4195-b4ef-be1cddad861e
2025-12-15 04:23:39.732 DEBUG [src.steps.common] Running fixture setup: common_setup
2025-12-15 04:23:39.732 DEBUG [src.steps.store] Running fixture setup: store_setup
2025-12-15 04:23:39.740 DEBUG [src.node.docker_mananger] Docker client initialized with image wakuorg/nwaku:latest
2025-12-15 04:23:39.740 DEBUG [src.node.waku_node] WakuNode instance initialized with log path ./log/docker/publishing_node1_2025-12-15_04-23-39__4a918d4f-f59d-4195-b4ef-be1cddad861e__wakuorg_nwaku:latest.log
2025-12-15 04:23:39.740 DEBUG [src.node.waku_node] Starting Node...
2025-12-15 04:23:39.740 DEBUG [src.node.docker_mananger] Attempting to create or retrieve network waku
2025-12-15 04:23:39.742 DEBUG [src.node.docker_mananger] Network waku already exists
2025-12-15 04:23:39.742 DEBUG [src.node.docker_mananger] Generated random external IP 172.18.7.127
2025-12-15 04:23:39.742 DEBUG [src.node.docker_mananger] Generated ports ['17468', '17469', '17470', '17471', '17472']
2025-12-15 04:23:39.742 DEBUG [src.node.waku_node] RLN credentials were not set
2025-12-15 04:23:39.742 INFO [src.node.waku_node] RLN credentials not set or credential store not available, starting without RLN
2025-12-15 04:23:39.742 DEBUG [src.node.waku_node] Using volumes []
2025-12-15 04:23:39.743 DEBUG [src.node.docker_mananger] docker run -i -t -p 17468:17468 -p 17469:17469 -p 17470:17470 -p 17471:17471 -p 17472:17472 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=17470 --rest-port=17468 --tcp-port=17469 --discv5-udp-port=17471 --rest-address=0.0.0.0 --nat=extip:172.18.7.127 --peer-exchange=true --discv5-discovery=true --cluster-id=3 --nodekey=c44d0fa7edf3606ed5e61f1c451dd4daeaaae9180e63ff5398fe6aa6bc54a67a --shard=0 --metrics-server=true --metrics-server-address=0.0.0.0 --metrics-server-port=17472 --metrics-logging=true --store=true --relay=true
2025-12-15 04:23:39.927 DEBUG [src.node.docker_mananger] docker network connect --ip 172.18.7.127 waku 59c4d6ccea48d19952ea40b273722798f1943c4c37c07b9dc7216adc1f9187ad
2025-12-15 04:23:39.935 ERROR [src.node.docker_mananger] Max retries reached for container 6ea3443b4dd2. Exiting log stream.
2025-12-15 04:23:39.968 DEBUG [src.node.docker_mananger] Container started with ID 59c4d6ccea48. Setting up logs at ./log/docker/publishing_node1_2025-12-15_04-23-39__4a918d4f-f59d-4195-b4ef-be1cddad861e__wakuorg_nwaku:latest.log
2025-12-15 04:23:39.969 DEBUG [src.node.waku_node] Started container from image wakuorg/nwaku:latest. REST: 17468
2025-12-15 04:23:39.969 DEBUG [src.libs.common] Sleeping for 1 seconds
2025-12-15 04:23:40.524 ERROR [src.node.docker_mananger] Max retries reached for container 69107b591fe8. Exiting log stream.
2025-12-15 04:23:40.972 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:17468/health" -H "Content-Type: application/json" -d 'None'
2025-12-15 04:23:40.975 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":"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"}]}'
2025-12-15 04:23:40.976 INFO [src.node.waku_node] Node protocols are initialized !!
2025-12-15 04:23:40.976 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:17468/debug/v1/info" -H "Content-Type: application/json" -d 'None'
2025-12-15 04:23:40.978 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"listenAddresses":["/ip4/172.18.7.127/tcp/17469/p2p/16Uiu2HAm9qykZsMw7GBLEfczDJNgpxxS5Au9greBrmDJqZwMBGuJ","/ip4/172.18.7.127/tcp/17470/ws/p2p/16Uiu2HAm9qykZsMw7GBLEfczDJNgpxxS5Au9greBrmDJqZwMBGuJ"],"enrUri":"enr:-L24QE1YWGANToe5ZUhaGKzfO-CmDCYyjJLUtzRQryb1U0FcQTiIfZ-zQooBT33q6UyRu3BZGYfZINdvdFyOYJxtGeICgmlkgnY0gmlwhKwSB3-KbXVsdGlhZGRyc5YACASsEgd_BkQ9AAoErBIHfwZEPt0DgnJzhQADAQAAiXNlY3AyNTZrMaEC1j2mtdXuFX-A8rm3Q8sUgKtpaOe2bnFxJVQ6OHoh7IWDdGNwgkQ9g3VkcIJEP4V3YWt1MgM"}'
2025-12-15 04:23:40.978 INFO [src.node.waku_node] REST service is ready !!
2025-12-15 04:23:40.986 DEBUG [src.node.docker_mananger] Docker client initialized with image wakuorg/nwaku:latest
2025-12-15 04:23:40.986 DEBUG [src.node.waku_node] WakuNode instance initialized with log path ./log/docker/store_node1_2025-12-15_04-23-39__4a918d4f-f59d-4195-b4ef-be1cddad861e__wakuorg_nwaku:latest.log
2025-12-15 04:23:40.986 DEBUG [src.node.waku_node] Starting Node...
2025-12-15 04:23:40.986 DEBUG [src.node.docker_mananger] Attempting to create or retrieve network waku
2025-12-15 04:23:40.988 DEBUG [src.node.docker_mananger] Network waku already exists
2025-12-15 04:23:40.988 DEBUG [src.node.docker_mananger] Generated random external IP 172.18.127.43
2025-12-15 04:23:40.988 DEBUG [src.node.docker_mananger] Generated ports ['46678', '46679', '46680', '46681', '46682']
2025-12-15 04:23:40.988 DEBUG [src.node.waku_node] RLN credentials were not set
2025-12-15 04:23:40.988 INFO [src.node.waku_node] RLN credentials not set or credential store not available, starting without RLN
2025-12-15 04:23:40.988 DEBUG [src.node.waku_node] Using volumes []
2025-12-15 04:23:40.988 DEBUG [src.node.docker_mananger] docker run -i -t -p 46678:46678 -p 46679:46679 -p 46680:46680 -p 46681:46681 -p 46682:46682 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=46680 --rest-port=46678 --tcp-port=46679 --discv5-udp-port=46681 --rest-address=0.0.0.0 --nat=extip:172.18.127.43 --peer-exchange=true --discv5-discovery=true --cluster-id=3 --nodekey=76bdd58cdbfdcbdab4a2ce09fabe555bf9cdeb9f9df77b89eeaf7efadd7f288a --shard=0 --metrics-server=true --metrics-server-address=0.0.0.0 --metrics-server-port=46682 --metrics-logging=true --discv5-bootstrap-node=enr:-L24QE1YWGANToe5ZUhaGKzfO-CmDCYyjJLUtzRQryb1U0FcQTiIfZ-zQooBT33q6UyRu3BZGYfZINdvdFyOYJxtGeICgmlkgnY0gmlwhKwSB3-KbXVsdGlhZGRyc5YACASsEgd_BkQ9AAoErBIHfwZEPt0DgnJzhQADAQAAiXNlY3AyNTZrMaEC1j2mtdXuFX-A8rm3Q8sUgKtpaOe2bnFxJVQ6OHoh7IWDdGNwgkQ9g3VkcIJEP4V3YWt1MgM --storenode=/ip4/172.18.7.127/tcp/17469/p2p/16Uiu2HAm9qykZsMw7GBLEfczDJNgpxxS5Au9greBrmDJqZwMBGuJ --store=false --relay=false
2025-12-15 04:23:41.185 DEBUG [src.node.docker_mananger] docker network connect --ip 172.18.127.43 waku 75e885ce0e77e58d5b34c19a5b0eec322a3ed95a93b981be5274dc9ad88a51f0
2025-12-15 04:23:41.215 DEBUG [src.node.docker_mananger] Container started with ID 75e885ce0e77. Setting up logs at ./log/docker/store_node1_2025-12-15_04-23-39__4a918d4f-f59d-4195-b4ef-be1cddad861e__wakuorg_nwaku:latest.log
2025-12-15 04:23:41.216 DEBUG [src.node.waku_node] Started container from image wakuorg/nwaku:latest. REST: 46678
2025-12-15 04:23:41.216 DEBUG [src.libs.common] Sleeping for 1 seconds
2025-12-15 04:23:42.216 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:46678/health" -H "Content-Type: application/json" -d 'None'
2025-12-15 04:23:42.220 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":"READY"},{"Legacy Store Client":"READY"},{"Filter Client":"NOT_READY","desc":"No Filter service peer available yet"}]}'
2025-12-15 04:23:42.221 INFO [src.node.waku_node] Node protocols are initialized !!
2025-12-15 04:23:42.221 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:46678/debug/v1/info" -H "Content-Type: application/json" -d 'None'
2025-12-15 04:23:42.223 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"listenAddresses":["/ip4/172.18.127.43/tcp/46679/p2p/16Uiu2HAm6KGT2knFsU3NRAn6SJRCJ7FtRkn8on5xGfUGtJYAJm2G","/ip4/172.18.127.43/tcp/46680/ws/p2p/16Uiu2HAm6KGT2knFsU3NRAn6SJRCJ7FtRkn8on5xGfUGtJYAJm2G"],"enrUri":"enr:-L24QOHIe_u98tyKcZMvd_MimcF_Akg8JeLN_k8WwEugFySNI75Oha10OnzjwLJpPuU2fe0lmU_yz-6cMq4_rhI6TmMCgmlkgnY0gmlwhKwSfyuKbXVsdGlhZGRyc5YACASsEn8rBrZXAAoErBJ_Kwa2WN0DgnJzhQADAQAAiXNlY3AyNTZrMaECocx3JzW7yPjNHHIUnyylCirKRa27Erx2zp2q_U5_IdGDdGNwgrZXg3VkcIK2WYV3YWt1MgA"}'
2025-12-15 04:23:42.223 INFO [src.node.waku_node] REST service is ready !!
2025-12-15 04:23:42.224 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:46678/admin/v1/peers" -H "Content-Type: application/json" -d '["/ip4/172.18.7.127/tcp/17469/p2p/16Uiu2HAm9qykZsMw7GBLEfczDJNgpxxS5Au9greBrmDJqZwMBGuJ"]'
2025-12-15 04:23:42.256 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-15 04:23:42.256 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:17468/relay/v1/subscriptions" -H "Content-Type: application/json" -d '["/waku/2/rs/3/0"]'
2025-12-15 04:23:42.269 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-15 04:23:42.271 DEBUG [src.steps.store] Relaying message
2025-12-15 04:23:42.272 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:17468/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)'}'
2025-12-15 04:23:42.281 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-15 04:23:42.281 DEBUG [src.libs.common] Sleeping for 0.2 seconds
2025-12-15 04:23:42.482 DEBUG [src.steps.store] Checking that peer wakuorg/nwaku:latest can find the stored messages
2025-12-15 04:23:42.483 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:17468/store/v3/messages?pubsubTopic=%2Fwaku%2F2%2Frs%2F3%2F0&pageSize=5" -H "Content-Type: application/json" -d 'None'
2025-12-15 04:23:42.486 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"requestId":"","statusCode":200,"statusDesc":"OK","messages":[{"messageHash":"0x03b0a3ce63b6c024e9b4df5df991aec7ed5b1b56a1dde871723898bccaeb1a0f"}]}'
2025-12-15 04:23:42.486 DEBUG [src.steps.store] messages length is 1
2025-12-15 04:23:42.487 DEBUG [src.steps.store] Checking that peer wakuorg/nwaku:latest can find the stored messages
2025-12-15 04:23:42.487 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:46678/store/v3/messages?pubsubTopic=%2Fwaku%2F2%2Frs%2F3%2F0&pageSize=5" -H "Content-Type: application/json" -d 'None'
2025-12-15 04:23:42.496 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"requestId":"a0663c256beb5b16c947","statusCode":200,"statusDesc":"OK","messages":[{"messageHash":"0x03b0a3ce63b6c024e9b4df5df991aec7ed5b1b56a1dde871723898bccaeb1a0f"}]}'
2025-12-15 04:23:42.497 DEBUG [src.steps.store] messages length is 1
2025-12-15 04:23:43.015 DEBUG [src.steps.store] Relaying message
2025-12-15 04:23:43.015 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:17468/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)'}'
2025-12-15 04:23:43.021 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-15 04:23:43.021 DEBUG [src.libs.common] Sleeping for 0.2 seconds
2025-12-15 04:23:43.434 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:46678/health" -H "Content-Type: application/json" -d 'None'
2025-12-15 04:23:43.538 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:46678/health" -H "Content-Type: application/json" -d 'None'
2025-12-15 04:23:43.542 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":"READY"},{"Legacy Store Client":"READY"},{"Filter Client":"NOT_READY","desc":"No Filter service peer available yet"}]}'
2025-12-15 04:23:43.542 INFO [src.node.waku_node] Node protocols are initialized !!
2025-12-15 04:23:43.543 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:46678/debug/v1/info" -H "Content-Type: application/json" -d 'None'
2025-12-15 04:23:43.545 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"listenAddresses":["/ip4/172.18.127.43/tcp/46679/p2p/16Uiu2HAm6KGT2knFsU3NRAn6SJRCJ7FtRkn8on5xGfUGtJYAJm2G","/ip4/172.18.127.43/tcp/46680/ws/p2p/16Uiu2HAm6KGT2knFsU3NRAn6SJRCJ7FtRkn8on5xGfUGtJYAJm2G"],"enrUri":"enr:-L24QOHIe_u98tyKcZMvd_MimcF_Akg8JeLN_k8WwEugFySNI75Oha10OnzjwLJpPuU2fe0lmU_yz-6cMq4_rhI6TmMCgmlkgnY0gmlwhKwSfyuKbXVsdGlhZGRyc5YACASsEn8rBrZXAAoErBJ_Kwa2WN0DgnJzhQADAQAAiXNlY3AyNTZrMaECocx3JzW7yPjNHHIUnyylCirKRa27Erx2zp2q_U5_IdGDdGNwgrZXg3VkcIK2WYV3YWt1MgA"}'
2025-12-15 04:23:43.545 INFO [src.node.waku_node] REST service is ready !!
2025-12-15 04:23:43.546 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:17468/store/v3/messages?pubsubTopic=%2Fwaku%2F2%2Frs%2F3%2F0&pageSize=5&ascending=true" -H "Content-Type: application/json" -d 'None'
2025-12-15 04:23:43.549 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"requestId":"","statusCode":200,"statusDesc":"OK","messages":[{"messageHash":"0x03b0a3ce63b6c024e9b4df5df991aec7ed5b1b56a1dde871723898bccaeb1a0f"},{"messageHash":"0x20b80387f00aaf2c1dbf200460546b975603614032ca3dcf575873f5fda2ade6"}]}'
2025-12-15 04:23:43.549 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:46678/store/v3/messages?pubsubTopic=%2Fwaku%2F2%2Frs%2F3%2F0&pageSize=5&ascending=true" -H "Content-Type: application/json" -d 'None'
2025-12-15 04:23:43.588 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"requestId":"489471b54b8897ebc43f","statusCode":200,"statusDesc":"OK","messages":[{"messageHash":"0x03b0a3ce63b6c024e9b4df5df991aec7ed5b1b56a1dde871723898bccaeb1a0f"},{"messageHash":"0x20b80387f00aaf2c1dbf200460546b975603614032ca3dcf575873f5fda2ade6"}]}'
2025-12-15 04:23:43.595 DEBUG [tests.conftest] Running fixture teardown: test_setup
2025-12-15 04:23:43.596 DEBUG [tests.conftest] Running fixture teardown: close_open_nodes
2025-12-15 04:23:43.596 DEBUG [src.node.waku_node] Stopping container with id 59c4d6ccea48
2025-12-15 04:23:44.150 DEBUG [src.node.waku_node] Container stopped.
2025-12-15 04:23:44.153 DEBUG [src.node.waku_node] Stopping container with id 75e885ce0e77
2025-12-15 04:23:44.704 DEBUG [src.node.waku_node] Container stopped.
2025-12-15 04:23:44.706 DEBUG [tests.conftest] Running fixture teardown: check_waku_log_errors
2025-12-15 04:23:44.722 DEBUG [src.node.docker_mananger] No errors found in the waku logs.
2025-12-15 04:23:44.802 DEBUG [src.node.docker_mananger] No errors found in the waku logs.