Problem:(CRO-661) not enough logging in debug enclave execution

chain-tx-enclave/tx-validation/app/src/enclave_u/mod.rs

@@ -96,10 +96,21 @@ pub fn encrypt_tx(
         let response = IntraEnclaveResponse::decode(&mut response_buf.as_slice());
         match response {
             Ok(Ok(IntraEnclaveResponseOk::Encrypt(obftx))) => Ok(obftx),
-            Ok(Err(e)) => Err(e),
-            _ => Err(Error::EnclaveRejected),
+            Ok(Ok(_)) => {
+                log::error!("encrypt unsupported tx");
+                Err(Error::EnclaveRejected)
+            },
+            Ok(Err(e)) => {
+                log::error!("encrypt tx error: {:?}", e);
+                Err(Error::EnclaveRejected)
+            },
+            Err(e) => {
+                log::error!("encrypt tx response failed: {:?}", e);
+                Err(Error::EnclaveRejected)
+            }
         }
     } else {
+        log::error!("sgx status error: retval: {:?}, ecall result: {:?}", retval, result);
         Err(Error::EnclaveRejected)
     }
 }
@@ -136,7 +147,10 @@ pub fn check_tx(
             ) => {
                 let _ = txdb
                     .insert(&request.tx.tx_id(), sealed_tx)
-                    .map_err(|_| Error::IoError)?;
+                    .map_err(|e| {
+                        log::error!("insert tx id to db failed: {:?}", e);
+                        Error::IoError
+                    })?;
                 if let Some(mut account) = request.account {
                     account.withdraw();
                     Ok((paid_fee, Some(account)))
@@ -175,10 +189,17 @@ pub fn check_tx(
                 let fee = request.info.min_fee_computed;
                 Ok((fee, account))
             }
-            (_, Ok(Err(e))) => Err(e),
-            (_, _) => Err(Error::EnclaveRejected),
+            (_, Ok(Err(e))) => {
+                log::error!("get error response: {:?}", e);
+                Err(e)
+            },
+            (_req, _resp) => {
+                log::error!("unsupported or error response");
+                Err(Error::EnclaveRejected)
+            },
         }
     } else {
+        log::error!("sgx status error: retval: {:?}, ecall result: {:?}", retval, result);
         Err(Error::EnclaveRejected)
     }
 }

chain-tx-enclave/tx-validation/app/src/server/mod.rs

@@ -7,7 +7,6 @@ use enclave_protocol::IntraEnclaveRequest;
 use enclave_protocol::{
     is_basic_valid_tx_request, EnclaveRequest, EnclaveResponse, IntraEncryptRequest, FLAGS,
 };
-use log::{debug, info};
 use parity_scale_codec::{Decode, Encode};
 use sgx_urts::SgxEnclave;
 use sled::Tree;
@@ -32,7 +31,10 @@ impl TxValidationServer {
         metadb: Tree,
     ) -> Result<TxValidationServer, Error> {
         match metadb.get(LAST_CHAIN_INFO_KEY) {
-            Err(_) => Err(Error::EFAULT),
+            Err(e) => {
+                log::error!("get last chain info failed: {:?}", e);
+                Err(Error::EFAULT)
+            },
             Ok(s) => {
                 let info = s.map(|stored| {
                     ChainInfo::decode(&mut stored.as_ref()).expect("stored chain info corrupted")
@@ -86,19 +88,22 @@ impl TxValidationServer {
     }
 
     pub fn execute(&mut self) {
-        info!("running zmq server");
+        log::info!("running zmq server");
         loop {
             if let Ok(msg) = self.socket.recv_bytes(FLAGS) {
-                debug!("received a message");
+                log::debug!("received a message");
                 let mcmd = EnclaveRequest::decode(&mut msg.as_slice());
                 let resp = match mcmd {
                     Ok(EnclaveRequest::CheckChain {
                         chain_hex_id,
                         last_app_hash,
                     }) => {
-                        debug!("check chain");
+                        log::debug!("check chain");
                         match self.metadb.get(LAST_APP_HASH_KEY) {
-                            Err(_) => EnclaveResponse::CheckChain(Err(None)),
+                            Err(e) => {
+                                log::error!("get last app hash failed: {:?}", e);
+                                EnclaveResponse::CheckChain(Err(None))
+                            },
                             Ok(s) => {
                                 let ss = s.map(|stored| {
                                     let mut app_hash = [0u8; 32];
@@ -112,6 +117,7 @@ impl TxValidationServer {
                                         ss,
                                     ))
                                 } else {
+                                    log::error!("app hash not match");
                                     EnclaveResponse::CheckChain(Err(ss))
                                 }
                             }
@@ -128,14 +134,16 @@ impl TxValidationServer {
                             self.info = Some(info);
                             EnclaveResponse::CommitBlock(Ok(()))
                         } else {
+                            log::error!("flush data failed when commit block");
                             EnclaveResponse::CommitBlock(Err(()))
                         }
                     }
                     Ok(EnclaveRequest::VerifyTx(req)) => {
                         let chid = req.info.chain_hex_id;
                         let mtxins = self.lookup(&req.tx);
-                        if is_basic_valid_tx_request(&req, &mtxins, chid).is_err() {
-                            EnclaveResponse::UnknownRequest
+                        if let Err(e) = is_basic_valid_tx_request(&req, &mtxins, chid) {
+                            log::error!("verify transaction failed: {:?}", e);
+                                EnclaveResponse::UnknownRequest
                         } else {
                             EnclaveResponse::VerifyTx(check_tx(
                                 self.enclave.geteid(),
@@ -170,12 +178,15 @@ impl TxValidationServer {
                                     IntraEnclaveRequest::Encrypt(Box::new(request)),
                                 )
                             }
-                            _ => Err(chain_tx_validation::Error::EnclaveRejected),
+                            _ => {
+                                log::error!("can not find encrypted transaction");
+                                Err(chain_tx_validation::Error::EnclaveRejected)
+                            },
                         };
                         EnclaveResponse::EncryptTx(result)
                     }
                     Err(e) => {
-                        debug!("unknown request / failed to decode: {}", e);
+                        log::error!("unknown request / failed to decode: {}", e);
                         EnclaveResponse::UnknownRequest
                     }
                 };

chain-tx-enclave/tx-validation/enclave/Cargo.toml

@@ -33,4 +33,5 @@ lazy_static  = { version = "1.4", features = ["spin_no_std"] }
 enclave-t-common = { path = "../../enclave-t-common" }
 aes-gcm-siv = "0.3"
 aead = "0.2"
+log = "0.4.8"
 zeroize = { version = "1.0", default-features = false }

chain-tx-enclave/tx-validation/enclave/src/lib.rs

@@ -25,6 +25,7 @@ pub extern "C" fn ecall_initchain(chain_hex_id: u8) -> sgx_status_t {
     if chain_hex_id == NETWORK_HEX_ID {
         sgx_status_t::SGX_SUCCESS
     } else {
+        log::error!("network hex id not match");
         sgx_status_t::SGX_ERROR_INVALID_PARAMETER
     }
 }
@@ -45,7 +46,12 @@ pub extern "C" fn ecall_check_tx(
         Ok(IntraEnclaveRequest::Encrypt(request)) => {
             obfuscate::handle_encrypt_request(request, response_buf, response_len)
         }
-        _ => {
+        Ok(s) => {
+            log::error!("unsupported request");
+            return sgx_status_t::SGX_ERROR_INVALID_PARAMETER;
+        }
+        Err(e) => {
+            log::error!("ecall check tx failed: {:?}", e);
             return sgx_status_t::SGX_ERROR_INVALID_PARAMETER;
         }
     }

chain-tx-enclave/tx-validation/enclave/src/obfuscate.rs

@@ -123,7 +123,8 @@ fn unseal_request(request: &mut IntraEncryptRequest) -> Option<EncryptionRequest
     let result = sealed_data.unseal_data();
     let mut unsealed_data = match result {
         Ok(x) => x,
-        Err(_) => {
+        Err(e) => {
+            log::error!("unsal data failed: {:?}", e);
             return None;
         }
     };
@@ -134,7 +135,10 @@ fn unseal_request(request: &mut IntraEncryptRequest) -> Option<EncryptionRequest
     let otx = EncryptionRequest::decode(&mut unsealed_data.get_decrypt_txt());
     match otx {
         Ok(o) => Some(o),
-        Err(_) => None,
+        Err(e) => {
+            log::error!("decode encryption request failed: {:?}", e);
+            None
+        },
     }
 }
 

chain-tx-enclave/tx-validation/enclave/src/validate.rs

@@ -68,12 +68,16 @@ fn construct_sealed_response(
 ) -> Result<IntraEnclaveResponse, sgx_status_t> {
     let to_seal = to_seal_tx.encode();
     match result {
-        Err(e) => Ok(Err(e)),
+        Err(e) => {
+            log::error!("encode tx witoutputs failed: {:?}", e);
+            Ok(Err(e))
+        },
         Ok(fee) => {
             let sealing_result = SgxSealedData::<[u8]>::seal_data(txid, &to_seal);
             let sealed_data = match sealing_result {
                 Ok(x) => x,
                 Err(ret) => {
+                    log::error!("sgx failed to seal data: {:?}", ret);
                     return Err(ret);
                 }
             };
@@ -89,6 +93,7 @@ fn construct_sealed_response(
                     sealed_log_size as u32,
                 );
                 if sealed_r.is_none() {
+                    log::error!("decode sealed data to raw failed");
                     return Err(sgx_status_t::SGX_ERROR_INVALID_PARAMETER);
                 }
             }
@@ -128,6 +133,7 @@ pub(crate) fn write_back_response(
                 }
                 sgx_status_t::SGX_SUCCESS
             } else {
+                log::error!("response length exceeds the limit");
                 sgx_status_t::SGX_ERROR_INVALID_PARAMETER
             }
         }
@@ -148,7 +154,8 @@ pub(crate) fn handle_validate_tx(
     response_buf: *mut u8,
     response_len: u32,
 ) -> sgx_status_t {
-    if is_basic_valid_tx_request(&request, &tx_inputs, crate::NETWORK_HEX_ID).is_err() {
+    if let Err(e) = is_basic_valid_tx_request(&request, &tx_inputs, crate::NETWORK_HEX_ID) {
+        log::error!("check request failed: {}", e);
         return sgx_status_t::SGX_ERROR_INVALID_PARAMETER;
     }
     match (tx_inputs, request.tx) {
@@ -166,6 +173,7 @@ pub(crate) fn handle_validate_tx(
             match (plaintx, unsealed_inputs) {
                 (Ok(PlainTxAux::TransferTx(tx, witness)), Some(inputs)) => {
                     if tx.id() != payload.txid || tx.outputs.len() as TxoIndex != no_of_outputs {
+                        log::error!("input invalid txid or outputs index not match!");
                         return sgx_status_t::SGX_ERROR_INVALID_PARAMETER;
                     }
                     let result = verify_transfer(&tx, &witness, request.info, inputs);
@@ -177,6 +185,7 @@ pub(crate) fn handle_validate_tx(
                     write_back_response(response, response_buf, response_len)
                 }
                 _ => {
+                    log::error!("can not find plain transfer transaction or unsealed inputs");
                     return sgx_status_t::SGX_ERROR_INVALID_PARAMETER;
                 }
             }
@@ -191,6 +200,7 @@ pub(crate) fn handle_validate_tx(
                     write_back_response(response, response_buf, response_len)
                 }
                 _ => {
+                    log::error!("can not get plain deposit stake transaction or unsealed inputs");
                     return sgx_status_t::SGX_ERROR_INVALID_PARAMETER;
                 }
             }
@@ -204,7 +214,8 @@ pub(crate) fn handle_validate_tx(
             },
         ) => {
             let address = verify_tx_recover_address(&witness, &payload.txid);
-            if address.is_err() {
+            if let Err(e) = address {
+                log::error!("get recover address failed: {:?}", e);
                 return sgx_status_t::SGX_ERROR_INVALID_PARAMETER;
             }
             let plaintx = decrypt(&payload);
@@ -225,11 +236,13 @@ pub(crate) fn handle_validate_tx(
                     write_back_response(response, response_buf, response_len)
                 }
                 _ => {
+                    log::error!("invalid parameter");
                     return sgx_status_t::SGX_ERROR_INVALID_PARAMETER;
                 }
             }
         }
         (_, _) => {
+            log::error!("invalid parameter");
             return sgx_status_t::SGX_ERROR_INVALID_PARAMETER;
         }
     }

enclave-protocol/src/lib.rs

@@ -68,24 +68,28 @@ pub fn is_basic_valid_tx_request(
     request: &VerifyTxRequest,
     tx_inputs: &Option<Vec<SealedLog>>,
     chain_hex_id: u8,
-) -> Result<(), ()> {
+) -> Result<(), std::string::String> {
     if request.info.chain_hex_id != chain_hex_id {
-        return Err(());
+        return Err("hex id mismatch".into());
     }
     match request.tx {
         TxEnclaveAux::DepositStakeTx { .. } => match tx_inputs {
             Some(ref i) if !i.is_empty() => Ok(()),
-            _ => Err(()),
+            _ => {
+                Err("sealed log is empty".into())
+            },
         },
         TxEnclaveAux::TransferTx { .. } => match tx_inputs {
             Some(ref i) if !i.is_empty() => Ok(()),
-            _ => Err(()),
+            _ => {
+                Err("sealed log is empty".into())
+            },
         },
         TxEnclaveAux::WithdrawUnbondedStakeTx { .. } => {
             if request.account.is_some() {
                 Ok(())
             } else {
-                Err(())
+                Err("request account is empty".into())
             }
         }
     }