def test_handles_batched_traces(self):
t1 = self.trace
t2 = Trace('test2', 3, 4)
cs1 = Annotation.client_send(1)
cs2 = Annotation.client_send(2)
cr1 = Annotation.client_recv(3)
cr2 = Annotation.client_recv(4)
self.tracer.record([(t1, [cs1, cr1]), (t2, [cs2, cr2])])
self.assertEqual(self.agent.request.call_count, 1)
args = self.agent.request.mock_calls[0][1]
self.assertEqual(('POST', 'http://trace.it', Headers({})), args[:3])
bodyProducer = args[3]
return self.assertBodyEquals(
bodyProducer,
[{'trace_id': '0000000000000001',
'span_id': '0000000000000002',
'name': 'test',
'annotations': [
{'type': 'timestamp', 'value': 1, 'key': 'cs'},
{'type': 'timestamp', 'value': 3, 'key': 'cr'}
]},
{'trace_id': '0000000000000003',
'span_id': '0000000000000004',
'name': 'test2',
'annotations': [
{'type': 'timestamp', 'value': 2, 'key': 'cs'},
{'type': 'timestamp', 'value': 4, 'key': 'cr'}
]}])
def test_handles_batched_traces(self):
t1 = Trace('test', 1, 2)
t2 = Trace('test2', 3, 4)
cs1 = Annotation.client_send(1)
cs2 = Annotation.client_send(2)
cr1 = Annotation.client_recv(3)
cr2 = Annotation.client_recv(4)
self.tracer.record([(t1, [cs1, cr1]), (t2, [cs2, cr2])])
self.assertEqual(self.scribe.log.call_count, 1)
args = self.scribe.log.mock_calls[0][1]
self.assertEqual('restkin', args[0])
entries = args[1]
self.assertEqual(len(entries), 1)
self.assertEqual(
json.loads(entries[0]),
[{'trace_id': '0000000000000001',
'span_id': '0000000000000002',
'name': 'test',
'annotations': [
{'type': 'timestamp', 'value': 1, 'key': 'cs'},
{'type': 'timestamp', 'value': 3, 'key': 'cr'}]},
{'trace_id': '0000000000000003',
'span_id': '0000000000000004',
'name': 'test2',
'annotations': [
{'type': 'timestamp', 'value': 2, 'key': 'cs'},
{'type': 'timestamp', 'value': 4, 'key': 'cr'}]}])
def test_handles_batched_traces(self):
t1 = Trace('test', 1, 2)
t2 = Trace('test2', 3, 4)
cs1 = Annotation.client_send(1)
cs2 = Annotation.client_send(2)
cr1 = Annotation.client_recv(3)
cr2 = Annotation.client_recv(4)
self.tracer.record([(t1, [cs1, cr1]), (t2, [cs2, cr2])])
self.assertEqual(self.scribe.log.call_count, 1)
args = self.scribe.log.mock_calls[0][1]
self.assertEqual('restkin', args[0])
entries = args[1]
self.assertEqual(len(entries), 1)
self.assertEqual(json.loads(entries[0]), [{
'trace_id':
'0000000000000001',
'span_id':
'0000000000000002',
'name':
'test',
'annotations': [{
'type': 'timestamp',
'value': 1,
'key': 'cs'
}, {
'type': 'timestamp',
'value': 3,
'key': 'cr'
}]
}, {
'trace_id':
'0000000000000003',
'span_id':
'0000000000000004',
'name':
'test2',
'annotations': [{
'type': 'timestamp',
'value': 2,
'key': 'cs'
}, {
'type': 'timestamp',
'value': 4,
'key': 'cr'
}]
}])
def test_handles_batched_traces(self):
t1 = self.trace
t2 = Trace('test2', 3, 4)
cs1 = Annotation.client_send(1)
cs2 = Annotation.client_send(2)
cr1 = Annotation.client_recv(3)
cr2 = Annotation.client_recv(4)
self.tracer.record([(t1, [cs1, cr1]), (t2, [cs2, cr2])])
self.assertEqual(self.agent.request.call_count, 1)
args = self.agent.request.mock_calls[0][1]
self.assertEqual(('POST', 'http://trace.it', Headers({})), args[:3])
bodyProducer = args[3]
return self.assertBodyEquals(bodyProducer, [{
'trace_id':
'0000000000000001',
'span_id':
'0000000000000002',
'name':
'test',
'annotations': [{
'type': 'timestamp',
'value': 1,
'key': 'cs'
}, {
'type': 'timestamp',
'value': 3,
'key': 'cr'
}]
}, {
'trace_id':
'0000000000000003',
'span_id':
'0000000000000004',
'name':
'test2',
'annotations': [{
'type': 'timestamp',
'value': 2,
'key': 'cs'
}, {
'type': 'timestamp',
'value': 4,
'key': 'cr'
}]
}])
def handle_response(response):
if response.error:
future.set_exception(response.error)
else:
future.set_result(response)
if options.client_trace:
request.trace.record(Annotation.client_recv())
def fetch(self, request, *args, **kwargs):
method, url = _request_info(request)
ZipkinTracer.record(Annotation.string('Url', url))
ZipkinTracer.record(Annotation.client_send())
response = super(HTTPClient, self).fetch(request, *args, **kwargs)
ZipkinTracer.record(Annotation.client_recv())
return response
def handle_response(response):
if response.error:
future.set_exception(response.error)
else:
future.set_result(response)
if options.client_trace:
request.trace.record(Annotation.client_recv())
def test_handles_batched_traces(self):
tracer = EndAnnotationTracer(self.tracer)
t1 = Trace('test1', tracers=[tracer])
t2 = Trace('test2', tracers=[tracer])
cs1 = Annotation.client_send()
cs2 = Annotation.client_send()
cr1 = Annotation.client_recv()
cr2 = Annotation.client_recv()
tracer.record([(t1, [cs1, cr1]), (t2, [cs2, cr2])])
self.assertEqual(self.tracer.record.call_count, 2)
self.tracer.record.assert_any_call([(t1, [cs1, cr1])])
self.tracer.record.assert_any_call([(t2, [cs2, cr2])])
def _finished(resp):
# TODO: It may be advantageous here to return a wrapped response
# whose deliverBody can wrap it's protocol and record when the
# application has finished reading the contents.
trace.record(
Annotation.string('http.responsecode',
'{0} {1}'.format(resp.code, resp.phrase)))
trace.record(Annotation.client_recv())
return resp
def _finished(resp):
# TODO: It may be advantageous here to return a wrapped response
# whose deliverBody can wrap it's protocol and record when the
# application has finished reading the contents.
trace.record(Annotation.string(
'http.responsecode',
'{0} {1}'.format(resp.code, resp.phrase)))
trace.record(Annotation.client_recv())
return resp
def test_handles_batched_traces(self):
tracer = EndAnnotationTracer(self.tracer)
t1 = Trace('test1', tracers=[tracer])
t2 = Trace('test2', tracers=[tracer])
cs1 = Annotation.client_send()
cs2 = Annotation.client_send()
cr1 = Annotation.client_recv()
cr2 = Annotation.client_recv()
tracer.record([(t1, [cs1, cr1]), (t2, [cs2, cr2])])
self.assertEqual(self.tracer.record.call_count, 2)
self.tracer.record.assert_any_call([(t1, [cs1, cr1])])
self.tracer.record.assert_any_call([(t2, [cs2, cr2])])
def test_traces_buffered_until_max_idle_time(self):
completed_trace = (Trace('completed'), [Annotation.client_send(1),
Annotation.client_recv(2)])
self.tracer.record([completed_trace])
self.assertEqual(self.record_function.call_count, 0)
self.clock.advance(10)
self.assertEqual(self.record_function.call_count, 1)
def test_logs_to_scribe_with_non_default_category(self):
tracer = RawZipkinTracer(self.scribe, 'not-zipkin')
t = Trace('test_raw_zipkin', 1, 2, tracers=[tracer])
t.record(Annotation.client_send(1), Annotation.client_recv(2))
self.scribe.log.assert_called_once_with(
'not-zipkin',
['CgABAAAAAAAAAAELAAMAAAAPdGVzdF9yYXdfemlwa2luCgAEAAAAAAAAAAIPAAY'
'MAAAAAgoAAQAA\nAAAAAAABCwACAAAAAmNzAAoAAQAAAAAAAAACCwACAAAAAmNy'
'AA8ACAwAAAAAAA=='])
def test_logs_to_scribe_with_non_default_category(self):
tracer = RawZipkinTracer(self.scribe, 'not-zipkin')
t = Trace('test_raw_zipkin', 1, 2, tracers=[tracer])
t.record(Annotation.client_send(1), Annotation.client_recv(2))
self.scribe.log.assert_called_once_with('not-zipkin', [
'CgABAAAAAAAAAAELAAMAAAAPdGVzdF9yYXdfemlwa2luCgAEAAAAAAAAAAIPAAY'
'MAAAAAgoAAQAA\nAAAAAAABCwACAAAAAmNzAAoAAQAAAAAAAAACCwACAAAAAmNy'
'AA8ACAwAAAAAAA=='
])
def test_delegates_on_end_annotation(self):
tracer = EndAnnotationTracer(self.tracer)
t = Trace('test_delegation', tracers=[tracer])
cs = Annotation.client_send()
ce = Annotation.client_recv()
t.record(cs)
t.record(ce)
self.tracer.record.assert_called_once_with([(t, [cs, ce])])
def test_traces_buffered_until_max_idle_time(self):
completed_trace = (Trace('completed'), [
Annotation.client_send(1),
Annotation.client_recv(2)
])
self.tracer.record([completed_trace])
self.assertEqual(self.record_function.call_count, 0)
self.clock.advance(10)
self.assertEqual(self.record_function.call_count, 1)
def test_delegates_on_end_annotation(self):
tracer = EndAnnotationTracer(self.tracer)
t = Trace('test_delegation', tracers=[tracer])
cs = Annotation.client_send()
ce = Annotation.client_recv()
t.record(cs)
t.record(ce)
self.tracer.record.assert_called_once_with([(t, [cs, ce])])
def test_traces_bufferred_until_max_traces(self):
completed_traces = [
(Trace('completed'), [Annotation.client_send(1),
Annotation.client_recv(2)])
for x in xrange(50)]
self.tracer.record(completed_traces[:10])
self.clock.advance(1)
self.assertEqual(self.record_function.call_count, 0)
self.tracer.record(completed_traces[10:])
self.clock.advance(1)
self.assertEqual(self.record_function.call_count, 1)
def test_traces_bufferred_until_max_traces(self):
completed_traces = [
(Trace('completed'),
[Annotation.client_send(1),
Annotation.client_recv(2)]) for x in xrange(50)
]
self.tracer.record(completed_traces[:10])
self.clock.advance(1)
self.assertEqual(self.record_function.call_count, 0)
self.tracer.record(completed_traces[10:])
self.clock.advance(1)
self.assertEqual(self.record_function.call_count, 1)
def test_handles_batched_traces(self):
tracer = RawZipkinTracer(self.scribe)
t1 = Trace('test_raw_zipkin', 1, 2, tracers=[tracer])
cs1 = Annotation.client_send(1)
t2 = Trace('test_raw_zipkin', 1, 2, tracers=[tracer])
cs2 = Annotation.client_send(1)
cr2 = Annotation.client_recv(2)
tracer.record([(t1, [cs1]), (t2, [cs2, cr2])])
self.scribe.log.assert_called_once_with(
'zipkin',
['CgABAAAAAAAAAAELAAMAAAAPdGVzdF9yYXdfemlwa2luCgAEAAAAAAAAAAIPAAY'
'MAAAAAQoAAQAA\nAAAAAAABCwACAAAAAmNzAA8ACAwAAAAAAA==',
'CgABAAAAAAAAAAELAAMAAAAPdGVzdF9yYXdfemlwa2luCgAEAAAAAAAAAAIPAAY'
'MAAAAAgoAAQAA\nAAAAAAABCwACAAAAAmNzAAoAAQAAAAAAAAACCwACAAAAAmNy'
'AA8ACAwAAAAAAA=='])
def test_handles_batched_traces(self):
tracer = RawZipkinTracer(self.scribe)
t1 = Trace('test_raw_zipkin', 1, 2, tracers=[tracer])
cs1 = Annotation.client_send(1)
t2 = Trace('test_raw_zipkin', 1, 2, tracers=[tracer])
cs2 = Annotation.client_send(1)
cr2 = Annotation.client_recv(2)
tracer.record([(t1, [cs1]), (t2, [cs2, cr2])])
self.scribe.log.assert_called_once_with('zipkin', [
'CgABAAAAAAAAAAELAAMAAAAPdGVzdF9yYXdfemlwa2luCgAEAAAAAAAAAAIPAAY'
'MAAAAAQoAAQAA\nAAAAAAABCwACAAAAAmNzAA8ACAwAAAAAAA==',
'CgABAAAAAAAAAAELAAMAAAAPdGVzdF9yYXdfemlwa2luCgAEAAAAAAAAAAIPAAY'
'MAAAAAgoAAQAA\nAAAAAAABCwACAAAAAmNzAAoAAQAAAAAAAAACCwACAAAAAmNy'
'AA8ACAwAAAAAAA=='
])
def test_client_recv(self):
a = Annotation.client_recv()
self.assertEqual(a.value, 1000000)
self.assertEqual(a.name, 'cr')
self.assertEqual(a.annotation_type, 'timestamp')
def test_client_recv(self):
a = Annotation.client_recv()
self.assertEqual(a.value, 1000000)
self.assertEqual(a.name, 'cr')
self.assertEqual(a.annotation_type, 'timestamp')
def wrapper(request, callback, response, *args):
ZipkinTracer.record(Annotation.client_recv())
callback(response)
def process(self, data):
msg = json.loads(data)
if msg["frontend_name"] == "haproxy_monitoring":
return
frontend = FE_OR_BE.search(msg["frontend_name"]).group(2)
backend = FE_OR_BE.search(msg["backend_name"]).group(2)
server = SERVER_SUB.sub("_", msg["server_name"])
# Consider server received to be the accept_date plus the time to
# receive request headers.
accept = parse_date_micro(msg["accept_date"])
request = int(msg["time_request"]) * 1000
if request < 0:
request = 0
sr = accept + request
ctrace = Trace(msg["http_verb"],
trace_id=int_or_none(msg.get("zipkin_trace_id")),
span_id=int_or_none(msg.get("zipkin_next_span_id")),
parent_span_id=int_or_none(msg.get("zipkin_span_id")),
tracers=self.tracers)
# There's an assumption here and in the server endpoint that the 'host'
# parsed by Logstash from the syslog message is the same host as the
# service is running on.
endpoint = Endpoint(msg["host"], 0, backend)
ctrace.set_endpoint(endpoint)
# For client sent we consider the time in queue plus backend connect
# time (which is the time to get the SYN/ACK from the backend).
queue = int(msg["time_queue"]) * 1000
if queue < 0:
queue = 0
connect = int(msg["time_backend_connect"]) * 1000
if connect < 0:
connect = 0
cs = sr + queue + connect
ctrace.record(Annotation.client_send(cs))
ctrace.record(Annotation.string('haproxy.backend.server_name', server))
# Record response time in ms into an annotation since it doesn't fit
# anywhere in zipkin.
response = int(msg["time_backend_response"]) * 1000
if response < 0:
response = 0
ctrace.record(Annotation.string("haproxy.backend.time",
str(response)))
ctrace.record(Annotation.string("haproxy.backend.queue",
msg["backend_queue"]))
# Apache sends the duration in microseconds already. For haproxy we
# have to convert from ms.
duration = int(msg["time_duration"])
if msg["program"] == "haproxy":
duration = duration * 1000
if duration < 0:
duration = 0
# Assume client response time to be the same as the request duration
# minus a microsecond, just to keep ordering.
ss = sr + duration
cr = ss - 1
ctrace.record(Annotation.client_recv(cr))
# The top-level span is generally Apache. We record the parent span id
# as '-' there if the parent span id is missing so convert to None.
parent_span_id = msg.get("zipkin_parent_span_id")
if parent_span_id is not None and parent_span_id == "-":
parent_span_id = None
strace = Trace(msg["http_verb"],
trace_id=int_or_none(msg.get("zipkin_trace_id")),
span_id=int_or_none(msg.get("zipkin_span_id")),
parent_span_id=int_or_none(parent_span_id),
tracers=self.tracers)
endpoint = Endpoint(msg["host"], 0, frontend)
strace.set_endpoint(endpoint)
strace.record(Annotation.server_recv(sr))
strace.record(Annotation.string('http.uri', msg["http_request"]))
strace.record(Annotation.string(
'http.responsecode', msg["http_status_code"]))
strace.record(Annotation.server_send(ss))
