Skip to content
GitLab
Commit 9848f844 authored by Richard van der Hoff's avatar Richard van der Hoff
Browse files

Add some logging to help understand what's going on

parent e7a2af1e
Hide whitespace changes
Inline Side-by-side
include/olm/crypto.hh
View file @ 9848f844
......@@ -17,6 +17,7 @@
#include <cstdint>
#include <cstddef>
#include <string>
namespace olm {
......@@ -26,6 +27,7 @@ static const std::size_t IV_LENGTH = 16;
struct Curve25519PublicKey {
std::uint8_t public_key[KEY_LENGTH];
std::string to_string() const;
};
......
include/olm/logging.hh
View file @ 9848f844
......@@ -23,6 +23,7 @@ const unsigned int LOG_ERROR = 2;
const unsigned int LOG_WARNING = 3;
const unsigned int LOG_INFO = 4;
const unsigned int LOG_DEBUG = 5;
const unsigned int LOG_TRACE = 6;
void set_log_level(unsigned int log_level);
......
include/olm/memory.hh
View file @ 9848f844
/* 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.
......@@ -15,6 +15,9 @@
#include <cstddef>
#include <cstdint>
#include <cstring>
#include <iomanip>
#include <iostream>
#include <sstream>
#include <type_traits>
namespace olm {
......@@ -84,4 +87,23 @@ std::uint8_t * store_array(
return destination + sizeof(T);
}
/** convert an array of bytes to a string representation */
template<typename T>
std::string bytes_to_string(T start, T end) {
std::ostringstream ss;
ss << std::hex << std::setfill('0');
while (start != end) {
ss << std::setw(2) << static_cast<int>(*start++);
if (start != end) {
ss << ":";
}
}
return ss.str();
}
template<typename T>
std::string bytes_to_string(T start, size_t len) {
return bytes_to_string(start, start+len);
}
} // namespace olm
include/olm/ratchet.hh
View file @ 9848f844
......@@ -29,7 +29,6 @@ struct ChainKey {
SharedKey key;
};
struct MessageKey {
std::uint32_t index;
SharedKey key;
......@@ -82,8 +81,18 @@ struct Ratchet {
/** The last error that happened encrypting or decrypting a message. */
ErrorCode last_error;
/**
* A count of the number of times the root key has been advanced; this is
* maintained purely for diagnostics.
*
* If sender_chain is empty, this will be the index of the current receiver
* chain (odd for Alice, even for Bob); otherwise, the index of the current
* sender chain (even for Alice, odd for Bob).
*/
std::uint32_t chain_index;
/** The root key is used to generate chain keys from the ephemeral keys.
* A new root_key derived each time a chain key is derived. */
* A new root_key derived each time a new chain is started. */
SharedKey root_key;
/** The sender chain is used to send messages. Each time a new ephemeral
......
javascript/demo.html
View file @ 9848f844
<html>
<head>
<script src="../build/olm.js"></script>
<script src="olm.js"></script>
<script>
document.addEventListener("DOMContentLoaded", function (event) {
function progress(who, message) {
var message_element = document.createElement("pre");
......
src/account.cpp
View file @ 9848f844
/* 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;
}
......
src/crypto.cpp
View file @ 9848f844
......@@ -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,
......
src/message.cpp
View file @ 9848f844
......@@ -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<typename T>
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()
);
}
src/ratchet.cpp
View file @ 9848f844
/* 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 <cstring>
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;
}
src/session.cpp
View file @ 9848f844
/* 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
) {