DEV Community: Stephen Sadowski

Honeycomb, Python, and I: an OpenTelemetry Horror Story (With a Happy Ending)

Stephen Sadowski — Mon, 18 Apr 2022 19:02:34 +0000

Background

I'm currently on day 1.5 of my Staycation where I'm trying to catch up on my MBA coursework, but it can be somewhat painful and I needed a break. I decided to take up the challenge of finally integrating distributed tracing into my web apps.

It's no surprise that my apps are mostly written using Sanic as I'm pretty involved with the project. I've been wanting to start testing honeycomb out as well, so it seemed the perfect opportunity to try out.

OpenTelemetry & Python: The Nightmare Begins

First thing I want to say is that the OpenTelemetry project is both admirable for its goals and awesome in its scope. There's a lot going for it.

Second thing I want to say is that the documentation sucks. And I'm not the only person that thinks so. But it's okay enough to kind of work out the kinks once you've been spinning for a bit.

The third thing I want to say is that there need to be better examples for both manual instrumentation and automatic instrumentation NOT using the Flask example. I love Flask, and it's definitely one of the most popular Python web frameworks, but if you search for "Python OpenTelemetry" that's pretty much all you get.

For reference they all pretty much include the following instructions:

In your shell

virtualenv venv
source ./venv/bin/activate
pip install opentelemetry-api
pip install opentelemetry-sdk
pip install opentelemetry-distro
pip install opentelemetry-instrumentation-flask
pip install flask
pip install requests

app.py:

from opentelemetry import trace
from opentelemetry.exporter.otlp.proto.grpc.trace_exporter import OTLPSpanExporter
from opentelemetry.sdk.trace import TracerProvider
from opentelemetry.sdk.trace.export import BatchSpanProcessor, ConsoleSpanExporter
from opentelemetry.instrumentation.flask import FlaskInstrumentor
from flask import Flask

app = Flask(__name__)
FlaskInstrumentor().instrument_app(app)

@app.route("/")
def hello_world():    # You can still use the OpenTelemetry API as usual to create custom spans    # within your trace    
    with tracer.start_as_current_span("do_work"):
        time.sleep(0.1) 
     return "Hello, World!"

This is great... but I'm not using Flask and Sanic does not yet have automatic instrumentation.

Honeycomb Tasting

I've been a fan of the idea of honeycomb for some time, and have interacted from time to time with the honeycomb team.

I had signed up for a honeycomb account some time back, and thankfully they understand the concept of try-before-you-buy with a free tier that I never got to take advantage of. After logging in and setting up a new API key, I went to work attempting manual instrumentation of my sanic app.

So first, let's just try exporting a span with a test script:

from opentelemetry import trace
from opentelemetry.exporter.otlp.proto.grpc.trace_exporter import OTLPSpanExporter
from opentelemetry.sdk.trace import TracerProvider
from opentelemetry.sdk.trace.export import SimpleSpanProcessor
from opentelemetry.sdk.resources import Resource

OTEL_EXPORTER_OTLP_ENDPOINT="https://api.honeycomb.io"
OTEL_EXPORTER_OTLP_HEADERS={'x-honeycomb-team': 'no-i-wont-tell-you'}
OTEL_SERVICE_NAME="test-service-for-hcotel"

resource = Resource({'name': 'test'})
provider = TracerProvider(resource=resource)
processor = SimpleSpanProcessor(OTLPSpanExporter(endpoint=OTEL_EXPORTER_OTLP_ENDPOINT, headers=OTEL_EXPORTER_OTLP_HEADERS))
provider.add_span_processor(processor)
trace.set_tracer_provider(provider)
tracer = trace.get_tracer(__name__)

with tracer.start_as_current_span("test-span"):
    print("test service")

Failure, Failure, Failure

My workflow often varies depending on location, time of day, phase of the moon, etc. My primary devices for development are a Lenovo X1 Nano running Fedora 35, a Dell XPS 8930 Desktop with some significant upgrades, an M1 Mac Mini, and a 14" MacBook Pro.

When developing in Python, on the linux systems, things Just Work™ but M1 macs still have some quirks. During this test, I was working on the MacBook Pro

GRPC Problems

On M1 macs, for some time now the grpcio wheel has been broken. There are a few different workarounds, but in some cases you won't even know you need them until you try testing out something that relies on it - say, the otel grpc trace exporter, and then you get a traceback like this:

Traceback (most recent call last):
  File "/Users/ssadowski/projects/otel-honeycomb-test/test.py", line 4, in <module>
    from opentelemetry.exporter.otlp.proto.grpc.trace_exporter import OTLPSpanExporter
  File "/Users/ssadowski/projects/otel-honeycomb-test/__pypackages__/3.10/lib/opentelemetry/exporter/otlp/proto/grpc/trace_exporter/__init__.py", line 20, in <module>
    from grpc import ChannelCredentials, Compression
  File "/Users/ssadowski/projects/otel-honeycomb-test/__pypackages__/3.10/lib/grpc/__init__.py", line 22, in <module>
    from grpc import _compression
  File "/Users/ssadowski/projects/otel-honeycomb-test/__pypackages__/3.10/lib/grpc/_compression.py", line 15, in <module>
    from grpc._cython import cygrpc
ImportError: dlopen(/Users/ssadowski/projects/otel-honeycomb-test/__pypackages__/3.10/lib/grpc/_cython/cygrpc.cpython-310-darwin.so, 0x0002): tried: '/Users/ssadowski/projects/otel-honeycomb-test/__pypackages__/3.10/lib/grpc/_cython/cygrpc.cpython-310-darwin.so' (mach-o file, but is an incompatible architecture (have 'x86_64', need 'arm64e'))

The solution for me was to do the following as part of my installation... sort of:

$ export PIP_NO_BINARY=grpcio

This gets me a bit farther, as now we get this weird error:

test service
Failed to export span batch, error code: StatusCode.UNAUTHENTICATED

Honeycomb's Bad Taste

There are a few things missing in honeycomb's documentation for using OpenTelemetry and unfortunately, that's not obvious. When reading through the docs, there are some significant misses that make honeycomb unusable as a collector, and what's worse if you're using the grpc exporter there are two major hurdles to surpass.

I spent a huge amount of time - maybe 6 hours - digging into the problem. I was flipping back and forth between honeycomb's docs, the open telemetry docs, and the open telemetry python repo digging through issues.

One of the big problems is that the python exporters do this bit of stupid in the grpc exporter on lines 152-153. Also it's clear the author knew the issue, because they specifically disable the pylint warning!

            except Exception as error:  # pylint: disable=broad-except
                logger.exception(error)

Yes, we just catch the exception and don't really provide any detail, which yes, in our case just told us the error listed above.

I kept digging, however, and found that honeycomb has experimental http support for open telemetry... I decided to give it a whirl and see if I could at least get a better error. Answer? Yes, and also answer too problem #1 with the honeycomb docs: the API endpoint was wrong. After switching to the http exporter, the error changed:

test service
Failed to export batch code: 400, reason: {"error":"invalid OTLP endpoint - should you be sending to /v1/traces?, see API docs https://docs.honeycomb.io/"}

Well gosh, probably I should be sending my traces there. So I updated my endpoint and switched back to grpc. Bad move.

test service
Failed to export span batch, error code: StatusCode.UNAUTHENTICATED

Well crap. Back to http? But first - is the http exporter really that much better?

     _logger.error(
                    "Failed to export batch code: %s, reason: %s",
                    resp.status_code,
                    resp.text,
                )

So yes, we'll get significantly more detail fromt he http exporter. But what did we get?

test service
Failed to export batch code: 401, reason: {"message":"missing 'x-honeycomb-dataset' header"}

Now wait a minute, that's not even a header the doc says to use... so is that problem 2? If I add the header, what do I get from the http exporter this time?

test service

Success? Yes! I was able to validate that the span was present, and that's what I needed.

Making the changes to the grpc exporter got the same results, and so clearly that was the issue.

In the end, I was able to start exporting spans to honeycomb and could take my learning with me.

Gotta Go Fast

So with no automatic instrumentation, how can we get things going quickly?

Off To The Races

Like many python frameworks, Sanic has a method to hook into the request/response cycle. In Sanic, also like many python frameworks, we call this middleware and we can do some execution before and after. We also have some convenience decorators, which I generally don't use outside of doing some POCs. Because this is a POC, let's set up our hooks!


@app.on_request
async def otel_req_middleware(request: request.Request) -> None:
    route_name = request.route.name if request.route else 'Error' # set a default route name
                                                                  # necessary because route isn't
                                                                  # set on some errors like NotFound
    request.ctx.span = tracer.start_span(name=route_name)         # create our span
    request.ctx.span.add_event("route", {"path": request.path})   # add our path as an event


@app.on_response
async def otel_rsp_middleware(request: request.Request, 
        response: response.HTTPResponse) -> None:
    try:
        if request.ctx.span:
            request.ctx.span.end()  # close the span, send to collector
    except Exception as e:
        print(e)                    # TODO: convert to logger, catch specific exceptions


@app.exception(exceptions.SanicException)
async def otel_exc_middleware(request: request.Request,
            exception: exceptions.SanicException) -> response.HTTPResponse:
    request.ctx.span.set_status(Status(StatusCode.ERROR))  # make sure to flag span as containing an error
    request.ctx.span.add_event("exception",
        {"data": traceback.extract_stack().format()})      # Add an error event
    return response.json({"error": str(exception), "status_code": exception.status_code},
        status=exception.status_code)                      # return our error

What's Happening Here?

The request middleware executes before the main portion of the request, so in the

@app.on_request

function, I initialize the span and add an event that tells me either that it's a route or an error. The route will always be present unless a NotFound exception has bubbled up from the router because the route hasn't been defined.

In the

@app.on_response

function, I close the span and in this situation, the span is exported to the collector.

The exception function sets the span to contain an error, and add an event to contain the trace for the exception.

Wrapping It All Up

At this point, spans are being exported to honeycomb for both successful requests and errors, so the Otel POC is largely complete. The big question is do I carry this further and add automatic instrumentation to Sanic, or do I complete the larger POC for the service first?

For Sanic

The answer is that we're trying to help Sanic grow up, and it would be really helpful if we natively supported Open Telemetry either as an add-on package or as part of Sanic Extensions. Either way, it's on my to-do list to get this done, but for now I have a pattern to work with Honeycomb in a way that will start to get me the observability metrics I need.

Outstanding Issues

Update Open Telemetry documentation, possibly through PR
Update GRPC exporter, possibly through PR, to return better errors
Open issue with Honeycomb for them to update their python documentation

Takeaways

Like so many efforts, this implementation was born out of necessity. I was somewhat aware of the issues with Open Telemetry and Python because of my long time friend Michael Stella had already fought some of the same battles.

I am a bit disappointed with the issues I had to uncover on my own with Honeycomb, but I'm not deterred by them. I'm excited to make it to the next steps for my own efforts, and I hope that this effort will help others, even outside the Sanic community, integrate observability and distributed tracing with their python apps and services.

With all of that being said - this was a great challenge and I learned lots. I'm very excited about the future of Open Telemetry and establishing a pattern for observability for my own services. I think that if my experience can help anyone shave down time it takes to get up and running with Otel on python, it was totally worth it.

"Speed" in Async Web Frameworks

Stephen Sadowski — Tue, 16 Jun 2020 13:31:40 +0000

This was simultaneously published on my blog

Over the weekend of 2020-06-06/07, Cal Patterson's post "Async Python is not faster" popped on my radar across multiple link aggregators. I agree - async python is not "faster," but I do have some thoughts of my own on the subject.

To begin I have a few caveats:
a) I am not an expert developer
b) I am not an expert on async
c) I am involved with the Sanic project, a python async web framework

With those out of the way, I'd like to talk a bit about the value of non-blocking io in a very simple way.

Consider this (and yes, it too is slightly unrealistic):
You are hungry. You decide you want to eat five hamburgers to satiate your hunger. To get those hamburgers, you go to the nearest quick-serve restaurant (McSynchronous's, or Micky Sync's) and order them.

This restaurant has one cook and that cook has only the capacity to make one burger at a time. It is not a great set up, but it does the job. It takes some time to cook each burger patty and assemble the burger, but in order to make it easy on you, the restaurant will give you each burger as soon as it is ready. Assuming each burger takes two minutes to make and assemble, after ten minutes you will have all of your burgers.

This looks like the following:

(1) order
(2) start burger 
(3) prep burger (two minutes)
(4) deliver burger 
(5) repeat steps 2 through 4 four times

Total time: ten minutes.

Down the street is another joint (this one is called Async & Await Burger) that also has one cook, but this cook has the capability prep multiple burgers at the same time. For this cook, it also takes two minutes to prep each burger, but because the cook has the advantage of being able to prep multiple burgers together, they can be delivered faster. This is done because the cook does not have to focus on each burger one at a time, but instead can start a burger and then start the next burger, returning to each burger as it is finished.

This looks like the following:

(1) order
(2) start burgers 1-5
(3) prep burgers 1-5 (two minutes each, simultaneously)
(4) deliver burgers

Total time: two minutes.

Finally let us add a restriction to our A&A Burger scenario: there is only capacity to prep one burger at a time. In this scenario, despite the cook being able to handle multiple burgers, it is not possible, and therefore it will take the cook ten minutes, just like at Micky Sync's.

Imagine, however, that you want just one burger. A&A and Micky Sync's both take the same amount of time to prepare just one burger, so there is no speed advantage at all.

All of this is the same for synchronous and asynchronous web frameworks and their "speed" in general. The ability for one process to handle multiple simultaneous requests is the advantage of asynchronous operations. If you place a synchronous or blocking request (our capacity to prep only one burger at a time, remember) the advantage is removed.

I have selected two highly regarded python frameworks to demonstrate this: falcon, served by gunicorn, and starlette, served by uvicorn. The code is as on parity as I can make them for synchronous and asynchronous as possible:

falcon:

import falcon
import time

class DefaultResource:
    def on_get(self, req, resp):
        """Handles GET requests"""
        time.sleep(5)
        resp.media = "200 OK"

falconapi = falcon.API()
falconapi.add_route('/', DefaultResource())

to serve:

gunicorn app:falconapi

starlette:

from starlette.applications import Starlette
from starlette.responses import PlainTextResponse
from starlette.routing import Route
import asyncio

async def default(request):
    await asyncio.sleep(5)
    return PlainTextResponse("200 OK")


starletteapi = Starlette(debug=True, routes=[
    Route('/', default),
])

to serve:

uvicorn app:starletteapi

To illustrate this, I used a simple (and old) tool - ab, making 5 requests at the same time as follows:

ab -n 5 -c 5 http://localhost:8000/

Results for falcon:

This is ApacheBench, Version 2.3 <$Revision: 1874286 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking localhost (be patient).....done


Server Software:        gunicorn/20.0.4
Server Hostname:        localhost
Server Port:            8000

Document Path:          /
Document Length:        8 bytes

Concurrency Level:      5
Time taken for tests:   25.031 seconds
Complete requests:      5
Failed requests:        0
Total transferred:      795 bytes
HTML transferred:       40 bytes
Requests per second:    0.20 [#/sec] (mean)
Time per request:       25031.488 [ms] (mean)
Time per request:       5006.298 [ms] (mean, across all concurrent requests)
Transfer rate:          0.03 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.3      1       1
Processing:  5006 11014 6527.0  12515   20025
Waiting:     5005 11013 6527.2  12515   20024
Total:       5007 11014 6526.9  12516   20025
ERROR: The median and mean for the initial connection time are more than twice the standard
       deviation apart. These results are NOT reliable.

Percentage of the requests served within a certain time (ms)
  50%  10013
  66%  15018
  75%  15018
  80%  20025
  90%  20025
  95%  20025
  98%  20025
  99%  20025
 100%  20025 (longest request)

Results for starlette:

This is ApacheBench, Version 2.3 <$Revision: 1874286 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking localhost (be patient).....done


Server Software:        uvicorn
Server Hostname:        localhost
Server Port:            8000

Document Path:          /
Document Length:        6 bytes

Concurrency Level:      5
Time taken for tests:   10.007 seconds
Complete requests:      5
Failed requests:        0
Total transferred:      695 bytes
HTML transferred:       30 bytes
Requests per second:    0.50 [#/sec] (mean)
Time per request:       10007.417 [ms] (mean)
Time per request:       2001.483 [ms] (mean, across all concurrent requests)
Transfer rate:          0.07 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    1   0.5      1       1
Processing:  5003 5003   0.2   5003    5004
Waiting:     5002 5003   0.5   5003    5003
Total:       5003 5004   0.6   5004    5005

Percentage of the requests served within a certain time (ms)
  50%   5004
  66%   5005
  75%   5005
  80%   5005
  90%   5005
  95%   5005
  98%   5005
  99%   5005
 100%   5005 (longest request)

Finally, starlette with a blocking call (time.sleep(5)) instead of await asyncio.sleep(5):

This is ApacheBench, Version 2.3 <$Revision: 1874286 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking localhost (be patient).....done


Server Software:        uvicorn
Server Hostname:        localhost
Server Port:            8000

Document Path:          /
Document Length:        6 bytes

Concurrency Level:      5
Time taken for tests:   25.036 seconds
Complete requests:      5
Failed requests:        0
Total transferred:      695 bytes
HTML transferred:       30 bytes
Requests per second:    0.20 [#/sec] (mean)
Time per request:       25035.827 [ms] (mean)
Time per request:       5007.165 [ms] (mean, across all concurrent requests)
Transfer rate:          0.03 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    1   0.6      1       2
Processing:  5009 17023 6716.0  20026   20026
Waiting:     5007 17022 6716.5  20026   20026
Total:       5009 17024 6716.6  20028   20028

Percentage of the requests served within a certain time (ms)
  50%  20027
  66%  20028
  75%  20028
  80%  20028
  90%  20028
  95%  20028
  98%  20028
  99%  20028
 100%  20028 (longest request)

As you can see, this is almost exactly the same as falcon.

With web APIs, things are rarely this simple, and there are other advantages to be found with the level of maturity of the ecosystem (synchronous libraries have had longer time to get things right) and one should never overlook ease of use to make sure things are done correctly, but the general idea is as follows:

Much of the "speed" of async IO comes from being able to do additional work while the other work is in progress, but does not need attention. In the simple tests above, this is serving a basic GET request, but it applies everywhere.