def test_log_unfinished_spans_disabled(self, log):
# the trace finished status logging is disabled
tracer = DummyTracer()
ctx = Context()
# manually create a root-child trace
root = Span(tracer=tracer, name="root")
child_1 = Span(tracer=tracer,
name="child_1",
trace_id=root.trace_id,
parent_id=root.span_id)
child_2 = Span(tracer=tracer,
name="child_2",
trace_id=root.trace_id,
parent_id=root.span_id)
child_1._parent = root
child_2._parent = root
ctx.add_span(root)
ctx.add_span(child_1)
ctx.add_span(child_2)
# close only the parent
root.finish()
# the logger has never been invoked to print unfinished spans
for call, _ in log.call_args_list:
msg = call[0]
assert "the trace has %d unfinished spans" not in msg
def test_on_finish_multi_callback():
m1 = mock.Mock()
m2 = mock.Mock()
s = Span(None, "test", on_finish=[m1, m2])
s.finish()
m1.assert_called_once_with(s)
m2.assert_called_once_with(s)
def test_finish(self):
# ensure span.finish() marks the end time of the span
s = Span(None, "test.span")
sleep = 0.05
time.sleep(sleep)
s.finish()
assert s.duration >= sleep, "%s < %s" % (s.duration, sleep)
def test_log_unfinished_spans(self, log):
# when the root parent is finished, notify if there are spans still pending
tracer = get_dummy_tracer()
tracer.debug_logging = True
ctx = Context()
# manually create a root-child trace
root = Span(tracer=tracer, name='root')
child_1 = Span(tracer=tracer, name='child_1', trace_id=root.trace_id, parent_id=root.span_id)
child_2 = Span(tracer=tracer, name='child_2', trace_id=root.trace_id, parent_id=root.span_id)
child_1._parent = root
child_2._parent = root
ctx.add_span(root)
ctx.add_span(child_1)
ctx.add_span(child_2)
# close only the parent
root.finish()
ok_(ctx.is_finished() is False)
unfinished_spans_log = log.call_args_list[-3][0][2]
child_1_log = log.call_args_list[-2][0][1]
child_2_log = log.call_args_list[-1][0][1]
eq_(2, unfinished_spans_log)
ok_('name child_1' in child_1_log)
ok_('name child_2' in child_2_log)
ok_('duration 0.000000s' in child_1_log)
ok_('duration 0.000000s' in child_2_log)
def test_finish_set_span_duration(self):
# If set the duration on a span, the span should be recorded with this
# duration
s = Span(tracer=None, name="test.span")
s.duration = 1337.0
s.finish()
assert s.duration == 1337.0
def test_setter_casts_duration_ns_as_int(self):
s = Span(tracer=None, name="test.span")
s.duration = 3.2
s.finish()
assert s.duration == 3.2
assert s.duration_ns == 3200000000
assert isinstance(s.duration_ns, int)
def test_custom_msgpack_encode(encoding):
encoder = MSGPACK_ENCODERS[encoding](1 << 20, 1 << 20)
refencoder = REF_MSGPACK_ENCODERS[encoding]()
trace = gen_trace(nspans=50)
# Note that we assert on the decoded versions because the encoded
# can vary due to non-deterministic map key/value positioning
encoder.put(trace)
assert decode(refencoder.encode_traces([trace])) == decode(encoder.encode())
ref_encoded = refencoder.encode_traces([trace, trace])
encoder.put(trace)
encoder.put(trace)
encoded = encoder.encode()
assert decode(encoded) == decode(ref_encoded)
# Empty trace (not that this should be done in practice)
encoder.put([])
assert decode(refencoder.encode_traces([[]])) == decode(encoder.encode())
s = Span(None, None)
# Need to .finish() to have a duration since the old implementation will not encode
# duration_ns, the new one will encode as None
s.finish()
encoder.put([s])
assert decode(refencoder.encode_traces([[s]])) == decode(encoder.encode())
def test_log_unfinished_spans(self, log):
# when the root parent is finished, notify if there are spans still pending
tracer = get_dummy_tracer()
tracer.debug_logging = True
ctx = Context()
# manually create a root-child trace
root = Span(tracer=tracer, name='root')
child_1 = Span(tracer=tracer,
name='child_1',
trace_id=root.trace_id,
parent_id=root.span_id)
child_2 = Span(tracer=tracer,
name='child_2',
trace_id=root.trace_id,
parent_id=root.span_id)
child_1._parent = root
child_2._parent = root
ctx.add_span(root)
ctx.add_span(child_1)
ctx.add_span(child_2)
# close only the parent
root.finish()
assert ctx.is_finished() is False
unfinished_spans_log = log.call_args_list[-3][0][2]
child_1_log = log.call_args_list[-2][0][1]
child_2_log = log.call_args_list[-1][0][1]
assert 2 == unfinished_spans_log
assert 'name child_1' in child_1_log
assert 'name child_2' in child_2_log
assert 'duration 0.000000s' in child_1_log
assert 'duration 0.000000s' in child_2_log
def test_finish_set_span_duration():
# If set the duration on a span, the span should be recorded with this
# duration
s = Span(tracer=None, name='test.span')
s.duration = 1337.0
s.finish()
assert s.duration == 1337.0
def test_log_unfinished_spans(log, tracer_with_debug_logging):
# when the root parent is finished, notify if there are spans still pending
tracer = tracer_with_debug_logging
ctx = Context()
# manually create a root-child trace
root = Span(tracer=tracer, name="root")
child_1 = Span(tracer=tracer,
name="child_1",
trace_id=root.trace_id,
parent_id=root.span_id)
child_2 = Span(tracer=tracer,
name="child_2",
trace_id=root.trace_id,
parent_id=root.span_id)
child_1._parent = root
child_2._parent = root
ctx.add_span(root)
ctx.add_span(child_1)
ctx.add_span(child_2)
# close only the parent
root.finish()
unfinished_spans_log = log.call_args_list[-3][0][2]
child_1_log = log.call_args_list[-2][0][1]
child_2_log = log.call_args_list[-1][0][1]
assert 2 == unfinished_spans_log
assert "name child_1" in child_1_log
assert "name child_2" in child_2_log
assert "duration 0.000000s" in child_1_log
assert "duration 0.000000s" in child_2_log
def test_log_unfinished_spans_disabled(self, log):
# the trace finished status logging is disabled
tracer = get_dummy_tracer()
tracer.debug_logging = False
ctx = Context()
# manually create a root-child trace
root = Span(tracer=tracer, name='root')
child_1 = Span(tracer=tracer,
name='child_1',
trace_id=root.trace_id,
parent_id=root.span_id)
child_2 = Span(tracer=tracer,
name='child_2',
trace_id=root.trace_id,
parent_id=root.span_id)
child_1._parent = root
child_2._parent = root
ctx.add_span(root)
ctx.add_span(child_1)
ctx.add_span(child_2)
# close only the parent
root.finish()
assert ctx.is_finished() is False
# the logger has never been invoked to print unfinished spans
for call, _ in log.call_args_list:
msg = call[0]
assert 'the trace has %d unfinished spans' not in msg
def test_finish_called_multiple_times():
# we should only record a span the first time finish is called on it
dt = DummyTracer()
assert dt.spans_recorded == 0
s = Span(dt, 'bar')
s.finish()
s.finish()
assert dt.spans_recorded == 1
def test_span_type(self):
s = Span(name="test.span",
service="s",
resource="r",
span_type=SpanTypes.WEB)
s.finish()
assert s.span_type == "web"
def test_finish_called_multiple_times(self):
# we should only record a span the first time finish is called on it
ctx = Context()
s = Span(self.tracer, 'bar', context=ctx)
ctx.add_span(s)
s.finish()
s.finish()
self.assert_span_count(1)
def test_span_boolean_err():
s = Span(tracer=None, name="foo.bar", service="s", resource="r")
s.error = True
s.finish()
d = s.to_dict()
assert d
eq_(d["error"], 1)
eq_(type(d["error"]), int)
def test_span_boolean_err(self):
s = Span(tracer=None, name="foo.bar", service="s", resource="r")
s.error = True
s.finish()
d = s.to_dict()
assert d
assert d["error"] == 1
assert type(d["error"]) == int
def test_duration_zero(self):
s = Span(tracer=None,
name="foo.bar",
service="s",
resource="r",
start=123)
s.finish(finish_time=123)
assert s.duration_ns == 0
assert s.duration == 0
def test_context_sampled(self):
# a context is sampled if the spans are sampled
ctx = Context()
span = Span(tracer=None, name='fake_span')
ctx.add_span(span)
span.finish()
trace, sampled = ctx.get()
assert sampled is True
assert ctx.sampling_priority is None
def test_finish_set_span_duration():
# If set the duration on a span, the span should be recorded with this
# duration
dt = DummyTracer()
assert dt.last_span is None
s = Span(dt, 'foo')
s.duration = 1337.0
s.finish()
assert dt.last_span.duration == 1337.0
def test_span_boolean_err(self):
s = Span(tracer=None, name='foo.bar', service='s', resource='r')
s.error = True
s.finish()
d = s.to_dict()
assert d
assert d['error'] == 1
assert type(d['error']) == int
def test_span_boolean_err():
s = Span(tracer=None, name='foo.bar', service='s', resource='r')
s.error = True
s.finish()
d = s.to_dict()
assert d
eq_(d['error'], 1)
eq_(type(d['error']), int)
def test_finish_called_multiple_times():
# we should only record a span the first time finish is called on it
dt = DummyTracer()
ctx = Context()
s = Span(dt, 'bar', context=ctx)
ctx.add_span(s)
s.finish()
s.finish()
assert dt.spans_recorded == 1
def test_span_boolean_err():
s = Span(tracer=None, name="foo.bar", service="s", resource="r")
s.error = True
s.finish()
d = s.to_dict()
assert d
eq_(d["error"], 1)
eq_(type(d["error"]), int)
def test_finish_called_multiple_times():
# we should only record a span the first time finish is called on it
dt = DummyTracer()
ctx = Context()
s = Span(dt, 'bar', context=ctx)
ctx.add_span(s)
s.finish()
s.finish()
assert dt.spans_recorded == 1
def test_get_report_hostname_enabled(self, get_hostname):
get_hostname.return_value = "test-hostname"
with self.override_global_config(dict(report_hostname=True)):
# Create a context and add a span and finish it
ctx = Context()
span = Span(tracer=None, name="fake_span")
ctx.add_span(span)
span.finish()
assert span.get_tag(HOSTNAME_KEY) == "test-hostname"
def test_span_pprint():
root = Span(None,
"test.span",
service="s",
resource="r",
span_type=SpanTypes.WEB)
root.set_tag("t", "v")
root.set_metric("m", 1.0)
root.finish()
actual = root.pprint()
assert "name='test.span'" in actual
assert "service='s'" in actual
assert "resource='r'" in actual
assert "type='web'" in actual
assert "error=0" in actual
assert ("tags={'t': 'v'}" if six.PY3 else "tags={'t': u'v'}") in actual
assert "metrics={'m': 1.0}" in actual
assert re.search("id=[0-9]+", actual) is not None
assert re.search("trace_id=[0-9]+", actual) is not None
assert "parent_id=None" in actual
assert re.search("duration=[0-9.]+", actual) is not None
assert re.search("start=[0-9.]+", actual) is not None
assert re.search("end=[0-9.]+", actual) is not None
root = Span(None,
"test.span",
service="s",
resource="r",
span_type=SpanTypes.WEB)
actual = root.pprint()
assert "duration=None" in actual
assert "end=None" in actual
root = Span(None,
"test.span",
service="s",
resource="r",
span_type=SpanTypes.WEB)
root.error = 1
actual = root.pprint()
assert "error=1" in actual
root = Span(None,
"test.span",
service="s",
resource="r",
span_type=SpanTypes.WEB)
root.set_tag(u"😌", u"😌")
actual = root.pprint()
assert (u"tags={'😌': '😌'}"
if six.PY3 else "tags={u'\\U0001f60c': u'\\U0001f60c'}") in actual
root = Span(None, "test.span", service=object())
actual = root.pprint()
assert "service=<object object at" in actual
def test_get_trace(self):
# it should return the internal trace structure
# if the context is finished
ctx = Context()
span = Span(tracer=None, name='fake_span')
ctx.add_span(span)
span.finish()
trace, sampled = ctx.get()
assert [span] == trace
assert sampled is True
# the context should be empty
assert 0 == len(ctx._trace)
assert ctx._current_span is None
def test_duration_int(self):
s = Span(tracer=None, name="foo.bar", service="s", resource="r")
s.finish()
assert isinstance(s.duration_ns, int)
assert isinstance(s.duration, float)
s = Span(tracer=None,
name="foo.bar",
service="s",
resource="r",
start=123)
s.finish(finish_time=123.2)
assert s.duration_ns == 200000000
assert s.duration == 0.2
s = Span(tracer=None,
name="foo.bar",
service="s",
resource="r",
start=123.1)
s.finish(finish_time=123.2)
assert s.duration_ns == 100000000
assert s.duration == 0.1
s = Span(tracer=None,
name="foo.bar",
service="s",
resource="r",
start=122)
s.finish(finish_time=123)
assert s.duration_ns == 1000000000
assert s.duration == 1
def test_span_to_dict():
s = Span(tracer=None, name="foo.bar", service="s", resource="r")
s.span_type = "foo"
s.set_tag("a", "1")
s.set_meta("b", "2")
s.finish()
d = s.to_dict()
assert d
eq_(d["span_id"], s.span_id)
eq_(d["trace_id"], s.trace_id)
eq_(d["parent_id"], s.parent_id)
eq_(d["meta"], {"a": "1", "b": "2"})
eq_(d["type"], "foo")
def test_context_priority(self):
# a context is sampled if the spans are sampled
ctx = Context()
for priority in [USER_REJECT, AUTO_REJECT, AUTO_KEEP, USER_KEEP, None, 999]:
ctx.sampling_priority = priority
span = Span(tracer=None, name=('fake_span_%s' % repr(priority)))
ctx.add_span(span)
span.finish()
# It's "normal" to have sampled be true even when priority sampling is
# set to 0 or -1. It would stay false even even with priority set to 2.
# The only criteria to send (or not) the spans to the agent should be
# this "sampled" attribute, as it's tightly related to the trace weight.
assert priority == ctx.sampling_priority
trace, sampled = ctx.get()
assert sampled is True, 'priority has no impact on sampled status'
def test_span_type(self):
s = Span(tracer=None, name="test.span", service="s", resource="r", span_type=SpanTypes.WEB)
s.set_tag("a", "1")
s.set_meta("b", "2")
s.finish()
d = s.to_dict()
assert d
assert d["span_id"] == s.span_id
assert d["trace_id"] == s.trace_id
assert d["parent_id"] == s.parent_id
assert d["meta"] == {"a": "1", "b": "2"}
assert d["type"] == "web"
assert d["error"] == 0
assert type(d["error"]) == int
def test_span_type(self):
s = Span(tracer=None, name='test.span', service='s', resource='r', span_type=SpanTypes.WEB)
s.set_tag('a', '1')
s.set_meta('b', '2')
s.finish()
d = s.to_dict()
assert d
assert d['span_id'] == s.span_id
assert d['trace_id'] == s.trace_id
assert d['parent_id'] == s.parent_id
assert d['meta'] == {'a': '1', 'b': '2'}
assert d['type'] == 'web'
assert d['error'] == 0
assert type(d['error']) == int
def test_get_report_hostname_default(self, get_hostname):
get_hostname.return_value = 'test-hostname'
# Create a context and add a span and finish it
ctx = Context()
span = Span(tracer=None, name='fake_span')
ctx.add_span(span)
span.finish()
# Assert that we have not added the tag to the span yet
assert span.get_tag(HOSTNAME_KEY) is None
# Assert that retrieving the trace does not set the tag
trace, _ = ctx.get()
assert trace[0].get_tag(HOSTNAME_KEY) is None
assert span.get_tag(HOSTNAME_KEY) is None
def test_span_to_dict():
s = Span(tracer=None, name="test.span", service="s", resource="r")
s.span_type = "foo"
s.set_tag("a", "1")
s.set_meta("b", "2")
s.finish()
d = s.to_dict()
assert d
eq_(d["span_id"], s.span_id)
eq_(d["trace_id"], s.trace_id)
eq_(d["parent_id"], s.parent_id)
eq_(d["meta"], {"a": "1", "b": "2"})
eq_(d["type"], "foo")
eq_(d["error"], 0)
eq_(type(d["error"]), int)
def test_finish():
# ensure finish will record a span.
dt = DummyTracer()
assert dt.last_span is None
s = Span(dt, "foo")
assert s.duration is None
sleep = 0.05
with s as s1:
assert s is s1
time.sleep(sleep)
assert s.duration >= sleep, "%s < %s" % (s.duration, sleep)
eq_(s, dt.last_span)
# ensure finish works with no tracer
s2 = Span(tracer=None, name="foo")
s2.finish()
def test_log_unfinished_spans_when_ok(self, log):
# if the unfinished spans logging is enabled but the trace is finished, don't log anything
tracer = get_dummy_tracer()
tracer.debug_logging = True
ctx = Context()
# manually create a root-child trace
root = Span(tracer=tracer, name='root')
child = Span(tracer=tracer, name='child_1', trace_id=root.trace_id, parent_id=root.span_id)
child._parent = root
ctx.add_span(root)
ctx.add_span(child)
# close the trace
child.finish()
root.finish()
# the logger has never been invoked to print unfinished spans
for call, _ in log.call_args_list:
msg = call[0]
ok_('the trace has %d unfinished spans' not in msg)
def test_log_unfinished_spans_disabled(self, log):
# the trace finished status logging is disabled
tracer = get_dummy_tracer()
tracer.debug_logging = False
ctx = Context()
# manually create a root-child trace
root = Span(tracer=tracer, name='root')
child_1 = Span(tracer=tracer, name='child_1', trace_id=root.trace_id, parent_id=root.span_id)
child_2 = Span(tracer=tracer, name='child_2', trace_id=root.trace_id, parent_id=root.span_id)
child_1._parent = root
child_2._parent = root
ctx.add_span(root)
ctx.add_span(child_1)
ctx.add_span(child_2)
# close only the parent
root.finish()
ok_(ctx.is_finished() is False)
# the logger has never been invoked to print unfinished spans
for call, _ in log.call_args_list:
msg = call[0]
ok_('the trace has %d unfinished spans' not in msg)
def test_finish_no_tracer():
# ensure finish works with no tracer without raising exceptions
s = Span(tracer=None, name="test.span")
s.finish()
