From cedfbeaa65105735db7f8b500067b8edb00648c7 Mon Sep 17 00:00:00 2001 From: Matt Bennett Date: Thu, 17 Jan 2019 14:27:32 +0000 Subject: [PATCH 01/20] add thread-safe tee utility --- nameko_grpc/utils.py | 54 ++++++++++++++++ test/test_utils.py | 146 +++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 200 insertions(+) create mode 100644 nameko_grpc/utils.py create mode 100644 test/test_utils.py diff --git a/nameko_grpc/utils.py b/nameko_grpc/utils.py new file mode 100644 index 0000000..bde575b --- /dev/null +++ b/nameko_grpc/utils.py @@ -0,0 +1,54 @@ +# -*- coding: utf-8 -*- +import itertools +from threading import Lock + + +class ThreadSafeTee: + """ Thread-safe wrapper for `itertools.tee` objects. + + Copied from https://stackoverflow.com/questions/6703594/itertools-tee-thread-safe + """ + + def __init__(self, tee, lock): + self.tee = tee + self.lock = lock + + def __iter__(self): + return self + + def __next__(self): + with self.lock: + return next(self.tee) + + def __copy__(self): + return ThreadSafeTee(self.tee.__copy__(), self.lock) + + +def safetee(iterable, n): + """ Replacement for `itertools.tee` that returns `ThreadSafeTee` objects. + """ + lock = Lock() + return (ThreadSafeTee(tee, lock) for tee in itertools.tee(iterable, n)) + + +class Teeable: + """ Wrapper for `iterable`s that allows them to later be `tee`d + (as in `itertools.tee`) *and* used in a thread-safe manner. + + This is useful for wrapping generators and other iterables that cannot be copied, + such as streaming requests and responses. It is required by extensions which + inspect requests and responses, such as the Nameko Tracer. + """ + + def __init__(self, iterable): + self.iterable = iter(iterable) + + def __iter__(self): + return self + + def __next__(self): + return next(self.iterable) + + def tee(self): + self.iterable, safe_tee = safetee(self.iterable, 2) + return safe_tee diff --git a/test/test_utils.py b/test/test_utils.py new file mode 100644 index 0000000..9de1f6f --- /dev/null +++ b/test/test_utils.py @@ -0,0 +1,146 @@ +# -*- coding: utf-8 -*- +import random +import time +from collections import defaultdict + +import eventlet +import pytest + +from nameko_grpc.utils import Teeable + + +class TestTeeable: + @pytest.fixture + def tracker(self): + return [] + + @pytest.fixture + def make_generator(self, tracker): + def gen(): + for i in range(10): + tracker.append(i) + yield i + + return gen + + def test_not_iterable(self): + with pytest.raises(TypeError): + Teeable(1) + + def test_tees_are_independent(self, make_generator): + + gen = Teeable(make_generator()) + tee = gen.tee() + + assert next(gen) == 0 + assert next(gen) == 1 + assert next(tee) == 0 + assert next(gen) == 2 + assert next(tee) == 1 + assert next(tee) == 2 + + def test_generator_only_advances_once(self, make_generator, tracker): + gen = Teeable(make_generator()) + tee = gen.tee() + + assert next(gen) == 0 + assert next(gen) == 1 + assert next(tee) == 0 + assert next(tee) == 1 + assert next(gen) == 2 + assert next(tee) == 2 + + assert tracker == [0, 1, 2] + + def test_wrap_after_start(self, make_generator): + generator = make_generator() + + assert next(generator) == 0 + assert next(generator) == 1 + + gen = Teeable(generator) + tee = gen.tee() + + assert next(gen) == 2 + assert next(tee) == 2 + assert next(gen) == 3 + assert next(tee) == 3 + + def test_tee_after_start(self, make_generator): + generator = make_generator() + gen = Teeable(generator) + + assert next(generator) == 0 + assert next(generator) == 1 + + tee = gen.tee() + + assert next(gen) == 2 + assert next(tee) == 2 + assert next(gen) == 3 + assert next(tee) == 3 + + def test_reentrant(self, make_generator, tracker): + + gen = Teeable(make_generator()) + tee1 = gen.tee() + tee2 = gen.tee() + + assert next(gen) == 0 + assert next(gen) == 1 + assert next(tee1) == 0 + assert next(tee1) == 1 + assert next(tee2) == 0 + assert next(tee2) == 1 + + def test_thread_safe(self, make_generator, tracker): + + gen = Teeable(make_generator()) + tee = gen.tee() + + consume_trackers = defaultdict(list) + + def consume(iterable, ident=None): + for i in iterable: + time.sleep(random.random() / 10) + consume_trackers[ident].append(i) + + gt1 = eventlet.spawn(consume, gen, ident="gen") + gt2 = eventlet.spawn(consume, tee, ident="tee") + + gt1.wait() + gt2.wait() + + assert consume_trackers["gen"] == list(range(10)) + assert consume_trackers["tee"] == list(range(10)) + assert tracker == list(range(10)) + + def test_thread_safe_and_reentrant(self, make_generator, tracker): + + gen = Teeable(make_generator()) + tee1 = gen.tee() + tee2 = gen.tee() + tee3 = gen.tee() + + consume_trackers = defaultdict(list) + + def consume(iterable, ident=None): + for i in iterable: + time.sleep(random.random() / 10) + consume_trackers[ident].append(i) + + gt1 = eventlet.spawn(consume, gen, ident="gen") + gt2 = eventlet.spawn(consume, tee1, ident="tee1") + gt3 = eventlet.spawn(consume, tee2, ident="tee2") + gt4 = eventlet.spawn(consume, tee3, ident="tee3") + + gt1.wait() + gt2.wait() + gt3.wait() + gt4.wait() + + assert consume_trackers["gen"] == list(range(10)) + assert consume_trackers["tee1"] == list(range(10)) + assert consume_trackers["tee2"] == list(range(10)) + assert consume_trackers["tee3"] == list(range(10)) + assert tracker == list(range(10)) From 624eef2f591f84d8c1c4dbfbe7d299bdabab0e5e Mon Sep 17 00:00:00 2001 From: Matt Bennett Date: Thu, 17 Jan 2019 14:44:06 +0000 Subject: [PATCH 02/20] wrap streaming requests and responses in Teeable response stream populate must happen in a thread, or the stream is consumed in Entrypoint.handle_result and will not be available to any extensions later (i.e. in worker_result) --- nameko_grpc/entrypoint.py | 33 +++++++++++++++++++++++---------- 1 file changed, 23 insertions(+), 10 deletions(-) diff --git a/nameko_grpc/entrypoint.py b/nameko_grpc/entrypoint.py index cebec63..16fded9 100644 --- a/nameko_grpc/entrypoint.py +++ b/nameko_grpc/entrypoint.py @@ -17,6 +17,7 @@ from nameko_grpc.inspection import Inspector from nameko_grpc.streams import ReceiveStream, SendStream from nameko_grpc.timeout import unbucket_timeout +from nameko_grpc.utils import Teeable log = getLogger(__name__) @@ -234,6 +235,8 @@ def handle_request(self, request_stream, response_stream): if self.cardinality in (Cardinality.UNARY_STREAM, Cardinality.UNARY_UNARY): request = next(request) + else: + request = Teeable(request) context = GrpcContext(request_stream, response_stream) @@ -261,18 +264,28 @@ def handle_request(self, request_stream, response_stream): def handle_result(self, response_stream, worker_ctx, result, exc_info): if self.cardinality in (Cardinality.STREAM_UNARY, Cardinality.UNARY_UNARY): - result = (result,) + response = (result,) + else: + result = Teeable(result) + response = result if exc_info is None: - try: - response_stream.populate(result) - except Exception as exception: - error = GrpcError( - status=StatusCode.UNKNOWN, - details="Exception iterating responses: {}".format(exception), - debug_error_string="", - ) - response_stream.close(error) + + def send_response(): + try: + response_stream.populate(response) + except Exception as exception: + error = GrpcError( + status=StatusCode.UNKNOWN, + details="Exception iterating responses: {}".format(exception), + debug_error_string="", + ) + response_stream.close(error) + + self.container.spawn_managed_thread( + send_response, identifier="send_response" + ) + else: error = GrpcError( status=StatusCode.UNKNOWN, From 1d02840783aa1ba0553a9b1d40309dcd2fe8c773 Mon Sep 17 00:00:00 2001 From: Matt Bennett Date: Fri, 18 Jan 2019 10:23:03 +0000 Subject: [PATCH 03/20] need to be able to throw exceptions from every tee --- nameko_grpc/utils.py | 38 +++++++++++++++++++++++++++++++++++--- test/test_utils.py | 22 ++++++++++++++++++++++ 2 files changed, 57 insertions(+), 3 deletions(-) diff --git a/nameko_grpc/utils.py b/nameko_grpc/utils.py index bde575b..5c02dfd 100644 --- a/nameko_grpc/utils.py +++ b/nameko_grpc/utils.py @@ -1,10 +1,42 @@ # -*- coding: utf-8 -*- -import itertools +import collections from threading import Lock +def raisetee(iterable, n=2): + """ Alternative to `itertools.tee` that will raise from all iterators if the + source iterable raises. + + Modified from the "roughly equivalent" example in the documentation at + https://docs.python.org/3/library/itertools.html#itertools.tee + """ + source = iter(iterable) + deques = [collections.deque() for i in range(n)] + + def gen(mydeque): + while True: + if not mydeque: + try: + val = next(source) + except StopIteration: + return + except Exception as exc: + val = exc + for d in deques: + d.append(val) + yield mydeque.popleft() + + def read(generator): + for item in generator: + if isinstance(item, Exception): + raise item + yield item + + return tuple(read(gen(d)) for d in deques) + + class ThreadSafeTee: - """ Thread-safe wrapper for `itertools.tee` objects. + """ Thread-safe wrapper for `itertools.tee` (or `raisetee`) objects. Copied from https://stackoverflow.com/questions/6703594/itertools-tee-thread-safe """ @@ -28,7 +60,7 @@ def safetee(iterable, n): """ Replacement for `itertools.tee` that returns `ThreadSafeTee` objects. """ lock = Lock() - return (ThreadSafeTee(tee, lock) for tee in itertools.tee(iterable, n)) + return (ThreadSafeTee(tee, lock) for tee in raisetee(iterable, n)) class Teeable: diff --git a/test/test_utils.py b/test/test_utils.py index 9de1f6f..b12d408 100644 --- a/test/test_utils.py +++ b/test/test_utils.py @@ -144,3 +144,25 @@ def consume(iterable, ident=None): assert consume_trackers["tee2"] == list(range(10)) assert consume_trackers["tee3"] == list(range(10)) assert tracker == list(range(10)) + + def test_generator_throws(self, tracker): + class Boom(Exception): + pass + + def make_generator(): + for i in range(10): + tracker.append(i) + yield i + raise Boom("boom") + + with pytest.raises(Boom): + list(make_generator()) + + gen = Teeable(make_generator()) + tee = gen.tee() + + with pytest.raises(Boom): + list(gen) + + with pytest.raises(Boom): + list(tee) From df80527c087f4bf7bef02e14f95594ac50e1b612 Mon Sep 17 00:00:00 2001 From: Matt Bennett Date: Sun, 20 Jan 2019 14:25:31 +0000 Subject: [PATCH 04/20] checkpoint: basic implementation and tests --- nameko_grpc/tracer.py | 239 ++++++++++++++++++++ setup.py | 3 +- test/spec/tracer_nameko.py | 9 + test/test_tracer.py | 446 +++++++++++++++++++++++++++++++++++++ tox.ini | 2 +- 5 files changed, 697 insertions(+), 2 deletions(-) create mode 100644 nameko_grpc/tracer.py create mode 100644 test/spec/tracer_nameko.py create mode 100644 test/test_tracer.py diff --git a/nameko_grpc/tracer.py b/nameko_grpc/tracer.py new file mode 100644 index 0000000..46be501 --- /dev/null +++ b/nameko_grpc/tracer.py @@ -0,0 +1,239 @@ +# -*- coding: utf-8 -*- +import logging +import sys +from datetime import datetime + +from nameko_tracer import Tracer, constants +from nameko_tracer.adapters import DefaultAdapter + +from nameko_grpc.constants import Cardinality + + +logger = logging.getLogger(__name__) + +GRPC_ADAPTER = { + "nameko_grpc.entrypoint.Grpc": ("nameko_grpc.tracer.GrpcEntrypointAdapter") +} + + +class GrpcEntrypointAdapter(DefaultAdapter): + def process(self, message, kwargs): + + kwargs["extra"][constants.TRACE_KEY] = {} # add info here first + + message, kwargs = super().process(message, kwargs) + + trace_data = kwargs["extra"][constants.TRACE_KEY] + + # add cardinality to trace_data + cardinality = kwargs["extra"]["worker_ctx"].entrypoint.cardinality + trace_data["cardinality"] = cardinality + + # add stream part to trace_data + stream_part = kwargs["extra"].get("stream_part", None) + if stream_part: + trace_data["stream_part"] = stream_part + + # add stream age to trace_data + stream_age = kwargs["extra"].get("stream_age", None) + if stream_age: + trace_data["stream_age"] = stream_age + + # remove response from trace_data if this is the top-level trace for a + # streaming response + if ( + cardinality in (Cardinality.UNARY_STREAM, Cardinality.STREAM_STREAM) + and stream_part is None + and trace_data["stage"] == "response" + ): + trace_data["response"] = "streaming" + + # remove request from trace_data if this is the top-level trace for a + # streaming request + if ( + cardinality in (Cardinality.STREAM_UNARY, Cardinality.STREAM_STREAM) + and stream_part is None + and trace_data["stage"] == "request" + ): + trace_data["call_args"]["request"] == "streaming" + + return message, kwargs + + def get_result(self, result): + return result + + +class GrpcTracer(Tracer): + """ Extend nameko_tracer.Tracer to add support for the Grpc entrypoint, including + streaming requests and responses. + """ + + def setup(self): + self.configure_adapter_types(GRPC_ADAPTER) + super().setup() + + def log_request(self, worker_ctx): + request, context = worker_ctx.args + + cardinality = worker_ctx.entrypoint.cardinality + + request_stream = None + if cardinality in (Cardinality.STREAM_UNARY, Cardinality.STREAM_STREAM): + request_stream = request.tee() + + timestamp = datetime.utcnow() + self.worker_timestamps[worker_ctx] = timestamp + + extra = { + "stage": constants.Stage.request, + "worker_ctx": worker_ctx, + "timestamp": timestamp, + } + try: + adapter = self.adapter_factory(worker_ctx) + adapter.info("[%s] entrypoint call trace", worker_ctx.call_id, extra=extra) + except Exception: + logger.warning("Failed to log entrypoint trace", exc_info=True) + + if request_stream: + self.container.spawn_managed_thread( + lambda: self.log_request_stream(worker_ctx, request_stream) + ) + + def log_result(self, worker_ctx, result, exc_info): + + cardinality = worker_ctx.entrypoint.cardinality + + timestamp = datetime.utcnow() + worker_setup_timestamp = self.worker_timestamps[worker_ctx] + response_time = (timestamp - worker_setup_timestamp).total_seconds() + + result_stream = None + + if exc_info is None and cardinality in ( + Cardinality.UNARY_STREAM, + Cardinality.STREAM_STREAM, + ): + result_stream = result.tee() + + extra = { + "stage": constants.Stage.response, + "worker_ctx": worker_ctx, + "result": result, + "exc_info_": exc_info, + "timestamp": timestamp, + "response_time": response_time, + } + + try: + adapter = self.adapter_factory(worker_ctx) + if exc_info: + adapter.warning( + "[%s] entrypoint result trace", worker_ctx.call_id, extra=extra + ) + else: + adapter.info( + "[%s] entrypoint result trace", worker_ctx.call_id, extra=extra + ) + except Exception: + logger.warning("Failed to log entrypoint trace", exc_info=True) + + if result_stream: + self.container.spawn_managed_thread( + lambda: self.log_result_stream(worker_ctx, result_stream) + ) + + def log_request_stream(self, worker_ctx, request_stream): + + stream_start = datetime.utcnow() + + for index, request in enumerate(request_stream, start=1): + + timestamp = datetime.utcnow() + stream_age = (timestamp - stream_start).total_seconds() + + extra = { + "stage": constants.Stage.request, + "worker_ctx": worker_ctx, + "timestamp": timestamp, + "stream_age": stream_age, + "stream_part": index, + } + try: + adapter = self.adapter_factory(worker_ctx) + adapter.info( + "[%s] entrypoint call trace [stream_part %s]", + worker_ctx.call_id, + index, + extra=extra, + ) + except Exception: + logger.warning("Failed to log entrypoint trace", exc_info=True) + + def log_result_stream(self, worker_ctx, result_stream): + + stream_start = datetime.utcnow() + + try: + for index, result in enumerate(result_stream, start=1): + timestamp = datetime.utcnow() + stream_age = (timestamp - stream_start).total_seconds() + + extra = { + "stage": constants.Stage.response, + "worker_ctx": worker_ctx, + "result": result, + "exc_info_": None, + "timestamp": timestamp, + "response_time": None, # TODO i think we want this on stream end + "stream_age": stream_age, + "stream_part": index, + } + try: + adapter = self.adapter_factory(worker_ctx) + adapter.info( + "[%s] entrypoint result trace [stream_part %s]", + worker_ctx.call_id, + index, + extra=extra, + ) + except Exception: + logger.warning("Failed to log entrypoint trace", exc_info=True) + + except Exception: + + timestamp = datetime.utcnow() + stream_age = (timestamp - stream_start).total_seconds() + + # NB> this is _idential_ to block above; all the cleverness to extract + # rhe traceback is already in the adapter (stream part not identical, actly) + extra = { + "stage": constants.Stage.response, + "worker_ctx": worker_ctx, + "result": None, + "exc_info_": sys.exc_info(), + "timestamp": timestamp, + "response_time": None, # TODO i think we want this on stream end + "stream_age": stream_age, + "stream_part": index + 1, + } + try: + adapter = self.adapter_factory(worker_ctx) + adapter.info( + "[%s] entrypoint result trace [stream_part %s]", + worker_ctx.call_id, + index, + extra=extra, + ) + except Exception: + logger.warning("Failed to log entrypoint trace", exc_info=True) + + def worker_setup(self, worker_ctx): + """ Log entrypoint call details + """ + self.log_request(worker_ctx) + + def worker_result(self, worker_ctx, result=None, exc_info=None): + """ Log entrypoint result details + """ + self.log_result(worker_ctx, result, exc_info) diff --git a/setup.py b/setup.py index 55aaf41..8ca1882 100644 --- a/setup.py +++ b/setup.py @@ -22,6 +22,7 @@ packages=find_packages(exclude=["test", "test.*"]), install_requires=["nameko", "h2>=3"], extras_require={ + "tracer": ["nameko_tracer"], "dev": [ "pytest", "grpcio", @@ -30,7 +31,7 @@ "pre-commit", "wrapt", "zmq", - ] + ], }, zip_safe=True, license="Apache License, Version 2.0", diff --git a/test/spec/tracer_nameko.py b/test/spec/tracer_nameko.py new file mode 100644 index 0000000..8632185 --- /dev/null +++ b/test/spec/tracer_nameko.py @@ -0,0 +1,9 @@ +# -*- coding: utf-8 -*- +from example_nameko import example + +from nameko_grpc.tracer import GrpcTracer + + +class tracer(example): + + tracer = GrpcTracer() diff --git a/test/test_tracer.py b/test/test_tracer.py new file mode 100644 index 0000000..83c60cd --- /dev/null +++ b/test/test_tracer.py @@ -0,0 +1,446 @@ +# -*- coding: utf-8 -*- +""" Test integration with https://github.com/nameko/nameko-tracer +""" + +import logging + +import pytest +from grpc import StatusCode +from nameko_tracer.constants import Stage + +from nameko_grpc.constants import Cardinality +from nameko_grpc.exceptions import GrpcError + + +@pytest.mark.usefixtures("predictable_call_ids") +class TestTracerIntegration: + @pytest.fixture + def client_type(self): + return "nameko" # no point testing multiple clients + + @pytest.fixture + def server(self, start_nameko_server): + return start_nameko_server("tracer") + + @pytest.fixture + def caplog(self, caplog): + with caplog.at_level(logging.INFO): + yield caplog + + @pytest.fixture + def get_log_records(self, caplog): + def is_trace(record): + return record.name == "nameko_tracer" + + def is_request(record): + return record.stage == Stage.request + + def is_response(record): + return record.stage == Stage.response + + def is_stream(record): + return getattr(record, "stream_part", False) + + def match_all(*fns): + def check(val): + return all(fn(val) for fn in fns) + + return check + + def extract_trace(record): + return record.nameko_trace + + def extract_records(): + trace_records = list(filter(is_trace, caplog.records)) + + request_trace = extract_trace(next(filter(is_request, trace_records))) + response_trace = extract_trace(next(filter(is_response, trace_records))) + + request_stream = list( + map( + extract_trace, + filter(match_all(is_request, is_stream), trace_records), + ) + ) + response_stream = list( + map( + extract_trace, + filter(match_all(is_response, is_stream), trace_records), + ) + ) + return request_trace, response_trace, request_stream, response_stream + + return extract_records + + @pytest.fixture + def check_trace(self): + def check(data, requires): + for key, value in requires.items(): + if callable(value): + assert value(data[key]) + else: + assert data[key] == value + + return check + + def test_unary_unary(self, client, protobufs, get_log_records, check_trace): + response = client.unary_unary(protobufs.ExampleRequest(value="A")) + assert response.message == "A" + + request_trace, response_trace, request_stream, result_stream = get_log_records() + + common = { + "call_id": "example.unary_unary.0", + "call_id_stack": ["example.unary_unary.0"], + "entrypoint_name": "unary_unary", + "entrypoint_type": "Grpc", + "service": "example", + } + + check_trace( + request_trace, + dict( + common, **{"stage": "request", "cardinality": Cardinality.UNARY_UNARY} + ), + ) + + check_trace( + response_trace, + dict( + common, + **{ + "stage": "response", + "cardinality": Cardinality.UNARY_UNARY, + "response": response, + "response_status": "success", + "response_time": lambda value: value > 0, + } + ), + ) + + assert len(request_stream) == 0 + + assert len(result_stream) == 0 + + def test_unary_stream(self, client, protobufs, get_log_records, check_trace): + responses = client.unary_stream( + protobufs.ExampleRequest(value="A", response_count=2) + ) + assert [(response.message, response.seqno) for response in responses] == [ + ("A", 1), + ("A", 2), + ] + + request_trace, response_trace, request_stream, result_stream = get_log_records() + + common = { + "call_id": "example.unary_stream.0", + "call_id_stack": ["example.unary_stream.0"], + "entrypoint_name": "unary_stream", + "entrypoint_type": "Grpc", + "service": "example", + } + + check_trace( + request_trace, + dict( + common, **{"stage": "request", "cardinality": Cardinality.UNARY_STREAM} + ), + ) + + check_trace( + response_trace, + dict( + common, + **{ + "stage": "response", + "cardinality": Cardinality.UNARY_STREAM, + "response": "streaming", + "response_status": "success", + "response_time": lambda value: value > 0, + } + ), + ) + + assert len(request_stream) == 0 + + assert len(result_stream) == 2 + for index, trace in enumerate(result_stream, 1): + check_trace( + trace, + dict( + common, + **{ + "stage": "response", + "cardinality": Cardinality.UNARY_STREAM, + "stream_part": index, + "response_time": None, + "stream_age": lambda value: value > 0, + } + ), + ) + + def test_stream_unary(self, client, protobufs, get_log_records, check_trace): + def generate_requests(): + for value in ["A", "B"]: + yield protobufs.ExampleRequest(value=value) + + response = client.stream_unary(generate_requests()) + assert response.message == "A,B" + + request_trace, response_trace, request_stream, result_stream = get_log_records() + + common = { + "call_id": "example.stream_unary.0", + "call_id_stack": ["example.stream_unary.0"], + "entrypoint_name": "stream_unary", + "entrypoint_type": "Grpc", + "service": "example", + } + + check_trace( + request_trace, + dict( + common, **{"stage": "request", "cardinality": Cardinality.STREAM_UNARY} + ), + ) + + check_trace( + response_trace, + dict( + common, + **{ + "stage": "response", + "cardinality": Cardinality.STREAM_UNARY, + "response": response, + "response_status": "success", + "response_time": lambda value: value > 0, + } + ), + ) + + assert len(request_stream) == 2 + for index, trace in enumerate(request_stream, 1): + check_trace( + trace, + dict( + common, + **{ + "stage": "request", + "cardinality": Cardinality.STREAM_UNARY, + "stream_part": index, + "stream_age": lambda value: value > 0, + } + ), + ) + + assert len(result_stream) == 0 + + def test_stream_stream(self, client, protobufs, get_log_records, check_trace): + def generate_requests(): + for value in ["A", "B"]: + yield protobufs.ExampleRequest(value=value) + + responses = client.stream_stream(generate_requests()) + assert [(response.message, response.seqno) for response in responses] == [ + ("A", 1), + ("B", 2), + ] + + request_trace, response_trace, request_stream, result_stream = get_log_records() + + common = { + "call_id": "example.stream_stream.0", + "call_id_stack": ["example.stream_stream.0"], + "entrypoint_name": "stream_stream", + "entrypoint_type": "Grpc", + "service": "example", + } + + check_trace( + request_trace, + dict( + common, **{"stage": "request", "cardinality": Cardinality.STREAM_STREAM} + ), + ) + + check_trace( + response_trace, + dict( + common, + **{ + "stage": "response", + "cardinality": Cardinality.STREAM_STREAM, + "response": "streaming", + "response_status": "success", + "response_time": lambda value: value > 0, + } + ), + ) + + assert len(request_stream) == 2 + for index, trace in enumerate(request_stream, 1): + check_trace( + trace, + dict( + common, + **{ + "stage": "request", + "cardinality": Cardinality.STREAM_STREAM, + "stream_part": index, + "stream_age": lambda value: value > 0, + } + ), + ) + + assert len(result_stream) == 2 + for index, trace in enumerate(result_stream, 1): + check_trace( + trace, + dict( + common, + **{ + "stage": "response", + "cardinality": Cardinality.STREAM_STREAM, + "stream_part": index, + "response_time": None, + "stream_age": lambda value: value > 0, + } + ), + ) + + def test_error_before_response( + self, client, protobufs, get_log_records, check_trace + ): + with pytest.raises(GrpcError) as error: + client.unary_error(protobufs.ExampleRequest(value="A")) + assert error.value.status == StatusCode.UNKNOWN + assert error.value.details == "Exception calling application: boom" + + request_trace, response_trace, request_stream, result_stream = get_log_records() + + common = { + # XXX add call_args here (for all tests) + "call_id": "example.unary_error.0", + "call_id_stack": ["example.unary_error.0"], + "entrypoint_name": "unary_error", + "entrypoint_type": "Grpc", + "service": "example", + } + + check_trace( + request_trace, + dict( + common, **{"stage": "request", "cardinality": Cardinality.UNARY_UNARY} + ), + ) + + check_trace( + response_trace, + dict( + common, + **{ + "stage": "response", + "cardinality": Cardinality.UNARY_UNARY, + "response_status": "error", + "response_time": lambda value: value > 0, + "exception_value": "boom", + "exception_type": "Error", + "exception_path": "example_nameko.Error", + "exception_args": ["boom"], + "exception_traceback": lambda tb: 'raise Error("boom")' in tb, + "exception_expected": True, + } + ), + ) + + assert len(request_stream) == 0 + + assert len(result_stream) == 0 + + def test_error_while_streaming_response( + self, client, protobufs, get_log_records, check_trace + ): + res = client.stream_error( + protobufs.ExampleRequest(value="A", response_count=10) + ) + with pytest.raises(GrpcError) as error: + list(res) + + assert error.value.status == StatusCode.UNKNOWN + assert error.value.details == "Exception iterating responses: boom" + + request_trace, response_trace, request_stream, result_stream = get_log_records() + + common = { + # XXX add call_args here (for all tests) + "call_id": "example.stream_error.0", + "call_id_stack": ["example.stream_error.0"], + "entrypoint_name": "stream_error", + "entrypoint_type": "Grpc", + "service": "example", + } + + check_trace( + request_trace, + dict( + common, **{"stage": "request", "cardinality": Cardinality.UNARY_STREAM} + ), + ) + + check_trace( + response_trace, + dict( + common, + **{ + "stage": "response", + "cardinality": Cardinality.UNARY_STREAM, + "response_status": "success", # XXX URM + "response_time": lambda value: value > 0, + } + ), + ) + + assert len(request_stream) == 0 + + assert len(result_stream) == 10 + + # check first 9 stream parts + for index, trace in enumerate(result_stream[:-1], 1): + check_trace( + trace, + dict( + common, + **{ + "stage": "response", + "cardinality": Cardinality.UNARY_STREAM, + "stream_part": index, + # "result": "something", + "response_status": "success", + "response_time": None, + "stream_age": lambda value: value > 0, + } + ), + ) + + # check last stream part + check_trace( + result_stream[-1], + dict( + common, + **{ + "stage": "response", + "cardinality": Cardinality.UNARY_STREAM, + "stream_part": 10, + "response_status": "error", + "response_time": None, + "stream_age": lambda value: value > 0, + "exception_value": "boom", + "exception_type": "Error", + "exception_path": "example_nameko.Error", + "exception_args": ["boom"], + "exception_traceback": lambda tb: 'raise Error("boom")' in tb, + "exception_expected": True, + } + ), + ) diff --git a/tox.ini b/tox.ini index beac1da..f30d3e8 100644 --- a/tox.ini +++ b/tox.ini @@ -9,5 +9,5 @@ commands = static: pip install --editable .[dev] static: make static - test: pip install --editable .[dev] + test: pip install --editable .[tracer,dev] test: make test From 370eebd5497c266ccfab8660c36681080cab719c Mon Sep 17 00:00:00 2001 From: Matt Bennett Date: Mon, 21 Jan 2019 10:05:54 +0000 Subject: [PATCH 05/20] tidyup adapter slightly --- nameko_grpc/tracer.py | 33 ++++++++++++++------------------- 1 file changed, 14 insertions(+), 19 deletions(-) diff --git a/nameko_grpc/tracer.py b/nameko_grpc/tracer.py index 46be501..4c858a8 100644 --- a/nameko_grpc/tracer.py +++ b/nameko_grpc/tracer.py @@ -19,28 +19,23 @@ class GrpcEntrypointAdapter(DefaultAdapter): def process(self, message, kwargs): - kwargs["extra"][constants.TRACE_KEY] = {} # add info here first - - message, kwargs = super().process(message, kwargs) - - trace_data = kwargs["extra"][constants.TRACE_KEY] - - # add cardinality to trace_data - cardinality = kwargs["extra"]["worker_ctx"].entrypoint.cardinality - trace_data["cardinality"] = cardinality + worker_ctx = kwargs["extra"]["worker_ctx"] + cardinality = worker_ctx.entrypoint.cardinality - # add stream part to trace_data stream_part = kwargs["extra"].get("stream_part", None) + stream_age = kwargs["extra"].get("stream_age", None) + + trace_data = {"cardinality": cardinality} if stream_part: trace_data["stream_part"] = stream_part - - # add stream age to trace_data - stream_age = kwargs["extra"].get("stream_age", None) if stream_age: trace_data["stream_age"] = stream_age - # remove response from trace_data if this is the top-level trace for a - # streaming response + kwargs["extra"][constants.TRACE_KEY] = trace_data + + message, kwargs = super().process(message, kwargs) + + # replace `response` if this is the top-level trace for a streaming response if ( cardinality in (Cardinality.UNARY_STREAM, Cardinality.STREAM_STREAM) and stream_part is None @@ -48,8 +43,7 @@ def process(self, message, kwargs): ): trace_data["response"] = "streaming" - # remove request from trace_data if this is the top-level trace for a - # streaming request + # replace `request` if this is the top-level trace for a streaming request if ( cardinality in (Cardinality.STREAM_UNARY, Cardinality.STREAM_STREAM) and stream_part is None @@ -206,7 +200,8 @@ def log_result_stream(self, worker_ctx, result_stream): stream_age = (timestamp - stream_start).total_seconds() # NB> this is _idential_ to block above; all the cleverness to extract - # rhe traceback is already in the adapter (stream part not identical, actly) + # rhe traceback is already in the adapter + # (stream part not identical, actually. nor log level) extra = { "stage": constants.Stage.response, "worker_ctx": worker_ctx, @@ -219,7 +214,7 @@ def log_result_stream(self, worker_ctx, result_stream): } try: adapter = self.adapter_factory(worker_ctx) - adapter.info( + adapter.warning( "[%s] entrypoint result trace [stream_part %s]", worker_ctx.call_id, index, From bcf5f4e83ae7185a892e4d5a95d755cafdd143bc Mon Sep 17 00:00:00 2001 From: Matt Bennett Date: Mon, 21 Jan 2019 10:37:56 +0000 Subject: [PATCH 06/20] expand tests to cover all expected keys --- test/test_tracer.py | 49 ++++++++++++++++++++++++++++++++++----------- 1 file changed, 37 insertions(+), 12 deletions(-) diff --git a/test/test_tracer.py b/test/test_tracer.py index 83c60cd..2049b9c 100644 --- a/test/test_tracer.py +++ b/test/test_tracer.py @@ -3,9 +3,12 @@ """ import logging +import socket +from datetime import datetime import pytest from grpc import StatusCode +from mock import ANY from nameko_tracer.constants import Stage from nameko_grpc.constants import Cardinality @@ -84,17 +87,22 @@ def check(data, requires): return check def test_unary_unary(self, client, protobufs, get_log_records, check_trace): - response = client.unary_unary(protobufs.ExampleRequest(value="A")) + request = protobufs.ExampleRequest(value="A") + response = client.unary_unary(request) assert response.message == "A" request_trace, response_trace, request_stream, result_stream = get_log_records() common = { + "hostname": socket.gethostname(), + "timestamp": lambda dt: isinstance(dt, datetime), "call_id": "example.unary_unary.0", "call_id_stack": ["example.unary_unary.0"], "entrypoint_name": "unary_unary", "entrypoint_type": "Grpc", "service": "example", + "call_args": {"context": ANY, "request": request}, + "call_args_redacted": False, } check_trace( @@ -123,9 +131,8 @@ def test_unary_unary(self, client, protobufs, get_log_records, check_trace): assert len(result_stream) == 0 def test_unary_stream(self, client, protobufs, get_log_records, check_trace): - responses = client.unary_stream( - protobufs.ExampleRequest(value="A", response_count=2) - ) + request = protobufs.ExampleRequest(value="A", response_count=2) + responses = list(client.unary_stream(request)) assert [(response.message, response.seqno) for response in responses] == [ ("A", 1), ("A", 2), @@ -134,11 +141,15 @@ def test_unary_stream(self, client, protobufs, get_log_records, check_trace): request_trace, response_trace, request_stream, result_stream = get_log_records() common = { + "hostname": socket.gethostname(), + "timestamp": lambda dt: isinstance(dt, datetime), "call_id": "example.unary_stream.0", "call_id_stack": ["example.unary_stream.0"], "entrypoint_name": "unary_stream", "entrypoint_type": "Grpc", "service": "example", + "call_args": {"context": ANY, "request": request}, + "call_args_redacted": False, } check_trace( @@ -185,17 +196,22 @@ def generate_requests(): for value in ["A", "B"]: yield protobufs.ExampleRequest(value=value) - response = client.stream_unary(generate_requests()) + requests = list(generate_requests()) + response = client.stream_unary(requests) assert response.message == "A,B" request_trace, response_trace, request_stream, result_stream = get_log_records() common = { + "hostname": socket.gethostname(), + "timestamp": lambda dt: isinstance(dt, datetime), "call_id": "example.stream_unary.0", "call_id_stack": ["example.stream_unary.0"], "entrypoint_name": "stream_unary", "entrypoint_type": "Grpc", "service": "example", + "call_args": {"context": ANY, "request": "streaming"}, + "call_args_redacted": False, } check_trace( @@ -241,7 +257,8 @@ def generate_requests(): for value in ["A", "B"]: yield protobufs.ExampleRequest(value=value) - responses = client.stream_stream(generate_requests()) + requests = list(generate_requests()) + responses = list(client.stream_stream(requests)) assert [(response.message, response.seqno) for response in responses] == [ ("A", 1), ("B", 2), @@ -250,11 +267,15 @@ def generate_requests(): request_trace, response_trace, request_stream, result_stream = get_log_records() common = { + "hostname": socket.gethostname(), + "timestamp": lambda dt: isinstance(dt, datetime), "call_id": "example.stream_stream.0", "call_id_stack": ["example.stream_stream.0"], "entrypoint_name": "stream_stream", "entrypoint_type": "Grpc", "service": "example", + "call_args": {"context": ANY, "request": "streaming"}, + "call_args_redacted": False, } check_trace( @@ -320,7 +341,8 @@ def test_error_before_response( request_trace, response_trace, request_stream, result_stream = get_log_records() common = { - # XXX add call_args here (for all tests) + "hostname": socket.gethostname(), + "timestamp": lambda dt: isinstance(dt, datetime), "call_id": "example.unary_error.0", "call_id_stack": ["example.unary_error.0"], "entrypoint_name": "unary_error", @@ -361,11 +383,13 @@ def test_error_before_response( def test_error_while_streaming_response( self, client, protobufs, get_log_records, check_trace ): - res = client.stream_error( - protobufs.ExampleRequest(value="A", response_count=10) - ) + responses = [] with pytest.raises(GrpcError) as error: - list(res) + responses.extend( + client.stream_error( + protobufs.ExampleRequest(value="A", response_count=10) + ) + ) assert error.value.status == StatusCode.UNKNOWN assert error.value.details == "Exception iterating responses: boom" @@ -373,7 +397,8 @@ def test_error_while_streaming_response( request_trace, response_trace, request_stream, result_stream = get_log_records() common = { - # XXX add call_args here (for all tests) + "hostname": socket.gethostname(), + "timestamp": lambda dt: isinstance(dt, datetime), "call_id": "example.stream_error.0", "call_id_stack": ["example.stream_error.0"], "entrypoint_name": "stream_error", From 87207b94358e4d3d8a8f8993a1c4bba408114271 Mon Sep 17 00:00:00 2001 From: Matt Bennett Date: Mon, 21 Jan 2019 13:52:22 +0000 Subject: [PATCH 07/20] simplify adapter, split into multiple modules; test we're returning requests/responses in streams --- nameko_grpc/tracer/__init__.py | 3 + nameko_grpc/tracer/adapter.py | 93 +++++++++++++++++++ .../{tracer.py => tracer/dependency.py} | 43 +-------- test/test_tracer.py | 58 ++++++++---- 4 files changed, 135 insertions(+), 62 deletions(-) create mode 100644 nameko_grpc/tracer/__init__.py create mode 100644 nameko_grpc/tracer/adapter.py rename nameko_grpc/{tracer.py => tracer/dependency.py} (81%) diff --git a/nameko_grpc/tracer/__init__.py b/nameko_grpc/tracer/__init__.py new file mode 100644 index 0000000..1be39ab --- /dev/null +++ b/nameko_grpc/tracer/__init__.py @@ -0,0 +1,3 @@ +# -*- coding: utf-8 -*- +from nameko_grpc.tracer.adapter import GrpcEntrypointAdapter # noqa: F401 +from nameko_grpc.tracer.dependency import GrpcTracer # noqa: F401 diff --git a/nameko_grpc/tracer/adapter.py b/nameko_grpc/tracer/adapter.py new file mode 100644 index 0000000..88da367 --- /dev/null +++ b/nameko_grpc/tracer/adapter.py @@ -0,0 +1,93 @@ +# -*- coding: utf-8 -*- +from nameko_tracer import constants +from nameko_tracer.adapters import DefaultAdapter + +from nameko_grpc.constants import Cardinality + + +def clean_call_args(extra): + cardinality = get_cardinality(extra) + if cardinality in (Cardinality.STREAM_UNARY, Cardinality.STREAM_STREAM): + trace_data = extra[constants.TRACE_KEY] + trace_data["call_args"]["request"] = "streaming" + + +def clean_response(extra): + if not is_response(extra): + return + + cardinality = get_cardinality(extra) + if cardinality in ( + Cardinality.UNARY_STREAM, + Cardinality.STREAM_STREAM, + ) and not is_stream(extra): + trace_data = extra[constants.TRACE_KEY] + trace_data["response"] = "streaming" + + +def is_request(extra): + return extra["stage"] == constants.Stage.request + + +def is_response(extra): + return extra["stage"] == constants.Stage.response + + +def is_stream(extra): + return "stream_part" in extra + + +def get_cardinality(extra): + return extra["worker_ctx"].entrypoint.cardinality + + +def add_cardinality(extra): + trace_data = extra[constants.TRACE_KEY] + trace_data["cardinality"] = get_cardinality(extra) + + +def add_stream_part(extra): + if not is_stream(extra): + return + trace_data = extra[constants.TRACE_KEY] + trace_data["stream_part"] = extra["stream_part"] + + +def add_stream_age(extra): + if not is_stream(extra): + return + trace_data = extra[constants.TRACE_KEY] + trace_data["stream_age"] = extra["stream_age"] + + +def add_request(extra): + if not is_request(extra) or not is_stream(extra): + return + + trace_data = extra[constants.TRACE_KEY] + trace_data["request"] = extra["request"] + + +class GrpcEntrypointAdapter(DefaultAdapter): + + # EXPOSE REQUEST separately (RESPONSE already exists) + # AND GRPC CONTEXT? + + def process(self, message, kwargs): + message, kwargs = super().process(message, kwargs) + + extra = kwargs["extra"] + + add_cardinality(extra) + add_stream_part(extra) + add_stream_age(extra) + add_request(extra) + + clean_call_args(extra) + clean_response(extra) + + return message, kwargs + + def get_result(self, result): + # override to avoid serialization? + return result diff --git a/nameko_grpc/tracer.py b/nameko_grpc/tracer/dependency.py similarity index 81% rename from nameko_grpc/tracer.py rename to nameko_grpc/tracer/dependency.py index 4c858a8..b0683db 100644 --- a/nameko_grpc/tracer.py +++ b/nameko_grpc/tracer/dependency.py @@ -4,7 +4,6 @@ from datetime import datetime from nameko_tracer import Tracer, constants -from nameko_tracer.adapters import DefaultAdapter from nameko_grpc.constants import Cardinality @@ -16,47 +15,6 @@ } -class GrpcEntrypointAdapter(DefaultAdapter): - def process(self, message, kwargs): - - worker_ctx = kwargs["extra"]["worker_ctx"] - cardinality = worker_ctx.entrypoint.cardinality - - stream_part = kwargs["extra"].get("stream_part", None) - stream_age = kwargs["extra"].get("stream_age", None) - - trace_data = {"cardinality": cardinality} - if stream_part: - trace_data["stream_part"] = stream_part - if stream_age: - trace_data["stream_age"] = stream_age - - kwargs["extra"][constants.TRACE_KEY] = trace_data - - message, kwargs = super().process(message, kwargs) - - # replace `response` if this is the top-level trace for a streaming response - if ( - cardinality in (Cardinality.UNARY_STREAM, Cardinality.STREAM_STREAM) - and stream_part is None - and trace_data["stage"] == "response" - ): - trace_data["response"] = "streaming" - - # replace `request` if this is the top-level trace for a streaming request - if ( - cardinality in (Cardinality.STREAM_UNARY, Cardinality.STREAM_STREAM) - and stream_part is None - and trace_data["stage"] == "request" - ): - trace_data["call_args"]["request"] == "streaming" - - return message, kwargs - - def get_result(self, result): - return result - - class GrpcTracer(Tracer): """ Extend nameko_tracer.Tracer to add support for the Grpc entrypoint, including streaming requests and responses. @@ -152,6 +110,7 @@ def log_request_stream(self, worker_ctx, request_stream): "timestamp": timestamp, "stream_age": stream_age, "stream_part": index, + "request": request, } try: adapter = self.adapter_factory(worker_ctx) diff --git a/test/test_tracer.py b/test/test_tracer.py index 2049b9c..2cdc3ec 100644 --- a/test/test_tracer.py +++ b/test/test_tracer.py @@ -44,6 +44,9 @@ def is_response(record): def is_stream(record): return getattr(record, "stream_part", False) + def is_not_stream(record): + return not is_stream(record) + def match_all(*fns): def check(val): return all(fn(val) for fn in fns) @@ -56,8 +59,12 @@ def extract_trace(record): def extract_records(): trace_records = list(filter(is_trace, caplog.records)) - request_trace = extract_trace(next(filter(is_request, trace_records))) - response_trace = extract_trace(next(filter(is_response, trace_records))) + request_trace = extract_trace( + next(filter(match_all(is_request, is_not_stream), trace_records)) + ) + response_trace = extract_trace( + next(filter(match_all(is_response, is_not_stream), trace_records)) + ) request_stream = list( map( @@ -176,7 +183,7 @@ def test_unary_stream(self, client, protobufs, get_log_records, check_trace): assert len(request_stream) == 0 assert len(result_stream) == 2 - for index, trace in enumerate(result_stream, 1): + for index, trace in enumerate(result_stream): check_trace( trace, dict( @@ -184,7 +191,8 @@ def test_unary_stream(self, client, protobufs, get_log_records, check_trace): **{ "stage": "response", "cardinality": Cardinality.UNARY_STREAM, - "stream_part": index, + "response": responses[index], + "stream_part": index + 1, "response_time": None, "stream_age": lambda value: value > 0, } @@ -236,7 +244,7 @@ def generate_requests(): ) assert len(request_stream) == 2 - for index, trace in enumerate(request_stream, 1): + for index, trace in enumerate(request_stream): check_trace( trace, dict( @@ -244,7 +252,8 @@ def generate_requests(): **{ "stage": "request", "cardinality": Cardinality.STREAM_UNARY, - "stream_part": index, + "request": requests[index], + "stream_part": index + 1, "stream_age": lambda value: value > 0, } ), @@ -300,7 +309,7 @@ def generate_requests(): ) assert len(request_stream) == 2 - for index, trace in enumerate(request_stream, 1): + for index, trace in enumerate(request_stream): check_trace( trace, dict( @@ -308,14 +317,15 @@ def generate_requests(): **{ "stage": "request", "cardinality": Cardinality.STREAM_STREAM, - "stream_part": index, + "request": requests[index], + "stream_part": index + 1, "stream_age": lambda value: value > 0, } ), ) assert len(result_stream) == 2 - for index, trace in enumerate(result_stream, 1): + for index, trace in enumerate(result_stream): check_trace( trace, dict( @@ -323,8 +333,9 @@ def generate_requests(): **{ "stage": "response", "cardinality": Cardinality.STREAM_STREAM, - "stream_part": index, - "response_time": None, + "response": responses[index], + "stream_part": index + 1, + "response_time": None, # XXX "stream_age": lambda value: value > 0, } ), @@ -333,8 +344,9 @@ def generate_requests(): def test_error_before_response( self, client, protobufs, get_log_records, check_trace ): + request = protobufs.ExampleRequest(value="A") with pytest.raises(GrpcError) as error: - client.unary_error(protobufs.ExampleRequest(value="A")) + client.unary_error(request) assert error.value.status == StatusCode.UNKNOWN assert error.value.details == "Exception calling application: boom" @@ -348,6 +360,8 @@ def test_error_before_response( "entrypoint_name": "unary_error", "entrypoint_type": "Grpc", "service": "example", + "call_args": {"context": ANY, "request": request}, + "call_args_redacted": False, } check_trace( @@ -383,13 +397,15 @@ def test_error_before_response( def test_error_while_streaming_response( self, client, protobufs, get_log_records, check_trace ): + + # NOTE it's important that the server sleeps between streaming responses + # otherwise it terminates the stream with an error before any parts of the + # response stream are put on the wire + request = protobufs.ExampleRequest(value="A", response_count=10, delay=10) responses = [] with pytest.raises(GrpcError) as error: - responses.extend( - client.stream_error( - protobufs.ExampleRequest(value="A", response_count=10) - ) - ) + for response in client.stream_error(request): + responses.append(response) assert error.value.status == StatusCode.UNKNOWN assert error.value.details == "Exception iterating responses: boom" @@ -404,6 +420,8 @@ def test_error_while_streaming_response( "entrypoint_name": "stream_error", "entrypoint_type": "Grpc", "service": "example", + "call_args": {"context": ANY, "request": request}, + "call_args_redacted": False, } check_trace( @@ -431,7 +449,7 @@ def test_error_while_streaming_response( assert len(result_stream) == 10 # check first 9 stream parts - for index, trace in enumerate(result_stream[:-1], 1): + for index, trace in enumerate(result_stream[:-1]): check_trace( trace, dict( @@ -439,8 +457,8 @@ def test_error_while_streaming_response( **{ "stage": "response", "cardinality": Cardinality.UNARY_STREAM, - "stream_part": index, - # "result": "something", + "response": responses[index], + "stream_part": index + 1, "response_status": "success", "response_time": None, "stream_age": lambda value: value > 0, From 1e8d6f407977344ffabbf68e814563be7d37d145 Mon Sep 17 00:00:00 2001 From: Matt Bennett Date: Wed, 23 Jan 2019 12:12:19 +0000 Subject: [PATCH 08/20] checkpoint: split tests into separate functional groups --- nameko_grpc/tracer/adapter.py | 2 + test/test_tracer.py | 942 ++++++++++++++++++++++++++++++++-- 2 files changed, 888 insertions(+), 56 deletions(-) diff --git a/nameko_grpc/tracer/adapter.py b/nameko_grpc/tracer/adapter.py index 88da367..ea5da71 100644 --- a/nameko_grpc/tracer/adapter.py +++ b/nameko_grpc/tracer/adapter.py @@ -6,6 +6,7 @@ def clean_call_args(extra): + # TODO can fix this by overriding get_call_args cardinality = get_cardinality(extra) if cardinality in (Cardinality.STREAM_UNARY, Cardinality.STREAM_STREAM): trace_data = extra[constants.TRACE_KEY] @@ -13,6 +14,7 @@ def clean_call_args(extra): def clean_response(extra): + # TODO can fix this by overriding get_result if not is_response(extra): return diff --git a/test/test_tracer.py b/test/test_tracer.py index 2cdc3ec..5f47dd4 100644 --- a/test/test_tracer.py +++ b/test/test_tracer.py @@ -15,84 +15,914 @@ from nameko_grpc.exceptions import GrpcError +@pytest.fixture +def client_type(): + return "nameko" # no point testing multiple clients + + +@pytest.fixture +def server(start_nameko_server): + return start_nameko_server("tracer") + + +@pytest.fixture +def caplog(caplog): + with caplog.at_level(logging.INFO): + yield caplog + + +@pytest.fixture +def get_log_records(caplog): + def is_trace(record): + return record.name == "nameko_tracer" + + def is_request(record): + return record.stage == Stage.request + + def is_response(record): + return record.stage == Stage.response + + def is_stream(record): + return getattr(record, "stream_part", False) + + def is_not_stream(record): + return not is_stream(record) + + def match_all(*fns): + def check(val): + return all(fn(val) for fn in fns) + + return check + + def extract_trace(record): + return record.nameko_trace + + def extract_records(): + trace_records = list(filter(is_trace, caplog.records)) + + request_trace = extract_trace( + next(filter(match_all(is_request, is_not_stream), trace_records)) + ) + response_trace = extract_trace( + next(filter(match_all(is_response, is_not_stream), trace_records)) + ) + + request_stream = list( + map(extract_trace, filter(match_all(is_request, is_stream), trace_records)) + ) + response_stream = list( + map(extract_trace, filter(match_all(is_response, is_stream), trace_records)) + ) + return request_trace, response_trace, request_stream, response_stream + + return extract_records + + +@pytest.fixture +def check_trace(): + def check(data, requires): + for key, value in requires.items(): + if callable(value): + assert value(data[key]) + else: + assert data[key] == value + + return check + + @pytest.mark.usefixtures("predictable_call_ids") -class TestTracerIntegration: - @pytest.fixture - def client_type(self): - return "nameko" # no point testing multiple clients +class TestEssentialFields: + """ Verify "essential" fields are present on every log trace, including stream + parts. + + Essential fields: + + - hostname + - timestamp + - entrypoint_name + - entrypoint_type + - service + - cardinality + - call_id + - call_id_stack + - stage + - stream_part (for streams) + - stream_age (for streams) + + """ + + def test_unary_unary(self, client, protobufs, get_log_records, check_trace): + request = protobufs.ExampleRequest(value="A") + response = client.unary_unary(request) + assert response.message == "A" + + request_trace, response_trace, request_stream, result_stream = get_log_records() + + common = { + "hostname": socket.gethostname(), + "timestamp": lambda dt: isinstance(dt, datetime), + "entrypoint_name": "unary_unary", + "entrypoint_type": "Grpc", + "service": "example", + "cardinality": Cardinality.UNARY_UNARY, + "call_id": "example.unary_unary.0", + "call_id_stack": ["example.unary_unary.0"], + } + + check_trace(request_trace, dict(common, **{"stage": "request"})) + + check_trace(response_trace, dict(common, **{"stage": "response"})) + + assert len(request_stream) == 0 + + assert len(result_stream) == 0 + + def test_unary_stream(self, client, protobufs, get_log_records, check_trace): + request = protobufs.ExampleRequest(value="A", response_count=2) + responses = list(client.unary_stream(request)) + assert [(response.message, response.seqno) for response in responses] == [ + ("A", 1), + ("A", 2), + ] + + request_trace, response_trace, request_stream, result_stream = get_log_records() - @pytest.fixture - def server(self, start_nameko_server): - return start_nameko_server("tracer") + common = { + "hostname": socket.gethostname(), + "timestamp": lambda dt: isinstance(dt, datetime), + "entrypoint_name": "unary_stream", + "entrypoint_type": "Grpc", + "service": "example", + "cardinality": Cardinality.UNARY_STREAM, + "call_id": "example.unary_stream.0", + "call_id_stack": ["example.unary_stream.0"], + } - @pytest.fixture - def caplog(self, caplog): - with caplog.at_level(logging.INFO): - yield caplog + check_trace(request_trace, dict(common, **{"stage": "request"})) - @pytest.fixture - def get_log_records(self, caplog): - def is_trace(record): - return record.name == "nameko_tracer" + check_trace(response_trace, dict(common, **{"stage": "response"})) - def is_request(record): - return record.stage == Stage.request + assert len(request_stream) == 0 - def is_response(record): - return record.stage == Stage.response + assert len(result_stream) == 2 + for index, trace in enumerate(result_stream): + check_trace( + trace, + dict( + common, + **{ + "stage": "response", + "stream_part": index + 1, + "stream_age": lambda value: value > 0, + } + ), + ) - def is_stream(record): - return getattr(record, "stream_part", False) + def test_stream_unary(self, client, protobufs, get_log_records, check_trace): + def generate_requests(): + for value in ["A", "B"]: + yield protobufs.ExampleRequest(value=value) - def is_not_stream(record): - return not is_stream(record) + requests = list(generate_requests()) + response = client.stream_unary(requests) + assert response.message == "A,B" - def match_all(*fns): - def check(val): - return all(fn(val) for fn in fns) + request_trace, response_trace, request_stream, result_stream = get_log_records() - return check + common = { + "hostname": socket.gethostname(), + "timestamp": lambda dt: isinstance(dt, datetime), + "entrypoint_name": "stream_unary", + "entrypoint_type": "Grpc", + "service": "example", + "cardinality": Cardinality.STREAM_UNARY, + "call_id": "example.stream_unary.0", + "call_id_stack": ["example.stream_unary.0"], + } - def extract_trace(record): - return record.nameko_trace + check_trace(request_trace, dict(common, **{"stage": "request"})) - def extract_records(): - trace_records = list(filter(is_trace, caplog.records)) + check_trace(response_trace, dict(common, **{"stage": "response"})) - request_trace = extract_trace( - next(filter(match_all(is_request, is_not_stream), trace_records)) + assert len(request_stream) == 2 + for index, trace in enumerate(request_stream): + check_trace( + trace, + dict( + common, + **{ + "stage": "request", + "stream_part": index + 1, + "stream_age": lambda value: value > 0, + } + ), ) - response_trace = extract_trace( - next(filter(match_all(is_response, is_not_stream), trace_records)) + + assert len(result_stream) == 0 + + def test_stream_stream(self, client, protobufs, get_log_records, check_trace): + def generate_requests(): + for value in ["A", "B"]: + yield protobufs.ExampleRequest(value=value) + + requests = list(generate_requests()) + responses = list(client.stream_stream(requests)) + assert [(response.message, response.seqno) for response in responses] == [ + ("A", 1), + ("B", 2), + ] + + request_trace, response_trace, request_stream, result_stream = get_log_records() + + common = { + "hostname": socket.gethostname(), + "timestamp": lambda dt: isinstance(dt, datetime), + "entrypoint_name": "stream_stream", + "entrypoint_type": "Grpc", + "service": "example", + "cardinality": Cardinality.STREAM_STREAM, + "call_id": "example.stream_stream.0", + "call_id_stack": ["example.stream_stream.0"], + } + + check_trace(request_trace, dict(common, **{"stage": "request"})) + + check_trace(response_trace, dict(common, **{"stage": "response"})) + + assert len(request_stream) == 2 + for index, trace in enumerate(request_stream): + check_trace( + trace, + dict( + common, + **{ + "stage": "request", + "stream_part": index + 1, + "stream_age": lambda value: value > 0, + } + ), ) - request_stream = list( - map( - extract_trace, - filter(match_all(is_request, is_stream), trace_records), - ) + assert len(result_stream) == 2 + for index, trace in enumerate(result_stream): + check_trace( + trace, + dict( + common, + **{ + "stage": "response", + "stream_part": index + 1, + "stream_age": lambda value: value > 0, + } + ), ) - response_stream = list( - map( - extract_trace, - filter(match_all(is_response, is_stream), trace_records), - ) + + def test_error_before_response( + self, client, protobufs, get_log_records, check_trace + ): + request = protobufs.ExampleRequest(value="A") + with pytest.raises(GrpcError) as error: + client.unary_error(request) + assert error.value.status == StatusCode.UNKNOWN + assert error.value.details == "Exception calling application: boom" + + request_trace, response_trace, request_stream, result_stream = get_log_records() + + common = { + "hostname": socket.gethostname(), + "timestamp": lambda dt: isinstance(dt, datetime), + "entrypoint_name": "unary_error", + "entrypoint_type": "Grpc", + "service": "example", + "cardinality": Cardinality.UNARY_UNARY, + "call_id": "example.unary_error.0", + "call_id_stack": ["example.unary_error.0"], + } + + check_trace(request_trace, dict(common, **{"stage": "request"})) + + check_trace(response_trace, dict(common, **{"stage": "response"})) + + assert len(request_stream) == 0 + + assert len(result_stream) == 0 + + def test_error_while_streaming_response( + self, client, protobufs, get_log_records, check_trace + ): + + # NOTE it's important that the server sleeps between streaming responses + # otherwise it terminates the stream with an error before any parts of the + # response stream are put on the wire + request = protobufs.ExampleRequest(value="A", response_count=10, delay=10) + responses = [] + with pytest.raises(GrpcError) as error: + for response in client.stream_error(request): + responses.append(response) + + assert error.value.status == StatusCode.UNKNOWN + assert error.value.details == "Exception iterating responses: boom" + + request_trace, response_trace, request_stream, result_stream = get_log_records() + + common = { + "hostname": socket.gethostname(), + "timestamp": lambda dt: isinstance(dt, datetime), + "entrypoint_name": "stream_error", + "entrypoint_type": "Grpc", + "service": "example", + "cardinality": Cardinality.UNARY_STREAM, + "call_id": "example.stream_error.0", + "call_id_stack": ["example.stream_error.0"], + } + + check_trace(request_trace, dict(common, **{"stage": "request"})) + + check_trace(response_trace, dict(common, **{"stage": "response"})) + + assert len(request_stream) == 0 + + assert len(result_stream) == 10 + for index, trace in enumerate(result_stream): + check_trace( + trace, + dict( + common, + **{ + "stage": "response", + "stream_part": index + 1, + "stream_age": lambda value: value > 0, + } + ), ) - return request_trace, response_trace, request_stream, response_stream - return extract_records - @pytest.fixture - def check_trace(self): - def check(data, requires): - for key, value in requires.items(): - if callable(value): - assert value(data[key]) - else: - assert data[key] == value +class TestCallArgsField: + # XXX these are all a bit boring and similar; are they adding value? + # also we should really test call args redaction + def test_unary_unary(self, client, protobufs, get_log_records, check_trace): + request = protobufs.ExampleRequest(value="A") + response = client.unary_unary(request) + assert response.message == "A" + + request_trace, response_trace, request_stream, result_stream = get_log_records() + + common = { + "call_args": {"context": ANY, "request": request}, + "call_args_redacted": False, + } + + check_trace(request_trace, common) + + check_trace(response_trace, common) - return check + assert len(request_stream) == 0 + + assert len(result_stream) == 0 + def test_unary_stream(self, client, protobufs, get_log_records, check_trace): + request = protobufs.ExampleRequest(value="A", response_count=2) + responses = list(client.unary_stream(request)) + assert [(response.message, response.seqno) for response in responses] == [ + ("A", 1), + ("A", 2), + ] + + request_trace, response_trace, request_stream, result_stream = get_log_records() + + common = { + "call_args": {"context": ANY, "request": request}, + "call_args_redacted": False, + } + + check_trace(request_trace, common) + + check_trace(response_trace, common) + + assert len(request_stream) == 0 + + assert len(result_stream) == 2 + for index, trace in enumerate(result_stream): + check_trace(trace, common) + + def test_stream_unary(self, client, protobufs, get_log_records, check_trace): + def generate_requests(): + for value in ["A", "B"]: + yield protobufs.ExampleRequest(value=value) + + requests = list(generate_requests()) + response = client.stream_unary(requests) + assert response.message == "A,B" + + request_trace, response_trace, request_stream, result_stream = get_log_records() + + # streaming request, so the request object is replaced + common = { + "call_args": {"context": ANY, "request": "streaming"}, + "call_args_redacted": False, + } + + check_trace(request_trace, common) + + check_trace(response_trace, common) + + assert len(request_stream) == 2 + for index, trace in enumerate(request_stream): + check_trace(trace, common) + + assert len(result_stream) == 0 + + def test_stream_stream(self, client, protobufs, get_log_records, check_trace): + def generate_requests(): + for value in ["A", "B"]: + yield protobufs.ExampleRequest(value=value) + + requests = list(generate_requests()) + responses = list(client.stream_stream(requests)) + assert [(response.message, response.seqno) for response in responses] == [ + ("A", 1), + ("B", 2), + ] + + request_trace, response_trace, request_stream, result_stream = get_log_records() + + # streaming request, so the request object is replaced + common = { + "call_args": {"context": ANY, "request": "streaming"}, + "call_args_redacted": False, + } + + check_trace(request_trace, common) + + check_trace(response_trace, common) + + assert len(request_stream) == 2 + for index, trace in enumerate(request_stream): + check_trace(trace, common) + + assert len(result_stream) == 2 + for index, trace in enumerate(result_stream): + check_trace(trace, common) + + +class TestResponseFields: + def test_unary_unary(self, client, protobufs, get_log_records, check_trace): + request = protobufs.ExampleRequest(value="A") + response = client.unary_unary(request) + assert response.message == "A" + + request_trace, response_trace, request_stream, result_stream = get_log_records() + + check_trace( + response_trace, + { + # "response": response, # XXX want this? + "response_status": "success", + "response_time": lambda value: value > 0, + }, + ) + + assert len(result_stream) == 0 + + def test_unary_stream(self, client, protobufs, get_log_records, check_trace): + request = protobufs.ExampleRequest(value="A", response_count=2) + responses = list(client.unary_stream(request)) + assert [(response.message, response.seqno) for response in responses] == [ + ("A", 1), + ("A", 2), + ] + + request_trace, response_trace, request_stream, result_stream = get_log_records() + + check_trace( + response_trace, + { + # "response": "streaming", # XXX want this? + "response_status": "success", + "response_time": lambda value: value > 0, + }, + ) + + assert len(result_stream) == 2 + for index, trace in enumerate(result_stream): + check_trace( + trace, + { + # "response": responses[index], # XXX want this? + "response_status": "success", + "response_time": lambda value: value > 0, + }, + ) + + def test_stream_unary(self, client, protobufs, get_log_records, check_trace): + def generate_requests(): + for value in ["A", "B"]: + yield protobufs.ExampleRequest(value=value) + + requests = list(generate_requests()) + response = client.stream_unary(requests) + assert response.message == "A,B" + + request_trace, response_trace, request_stream, result_stream = get_log_records() + + check_trace( + response_trace, + { + # "response": response, # XXX want this? + "response_status": "success", + "response_time": lambda value: value > 0, + }, + ) + + assert len(result_stream) == 0 + + def test_stream_stream(self, client, protobufs, get_log_records, check_trace): + def generate_requests(): + for value in ["A", "B"]: + yield protobufs.ExampleRequest(value=value) + + requests = list(generate_requests()) + responses = list(client.stream_stream(requests)) + assert [(response.message, response.seqno) for response in responses] == [ + ("A", 1), + ("B", 2), + ] + + request_trace, response_trace, request_stream, result_stream = get_log_records() + + check_trace( + response_trace, + { + # "response": "streaming", + "response_status": "success", + "response_time": lambda value: value > 0, + }, + ) + + assert len(result_stream) == 2 + for index, trace in enumerate(result_stream): + check_trace( + trace, + { + # "response": responses[index], + "response_status": "success", + "response_time": lambda value: value > 0, + }, + ) + + def test_error_before_response( + self, client, protobufs, get_log_records, check_trace + ): + request = protobufs.ExampleRequest(value="A") + with pytest.raises(GrpcError) as error: + client.unary_error(request) + assert error.value.status == StatusCode.UNKNOWN + assert error.value.details == "Exception calling application: boom" + + request_trace, response_trace, request_stream, result_stream = get_log_records() + + check_trace( + response_trace, + { + # response: None # XXX + "response_status": "error", + "response_time": lambda value: value > 0, + }, + ) + + assert len(result_stream) == 0 + + def test_error_while_streaming_response( + self, client, protobufs, get_log_records, check_trace + ): + + # NOTE it's important that the server sleeps between streaming responses + # otherwise it terminates the stream with an error before any parts of the + # response stream are put on the wire + request = protobufs.ExampleRequest(value="A", response_count=10, delay=10) + responses = [] + with pytest.raises(GrpcError) as error: + for response in client.stream_error(request): + responses.append(response) + + assert error.value.status == StatusCode.UNKNOWN + assert error.value.details == "Exception iterating responses: boom" + + request_trace, response_trace, request_stream, result_stream = get_log_records() + + check_trace( + response_trace, + { + # response: None # XXX + "response_status": "success", # XXX URM + "response_time": lambda value: value > 0, + }, + ) + + assert len(result_stream) == 10 + + # check first 9 stream parts + for index, trace in enumerate(result_stream[:-1]): + check_trace( + trace, + { + # "response": responses[index], + "response_status": "success", + "response_time": lambda value: value > 0, + }, + ) + + # check last stream part + check_trace( + result_stream[-1], + { + # response: None # XXX + "response_status": "error", + "response_time": lambda value: value > 0, + }, + ) + + +class TestGrpcRequestFields: + def test_unary_unary(self, client, protobufs, get_log_records, check_trace): + request = protobufs.ExampleRequest(value="A") + response = client.unary_unary(request) + assert response.message == "A" + + request_trace, response_trace, request_stream, result_stream = get_log_records() + + common = {"request": request} + + check_trace(request_trace, common) + + check_trace(response_trace, common) + + assert len(request_stream) == 0 + + assert len(result_stream) == 0 + + def test_unary_stream(self, client, protobufs, get_log_records, check_trace): + request = protobufs.ExampleRequest(value="A", response_count=2) + responses = list(client.unary_stream(request)) + assert [(response.message, response.seqno) for response in responses] == [ + ("A", 1), + ("A", 2), + ] + + request_trace, response_trace, request_stream, result_stream = get_log_records() + + common = {"request": request} + + check_trace(request_trace, common) + + check_trace(response_trace, common) + + assert len(request_stream) == 0 + + assert len(result_stream) == 2 + for index, trace in enumerate(result_stream): + check_trace(trace, common) + + def test_stream_unary(self, client, protobufs, get_log_records, check_trace): + def generate_requests(): + for value in ["A", "B"]: + yield protobufs.ExampleRequest(value=value) + + requests = list(generate_requests()) + response = client.stream_unary(requests) + assert response.message == "A,B" + + request_trace, response_trace, request_stream, result_stream = get_log_records() + + # XXX is this actually the API we want? would it be clearer if request/grpc_req + # _wasn't_ populated apart from when we actually had one? + # ALSO what do we want to do about serialization; not a lot of point in logging + # a grpc message [is there a "to dict" or similar?] + common = {"request": "streaming"} + + check_trace(request_trace, common) + + check_trace(response_trace, common) + + assert len(request_stream) == 2 + for index, trace in enumerate(request_stream): + check_trace(trace, {"request": requests[index]}) + + assert len(result_stream) == 0 + + def test_stream_stream(self, client, protobufs, get_log_records, check_trace): + def generate_requests(): + for value in ["A", "B"]: + yield protobufs.ExampleRequest(value=value) + + requests = list(generate_requests()) + responses = list(client.stream_stream(requests)) + assert [(response.message, response.seqno) for response in responses] == [ + ("A", 1), + ("B", 2), + ] + + request_trace, response_trace, request_stream, result_stream = get_log_records() + + common = {"request": "streaming"} + + check_trace(request_trace, common) + + check_trace(response_trace, common) + + assert len(request_stream) == 2 + for index, trace in enumerate(request_stream): + check_trace(trace, {"request": requests[index]}) + + assert len(result_stream) == 2 + for index, trace in enumerate(result_stream): + check_trace(trace, common) + + +class TestGrpcResponseFields: + def test_unary_unary(self, client, protobufs, get_log_records, check_trace): + request = protobufs.ExampleRequest(value="A") + response = client.unary_unary(request) + assert response.message == "A" + + request_trace, response_trace, request_stream, result_stream = get_log_records() + + check_trace( + response_trace, + { + "response": response, + # "response_status": "success", + # "response_time": lambda value: value > 0, + }, + ) + + assert len(result_stream) == 0 + + def test_unary_stream(self, client, protobufs, get_log_records, check_trace): + request = protobufs.ExampleRequest(value="A", response_count=2) + responses = list(client.unary_stream(request)) + assert [(response.message, response.seqno) for response in responses] == [ + ("A", 1), + ("A", 2), + ] + + request_trace, response_trace, request_stream, result_stream = get_log_records() + + check_trace( + response_trace, + { + "response": "streaming", + # "response_status": "success", + # "response_time": lambda value: value > 0, + }, + ) + + assert len(result_stream) == 2 + for index, trace in enumerate(result_stream): + check_trace(trace, {"stage": "response", "response": responses[index]}) + + def test_stream_unary(self, client, protobufs, get_log_records, check_trace): + def generate_requests(): + for value in ["A", "B"]: + yield protobufs.ExampleRequest(value=value) + + requests = list(generate_requests()) + response = client.stream_unary(requests) + assert response.message == "A,B" + + request_trace, response_trace, request_stream, result_stream = get_log_records() + + check_trace( + response_trace, + { + "response": response, + # "response_status": "success", + # "response_time": lambda value: value > 0, + }, + ) + + assert len(result_stream) == 0 + + def test_stream_stream(self, client, protobufs, get_log_records, check_trace): + def generate_requests(): + for value in ["A", "B"]: + yield protobufs.ExampleRequest(value=value) + + requests = list(generate_requests()) + responses = list(client.stream_stream(requests)) + assert [(response.message, response.seqno) for response in responses] == [ + ("A", 1), + ("B", 2), + ] + + request_trace, response_trace, request_stream, result_stream = get_log_records() + + check_trace( + response_trace, + { + "response": "streaming", + # "response_status": "success", # XXX + # "response_time": lambda value: value > 0, + }, + ) + + assert len(result_stream) == 2 + for index, trace in enumerate(result_stream): + check_trace( + trace, + { + "response": responses[index], + # "response_status": "success", + # "response_time": None, # XXX + }, + ) + + +class TestExceptionFields: + def test_error_before_response( + self, client, protobufs, get_log_records, check_trace + ): + request = protobufs.ExampleRequest(value="A") + with pytest.raises(GrpcError) as error: + client.unary_error(request) + assert error.value.status == StatusCode.UNKNOWN + assert error.value.details == "Exception calling application: boom" + + request_trace, response_trace, request_stream, result_stream = get_log_records() + + check_trace( + response_trace, + { + # "response_status": "error", + # "response_time": lambda value: value > 0, + "exception_value": "boom", + "exception_type": "Error", + "exception_path": "example_nameko.Error", + "exception_args": ["boom"], + "exception_traceback": lambda tb: 'raise Error("boom")' in tb, + "exception_expected": True, + }, + ) + + assert len(result_stream) == 0 + + def test_error_while_streaming_response( + self, client, protobufs, get_log_records, check_trace + ): + + # NOTE it's important that the server sleeps between streaming responses + # otherwise it terminates the stream with an error before any parts of the + # response stream are put on the wire + request = protobufs.ExampleRequest(value="A", response_count=10, delay=10) + responses = [] + with pytest.raises(GrpcError) as error: + for response in client.stream_error(request): + responses.append(response) + + assert error.value.status == StatusCode.UNKNOWN + assert error.value.details == "Exception iterating responses: boom" + + request_trace, response_trace, request_stream, result_stream = get_log_records() + + check_trace( + response_trace, + { + # "response_status": "success", # XXX URM + # "response_time": lambda value: value > 0, + }, + ) + + assert len(result_stream) == 10 + + # check first 9 stream parts + for index, trace in enumerate(result_stream[:-1]): + check_trace( + trace, + { + "response": responses[index], + # "response_status": "success", + # "response_time": None, + }, + ) + + # check last stream part + check_trace( + result_stream[-1], + { + # "response_status": "error", + # "response_time": None, + "exception_value": "boom", + "exception_type": "Error", + "exception_path": "example_nameko.Error", + "exception_args": ["boom"], + "exception_traceback": lambda tb: 'raise Error("boom")' in tb, + "exception_expected": True, + }, + ) + + +@pytest.mark.usefixtures("predictable_call_ids") +class TestTracerIntegration: def test_unary_unary(self, client, protobufs, get_log_records, check_trace): request = protobufs.ExampleRequest(value="A") response = client.unary_unary(request) From f6bd6fc5b51183cd5bb26bb8075892259daaff6d Mon Sep 17 00:00:00 2001 From: Matt Bennett Date: Wed, 23 Jan 2019 16:23:46 +0000 Subject: [PATCH 09/20] green: tests passing --- nameko_grpc/tracer/adapter.py | 96 +++++- nameko_grpc/tracer/dependency.py | 7 +- test/test_tracer.py | 534 +++---------------------------- 3 files changed, 137 insertions(+), 500 deletions(-) diff --git a/nameko_grpc/tracer/adapter.py b/nameko_grpc/tracer/adapter.py index ea5da71..809bd83 100644 --- a/nameko_grpc/tracer/adapter.py +++ b/nameko_grpc/tracer/adapter.py @@ -5,26 +5,56 @@ from nameko_grpc.constants import Cardinality +GRPC_STREAM = "GrpcStream" +GRPC_CONTEXT = "GrpcContext" +GRPC_REQUEST = "GrpcRequest" +GRPC_RESPONSE = "GrpcResponse" + + def clean_call_args(extra): # TODO can fix this by overriding get_call_args + + trace_data = extra[constants.TRACE_KEY] + trace_data["call_args"]["context"] = GRPC_CONTEXT + cardinality = get_cardinality(extra) if cardinality in (Cardinality.STREAM_UNARY, Cardinality.STREAM_STREAM): - trace_data = extra[constants.TRACE_KEY] - trace_data["call_args"]["request"] = "streaming" + trace_data["call_args"]["request"] = GRPC_STREAM + else: + trace_data["call_args"]["request"] = GRPC_REQUEST def clean_response(extra): # TODO can fix this by overriding get_result + if not is_response(extra): return + trace_data = extra[constants.TRACE_KEY] + cardinality = get_cardinality(extra) - if cardinality in ( + if not is_stream(extra) and cardinality in ( Cardinality.UNARY_STREAM, Cardinality.STREAM_STREAM, - ) and not is_stream(extra): + ): + trace_data["response"] = GRPC_STREAM + else: + trace_data["response"] = GRPC_RESPONSE + + +def clean_response_state(extra): + # TODO can fix this by overriding get_result (probably) + + if not is_response(extra): + return + + cardinality = get_cardinality(extra) + if not is_stream(extra) and cardinality in ( + Cardinality.UNARY_STREAM, + Cardinality.STREAM_STREAM, + ): trace_data = extra[constants.TRACE_KEY] - trace_data["response"] = "streaming" + trace_data["response_status"] = None def is_request(extra): @@ -39,6 +69,16 @@ def is_stream(extra): return "stream_part" in extra +def has_streaming_request(extra): + cardinality = get_cardinality(extra) + return cardinality in (Cardinality.STREAM_UNARY, Cardinality.STREAM_STREAM) + + +def has_streaming_response(extra): + cardinality = get_cardinality(extra) + return cardinality in (Cardinality.UNARY_STREAM, Cardinality.STREAM_STREAM) + + def get_cardinality(extra): return extra["worker_ctx"].entrypoint.cardinality @@ -62,19 +102,47 @@ def add_stream_age(extra): trace_data["stream_age"] = extra["stream_age"] -def add_request(extra): - if not is_request(extra) or not is_stream(extra): +def add_grpc_request(extra): + trace_data = extra[constants.TRACE_KEY] + + if has_streaming_request(extra): + if is_request(extra) and is_stream(extra): + trace_data["grpc_request"] = extra["request"] + else: + trace_data["grpc_request"] = GRPC_STREAM + else: + request, context = extra["worker_ctx"].args + trace_data["grpc_request"] = request + + +def add_grpc_response(extra): + if not is_response(extra): return trace_data = extra[constants.TRACE_KEY] - trace_data["request"] = extra["request"] + if not has_streaming_response(extra): + trace_data["grpc_response"] = extra["result"] + return -class GrpcEntrypointAdapter(DefaultAdapter): + if is_stream(extra): + trace_data["grpc_response"] = extra["result"] + else: + trace_data["grpc_response"] = GRPC_STREAM - # EXPOSE REQUEST separately (RESPONSE already exists) - # AND GRPC CONTEXT? +def add_grpc_context(extra): + grpc_context = extra["grpc_context"] + + trace_data = extra[constants.TRACE_KEY] + trace_data["grpc_context"] = { + "request_headers": grpc_context.invocation_metadata, + "response_headers": grpc_context.headers, + "response_trailers": grpc_context.trailers, + } + + +class GrpcEntrypointAdapter(DefaultAdapter): def process(self, message, kwargs): message, kwargs = super().process(message, kwargs) @@ -83,10 +151,14 @@ def process(self, message, kwargs): add_cardinality(extra) add_stream_part(extra) add_stream_age(extra) - add_request(extra) + + add_grpc_request(extra) + add_grpc_response(extra) + # add_grpc_context(extra) clean_call_args(extra) clean_response(extra) + clean_response_state(extra) return message, kwargs diff --git a/nameko_grpc/tracer/dependency.py b/nameko_grpc/tracer/dependency.py index b0683db..77c1c7e 100644 --- a/nameko_grpc/tracer/dependency.py +++ b/nameko_grpc/tracer/dependency.py @@ -126,11 +126,13 @@ def log_request_stream(self, worker_ctx, request_stream): def log_result_stream(self, worker_ctx, result_stream): stream_start = datetime.utcnow() + worker_setup_timestamp = self.worker_timestamps[worker_ctx] try: for index, result in enumerate(result_stream, start=1): timestamp = datetime.utcnow() stream_age = (timestamp - stream_start).total_seconds() + response_time = (timestamp - worker_setup_timestamp).total_seconds() extra = { "stage": constants.Stage.response, @@ -138,7 +140,7 @@ def log_result_stream(self, worker_ctx, result_stream): "result": result, "exc_info_": None, "timestamp": timestamp, - "response_time": None, # TODO i think we want this on stream end + "response_time": response_time, "stream_age": stream_age, "stream_part": index, } @@ -157,6 +159,7 @@ def log_result_stream(self, worker_ctx, result_stream): timestamp = datetime.utcnow() stream_age = (timestamp - stream_start).total_seconds() + response_time = (timestamp - worker_setup_timestamp).total_seconds() # NB> this is _idential_ to block above; all the cleverness to extract # rhe traceback is already in the adapter @@ -167,7 +170,7 @@ def log_result_stream(self, worker_ctx, result_stream): "result": None, "exc_info_": sys.exc_info(), "timestamp": timestamp, - "response_time": None, # TODO i think we want this on stream end + "response_time": response_time, "stream_age": stream_age, "stream_part": index + 1, } diff --git a/test/test_tracer.py b/test/test_tracer.py index 5f47dd4..3a65b3f 100644 --- a/test/test_tracer.py +++ b/test/test_tracer.py @@ -8,11 +8,16 @@ import pytest from grpc import StatusCode -from mock import ANY from nameko_tracer.constants import Stage from nameko_grpc.constants import Cardinality from nameko_grpc.exceptions import GrpcError +from nameko_grpc.tracer.adapter import ( + GRPC_CONTEXT, + GRPC_REQUEST, + GRPC_RESPONSE, + GRPC_STREAM, +) @pytest.fixture @@ -368,7 +373,7 @@ def test_unary_unary(self, client, protobufs, get_log_records, check_trace): request_trace, response_trace, request_stream, result_stream = get_log_records() common = { - "call_args": {"context": ANY, "request": request}, + "call_args": {"context": GRPC_CONTEXT, "request": GRPC_REQUEST}, "call_args_redacted": False, } @@ -391,7 +396,7 @@ def test_unary_stream(self, client, protobufs, get_log_records, check_trace): request_trace, response_trace, request_stream, result_stream = get_log_records() common = { - "call_args": {"context": ANY, "request": request}, + "call_args": {"context": GRPC_CONTEXT, "request": GRPC_REQUEST}, "call_args_redacted": False, } @@ -416,9 +421,9 @@ def generate_requests(): request_trace, response_trace, request_stream, result_stream = get_log_records() - # streaming request, so the request object is replaced + # streaming request common = { - "call_args": {"context": ANY, "request": "streaming"}, + "call_args": {"context": GRPC_CONTEXT, "request": GRPC_STREAM}, "call_args_redacted": False, } @@ -446,9 +451,9 @@ def generate_requests(): request_trace, response_trace, request_stream, result_stream = get_log_records() - # streaming request, so the request object is replaced + # streaming request common = { - "call_args": {"context": ANY, "request": "streaming"}, + "call_args": {"context": GRPC_CONTEXT, "request": GRPC_STREAM}, "call_args_redacted": False, } @@ -476,7 +481,7 @@ def test_unary_unary(self, client, protobufs, get_log_records, check_trace): check_trace( response_trace, { - # "response": response, # XXX want this? + "response": GRPC_RESPONSE, "response_status": "success", "response_time": lambda value: value > 0, }, @@ -497,8 +502,8 @@ def test_unary_stream(self, client, protobufs, get_log_records, check_trace): check_trace( response_trace, { - # "response": "streaming", # XXX want this? - "response_status": "success", + "response": GRPC_STREAM, # streaming response + "response_status": None, # still pending "response_time": lambda value: value > 0, }, ) @@ -508,7 +513,7 @@ def test_unary_stream(self, client, protobufs, get_log_records, check_trace): check_trace( trace, { - # "response": responses[index], # XXX want this? + "response": GRPC_RESPONSE, # individual response "response_status": "success", "response_time": lambda value: value > 0, }, @@ -528,7 +533,7 @@ def generate_requests(): check_trace( response_trace, { - # "response": response, # XXX want this? + "response": GRPC_RESPONSE, "response_status": "success", "response_time": lambda value: value > 0, }, @@ -553,8 +558,8 @@ def generate_requests(): check_trace( response_trace, { - # "response": "streaming", - "response_status": "success", + "response": GRPC_STREAM, # streaming response + "response_status": None, # still pending "response_time": lambda value: value > 0, }, ) @@ -564,7 +569,7 @@ def generate_requests(): check_trace( trace, { - # "response": responses[index], + "response": GRPC_RESPONSE, # individual response "response_status": "success", "response_time": lambda value: value > 0, }, @@ -584,7 +589,7 @@ def test_error_before_response( check_trace( response_trace, { - # response: None # XXX + "response": GRPC_RESPONSE, "response_status": "error", "response_time": lambda value: value > 0, }, @@ -613,8 +618,8 @@ def test_error_while_streaming_response( check_trace( response_trace, { - # response: None # XXX - "response_status": "success", # XXX URM + "response": GRPC_STREAM, # streaming response + "response_status": None, # still pending "response_time": lambda value: value > 0, }, ) @@ -626,7 +631,7 @@ def test_error_while_streaming_response( check_trace( trace, { - # "response": responses[index], + "response": GRPC_RESPONSE, # individual response "response_status": "success", "response_time": lambda value: value > 0, }, @@ -636,7 +641,7 @@ def test_error_while_streaming_response( check_trace( result_stream[-1], { - # response: None # XXX + "response": GRPC_RESPONSE, # XXX wrong "response_status": "error", "response_time": lambda value: value > 0, }, @@ -651,7 +656,7 @@ def test_unary_unary(self, client, protobufs, get_log_records, check_trace): request_trace, response_trace, request_stream, result_stream = get_log_records() - common = {"request": request} + common = {"grpc_request": request} check_trace(request_trace, common) @@ -671,7 +676,7 @@ def test_unary_stream(self, client, protobufs, get_log_records, check_trace): request_trace, response_trace, request_stream, result_stream = get_log_records() - common = {"request": request} + common = {"grpc_request": request} check_trace(request_trace, common) @@ -694,11 +699,7 @@ def generate_requests(): request_trace, response_trace, request_stream, result_stream = get_log_records() - # XXX is this actually the API we want? would it be clearer if request/grpc_req - # _wasn't_ populated apart from when we actually had one? - # ALSO what do we want to do about serialization; not a lot of point in logging - # a grpc message [is there a "to dict" or similar?] - common = {"request": "streaming"} + common = {"grpc_request": GRPC_STREAM} check_trace(request_trace, common) @@ -706,7 +707,7 @@ def generate_requests(): assert len(request_stream) == 2 for index, trace in enumerate(request_stream): - check_trace(trace, {"request": requests[index]}) + check_trace(trace, {"grpc_request": requests[index]}) assert len(result_stream) == 0 @@ -724,7 +725,7 @@ def generate_requests(): request_trace, response_trace, request_stream, result_stream = get_log_records() - common = {"request": "streaming"} + common = {"grpc_request": GRPC_STREAM} check_trace(request_trace, common) @@ -732,7 +733,7 @@ def generate_requests(): assert len(request_stream) == 2 for index, trace in enumerate(request_stream): - check_trace(trace, {"request": requests[index]}) + check_trace(trace, {"grpc_request": requests[index]}) assert len(result_stream) == 2 for index, trace in enumerate(result_stream): @@ -747,14 +748,7 @@ def test_unary_unary(self, client, protobufs, get_log_records, check_trace): request_trace, response_trace, request_stream, result_stream = get_log_records() - check_trace( - response_trace, - { - "response": response, - # "response_status": "success", - # "response_time": lambda value: value > 0, - }, - ) + check_trace(response_trace, {"grpc_response": response}) assert len(result_stream) == 0 @@ -768,18 +762,11 @@ def test_unary_stream(self, client, protobufs, get_log_records, check_trace): request_trace, response_trace, request_stream, result_stream = get_log_records() - check_trace( - response_trace, - { - "response": "streaming", - # "response_status": "success", - # "response_time": lambda value: value > 0, - }, - ) + check_trace(response_trace, {"grpc_response": GRPC_STREAM}) assert len(result_stream) == 2 for index, trace in enumerate(result_stream): - check_trace(trace, {"stage": "response", "response": responses[index]}) + check_trace(trace, {"grpc_response": responses[index]}) def test_stream_unary(self, client, protobufs, get_log_records, check_trace): def generate_requests(): @@ -792,14 +779,7 @@ def generate_requests(): request_trace, response_trace, request_stream, result_stream = get_log_records() - check_trace( - response_trace, - { - "response": response, - # "response_status": "success", - # "response_time": lambda value: value > 0, - }, - ) + check_trace(response_trace, {"grpc_response": response}) assert len(result_stream) == 0 @@ -817,25 +797,17 @@ def generate_requests(): request_trace, response_trace, request_stream, result_stream = get_log_records() - check_trace( - response_trace, - { - "response": "streaming", - # "response_status": "success", # XXX - # "response_time": lambda value: value > 0, - }, - ) + check_trace(response_trace, {"grpc_response": GRPC_STREAM}) assert len(result_stream) == 2 for index, trace in enumerate(result_stream): - check_trace( - trace, - { - "response": responses[index], - # "response_status": "success", - # "response_time": None, # XXX - }, - ) + check_trace(trace, {"grpc_response": responses[index]}) + + +# TODO: class TestGrpcContext: +# - invocation metadata +# - response headers +# - response trailers class TestExceptionFields: @@ -853,8 +825,7 @@ def test_error_before_response( check_trace( response_trace, { - # "response_status": "error", - # "response_time": lambda value: value > 0, + "response_status": "error", "exception_value": "boom", "exception_type": "Error", "exception_path": "example_nameko.Error", @@ -884,33 +855,22 @@ def test_error_while_streaming_response( request_trace, response_trace, request_stream, result_stream = get_log_records() - check_trace( - response_trace, - { - # "response_status": "success", # XXX URM - # "response_time": lambda value: value > 0, - }, - ) + check_trace(response_trace, {"response": GRPC_STREAM, "response_status": None}) assert len(result_stream) == 10 # check first 9 stream parts for index, trace in enumerate(result_stream[:-1]): check_trace( - trace, - { - "response": responses[index], - # "response_status": "success", - # "response_time": None, - }, + trace, {"response": GRPC_RESPONSE, "response_status": "success"} ) # check last stream part check_trace( result_stream[-1], { - # "response_status": "error", - # "response_time": None, + "response": GRPC_RESPONSE, + "response_status": "error", "exception_value": "boom", "exception_type": "Error", "exception_path": "example_nameko.Error", @@ -919,401 +879,3 @@ def test_error_while_streaming_response( "exception_expected": True, }, ) - - -@pytest.mark.usefixtures("predictable_call_ids") -class TestTracerIntegration: - def test_unary_unary(self, client, protobufs, get_log_records, check_trace): - request = protobufs.ExampleRequest(value="A") - response = client.unary_unary(request) - assert response.message == "A" - - request_trace, response_trace, request_stream, result_stream = get_log_records() - - common = { - "hostname": socket.gethostname(), - "timestamp": lambda dt: isinstance(dt, datetime), - "call_id": "example.unary_unary.0", - "call_id_stack": ["example.unary_unary.0"], - "entrypoint_name": "unary_unary", - "entrypoint_type": "Grpc", - "service": "example", - "call_args": {"context": ANY, "request": request}, - "call_args_redacted": False, - } - - check_trace( - request_trace, - dict( - common, **{"stage": "request", "cardinality": Cardinality.UNARY_UNARY} - ), - ) - - check_trace( - response_trace, - dict( - common, - **{ - "stage": "response", - "cardinality": Cardinality.UNARY_UNARY, - "response": response, - "response_status": "success", - "response_time": lambda value: value > 0, - } - ), - ) - - assert len(request_stream) == 0 - - assert len(result_stream) == 0 - - def test_unary_stream(self, client, protobufs, get_log_records, check_trace): - request = protobufs.ExampleRequest(value="A", response_count=2) - responses = list(client.unary_stream(request)) - assert [(response.message, response.seqno) for response in responses] == [ - ("A", 1), - ("A", 2), - ] - - request_trace, response_trace, request_stream, result_stream = get_log_records() - - common = { - "hostname": socket.gethostname(), - "timestamp": lambda dt: isinstance(dt, datetime), - "call_id": "example.unary_stream.0", - "call_id_stack": ["example.unary_stream.0"], - "entrypoint_name": "unary_stream", - "entrypoint_type": "Grpc", - "service": "example", - "call_args": {"context": ANY, "request": request}, - "call_args_redacted": False, - } - - check_trace( - request_trace, - dict( - common, **{"stage": "request", "cardinality": Cardinality.UNARY_STREAM} - ), - ) - - check_trace( - response_trace, - dict( - common, - **{ - "stage": "response", - "cardinality": Cardinality.UNARY_STREAM, - "response": "streaming", - "response_status": "success", - "response_time": lambda value: value > 0, - } - ), - ) - - assert len(request_stream) == 0 - - assert len(result_stream) == 2 - for index, trace in enumerate(result_stream): - check_trace( - trace, - dict( - common, - **{ - "stage": "response", - "cardinality": Cardinality.UNARY_STREAM, - "response": responses[index], - "stream_part": index + 1, - "response_time": None, - "stream_age": lambda value: value > 0, - } - ), - ) - - def test_stream_unary(self, client, protobufs, get_log_records, check_trace): - def generate_requests(): - for value in ["A", "B"]: - yield protobufs.ExampleRequest(value=value) - - requests = list(generate_requests()) - response = client.stream_unary(requests) - assert response.message == "A,B" - - request_trace, response_trace, request_stream, result_stream = get_log_records() - - common = { - "hostname": socket.gethostname(), - "timestamp": lambda dt: isinstance(dt, datetime), - "call_id": "example.stream_unary.0", - "call_id_stack": ["example.stream_unary.0"], - "entrypoint_name": "stream_unary", - "entrypoint_type": "Grpc", - "service": "example", - "call_args": {"context": ANY, "request": "streaming"}, - "call_args_redacted": False, - } - - check_trace( - request_trace, - dict( - common, **{"stage": "request", "cardinality": Cardinality.STREAM_UNARY} - ), - ) - - check_trace( - response_trace, - dict( - common, - **{ - "stage": "response", - "cardinality": Cardinality.STREAM_UNARY, - "response": response, - "response_status": "success", - "response_time": lambda value: value > 0, - } - ), - ) - - assert len(request_stream) == 2 - for index, trace in enumerate(request_stream): - check_trace( - trace, - dict( - common, - **{ - "stage": "request", - "cardinality": Cardinality.STREAM_UNARY, - "request": requests[index], - "stream_part": index + 1, - "stream_age": lambda value: value > 0, - } - ), - ) - - assert len(result_stream) == 0 - - def test_stream_stream(self, client, protobufs, get_log_records, check_trace): - def generate_requests(): - for value in ["A", "B"]: - yield protobufs.ExampleRequest(value=value) - - requests = list(generate_requests()) - responses = list(client.stream_stream(requests)) - assert [(response.message, response.seqno) for response in responses] == [ - ("A", 1), - ("B", 2), - ] - - request_trace, response_trace, request_stream, result_stream = get_log_records() - - common = { - "hostname": socket.gethostname(), - "timestamp": lambda dt: isinstance(dt, datetime), - "call_id": "example.stream_stream.0", - "call_id_stack": ["example.stream_stream.0"], - "entrypoint_name": "stream_stream", - "entrypoint_type": "Grpc", - "service": "example", - "call_args": {"context": ANY, "request": "streaming"}, - "call_args_redacted": False, - } - - check_trace( - request_trace, - dict( - common, **{"stage": "request", "cardinality": Cardinality.STREAM_STREAM} - ), - ) - - check_trace( - response_trace, - dict( - common, - **{ - "stage": "response", - "cardinality": Cardinality.STREAM_STREAM, - "response": "streaming", - "response_status": "success", - "response_time": lambda value: value > 0, - } - ), - ) - - assert len(request_stream) == 2 - for index, trace in enumerate(request_stream): - check_trace( - trace, - dict( - common, - **{ - "stage": "request", - "cardinality": Cardinality.STREAM_STREAM, - "request": requests[index], - "stream_part": index + 1, - "stream_age": lambda value: value > 0, - } - ), - ) - - assert len(result_stream) == 2 - for index, trace in enumerate(result_stream): - check_trace( - trace, - dict( - common, - **{ - "stage": "response", - "cardinality": Cardinality.STREAM_STREAM, - "response": responses[index], - "stream_part": index + 1, - "response_time": None, # XXX - "stream_age": lambda value: value > 0, - } - ), - ) - - def test_error_before_response( - self, client, protobufs, get_log_records, check_trace - ): - request = protobufs.ExampleRequest(value="A") - with pytest.raises(GrpcError) as error: - client.unary_error(request) - assert error.value.status == StatusCode.UNKNOWN - assert error.value.details == "Exception calling application: boom" - - request_trace, response_trace, request_stream, result_stream = get_log_records() - - common = { - "hostname": socket.gethostname(), - "timestamp": lambda dt: isinstance(dt, datetime), - "call_id": "example.unary_error.0", - "call_id_stack": ["example.unary_error.0"], - "entrypoint_name": "unary_error", - "entrypoint_type": "Grpc", - "service": "example", - "call_args": {"context": ANY, "request": request}, - "call_args_redacted": False, - } - - check_trace( - request_trace, - dict( - common, **{"stage": "request", "cardinality": Cardinality.UNARY_UNARY} - ), - ) - - check_trace( - response_trace, - dict( - common, - **{ - "stage": "response", - "cardinality": Cardinality.UNARY_UNARY, - "response_status": "error", - "response_time": lambda value: value > 0, - "exception_value": "boom", - "exception_type": "Error", - "exception_path": "example_nameko.Error", - "exception_args": ["boom"], - "exception_traceback": lambda tb: 'raise Error("boom")' in tb, - "exception_expected": True, - } - ), - ) - - assert len(request_stream) == 0 - - assert len(result_stream) == 0 - - def test_error_while_streaming_response( - self, client, protobufs, get_log_records, check_trace - ): - - # NOTE it's important that the server sleeps between streaming responses - # otherwise it terminates the stream with an error before any parts of the - # response stream are put on the wire - request = protobufs.ExampleRequest(value="A", response_count=10, delay=10) - responses = [] - with pytest.raises(GrpcError) as error: - for response in client.stream_error(request): - responses.append(response) - - assert error.value.status == StatusCode.UNKNOWN - assert error.value.details == "Exception iterating responses: boom" - - request_trace, response_trace, request_stream, result_stream = get_log_records() - - common = { - "hostname": socket.gethostname(), - "timestamp": lambda dt: isinstance(dt, datetime), - "call_id": "example.stream_error.0", - "call_id_stack": ["example.stream_error.0"], - "entrypoint_name": "stream_error", - "entrypoint_type": "Grpc", - "service": "example", - "call_args": {"context": ANY, "request": request}, - "call_args_redacted": False, - } - - check_trace( - request_trace, - dict( - common, **{"stage": "request", "cardinality": Cardinality.UNARY_STREAM} - ), - ) - - check_trace( - response_trace, - dict( - common, - **{ - "stage": "response", - "cardinality": Cardinality.UNARY_STREAM, - "response_status": "success", # XXX URM - "response_time": lambda value: value > 0, - } - ), - ) - - assert len(request_stream) == 0 - - assert len(result_stream) == 10 - - # check first 9 stream parts - for index, trace in enumerate(result_stream[:-1]): - check_trace( - trace, - dict( - common, - **{ - "stage": "response", - "cardinality": Cardinality.UNARY_STREAM, - "response": responses[index], - "stream_part": index + 1, - "response_status": "success", - "response_time": None, - "stream_age": lambda value: value > 0, - } - ), - ) - - # check last stream part - check_trace( - result_stream[-1], - dict( - common, - **{ - "stage": "response", - "cardinality": Cardinality.UNARY_STREAM, - "stream_part": 10, - "response_status": "error", - "response_time": None, - "stream_age": lambda value: value > 0, - "exception_value": "boom", - "exception_type": "Error", - "exception_path": "example_nameko.Error", - "exception_args": ["boom"], - "exception_traceback": lambda tb: 'raise Error("boom")' in tb, - "exception_expected": True, - } - ), - ) From 1f7ed3f4e9642ca7fa8df34c405b9b85bbdbd737 Mon Sep 17 00:00:00 2001 From: Matt Bennett Date: Wed, 23 Jan 2019 17:13:26 +0000 Subject: [PATCH 10/20] DRY out log_result_stream --- nameko_grpc/tracer/dependency.py | 50 +++++++++----------------------- 1 file changed, 13 insertions(+), 37 deletions(-) diff --git a/nameko_grpc/tracer/dependency.py b/nameko_grpc/tracer/dependency.py index 77c1c7e..6eb3699 100644 --- a/nameko_grpc/tracer/dependency.py +++ b/nameko_grpc/tracer/dependency.py @@ -128,63 +128,39 @@ def log_result_stream(self, worker_ctx, result_stream): stream_start = datetime.utcnow() worker_setup_timestamp = self.worker_timestamps[worker_ctx] - try: - for index, result in enumerate(result_stream, start=1): - timestamp = datetime.utcnow() - stream_age = (timestamp - stream_start).total_seconds() - response_time = (timestamp - worker_setup_timestamp).total_seconds() - - extra = { - "stage": constants.Stage.response, - "worker_ctx": worker_ctx, - "result": result, - "exc_info_": None, - "timestamp": timestamp, - "response_time": response_time, - "stream_age": stream_age, - "stream_part": index, - } - try: - adapter = self.adapter_factory(worker_ctx) - adapter.info( - "[%s] entrypoint result trace [stream_part %s]", - worker_ctx.call_id, - index, - extra=extra, - ) - except Exception: - logger.warning("Failed to log entrypoint trace", exc_info=True) - - except Exception: - + def log(stream_part, result, exc_info, level): timestamp = datetime.utcnow() stream_age = (timestamp - stream_start).total_seconds() response_time = (timestamp - worker_setup_timestamp).total_seconds() - # NB> this is _idential_ to block above; all the cleverness to extract - # rhe traceback is already in the adapter - # (stream part not identical, actually. nor log level) extra = { "stage": constants.Stage.response, "worker_ctx": worker_ctx, - "result": None, - "exc_info_": sys.exc_info(), + "result": result, + "exc_info_": exc_info, "timestamp": timestamp, "response_time": response_time, "stream_age": stream_age, - "stream_part": index + 1, + "stream_part": stream_part, } try: adapter = self.adapter_factory(worker_ctx) - adapter.warning( + adapter.log( + level, "[%s] entrypoint result trace [stream_part %s]", worker_ctx.call_id, - index, + stream_part, extra=extra, ) except Exception: logger.warning("Failed to log entrypoint trace", exc_info=True) + try: + for index, result in enumerate(result_stream, start=1): + log(index, result, None, logging.INFO) + except Exception: + log(index + 1, None, sys.exc_info(), logging.WARNING) + def worker_setup(self, worker_ctx): """ Log entrypoint call details """ From cdda0fbfe2fb986b4aa86353965f3417d1eae6a5 Mon Sep 17 00:00:00 2001 From: Matt Bennett Date: Wed, 23 Jan 2019 17:52:05 +0000 Subject: [PATCH 11/20] add grpc_context --- nameko_grpc/tracer/adapter.py | 10 ++-- test/test_tracer.py | 95 +++++++++++++++++++++++++++++++++-- 2 files changed, 94 insertions(+), 11 deletions(-) diff --git a/nameko_grpc/tracer/adapter.py b/nameko_grpc/tracer/adapter.py index 809bd83..95cefe0 100644 --- a/nameko_grpc/tracer/adapter.py +++ b/nameko_grpc/tracer/adapter.py @@ -132,14 +132,10 @@ def add_grpc_response(extra): def add_grpc_context(extra): - grpc_context = extra["grpc_context"] + request, context = extra["worker_ctx"].args trace_data = extra[constants.TRACE_KEY] - trace_data["grpc_context"] = { - "request_headers": grpc_context.invocation_metadata, - "response_headers": grpc_context.headers, - "response_trailers": grpc_context.trailers, - } + trace_data["grpc_context"] = context class GrpcEntrypointAdapter(DefaultAdapter): @@ -154,7 +150,7 @@ def process(self, message, kwargs): add_grpc_request(extra) add_grpc_response(extra) - # add_grpc_context(extra) + add_grpc_context(extra) clean_call_args(extra) clean_response(extra) diff --git a/test/test_tracer.py b/test/test_tracer.py index 3a65b3f..aa085d5 100644 --- a/test/test_tracer.py +++ b/test/test_tracer.py @@ -11,6 +11,7 @@ from nameko_tracer.constants import Stage from nameko_grpc.constants import Cardinality +from nameko_grpc.context import GrpcContext from nameko_grpc.exceptions import GrpcError from nameko_grpc.tracer.adapter import ( GRPC_CONTEXT, @@ -804,10 +805,96 @@ def generate_requests(): check_trace(trace, {"grpc_response": responses[index]}) -# TODO: class TestGrpcContext: -# - invocation metadata -# - response headers -# - response trailers +class TestGrpcContextFields: + def test_unary_unary(self, client, protobufs, get_log_records, check_trace): + request = protobufs.ExampleRequest(value="A") + response = client.unary_unary(request) + assert response.message == "A" + + request_trace, response_trace, request_stream, result_stream = get_log_records() + + common = {"grpc_context": lambda value: isinstance(value, GrpcContext)} + + check_trace(request_trace, common) + + check_trace(response_trace, common) + + assert len(request_stream) == 0 + + assert len(result_stream) == 0 + + def test_unary_stream(self, client, protobufs, get_log_records, check_trace): + request = protobufs.ExampleRequest(value="A", response_count=2) + responses = list(client.unary_stream(request)) + assert [(response.message, response.seqno) for response in responses] == [ + ("A", 1), + ("A", 2), + ] + + request_trace, response_trace, request_stream, result_stream = get_log_records() + + common = {"grpc_context": lambda value: isinstance(value, GrpcContext)} + + check_trace(request_trace, common) + + check_trace(response_trace, common) + + assert len(request_stream) == 0 + + assert len(result_stream) == 2 + for index, trace in enumerate(result_stream): + check_trace(trace, common) + + def test_stream_unary(self, client, protobufs, get_log_records, check_trace): + def generate_requests(): + for value in ["A", "B"]: + yield protobufs.ExampleRequest(value=value) + + requests = list(generate_requests()) + response = client.stream_unary(requests) + assert response.message == "A,B" + + request_trace, response_trace, request_stream, result_stream = get_log_records() + + common = {"grpc_context": lambda value: isinstance(value, GrpcContext)} + + check_trace(request_trace, common) + + check_trace(response_trace, common) + + assert len(request_stream) == 2 + for index, trace in enumerate(request_stream): + check_trace(trace, common) + + assert len(result_stream) == 0 + + def test_stream_stream(self, client, protobufs, get_log_records, check_trace): + def generate_requests(): + for value in ["A", "B"]: + yield protobufs.ExampleRequest(value=value) + + requests = list(generate_requests()) + responses = list(client.stream_stream(requests)) + assert [(response.message, response.seqno) for response in responses] == [ + ("A", 1), + ("B", 2), + ] + + request_trace, response_trace, request_stream, result_stream = get_log_records() + + common = {"grpc_context": lambda value: isinstance(value, GrpcContext)} + + check_trace(request_trace, common) + + check_trace(response_trace, common) + + assert len(request_stream) == 2 + for index, trace in enumerate(request_stream): + check_trace(trace, common) + + assert len(result_stream) == 2 + for index, trace in enumerate(result_stream): + check_trace(trace, common) class TestExceptionFields: From b20b8c4f26aeb78f8c9b3282d91fc81cd8fec3dd Mon Sep 17 00:00:00 2001 From: Matt Bennett Date: Wed, 23 Jan 2019 22:34:47 +0000 Subject: [PATCH 12/20] test grpc req/res fields formatted correctly --- nameko_grpc/tracer/formatter.py | 47 ++++++++++++ test/test_tracer.py | 123 +++++++++++++++++++++++--------- 2 files changed, 138 insertions(+), 32 deletions(-) create mode 100644 nameko_grpc/tracer/formatter.py diff --git a/nameko_grpc/tracer/formatter.py b/nameko_grpc/tracer/formatter.py new file mode 100644 index 0000000..023a53e --- /dev/null +++ b/nameko_grpc/tracer/formatter.py @@ -0,0 +1,47 @@ +# -*- coding: utf-8 -*- +import json + +from google.protobuf.json_format import MessageToJson +from nameko_tracer import constants +from nameko_tracer.formatters import JSONFormatter + +from nameko_grpc.context import GrpcContext + + +def default(obj): + try: + return MessageToJson(obj) + except Exception: + pass + + if isinstance(obj, GrpcContext): + return { + "request_metadata": obj.invocation_metadata, + "response_headers": obj.response_stream.headers.for_application, + "response_trailers": obj.response_stream.trailers.for_application, + } + + return str(obj) + + +def serialise(obj): + return json.dumps(obj, default=default) + + +class GrpcFormatter(JSONFormatter): + + extra_serialise_keys = ( + constants.CONTEXT_DATA_KEY, + constants.EXCEPTION_ARGS_KEY, + "grpc_context", + ) + + def format(self, record): + + trace = getattr(record, constants.TRACE_KEY) + + for key in self.extra_serialise_keys: + if key in trace: + trace[key] = serialise(trace[key]) + + return serialise(trace) diff --git a/test/test_tracer.py b/test/test_tracer.py index aa085d5..4e8db6a 100644 --- a/test/test_tracer.py +++ b/test/test_tracer.py @@ -2,11 +2,13 @@ """ Test integration with https://github.com/nameko/nameko-tracer """ +import json import logging import socket from datetime import datetime import pytest +from google.protobuf.json_format import MessageToJson from grpc import StatusCode from nameko_tracer.constants import Stage @@ -19,6 +21,7 @@ GRPC_RESPONSE, GRPC_STREAM, ) +from nameko_grpc.tracer.formatter import GrpcFormatter @pytest.fixture @@ -66,19 +69,15 @@ def extract_trace(record): def extract_records(): trace_records = list(filter(is_trace, caplog.records)) - request_trace = extract_trace( - next(filter(match_all(is_request, is_not_stream), trace_records)) + request_trace = next( + filter(match_all(is_request, is_not_stream), trace_records) ) - response_trace = extract_trace( - next(filter(match_all(is_response, is_not_stream), trace_records)) + response_trace = next( + filter(match_all(is_response, is_not_stream), trace_records) ) - request_stream = list( - map(extract_trace, filter(match_all(is_request, is_stream), trace_records)) - ) - response_stream = list( - map(extract_trace, filter(match_all(is_response, is_stream), trace_records)) - ) + request_stream = list(filter(match_all(is_request, is_stream), trace_records)) + response_stream = list(filter(match_all(is_response, is_stream), trace_records)) return request_trace, response_trace, request_stream, response_stream return extract_records @@ -86,7 +85,25 @@ def extract_records(): @pytest.fixture def check_trace(): - def check(data, requires): + def check(record, requires): + data = record.nameko_trace + for key, value in requires.items(): + if callable(value): + assert value(data[key]) + else: + assert data[key] == value + + return check + + +@pytest.fixture +def check_format(): + + formatter = GrpcFormatter() + + def check(record, requires): + formatted = formatter.format(record) + data = json.loads(formatted) for key, value in requires.items(): if callable(value): assert value(data[key]) @@ -364,8 +381,6 @@ def test_error_while_streaming_response( class TestCallArgsField: - # XXX these are all a bit boring and similar; are they adding value? - # also we should really test call args redaction def test_unary_unary(self, client, protobufs, get_log_records, check_trace): request = protobufs.ExampleRequest(value="A") response = client.unary_unary(request) @@ -650,24 +665,31 @@ def test_error_while_streaming_response( class TestGrpcRequestFields: - def test_unary_unary(self, client, protobufs, get_log_records, check_trace): + def test_unary_unary( + self, client, protobufs, get_log_records, check_trace, check_format + ): request = protobufs.ExampleRequest(value="A") response = client.unary_unary(request) assert response.message == "A" request_trace, response_trace, request_stream, result_stream = get_log_records() - common = {"grpc_request": request} + common_trace = {"grpc_request": request} + common_format = {"grpc_request": MessageToJson(request)} - check_trace(request_trace, common) + check_trace(request_trace, common_trace) + check_format(request_trace, common_format) - check_trace(response_trace, common) + check_trace(response_trace, common_trace) + check_format(response_trace, common_format) assert len(request_stream) == 0 assert len(result_stream) == 0 - def test_unary_stream(self, client, protobufs, get_log_records, check_trace): + def test_unary_stream( + self, client, protobufs, get_log_records, check_trace, check_format + ): request = protobufs.ExampleRequest(value="A", response_count=2) responses = list(client.unary_stream(request)) assert [(response.message, response.seqno) for response in responses] == [ @@ -677,19 +699,25 @@ def test_unary_stream(self, client, protobufs, get_log_records, check_trace): request_trace, response_trace, request_stream, result_stream = get_log_records() - common = {"grpc_request": request} + common_trace = {"grpc_request": request} + common_format = {"grpc_request": MessageToJson(request)} - check_trace(request_trace, common) + check_trace(request_trace, common_trace) + check_format(request_trace, common_format) - check_trace(response_trace, common) + check_trace(response_trace, common_trace) + check_format(response_trace, common_format) assert len(request_stream) == 0 assert len(result_stream) == 2 for index, trace in enumerate(result_stream): - check_trace(trace, common) + check_trace(response_trace, common_trace) + check_format(response_trace, common_format) - def test_stream_unary(self, client, protobufs, get_log_records, check_trace): + def test_stream_unary( + self, client, protobufs, get_log_records, check_trace, check_format + ): def generate_requests(): for value in ["A", "B"]: yield protobufs.ExampleRequest(value=value) @@ -703,16 +731,21 @@ def generate_requests(): common = {"grpc_request": GRPC_STREAM} check_trace(request_trace, common) + check_format(response_trace, common) check_trace(response_trace, common) + check_format(response_trace, common) assert len(request_stream) == 2 for index, trace in enumerate(request_stream): check_trace(trace, {"grpc_request": requests[index]}) + check_format(trace, {"grpc_request": MessageToJson(requests[index])}) assert len(result_stream) == 0 - def test_stream_stream(self, client, protobufs, get_log_records, check_trace): + def test_stream_stream( + self, client, protobufs, get_log_records, check_trace, check_format + ): def generate_requests(): for value in ["A", "B"]: yield protobufs.ExampleRequest(value=value) @@ -729,20 +762,26 @@ def generate_requests(): common = {"grpc_request": GRPC_STREAM} check_trace(request_trace, common) + check_format(request_trace, common) check_trace(response_trace, common) + check_format(response_trace, common) assert len(request_stream) == 2 for index, trace in enumerate(request_stream): check_trace(trace, {"grpc_request": requests[index]}) + check_format(trace, {"grpc_request": MessageToJson(requests[index])}) assert len(result_stream) == 2 for index, trace in enumerate(result_stream): check_trace(trace, common) + check_format(trace, common) class TestGrpcResponseFields: - def test_unary_unary(self, client, protobufs, get_log_records, check_trace): + def test_unary_unary( + self, client, protobufs, get_log_records, check_trace, check_format + ): request = protobufs.ExampleRequest(value="A") response = client.unary_unary(request) assert response.message == "A" @@ -750,10 +789,13 @@ def test_unary_unary(self, client, protobufs, get_log_records, check_trace): request_trace, response_trace, request_stream, result_stream = get_log_records() check_trace(response_trace, {"grpc_response": response}) + check_format(response_trace, {"grpc_response": MessageToJson(response)}) assert len(result_stream) == 0 - def test_unary_stream(self, client, protobufs, get_log_records, check_trace): + def test_unary_stream( + self, client, protobufs, get_log_records, check_trace, check_format + ): request = protobufs.ExampleRequest(value="A", response_count=2) responses = list(client.unary_stream(request)) assert [(response.message, response.seqno) for response in responses] == [ @@ -764,12 +806,16 @@ def test_unary_stream(self, client, protobufs, get_log_records, check_trace): request_trace, response_trace, request_stream, result_stream = get_log_records() check_trace(response_trace, {"grpc_response": GRPC_STREAM}) + check_format(response_trace, {"grpc_response": GRPC_STREAM}) assert len(result_stream) == 2 for index, trace in enumerate(result_stream): check_trace(trace, {"grpc_response": responses[index]}) + check_format(trace, {"grpc_response": MessageToJson(responses[index])}) - def test_stream_unary(self, client, protobufs, get_log_records, check_trace): + def test_stream_unary( + self, client, protobufs, get_log_records, check_trace, check_format + ): def generate_requests(): for value in ["A", "B"]: yield protobufs.ExampleRequest(value=value) @@ -781,10 +827,13 @@ def generate_requests(): request_trace, response_trace, request_stream, result_stream = get_log_records() check_trace(response_trace, {"grpc_response": response}) + check_format(response_trace, {"grpc_response": response}) assert len(result_stream) == 0 - def test_stream_stream(self, client, protobufs, get_log_records, check_trace): + def test_stream_stream( + self, client, protobufs, get_log_records, check_trace, check_format + ): def generate_requests(): for value in ["A", "B"]: yield protobufs.ExampleRequest(value=value) @@ -799,14 +848,18 @@ def generate_requests(): request_trace, response_trace, request_stream, result_stream = get_log_records() check_trace(response_trace, {"grpc_response": GRPC_STREAM}) + check_format(response_trace, {"grpc_response": GRPC_STREAM}) assert len(result_stream) == 2 for index, trace in enumerate(result_stream): check_trace(trace, {"grpc_response": responses[index]}) + check_format(trace, {"grpc_response": MessageToJson(responses[index])}) class TestGrpcContextFields: - def test_unary_unary(self, client, protobufs, get_log_records, check_trace): + def test_unary_unary( + self, client, protobufs, get_log_records, check_trace, check_format + ): request = protobufs.ExampleRequest(value="A") response = client.unary_unary(request) assert response.message == "A" @@ -823,7 +876,9 @@ def test_unary_unary(self, client, protobufs, get_log_records, check_trace): assert len(result_stream) == 0 - def test_unary_stream(self, client, protobufs, get_log_records, check_trace): + def test_unary_stream( + self, client, protobufs, get_log_records, check_trace, check_format + ): request = protobufs.ExampleRequest(value="A", response_count=2) responses = list(client.unary_stream(request)) assert [(response.message, response.seqno) for response in responses] == [ @@ -845,7 +900,9 @@ def test_unary_stream(self, client, protobufs, get_log_records, check_trace): for index, trace in enumerate(result_stream): check_trace(trace, common) - def test_stream_unary(self, client, protobufs, get_log_records, check_trace): + def test_stream_unary( + self, client, protobufs, get_log_records, check_trace, check_format + ): def generate_requests(): for value in ["A", "B"]: yield protobufs.ExampleRequest(value=value) @@ -868,7 +925,9 @@ def generate_requests(): assert len(result_stream) == 0 - def test_stream_stream(self, client, protobufs, get_log_records, check_trace): + def test_stream_stream( + self, client, protobufs, get_log_records, check_trace, check_format + ): def generate_requests(): for value in ["A", "B"]: yield protobufs.ExampleRequest(value=value) From 62a6b7ada707e1391bc4422201e899035e7c6298 Mon Sep 17 00:00:00 2001 From: Matt Bennett Date: Wed, 23 Jan 2019 23:06:20 +0000 Subject: [PATCH 13/20] test formatter formats context correectly --- nameko_grpc/tracer/formatter.py | 2 +- test/test_tracer.py | 92 ++++++++++++++++++++++++++++----- 2 files changed, 81 insertions(+), 13 deletions(-) diff --git a/nameko_grpc/tracer/formatter.py b/nameko_grpc/tracer/formatter.py index 023a53e..3196ba2 100644 --- a/nameko_grpc/tracer/formatter.py +++ b/nameko_grpc/tracer/formatter.py @@ -16,7 +16,7 @@ def default(obj): if isinstance(obj, GrpcContext): return { - "request_metadata": obj.invocation_metadata, + "request_metadata": obj.invocation_metadata(), "response_headers": obj.response_stream.headers.for_application, "response_trailers": obj.response_stream.trailers.for_application, } diff --git a/test/test_tracer.py b/test/test_tracer.py index 4e8db6a..d22c3ca 100644 --- a/test/test_tracer.py +++ b/test/test_tracer.py @@ -857,9 +857,7 @@ def generate_requests(): class TestGrpcContextFields: - def test_unary_unary( - self, client, protobufs, get_log_records, check_trace, check_format - ): + def test_unary_unary(self, client, protobufs, get_log_records, check_trace): request = protobufs.ExampleRequest(value="A") response = client.unary_unary(request) assert response.message == "A" @@ -876,9 +874,7 @@ def test_unary_unary( assert len(result_stream) == 0 - def test_unary_stream( - self, client, protobufs, get_log_records, check_trace, check_format - ): + def test_unary_stream(self, client, protobufs, get_log_records, check_trace): request = protobufs.ExampleRequest(value="A", response_count=2) responses = list(client.unary_stream(request)) assert [(response.message, response.seqno) for response in responses] == [ @@ -900,9 +896,7 @@ def test_unary_stream( for index, trace in enumerate(result_stream): check_trace(trace, common) - def test_stream_unary( - self, client, protobufs, get_log_records, check_trace, check_format - ): + def test_stream_unary(self, client, protobufs, get_log_records, check_trace): def generate_requests(): for value in ["A", "B"]: yield protobufs.ExampleRequest(value=value) @@ -925,9 +919,7 @@ def generate_requests(): assert len(result_stream) == 0 - def test_stream_stream( - self, client, protobufs, get_log_records, check_trace, check_format - ): + def test_stream_stream(self, client, protobufs, get_log_records, check_trace): def generate_requests(): for value in ["A", "B"]: yield protobufs.ExampleRequest(value=value) @@ -955,6 +947,82 @@ def generate_requests(): for index, trace in enumerate(result_stream): check_trace(trace, common) + def test_invocation_metadata( + self, client, protobufs, get_log_records, check_trace, check_format + ): + request = protobufs.ExampleRequest(value="A") + response = client.unary_unary( + request, metadata=[("foo", "foo1"), ("foo", "foo2")] + ) + assert response.message == "A" + + request_trace, response_trace, request_stream, result_stream = get_log_records() + + expected = json.dumps( + { + "request_metadata": [("foo", "foo1"), ("foo", "foo2")], + "response_headers": [], + "response_trailers": [], + } + ) + + check_format(request_trace, {"grpc_context": expected}) + + check_format(response_trace, {"grpc_context": expected}) + + def test_response_headers( + self, client, protobufs, get_log_records, check_trace, check_format + ): + request = protobufs.ExampleRequest(value="A") + response = client.unary_unary( + request, metadata=[("echo-header-foo", "foo1"), ("echo-header-foo", "foo2")] + ) + assert response.message == "A" + + request_trace, response_trace, request_stream, result_stream = get_log_records() + + expected = json.dumps( + { + "request_metadata": [ + ("echo-header-foo", "foo1"), + ("echo-header-foo", "foo2"), + ], + "response_headers": [("foo", "foo1"), ("foo", "foo2")], + "response_trailers": [], + } + ) + + check_format(request_trace, {"grpc_context": expected}) + + check_format(response_trace, {"grpc_context": expected}) + + def test_response_trailers( + self, client, protobufs, get_log_records, check_trace, check_format + ): + request = protobufs.ExampleRequest(value="A") + response = client.unary_unary( + request, + metadata=[("echo-trailer-foo", "foo1"), ("echo-trailer-foo", "foo2")], + ) + assert response.message == "A" + + request_trace, response_trace, request_stream, result_stream = get_log_records() + + expected = json.dumps( + { + "request_metadata": [ + ("echo-trailer-foo", "foo1"), + ("echo-trailer-foo", "foo2"), + ], + "response_headers": [], + "response_trailers": [("foo", "foo1"), ("foo", "foo2")], + } + ) + + check_format(request_trace, {"grpc_context": expected}) + + check_format(response_trace, {"grpc_context": expected}) + class TestExceptionFields: def test_error_before_response( From 86bae2c1ee30775ed73f49489e2074b103c6c86d Mon Sep 17 00:00:00 2001 From: Matt Bennett Date: Thu, 24 Jan 2019 09:46:01 +0000 Subject: [PATCH 14/20] refactor check_trace callback to accept data and key, not just value --- test/test_tracer.py | 69 ++++++++++++++++++++++++++------------------- 1 file changed, 40 insertions(+), 29 deletions(-) diff --git a/test/test_tracer.py b/test/test_tracer.py index d22c3ca..cd2df0e 100644 --- a/test/test_tracer.py +++ b/test/test_tracer.py @@ -89,7 +89,7 @@ def check(record, requires): data = record.nameko_trace for key, value in requires.items(): if callable(value): - assert value(data[key]) + assert value(data, key) else: assert data[key] == value @@ -99,6 +99,7 @@ def check(record, requires): @pytest.fixture def check_format(): + # TODO install formatter when starting service, rather than instaniating manually formatter = GrpcFormatter() def check(record, requires): @@ -131,6 +132,7 @@ class TestEssentialFields: - stage - stream_part (for streams) - stream_age (for streams) + - context_data # TODO: this, plus check format """ @@ -143,7 +145,7 @@ def test_unary_unary(self, client, protobufs, get_log_records, check_trace): common = { "hostname": socket.gethostname(), - "timestamp": lambda dt: isinstance(dt, datetime), + "timestamp": lambda data, key: isinstance(data[key], datetime), "entrypoint_name": "unary_unary", "entrypoint_type": "Grpc", "service": "example", @@ -172,7 +174,7 @@ def test_unary_stream(self, client, protobufs, get_log_records, check_trace): common = { "hostname": socket.gethostname(), - "timestamp": lambda dt: isinstance(dt, datetime), + "timestamp": lambda data, key: isinstance(data[key], datetime), "entrypoint_name": "unary_stream", "entrypoint_type": "Grpc", "service": "example", @@ -196,7 +198,7 @@ def test_unary_stream(self, client, protobufs, get_log_records, check_trace): **{ "stage": "response", "stream_part": index + 1, - "stream_age": lambda value: value > 0, + "stream_age": lambda data, key: data[key] > 0, } ), ) @@ -214,7 +216,7 @@ def generate_requests(): common = { "hostname": socket.gethostname(), - "timestamp": lambda dt: isinstance(dt, datetime), + "timestamp": lambda data, key: isinstance(data[key], datetime), "entrypoint_name": "stream_unary", "entrypoint_type": "Grpc", "service": "example", @@ -236,7 +238,7 @@ def generate_requests(): **{ "stage": "request", "stream_part": index + 1, - "stream_age": lambda value: value > 0, + "stream_age": lambda data, key: data[key] > 0, } ), ) @@ -259,7 +261,7 @@ def generate_requests(): common = { "hostname": socket.gethostname(), - "timestamp": lambda dt: isinstance(dt, datetime), + "timestamp": lambda data, key: isinstance(data[key], datetime), "entrypoint_name": "stream_stream", "entrypoint_type": "Grpc", "service": "example", @@ -281,7 +283,7 @@ def generate_requests(): **{ "stage": "request", "stream_part": index + 1, - "stream_age": lambda value: value > 0, + "stream_age": lambda data, key: data[key] > 0, } ), ) @@ -295,7 +297,7 @@ def generate_requests(): **{ "stage": "response", "stream_part": index + 1, - "stream_age": lambda value: value > 0, + "stream_age": lambda data, key: data[key] > 0, } ), ) @@ -313,7 +315,7 @@ def test_error_before_response( common = { "hostname": socket.gethostname(), - "timestamp": lambda dt: isinstance(dt, datetime), + "timestamp": lambda data, key: isinstance(data[key], datetime), "entrypoint_name": "unary_error", "entrypoint_type": "Grpc", "service": "example", @@ -350,7 +352,7 @@ def test_error_while_streaming_response( common = { "hostname": socket.gethostname(), - "timestamp": lambda dt: isinstance(dt, datetime), + "timestamp": lambda data, key: isinstance(data[key], datetime), "entrypoint_name": "stream_error", "entrypoint_type": "Grpc", "service": "example", @@ -374,7 +376,7 @@ def test_error_while_streaming_response( **{ "stage": "response", "stream_part": index + 1, - "stream_age": lambda value: value > 0, + "stream_age": lambda data, key: data[key] > 0, } ), ) @@ -499,7 +501,7 @@ def test_unary_unary(self, client, protobufs, get_log_records, check_trace): { "response": GRPC_RESPONSE, "response_status": "success", - "response_time": lambda value: value > 0, + "response_time": lambda data, key: data[key] > 0, }, ) @@ -520,7 +522,7 @@ def test_unary_stream(self, client, protobufs, get_log_records, check_trace): { "response": GRPC_STREAM, # streaming response "response_status": None, # still pending - "response_time": lambda value: value > 0, + "response_time": lambda data, key: data[key] > 0, }, ) @@ -531,7 +533,7 @@ def test_unary_stream(self, client, protobufs, get_log_records, check_trace): { "response": GRPC_RESPONSE, # individual response "response_status": "success", - "response_time": lambda value: value > 0, + "response_time": lambda data, key: data[key] > 0, }, ) @@ -551,7 +553,7 @@ def generate_requests(): { "response": GRPC_RESPONSE, "response_status": "success", - "response_time": lambda value: value > 0, + "response_time": lambda data, key: data[key] > 0, }, ) @@ -576,7 +578,7 @@ def generate_requests(): { "response": GRPC_STREAM, # streaming response "response_status": None, # still pending - "response_time": lambda value: value > 0, + "response_time": lambda data, key: data[key] > 0, }, ) @@ -587,7 +589,7 @@ def generate_requests(): { "response": GRPC_RESPONSE, # individual response "response_status": "success", - "response_time": lambda value: value > 0, + "response_time": lambda data, key: data[key] > 0, }, ) @@ -607,7 +609,7 @@ def test_error_before_response( { "response": GRPC_RESPONSE, "response_status": "error", - "response_time": lambda value: value > 0, + "response_time": lambda data, key: data[key] > 0, }, ) @@ -636,7 +638,7 @@ def test_error_while_streaming_response( { "response": GRPC_STREAM, # streaming response "response_status": None, # still pending - "response_time": lambda value: value > 0, + "response_time": lambda data, key: data[key] > 0, }, ) @@ -649,7 +651,7 @@ def test_error_while_streaming_response( { "response": GRPC_RESPONSE, # individual response "response_status": "success", - "response_time": lambda value: value > 0, + "response_time": lambda data, key: data[key] > 0, }, ) @@ -659,7 +661,7 @@ def test_error_while_streaming_response( { "response": GRPC_RESPONSE, # XXX wrong "response_status": "error", - "response_time": lambda value: value > 0, + "response_time": lambda data, key: data[key] > 0, }, ) @@ -827,7 +829,7 @@ def generate_requests(): request_trace, response_trace, request_stream, result_stream = get_log_records() check_trace(response_trace, {"grpc_response": response}) - check_format(response_trace, {"grpc_response": response}) + check_format(response_trace, {"grpc_response": MessageToJson(response)}) assert len(result_stream) == 0 @@ -864,7 +866,7 @@ def test_unary_unary(self, client, protobufs, get_log_records, check_trace): request_trace, response_trace, request_stream, result_stream = get_log_records() - common = {"grpc_context": lambda value: isinstance(value, GrpcContext)} + common = {"grpc_context": lambda data, key: isinstance(data[key], GrpcContext)} check_trace(request_trace, common) @@ -884,7 +886,7 @@ def test_unary_stream(self, client, protobufs, get_log_records, check_trace): request_trace, response_trace, request_stream, result_stream = get_log_records() - common = {"grpc_context": lambda value: isinstance(value, GrpcContext)} + common = {"grpc_context": lambda data, key: isinstance(data[key], GrpcContext)} check_trace(request_trace, common) @@ -907,7 +909,7 @@ def generate_requests(): request_trace, response_trace, request_stream, result_stream = get_log_records() - common = {"grpc_context": lambda value: isinstance(value, GrpcContext)} + common = {"grpc_context": lambda data, key: isinstance(data[key], GrpcContext)} check_trace(request_trace, common) @@ -933,7 +935,7 @@ def generate_requests(): request_trace, response_trace, request_stream, result_stream = get_log_records() - common = {"grpc_context": lambda value: isinstance(value, GrpcContext)} + common = {"grpc_context": lambda data, key: isinstance(data[key], GrpcContext)} check_trace(request_trace, common) @@ -1039,16 +1041,21 @@ def test_error_before_response( check_trace( response_trace, { + "response": GRPC_RESPONSE, # XXX wrong "response_status": "error", "exception_value": "boom", "exception_type": "Error", "exception_path": "example_nameko.Error", "exception_args": ["boom"], - "exception_traceback": lambda tb: 'raise Error("boom")' in tb, + "exception_traceback": ( + lambda data, key: 'raise Error("boom")' in data[key] + ), "exception_expected": True, }, ) + # TODO: check format of exception_args + assert len(result_stream) == 0 def test_error_while_streaming_response( @@ -1089,7 +1096,11 @@ def test_error_while_streaming_response( "exception_type": "Error", "exception_path": "example_nameko.Error", "exception_args": ["boom"], - "exception_traceback": lambda tb: 'raise Error("boom")' in tb, + "exception_traceback": ( + lambda data, key: 'raise Error("boom")' in data[key] + ), "exception_expected": True, }, ) + + # TODO: check format of exception_args From ceefcc28cd8395b8d77d88826c816b52e78f8595 Mon Sep 17 00:00:00 2001 From: Matt Bennett Date: Thu, 24 Jan 2019 10:04:25 +0000 Subject: [PATCH 15/20] test that response field is not present on error traces --- nameko_grpc/tracer/adapter.py | 2 +- test/test_tracer.py | 12 +++--------- 2 files changed, 4 insertions(+), 10 deletions(-) diff --git a/nameko_grpc/tracer/adapter.py b/nameko_grpc/tracer/adapter.py index 95cefe0..c2e06fe 100644 --- a/nameko_grpc/tracer/adapter.py +++ b/nameko_grpc/tracer/adapter.py @@ -27,7 +27,7 @@ def clean_call_args(extra): def clean_response(extra): # TODO can fix this by overriding get_result - if not is_response(extra): + if not is_response(extra) or extra["exc_info_"]: return trace_data = extra[constants.TRACE_KEY] diff --git a/test/test_tracer.py b/test/test_tracer.py index cd2df0e..7ce1ffb 100644 --- a/test/test_tracer.py +++ b/test/test_tracer.py @@ -607,7 +607,7 @@ def test_error_before_response( check_trace( response_trace, { - "response": GRPC_RESPONSE, + "response": lambda data, key: key not in data, "response_status": "error", "response_time": lambda data, key: data[key] > 0, }, @@ -659,7 +659,7 @@ def test_error_while_streaming_response( check_trace( result_stream[-1], { - "response": GRPC_RESPONSE, # XXX wrong + "response": lambda data, key: key not in data, "response_status": "error", "response_time": lambda data, key: data[key] > 0, }, @@ -1041,8 +1041,6 @@ def test_error_before_response( check_trace( response_trace, { - "response": GRPC_RESPONSE, # XXX wrong - "response_status": "error", "exception_value": "boom", "exception_type": "Error", "exception_path": "example_nameko.Error", @@ -1082,16 +1080,12 @@ def test_error_while_streaming_response( # check first 9 stream parts for index, trace in enumerate(result_stream[:-1]): - check_trace( - trace, {"response": GRPC_RESPONSE, "response_status": "success"} - ) + check_trace(trace, {"exception_value": lambda data, key: key not in data}) # check last stream part check_trace( result_stream[-1], { - "response": GRPC_RESPONSE, - "response_status": "error", "exception_value": "boom", "exception_type": "Error", "exception_path": "example_nameko.Error", From 7573bf13574df47b0a8acd70c748af61a52ceafa Mon Sep 17 00:00:00 2001 From: Matt Bennett Date: Fri, 25 Jan 2019 12:30:39 +0000 Subject: [PATCH 16/20] docstrings and cleanup --- nameko_grpc/tracer/adapter.py | 223 ++++++++++++++++++++++++---------- 1 file changed, 158 insertions(+), 65 deletions(-) diff --git a/nameko_grpc/tracer/adapter.py b/nameko_grpc/tracer/adapter.py index c2e06fe..794d886 100644 --- a/nameko_grpc/tracer/adapter.py +++ b/nameko_grpc/tracer/adapter.py @@ -11,102 +11,100 @@ GRPC_RESPONSE = "GrpcResponse" -def clean_call_args(extra): - # TODO can fix this by overriding get_call_args - - trace_data = extra[constants.TRACE_KEY] - trace_data["call_args"]["context"] = GRPC_CONTEXT - - cardinality = get_cardinality(extra) - if cardinality in (Cardinality.STREAM_UNARY, Cardinality.STREAM_STREAM): - trace_data["call_args"]["request"] = GRPC_STREAM - else: - trace_data["call_args"]["request"] = GRPC_REQUEST - - -def clean_response(extra): - # TODO can fix this by overriding get_result - - if not is_response(extra) or extra["exc_info_"]: - return - - trace_data = extra[constants.TRACE_KEY] - - cardinality = get_cardinality(extra) - if not is_stream(extra) and cardinality in ( - Cardinality.UNARY_STREAM, - Cardinality.STREAM_STREAM, - ): - trace_data["response"] = GRPC_STREAM - else: - trace_data["response"] = GRPC_RESPONSE - - -def clean_response_state(extra): - # TODO can fix this by overriding get_result (probably) - - if not is_response(extra): - return - - cardinality = get_cardinality(extra) - if not is_stream(extra) and cardinality in ( - Cardinality.UNARY_STREAM, - Cardinality.STREAM_STREAM, - ): - trace_data = extra[constants.TRACE_KEY] - trace_data["response_status"] = None - - -def is_request(extra): +def is_request_record(extra): + """ Determine whether the record represents a request. + """ return extra["stage"] == constants.Stage.request -def is_response(extra): +def is_response_record(extra): + """ Determine whether the record represents a response. + """ return extra["stage"] == constants.Stage.response -def is_stream(extra): +def is_stream_record(extra): + """ Determine whether the record represents part of a streaming request or response. + """ return "stream_part" in extra -def has_streaming_request(extra): +def is_error_record(extra): + """ Determine whether the record represents an error response + """ + return is_response_record(extra) and extra["exc_info_"] + + +def is_streaming_request_method(extra): + """ Determine whether the record relates to a method that has a streaming request. + + Note that the record may be the request or response trace, or part of one of these. + """ cardinality = get_cardinality(extra) return cardinality in (Cardinality.STREAM_UNARY, Cardinality.STREAM_STREAM) -def has_streaming_response(extra): +def is_streaming_response_method(extra): + """ Determine whether the record relates to a method that has a streaming response. + + Note that the record may be the request or response trace, or part of one of these. + """ cardinality = get_cardinality(extra) return cardinality in (Cardinality.UNARY_STREAM, Cardinality.STREAM_STREAM) def get_cardinality(extra): + """ Extract the cardinality of the method that this record relates to. + """ return extra["worker_ctx"].entrypoint.cardinality def add_cardinality(extra): + """ Add the cardinality of the method to which this record relates to the trace + data. + """ trace_data = extra[constants.TRACE_KEY] trace_data["cardinality"] = get_cardinality(extra) def add_stream_part(extra): - if not is_stream(extra): + """ If this record represents part of a stream, add the stream part identifier to + the trace data. + """ + if not is_stream_record(extra): return trace_data = extra[constants.TRACE_KEY] trace_data["stream_part"] = extra["stream_part"] def add_stream_age(extra): - if not is_stream(extra): + """ If this record represents part of a stream, add the commulative stream age to + the trace data. + """ + if not is_stream_record(extra): return trace_data = extra[constants.TRACE_KEY] trace_data["stream_age"] = extra["stream_age"] +# ^^^^^ done +# vvvvv TODO + + def add_grpc_request(extra): + """ Add the GRPC request message to the trace data for this record, under the + `grpc_request` key. + + All records receive a value for this key. + + If this record relates to a method that has a streaming request and the record + does not represent part that stream (i.e. it's a "top-level" record, or a response), + the value is the GRPC_STREAM placeholder. + """ trace_data = extra[constants.TRACE_KEY] - if has_streaming_request(extra): - if is_request(extra) and is_stream(extra): + if is_streaming_request_method(extra): + if is_request_record(extra) and is_stream_record(extra): trace_data["grpc_request"] = extra["request"] else: trace_data["grpc_request"] = GRPC_STREAM @@ -116,29 +114,123 @@ def add_grpc_request(extra): def add_grpc_response(extra): - if not is_response(extra): - return + """ Add the GRPC response message to the trace data for this record, under the + `grpc_response` key. - trace_data = extra[constants.TRACE_KEY] + Only response records receive a value for this key. - if not has_streaming_response(extra): - trace_data["grpc_response"] = extra["result"] + If this record relates to a method that has a streaming response and the record + does not represent part of that stream (i.e. it's the "top-level" record), + the value is the GRPC_STREAM placeholder. + """ + if not is_response_record(extra): return - if is_stream(extra): - trace_data["grpc_response"] = extra["result"] + trace_data = extra[constants.TRACE_KEY] + + if is_streaming_response_method(extra): + if is_stream_record(extra): + trace_data["grpc_response"] = extra["result"] + else: + trace_data["grpc_response"] = GRPC_STREAM else: - trace_data["grpc_response"] = GRPC_STREAM + trace_data["grpc_response"] = extra["result"] def add_grpc_context(extra): + """ Add the GRPC context object to the trace data for this record, under the + `grpc_context` key. + """ request, context = extra["worker_ctx"].args trace_data = extra[constants.TRACE_KEY] trace_data["grpc_context"] = context +def clean_call_args(extra): + """ Replace the `context` and `request` keys of `call_args` in the trace data for + this record. + + These objects are exposed in the `grpc_context` and `grpc_request` fields + respectively and don't need to be in multiple places. See `add_grpc_context` and + `add_grpc_request` respectively. + + The value for `context` is the GRPC_CONTEXT placeholder. The value for `request` + is the GRPC_REQUEST placeholder, or GRPC_STREAM placeholder if this record relates + to a method that has a streaming request. + """ + + trace_data = extra[constants.TRACE_KEY] + trace_data["call_args"]["context"] = GRPC_CONTEXT + + if is_streaming_request_method(extra): + trace_data["call_args"]["request"] = GRPC_STREAM + else: + trace_data["call_args"]["request"] = GRPC_REQUEST + + +def clean_response(extra): + """ Replaces the `response` key in the trace data for this record. + + Only successful response records have a value for this key. + + The GRPC response message is exposed in the `grpc_response` field and doesn't need + to be in multiple places. See `add_grpc_response`. + + The value for `response` is the GRPC_RESPONSE placeholder, or GRPC_STREAM + placeholder if this record relates to a method that has a streaming response. + + """ + + if not is_response_record(extra) or is_error_record(extra): + return + + trace_data = extra[constants.TRACE_KEY] + + if is_streaming_response_method(extra) and not is_stream_record(extra): + trace_data["response"] = GRPC_STREAM + else: + trace_data["response"] = GRPC_RESPONSE + + +def clean_response_status(extra): + """ Replaces `response_status` keys in the trace data for this record. + + Only response records have a value for this key. + + The value for is unchanged unless this record relates to a method that has a + streaming response and the record does not represent part of that stream + (i.e. it's the "top-level" record), and the record does not already indicate an + error (i.e. the method immediately failed). + + The status of the response is therefore not yet known, so the value is set to + `None`. + + """ + if not is_response_record(extra) or is_error_record(extra): + return + + trace_data = extra[constants.TRACE_KEY] + + if is_streaming_response_method(extra) and not is_stream_record(extra): + # response status still unknown + trace_data["response_status"] = None + + class GrpcEntrypointAdapter(DefaultAdapter): + """ Logging adapter for methods decorated with the Grpc entrypoint. + + Records may represent one of the following: + + * The request to a "unary request" RPC method + * The response from a "unary response" RPC method + * The "top-level" request to a "streaming request" RPC method + * Each "part" of the stream to a "streaming request" RPC method + * The "top-level" response from a "streaming response" RPC method + * Each "part" of the stream from a "streaming response" RPC method + + """ + def process(self, message, kwargs): message, kwargs = super().process(message, kwargs) @@ -154,10 +246,11 @@ def process(self, message, kwargs): clean_call_args(extra) clean_response(extra) - clean_response_state(extra) + clean_response_status(extra) return message, kwargs def get_result(self, result): - # override to avoid serialization? + """ Override get_result to remove serialization. + """ return result From d2ef962a5ac0aa54880040c417193cbd7d5f90a5 Mon Sep 17 00:00:00 2001 From: Matt Bennett Date: Fri, 25 Jan 2019 12:35:28 +0000 Subject: [PATCH 17/20] add tests for grpc_response in error cases --- test/test_tracer.py | 46 +++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 46 insertions(+) diff --git a/test/test_tracer.py b/test/test_tracer.py index 7ce1ffb..bd31354 100644 --- a/test/test_tracer.py +++ b/test/test_tracer.py @@ -857,6 +857,52 @@ def generate_requests(): check_trace(trace, {"grpc_response": responses[index]}) check_format(trace, {"grpc_response": MessageToJson(responses[index])}) + def test_error_before_response( + self, client, protobufs, get_log_records, check_trace + ): + request = protobufs.ExampleRequest(value="A") + with pytest.raises(GrpcError) as error: + client.unary_error(request) + assert error.value.status == StatusCode.UNKNOWN + assert error.value.details == "Exception calling application: boom" + + request_trace, response_trace, request_stream, result_stream = get_log_records() + + check_trace(response_trace, {"grpc_response": None}) + + assert len(result_stream) == 0 + + def test_error_while_streaming_response( + self, client, protobufs, get_log_records, check_trace + ): + + # NOTE it's important that the server sleeps between streaming responses + # otherwise it terminates the stream with an error before any parts of the + # response stream are put on the wire + request = protobufs.ExampleRequest(value="A", response_count=10, delay=10) + responses = [] + with pytest.raises(GrpcError) as error: + for response in client.stream_error(request): + responses.append(response) + + assert error.value.status == StatusCode.UNKNOWN + assert error.value.details == "Exception iterating responses: boom" + + request_trace, response_trace, request_stream, result_stream = get_log_records() + + check_trace( + response_trace, {"grpc_response": GRPC_STREAM} # streaming response + ) + + assert len(result_stream) == 10 + + # check first 9 stream parts + for index, trace in enumerate(result_stream[:-1]): + check_trace(trace, {"grpc_response": responses[index]}) + + # check last stream part + check_trace(result_stream[-1], {"grpc_response": None}) + class TestGrpcContextFields: def test_unary_unary(self, client, protobufs, get_log_records, check_trace): From cc1face73f4efea6527e4e12f0dc3c2299147f16 Mon Sep 17 00:00:00 2001 From: Matt Bennett Date: Mon, 28 Jan 2019 10:50:52 +0000 Subject: [PATCH 18/20] test context_data "essential" key --- nameko_grpc/tracer/adapter.py | 4 --- test/test_tracer.py | 52 ++++++++++++++++++++++++++--------- 2 files changed, 39 insertions(+), 17 deletions(-) diff --git a/nameko_grpc/tracer/adapter.py b/nameko_grpc/tracer/adapter.py index 794d886..2cf22e4 100644 --- a/nameko_grpc/tracer/adapter.py +++ b/nameko_grpc/tracer/adapter.py @@ -87,10 +87,6 @@ def add_stream_age(extra): trace_data["stream_age"] = extra["stream_age"] -# ^^^^^ done -# vvvvv TODO - - def add_grpc_request(extra): """ Add the GRPC request message to the trace data for this record, under the `grpc_request` key. diff --git a/test/test_tracer.py b/test/test_tracer.py index bd31354..751d711 100644 --- a/test/test_tracer.py +++ b/test/test_tracer.py @@ -132,13 +132,15 @@ class TestEssentialFields: - stage - stream_part (for streams) - stream_age (for streams) - - context_data # TODO: this, plus check format + - context_data """ - def test_unary_unary(self, client, protobufs, get_log_records, check_trace): + def test_unary_unary( + self, client, protobufs, get_log_records, check_trace, check_format + ): request = protobufs.ExampleRequest(value="A") - response = client.unary_unary(request) + response = client.unary_unary(request, metadata=[("foo", "bar")]) assert response.message == "A" request_trace, response_trace, request_stream, result_stream = get_log_records() @@ -152,19 +154,24 @@ def test_unary_unary(self, client, protobufs, get_log_records, check_trace): "cardinality": Cardinality.UNARY_UNARY, "call_id": "example.unary_unary.0", "call_id_stack": ["example.unary_unary.0"], + "context_data": {"foo": "bar"}, } check_trace(request_trace, dict(common, **{"stage": "request"})) + check_format(request_trace, {"context_data": '{"foo": "bar"}'}) check_trace(response_trace, dict(common, **{"stage": "response"})) + check_format(response_trace, {"context_data": '{"foo": "bar"}'}) assert len(request_stream) == 0 assert len(result_stream) == 0 - def test_unary_stream(self, client, protobufs, get_log_records, check_trace): + def test_unary_stream( + self, client, protobufs, get_log_records, check_trace, check_format + ): request = protobufs.ExampleRequest(value="A", response_count=2) - responses = list(client.unary_stream(request)) + responses = list(client.unary_stream(request, metadata=[("foo", "bar")])) assert [(response.message, response.seqno) for response in responses] == [ ("A", 1), ("A", 2), @@ -181,11 +188,14 @@ def test_unary_stream(self, client, protobufs, get_log_records, check_trace): "cardinality": Cardinality.UNARY_STREAM, "call_id": "example.unary_stream.0", "call_id_stack": ["example.unary_stream.0"], + "context_data": {"foo": "bar"}, } check_trace(request_trace, dict(common, **{"stage": "request"})) + check_format(request_trace, {"context_data": '{"foo": "bar"}'}) check_trace(response_trace, dict(common, **{"stage": "response"})) + check_format(response_trace, {"context_data": '{"foo": "bar"}'}) assert len(request_stream) == 0 @@ -203,13 +213,15 @@ def test_unary_stream(self, client, protobufs, get_log_records, check_trace): ), ) - def test_stream_unary(self, client, protobufs, get_log_records, check_trace): + def test_stream_unary( + self, client, protobufs, get_log_records, check_trace, check_format + ): def generate_requests(): for value in ["A", "B"]: yield protobufs.ExampleRequest(value=value) requests = list(generate_requests()) - response = client.stream_unary(requests) + response = client.stream_unary(requests, metadata=[("foo", "bar")]) assert response.message == "A,B" request_trace, response_trace, request_stream, result_stream = get_log_records() @@ -223,11 +235,14 @@ def generate_requests(): "cardinality": Cardinality.STREAM_UNARY, "call_id": "example.stream_unary.0", "call_id_stack": ["example.stream_unary.0"], + "context_data": {"foo": "bar"}, } check_trace(request_trace, dict(common, **{"stage": "request"})) + check_format(request_trace, {"context_data": '{"foo": "bar"}'}) check_trace(response_trace, dict(common, **{"stage": "response"})) + check_format(response_trace, {"context_data": '{"foo": "bar"}'}) assert len(request_stream) == 2 for index, trace in enumerate(request_stream): @@ -245,13 +260,15 @@ def generate_requests(): assert len(result_stream) == 0 - def test_stream_stream(self, client, protobufs, get_log_records, check_trace): + def test_stream_stream( + self, client, protobufs, get_log_records, check_trace, check_format + ): def generate_requests(): for value in ["A", "B"]: yield protobufs.ExampleRequest(value=value) requests = list(generate_requests()) - responses = list(client.stream_stream(requests)) + responses = list(client.stream_stream(requests, metadata=[("foo", "bar")])) assert [(response.message, response.seqno) for response in responses] == [ ("A", 1), ("B", 2), @@ -268,11 +285,14 @@ def generate_requests(): "cardinality": Cardinality.STREAM_STREAM, "call_id": "example.stream_stream.0", "call_id_stack": ["example.stream_stream.0"], + "context_data": {"foo": "bar"}, } check_trace(request_trace, dict(common, **{"stage": "request"})) + check_format(request_trace, {"context_data": '{"foo": "bar"}'}) check_trace(response_trace, dict(common, **{"stage": "response"})) + check_format(response_trace, {"context_data": '{"foo": "bar"}'}) assert len(request_stream) == 2 for index, trace in enumerate(request_stream): @@ -303,11 +323,11 @@ def generate_requests(): ) def test_error_before_response( - self, client, protobufs, get_log_records, check_trace + self, client, protobufs, get_log_records, check_trace, check_format ): request = protobufs.ExampleRequest(value="A") with pytest.raises(GrpcError) as error: - client.unary_error(request) + client.unary_error(request, metadata=[("foo", "bar")]) assert error.value.status == StatusCode.UNKNOWN assert error.value.details == "Exception calling application: boom" @@ -322,18 +342,21 @@ def test_error_before_response( "cardinality": Cardinality.UNARY_UNARY, "call_id": "example.unary_error.0", "call_id_stack": ["example.unary_error.0"], + "context_data": {"foo": "bar"}, } check_trace(request_trace, dict(common, **{"stage": "request"})) + check_format(request_trace, {"context_data": '{"foo": "bar"}'}) check_trace(response_trace, dict(common, **{"stage": "response"})) + check_format(response_trace, {"context_data": '{"foo": "bar"}'}) assert len(request_stream) == 0 assert len(result_stream) == 0 def test_error_while_streaming_response( - self, client, protobufs, get_log_records, check_trace + self, client, protobufs, get_log_records, check_trace, check_format ): # NOTE it's important that the server sleeps between streaming responses @@ -342,7 +365,7 @@ def test_error_while_streaming_response( request = protobufs.ExampleRequest(value="A", response_count=10, delay=10) responses = [] with pytest.raises(GrpcError) as error: - for response in client.stream_error(request): + for response in client.stream_error(request, metadata=[("foo", "bar")]): responses.append(response) assert error.value.status == StatusCode.UNKNOWN @@ -359,11 +382,14 @@ def test_error_while_streaming_response( "cardinality": Cardinality.UNARY_STREAM, "call_id": "example.stream_error.0", "call_id_stack": ["example.stream_error.0"], + "context_data": {"foo": "bar"}, } check_trace(request_trace, dict(common, **{"stage": "request"})) + check_format(request_trace, {"context_data": '{"foo": "bar"}'}) check_trace(response_trace, dict(common, **{"stage": "response"})) + check_format(response_trace, {"context_data": '{"foo": "bar"}'}) assert len(request_stream) == 0 From 49a48fba38321248bec3d22da65d852391b1c24e Mon Sep 17 00:00:00 2001 From: Matt Bennett Date: Mon, 28 Jan 2019 11:05:17 +0000 Subject: [PATCH 19/20] test format of exception_args --- test/test_tracer.py | 11 +++++------ 1 file changed, 5 insertions(+), 6 deletions(-) diff --git a/test/test_tracer.py b/test/test_tracer.py index 751d711..d4190d2 100644 --- a/test/test_tracer.py +++ b/test/test_tracer.py @@ -930,7 +930,7 @@ def test_error_while_streaming_response( check_trace(result_stream[-1], {"grpc_response": None}) -class TestGrpcContextFields: +class TestGrpcContextField: def test_unary_unary(self, client, protobufs, get_log_records, check_trace): request = protobufs.ExampleRequest(value="A") response = client.unary_unary(request) @@ -1100,7 +1100,7 @@ def test_response_trailers( class TestExceptionFields: def test_error_before_response( - self, client, protobufs, get_log_records, check_trace + self, client, protobufs, get_log_records, check_trace, check_format ): request = protobufs.ExampleRequest(value="A") with pytest.raises(GrpcError) as error: @@ -1124,12 +1124,12 @@ def test_error_before_response( }, ) - # TODO: check format of exception_args + check_format(response_trace, {"exception_args": json.dumps(["boom"])}) assert len(result_stream) == 0 def test_error_while_streaming_response( - self, client, protobufs, get_log_records, check_trace + self, client, protobufs, get_log_records, check_trace, check_format ): # NOTE it's important that the server sleeps between streaming responses @@ -1168,5 +1168,4 @@ def test_error_while_streaming_response( "exception_expected": True, }, ) - - # TODO: check format of exception_args + check_format(result_stream[-1], {"exception_args": json.dumps(["boom"])}) From 5719bf94151693e9595d1d0a3394d9c3297ee737 Mon Sep 17 00:00:00 2001 From: Matt Bennett Date: Mon, 28 Jan 2019 13:37:37 +0000 Subject: [PATCH 20/20] format cardinality --- nameko_grpc/tracer/formatter.py | 9 ++++- setup.cfg | 2 + test/test_tracer.py | 66 +++++++++++++++++++++++++-------- 3 files changed, 61 insertions(+), 16 deletions(-) diff --git a/nameko_grpc/tracer/formatter.py b/nameko_grpc/tracer/formatter.py index 3196ba2..7ab5110 100644 --- a/nameko_grpc/tracer/formatter.py +++ b/nameko_grpc/tracer/formatter.py @@ -5,6 +5,7 @@ from nameko_tracer import constants from nameko_tracer.formatters import JSONFormatter +from nameko_grpc.constants import Cardinality from nameko_grpc.context import GrpcContext @@ -21,6 +22,12 @@ def default(obj): "response_trailers": obj.response_stream.trailers.for_application, } + try: + if obj in Cardinality: + return obj.name + except TypeError: + pass # https://docs.python.org/3/whatsnew/3.7.html#enum + return str(obj) @@ -28,7 +35,7 @@ def serialise(obj): return json.dumps(obj, default=default) -class GrpcFormatter(JSONFormatter): +class GrpcJsonFormatter(JSONFormatter): extra_serialise_keys = ( constants.CONTEXT_DATA_KEY, diff --git a/setup.cfg b/setup.cfg index 1e02266..a057b40 100644 --- a/setup.cfg +++ b/setup.cfg @@ -26,3 +26,5 @@ skip=.tox,.git [tool:pytest] markers = equivalence: mark a test as an equivalence test. +filterwarnings = + ignore:.*non-Enums in containment checks will raise TypeError.*:DeprecationWarning diff --git a/test/test_tracer.py b/test/test_tracer.py index d4190d2..9158547 100644 --- a/test/test_tracer.py +++ b/test/test_tracer.py @@ -21,7 +21,7 @@ GRPC_RESPONSE, GRPC_STREAM, ) -from nameko_grpc.tracer.formatter import GrpcFormatter +from nameko_grpc.tracer.formatter import GrpcJsonFormatter @pytest.fixture @@ -99,10 +99,10 @@ def check(record, requires): @pytest.fixture def check_format(): - # TODO install formatter when starting service, rather than instaniating manually - formatter = GrpcFormatter() + formatter = GrpcJsonFormatter() def check(record, requires): + formatted = formatter.format(record) data = json.loads(formatted) for key, value in requires.items(): @@ -158,10 +158,16 @@ def test_unary_unary( } check_trace(request_trace, dict(common, **{"stage": "request"})) - check_format(request_trace, {"context_data": '{"foo": "bar"}'}) + check_format( + request_trace, + {"context_data": '{"foo": "bar"}', "cardinality": "UNARY_UNARY"}, + ) check_trace(response_trace, dict(common, **{"stage": "response"})) - check_format(response_trace, {"context_data": '{"foo": "bar"}'}) + check_format( + response_trace, + {"context_data": '{"foo": "bar"}', "cardinality": "UNARY_UNARY"}, + ) assert len(request_stream) == 0 @@ -192,10 +198,16 @@ def test_unary_stream( } check_trace(request_trace, dict(common, **{"stage": "request"})) - check_format(request_trace, {"context_data": '{"foo": "bar"}'}) + check_format( + request_trace, + {"context_data": '{"foo": "bar"}', "cardinality": "UNARY_STREAM"}, + ) check_trace(response_trace, dict(common, **{"stage": "response"})) - check_format(response_trace, {"context_data": '{"foo": "bar"}'}) + check_format( + response_trace, + {"context_data": '{"foo": "bar"}', "cardinality": "UNARY_STREAM"}, + ) assert len(request_stream) == 0 @@ -239,10 +251,16 @@ def generate_requests(): } check_trace(request_trace, dict(common, **{"stage": "request"})) - check_format(request_trace, {"context_data": '{"foo": "bar"}'}) + check_format( + request_trace, + {"context_data": '{"foo": "bar"}', "cardinality": "STREAM_UNARY"}, + ) check_trace(response_trace, dict(common, **{"stage": "response"})) - check_format(response_trace, {"context_data": '{"foo": "bar"}'}) + check_format( + response_trace, + {"context_data": '{"foo": "bar"}', "cardinality": "STREAM_UNARY"}, + ) assert len(request_stream) == 2 for index, trace in enumerate(request_stream): @@ -289,10 +307,16 @@ def generate_requests(): } check_trace(request_trace, dict(common, **{"stage": "request"})) - check_format(request_trace, {"context_data": '{"foo": "bar"}'}) + check_format( + request_trace, + {"context_data": '{"foo": "bar"}', "cardinality": "STREAM_STREAM"}, + ) check_trace(response_trace, dict(common, **{"stage": "response"})) - check_format(response_trace, {"context_data": '{"foo": "bar"}'}) + check_format( + response_trace, + {"context_data": '{"foo": "bar"}', "cardinality": "STREAM_STREAM"}, + ) assert len(request_stream) == 2 for index, trace in enumerate(request_stream): @@ -346,10 +370,16 @@ def test_error_before_response( } check_trace(request_trace, dict(common, **{"stage": "request"})) - check_format(request_trace, {"context_data": '{"foo": "bar"}'}) + check_format( + request_trace, + {"context_data": '{"foo": "bar"}', "cardinality": "UNARY_UNARY"}, + ) check_trace(response_trace, dict(common, **{"stage": "response"})) - check_format(response_trace, {"context_data": '{"foo": "bar"}'}) + check_format( + response_trace, + {"context_data": '{"foo": "bar"}', "cardinality": "UNARY_UNARY"}, + ) assert len(request_stream) == 0 @@ -386,10 +416,16 @@ def test_error_while_streaming_response( } check_trace(request_trace, dict(common, **{"stage": "request"})) - check_format(request_trace, {"context_data": '{"foo": "bar"}'}) + check_format( + request_trace, + {"context_data": '{"foo": "bar"}', "cardinality": "UNARY_STREAM"}, + ) check_trace(response_trace, dict(common, **{"stage": "response"})) - check_format(response_trace, {"context_data": '{"foo": "bar"}'}) + check_format( + response_trace, + {"context_data": '{"foo": "bar"}', "cardinality": "UNARY_STREAM"}, + ) assert len(request_stream) == 0