michael@0: import argparse michael@0: import os michael@0: import time michael@0: import unittest michael@0: import StringIO michael@0: import json michael@0: michael@0: from mozlog.structured import ( michael@0: commandline, michael@0: reader, michael@0: structuredlog, michael@0: ) michael@0: michael@0: michael@0: class TestHandler(object): michael@0: def __init__(self): michael@0: self.last_item = None michael@0: michael@0: def __call__(self, data): michael@0: self.last_item = data michael@0: michael@0: michael@0: class BaseStructuredTest(unittest.TestCase): michael@0: def setUp(self): michael@0: self.logger = structuredlog.StructuredLogger("test") michael@0: self.handler = TestHandler() michael@0: self.logger.add_handler(self.handler) michael@0: michael@0: @property michael@0: def last_item(self): michael@0: return self.handler.last_item michael@0: michael@0: def assert_log_equals(self, expected, actual=None): michael@0: if actual is None: michael@0: actual = self.last_item michael@0: michael@0: all_expected = {"pid": os.getpid(), michael@0: "thread": "MainThread", michael@0: "source": "test"} michael@0: specials = set(["time"]) michael@0: michael@0: all_expected.update(expected) michael@0: for key, value in all_expected.iteritems(): michael@0: self.assertEqual(actual[key], value) michael@0: michael@0: self.assertEquals(set(all_expected.keys()) | specials, set(actual.keys())) michael@0: michael@0: michael@0: class TestStructuredLog(BaseStructuredTest): michael@0: def test_suite_start(self): michael@0: self.logger.suite_start(["test"]) michael@0: self.assert_log_equals({"action": "suite_start", michael@0: "tests":["test"]}) michael@0: michael@0: def test_suite_end(self): michael@0: self.logger.suite_end() michael@0: self.assert_log_equals({"action": "suite_end"}) michael@0: michael@0: def test_start(self): michael@0: self.logger.test_start("test1") michael@0: self.assert_log_equals({"action": "test_start", michael@0: "test":"test1"}) michael@0: michael@0: self.logger.test_start(("test1", "==", "test1-ref")) michael@0: self.assert_log_equals({"action": "test_start", michael@0: "test":("test1", "==", "test1-ref")}) michael@0: michael@0: def test_status(self): michael@0: self.logger.test_status("test1", "subtest name", "fail", expected="FAIL", message="Test message") michael@0: self.assert_log_equals({"action": "test_status", michael@0: "subtest": "subtest name", michael@0: "status": "FAIL", michael@0: "message": "Test message", michael@0: "test":"test1"}) michael@0: michael@0: def test_status_1(self): michael@0: self.logger.test_status("test1", "subtest name", "fail") michael@0: self.assert_log_equals({"action": "test_status", michael@0: "subtest": "subtest name", michael@0: "status": "FAIL", michael@0: "expected": "PASS", michael@0: "test":"test1"}) michael@0: michael@0: def test_status_2(self): michael@0: self.assertRaises(ValueError, self.logger.test_status, "test1", "subtest name", "XXXUNKNOWNXXX") michael@0: michael@0: def test_end(self): michael@0: self.logger.test_end("test1", "fail", message="Test message") michael@0: self.assert_log_equals({"action": "test_end", michael@0: "status": "FAIL", michael@0: "expected": "OK", michael@0: "message": "Test message", michael@0: "test":"test1"}) michael@0: michael@0: def test_end_1(self): michael@0: self.logger.test_end("test1", "PASS", expected="PASS", extra={"data":123}) michael@0: self.assert_log_equals({"action": "test_end", michael@0: "status": "PASS", michael@0: "extra": {"data": 123}, michael@0: "test":"test1"}) michael@0: michael@0: def test_end_2(self): michael@0: self.assertRaises(ValueError, self.logger.test_end, "test1", "XXXUNKNOWNXXX") michael@0: michael@0: def test_process(self): michael@0: self.logger.process_output(1234, "test output") michael@0: self.assert_log_equals({"action": "process_output", michael@0: "process": 1234, michael@0: "data": "test output"}) michael@0: michael@0: def test_log(self): michael@0: for level in ["critical", "error", "warning", "info", "debug"]: michael@0: getattr(self.logger, level)("message") michael@0: self.assert_log_equals({"action": "log", michael@0: "level": level.upper(), michael@0: "message": "message"}) michael@0: michael@0: def test_logging_adapter(self): michael@0: import logging michael@0: logging.basicConfig(level="DEBUG") michael@0: old_level = logging.root.getEffectiveLevel() michael@0: logging.root.setLevel("DEBUG") michael@0: michael@0: std_logger = logging.getLogger("test") michael@0: std_logger.setLevel("DEBUG") michael@0: michael@0: logger = structuredlog.std_logging_adapter(std_logger) michael@0: michael@0: try: michael@0: for level in ["critical", "error", "warning", "info", "debug"]: michael@0: getattr(logger, level)("message") michael@0: self.assert_log_equals({"action": "log", michael@0: "level": level.upper(), michael@0: "message": "message"}) michael@0: finally: michael@0: logging.root.setLevel(old_level) michael@0: michael@0: def test_add_remove_handlers(self): michael@0: handler = TestHandler() michael@0: self.logger.add_handler(handler) michael@0: self.logger.info("test1") michael@0: michael@0: self.assert_log_equals({"action": "log", michael@0: "level": "INFO", michael@0: "message": "test1"}) michael@0: michael@0: self.assert_log_equals({"action": "log", michael@0: "level": "INFO", michael@0: "message": "test1"}, actual=handler.last_item) michael@0: michael@0: self.logger.remove_handler(handler) michael@0: self.logger.info("test2") michael@0: michael@0: self.assert_log_equals({"action": "log", michael@0: "level": "INFO", michael@0: "message": "test2"}) michael@0: michael@0: self.assert_log_equals({"action": "log", michael@0: "level": "INFO", michael@0: "message": "test1"}, actual=handler.last_item) michael@0: michael@0: def test_wrapper(self): michael@0: file_like = structuredlog.StructuredLogFileLike(self.logger) michael@0: michael@0: file_like.write("line 1") michael@0: michael@0: self.assert_log_equals({"action": "log", michael@0: "level": "INFO", michael@0: "message": "line 1"}) michael@0: michael@0: file_like.write("line 2\n") michael@0: michael@0: self.assert_log_equals({"action": "log", michael@0: "level": "INFO", michael@0: "message": "line 2"}) michael@0: michael@0: file_like.write("line 3\r") michael@0: michael@0: self.assert_log_equals({"action": "log", michael@0: "level": "INFO", michael@0: "message": "line 3"}) michael@0: michael@0: file_like.write("line 4\r\n") michael@0: michael@0: self.assert_log_equals({"action": "log", michael@0: "level": "INFO", michael@0: "message": "line 4"}) michael@0: michael@0: class TestCommandline(unittest.TestCase): michael@0: def test_setup_logging(self): michael@0: parser = argparse.ArgumentParser() michael@0: commandline.add_logging_group(parser) michael@0: args = parser.parse_args(["--log-raw=/tmp/foo"]) michael@0: logger = commandline.setup_logging("test", args, {}) michael@0: self.assertEqual(len(logger.handlers), 1) michael@0: michael@0: class TestReader(unittest.TestCase): michael@0: def to_file_like(self, obj): michael@0: data_str = "\n".join(json.dumps(item) for item in obj) michael@0: return StringIO.StringIO(data_str) michael@0: michael@0: def test_read(self): michael@0: data = [{"action": "action_0", "data": "data_0"}, michael@0: {"action": "action_1", "data": "data_1"}] michael@0: michael@0: f = self.to_file_like(data) michael@0: self.assertEquals(data, list(reader.read(f))) michael@0: michael@0: def test_imap_log(self): michael@0: data = [{"action": "action_0", "data": "data_0"}, michael@0: {"action": "action_1", "data": "data_1"}] michael@0: michael@0: f = self.to_file_like(data) michael@0: michael@0: def f_action_0(item): michael@0: return ("action_0", item["data"]) michael@0: michael@0: def f_action_1(item): michael@0: return ("action_1", item["data"]) michael@0: michael@0: res_iter = reader.imap_log(reader.read(f), michael@0: {"action_0": f_action_0, michael@0: "action_1": f_action_1}) michael@0: self.assertEquals([("action_0", "data_0"), ("action_1", "data_1")], michael@0: list(res_iter)) michael@0: michael@0: def test_each_log(self): michael@0: data = [{"action": "action_0", "data": "data_0"}, michael@0: {"action": "action_1", "data": "data_1"}] michael@0: michael@0: f = self.to_file_like(data) michael@0: michael@0: count = {"action_0":0, michael@0: "action_1":0} michael@0: michael@0: def f_action_0(item): michael@0: count[item["action"]] += 1 michael@0: michael@0: def f_action_1(item): michael@0: count[item["action"]] += 2 michael@0: michael@0: reader.each_log(reader.read(f), michael@0: {"action_0": f_action_0, michael@0: "action_1": f_action_1}) michael@0: michael@0: self.assertEquals({"action_0":1, "action_1":2}, count) michael@0: michael@0: def test_handler(self): michael@0: data = [{"action": "action_0", "data": "data_0"}, michael@0: {"action": "action_1", "data": "data_1"}] michael@0: michael@0: f = self.to_file_like(data) michael@0: michael@0: test = self michael@0: class ReaderTestHandler(reader.LogHandler): michael@0: def __init__(self): michael@0: self.action_0_count = 0 michael@0: self.action_1_count = 0 michael@0: michael@0: def action_0(self, item): michael@0: test.assertEquals(item["action"], "action_0") michael@0: self.action_0_count += 1 michael@0: michael@0: def action_1(self, item): michael@0: test.assertEquals(item["action"], "action_1") michael@0: self.action_1_count += 1 michael@0: michael@0: handler = ReaderTestHandler() michael@0: reader.handle_log(reader.read(f), handler) michael@0: michael@0: self.assertEquals(handler.action_0_count, 1) michael@0: self.assertEquals(handler.action_1_count, 1) michael@0: michael@0: if __name__ == "__main__": michael@0: unittest.main()