feat: produce OpenTelemetry traces with hs-opentelemetry#3140
Conversation
|
Awesome work! 🔥 🔥
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. |
8c0e16a to
64a0ee9
Compare
|
The recent problem I'm seemingly stuck with is There's a more straightforward 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? |
|
@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 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. |
6b891c2 to
586e7a1
Compare
Not only that, you want traces in tests too, for one. The good news is
Good call @steve-chavez, thank you for the suggestion. Will try too. |
0830a45 to
dc882f1
Compare
|
Since now we have an postgrest/src/PostgREST/App.hs Lines 170 to 172 in 229bc77 postgrest/src/PostgREST/Observation.hs Lines 15 to 18 in 229bc77 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 postgrest/src/PostgREST/CLI.hs Line 50 in 7c6c056 For OTel, maybe the following would make sense: otelState <- Otel.init
App.run appState (Logger.logObservation loggerState >> OTel.tracer otelState)) |
dc882f1 to
7794848
Compare
Agreed, server timings definitely belong there. |
7794848 to
398206b
Compare
398206b to
4cd99c6
Compare
|
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. |
4cd99c6 to
94d2b9b
Compare
|
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. |
590d142 to
e809a65
Compare
|
A status update:
|
Hm. I looked at your fork. It depends on support for GHC 9.8 in 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? |
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. |
e809a65 to
4697009
Compare
650d008 to
ac33872
Compare
|
Update: rebased the PR against latest |
wolfgangwalther
left a comment
There was a problem hiding this comment.
Most things are smaller nits. I guess we need to get this over the line now.
| let tracer' = if configServerOtelEnabled conf && tracerIsEnabled tracer | ||
| then Just tracer | ||
| else Nothing |
There was a problem hiding this comment.
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?
There was a problem hiding this comment.
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.
There was a problem hiding this comment.
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?
There was a problem hiding this comment.
let us control
otel-enabledin 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.
PR here: NixOS/nixpkgs#512285 |
|
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. |
|
The following comments are still open:
What's the plan for getting these resolved? |
|
@wolfgangwalther they're being addressed, will push updates on Monday |
|
yes, precisely
|
| postgrest :: LogLevel -> AppState.AppState -> IO () -> Wai.Application | ||
| postgrest :: HasCallStack => LogLevel -> AppState.AppState -> IO () -> Wai.Application | ||
| postgrest logLevel appState connWorker = | ||
| OTel.middleware appState . |
There was a problem hiding this comment.
Now that we merged #4884, I think this middleware shouldn't be needed anymore?
Maybe we can root cause the perf issues once we integrate with the new ResponseObs too.
There was a problem hiding this comment.
This middleware's purpose is to pick up Trace ID from the request headers and initialize our tracer's parent_trace_id with it, so we'll produce traces that are part of traces' chain, thus ensuring their continuity so the trace viewer will be able to know they are the part of a certain transaction.
That could improve the performance though, now that hs-otel is the only Vault client
There was a problem hiding this comment.
I see. So if we could get rid of the traceHeaderMiddleware then the OTel middleware wouldn't be necessary right?
There was a problem hiding this comment.
Are all those changes to test/spec left-overs from before rebasing on top of the move to test/observability? It doesn't look like we need the changes to that extend - just passing Nothing in as the tracer should be enough here?
There was a problem hiding this comment.
Are all those changes to
test/specleft-overs from before rebasing
Not really. hs-opentelemetry provides hspec instrumentation, this wires it up.
It doesn't look like we need the changes to that extend - just passing
Nothingin as the tracer should be enough here?
Not anymore, I've upgraded AppState.otelTracer to a AppState.TracerState. OTOH a smart constructor i.o. L98 probably won't hurt.
It kind of makes sense to collect openelemetry from every source, tests included, and this makes our test suite ready for it. Although one could think it is preliminary, which is fair as well.
There was a problem hiding this comment.
If I'm not mistaken there is no way for me to enable instrumentation in spec tests other than changing the code to enable the config option. This indeed seems like dead code to me then. Let's introduce this once we have a way to actually use it.
| OTelNoConfigSupplied -> | ||
| pure $ "No OpenTelemetry configuration via environment variables is supplied. " <> "Please refer https://docs.postgrest.org/en/stable/references/observability.html#opentelemetry for details." |
There was a problem hiding this comment.
How can I trigger this?
I tried PGRST_OTEL_ENABLED=true postgrest-with-pg-18 -f test/spec/fixtures/load.sql postgrest-run, but that doesn't log this. I also tried with log-level debug, nope.
There was a problem hiding this comment.
throw OTEL_SDK_DISABLED=true in, that's when tracerIsEnabled tracer == false
There was a problem hiding this comment.
The problem is, though, it prevents propagating TraceID downstream. Luckily, we don't have to, yet.
More importantly, a default OTel configuration does collect all the traces (because OTEL_TRACES_SAMPLER's default parentbased_always_on means "same as for parent span, always_on if there's none), sends them to default OTEL_EXPORTER_OTLP_ENDPOINT of http://localhost:4317 and does propagate (OTEL_PROPAGATORS=…) trace ID, parent span ID and sampling type (tracecontext), along with custom metadata (baggage) downstream.
There was a problem hiding this comment.
The problem is, though, it prevents propagating
TraceIDdownstream. Luckily, we don't have to, yet.
Are you saying that PostgREST has a behavioral change in the PGRST_OTEL_ENABLED=true OTEL_SDK_DISABLED=true case? It should not have any.
There was a problem hiding this comment.
throw
OTEL_SDK_DISABLED=truein, that's whentracerIsEnabled tracer == false
I tried running Edit: My bad, I ran it on the wrong branch... the following still applies though:PGRST_OTEL_ENABLED=true OTEL_SDK_DISABLED=true PGRST_LOG_LEVEL=warn postgrest-with-pg-18 -f test/spec/fixtures/load.sql postgrest-run, but did not get a log message. Is this not something that is logged at all? Where does this message appear?
Maybe... there should just be a test for that, that I could read and understand.
|
|
||
| let TracerState{..} = getOTelTracer appState | ||
|
|
||
| when (isNothing ts'otelTracer && ts'enabled) $ observer OTelNoConfigSupplied |
There was a problem hiding this comment.
This check & observation / log message is happening at the wrong time, I think. When I enable otel via in-database configuration, but disable otel via OTEL_SDK_DISABLED=true, then I don't get the warning logged.
This indicates that at least this, but possibly other things, are not working with in-database configuration and/or reloadable configuration for otel-enabled in general.
|
@wolfgangwalther I'd like to pause this PR for the weekend — hs-opentelemetry 1.0 is literally being cooked as we speak and seems to be released any day now; it's a major update and upgrade in a lots of ways, in particular it has logs and metrics, and ticks all the boxes I could imagine and then some — looks like worth the wait, in other words |
|
Gotta be honest, I'm not enthusiastic about the 1.0 release. Among others, a huge part is iand675/hs-opentelemetry#252, which is a LLM-generated rewrite with a +36k/-9k diff merged within 5 days. Essentially, hs-opentelemetry is vibe-coded by now. |
Does that force us to stick to the old (pre 1.0) version and probably vendor (ie. fork) the library, similar to |
Neither of these seem attractive to me either. That being said, hs-opentelemetry is certainly less "core" to us than hasql. We can do without the former, but not the latter. Now, "without" can go two ways: Arguably a user could just run without opentelemetry support enabled (maybe even via a build flag or something? dunno). Or from a different perspective, we can just do without opentelemetry support in general - PostgREST has been working fine so far as well. Neither is possible wrt hasql. My personal current feeling is in direction of "there is no suitable library for us out there, we shouldn't do it". Not satisfying at all, especially given the work that has already gone into this. :( |
There is a growing risk of forks popping up from people that are more open to AI generated code and just want certain features... OTEL integration seems to be one of the most waited for. |
Not really an argument to support shipping vibe-coded dependencies :D. Edit: In fact it's a nice argument against depending on this: If somebody is open to AI-generated code, they can probably just vibe-code their own PostgREST with OTEL support. But those who are against it, can not get out of this. (I could not care less whether somebody wants to fork PostgREST and vibe-code their way to their own thing - this is Open Source after all) |
Fragmented ecosystem/community is still a problem for many and there is a risk of getting irrelevant once you are left behind with features... Which of course you are free to ignore - this is open source after all. |
* Introduces producing OpenTelemetry traces with hs-opentelemetry. * Adds OTel spans over the whole application loop and over each request processing phase * Preliminary OTel tracing support in spec tests * Disables tracing in load and memory tests fix deps
This is quite unfortunate after all the effort here 😞. Indeed I looked at iand675/hs-opentelemetry#252 and there are some C files that had no review, so we cannot put that version into a production release. I've been thinking of another way in the meantime, what if we do #4831 and then have another program forward the structured logs to the OTel destination?
Thoughts? |
We should implement structured logging anyway, yeah. |
Won't the forwarding to an OTel endpoint by the sidecar service work? Why not? |
Forwarding logs would do exactly that - provide logs. But the whole point of this PR is to add traces to the PostgREST code - and just relaying logging does not create any of them. There must be a misunderstanding of some sort - do you intend to do more than just logging and relaying these logs? |
I referenced https://opentelemetry.io/docs/specs/otel/compatibility/logging_trace_context/#json-formats above, that says:
My understanding is that by adding the above fields, we can convert the logs to traces? |
So, are you saying we should start logging all kinds of events like "request handling started", "planning started", "planning finished", "query started", "query finished", .. and so on? All the places in App.hs where |
Those look fit for |
Performance. OTEL instrumentation is based on sampling so it can stay "always on". There is also the question of transparent context propagation and much more. We can try that but I wouldn't hold my breath... |
|
As it doesn't look like we're going to move with this as-is, I'll mark this as draft until we decide on the right path forward. |

This PR introduces producing OpenTelemetry traces containing, among others, metrics same as in
ServerTimingheader from before.TODO:
build with Nix as well (for now Stack only)DONE for freemake an example of exporting log messageshs-opentelemetrydoesn't support logging, per Logging roadmap iand675/hs-opentelemetry#100makeseems like impossible without major refactoringgetTraceravailable globally: we're interested in using as many different spans as it makes sense, sogetTracershould be available everywhere, as described inhs-opentelemetry-sdk's READMEhs-opentelemetry-waimiddlewarelook into failing Windows buildshs-opentelemetry-sdkdepends onunix, tracking in Windows support iand675/hs-opentelemetry#109Running:
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:
stack build, and get its path withstack exec -- which postgrestnix-shell, thenpostgrest-with-postgresql-15 --fixture ./test/load/fixture.sql -- cat). Note the server URL, you'll need it when running PostgREST serverpostgrest-jwt --exp 36000 postgrest_test_anonymousTests
hspec tests are also instrumented, for those to produce traces you need to set
OTEL_*vars only: