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())