feat: produce OpenTelemetry traces with hs-opentelemetry

[develop7]

This PR introduces producing OpenTelemetry traces containing, among others, metrics same as in ServerTiming header from before.

TODO:

• document oTel configuration
• make code location attributes show call sites instead of helpers
• build with Nix as well (for now Stack only) DONE for free
• make an example of exporting log messages hs-opentelemetry doesn't support logging, per Logging roadmap iand675/hs-opentelemetry#100
• make getTracer available globally: we're interested in using as many different spans as it makes sense, so getTracer should be available everywhere, as described in hs-opentelemetry-sdk's README seems like impossible without major refactoring
• make use of hs-opentelemetry-wai middleware
• look into failing Windows builds hs-opentelemetry-sdk depends on unix, tracking in Windows support iand675/hs-opentelemetry#109
• fix "memory test" failures (https://github.com/PostgREST/postgrest/actions/runs/7888534966/job/21526302784?pr=3140)
• fix dependency issues on 9.8 (https://github.com/PostgREST/postgrest/actions/runs/7888534966/job/21526300453?pr=3140)

Running:

I sort of gave up deploying and configuring all the moving bits locally, so you'd need to create the honeycomb.io account for this one (or ask me for the invite). After that, it's quite straightforward:

1. Build PostgREST executable with stack build, and get its path with stack exec -- which postgrest
2. Get a PostgreSQL server running (e.g. run nix-shell, then postgrest-with-postgresql-15 --fixture ./test/load/fixture.sql -- cat). Note the server URL, you'll need it when running PostgREST server
3. get a JWT token with default secret by running postgrest-jwt --exp 36000 postgrest_test_anonymous
4. Run PostgREST server with

   OTEL_EXPORTER_OTLP_ENDPOINT='https://api.honeycomb.io/' \
   OTEL_EXPORTER_OTLP_HEADERS="x-honeycomb-team=<honeycomb_api_key>"  \
   OTEL_SERVICE_NAME='PostgREST' OTEL_LOG_LEVEL='debug' OTEL_TRACES_SAMPLER='always_on' \
   PGRST_DB_URI='<postgresql_server_url>'   \
   postgrest-run 

5. request some data using the JWT token from above and check the honeycomb dashboard for the traces:

Tests

hspec tests are also instrumented, for those to produce traces you need to set OTEL_* vars only:

OTEL_EXPORTER_OTLP_ENDPOINT='https://api.honeycomb.io/' \
OTEL_EXPORTER_OTLP_HEADERS="x-honeycomb-team=<honeycomb_api_key>"  \
OTEL_SERVICE_NAME='PostgREST' OTEL_LOG_LEVEL='debug' OTEL_TRACES_SAMPLER='always_on' \
postgrest-test-spec

[steve-chavez]

Awesome work! 🔥 🔥

I sort of gave up deploying and configuring all the moving bits locally, so you'd need to create the honeycomb.io account for this one

Found this Nix flake that contains an OTel GUI: https://flakestry.dev/flake/github/FriendsOfOpenTelemetry/opentelemetry-nix/1.0.1

I'll try to integrate that once the PR is ready for review.

[develop7]

The recent problem I'm seemingly stuck with is hs-opentelemetry is using UnliftIO, which seems not quite composable with our (implicit, correct?) monad stack. So the deeper into the call stack the instrumented code is (the one I'm trying to wrap with inSpan), the more ridiculously complex it should be changed to be instrumented, i.e. https://github.com/PostgREST/postgrest/pull/3140/files#diff-5de3ff2b2d013b33dccece6ead9aeb61feffeb0fbd6e38779750511394cf9701R156-R157, up to the point I have no idea how to proceed further (e.g. wrapping App.handleRequests cases with their own spans, which is semantically correct)

There's a more straightforward MonadIO-involving opentelemetry library, with less activity and quite different approach to the telemetry data export (GHC eventlog → file/pipe by the GHC runtime). It looks less invasive approach, refactoring-wise, but requires more hoops to jump to actually deliver traces to Honeycomb/Lightstep/whatnot (pull eventlog → convert it to zipkin/jaeger/b3 → upload somewhere for analysis).

It also seems to boil down to the conceptual choice between online and offline traces' delivery-wise, or push and pull model.

@steve-chavez @wolfgangwalther @laurenceisla what do you think guys?

[steve-chavez]

@develop7 Would vault help? It was introduced on #1988, I recall it helped with IORef handling.

It's still used on

postgrest/src/PostgREST/Auth.hs

Lines 160 to 165 in d2fb67f

	jwtDurKey :: Vault.Key Double
	jwtDurKey = unsafePerformIO Vault.newKey
	{-# NOINLINE jwtDurKey #-}
	getJwtDur :: Wai.Request -> Maybe Double
	getJwtDur = Vault.lookup jwtDurKey . Wai.vault

I'm still not that familiar with OTel but the basic idea I had was to store these traces on AppState and export them async.

[steve-chavez]

@develop7 Recently merged #3213, which logs schema cache stats to stderr. Perhaps that can be used for introductory OTel integration instead? It might be easier since the scache stats are already in IO space.

[develop7]

Would vault help?

hs-opentelemetry is using it already

basic idea I had was to store these traces on AppState and export them async

Not only that, you want traces in tests too, for one.

The good news is hs-opentelemetry-utils-exceptions seems to be just what we need, let me try it.

Perhaps that can be used for introductory OTel integration instead?

Good call @steve-chavez, thank you for the suggestion. Will try too.

[develop7]

it works!

[steve-chavez]

Since now we have an observer function and Observation module

postgrest/src/PostgREST/App.hs

Lines 170 to 172 in 229bc77

	handleRequest :: AuthResult -> AppConfig -> AppState.AppState -> Bool -> Bool -> PgVersion -> ApiRequest -> SchemaCache ->
	Maybe Double -> Maybe Double -> (Observation -> IO ()) -> Handler IO Wai.Response
	handleRequest AuthResult{..} conf appState authenticated prepared pgVer apiReq@ApiRequest{..} sCache jwtTime parseTime observer =

postgrest/src/PostgREST/Observation.hs

Lines 15 to 18 in 229bc77

	data Observation
	= AdminStartObs (Maybe Int)
	| AppStartObs ByteString
	| AppServerPortObs NS.PortNumber

Perhaps we can add some observations for the timings?

Also the Logger is now used like:

postgrest/src/PostgREST/Logger.hs

Lines 53 to 54 in 7c6c056

	logObservation :: LoggerState -> Observation -> IO ()
	logObservation loggerState obs = logWithZTime loggerState $ observationMessage obs

postgrest/src/PostgREST/CLI.hs

Line 50 in 7c6c056

CmdRun -> App.run appState (Logger.logObservation loggerState))

For OTel, maybe the following would make sense:

otelState <- Otel.init

App.run appState (Logger.logObservation loggerState >> OTel.tracer otelState)) 

[develop7]

Perhaps we can add some observations for the timings?

Agreed, server timings definitely belong there.

[develop7]

Okay, the PR is in the cooking for long enough, let's pull the plug and start small. Let's have it reviewed while I'm fixing the remaining CI failures.

[wolfgangwalther]

hs-opentelemetry is, according to the repo, in alpha state. According to the TODO list above, the issue tracker and the repo description, it does not support:

• GHC 9.8.x
• Windows
• Metrics or Logging

I don't think we depend on this in the current state. And we should certainly not depend on an even-less-maintained fork of the same.

So to go forward here, there needs to be some effort put into the upstream package first, to make it usable for us.

[develop7]

A status update:

• GHC 9.8: hs-opentelemetry-sdk doesn't build against 9.8 because of hs-opentelemetry-exporter-otlp → proto-lens chain. Given the upstream of the latter being bit unresponsive for the suggestions to bump upper bounds, I've managed to make the latter build for 9.8 in develop7/proto-lens@985290f, but haven't figured out how to pick it up to the project since it depends on the google's protobuf compiler installed and the protobuf's source checked out. Another approach is to not use hs-o-sdk and hs-o-e-otlp altogether, which I probably should've tried way before.

[wolfgangwalther]

• GHC 9.8: hs-opentelemetry-sdk doesn't build against 9.8 because of hs-opentelemetry-exporter-otlp → proto-lens chain. Given the upstream of the latter being bit unresponsive for the suggestions to bump upper bounds, I've managed to make the latter build for 9.8 in develop7/proto-lens@985290f,

Hm. I looked at your fork. It depends on support for GHC 9.8 in ghc-source-gen. This repo has a PR, which just was updated 3 days ago. I wouldn't call that "unresponsive", yet. Once ghc-source-gen is GHC 9.8 compatible, you could open a PR to update bounds in proto-lens itself. But since the last release for GHC 9.6 support was in December... I would not expect this to take too long to get responded to. It certainly doesn't look like it's unmaintained.

I guess for GHC 9.8 support it's just a matter of time.

What about the other issues mentioned above? Were you able to make progress on those?

[mkleczek]

The recent problem I'm seemingly stuck with is hs-opentelemetry is using UnliftIO, which seems not quite composable with our (implicit, correct?) monad stack. So the deeper into the call stack the instrumented code is (the one I'm trying to wrap with inSpan), the more ridiculously complex it should be changed to be instrumented, i.e. https://github.com/PostgREST/postgrest/pull/3140/files#diff-5de3ff2b2d013b33dccece6ead9aeb61feffeb0fbd6e38779750511394cf9701R156-R157, up to the point I have no idea how to proceed further (e.g. wrapping App.handleRequests cases with their own spans, which is semantically correct)

There's a more straightforward MonadIO-involving opentelemetry library, with less activity and quite different approach to the telemetry data export (GHC eventlog → file/pipe by the GHC runtime). It looks less invasive approach, refactoring-wise, but requires more hoops to jump to actually deliver traces to Honeycomb/Lightstep/whatnot (pull eventlog → convert it to zipkin/jaeger/b3 → upload somewhere for analysis).

It also seems to boil down to the conceptual choice between online and offline traces' delivery-wise, or push and pull model.

@steve-chavez @wolfgangwalther @laurenceisla what do you think guys?

In my prototype I actually played with replacing HASQL Session with an https://github.com/haskell-effectful/effectful based monad to make it extensible:

https://github.com/mkleczek/hasql-api/blob/master/src/Hasql/Api/Eff/Session.hs#L37

Using it in PostgREST required some mixins usage in Cabal:

29b946e#diff-eb6a76805a0bd3204e7abf68dcceb024912d0200dee7e4e9b9bce3040153f1e1R140

Some work was required in PostgREST startup/configuration code to set-up appropriate effect handlers and middlewares but the changes were quite well isolated.

At the end of the day I think basing your monad stack on an effect library (effectful, cleff etc.) is the way forward as it makes the solution highly extensible and configurable.

[develop7]

Update: rebased the PR against latest master, updated hs-opentelemetry (with the Windows support merged!) & asked hs-opentelemetry maintainers to cut a new release in iand675/hs-opentelemetry#154 so we don't have to depend on forks again.

[develop7]

@mkleczek I've also added pg_tracing support via GUC, check it out

[steve-chavez]

I've also added pg_tracing support via GUC, check it out

As mentioned before, this PR is already too long, we shouldn't be adding more to it.. it's a lot to review as it is.

[develop7]

@steve-chavez done, extracted it to #4666
/cc @mkleczek

[steve-chavez]

An idea to test this.

Could we have opentelemetry-collector (included in Nixpkgs) collect all the generated OTel traces and then use its fileexporter to match the expected outputs?

I'm imagining the test could be similar to how we capture our schema cache snapshots (ref).

[laurenceisla]

Could we have opentelemetry-collector (included in Nixpkgs) collect all the generated OTel traces and then use its fileexporter to match the expected outputs?

@develop7 is this something that can be done here? The manual tests are working right now as mentioned in #3140 (comment), so maybe we could implement this test later on if it's not that feasible to do here? (cc. @steve-chavez)

[develop7]

re: tests with actual otel collector — I've managed to prototype collector-including tests that compile, fail and and now I'm working on making them pass and be useful.

[develop7]

the test is in, chose to manage collector binary from Haskell for a change

[steve-chavez]

Q: What does this test? 🤔

So my expectation was:

• To have a test that has a client doing some requests
• Capture the generated OTel output in a file

Is it possible to get close to that?

[develop7]

The test does one request, generates 5 (6 actually) spans and is making sure 1) all the spans of types specified in this file are present in the output, 2) they have spans of specified type as their parent (here all of them are of type request). Since spans are located by their unique spanId and parentSpanId respectively, this test also makes sure spans are linked properly; doesn't test for the lack of astray spans though, which matches the real life behavior IMO. This file is kind of scarce, I admit, but that's because the data in traces are either volatile (timestamps, IDs, timings) or fixed through the whole test (library name, SDK name, programming language, etc.). I've attached a sample collector output file for the reference, feel free to look it up and suggest more things to test: scratch_4.json

To think of it, I'd throw in matching against the SQL query, let me try writing it to the trace.

[steve-chavez]

I've attached a sample collector output file for the reference, feel free to look it up and suggest more things to test: scratch_4.json

Many thanks for that. By looking at the file I'm finally starting to understand OTel concepts (what's a resource, what's scope, etc).

How do you generate the json file? The way I'm thinking to test this:

• Generate the otel json file with some command.
• Use jq to filter out the non-deterministic parts
• Then compare it to a snapshotted file

I'm not sure if Haskell is the right tool here because so far it looks it results in more code. If we could do it with jq it would be less to maintain it seems.

[develop7]

How do you generate the json file?

I start an otelcol OpenTelemetry collector supplying it a configuration file generated by OTelHelper.collectorConfig, start a PostgREST instance wired to said collector instance, then perform requests to PostgREST instance, shut everything down (so traces get flushed for sure), both PostgREST and collector, and take the output file in the temporary directory containing traces' JSON.

[develop7]

If we could do it with jq it would be less to maintain it seems.

Maybe with optics instead? We do have optics-core & optics-extras through dependencies already, so no build time hit. Let me try that

[develop7]

Maybe with optics instead?

Nope, same amount of code, but harder to read :)

[steve-chavez]

Given there are lots of non-deterministic parts on the otel output, I don't think snapshot testing is right.. it doesn't help that much in understanding.

How about just matching the deterministic parts in Haskell? Things like the name = "hs-opentelemetry-instrumentation-wai", telemetry.sdk.name = hs-opentelemetry-sdk, etc.

I start an otelcol OpenTelemetry collector supplying it a configuration file generated by OTelHelper.collectorConfig, start a PostgREST instance wired to said collector instance, then perform requests to PostgREST instance, shut everything down (so traces get flushed for sure), both PostgREST and collector, and take the output file in the temporary directory containing traces' JSON.

It would be great if running the test actually persists that file somewhere so we can read it afterwards (helps in understanding for otel newcomers)

[develop7]

It would be great if running the test actually persists that file somewhere so we can read it afterwards (helps in understanding for otel newcomers)

Good point, it is now.

[develop7]

Discovered a way to relay metrics to OpenTelemetry collector with the otelcol's own https://github.com/open-telemetry/opentelemetry-collector-contrib/tree/main/receiver/prometheusreceiver, added a rough config draft to the OpenTelemetry page; should help work the lack of native metrics in hs-otel around for now.

@steve-chavez @wolfgangwalther I've realized opentelemetry.rst is too small for separate page, but for a section at observability.rst, it should be fine, WDYT?

[steve-chavez]

Discovered a way to relay metrics to OpenTelemetry collector with the otelcol's own https://github.com/open-telemetry/opentelemetry-collector-contrib/tree/main/receiver/prometheusreceiver, added a rough config draft to the OpenTelemetry page; should help work the lack of native metrics in hs-otel around for now.

Cool, that looks good.

@steve-chavez @wolfgangwalther I've realized opentelemetry.rst is too small for separate page, but for a section at observability.rst, it should be fine, WDYT?

Yes, it would fit better since observability is inside References too; integrations currently don't contain PostgREST features.

[wolfgangwalther]

The nix build seems to need some fixes for some of the opentelemetry dependencies. You can try to mark unbroken first, then see what the build error is etc.

I will have a look at the nixpkgs side of this as well.

[develop7]

You can try to mark unbroken first, then see what the build error is etc.

@wolfgangwalther it's tasty-quickcheck being upgraded in the snapshot to 0.11 and hs-otel-api wants < 0.11, see https://hydra.nixos.org/build/285112733/nixlog/1

Actually there's hs-opentelemetry-api v0.3.0.1 released sometime ago that would also let me drop my homemade workaround; I'll try with upgrading it first then.

UPD: all right, how do I unbreak a nix package for us?

[develop7]

@wolfgangwalther I've updated hs-otel deps to latest upstream versions, unbreaking the broken ones as a byproduct; upstream is a bit sloppy TBH — while they do update package sources and bump deps, but do not publish all the packages on hackage, ugh

[wolfgangwalther]

while they do update package sources and bump deps, but do not publish all the packages on hackage, ugh

Yeah, I noticed that while working on the Nixpkgs side to unbreak these deps.

I've updated hs-otel deps to latest upstream versions, unbreaking the broken ones as a byproduct;

Yeah, that's a fine approach for now, we will want to switch back to the Nixpkgs-provided versions eventually, though.

[develop7]

all right, cabal builds are green as well now, had to add few VCS deps to the cabal.project

[wolfgangwalther]

Most things are smaller nits. I guess we need to get this over the line now.

[wolfgangwalther]

Which scenario is config-server-otel-enabled = true and tracerIsEnabled = false? Aka can it happen that one tries to enable otel via the config option, but otel is effectively still disabled? How? Do / should we log this or throw an error or so?

[develop7]

Which scenario is config-server-otel-enabled = true and tracerIsEnabled = false? Aka can it happen that one tries to enable otel via the config option, but otel is effectively still disabled? How?

tracerIsEnabled == true when otel is enabled (it is by default) but no trace collectors to post them to have been configured, per the iand675/hs-opentelemetry#201. This results in resources being consumed for tracing but no traces actually make their way to a consumer. That's why I'm taking this into account and plugging up the case with an explicit noop.

Do / should we log this or throw an error or so?

We do not, but this is a great idea, and yes, we should, now that we have our own otel-related config parameter. Thank you for pointing that out. IMO this warrants for a warning rather than an hard error (so the user wouldn't have to configure the whole otel stack in order to continue playing around with postgrest). Let me add the thing in a jiff.

[develop7]

there seems no way to log a warning and continue, there's either "here's config value I've parsed" or fail "something bad happened". Failure it is then. UPD: OR I could move the tracerIsEnabled value to AppState, still emit a warning, just later on during app initialization and let us control otel-enabled in runtime which might come in handy for end user given how resource-consuming OTel currently is. @wolfgangwalther @steve-chavez WDYT?

[wolfgangwalther]

let us control otel-enabled in runtime which might come in handy for end user given how resource-consuming OTel currently is

You mean, I could start with otel-enabled = false, but provide all the setup for otel environment variables themselves (so tracerIsEnabled = true). Then, when I have specific use-case I want to look at, I enable otel-enabled = true via reloading and the data starts flowing?

Sounds useful to me.

[wolfgangwalther]

The nix build seems to need some fixes for some of the opentelemetry dependencies. You can try to mark unbroken first, then see what the build error is etc.

I will have a look at the nixpkgs side of this as well.

PR here: NixOS/nixpkgs#512285

[wolfgangwalther]

I rebased, resolved conflicts and addressed most of my own feedback from above. There's still some comments to look at - and some CI results, not sure whether I was able to test everything locally.

[wolfgangwalther]

The following comments are still open:

• feat: produce OpenTelemetry traces with hs-opentelemetry #3140 (comment)
• feat: produce OpenTelemetry traces with hs-opentelemetry #3140 (comment)

What's the plan for getting these resolved?

[develop7]

@wolfgangwalther they're being addressed, will push updates on Monday

[develop7]

yes, precisely