def __init__(self,
account_name=None,
account_key=None,
protocol='https',
table='logs',
batch_size=0,
extra_properties=None,
partition_key_formatter=None,
row_key_formatter=None,
user_id='0'
):
"""
Initialize the handler.
"""
logging.Handler.__init__(self)
self.service = TableService(account_name=account_name,
account_key=account_key,
protocol=protocol)
self.meta = {'hostname': gethostname(), 'process': os.getpid(), 'userid':user_id}
self.table = _formatName(table, self.meta)
self.ready = False
self.rowno = 0
if not partition_key_formatter:
# default format for partition keys
fmt = '%(asctime)s'
datefmt = '%Y%m%d%H%M'
partition_key_formatter = logging.Formatter(fmt, datefmt)
self.partition_key_formatter = partition_key_formatter
if not row_key_formatter:
# default format for row keys
fmt = '%(asctime)s%(msecs)03d-%(hostname)s-%(process)d-%(rowno)02d'
datefmt = '%Y%m%d%H%M%S'
row_key_formatter = logging.Formatter(fmt, datefmt)
self.row_key_formatter = row_key_formatter
# extra properties and formatters for them
self.extra_properties = extra_properties
if extra_properties:
self.extra_property_formatters = {}
self.extra_property_names = {}
for extra in extra_properties:
if _PY3:
f = logging.Formatter(fmt=extra, style=extra[0])
else:
f = logging.Formatter(fmt=extra)
self.extra_property_formatters[extra] = f
self.extra_property_names[extra] = self._getFormatName(extra)
# the storage emulator doesn't support batch operations
if batch_size <= 1 or self.service.use_local_storage:
self.batch = False
else:
self.batch = True
if batch_size > TableStorageHandler.MAX_BATCH_SIZE:
self.batch_size = TableStorageHandler.MAX_BATCH_SIZE
else:
self.batch_size = batch_size
if self.batch:
self.current_partition_key = None
def setUp(self):
self.service = TableService(ACCOUNT_NAME, ACCOUNT_KEY)
# ensure that there's no entity in the table before each test
tables = set()
for cfg in LOGGING['handlers'].values():
if 'table' in cfg:
tables.add(cfg['table'])
for table in self.service.query_tables():
if table.name in tables:
for entity in self.service.query_entities(table.name):
self.service.delete_entity(table.name,
entity.PartitionKey,
entity.RowKey)
def create_table_service(self):
return TableService(self.account_name, self.account_key)
class TableStorageHandler(logging.Handler):
"""
Handler class which writes log messages to a Windows Azure Storage table.
"""
MAX_BATCH_SIZE = 100
def __init__(self,
account_name=None,
account_key=None,
protocol='https',
table='logs',
batch_size=0,
extra_properties=None,
partition_key_formatter=None,
row_key_formatter=None,
):
"""
Initialize the handler.
"""
logging.Handler.__init__(self)
self.service = TableService(account_name=account_name,
account_key=account_key,
protocol=protocol)
self.meta = {'hostname': gethostname(), 'process': os.getpid()}
self.table = _formatName(table, self.meta)
self.table_created = False
self.rowno = 0
if not partition_key_formatter:
# default format for partition keys
fmt = '%(asctime)s'
datefmt = '%Y%m%d%H%M'
partition_key_formatter = logging.Formatter(fmt, datefmt)
self.partition_key_formatter = partition_key_formatter
if not row_key_formatter:
# default format for row keys
fmt = '%(asctime)s%(msecs)03d-%(hostname)s-%(process)d-%(rowno)02d'
datefmt = '%Y%m%d%H%M%S'
row_key_formatter = logging.Formatter(fmt, datefmt)
self.row_key_formatter = row_key_formatter
# extra properties and formatters for them
self.extra_properties = extra_properties
if extra_properties:
self.extra_property_formatters = {}
self.extra_property_names = {}
for extra in extra_properties:
if _PY3:
f = logging.Formatter(fmt=extra, style=extra[0])
else:
f = logging.Formatter(fmt=extra)
self.extra_property_formatters[extra] = f
self.extra_property_names[extra] = self._getFormatName(extra)
# the storage emulator doesn't support batch operations
if batch_size <= 1 or self.service.use_local_storage:
self.batch = False
else:
self.batch = True
if batch_size > TableStorageHandler.MAX_BATCH_SIZE:
self.batch_size = TableStorageHandler.MAX_BATCH_SIZE
else:
self.batch_size = batch_size
if self.batch:
self.current_partition_key = None
def _copyLogRecord(self, record):
copy = logging.makeLogRecord(record.__dict__)
copy.exc_info = None
copy.exc_text = None
if _PY3:
copy.stack_info = None
return copy
def _getFormatName(self, extra):
name = extra
style = extra[0]
if style == '%':
name = extra[2:extra.index(')')]
elif _PY3:
if style == '{':
name = next(string.Formatter().parse(extra))[1]
elif style == '$':
name = extra[1:]
if name.startswith('{'):
name = name[1:-1]
return name
def emit(self, record):
"""
Emit a record.
Format the record and send it to the specified table.
"""
try:
if not self.table_created:
self.service.create_table(self.table)
self.table_created = True
if self.batch:
self.service.begin_batch()
# generate partition key for the entity
record.hostname = self.meta['hostname']
copy = self._copyLogRecord(record)
partition_key = self.partition_key_formatter.format(copy)
# ensure entities in the batch all have the same patition key
if self.batch:
if self.current_partition_key is not None:
if partition_key != self.current_partition_key:
self.flush()
self.service.begin_batch()
self.current_partition_key = partition_key
# add log message and extra properties to the entity
entity = {}
if self.extra_properties:
for extra in self.extra_properties:
formatter = self.extra_property_formatters[extra]
name = self.extra_property_names[extra]
entity[name] = formatter.format(copy)
entity['message'] = self.format(record)
# generate row key for the entity
copy.rowno = self.rowno
row_key = self.row_key_formatter.format(copy)
# add entitiy to the table
self.service.insert_or_replace_entity(self.table,
partition_key,
row_key,
entity)
# commit the ongoing batch if it reaches the high mark
if self.batch:
self.rowno += 1
if self.rowno >= self.batch_size:
self.flush()
self.service.begin_batch()
except (KeyboardInterrupt, SystemExit):
raise
except:
self.handleError(record)
def flush(self):
"""
Ensure all logging output has been flushed.
"""
if self.batch:
self.service.commit_batch()
self.rowno = 0
def setFormatter(self, fmt):
"""
Set the message formatter.
"""
super(TableStorageHandler, self).setFormatter(fmt)
if self.extra_properties:
logging._acquireLock()
try:
for extra in self.extra_property_formatters.values():
extra.converter = fmt.converter
extra.datefmt = fmt.datefmt
if _PY3:
extra.default_time_format = fmt.default_time_format
extra.default_msec_format = fmt.default_msec_format
finally:
logging._releaseLock()
def setPartitionKeyFormatter(self, fmt):
"""
Set the partition key formatter.
"""
self.partition_key_formatter = fmt
def setRowKeyFormatter(self, fmt):
"""
Set the row key formatter.
"""
self.row_key_formatter = fmt
def __init__(self, account_name, account_key, *args, **kwargs):
super(TableServiceAdapter, self).__init__(
TableService(account_name, account_key, *args, **kwargs))
class TableStorageHandlerTest(_TestCase):
def _divide_key(self, key):
divided = []
hostname = gethostname()
if key.find(hostname) >= 0:
preceding, hostname, remaining = key.rpartition(hostname)
preceding = preceding[:-1] if preceding.endswith('-') else preceding
divided.extend(preceding.split('-'))
divided.append(hostname)
remaining = remaining[1:] if remaining.startswith('-') else remaining
divided.extend(remaining.split('-'))
else:
divided.extend(key.split('-'))
return iter(divided)
def _get_formatter_name(self, handler_name, formatter_type):
name = _get_handler_config_value(handler_name, formatter_type)
if name:
if name.startswith('cfg://formatters.'):
name = name.split('.')[1]
return name
def _get_partition_key_formatter_name(self, handler_name):
return self._get_formatter_name(handler_name, 'partition_key_formatter')
def _get_row_key_formatter_name(self, handler_name):
return self._get_formatter_name(handler_name, 'row_key_formatter')
def setUp(self):
self.service = TableService(ACCOUNT_NAME, ACCOUNT_KEY)
# ensure that there's no entity in the table before each test
tables = set()
for cfg in LOGGING['handlers'].values():
if 'table' in cfg:
tables.add(cfg['table'])
for table in self.service.query_tables():
if table.name in tables:
for entity in self.service.query_entities(table.name):
self.service.delete_entity(table.name,
entity.PartitionKey,
entity.RowKey)
def test_logging(self):
# get the logger for the test
logger_name = 'table'
logger = logging.getLogger(logger_name)
handler_name = _get_handler_name(logger_name)
# perform logging
log_text = 'logging test'
logging_started = datetime.now()
logger.info(log_text)
logging_finished = datetime.now()
# confirm that the entity has correct log text
table = _get_handler_config_value(handler_name, 'table')
entities = iter(self.service.query_entities(table))
entity = next(entities)
self.assertEqual(entity.message, 'INFO %s' % log_text)
# confirm that the entity has the default partitiok key
fmt = '%Y%m%d%H%M'
try:
self.assertEqual(entity.PartitionKey, logging_started.strftime(fmt))
except AssertionError:
if logging_started == logging_finished:
raise
self.assertEqual(entity.PartitionKey, logging_finished.strftime(fmt))
# confirm that the entity has the default row key
divided = self._divide_key(entity.RowKey)
timestamp = next(divided)
fmt = '%Y%m%d%H%M%S'
self.assertGreaterEqual(timestamp[:-3], logging_started.strftime(fmt))
self.assertLessEqual(timestamp[:-3], logging_finished.strftime(fmt))
self.assertRegex(timestamp[-3:], '^[0-9]{3}$')
self.assertEqual(next(divided), gethostname())
self.assertEqual(int(next(divided)), os.getpid())
self.assertEqual(next(divided), '00')
with self.assertRaises(StopIteration):
next(divided)
# confirm that there's no more entity in the table
with self.assertRaises(StopIteration):
next(entities)
@unittest.skipIf(_EMULATED, "Azure Storage Emulator doesn't support batch operation.")
def test_batch(self):
# get the logger for the test
logger_name = 'batch'
logger = logging.getLogger(logger_name)
handler_name = _get_handler_name(logger_name)
# perform logging and execute the first batch
batch_size = _get_handler_config_value(handler_name, 'batch_size')
log_text = 'batch logging test'
for i in range(batch_size + int(batch_size/2)):
logger.info('%s#%02d' % (log_text, i))
# confirm that only batch_size entities are committed at this point
table = _get_handler_config_value(handler_name, 'table')
entities = list(iter(self.service.query_entities(table)))
self.assertEqual(len(entities), batch_size)
rowno_found = set()
seq_found = set()
for entity in entities:
# partition key
self.assertEqual(entity.PartitionKey, 'batch-%s' % gethostname())
# row key
rowno = entity.RowKey.split('-')[-1]
self.assertLess(int(rowno), batch_size)
self.assertNotIn(rowno, rowno_found)
rowno_found.add(rowno)
# message
message, seq = entity.message.split('#')
self.assertEqual(message, 'INFO %s' % log_text)
self.assertLess(int(seq), batch_size)
self.assertNotIn(seq, seq_found)
seq_found.add(seq)
# remove currently created entities before the next batch
for entity in entities:
self.service.delete_entity(table,
entity.PartitionKey,
entity.RowKey)
# perform logging again and execute the next batch
for j in range(i+1, int(batch_size/2)+i+1):
logger.info('%s#%02d' % (log_text, j))
# confirm that the remaining entities are committed in the next batch
entities = list(iter(self.service.query_entities(table)))
self.assertEqual(len(entities), batch_size)
rowno_found.clear()
for entity in entities:
# partition key
self.assertEqual(entity.PartitionKey, 'batch-%s' % gethostname())
# row key
rowno = entity.RowKey.split('-')[-1]
self.assertLess(int(rowno), batch_size)
self.assertNotIn(rowno, rowno_found)
rowno_found.add(rowno)
# message
message, seq = entity.message.split('#')
self.assertEqual(message, 'INFO %s' % log_text)
self.assertGreaterEqual(int(seq), batch_size)
self.assertLess(int(seq), batch_size*2)
self.assertNotIn(seq, seq_found)
seq_found.add(seq)
def test_extra_properties(self):
# get the logger for the test
logger_name = 'extra_properties'
logger = logging.getLogger(logger_name)
handler_name = _get_handler_name(logger_name)
# perform logging
log_text = 'extra properties test'
logger.info(log_text)
# confirm that the entity has correct log text
table = _get_handler_config_value(handler_name, 'table')
entities = iter(self.service.query_entities(table))
entity = next(entities)
self.assertEqual(entity.message, 'INFO %s' % log_text)
# confirm that the extra properties have correct values
entity = next(iter(self.service.query_entities(table)))
self.assertEqual(entity.hostname, gethostname())
self.assertEqual(entity.levelname, 'INFO')
self.assertEqual(int(entity.levelno), logging.INFO)
self.assertEqual(entity.module, os.path.basename(__file__).rpartition('.')[0])
self.assertEqual(entity.name, logger_name)
self.assertEqual(int(entity.process), os.getpid())
self.assertEqual(int(entity.thread), current_thread().ident)
# confirm that there's no more entity in the table
with self.assertRaises(StopIteration):
next(entities)
def test_custom_key_formatters(self):
# get the logger for the test
logger_name = 'custom_keys'
logger = logging.getLogger(logger_name)
handler_name = _get_handler_name(logger_name)
# perform logging
log_text = 'custom key formatters test'
logging_started = datetime.now()
logger.info(log_text)
logging_finished = datetime.now()
# confirm that the entity correct log text
table = _get_handler_config_value(handler_name, 'table')
entities = iter(self.service.query_entities(table))
entity = next(entities)
self.assertEqual(entity.message, 'INFO %s' % log_text)
# confirm that the entity has a custom partitiok key
divided = self._divide_key(entity.PartitionKey)
self.assertEqual(next(divided), 'mycustompartitionkey')
self.assertEqual(next(divided), gethostname())
formatter_name = self._get_partition_key_formatter_name(handler_name)
fmt = _get_formatter_config_value(formatter_name, 'datefmt')
asctime = next(divided)
try:
self.assertEqual(asctime, logging_started.strftime(fmt))
except AssertionError:
if logging_started == logging_finished:
raise
self.assertEqual(asctime, logging_finished.strftime(fmt))
with self.assertRaises(StopIteration):
next(divided)
# confirm that the entity has a custom row key
divided = self._divide_key(entity.RowKey)
self.assertEqual(next(divided), 'mycustomrowkey')
self.assertEqual(next(divided), gethostname())
formatter_name = self._get_row_key_formatter_name(handler_name)
fmt = _get_formatter_config_value(formatter_name, 'datefmt')
asctime = next(divided)
try:
self.assertEqual(asctime, logging_started.strftime(fmt))
except AssertionError:
if logging_started == logging_finished:
raise
self.assertEqual(asctime, logging_finished.strftime(fmt))
with self.assertRaises(StopIteration):
next(divided)
# confirm that there's no more entity in the table
with self.assertRaises(StopIteration):
next(entities)