Commit 0eb4e311 authored by Jerry's avatar Jerry
Browse files

merge of ticket #176 (python logging framework), also changes xfrout to use the python logging.

[func]       jerry
Added python logging framework. It is for testing and experimenting
with logging ideas. Currently, it supports three channels(file,
syslog and stderr) and five levels(debug, info, warning, error and
critical).



git-svn-id: svn://bind10.isc.org/svn/bind10/trunk@2338 e5f2f494-b856-4b98-b285-d166d9295462
parents dabb1631 bfc4bec5
64. [func] jerry
Added python logging framework. It is for testing and experimenting
with logging ideas. Currently, it supports three channels(file,
syslog and stderr) and five levels(debug, info, warning, error and
critical).
(Trac #176, svn r2338)
63. [func] shane
Added initial support for setuid(), using the "-u" flag. This will
be replaced in the future, but for now provides a reasonable
......
......@@ -433,6 +433,8 @@ AC_CONFIG_FILES([Makefile
src/lib/python/isc/cc/tests/Makefile
src/lib/python/isc/config/Makefile
src/lib/python/isc/config/tests/Makefile
src/lib/python/isc/log/Makefile
src/lib/python/isc/log/tests/Makefile
src/lib/config/Makefile
src/lib/config/tests/Makefile
src/lib/dns/Makefile
......@@ -473,6 +475,7 @@ AC_OUTPUT([src/bin/cfgmgr/b10-cfgmgr.py
src/lib/config/tests/data_def_unittests_config.h
src/lib/python/isc/config/tests/config_test
src/lib/python/isc/cc/tests/cc_test
src/lib/python/isc/log/tests/log_test
src/lib/dns/gen-rdatacode.py
src/lib/python/bind10_config.py
src/lib/dns/tests/testdata/gen-wiredata.py
......
......@@ -75,7 +75,8 @@ class TestXfroutSession(unittest.TestCase):
def setUp(self):
request = MySocket(socket.AF_INET,socket.SOCK_STREAM)
self.xfrsess = MyXfroutSession(request, None, None)
self.log = isc.log.NSLogger('xfrout', '', severity = 'critical', log_to_console = False )
self.xfrsess = MyXfroutSession(request, None, None, self.log)
self.xfrsess.server = Dbserver()
self.mdata = b'\xd6=\x00\x00\x00\x01\x00\x00\x00\x00\x00\x00\x07example\x03com\x00\x00\xfc\x00\x01'
self.sock = MySocket(socket.AF_INET,socket.SOCK_STREAM)
......@@ -238,10 +239,6 @@ class TestXfroutSession(unittest.TestCase):
reply_msg = self.sock.read_msg()
self.assertEqual(reply_msg.get_rr_count(section.ANSWER()), 2)
# set event
self.xfrsess.server._shutdown_event.set()
self.assertRaises(XfroutException, self.xfrsess._reply_xfrout_query, self.getmsg(), self.sock, "example.com.")
class MyCCSession():
def __init__(self):
pass
......@@ -260,6 +257,7 @@ class MyUnixSockServer(UnixSockServer):
self._shutdown_event = threading.Event()
self._max_transfers_out = 10
self._cc = MyCCSession()
self._log = isc.log.NSLogger('xfrout', '', severity = 'critical', log_to_console = False )
class TestUnixSockServer(unittest.TestCase):
def setUp(self):
......
......@@ -26,6 +26,7 @@ from isc.datasrc import sqlite3_ds
from socketserver import *
import os
from isc.config.ccsession import *
from isc.log.log import *
from isc.cc import SessionError
import socket
import select
......@@ -53,21 +54,20 @@ else:
SPECFILE_LOCATION = SPECFILE_PATH + "/xfrout.spec"
AUTH_SPECFILE_LOCATION = AUTH_SPECFILE_PATH + os.sep + "auth.spec"
MAX_TRANSFERS_OUT = 10
verbose_mode = False
class XfroutException(Exception): pass
VERBOSE_MODE = False
class XfroutSession(BaseRequestHandler):
def __init__(self, request, client_address, server, log):
BaseRequestHandler.__init__(self, request, client_address, server)
self._log = log
def handle(self):
fd = recv_fd(self.request.fileno())
if fd < 0:
# This may happen when one xfrout process try to connect to
# xfrout unix socket server, to check whether there is another
# xfrout running.
print("[b10-xfrout] Failed to receive the FD for XFR connection, "
"maybe because another xfrout process was started.")
self._log.log_message("error", "Failed to receive the file descriptor for XFR connection")
return
data_len = self.request.recv(2)
......@@ -77,8 +77,7 @@ class XfroutSession(BaseRequestHandler):
try:
self.dns_xfrout_start(sock, msgdata)
except Exception as e:
if verbose_mode:
self.log_msg(str(e))
self._log.log_message("error", str(e))
sock.close()
......@@ -89,8 +88,7 @@ class XfroutSession(BaseRequestHandler):
msg = message(message_mode.PARSE)
msg.from_wire(input_buffer(mdata))
except Exception as err:
if verbose_mode:
self.log_msg(str(err))
self._log.log_message("error", str(err))
return rcode.FORMERR(), None
return rcode.NOERROR(), msg
......@@ -179,16 +177,11 @@ class XfroutSession(BaseRequestHandler):
return self. _reply_query_with_error_rcode(msg, sock, rcode_)
try:
if verbose_mode:
self.log_msg("transfer of '%s/IN': AXFR started" % zone_name)
self._log.log_message("info", "transfer of '%s/IN': AXFR started" % zone_name)
self._reply_xfrout_query(msg, sock, zone_name)
if verbose_mode:
self.log_msg("transfer of '%s/IN': AXFR end" % zone_name)
self._log.log_message("info", "transfer of '%s/IN': AXFR end" % zone_name)
except Exception as err:
if verbose_mode:
sys.stderr.write("[b10-xfrout] %s\n" % str(err))
self._log.log_message("error", str(err))
self.server.decrease_transfers_counter()
return
......@@ -262,7 +255,7 @@ class XfroutSession(BaseRequestHandler):
# the message length to know if the rrset has been added sucessfully.
for rr_data in sqlite3_ds.get_zone_datas(zone_name, self.server.get_db_file()):
if self.server._shutdown_event.is_set(): # Check if xfrout is shutdown
raise XfroutException("shutdown!")
self._log.log_message("error", "shutdown!")
if rr_type(rr_data[5]) == rr_type.SOA(): #ignore soa record
continue
......@@ -281,22 +274,23 @@ class XfroutSession(BaseRequestHandler):
self._send_message_with_last_soa(msg, sock, rrset_soa)
def log_msg(self, msg):
print('[b10-xfrout] ', msg)
class UnixSockServer(ThreadingUnixStreamServer):
'''The unix domain socket server which accept xfr query sent from auth server.'''
def __init__(self, sock_file, handle_class, shutdown_event, config_data, cc):
def __init__(self, sock_file, handle_class, shutdown_event, config_data, cc, log):
self._remove_unused_sock_file(sock_file)
self._sock_file = sock_file
ThreadingUnixStreamServer.__init__(self, sock_file, handle_class)
self._lock = threading.Lock()
self._transfers_counter = 0
self._shutdown_event = shutdown_event
self._log = log
self.update_config_data(config_data)
self._cc = cc
def finish_request(self, request, client_address):
'''Finish one request by instantiating RequestHandlerClass.'''
self.RequestHandlerClass(request, client_address, self, self._log)
def _remove_unused_sock_file(self, sock_file):
'''Try to remove the socket file. If the file is being used
......@@ -333,14 +327,17 @@ class UnixSockServer(ThreadingUnixStreamServer):
ThreadingUnixStreamServer.shutdown(self)
try:
os.unlink(self._sock_file)
except:
pass
except Exception as e:
self._log.log_message("error", str(e))
def update_config_data(self, new_config):
'''Apply the new config setting of xfrout module. '''
self._log.log_message('info', 'update config data start.')
self._lock.acquire()
self._max_transfers_out = new_config.get('transfers_out')
self._log.log_message('info', 'max transfer out : %d', self._max_transfers_out)
self._lock.release()
self._log.log_message('info', 'update config data complete.')
def get_db_file(self):
file, is_default = self._cc.get_remote_config_value("Auth", "database_file")
......@@ -391,19 +388,24 @@ def listen_on_xfr_query(unix_socket_server):
class XfroutServer:
def __init__(self):
self._unix_socket_server = None
self._log = None
self._listen_sock_file = UNIX_SOCKET_FILE
self._shutdown_event = threading.Event()
self._cc = isc.config.ModuleCCSession(SPECFILE_LOCATION, self.config_handler, self.command_handler)
self._cc.add_remote_config(AUTH_SPECFILE_LOCATION);
self._config_data = self._cc.get_full_config()
self._cc.start()
self._log = isc.log.NSLogger(self._config_data.get('log_name'), self._config_data.get('log_file'),
self._config_data.get('log_severity'), self._config_data.get('log_versions'),
self._config_data.get('log_max_bytes'), True)
self._start_xfr_query_listener()
def _start_xfr_query_listener(self):
'''Start a new thread to accept xfr query. '''
self._unix_socket_server = UnixSockServer(self._listen_sock_file, XfroutSession,
self._shutdown_event, self._config_data, self._cc);
self._shutdown_event, self._config_data,
self._cc, self._log);
listener = threading.Thread(target = listen_on_xfr_query, args = (self._unix_socket_server,))
listener.start()
......@@ -417,6 +419,9 @@ class XfroutServer:
continue
self._config_data[key] = new_config[key]
if self._log:
self._log.update_config(new_config)
if self._unix_socket_server:
self._unix_socket_server.update_config_data(self._config_data)
......@@ -442,8 +447,7 @@ class XfroutServer:
def command_handler(self, cmd, args):
if cmd == "shutdown":
if verbose_mode:
print("[b10-xfrout] Received shutdown command")
self._log.log_message("info", "Received shutdown command.")
self.shutdown()
answer = create_answer(0)
else:
......@@ -478,18 +482,18 @@ if '__main__' == __name__:
parser = OptionParser()
set_cmd_options(parser)
(options, args) = parser.parse_args()
verbose_mode = options.verbose
VERBOSE_MODE = options.verbose
set_signal_handler()
xfrout_server = XfroutServer()
xfrout_server.run()
except KeyboardInterrupt:
print("[b10-xfrout] exit xfrout process")
sys.stderr.write("[b10-xfrout] exit xfrout process")
except SessionError as e:
print('[b10-xfrout] Error creating xfrout, '
'is the command channel daemon running?' )
sys.stderr.write("[b10-xfrout] Error creating xfrout,"
"is the command channel daemon running?")
except ModuleCCSessionError as e:
print('[b10-xfrout] exit xfrout process:', e)
sys.stderr.write("info", '[b10-xfrout] exit xfrout process:', e)
if xfrout_server:
xfrout_server.shutdown()
......
......@@ -12,7 +12,37 @@
"item_name": "db_file",
"item_type": "string",
"item_optional": False,
"item_default": '@@LOCALSTATEDIR@@/@PACKAGE@/zone.sqlite3'
"item_default": "@@LOCALSTATEDIR@@/@PACKAGE@/zone.sqlite3"
},
{
"item_name": "log_name",
"item_type": "string",
"item_optional": False,
"item_default": "Xfrout"
},
{
"item_name": "log_file",
"item_type": "string",
"item_optional": False,
"item_default": "@@LOCALSTATEDIR@@/@PACKAGE@/log/Xfrout.log"
},
{
"item_name": "log_severity",
"item_type": "string",
"item_optional": False,
"item_default": "debug"
},
{
"item_name": "log_versions",
"item_type": "integer",
"item_optional": False,
"item_default": 5
},
{
"item_name": "log_max_bytes",
"item_type": "integer",
"item_optional": False,
"item_default": 1048576
}
],
"commands": [
......
SUBDIRS = datasrc cc config # Util
SUBDIRS = datasrc cc config log # Util
python_PYTHON = __init__.py
......
import isc.datasrc
import isc.cc
import isc.config
import isc.log
SUBDIRS = tests
python_PYTHON = __init__.py log.py
pythondir = $(pyexecdir)/isc/log
pytest:
$(SHELL) tests/log_test
from isc.log.log import *
# Copyright (C) 2010 Internet Systems Consortium.
#
# Permission to use, copy, modify, and distribute this software for any
# purpose with or without fee is hereby granted, provided that the above
# copyright notice and this permission notice appear in all copies.
#
# THE SOFTWARE IS PROVIDED "AS IS" AND INTERNET SYSTEMS CONSORTIUM
# DISCLAIMS ALL WARRANTIES WITH REGARD TO THIS SOFTWARE INCLUDING ALL
# IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS. IN NO EVENT SHALL
# INTERNET SYSTEMS CONSORTIUM BE LIABLE FOR ANY SPECIAL, DIRECT,
# INDIRECT, OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES WHATSOEVER RESULTING
# FROM LOSS OF USE, DATA OR PROFITS, WHETHER IN AN ACTION OF CONTRACT,
# NEGLIGENCE OR OTHER TORTIOUS ACTION, ARISING OUT OF OR IN CONNECTION
# WITH THE USE OR PERFORMANCE OF THIS SOFTWARE.
"""This module is to convert python logging module over
to log4python.
Copyright (C) 2010 Internet Systems Consortium.
To use, simply 'import isc.log.log' and log away!
"""
import os
import syslog
import logging
import logging.handlers
"""LEVELS: logging levels mapping
"""
LEVELS = {'debug' : logging.DEBUG,
'info' : logging.INFO,
'warning' : logging.WARNING,
'error' : logging.ERROR,
'critical' : logging.CRITICAL}
FORMATTER = logging.Formatter("%(name)s: %(levelname)s: %(message)s")
TIME_FORMATTER = logging.Formatter("%(asctime)s.%(msecs)03d %(name)s: %(levelname)s: %(message)s",
"%d-%b-%Y %H:%M:%S")
class NSFileLogHandler(logging.handlers.RotatingFileHandler):
"""RotatingFileHandler: replace RotatingFileHandler with a custom handler"""
def __init__(self, filename, mode='a', maxBytes=0, backupCount=0, encoding=None, delay=0):
dir = os.path.split(filename)
if not (os.path.exists(dir[0])):
os.makedirs(dir[0])
super(NSFileLogHandler, self).__init__(filename, mode, maxBytes,
backupCount, encoding, delay)
def shouldRollover(self, record):
"""Rewrite RotatingFileHandler.shouldRollover.
If the log file is deleted at runtime, a new file will be created.
"""
dfn = self.baseFilename
if (self.stream) and (not os.path.exists(dfn)): #Does log file exist?
self.stream.close()
dir = os.path.split(dfn)
if not (os.path.exists(dir[0])): #Does log subdirectory exist?
os.makedirs(dir[0])
self.stream = self._open()
return super(NSFileLogHandler, self).shouldRollover(record)
def update_config(self, file_name, backup_count, max_bytes):
"""Update RotatingFileHandler configuration.
If the file path does not exist, we will use the old log file.
input:
log file name
max backup count
predetermined log file size
"""
dir = os.path.split(file_name)
if(os.path.exists(dir[0])):
self.baseFilename = file_name
self.maxBytes = max_bytes
self.backupCount = backup_count
class NSSysLogHandler(logging.Handler):
"""Replace SysLogHandler with a custom handler
A handler class which sends formatted logging records to a syslog
server.
"""
def __init__(self, ident, logopt=0, facility=syslog.LOG_USER):
"""Initialize a handler.
If facility is not specified, LOG_USER is used.
"""
super(NSSysLogHandler, self).__init__()
self._ident = ident
self._logopt = logopt
self._facility = facility
self._mappings = {
logging.DEBUG: syslog.LOG_DEBUG,
logging.INFO: syslog.LOG_INFO,
logging.WARNING: syslog.LOG_WARNING,
logging.ERROR: syslog.LOG_ERR,
logging.CRITICAL: syslog.LOG_CRIT,
}
def _encodeLevel(self, level):
"""Encoding the priority."""
return self._mappings.get(level, syslog.LOG_INFO)
def emit(self, record):
"""Emit a record.
The record is formatted, and then sent to the syslog server. If
exception information is present, it is NOT sent to the server.
"""
syslog.openlog(self._ident, self._logopt, self._facility)
msg = self.format(record)
prio = self._encodeLevel(record.levelno)
syslog.syslog(prio, msg)
syslog.closelog()
class NSLogger(logging.getLoggerClass()):
"""Override logging.logger behaviour."""
def __init__(self, log_name, log_file, severity='debug', versions=0,
max_bytes=0, log_to_console=True):
"""Initializes the logger with some specific parameters
If log_to_console is True, stream handler will be used;
else syslog handler will be used.
To disable file handler, set log_file = ''.
"""
self._log_name = log_name
self._log_file = log_file
self._severity = severity
self._versions = versions
self._max_bytes = max_bytes
super(NSLogger, self).__init__(self._log_name)
# Set up a specific logger with our desired output level
logLevel = LEVELS.get(self._severity, logging.NOTSET)
self.setLevel(logLevel)
self._file_handler = None
self._stream_handler = None
self._syslog_handler = None
self._add_rotate_handler(self._log_file, self._versions, self._max_bytes)
if log_to_console:
self._add_stream_handler()
else:
self._add_syslog_handler()
def _add_rotate_handler(self, log_file, backup_count, max_bytes):
"""Add a rotate file handler.
input:
log_file : the location of log file. Handler will not be created
if log_file=''
max_bytes : limit log growth
backup_count : max backup count
"""
if(log_file != 0 and log_file != ''):
try:
self._file_handler = NSFileLogHandler(filename = log_file,
maxBytes = max_bytes, backupCount = backup_count)
except IOError:
self._file_handler = None
return
self._file_handler.setFormatter(TIME_FORMATTER)
self.addHandler(self._file_handler)
def _add_stream_handler(self):
"""Add a stream handler.
sys.stderr will be used for logging output.
"""
self._stream_handler = logging.StreamHandler()
self._stream_handler.setFormatter(TIME_FORMATTER)
self.addHandler(self._stream_handler)
def _add_syslog_handler(self, nsfacility=syslog.LOG_USER):
"""Add a syslog handler.
If facility is not specified, LOG_USER is used.
The default severity level is INFO.
"""
self._syslog_handler = NSSysLogHandler('BIND10', facility = nsfacility)
self._syslog_handler.setFormatter(FORMATTER)
#set syslog handler severity level INFO
self._syslog_handler.setLevel(logging.INFO)
self.addHandler(self._syslog_handler)
def _update_rotate_handler(self, log_file, backup_count, max_bytes):
"""If the rotate file handler has been added to the logger, update its
configuration, or add it to the logger.
"""
if (self._file_handler in self.handlers):
if(log_file != 0 and log_file != ''):
self._file_handler.update_config(log_file, backup_count, max_bytes)
else:
"""If log file is empty, the handler will be removed."""
self._file_handler.flush()
self._file_handler.close()
self.removeHandler(self._file_handler)
else:
self._add_rotate_handler(log_file, backup_count, max_bytes)
def _get_config(self, config_data):
"""Get config data from module configuration"""
log_file_str = config_data.get('log_file')
if(log_file_str):
self._log_file = log_file_str
severity_str = config_data.get('log_severity')
if(severity_str):
self._severity = severity_str
versions_str = config_data.get('log_versions')
if(versions_str):
self._versions = int(versions_str)
max_bytes_str = config_data.get('log_max_bytes')
if(max_bytes_str):
self._max_bytes = int(max_bytes_str)
def update_config(self, config_data):
"""Update logger's configuration.
We can update logger's log level and its rotate file handler's configuration.
"""
self._get_config(config_data)
logLevel = LEVELS.get(self._severity, logging.NOTSET)
if(logLevel != self.getEffectiveLevel()):
self.setLevel(logLevel)
self._update_rotate_handler(self._log_file, self._versions, self._max_bytes)
def log_message(self, level, msg, *args, **kwargs):
"""Log 'msg % args' with the integer severity 'level'.
To pass exception information, use the keyword argument exc_info with
a true value, e.g.
logger.log_message('info', "We have a %s", "mysterious problem").
"""
logLevel = LEVELS.get(level, logging.NOTSET)
self.log(logLevel, msg, *args, **kwargs)
PYTESTS = log_test.py
EXTRA_DIST = $(PYTESTS)
# later will have configure option to choose this, like: coverage run --branch
PYCOVERAGE = $(PYTHON)
# test using command-line arguments, so use check-local target instead of TESTS
check-local:
for pytest in $(PYTESTS) ; do \
echo Running test: $$pytest ; \
env PYTHONPATH=$(abs_top_srcdir)/src/lib/python::$(abs_top_builddir)/src/lib/python/isc/log \
$(PYCOVERAGE) $(abs_srcdir)/$$pytest ; \
done
#! /bin/sh
# Copyright (C) 2010 Internet Systems Consortium.
#
# Permission to use, copy, modify, and distribute this software for any
# purpose with or without fee is hereby granted, provided that the above
# copyright notice and this permission notice appear in all copies.
#
# THE SOFTWARE IS PROVIDED "AS IS" AND INTERNET SYSTEMS CONSORTIUM
# DISCLAIMS ALL WARRANTIES WITH REGARD TO THIS SOFTWARE INCLUDING ALL
# IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS. IN NO EVENT SHALL
# INTERNET SYSTEMS CONSORTIUM BE LIABLE FOR ANY SPECIAL, DIRECT,
# INDIRECT, OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES WHATSOEVER RESULTING
# FROM LOSS OF USE, DATA OR PROFITS, WHETHER IN AN ACTION OF CONTRACT,
# NEGLIGENCE OR OTHER TORTIOUS ACTION, ARISING OUT OF OR IN CONNECTION
# WITH THE USE OR PERFORMANCE OF THIS SOFTWARE.
PYTHON_EXEC=${PYTHON_EXEC:-@PYTHON@}
export PYTHON_EXEC
TEST_PATH=@abs_top_srcdir@/src/lib/python/isc/log/tests
PYTHONPATH=@abs_top_srcdir@/src/lib/python
export PYTHONPATH
cd ${TEST_PATH}
exec ${PYTHON_EXEC} -O log_test.py $*
from isc.log.log import *
import unittest
import os
import tempfile
class TestRotateFileHandler(unittest.TestCase):
def setUp(self):
self.FILE_LOG1 = tempfile.NamedTemporaryFile(mode='w',
prefix="b10",
delete=True)
self.FILE_LOG2 = tempfile.NamedTemporaryFile(mode='w',
prefix="b10",
delete=True)
self.FILE_LOG3 = tempfile.NamedTemporaryFile(mode='w',