From 0ddd97a0c9b13b8d7f5b4cf84bf44e40126b5522 Mon Sep 17 00:00:00 2001 From: Gluzskiy Alexandr Date: Thu, 11 May 2017 12:45:29 +0300 Subject: jabber: omemo: added some debug logging into netlib --- protocols/JabberG/src/jabber_omemo.cpp | 108 +++++++++++++++++++++++++++++++++ 1 file changed, 108 insertions(+) diff --git a/protocols/JabberG/src/jabber_omemo.cpp b/protocols/JabberG/src/jabber_omemo.cpp index f0c52edf2e..5378a21e9e 100755 --- a/protocols/JabberG/src/jabber_omemo.cpp +++ b/protocols/JabberG/src/jabber_omemo.cpp @@ -409,11 +409,13 @@ namespace omemo { if (signal_context_set_crypto_provider(global_context, &provider)) { + Netlib_Log(nullptr, "Jabber OMEMO: signal_context_set_crypto_provider failed"); //TODO: handle error } if (signal_context_set_locking_functions(global_context, &lock, &unlock)) { + Netlib_Log(nullptr, "Jabber OMEMO: signal_context_set_locking_functions failed"); //TODO: handle error } @@ -436,6 +438,7 @@ namespace omemo { if (signal_protocol_key_helper_generate_identity_key_pair(&(dev->device_key), global_context)) { + Netlib_Log(nullptr, "Jabber OMEMO: signal_protocol_key_helper_generate_identity_key_pair failed"); //TODO: handle error } @@ -638,9 +641,15 @@ namespace omemo { */ //some sanity checks if ((unsigned long)address->device_id == 0) + { + Netlib_Log(nullptr, "Jabber OMEMO: libsignal data backend impl: failed to load session (invalid device id)"); return -1; + } if (address->name_len > JABBER_MAX_JID_LEN) + { + Netlib_Log(nullptr, "Jabber OMEMO: libsignal data backend impl: failed to load session (invalid address length)"); return -1; + } signal_store_backend_user_data* data = (signal_store_backend_user_data*)user_data; @@ -661,6 +670,7 @@ namespace omemo { if (!dbv.cpbVal) { db_free(&dbv); + Netlib_Log(nullptr, "Jabber OMEMO: libsignal data backend impl: failed to load session (session does not exist)"); return 0; } *record = signal_buffer_create(dbv.pbVal, dbv.cpbVal); @@ -906,6 +916,7 @@ namespace omemo { if (!dbv.cpbVal) { db_free(&dbv); + Netlib_Log(nullptr, "Jabber OMEMO: libsignal data backend impl: failed to load prekey SG_ERR_INVALID_KEY_ID"); return SG_ERR_INVALID_KEY_ID; } *record = signal_buffer_create(dbv.pbVal, dbv.cpbVal); @@ -1045,6 +1056,7 @@ namespace omemo { if (!dbv.cpbVal) { db_free(&dbv); + Netlib_Log(nullptr, "Jabber OMEMO: libsignal data backend impl: failed to load signed prekey SG_ERR_INVALID_KEY_ID"); return SG_ERR_INVALID_KEY_ID; } *record = signal_buffer_create(dbv.pbVal, dbv.cpbVal); @@ -1345,7 +1357,10 @@ namespace omemo { session_builder *builder; if (session_builder_create(&builder, sessions_internal[hContact][dev_id_int].store_context, address, global_context) < 0) + { + Netlib_Log(nullptr, "Jabber OMEMO: session_builder_create failed"); return false; //failure + } sessions_internal[hContact][dev_id_int].builder = builder; @@ -1412,7 +1427,10 @@ namespace omemo { } if (!fp_trusted) + { + Netlib_Log(nullptr, "Jabber OMEMO: untrusted key, session build failure"); return false; //TODO: cleanup here + } pre_key_a = mir_u2a(signed_pre_key_signature); key_buf = (uint8_t*)mir_base64_decode(pre_key_a, &key_buf_len); mir_free(pre_key_a); @@ -1434,6 +1452,7 @@ namespace omemo { //TODO: do necessary actions for untrusted identity break; case SG_ERR_INVALID_KEY: + Netlib_Log(nullptr, "Jabber OMEMO: session_builder_process_pre_key_bundle failure SG_ERR_INVALID_KEY"); return false; //failure break; default: @@ -1444,7 +1463,10 @@ namespace omemo { /* Create the session cipher and encrypt the message */ session_cipher *cipher; if (session_cipher_create(&cipher, sessions_internal[hContact][dev_id_int].store_context, address, global_context) < 0) + { + Netlib_Log(nullptr, "Jabber OMEMO: session_cipher_create failure"); return false; //failure + } sessions_internal[hContact][dev_id_int].cipher = cipher; return true; //success @@ -1465,27 +1487,46 @@ void CJabberProto::OmemoHandleMessage(HXML node, LPCTSTR jid, time_t msgTime) { MCONTACT hContact = HContactFromJID(jid); if (!OmemoCheckSession(hContact)) //TODO: something better here + { + Netlib_Log(nullptr, "Jabber OMEMO: sessions not yet created, session creation launched, message will not be decrypted"); return; + } HXML header_node = XmlGetChild(node, L"header"); if (!header_node) + { + Netlib_Log(nullptr, "Jabber OMEMO: error: omemo message does not contain header"); return; + } HXML payload_node = XmlGetChild(node, L"payload"); if (!payload_node) + { + Netlib_Log(nullptr, "Jabber OMEMO: omemo message does not contain payload, it's may be \"KeyTransportElement\" which is currently unused by our implementation"); return; //this is "KeyTransportElement" which is currently unused + } LPCTSTR payload_base64w = XmlGetText(payload_node); if (!payload_base64w) + { + Netlib_Log(nullptr, "Jabber OMEMO: error: failed to get payload data"); return; + } LPCTSTR iv_base64 = XmlGetText(XmlGetChild(header_node, L"iv")); if (!iv_base64) + { + Netlib_Log(nullptr, "Jabber OMEMO: error: failed to get iv data"); return; + } LPCTSTR sender_dev_id = XmlGetAttrValue(header_node, L"sid"); if (!sender_dev_id) + { + Netlib_Log(nullptr, "Jabber OMEMO: error: failed to get sender device id"); return; + } char *sender_device_id_a = mir_u2a(sender_dev_id); DWORD sender_dev_id_int = strtoul(sender_device_id_a, nullptr, 10); mir_free(sender_device_id_a); if (!omemo::sessions_internal[hContact][sender_dev_id_int].cipher || !omemo::sessions_internal[hContact][sender_dev_id_int].builder || !omemo::sessions_internal[hContact][sender_dev_id_int].store_context) { + Netlib_Log(nullptr, "Jabber OMEMO: bug: omemo session does not exist or broken"); OmemoCheckSession(hContact); //this should not normally happened return; } @@ -1505,7 +1546,10 @@ void CJabberProto::OmemoHandleMessage(HXML node, LPCTSTR jid, time_t msgTime) } } if (!encrypted_key_base64) + { + Netlib_Log(nullptr, "Jabber OMEMO: message does not have decryption key for our device"); return; //node does not contain key for our device + } unsigned int encrypted_key_len; unsigned char *encrypted_key; { @@ -1531,27 +1575,37 @@ void CJabberProto::OmemoHandleMessage(HXML node, LPCTSTR jid, time_t msgTime) case SG_SUCCESS: break; case SG_ERR_INVALID_MESSAGE: + Netlib_Log(nullptr, "Jabber OMEMO: error: session_cipher_decrypt_pre_key_signal_message failed SG_ERR_INVALID_MESSAGE"); return; break; case SG_ERR_DUPLICATE_MESSAGE: + Netlib_Log(nullptr, "Jabber OMEMO: error: session_cipher_decrypt_pre_key_signal_message failed SG_ERR_DUPLICATE_MESSAGE"); return; break; case SG_ERR_LEGACY_MESSAGE: + Netlib_Log(nullptr, "Jabber OMEMO: error: session_cipher_decrypt_pre_key_signal_message failed SG_ERR_LEGACY_MESSAGE"); return; break; case SG_ERR_INVALID_KEY_ID: + Netlib_Log(nullptr, "Jabber OMEMO: error: session_cipher_decrypt_pre_key_signal_message failed SG_ERR_INVALID_KEY_ID"); return; break; case SG_ERR_INVALID_KEY: + Netlib_Log(nullptr, "Jabber OMEMO: error: session_cipher_decrypt_pre_key_signal_message failed SG_ERR_INVALID_KEY"); return; break; case SG_ERR_UNTRUSTED_IDENTITY: + Netlib_Log(nullptr, "Jabber OMEMO: error: session_cipher_decrypt_pre_key_signal_message failed SG_ERR_UNTRUSTED_IDENTITY"); return; break; default: break; } } + else + { + Netlib_Log(nullptr, "Jabber OMEMO: error: pre_key_signal_message_deserialize failed"); + } char *out = nullptr; { int dec_success = 0; @@ -1584,6 +1638,7 @@ void CJabberProto::OmemoHandleMessage(HXML node, LPCTSTR jid, time_t msgTime) EVP_CIPHER_CTX_free(ctx); if (!dec_success) { + Netlib_Log(nullptr, "Jabber OMEMO: error: aes_128_gcm verification failed (ignored for now, but still error)"); //return; //TODO: handle decryption failure } @@ -1616,10 +1671,16 @@ void CJabberProto::OmemoHandleDeviceList(HXML node) MCONTACT hContact = HContactFromJID(jid); node = XmlGetChild(node, "item"); //get node if (!node) + { + Netlib_Log(nullptr, "Jabber OMEMO: error: omemo devicelist does not have node"); return; + } node = XmlGetChildByTag(node, L"list", L"xmlns", JABBER_FEAT_OMEMO); // if (!node) + { + Netlib_Log(nullptr, "Jabber OMEMO: error: omemo devicelist does not have node"); return; + } bool own_jid = false; if (wcsstr(m_ThreadInfo->fullJID, jid)) own_jid = true; @@ -1861,6 +1922,8 @@ bool CJabberProto::OmemoCheckSession(MCONTACT hContact) if (!pending_check) return true; + else + Netlib_Log(nullptr, "Jabber OMEMO: info: OmemoCheckSession: pending session creation encryption/decryption of THIS message will not be done and message WILL be lost"); return false; } @@ -1898,6 +1961,7 @@ void CJabberProto::OmemoOnIqResultGetBundle(HXML iqNode, CJabberIqInfo *pInfo) db_set_resident(m_szModuleName, setting_name2); id = getDword(hContact, setting_name, 0); } + Netlib_Log(nullptr, "Jabber OMEMO: error: failed to get bundle for device, this may be due to absent data on server or due to our bug (incorrect device id in request)"); return; } @@ -1906,29 +1970,50 @@ void CJabberProto::OmemoOnIqResultGetBundle(HXML iqNode, CJabberIqInfo *pInfo) HXML pubsub = XmlGetChildByTag(iqNode, L"pubsub", L"xmlns", L"http://jabber.org/protocol/pubsub"); if (!pubsub) + { + Netlib_Log(nullptr, "Jabber OMEMO: error: device bundle does not contain pubsub node"); return; + } HXML items = XmlGetChild(pubsub, L"items"); LPCTSTR items_node_val = XmlGetAttrValue(items, L"node"); LPCTSTR device_id = items_node_val; device_id += mir_wstrlen(JABBER_FEAT_OMEMO L".bundles:"); HXML bundle = XmlGetChild(XmlGetChild(items, L"item"), L"bundle"); if (!bundle) + { + Netlib_Log(nullptr, "Jabber OMEMO: error: device bundle does not contain bundle node"); return; + } LPCTSTR signedPreKeyPublic = XmlGetText(XmlGetChild(bundle, L"signedPreKeyPublic")); if (!signedPreKeyPublic) + { + Netlib_Log(nullptr, "Jabber OMEMO: error: device bundle does not contain signedPreKeyPublic node"); return; + } LPCTSTR signedPreKeyId = XmlGetAttrValue(XmlGetChild(bundle, L"signedPreKeyPublic"), L"signedPreKeyId"); if (!signedPreKeyId) + { + Netlib_Log(nullptr, "Jabber OMEMO: error: device bundle does not contain signedPreKeyPublic node"); return; + } LPCTSTR signedPreKeySignature = XmlGetText(XmlGetChild(bundle, L"signedPreKeySignature")); if (!signedPreKeySignature) + { + Netlib_Log(nullptr, "Jabber OMEMO: error: device bundle does not contain signedPreKeySignature node"); return; + } LPCTSTR identityKey = XmlGetText(XmlGetChild(bundle, L"identityKey")); if (!identityKey) + { + Netlib_Log(nullptr, "Jabber OMEMO: error: device bundle does not contain identityKey node"); return; + } HXML prekeys = XmlGetChild(bundle, L"prekeys"); if (!prekeys) + { + Netlib_Log(nullptr, "Jabber OMEMO: error: device bundle does not contain prekeys node"); return; + } unsigned char key_num = 0; while(key_num == 0) @@ -1941,22 +2026,37 @@ void CJabberProto::OmemoOnIqResultGetBundle(HXML iqNode, CJabberIqInfo *pInfo) for (int p = 1; (prekey_node = XmlGetNthChild(prekeys, L"preKeyPublic", p)) != NULL && p <= key_num; p++) ; if (!prekey_node) + { + Netlib_Log(nullptr, "Jabber OMEMO: error: device bundle does not contain preKeyPublic node"); return; + } LPCTSTR preKeyPublic = XmlGetText(prekey_node); if (!preKeyPublic) + { + Netlib_Log(nullptr, "Jabber OMEMO: error: failed to get preKeyPublic data"); return; + } LPCTSTR preKeyId = XmlGetAttrValue(prekey_node, L"preKeyId"); if (!preKeyId) + { + Netlib_Log(nullptr, "Jabber OMEMO: error: failed to get preKeyId data"); return; + } if (!omemo::create_session_store(hContact, device_id, this)) + { + Netlib_Log(nullptr, "Jabber OMEMO: error: omemo::create_session_store failed"); return; //failed to create session store + } if (!omemo::build_session(hContact, jid, device_id, preKeyId, preKeyPublic, signedPreKeyId, signedPreKeyPublic, signedPreKeySignature, identityKey, this)) + { + Netlib_Log(nullptr, "Jabber OMEMO: error: omemo::build_session failed"); return; //failed to build signal(omemo) session + } { unsigned int *dev_id = (unsigned int*)pInfo->GetUserData(); @@ -2028,12 +2128,16 @@ unsigned int CJabberProto::OmemoEncryptMessage(XmlNode &msg, const wchar_t *msg_ for (std::map::iterator i = omemo::sessions_internal[hContact].begin(), end = omemo::sessions_internal[hContact].end(); i != end; i++) { if (!i->second.cipher) + { + Netlib_Log(nullptr, "Jabber OMEMO: bug: omemo session does not have valid cipher"); continue; + } unsigned int intdev_id = i->first; ciphertext_message *encrypted_key; if (session_cipher_encrypt(i->second.cipher, (uint8_t*)key, 16, &encrypted_key) != SG_SUCCESS) { //TODO: handle encryption error + Netlib_Log(nullptr, "Jabber OMEMO: bug: session_cipher_encrypt failed"); continue; } else @@ -2057,6 +2161,10 @@ unsigned int CJabberProto::OmemoEncryptMessage(XmlNode &msg, const wchar_t *msg_ xmlSetText(iv_node, iv_base64w); mir_free(iv_base64w); msg << XCHILDNS(L"store", L"urn:xmpp:hints"); + if (!session_count) + { + Netlib_Log(nullptr, "Jabber OMEMO: error: message does not encrypted for any sessions"); + } return session_count; } bool CJabberProto::OmemoIsEnabled(MCONTACT /*hContact*/) -- cgit v1.2.3