From 93baf42b8454395d280a80b15c759feea371bfc0 Mon Sep 17 00:00:00 2001 From: Heiko Schaefer Date: Tue, 22 Mar 2022 12:45:34 +0100 Subject: [PATCH] Re-organize log levels. - card operations are logged at "info" level - APDU command/response are logged at "debug" - other log output is at "trace" --- openpgp-card/src/apdu.rs | 30 ++++++++------ openpgp-card/src/card_do.rs | 10 ++--- openpgp-card/src/keys.rs | 6 +++ openpgp-card/src/lib.rs | 5 ++- openpgp-card/src/openpgp.rs | 82 +++++++++++++++++++++++++++++++++++++ pcsc/src/lib.rs | 56 ++++++++++++------------- scdc/src/lib.rs | 14 +++---- 7 files changed, 147 insertions(+), 56 deletions(-) diff --git a/openpgp-card/src/apdu.rs b/openpgp-card/src/apdu.rs index 88c2c90..e14c4f0 100644 --- a/openpgp-card/src/apdu.rs +++ b/openpgp-card/src/apdu.rs @@ -29,6 +29,8 @@ pub(crate) fn send_command( where C: CardTransaction + ?Sized, { + log::debug!(" -> full APDU command: {:x?}", cmd); + let mut resp = RawResponse::try_from(send_command_low_level( card_tx, cmd.clone(), @@ -45,7 +47,7 @@ where while let StatusBytes::OkBytesAvailable(bytes) = resp.status() { // More data is available for this command from the card - log::debug!(" chained response, getting more data"); + log::trace!(" chained response, getting more data"); // Get next chunk of data let next = RawResponse::try_from(send_command_low_level( @@ -56,7 +58,7 @@ where match next.status() { StatusBytes::OkBytesAvailable(_) | StatusBytes::Ok => { - log::debug!(" appending {} bytes to response", next.raw_data().len()); + log::trace!(" appending {} bytes to response", next.raw_data().len()); // Append new data to resp.data and overwrite status. resp.raw_mut_data().extend_from_slice(next.raw_data()); @@ -66,7 +68,11 @@ where } } - log::debug!(" final response len: {}", resp.raw_data().len()); + log::debug!( + " <- APDU response [len {}]: {:x?}", + resp.raw_data().len(), + resp + ); Ok(resp) } @@ -86,7 +92,7 @@ where { let (ext_support, chaining_support, mut max_cmd_bytes, max_rsp_bytes) = if let Some(caps) = card_tx.card_caps() { - log::debug!("found card caps data!"); + log::trace!("found card caps data!"); ( caps.ext_support, @@ -95,7 +101,7 @@ where caps.max_rsp_bytes as usize, ) } else { - log::debug!("found NO card caps data!"); + log::trace!("found NO card caps data!"); // default settings (false, false, 255, 255) @@ -110,7 +116,7 @@ where max_cmd_bytes = usize::min(max_cmd_bytes, max_card_cmd_bytes); } - log::debug!( + log::trace!( "ext le/lc {}, chaining {}, max cmd {}, max rsp {}", ext_support, chaining_support, @@ -128,8 +134,6 @@ where // key data from cards?) let ext_len = ext_support && (max_cmd_bytes > 0xFF); - log::debug!(" -> full APDU command: {:x?}", cmd); - let buf_size = if !ext_len { MAX_BUFFER_SIZE } else { @@ -141,7 +145,7 @@ where if chaining_support && !cmd.data().is_empty() { // Send command in chained mode - log::debug!("chained command mode"); + log::trace!("chained command mode"); // Break up payload into chunks that fit into one command, each let chunks: Vec<_> = cmd.data().chunks(max_cmd_bytes).collect(); @@ -154,11 +158,11 @@ where let serialized = partial.serialize(ext_len, expect_response)?; - log::debug!(" -> chained APDU command: {:x?}", &serialized); + log::trace!(" -> chained APDU command: {:x?}", &serialized); let resp = card_tx.transmit(&serialized, buf_size)?; - log::debug!(" <- APDU response: {:x?}", &resp); + log::trace!(" <- APDU response: {:x?}", &resp); if resp.len() < 2 { return Err(Error::ResponseLength(resp.len())); @@ -196,11 +200,11 @@ where return Err(Error::CommandTooLong(serialized.len())); } - log::debug!(" -> APDU command: {:x?}", &serialized); + log::trace!(" -> APDU command: {:x?}", &serialized); let resp = card_tx.transmit(&serialized, buf_size)?; - log::debug!(" <- APDU response: {:x?}", resp); + log::trace!(" <- APDU response: {:x?}", resp); Ok(resp) } diff --git a/openpgp-card/src/card_do.rs b/openpgp-card/src/card_do.rs index 668b268..503bb89 100644 --- a/openpgp-card/src/card_do.rs +++ b/openpgp-card/src/card_do.rs @@ -50,7 +50,7 @@ impl ApplicationRelatedData { let hist = self.0.find(&[0x5f, 0x52].into()); if let Some(hist) = hist { - log::debug!("Historical bytes: {:x?}", hist); + log::trace!("Historical bytes: {:x?}", hist); (hist.serialize().as_slice()).try_into() } else { Err(Error::NotFound( @@ -65,7 +65,7 @@ impl ApplicationRelatedData { // get from cached "application related data" let eli = self.0.find(&[0x7f, 0x66].into()); - log::debug!("Extended length information: {:x?}", eli); + log::trace!("Extended length information: {:x?}", eli); if let Some(eli) = eli { // The card has returned extended length information @@ -130,7 +130,7 @@ impl ApplicationRelatedData { if let Some(psb) = psb { let pws = (&psb.serialize()[..]).try_into()?; - log::debug!("PW Status: {:x?}", pws); + log::trace!("PW Status: {:x?}", pws); Ok(pws) } else { @@ -149,7 +149,7 @@ impl ApplicationRelatedData { if let Some(fp) = fp { let fp: KeySet = (&fp.serialize()[..]).try_into()?; - log::debug!("Fp: {:x?}", fp); + log::trace!("Fp: {:x?}", fp); Ok(fp) } else { @@ -164,7 +164,7 @@ impl ApplicationRelatedData { if let Some(kg) = kg { let kg: KeySet = (&kg.serialize()[..]).try_into()?; - log::debug!("Key generation: {:x?}", kg); + log::trace!("Key generation: {:x?}", kg); Ok(kg) } else { diff --git a/openpgp-card/src/keys.rs b/openpgp-card/src/keys.rs index 24cb65c..4ba8afd 100644 --- a/openpgp-card/src/keys.rs +++ b/openpgp-card/src/keys.rs @@ -125,6 +125,8 @@ pub(crate) fn generate_asymmetric_key_pair( card_tx: &mut OpenPgpTransaction, key_type: KeyType, ) -> Result { + log::info!("OpenPgpTransaction: generate_asymmetric_key_pair"); + // generate key let crt = control_reference_template(key_type)?; let gen_key_cmd = commands::gen_key(crt.serialize().to_vec()); @@ -147,6 +149,8 @@ pub(crate) fn public_key( card_tx: &mut OpenPgpTransaction, key_type: KeyType, ) -> Result { + log::info!("OpenPgpTransaction: public_key"); + // get current algo let ard = card_tx.application_related_data()?; // FIXME: caching let algo = ard.algorithm_attributes(key_type)?; @@ -175,6 +179,8 @@ pub(crate) fn key_import( key_type: KeyType, algo_info: Option, ) -> Result<(), Error> { + log::info!("OpenPgpTransaction: key_import"); + // FIXME: caching? let ard = card_tx.application_related_data()?; diff --git a/openpgp-card/src/lib.rs b/openpgp-card/src/lib.rs index e784705..bdbbc40 100644 --- a/openpgp-card/src/lib.rs +++ b/openpgp-card/src/lib.rs @@ -100,6 +100,7 @@ pub trait CardTransaction { /// Select the OpenPGP card application fn select(&mut self) -> Result, Error> { + log::info!("CardTransaction: select"); let select_openpgp = commands::select_openpgp(); apdu::send_command(self, select_openpgp, false)?.try_into() } @@ -114,7 +115,7 @@ pub trait CardTransaction { let resp = apdu::send_command(self, ad, true)?; let value = Value::from(resp.data()?, true)?; - log::debug!(" ARD value: {:x?}", value); + log::trace!(" ARD value: {:x?}", value); Ok(ApplicationRelatedData(Tlv::new(Tag::from([0x6E]), value))) } @@ -171,7 +172,7 @@ pub trait CardTransaction { pw3_max_len: pw3_max, }; - log::debug!("init_card_caps to: {:x?}", caps); + log::trace!("init_card_caps to: {:x?}", caps); self.init_card_caps(caps); diff --git a/openpgp-card/src/openpgp.rs b/openpgp-card/src/openpgp.rs index 9e7e897..90964dc 100644 --- a/openpgp-card/src/openpgp.rs +++ b/openpgp-card/src/openpgp.rs @@ -80,6 +80,8 @@ impl<'a> OpenPgpTransaction<'a> { /// it are needed regularly, and it does not usually change during /// normal use of a card.) pub fn application_related_data(&mut self) -> Result { + log::info!("OpenPgpTransaction: application_related_data"); + self.tx.application_related_data() } @@ -117,6 +119,8 @@ impl<'a> OpenPgpTransaction<'a> { /// Get URL (5f50) pub fn url(&mut self) -> Result, Error> { + log::info!("OpenPgpTransaction: url"); + let resp = apdu::send_command(self.tx(), commands::url(), true)?; Ok(resp.data()?.to_vec()) @@ -124,6 +128,8 @@ impl<'a> OpenPgpTransaction<'a> { /// Get cardholder related data (65) pub fn cardholder_related_data(&mut self) -> Result { + log::info!("OpenPgpTransaction: cardholder_related_data"); + let crd = commands::cardholder_related_data(); let resp = apdu::send_command(self.tx(), crd, true)?; resp.check_ok()?; @@ -133,6 +139,8 @@ impl<'a> OpenPgpTransaction<'a> { /// Get security support template (7a) pub fn security_support_template(&mut self) -> Result { + log::info!("OpenPgpTransaction: security_support_template"); + let sst = commands::security_support_template(); let resp = apdu::send_command(self.tx(), sst, true)?; resp.check_ok()?; @@ -164,12 +172,16 @@ impl<'a> OpenPgpTransaction<'a> { /// certificate (if the card supports multiple certificates). #[allow(dead_code)] pub fn cardholder_certificate(&mut self) -> Result, Error> { + log::info!("OpenPgpTransaction: cardholder_certificate"); + let cmd = commands::cardholder_certificate(); apdu::send_command(self.tx(), cmd, true)?.try_into() } /// Get "Algorithm Information" pub fn algorithm_information(&mut self) -> Result, Error> { + log::info!("OpenPgpTransaction: algorithm_information"); + let resp = apdu::send_command(self.tx(), commands::algo_info(), true)?; resp.check_ok()?; @@ -179,6 +191,8 @@ impl<'a> OpenPgpTransaction<'a> { /// Firmware Version (YubiKey specific (?)) pub fn firmware_version(&mut self) -> Result, Error> { + log::info!("OpenPgpTransaction: firmware_version"); + let resp = apdu::send_command(self.tx(), commands::firmware_version(), true)?; Ok(resp.data()?.into()) @@ -189,6 +203,8 @@ impl<'a> OpenPgpTransaction<'a> { /// /// ] pub fn set_identity(&mut self, id: u8) -> Result, Error> { + log::info!("OpenPgpTransaction: set_identity"); + let resp = apdu::send_command(self.tx(), commands::set_identity(id), false); // Apparently it's normal to get "NotTransacted" from pcsclite when @@ -203,6 +219,8 @@ impl<'a> OpenPgpTransaction<'a> { /// SELECT DATA ("select a DO in the current template", /// e.g. for cardholder certificate) pub fn select_data(&mut self, num: u8, tag: &[u8]) -> Result, Error> { + log::info!("OpenPgpTransaction: select_data"); + let tlv = Tlv::new( [0x60], Value::C(vec![Tlv::new([0x5c], Value::S(tag.to_vec()))]), @@ -220,6 +238,8 @@ impl<'a> OpenPgpTransaction<'a> { /// /// `num` must be between 1 and 4. pub fn private_use_do(&mut self, num: u8) -> Result, Error> { + log::info!("OpenPgpTransaction: private_use_do"); + assert!((1..=4).contains(&num)); let cmd = commands::private_use_do(num); @@ -236,6 +256,8 @@ impl<'a> OpenPgpTransaction<'a> { /// - 1/3 need PW1 (82) /// - 2/4 need PW3 pub fn set_private_use_do(&mut self, num: u8, data: Vec) -> Result, Error> { + log::info!("OpenPgpTransaction: set_private_use_do"); + assert!((1..=4).contains(&num)); let cmd = commands::put_private_use_do(num, data); @@ -262,9 +284,12 @@ impl<'a> OpenPgpTransaction<'a> { /// Gnuk needs to be built with the `--enable-factory-reset` /// option to the `configure` script to enable this functionality). pub fn factory_reset(&mut self) -> Result<(), Error> { + log::info!("OpenPgpTransaction: factory_reset"); + // send 4 bad requests to verify pw1 // [apdu 00 20 00 81 08 40 40 40 40 40 40 40 40] for _ in 0..4 { + log::info!(" verify_pw1_81"); let verify = commands::verify_pw1_81([0x40; 8].to_vec()); let resp = apdu::send_command(self.tx(), verify, false)?; if !(resp.status() == StatusBytes::SecurityStatusNotSatisfied @@ -280,6 +305,7 @@ impl<'a> OpenPgpTransaction<'a> { // send 4 bad requests to verify pw3 // [apdu 00 20 00 83 08 40 40 40 40 40 40 40 40] for _ in 0..4 { + log::info!(" verify_pw3"); let verify = commands::verify_pw3([0x40; 8].to_vec()); let resp = apdu::send_command(self.tx(), verify, false)?; @@ -294,11 +320,13 @@ impl<'a> OpenPgpTransaction<'a> { } // terminate_df [apdu 00 e6 00 00] + log::info!(" terminate_df"); let term = commands::terminate_df(); let resp = apdu::send_command(self.tx(), term, false)?; resp.check_ok()?; // activate_file [apdu 00 44 00 00] + log::info!(" activate_file"); let act = commands::activate_file(); let resp = apdu::send_command(self.tx(), act, false)?; resp.check_ok()?; @@ -314,6 +342,8 @@ impl<'a> OpenPgpTransaction<'a> { /// access condition is only valid for one PSO:CDS command or remains /// valid for several attempts. pub fn verify_pw1_sign(&mut self, pin: &[u8]) -> Result<(), Error> { + log::info!("OpenPgpTransaction: verify_pw1_sign"); + let verify = commands::verify_pw1_81(pin.to_vec()); apdu::send_command(self.tx(), verify, false)?.try_into() } @@ -326,6 +356,8 @@ impl<'a> OpenPgpTransaction<'a> { /// access condition is only valid for one PSO:CDS command or remains /// valid for several attempts. pub fn verify_pw1_sign_pinpad(&mut self) -> Result<(), Error> { + log::info!("OpenPgpTransaction: verify_pw1_sign_pinpad"); + let res = self.tx().pinpad_verify(PinType::Sign)?; RawResponse::try_from(res)?.try_into() } @@ -339,6 +371,8 @@ impl<'a> OpenPgpTransaction<'a> { /// - some cards that don't support this instruction may decrease the pin's error count, /// eventually requiring the user to reset the pin) pub fn check_pw1_sign(&mut self) -> Result<(), Error> { + log::info!("OpenPgpTransaction: check_pw1_sign"); + let verify = commands::verify_pw1_81(vec![]); apdu::send_command(self.tx(), verify, false)?.try_into() } @@ -346,6 +380,8 @@ impl<'a> OpenPgpTransaction<'a> { /// Verify PW1 (user). /// (For operations except signing, mode 82). pub fn verify_pw1_user(&mut self, pin: &[u8]) -> Result<(), Error> { + log::info!("OpenPgpTransaction: verify_pw1_user"); + let verify = commands::verify_pw1_82(pin.to_vec()); apdu::send_command(self.tx(), verify, false)?.try_into() } @@ -355,6 +391,8 @@ impl<'a> OpenPgpTransaction<'a> { /// an error is returned. pub fn verify_pw1_user_pinpad(&mut self) -> Result<(), Error> { + log::info!("OpenPgpTransaction: verify_pw1_user_pinpad"); + let res = self.tx().pinpad_verify(PinType::User)?; RawResponse::try_from(res)?.try_into() } @@ -369,12 +407,16 @@ impl<'a> OpenPgpTransaction<'a> { /// - some cards that don't support this instruction may decrease the pin's error count, /// eventually requiring the user to reset the pin) pub fn check_pw1_user(&mut self) -> Result<(), Error> { + log::info!("OpenPgpTransaction: check_pw1_user"); + let verify = commands::verify_pw1_82(vec![]); apdu::send_command(self.tx(), verify, false)?.try_into() } /// Verify PW3 (admin). pub fn verify_pw3(&mut self, pin: &[u8]) -> Result<(), Error> { + log::info!("OpenPgpTransaction: verify_pw3"); + let verify = commands::verify_pw3(pin.to_vec()); apdu::send_command(self.tx(), verify, false)?.try_into() } @@ -382,6 +424,8 @@ impl<'a> OpenPgpTransaction<'a> { /// Verify PW3 (admin) using a pinpad on the card reader. If no usable /// pinpad is found, an error is returned. pub fn verify_pw3_pinpad(&mut self) -> Result<(), Error> { + log::info!("OpenPgpTransaction: verify_pw3_pinpad"); + let res = self.tx().pinpad_verify(PinType::Admin)?; RawResponse::try_from(res)?.try_into() } @@ -395,6 +439,8 @@ impl<'a> OpenPgpTransaction<'a> { /// - some cards that don't support this instruction may decrease the pin's error count, /// eventually requiring the user to reset the pin) pub fn check_pw3(&mut self) -> Result<(), Error> { + log::info!("OpenPgpTransaction: check_pw3"); + let verify = commands::verify_pw3(vec![]); apdu::send_command(self.tx(), verify, false)?.try_into() } @@ -403,6 +449,8 @@ impl<'a> OpenPgpTransaction<'a> { /// /// The current value of PW1 must be presented in `old` for authorization. pub fn change_pw1(&mut self, old: &[u8], new: &[u8]) -> Result<(), Error> { + log::info!("OpenPgpTransaction: change_pw1"); + let mut data = vec![]; data.extend(old); data.extend(new); @@ -414,6 +462,8 @@ impl<'a> OpenPgpTransaction<'a> { /// Change the value of PW1 (0x81) using a pinpad on the /// card reader. If no usable pinpad is found, an error is returned. pub fn change_pw1_pinpad(&mut self) -> Result<(), Error> { + log::info!("OpenPgpTransaction: change_pw1_pinpad"); + // Note: for change PW, only 0x81 and 0x83 are used! // 0x82 is implicitly the same as 0x81. let res = self.tx().pinpad_modify(PinType::Sign)?; @@ -424,6 +474,8 @@ impl<'a> OpenPgpTransaction<'a> { /// /// The current value of PW3 must be presented in `old` for authorization. pub fn change_pw3(&mut self, old: &[u8], new: &[u8]) -> Result<(), Error> { + log::info!("OpenPgpTransaction: change_pw3"); + let mut data = vec![]; data.extend(old); data.extend(new); @@ -435,6 +487,8 @@ impl<'a> OpenPgpTransaction<'a> { /// Change the value of PW3 (admin password) using a pinpad on the /// card reader. If no usable pinpad is found, an error is returned. pub fn change_pw3_pinpad(&mut self) -> Result<(), Error> { + log::info!("OpenPgpTransaction: change_pw3_pinpad"); + let res = self.tx().pinpad_modify(PinType::Admin)?; RawResponse::try_from(res)?.try_into() } @@ -451,6 +505,8 @@ impl<'a> OpenPgpTransaction<'a> { new_pw1: &[u8], resetting_code: Option<&[u8]>, ) -> Result<(), Error> { + log::info!("OpenPgpTransaction: reset_retry_counter_pw1"); + let reset = commands::reset_retry_counter_pw1(resetting_code, new_pw1); apdu::send_command(self.tx(), reset, false)?.try_into() } @@ -498,6 +554,8 @@ impl<'a> OpenPgpTransaction<'a> { /// (consider using the `decipher()` method if you don't want to create /// the data field manually) pub fn pso_decipher(&mut self, data: Vec) -> Result, Error> { + log::info!("OpenPgpTransaction: pso_decipher"); + // The OpenPGP card is already connected and PW1 82 has been verified let dec_cmd = commands::decryption(data); let resp = apdu::send_command(self.tx(), dec_cmd, true)?; @@ -529,6 +587,8 @@ impl<'a> OpenPgpTransaction<'a> { /// (consider using the `signature_for_hash()` method if you don't /// want to create the data field manually) pub fn pso_compute_digital_signature(&mut self, data: Vec) -> Result, Error> { + log::info!("OpenPgpTransaction: pso_compute_digital_signature"); + let cds_cmd = commands::signature(data); let resp = apdu::send_command(self.tx(), cds_cmd, true)?; @@ -558,6 +618,8 @@ impl<'a> OpenPgpTransaction<'a> { /// (consider using the `authenticate_for_hash()` method if you don't /// want to create the data field manually) pub fn internal_authenticate(&mut self, data: Vec) -> Result, Error> { + log::info!("OpenPgpTransaction: internal_authenticate"); + let ia_cmd = commands::internal_authenticate(data); let resp = apdu::send_command(self.tx(), ia_cmd, true)?; @@ -567,11 +629,15 @@ impl<'a> OpenPgpTransaction<'a> { // --- admin --- pub fn set_name(&mut self, name: &[u8]) -> Result<(), Error> { + log::info!("OpenPgpTransaction: set_name"); + let put_name = commands::put_name(name.to_vec()); apdu::send_command(self.tx(), put_name, false)?.try_into() } pub fn set_lang(&mut self, lang: &[Lang]) -> Result<(), Error> { + log::info!("OpenPgpTransaction: set_lang"); + let bytes: Vec = lang .iter() .flat_map(|&l| Into::>::into(l)) @@ -582,11 +648,15 @@ impl<'a> OpenPgpTransaction<'a> { } pub fn set_sex(&mut self, sex: Sex) -> Result<(), Error> { + log::info!("OpenPgpTransaction: set_sex"); + let put_sex = commands::put_sex((&sex).into()); apdu::send_command(self.tx(), put_sex, false)?.try_into() } pub fn set_url(&mut self, url: &[u8]) -> Result<(), Error> { + log::info!("OpenPgpTransaction: set_url"); + let put_url = commands::put_url(url.to_vec()); apdu::send_command(self.tx(), put_url, false)?.try_into() } @@ -596,6 +666,8 @@ impl<'a> OpenPgpTransaction<'a> { time: KeyGenerationTime, key_type: KeyType, ) -> Result<(), Error> { + log::info!("OpenPgpTransaction: set_creation_time"); + // Timestamp update let time_value: Vec = time .get() @@ -611,6 +683,8 @@ impl<'a> OpenPgpTransaction<'a> { } pub fn set_fingerprint(&mut self, fp: Fingerprint, key_type: KeyType) -> Result<(), Error> { + log::info!("OpenPgpTransaction: set_fingerprint"); + let fp_cmd = commands::put_data(&[key_type.fingerprint_put_tag()], fp.as_bytes().to_vec()); apdu::send_command(self.tx(), fp_cmd, false)?.try_into() @@ -632,6 +706,8 @@ impl<'a> OpenPgpTransaction<'a> { pw_status: &PWStatusBytes, long: bool, ) -> Result<(), Error> { + log::info!("OpenPgpTransaction: set_pw_status_bytes"); + let data = pw_status.serialize_for_put(long); let cmd = commands::put_pw_status(data); @@ -643,6 +719,8 @@ impl<'a> OpenPgpTransaction<'a> { /// Call select_data() before calling this fn, to select a particular /// certificate (if the card supports multiple certificates). pub fn set_cardholder_certificate(&mut self, data: Vec) -> Result<(), Error> { + log::info!("OpenPgpTransaction: set_cardholder_certificate"); + let cmd = commands::put_cardholder_certificate(data); apdu::send_command(self.tx(), cmd, false)?.try_into() } @@ -654,6 +732,8 @@ impl<'a> OpenPgpTransaction<'a> { key_type: KeyType, algo: &Algo, ) -> Result<(), Error> { + log::info!("OpenPgpTransaction: set_algorithm_attributes"); + // Command to PUT the algorithm attributes let cmd = commands::put_data(&[key_type.algorithm_tag()], algo.to_data_object()?); @@ -663,6 +743,8 @@ impl<'a> OpenPgpTransaction<'a> { /// Set resetting code /// (4.3.4 Resetting Code) pub fn set_resetting_code(&mut self, resetting_code: &[u8]) -> Result<(), Error> { + log::info!("OpenPgpTransaction: set_resetting_code"); + let cmd = commands::put_data(&[0xd3], resetting_code.to_vec()); apdu::send_command(self.tx(), cmd, false)?.try_into() } diff --git a/pcsc/src/lib.rs b/pcsc/src/lib.rs index a97c062..ab02e13 100644 --- a/pcsc/src/lib.rs +++ b/pcsc/src/lib.rs @@ -76,7 +76,7 @@ impl<'b> PcscTransaction<'b> { // A transaction has been successfully started if was_reset { - log::debug!("start_tx: card was reset, select!"); + log::trace!("start_tx: card was reset, select!"); let mut txc = Self { tx, @@ -113,7 +113,7 @@ impl<'b> PcscTransaction<'b> { c = c_; - log::debug!("start_tx: do reconnect"); + log::trace!("start_tx: do reconnect"); { c.reconnect(mode, pcsc::Protocols::ANY, Disposition::ResetCard) @@ -125,12 +125,12 @@ impl<'b> PcscTransaction<'b> { })?; } - log::debug!("start_tx: reconnected."); + log::trace!("start_tx: reconnected."); // -> try opening a transaction again } Err((_, e)) => { - log::debug!("start_tx: error {:?}", e); + log::trace!("start_tx: error {:?}", e); break Err(Error::Smartcard(SmartcardError::Error(format!( "Error: {:?}", e @@ -212,8 +212,6 @@ impl CardTransaction for PcscTransaction<'_> { _ => Error::Smartcard(SmartcardError::Error(format!("Transmit failed: {:?}", e))), })?; - log::debug!(" <- APDU response: {:x?}", resp); - Ok(resp.to_vec()) } @@ -302,7 +300,7 @@ impl CardTransaction for PcscTransaction<'_> { // 19 abData BYTE[] Data to send to the ICC send.extend(ab_data); - log::debug!("pcsc pinpad_verify send: {:x?}", send); + log::trace!("pcsc pinpad_verify send: {:x?}", send); let mut recv = vec![0xAA; 256]; @@ -321,7 +319,7 @@ impl CardTransaction for PcscTransaction<'_> { Error::Smartcard(SmartcardError::Error(format!("pcsc Error: {:?}", e))) })?; - log::debug!(" <- pcsc pinpad_verify result: {:x?}", res); + log::trace!(" <- pcsc pinpad_verify result: {:x?}", res); Ok(res.to_vec()) } @@ -405,7 +403,7 @@ impl CardTransaction for PcscTransaction<'_> { // 19 abData BYTE[] Data to send to the ICC send.extend(ab_data); - log::debug!("pcsc pinpad_modify send: {:x?}", send); + log::trace!("pcsc pinpad_modify send: {:x?}", send); let mut recv = vec![0xAA; 256]; @@ -424,7 +422,7 @@ impl CardTransaction for PcscTransaction<'_> { Error::Smartcard(SmartcardError::Error(format!("pcsc Error: {:?}", e))) })?; - log::debug!(" <- pcsc pinpad_modify result: {:x?}", res); + log::trace!(" <- pcsc pinpad_modify result: {:x?}", res); Ok(res.to_vec()) } @@ -442,29 +440,29 @@ impl PcscBackend { /// A list of "raw" opened PCSC Cards (without selecting the OpenPGP card /// application) fn raw_pcsc_cards(mode: pcsc::ShareMode) -> Result, SmartcardError> { - log::debug!("raw_pcsc_cards start"); + log::trace!("raw_pcsc_cards start"); let ctx = match pcsc::Context::establish(pcsc::Scope::User) { Ok(ctx) => ctx, Err(err) => { - log::debug!("Context::establish failed: {:?}", err); + log::trace!("Context::establish failed: {:?}", err); return Err(SmartcardError::ContextError(err.to_string())); } }; - log::debug!("raw_pcsc_cards got context"); + log::trace!("raw_pcsc_cards got context"); // List available readers. let mut readers_buf = [0; 2048]; let readers = match ctx.list_readers(&mut readers_buf) { Ok(readers) => readers, Err(err) => { - log::debug!("list_readers failed: {:?}", err); + log::trace!("list_readers failed: {:?}", err); return Err(SmartcardError::ReaderError(err.to_string())); } }; - log::debug!(" readers: {:?}", readers); + log::trace!(" readers: {:?}", readers); let mut found_reader = false; @@ -475,13 +473,13 @@ impl PcscBackend { // We've seen at least one smartcard reader found_reader = true; - log::debug!("Checking reader: {:?}", reader); + log::trace!("Checking reader: {:?}", reader); // Try connecting to card in this reader let card = match ctx.connect(reader, mode, pcsc::Protocols::ANY) { Ok(card) => card, Err(pcsc::Error::NoSmartcard) => { - log::debug!("No Smartcard"); + log::trace!("No Smartcard"); continue; // try next reader } @@ -492,7 +490,7 @@ impl PcscBackend { } }; - log::debug!("Found card"); + log::trace!("Found card"); cards.push(card); } @@ -512,8 +510,8 @@ impl PcscBackend { let mut cards: Vec = vec![]; for mut card in Self::raw_pcsc_cards(mode).map_err(Error::Smartcard)? { - log::debug!("cards_filter: next card"); - log::debug!(" status: {:x?}", card.status2_owned()); + log::trace!("cards_filter: next card"); + log::trace!(" status: {:x?}", card.status2_owned()); let mut store_card = false; { @@ -523,11 +521,11 @@ impl PcscBackend { { if let Err(e) = PcscTransaction::select(&mut txc) { - log::debug!(" select error: {:?}", e); + log::trace!(" select error: {:?}", e); } else { // successfully opened the OpenPGP application - log::debug!(" select ok, will read ARD"); - log::debug!(" status: {:x?}", txc.tx.status2_owned()); + log::trace!(" select ok, will read ARD"); + log::trace!(" status: {:x?}", txc.tx.status2_owned()); if let Some(ident) = ident { if let Ok(ard) = PcscTransaction::application_related_data(&mut txc) { @@ -535,12 +533,12 @@ impl PcscBackend { if aid.ident() == ident.to_ascii_uppercase() { // FIXME: handle multiple cards with matching ident - log::debug!(" will use: {:?}", ident); + log::info!(" found card: {:?} (will use)", ident); // we want to return this one card store_card = true; } else { - log::debug!(" won't use {:?}", aid.ident()); + log::info!(" found card: {:?} (won't use)", aid.ident()); } } else { // couldn't read ARD for this card. @@ -564,7 +562,7 @@ impl PcscBackend { } } - log::debug!("cards_filter: found {} cards", cards.len()); + log::trace!("cards_filter: found {} cards", cards.len()); Ok(cards) } @@ -581,7 +579,7 @@ impl PcscBackend { /// A fully initialized PcscCard is returned: the OpenPGP application has /// been selected, card_caps and reader_caps have been initialized. pub fn open_by_ident(ident: &str, mode: Option) -> Result { - log::debug!("open_by_ident for {:?}", ident); + log::trace!("open_by_ident for {:?}", ident); let mut cards = Self::cards_filter(Some(ident), default_mode(mode))?; @@ -609,7 +607,7 @@ impl PcscBackend { /// - Obtain and store feature lists from reader (pinpad functionality). /// - Get ARD from card, set CardCaps based on ARD. fn initialize_card(mut self) -> Result { - log::debug!("pcsc initialize_card"); + log::trace!("pcsc initialize_card"); let mut h: HashMap = HashMap::default(); @@ -618,7 +616,7 @@ impl PcscBackend { // Get Features from reader (pinpad verify/modify) if let Ok(feat) = txc.features() { for tlv in feat { - log::debug!(" Found reader feature {:?}", tlv); + log::trace!(" Found reader feature {:?}", tlv); h.insert(tlv.tag().into(), tlv); } } diff --git a/scdc/src/lib.rs b/scdc/src/lib.rs index d17bf37..9a9667b 100644 --- a/scdc/src/lib.rs +++ b/scdc/src/lib.rs @@ -146,7 +146,7 @@ impl ScdBackend { self.send2(send)?; while let Some(response) = rt.block_on(self.agent.next()) { - log::debug!("init res: {:x?}", response); + log::trace!("init res: {:x?}", response); if let Ok(Response::Status { .. }) = response { // drop remaining lines @@ -172,7 +172,7 @@ impl ScdBackend { let mut rt = RT.lock().unwrap(); while let Some(response) = rt.block_on(self.agent.next()) { - log::debug!("select res: {:x?}", response); + log::trace!("select res: {:x?}", response); if response.is_err() { return Err(Error::Smartcard(SmartcardError::CardNotFound( @@ -183,7 +183,7 @@ impl ScdBackend { if let Ok(Response::Status { .. }) = response { // drop remaining lines while let Some(_drop) = rt.block_on(self.agent.next()) { - log::debug!("select drop: {:x?}", _drop); + log::trace!("select drop: {:x?}", _drop); } return Ok(()); @@ -201,7 +201,7 @@ impl ScdBackend { let mut rt = RT.lock().unwrap(); while let Some(response) = rt.block_on(self.agent.next()) { - log::debug!("select res: {:x?}", response); + log::trace!("select res: {:x?}", response); if let Err(e) = response { return Err(Error::Smartcard(SmartcardError::Error(format!("{:?}", e)))); @@ -210,7 +210,7 @@ impl ScdBackend { if let Ok(..) = response { // drop remaining lines while let Some(_drop) = rt.block_on(self.agent.next()) { - log::debug!(" drop: {:x?}", _drop); + log::trace!(" drop: {:x?}", _drop); } return Ok(()); @@ -251,7 +251,7 @@ impl CardTransaction for ScdTransaction<'_> { }; let send = format!("SCD APDU {}{}\n", ext, hex); - log::debug!("SCDC command: '{}'", send); + log::trace!("SCDC command: '{}'", send); if send.len() > ASSUAN_LINELENGTH { return Err(Error::Smartcard(SmartcardError::Error(format!( @@ -265,7 +265,7 @@ impl CardTransaction for ScdTransaction<'_> { let mut rt = RT.lock().unwrap(); while let Some(response) = rt.block_on(self.scd.agent.next()) { - log::debug!("res: {:x?}", response); + log::trace!("res: {:x?}", response); if response.is_err() { return Err(Error::Smartcard(SmartcardError::Error(format!( "Unexpected error response from SCD {:?}",