mirror/libsignal
0
0
Fork 0
mirror of https://github.com/signalapp/libsignal.git synced 2024-09-20 12:02:18 +02:00
Code

Add logging that matches SignalProtocolKit (the ObjC library)

Browse Source
This commit is contained in:
Jordan Rose 2021-02-04 15:21:05 -08:00
parent a1eb7f72e1
commit d72113ee8c
8 changed files with 149 additions and 7 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

1
Cargo.lock generated
View File

@ -823,6 +823,7 @@ dependencies = [
"futures",
"hex",
"hmac",
"log",
"prost",
"prost-build",
"rand",

1
rust/protocol/Cargo.toml
View File

@ -28,6 +28,7 @@ sha2 = "0.9"
subtle = "2.2.3"
x25519-dalek = "1.0"
hex = "0.4"
log = "0.4"
[features]
default = ["u64_backend"]

2
rust/protocol/src/address.rs
View File

@ -27,6 +27,6 @@ impl ProtocolAddress {
impl fmt::Display for ProtocolAddress {
fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
write!(f, "{} {}", self.name, self.device_id)
write!(f, "{}.{}", self.name, self.device_id)
}
}

10
rust/protocol/src/protocol.rs
View File

@ -144,7 +144,15 @@ impl SignalMessage {
&self.serialized[..self.serialized.len() - Self::MAC_LENGTH],
)?;
let their_mac = &self.serialized[self.serialized.len() - Self::MAC_LENGTH..];
Ok(our_mac.ct_eq(their_mac).into())
let result: bool = our_mac.ct_eq(their_mac).into();
if !result {
log::error!(
"Bad Mac! Their Mac: {} Our Mac: {}",
hex::encode(their_mac),
hex::encode(our_mac)
);
}
Ok(result)
}
fn compute_mac(

7
rust/protocol/src/ratchet/keys.rs
View File

@ -9,6 +9,7 @@ use crate::crypto;
use crate::curve;
use crate::error::{Result, SignalProtocolError};
use crate::kdf::HKDF;
use std::fmt;
pub struct MessageKeys {
cipher_key: [u8; 32],
@ -169,6 +170,12 @@ impl RootKey {
}
}
impl fmt::Display for RootKey {
fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
write!(f, "{}", hex::encode(self.key))
}
}
#[cfg(test)]
mod tests {
use super::*;

7
rust/protocol/src/session.rs
View File

@ -97,6 +97,7 @@ async fn process_prekey_v3(
.key_pair()?,
)
} else {
log::warn!("Processing PreKey message which had no one-time prekey");
None
};
@ -173,6 +174,12 @@ pub async fn process_prekey_bundle<R: Rng + CryptoRng>(
let mut session = ratchet::initialize_alice_session(&parameters, csprng)?;
log::info!(
"set_unacknowledged_pre_key_message for: {} with preKeyId: {}",
remote_address,
their_one_time_prekey_id.map_or_else(|| "<none>".to_string(), |id| id.to_string())
);
session.set_unacknowledged_pre_key_message(
their_one_time_prekey_id,
bundle.signed_pre_key_id()?,

114
rust/protocol/src/session_cipher.rs
View File

@ -51,6 +51,14 @@ pub async fn message_encrypt(
let message = if let Some(items) = session_state.unacknowledged_pre_key_message_items()? {
let local_registration_id = session_state.local_registration_id()?;
log::info!(
"Building PreKeyWhisperMessage for: {} with preKeyId: {}",
remote_address,
items
.pre_key_id()?
.map_or_else(|| "<none>".to_string(), |id| id.to_string())
);
let message = SignalMessage::new(
session_version,
message_keys.mac_key(),
@ -96,6 +104,14 @@ pub async fn message_encrypt(
)
.await?
{
log::warn!(
"Identity key {} is not trusted for remote address {}",
their_identity_key
.public_key()
.public_key_bytes()
.map_or_else(|e| format!("<error: {}>", e), hex::encode),
remote_address,
);
return Err(SignalProtocolError::UntrustedIdentity(
remote_address.clone(),
));
@ -228,6 +244,14 @@ pub async fn message_decrypt_signal<R: Rng + CryptoRng>(
)
.await?
{
log::warn!(
"Identity key {} is not trusted for remote address {}",
their_identity_key
.public_key()
.public_key_bytes()
.map_or_else(|e| format!("<error: {}>", e), hex::encode),
remote_address,
);
return Err(SignalProtocolError::UntrustedIdentity(
remote_address.clone(),
));
@ -296,14 +320,41 @@ fn decrypt_message_with_record<R: Rng + CryptoRng>(
ciphertext: &SignalMessage,
csprng: &mut R,
) -> Result<Vec<u8>> {
let log_decryption_failure = |state: &SessionState, error: &SignalProtocolError| {
log::error!(
"Failed to decrypt whisper message with ratchet key: {} and counter: {}. \
Session loaded for {}. Local session has base key: {} and counter: {}. {}",
ciphertext
.sender_ratchet_key()
.public_key_bytes()
.map_or_else(|e| format!("<error: {}>", e), hex::encode),
ciphertext.counter(),
remote_address,
state
.sender_ratchet_key_for_logging()
.unwrap_or_else(|e| format!("<error: {}>", e)),
state.previous_counter().unwrap_or(u32::MAX),
error
);
};
let mut errs = vec![];
if let Ok(current_state) = record.session_state() {
let mut current_state = current_state.clone();
let result = decrypt_message_with_state(&mut current_state, ciphertext, csprng);
let result =
decrypt_message_with_state(&mut current_state, ciphertext, remote_address, csprng);
match result {
Ok(ptext) => {
log::debug!(
"successfully decrypted with current session state (base key {})",
hex::encode(
current_state
.sender_ratchet_key_for_logging()
.expect("successful decrypt always has a valid base key")
),
);
record.set_session_state(current_state)?; // update the state
return Ok(ptext);
}
@ -311,6 +362,7 @@ fn decrypt_message_with_record<R: Rng + CryptoRng>(
return result;
}
Err(e) => {
log_decryption_failure(&current_state, &e);
errs.push(e);
}
}
@ -322,10 +374,18 @@ fn decrypt_message_with_record<R: Rng + CryptoRng>(
for (idx, previous) in record.previous_session_states()?.enumerate() {
let mut updated = previous.clone();
let result = decrypt_message_with_state(&mut updated, ciphertext, csprng);
let result = decrypt_message_with_state(&mut updated, ciphertext, remote_address, csprng);
match result {
Ok(ptext) => {
log::info!(
"successfully decrypted with PREVIOUS session state (base key {})",
hex::encode(
previous
.sender_ratchet_key_for_logging()
.expect("successful decrypt always has a valid base key")
),
);
updated_session = Some((ptext, idx, updated));
break;
}
@ -333,6 +393,7 @@ fn decrypt_message_with_record<R: Rng + CryptoRng>(
return result;
}
Err(e) => {
log_decryption_failure(&previous, &e);
errs.push(e);
}
}
@ -342,6 +403,28 @@ fn decrypt_message_with_record<R: Rng + CryptoRng>(
record.promote_old_session(idx, updated_session)?;
Ok(ptext)
} else {
let previous_state_count = || {
record.previous_session_states().map_or_else(
|e| format!("<error: {}>", e),
|states| states.count().to_string(),
)
};
if let Ok(current_state) = record.session_state() {
log::error!(
"No valid session for recipient: {}, current session base key {}, number of previous states: {}",
remote_address,
current_state.sender_ratchet_key_for_logging()
.unwrap_or_else(|e| format!("<error: {}>", e)),
previous_state_count(),
);
} else {
log::error!(
"No valid session for recipient: {}, (no current session state), number of previous states: {}",
remote_address,
previous_state_count(),
);
}
Err(SignalProtocolError::MessageDecryptionFailed(
create_decryption_failure_log(remote_address, &errs, record, ciphertext)?,
))
@ -351,6 +434,7 @@ fn decrypt_message_with_record<R: Rng + CryptoRng>(
fn decrypt_message_with_state<R: Rng + CryptoRng>(
state: &mut SessionState,
ciphertext: &SignalMessage,
remote_address: &ProtocolAddress,
csprng: &mut R,
) -> Result<Vec<u8>> {
if !state.has_sender_chain()? {
@ -368,8 +452,9 @@ fn decrypt_message_with_state<R: Rng + CryptoRng>(
let their_ephemeral = ciphertext.sender_ratchet_key();
let counter = ciphertext.counter();
let chain_key = get_or_create_chain_key(state, their_ephemeral, csprng)?;
let message_keys = get_or_create_message_key(state, their_ephemeral, &chain_key, counter)?;
let chain_key = get_or_create_chain_key(state, their_ephemeral, remote_address, csprng)?;
let message_keys =
get_or_create_message_key(state, their_ephemeral, remote_address, &chain_key, counter)?;
let their_identity_key = state
.remote_identity_key()?
@ -399,12 +484,16 @@ fn decrypt_message_with_state<R: Rng + CryptoRng>(
fn get_or_create_chain_key<R: Rng + CryptoRng>(
state: &mut SessionState,
their_ephemeral: &curve::PublicKey,
remote_address: &ProtocolAddress,
csprng: &mut R,
) -> Result<ChainKey> {
if let Some(chain) = state.get_receiver_chain_key(their_ephemeral)? {
log::debug!("{} has existing receiver chain.", remote_address);
return Ok(chain);
}
log::info!("{} creating new chains.", remote_address);
let root_key = state.root_key()?;
let our_ephemeral = state.sender_ratchet_private_key()?;
let receiver_chain = root_key.create_chain(their_ephemeral, &our_ephemeral)?;
@ -431,6 +520,7 @@ fn get_or_create_chain_key<R: Rng + CryptoRng>(
fn get_or_create_message_key(
state: &mut SessionState,
their_ephemeral: &curve::PublicKey,
remote_address: &ProtocolAddress,
chain_key: &ChainKey,
counter: u32,
) -> Result<MessageKeys> {
@ -439,7 +529,14 @@ fn get_or_create_message_key(
if chain_index > counter {
return match state.get_message_keys(their_ephemeral, counter)? {
Some(keys) => Ok(keys),
None => Err(SignalProtocolError::DuplicatedMessage(chain_index, counter)),
None => {
log::info!(
"{} Duplicate message for counter: {}",
remote_address,
counter
);
Err(SignalProtocolError::DuplicatedMessage(chain_index, counter))
}
};
}
@ -448,6 +545,13 @@ fn get_or_create_message_key(
let jump = (counter - chain_index) as usize;
if jump > MAX_FORWARD_JUMPS {
log::error!(
"{} Exceeded future message limit: {}, index: {}, counter: {})",
remote_address,
MAX_FORWARD_JUMPS,
chain_index,
counter
);
return Err(SignalProtocolError::InvalidMessage(
"message from too far into the future",
));

14
rust/protocol/src/state/session.rs
View File

@ -123,6 +123,12 @@ impl SessionState {
}
}
pub(crate) fn sender_ratchet_key_for_logging(&self) -> Result<String> {
self.sender_ratchet_key()?
.public_key_bytes()
.map(hex::encode)
}
pub(crate) fn sender_ratchet_private_key(&self) -> Result<curve::PrivateKey> {
match self.session.sender_chain {
None => Err(SignalProtocolError::InvalidProtobufEncoding),
@ -210,6 +216,12 @@ impl SessionState {
self.session.receiver_chains.push(chain);
if self.session.receiver_chains.len() > consts::MAX_RECEIVER_CHAINS {
log::info!(
"Trimming excessive receiver_chain for session with base key {}, chain count: {}",
self.sender_ratchet_key_for_logging()
.unwrap_or_else(|e| format!("<error: {}>", e)),
self.session.receiver_chains.len()
);
self.session.receiver_chains.remove(0);
}
@ -559,6 +571,8 @@ impl SessionRecord {
if self.previous_sessions.len() > consts::ARCHIVED_STATES_MAX_LENGTH {
self.previous_sessions.pop_back();
}
} else {
log::info!("Skipping archive, current session state is fresh",);
}
Ok(())