Commit 5cc8dca3 authored by Philipp Hörist's avatar Philipp Hörist

Logging: Add context to logging output

parent 0c7293b8
Pipeline #5201 failed with stages
in 16 seconds
......@@ -28,6 +28,7 @@ from nbxmpp.protocol import SASL_ERROR_CONDITIONS
from nbxmpp.protocol import SASL_AUTH_MECHS
from nbxmpp.util import b64decode
from nbxmpp.util import b64encode
from nbxmpp.util import LogAdapter
from nbxmpp.const import GSSAPIState
from nbxmpp.const import StreamState
......@@ -45,10 +46,7 @@ class SASL:
"""
Implements SASL authentication.
"""
def __init__(self, client):
"""
:param client: Client object
"""
def __init__(self, client, log_context):
self._client = client
self._password = None
......@@ -58,6 +56,8 @@ class SASL:
self._method = None
self._error = None
self._log = LogAdapter(log, {'context': log_context})
@property
def error(self):
return self._error
......@@ -95,14 +95,14 @@ class SASL:
self._enabled_mechs.discard('GSSAPI')
available_mechs = features.get_mechs() & self._enabled_mechs
log.info('Available mechanisms: %s', available_mechs)
self._log.info('Available mechanisms: %s', available_mechs)
domain_based_name = features.get_domain_based_name()
if domain_based_name is not None:
log.info('Found domain based name: %s', domain_based_name)
self._log.info('Found domain based name: %s', domain_based_name)
if not available_mechs:
log.error('No available auth mechanisms found')
self._log.error('No available auth mechanisms found')
self._abort_auth('invalid-mechanism')
return
......@@ -113,11 +113,11 @@ class SASL:
break
if chosen_mechanism is None:
log.error('No available auth mechanisms found')
self._log.error('No available auth mechanisms found')
self._abort_auth('invalid-mechanism')
return
log.info('Chosen auth mechanism: %s', chosen_mechanism)
self._log.info('Chosen auth mechanism: %s', chosen_mechanism)
if chosen_mechanism in ('SCRAM-SHA-256', 'SCRAM-SHA-1', 'PLAIN'):
if not self._password:
......@@ -160,26 +160,26 @@ class SASL:
self._client.domain)
else:
log.error('Unknown auth mech')
self._log.error('Unknown auth mech')
def _on_challenge(self, stanza):
try:
self._method.response(stanza.getData())
except AttributeError:
log.info('Mechanism has no response method')
self._log.info('Mechanism has no response method')
self._abort_auth()
except AuthFail as error:
log.error(error)
self._log.error(error)
self._abort_auth()
def _on_success(self, stanza):
log.info('Successfully authenticated with remote server')
self._log.info('Successfully authenticated with remote server')
try:
self._method.success(stanza.getData())
except AttributeError:
pass
except AuthFail as error:
log.error(error)
self._log.error(error)
self._abort_auth()
return
......@@ -197,7 +197,7 @@ class SASL:
reason = name
break
log.info('Failed SASL authentification: %s %s', reason, text)
self._log.info('Failed SASL authentification: %s %s', reason, text)
self._abort_auth(reason, text)
def _abort_auth(self, reason='malformed-request', text=None):
......@@ -379,7 +379,6 @@ class SCRAM:
server_key = self._hmac(salted_password, 'Server Key')
self._server_signature = self._hmac(server_key, auth_message)
log.debug('Response: %s', client_finale_message)
payload = b64encode(client_finale_message)
node = Node('response',
attrs={'xmlns': NS_SASL},
......
This diff is collapsed.
......@@ -21,6 +21,7 @@ from gi.repository import Gio
from nbxmpp.const import TCPState
from nbxmpp.util import Observable
from nbxmpp.util import LogAdapter
log = logging.getLogger('nbxmpp.connection')
......@@ -39,12 +40,16 @@ class Connection(Observable):
disconnected
'''
def __init__(self,
log_context,
address,
accepted_certificates,
ignore_tls_errors,
ignored_tls_errors,
client_cert):
Observable.__init__(self, log)
self._log = LogAdapter(log, {'context': log_context})
Observable.__init__(self, self._log)
self._client_cert = client_cert
self._address = address
......@@ -72,23 +77,23 @@ class Connection(Observable):
@state.setter
def state(self, value):
log.info('Set Connection State: %s', value)
self._log.info('Set Connection State: %s', value)
self._state = value
def _accept_certificate(self):
if not self._peer_certificate_errors:
return True
log.info('Found TLS certificate errors: %s',
self._peer_certificate_errors)
self._log.info('Found TLS certificate errors: %s',
self._peer_certificate_errors)
if self._ignore_tls_errors:
log.warning('Ignore all errors')
self._log.warning('Ignore all errors')
return True
if self._ignored_tls_errors:
log.warning('Ignore TLS certificate errors: %s',
self._ignored_tls_errors)
self._log.warning('Ignore TLS certificate errors: %s',
self._ignored_tls_errors)
self._peer_certificate_errors -= self._ignored_tls_errors
if Gio.TlsCertificateFlags.UNKNOWN_CA in self._peer_certificate_errors:
......@@ -111,14 +116,13 @@ class Connection(Observable):
def send(self, stanza, now=False):
raise NotImplementedError
@staticmethod
def _log_stanza(data, received=True):
def _log_stanza(self, data, received=True):
direction = 'RECEIVED' if received else 'SENT'
message = ('::::: DATA %s ::::'
'\n_____________\n'
'%s'
'\n_____________')
log.info(message, direction, data)
self._log.info(message, direction, data)
def start_tls_negotiation(self):
raise NotImplementedError
......
......@@ -84,6 +84,7 @@ from nbxmpp.util import get_invalid_xml_regex
from nbxmpp.util import is_websocket_close
from nbxmpp.util import is_websocket_stream_error
from nbxmpp.util import Observable
from nbxmpp.util import LogAdapter
log = logging.getLogger('nbxmpp.dispatcher')
......@@ -100,13 +101,15 @@ class StanzaDispatcher(Observable):
"""
def __init__(self, client):
def __init__(self, client, log_context):
Observable.__init__(self, log)
self._client = client
self._modules = {}
self._parser = None
self._websocket_stream_error = None
self._log = LogAdapter(log, {'context': log_context})
self._handlers = {}
self._id_callbacks = {}
......@@ -132,7 +135,7 @@ class StanzaDispatcher(Observable):
self._register_modules()
def set_dispatch_callback(self, callback):
log.info('Set dispatch callback: %s', callback)
self._log.info('Set dispatch callback: %s', callback)
self._dispatch_callback = callback
def get_module(self, name):
......@@ -212,7 +215,7 @@ class StanzaDispatcher(Observable):
self._websocket_stream_error = name
elif is_websocket_close(stanza):
log.info('Stream <close> received')
self._log.info('Stream <close> received')
self.notify('stream-end', self._websocket_stream_error)
return
......@@ -222,13 +225,13 @@ class StanzaDispatcher(Observable):
try:
self._parser.Parse(data)
except (ExpatError, ValueError) as error:
log.error('XML parsing error: %s', error)
self._log.error('XML parsing error: %s', error)
self.notify('parsing-error', error)
return
# end stream:stream tag received
if self._parser.has_received_endtag():
log.info('End of stream: %s', self._parser.streamError)
self._log.info('End of stream: %s', self._parser.streamError)
self.notify('stream-end', self._parser.streamError)
return
......@@ -236,7 +239,7 @@ class StanzaDispatcher(Observable):
"""
Setup handler structure for namespace
"""
log.debug('Register namespace "%s"', xmlns)
self._log.debug('Register namespace "%s"', xmlns)
self._handlers[xmlns] = {}
self._register_protocol('error', Protocol, xmlns=xmlns)
self._register_protocol('unknown', Protocol, xmlns=xmlns)
......@@ -248,8 +251,8 @@ class StanzaDispatcher(Observable):
"""
if xmlns is None:
xmlns = NS_CLIENT
log.debug('Register protocol "%s (%s)" as %s',
tag_name, xmlns, protocol)
self._log.debug('Register protocol "%s (%s)" as %s',
tag_name, xmlns, protocol)
self._handlers[xmlns][tag_name] = {'type': protocol, 'default': []}
def register_handler(self, name, handler, typ='', ns='',
......@@ -272,8 +275,8 @@ class StanzaDispatcher(Observable):
if not typ and not ns:
typ = 'default'
log.debug('Register handler %s for "%s" type->%s ns->%s(%s) priority->%s',
handler, name, typ, ns, xmlns, priority)
self._log.debug('Register handler %s for "%s" type->%s ns->%s(%s) priority->%s',
handler, name, typ, ns, xmlns, priority)
if xmlns not in self._handlers:
self._register_namespace(xmlns)
......@@ -313,11 +316,11 @@ class StanzaDispatcher(Observable):
try:
self._handlers[xmlns][name][specific].remove(handler_dict)
except ValueError:
log.warning('Unregister failed: %s for "%s" type->%s ns->%s(%s)',
handler, name, typ, ns, xmlns)
self._log.warning('Unregister failed: %s for "%s" type->%s ns->%s(%s)',
handler, name, typ, ns, xmlns)
else:
log.debug('Unregister handler %s for "%s" type->%s ns->%s(%s)',
handler, name, typ, ns, xmlns)
self._log.debug('Unregister handler %s for "%s" type->%s ns->%s(%s)',
handler, name, typ, ns, xmlns)
def _default_handler(self, stanza):
"""
......@@ -344,19 +347,19 @@ class StanzaDispatcher(Observable):
xmlns = stanza.getNamespace()
if xmlns not in self._handlers:
log.warning('Unknown namespace: %s', xmlns)
self._log.warning('Unknown namespace: %s', xmlns)
xmlns = 'unknown'
if name not in self._handlers[xmlns]:
log.warning('Unknown stanza: %s', stanza)
self._log.warning('Unknown stanza: %s', stanza)
name = 'unknown'
# Convert simplexml to Protocol object
try:
stanza = self._handlers[xmlns][name]['type'](node=stanza)
except InvalidJid:
log.warning('Invalid JID, ignoring stanza')
log.warning(stanza)
self._log.warning('Invalid JID, ignoring stanza')
self._log.warning(stanza)
return
own_jid = self._client.get_bound_jid()
......@@ -376,7 +379,8 @@ class StanzaDispatcher(Observable):
if to is None:
stanza.setTo(own_jid)
elif not to.bareMatch(own_jid):
log.warning('Message addressed to someone else: %s', stanza)
self._log.warning('Message addressed to someone else: %s',
stanza)
return
if stanza.getFrom() is None:
......@@ -386,19 +390,19 @@ class StanzaDispatcher(Observable):
try:
stanza, properties.carbon = unwrap_carbon(stanza, own_jid)
except (InvalidFrom, InvalidJid) as exc:
log.warning(exc)
log.warning(stanza)
self._log.warning(exc)
self._log.warning(stanza)
return
except NodeProcessed as exc:
log.info(exc)
self._log.info(exc)
return
# Unwrap mam
try:
stanza, properties.mam = unwrap_mam(stanza, own_jid)
except (InvalidStanza, InvalidJid) as exc:
log.warning(exc)
log.warning(stanza)
self._log.warning(exc)
self._log.warning(stanza)
return
typ = stanza.getType()
......@@ -408,7 +412,7 @@ class StanzaDispatcher(Observable):
typ = ''
stanza.props = stanza.getProperties()
log.debug('type: %s, properties: %s', typ, stanza.props)
self._log.debug('type: %s, properties: %s', typ, stanza.props)
# Process callbacks
_id = stanza.getID()
......@@ -421,7 +425,7 @@ class StanzaDispatcher(Observable):
try:
func(self._client, stanza, **user_data)
except Exception:
log.exception('Error while handling stanza')
self._log.exception('Error while handling stanza')
return
# Gather specifics depending on stanza properties
......@@ -444,13 +448,13 @@ class StanzaDispatcher(Observable):
chain.sort(key=lambda x: x['priority'])
for handler in chain:
log.info('Call handler: %s', handler['func'].__qualname__)
self._log.info('Call handler: %s', handler['func'].__qualname__)
try:
handler['func'](self._client, stanza, properties)
except NodeProcessed:
return
except Exception:
log.exception('Handler exception:')
self._log.exception('Handler exception:')
return
# Stanza was not processed call default handler
......@@ -458,16 +462,16 @@ class StanzaDispatcher(Observable):
def add_callback_for_id(self, id_, func, timeout, user_data):
if timeout is not None and self._timeout_id is None:
log.info('Add timeout source')
self._log.info('Add timeout source')
self._timeout_id = GLib.timeout_add_seconds(
1, self._timeout_check)
timeout = time.monotonic() + timeout
self._id_callbacks[id_] = (func, timeout, user_data)
def _timeout_check(self):
log.info('Run timeout check')
self._log.info('Run timeout check')
if not self._id_callbacks:
log.info('Remove timeout source, no callbacks scheduled')
self._log.info('Remove timeout source, no callbacks scheduled')
self._timeout_id = None
return False
......
......@@ -25,8 +25,9 @@ log = logging.getLogger('nbxmpp')
log.setLevel('INFO')
log.addHandler(consoleloghandler)
formatter = logging.Formatter('%(asctime)s %(levelname)-7s %(name)-18s %(message)s',
datefmt='%H:%M:%S')
formatter = logging.Formatter(
'%(asctime)s %(levelname)-7s %(name)-25s %(message)s',
datefmt='%H:%M:%S')
consoleloghandler.setFormatter(formatter)
......@@ -77,7 +78,7 @@ class TestClient(Gtk.Window):
self._load_config()
def _create_client(self):
self._client = Client()
self._client = Client(log_context='TEST')
self._client.set_domain(self.address.getDomain())
self._client.set_username(self.address.getNode())
self._client.set_resource('test')
......
......@@ -15,8 +15,6 @@
# You should have received a copy of the GNU General Public License
# along with this program; If not, see <http://www.gnu.org/licenses/>.
import logging
from nbxmpp.protocol import NS_ACTIVITY
from nbxmpp.protocol import NS_PUBSUB_EVENT
from nbxmpp.protocol import Node
......@@ -24,12 +22,13 @@ from nbxmpp.protocol import NodeProcessed
from nbxmpp.structs import StanzaHandler
from nbxmpp.structs import ActivityData
from nbxmpp.const import ACTIVITIES
log = logging.getLogger('nbxmpp.m.activity')
from nbxmpp.modules.base import BaseModule
class Activity:
class Activity(BaseModule):
def __init__(self, client):
BaseModule.__init__(self, client)
self._client = client
self.handlers = [
StanzaHandler(name='message',
......@@ -52,7 +51,8 @@ class Activity:
activity_node = item.getTag('activity', namespace=NS_ACTIVITY)
if not activity_node.getChildren():
log.info('Received activity: %s - no activity set', properties.jid)
self._log.info('Received activity: %s - no activity set',
properties.jid)
return
activity, subactivity, text = None, None, None
......@@ -65,13 +65,13 @@ class Activity:
subactivity = self._parse_sub_activity(child)
if activity is None and activity_node.getPayload():
log.warning('No valid activity value found')
log.warning(stanza)
self._log.warning('No valid activity value found')
self._log.warning(stanza)
raise NodeProcessed
data = ActivityData(activity, subactivity, text)
pubsub_event = properties.pubsub_event._replace(data=data)
log.info('Received activity: %s - %s', properties.jid, data)
self._log.info('Received activity: %s - %s', properties.jid, data)
properties.pubsub_event = pubsub_event
......
......@@ -15,8 +15,6 @@
# You should have received a copy of the GNU General Public License
# along with this program; If not, see <http://www.gnu.org/licenses/>.
import logging
from nbxmpp.protocol import NS_COMMANDS
from nbxmpp.protocol import NS_DISCO_ITEMS
from nbxmpp.protocol import NS_DATA
......@@ -32,13 +30,13 @@ from nbxmpp.const import AdHocStatus
from nbxmpp.const import AdHocAction
from nbxmpp.const import AdHocNoteType
from nbxmpp.modules.discovery import get_disco_request
from nbxmpp.modules.base import BaseModule
log = logging.getLogger('nbxmpp.m.adhoc')
class AdHoc:
class AdHoc(BaseModule):
def __init__(self, client):
BaseModule.__init__(self, client)
self._client = client
self.handlers = []
......@@ -51,11 +49,11 @@ class AdHoc:
@callback
def _command_list_received(self, stanza):
if not isResultNode(stanza):
return raise_error(log.info, stanza)
return raise_error(self._log.info, stanza)
payload = stanza.getQueryPayload()
if payload is None:
return raise_error(log.warning, stanza, 'stanza-malformed')
return raise_error(self._log.warning, stanza, 'stanza-malformed')
command_list = []
for item in payload:
......@@ -64,8 +62,10 @@ class AdHoc:
try:
command_list.append(AdHocCommand(**item.getAttrs()))
except Exception as error:
log.warning(error)
return raise_error(log.warning, stanza, 'stanza-malformed')
self._log.warning(error)
return raise_error(self._log.warning,
stanza,
'stanza-malformed')
return command_list
......@@ -89,11 +89,11 @@ class AdHoc:
@callback
def _command_result_received(self, stanza):
if not isResultNode(stanza):
return raise_error(log.info, stanza)
return raise_error(self._log.info, stanza)
command = stanza.getTag('command', namespace=NS_COMMANDS)
if command is None:
return raise_error(log.warning, stanza, 'stanza-malformed')
return raise_error(self._log.warning, stanza, 'stanza-malformed')
attrs = command.getAttrs()
notes = []
......@@ -121,5 +121,5 @@ class AdHoc:
actions=actions,
notes=notes)
except Exception as error:
log.warning(error)
return raise_error(log.warning, stanza, 'stanza-malformed')
self._log.warning(error)
return raise_error(self._log.warning, stanza, 'stanza-malformed')
......@@ -15,8 +15,6 @@
# You should have received a copy of the GNU General Public License
# along with this program; If not, see <http://www.gnu.org/licenses/>.
import logging
from nbxmpp.protocol import NS_PRIVATE
from nbxmpp.protocol import NS_ROSTERNOTES
from nbxmpp.protocol import Iq
......@@ -29,12 +27,13 @@ from nbxmpp.modules.date_and_time import parse_datetime
from nbxmpp.util import call_on_response
from nbxmpp.util import callback
from nbxmpp.util import raise_error
log = logging.getLogger('nbxmpp.m.annotations')
from nbxmpp.modules.base import BaseModule
class Annotations:
class Annotations(BaseModule):
def __init__(self, client):
BaseModule.__init__(self, client)
self._client = client
self.handlers = []
......@@ -44,18 +43,18 @@ class Annotations:
@call_on_response('_annotations_received')
def request_annotations(self):
log.info('Request annotations for %s', self.domain)
self._log.info('Request annotations for %s', self.domain)
payload = Node('storage', attrs={'xmlns': NS_ROSTERNOTES})
return Iq(typ='get', queryNS=NS_PRIVATE, payload=payload)
@callback
def _annotations_received(self, stanza):
if not isResultNode(stanza):
return raise_error(log.info, stanza)
return raise_error(self._log.info, stanza)
storage = stanza.getQueryChild('storage')
if storage is None:
return raise_error(log.warning, stanza, 'stanza-malformed',
return raise_error(self._log.warning, stanza, 'stanza-malformed',
'No annotations found')
notes = []
......@@ -63,8 +62,8 @@ class Annotations:
try:
jid = JID(note.getAttr('jid'))
except Exception as error:
log.warning('Invalid JID: %s, %s',
note.getAttr('jid'), error)
self._log.warning('Invalid JID: %s, %s',
note.getAttr('jid'), error)
continue
cdate = note.getAttr('cdate')
......@@ -79,16 +78,16 @@ class Annotations:
notes.append(AnnotationNote(jid=jid, cdate=cdate,
mdate=mdate, data=data))
log.info('Received annotations from %s:', self.domain)
self._log.info('Received annotations from %s:', self.domain)
for note in notes:
log.info(note)
self._log.info(note)
return notes
@call_on_response('_default_response')
def set_annotations(self, notes):
log.info('Set annotations for %s:', self.domain)
self._log.info('Set annotations for %s:', self.domain)
for note in notes:
log.info(note)
self._log.info(note)
storage = Node('storage', attrs={'xmlns': NS_ROSTERNOTES})
for note in notes:
node = Node('note', attrs={'jid': note.jid})
......@@ -103,5 +102,5 @@ class Annotations:
@callback
def _default_response(self, stanza):
if not isResultNode(stanza):
return raise_error(log.info, stanza)
return raise_error(self._log.info, stanza)
return CommonResult(jid=stanza.getFrom())
......@@ -15,17 +15,16 @@
# You should have received a copy of the GNU General Public License
# along with this program; If not, see <http://www.gnu.org/licenses/>.
import logging
from nbxmpp.protocol import NS_ATTENTION
from nbxmpp.protocol import NS_DELAY2
from nbxmpp.structs import StanzaHandler
log = logging.getLogger('nbxmpp.m.attention')
from nbxmpp.modules.base import BaseModule
class Attention:
class Attention(BaseModule):
def __init__(self, client):
BaseModule.__init__(self, client)
self._client = client
self.handlers = [
StanzaHandler(name='message',
......
# Copyright (C) 2018 Philipp Hörist <philipp AT hoerist.com>
#
# This file is part of nbxmpp.
#
# This program is free software; you can redistribute it and/or
# modify it under the terms of the GNU General Public License
# as published by the Free Software Foundation; either version 3
# of the License, or (at your option) any later version.
#
# This program is distributed in the hope that it will be useful,
# but WITHOUT ANY WARRANTY; without even the implied warranty of
# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
# GNU General Public License for more details.
#
# You should have received a copy of the GNU General Public License
# along with this program; If not, see <http://www.gnu.org/licenses/>.
import logging
from nbxmpp.util import LogAdapter
class BaseModule:
def __init__(self, client):
logger_name = 'nbxmpp.m.%s' % self.__class__.__name__.lower()
self._log = LogAdapter(logging.getLogger(logger_name),
{'context': client.log_context})
......@@ -15,8 +15,6 @@
# You should have received a copy of the GNU General Public License
# along with this program; If not, see <http://www.gnu.org/licenses/>.
import logging
from nbxmpp.protocol import NS_BLOCKING
from nbxmpp.protocol import Iq
from nbxmpp.protocol import isResultNode
......@@ -25,12 +23,13 @@ from nbxmpp.structs import CommonResult
from nbxmpp.util import call_on_response
from nbxmpp.util import callback
from nbxmpp.util import raise_error
log = logging.getLogger('nbxmpp.m.blocking')
from nbxmpp.modules.base import BaseModule
class Blocking:
class Blocking(BaseModule):
def __init__(self, client):
BaseModule.__init__(self, client)
self._client = client
self.handlers = []
......@@ -44,21 +43,21 @@ class Blocking:
def _blocking_list_received(self, stanza):
blocked = []
if not isResultNode(stanza):
return raise_error(log.info, stanza)
return raise_error(self._log.info, stanza)
blocklist = stanza.getTag('blocklist', namespace=NS_BLOCKING)
if blocklist is None:
return raise_error(log.warning, stanza, 'stanza-malformed')
return raise_error(self._log.warning, stanza, 'stanza-malformed')
for item in blocklist.getTags('item'):
blocked.append(item.getAttr('jid'))