aboutsummaryrefslogtreecommitdiff
path: root/src/session.cpp
diff options
context:
space:
mode:
authorRichard van der Hoff <richard@matrix.org>2016-04-26 11:44:32 +0100
committerRichard van der Hoff <richard@matrix.org>2016-04-26 17:55:26 +0100
commit9848f8445292ad3f7ff92bd4abfeb8f2d08ec32d (patch)
tree36f1f030f71bd16b85e0fe1aa77c42f457a3b168 /src/session.cpp
parente7a2af1ede768589e612bad1c61b10186a1bb686 (diff)
Add some logging to help understand what's going on
Diffstat (limited to 'src/session.cpp')
-rw-r--r--src/session.cpp74
1 files changed, 67 insertions, 7 deletions
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;
}
-