class LogManager(object):
__metaclass__ = Singleton
implements(IObserver)
def __init__(self):
self.name = os.path.basename(sys.argv[0]).rsplit('.py', 1)[0]
self.pid = os.getpid()
self.msrp_level = log.level.INFO
self.siptrace_file = Null
self.msrptrace_file = Null
self.pjsiptrace_file = Null
self.notifications_file = Null
self.event_queue = Null
self.notification_queue = NotificationQueue()
self._siptrace_start_time = None
self._siptrace_packet_count = None
def start(self):
settings = SIPSimpleSettings()
notification_center = NotificationCenter()
notification_center.add_observer(self)
if settings.logs.trace_sip:
self.siptrace_file = LogFile(
os.path.join(ApplicationData.directory, 'logs',
'sip_trace.txt'))
if settings.logs.trace_msrp:
self.msrptrace_file = LogFile(
os.path.join(ApplicationData.directory, 'logs',
'msrp_trace.txt'))
if settings.logs.trace_pjsip:
self.pjsiptrace_file = LogFile(
os.path.join(ApplicationData.directory, 'logs',
'pjsip_trace.txt'))
if settings.logs.trace_notifications:
self.notifications_file = LogFile(
os.path.join(ApplicationData.directory, 'logs',
'notifications_trace.txt'))
self._siptrace_start_time = datetime.now()
self._siptrace_packet_count = 0
self.event_queue = EventQueue(handler=self._process_notification,
name='Blink LogManager')
self.event_queue.start()
while settings.logs.trace_notifications and self.notification_queue and self.notification_queue.notifications:
notification = self.notification_queue.notifications.popleft()
self.handle_notification(notification)
self.notification_queue = None
def stop(self):
notification_center = NotificationCenter()
notification_center.remove_observer(self)
self.event_queue.stop()
self.event_queue.join()
self.event_queue = Null
self.siptrace_file = Null
self.msrptrace_file = Null
self.pjsiptrace_file = Null
self.notifications_file = Null
def handle_notification(self, notification):
self.event_queue.put(notification)
def _process_notification(self, notification):
handler = getattr(self, '_NH_%s' % notification.name, Null)
handler(notification)
handler = getattr(self, '_LH_%s' % notification.name, Null)
handler(notification)
settings = SIPSimpleSettings()
if notification.name not in ('SIPEngineLog', 'SIPEngineSIPTrace'
) and settings.logs.trace_notifications:
message = 'Notification name=%s sender=%s data=%s' % (
notification.name, notification.sender,
pformat(notification.data))
try:
self.notifications_file.write(
'%s [%s %d]: %s\n' %
(datetime.now(), self.name, self.pid, message))
self.notifications_file.flush()
except Exception:
pass
def _NH_CFGSettingsObjectDidChange(self, notification):
settings = SIPSimpleSettings()
if notification.sender is settings:
if 'logs.trace_sip' in notification.data.modified:
self.siptrace_file = LogFile(
os.path.join(
ApplicationData.directory, 'logs',
'sip_trace.txt')) if settings.logs.trace_sip else Null
if 'logs.trace_msrp' in notification.data.modified:
self.msrptrace_file = LogFile(
os.path.join(ApplicationData.directory, 'logs',
'msrp_trace.txt')
) if settings.logs.trace_msrp else Null
if 'logs.trace_pjsip' in notification.data.modified:
self.pjsiptrace_file = LogFile(
os.path.join(ApplicationData.directory, 'logs',
'pjsip_trace.txt')
) if settings.logs.trace_pjsip else Null
if 'logs.trace_notifications' in notification.data.modified:
self.notifications_file = LogFile(
os.path.join(ApplicationData.directory, 'logs',
'notifications_trace.txt')
) if settings.logs.trace_notifications else Null
def _LH_SIPEngineSIPTrace(self, notification):
settings = SIPSimpleSettings()
if not settings.logs.trace_sip:
return
self._siptrace_packet_count += 1
if notification.data.received:
direction = "RECEIVED"
else:
direction = "SENDING"
buf = [
"%s: Packet %d, +%s" %
(direction, self._siptrace_packet_count,
(notification.datetime - self._siptrace_start_time)),
"%(source_ip)s:%(source_port)d -(SIP over %(transport)s)-> %(destination_ip)s:%(destination_port)d"
% notification.data.__dict__, notification.data.data, '--'
]
message = '\n'.join(buf)
try:
self.siptrace_file.write(
'%s [%s %d]: %s\n' %
(notification.datetime, self.name, self.pid, message))
self.siptrace_file.flush()
except Exception:
pass
def _LH_SIPEngineLog(self, notification):
settings = SIPSimpleSettings()
if not settings.logs.trace_pjsip:
return
message = "(%(level)d) %(message)s" % notification.data.__dict__
try:
self.pjsiptrace_file.write('[%s %d] %s\n' %
(self.name, self.pid, message))
self.pjsiptrace_file.flush()
except Exception:
pass
def _LH_DNSLookupTrace(self, notification):
settings = SIPSimpleSettings()
if not settings.logs.trace_sip:
return
message = 'DNS lookup %(query_type)s %(query_name)s' % notification.data.__dict__
if notification.data.error is None:
message += ' succeeded, ttl=%d: ' % notification.data.answer.ttl
if notification.data.query_type == 'A':
message += ", ".join(record.address
for record in notification.data.answer)
elif notification.data.query_type == 'SRV':
message += ", ".join('%d %d %d %s' %
(record.priority, record.weight,
record.port, record.target)
for record in notification.data.answer)
elif notification.data.query_type == 'NAPTR':
message += ", ".join(
'%d %d "%s" "%s" "%s" %s' %
(record.order, record.preference, record.flags,
record.service, record.regexp, record.replacement)
for record in notification.data.answer)
else:
import dns.resolver
message_map = {
dns.resolver.NXDOMAIN:
'DNS record does not exist',
dns.resolver.NoAnswer:
'DNS response contains no answer',
dns.resolver.NoNameservers:
'no DNS name servers could be reached',
dns.resolver.Timeout:
'no DNS response received, the query has timed out'
}
message += ' failed: %s' % message_map.get(
notification.data.error.__class__, '')
try:
self.siptrace_file.write(
'%s [%s %d]: %s\n' %
(notification.datetime, self.name, self.pid, message))
self.siptrace_file.flush()
except Exception:
pass
def _LH_MSRPTransportTrace(self, notification):
settings = SIPSimpleSettings()
if not settings.logs.trace_msrp:
return
arrow = {
'incoming': '<--',
'outgoing': '-->'
}[notification.data.direction]
local_address = '%s:%d' % (notification.data.local_address.host,
notification.data.local_address.port)
remote_address = '%s:%d' % (notification.data.remote_address.host,
notification.data.remote_address.port)
message = '%s %s %s\n' % (local_address, arrow,
remote_address) + notification.data.data
prefix = '[Illegal request!] ' if notification.data.illegal else ''
try:
self.msrptrace_file.write(
'%s [%s %d]: %s%s\n' %
(notification.datetime, self.name, self.pid, prefix, message))
self.msrptrace_file.flush()
except Exception:
pass
def _LH_MSRPLibraryLog(self, notification):
settings = SIPSimpleSettings()
if not settings.logs.trace_msrp:
return
if notification.data.level < self.msrp_level:
return
message = '%s %s' % (notification.data.level,
notification.data.message)
try:
self.msrptrace_file.write(
'%s [%s %d]: %s\n' %
(notification.datetime, self.name, self.pid, message))
self.msrptrace_file.flush()
except Exception:
pass
class Logger(object):
implements(IObserver)
# public methods
#
def __init__(
self,
sip_to_stdout=False,
msrp_to_stdout=False,
pjsip_to_stdout=False,
notifications_to_stdout=False,
msrp_level=log.level.ERROR,
):
self.sip_to_stdout = sip_to_stdout
self.msrp_to_stdout = msrp_to_stdout
self.pjsip_to_stdout = pjsip_to_stdout
self.notifications_to_stdout = notifications_to_stdout
self.msrp_level = msrp_level
self._siptrace_filename = None
self._siptrace_file = None
self._siptrace_error = False
self._siptrace_start_time = None
self._siptrace_packet_count = 0
self._msrptrace_filename = None
self._msrptrace_file = None
self._msrptrace_error = False
self._pjsiptrace_filename = None
self._pjsiptrace_file = None
self._pjsiptrace_error = False
self._notifications_filename = None
self._notifications_file = None
self._notifications_error = False
self._event_queue = EventQueue(handler=self._process_notification, name="Log handling")
self._log_directory_error = False
def start(self):
# try to create the log directory
try:
self._init_log_directory()
except Exception:
pass
# register to receive log notifications
notification_center = NotificationCenter()
notification_center.add_observer(self)
# start the thread processing the notifications
self._event_queue.start()
def stop(self):
# stop the thread processing the notifications
self._event_queue.stop()
self._event_queue.join()
# close sip trace file
if self._siptrace_file is not None:
self._siptrace_file.close()
self._siptrace_file = None
# close msrp trace file
if self._msrptrace_file is not None:
self._msrptrace_file.close()
self._msrptrace_file = None
# close pjsip trace file
if self._pjsiptrace_file is not None:
self._pjsiptrace_file.close()
self._pjsiptrace_file = None
# close notifications trace file
if self._notifications_file is not None:
self._notifications_file.close()
self._notifications_file = None
# unregister from receiving notifications
notification_center = NotificationCenter()
notification_center.remove_observer(self)
def handle_notification(self, notification):
self._event_queue.put(notification)
def _process_notification(self, notification):
settings = SIPSimpleSettings()
handler = getattr(self, "_NH_%s" % notification.name, None)
if handler is not None:
handler(notification)
handler = getattr(self, "_LH_%s" % notification.name, None)
if handler is not None:
handler(notification)
if notification.name not in ("SIPEngineLog", "SIPEngineSIPTrace") and (
self.notifications_to_stdout or settings.logs.trace_notifications
):
message = "Notification name=%s sender=%s" % (notification.name, notification.sender)
if notification.data is not None:
message += "\n%s" % pformat(notification.data.__dict__)
if self.notifications_to_stdout:
print "%s: %s" % (datetime.datetime.now(), message)
if settings.logs.trace_notifications:
try:
self._init_log_file("notifications")
except Exception:
pass
else:
self._notifications_file.write(
"%s [%s %d]: %s\n"
% (datetime.datetime.now(), os.path.basename(sys.argv[0]).rstrip(".py"), os.getpid(), message)
)
self._notifications_file.flush()
# notification handlers
#
def _NH_CFGSettingsObjectDidChange(self, notification):
settings = SIPSimpleSettings()
if notification.sender is settings:
if "logs.directory" in notification.data.modified:
# sip trace
if self._siptrace_file is not None:
self._siptrace_file.close()
self._siptrace_file = None
# pjsip trace
if self._pjsiptrace_file is not None:
self._pjsiptrace_file.close()
self._pjsiptrace_file = None
# notifications trace
if self._notifications_file is not None:
self._notifications_file.close()
self._notifications_file = None
# try to create the log directory
try:
self._init_log_directory()
except Exception:
pass
# log handlers
#
def _LH_SIPEngineSIPTrace(self, notification):
settings = SIPSimpleSettings()
if not self.sip_to_stdout and not settings.logs.trace_sip:
return
if self._siptrace_start_time is None:
self._siptrace_start_time = notification.data.timestamp
self._siptrace_packet_count += 1
if notification.data.received:
direction = "RECEIVED"
else:
direction = "SENDING"
buf = [
"%s: Packet %d, +%s"
% (direction, self._siptrace_packet_count, (notification.data.timestamp - self._siptrace_start_time))
]
buf.append(
"%(source_ip)s:%(source_port)d -(SIP over %(transport)s)-> %(destination_ip)s:%(destination_port)d"
% notification.data.__dict__
)
buf.append(notification.data.data)
buf.append("--")
message = "\n".join(buf)
if self.sip_to_stdout:
print "%s: %s\n" % (notification.data.timestamp, message)
if settings.logs.trace_sip:
try:
self._init_log_file("siptrace")
except Exception:
pass
else:
self._siptrace_file.write(
"%s [%s %d]: %s\n"
% (notification.data.timestamp, os.path.basename(sys.argv[0]).rstrip(".py"), os.getpid(), message)
)
self._siptrace_file.flush()
def _LH_SIPEngineLog(self, notification):
settings = SIPSimpleSettings()
if not self.pjsip_to_stdout and not settings.logs.trace_pjsip:
return
message = "(%(level)d) %(sender)14s: %(message)s" % notification.data.__dict__
if self.pjsip_to_stdout:
print "%s %s" % (notification.data.timestamp, message)
if settings.logs.trace_pjsip:
try:
self._init_log_file("pjsiptrace")
except Exception:
pass
else:
self._pjsiptrace_file.write(
"%s [%s %d] %s\n"
% (notification.data.timestamp, os.path.basename(sys.argv[0]).rstrip(".py"), os.getpid(), message)
)
self._pjsiptrace_file.flush()
def _LH_DNSLookupTrace(self, notification):
settings = SIPSimpleSettings()
if not self.sip_to_stdout and not settings.logs.trace_sip:
return
message = "DNS lookup %(query_type)s %(query_name)s" % notification.data.__dict__
if notification.data.error is None:
message += " succeeded, ttl=%d: " % notification.data.answer.ttl
if notification.data.query_type == "A":
message += ", ".join(record.address for record in notification.data.answer)
elif notification.data.query_type == "SRV":
message += ", ".join(
"%d %d %d %s" % (record.priority, record.weight, record.port, record.target)
for record in notification.data.answer
)
elif notification.data.query_type == "NAPTR":
message += ", ".join(
'%d %d "%s" "%s" "%s" %s'
% (record.order, record.preference, record.flags, record.service, record.regexp, record.replacement)
for record in notification.data.answer
)
else:
import dns.resolver
message_map = {
dns.resolver.NXDOMAIN: "DNS record does not exist",
dns.resolver.NoAnswer: "DNS response contains no answer",
dns.resolver.NoNameservers: "no DNS name servers could be reached",
dns.resolver.Timeout: "no DNS response received, the query has timed out",
}
message += " failed: %s" % message_map.get(notification.data.error.__class__, "")
if self.sip_to_stdout:
print "%s: %s" % (notification.data.timestamp, message)
if settings.logs.trace_sip:
try:
self._init_log_file("siptrace")
except Exception:
pass
else:
self._siptrace_file.write(
"%s [%s %d]: %s\n"
% (notification.data.timestamp, os.path.basename(sys.argv[0]).rstrip(".py"), os.getpid(), message)
)
self._siptrace_file.flush()
def _LH_MSRPTransportTrace(self, notification):
settings = SIPSimpleSettings()
if not self.msrp_to_stdout and not settings.logs.trace_msrp:
return
arrow = {"incoming": "<--", "outgoing": "-->"}[notification.data.direction]
local_address = notification.sender.getHost()
local_address = "%s:%d" % (local_address.host, local_address.port)
remote_address = notification.sender.getPeer()
remote_address = "%s:%d" % (remote_address.host, remote_address.port)
message = "%s %s %s\n" % (local_address, arrow, remote_address) + notification.data.data
if self.msrp_to_stdout:
print "%s: %s" % (notification.data.timestamp, message)
if settings.logs.trace_msrp:
try:
self._init_log_file("msrptrace")
except Exception:
pass
else:
self._msrptrace_file.write(
"%s [%s %d]: %s\n"
% (notification.data.timestamp, os.path.basename(sys.argv[0]).rstrip(".py"), os.getpid(), message)
)
self._msrptrace_file.flush()
def _LH_MSRPLibraryLog(self, notification):
settings = SIPSimpleSettings()
if not self.msrp_to_stdout and not settings.logs.trace_msrp:
return
if notification.data.level < self.msrp_level:
return
message = "%s%s" % (notification.data.level.prefix, notification.data.message)
if self.msrp_to_stdout:
print "%s: %s" % (notification.data.timestamp, message)
if settings.logs.trace_msrp:
try:
self._init_log_file("msrptrace")
except Exception:
pass
else:
self._msrptrace_file.write(
"%s [%s %d]: %s\n"
% (notification.data.timestamp, os.path.basename(sys.argv[0]).rstrip(".py"), os.getpid(), message)
)
self._msrptrace_file.flush()
# private methods
#
def _init_log_directory(self):
settings = SIPSimpleSettings()
log_directory = settings.logs.directory.normalized
try:
makedirs(log_directory)
except Exception, e:
if not self._log_directory_error:
print "failed to create logs directory '%s': %s" % (log_directory, e)
self._log_directory_error = True
self._siptrace_error = True
self._pjsiptrace_error = True
self._notifications_error = True
raise
else:
class FileLogger(object):
implements(IObserver)
# public methods
#
def __init__(self, msrp_level=log.level.INFO):
self.msrp_level = msrp_level
self._siptrace_filename = None
self._siptrace_file = None
self._siptrace_error = False
self._siptrace_start_time = None
self._siptrace_packet_count = 0
self._msrptrace_filename = None
self._msrptrace_file = None
self._msrptrace_error = False
self._pjsiptrace_filename = None
self._pjsiptrace_file = None
self._pjsiptrace_error = False
self._notifications_filename = None
self._notifications_file = None
self._notifications_error = False
self._event_queue = EventQueue(handler=self._process_notification, name='Log handling')
self._log_directory_error = False
def start(self):
# try to create the log directory
try:
self._init_log_directory()
except Exception:
pass
# register to receive log notifications
notification_center = NotificationCenter()
notification_center.add_observer(self)
# start the thread processing the notifications
self._event_queue.start()
def stop(self):
# stop the thread processing the notifications
self._event_queue.stop()
self._event_queue.join()
# close sip trace file
if self._siptrace_file is not None:
self._siptrace_file.close()
self._siptrace_file = None
# close msrp trace file
if self._msrptrace_file is not None:
self._msrptrace_file.close()
self._msrptrace_file = None
# close pjsip trace file
if self._pjsiptrace_file is not None:
self._pjsiptrace_file.close()
self._pjsiptrace_file = None
# close notifications trace file
if self._notifications_file is not None:
self._notifications_file.close()
self._notifications_file = None
# unregister from receiving notifications
notification_center = NotificationCenter()
notification_center.remove_observer(self)
def handle_notification(self, notification):
self._event_queue.put(notification)
@allocate_autorelease_pool
def _process_notification(self, notification):
settings = SIPSimpleSettings()
handler = getattr(self, '_NH_%s' % notification.name, None)
if handler is not None:
handler(notification)
handler = getattr(self, '_LH_%s' % notification.name, None)
if handler is not None:
handler(notification)
if notification.name not in ('SIPEngineLog', 'SIPEngineSIPTrace') and settings.logs.trace_notifications:
try:
self._init_log_file('notifications')
except Exception:
pass
else:
message = 'Notification name=%s sender=%s data=%s' % (notification.name, notification.sender, pformat(notification.data))
self._notifications_file.write('%s: %s\n' % (datetime.datetime.now(), message))
self._notifications_file.flush()
# notification handlers
#
def _NH_CFGSettingsObjectDidChange(self, notification):
settings = SIPSimpleSettings()
if notification.sender is settings:
if 'logs.directory' in notification.data.modified:
# sip trace
if self._siptrace_file is not None:
self._siptrace_file.close()
self._siptrace_file = None
# pjsip trace
if self._pjsiptrace_file is not None:
self._pjsiptrace_file.close()
self._pjsiptrace_file = None
# notifications trace
if self._notifications_file is not None:
self._notifications_file.close()
self._notifications_file = None
# try to create the log directory
try:
self._init_log_directory()
except Exception:
pass
# log handlers
#
def _LH_SIPEngineSIPTrace(self, notification):
settings = SIPSimpleSettings()
if not settings.logs.trace_sip:
return
if self._siptrace_start_time is None:
self._siptrace_start_time = notification.data.timestamp
self._siptrace_packet_count += 1
if notification.data.received:
direction = "RECEIVED"
else:
direction = "SENDING"
buf = ["%s: Packet %d, +%s" % (direction, self._siptrace_packet_count, (notification.data.timestamp - self._siptrace_start_time))]
buf.append("%(source_ip)s:%(source_port)d -(SIP over %(transport)s)-> %(destination_ip)s:%(destination_port)d" % notification.data.__dict__)
buf.append(notification.data.data)
buf.append('--')
message = '\n'.join(buf)
try:
self._init_log_file('siptrace')
except Exception:
pass
else:
self._siptrace_file.write('%s [%s %d]: %s\n' % (notification.data.timestamp, os.path.basename(sys.argv[0]).rstrip('.py'), os.getpid(), message))
self._siptrace_file.flush()
def _LH_SIPEngineLog(self, notification):
settings = SIPSimpleSettings()
if not settings.logs.trace_pjsip:
return
message = "(%(level)d) %(sender)14s: %(message)s" % notification.data.__dict__
try:
self._init_log_file('pjsiptrace')
except Exception:
pass
else:
self._pjsiptrace_file.write('%s [%s %d] %s\n' % (notification.data.timestamp, os.path.basename(sys.argv[0]).rstrip('.py'), os.getpid(), message))
self._pjsiptrace_file.flush()
def _LH_DNSLookupTrace(self, notification):
settings = SIPSimpleSettings()
if not settings.logs.trace_sip:
return
message = 'DNS lookup %(query_type)s %(query_name)s' % notification.data.__dict__
if notification.data.error is None:
message += ' succeeded, ttl=%d: ' % notification.data.answer.ttl
if notification.data.query_type == 'A':
message += ", ".join(record.address for record in notification.data.answer)
elif notification.data.query_type == 'SRV':
message += ", ".join('%d %d %d %s' % (record.priority, record.weight, record.port, record.target) for record in notification.data.answer)
elif notification.data.query_type == 'NAPTR':
message += ", ".join('%d %d "%s" "%s" "%s" %s' % (record.order, record.preference, record.flags, record.service, record.regexp, record.replacement) for record in notification.data.answer)
else:
import dns.resolver
message_map = {dns.resolver.NXDOMAIN: 'DNS record does not exist',
dns.resolver.NoAnswer: 'DNS response contains no answer',
dns.resolver.NoNameservers: 'no DNS name servers could be reached',
dns.resolver.Timeout: 'no DNS response received, the query has timed out'}
message += ' failed: %s' % message_map.get(notification.data.error.__class__, '')
try:
self._init_log_file('siptrace')
except Exception:
pass
else:
self._siptrace_file.write('%s [%s %d]: %s\n' % (notification.data.timestamp, os.path.basename(sys.argv[0]).rstrip('.py'), os.getpid(), message))
self._siptrace_file.flush()
def _LH_MSRPTransportTrace(self, notification):
settings = SIPSimpleSettings()
if not settings.logs.trace_msrp:
return
arrow = {'incoming': '<--', 'outgoing': '-->'}[notification.data.direction]
local_address = notification.sender.getHost()
local_address = '%s:%d' % (local_address.host, local_address.port)
remote_address = notification.sender.getPeer()
remote_address = '%s:%d' % (remote_address.host, remote_address.port)
message = '%s %s %s\n' % (local_address, arrow, remote_address) + notification.data.data
try:
self._init_log_file('msrptrace')
except Exception:
pass
else:
self._msrptrace_file.write('%s [%s %d]: %s\n' % (notification.data.timestamp, os.path.basename(sys.argv[0]).rstrip('.py'), os.getpid(), message))
self._msrptrace_file.flush()
def _LH_MSRPLibraryLog(self, notification):
settings = SIPSimpleSettings()
if not settings.logs.trace_msrp:
return
if notification.data.level < self.msrp_level:
return
message = '%s%s' % (notification.data.level.prefix, notification.data.message)
try:
self._init_log_file('msrptrace')
except Exception:
pass
else:
self._msrptrace_file.write('%s [%s %d]: %s\n' % (notification.data.timestamp, os.path.basename(sys.argv[0]).rstrip('.py'), os.getpid(), message))
self._msrptrace_file.flush()
# private methods
#
def _init_log_directory(self):
settings = SIPSimpleSettings()
log_directory = settings.logs.directory.normalized
try:
makedirs(log_directory)
except Exception, e:
if not self._log_directory_error:
print "failed to create logs directory '%s': %s" % (log_directory, e)
self._log_directory_error = True
self._siptrace_error = True
self._pjsiptrace_error = True
self._notifications_error = True
raise
else:
class FileLogger(object, metaclass=Singleton):
# public methods
#
def __init__(self, msrp_level=log.level.INFO):
self.msrp_level = msrp_level
self._siptrace_filename = None
self._siptrace_file = None
self._siptrace_error = False
self._siptrace_start_time = None
self._siptrace_packet_count = 0
self._msrptrace_filename = None
self._msrptrace_file = None
self._msrptrace_error = False
self._pjsiptrace_filename = None
self._pjsiptrace_file = None
self._pjsiptrace_error = False
self._notifications_filename = None
self._notifications_file = None
self._notifications_error = False
self._log_directory_error = False
self._event_queue = None
def start(self):
# try to create the log directory
try:
self._init_log_directory()
except Exception:
pass
# register to receive log notifications
notification_center = NotificationCenter()
notification_center.add_observer(self)
# start the thread processing the notifications
self._event_queue = EventQueue(handler=self._process_notification,
name='Log handling')
self._event_queue.start()
def stop(self):
# stop the thread processing the notifications
self._event_queue.stop()
self._event_queue.join()
# close sip trace file
if self._siptrace_file is not None:
self._siptrace_file.close()
self._siptrace_file = None
# close msrp trace file
if self._msrptrace_file is not None:
self._msrptrace_file.close()
self._msrptrace_file = None
# close pjsip trace file
if self._pjsiptrace_file is not None:
self._pjsiptrace_file.close()
self._pjsiptrace_file = None
# close notifications trace file
if self._notifications_file is not None:
self._notifications_file.close()
self._notifications_file = None
# unregister from receiving notifications
notification_center = NotificationCenter()
notification_center.remove_observer(self)
def handle_notification(self, notification):
self._event_queue.put(notification)
def _process_notification(self, notification):
settings = SIPSimpleSettings()
handler = getattr(self, '_NH_%s' % notification.name, None)
if handler is not None:
handler(notification)
handler = getattr(self, '_LH_%s' % notification.name, None)
if handler is not None:
handler(notification)
if notification.name not in (
'SIPEngineLog', 'SIPEngineSIPTrace'
) and settings.logs.trace_notifications and settings.logs.trace_notifications_to_file:
try:
self._init_log_file('notifications')
except Exception:
pass
else:
message = 'Notification name=%s sender=%s data=%s' % (
notification.name, notification.sender,
pformat(notification.data))
try:
self._notifications_file.write(
'%s: %s\n' % (datetime.datetime.now(), message))
self._notifications_file.flush()
except Exception as e:
print('Write message failed: %s' % message)
# notification handlers
#
def _NH_CFGSettingsObjectDidChange(self, notification):
settings = SIPSimpleSettings()
if notification.sender is settings:
if 'logs.directory' in notification.data.modified:
# sip trace
if self._siptrace_file is not None:
self._siptrace_file.close()
self._siptrace_file = None
# pjsip trace
if self._pjsiptrace_file is not None:
self._pjsiptrace_file.close()
self._pjsiptrace_file = None
# notifications trace
if self._notifications_file is not None:
self._notifications_file.close()
self._notifications_file = None
# try to create the log directory
try:
self._init_log_directory()
except Exception:
pass
# log handlers
#
def _LH_SIPEngineSIPTrace(self, notification):
settings = SIPSimpleSettings()
if not settings.logs.trace_sip or not settings.logs.trace_sip_to_file:
return
if self._siptrace_start_time is None:
self._siptrace_start_time = notification.datetime
self._siptrace_packet_count += 1
if notification.data.received:
direction = "RECEIVED"
else:
direction = "SENDING"
buf = [
"%s: Packet %d, +%s" %
(direction, self._siptrace_packet_count,
(notification.datetime - self._siptrace_start_time))
]
buf.append(
"%(source_ip)s:%(source_port)d -(SIP over %(transport)s)-> %(destination_ip)s:%(destination_port)d"
% notification.data.__dict__)
buf.append(notification.data.data)
buf.append('--')
message = '\n'.join(buf)
try:
self._init_log_file('siptrace')
except Exception:
pass
else:
self._siptrace_file.write(
'%s [%s %d]: %s\n' %
(notification.datetime, os.path.basename(
sys.argv[0]).rstrip('.py'), os.getpid(), message))
self._siptrace_file.flush()
def _LH_SIPEngineLog(self, notification):
settings = SIPSimpleSettings()
if not settings.logs.trace_pjsip or not settings.logs.trace_pjsip_to_file:
return
message = "(%(level)d) %(message)s" % notification.data.__dict__
try:
self._init_log_file('pjsiptrace')
except Exception:
pass
else:
self._pjsiptrace_file.write('[%s %d] %s\n' % (os.path.basename(
sys.argv[0]).rstrip('.py'), os.getpid(), message))
self._pjsiptrace_file.flush()
def _LH_DNSLookupTrace(self, notification):
settings = SIPSimpleSettings()
if not settings.logs.trace_sip or not settings.logs.trace_sip_to_file:
return
message = 'DNS lookup %(query_type)s %(query_name)s' % notification.data.__dict__
if notification.data.error is None:
message += ' succeeded, ttl=%d: ' % notification.data.answer.ttl
if notification.data.query_type == 'A':
message += ", ".join(record.address
for record in notification.data.answer)
elif notification.data.query_type == 'SRV':
message += ", ".join('%d %d %d %s' %
(record.priority, record.weight,
record.port, record.target)
for record in notification.data.answer)
elif notification.data.query_type == 'NAPTR':
message += ", ".join(
'%d %d "%s" "%s" "%s" %s' %
(record.order, record.preference, record.flags,
record.service, record.regexp, record.replacement)
for record in notification.data.answer)
else:
import dns.resolver
message_map = {
dns.resolver.NXDOMAIN:
'DNS record does not exist',
dns.resolver.NoAnswer:
'DNS response contains no answer',
dns.resolver.NoNameservers:
'no DNS name servers could be reached',
dns.resolver.Timeout:
'no DNS response received, the query has timed out'
}
message += ' failed: %s' % message_map.get(
notification.data.error.__class__, '')
try:
self._init_log_file('siptrace')
except Exception:
pass
else:
self._siptrace_file.write(
'%s [%s %d]: %s\n' %
(notification.datetime, os.path.basename(
sys.argv[0]).rstrip('.py'), os.getpid(), message))
self._siptrace_file.flush()
def _LH_MSRPTransportTrace(self, notification):
settings = SIPSimpleSettings()
if not settings.logs.trace_msrp or not settings.logs.trace_msrp_to_file:
return
arrow = {
'incoming': '<--',
'outgoing': '-->'
}[notification.data.direction]
local_address = notification.sender.getHost()
local_address = '%s:%d' % (local_address.host, local_address.port)
remote_address = notification.sender.getPeer()
remote_address = '%s:%d' % (remote_address.host, remote_address.port)
message = '%s %s %s\n' % (local_address, arrow,
remote_address) + notification.data.data
try:
self._init_log_file('msrptrace')
except Exception:
pass
else:
self._msrptrace_file.write(
'%s [%s %d]: %s\n' %
(notification.datetime, os.path.basename(
sys.argv[0]).rstrip('.py'), os.getpid(), message))
self._msrptrace_file.flush()
def _LH_MSRPLibraryLog(self, notification):
settings = SIPSimpleSettings()
if not settings.logs.trace_msrp or not settings.logs.trace_msrp_to_file:
return
if notification.data.level < self.msrp_level:
return
message = '%s%s' % (notification.data.level.prefix,
notification.data.message)
try:
self._init_log_file('msrptrace')
except Exception:
pass
else:
self._msrptrace_file.write(
'%s [%s %d]: %s\n' %
(notification.datetime, os.path.basename(
sys.argv[0]).rstrip('.py'), os.getpid(), message))
self._msrptrace_file.flush()
# private methods
#
def _init_log_directory(self):
settings = SIPSimpleSettings()
log_directory = settings.logs.directory.normalized
try:
makedirs(log_directory)
except Exception as e:
if not self._log_directory_error:
print("failed to create logs directory '%s': %s" %
(log_directory, e))
self._log_directory_error = True
self._siptrace_error = True
self._pjsiptrace_error = True
self._notifications_error = True
raise
else:
self._log_directory_error = False
# sip trace
if self._siptrace_filename is None:
self._siptrace_filename = os.path.join(log_directory,
'sip_trace.txt')
self._siptrace_error = False
# msrp trace
if self._msrptrace_filename is None:
self._msrptrace_filename = os.path.join(
log_directory, 'msrp_trace.txt')
self._msrptrace_error = False
# pjsip trace
if self._pjsiptrace_filename is None:
self._pjsiptrace_filename = os.path.join(
log_directory, 'pjsip_trace.txt')
self._pjsiptrace_error = False
# notifications trace
if self._notifications_filename is None:
self._notifications_filename = os.path.join(
log_directory, 'notifications_trace.txt')
self._notifications_error = False
def _init_log_file(self, type):
if getattr(self, '_%s_file' % type) is None:
self._init_log_directory()
filename = getattr(self, '_%s_filename' % type)
try:
setattr(self, '_%s_file' % type, open(filename, 'a'))
except Exception as e:
if not getattr(self, '_%s_error' % type):
print("failed to create log file '%s': %s" % (filename, e))
setattr(self, '_%s_error' % type, True)
raise
else:
setattr(self, '_%s_error' % type, False)
class RadiusDatabase(object):
"""Interface with the Radius database"""
class RadiusTask(object):
def __init__(self, deferred, tasktype, **kwargs):
self.deferred = deferred
self.tasktype = tasktype
self.args = kwargs
def __init__(self):
self.queue = EventQueue(handler=self._handle_task, name='RadiusQueue')
self.queue.start()
credentials = RadiusDatabaseConfig.user and (
"%s%s@" % (RadiusDatabaseConfig.user,
RadiusDatabaseConfig.password and ":%s" %
(RadiusDatabaseConfig.password) or '')) or ''
self.conn = sqlobject.connectionForURI(
"mysql://%s%s/%s" % (credentials, RadiusDatabaseConfig.host,
RadiusDatabaseConfig.database))
def close(self):
return threads.deferToThread(self._close)
def _close(self):
self.queue.stop()
self.queue.join()
self.conn.close()
def getTerminatedCalls(self, calls):
"""
Retrieve those calls from the ones in progress that were already terminated by caller/called.
Returns a Deferred. Callback will be called with list of call ids.
"""
deferred = defer.Deferred()
self.queue.put(
RadiusDatabase.RadiusTask(deferred, 'terminated', calls=calls))
return deferred
def getTimedoutCalls(self, calls):
"""
Retrieve those calls from the ones in progress that did timeout and were closed by mediaproxy.
Returns a Deferred. Callback will be called with list of call ids.
"""
deferred = defer.Deferred()
self.queue.put(
RadiusDatabase.RadiusTask(deferred, 'timedout', calls=calls))
return deferred
def query(self, task):
def _unknown_task(task):
raise RadiusDatabaseError("Got unknown task to handle: %s" %
task.tasktype)
return getattr(self, '_RD_%s' % task.tasktype, _unknown_task)(task)
def _handle_task(self, task):
try:
reactor.callFromThread(task.deferred.callback, self.query(task))
except Exception, e:
reactor.callFromThread(task.deferred.errback, failure.Failure(e))
class TraceManager(object):
__metaclass__ = Singleton
implements(IObserver)
def __init__(self):
self.name = os.path.basename(sys.argv[0]).rsplit('.py', 1)[0]
self.pid = os.getpid()
self.msrp_level = log.level.INFO
self.siptrace_file = Null
self.msrptrace_file = Null
self.pjsiptrace_file = Null
self.notifications_file = Null
self.event_queue = Null
self.notification_queue = NotificationQueue()
self._siptrace_start_time = None
self._siptrace_packet_count = None
def start(self):
settings = SIPSimpleSettings()
notification_center = NotificationCenter()
notification_center.add_observer(self)
self.siptrace_file = LogFile(os.path.join(ApplicationData.directory, 'logs', 'sip.log'))
self.msrptrace_file = LogFile(os.path.join(ApplicationData.directory, 'logs', 'msrp.log'))
self.pjsiptrace_file = LogFile(os.path.join(ApplicationData.directory, 'logs', 'pjsip.log'))
self.notifications_file = LogFile(os.path.join(ApplicationData.directory, 'logs', 'notifications.log'))
self._siptrace_start_time = datetime.now()
self._siptrace_packet_count = 0
self.event_queue = EventQueue(handler=self._process_notification, name='Log handling')
self.event_queue.start()
while settings.logs.trace_notifications and self.notification_queue and self.notification_queue.notifications:
notification = self.notification_queue.notifications.popleft()
self.handle_notification(notification)
self.notification_queue = None
def stop(self):
notification_center = NotificationCenter()
notification_center.remove_observer(self)
self.event_queue.stop()
self.event_queue.join()
self.event_queue = Null
self.siptrace_file = Null
self.msrptrace_file = Null
self.pjsiptrace_file = Null
self.notifications_file = Null
def handle_notification(self, notification):
self.event_queue.put(notification)
def _process_notification(self, notification):
handler = getattr(self, '_NH_%s' % notification.name, Null)
handler(notification)
handler = getattr(self, '_LH_%s' % notification.name, Null)
handler(notification)
settings = SIPSimpleSettings()
if notification.name not in ('SIPEngineLog', 'SIPEngineSIPTrace') and settings.logs.trace_notifications:
message = 'Notification name=%s sender=%s data=%s' % (notification.name, notification.sender, pformat(notification.data))
try:
self.notifications_file.write('%s [%s %d]: %s\n' % (datetime.now(), self.name, self.pid, message))
except Exception:
pass
def _LH_SIPEngineSIPTrace(self, notification):
settings = SIPSimpleSettings()
if not settings.logs.trace_sip:
return
self._siptrace_packet_count += 1
if notification.data.received:
direction = "RECEIVED"
else:
direction = "SENDING"
buf = ["%s: Packet %d, +%s" % (direction, self._siptrace_packet_count, (notification.datetime - self._siptrace_start_time))]
buf.append("%(source_ip)s:%(source_port)d -(SIP over %(transport)s)-> %(destination_ip)s:%(destination_port)d" % notification.data.__dict__)
buf.append(notification.data.data)
buf.append('--')
message = '\n'.join(buf)
try:
self.siptrace_file.write('%s [%s %d]: %s\n' % (notification.datetime, self.name, self.pid, message))
except Exception:
pass
def _LH_SIPEngineLog(self, notification):
settings = SIPSimpleSettings()
if not settings.logs.trace_pjsip:
return
message = "(%(level)d) %(message)s" % notification.data.__dict__
try:
self.pjsiptrace_file.write('[%s %d] %s\n' % (self.name, self.pid, message))
except Exception:
pass
def _LH_DNSLookupTrace(self, notification):
settings = SIPSimpleSettings()
if not settings.logs.trace_sip:
return
message = 'DNS lookup %(query_type)s %(query_name)s' % notification.data.__dict__
if notification.data.error is None:
message += ' succeeded, ttl=%d: ' % notification.data.answer.ttl
if notification.data.query_type == 'A':
message += ", ".join(record.address for record in notification.data.answer)
elif notification.data.query_type == 'SRV':
message += ", ".join('%d %d %d %s' % (record.priority, record.weight, record.port, record.target) for record in notification.data.answer)
elif notification.data.query_type == 'NAPTR':
message += ", ".join('%d %d "%s" "%s" "%s" %s' % (record.order, record.preference, record.flags, record.service, record.regexp, record.replacement) for record in notification.data.answer)
else:
import dns.resolver
message_map = {dns.resolver.NXDOMAIN: 'DNS record does not exist',
dns.resolver.NoAnswer: 'DNS response contains no answer',
dns.resolver.NoNameservers: 'no DNS name servers could be reached',
dns.resolver.Timeout: 'no DNS response received, the query has timed out'}
message += ' failed: %s' % message_map.get(notification.data.error.__class__, '')
try:
self.siptrace_file.write('%s [%s %d]: %s\n' % (notification.datetime, self.name, self.pid, message))
except Exception:
pass
def _LH_MSRPTransportTrace(self, notification):
settings = SIPSimpleSettings()
if not settings.logs.trace_msrp:
return
arrow = {'incoming': '<--', 'outgoing': '-->'}[notification.data.direction]
local_address = notification.data.local_address
local_address = '%s:%d' % (local_address.host, local_address.port)
remote_address = notification.data.remote_address
remote_address = '%s:%d' % (remote_address.host, remote_address.port)
message = '%s %s %s\n' % (local_address, arrow, remote_address) + notification.data.data
try:
self.msrptrace_file.write('%s [%s %d]: %s\n' % (notification.datetime, self.name, self.pid, message))
except Exception:
pass
def _LH_MSRPLibraryLog(self, notification):
settings = SIPSimpleSettings()
if not settings.logs.trace_msrp:
return
if notification.data.level < self.msrp_level:
return
message = '%s%s' % (notification.data.level.prefix, notification.data.message)
try:
self.msrptrace_file.write('%s [%s %d]: %s\n' % (notification.datetime, self.name, self.pid, message))
except Exception:
pass
class RadiusDatabase(object):
"""Interface with the Radius database"""
class RadiusTask(object):
def __init__(self, deferred, tasktype, **kwargs):
self.deferred = deferred
self.tasktype = tasktype
self.args = kwargs
def __init__(self):
self.queue = EventQueue(handler=self._handle_task, name='RadiusQueue')
self.queue.start()
credentials = RadiusDatabaseConfig.user and ( "%s%s@" % (RadiusDatabaseConfig.user, RadiusDatabaseConfig.password and ":%s" % (RadiusDatabaseConfig.password) or '') ) or ''
self.conn = sqlobject.connectionForURI("mysql://%s%s/%s" % (credentials, RadiusDatabaseConfig.host, RadiusDatabaseConfig.database))
def close(self):
return threads.deferToThread(self._close)
def _close(self):
self.queue.stop()
self.queue.join()
self.conn.close()
def getTerminatedCalls(self, calls):
"""
Retrieve those calls from the ones in progress that were already terminated by caller/called.
Returns a Deferred. Callback will be called with list of call ids.
"""
deferred = defer.Deferred()
self.queue.put(RadiusDatabase.RadiusTask(deferred, 'terminated', calls=calls))
return deferred
def getTimedoutCalls(self, calls):
"""
Retrieve those calls from the ones in progress that did timeout and were closed by mediaproxy.
Returns a Deferred. Callback will be called with list of call ids.
"""
deferred = defer.Deferred()
self.queue.put(RadiusDatabase.RadiusTask(deferred, 'timedout', calls=calls))
return deferred
def query(self, task):
def _unknown_task(task):
raise RadiusDatabaseError("Got unknown task to handle: %s" % task.tasktype)
return getattr(self, '_RD_%s' % task.tasktype, _unknown_task)(task)
def _handle_task(self, task):
try:
reactor.callFromThread(task.deferred.callback, self.query(task))
except Exception as e:
reactor.callFromThread(task.deferred.errback, failure.Failure(e))
def _RD_terminated(self, task):
calls = dict([(call.callid, call) for call in list(task.args['calls'].values()) if call.inprogress])
if not calls:
return {}
ids = "(%s)" % ','.join(["'" + key + "'" for key in list(calls.keys())])
query = """SELECT %(session_id_field)s AS callid, %(duration_field)s AS duration,
%(from_tag_field)s AS fromtag, %(to_tag_field)s AS totag
FROM %(table)s
WHERE %(session_id_field)s IN %(ids)s AND
(%(stop_info_field)s IS NOT NULL OR
%(stop_time_field)s IS NOT NULL)""" % {'session_id_field': RadiusDatabaseConfig.sessionIdField,
'duration_field': RadiusDatabaseConfig.durationField,
'from_tag_field': RadiusDatabaseConfig.fromTagField,
'to_tag_field': RadiusDatabaseConfig.toTagField,
'stop_info_field': RadiusDatabaseConfig.stopInfoField,
'stop_time_field': RadiusDatabaseConfig.stopTimeField,
'table': RadiusDatabaseConfig.table.normalized,
'ids': ids}
try:
rows = self.conn.queryAll(query)
except Exception as e:
log.error("Query failed: %s" % query)
raise RadiusDatabaseError("Exception while querying for terminated calls %s." % e)
def find(row, calls):
try:
call = calls[row[0]]
except KeyError:
return False
return call.fromtag==row[2] and call.totag==row[3]
return dict([(row[0], {'callid': row[0], 'duration': row[1], 'fromtag': row[2], 'totag': row[3]}) for row in rows if find(row, calls)])
def _RD_timedout(self, task):
calls = dict([(call.callid, call) for call in list(task.args['calls'].values()) if call.inprogress])
if not calls:
return {}
ids = "(%s)" % ','.join(["'" + key + "'" for key in list(calls.keys())])
query = '''SELECT %(session_id_field)s AS callid, %(duration_field)s AS duration,
%(from_tag_field)s AS fromtag, %(to_tag_field)s AS totag
FROM %(table)s
WHERE %(session_id_field)s IN %(ids)s AND
%(media_info_field)s = 'timeout' AND
%(stop_info_field)s IS NULL''' % {'session_id_field': RadiusDatabaseConfig.sessionIdField,
'duration_field': RadiusDatabaseConfig.durationField,
'from_tag_field': RadiusDatabaseConfig.fromTagField,
'to_tag_field': RadiusDatabaseConfig.toTagField,
'media_info_field': RadiusDatabaseConfig.mediaInfoField,
'stop_info_field': RadiusDatabaseConfig.stopInfoField,
'table': RadiusDatabaseConfig.table.normalized,
'ids': ids}
try:
rows = self.conn.queryAll(query)
except Exception as e:
log.error("Query failed: %s" % query)
raise RadiusDatabaseError("Exception while querying for timedout calls %s." % e)
def find(row, calls):
try:
call = calls[row[0]]
except KeyError:
return False
return call.fromtag==row[2] and call.totag==row[3]
return dict([(row[0], {'callid': row[0], 'duration': row[1], 'fromtag': row[2], 'totag': row[3]}) for row in rows if find(row, calls)])
