def test_run_hooks_and_send_adds_trace_fields(self):
''' ensure trace fields are propagated backwards '''
m_client = Mock()
tracer = SynchronousTracer(m_client)
m_span = Mock()
m_span.event = Event()
m_span.event.start_time = datetime.datetime.now()
# set an existing trace field
m_span.event.add_field('app.a', 1)
m_span.rollup_fields = defaultdict(float)
with patch('beeline.trace._should_sample') as m_sample_fn:
m_sample_fn.return_value = True
# add some trace fields
tracer.add_trace_field('a', 0)
tracer.add_trace_field('b', 2)
tracer.add_trace_field('c', 3)
tracer.finish_span(m_span)
# ensure we only added fields b and c and did not try to overwrite a
self.assertDictContainsSubset({
'app.a': 1,
'app.b': 2,
'app.c': 3
}, m_span.event.fields())
def test_propagate_and_start_trace_uses_w3c_header_as_fallback(self):
# implicitly tests finish_span
m_client = Mock()
# these values are used before sending
m_client.new_event.return_value.start_time = datetime.datetime.now()
m_client.new_event.return_value.sample_rate = 1
tracer = SynchronousTracer(m_client)
header_value = '00-0af7651916cd43dd8448eb211c80319c-b7ad6b7169203331-00'
req = DictRequest({
'traceparent': header_value,
})
span = tracer.propagate_and_start_trace(
context={'big': 'important_stuff'}, request=req)
self.assertEqual(tracer._trace.stack[0], span)
self.assertEqual(span.trace_id, "0af7651916cd43dd8448eb211c80319c")
self.assertEqual(span.parent_id, "b7ad6b7169203331")
tracer.finish_trace(span)
# ensure the event is sent
span.event.send_presampled.assert_called_once_with()
# ensure that there is no current trace
self.assertIsNone(tracer._trace)
def test_propagate_and_start_trace_uses_honeycomb_header_when_w3c_also_present(
self):
# implicitly tests finish_span
m_client = Mock()
# these values are used before sending
m_client.new_event.return_value.start_time = datetime.datetime.now()
m_client.new_event.return_value.sample_rate = 1
tracer = SynchronousTracer(m_client)
w3c_value = '00-0af7651916cd43dd8448eb211c80319c-b7ad6b7169203331-00'
honeycomb_value = '1;dataset=flibble,trace_id=bloop,parent_id=scoop,context=e30K'
req = DictRequest({
'traceparent': w3c_value,
'x-honeycomb-trace': honeycomb_value
})
span = tracer.propagate_and_start_trace(
context={'big': 'important_stuff'}, request=req)
self.assertEqual(tracer._trace.stack[0], span)
self.assertEqual(span.trace_id, "bloop")
self.assertEqual(span.parent_id, "scoop")
tracer.finish_trace(span)
self.assertEqual(span.event.dataset, 'flibble')
# ensure the event is sent
span.event.send_presampled.assert_called_once_with()
# ensure that there is no current trace
self.assertIsNone(tracer._trace)
def test_error_handling(self):
class TestException(Exception):
pass
def error_parser(propagation_context):
raise TestException()
# implicitly tests finish_span
m_client = Mock()
# these values are used before sending
m_client.new_event.return_value.start_time = datetime.datetime.now()
m_client.new_event.return_value.sample_rate = 99
tracer = SynchronousTracer(m_client)
tracer.register_hooks(http_trace_parser=error_parser)
header_value = '1;trace_id=bloop,parent_id=scoop,context=e30K'
req = DictRequest({
# case shouldn't matter
'X-HoNEyComb-TrACE': header_value,
})
span = tracer.propagate_and_start_trace(
context={'big': 'important_stuff'}, request=req)
# Verify that our new span is at the top of the stack
self.assertEqual(tracer._trace.stack[0], span)
# Verify that we got the event in the mock.
self.assertEqual(span.event.sample_rate, 99)
def test_run_hooks_and_send_adds_trace_fields(self):
''' ensure trace fields are propagated backwards '''
m_client = Mock()
tracer = SynchronousTracer(m_client)
tracer.start_trace()
m_span = Mock()
m_span.event = Event()
m_span.event.start_time = datetime.datetime.now()
# set an existing trace field
m_span.event.add_field('app.a', 1)
m_span.rollup_fields = defaultdict(float)
with patch('beeline.trace._should_sample') as m_sample_fn:
m_sample_fn.return_value = True
# add some trace fields
tracer.add_trace_field('a', 0)
tracer.add_trace_field('b', 2)
tracer.add_trace_field('c', 3)
tracer.finish_span(m_span)
# Check that the new, unique fields were successfully added
self.assertIn("app.b", m_span.event.fields())
self.assertIn("app.c", m_span.event.fields())
# Check that a was not overwritten with the new value of 0.
self.assertEqual(m_span.event.fields()["app.a"], 1)
def test_propagate_and_start_trace(self):
# FIXME: Test basics, including error handling and custom hooks
# implicitly tests finish_span
m_client = Mock()
# these values are used before sending
m_client.new_event.return_value.start_time = datetime.datetime.now()
m_client.new_event.return_value.sample_rate = 1
tracer = SynchronousTracer(m_client)
header_value = '1;dataset=flibble,trace_id=bloop,parent_id=scoop,context=e30K'
req = DictRequest({
# case shouldn't matter
'X-HoNEyComb-TrACE': header_value,
})
span = tracer.propagate_and_start_trace(
context={'big': 'important_stuff'}, request=req)
self.assertEqual(tracer._trace.stack[0], span)
self.assertEqual(span.trace_id, "bloop")
self.assertEqual(span.parent_id, "scoop")
tracer.finish_trace(span)
self.assertEqual(span.event.dataset, 'flibble')
# ensure the event is sent
span.event.send_presampled.assert_called_once_with()
# ensure that there is no current trace
self.assertIsNone(tracer._trace)
def test_run_hooks_and_send_sampler(self):
''' ensure send works with a sampler hook defined '''
m_client = Mock()
tracer = SynchronousTracer(m_client)
m_span = Mock()
def _sampler_drop_all(fields):
return False, 0
tracer.register_hooks(sampler=_sampler_drop_all)
with patch('beeline.trace._should_sample') as m_sample_fn:
m_sample_fn.return_value = True
tracer._run_hooks_and_send(m_span)
# sampler ensures we drop everything
m_span.event.send.assert_not_called() # pylint: disable=no-member
m_span.event.send_presampled.assert_not_called() # pylint: disable=no-member
def _sampler_drop_none(fields):
return True, 100
tracer.register_hooks(sampler=_sampler_drop_none)
m_span.reset_mock()
with patch('beeline.trace._should_sample') as m_sample_fn:
m_sample_fn.return_value = True
tracer._run_hooks_and_send(m_span)
# sampler drops nothing, _should_sample rigged to always return true so
# we always call send_presampled
m_span.event.send.assert_not_called() # pylint: disable=no-member
m_span.event.send_presampled.assert_called_once_with() # pylint: disable=no-member
# ensure event is updated with new sample rate
self.assertEqual(m_span.event.sample_rate, 100)
def test_run_hooks_and_send_presend_hook(self):
''' ensure send works when presend hook is defined '''
m_client = Mock()
tracer = SynchronousTracer(m_client)
m_span = Mock()
def _presend_hook(fields):
fields["thing i want"] = "put it there"
del fields["thing i don't want"]
m_span = Mock()
m_span.event.fields.return_value = {
"thing i don't want": "get it out of here",
"happy data": "so happy",
}
tracer.register_hooks(presend=_presend_hook)
with patch('beeline.trace._should_sample') as m_sample_fn:
m_sample_fn.return_value = True
tracer._run_hooks_and_send(m_span)
m_span.event.send_presampled.assert_called_once_with() # pylint: disable=no-member
self.assertDictEqual(
m_span.event.fields(),
{
"thing i want": "put it there",
"happy data": "so happy",
},
)
def test_start_span(self):
m_client = Mock()
tracer = SynchronousTracer(m_client)
span = tracer.start_trace(context={'big': 'important_stuff'})
# make sure this is the only event in the stack
self.assertEqual(tracer._state.stack[0], span)
self.assertEqual(len(tracer._state.stack), 1)
span2 = tracer.start_span(context={'more': 'important_stuff'})
# should still have the root span as the first item in the stack
self.assertEqual(tracer._state.stack[0], span)
self.assertEqual(tracer._state.stack[-1], span2)
# should have the first span id as its parent
# should share the same trace id
self.assertEqual(span.trace_id, span2.trace_id)
self.assertEqual(span.id, span2.parent_id)
# trace id should match what the tracer has
self.assertEqual(span.trace_id, tracer._state.trace_id)
m_client.new_event.return_value.add.assert_has_calls([
call(data={'more': 'important_stuff'}),
call(
data={
'trace.trace_id': span2.trace_id,
'trace.parent_id': span2.parent_id,
'trace.span_id': span2.id,
}),
])
def test_start_span_returns_none_if_no_trace(self):
m_client = Mock()
tracer = SynchronousTracer(m_client)
span = tracer.start_span(context={'more': 'important_stuff'})
# should still have the root span as the first item in the stack
self.assertIsNone(span)
self.assertEqual(len(tracer._state.stack), 0)
def test_start_span_returns_none_if_no_trace(self):
m_client = Mock()
tracer = SynchronousTracer(m_client)
span = tracer.start_span(context={'more': 'important_stuff'})
# should still have no active trace
self.assertIsNone(span)
self.assertIsNone(tracer._trace)
def test_add_trace_field_propagates(self):
m_client = Mock()
tracer = SynchronousTracer(m_client)
span = tracer.start_trace(context={'big': 'important_stuff'})
# make sure this is the only event in the stack
self.assertEqual(tracer._state.stack[0], span)
self.assertEqual(len(tracer._state.stack), 1)
m_client.new_event.reset_mock()
tracer.add_trace_field('another', 'important_thing')
tracer.add_trace_field('wide', 'events_are_great')
span2 = tracer.start_span(context={'more': 'important_stuff'})
# should still have the root span as the first item in the stack
self.assertEqual(tracer._state.stack[0], span)
self.assertEqual(tracer._state.stack[-1], span2)
# should have the first span id as its parent
# should share the same trace id
self.assertEqual(span.trace_id, span2.trace_id)
self.assertEqual(span.id, span2.parent_id)
# trace id should match what the tracer has
self.assertEqual(span.trace_id, tracer._state.trace_id)
m_client.new_event.assert_called_once_with(
data={
'app.another': 'important_thing',
'app.wide': 'events_are_great'
})
m_client.new_event.return_value.add.assert_has_calls([
call(data={'more': 'important_stuff'}),
call(
data={
'trace.trace_id': span2.trace_id,
'trace.parent_id': span2.parent_id,
'trace.span_id': span2.id,
}),
])
m_client.new_event.reset_mock()
m_client.new_event.return_value.fields.return_value = {}
# swap out some trace fields
tracer.add_trace_field('more', 'data!')
tracer.remove_trace_field('another')
span3 = tracer.start_span(context={'more': 'important_stuff'})
self.assertEqual(tracer._state.stack[0], span)
self.assertEqual(tracer._state.stack[1], span2)
self.assertEqual(tracer._state.stack[-1], span3)
# should have the second span id as its parent
# should share the same trace id
self.assertEqual(span.trace_id, span3.trace_id)
self.assertEqual(span2.id, span3.parent_id)
m_client.new_event.assert_called_once_with(data={
'app.wide': 'events_are_great',
'app.more': 'data!',
})
def test_add_rollup_field_propagates(self):
m_client = Mock()
tracer = SynchronousTracer(m_client)
tracer._run_hooks_and_send = Mock()
span1 = tracer.start_trace(context={'name': 'root'})
event1 = m_client.new_event.return_value
span2 = tracer.start_span(context={'name': 'middle'})
event2 = m_client.new_event.return_value
span3 = tracer.start_span(context={'name': 'inner1'})
event3 = m_client.new_event.return_value
tracer.add_rollup_field('database_ms', 17)
tracer.add_rollup_field('calories', 180)
tracer.add_rollup_field('database_ms', 23.1)
event3.add_field.reset_mock()
tracer.finish_span(span3)
event3.add_field.assert_has_calls([
call('database_ms', 17.0 + 23.1),
call('calories', 180.0),
call('duration_ms', ANY),
],
any_order=True)
span4 = tracer.start_span(context={'name': 'inner2'})
event4 = m_client.new_event.return_value
tracer.add_rollup_field('calories', 120)
event4.add_field.reset_mock()
tracer.finish_span(span4)
event4.add_field.assert_has_calls([
call('calories', 120.0),
call('duration_ms', ANY),
],
any_order=True)
event2.add_field.reset_mock()
tracer.finish_span(span2)
event2.add_field.assert_has_calls(
[
# This intermediate span doesn't get any rollup fields.
call('duration_ms', ANY),
],
any_order=True)
event1.add_field.reset_mock()
tracer.finish_span(span1)
event1.add_field.assert_has_calls([
call('rollup.database_ms', 17.0 + 23.1),
call('rollup.calories', 180.0 + 120.0),
call('duration_ms', ANY),
],
any_order=True)
def test_custom_dataset_propagates_to_event(self):
dataset = 'flibble'
m_client = Mock()
tracer = SynchronousTracer(m_client)
tracer._run_hooks_and_send = Mock()
span = tracer.start_trace(dataset=dataset)
event = m_client.new_event.return_value
tracer.finish_span(span)
self.assertEqual(event.dataset, dataset)
def init(writekey='', dataset='', service_name='', state_manager=None, tracer=None,
sample_rate=1, api_host='https://api.honeycomb.io', max_concurrent_batches=10,
max_batch_size=100, send_frequency=0.25,
block_on_send=False, block_on_response=False, transmission_impl=None):
''' initialize the honeycomb beeline. This will initialize a libhoney
client local to this module, and a state manager for tracking event context.
Args:
- `writekey`: the authorization key for your team on Honeycomb. Find your team
write key at [https://ui.honeycomb.io/account](https://ui.honeycomb.io/account)
- `dataset`: the name of the default dataset to which to write
- `sample_rate`: the default sample rate. 1 / `sample_rate` events will be sent.
- `max_concurrent_batches`: the maximum number of concurrent threads sending events.
- `max_batch_size`: the maximum number of events to batch before sendinga.
- `send_frequency`: how long to wait before sending a batch of events, in seconds.
- `block_on_send`: if true, block when send queue fills. If false, drop
events until there's room in the queue
- `block_on_response`: if true, block when the response queue fills. If
false, drop response objects.
- `transmission_impl`: if set, override the default transmission implementation
(for example, TornadoTransmission)
If in doubt, just set `writekey` and `dataset` and move on!
'''
global g_client, g_state, g_tracer
if g_client:
return
# allow setting some values from the environment
if not writekey:
writekey = os.environ.get('HONEYCOMB_WRITEKEY', '')
if not dataset:
dataset = os.environ.get('HONEYCOMB_DATASET', '')
if not service_name:
service_name = os.environ.get('HONEYCOMB_SERVICE', dataset)
g_client = Client(
writekey=writekey, dataset=dataset, sample_rate=sample_rate,
api_host=api_host, max_concurrent_batches=max_concurrent_batches,
max_batch_size=max_batch_size, send_frequency=send_frequency,
block_on_send=block_on_send, block_on_response=block_on_response,
transmission_impl=transmission_impl,
user_agent_addition=USER_AGENT_ADDITION,
)
g_client.add_field('service_name', service_name)
g_client.add_field('meta.beeline_version', VERSION)
g_client.add_field('meta.local_hostname', socket.gethostname())
if state_manager:
g_state = state_manager
else:
g_state = ThreadLocalState()
g_tracer = SynchronousTracer(g_client, g_state)
def __init__(self,
writekey='', dataset='', service_name='',
tracer=None, sample_rate=1, api_host='https://api.honeycomb.io',
max_concurrent_batches=10, max_batch_size=100, send_frequency=0.25,
block_on_send=False, block_on_response=False,
transmission_impl=None, sampler_hook=None, presend_hook=None,
debug=False):
self.client = None
self.tracer_impl = None
self.presend_hook = None
self.sampler_hook = None
self.debug = debug
if debug:
self._init_logger()
# allow setting some values from the environment
if not writekey:
writekey = os.environ.get('HONEYCOMB_WRITEKEY', '')
if not dataset:
dataset = os.environ.get('HONEYCOMB_DATASET', '')
if not service_name:
service_name = os.environ.get('HONEYCOMB_SERVICE', dataset)
self.client = Client(
writekey=writekey, dataset=dataset, sample_rate=sample_rate,
api_host=api_host, max_concurrent_batches=max_concurrent_batches,
max_batch_size=max_batch_size, send_frequency=send_frequency,
block_on_send=block_on_send, block_on_response=block_on_response,
transmission_impl=transmission_impl,
user_agent_addition=USER_AGENT_ADDITION,
debug=debug,
)
self.log('initialized honeycomb client: writekey=%s dataset=%s service_name=%s',
writekey, dataset, service_name)
if not writekey:
self.log('writekey not set! set the writekey if you want to send data to honeycomb')
if not dataset:
self.log('dataset not set! set a value for dataset if you want to send data to honeycomb')
self.client.add_field('service_name', service_name)
self.client.add_field('meta.beeline_version', VERSION)
self.client.add_field('meta.local_hostname', socket.gethostname())
if in_async_code():
self.tracer_impl = AsyncioTracer(self.client)
else:
self.tracer_impl = SynchronousTracer(self.client)
self.tracer_impl.register_hooks(presend=presend_hook, sampler=sampler_hook)
self.sampler_hook = sampler_hook
self.presend_hook = presend_hook
def test_trace_context_manager_does_not_crash_if_span_is_none(self):
m_client = Mock()
tracer = SynchronousTracer(m_client)
tracer.start_span = Mock()
tracer.start_span.return_value = None
tracer.finish_span = Mock()
with tracer('foo'):
pass
tracer.start_span.assert_called_once_with(context={'name': 'foo'}, parent_id=None)
def test_trace_context_manager_exception(self):
''' ensure that send_traced_event is called even if an exception is
raised inside the context manager '''
m_client, m_state = Mock(), Mock()
tracer = SynchronousTracer(m_client, m_state)
try:
with tracer('foo'):
raise Exception('boom!')
except Exception:
pass
m_state.pop_event.assert_called_once_with()
def test_trace_context_manager_starts_trace_if_trace_id_supplied(self):
''' ensure trace_id and parent_id get passed to start_trace if supplied '''
m_client = Mock()
tracer = SynchronousTracer(m_client)
tracer.start_trace = Mock()
mock_span = Mock()
tracer.start_trace.return_value = mock_span
tracer.finish_span = Mock()
with tracer('foo', trace_id='asdf', parent_id='zyxw'):
pass
tracer.start_trace.assert_called_once_with(context={'name': 'foo'}, trace_id='asdf', parent_span_id='zyxw')
tracer.finish_span.assert_called_once_with(mock_span)
def test_trace_context_manager_exception(self):
''' ensure that span is sent even if an exception is
raised inside the context manager '''
m_client = Mock()
tracer = SynchronousTracer(m_client)
tracer.start_trace = Mock()
mock_span = Mock()
tracer.start_trace.return_value = mock_span
tracer.finish_trace = Mock()
try:
with tracer('foo'):
raise Exception('boom!')
except Exception:
pass
tracer.finish_trace.assert_called_once_with(mock_span)
def test_start_trace_with_trace_id_set(self):
m_client = Mock()
tracer = SynchronousTracer(m_client)
span = tracer.start_trace(trace_id='123456', parent_span_id='999999')
self.assertEqual(span.trace_id, '123456')
self.assertEqual(span.parent_id, '999999')
self.assertEqual(tracer._state.trace_id, '123456')
m_client.new_event.return_value.add.assert_has_calls([
call(data={
'trace.trace_id': span.trace_id,
'trace.parent_id': span.parent_id,
'trace.span_id': span.id,
}),
])
def test_finish_trace(self):
# implicitly tests finish_span
m_client = Mock()
# these values are used before sending
m_client.new_event.return_value.start_time = datetime.datetime.now()
m_client.new_event.return_value.sample_rate = 1
tracer = SynchronousTracer(m_client)
span = tracer.start_trace(context={'big': 'important_stuff'})
self.assertEqual(tracer._trace.stack[0], span)
tracer.finish_trace(span)
# ensure the event is sent
span.event.send_presampled.assert_called_once_with()
# ensure that there is no current trace
self.assertIsNone(tracer._trace)
def test_run_hooks_and_send_no_hooks(self):
''' ensure send works when no hooks defined '''
m_client = Mock()
tracer = SynchronousTracer(m_client)
m_span = Mock()
with patch('beeline.trace._should_sample') as m_sample_fn:
m_sample_fn.return_value = True
tracer._run_hooks_and_send(m_span)
# no hooks - trace's _should_sample is rigged to always return True, so we
# always call send_presampled
# send should never be called because at a minimum we always do deterministic
# sampling
m_span.event.send.assert_not_called() # pylint: disable=no-member
m_span.event.send_presampled.assert_called_once_with() # pylint: disable=no-member
def test_trace_context_manager_starts_span_if_trace_active(self):
m_client = Mock()
tracer = SynchronousTracer(m_client)
tracer.start_span = Mock()
tracer.start_trace = Mock()
tracer.get_active_trace_id = Mock(return_value='asdf')
mock_span = Mock()
tracer.start_span.return_value = mock_span
tracer.finish_span = Mock()
with tracer('foo') as span:
self.assertEqual(span, mock_span, 'tracer context manager should yield the span')
tracer.start_span.assert_called_once_with(context={'name': 'foo'}, parent_id=None)
tracer.start_trace.assert_not_called()
tracer.finish_span.assert_called_once_with(mock_span)
def test_start_trace(self):
m_client = Mock()
tracer = SynchronousTracer(m_client)
span = tracer.start_trace(context={'big': 'important_stuff'})
self.assertIsInstance(span.event.start_time, datetime.datetime)
# make sure our context got passed on to the event
m_client.new_event.return_value.add.assert_has_calls([
call(data={'big': 'important_stuff'}),
call(data={
'trace.trace_id': span.trace_id,
'trace.parent_id': span.parent_id,
'trace.span_id': span.id,
}),
])
self.assertEqual(tracer._state.stack[0], span)
# ensure we started a trace by setting a trace_id
self.assertIsNotNone(tracer._state.trace_id)
def test_trace_with_custom_dataset(self):
dataset = 'flibble'
m_client = Mock()
tracer = SynchronousTracer(m_client)
tracer.start_trace(dataset=dataset)
self.assertEqual(tracer._trace.dataset, dataset)
def test_get_active_span(self):
m_client = Mock()
tracer = SynchronousTracer(m_client)
span = tracer.start_trace()
self.assertEquals(tracer.get_active_span().id, span.id)