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_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_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_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_passes_parent_id_if_supplied(self):
''' ensure parent_id gets passed to start_span if supplied '''
m_client = Mock()
tracer = SynchronousTracer(m_client)
tracer.start_span = Mock()
mock_span = Mock()
tracer.start_span.return_value = mock_span
tracer.finish_span = Mock()
with tracer('foo', parent_id='zyxw'):
pass
tracer.start_span.assert_called_once_with(context={'name': 'foo'}, parent_id='zyxw')
tracer.finish_span.assert_called_once_with(mock_span)
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)
class Beeline(object):
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())
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 send_now(self, data):
''' DEPRECATED - to be removed in a future release
Create an event and enqueue it immediately. Does not work with
`beeline.add_field` - this is equivalent to calling `libhoney.send_now`
'''
ev = self.client.new_event()
if data:
ev.add(data)
self._run_hooks_and_send(ev)
def add_field(self, name, value):
''' Add a field to the currently active span.
`beeline.add_field("my field", "my value")`
If a field is being attributed to the wrong span/event,
make sure that `new_event` and `close_event` calls are matched.
'''
# fetch the current event from our tracer
span = self.tracer_impl.get_active_span()
# if there are no spans, this is a noop
if span is None:
return
span.add_context_field(name, value)
def add(self, data):
'''Similar to add_field(), but allows you to add a number of name:value pairs
to the currently active event at the same time.
`beeline.add({ "first_field": "a", "second_field": "b"})`
'''
# fetch the current event from the tracer
span = self.tracer_impl.get_active_span()
# if there are no spans, this is a noop
if span is None:
return
span.add_context(data)
def tracer(self, name, trace_id=None, parent_id=None):
return self.tracer_impl(name=name, trace_id=trace_id, parent_id=parent_id)
def new_event(self, data=None, trace_name=''):
''' DEPRECATED: Helper method that wraps `start_trace` and
`start_span`. It is better to use these methods as it provides
better control and context around how traces are implemented in your
app.
Creates a new span, populating it with the given data if
supplied. If no trace is running, a new trace will be started,
otherwise the event will be added as a span of the existing trace.
To send the event, call `beeline.send_event()`. There should be a
`send_event()` for each call to `new_event()`, or tracing and
`add` and `add_field` will not work correctly.
If trace_name is specified, will set the "name" field of the current span,
which is used in the trace visualizer.
'''
if trace_name:
data['name'] = trace_name
if self.tracer_impl.get_active_trace_id():
self.tracer_impl.start_span(context=data)
else:
self.tracer_impl.start_trace(context=data)
def send_event(self):
''' DEPRECATED: Sends the currently active event (current span),
if it exists.
There must be one call to `send_event` for each call to `new_event`.
'''
span = self.tracer_impl.get_active_span()
if span:
if span.is_root():
self.tracer_impl.finish_trace(span)
return
self.tracer_impl.finish_span(span)
def send_all(self):
''' send all spans in the trace stack, regardless of their
state
'''
span = self.tracer_impl.get_active_span()
while span:
if span.is_root():
self.tracer_impl.finish_trace(span)
return
self.tracer_impl.finish_span(span)
span = self.tracer_impl.get_active_span()
def traced(self, name, trace_id=None, parent_id=None):
def wrapped(fn, *args, **kwargs):
@functools.wraps(fn)
def inner(*args, **kwargs):
with self.tracer(name=name, trace_id=trace_id, parent_id=parent_id):
return fn(*args, **kwargs)
return inner
return wrapped
def traced_thread(self, fn):
trace_id = self.tracer_impl._state.trace_id
# copy as a new list - reference will be unavailable when we enter the new thread
stack = copy.copy(self.tracer_impl._state.stack)
trace_fields = copy.copy(self.tracer_impl._state.trace_fields)
@functools.wraps(fn)
def wrapped(*args, **kwargs):
self.tracer_impl._state.trace_id = trace_id
self.tracer_impl._state.stack = stack
self.tracer_impl._state.trace_fields = trace_fields
return fn(*args, **kwargs)
return wrapped
def _run_hooks_and_send(self, ev):
''' internal - run any defined hooks on the event and send '''
presampled = False
if self.sampler_hook:
self.log("executing sampler hook on event ev = %s", ev.fields())
keep, new_rate = self.sampler_hook(ev.fields())
if not keep:
self.log("skipping event due to sampler hook sampling ev = %s", ev.fields())
return
ev.sample_rate = new_rate
presampled = True
if self.presend_hook:
self.log("executing presend hook on event ev = %s", ev.fields())
self.presend_hook(ev.fields())
if presampled:
self.log("enqueuing presampled event ev = %s", ev.fields())
ev.send_presampled()
else:
self.log("enqueuing event ev = %s", ev.fields())
ev.send()
def _init_logger(self):
self._logger = logging.getLogger('honeycomb-beeline')
self._logger.setLevel(logging.DEBUG)
ch = logging.StreamHandler()
ch.setLevel(logging.DEBUG)
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
ch.setFormatter(formatter)
self._logger.addHandler(ch)
def log(self, msg, *args, **kwargs):
if self.debug:
self._logger.debug(msg, *args, **kwargs)
def get_responses_queue(self):
return self.client.responses()
def close(self):
if self.client:
self.client.close()