1# -*- coding: utf-8 -*- 2import re 3import sys 4import time 5from unittest.case import SkipTest 6 7import mock 8import pytest 9import six 10 11from ddtrace.constants import ANALYTICS_SAMPLE_RATE_KEY 12from ddtrace.constants import ENV_KEY 13from ddtrace.constants import ERROR_MSG 14from ddtrace.constants import ERROR_STACK 15from ddtrace.constants import ERROR_TYPE 16from ddtrace.constants import SERVICE_VERSION_KEY 17from ddtrace.constants import SPAN_MEASURED_KEY 18from ddtrace.constants import VERSION_KEY 19from ddtrace.ext import SpanTypes 20from ddtrace.span import Span 21from tests.utils import TracerTestCase 22from tests.utils import assert_is_measured 23from tests.utils import assert_is_not_measured 24from tests.utils import override_global_config 25 26 27class SpanTestCase(TracerTestCase): 28 def test_ids(self): 29 s = Span(tracer=None, name="span.test") 30 assert s.trace_id 31 assert s.span_id 32 assert not s.parent_id 33 34 s2 = Span(tracer=None, name="t", trace_id=1, span_id=2, parent_id=1) 35 assert s2.trace_id == 1 36 assert s2.span_id == 2 37 assert s2.parent_id == 1 38 39 def test_tags(self): 40 s = Span(tracer=None, name="test.span") 41 s.set_tag("a", "a") 42 s.set_tag("b", 1) 43 s.set_tag("c", "1") 44 d = s.to_dict() 45 assert d["meta"] == dict(a="a", c="1") 46 assert d["metrics"] == dict(b=1) 47 48 def test_numeric_tags(self): 49 s = Span(tracer=None, name="test.span") 50 s.set_tag("negative", -1) 51 s.set_tag("zero", 0) 52 s.set_tag("positive", 1) 53 s.set_tag("large_int", 2 ** 53) 54 s.set_tag("really_large_int", (2 ** 53) + 1) 55 s.set_tag("large_negative_int", -(2 ** 53)) 56 s.set_tag("really_large_negative_int", -((2 ** 53) + 1)) 57 s.set_tag("float", 12.3456789) 58 s.set_tag("negative_float", -12.3456789) 59 s.set_tag("large_float", 2.0 ** 53) 60 s.set_tag("really_large_float", (2.0 ** 53) + 1) 61 62 d = s.to_dict() 63 assert d["meta"] == dict( 64 really_large_int=str(((2 ** 53) + 1)), 65 really_large_negative_int=str(-((2 ** 53) + 1)), 66 ) 67 assert d["metrics"] == { 68 "negative": -1, 69 "zero": 0, 70 "positive": 1, 71 "large_int": 2 ** 53, 72 "large_negative_int": -(2 ** 53), 73 "float": 12.3456789, 74 "negative_float": -12.3456789, 75 "large_float": 2.0 ** 53, 76 "really_large_float": (2.0 ** 53) + 1, 77 } 78 79 def test_set_tag_bool(self): 80 s = Span(tracer=None, name="test.span") 81 s.set_tag("true", True) 82 s.set_tag("false", False) 83 84 d = s.to_dict() 85 assert d["meta"] == dict(true="True", false="False") 86 assert "metrics" not in d 87 88 def test_set_tag_metric(self): 89 s = Span(tracer=None, name="test.span") 90 91 s.set_tag("test", "value") 92 assert s.meta == dict(test="value") 93 assert s.metrics == dict() 94 95 s.set_tag("test", 1) 96 assert s.meta == dict() 97 assert s.metrics == dict(test=1) 98 99 def test_set_valid_metrics(self): 100 s = Span(tracer=None, name="test.span") 101 s.set_metric("a", 0) 102 s.set_metric("b", -12) 103 s.set_metric("c", 12.134) 104 s.set_metric("d", 1231543543265475686787869123) 105 s.set_metric("e", "12.34") 106 d = s.to_dict() 107 expected = { 108 "a": 0, 109 "b": -12, 110 "c": 12.134, 111 "d": 1231543543265475686787869123, 112 "e": 12.34, 113 } 114 assert d["metrics"] == expected 115 116 def test_set_invalid_metric(self): 117 s = Span(tracer=None, name="test.span") 118 119 invalid_metrics = [None, {}, [], s, "quarante-douze", float("nan"), float("inf"), 1j] 120 121 for i, m in enumerate(invalid_metrics): 122 k = str(i) 123 s.set_metric(k, m) 124 assert s.get_metric(k) is None 125 126 def test_set_numpy_metric(self): 127 try: 128 import numpy as np 129 except ImportError: 130 raise SkipTest("numpy not installed") 131 s = Span(tracer=None, name="test.span") 132 s.set_metric("a", np.int64(1)) 133 assert s.get_metric("a") == 1 134 assert type(s.get_metric("a")) == float 135 136 def test_tags_not_string(self): 137 # ensure we can cast as strings 138 class Foo(object): 139 def __repr__(self): 140 1 / 0 141 142 s = Span(tracer=None, name="test.span") 143 s.set_tag("a", Foo()) 144 145 def test_finish(self): 146 # ensure span.finish() marks the end time of the span 147 s = Span(None, "test.span") 148 sleep = 0.05 149 time.sleep(sleep) 150 s.finish() 151 assert s.duration >= sleep, "%s < %s" % (s.duration, sleep) 152 153 def test_finish_no_tracer(self): 154 # ensure finish works with no tracer without raising exceptions 155 s = Span(tracer=None, name="test.span") 156 s.finish() 157 158 def test_finish_called_multiple_times(self): 159 # we should only record a span the first time finish is called on it 160 s = Span(self.tracer, "bar") 161 s.finish() 162 s.finish() 163 164 def test_finish_set_span_duration(self): 165 # If set the duration on a span, the span should be recorded with this 166 # duration 167 s = Span(tracer=None, name="test.span") 168 s.duration = 1337.0 169 s.finish() 170 assert s.duration == 1337.0 171 172 def test_setter_casts_duration_ns_as_int(self): 173 s = Span(tracer=None, name="test.span") 174 s.duration = 3.2 175 s.finish() 176 assert s.duration == 3.2 177 assert s.duration_ns == 3200000000 178 assert isinstance(s.duration_ns, int) 179 180 def test_get_span_returns_none_by_default(self): 181 s = Span(tracer=None, name="test.span") 182 assert s.duration is None 183 184 def test_traceback_with_error(self): 185 s = Span(None, "test.span") 186 try: 187 1 / 0 188 except ZeroDivisionError: 189 s.set_traceback() 190 else: 191 assert 0, "should have failed" 192 193 assert s.error 194 assert "by zero" in s.get_tag(ERROR_MSG) 195 assert "ZeroDivisionError" in s.get_tag(ERROR_TYPE) 196 197 def test_traceback_without_error(self): 198 s = Span(None, "test.span") 199 s.set_traceback() 200 assert not s.error 201 assert not s.get_tag(ERROR_MSG) 202 assert not s.get_tag(ERROR_TYPE) 203 assert "in test_traceback_without_error" in s.get_tag(ERROR_STACK) 204 205 def test_ctx_mgr(self): 206 s = Span(self.tracer, "bar") 207 assert not s.duration 208 assert not s.error 209 210 e = Exception("boo") 211 try: 212 with s: 213 time.sleep(0.01) 214 raise e 215 except Exception as out: 216 assert out == e 217 assert s.duration > 0, s.duration 218 assert s.error 219 assert s.get_tag(ERROR_MSG) == "boo" 220 assert "Exception" in s.get_tag(ERROR_TYPE) 221 assert s.get_tag(ERROR_STACK) 222 223 else: 224 assert 0, "should have failed" 225 226 def test_span_type(self): 227 s = Span(tracer=None, name="test.span", service="s", resource="r", span_type=SpanTypes.WEB) 228 s.set_tag("a", "1") 229 s.set_meta("b", "2") 230 s.finish() 231 232 d = s.to_dict() 233 assert d 234 assert d["span_id"] == s.span_id 235 assert d["trace_id"] == s.trace_id 236 assert d["parent_id"] == s.parent_id 237 assert d["meta"] == {"a": "1", "b": "2"} 238 assert d["type"] == "web" 239 assert d["error"] == 0 240 assert type(d["error"]) == int 241 242 def test_span_to_dict(self): 243 s = Span(tracer=None, name="test.span", service="s", resource="r") 244 s.span_type = "foo" 245 s.set_tag("a", "1") 246 s.set_meta("b", "2") 247 s.finish() 248 249 d = s.to_dict() 250 assert d 251 assert d["span_id"] == s.span_id 252 assert d["trace_id"] == s.trace_id 253 assert d["parent_id"] == s.parent_id 254 assert d["meta"] == {"a": "1", "b": "2"} 255 assert d["type"] == "foo" 256 assert d["error"] == 0 257 assert type(d["error"]) == int 258 259 def test_span_to_dict_sub(self): 260 parent = Span(tracer=None, name="test.span", service="s", resource="r") 261 s = Span(tracer=None, name="test.span", service="s", resource="r") 262 s._parent = parent 263 s.span_type = "foo" 264 s.set_tag("a", "1") 265 s.set_meta("b", "2") 266 s.finish() 267 268 d = s.to_dict() 269 assert d 270 assert d["span_id"] == s.span_id 271 assert d["trace_id"] == s.trace_id 272 assert d["parent_id"] == s.parent_id 273 assert d["meta"] == {"a": "1", "b": "2"} 274 assert d["type"] == "foo" 275 assert d["error"] == 0 276 assert type(d["error"]) == int 277 278 def test_span_boolean_err(self): 279 s = Span(tracer=None, name="foo.bar", service="s", resource="r") 280 s.error = True 281 s.finish() 282 283 d = s.to_dict() 284 assert d 285 assert d["error"] == 1 286 assert type(d["error"]) == int 287 288 @mock.patch("ddtrace.span.log") 289 def test_numeric_tags_none(self, span_log): 290 s = Span(tracer=None, name="test.span") 291 s.set_tag(ANALYTICS_SAMPLE_RATE_KEY, None) 292 d = s.to_dict() 293 assert d 294 assert "metrics" not in d 295 296 # Ensure we log a debug message 297 span_log.debug.assert_called_once_with( 298 "ignoring not number metric %s:%s", 299 ANALYTICS_SAMPLE_RATE_KEY, 300 None, 301 ) 302 303 def test_numeric_tags_true(self): 304 s = Span(tracer=None, name="test.span") 305 s.set_tag(ANALYTICS_SAMPLE_RATE_KEY, True) 306 d = s.to_dict() 307 assert d 308 expected = {ANALYTICS_SAMPLE_RATE_KEY: 1.0} 309 assert d["metrics"] == expected 310 311 def test_numeric_tags_value(self): 312 s = Span(tracer=None, name="test.span") 313 s.set_tag(ANALYTICS_SAMPLE_RATE_KEY, 0.5) 314 d = s.to_dict() 315 assert d 316 expected = {ANALYTICS_SAMPLE_RATE_KEY: 0.5} 317 assert d["metrics"] == expected 318 319 def test_numeric_tags_bad_value(self): 320 s = Span(tracer=None, name="test.span") 321 s.set_tag(ANALYTICS_SAMPLE_RATE_KEY, "Hello") 322 d = s.to_dict() 323 assert d 324 assert "metrics" not in d 325 326 def test_set_tag_none(self): 327 s = Span(tracer=None, name="root.span", service="s", resource="r") 328 assert s.meta == dict() 329 330 s.set_tag("custom.key", "100") 331 332 assert s.meta == {"custom.key": "100"} 333 334 s.set_tag("custom.key", None) 335 336 assert s.meta == {"custom.key": "None"} 337 338 def test_duration_zero(self): 339 s = Span(tracer=None, name="foo.bar", service="s", resource="r", start=123) 340 s.finish(finish_time=123) 341 assert s.duration_ns == 0 342 assert s.duration == 0 343 344 def test_start_int(self): 345 s = Span(tracer=None, name="foo.bar", service="s", resource="r", start=123) 346 assert s.start == 123 347 assert s.start_ns == 123000000000 348 349 s = Span(tracer=None, name="foo.bar", service="s", resource="r", start=123.123) 350 assert s.start == 123.123 351 assert s.start_ns == 123123000000 352 353 s = Span(tracer=None, name="foo.bar", service="s", resource="r", start=123.123) 354 s.start = 234567890.0 355 assert s.start == 234567890 356 assert s.start_ns == 234567890000000000 357 358 def test_duration_int(self): 359 s = Span(tracer=None, name="foo.bar", service="s", resource="r") 360 s.finish() 361 assert isinstance(s.duration_ns, int) 362 assert isinstance(s.duration, float) 363 364 s = Span(tracer=None, name="foo.bar", service="s", resource="r", start=123) 365 s.finish(finish_time=123.2) 366 assert s.duration_ns == 200000000 367 assert s.duration == 0.2 368 369 s = Span(tracer=None, name="foo.bar", service="s", resource="r", start=123.1) 370 s.finish(finish_time=123.2) 371 assert s.duration_ns == 100000000 372 assert s.duration == 0.1 373 374 s = Span(tracer=None, name="foo.bar", service="s", resource="r", start=122) 375 s.finish(finish_time=123) 376 assert s.duration_ns == 1000000000 377 assert s.duration == 1 378 379 def test_set_tag_version(self): 380 s = Span(tracer=None, name="test.span") 381 s.set_tag(VERSION_KEY, "1.2.3") 382 assert s.get_tag(VERSION_KEY) == "1.2.3" 383 assert s.get_tag(SERVICE_VERSION_KEY) is None 384 385 s.set_tag(SERVICE_VERSION_KEY, "service.version") 386 assert s.get_tag(VERSION_KEY) == "service.version" 387 assert s.get_tag(SERVICE_VERSION_KEY) == "service.version" 388 389 def test_set_tag_env(self): 390 s = Span(tracer=None, name="test.span") 391 s.set_tag(ENV_KEY, "prod") 392 assert s.get_tag(ENV_KEY) == "prod" 393 394 395@pytest.mark.parametrize( 396 "value,assertion", 397 [ 398 (None, assert_is_measured), 399 (1, assert_is_measured), 400 (1.0, assert_is_measured), 401 (-1, assert_is_measured), 402 (True, assert_is_measured), 403 ("true", assert_is_measured), 404 # DEV: Ends up being measured because we do `bool("false")` which is `True` 405 ("false", assert_is_measured), 406 (0, assert_is_not_measured), 407 (0.0, assert_is_not_measured), 408 (False, assert_is_not_measured), 409 ], 410) 411def test_set_tag_measured(value, assertion): 412 s = Span(tracer=None, name="test.span") 413 s.set_tag(SPAN_MEASURED_KEY, value) 414 assertion(s) 415 416 417def test_set_tag_measured_not_set(): 418 # Span is not measured by default 419 s = Span(tracer=None, name="test.span") 420 assert_is_not_measured(s) 421 422 423def test_set_tag_measured_no_value(): 424 s = Span(tracer=None, name="test.span") 425 s.set_tag(SPAN_MEASURED_KEY) 426 assert_is_measured(s) 427 428 429def test_set_tag_measured_change_value(): 430 s = Span(tracer=None, name="test.span") 431 s.set_tag(SPAN_MEASURED_KEY, True) 432 assert_is_measured(s) 433 434 s.set_tag(SPAN_MEASURED_KEY, False) 435 assert_is_not_measured(s) 436 437 s.set_tag(SPAN_MEASURED_KEY) 438 assert_is_measured(s) 439 440 441@mock.patch("ddtrace.span.log") 442def test_span_key(span_log): 443 # Span tag keys must be strings 444 s = Span(tracer=None, name="test.span") 445 446 s.set_tag(123, True) 447 span_log.warning.assert_called_once_with("Ignoring tag pair %s:%s. Key must be a string.", 123, True) 448 assert s.get_tag(123) is None 449 assert s.get_tag("123") is None 450 451 span_log.reset_mock() 452 453 s.set_tag(None, "val") 454 span_log.warning.assert_called_once_with("Ignoring tag pair %s:%s. Key must be a string.", None, "val") 455 assert s.get_tag(123.32) is None 456 457 458def test_span_finished(): 459 span = Span(None, None) 460 assert span.finished is False 461 assert span.duration_ns is None 462 463 span.finished = True 464 assert span.finished is True 465 assert span.duration_ns is not None 466 duration = span.duration_ns 467 468 span.finished = True 469 assert span.finished is True 470 assert span.duration_ns == duration 471 472 span.finished = False 473 assert span.finished is False 474 475 span.finished = True 476 assert span.finished is True 477 assert span.duration_ns != duration 478 479 480def test_span_unicode_set_tag(): 481 span = Span(None, None) 482 span.set_tag("key", u"") 483 span.set_tag("", u"") 484 span._set_str_tag("key", u"") 485 span._set_str_tag(u"", u"") 486 487 488@pytest.mark.skipif(sys.version_info.major != 2, reason="This test only applies Python 2") 489@mock.patch("ddtrace.span.log") 490def test_span_binary_unicode_set_tag(span_log): 491 span = Span(None, None) 492 span.set_tag("key", "") 493 span._set_str_tag("key_str", "") 494 # only span.set_tag() will fail 495 span_log.warning.assert_called_once_with("error setting tag %s, ignoring it", "key", exc_info=True) 496 assert "key" not in span.meta 497 assert span.meta["key_str"] == u"" 498 499 500@pytest.mark.skipif(sys.version_info.major == 2, reason="This test does not apply to Python 2") 501@mock.patch("ddtrace.span.log") 502def test_span_bytes_string_set_tag(span_log): 503 span = Span(None, None) 504 span.set_tag("key", b"\xf0\x9f\xa4\x94") 505 span._set_str_tag("key_str", b"\xf0\x9f\xa4\x94") 506 assert span.meta["key"] == "b'\\xf0\\x9f\\xa4\\x94'" 507 assert span.meta["key_str"] == "" 508 span_log.warning.assert_not_called() 509 510 511@mock.patch("ddtrace.span.log") 512def test_span_encoding_set_str_tag(span_log): 513 span = Span(None, None) 514 span._set_str_tag("foo", u"/?foo=bar&baz=정상처리".encode("euc-kr")) 515 span_log.warning.assert_not_called() 516 assert span.meta["foo"] == u"/?foo=bar&baz=����ó��" 517 518 519def test_span_nonstring_set_str_tag_exc(): 520 span = Span(None, None) 521 with pytest.raises(TypeError): 522 span._set_str_tag("foo", dict(a=1)) 523 assert "foo" not in span.meta 524 525 526@mock.patch("ddtrace.span.log") 527def test_span_nonstring_set_str_tag_warning(span_log): 528 with override_global_config(dict(_raise=False)): 529 span = Span(None, None) 530 span._set_str_tag("foo", dict(a=1)) 531 span_log.warning.assert_called_once_with( 532 "Failed to set text tag '%s'", 533 "foo", 534 exc_info=True, 535 ) 536 537 538def test_span_ignored_exceptions(): 539 s = Span(None, None) 540 s._ignore_exception(ValueError) 541 542 with pytest.raises(ValueError): 543 with s: 544 raise ValueError() 545 546 assert s.error == 0 547 assert s.get_tag(ERROR_MSG) is None 548 assert s.get_tag(ERROR_TYPE) is None 549 assert s.get_tag(ERROR_STACK) is None 550 551 s = Span(None, None) 552 s._ignore_exception(ValueError) 553 554 with pytest.raises(ValueError): 555 with s: 556 raise ValueError() 557 558 with pytest.raises(RuntimeError): 559 with s: 560 raise RuntimeError() 561 562 assert s.error == 1 563 assert s.get_tag(ERROR_MSG) is not None 564 assert "RuntimeError" in s.get_tag(ERROR_TYPE) 565 assert s.get_tag(ERROR_STACK) is not None 566 567 568def test_span_ignored_exception_multi(): 569 s = Span(None, None) 570 s._ignore_exception(ValueError) 571 s._ignore_exception(RuntimeError) 572 573 with pytest.raises(ValueError): 574 with s: 575 raise ValueError() 576 577 with pytest.raises(RuntimeError): 578 with s: 579 raise RuntimeError() 580 581 assert s.error == 0 582 assert s.get_tag(ERROR_MSG) is None 583 assert s.get_tag(ERROR_TYPE) is None 584 assert s.get_tag(ERROR_STACK) is None 585 586 587def test_span_ignored_exception_subclass(): 588 s = Span(None, None) 589 s._ignore_exception(Exception) 590 591 with pytest.raises(ValueError): 592 with s: 593 raise ValueError() 594 595 with pytest.raises(RuntimeError): 596 with s: 597 raise RuntimeError() 598 599 assert s.error == 0 600 assert s.get_tag(ERROR_MSG) is None 601 assert s.get_tag(ERROR_TYPE) is None 602 assert s.get_tag(ERROR_STACK) is None 603 604 605def test_on_finish_single_callback(): 606 m = mock.Mock() 607 s = Span(None, "test", on_finish=[m]) 608 m.assert_not_called() 609 s.finish() 610 m.assert_called_once_with(s) 611 612 613def test_on_finish_multi_callback(): 614 m1 = mock.Mock() 615 m2 = mock.Mock() 616 s = Span(None, "test", on_finish=[m1, m2]) 617 s.finish() 618 m1.assert_called_once_with(s) 619 m2.assert_called_once_with(s) 620 621 622@pytest.mark.parametrize("arg", ["span_id", "trace_id", "parent_id"]) 623def test_span_preconditions(arg): 624 Span(None, "test", **{arg: None}) 625 with pytest.raises(TypeError): 626 Span(None, "test", **{arg: "foo"}) 627 628 629def test_span_pprint(): 630 root = Span(None, "test.span", service="s", resource="r", span_type=SpanTypes.WEB) 631 root.set_tag("t", "v") 632 root.set_metric("m", 1.0) 633 root.finish() 634 actual = root.pprint() 635 assert "name='test.span'" in actual 636 assert "service='s'" in actual 637 assert "resource='r'" in actual 638 assert "type='web'" in actual 639 assert "error=0" in actual 640 assert ("tags={'t': 'v'}" if six.PY3 else "tags={'t': u'v'}") in actual 641 assert "metrics={'m': 1.0}" in actual 642 assert re.search("id=[0-9]+", actual) is not None 643 assert re.search("trace_id=[0-9]+", actual) is not None 644 assert "parent_id=None" in actual 645 assert re.search("duration=[0-9.]+", actual) is not None 646 assert re.search("start=[0-9.]+", actual) is not None 647 assert re.search("end=[0-9.]+", actual) is not None 648 649 root = Span(None, "test.span", service="s", resource="r", span_type=SpanTypes.WEB) 650 actual = root.pprint() 651 assert "duration=None" in actual 652 assert "end=None" in actual 653 654 root = Span(None, "test.span", service="s", resource="r", span_type=SpanTypes.WEB) 655 root.error = 1 656 actual = root.pprint() 657 assert "error=1" in actual 658 659 root = Span(None, "test.span", service="s", resource="r", span_type=SpanTypes.WEB) 660 root.set_tag(u"", u"") 661 actual = root.pprint() 662 assert (u"tags={'': ''}" if six.PY3 else "tags={u'\\U0001f60c': u'\\U0001f60c'}") in actual 663 664 root = Span(None, "test.span", service=object()) 665 actual = root.pprint() 666 assert "service=<object object at" in actual 667 668 669def test_manual_context_usage(): 670 span1 = Span(None, "span1") 671 span2 = Span(None, "span2", context=span1.context) 672 673 span2.context.sampling_priority = 2 674 assert span1.context.sampling_priority == 2 675 676 span1.context.sampling_priority = 1 677 assert span2.context.sampling_priority == 1 678 assert span1.context.sampling_priority == 1 679