diff --git a/.gitignore b/.gitignore index b4f362ea..af2489b7 100644 --- a/.gitignore +++ b/.gitignore @@ -34,3 +34,4 @@ metadata.json examples/javascript/node_modules examples/javascript/response.bin examples/javascript/package-lock.json +\#* diff --git a/libs/gl-client/src/lib.rs b/libs/gl-client/src/lib.rs index 08655d86..e17c825c 100644 --- a/libs/gl-client/src/lib.rs +++ b/libs/gl-client/src/lib.rs @@ -61,6 +61,9 @@ use thiserror::Error; pub enum Error { #[error("The signature request does not match any authorized RPC calls")] MissingAuthorization, + + #[error("Illegal argument: {0}")] + IllegalArgument(String), } pub use lightning_signer::bitcoin; diff --git a/libs/gl-client/src/signer/auth.rs b/libs/gl-client/src/signer/auth.rs index 6ef17e4a..04af2c69 100644 --- a/libs/gl-client/src/signer/auth.rs +++ b/libs/gl-client/src/signer/auth.rs @@ -19,16 +19,24 @@ impl Authorizer for GreenlightAuthorizer { &self, requests: &Vec, ) -> Result, Error> { - let approvals : Vec<_> = requests.iter().flat_map(|request| { + let mut approvals = Vec::new(); + for request in requests.iter() { match request { Request::Pay(req) => { - // TODO error handling - Some(Approval::Invoice(Invoice::from_str(&req.bolt11) - .expect(""))) + match Invoice::from_str(&req.bolt11) { + Ok(invoice) => { + approvals.push(Approval::Invoice(invoice)); + } + Err(e) => { + return Err(crate::Error::IllegalArgument( + format!("Failed to parse invoice from Pay request: {:?}", e) + )); + } + } } - _ => None, + _ => {} } - }).collect(); + } Ok(approvals) } } diff --git a/libs/gl-client/src/signer/mod.rs b/libs/gl-client/src/signer/mod.rs index 8533db57..4eb77e2e 100644 --- a/libs/gl-client/src/signer/mod.rs +++ b/libs/gl-client/src/signer/mod.rs @@ -195,7 +195,9 @@ impl Signer { // we need for the rest of the run. let init = Signer::initmsg(&mut handler)?; - let init = HsmdInitReplyV4::from_vec(init).unwrap(); + let init = HsmdInitReplyV4::from_vec(init).map_err(|e| { + anyhow!("Failed to parse init message as HsmdInitReplyV4: {:?}", e) + })?; let id = init.node_id.0.to_vec(); use vls_protocol::msgs::SerBolt; @@ -235,7 +237,7 @@ impl Signer { fn handler(&self) -> Result { let mut h = self.init_handler()?; h.handle(Signer::initreq()) - .expect("handling the hsmd_init message"); + .map_err(|e| anyhow!("Failed to handle hsmd_init message: {:?}", e))?; Ok(h.into()) } @@ -253,7 +255,7 @@ impl Signer { .build() .map_err(|e| crate::signer::Error::Other(anyhow!("Could not create handler: {:?}", e)))?; h.handle(Signer::initreq()) - .expect("handling the hsmd_init message"); + .map_err(|e| Error::Other(anyhow!("Failed to handle hsmd_init message: {:?}", e)))?; Ok(h.into()) } @@ -276,12 +278,10 @@ impl Signer { } fn initmsg(handler: &mut vls_protocol_signer::handler::InitHandler) -> Result, Error> { - Ok(handler + let (_req, response) = handler .handle(Signer::initreq()) - .unwrap() - .1 - .map(|a| a.as_vec()) - .unwrap_or_default()) + .map_err(|e| Error::Other(anyhow!("Failed to handle init request: {:?}", e)))?; + Ok(response.map(|a| a.as_vec()).unwrap_or_default()) } /// Filter out any request that is not signed, such that the @@ -409,7 +409,7 @@ impl Signer { .await? .into_inner(); - debug!("Starting to stream signer requests"); + info!("Starting to stream signer requests"); loop { let req = match stream .message() @@ -427,7 +427,7 @@ impl Signer { let signer_state = req.signer_state.clone(); trace!("Received request {}", hex_req); - match self.process_request(req).await { + match self.process_request(req.clone()).await { Ok(response) => { trace!("Sending response {}", hex::encode(&response.raw)); client @@ -436,6 +436,17 @@ impl Signer { .map_err(|e| Error::NodeDisconnect(e))?; } Err(e) => { + // Report the rejection to the server for debugging + // Note: process_request already reports some errors, but we ensure + // all errors are reported here as a safety net + report::Reporter::report(crate::pb::scheduler::SignerRejection { + msg: format!("Error in run_once loop: {:?}", e), + request: Some(req.clone()), + git_version: GITHASH.to_string(), + node_id: self.node_id(), + }) + .await; + let response = HsmResponse { raw: vec![], request_id, @@ -447,8 +458,8 @@ impl Signer { .await .map_err(|e| Error::NodeDisconnect(e))?; warn!( - "Ignoring error {} for request {} with state {:?}", - e, hex_req, signer_state, + "Rejected request {} with error: {}. State: {:?}", + hex_req, e, signer_state, ) } }; @@ -478,8 +489,12 @@ impl Signer { let prestate = { debug!("Updating local signer state with state from node"); - let mut state = self.state.lock().unwrap(); - state.merge(&diff).unwrap(); + let mut state = self.state.lock().map_err(|e| { + Error::Other(anyhow!("Failed to acquire state lock: {:?}", e)) + })?; + state.merge(&diff).map_err(|e| { + Error::Other(anyhow!("Failed to merge signer state: {:?}", e)) + })?; trace!("Processing request {}", hex::encode(&req.raw)); state.clone() }; @@ -512,7 +527,10 @@ impl Signer { let msg = vls_protocol::msgs::from_vec(req.raw.clone()).map_err(|e| Error::Protocol(e))?; log::debug!("Handling message {:?}", msg); - log::trace!("Signer state {}", serde_json::to_string(&prestate).unwrap()); + log::trace!( + "Signer state {}", + serde_json::to_string(&prestate).unwrap_or_else(|_| "".to_string()) + ); if let Err(e) = self.authenticate_request(&msg, &ctxrequests) { report::Reporter::report(crate::pb::scheduler::SignerRejection { @@ -560,8 +578,17 @@ impl Signer { let root_handler = self.handler_with_approver(approver)?; log::trace!("Updating state from context"); - update_state_from_context(&ctxrequests, &root_handler) - .expect("Updating state from context requests"); + if let Err(e) = update_state_from_context(&ctxrequests, &root_handler) { + error!("Failed to update state from context: {:?}", e); + report::Reporter::report(crate::pb::scheduler::SignerRejection { + msg: format!("Failed to update state from context: {:?}", e), + request: Some(req.clone()), + git_version: GITHASH.to_string(), + node_id: self.node_id(), + }) + .await; + return Err(Error::Other(anyhow!("Failed to update state from context: {:?}", e))); + } log::trace!("State updated"); // Match over root and client handler. @@ -571,7 +598,10 @@ impl Signer { root_handler.handle(msg) } Some(c) => { - let pk: [u8; 33] = c.node_id.try_into().unwrap(); + let node_id_len = c.node_id.len(); + let pk: [u8; 33] = c.node_id.try_into().map_err(|_| { + Error::Other(anyhow!("Invalid node_id length in context: expected 33 bytes, got {}", node_id_len)) + })?; let pk = vls_protocol::model::PubKey(pk); root_handler .for_new_client(1 as u64, pk, c.dbid) @@ -579,21 +609,25 @@ impl Signer { } }; - if let Err(e) = response { - report::Reporter::report(crate::pb::scheduler::SignerRejection { - msg: format!("{:?}", e), - request: Some(req.clone()), - git_version: GITHASH.to_string(), - node_id: self.node_id(), - }) - .await; - return Err(Error::Other(anyhow!("processing request: {e:?}"))); - } + let response = match response { + Ok(r) => r, + Err(e) => { + report::Reporter::report(crate::pb::scheduler::SignerRejection { + msg: format!("{:?}", e), + request: Some(req.clone()), + git_version: GITHASH.to_string(), + node_id: self.node_id(), + }) + .await; + return Err(Error::Other(anyhow!("processing request: {e:?}"))); + } + }; - let response = response.unwrap(); let signer_state: Vec = { debug!("Serializing state changes to report to node"); - let state = self.state.lock().unwrap(); + let state = self.state.lock().map_err(|e| { + Error::Other(anyhow!("Failed to acquire state lock for serialization: {:?}", e)) + })?; state.clone().into() }; Ok(HsmResponse { @@ -678,18 +712,30 @@ impl Signer { pub fn bip32_ext_key(&self) -> Vec { use vls_protocol::{msgs, msgs::Message}; - let initmsg = msgs::from_vec(self.init.clone()).expect("unparseable init message"); + // This should never fail since we validated it during construction + let initmsg = msgs::from_vec(self.init.clone()) + .expect("init message should be valid (validated during Signer::new)"); match initmsg { Message::HsmdInit2Reply(m) => m.bip32.0.to_vec(), Message::HsmdInitReplyV4(m) => m.bip32.0.to_vec(), Message::HsmdInitReplyV2(m) => m.bip32.0.to_vec(), - m => panic!("Unknown initmsg {:?}, cannot extract bip32 key", m), + m => { + // This should never happen, but log and return empty instead of panicking + error!("Unknown initmsg type {:?}, cannot extract bip32 key", m); + vec![] + } } } pub fn legacy_bip32_ext_key(&self) -> Vec { - let mut handler = self.init_handler().expect("retrieving the handler"); + let mut handler = match self.init_handler() { + Ok(h) => h, + Err(e) => { + error!("Failed to retrieve handler for legacy bip32 key: {:?}", e); + return vec![]; + } + }; let req = vls_protocol::msgs::Message::HsmdInit(vls_protocol::msgs::HsmdInit { key_version: vls_protocol::model::Bip32KeyVersion { pubkey_version: 0, @@ -705,13 +751,18 @@ impl Signer { hsm_wire_max_version: 2, }); - let initmsg = handler - .handle(req) - .expect("handling legacy init message") - .1 - .map(|a| a.as_vec()) - .unwrap_or_default(); + let initmsg = match handler.handle(req) { + Ok((_req, response)) => response.map(|a| a.as_vec()).unwrap_or_default(), + Err(e) => { + error!("Failed to handle legacy init message: {:?}", e); + return vec![]; + } + }; + if initmsg.len() <= 35 { + error!("Legacy init message too short: expected >35 bytes, got {}", initmsg.len()); + return vec![]; + } initmsg[35..].to_vec() } @@ -746,6 +797,8 @@ impl Signer { // Upgrade node if necessary. // If it fails due to connection error, sleep and retry. Re-throw all other errors. loop { + let call_start = tokio::time::Instant::now(); + debug!("Sending maybe_upgrade to {}", self.version()); #[allow(deprecated)] let res = scheduler .maybe_upgrade(UpgradeRequest { @@ -758,6 +811,11 @@ impl Signer { .collect(), }) .await; + debug!( + "Server returned {:?} after {}s", + res, + call_start.elapsed().as_secs() + ); match res { Err(e) => match e.code() { @@ -785,7 +843,7 @@ impl Signer { mut scheduler: SchedulerClient, ) -> Result<(), anyhow::Error> { loop { - debug!("Calling scheduler.get_node_info"); + info!("Calling scheduler.get_node_info"); let node_info_res = scheduler .get_node_info(NodeInfoRequest { node_id: self.id.clone(), @@ -801,7 +859,7 @@ impl Signer { let node_info = match node_info_res.map(|v| v.into_inner()) { Ok(v) => { - debug!("Got node_info from scheduler: {:?}", v); + info!("Got node_info from scheduler: {:?}", v); v } Err(e) => { @@ -1141,7 +1199,11 @@ fn update_state_from_context( requests .iter() - .for_each(|r| update_state_from_request(r, &node).unwrap()); + .for_each(|r| { + if let Err(e) = update_state_from_request(r, &node) { + log::warn!("Failed to update state from request: {:?}", e); + } + }); Ok(()) } @@ -1155,13 +1217,21 @@ fn update_state_from_request( model::Request::SendPay(model::cln::SendpayRequest { bolt11: Some(inv), .. }) => { - let invoice = Invoice::from_str(inv).unwrap(); - log::debug!( - "Adding invoice {:?} as side-effect of this sendpay {:?}", - invoice, - request - ); - node.add_invoice(invoice).unwrap(); + match Invoice::from_str(inv) { + Ok(invoice) => { + log::debug!( + "Adding invoice {:?} as side-effect of this sendpay {:?}", + invoice, + request + ); + if let Err(e) = node.add_invoice(invoice) { + log::warn!("Failed to add invoice to node state: {:?}", e); + } + } + Err(e) => { + log::warn!("Failed to parse invoice from sendpay request: {:?}", e); + } + } } _ => {} }