More logging

Log some of the secrets at trace level.

include/olm/logging.h

@@ -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_ */

include/olm/memory.hh

@@ -87,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/olm.h

@@ -442,6 +442,13 @@ size_t olm_ed25519_verify(
     void * signature, size_t signature_length
 );
 
+/**
+ * Set the log level. By default, 1, which logs only FATAL messages.
+ */
+void olm_set_log_level(
+    unsigned int level
+);
+
 #ifdef __cplusplus
 }
 #endif

include/olm/ratchet.hh

@@ -88,6 +88,16 @@ struct Ratchet {
     /** The last error that happened encrypting or decrypting a message. */
     OlmErrorCode 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 new chain is started. */
     SharedKey root_key;

javascript/olm_post.js

@@ -410,6 +410,8 @@ olm_exports["Account"] = Account;
 olm_exports["Session"] = Session;
 olm_exports["Utility"] = Utility;
 
+olm_exports['set_log_level'] = Module['_olm_set_log_level'];
+
 olm_exports["get_library_version"] = restore_stack(function() {
     var buf = stack(3);
     Module['_olm_get_library_version'](buf, buf+1, buf+2);

python/olm/__init__.py

@@ -1,4 +1,5 @@
 from .account import Account
+from .account import set_log_level
 from .session import Session
 from .outbound_group_session import OutboundGroupSession
 from .inbound_group_session import InboundGroupSession

python/olm/__main__.py

@@ -18,6 +18,8 @@ def read_base64_file(filename):
 def build_arg_parser():
     parser = argparse.ArgumentParser()
     parser.add_argument("--key", help="Account encryption key", default="")
+    parser.add_argument("--log-level", help="Log level", type=int, default=None)
+
     commands = parser.add_subparsers()
 
     create_account = commands.add_parser("create_account", help="Create a new account")
@@ -336,4 +338,7 @@ def do_group_decrypt(args):
 if __name__ == '__main__':
     parser = build_arg_parser()
     args = parser.parse_args()
+    if args.log_level is not None:
+        set_log_level(args.log_level)
+
     args.func(args)

python/olm/account.py

@@ -2,6 +2,11 @@ import json
 
 from ._base import *
 
+lib.olm_set_log_level.argtypes = [c_uint]
+lib.olm_set_log_level.restype = None
+
+set_log_level = lib.olm_set_log_level
+
 lib.olm_account_size.argtypes = []
 lib.olm_account_size.restype = c_size_t
 

src/account.cpp

@@ -14,10 +14,13 @@
  */
 #include "olm/account.hh"
 #include "olm/base64.hh"
+#include "olm/logging.h"
 #include "olm/pickle.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(OlmErrorCode::OLM_SUCCESS) {
@@ -43,9 +46,11 @@ std::size_t olm::Account::remove_key(
         if (olm::array_equal(i->key.public_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);
 }
 
@@ -65,6 +70,8 @@ std::size_t olm::Account::new_account(
     random += ED25519_RANDOM_LENGTH;
     _olm_crypto_curve25519_generate_key(random, &identity_keys.curve25519_key);
 
+    olm_logf(OLM_LOG_DEBUG, LOG_CATEGORY, "Created new account");
+
     return 0;
 }
 

src/logging.c

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

src/message.cpp

@@ -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,6 +334,16 @@ 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/olm.cpp

@@ -20,6 +20,7 @@
 #include "olm/utility.hh"
 #include "olm/base64.hh"
 #include "olm/memory.hh"
+#include "olm/logging.h"
 
 #include <new>
 #include <cstring>

src/ratchet.cpp

@@ -17,11 +17,14 @@
 #include "olm/memory.hh"
 #include "olm/cipher.h"
 #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};
@@ -49,6 +52,11 @@ static void create_chain_key(
 ) {
     olm::SharedKey secret;
     _olm_crypto_curve25519_shared_secret(&our_key, &their_key, secret);
+    olm_logf(
+        OLM_LOG_TRACE, LOG_CATEGORY, "Shared secret for new chain: %s",
+        olm::bytes_to_string(secret, olm::OLM_SHARED_KEY_LENGTH).c_str()
+    );
+
     std::uint8_t derived_secrets[2 * olm::OLM_SHARED_KEY_LENGTH];
     _olm_crypto_hkdf_sha256(
         secret, sizeof(secret),
@@ -66,6 +74,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
 ) {
@@ -75,10 +84,13 @@ 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) {
@@ -88,6 +100,11 @@ 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);
+    olm_logf(OLM_LOG_TRACE, LOG_CATEGORY, "Message key for C(%i,%i) is %s",
+             chain_index, message_key.index,
+             olm::bytes_to_string(message_key.key, olm::OLM_SHARED_KEY_LENGTH).c_str());
 }
 
 
@@ -109,6 +126,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
@@ -125,11 +143,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,
@@ -161,13 +179,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);
@@ -204,7 +226,14 @@ 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)");
+    olm_logf(OLM_LOG_TRACE, LOG_CATEGORY, "Root key R(0) is %s",
+             olm::bytes_to_string(root_key, olm::OLM_SHARED_KEY_LENGTH).c_str());
+    olm_logf(OLM_LOG_TRACE, LOG_CATEGORY, "Chain key C(0,0) is %s",
+             olm::bytes_to_string(receiver_chains[0].chain_key.key,
+                                  olm::OLM_SHARED_KEY_LENGTH).c_str());
 }
 
 
@@ -225,7 +254,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 {
@@ -363,6 +394,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;
 }
 
@@ -374,6 +406,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;
 }
 
@@ -390,8 +423,7 @@ std::uint8_t const * olm::unpickle(
 
     // pickle v 0x80000001 includes a chain index; pickle v1 does not.
     if (includes_chain_index) {
-        std::uint32_t dummy;
+        pos = unpickle(pos, end, value.chain_index);
-        pos = unpickle(pos, end, dummy);
     }
     return pos;
 }
@@ -438,6 +470,14 @@ std::size_t olm::Ratchet::encrypt(
     if (sender_chain.empty()) {
         sender_chain.insert();
         _olm_crypto_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,
+            olm::bytes_to_string(
+                std::begin(sender_chain[0].ratchet_key.public_key.public_key),
+                std::end(sender_chain[0].ratchet_key.public_key.public_key)
+            ).c_str()
+        );
         create_chain_key(
             root_key,
             sender_chain[0].ratchet_key,
@@ -445,11 +485,23 @@ 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);
+        olm_logf(
+            OLM_LOG_TRACE, LOG_CATEGORY, "Root key R(%i): %s", chain_index + 1,
+            olm::bytes_to_string(root_key, OLM_SHARED_KEY_LENGTH).c_str()
+        );
+        olm_logf(
+            OLM_LOG_TRACE, LOG_CATEGORY, "Chain key C(%i, 0): %s", chain_index + 1,
+            olm::bytes_to_string(sender_chain[0].chain_key.key, OLM_SHARED_KEY_LENGTH).c_str()
+        );
+
+        chain_index++;
     }
 
     MessageKey keys;
-    create_message_keys(sender_chain[0].chain_key, kdf_info, keys);
+    create_message_keys(chain_index, sender_chain[0].chain_key, kdf_info, keys);
-    advance_chain_key(sender_chain[0].chain_key, sender_chain[0].chain_key);
+    advance_chain_key(chain_index, sender_chain[0].chain_key, sender_chain[0].chain_key);
 
     std::size_t ciphertext_length = ratchet_cipher->ops->encrypt_ciphertext_length(
         ratchet_cipher,
@@ -477,6 +529,15 @@ 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, CURVE25519_KEY_LENGTH).c_str(),
+        counter,
+        olm::bytes_to_string(writer.ciphertext, ciphertext_length).c_str()
+    );
+
     olm::unset(keys);
     return output_length;
 }
@@ -505,6 +566,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,
@@ -537,6 +602,12 @@ 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(
@@ -546,11 +617,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
         );
@@ -582,7 +656,7 @@ std::size_t olm::Ratchet::decrypt(
         }
     } else {
         result = verify_mac_and_decrypt_for_existing_chain(
-            *this, chain->chain_key,
+            *this, receiver_chain_index, chain->chain_key,
             reader, plaintext, max_plaintext_length
         );
     }
@@ -610,16 +684,19 @@ 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) {
         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

@@ -16,6 +16,7 @@
 #include "olm/cipher.h"
 #include "olm/crypto.h"
 #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";
@@ -38,6 +41,23 @@ static const olm::KdfInfo OLM_KDF_INFO = {
 static const struct _olm_cipher_aes_sha_256 OLM_CIPHER =
     OLM_CIPHER_INIT_AES_SHA_256(CIPHER_KDF_INFO);
 
+
+static std::string to_string(const _olm_curve25519_public_key *key) {
+    return olm::bytes_to_string(
+        std::begin(key->public_key),
+        std::end(key->public_key)
+    );
+};
+
+static std::string to_string(const _olm_curve25519_key_pair *key) {
+    return olm::bytes_to_string(
+        std::begin(key->public_key.public_key),
+        std::end(key->public_key.public_key)
+    );
+};
+
+
+
 } // namespace
 
 olm::Session::Session(
@@ -64,11 +84,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", to_string(&identity_key).c_str(),
+              to_string(&one_time_key).c_str()
+    );
+
     _olm_curve25519_key_pair base_key;
     _olm_crypto_curve25519_generate_key(random, &base_key);
+    olm_logf(OLM_LOG_DEBUG, LOG_CATEGORY, "Created new ephemeral key EA %s",
+              to_string(&base_key).c_str());
 
     _olm_curve25519_key_pair ratchet_key;
     _olm_crypto_curve25519_generate_key(random + CURVE25519_RANDOM_LENGTH, &ratchet_key);
+    olm_logf(OLM_LOG_DEBUG, LOG_CATEGORY, "Created new ratchet key T(0) %s",
+              to_string(&ratchet_key).c_str());
 
     _olm_curve25519_key_pair const & alice_identity_key_pair = (
         local_account.identity_keys.curve25519_key
@@ -89,12 +119,16 @@ std::size_t olm::Session::new_outbound_session(
     pos += CURVE25519_SHARED_SECRET_LENGTH;
     _olm_crypto_curve25519_shared_secret(&base_key, &one_time_key, pos);
 
+    olm_logf(OLM_LOG_TRACE, LOG_CATEGORY,
+             "Initial shared secret %s", bytes_to_string(secret, pos).c_str());
+
     ratchet.initialise_as_alice(secret, sizeof(secret), ratchet_key);
 
     olm::unset(base_key);
     olm::unset(ratchet_key);
     olm::unset(secret);
 
+    olm_logf(OLM_LOG_DEBUG, LOG_CATEGORY, "Initialised outbound session");
     return std::size_t(0);
 }
 
@@ -137,6 +171,14 @@ std::size_t olm::Session::new_inbound_session(
             their_identity_key->public_key, reader.identity_key, CURVE25519_KEY_LENGTH
         );
         if (!same) {
+            olm_logf(OLM_LOG_INFO, LOG_CATEGORY,
+                      "Identity key on received message is incorrect "
+                      "(expected %s, got %s)",
+                      to_string(their_identity_key).c_str(),
+                      olm::bytes_to_string(
+                          reader.identity_key,
+                          reader.identity_key + CURVE25519_KEY_LENGTH
+                      ).c_str());
             last_error = OlmErrorCode::OLM_BAD_MESSAGE_KEY_ID;
             return std::size_t(-1);
         }
@@ -146,6 +188,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",
+              to_string(&alice_identity_key).c_str(),
+              to_string(&alice_base_key).c_str(),
+              to_string(&bob_one_time_key).c_str());
+
     olm::MessageReader message_reader;
     decode_message(
         message_reader, reader.message, reader.message_length,
@@ -161,11 +210,17 @@ std::size_t olm::Session::new_inbound_session(
     _olm_curve25519_public_key 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", to_string(&ratchet_key).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",
+                  to_string(&bob_one_time_key).c_str());
         last_error = OlmErrorCode::OLM_BAD_MESSAGE_KEY_ID;
         return std::size_t(-1);
     }
@@ -184,10 +239,14 @@ std::size_t olm::Session::new_inbound_session(
     pos += CURVE25519_SHARED_SECRET_LENGTH;
     _olm_crypto_curve25519_shared_secret(&bob_one_time_key, &alice_base_key, pos);
 
+    olm_logf(OLM_LOG_DEBUG, LOG_CATEGORY,
+             "Initial shared secret %s", bytes_to_string(secret, pos).c_str());
+
     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);
 }
 
@@ -286,6 +345,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 = OlmErrorCode::OLM_OUTPUT_BUFFER_TOO_SMALL;
         return std::size_t(-1);
@@ -312,6 +374,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, CURVE25519_KEY_LENGTH).c_str(),
+                  olm::bytes_to_string(writer.base_key, CURVE25519_KEY_LENGTH).c_str(),
+                  olm::bytes_to_string(writer.identity_key, CURVE25519_KEY_LENGTH).c_str()
+        );
     }
 
     std::size_t result = ratchet.encrypt(
@@ -326,6 +398,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;
 }
 
@@ -367,6 +442,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) {
@@ -394,13 +472,15 @@ std::size_t olm::Session::decrypt(
     }
 
     received_message = true;
+    olm_logf(OLM_LOG_DEBUG, LOG_CATEGORY, "Decrypted '%.*s'",
+              (int)result, plaintext);
     return result;
 }
 
 namespace {
 // the master branch writes pickle version 1; the logging_enabled branch writes
 // 0x80000001.
-static const std::uint32_t SESSION_PICKLE_VERSION = 1;
+static const std::uint32_t SESSION_PICKLE_VERSION = 0x80000001;
 }
 
 std::size_t olm::pickle_length(