85 lines
14 KiB
Plaintext

2025-12-20 04:14:52.658 DEBUG [tests.conftest] Running fixture setup: test_id
2025-12-20 04:14:52.659 DEBUG [tests.conftest] Running test: test_store_with_non_hex_characters_in_hash with id: 2025-12-20_04-14-52__ef6e9ccf-4486-45fe-bd3b-5eb4d7a70830
2025-12-20 04:14:52.659 DEBUG [src.steps.common] Running fixture setup: common_setup
2025-12-20 04:14:52.659 DEBUG [src.steps.store] Running fixture setup: store_setup
2025-12-20 04:14:52.659 DEBUG [src.steps.store] Running fixture setup: node_setup
2025-12-20 04:14:52.666 DEBUG [src.node.docker_mananger] Docker client initialized with image wakuorg/nwaku:latest
2025-12-20 04:14:52.666 DEBUG [src.node.waku_node] WakuNode instance initialized with log path ./log/docker/publishing_node1_2025-12-20_04-14-52__ef6e9ccf-4486-45fe-bd3b-5eb4d7a70830__wakuorg_nwaku:latest.log
2025-12-20 04:14:52.666 DEBUG [src.node.waku_node] Starting Node...
2025-12-20 04:14:52.666 DEBUG [src.node.docker_mananger] Attempting to create or retrieve network waku
2025-12-20 04:14:52.667 DEBUG [src.node.docker_mananger] Network waku already exists
2025-12-20 04:14:52.667 DEBUG [src.node.docker_mananger] Generated random external IP 172.18.89.31
2025-12-20 04:14:52.667 DEBUG [src.node.docker_mananger] Generated ports ['3156', '3157', '3158', '3159', '3160']
2025-12-20 04:14:52.668 DEBUG [src.node.waku_node] RLN credentials were not set
2025-12-20 04:14:52.668 INFO [src.node.waku_node] RLN credentials not set or credential store not available, starting without RLN
2025-12-20 04:14:52.668 DEBUG [src.node.waku_node] Using volumes []
2025-12-20 04:14:52.668 DEBUG [src.node.docker_mananger] docker run -i -t -p 3156:3156 -p 3157:3157 -p 3158:3158 -p 3159:3159 -p 3160:3160 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=3158 --rest-port=3156 --tcp-port=3157 --discv5-udp-port=3159 --rest-address=0.0.0.0 --nat=extip:172.18.89.31 --peer-exchange=true --discv5-discovery=true --cluster-id=3 --nodekey=9c32f7e2eeda909ddcbc3dce4ba1b9e6cc1cbe3324ccfb27dbfeb60d0bde641e --shard=0 --metrics-server=true --metrics-server-address=0.0.0.0 --metrics-server-port=3160 --metrics-logging=true --store=true --relay=true
2025-12-20 04:14:52.849 DEBUG [src.node.docker_mananger] docker network connect --ip 172.18.89.31 waku 200e94e5c3bdacb673d4dfa20d9d667f1702b44a513052f1f01de2d412116811
2025-12-20 04:14:52.881 DEBUG [src.node.docker_mananger] Container started with ID 200e94e5c3bd. Setting up logs at ./log/docker/publishing_node1_2025-12-20_04-14-52__ef6e9ccf-4486-45fe-bd3b-5eb4d7a70830__wakuorg_nwaku:latest.log
2025-12-20 04:14:52.883 DEBUG [src.node.waku_node] Started container from image wakuorg/nwaku:latest. REST: 3156
2025-12-20 04:14:52.883 DEBUG [src.libs.common] Sleeping for 1 seconds
2025-12-20 04:14:52.931 ERROR [src.node.docker_mananger] Max retries reached for container 3020947710c2. Exiting log stream.
2025-12-20 04:14:53.459 ERROR [src.node.docker_mananger] Max retries reached for container 03ab425c56eb. Exiting log stream.
2025-12-20 04:14:53.885 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:3156/health" -H "Content-Type: application/json" -d 'None'
2025-12-20 04:14:53.888 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-20 04:14:53.888 INFO [src.node.waku_node] Node protocols are initialized !!
2025-12-20 04:14:53.888 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:3156/debug/v1/info" -H "Content-Type: application/json" -d 'None'
2025-12-20 04:14:53.890 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"listenAddresses":["/ip4/172.18.89.31/tcp/3157/p2p/16Uiu2HAkwaTHcWTom8Lssj5bhQDxXtqcZaLrWrXxsZBPeGanVveD","/ip4/172.18.89.31/tcp/3158/ws/p2p/16Uiu2HAkwaTHcWTom8Lssj5bhQDxXtqcZaLrWrXxsZBPeGanVveD"],"enrUri":"enr:-L24QOg6-oSk_nBL3diGecJbyRnm8VP4dhXJKF0PD8uCydaDQXA5HK3Rzyz8Ml88_9Mm25KU2qGvcMS9YbvjDm1xBtQCgmlkgnY0gmlwhKwSWR-KbXVsdGlhZGRyc5YACASsElkfBgxVAAoErBJZHwYMVt0DgnJzhQADAQAAiXNlY3AyNTZrMaECH_c_1yi8wb1hAjvl7VDUE2z1b-POBxIYNKlYwTkHLvKDdGNwggxVg3VkcIIMV4V3YWt1MgM"}'
2025-12-20 04:14:53.890 INFO [src.node.waku_node] REST service is ready !!
2025-12-20 04:14:53.897 DEBUG [src.node.docker_mananger] Docker client initialized with image wakuorg/nwaku:latest
2025-12-20 04:14:53.897 DEBUG [src.node.waku_node] WakuNode instance initialized with log path ./log/docker/store_node1_2025-12-20_04-14-52__ef6e9ccf-4486-45fe-bd3b-5eb4d7a70830__wakuorg_nwaku:latest.log
2025-12-20 04:14:53.897 DEBUG [src.node.waku_node] Starting Node...
2025-12-20 04:14:53.897 DEBUG [src.node.docker_mananger] Attempting to create or retrieve network waku
2025-12-20 04:14:53.899 DEBUG [src.node.docker_mananger] Network waku already exists
2025-12-20 04:14:53.899 DEBUG [src.node.docker_mananger] Generated random external IP 172.18.183.123
2025-12-20 04:14:53.899 DEBUG [src.node.docker_mananger] Generated ports ['62563', '62564', '62565', '62566', '62567']
2025-12-20 04:14:53.899 DEBUG [src.node.waku_node] RLN credentials were not set
2025-12-20 04:14:53.900 INFO [src.node.waku_node] RLN credentials not set or credential store not available, starting without RLN
2025-12-20 04:14:53.900 DEBUG [src.node.waku_node] Using volumes []
2025-12-20 04:14:53.900 DEBUG [src.node.docker_mananger] docker run -i -t -p 62563:62563 -p 62564:62564 -p 62565:62565 -p 62566:62566 -p 62567:62567 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=62565 --rest-port=62563 --tcp-port=62564 --discv5-udp-port=62566 --rest-address=0.0.0.0 --nat=extip:172.18.183.123 --peer-exchange=true --discv5-discovery=true --cluster-id=3 --nodekey=efb7bd1aa7343a862e783a9cfd0dd73e4faf66f97cd66c4a824e47fbe5bdb6ce --shard=0 --metrics-server=true --metrics-server-address=0.0.0.0 --metrics-server-port=62567 --metrics-logging=true --discv5-bootstrap-node=enr:-L24QOg6-oSk_nBL3diGecJbyRnm8VP4dhXJKF0PD8uCydaDQXA5HK3Rzyz8Ml88_9Mm25KU2qGvcMS9YbvjDm1xBtQCgmlkgnY0gmlwhKwSWR-KbXVsdGlhZGRyc5YACASsElkfBgxVAAoErBJZHwYMVt0DgnJzhQADAQAAiXNlY3AyNTZrMaECH_c_1yi8wb1hAjvl7VDUE2z1b-POBxIYNKlYwTkHLvKDdGNwggxVg3VkcIIMV4V3YWt1MgM --storenode=/ip4/172.18.89.31/tcp/3157/p2p/16Uiu2HAkwaTHcWTom8Lssj5bhQDxXtqcZaLrWrXxsZBPeGanVveD --store=true --relay=true
2025-12-20 04:14:54.084 DEBUG [src.node.docker_mananger] docker network connect --ip 172.18.183.123 waku 9cea4c624a8f99e0285353fb40b146a9adc67317ccff3e31c0119cc1d69988be
2025-12-20 04:14:54.118 DEBUG [src.node.docker_mananger] Container started with ID 9cea4c624a8f. Setting up logs at ./log/docker/store_node1_2025-12-20_04-14-52__ef6e9ccf-4486-45fe-bd3b-5eb4d7a70830__wakuorg_nwaku:latest.log
2025-12-20 04:14:54.119 DEBUG [src.node.waku_node] Started container from image wakuorg/nwaku:latest. REST: 62563
2025-12-20 04:14:54.119 DEBUG [src.libs.common] Sleeping for 1 seconds
2025-12-20 04:14:55.119 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:62563/health" -H "Content-Type: application/json" -d 'None'
2025-12-20 04:14:55.123 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"nodeHealth":"READY","protocolsHealth":[{"Relay":"READY"},{"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":"READY"},{"Filter Client":"NOT_READY","desc":"No Filter service peer available yet"}]}'
2025-12-20 04:14:55.123 INFO [src.node.waku_node] Node protocols are initialized !!
2025-12-20 04:14:55.124 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:62563/debug/v1/info" -H "Content-Type: application/json" -d 'None'
2025-12-20 04:14:55.126 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'{"listenAddresses":["/ip4/172.18.183.123/tcp/62564/p2p/16Uiu2HAm3w6fkFoERVVsSYiSLXa7e15SXCPU2scqrhjWL9oZ1GZu","/ip4/172.18.183.123/tcp/62565/ws/p2p/16Uiu2HAm3w6fkFoERVVsSYiSLXa7e15SXCPU2scqrhjWL9oZ1GZu"],"enrUri":"enr:-L24QGs8usJnS5F_0ljE7F9umCnsYgw0IztsJZ9OIbl2B9cfZctE9WSYxpnrJ5zG2CI2r_vGFZFczQe2Wfe-8OFi5FkCgmlkgnY0gmlwhKwSt3uKbXVsdGlhZGRyc5YACASsErd7BvRkAAoErBK3ewb0Zd0DgnJzhQADAQAAiXNlY3AyNTZrMaECfmdBMCzfP-z2dGwiD_EOnp4-dCdgYm18nxDW0au2U9CDdGNwgvRkg3VkcIL0ZoV3YWt1MgM"}'
2025-12-20 04:14:55.126 INFO [src.node.waku_node] REST service is ready !!
2025-12-20 04:14:55.126 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:62563/admin/v1/peers" -H "Content-Type: application/json" -d '["/ip4/172.18.89.31/tcp/3157/p2p/16Uiu2HAkwaTHcWTom8Lssj5bhQDxXtqcZaLrWrXxsZBPeGanVveD"]'
2025-12-20 04:14:55.128 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-20 04:14:55.129 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:3156/relay/v1/subscriptions" -H "Content-Type: application/json" -d '["/waku/2/rs/3/0"]'
2025-12-20 04:14:55.131 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-20 04:14:55.131 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:62563/relay/v1/subscriptions" -H "Content-Type: application/json" -d '["/waku/2/rs/3/0"]'
2025-12-20 04:14:55.133 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-20 04:14:55.134 DEBUG [src.steps.store] Relaying message
2025-12-20 04:14:55.135 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:3156/relay/v1/messages/%2Fwaku%2F2%2Frs%2F3%2F0" -H "Content-Type: application/json" -d '{"payload": "TWVzc2FnZV8w", "contentTopic": "/myapp/1/latest/proto", "timestamp": '$(date +%s%N)'}'
2025-12-20 04:14:55.139 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-20 04:14:55.140 DEBUG [src.libs.common] Sleeping for 0.2 seconds
2025-12-20 04:14:55.341 DEBUG [src.steps.store] Relaying message
2025-12-20 04:14:55.341 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:3156/relay/v1/messages/%2Fwaku%2F2%2Frs%2F3%2F0" -H "Content-Type: application/json" -d '{"payload": "TWVzc2FnZV8x", "contentTopic": "/myapp/1/latest/proto", "timestamp": '$(date +%s%N)'}'
2025-12-20 04:14:55.346 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-20 04:14:55.346 DEBUG [src.libs.common] Sleeping for 0.2 seconds
2025-12-20 04:14:55.547 DEBUG [src.steps.store] Relaying message
2025-12-20 04:14:55.547 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:3156/relay/v1/messages/%2Fwaku%2F2%2Frs%2F3%2F0" -H "Content-Type: application/json" -d '{"payload": "TWVzc2FnZV8y", "contentTopic": "/myapp/1/latest/proto", "timestamp": '$(date +%s%N)'}'
2025-12-20 04:14:55.552 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-20 04:14:55.552 DEBUG [src.libs.common] Sleeping for 0.2 seconds
2025-12-20 04:14:55.752 DEBUG [src.steps.store] Relaying message
2025-12-20 04:14:55.753 INFO [src.node.api_clients.base_client] curl -v -X POST "http://127.0.0.1:3156/relay/v1/messages/%2Fwaku%2F2%2Frs%2F3%2F0" -H "Content-Type: application/json" -d '{"payload": "TWVzc2FnZV8z", "contentTopic": "/myapp/1/latest/proto", "timestamp": '$(date +%s%N)'}'
2025-12-20 04:14:55.757 INFO [src.node.api_clients.base_client] Response status code: 200. Response content: b'OK'
2025-12-20 04:14:55.757 DEBUG [src.libs.common] Sleeping for 0.2 seconds
2025-12-20 04:14:55.958 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:3156/store/v3/messages?hashes=%23%23%23%20INVALID%20HASH%20%23%23%23&pageSize=50&ascending=true" -H "Content-Type: application/json" -d 'None'
2025-12-20 04:14:55.960 ERROR [src.node.api_clients.base_client] HTTP error occurred: 400 Client Error: Bad Request for url: http://127.0.0.1:3156/store/v3/messages?hashes=%23%23%23%20INVALID%20HASH%20%23%23%23&pageSize=50&ascending=true. Response content: b'Exception converting hex string to bytes: # is not a hexadecimal character'
2025-12-20 04:14:55.961 INFO [src.node.api_clients.base_client] curl -v -X GET "http://127.0.0.1:62563/store/v3/messages?hashes=%23%23%23%20INVALID%20HASH%20%23%23%23&pageSize=50&ascending=true" -H "Content-Type: application/json" -d 'None'
2025-12-20 04:14:55.963 ERROR [src.node.api_clients.base_client] HTTP error occurred: 400 Client Error: Bad Request for url: http://127.0.0.1:62563/store/v3/messages?hashes=%23%23%23%20INVALID%20HASH%20%23%23%23&pageSize=50&ascending=true. Response content: b'Exception converting hex string to bytes: # is not a hexadecimal character'
2025-12-20 04:14:55.965 DEBUG [tests.conftest] Running fixture teardown: test_setup
2025-12-20 04:14:55.966 DEBUG [tests.conftest] Running fixture teardown: close_open_nodes
2025-12-20 04:14:55.966 DEBUG [src.node.waku_node] Stopping container with id 200e94e5c3bd
2025-12-20 04:14:56.495 DEBUG [src.node.waku_node] Container stopped.
2025-12-20 04:14:56.495 DEBUG [src.node.waku_node] Stopping container with id 9cea4c624a8f
2025-12-20 04:14:57.038 DEBUG [src.node.waku_node] Container stopped.
2025-12-20 04:14:57.039 DEBUG [tests.conftest] Running fixture teardown: check_waku_log_errors
2025-12-20 04:14:57.045 DEBUG [src.node.docker_mananger] No errors found in the waku logs.
2025-12-20 04:14:57.052 DEBUG [src.node.docker_mananger] No errors found in the waku logs.