Re-enable logging
A separate branch which retains logging functionality, for debugging and/or documentation purposes. (This branch is currently lacking support for C sources, so won't compile correctly.)
This commit is contained in:
parent
46bc4ff82e
commit
8feb428579
7 changed files with 208 additions and 0 deletions
44
include/olm/logging.h
Normal file
44
include/olm/logging.h
Normal file
|
@ -0,0 +1,44 @@
|
|||
/* Copyright 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.
|
||||
* You may obtain a copy of the License at
|
||||
*
|
||||
* http://www.apache.org/licenses/LICENSE-2.0
|
||||
*
|
||||
* Unless required by applicable law or agreed to in writing, software
|
||||
* distributed under the License is distributed on an "AS IS" BASIS,
|
||||
* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
|
||||
* See the License for the specific language governing permissions and
|
||||
* limitations under the License.
|
||||
*/
|
||||
|
||||
#ifndef OLM_LOGGING_H_
|
||||
#define OLM_LOGGING_H_
|
||||
|
||||
#include "olm/olm.hh"
|
||||
|
||||
#ifdef __cplusplus
|
||||
extern "C" {
|
||||
#endif
|
||||
|
||||
#define OLM_LOG_FATAL 1
|
||||
#define OLM_LOG_ERROR 2
|
||||
#define OLM_LOG_WARNING 3
|
||||
#define OLM_LOG_INFO 4
|
||||
#define OLM_LOG_DEBUG 5
|
||||
#define OLM_LOG_TRACE 6
|
||||
|
||||
/* returns non-zero if logging is enabled for this level */
|
||||
int olm_log_enabled_for(unsigned int level, const char *category);
|
||||
|
||||
__attribute__((__format__ (__printf__, 3, 4)))
|
||||
void olm_logf(unsigned int level, const char *category,
|
||||
const char *format, ...);
|
||||
|
||||
|
||||
#ifdef __cplusplus
|
||||
} // extern "C"
|
||||
#endif
|
||||
|
||||
#endif /* OLM_LOGGING_H_ */
|
|
@ -14,9 +14,12 @@
|
|||
*/
|
||||
#include "olm/account.hh"
|
||||
#include "olm/base64.hh"
|
||||
#include "olm/logging.h"
|
||||
#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;
|
||||
}
|
||||
|
||||
|
|
47
src/logging.c
Normal file
47
src/logging.c
Normal file
|
@ -0,0 +1,47 @@
|
|||
/* Copyright 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.
|
||||
* You may obtain a copy of the License at
|
||||
*
|
||||
* http://www.apache.org/licenses/LICENSE-2.0
|
||||
*
|
||||
* Unless required by applicable law or agreed to in writing, software
|
||||
* distributed under the License is distributed on an "AS IS" BASIS,
|
||||
* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
|
||||
* See the License for the specific language governing permissions and
|
||||
* limitations under the License.
|
||||
*/
|
||||
|
||||
#include "olm/logging.h"
|
||||
|
||||
#include <stdarg.h>
|
||||
#include <stdio.h>
|
||||
|
||||
static unsigned int log_level = 1;
|
||||
|
||||
void olm_set_log_level(unsigned int level) {
|
||||
log_level = level;
|
||||
}
|
||||
|
||||
int olm_log_enabled_for(unsigned int level, const char *category)
|
||||
{
|
||||
return level <= log_level;
|
||||
}
|
||||
|
||||
void olm_logf(unsigned int level, const char *category,
|
||||
const char *format, ...) {
|
||||
if (level > log_level) {
|
||||
return;
|
||||
}
|
||||
|
||||
fputs(category, stdout);
|
||||
fputs(": ", stdout);
|
||||
|
||||
va_list ap;
|
||||
va_start(ap, format);
|
||||
vprintf(format, ap);
|
||||
va_end(ap);
|
||||
|
||||
putchar('\n');
|
||||
}
|
|
@ -14,10 +14,13 @@
|
|||
*/
|
||||
#include "olm/message.hh"
|
||||
|
||||
#include "olm/logging.h"
|
||||
#include "olm/memory.hh"
|
||||
|
||||
namespace {
|
||||
|
||||
static const char *LOG_CATEGORY = "olm::Message";
|
||||
|
||||
template<typename T>
|
||||
static std::size_t varint_length(
|
||||
T value
|
||||
|
@ -236,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()
|
||||
);
|
||||
}
|
||||
|
||||
|
||||
|
@ -324,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()
|
||||
);
|
||||
}
|
||||
|
|
|
@ -19,6 +19,7 @@
|
|||
#include "olm/base64.hh"
|
||||
#include "olm/cipher.hh"
|
||||
#include "olm/memory.hh"
|
||||
#include "olm/logging.h"
|
||||
|
||||
#include <new>
|
||||
#include <cstring>
|
||||
|
|
|
@ -17,11 +17,14 @@
|
|||
#include "olm/memory.hh"
|
||||
#include "olm/cipher.hh"
|
||||
#include "olm/pickle.hh"
|
||||
#include "olm/logging.h"
|
||||
|
||||
#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};
|
||||
|
@ -76,6 +79,8 @@ 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);
|
||||
}
|
||||
|
||||
|
||||
|
@ -90,6 +95,8 @@ static void create_message_keys(
|
|||
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);
|
||||
}
|
||||
|
||||
|
||||
|
@ -169,6 +176,9 @@ static std::size_t verify_mac_and_decrypt_for_new_chain(
|
|||
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, chain_index, new_chain.chain_key, reader,
|
||||
plaintext, max_plaintext_length
|
||||
|
@ -209,6 +219,7 @@ void olm::Ratchet::initialise_as_bob(
|
|||
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)");
|
||||
}
|
||||
|
||||
|
||||
|
@ -231,6 +242,7 @@ void olm::Ratchet::initialise_as_alice(
|
|||
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 {
|
||||
|
@ -438,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,
|
||||
|
@ -445,6 +460,8 @@ 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++;
|
||||
}
|
||||
|
||||
|
@ -474,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;
|
||||
}
|
||||
|
@ -500,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()
|
||||
|
@ -551,6 +580,8 @@ std::size_t olm::Ratchet::decrypt(
|
|||
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
|
||||
);
|
||||
|
@ -611,6 +642,8 @@ std::size_t olm::Ratchet::decrypt(
|
|||
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) {
|
||||
|
|
|
@ -16,6 +16,7 @@
|
|||
#include "olm/cipher.hh"
|
||||
#include "olm/crypto.hh"
|
||||
#include "olm/account.hh"
|
||||
#include "olm/logging.h"
|
||||
#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,6 +151,13 @@ 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);
|
||||
}
|
||||
|
@ -146,6 +167,13 @@ std::size_t olm::Session::new_inbound_session(
|
|||
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,
|
||||
|
@ -161,11 +189,17 @@ std::size_t olm::Session::new_inbound_session(
|
|||
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);
|
||||
}
|
||||
|
@ -187,6 +221,7 @@ std::size_t olm::Session::new_inbound_session(
|
|||
|
||||
olm::unset(secret);
|
||||
|
||||
olm_logf(OLM_LOG_DEBUG, LOG_CATEGORY, "Initialised inbound session");
|
||||
return std::size_t(0);
|
||||
}
|
||||
|
||||
|
@ -285,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);
|
||||
|
@ -311,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(
|
||||
|
@ -325,6 +373,9 @@ std::size_t olm::Session::encrypt(
|
|||
return result;
|
||||
}
|
||||
|
||||
olm_logf(OLM_LOG_TRACE, LOG_CATEGORY, "Encrypted message %s",
|
||||
olm::bytes_to_string(message_body, result).c_str());
|
||||
|
||||
return result;
|
||||
}
|
||||
|
||||
|
@ -366,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) {
|
||||
|
@ -393,6 +447,8 @@ std::size_t olm::Session::decrypt(
|
|||
}
|
||||
|
||||
received_message = true;
|
||||
olm_logf(OLM_LOG_DEBUG, LOG_CATEGORY, "Decrypted '%.*s'",
|
||||
(int)result, plaintext);
|
||||
return result;
|
||||
}
|
||||
|
||||
|
|
Loading…
Reference in a new issue