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/session.cpp | 74 +++++++++++++++++++++++++++++++++++++++++++++++++++------ 1 file changed, 67 insertions(+), 7 deletions(-) (limited to 'src/session.cpp') 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