def test_batch_sender_flush_calls_transport_handler_with_correct_params( empty_annotations_dict, empty_binary_annotations_dict, fake_endpoint, ): # Tests that the transport handler is called with the value returned # by encoder.encode_queue. transport_handler = mock.Mock() transport_handler.get_max_payload_bytes = lambda: None encoder = MockEncoder(encoded_queue='foobar') sender = logging_helper.ZipkinBatchSender( transport_handler=transport_handler, max_portion_size=None, encoder=encoder, ) with sender: sender.add_span( SpanBuilder( trace_id='000000000000000f', name='span', parent_id='0000000000000001', span_id='0000000000000002', timestamp=26.0, duration=4.0, annotations=empty_annotations_dict, tags=empty_binary_annotations_dict, kind=Kind.CLIENT, local_endpoint=fake_endpoint, service_name='test_service', report_timestamp=False, )) transport_handler.assert_called_once_with('foobar')
def test_batch_sender_defensive_about_transport_handler( empty_annotations_dict, empty_binary_annotations_dict, fake_endpoint, ): """Make sure log_span doesn't try to call the transport handler if it's None.""" encoder = MockEncoder() sender = logging_helper.ZipkinBatchSender( transport_handler=None, max_portion_size=None, encoder=encoder, ) with sender: sender.add_span( SpanBuilder( trace_id='000000000000000f', name='span', parent_id='0000000000000001', span_id='0000000000000002', timestamp=26.0, duration=4.0, annotations=empty_annotations_dict, tags=empty_binary_annotations_dict, kind=Kind.CLIENT, local_endpoint=fake_endpoint, service_name='test_service', report_timestamp=False, )) assert encoder.encode_span.call_count == 1 assert encoder.encode_queue.call_count == 0
def test_batch_sender_add_span( empty_annotations_dict, empty_binary_annotations_dict, fake_endpoint, ): # This test verifies it's possible to add 1 span without throwing errors. # It also checks that exiting the ZipkinBatchSender context manager # triggers a flush of all the already added spans. encoder = MockEncoder(encoded_queue='foobar') sender = logging_helper.ZipkinBatchSender( transport_handler=MockTransportHandler(), max_portion_size=None, encoder=encoder, ) with sender: sender.add_span( SpanBuilder( trace_id='000000000000000f', name='span', parent_id='0000000000000001', span_id='0000000000000002', timestamp=26.0, duration=4.0, annotations=empty_annotations_dict, tags=empty_binary_annotations_dict, kind=Kind.CLIENT, local_endpoint=fake_endpoint, service_name='test_service', )) assert encoder.encode_queue.call_count == 1
def _emit_spans_with_span_sender(self, span_sender): with span_sender: end_timestamp = time.time() # Collect, annotate, and log client spans from the logging handler for span in self.span_storage: span.local_endpoint = copy_endpoint_with_new_service_name( self.endpoint, span.service_name, ) span_sender.add_span(span) annotations = {} if self.add_logging_annotation: annotations[LOGGING_END_KEY] = time.time() span_sender.add_span( SpanBuilder( trace_id=self.zipkin_attrs.trace_id, name=self.span_name, parent_id=self.zipkin_attrs.parent_span_id, span_id=self.zipkin_attrs.span_id, timestamp=self.start_timestamp, duration=end_timestamp - self.start_timestamp, annotations=annotations, tags=self.binary_annotations_dict, kind=Kind.CLIENT if self.client_context else Kind.SERVER, local_endpoint=self.endpoint, service_name=self.service_name, sa_endpoint=self.sa_endpoint, report_timestamp=self.report_root_timestamp, ))
def stop(self, _exc_type=None, _exc_value=None, _exc_traceback=None): """Exit the span context. Zipkin attrs are pushed onto the threadlocal stack regardless of sampling, so they always need to be popped off. The actual logging of spans depends on sampling and that the logging was correctly set up. """ if self.do_pop_attrs: self._context_stack.pop() # If no transport is configured, there's no reason to create a new Span. # This also helps avoiding memory leaks since without a transport nothing # would pull spans out of _span_storage. if not self._span_storage.is_transport_configured(): return # Add the error annotation if an exception occurred if any((_exc_type, _exc_value, _exc_traceback)): error_msg = u'{0}: {1}'.format(_exc_type.__name__, _exc_value) self.update_binary_annotations({ ERROR_KEY: error_msg, }) # Logging context is only initialized for "root" spans of the local # process (i.e. this zipkin_span not inside of any other local # zipkin_spans) if self.logging_context: self.logging_context.stop() self.logging_context = None self._span_storage.set_transport_configured(configured=False) return # If we've gotten here, that means that this span is a child span of # this context's root span (i.e. it's a zipkin_span inside another # zipkin_span). end_timestamp = time.time() # If self.duration is set, it means the user wants to override it if self.duration: duration = self.duration else: duration = end_timestamp - self.start_timestamp self._span_storage.append( SpanBuilder( trace_id=self.zipkin_attrs.trace_id, name=self.span_name, parent_id=self.zipkin_attrs.parent_span_id, span_id=self.zipkin_attrs.span_id, timestamp=self.timestamp if self.timestamp else self.start_timestamp, duration=duration, annotations=self.annotations, tags=self.binary_annotations, kind=self.kind, service_name=self.service_name, sa_endpoint=self.sa_endpoint, ))
def test_zipkin_logging_client_context_emit_spans(add_span_mock, flush_mock, time_mock, fake_endpoint): # This lengthy function tests that the logging context properly # logs root client span trace_id = '000000000000000f' client_span_id = '0000000000000003' attr = ZipkinAttrs( trace_id=trace_id, span_id=client_span_id, parent_span_id=None, flags=None, is_sampled=True, ) span_storage = SpanStorage() transport_handler = mock.Mock() context = logging_helper.ZipkinLoggingContext( zipkin_attrs=attr, endpoint=fake_endpoint, span_name='GET /foo', transport_handler=transport_handler, report_root_timestamp=True, span_storage=span_storage, client_context=True, service_name='test_server', encoding=Encoding.V1_JSON, ) context.start_timestamp = 24 context.response_status_code = 200 context.binary_annotations_dict = {'k': 'v'} time_mock.return_value = 42 context.emit_spans() log_call = add_span_mock.call_args_list[0] assert log_call[0][1].build_v1_span() == SpanBuilder( trace_id=trace_id, name='GET /foo', parent_id=None, span_id=client_span_id, timestamp=24.0, duration=18.0, annotations={ 'cs': 24, 'cr': 42 }, tags={ 'k': 'v' }, kind=Kind.CLIENT, service_name='test_server', local_endpoint=fake_endpoint, ).build_v1_span() assert flush_mock.call_count == 1
def _decode_thrift_span(self, thrift_span): """Decodes a thrift span. :param thrift_span: thrift span :type thrift_span: thrift Span object :returns: span builder representing this span :rtype: SpanBuilder """ parent_id = None local_endpoint = None annotations = {} tags = {} kind = Kind.LOCAL service_name = '' sa_endpoint = None timestamp = None duration = None if thrift_span.parent_id: parent_id = self._convert_unsigned_long_to_lower_hex( thrift_span.parent_id, ) if thrift_span.annotations: annotations, local_endpoint, kind, timestamp, duration = \ self._decode_thrift_annotations(thrift_span.annotations) if thrift_span.binary_annotations: tags, local_endpoint, sa_endpoint = \ self._convert_from_thrift_binary_annotations( thrift_span.binary_annotations, ) trace_id = self._convert_trace_id_to_string( thrift_span.trace_id, thrift_span.trace_id_high, ) return SpanBuilder( trace_id=trace_id, name=thrift_span.name, parent_id=parent_id, span_id=self._convert_unsigned_long_to_lower_hex(thrift_span.id), timestamp=self.seconds(timestamp or thrift_span.timestamp), duration=self.seconds(duration or thrift_span.duration), annotations=annotations, tags=tags, kind=kind, local_endpoint=local_endpoint, service_name=service_name, sa_endpoint=sa_endpoint, report_timestamp=thrift_span.timestamp is not None, )
def test_batch_sender_add_span_too_big( empty_annotations_dict, empty_binary_annotations_dict, fake_endpoint, ): # This time we set max_payload_bytes to 1000, so we have to send more batches. # Each encoded span is 175 bytes, so we can fit 5 of those in 1000 bytes. mock_transport_handler = mock.Mock(spec=MockTransportHandler) mock_transport_handler.get_max_payload_bytes = lambda: 1000 sender = logging_helper.ZipkinBatchSender( mock_transport_handler, 100, get_encoder(Encoding.V1_THRIFT), ) with sender: for _ in range(201): sender.add_span( SpanBuilder( trace_id='000000000000000f', name='span', parent_id='0000000000000001', span_id='0000000000000002', timestamp=26.0, duration=4.0, annotations=empty_annotations_dict, tags=empty_binary_annotations_dict, kind=Kind.CLIENT, local_endpoint=fake_endpoint, service_name='test_service', report_timestamp=False, )) # 5 spans per batch, means we need 201 / 4 = 41 batches to send them all. assert mock_transport_handler.call_count == 41 for i in range(40): # The first 40 batches have 5 spans of 175 bytes + 5 bytes of # list headers = 880 bytes assert len(mock_transport_handler.call_args_list[i][0][0]) == 880 # The last batch has a single remaining span of 175 bytes + 5 bytes of # list headers = 180 bytes assert len(mock_transport_handler.call_args_list[40][0][0]) == 180
def test_batch_sender_add_span_many_times( empty_annotations_dict, empty_binary_annotations_dict, fake_endpoint, ): # We create MAX_PORTION_SIZE * 2 + 1 spans, so we should trigger flush 3 # times, once every MAX_PORTION_SIZE spans. encoder = MockEncoder() sender = logging_helper.ZipkinBatchSender( transport_handler=MockTransportHandler(), max_portion_size=None, encoder=encoder, ) max_portion_size = logging_helper.ZipkinBatchSender.MAX_PORTION_SIZE with sender: for _ in range(max_portion_size * 2 + 1): sender.add_span( SpanBuilder( trace_id='000000000000000f', name='span', parent_id='0000000000000001', span_id='0000000000000002', timestamp=26.0, duration=4.0, annotations=empty_annotations_dict, tags=empty_binary_annotations_dict, kind=Kind.CLIENT, local_endpoint=fake_endpoint, service_name='test_service', report_timestamp=False, )) assert encoder.encode_queue.call_count == 3 assert len( encoder.encode_queue.call_args_list[0][0][0]) == max_portion_size assert len( encoder.encode_queue.call_args_list[1][0][0]) == max_portion_size assert len(encoder.encode_queue.call_args_list[2][0][0]) == 1
def test_zipkin_logging_server_context_emit_spans(add_span_mock, flush_mock, time_mock, fake_endpoint): # This lengthy function tests that the logging context properly # logs both client and server spans. trace_id = '000000000000000f' parent_span_id = '0000000000000001' server_span_id = '0000000000000002' client_span_id = '0000000000000003' client_span_name = 'breadcrumbs' client_svc_name = 'svc' attr = ZipkinAttrs( trace_id=trace_id, span_id=server_span_id, parent_span_id=parent_span_id, flags=None, is_sampled=True, ) span_storage = SpanStorage() client_span = SpanBuilder( trace_id=trace_id, name=client_span_name, parent_id=server_span_id, span_id=client_span_id, timestamp=26.0, duration=4.0, annotations={ 'ann2': 2, 'cs': 26, 'cr': 30 }, tags={'bann2': 'yiss'}, kind=Kind.CLIENT, service_name=client_svc_name, ) span_storage.append(client_span) transport_handler = mock.Mock() context = logging_helper.ZipkinLoggingContext( zipkin_attrs=attr, endpoint=fake_endpoint, span_name='GET /foo', transport_handler=transport_handler, report_root_timestamp=True, span_storage=span_storage, service_name='test_server', encoding=Encoding.V1_JSON, ) context.start_timestamp = 24 context.response_status_code = 200 context.binary_annotations_dict = {'k': 'v'} time_mock.return_value = 42 context.emit_spans() client_log_call, server_log_call = add_span_mock.call_args_list assert server_log_call[0][1].build_v1_span() == SpanBuilder( trace_id=trace_id, name='GET /foo', parent_id=parent_span_id, span_id=server_span_id, timestamp=24.0, duration=18.0, annotations={ 'sr': 24, 'ss': 42 }, tags={ 'k': 'v' }, kind=Kind.SERVER, service_name=client_svc_name, local_endpoint=fake_endpoint, ).build_v1_span() assert client_log_call[0][1] == client_span assert flush_mock.call_count == 1