[omemo] Improve logging

omemo/backend/devices.py

@@ -14,15 +14,12 @@
 # You should have received a copy of the GNU General Public License
 # along with OMEMO Gajim Plugin. If not, see <http://www.gnu.org/licenses/>.
 
-import logging
 from collections import defaultdict
 
 from gajim.common import app
 
 from omemo.backend.util import UNACKNOWLEDGED_COUNT
 
-log = logging.getLogger('gajim.plugin_system.omemo')
-
 
 class DeviceManager:
     def __init__(self):
@@ -34,10 +31,10 @@ class DeviceManager:
             raise ValueError('No own device found')
         self.__own_device = (reg_id % 2147483646) + 1
         self.add_device(self._own_jid, self.__own_device)
-        log.info('Our device id: %s', self.__own_device)
+        self._log.info('Our device id: %s', self.__own_device)
 
         for jid, device in self._storage.getActiveDeviceTuples():
-            log.info('Load device from storage: %s - %s', jid, device)
+            self._log.info('Load device from storage: %s - %s', jid, device)
             self.add_device(jid, device)
 
     def update_devicelist(self, jid, devicelist):
@@ -46,20 +43,20 @@ class DeviceManager:
                 continue
             count = self._storage.getUnacknowledgedCount(jid, device)
             if count > UNACKNOWLEDGED_COUNT:
-                log.warning('Ignore device because of %s unacknowledged'
-                            ' messages: %s %s', count, jid, device)
+                self._log.warning('Ignore device because of %s unacknowledged'
+                                  ' messages: %s %s', count, jid, device)
                 devicelist.remove(device)
 
         self.__device_store[jid] = set(devicelist)
-        log.info('Saved devices for %s', jid)
+        self._log.info('Saved devices for %s', jid)
         self._storage.setActiveState(jid, devicelist)
 
     def add_muc_member(self, room_jid, jid):
-        log.info('Saved MUC member %s %s', room_jid, jid)
+        self._log.info('Saved MUC member %s %s', room_jid, jid)
         self.__muc_member_store[room_jid].add(jid)
 
     def remove_muc_member(self, room_jid, jid):
-        log.info('Removed MUC member %s %s', room_jid, jid)
+        self._log.info('Removed MUC member %s %s', room_jid, jid)
         self.__muc_member_store[room_jid].discard(jid)
 
     def get_muc_members(self, room_jid, without_self=True):

omemo/backend/liteaxolotlstore.py

@@ -16,7 +16,6 @@
 # along with OMEMO Gajim Plugin. If not, see <http://www.gnu.org/licenses/>.
 
 import time
-import logging
 import sqlite3
 from collections import namedtuple
 
@@ -36,9 +35,6 @@ from omemo.backend.util import IdentityKeyExtended
 from omemo.backend.util import DEFAULT_PREKEY_AMOUNT
 
 
-log = logging.getLogger('gajim.plugin_system.omemo')
-
-
 def _convert_to_string(text):
     return text.decode()
 
@@ -59,7 +55,8 @@ sqlite3.register_converter('session_record', _convert_record)
 
 
 class LiteAxolotlStore(AxolotlStore):
-    def __init__(self, db_path):
+    def __init__(self, db_path, log):
+        self._log = log
         self._con = sqlite3.connect(db_path,
                                     detect_types=sqlite3.PARSE_COLNAMES)
         self._con.text_factory = bytes
@@ -77,7 +74,7 @@ class LiteAxolotlStore(AxolotlStore):
         self._con.commit()
 
         if not self.getLocalRegistrationId():
-            log.info("Generating OMEMO keys")
+            self._log.info("Generating OMEMO keys")
             self._generate_axolotl_keys()
 
     @staticmethod
@@ -318,7 +315,7 @@ class LiteAxolotlStore(AxolotlStore):
         return result is not None
 
     def deleteSession(self, recipientId, deviceId):
-        log.info('Delete session for %s %s', recipientId, deviceId)
+        self._log.info('Delete session for %s %s', recipientId, deviceId)
         query = "DELETE FROM sessions WHERE recipient_id = ? AND device_id = ?"
         self._con.execute(query, (recipientId, deviceId))
         self._con.commit()
@@ -551,7 +548,7 @@ class LiteAxolotlStore(AxolotlStore):
     def setIdentityLastSeen(self, recipient_id, identity_key):
         timestamp = int(time.time())
         identity_key = identity_key.getPublicKey().serialize()
-        log.info('Set last seen for %s %s', recipient_id, timestamp)
+        self._log.info('Set last seen for %s %s', recipient_id, timestamp)
         query = '''UPDATE identities SET timestamp = ?
                    WHERE recipient_id = ? AND public_key = ?'''
         self._con.execute(query, (timestamp, recipient_id, identity_key))

omemo/backend/state.py

@@ -15,7 +15,6 @@
 # You should have received a copy of the GNU General Public License
 # along with OMEMO Gajim Plugin. If not, see <http://www.gnu.org/licenses/>.
 
-import logging
 import time
 from collections import defaultdict
 
@@ -48,23 +47,20 @@ from omemo.backend.util import SPK_ARCHIVE_TIME
 from omemo.backend.util import UNACKNOWLEDGED_COUNT
 
 
-log = logging.getLogger('gajim.plugin_system.omemo')
-
-
 class OmemoState(DeviceManager):
     def __init__(self, own_jid, db_path, account, xmpp_con):
         self._account = account
         self._own_jid = own_jid
+        self._log = xmpp_con._log
         self._session_ciphers = defaultdict(dict)
-        self._storage = LiteAxolotlStore(db_path)
+        self._storage = LiteAxolotlStore(db_path, self._log)
 
         DeviceManager.__init__(self)
 
         self.xmpp_con = xmpp_con
 
-        log.info('%s => %s PreKeys available',
-                 self._account,
-                 self._storage.getPreKeyCount())
+        self._log.info('%s PreKeys available',
+                       self._storage.getPreKeyCount())
 
     def build_session(self, jid, device_id, bundle):
         session = SessionBuilder(self._storage, self._storage, self._storage,
@@ -122,13 +118,13 @@ class OmemoState(DeviceManager):
 
     def decrypt_message(self, omemo_message, jid):
         if omemo_message.sid == self.own_device:
-            log.info('Received previously sent message by us')
+            self._log.info('Received previously sent message by us')
             raise SelfMessage
 
         try:
             encrypted_key, prekey = omemo_message.keys[self.own_device]
         except KeyError:
-            log.info('Received message not for our device')
+            self._log.info('Received message not for our device')
             raise MessageNotForDevice
 
         try:
@@ -140,23 +136,23 @@ class OmemoState(DeviceManager):
                     jid, omemo_message.sid, encrypted_key)
 
         except SenderNotTrusted:
-            log.info('Sender not trusted, ignore message')
+            self._log.info('Sender not trusted, ignore message')
             raise
 
         except DuplicateMessageException:
-            log.info('Received duplicated message')
+            self._log.info('Received duplicated message')
             raise DuplicateMessage
 
         except Exception as error:
-            log.warning(error)
+            self._log.warning(error)
             raise DecryptionFailed
 
         if omemo_message.payload is None:
-            log.debug("Decrypted Key Exchange Message")
+            self._log.debug("Decrypted Key Exchange Message")
             raise KeyExchangeMessage
 
         result = aes_decrypt(key, omemo_message.iv, omemo_message.payload)
-        log.debug("Decrypted Message => %s", result)
+        self._log.debug("Decrypted Message => %s", result)
         return result, fingerprint
 
     def _get_whisper_message(self, jid, device, key):
@@ -169,7 +165,7 @@ class OmemoState(DeviceManager):
         try:
             devices_for_encryption = self.get_devices_for_encryption(jid)
         except NoDevicesFound:
-            log.warning('No devices for encryption found for: %s', jid)
+            self._log.warning('No devices for encryption found for: %s', jid)
             return
 
         result = aes_encrypt(plaintext)
@@ -178,29 +174,29 @@ class OmemoState(DeviceManager):
         for jid_, device in devices_for_encryption:
             count = self._storage.getUnacknowledgedCount(jid_, device)
             if count >= UNACKNOWLEDGED_COUNT:
-                log.warning('Set device inactive %s because of %s '
-                            'unacknowledged messages', device, count)
+                self._log.warning('Set device inactive %s because of %s '
+                                  'unacknowledged messages', device, count)
                 self.remove_device(jid_, device)
 
             try:
                 whisper_messages[jid_][device] = self._get_whisper_message(
                     jid_, device, result.key)
             except Exception:
-                log.exception('Failed to encrypt')
+                self._log.exception('Failed to encrypt')
                 continue
 
         recipients = set(whisper_messages.keys())
         if jid != self._own_jid:
             recipients -= set([self._own_jid])
         if not recipients:
-            log.error('Encrypted keys empty')
+            self._log.error('Encrypted keys empty')
             return
 
         encrypted_keys = {}
         for jid_ in whisper_messages:
             encrypted_keys.update(whisper_messages[jid_])
 
-        log.debug('Finished encrypting message')
+        self._log.debug('Finished encrypting message')
         return OMEMOMessage(sid=self.own_device,
                             keys=encrypted_keys,
                             iv=result.iv,
@@ -213,14 +209,14 @@ class OmemoState(DeviceManager):
                 whisper_messages[jid][device] = self._get_whisper_message(
                     jid, device, get_new_key())
             except Exception:
-                log.exception('Failed to encrypt')
+                self._log.exception('Failed to encrypt')
                 continue
 
         if not whisper_messages[jid]:
-            log.error('Encrypted keys empty')
+            self._log.error('Encrypted keys empty')
             return
 
-        log.debug('Finished Key Transport message')
+        self._log.debug('Finished Key Transport message')
         return OMEMOMessage(sid=self.own_device,
                             keys=whisper_messages[jid],
                             iv=get_new_iv(),
@@ -237,8 +233,8 @@ class OmemoState(DeviceManager):
                            for dev in known_devices
                            if not self._storage.containsSession(jid, dev)]
         if missing_devices:
-            log.info('%s => Missing device sessions for %s: %s',
-                     self._account, jid, missing_devices)
+            self._log.info('Missing device sessions for %s: %s',
+                           jid, missing_devices)
         return missing_devices
 
     def _get_session_cipher(self, jid, device_id):
@@ -262,8 +258,7 @@ class OmemoState(DeviceManager):
 
         session_cipher = self._get_session_cipher(jid, device)
 
-        log.info('%s => Process pre key message from %s',
-                 self._account, jid)
+        self._log.info('Process pre key message from %s', jid)
         key = session_cipher.decryptPkmsg(pre_key_message)
         fingerprint = get_fingerprint(identity_key)
 
@@ -275,7 +270,7 @@ class OmemoState(DeviceManager):
 
     def _process_message(self, jid, device, key):
         message = WhisperMessage(serialized=key)
-        log.info('%s => Process message from %s', self._account, jid)
+        self._log.info('Process message from %s', jid)
 
         session_cipher = self._get_session_cipher(jid, device)
         key = session_cipher.decryptMsg(message, textMsg=False)
@@ -299,7 +294,7 @@ class OmemoState(DeviceManager):
         if pre_key_count < MIN_PREKEY_AMOUNT:
             missing_count = DEFAULT_PREKEY_AMOUNT - pre_key_count
             self._storage.generateNewPreKeys(missing_count)
-            log.info('%s => %s PreKeys created', self._account, missing_count)
+            self._log.info('%s PreKeys created', missing_count)
 
     def _cycle_signed_pre_key(self, ik_pair):
         # Publish every SPK_CYCLE_TIME a new SignedPreKey
@@ -311,8 +306,7 @@ class OmemoState(DeviceManager):
             spk = KeyHelper.generateSignedPreKey(
                 ik_pair, self._storage.getNextSignedPreKeyId())
             self._storage.storeSignedPreKey(spk.getId(), spk)
-            log.debug('%s => New SignedPreKey created, because none existed',
-                      self._account)
+            self._log.debug('New SignedPreKey created, because none existed')
 
         # if SPK_CYCLE_TIME is reached, generate a new SignedPreKey
         now = int(time.time())
@@ -323,7 +317,7 @@ class OmemoState(DeviceManager):
             spk = KeyHelper.generateSignedPreKey(
                 ik_pair, self._storage.getNextSignedPreKeyId())
             self._storage.storeSignedPreKey(spk.getId(), spk)
-            log.debug('%s => Cycled SignedPreKey', self._account)
+            self._log.debug('Cycled SignedPreKey')
 
         # Delete all SignedPreKeys that are older than SPK_ARCHIVE_TIME
         timestamp = now - SPK_ARCHIVE_TIME

omemo/backend/util.py

@@ -16,6 +16,7 @@
 
 import binascii
 import textwrap
+from logging import LoggerAdapter
 from enum import IntEnum
 
 from axolotl.identitykey import IdentityKey
@@ -53,4 +54,3 @@ class IdentityKeyExtended(IdentityKey):
 
     def get_fingerprint(self, formatted=False):
         return get_fingerprint(self, formatted=formatted)
-    
\ No newline at end of file

omemo/modules/omemo.py

@@ -87,7 +87,7 @@ class OMEMO(BaseModule):
     ]
 
     def __init__(self, con):
-        BaseModule.__init__(self, con)
+        BaseModule.__init__(self, con, log)
 
         self.handlers = [
             StanzaHandler(name='message',
@@ -131,7 +131,7 @@ class OMEMO(BaseModule):
         return room_jid in self._omemo_groupchats
 
     def on_signed_in(self):
-        log.info('%s => Announce Support after Sign In', self._account)
+        self._log.info('Announce Support after Sign In')
         self._query_for_bundles = []
         self.set_bundle()
         self.request_devicelist()
@@ -144,8 +144,7 @@ class OMEMO(BaseModule):
             helpers.update_optional_features(self._account)
 
         if app.account_is_connected(self._account):
-            log.info('%s => Announce Support after Plugin Activation',
-                     self._account)
+            self._log.info('Announce Support after Plugin Activation')
             self._query_for_bundles = []
             self.set_bundle()
             self.request_devicelist()
@@ -197,11 +196,12 @@ class OMEMO(BaseModule):
     def _send_key_transport_message(self, typ, jid, devices):
         omemo_message = self.backend.encrypt_key_transport(jid, devices)
         if omemo_message is None:
-            log.warning('Key transport message to %s (%s) failed', jid, devices)
+            self._log.warning('Key transport message to %s (%s) failed',
+                              jid, devices)
             return
 
         transport_message = get_key_transport_message(typ, jid, omemo_message)
-        log.info('Send key transport message %s (%s)', jid, devices)
+        self._log.info('Send key transport message %s (%s)', jid, devices)
         self._con.connection.send(transport_message)
 
     def _message_received(self, _con, stanza, properties):
@@ -218,7 +218,7 @@ class OMEMO(BaseModule):
         if from_jid is None:
             return
 
-        log.info('%s => Message received from: %s', self._account, from_jid)
+        self._log.info('Message received from: %s', from_jid)
 
         try:
             plaintext, fingerprint = self.backend.decrypt_message(
@@ -233,8 +233,7 @@ class OMEMO(BaseModule):
                     fingerprint = self.backend.own_fingerprint
                     del self._muc_temp_store[properties.omemo.payload]
                 else:
-                    log.warning("%s => Can't decrypt own GroupChat Message",
-                                self._account)
+                    self._log.warning("Can't decrypt own GroupChat Message")
                     return
             else:
                 raise NodeProcessed
@@ -258,23 +257,20 @@ class OMEMO(BaseModule):
         if contact is not None:
             return JID(contact.jid).getBare()
 
-        log.info('%s => Groupchat: Last resort trying to '
-                 'find SID in DB', self._account)
+        self._log.info('Groupchat: Last resort trying to find SID in DB')
         from_jid = self.backend.storage.getJidFromDevice(properties.omemo.sid)
         if not from_jid:
-            log.error("%s => Can't decrypt GroupChat Message "
-                      "from %s", self._account, resource)
+            self._log.error("Can't decrypt GroupChat Message from %s", resource)
             return
         return from_jid
 
     def _process_mam_message(self, properties):
-        log.info('%s => Message received, archive: %s',
-                 self._account, properties.mam.archive)
+        self._log.info('Message received, archive: %s', properties.mam.archive)
         from_jid = properties.jid.getBare()
         if properties.from_muc:
-            log.info('%s => MUC MAM Message received', self._account)
+            self._log.info('MUC MAM Message received')
             if properties.muc_user.jid is None:
-                log.info('%s => No real jid found', self._account)
+                self._log.info('No real jid found')
                 return
             from_jid = properties.muc_user.jid.getBare()
         return from_jid
@@ -304,7 +300,7 @@ class OMEMO(BaseModule):
         if room in self._omemo_groupchats:
             if not self.is_contact_in_roster(jid):
                 # Query Devicelists from JIDs not in our Roster
-                log.info('%s not in Roster, query devicelist...', jid)
+                self._log.info('%s not in Roster, query devicelist...', jid)
                 self.request_devicelist(jid)
 
         if properties.is_muc_self_presence:
@@ -312,7 +308,7 @@ class OMEMO(BaseModule):
                 # non-anonymous Room (Full JID)
                 self._omemo_groupchats.add(room)
 
-                log.info('OMEMO capable Room found: %s', room)
+                self._log.info('OMEMO capable Room found: %s', room)
                 self.get_affiliation_list(room)
 
     def get_affiliation_list(self, room_jid):
@@ -325,21 +321,21 @@ class OMEMO(BaseModule):
 
     def _on_affiliations_received(self, result, room_jid):
         if is_error_result(result):
-            log.info('Affiliation request failed: %s', result)
+            self._log.info('Affiliation request failed: %s', result)
             return
 
         for user_jid in result.users:
             try:
                 jid = helpers.parse_jid(user_jid)
             except helpers.InvalidFormat:
-                log.warning('Invalid JID: %s, ignoring it', user_jid)
+                self._log.warning('Invalid JID: %s, ignoring it', user_jid)
                 continue
 
             self.backend.add_muc_member(room_jid, jid)
 
             if not self.is_contact_in_roster(jid):
                 # Query Devicelists from JIDs not in our Roster
-                log.info('%s not in Roster, query devicelist...', jid)
+                self._log.info('%s not in Roster, query devicelist...', jid)
                 self.request_devicelist(jid)
 
     def is_contact_in_roster(self, jid):
@@ -355,7 +351,7 @@ class OMEMO(BaseModule):
         status_codes = event.status_codes or []
         if StatusCode.CONFIG_NON_ANONYMOUS in status_codes:
             self._omemo_groupchats.add(room)
-            log.info('Room config change: non-anonymous')
+            self._log.info('Room config change: non-anonymous')
 
     def _check_for_missing_sessions(self, jid):
         devices_without_session = self.backend.devices_without_sessions(jid)
@@ -413,8 +409,7 @@ class OMEMO(BaseModule):
                                          self.backend.own_device)
 
     def request_bundle(self, jid, device_id):
-        log.info('%s => Fetch device bundle %s %s',
-                 self._account, device_id, jid)
+        self._log.info('Fetch device bundle %s %s', device_id, jid)
 
         self._nbxmpp('OMEMO').request_bundle(
             jid,
@@ -425,13 +420,12 @@ class OMEMO(BaseModule):
     def _bundle_received(self, bundle, user_data):
         jid, device_id = user_data
         if is_error_result(bundle):
-            log.info('%s => Bundle request failed: %s %s: %s',
-                     self._account, jid, device_id, bundle)
+            self._log.info('Bundle request failed: %s %s: %s',
+                           jid, device_id, bundle)
             return
 
         self.backend.build_session(jid, device_id, bundle)
-        log.info('%s => session created for: %s',
-                 self._account, jid)
+        self._log.info('Session created for: %s', jid)
         # TODO: In MUC we should send a groupchat message
         self._send_key_transport_message('chat', jid, [device_id])
 
@@ -447,8 +441,7 @@ class OMEMO(BaseModule):
         devicelist_ = set([self.backend.own_device])
         if devicelist is not None:
             devicelist_.add(devicelist)
-        log.info('%s => Publishing own devicelist: %s',
-                 self._account, devicelist_)
+        self._log.info('Publishing own devicelist: %s', devicelist_)
         self._nbxmpp('OMEMO').set_devicelist(devicelist_)
 
     def clear_devicelist(self):
@@ -470,8 +463,7 @@ class OMEMO(BaseModule):
 
     def _devicelist_received(self, devicelist, jid):
         if is_error_result(devicelist):
-            log.info('%s => Devicelist request failed: %s %s',
-                     self._account, jid, devicelist)
+            self._log.info('Devicelist request failed: %s %s', jid, devicelist)
             devicelist = []
 
         self._process_devicelist_update(jid, devicelist)
@@ -489,8 +481,7 @@ class OMEMO(BaseModule):
         if own_devices:
             jid = self._own_jid
 
-        log.info('%s => Received device list for %s: %s',
-                 self._account, jid, devicelist)
+        self._log.info('Received device list for %s: %s', jid, devicelist)
         # Pass a copy, we need the full list for potential set_devicelist()
         self.backend.update_devicelist(jid, list(devicelist))
 
@@ -505,13 +496,10 @@ class OMEMO(BaseModule):
 
         self._check_for_missing_sessions(jid)
 
-    @staticmethod
-    def _debug_print_stanza(stanza):
-        log.debug('-'*15)
+    def _debug_print_stanza(self, stanza):
         stanzastr = '\n' + stanza.__str__(fancy=True)
         stanzastr = stanzastr[0:-1]
-        log.debug(stanzastr)
-        log.debug('-'*15)
+        self._log.debug(stanzastr)
 
 
 def get_instance(*args, **kwargs):