Add some logging to help understand what's going on

5 files changed, 182 insertions, 22 deletions

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<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()
+    );
 }
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 <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;
 }
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;
 }
-