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

chain-tx-enclave/tx-query/enclave/src/attest.rs

@@ -169,7 +169,7 @@ fn parse_response_attn_report(resp: &[u8]) -> Result<AttnReport, RAError> {
                     attn_report = str::from_utf8(resp_body)
                         .map_err(|_| RAError::ParseError)?
                         .to_string();
-                    // println!("Attestation report: {}", attn_report);
+                    println!("Attestation report: {}", attn_report);
                 }
             }
             "X-IASReport-Signature" => {
@@ -259,8 +259,8 @@ fn get_sigrl_from_intel(ias_key: &str, fd: c_int, gid: u32) -> Result<Vec<u8>, R
 
     match tls.read_to_end(&mut plaintext) {
         Ok(_) => (),
-        Err(_) => {
-            // println!("get_sigrl_from_intel tls.read_to_end: {:?}", e);
+        Err(e) => {
+            println!("get_sigrl_from_intel tls.read_to_end: {:?}", e);
             return Err(RAError::CommunicationError);
         }
     }
@@ -296,7 +296,10 @@ fn get_report_from_intel(ias_key: &str, fd: c_int, quote: Vec<u8>) -> Result<Att
     // println!("write complete");
 
     tls.read_to_end(&mut plaintext)
-        .map_err(|_| RAError::CommunicationError)?;
+        .map_err(|e| {
+            println!("get report from intel failed to read: {:?}", e);
+            RAError::CommunicationError
+        })?;
     // println!("read_to_end complete");
     parse_response_attn_report(&plaintext)
 }
@@ -366,14 +369,14 @@ fn create_attestation_report(
                 sigrl_acquired = true;
                 break;
             }
-            Err(_) => {
-                //println!("get sirl failed, retry...");
+            Err(e) => {
+                println!("get sirl failed: {:?}, retry...", e);
             }
         }
     }
 
     if !sigrl_acquired {
-        // println!("Cannot acquire sigrl from Intel for three times");
+        println!("Cannot acquire sigrl from Intel for three times");
         return Err(sgx_status_t::SGX_ERROR_UNEXPECTED);
     }
 
@@ -393,7 +396,7 @@ fn create_attestation_report(
             Some(r)
         }
         Err(e) => {
-            // println!("Report creation => failed {:?}", e);
+            println!("Report creation => failed {:?}", e);
             return Err(e);
         }
     };
@@ -461,7 +464,7 @@ fn create_attestation_report(
             // println!("rsgx_verify_report passed!")
         }
         Err(x) => {
-            // println!("rsgx_verify_report failed with {:?}", x);
+            println!("rsgx_verify_report failed with {:?}", x);
             return Err(x);
         }
     }
@@ -471,7 +474,7 @@ fn create_attestation_report(
         || ti.attributes.flags != qe_report.body.attributes.flags
         || ti.attributes.xfrm != qe_report.body.attributes.xfrm
     {
-        // println!("qe_report does not match current target_info!");
+        println!("qe_report does not match current target_info!");
         return Err(sgx_status_t::SGX_ERROR_UNEXPECTED);
     }
 
@@ -501,7 +504,7 @@ fn create_attestation_report(
     // println!("report hs= {:02X}", lhs_hash.iter().format(""));
 
     if rhs_hash != lhs_hash {
-        // println!("Quote is tampered!");
+        println!("Quote is tampered!");
         return Err(sgx_status_t::SGX_ERROR_UNEXPECTED);
     }
 
@@ -655,9 +658,9 @@ pub(crate) fn get_tls_config() -> Arc<rustls::ServerConfig> {
                 //println!("SVRCONFIGCACHE invalidate all config cache!");
                 cfg_cache.clear();
             }
-            Err(_) => {
+            Err(e) => {
                 // Poisoned
-                // println!("SVRCONFIGCACHE invalidate cache failed {}!", x);
+                println!("SVRCONFIGCACHE invalidate cache failed {}!", e);
             }
         }
     }

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,8 @@ pub extern "C" fn ecall_check_tx(
         Ok(IntraEnclaveRequest::Encrypt(request)) => {
             obfuscate::handle_encrypt_request(request, response_buf, response_len)
         }
-        _ => {
+        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,15 @@ 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) => {
+            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 +92,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 +132,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 +153,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 +172,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 +184,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 +199,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 +213,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 +235,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;
         }
     }