search

stakwork / sphinx-key

Lightning hardware signer on ESP32
28 stars 1 forks source link

`client switched` and `SENDING TO` don't always agree #130

Closed irriden closed 9 months ago

irriden commented 10 months ago

In the logs below, we switch to client 7a19 but then still send to 6edb. Maybe that's expected, I will have to double check, but writing this down here.

2023-09-22T00:58:02.295 hsmd  /lss_connector::broker INFO] MSG TO SIGNER: Stored(BrokerMutations { server_hmac: Some([58, 114, 9, 156, 83, 107, 127, 202, 164, 84, 72, 248, 240, 40, 206, 156, 126, 174, 255, 243, 111, 253, 152, 236, 17, 88, 214, 225, 187, 226, 247, 77]), muts: [] })
[2023-09-22T00:58:02.295 hsmd  /sphinx_key_broker::handle INFO] LSS REPLY LEN 61
[2023-09-22T00:58:02.295 hsmd  /sphinx_key_broker::handle INFO] SEND ON lss-msg
[2023-09-22T00:58:02.295 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 6edb9d322098987132548aa64a1d78fb on topic lss-msg
[2023-09-22T00:58:06.296 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 6edb9d322098987132548aa64a1d78fb on topic lss-msg
[2023-09-22T00:58:10.296 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 6edb9d322098987132548aa64a1d78fb on topic lss-msg
[2023-09-22T00:58:14.296 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 6edb9d322098987132548aa64a1d78fb on topic lss-msg
[2023-09-22T00:58:18.297 hsmd  /sphinx_key_broker::handle WARN] no reply from signer...
[2023-09-22T00:58:18.297 hsmd  /sphinx_key_broker::handle WARN] error handle_message_inner, trying again... Eof
[2023-09-22T00:58:18.297 hsmd  /sphinx_key_broker::conn INFO] => client switched to 7a19c73d7f39d8c1b766fefa682c61b6
[2023-09-22T00:58:18.302 hsmd  /sphinx_key_broker::handle INFO] SEND ON vls
[2023-09-22T00:58:18.302 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 6edb9d322098987132548aa64a1d78fb on topic vls
[2023-09-22T00:58:18.394 hsmd  /sphinx_key_broker::conn WARN] current client and synced returns Some("7a19c73d7f39d8c1b766fefa682c61b6"), true
[2023-09-22T00:58:22.303 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 6edb9d322098987132548aa64a1d78fb on topic vls
[2023-09-22T00:58:26.303 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 6edb9d322098987132548aa64a1d78fb on topic vls
[2023-09-22T00:58:30.304 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 6edb9d322098987132548aa64a1d78fb on topic vls
2023-09-22T00:58:32.007Z UNUSUAL 0260452a05af8ba367e05032cca3622f47a1cd984658f89932e8ad5d7fab076595-channeld-chan#1: Adding HTLC 430 too slow: killing connection
2023-09-22T00:58:32.008Z INFO    0260452a05af8ba367e05032cca3622f47a1cd984658f89932e8ad5d7fab076595-chan#1: Peer transient failure in CHANNELD_NORMAL: channeld: Owning subdaemon channeld died (9)
[2023-09-22T00:58:32.028 hsmd  /sphinx_key_broker::looper INFO] loop 121730/30: got SignChannelUpdate(SignChannelUpdate { update: 0102184f66d2fd2546ae8ec3a426481e6722e5dde6abeda0d9bc629ab97cfda5866901ce2082827e6e21a15ae77a689a81dbe93a6422be612524c2ec0b85755d0e0e06226e46111a0b59caaf126043eb5bbf28c34f3a5e332a1fc7b2b73cf188910f0000700000010000650ce6b9010300060000000000000000000000010000000a00000001270b0180 })
[2023-09-22T00:58:32.028 hsmd  /sphinx_key_broker::conn WARN] current client and synced returns Some("7a19c73d7f39d8c1b766fefa682c61b6"), true
[2023-09-22T00:58:33.431 hsmd  /sphinx_key_broker::looper INFO] loop 121730/29: got Ecdh(Ecdh { point: 030cc966498c989e43633650d83ec9f608372c28fadb43013613ef1913fb28bef5 })
[2023-09-22T00:58:33.432 hsmd  /sphinx_key_broker::conn WARN] current client and synced returns Some("7a19c73d7f39d8c1b766fefa682c61b6"), true
[2023-09-22T00:58:34.304 hsmd  /sphinx_key_broker::handle WARN] no reply from signer...
[2023-09-22T00:58:34.304 hsmd  /sphinx_key_broker::handle WARN] error handle_message_inner, trying again... Eof
[2023-09-22T00:58:34.305 hsmd  /sphinx_key_broker::conn INFO] => client switched to 7a19c73d7f39d8c1b766fefa682c61b6
[2023-09-22T00:58:34.362 hsmd  /sphinx_key_broker::handle INFO] SEND ON vls
[2023-09-22T00:58:34.362 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 7a19c73d7f39d8c1b766fefa682c61b6 on topic vls
[2023-09-22T00:58:34.401 hsmd  /sphinx_key_broker::conn WARN] current client and synced returns Some("7a19c73d7f39d8c1b766fefa682c61b6"), true
irriden commented 10 months ago

One more example, with a little more context:

[2023-09-22T01:02:34.166 hsmd  /lss_connector::broker INFO] MSG TO SIGNER: Stored(BrokerMutations { server_hmac: Some([62, 44, 99, 60, 66, 53, 15, 180, 99, 24
2, 132, 228, 108, 141, 26, 25, 63, 65, 139, 168, 18, 140, 201, 226, 39, 174, 108, 149, 218, 130, 81, 51]), muts: [] })                                        
[2023-09-22T01:02:34.166 hsmd  /sphinx_key_broker::handle INFO] LSS REPLY LEN 61                                                                              
[2023-09-22T01:02:34.166 hsmd  /sphinx_key_broker::handle INFO] SEND ON lss-msg                                                                               
[2023-09-22T01:02:34.166 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 6edb9d322098987132548aa64a1d78fb on topic lss-msg                                    
[2023-09-22T01:02:38.167 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 6edb9d322098987132548aa64a1d78fb on topic lss-msg                                    
[2023-09-22T01:02:42.167 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 6edb9d322098987132548aa64a1d78fb on topic lss-msg                                    
[2023-09-22T01:02:46.168 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 6edb9d322098987132548aa64a1d78fb on topic lss-msg                                    
[2023-09-22T01:02:50.168 hsmd  /sphinx_key_broker::handle WARN] no reply from signer...                                                                       
[2023-09-22T01:02:50.169 hsmd  /sphinx_key_broker::handle WARN] error handle_message_inner, trying again... Eof                                               
[2023-09-22T01:02:50.169 hsmd  /sphinx_key_broker::conn INFO] => client switched to 7a19c73d7f39d8c1b766fefa682c61b6                                          
[2023-09-22T01:02:50.192 hsmd  /sphinx_key_broker::handle INFO] SEND ON vls                                                                                   
[2023-09-22T01:02:50.193 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 6edb9d322098987132548aa64a1d78fb on topic vls                                        
[2023-09-22T01:02:50.265 hsmd  /sphinx_key_broker::conn WARN] current client and synced returns Some("7a19c73d7f39d8c1b766fefa682c61b6"), true                
[2023-09-22T01:02:54.193 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 6edb9d322098987132548aa64a1d78fb on topic vls                                        
[2023-09-22T01:02:58.193 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 6edb9d322098987132548aa64a1d78fb on topic vls                                        
[2023-09-22T01:03:02.194 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 6edb9d322098987132548aa64a1d78fb on topic vls                                        
[2023-09-22T01:03:06.194 hsmd  /sphinx_key_broker::handle WARN] no reply from signer...                                                                       
[2023-09-22T01:03:06.195 hsmd  /sphinx_key_broker::handle WARN] error handle_message_inner, trying again... Eof                                               
[2023-09-22T01:03:06.195 hsmd  /sphinx_key_broker::conn INFO] => client switched to 7a19c73d7f39d8c1b766fefa682c61b6                                          
[2023-09-22T01:03:06.233 hsmd  /sphinx_key_broker::handle INFO] SEND ON vls                                                                                   
[2023-09-22T01:03:06.234 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 7a19c73d7f39d8c1b766fefa682c61b6 on topic vls                                        
[2023-09-22T01:03:06.291 hsmd  /sphinx_key_broker::conn WARN] current client and synced returns Some("7a19c73d7f39d8c1b766fefa682c61b6"), true                
[2023-09-22T01:03:10.234 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 7a19c73d7f39d8c1b766fefa682c61b6 on topic vls                                        
[2023-09-22T01:03:14.235 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 7a19c73d7f39d8c1b766fefa682c61b6 on topic vls                                        
[2023-09-22T01:03:14.380 hsmd  /rumqttd::server::broker ERROR] Disconnected!! error=Network(Io(Os { code: 104, kind: ConnectionReset, message: "Connection res
et by peer" }))                                                                                                                                               
[2023-09-22T01:03:15.383 hsmd  /rumqttd::server::broker ERROR] remote_link; tenant_id=None                                                                    
[2023-09-22T01:03:17.150 hsmd  /sphinx_key_broker INFO] => connection status: 7a19c73d7f39d8c1b766fefa682c61b6: true                                          
[2023-09-22T01:03:17.150 hsmd  /sphinx_key_broker::lss INFO] CLIENT 7a19c73d7f39d8c1b766fefa682c61b6 connected!                                               
[2023-09-22T01:03:17.154 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 7a19c73d7f39d8c1b766fefa682c61b6 on topic init-1-msg                                 
[2023-09-22T01:03:18.055 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 7a19c73d7f39d8c1b766fefa682c61b6 on topic init-2-msg                                 
[2023-09-22T01:03:18.235 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 7a19c73d7f39d8c1b766fefa682c61b6 on topic vls                                        
[2023-09-22T01:03:19.786 hsmd  /sphinx_key_broker INFO] adding client to the list? true                                                                       
[2023-09-22T01:03:20.355 hsmd  /sphinx_key_broker::handle INFO] GOT ON lss-res                                                                                
[2023-09-22T01:03:20.356 hsmd  /lss_connector::broker INFO] HANDLE LSS VlsMuts(SignerMutations { client_hmac: [169, 64, 151, 72, 90, 2, 204, 95, 64, 218, 55,
irriden commented 9 months ago

Fixed in 80a23cb5f07bebc29e9bd0195423020f223a3a40

irriden commented 9 months ago

The key was to take a ticket, then when it's the thread's turn to handle_message, call current_client_and_synced.