def format(self, record):
json_log_object = {
"@timestamp": datetime.utcnow().isoformat(),
"@version": version,
"level": record.levelname,
"message": record.getMessage(),
"caller": record.filename + '::' + record.funcName,
"logger_name": "python-logger",
"application_name": "py-app"
}
json_log_object['data'] = {
f'{self.python_log_prefix}logger_name': record.name,
f'{self.python_log_prefix}module': record.module,
f'{self.python_log_prefix}funcName': record.funcName,
f'{self.python_log_prefix}filename': record.filename,
f'{self.python_log_prefix}lineno': record.lineno,
f'{self.python_log_prefix}thread':
f'{record.threadName}[{record.thread}]',
f'{self.python_log_prefix}pid': record.process
}
json_log_object['trace'] = {
"trace_id": b3.values()['X-B3-TraceId'],
"span_id": b3.values()['X-B3-TraceId'],
"exportable": "false"
}
if hasattr(record, 'props'):
json_log_object['data'].update(record.props)
if record.exc_info or record.exc_text:
json_log_object['data'].update(self.get_exc_fields(record))
return json.dumps(json_log_object)
def default():
log.warning("Starting with b3 values: {}".format(b3.values()))
with b3.SubSpan() as headers:
# Pretend to call a downstream service in the sub-span
log.warning("Calling downstream service with b3 values: {}".format(
b3.values()))
log.warning("Finishing with b3 values: {}".format(b3.values()))
return jsonify(b3.values())
def service():
log = logging.getLogger(app.name)
log.setLevel(logging.INFO)
log.info(app.name + " has been called.")
log.info("B3 span values: " + str(b3.values()))
with b3.SubSpan() as headers:
log.info("B3 subspan values: " + str(b3.values()))
log.debug("Making a request to service B")
r = requests.get(service_b, headers=headers)
log.debug("Service B said: " + str(r.text))
result = b3.values()
result["service"] = app.name
return jsonify(result)
def test_should_add_tracing_information(self):
# Given
with Flask("tracing").app_context():
# A mock LogRecord and B3 tracing information
created = time.time()
levelname = "INFO"
name = "Logger name"
record = MockLogRecord(created, levelname, name)
dt = datetime.fromtimestamp(time.time())
b3.start_span()
values = b3.values()
# When
# We update the record
sleuth._update_record(record)
# Then
# We should get tracing information
self.assertTrue(record.tracing_information)
# "[test,ba580718aefa94b9,ba580718aefa94b9,false] "
fields = record.tracing_information.strip()[1:-1].split(",")
self.assertEqual(fields[0], "tracing")
self.assertEqual(fields[1], values[b3.b3_trace_id])
self.assertEqual(fields[2], values[b3.b3_span_id])
self.assertEqual(fields[3], "false")
def test_should_update_span_info_on_subspan_start(self):
# Given
# We have a full set of span values
b3.start_span({b3_sampled: "1", b3_flags: "1"})
# When
# We start a subspan
span = b3.values()
b3._start_subspan()
# Then
# Values should now reflect the sub-span
subspan = b3.values()
self.assertEqual(span[b3_trace_id], subspan[b3_trace_id])
self.assertEqual(span[b3_span_id], subspan[b3_parent_span_id])
self.assertNotEqual(span[b3_span_id], subspan[b3_span_id])
self.assertEqual(span[b3_sampled], subspan[b3_sampled])
self.assertEqual(span[b3_flags], subspan[b3_flags])
def test_should_revert_span_info_on_subspan_end(self):
# Given
# We have a full set of span values and a subspan
b3.start_span({b3_sampled: "1", b3_flags: "1"})
span = b3.values()
b3._start_subspan()
# When
# We end the subspan
b3._end_subspan()
# Then
# Values should now reflect the sub-span
reverted = b3.values()
self.assertEqual(span[b3_trace_id], reverted[b3_trace_id])
self.assertEqual(span[b3_parent_span_id], reverted[b3_parent_span_id])
self.assertEqual(span[b3_span_id], reverted[b3_span_id])
self.assertEqual(span[b3_sampled], reverted[b3_sampled])
self.assertEqual(span[b3_flags], reverted[b3_flags])
def service():
log = logging.getLogger(app.name)
log.setLevel(logging.DEBUG)
log.info(app.name + " has been called.")
with b3.SubSpan() as headers:
log.info(
app.name +
" pretending to call a database that doesn't support B3 headers.")
log.info(app.name + " did a thing.")
result = b3.values()
result["service"] = app.name
return jsonify(result)
def test_should_maintain_sampled(self):
# Given
# Sampled is not set in the request headers
sampled = '0'
b3.start_span({b3_sampled: sampled})
# When
# We get b3 values and update onward request headers
values = b3.values()
headers = b3._start_subspan()
# Then
# The Sampled value should be maintained
self.assertEqual(sampled, values[b3_sampled])
self.assertEqual(sampled, headers[b3_sampled])
def test_should_not_set_sampled(self):
# Given
# Sampled is not set in the request headers
b3.start_span({})
# When
# We get b3 values and update onward request headers
values = b3.values()
headers = b3._start_subspan()
# Then
# Sampled should not be set and should
# remain absent from onward request headers
self.assertIsNone(values[b3_sampled])
self.assertFalse(b3_sampled in headers)
def test_should_maintain_trace_id(self):
# Given
# A trace ID in the B3 headers
trace_id = "Barbapapa"
b3.start_span({b3_trace_id: trace_id})
# When
# We get b3 values and update onward request headers
values = b3.values()
headers = b3._start_subspan()
# Then
# The incoming trace ID should be maintained
self.assertEqual(trace_id, values[b3_trace_id])
self.assertEqual(trace_id, headers[b3_trace_id])
def test_should_set_flags_for_debug(self):
# Given
# We have set debug on
b3.debug = True
b3.start_span({})
# When
# We get b3 values and update onward request headers
values = b3.values()
headers = b3._start_subspan()
# Then
# Flags should be set to 1 to indicate debug
self.assertEqual("1", values[b3_flags])
self.assertEqual("1", headers[b3_flags])
def test_should_maintain_flags_for_debug(self):
# Given
# Flags is set in the B3 headers
flags = '1'
b3.start_span({b3_flags: flags})
# When
# We get b3 values and update onward request headers
values = b3.values()
headers = b3._start_subspan()
# Then
# Flags should be set to 1 to indicate debug
self.assertEqual(flags, values[b3.b3_flags])
self.assertEqual(flags, headers[b3_flags])
def test_should_generate_root_span_ids(self):
# Given
# No B3 headers - this is the root span
b3.start_span({})
# When
# We get the B3 values
values = b3.values()
# Then
# Both trace ID and span ID should have been genenated
self.assertTrue(values[b3_trace_id])
self.assertTrue(values[b3_span_id])
# The IDs should be 16 characters of hex
self.assertTrue(re.match("[a-fA-F0-9]{16}", values[b3_trace_id]))
self.assertTrue(re.match("[a-fA-F0-9]{16}", values[b3_span_id]))
def _tracing_information():
"""Gets B3 distributed tracing information, if available.
This is returned as a list, ready to be formatted into Spring Cloud Sleuth compatible format.
"""
# We'll collate trace information if the B3 headers have been collected:
values = b3.values()
if values[b3.b3_trace_id]:
# Trace information would normally be sent to Zipkin if either of sampled or debug ("flags") is set to 1
# However we're not currently using Zipkin, so it's always false
# exported = "true" if values[b3.b3_sampled] == '1' or values[b3.b3_flags] == '1' else "false"
return [
current_app.name if current_app.name else " - ",
values[b3.b3_trace_id],
values[b3.b3_span_id],
"false",
]
def decorated():
log.warning("Using decorator: {}".format(b3.values()))
return jsonify(b3.values())
