Troubleshoot logflare analytics 401 Unauthorized response

[jeffmccune]

Questions

1. How should / could I troubleshoot 401 Unauthorized response bodies from the Next.js studio service backend, received by the browser?
2. How can I enable request logging / debug logging on the studio service?
3. How can I find the request id returned in the 401 response body?
4. Are there better techniques to troubleshoot the studio service?

Context

I have a self-hosted setup in both kubernetes and docker-compose. The kubernetes deployment is a faithful translation of the current official docker-compose file in the main branch. Nearly everything is working with full parity between the two, except logs, which I'm working on presently. I have both running simultaneously to compare behavior.

Expected behavior

In the docker compose, fetching http://localhost:8000/project/default/logs/edge-logs?ite=&its= correctly returns the Kong API gateway logs.

Actual behavior

In my kubernetes cluster, fetching the same path, https://api.example.com/project/default/logs/edge-logs?ite=&its= returns:

{
  "code": 401,
  "message": "Unauthorized",
  "requestId": "4561f640-f54a-4464-9ad6-47a434c596ec"
}

I can see the fetch request in the browser, and I can see this request makes it through the Kong API gateway and is destined for the studio service:

k logs -l app.kubernetes.io/name=kong -f | grep edge-logs

127.0.0.6 - - [30/Dec/2023:16:28:27 +0000] "GET /api/projects/default/analytics/endpoints/logs.all?project=default&sql=%0ASELECT... HTTP/1.1" 200 98 "https://api.example.som/project/default/logs/edge-logs?ite=&its=" "Mozilla/5.0"

I assume this request is sent to the studio given this route:

services:
  ## Protected Dashboard - catch all remaining routes
  - name: dashboard
    _comment: 'Studio: /* -> http://studio:3000/*'
    url: http://studio:3000/
    routes:
      - name: dashboard-all
        strip_path: true
        paths:
          - /
    plugins:
      - name: cors
      - name: basic-auth
        config:
          hide_credentials: true

However, I'm struggling to figure out why the request is unauthorized. The studio logs are empty in both docker-compose and kubernetes:

❯ docker logs supabase-studio
  ▲ Next.js 13.5.3
  - Local:        http://8bee876c6fa4:3000
  - Network:      http://172.31.0.12:3000

 ✓ Ready in 408ms

❯ k logs -l app.kubernetes.io/name=studio
  ▲ Next.js 13.5.3
  - Local:        http://studio-74f55c4b8-92tbk:3000
  - Network:      http://10.65.246.88:3000

 ✓ Ready in 104ms

Lastly, I've searched through all of the services container log outputs and I can't find that request id (4561f640-f54a-4464-9ad6-47a434c596ec) anywhere. Is this expected?

Please advise, thank you!

[jeffmccune]

I verified the request is going from kong to studio by incorporating the studio pod into the service mesh. This allows me to observe the request id from kong to studio to analytics, but it's still unclear why the request is unauthorized.

k logs -l app.kubernetes.io/name=studio -c istio-proxy | grep -i cac80416-b6f0-4b3f-a889-e079244d175d | jq .

{
  "protocol": "HTTP/1.1",
  "authority": "analytics:4000",
  "route_name": "default",
  "upstream_local_address": "10.65.200.220:53792",
  "bytes_sent": 24,
  "requested_server_name": null,
  "upstream_host": "10.65.246.126:4000",
  "start_time": "2023-12-30T20:49:23.262Z",
  "user_agent": "node",
  "x_forwarded_for": null,
  "client_ip": null,
  "path": "/api/endpoints/query/logs.all?project=default&sql=%0ASELECT%0A--+log-event-chart%0A++timestamp_trunc%28t.timestamp%2C+minute%29+as+timestamp%2C%0A++count%28t.timestamp%29+as+count%0AFROM%0A++edge_logs+t%0A++cross+join+unnest%28metadata%29+as+m%0A++cross+join+unnest%28m.request%29+as+request%0A++cross+join+unnest%28m.response%29+as+response%0A++where+t.timestamp+%3E+%272023-12-30T13%3A00%3A00.000Z%27%0AGROUP+BY%0Atimestamp%0AORDER+BY%0A++timestamp+ASC%0A++&ref=default&project_tier=ENTERPRISE",
  "method": "GET",
  "upstream_cluster": "outbound|4000||analytics.dev-jeff.svc.cluster.local",
  "response_flags": "-",
  "upstream_transport_failure_reason": null,
  "bytes_received": 0,
  "downstream_remote_address": "10.65.200.220:45902",
  "downstream_local_address": "10.64.27.78:4000",
  "response_code_details": "via_upstream",
  "status_code": 401,
  "request_id": "cac80416-b6f0-4b3f-a889-e079244d175d",
  "duration": 6,
  "upstream_service_time": null
}

[jeffmccune]

I've verified it's definitely logflare by enabling debug logs with LOGFLARE_LOG_LEVEL=debug but I'm still not sure why logflare responds with a 401.

22:18:53.330 [debug] GET /api/endpoints/query/logs.all

22:18:53.331 [debug] Processing with LogflareWeb.EndpointsController.query/2
  Parameters: %{"iso_timestamp_start" => "2023-12-30T21:00:00.000Z", "project" => "default", "project_tier" => "ENTERPRISE", "ref" => "default", "sql" => "select id, timestamp, event_message, request.method, request.path, response.status_code\n  from edge_logs\n  cross join unnest(metadata) as m\n  cross join unnest(m.request) as request\n  cross join unnest(m.response) as response\n  \n  order by timestamp desc\n  limit 100\n  ", "token_or_name" => "logs.all"}
  Pipelines: [:api, :require_endpoint_auth]

22:18:53.334 [debug] QUERY OK source="oauth_access_tokens" db=1.6ms queue=1.6ms idle=840.4ms
SELECT o0."id", o0."token", o0."refresh_token", o0."expires_in", o0."revoked_at", o0."scopes", o0."previous_refresh_token", o0."resource_owner_id", o0."application_id", o0."description", o0."inserted_at", o0."updated_at" FROM "oauth_access_tokens" AS o0 WHERE (o0."token" = $1) ["REDACTED"]

22:18:53.338 [debug] QUERY OK source="users" db=1.4ms queue=1.2ms idle=844.3ms
SELECT u0."id", u0."email", u0."provider", u0."token", u0."api_key", u0."old_api_key", u0."email_preferred", u0."name", u0."image", u0."email_me_product", u0."admin", u0."phone", u0."bigquery_project_id", u0."bigquery_dataset_location", u0."bigquery_dataset_id", u0."bigquery_udfs_hash", u0."bigquery_processed_bytes_limit", u0."api_quota", u0."valid_google_account", u0."provider_uid", u0."company", u0."billing_enabled", u0."endpoints_beta", u0."preferences", u0."inserted_at", u0."updated_at" FROM "users" AS u0 WHERE (u0."api_key" = $1) ["REDACTED"]

22:18:53.341 [debug] QUERY OK source="endpoint_queries" db=1.2ms decode=0.1ms queue=1.4ms idle=847.6ms
SELECT e0."id", e0."token", e0."name", e0."query", e0."language", e0."source_mapping", e0."sandboxable", e0."cache_duration_seconds", e0."proactive_requerying_seconds", e0."max_limit", e0."enable_auth", e0."user_id", e0."sandbox_query_id", e0."inserted_at", e0."updated_at" FROM "endpoint_queries" AS e0 WHERE ((e0."name" = $1) AND (e0."user_id" = $2)) ["logs.all", 1]

22:18:53.342 [debug] Sent 401 in 11ms

[jeffmccune]

I notice the endpoint_queries table is empty, which might explain the 401 Unauthorized response. I also see this error when the analytics pod starts up, which explains why the endpoint queries table is empty. I'm curious what's causing this error, I don't see it in the docker-compose setup. Could it be related to changing the LOGFLARE_API_KEY?

23:04:11.994 [error] Task #PID<0.8065.0> started from Logflare.Supervisor terminating
** (MatchError) no match of right hand side value: {:error, #Ecto.Changeset<action: :insert, changes: %{name: "logs.all", query: "with retention as (\n  select (\n    CASE\n      WHEN @project_tier = 'FREE' THEN TIMESTAMP_SUB(CURRENT_TIMESTAMP(), INTERVAL 1 day)\n      WHEN @project_tier = 'PRO' THEN TIMESTAMP_SUB(CURRENT_TIMESTAMP(), INTERVAL 7 day)\n      WHEN (@project_tier = 'PAYG' OR @project_tier = 'ENTERPRISE') THEN TIMESTAMP_SUB(CURRENT_TIMESTAMP(), INTERVAL 90 day) \n      ELSE  TIMESTAMP_SUB(CURRENT_TIMESTAMP(), INTERVAL 1 day) \n    END\n  ) as date\n),\n\nedge_logs as (\nselect \n  t.timestamp,\n  t.id, \n  t.event_message, \n  t.metadata \nfrom retention, `cloudflare.logs.prod` as t\n  cross join unnest(metadata) as m\nwhere\n  -- order of the where clauses matters\n  -- project then timestamp then everything else\n  t.project = @project\n  AND CASE WHEN COALESCE(@iso_timestamp_start, '') = '' THEN  TRUE ELSE  cast(t.timestamp as timestamp) > cast(@iso_timestamp_start as timestamp) END\n  AND CASE WHEN COALESCE(@iso_timestamp_end, '') = '' THEN TRUE ELSE cast(t.timestamp as timestamp) <= cast(@iso_timestamp_end as timestamp) END\n  AND cast(t.timestamp as timestamp) > retention.date\norder by\n  cast(t.timestamp as timestamp) desc\n),\n\npostgres_logs as (\n  select \n  t.timestamp,\n  t.id, \n  t.event_message, \n  t.metadata\nfrom retention, `postgres.logs` as t\nwhere\n  -- order of the where clauses matters\n  -- project then timestamp then everything else\n  t.project = @project\n  AND CASE WHEN COALESCE(@iso_timestamp_start, '') = '' THEN  TRUE ELSE  cast(t.timestamp as timestamp) > cast(@iso_timestamp_start as timestamp) END\n  AND CASE WHEN COALESCE(@iso_timestamp_end, '') = '' THEN TRUE ELSE cast(t.timestamp as timestamp) <= cast(@iso_timestamp_end as timestamp) END\n  AND cast(t.timestamp as timestamp) > retention.date\n  order by cast(t.timestamp as timestamp) desc\n),\n\nfunction_edge_logs as (\nselect \n  t.timestamp,\n  t.id, \n  t.event_message, \n  t.metadata \nfrom retention, `deno-relay-logs` as t\n  cross join unnest(t.metadata) as m\nwhere\n  CASE WHEN COALESCE(@iso_timestamp_start, '') = '' THEN  TRUE ELSE  cast(t.timestamp as timestamp) > cast(@iso_timestamp_start as timestamp) END\n  AND CASE WHEN COALESCE(@iso_timestamp_end, '') = '' THEN TRUE ELSE cast(t.timestamp as timestamp) <= cast(@iso_timestamp_end as timestamp) END\n  and m.project_ref = @project\n  AND cast(t.timestamp as timestamp) > retention.date\norder by cast(t.timestamp as timestamp) desc\n),\n\nfunction_logs as (\nselect \n  t.timestamp,\n  t.id, \n  t.event_message, \n  t.metadata \nfrom retention, `deno-subhosting-events` as t\n  cross join unnest(t.metadata) as m\nwhere\n  -- order of the where clauses matters\n  -- project then timestamp then everything else\n  m.project_ref = @project\n  AND CASE WHEN COALESCE(@iso_timestamp_start, '') = '' THEN  TRUE ELSE  cast(t.timestamp as timestamp) > cast(@iso_timestamp_start as timestamp) END\n  AND CASE WHEN COALESCE(@iso_timestamp_end, '') = '' THEN TRUE ELSE cast(t.timestamp as timestamp) <= cast(@iso_timestamp_end as timestamp) END\n  AND cast(t.timestamp as timestamp) > retention.date\norder by cast(t.timestamp as timestamp) desc\n),\n\nauth_logs as (\nselect \n  t.timestamp,\n  t.id, \n  t.event_message, \n  t.metadata \nfrom retention, `gotrue.logs.prod` as t\n  cross join unnest(t.metadata) as m\nwhere\n  -- order of the where clauses matters\n  -- project then timestamp then everything else\n  -- m.project = @project\n  t.project = @project\n  AND CASE WHEN COALESCE(@iso_timestamp_start, '') = '' THEN  TRUE ELSE  cast(t.timestamp as timestamp) > cast(@iso_timestamp_start as timestamp) END\n  AND CASE WHEN COALESCE(@iso_timestamp_end, '') = '' THEN TRUE ELSE cast(t.timestamp as timestamp) <= cast(@iso_timestamp_end as timestamp) END\n  AND cast(t.timestamp as timestamp) > retention.date\norder by cast(t.timestamp as timestamp) desc\n),\n\nrealtime_logs as (\nselect \n  t.timestamp,\n  t.id, \n  t.event_message, \n  t.metadata \nfrom retention, `realtime.logs.prod` as t\n  cross join unnest(t.metadata) as m\nwhere\n  m.project = @project \n  AND CASE WHEN COALESCE(@iso_timestamp_start, '') = '' THEN  TRUE ELSE  cast(t.timestamp as timestamp) > cast(@iso_timestamp_start as timestamp) END\n  AND CASE WHEN" <> ..., sandboxable: true, cache_duration_seconds: 0}, errors: [query: {"can't find source postgres.logs", []}], data: #Logflare.Endpoints.Query<>, valid?: false>}
    (logflare 1.5.13) lib/logflare/single_tenant.ex:198: anonymous fn/2 in Logflare.SingleTenant.create_supabase_endpoints/0
    (elixir 1.15.7) lib/enum.ex:1693: Enum."-map/2-lists^map/1-1-"/2
    (logflare 1.5.13) lib/logflare/single_tenant.ex:197: Logflare.SingleTenant.create_supabase_endpoints/0
    (logflare 1.5.13) lib/logflare/application.ex:273: Logflare.Application.startup_tasks/0
    (elixir 1.15.7) lib/task/supervised.ex:101: Task.Supervised.invoke_mfa/2
Function: #Function<3.93554717/0 in Logflare.Application.get_children/1>
    Args: []

23:04:12.154 [debug] starting init task

[jeffmccune]

The key piece of information seems to be errors: [query: {"can't find source postgres.logs", []}].

What is this source and how does it get created in the official docker-compose setup?

Here's the code

I think this has something to do with this comment

# We must route the sink through kong because ingesting logs before logflare is fully initialised will
# lead to broken queries from studio. This works by the assumption that containers are started in the
# following order: vector > db > logflare > kong
uri: 'http://kong:8000/analytics/v1/api/logs?source_name=postgres.logs&api_key=your-super-secret-and-long-logflare-key'

[williamoverton]

Did you ever figure this out?

[bayerlse]

Also having this error :/

[stubclan]

@jeffmccune getting same issue but with Database, did you have trouble with Database part too or just logs ?

below is from kong pod

"POST /pg/query HTTP/1.1" 401 52 "-" "node"
"GET /pg/schemas HTTP/1.1" 401 52 "-" "node"
"GET /pg/tables?include_columns=true&included_schemas=public&ref=default HTTP/1.1" 401 52 "-" "node"
"GET /pg/publications HTTP/1.1" 401 52 "-" "node"
"GET /pg/types HTTP/1.1" 401 52 "-" "node"
"GET /pg/extensions HTTP/1.1" 401 52 "-" "node"

[Ziinc]

This seems to be unrelated.

[jeffmccune]

Never figured this out unfortunately, mainly because I hit my time box limit working on this issue.

[Ziinc]

Hi, dev of logflare here. The issue as to why the queries are failing is due to the seeding sources not completing before queries are getting made. Somehow or the other, the necessary supabase log sources are not getting created.

A few things that we can determine from your analysis:

1. role used definitely has enough perms to query the db, so it isn't a perms issue
2. if the k8s config is translated correctly, there should be 2 boolean flags set here that will enable the startup seeding.

Some things that I can advise to help with debugging this:

1. ensure that there are health checks set up for the service, as it will only return healthy if there is data seeded.
2. ensure that the correct stable version of logflare is in use which will correspond with what is used on CLI
3. if you navigate to localhost:4000/dashboard, you should see the necessary seeded sources (the ui won't work beyond that), but it would help with verifying that the seeding is done correctly.

Edit 10 sept: Please try to use v1.8.9, as it contains a patch relating to stale PG config.

[AntonOfTheWoods]

@Ziinc , is there any plan to make the logs/errors any more meaningful and explicit? To give any usable documentation on how to get things set up outside of just reusing the provided compose file?

It seems lots and lots of us are trying to get things working properly in kubernetes and this is the one that many of us seem to stumble on. The supabase-community helm chart actually does have some of the logs appearing in the studio interface but that chart points to a single db deployment without persistence for both the main db and the logs... So it's really utterly unusable, and I have been completely incapable of getting logs in the studio in kube using anything else. By trying various things I can get log data going into tables but there doesn't seem to be any way to query either from the studio or from the :4000/dashboard.

At the very least, there seems to be a certain number of extensions that need to be enabled but I couldn't find anything more than "you are invited to use the docker compose". It would be great to know what we need to put, and whether that has changed in later versions (I can also get values in the db with 1.6.4, but even the community chart won't show logs in the studio with that...).

I personally have what looks to be an identical dashboard (with endpoints also) for the working compose/community chart and my own, and get the same back from the health check.

Thanks for the great work!

[Ziinc]

Can you try with v1.8.9? We have recently fixed a bug relating to stale PG backend configuration where if there is a password change it now gets correctly adjusted at runtime.

As for specific help relating to k8s deployments, I'm afraid that given the complexities and customizations that each self hosting setup has, it is near impossible to provide a one-size-fits-all guidance beyond the compose file, which itself provides a solid foundation to build a k8s config off.

The postgres backend was specifically built for local development in mind, it does not make sense to store your logs on your production database due to lack of separation of concerns, and it would be advisable to use the BQ backend instead.
This is already advised in the self hosting documentation.

As for postgres extension enabling, the supabase postgres image should have the extensions pre-installed, so i'm not quite sure what you mean.

[Songyawn]

still same error .....

[Madjarx]

TLDR & ANSWER: Find the analytics service in the main docker-compose.yml. Shoud say something like analytics and image: supabase/logflare:1.4.0 or whatever is the image version at the time of reading

Just bump up the version to 1.8.9 and you should see stuff being visible in your supabase dashboard

logs are being captured but for whatever reason you cant access them with the 1.4.0

Also generate an access token on the logflare website, its pretty straightforward, and use it for the LOGFLARE_API_KEY in the .env