From 9848f8445292ad3f7ff92bd4abfeb8f2d08ec32d Mon Sep 17 00:00:00 2001 From: Richard van der Hoff Date: Tue, 26 Apr 2016 11:44:32 +0100 Subject: Add some logging to help understand what's going on --- src/account.cpp | 9 +++++- src/crypto.cpp | 4 +++ src/message.cpp | 22 +++++++++++++ src/ratchet.cpp | 95 ++++++++++++++++++++++++++++++++++++++++++++++++--------- src/session.cpp | 74 +++++++++++++++++++++++++++++++++++++++----- 5 files changed, 182 insertions(+), 22 deletions(-) (limited to 'src') diff --git a/src/account.cpp b/src/account.cpp index 43033c8..4fca953 100644 --- a/src/account.cpp +++ b/src/account.cpp @@ -1,4 +1,4 @@ -/* Copyright 2015 OpenMarket Ltd +/* Copyright 2015, 2016 OpenMarket Ltd * * Licensed under the Apache License, Version 2.0 (the "License"); * you may not use this file except in compliance with the License. @@ -14,9 +14,12 @@ */ #include "olm/account.hh" #include "olm/base64.hh" +#include "olm/logging.hh" #include "olm/pickle.hh" #include "olm/memory.hh" +static const char *LOG_CATEGORY = "olm::Account"; + olm::Account::Account( ) : next_one_time_key_id(0), last_error(olm::ErrorCode::SUCCESS) { @@ -42,9 +45,11 @@ std::size_t olm::Account::remove_key( if (olm::array_equal(i->key.public_key, public_key.public_key)) { std::uint32_t id = i->id; one_time_keys.erase(i); + olm::logf(olm::LOG_INFO, LOG_CATEGORY, "removed key id %i", id); return id; } } + olm::logf(olm::LOG_WARNING, LOG_CATEGORY, "Couldn't find key to remove"); return std::size_t(-1); } @@ -64,6 +69,8 @@ std::size_t olm::Account::new_account( random += KEY_LENGTH; olm::curve25519_generate_key(random, identity_keys.curve25519_key); + olm::logf(olm::LOG_DEBUG, LOG_CATEGORY, "Created new account"); + return 0; } diff --git a/src/crypto.cpp b/src/crypto.cpp index 8867688..3801e93 100644 --- a/src/crypto.cpp +++ b/src/crypto.cpp @@ -101,6 +101,10 @@ inline static void hmac_sha256_final( } // namespace +std::string olm::Curve25519PublicKey::to_string() const { + return olm::bytes_to_string(std::begin(public_key), + std::end(public_key)); +}; void olm::curve25519_generate_key( std::uint8_t const * random_32_bytes, diff --git a/src/message.cpp b/src/message.cpp index 05f707f..30abd9c 100644 --- a/src/message.cpp +++ b/src/message.cpp @@ -14,8 +14,13 @@ */ #include "olm/message.hh" +#include "olm/logging.hh" +#include "olm/memory.hh" + namespace { +static const char *LOG_CATEGORY = "olm::Message"; + template static std::size_t varint_length( T value @@ -234,6 +239,13 @@ void olm::decode_message( } unknown = pos; } + olm::logf(olm::LOG_TRACE, LOG_CATEGORY, + "Decoded message ver=%i ratchet_key=%s chain_idx=%i ciphertext=%s", + reader.version, + olm::bytes_to_string(reader.ratchet_key, reader.ratchet_key_length).c_str(), + reader.has_counter ? reader.counter : -1, + olm::bytes_to_string(reader.ciphertext, reader.ciphertext_length).c_str() + ); } @@ -322,4 +334,14 @@ void olm::decode_one_time_key_message( } unknown = pos; } + + olm::logf(olm::LOG_TRACE, LOG_CATEGORY, + "Decoded pre-key message ver=%i one_time_key[Eb]=%s " + "base_key[Ea]=%s identity_key[Ia]=%s message=%s", + reader.version, + olm::bytes_to_string(reader.one_time_key, reader.one_time_key_length).c_str(), + olm::bytes_to_string(reader.base_key, reader.base_key_length).c_str(), + olm::bytes_to_string(reader.identity_key, reader.identity_key_length).c_str(), + olm::bytes_to_string(reader.message, reader.message_length).c_str() + ); } diff --git a/src/ratchet.cpp b/src/ratchet.cpp index 5ef1e56..03a0478 100644 --- a/src/ratchet.cpp +++ b/src/ratchet.cpp @@ -1,4 +1,4 @@ -/* Copyright 2015 OpenMarket Ltd +/* Copyright 2015, 2016 OpenMarket Ltd * * Licensed under the Apache License, Version 2.0 (the "License"); * you may not use this file except in compliance with the License. @@ -17,17 +17,31 @@ #include "olm/memory.hh" #include "olm/cipher.hh" #include "olm/pickle.hh" - +#include "olm/logging.hh" #include namespace { +static const char *LOG_CATEGORY = "olm::Ratchet"; + static const std::uint8_t PROTOCOL_VERSION = 3; static const std::uint8_t MESSAGE_KEY_SEED[1] = {0x01}; static const std::uint8_t CHAIN_KEY_SEED[1] = {0x02}; static const std::size_t MAX_MESSAGE_GAP = 2000; + +/** + * Advance the root key, creating a new message chain. + * + * @param root_key previous root key R(n-1) + * @param our_key our new ratchet key T(n) + * @param their_key their most recent ratchet key T(n-1) + * @param info table of constants for the ratchet function + * @param new_root_key[out] returns the new root key R(n) + * @param new_chain_key[out] returns the first chain key in the new chain + * C(n,0) + */ static void create_chain_key( olm::SharedKey const & root_key, olm::Curve25519KeyPair const & our_key, @@ -55,6 +69,7 @@ static void create_chain_key( static void advance_chain_key( + std::uint32_t chain_index, olm::ChainKey const & chain_key, olm::ChainKey & new_chain_key ) { @@ -64,20 +79,24 @@ static void advance_chain_key( new_chain_key.key ); new_chain_key.index = chain_key.index + 1; + olm::logf(olm::LOG_DEBUG, LOG_CATEGORY, "Derived chain key C(%i,%i)", + chain_index, new_chain_key.index); } static void create_message_keys( + std::uint32_t chain_index, olm::ChainKey const & chain_key, olm::KdfInfo const & info, - olm::MessageKey & message_key -) { + olm::MessageKey & message_key) { olm::hmac_sha256( chain_key.key, sizeof(chain_key.key), MESSAGE_KEY_SEED, sizeof(MESSAGE_KEY_SEED), message_key.key ); message_key.index = chain_key.index; + olm::logf(olm::LOG_DEBUG, LOG_CATEGORY, "Created message key with chain key C(%i,%i)", + chain_index, message_key.index); } @@ -98,6 +117,7 @@ static std::size_t verify_mac_and_decrypt( static std::size_t verify_mac_and_decrypt_for_existing_chain( olm::Ratchet const & session, + std::uint32_t chain_index, olm::ChainKey const & chain, olm::MessageReader const & reader, std::uint8_t * plaintext, std::size_t max_plaintext_length @@ -114,11 +134,11 @@ static std::size_t verify_mac_and_decrypt_for_existing_chain( olm::ChainKey new_chain = chain; while (new_chain.index < reader.counter) { - advance_chain_key(new_chain, new_chain); + advance_chain_key(chain_index, new_chain, new_chain); } olm::MessageKey message_key; - create_message_keys(new_chain, session.kdf_info, message_key); + create_message_keys(chain_index, new_chain, session.kdf_info, message_key); std::size_t result = verify_mac_and_decrypt( session.ratchet_cipher, message_key, reader, @@ -150,14 +170,17 @@ static std::size_t verify_mac_and_decrypt_for_new_chain( } olm::load_array(new_chain.ratchet_key.public_key, reader.ratchet_key); + std::uint32_t chain_index = session.chain_index + 1; create_chain_key( session.root_key, session.sender_chain[0].ratchet_key, new_chain.ratchet_key, session.kdf_info, new_root_key, new_chain.chain_key ); + olm::logf(olm::LOG_DEBUG, LOG_CATEGORY, "Calculated new receiver chain R(%i)", + chain_index); std::size_t result = verify_mac_and_decrypt_for_existing_chain( - session, new_chain.chain_key, reader, + session, chain_index, new_chain.chain_key, reader, plaintext, max_plaintext_length ); olm::unset(new_root_key); @@ -194,7 +217,9 @@ void olm::Ratchet::initialise_as_bob( pos = olm::load_array(root_key, pos); pos = olm::load_array(receiver_chains[0].chain_key.key, pos); receiver_chains[0].ratchet_key = their_ratchet_key; + chain_index = 0; olm::unset(derived_secrets); + olm::logf(olm::LOG_DEBUG, LOG_CATEGORY, "Initialised receiver chain R(0)"); } @@ -215,7 +240,9 @@ void olm::Ratchet::initialise_as_alice( pos = olm::load_array(root_key, pos); pos = olm::load_array(sender_chain[0].chain_key.key, pos); sender_chain[0].ratchet_key = our_ratchet_key; + chain_index = 0; olm::unset(derived_secrets); + olm::logf(olm::LOG_DEBUG, LOG_CATEGORY, "Initialised sender chain R(0)"); } namespace olm { @@ -353,6 +380,7 @@ std::size_t olm::pickle_length( length += olm::pickle_length(value.sender_chain); length += olm::pickle_length(value.receiver_chains); length += olm::pickle_length(value.skipped_message_keys); + length += olm::pickle_length(value.chain_index); return length; } @@ -364,6 +392,7 @@ std::uint8_t * olm::pickle( pos = pickle(pos, value.sender_chain); pos = pickle(pos, value.receiver_chains); pos = pickle(pos, value.skipped_message_keys); + pos = pickle(pos, value.chain_index); return pos; } @@ -376,6 +405,7 @@ std::uint8_t const * olm::unpickle( pos = unpickle(pos, end, value.sender_chain); pos = unpickle(pos, end, value.receiver_chains); pos = unpickle(pos, end, value.skipped_message_keys); + pos = unpickle(pos, end, value.chain_index); return pos; } @@ -420,6 +450,9 @@ std::size_t olm::Ratchet::encrypt( if (sender_chain.empty()) { sender_chain.insert(); olm::curve25519_generate_key(random, sender_chain[0].ratchet_key); + olm::logf(olm::LOG_DEBUG, LOG_CATEGORY, "Created new ratchet key T(%i) %s", + chain_index + 1, + sender_chain[0].ratchet_key.to_string().c_str()); create_chain_key( root_key, sender_chain[0].ratchet_key, @@ -427,11 +460,14 @@ std::size_t olm::Ratchet::encrypt( kdf_info, root_key, sender_chain[0].chain_key ); + olm::logf(olm::LOG_DEBUG, LOG_CATEGORY, "Initialised new sender chain R(%i)", + chain_index + 1); + chain_index++; } MessageKey keys; - create_message_keys(sender_chain[0].chain_key, kdf_info, keys); - advance_chain_key(sender_chain[0].chain_key, sender_chain[0].chain_key); + create_message_keys(chain_index, sender_chain[0].chain_key, kdf_info, keys); + advance_chain_key(chain_index, sender_chain[0].chain_key, sender_chain[0].chain_key); std::size_t ciphertext_length = ratchet_cipher.encrypt_ciphertext_length( plaintext_length @@ -455,6 +491,14 @@ std::size_t olm::Ratchet::encrypt( output, output_length ); + olm::logf(olm::LOG_TRACE, LOG_CATEGORY, + "Encoded message ver=%i ratchet_key=%s chain_idx=%i ciphertext=%s", + PROTOCOL_VERSION, + olm::bytes_to_string(writer.ratchet_key, olm::KEY_LENGTH).c_str(), + counter, + olm::bytes_to_string(writer.ciphertext, ciphertext_length).c_str() + ); + olm::unset(keys); return output_length; } @@ -481,6 +525,10 @@ std::size_t olm::Ratchet::decrypt( std::uint8_t const * input, std::size_t input_length, std::uint8_t * plaintext, std::size_t max_plaintext_length ) { + olm::logf(olm::LOG_TRACE, LOG_CATEGORY, + "Decrypting message %s", + olm::bytes_to_string(input, input_length).c_str()); + olm::MessageReader reader; olm::decode_message( reader, input, input_length, ratchet_cipher.mac_length() @@ -511,6 +559,13 @@ std::size_t olm::Ratchet::decrypt( } ReceiverChain * chain = nullptr; + auto receiver_chain_index = chain_index; + if (!sender_chain.empty()) { + // we've already advanced to the next (sender) chain; decrement to + // get back to the receiver chains + receiver_chain_index --; + } + for (olm::ReceiverChain & receiver_chain : receiver_chains) { if (0 == std::memcmp( receiver_chain.ratchet_key.public_key, reader.ratchet_key, @@ -519,11 +574,14 @@ std::size_t olm::Ratchet::decrypt( chain = &receiver_chain; break; } + receiver_chain_index -= 2; } std::size_t result = std::size_t(-1); if (!chain) { + olm::logf(olm::LOG_DEBUG, LOG_CATEGORY, + "Sender ratchet key does not match known chain; starting new one"); result = verify_mac_and_decrypt_for_new_chain( *this, reader, plaintext, max_plaintext_length ); @@ -555,7 +613,8 @@ std::size_t olm::Ratchet::decrypt( } } else { result = verify_mac_and_decrypt_for_existing_chain( - *this, chain->chain_key, reader, plaintext, max_plaintext_length + *this, receiver_chain_index, chain->chain_key, + reader, plaintext, max_plaintext_length ); } @@ -565,28 +624,36 @@ std::size_t olm::Ratchet::decrypt( } if (!chain) { - /* They have started using a new empheral ratchet key. + /* They have started using a new ephemeral ratchet key. * We need to derive a new set of chain keys. * We can discard our previous empheral ratchet key. * We will generate a new key when we send the next message. */ + chain = receiver_chains.insert(); olm::load_array(chain->ratchet_key.public_key, reader.ratchet_key); + + // TODO: we've already done this once, in + // verify_mac_and_decrypt_for_new_chain(). we could reuse the result. create_chain_key( root_key, sender_chain[0].ratchet_key, chain->ratchet_key, kdf_info, root_key, chain->chain_key ); + olm::unset(sender_chain[0]); sender_chain.erase(sender_chain.begin()); + receiver_chain_index = ++chain_index; + olm::logf(olm::LOG_DEBUG, LOG_CATEGORY, "Initialised new receiver chain R(%i)", + chain_index); } while (chain->chain_key.index < reader.counter) { olm::SkippedMessageKey & key = *skipped_message_keys.insert(); - create_message_keys(chain->chain_key, kdf_info, key.message_key); + create_message_keys(receiver_chain_index, chain->chain_key, kdf_info, key.message_key); key.ratchet_key = chain->ratchet_key; - advance_chain_key(chain->chain_key, chain->chain_key); + advance_chain_key(receiver_chain_index, chain->chain_key, chain->chain_key); } - advance_chain_key(chain->chain_key, chain->chain_key); + advance_chain_key(receiver_chain_index, chain->chain_key, chain->chain_key); return result; } diff --git a/src/session.cpp b/src/session.cpp index 71c80e4..6a9bb7e 100644 --- a/src/session.cpp +++ b/src/session.cpp @@ -1,4 +1,4 @@ -/* Copyright 2015 OpenMarket Ltd +/* Copyright 2015, 2016 OpenMarket Ltd * * Licensed under the Apache License, Version 2.0 (the "License"); * you may not use this file except in compliance with the License. @@ -16,6 +16,7 @@ #include "olm/cipher.hh" #include "olm/crypto.hh" #include "olm/account.hh" +#include "olm/logging.hh" #include "olm/memory.hh" #include "olm/message.hh" #include "olm/pickle.hh" @@ -24,6 +25,8 @@ namespace { +static const char *LOG_CATEGORY = "olm::Session"; + static const std::uint8_t PROTOCOL_VERSION = 0x3; static const std::uint8_t ROOT_KDF_INFO[] = "OLM_ROOT"; @@ -65,11 +68,21 @@ std::size_t olm::Session::new_outbound_session( return std::size_t(-1); } + olm::logf(olm::LOG_DEBUG, LOG_CATEGORY, + "Creating new outbound session to receiver identity IB %s, " + "receiver ephemeral EB %s", identity_key.to_string().c_str(), + one_time_key.to_string().c_str() + ); + olm::Curve25519KeyPair base_key; olm::curve25519_generate_key(random, base_key); + olm::logf(olm::LOG_DEBUG, LOG_CATEGORY, "Created new ephemeral key EA %s", + base_key.to_string().c_str()); olm::Curve25519KeyPair ratchet_key; olm::curve25519_generate_key(random + olm::KEY_LENGTH, ratchet_key); + olm::logf(olm::LOG_DEBUG, LOG_CATEGORY, "Created new ratchet key T(0) %s", + ratchet_key.to_string().c_str()); olm::Curve25519KeyPair const & alice_identity_key_pair = ( local_account.identity_keys.curve25519_key @@ -95,6 +108,7 @@ std::size_t olm::Session::new_outbound_session( olm::unset(ratchet_key); olm::unset(secret); + olm::logf(olm::LOG_DEBUG, LOG_CATEGORY, "Initialised outbound session"); return std::size_t(0); } @@ -137,11 +151,29 @@ std::size_t olm::Session::new_inbound_session( their_identity_key->public_key, reader.identity_key, olm::KEY_LENGTH ); if (!same) { + olm::logf(olm::LOG_INFO, LOG_CATEGORY, + "Identity key on received message is incorrect " + "(expected %s, got %s)", + their_identity_key->to_string().c_str(), + olm::bytes_to_string(reader.identity_key, + reader.identity_key + olm::KEY_LENGTH) + .c_str()); last_error = olm::ErrorCode::BAD_MESSAGE_KEY_ID; return std::size_t(-1); } } + olm::load_array(alice_identity_key.public_key, reader.identity_key); + olm::load_array(alice_base_key.public_key, reader.base_key); + olm::load_array(bob_one_time_key.public_key, reader.one_time_key); + + olm::logf(olm::LOG_DEBUG, LOG_CATEGORY, + "Creating new inbound session from sender identity IA %s, " + "sender ephemeral EA %s, our ephemeral EB %s", + alice_identity_key.to_string().c_str(), + alice_base_key.to_string().c_str(), + bob_one_time_key.to_string().c_str()); + olm::MessageReader message_reader; decode_message( message_reader, reader.message, reader.message_length, @@ -154,17 +186,20 @@ std::size_t olm::Session::new_inbound_session( return std::size_t(-1); } - olm::load_array(alice_identity_key.public_key, reader.identity_key); - olm::load_array(alice_base_key.public_key, reader.base_key); - olm::load_array(bob_one_time_key.public_key, reader.one_time_key); olm::Curve25519PublicKey ratchet_key; olm::load_array(ratchet_key.public_key, message_reader.ratchet_key); + olm::logf(olm::LOG_DEBUG, LOG_CATEGORY, + "Received ratchet key T(0) %s", ratchet_key.to_string().c_str()); + olm::OneTimeKey const * our_one_time_key = local_account.lookup_key( bob_one_time_key ); if (!our_one_time_key) { + olm::logf(olm::LOG_INFO, LOG_CATEGORY, + "Session uses unknown ephemeral key %s", + bob_one_time_key.to_string().c_str()); last_error = olm::ErrorCode::BAD_MESSAGE_KEY_ID; return std::size_t(-1); } @@ -185,6 +220,8 @@ std::size_t olm::Session::new_inbound_session( ratchet.initialise_as_bob(secret, sizeof(secret), ratchet_key); olm::unset(secret); + + olm::logf(olm::LOG_DEBUG, LOG_CATEGORY, "Initialised inbound session"); return std::size_t(0); } @@ -283,6 +320,9 @@ std::size_t olm::Session::encrypt( std::uint8_t const * random, std::size_t random_length, std::uint8_t * message, std::size_t message_length ) { + olm::logf(olm::LOG_DEBUG, LOG_CATEGORY, "Encrypting '%.*s'", + (int)plaintext_length, plaintext); + if (message_length < encrypt_message_length(plaintext_length)) { last_error = olm::ErrorCode::OUTPUT_BUFFER_TOO_SMALL; return std::size_t(-1); @@ -309,6 +349,16 @@ std::size_t olm::Session::encrypt( olm::store_array(writer.identity_key, alice_identity_key.public_key); olm::store_array(writer.base_key, alice_base_key.public_key); message_body = writer.message; + + + olm::logf(olm::LOG_DEBUG, LOG_CATEGORY, + "Encoded pre-key message ver=%i one_time_key[Eb]=%s " + "base_key[Ea]=%s identity_key[Ia]=%s", + PROTOCOL_VERSION, + olm::bytes_to_string(writer.one_time_key, olm::KEY_LENGTH).c_str(), + olm::bytes_to_string(writer.base_key, olm::KEY_LENGTH).c_str(), + olm::bytes_to_string(writer.identity_key, olm::KEY_LENGTH).c_str() + ); } std::size_t result = ratchet.encrypt( @@ -320,7 +370,12 @@ std::size_t olm::Session::encrypt( if (result == std::size_t(-1)) { last_error = ratchet.last_error; ratchet.last_error = olm::ErrorCode::SUCCESS; + return result; } + + olm::logf(olm::LOG_TRACE, LOG_CATEGORY, "Encrypted message %s", + olm::bytes_to_string(message_body, result).c_str()); + return result; } @@ -362,6 +417,9 @@ std::size_t olm::Session::decrypt( std::uint8_t const * message, std::size_t message_length, std::uint8_t * plaintext, std::size_t max_plaintext_length ) { + olm::logf(olm::LOG_TRACE, LOG_CATEGORY, "Decrypting %smessage", + message_type == olm::MessageType::MESSAGE ? "" : "pre-key "); + std::uint8_t const * message_body; std::size_t message_body_length; if (message_type == olm::MessageType::MESSAGE) { @@ -385,9 +443,12 @@ std::size_t olm::Session::decrypt( if (result == std::size_t(-1)) { last_error = ratchet.last_error; ratchet.last_error = olm::ErrorCode::SUCCESS; - } else { - received_message = true; + return result; } + + received_message = true; + olm::logf(olm::LOG_DEBUG, LOG_CATEGORY, "Decrypted '%.*s'", + (int)result, plaintext); return result; } @@ -440,4 +501,3 @@ std::uint8_t const * olm::unpickle( pos = olm::unpickle(pos, end, value.ratchet); return pos; } - -- cgit v1.2.3