search

0KnowledgeNetwork / opt

mixnet server plugins, client apps, and other components
GNU Affero General Public License v3.0
2 stars 1 forks source link

fix(walletshield): client freezes #27

Closed xendarboh closed 3 weeks ago

xendarboh commented 2 months ago

After running for about 10 minutes, the walletshield client freezes. It still receives requests (on its listening port) but appears to have lost communication with the mix network; including for decoy traffic.

build info:

version_zkn_opt: 0fc688b0d4b238ac8da5b2c373c74450ca4c0e13
version_katzenpost: v0.0.35

This issue has been experienced with the deployed network and the local docker mixnet (with default settings from this latest main branch, with DisableDecoyTraffic manually set to false in docker/voting_mixnet/client/client.toml -- which may not be related).

./apps/walletshield/walletshield -listen :7070 -config ./docker/voting_mixnet/client/client.toml 

## ... after running for about 10 minutes

7:42:04.814 DEBU minclient:gateway1: Hop[0] 'gateway1' - 109 ms
17:42:04.814 DEBU minclient:gateway1: Hop[1] 'mix1' - 220 ms
17:42:04.814 DEBU minclient:gateway1: Hop[2] 'mix2' - 46 ms
17:42:04.814 DEBU minclient:gateway1: Hop[3] 'mix3' - 392 ms
17:42:04.814 DEBU minclient:gateway1: Hop[4] 'servicenode1' - 0 ms
17:42:04.820 DEBU minclient/conn:gateway1: Enqueued packet for send.
17:42:04.820 DEBU minclient/conn:gateway1: Dequeued packet for send.
17:42:04.820 DEBU minclient/conn:gateway1: Sent SendPacket.
17:43:30.320 DEBU minclient/pki:gateway1: Fetching PKI doc for epoch 1858342 from Provider.
17:43:30.321 DEBU minclient/conn:gateway1: Enqueued GetConsensus command for send.
17:43:30.321 DEBU minclient/conn:gateway1: Dequeued GetConsesus for send.
17:43:30.321 DEBU minclient/conn:gateway1: Sent GetConsensus.
17:43:30.322 DEBU minclient/conn:gateway1: Received Consensus: ErrorCode: 0, Payload 8895 bytes
17:43:30.324 DEBU minclient/pki:gateway1: Discarding PKI for epoch: 1858340

17:44:00.248 DEBU gateway1_client: Running garbage collection process.
17:44:00.248 DEBU gateway1_client: Garbage collecting SURB ID Map entry for Message ID &8a6818613bd1892ac09017c4eb04f57c
17:44:00.326 DEBU gateway1_client: onDocument(): &{Epoch: 1858342 GenesisEpoch: 1858331
SendRatePerMinute: 100 Mu: 0.005 MuMaxDelay: 1000 LambdaP:0.001 LambdaPMaxDelay:1000 LambdaL:0.0005 LambdaLMaxDelay:1000 LambdaD:0.0005 LambdaDMaxDelay:3000 LambdaM: 0.0005 LambdaMMaxDelay: 100
SharedRandomValue: Oef3p8/M5pVxuIiSJCMLgib6mXHqJEPpLIXdeMnj3Nw= PriorSharedRandom: [i7ovTlUnol4OSmNIrZEGmLEIK6XLetxmjF8V42iDhF0=, i7ovTlUnol4OSmNIrZEGmLEIK6XLetxmjF8V42iDhF0=]
Topology:
  [0]{[{mix1 977795e7386552a2b145eba63e6429a0b00119ac8635237dfa2cc274fb952f60 map[tcp4:[127.0.0.1:30008]]}]}
  [1]{[{mix2 703aa7c5813dd188705a616a5c959953c7a0d13c7691454356bff75153df6378 map[tcp4:[127.0.0.1:30010]]}]}
  [2]{[{mix3 0a57f0345a88c15742d9d4e78df0aa261f5a5dcebd9a5a202ab7fa8ee3f2241e map[tcp4:[127.0.0.1:30012]]}]}
}
GatewayNodes:[]{[{gateway1 09c9964eb04e32b22458f9691ab91b40385920cacb947ba889629010495fae8a map[tcp:[localhost:30004] tcp4:[127.0.0.1:30004]]tofu}]}}}
}
ServiceNodes:[]{[{servicenode1 5b23957dd0d010ae9b3bba8a0684b5ce8835ddaba65bc2d405a042b973b45a3d map[tcp4:[127.0.0.1:30006]]map[echo:map[endpoint:+echo] http_proxy:map[endpoint:http_proxy]]}]}}}

## walletshield client appears frozen, the following request does not receive a response or timeout

INFO daemon: received http request
INFO daemon: RAW HTTP REQUEST: POST /mina/devnet HTTP/1.1
Host: localhost:7070
User-Agent: curl/7.81.0
Content-Length: 52
Accept: */*
Content-Type: application/json

{"query": "{ bestChain(maxLength: 1) { creator } }"}
17:44:23.676 DEBU gateway1_client: SendMessage
amitbasuri commented 2 months ago

@xendarboh I ran for more than 10 minutes, however I dont get this walletshield client appears frozen Logs...

``` $ ./apps/walletshield/walletshield -listen :7070 -config ./docker/voting_mixnet/client/client.toml 11:43:28.567 NOTI katzenpost/client: 😼 Katzenpost is still pre-alpha. DO NOT DEPEND ON IT FOR STRONG SECURITY OR ANONYMITY. 😼 11:43:28.567 NOTI pki/voting/Client: Get(ctx, 1860831) 11:43:28.570 NOTI pki/voting/client/connector: sending getConsensus to auth3 11:43:28.570 NOTI pki/voting/client/connector: got response from auth3 to GetConsensus(1860831) (attempt 0, err=, res=Ok) 11:43:28.571 NOTI pki/voting/Client: OK, received fully signed consensus document. 11:43:28.571 NOTI pki/voting/Client: voting/Client: Get() document: &{Epoch: 1860831 GenesisEpoch: 1860827 SendRatePerMinute: 100 Mu: 0.005 MuMaxDelay: 1000 LambdaP:0.001 LambdaPMaxDelay:1000 LambdaL:0.0005 LambdaLMaxDelay:1000 LambdaD:0.0005 LambdaDMaxDelay:3000 LambdaM: 0.0005 LambdaMMaxDelay: 100 SharedRandomValue: obnTo8Efdm/v1j507dakIq0UkiuGQ/Es1hvmazPlr4M= PriorSharedRandom: [P2gJ0eR+mvz1w4jmzMOzR+5YVCEXEVZuTqOaNKGt0ZM=, P2gJ0eR+mvz1w4jmzMOzR+5YVCEXEVZuTqOaNKGt0ZM=] Topology: [0]{[{mix1 c0cc7f87d7404fd2acf76c54b82a9a072be8b639c95eb7aae92138d322e3fc72 map[tcp4:[127.0.0.1:30008]]}]} [1]{[{mix2 004acc666996025ffd3b422a969c2725464ccd11e568cf68225045d6108e8339 map[tcp4:[127.0.0.1:30010]]}]} [2]{[{mix3 f6c8a0d7c201a56456dd81c22dafe5d95dfe71bc9ab0a711b4277223b32c279e map[tcp4:[127.0.0.1:30012]]}]} } GatewayNodes:[]{[{gateway1 b285e6db1f2f76e2c4f1ebd300fa6d9808fd262ea788021d1a6b029f89239109 map[tcp:[localhost:30004] tcp4:[127.0.0.1:30004]]tofu}]}}} } ServiceNodes:[]{[{servicenode1 b278f06ca7d8c5865b27471398ec0a5d4a3250925c47595dd40c93393bb2ede2 map[tcp4:[127.0.0.1:30006]]map[echo:map[endpoint:+echo] http_proxy:map[endpoint:http_proxy]]}]}}} 11:43:28.571 NOTI minclient:gateway1: Katzenpost is still pre-alpha. DO NOT DEPEND ON IT FOR STRONG SECURITY OR ANONYMITY. 11:43:28.571 DEBU minclient:gateway1: Gateway is: gateway1 11:43:28.571 DEBU minclient/pki:gateway1: Fetching PKI doc for epoch 1860832 from Provider. 11:43:28.571 DEBU minclient/conn:gateway1: PKI fetch successful. 11:43:28.571 DEBU minclient/pki:gateway1: Failed to fetch PKI doc for epoch 1860832 from Provider: minclient/conn: not connected to the Provider 11:43:28.571 DEBU minclient/pki:gateway1: Fetching PKI doc for epoch 1860832 directly from authority. 11:43:28.571 NOTI pki/voting/Client: Get(ctx, 1860832) 11:43:28.571 DEBU minclient/conn:gateway1: Descriptor for epoch 1860831: {gateway1 b285e6db1f2f76e2c4f1ebd300fa6d9808fd262ea788021d1a6b029f89239109 map[tcp:[localhost:30004] tcp4:[127.0.0.1:30004]]tofu} 11:43:28.571 DEBU minclient/conn:gateway1: Dialing: localhost:30004 11:43:28.572 DEBU minclient/conn:gateway1: TCP connection established. 11:43:28.576 NOTI pki/voting/client/connector: sending getConsensus to auth2 11:43:28.576 NOTI pki/voting/client/connector: got response from auth2 to GetConsensus(1860832) (attempt 0, err=, res=Ok) 11:43:28.576 NOTI pki/voting/Client: OK, received fully signed consensus document. 11:43:28.577 NOTI pki/voting/Client: voting/Client: Get() document: &{Epoch: 1860832 GenesisEpoch: 1860827 SendRatePerMinute: 100 Mu: 0.005 MuMaxDelay: 1000 LambdaP:0.001 LambdaPMaxDelay:1000 LambdaL:0.0005 LambdaLMaxDelay:1000 LambdaD:0.0005 LambdaDMaxDelay:3000 LambdaM: 0.0005 LambdaMMaxDelay: 100 SharedRandomValue: 6pof5Xg1QoMa5evgBKnzL3LHcp8TrmncvJFrny/4aUk= PriorSharedRandom: [P2gJ0eR+mvz1w4jmzMOzR+5YVCEXEVZuTqOaNKGt0ZM=, P2gJ0eR+mvz1w4jmzMOzR+5YVCEXEVZuTqOaNKGt0ZM=] Topology: [0]{[{mix1 c0cc7f87d7404fd2acf76c54b82a9a072be8b639c95eb7aae92138d322e3fc72 map[tcp4:[127.0.0.1:30008]]}]} [1]{[{mix2 004acc666996025ffd3b422a969c2725464ccd11e568cf68225045d6108e8339 map[tcp4:[127.0.0.1:30010]]}]} [2]{[{mix3 f6c8a0d7c201a56456dd81c22dafe5d95dfe71bc9ab0a711b4277223b32c279e map[tcp4:[127.0.0.1:30012]]}]} } GatewayNodes:[]{[{gateway1 b285e6db1f2f76e2c4f1ebd300fa6d9808fd262ea788021d1a6b029f89239109 map[tcp:[localhost:30004] tcp4:[127.0.0.1:30004]]tofu}]}}} } ServiceNodes:[]{[{servicenode1 b278f06ca7d8c5865b27471398ec0a5d4a3250925c47595dd40c93393bb2ede2 map[tcp4:[127.0.0.1:30006]]map[echo:map[endpoint:+echo] http_proxy:map[endpoint:http_proxy]]}]}}} 11:43:28.577 DEBU gateway1_client: onDocument(): &{Epoch: 1860831 GenesisEpoch: 1860827 SendRatePerMinute: 100 Mu: 0.005 MuMaxDelay: 1000 LambdaP:0.001 LambdaPMaxDelay:1000 LambdaL:0.0005 LambdaLMaxDelay:1000 LambdaD:0.0005 LambdaDMaxDelay:3000 LambdaM: 0.0005 LambdaMMaxDelay: 100 SharedRandomValue: obnTo8Efdm/v1j507dakIq0UkiuGQ/Es1hvmazPlr4M= PriorSharedRandom: [P2gJ0eR+mvz1w4jmzMOzR+5YVCEXEVZuTqOaNKGt0ZM=, P2gJ0eR+mvz1w4jmzMOzR+5YVCEXEVZuTqOaNKGt0ZM=] Topology: [0]{[{mix1 c0cc7f87d7404fd2acf76c54b82a9a072be8b639c95eb7aae92138d322e3fc72 map[tcp4:[127.0.0.1:30008]]}]} [1]{[{mix2 004acc666996025ffd3b422a969c2725464ccd11e568cf68225045d6108e8339 map[tcp4:[127.0.0.1:30010]]}]} [2]{[{mix3 f6c8a0d7c201a56456dd81c22dafe5d95dfe71bc9ab0a711b4277223b32c279e map[tcp4:[127.0.0.1:30012]]}]} } GatewayNodes:[]{[{gateway1 b285e6db1f2f76e2c4f1ebd300fa6d9808fd262ea788021d1a6b029f89239109 map[tcp:[localhost:30004] tcp4:[127.0.0.1:30004]]tofu}]}}} } ServiceNodes:[]{[{servicenode1 b278f06ca7d8c5865b27471398ec0a5d4a3250925c47595dd40c93393bb2ede2 map[tcp4:[127.0.0.1:30006]]map[echo:map[endpoint:+echo] http_proxy:map[endpoint:http_proxy]]}]}}} 11:43:28.612 DEBU minclient/conn:gateway1: Handshake completed. 11:43:28.612 DEBU minclient/pki:gateway1: New clock skew: 0 sec 11:43:28.612 DEBU gateway1_client: onConnection 11:43:28.612 DEBU gateway1_client: Clock skew vs provider: 0s 11:44:06.115 DEBU gateway1_client: onDocument(): &{Epoch: 1860832 GenesisEpoch: 1860827 SendRatePerMinute: 100 Mu: 0.005 MuMaxDelay: 1000 LambdaP:0.001 LambdaPMaxDelay:1000 LambdaL:0.0005 LambdaLMaxDelay:1000 LambdaD:0.0005 LambdaDMaxDelay:3000 LambdaM: 0.0005 LambdaMMaxDelay: 100 SharedRandomValue: 6pof5Xg1QoMa5evgBKnzL3LHcp8TrmncvJFrny/4aUk= PriorSharedRandom: [P2gJ0eR+mvz1w4jmzMOzR+5YVCEXEVZuTqOaNKGt0ZM=, P2gJ0eR+mvz1w4jmzMOzR+5YVCEXEVZuTqOaNKGt0ZM=] Topology: [0]{[{mix1 c0cc7f87d7404fd2acf76c54b82a9a072be8b639c95eb7aae92138d322e3fc72 map[tcp4:[127.0.0.1:30008]]}]} [1]{[{mix2 004acc666996025ffd3b422a969c2725464ccd11e568cf68225045d6108e8339 map[tcp4:[127.0.0.1:30010]]}]} [2]{[{mix3 f6c8a0d7c201a56456dd81c22dafe5d95dfe71bc9ab0a711b4277223b32c279e map[tcp4:[127.0.0.1:30012]]}]} } GatewayNodes:[]{[{gateway1 b285e6db1f2f76e2c4f1ebd300fa6d9808fd262ea788021d1a6b029f89239109 map[tcp:[localhost:30004] tcp4:[127.0.0.1:30004]]tofu}]}}} } ServiceNodes:[]{[{servicenode1 b278f06ca7d8c5865b27471398ec0a5d4a3250925c47595dd40c93393bb2ede2 map[tcp4:[127.0.0.1:30006]]map[echo:map[endpoint:+echo] http_proxy:map[endpoint:http_proxy]]}]}}} 11:45:28.620 DEBU minclient/pki:gateway1: Fetching PKI doc for epoch 1860833 from Provider. 11:45:28.620 DEBU minclient/conn:gateway1: Enqueued GetConsensus command for send. 11:45:28.621 DEBU minclient/conn:gateway1: Dequeued GetConsesus for send. 11:45:28.621 DEBU minclient/conn:gateway1: Sent GetConsensus. 11:45:28.621 DEBU minclient/conn:gateway1: Received Consensus: ErrorCode: 0, Payload 8895 bytes 11:45:28.622 DEBU minclient/pki:gateway1: Discarding PKI for epoch: 1860831 11:46:06.125 DEBU gateway1_client: onDocument(): &{Epoch: 1860833 GenesisEpoch: 1860827 SendRatePerMinute: 100 Mu: 0.005 MuMaxDelay: 1000 LambdaP:0.001 LambdaPMaxDelay:1000 LambdaL:0.0005 LambdaLMaxDelay:1000 LambdaD:0.0005 LambdaDMaxDelay:3000 LambdaM: 0.0005 LambdaMMaxDelay: 100 SharedRandomValue: DnTLdPCxb38ZpMX/k+/I5aDElwVf3EWqXj8P7frgpII= PriorSharedRandom: [P2gJ0eR+mvz1w4jmzMOzR+5YVCEXEVZuTqOaNKGt0ZM=, P2gJ0eR+mvz1w4jmzMOzR+5YVCEXEVZuTqOaNKGt0ZM=] Topology: [0]{[{mix1 c0cc7f87d7404fd2acf76c54b82a9a072be8b639c95eb7aae92138d322e3fc72 map[tcp4:[127.0.0.1:30008]]}]} [1]{[{mix2 004acc666996025ffd3b422a969c2725464ccd11e568cf68225045d6108e8339 map[tcp4:[127.0.0.1:30010]]}]} [2]{[{mix3 f6c8a0d7c201a56456dd81c22dafe5d95dfe71bc9ab0a711b4277223b32c279e map[tcp4:[127.0.0.1:30012]]}]} } GatewayNodes:[]{[{gateway1 b285e6db1f2f76e2c4f1ebd300fa6d9808fd262ea788021d1a6b029f89239109 map[tcp:[localhost:30004] tcp4:[127.0.0.1:30004]]tofu}]}}} } ServiceNodes:[]{[{servicenode1 b278f06ca7d8c5865b27471398ec0a5d4a3250925c47595dd40c93393bb2ede2 map[tcp4:[127.0.0.1:30006]]map[echo:map[endpoint:+echo] http_proxy:map[endpoint:http_proxy]]}]}}} 11:47:28.632 DEBU minclient/pki:gateway1: Fetching PKI doc for epoch 1860834 from Provider. 11:47:28.632 DEBU minclient/conn:gateway1: Enqueued GetConsensus command for send. 11:47:28.632 DEBU minclient/conn:gateway1: Dequeued GetConsesus for send. 11:47:28.632 DEBU minclient/conn:gateway1: Sent GetConsensus. 11:47:28.633 DEBU minclient/conn:gateway1: Received Consensus: ErrorCode: 0, Payload 8895 bytes 11:47:28.633 DEBU minclient/pki:gateway1: Discarding PKI for epoch: 1860832 11:48:06.136 DEBU gateway1_client: onDocument(): &{Epoch: 1860834 GenesisEpoch: 1860827 SendRatePerMinute: 100 Mu: 0.005 MuMaxDelay: 1000 LambdaP:0.001 LambdaPMaxDelay:1000 LambdaL:0.0005 LambdaLMaxDelay:1000 LambdaD:0.0005 LambdaDMaxDelay:3000 LambdaM: 0.0005 LambdaMMaxDelay: 100 SharedRandomValue: bOv3AMLIqrMj1D5I8VkATXJ5FjrEvKz9So186pimpH4= PriorSharedRandom: [P2gJ0eR+mvz1w4jmzMOzR+5YVCEXEVZuTqOaNKGt0ZM=, P2gJ0eR+mvz1w4jmzMOzR+5YVCEXEVZuTqOaNKGt0ZM=] Topology: [0]{[{mix1 c0cc7f87d7404fd2acf76c54b82a9a072be8b639c95eb7aae92138d322e3fc72 map[tcp4:[127.0.0.1:30008]]}]} [1]{[{mix2 004acc666996025ffd3b422a969c2725464ccd11e568cf68225045d6108e8339 map[tcp4:[127.0.0.1:30010]]}]} [2]{[{mix3 f6c8a0d7c201a56456dd81c22dafe5d95dfe71bc9ab0a711b4277223b32c279e map[tcp4:[127.0.0.1:30012]]}]} } GatewayNodes:[]{[{gateway1 b285e6db1f2f76e2c4f1ebd300fa6d9808fd262ea788021d1a6b029f89239109 map[tcp:[localhost:30004] tcp4:[127.0.0.1:30004]]tofu}]}}} } ServiceNodes:[]{[{servicenode1 b278f06ca7d8c5865b27471398ec0a5d4a3250925c47595dd40c93393bb2ede2 map[tcp4:[127.0.0.1:30006]]map[echo:map[endpoint:+echo] http_proxy:map[endpoint:http_proxy]]}]}}} 11:49:28.643 DEBU minclient/pki:gateway1: Fetching PKI doc for epoch 1860835 from Provider. 11:49:28.643 DEBU minclient/conn:gateway1: Enqueued GetConsensus command for send. 11:49:28.643 DEBU minclient/conn:gateway1: Dequeued GetConsesus for send. 11:49:28.644 DEBU minclient/conn:gateway1: Sent GetConsensus. 11:49:28.644 DEBU minclient/conn:gateway1: Received Consensus: ErrorCode: 0, Payload 8895 bytes 11:49:28.644 DEBU minclient/pki:gateway1: Discarding PKI for epoch: 1860833 11:50:06.148 DEBU gateway1_client: onDocument(): &{Epoch: 1860835 GenesisEpoch: 1860827 SendRatePerMinute: 100 Mu: 0.005 MuMaxDelay: 1000 LambdaP:0.001 LambdaPMaxDelay:1000 LambdaL:0.0005 LambdaLMaxDelay:1000 LambdaD:0.0005 LambdaDMaxDelay:3000 LambdaM: 0.0005 LambdaMMaxDelay: 100 SharedRandomValue: 9k4z35+yyfehJe3manV6zIFJ2Kngn+xaKa4cnnqEb2o= PriorSharedRandom: [P2gJ0eR+mvz1w4jmzMOzR+5YVCEXEVZuTqOaNKGt0ZM=, P2gJ0eR+mvz1w4jmzMOzR+5YVCEXEVZuTqOaNKGt0ZM=] Topology: [0]{[{mix1 c0cc7f87d7404fd2acf76c54b82a9a072be8b639c95eb7aae92138d322e3fc72 map[tcp4:[127.0.0.1:30008]]}]} [1]{[{mix2 004acc666996025ffd3b422a969c2725464ccd11e568cf68225045d6108e8339 map[tcp4:[127.0.0.1:30010]]}]} [2]{[{mix3 f6c8a0d7c201a56456dd81c22dafe5d95dfe71bc9ab0a711b4277223b32c279e map[tcp4:[127.0.0.1:30012]]}]} } GatewayNodes:[]{[{gateway1 b285e6db1f2f76e2c4f1ebd300fa6d9808fd262ea788021d1a6b029f89239109 map[tcp:[localhost:30004] tcp4:[127.0.0.1:30004]]tofu}]}}} } ServiceNodes:[]{[{servicenode1 b278f06ca7d8c5865b27471398ec0a5d4a3250925c47595dd40c93393bb2ede2 map[tcp4:[127.0.0.1:30006]]map[echo:map[endpoint:+echo] http_proxy:map[endpoint:http_proxy]]}]}}} 11:51:28.654 DEBU minclient/pki:gateway1: Fetching PKI doc for epoch 1860836 from Provider. 11:51:28.654 DEBU minclient/conn:gateway1: Enqueued GetConsensus command for send. 11:51:28.655 DEBU minclient/conn:gateway1: Dequeued GetConsesus for send. 11:51:28.655 DEBU minclient/conn:gateway1: Sent GetConsensus. 11:51:28.655 DEBU minclient/conn:gateway1: Received Consensus: ErrorCode: 0, Payload 8895 bytes 11:51:28.656 DEBU minclient/pki:gateway1: Discarding PKI for epoch: 1860834 11:52:06.160 DEBU gateway1_client: onDocument(): &{Epoch: 1860836 GenesisEpoch: 1860827 SendRatePerMinute: 100 Mu: 0.005 MuMaxDelay: 1000 LambdaP:0.001 LambdaPMaxDelay:1000 LambdaL:0.0005 LambdaLMaxDelay:1000 LambdaD:0.0005 LambdaDMaxDelay:3000 LambdaM: 0.0005 LambdaMMaxDelay: 100 SharedRandomValue: 936OE+gNaEczHgemkSml+kJFtu+gQHjdPwfTjlNGSs8= PriorSharedRandom: [P2gJ0eR+mvz1w4jmzMOzR+5YVCEXEVZuTqOaNKGt0ZM=, P2gJ0eR+mvz1w4jmzMOzR+5YVCEXEVZuTqOaNKGt0ZM=] Topology: [0]{[{mix1 c0cc7f87d7404fd2acf76c54b82a9a072be8b639c95eb7aae92138d322e3fc72 map[tcp4:[127.0.0.1:30008]]}]} [1]{[{mix2 004acc666996025ffd3b422a969c2725464ccd11e568cf68225045d6108e8339 map[tcp4:[127.0.0.1:30010]]}]} [2]{[{mix3 f6c8a0d7c201a56456dd81c22dafe5d95dfe71bc9ab0a711b4277223b32c279e map[tcp4:[127.0.0.1:30012]]}]} } GatewayNodes:[]{[{gateway1 b285e6db1f2f76e2c4f1ebd300fa6d9808fd262ea788021d1a6b029f89239109 map[tcp:[localhost:30004] tcp4:[127.0.0.1:30004]]tofu}]}}} } ServiceNodes:[]{[{servicenode1 b278f06ca7d8c5865b27471398ec0a5d4a3250925c47595dd40c93393bb2ede2 map[tcp4:[127.0.0.1:30006]]map[echo:map[endpoint:+echo] http_proxy:map[endpoint:http_proxy]]}]}}} 11:53:28.571 DEBU gateway1_client: Running garbage collection process. 11:53:28.668 DEBU minclient/pki:gateway1: Fetching PKI doc for epoch 1860837 from Provider. 11:53:28.668 DEBU minclient/conn:gateway1: Enqueued GetConsensus command for send. 11:53:28.668 DEBU minclient/conn:gateway1: Dequeued GetConsesus for send. 11:53:28.668 DEBU minclient/conn:gateway1: Sent GetConsensus. 11:53:28.668 DEBU minclient/conn:gateway1: Received Consensus: ErrorCode: 0, Payload 8895 bytes 11:53:28.669 DEBU minclient/pki:gateway1: Discarding PKI for epoch: 1860835 11:54:06.172 DEBU gateway1_client: onDocument(): &{Epoch: 1860837 GenesisEpoch: 1860827 SendRatePerMinute: 100 Mu: 0.005 MuMaxDelay: 1000 LambdaP:0.001 LambdaPMaxDelay:1000 LambdaL:0.0005 LambdaLMaxDelay:1000 LambdaD:0.0005 LambdaDMaxDelay:3000 LambdaM: 0.0005 LambdaMMaxDelay: 100 SharedRandomValue: 3crUw7OVnMcBWr3mT9fRIiasa5VNcMp2kpOCzDTCgf0= PriorSharedRandom: [P2gJ0eR+mvz1w4jmzMOzR+5YVCEXEVZuTqOaNKGt0ZM=, P2gJ0eR+mvz1w4jmzMOzR+5YVCEXEVZuTqOaNKGt0ZM=] Topology: [0]{[{mix1 c0cc7f87d7404fd2acf76c54b82a9a072be8b639c95eb7aae92138d322e3fc72 map[tcp4:[127.0.0.1:30008]]}]} [1]{[{mix2 004acc666996025ffd3b422a969c2725464ccd11e568cf68225045d6108e8339 map[tcp4:[127.0.0.1:30010]]}]} [2]{[{mix3 f6c8a0d7c201a56456dd81c22dafe5d95dfe71bc9ab0a711b4277223b32c279e map[tcp4:[127.0.0.1:30012]]}]} } GatewayNodes:[]{[{gateway1 b285e6db1f2f76e2c4f1ebd300fa6d9808fd262ea788021d1a6b029f89239109 map[tcp:[localhost:30004] tcp4:[127.0.0.1:30004]]tofu}]}}} } ServiceNodes:[]{[{servicenode1 b278f06ca7d8c5865b27471398ec0a5d4a3250925c47595dd40c93393bb2ede2 map[tcp4:[127.0.0.1:30006]]map[echo:map[endpoint:+echo] http_proxy:map[endpoint:http_proxy]]}]}}} 11:55:28.679 DEBU minclient/pki:gateway1: Fetching PKI doc for epoch 1860838 from Provider. 11:55:28.680 DEBU minclient/conn:gateway1: Enqueued GetConsensus command for send. 11:55:28.680 DEBU minclient/conn:gateway1: Dequeued GetConsesus for send. 11:55:28.680 DEBU minclient/conn:gateway1: Sent GetConsensus. 11:55:28.680 DEBU minclient/conn:gateway1: Received Consensus: ErrorCode: 0, Payload 8895 bytes 11:55:28.681 DEBU minclient/pki:gateway1: Discarding PKI for epoch: 1860836 11:56:06.184 DEBU gateway1_client: onDocument(): &{Epoch: 1860838 GenesisEpoch: 1860827 SendRatePerMinute: 100 Mu: 0.005 MuMaxDelay: 1000 LambdaP:0.001 LambdaPMaxDelay:1000 LambdaL:0.0005 LambdaLMaxDelay:1000 LambdaD:0.0005 LambdaDMaxDelay:3000 LambdaM: 0.0005 LambdaMMaxDelay: 100 SharedRandomValue: 9Yf//WpoH7Lkk4NKrE3YEYLY09h7zv/hRjgcHu1LWTQ= PriorSharedRandom: [P2gJ0eR+mvz1w4jmzMOzR+5YVCEXEVZuTqOaNKGt0ZM=, P2gJ0eR+mvz1w4jmzMOzR+5YVCEXEVZuTqOaNKGt0ZM=] Topology: [0]{[{mix1 c0cc7f87d7404fd2acf76c54b82a9a072be8b639c95eb7aae92138d322e3fc72 map[tcp4:[127.0.0.1:30008]]}]} [1]{[{mix2 004acc666996025ffd3b422a969c2725464ccd11e568cf68225045d6108e8339 map[tcp4:[127.0.0.1:30010]]}]} [2]{[{mix3 f6c8a0d7c201a56456dd81c22dafe5d95dfe71bc9ab0a711b4277223b32c279e map[tcp4:[127.0.0.1:30012]]}]} } GatewayNodes:[]{[{gateway1 b285e6db1f2f76e2c4f1ebd300fa6d9808fd262ea788021d1a6b029f89239109 map[tcp:[localhost:30004] tcp4:[127.0.0.1:30004]]tofu}]}}} } ServiceNodes:[]{[{servicenode1 b278f06ca7d8c5865b27471398ec0a5d4a3250925c47595dd40c93393bb2ede2 map[tcp4:[127.0.0.1:30006]]map[echo:map[endpoint:+echo] http_proxy:map[endpoint:http_proxy]]}]}}} 11:57:28.691 DEBU minclient/pki:gateway1: Fetching PKI doc for epoch 1860839 from Provider. 11:57:28.691 DEBU minclient/conn:gateway1: Enqueued GetConsensus command for send. 11:57:28.691 DEBU minclient/conn:gateway1: Dequeued GetConsesus for send. 11:57:28.692 DEBU minclient/conn:gateway1: Sent GetConsensus. 11:57:28.692 DEBU minclient/conn:gateway1: Received Consensus: ErrorCode: 0, Payload 8895 bytes 11:57:28.692 DEBU minclient/pki:gateway1: Discarding PKI for epoch: 1860837 11:58:06.197 DEBU gateway1_client: onDocument(): &{Epoch: 1860839 GenesisEpoch: 1860827 SendRatePerMinute: 100 Mu: 0.005 MuMaxDelay: 1000 LambdaP:0.001 LambdaPMaxDelay:1000 LambdaL:0.0005 LambdaLMaxDelay:1000 LambdaD:0.0005 LambdaDMaxDelay:3000 LambdaM: 0.0005 LambdaMMaxDelay: 100 SharedRandomValue: k6dfyRQwE5dzUcRKfn4DiagaZl6MhSwJYbobf4WPXiE= PriorSharedRandom: [P2gJ0eR+mvz1w4jmzMOzR+5YVCEXEVZuTqOaNKGt0ZM=, P2gJ0eR+mvz1w4jmzMOzR+5YVCEXEVZuTqOaNKGt0ZM=] Topology: [0]{[{mix1 c0cc7f87d7404fd2acf76c54b82a9a072be8b639c95eb7aae92138d322e3fc72 map[tcp4:[127.0.0.1:30008]]}]} [1]{[{mix2 004acc666996025ffd3b422a969c2725464ccd11e568cf68225045d6108e8339 map[tcp4:[127.0.0.1:30010]]}]} [2]{[{mix3 f6c8a0d7c201a56456dd81c22dafe5d95dfe71bc9ab0a711b4277223b32c279e map[tcp4:[127.0.0.1:30012]]}]} } GatewayNodes:[]{[{gateway1 b285e6db1f2f76e2c4f1ebd300fa6d9808fd262ea788021d1a6b029f89239109 map[tcp:[localhost:30004] tcp4:[127.0.0.1:30004]]tofu}]}}} } ServiceNodes:[]{[{servicenode1 b278f06ca7d8c5865b27471398ec0a5d4a3250925c47595dd40c93393bb2ede2 map[tcp4:[127.0.0.1:30006]]map[echo:map[endpoint:+echo] http_proxy:map[endpoint:http_proxy]]}]}}} 11:59:28.704 DEBU minclient/pki:gateway1: Fetching PKI doc for epoch 1860840 from Provider. 11:59:28.704 DEBU minclient/conn:gateway1: Enqueued GetConsensus command for send. 11:59:28.704 DEBU minclient/conn:gateway1: Dequeued GetConsesus for send. 11:59:28.704 DEBU minclient/conn:gateway1: Sent GetConsensus. 11:59:28.704 DEBU minclient/conn:gateway1: Received Consensus: ErrorCode: 0, Payload 8895 bytes 11:59:28.705 DEBU minclient/pki:gateway1: Discarding PKI for epoch: 1860838 12:00:06.207 DEBU gateway1_client: onDocument(): &{Epoch: 1860840 GenesisEpoch: 1860827 SendRatePerMinute: 100 Mu: 0.005 MuMaxDelay: 1000 LambdaP:0.001 LambdaPMaxDelay:1000 LambdaL:0.0005 LambdaLMaxDelay:1000 LambdaD:0.0005 LambdaDMaxDelay:3000 LambdaM: 0.0005 LambdaMMaxDelay: 100 SharedRandomValue: 2w/4ubNfko4nU2z4FDDBy7NcDVCMppr6JZB9TbuUJ1Y= PriorSharedRandom: [P2gJ0eR+mvz1w4jmzMOzR+5YVCEXEVZuTqOaNKGt0ZM=, P2gJ0eR+mvz1w4jmzMOzR+5YVCEXEVZuTqOaNKGt0ZM=] Topology: [0]{[{mix1 c0cc7f87d7404fd2acf76c54b82a9a072be8b639c95eb7aae92138d322e3fc72 map[tcp4:[127.0.0.1:30008]]}]} [1]{[{mix2 004acc666996025ffd3b422a969c2725464ccd11e568cf68225045d6108e8339 map[tcp4:[127.0.0.1:30010]]}]} [2]{[{mix3 f6c8a0d7c201a56456dd81c22dafe5d95dfe71bc9ab0a711b4277223b32c279e map[tcp4:[127.0.0.1:30012]]}]} } GatewayNodes:[]{[{gateway1 b285e6db1f2f76e2c4f1ebd300fa6d9808fd262ea788021d1a6b029f89239109 map[tcp:[localhost:30004] tcp4:[127.0.0.1:30004]]tofu}]}}} } ServiceNodes:[]{[{servicenode1 b278f06ca7d8c5865b27471398ec0a5d4a3250925c47595dd40c93393bb2ede2 map[tcp4:[127.0.0.1:30006]]map[echo:map[endpoint:+echo] http_proxy:map[endpoint:http_proxy]]}]}}} 12:01:28.713 DEBU minclient/pki:gateway1: Fetching PKI doc for epoch 1860841 from Provider. 12:01:28.713 DEBU minclient/conn:gateway1: Enqueued GetConsensus command for send. 12:01:28.713 DEBU minclient/conn:gateway1: Dequeued GetConsesus for send. 12:01:28.713 DEBU minclient/conn:gateway1: Sent GetConsensus. 12:01:28.714 DEBU minclient/conn:gateway1: Received Consensus: ErrorCode: 0, Payload 8895 bytes 12:01:28.714 DEBU minclient/pki:gateway1: Discarding PKI for epoch: 1860839 12:02:06.218 DEBU gateway1_client: onDocument(): &{Epoch: 1860841 GenesisEpoch: 1860827 SendRatePerMinute: 100 Mu: 0.005 MuMaxDelay: 1000 LambdaP:0.001 LambdaPMaxDelay:1000 LambdaL:0.0005 LambdaLMaxDelay:1000 LambdaD:0.0005 LambdaDMaxDelay:3000 LambdaM: 0.0005 LambdaMMaxDelay: 100 SharedRandomValue: QzrHyqCB0lbJZNlqVfR5FKJI93D0ZMeWd8F9mB56BU8= PriorSharedRandom: [P2gJ0eR+mvz1w4jmzMOzR+5YVCEXEVZuTqOaNKGt0ZM=, P2gJ0eR+mvz1w4jmzMOzR+5YVCEXEVZuTqOaNKGt0ZM=] Topology: [0]{[{mix1 c0cc7f87d7404fd2acf76c54b82a9a072be8b639c95eb7aae92138d322e3fc72 map[tcp4:[127.0.0.1:30008]]}]} [1]{[{mix2 004acc666996025ffd3b422a969c2725464ccd11e568cf68225045d6108e8339 map[tcp4:[127.0.0.1:30010]]}]} [2]{[{mix3 f6c8a0d7c201a56456dd81c22dafe5d95dfe71bc9ab0a711b4277223b32c279e map[tcp4:[127.0.0.1:30012]]}]} } GatewayNodes:[]{[{gateway1 b285e6db1f2f76e2c4f1ebd300fa6d9808fd262ea788021d1a6b029f89239109 map[tcp:[localhost:30004] tcp4:[127.0.0.1:30004]]tofu}]}}} } ServiceNodes:[]{[{servicenode1 b278f06ca7d8c5865b27471398ec0a5d4a3250925c47595dd40c93393bb2ede2 map[tcp4:[127.0.0.1:30006]]map[echo:map[endpoint:+echo] http_proxy:map[endpoint:http_proxy]]}]}}} 12:03:28.571 DEBU gateway1_client: Running garbage collection process. 12:03:28.725 DEBU minclient/pki:gateway1: Fetching PKI doc for epoch 1860842 from Provider. 12:03:28.725 DEBU minclient/conn:gateway1: Enqueued GetConsensus command for send. 12:03:28.725 DEBU minclient/conn:gateway1: Dequeued GetConsesus for send. 12:03:28.726 DEBU minclient/conn:gateway1: Sent GetConsensus. 12:03:28.726 DEBU minclient/conn:gateway1: Received Consensus: ErrorCode: 0, Payload 8895 bytes 12:03:28.727 DEBU minclient/pki:gateway1: Discarding PKI for epoch: 1860840 12:04:06.229 DEBU gateway1_client: onDocument(): &{Epoch: 1860842 GenesisEpoch: 1860827 SendRatePerMinute: 100 Mu: 0.005 MuMaxDelay: 1000 LambdaP:0.001 LambdaPMaxDelay:1000 LambdaL:0.0005 LambdaLMaxDelay:1000 LambdaD:0.0005 LambdaDMaxDelay:3000 LambdaM: 0.0005 LambdaMMaxDelay: 100 SharedRandomValue: PFdeGMsWgKODN4blPJU54cksmiiFPEgTifbMYa9JuLQ= PriorSharedRandom: [P2gJ0eR+mvz1w4jmzMOzR+5YVCEXEVZuTqOaNKGt0ZM=, P2gJ0eR+mvz1w4jmzMOzR+5YVCEXEVZuTqOaNKGt0ZM=] Topology: [0]{[{mix1 c0cc7f87d7404fd2acf76c54b82a9a072be8b639c95eb7aae92138d322e3fc72 map[tcp4:[127.0.0.1:30008]]}]} [1]{[{mix2 004acc666996025ffd3b422a969c2725464ccd11e568cf68225045d6108e8339 map[tcp4:[127.0.0.1:30010]]}]} [2]{[{mix3 f6c8a0d7c201a56456dd81c22dafe5d95dfe71bc9ab0a711b4277223b32c279e map[tcp4:[127.0.0.1:30012]]}]} } GatewayNodes:[]{[{gateway1 b285e6db1f2f76e2c4f1ebd300fa6d9808fd262ea788021d1a6b029f89239109 map[tcp:[localhost:30004] tcp4:[127.0.0.1:30004]]tofu}]}}} } ServiceNodes:[]{[{servicenode1 b278f06ca7d8c5865b27471398ec0a5d4a3250925c47595dd40c93393bb2ede2 map[tcp4:[127.0.0.1:30006]]map[echo:map[endpoint:+echo] http_proxy:map[endpoint:http_proxy]]}]}}} ``` <\details>
xendarboh commented 2 months ago

From those logs, looks like decoy traffic was not enabled ("sending loop decoy" not present). So, maybe the issue is related to decoy traffic being enabled.

Can you repeat the experiment with decoy traffic enabled?

with DisableDecoyTraffic manually set to false in docker/voting_mixnet/client/client.toml

amitbasuri commented 2 months ago

I ran with Disabling Decoy traffic, still didn't get any error wallet.log

xendarboh commented 2 months ago

ok, great -- the wallet.log illustrates you've recreated the issue. The log shows that sending loop decoy stops (after around 8 minutes of run time) when it should continue. If, after that point, you sent walletshield a request, you would see that it does not send a response. There is no error (message), as the issue declares, the client freezes. Only restarting it can recover.

The issue has been confirmed to be present only with DisableDecoyTraffic = false.

The issue is not intermittent, it occurs every time.

The source of the issue could be within the Katzenpost client code used by walletshield.

amitbasuri commented 2 months ago

@xendarboh then maybe its a deadlock situation, WDYT?

david415 commented 2 months ago

@xendarboh then maybe its a deadlock situation, WDYT?

Yes of course it's a deadlock... that's the whole point of this ticket and I'm sorry we didn't spell that out explicitly for you in the beginning... any software bug where software stops working after 10 minutes and then appears to do nothing is most likely a deadlock or partial deadlock.

xendarboh commented 2 months ago

recording a note: this task deferred for now as we pursue use of katzenpost client2 as the more future-forward solution

xendarboh commented 3 weeks ago

closed in favor of client2 #35