Robustness: votes are disappearing between the backend and the DELA node

[PascalinDe]

I observed this behaviour also before testing dedis/dela#270 but as the number of missing votes were a lot smaller (like off-by-one or by 3) I thought nothing of it, but now it is more pronounced:

1. created form
2. cast 512 votes
3. only 410 are present in the interface (and the blockchain is at index 417, which I guess includes the form and some other things)

according to the logs:

a. in the backend/DELA nodes: 3 concurrency-related failures (#345)
b. in the backend: 509 PUT requests that got an 200 answer
c. DELA: no errors apart from the 3 concurrency failures

which means that 102 votes or roughly a fifth of the votes are unaccounted for - are there dedicated logs of the DELA proxies somewhere?

[PascalinDe]

just to make sure that it is not introduced/exacerbated by the changes introduced in dela#270, I ran some tests on the main branch as well, and there I get consistently an off-by-one (n votes submitted by the backend to the cluster according to the logs, n-1 registered)

so either it is a problem that gets worse the more votes are cast (I tried with 10, 20, 40, 80 and 2, 4, 8, 16, 32, 64 on a new chain and always got only an off-by-one) or it is a problem that gets exacerbated by dela#270

any ideas how the changes in dedis/dela#270 might have led to this behaviour (and how to address the off-by-one)?

[PascalinDe]

redid the 2, 4, 8, 16, 64, 128 on DELA with the fix, and 128 is the first one where a notable number of votes are missing 117/128, which is also when the 256 blocks threshold would have been passed (similar results for 256 and 512)

so I'm not sure whether this is just another symptom of dedis/dela#269 that's not addressed by dela/dedis#270 or if it is behaviour we are just not aware of because we couldn't test this yet

(I tested some 192 votes on the branch without the fix, and there got also only an off-by-one, so it's not > 100 that causes the problem)

[nkcr]

• You can set the log level for the proxy with PROXY_LOG=info (https://github.com/dedis/dela/blob/4bcfa7981c828b150f7de448a7457aff80e5736e/mino/proxy/http/mod.go#L32)
• Can you post the content of the logs ?

[PascalinDe]

set the proxy log level, so now I've got this (on a completely clean chain with only one election):

docker compose logs --no-color dela-worker-0 | ansi2txt | grep -E 'url=/evoting/forms/.+/vote' | wc -l
512
docker compose logs --no-color backend | grep -E 'POST /api/evoting/forms/.+/vote' | wc -l
512
docker compose logs --no-color backend | grep -E 'sending payload: .* to http://172.19.44.254:8080/evoting/forms/.+/vote' | wc -l
512

so 512 requests and their respective payloads have been send to the proxd, and 512 requests have arrived at the proxy

some examples (it is always the same vote, so the payload is the same)

backend:

d-voting-backend-1  | sending payload: {"Payload":"eyJCYWxsb3QiOlt7IksiOls1NCwxNTIsMzMsMTEsMjAxLDIzMywyMTIsMTU3LDIwNCwxNzYsMTM2LDEzOCw1NCwyMTMsMjM5LDE5OCw3OSw1NSw3MSwyNiw5MSwyNDQsOTgsMjE1LDIwOCwyMzksNDgsMjUzLDE5NSw1MywxOTIsOTRdLCJDIjpbMTA1LDEyMSw4NywxNjQsNjgsMjQyLDE2NiwxOTQsMjIyLDE3OSwyNTMsMjMxLDIxMyw2MywzNCw2NiwyMTIsNDEsMjE0LDE3NSwxNzgsODMsMjI5LDE1NiwyNTUsMzgsNTUsMjM0LDE2OCwyMjIsODEsMTg1XX1dLCJVc2VySUQiOiJ4c1JIRE9pNkUxIn0=","Signature":"84aad264ae74e5f91bcd834fb882c74c3c3c00ab251d733d8cd4c3617bde98a90956474464665ea3afba78dd813e9a18d1dde87de1f486fbc8937a51d833250f"} to http://172.19.44.254:8080/evoting/forms/9454b3a1d12deea8f21c144a4648b7b1659d4521ae552747da38ae3ed0cd1c33/vote
d-voting-backend-1  | POST /api/evoting/forms/9454b3a1d12deea8f21c144a4648b7b1659d4521ae552747da38ae3ed0cd1c33/vote 200 491 - 749.359 ms
d-voting-backend-1  | sending payload: {"Payload":"eyJCYWxsb3QiOlt7IksiOls1NCwxNTIsMzMsMTEsMjAxLDIzMywyMTIsMTU3LDIwNCwxNzYsMTM2LDEzOCw1NCwyMTMsMjM5LDE5OCw3OSw1NSw3MSwyNiw5MSwyNDQsOTgsMjE1LDIwOCwyMzksNDgsMjUzLDE5NSw1MywxOTIsOTRdLCJDIjpbMTA1LDEyMSw4NywxNjQsNjgsMjQyLDE2NiwxOTQsMjIyLDE3OSwyNTMsMjMxLDIxMyw2MywzNCw2NiwyMTIsNDEsMjE0LDE3NSwxNzgsODMsMjI5LDE1NiwyNTUsMzgsNTUsMjM0LDE2OCwyMjIsODEsMTg1XX1dLCJVc2VySUQiOiJQTnhFTGprSHhhIn0=","Signature":"6518c8addcfe0df7200a9f8de9590b2e11b0596c99344b770c6c710a0feaff385ef68e894a6c04f19ffbe9b0976d5a96d8a737763ee3f8c23ba2a3f37b3bb904"} to http://172.19.44.254:8080/evoting/forms/9454b3a1d12deea8f21c144a4648b7b1659d4521ae552747da38ae3ed0cd1c33/vote
d-voting-backend-1  | POST /api/evoting/forms/9454b3a1d12deea8f21c144a4648b7b1659d4521ae552747da38ae3ed0cd1c33/vote 200 491 - 1339.730 ms

dela-worker-0 (also leader if that's important):

d-voting-dela-worker-0-1  | 2023-09-08T09:05:11Z INF pkg/mod/go.dedis.ch/dela@v0.0.0-20230907131212-0d61b081b4af/mino/proxy/http/mod.go:160 >  agent=axios/0.24.0 method=POST remoteAddr=172.19.44.3:39142 requestID=1694163910441992079 role="http proxy" url=/evoting/forms/9454b3a1d12deea8f21c144a4648b7b1659d4521ae552747da38ae3ed0cd1c33/vote
d-voting-dela-worker-0-1  | 2023-09-08T09:05:12Z DBG pkg/mod/go.dedis.ch/dela@v0.0.0-20230907131212-0d61b081b4af/core/ordering/cosipbft/mod.go:560 > pbft has started addr=dela-worker-0:2000 index=408
d-voting-dela-worker-0-1  | 2023-09-08T09:05:12Z DBG pkg/mod/go.dedis.ch/dela@v0.0.0-20230907131212-0d61b081b4af/core/ordering/cosipbft/mod.go:592 > transactions have been found addr=dela-worker-0:2000 num=1
d-voting-dela-worker-0-1  | 2023-09-08T09:05:12Z DBG pkg/mod/go.dedis.ch/dela@v0.0.0-20230907131212-0d61b081b4af/core/ordering/cosipbft/mod.go:633 > prepare done addr=dela-worker-0:2000 signature=thres[11101]:bls:8aaff5bb669a2a7176d6052ccb1c9cfefd9c4e71fd6491504cf48c518064a33c68fdd16ec66289a961ab2bcfd7b4782b3da028c59281ee62b01768bf3db14bab
d-voting-dela-worker-0-1  | 2023-09-08T09:05:12Z DBG pkg/mod/go.dedis.ch/dela@v0.0.0-20230907131212-0d61b081b4af/core/ordering/cosipbft/mod.go:643 > commit done addr=dela-worker-0:2000 signature=thres[11011]:bls:5dbb8b2d0b8c5e738c3d1839136c71660a9553bde6f5cf4ef2607dec36fcf489869dfffd1fc62c3e6ef64d42decb36eba3053be9be74181a8e865760a91e3204
d-voting-dela-worker-0-1  | 2023-09-08T09:05:12Z INF pkg/mod/go.dedis.ch/dela@v0.0.0-20230907131212-0d61b081b4af/core/ordering/cosipbft/pbft/mod.go:390 > finalize round with leader: 0
d-voting-dela-worker-0-1  | 2023-09-08T09:05:12Z INF pkg/mod/go.dedis.ch/dela@v0.0.0-20230907131212-0d61b081b4af/core/ordering/cosipbft/mod.go:387 > block event addr=dela-worker-0:2000 index=408 root=9e77736a

error messages:

docker compose logs --no-color dela-worker-0 | grep "ERR"
d-voting-dela-worker-0-1  | 2023-09-08T08:47:48Z ERR pkg/mod/go.dedis.ch/dela@v0.0.0-20230907131212-0d61b081b4af/mino/minogrpc/rpc.go:227 > stream to root failed error=EOF
d-voting-dela-worker-0-1  | 2023-09-08T08:47:58Z ERR pkg/mod/go.dedis.ch/dela@v0.0.0-20230907131212-0d61b081b4af/mino/minogrpc/rpc.go:227 > stream to root failed error=EOF

but these have always been there, not sure if they are related

[PascalinDe]

and according to the frontend, 412 votes and the chain is at index 419 (so the 412 plus 1 for the election itself plus 1 per node?)

[ineiti]

(it is always the same vote, so the payload is the same)

I don't understand that. What is in the payload? If it is the transaction, then I think the vote is supposed to be encrypted asymmetrically, so even if it is the same vote, the message should change. Or what am I missing here?

[PascalinDe]

the data I'm sending is the already encrypted vote (since I took one POST request from the client that I keep resending to cast a vote), and that is encoded in base64, so the payload is always the same

the signature changes, since it's added by the backend

[ineiti]

already encrypted vote

There is something I don't understand, or another bug: usually with asymmetric cryptography, if you encrypt the same data twice, you get another byte-blob. If this weren't the case, then you could very easily verify what the person voted: you just encrypt the different possible outcomes and compare them to the data stored on the blockchain.

So either I don't understand it, or it's a bug :)

[PascalinDe]

I'll try to explain better, that was a bit confusing the way I put it before:

1. I cast a vote
2. the client encrypted it, and send the encrypted request in base64 encoding to the backend server
3. I copied said request, and use it to cast votes automatically

i.e. it's the same already encrypted request that gets send, and hence the base64 encoding is always the same, but the signature in the payload changes because that's added by the backend server

[ineiti]

Ah, that makes sense. -1 bugs :)