Honeycomb doesn't correctly instrument the new /api/searchLocations streaming mechanism

[simonw]

Fun bug this one. The new /api/searchLocations?all=1 parameter added in #367 uses a Django StreamingHttpResponse to efficiently paginate through all matching records and return all of them. But... in Honeycomb a trace for that looks like this:

https://ui.honeycomb.io/vaccinateca/datasets/vial-staging/result/zMuwmKiKC8a/trace/7BpC1kJnKFN

This should have 20 SQL queries inside the search_locations section, since we are returning 10,000 results and the code works by keyset-paginating 500 at a time.

My hunch is that this is because Honeycomb only instruments the Django view - but those SQL queries aren't executed during the view function, they are executed outside of it when the wrapping Django code starts iterating through the streaming response.

[simonw]

Relevant code:

vial/vaccinate/api/search.py

Lines 64 to 94 in 885484e

	def stream():
	if callable(formatter.start):
	yield formatter.start(qs)
	else:
	yield formatter.start
	started = False
	for location in stream_qs:
	if started and formatter.separator:
	yield formatter.separator
	started = True
	yield formatter.transform(location)
	if callable(formatter.end):
	yield formatter.end(qs)
	else:
	yield formatter.end
	if debug:
	if all:
	return JsonResponse({"error": "Cannot use both all and debug"}, status=400)
	output = "".join(stream())
	if formatter.content_type == "application/json":
	output = json.dumps(json.loads(output), indent=2)
	return render(
	request,
	"api/search_locations_debug.html",
	{
	"output": mark_safe(escape(output)),
	},
	)
	return StreamingHttpResponse(stream(), content_type=formatter.content_type)

[simonw]

Tweeted about this in the hope that someone has a suggestion: https://twitter.com/simonw/status/1385040013369298944

[alexmv]

I also asked in the Honeycomb slack.

[simonw]

Here's the relevant beeline middleware - it looks like it doesn't take the weirdness of streaming responses into account: https://github.com/honeycombio/beeline-python/blob/4bbbb9ae1279cab0a5a33c7533a783436e4d3916/beeline/middleware/django/__init__.py#L1

[simonw]

Maybe this could be as easy as decorating that stream() function with @beeline.traced("search_locations_stream")?

[simonw]

That did at least give me a trace: https://ui.honeycomb.io/vaccinateca/datasets/vial-staging/result/cdvkXnwpYHa/trace/8VayW1fCoV2

It doesn't include the SQL queries that ran as part of the operation though, and it appears to be independent of the overall span for that HTTP request, which I think is this one: https://ui.honeycomb.io/vaccinateca/datasets/vial-staging/result/xnc9HP43C7g/trace/oy5gNzZYBaH

[simonw]

https://github.com/honeycombio/beeline-python/blob/12a2513c2161cff840999eba31dbb7cb3ff213ba/beeline/__init__.py#L220-L221

    def traced(self, name, trace_id=None, parent_id=None):
        return traced_impl(tracer_fn=self.tracer, name=name, trace_id=trace_id, parent_id=parent_id)

Maybe I can pass in an explicit trace_id to the decorator?

[simonw]

That almost worked, but the parent_id field is missing:

[simonw]

With that fix: https://ui.honeycomb.io/vaccinateca/datasets/vial-staging/result/d9D96M3qpnM

And a trace: https://ui.honeycomb.io/vaccinateca/datasets/vial-staging/result/d9D96M3qpnM/trace/qF9xrEWTGPs

The trace still doesn't capture the database queries that were executed though.

[simonw]

I don't think those database query spans are being recorded in Honeycomb at all. Here's a snapshot from when I loaded one of those endpoints:

It has the queries for user and session, but there's nothing else there - which suggests that the queries executed as part of the stream() function were not sent to Honeycomb.

[simonw]

https://github.com/honeycombio/beeline-python/blob/12a2513c2161cff840999eba31dbb7cb3ff213ba/beeline/middleware/django/__init__.py#L40-L45

class HoneyDBWrapper(object):

    def __call__(self, execute, sql, params, many, context):
        # if beeline has not been initialised, just execute query
        if not beeline.get_beeline():
            return execute(sql, params, many, context)

My hunch is that beeline.get_beeline() returns None by the time those DB queries are executed, due to the beeline.finish_trace(root_span) line in this bit of their code:

https://github.com/honeycombio/beeline-python/blob/12a2513c2161cff840999eba31dbb7cb3ff213ba/beeline/middleware/django/__init__.py#L108-L128

[simonw]

Django docs have some clues here: https://docs.djangoproject.com/en/3.2/topics/http/middleware/#dealing-with-streaming-responses

We would need to roll our own version of the beeline Django middleware, and maybe contribute that back upstream later on.

[simonw]

I think the trick is to implement an alternative create_http_event() method which, instead of directly calling beeline.finish_trace(root_span), instead (for streaming responses only) does response.streaming_content = wrap_streaming_content(response.streaming_content) where the wrapping function iterates through the original and then calls beeline.finish_trace(root_span) at the very end.

https://github.com/honeycombio/beeline-python/blob/12a2513c2161cff840999eba31dbb7cb3ff213ba/beeline/middleware/django/__init__.py#L108-L128

[alexmv]

honeycombio/beeline-python#166