1.1 --- /dev/null Thu Jan 01 00:00:00 1970 +0000
1.2 +++ b/testing/mozbase/mozlog/tests/test_structured.py Wed Dec 31 06:09:35 2014 +0100
1.3 @@ -0,0 +1,275 @@
1.4 +import argparse
1.5 +import os
1.6 +import time
1.7 +import unittest
1.8 +import StringIO
1.9 +import json
1.10 +
1.11 +from mozlog.structured import (
1.12 + commandline,
1.13 + reader,
1.14 + structuredlog,
1.15 +)
1.16 +
1.17 +
1.18 +class TestHandler(object):
1.19 + def __init__(self):
1.20 + self.last_item = None
1.21 +
1.22 + def __call__(self, data):
1.23 + self.last_item = data
1.24 +
1.25 +
1.26 +class BaseStructuredTest(unittest.TestCase):
1.27 + def setUp(self):
1.28 + self.logger = structuredlog.StructuredLogger("test")
1.29 + self.handler = TestHandler()
1.30 + self.logger.add_handler(self.handler)
1.31 +
1.32 + @property
1.33 + def last_item(self):
1.34 + return self.handler.last_item
1.35 +
1.36 + def assert_log_equals(self, expected, actual=None):
1.37 + if actual is None:
1.38 + actual = self.last_item
1.39 +
1.40 + all_expected = {"pid": os.getpid(),
1.41 + "thread": "MainThread",
1.42 + "source": "test"}
1.43 + specials = set(["time"])
1.44 +
1.45 + all_expected.update(expected)
1.46 + for key, value in all_expected.iteritems():
1.47 + self.assertEqual(actual[key], value)
1.48 +
1.49 + self.assertEquals(set(all_expected.keys()) | specials, set(actual.keys()))
1.50 +
1.51 +
1.52 +class TestStructuredLog(BaseStructuredTest):
1.53 + def test_suite_start(self):
1.54 + self.logger.suite_start(["test"])
1.55 + self.assert_log_equals({"action": "suite_start",
1.56 + "tests":["test"]})
1.57 +
1.58 + def test_suite_end(self):
1.59 + self.logger.suite_end()
1.60 + self.assert_log_equals({"action": "suite_end"})
1.61 +
1.62 + def test_start(self):
1.63 + self.logger.test_start("test1")
1.64 + self.assert_log_equals({"action": "test_start",
1.65 + "test":"test1"})
1.66 +
1.67 + self.logger.test_start(("test1", "==", "test1-ref"))
1.68 + self.assert_log_equals({"action": "test_start",
1.69 + "test":("test1", "==", "test1-ref")})
1.70 +
1.71 + def test_status(self):
1.72 + self.logger.test_status("test1", "subtest name", "fail", expected="FAIL", message="Test message")
1.73 + self.assert_log_equals({"action": "test_status",
1.74 + "subtest": "subtest name",
1.75 + "status": "FAIL",
1.76 + "message": "Test message",
1.77 + "test":"test1"})
1.78 +
1.79 + def test_status_1(self):
1.80 + self.logger.test_status("test1", "subtest name", "fail")
1.81 + self.assert_log_equals({"action": "test_status",
1.82 + "subtest": "subtest name",
1.83 + "status": "FAIL",
1.84 + "expected": "PASS",
1.85 + "test":"test1"})
1.86 +
1.87 + def test_status_2(self):
1.88 + self.assertRaises(ValueError, self.logger.test_status, "test1", "subtest name", "XXXUNKNOWNXXX")
1.89 +
1.90 + def test_end(self):
1.91 + self.logger.test_end("test1", "fail", message="Test message")
1.92 + self.assert_log_equals({"action": "test_end",
1.93 + "status": "FAIL",
1.94 + "expected": "OK",
1.95 + "message": "Test message",
1.96 + "test":"test1"})
1.97 +
1.98 + def test_end_1(self):
1.99 + self.logger.test_end("test1", "PASS", expected="PASS", extra={"data":123})
1.100 + self.assert_log_equals({"action": "test_end",
1.101 + "status": "PASS",
1.102 + "extra": {"data": 123},
1.103 + "test":"test1"})
1.104 +
1.105 + def test_end_2(self):
1.106 + self.assertRaises(ValueError, self.logger.test_end, "test1", "XXXUNKNOWNXXX")
1.107 +
1.108 + def test_process(self):
1.109 + self.logger.process_output(1234, "test output")
1.110 + self.assert_log_equals({"action": "process_output",
1.111 + "process": 1234,
1.112 + "data": "test output"})
1.113 +
1.114 + def test_log(self):
1.115 + for level in ["critical", "error", "warning", "info", "debug"]:
1.116 + getattr(self.logger, level)("message")
1.117 + self.assert_log_equals({"action": "log",
1.118 + "level": level.upper(),
1.119 + "message": "message"})
1.120 +
1.121 + def test_logging_adapter(self):
1.122 + import logging
1.123 + logging.basicConfig(level="DEBUG")
1.124 + old_level = logging.root.getEffectiveLevel()
1.125 + logging.root.setLevel("DEBUG")
1.126 +
1.127 + std_logger = logging.getLogger("test")
1.128 + std_logger.setLevel("DEBUG")
1.129 +
1.130 + logger = structuredlog.std_logging_adapter(std_logger)
1.131 +
1.132 + try:
1.133 + for level in ["critical", "error", "warning", "info", "debug"]:
1.134 + getattr(logger, level)("message")
1.135 + self.assert_log_equals({"action": "log",
1.136 + "level": level.upper(),
1.137 + "message": "message"})
1.138 + finally:
1.139 + logging.root.setLevel(old_level)
1.140 +
1.141 + def test_add_remove_handlers(self):
1.142 + handler = TestHandler()
1.143 + self.logger.add_handler(handler)
1.144 + self.logger.info("test1")
1.145 +
1.146 + self.assert_log_equals({"action": "log",
1.147 + "level": "INFO",
1.148 + "message": "test1"})
1.149 +
1.150 + self.assert_log_equals({"action": "log",
1.151 + "level": "INFO",
1.152 + "message": "test1"}, actual=handler.last_item)
1.153 +
1.154 + self.logger.remove_handler(handler)
1.155 + self.logger.info("test2")
1.156 +
1.157 + self.assert_log_equals({"action": "log",
1.158 + "level": "INFO",
1.159 + "message": "test2"})
1.160 +
1.161 + self.assert_log_equals({"action": "log",
1.162 + "level": "INFO",
1.163 + "message": "test1"}, actual=handler.last_item)
1.164 +
1.165 + def test_wrapper(self):
1.166 + file_like = structuredlog.StructuredLogFileLike(self.logger)
1.167 +
1.168 + file_like.write("line 1")
1.169 +
1.170 + self.assert_log_equals({"action": "log",
1.171 + "level": "INFO",
1.172 + "message": "line 1"})
1.173 +
1.174 + file_like.write("line 2\n")
1.175 +
1.176 + self.assert_log_equals({"action": "log",
1.177 + "level": "INFO",
1.178 + "message": "line 2"})
1.179 +
1.180 + file_like.write("line 3\r")
1.181 +
1.182 + self.assert_log_equals({"action": "log",
1.183 + "level": "INFO",
1.184 + "message": "line 3"})
1.185 +
1.186 + file_like.write("line 4\r\n")
1.187 +
1.188 + self.assert_log_equals({"action": "log",
1.189 + "level": "INFO",
1.190 + "message": "line 4"})
1.191 +
1.192 +class TestCommandline(unittest.TestCase):
1.193 + def test_setup_logging(self):
1.194 + parser = argparse.ArgumentParser()
1.195 + commandline.add_logging_group(parser)
1.196 + args = parser.parse_args(["--log-raw=/tmp/foo"])
1.197 + logger = commandline.setup_logging("test", args, {})
1.198 + self.assertEqual(len(logger.handlers), 1)
1.199 +
1.200 +class TestReader(unittest.TestCase):
1.201 + def to_file_like(self, obj):
1.202 + data_str = "\n".join(json.dumps(item) for item in obj)
1.203 + return StringIO.StringIO(data_str)
1.204 +
1.205 + def test_read(self):
1.206 + data = [{"action": "action_0", "data": "data_0"},
1.207 + {"action": "action_1", "data": "data_1"}]
1.208 +
1.209 + f = self.to_file_like(data)
1.210 + self.assertEquals(data, list(reader.read(f)))
1.211 +
1.212 + def test_imap_log(self):
1.213 + data = [{"action": "action_0", "data": "data_0"},
1.214 + {"action": "action_1", "data": "data_1"}]
1.215 +
1.216 + f = self.to_file_like(data)
1.217 +
1.218 + def f_action_0(item):
1.219 + return ("action_0", item["data"])
1.220 +
1.221 + def f_action_1(item):
1.222 + return ("action_1", item["data"])
1.223 +
1.224 + res_iter = reader.imap_log(reader.read(f),
1.225 + {"action_0": f_action_0,
1.226 + "action_1": f_action_1})
1.227 + self.assertEquals([("action_0", "data_0"), ("action_1", "data_1")],
1.228 + list(res_iter))
1.229 +
1.230 + def test_each_log(self):
1.231 + data = [{"action": "action_0", "data": "data_0"},
1.232 + {"action": "action_1", "data": "data_1"}]
1.233 +
1.234 + f = self.to_file_like(data)
1.235 +
1.236 + count = {"action_0":0,
1.237 + "action_1":0}
1.238 +
1.239 + def f_action_0(item):
1.240 + count[item["action"]] += 1
1.241 +
1.242 + def f_action_1(item):
1.243 + count[item["action"]] += 2
1.244 +
1.245 + reader.each_log(reader.read(f),
1.246 + {"action_0": f_action_0,
1.247 + "action_1": f_action_1})
1.248 +
1.249 + self.assertEquals({"action_0":1, "action_1":2}, count)
1.250 +
1.251 + def test_handler(self):
1.252 + data = [{"action": "action_0", "data": "data_0"},
1.253 + {"action": "action_1", "data": "data_1"}]
1.254 +
1.255 + f = self.to_file_like(data)
1.256 +
1.257 + test = self
1.258 + class ReaderTestHandler(reader.LogHandler):
1.259 + def __init__(self):
1.260 + self.action_0_count = 0
1.261 + self.action_1_count = 0
1.262 +
1.263 + def action_0(self, item):
1.264 + test.assertEquals(item["action"], "action_0")
1.265 + self.action_0_count += 1
1.266 +
1.267 + def action_1(self, item):
1.268 + test.assertEquals(item["action"], "action_1")
1.269 + self.action_1_count += 1
1.270 +
1.271 + handler = ReaderTestHandler()
1.272 + reader.handle_log(reader.read(f), handler)
1.273 +
1.274 + self.assertEquals(handler.action_0_count, 1)
1.275 + self.assertEquals(handler.action_1_count, 1)
1.276 +
1.277 +if __name__ == "__main__":
1.278 + unittest.main()
