Latency test can fail in a weird way High level transaction error: The transaction's signature is invalid

[dpc]

If you run nix build -L .#cli-test.latency it will sometimes fail with:

fedimint-cli-test-latency> RESULT complete                                                                                                                                                  
fedimint-cli-test-latency> LN RECEIVE 2                                                                                                                                                     
fedimint-cli-test-latency> mint 0: 2023-02-17T18:40:17.590617Z ERROR jsonrpsee_server::transport::ws: WS transport error: i/o error: Transport endpoint is not connected (os error 107); ter
minate connection: 41                                                                                                                                                                       
fedimint-cli-test-latency> mint 2: 2023-02-17T18:40:17.590617Z ERROR jsonrpsee_server::transport::ws: WS transport error: i/o error: Transport endpoint is not connected (os error 107); ter
minate connection: 42                                                                                                                                                                       
fedimint-cli-test-latency> mint 3: 2023-02-17T18:40:17.591157Z ERROR jsonrpsee_server::transport::ws: WS transport error: i/o error: Transport endpoint is not connected (os error 107); ter
minate connection: 42                                                                                                                                                                       
fedimint-cli-test-latency> mint 1: 2023-02-17T18:40:17.590693Z ERROR jsonrpsee_server::transport::ws: WS transport error: i/o error: Transport endpoint is not connected (os error 107); ter
minate connection: 43                                                                                                                                                                       
fedimint-cli-test-latency> 2023-02-17T18:40:18.403Z INFO    plugin-ln_gateway: buy_preimage_internal; payment_hash=a98c1a039fd546fd38ee838135f16ba913c319a93f93e5ca042cf7dd8cb7f89e invoice_
amount=Amount { msats: 50000000 }                                                                                                                                                           
fedimint-cli-test-latency> 2023-02-17T18:40:18.404Z INFO    plugin-ln_gateway: buy_preimage_internal                                                                                        
fedimint-cli-test-latency> 2023-02-17T18:40:18.613Z INFO    plugin-ln_gateway: Client::buy_preimage_offer; payment_hash=a98c1a039fd546fd38ee838135f16ba913c319a93f93e5ca042cf7dd8cb7f89e htl
c_amount=Amount { msats: 50000000 }                                                                                                                                                         
fedimint-cli-test-latency> 2023-02-17T18:40:18.613Z INFO    plugin-ln_gateway: buy_preimage_offer                                                                                           
fedimint-cli-test-latency> 2023-02-17T18:40:19.612Z INFO    plugin-ln_gateway: return=(OutPoint { txid: fd31998e81062cab83eabd2347da900c81017a7bca482eae9f760768e63bf916, out_idx: 0 }, a98c
1a039fd546fd38ee838135f16ba913c319a93f93e5ca042cf7dd8cb7f89e)                                                                                                                               
fedimint-cli-test-latency> 2023-02-17T18:40:19.613Z INFO    plugin-ln_gateway: buy_preimage_internal_await_decryption; out_point=OutPoint { txid: fd31998e81062cab83eabd2347da900c81017a7bca
482eae9f760768e63bf916, out_idx: 0 } contract_id=a98c1a039fd546fd38ee838135f16ba913c319a93f93e5ca042cf7dd8cb7f89e                                                                           
fedimint-cli-test-latency> 2023-02-17T18:40:19.613Z INFO    plugin-ln_gateway: Awaiting decryption of preimage                                                                              
fedimint-cli-test-latency> 2023-02-17T18:40:20.628Z UNUSUAL plugin-ln_gateway: Failed to decrypt preimage. Now requesting a refund error=Output outcome error: Core error: Pending preimage 
decryption                                                                                                                                                                                  
fedimint-cli-test-latency> 2023-02-17T18:40:20.629Z INFO    plugin-ln_gateway: Client::refund_incoming_contract; contract_id=a98c1a039fd546fd38ee838135f16ba913c319a93f93e5ca042cf7dd8cb7f89
e                                                                                                                                                                                           
fedimint-cli-test-latency> 2023-02-17T18:40:21.080Z **BROKEN** plugin-ln_gateway: error=Federation client operation error: MintApiError(FederationError({PeerId(0): Rpc(Call(Custom(ErrorObj
ect { code: ServerError(400), message: \"High level transaction error: The transaction's signature is invalid\", data: None }))), PeerId(1): Rpc(Call(Custom(ErrorObject { code: ServerError
(400), message: \"High level transaction error: The transaction's signature is invalid\", data: None })))}))                                                                                
fedimint-cli-test-latency> 2023-02-17T18:40:21.792Z INFO    02de9e41421b873fd2112835faa8a383ba3d9b86accfaebe68fc15b3015b640338-chan#1: htlc 1 failed from 0th node with code 0x1639 (INVALID
 5689)                                                                                                

The problem seems timing / load triggered. Seems like making things slower (run cargo build --release in the meantime or something) makes it more likely to happen.

[dpc]

@okjodom We've chatted about this on Discord, so just letting you know.

[justinmoon]

I saw this once before on a live federation when many clients were connected at the same time. So it does seem related to load ...

[elsirion]

We need to log the transaction somewhere if this happens so we have a chance at debugging this. I just took a stab at doing so in the client but we don't have all the pub keys there since LN inputs don't contain their pub key again. So server side it is probably (just dump the whole hex tx, should make sure it's not cut short by @dpc's recent fixes to make logs more readable 😆).

[justinmoon]

@dpc We can close this?

[dpc]

I wasn't able to reproduce and haven't seen it for a while now, so let's close.

[elsirion]

Do you remember the PR where you could repro it quite often @dpc? Would be good to document and get back to. We don't understand what caused it and that worries me.

[dpc]

@elsirion I don't know the exact PR, but I'm quite sure it was happening in the invoice refund code-path.

My theory is that because LN gateway was erroneously considering a successful LN payment as failed, it was creating an invalid refund tx, which fedimintd rejected with confusing error.

@okjodom

[dpc]

If I'm correct, then it possibly it might be worthwhile to check in fedimintd if a tx isn't trying to refund a valid tx, just to return a better error?

[justinmoon]

Do you remember the PR where you could repro it quite often @dpc? Would be good to document and get back to. We don't understand what caused it and that worries me.

@maan2003 could reproduce it consistently on #1197

[dpc]

Any PR before #1798 will do.

Some kind of a artificial sleep delaying epochs generating contract decryption shares will make the gateway hit it reliably. The load / slower machine made the problem happen more often, as it's all about gateway racing federation.

[justinmoon]

Just saw this again https://github.com/fedimint/fedimint/actions/runs/4417915746/jobs/7744300013#step:10:4981