Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

ERROR relay_server::services::project #3553

Open
snowair opened this issue May 6, 2024 · 6 comments
Open

ERROR relay_server::services::project #3553

snowair opened this issue May 6, 2024 · 6 comments
Assignees
@Dav1dde

Comments

@snowair
Copy link

snowair commented May 6, 2024 •
edited

I'm running into some ERROR logs and don't know what to do with them, can anyone help me? thanks

Relay: 24.4.2

self-hosted in k8s

Logs:

2024-05-05T16:57:38.018004Z ERROR relay::setup: unused topic assignment 'metrics_transactions'
**2024-05-05T16:57:38.018039Z  INFO relay_server: relay server starting**
2024-05-05T16:57:38.031517Z  INFO relay_server::services::upstream: registering with upstream descriptor=http://sentry-web:9000/
2024-05-05T16:57:38.092624Z  INFO relay_server::services::upstream: relay successfully registered with upstream
2024-05-05T16:57:38.128146Z  INFO relay_server::services::outcome: Configured to emit outcomes via kafka
2024-05-05T16:57:38.128601Z  INFO relay_server::services::outcome: OutcomeProducer started.
2024-05-05T16:57:38.128797Z  INFO relay_metrics::router: metrics router started
2024-05-05T16:57:38.128631Z  INFO relay_server::services::global_config: global config service starting
2024-05-05T16:57:38.129008Z  INFO relay_server::services::global_config: requesting global config from upstream
2024-05-05T16:57:38.128614Z  INFO relay_server::services::outcome_aggregator: outcome aggregator started
2024-05-05T16:57:38.129131Z  INFO relay_server::services::processor: starting 2 envelope processing workers
2024-05-05T16:57:38.129065Z  INFO relay_server::services::store: store forwarder started
2024-05-05T16:57:38.129285Z  INFO relay_server::services::project_cache: project cache started
2024-05-05T16:57:38.129409Z  INFO relay_server::services::project_cache: waiting for global config
2024-05-05T16:57:38.129503Z  INFO relay_server::services::project_upstream: project upstream cache started
2024-05-05T16:57:38.129513Z  INFO relay_server::services::project_local: project local cache started
2024-05-05T16:57:38.142773Z  INFO relay_server::services::relays: key cache started
2024-05-05T16:57:38.143071Z  INFO relay_server::services::server: spawning http server
2024-05-05T16:57:38.143085Z  INFO relay_server::services::server:   listening on http://0.0.0.0:3000/
2024-05-05T16:57:38.153305Z  INFO relay_server::services::global_config: received global config from upstream
**2024-05-05T17:33:26.730248Z ERROR relay_server::services::project: there is no project state: dropping 1 buckets tags.project_key="0ddfde987d11e3085b282e654389dd48"**

Configs:

    relay:
      mode: managed
      upstream: "http://sentry-web:9000/"
      host: 0.0.0.0
      port: 3000

    processing:
      enabled: false

      kafka_config:
        - name: "bootstrap.servers"
          value: "*.*.*.*:9092"
        - name: "message.max.bytes"
          value: 50000000  # 50MB or bust
      redis: "redis://:[email protected]:6379"
      topics:
        metrics_transactions: ingest-performance-metrics
        metrics_sessions: ingest-metrics
@snowair
Copy link
Author

snowair commented May 7, 2024 

2024-05-05T16:57:38.018004Z ERROR relay::setup: unused topic assignment 'metrics_transactions'
2024-05-05T17:33:26.730248Z ERROR relay_server::services::project: there is no project state: dropping 1 buckets tags.project_key="0ddfde987d11e3085b282e654389dd48"

0ddfde987d11e3085b282e654389dd48 is the internal project(id=1)

@jjbayer
Copy link
Member

jjbayer commented May 7, 2024

@snowair thanks for reporting this! We introduced a breaking change in 24.4.0, please rename your topics accordingly:

Kafka topic configuration keys now support the default topic name. The previous aliases metrics and metrics_transactions are no longer supported if configuring topics manually. Use ingest-metrics or metrics_sessions instead of metrics, and ingest-performance-metrics or metrics_generic instead of metrics_transactions. (#3361)

(changelog)

@snowair
Copy link
Author

snowair commented May 8, 2024 

2024-05-07T13:30:36.509228Z  INFO relay::setup: launching relay from config folder /work/.relay
2024-05-07T13:30:36.509265Z  INFO relay::setup:   relay mode: managed
2024-05-07T13:30:36.509269Z  INFO relay::setup:   relay id: c486d03f-b66d-45be-862e-e44b8f937f01
2024-05-07T13:30:36.509272Z  INFO relay::setup:   public key: FsHrTe2AQglgUjQZ_vbatYLrj5NgmmUWXwi8V7MITvY
2024-05-07T13:30:36.509276Z  INFO relay::setup:   log level: info
2024-05-07T13:30:36.509284Z  INFO relay_server: relay server starting
2024-05-07T13:30:36.526798Z  INFO relay_server::services::upstream: registering with upstream descriptor=http://sentry-web:9000/
2024-05-07T13:30:36.546526Z  INFO relay_server::services::outcome: Configured to emit outcomes via kafka
2024-05-07T13:30:36.546995Z  INFO relay_server::services::outcome: OutcomeProducer started.
2024-05-07T13:30:36.547019Z  INFO relay_server::services::global_config: global config service starting
2024-05-07T13:30:36.547219Z  INFO relay_server::services::global_config: requesting global config from upstream
2024-05-07T13:30:36.547007Z  INFO relay_server::services::outcome_aggregator: outcome aggregator started
2024-05-07T13:30:36.547428Z  INFO relay_server::services::processor: starting 2 envelope processing workers
2024-05-07T13:30:36.547486Z  INFO relay_metrics::router: metrics router started
2024-05-07T13:30:36.547314Z  INFO relay_server::services::store: store forwarder started
2024-05-07T13:30:36.547589Z  INFO relay_server::services::project_cache: project cache started
2024-05-07T13:30:36.547694Z  INFO relay_server::services::project_cache: waiting for global config
2024-05-07T13:30:36.547763Z  INFO relay_server::services::project_upstream: project upstream cache started
2024-05-07T13:30:36.547773Z  INFO relay_server::services::project_local: project local cache started
2024-05-07T13:30:36.554128Z  INFO relay_server::services::relays: key cache started
2024-05-07T13:30:36.554415Z  INFO relay_server::services::server: spawning http server
2024-05-07T13:30:36.554429Z  INFO relay_server::services::server:   listening on http://0.0.0.0:3000/
2024-05-07T13:30:36.580834Z  INFO relay_server::services::upstream: relay successfully registered with upstream
2024-05-07T13:30:36.619461Z  INFO relay_server::services::global_config: received global config from upstream
2024-05-07T14:11:37.047777Z ERROR relay_server::services::project: there is no project state: dropping 1 buckets tags.project_key="0ddfde987d11e3085b282e654389dd48"
2024-05-07T14:11:46.447835Z ERROR relay_server::services::project: there is no project state: dropping 6 buckets tags.project_key="0ddfde987d11e3085b282e654389dd48"
2024-05-07T14:11:47.047841Z ERROR relay_server::services::project: there is no project state: dropping 1 buckets tags.project_key="0ddfde987d11e3085b282e654389dd48"

@jjbayer Thank you very much , the "unused topic assignment" error has gone.

But ERROR relay_server::services::project is producing

New config file is:

    relay:
      mode: managed
      upstream: "http://sentry-web:9000/"
      host: 0.0.0.0
      port: 3000

    processing:
      enabled: true

      kafka_config:
        - name: "bootstrap.servers"
          value: "0.0.0.0:9092"
        - name: "message.max.bytes"
          value: 50000000  # 50MB or bust
      redis: "redis://:[email protected]:6379"
      topics:
        metrics_generic: ingest-performance-metrics
        metrics_sessions: ingest-metrics

@jjbayer
Copy link
Member

jjbayer commented May 10, 2024

@snowair, thanks, that error should not happen. Do these errors show up continuously, or rather sporadically in terms of incoming traffic? Could you try enabling debug logging? That should show lines like "project state xxx updated".

logging:
  level: debug

@snowair
Copy link
Author

snowair commented May 10, 2024

@jjbayer Hi, There are a few of these ERROR message every few minutes.

Here are some debug logs before a ERROR:

2024-05-10T10:21:01.572093Z DEBUG relay_server::services::project: sending metrics straight to aggregator
2024-05-10T10:21:01.572122Z DEBUG relay_server::services::project: sending metrics straight to aggregator
2024-05-10T10:21:01.573231Z DEBUG relay_server::services::project: sending metrics straight to aggregator
2024-05-10T10:21:01.573252Z DEBUG relay_server::services::project: sending metrics straight to aggregator
2024-05-10T10:21:02.273443Z DEBUG request{method=GET uri=/api/relay/healthcheck/live/ version=HTTP/1.1}: tower_http::trace::on_request: started processing request
2024-05-10T10:21:02.273445Z DEBUG request{method=GET uri=/api/relay/healthcheck/ready/ version=HTTP/1.1}: tower_http::trace::on_request: started processing request
2024-05-10T10:21:02.273524Z DEBUG request{method=GET uri=/api/relay/healthcheck/live/ version=HTTP/1.1}: tower_http::trace::on_response: finished processing request latency=0 ms status=200
2024-05-10T10:21:02.273704Z DEBUG request{method=GET uri=/api/relay/healthcheck/ready/ version=HTTP/1.1}: tower_http::trace::on_response: finished processing request latency=0 ms status=200
2024-05-10T10:21:02.273443Z DEBUG request{method=GET uri=/api/relay/healthcheck/live/ version=HTTP/1.1}: tower_http::trace::on_request: started processing request
2024-05-10T10:21:02.273445Z DEBUG request{method=GET uri=/api/relay/healthcheck/ready/ version=HTTP/1.1}: tower_http::trace::on_request: started processing request
2024-05-10T10:21:02.273524Z DEBUG request{method=GET uri=/api/relay/healthcheck/live/ version=HTTP/1.1}: tower_http::trace::on_response: finished processing request latency=0 ms status=200
2024-05-10T10:21:02.273704Z DEBUG request{method=GET uri=/api/relay/healthcheck/ready/ version=HTTP/1.1}: tower_http::trace::on_response: finished processing request latency=0 ms status=200
2024-05-10T10:21:03.534206Z DEBUG request{method=POST uri=/api/1/envelope/ version=HTTP/1.0}: tower_http::trace::on_request: started processing request
2024-05-10T10:21:03.534370Z DEBUG relay_server::services::project: project 0ddfde987d11e3085b282e654389dd48 state requested 1 times
2024-05-10T10:21:03.534469Z DEBUG request{method=POST uri=/api/1/envelope/ version=HTTP/1.0}: tower_http::trace::on_response: finished processing request latency=0 ms status=200
2024-05-10T10:21:03.535865Z DEBUG relay_server::services::project: project state 0ddfde987d11e3085b282e654389dd48 updated
2024-05-10T10:21:06.417775Z DEBUG request{method=POST uri=/api/1/envelope/ version=HTTP/1.0}: tower_http::trace::on_request: started processing request
2024-05-10T10:21:06.418293Z DEBUG relay_server::envelope: failed to parse sampling context error=missing field `public_key`
2024-05-10T10:21:06.418298Z DEBUG request{method=POST uri=/api/1/envelope/ version=HTTP/1.0}: tower_http::trace::on_response: finished processing request latency=0 ms status=200
2024-05-10T10:21:06.418307Z DEBUG relay_server::envelope: failed to parse sampling context error=missing field `public_key`
2024-05-10T10:21:06.418400Z DEBUG relay_server::utils::managed_envelope: dropped envelope: rate limited
2024-05-10T10:21:06.419058Z DEBUG relay_server::envelope: failed to parse sampling context error=missing field `public_key`
2024-05-10T10:21:06.419072Z DEBUG relay_server::envelope: failed to parse sampling context error=missing field `public_key`
2024-05-10T10:21:06.421489Z DEBUG relay_server::envelope: failed to parse sampling context error=missing field `public_key`
2024-05-10T10:21:06.434792Z DEBUG request{method=POST uri=/api/1/envelope/ version=HTTP/1.0}: tower_http::trace::on_request: started processing request
2024-05-10T10:21:06.435124Z DEBUG relay_server::envelope: failed to parse sampling context error=missing field `public_key`
2024-05-10T10:21:06.435131Z DEBUG request{method=POST uri=/api/1/envelope/ version=HTTP/1.0}: tower_http::trace::on_response: finished processing request latency=0 ms status=200
2024-05-10T10:21:06.435137Z DEBUG relay_server::envelope: failed to parse sampling context error=missing field `public_key`
2024-05-10T10:21:06.435411Z DEBUG relay_server::envelope: failed to parse sampling context error=missing field `public_key`
2024-05-10T10:21:06.435425Z DEBUG relay_server::envelope: failed to parse sampling context error=missing field `public_key`
2024-05-10T10:21:06.437403Z DEBUG relay_server::envelope: failed to parse sampling context error=missing field `public_key`
2024-05-10T10:21:11.463584Z DEBUG request{method=POST uri=/api/7/envelope/ version=HTTP/1.0}: tower_http::trace::on_request: started processing request
2024-05-10T10:21:11.467061Z DEBUG request{method=POST uri=/api/7/envelope/ version=HTTP/1.0}: tower_http::trace::on_response: finished processing request latency=3 ms status=200
2024-05-10T10:21:11.467132Z DEBUG relay_server::utils::managed_envelope: dropped envelope: rate limited
2024-05-10T10:21:11.485092Z DEBUG relay_server::services::project: sending metrics straight to aggregator
2024-05-10T10:21:11.485130Z DEBUG relay_server::services::project: sending metrics straight to aggregator
2024-05-10T10:21:12.273561Z DEBUG request{method=GET uri=/api/relay/healthcheck/ready/ version=HTTP/1.1}: tower_http::trace::on_request: started processing request
2024-05-10T10:21:12.273561Z DEBUG request{method=GET uri=/api/relay/healthcheck/live/ version=HTTP/1.1}: tower_http::trace::on_request: started processing request
2024-05-10T10:21:12.273663Z DEBUG request{method=GET uri=/api/relay/healthcheck/live/ version=HTTP/1.1}: tower_http::trace::on_response: finished processing request latency=0 ms status=200
2024-05-10T10:21:12.273818Z DEBUG request{method=GET uri=/api/relay/healthcheck/ready/ version=HTTP/1.1}: tower_http::trace::on_response: finished processing request latency=0 ms status=200
2024-05-10T10:21:22.273942Z DEBUG request{method=GET uri=/api/relay/healthcheck/live/ version=HTTP/1.1}: tower_http::trace::on_request: started processing request
2024-05-10T10:21:22.273942Z DEBUG request{method=GET uri=/api/relay/healthcheck/ready/ version=HTTP/1.1}: tower_http::trace::on_request: started processing request
2024-05-10T10:21:22.274058Z DEBUG request{method=GET uri=/api/relay/healthcheck/live/ version=HTTP/1.1}: tower_http::trace::on_response: finished processing request latency=0 ms status=200
2024-05-10T10:21:22.274249Z DEBUG request{method=GET uri=/api/relay/healthcheck/ready/ version=HTTP/1.1}: tower_http::trace::on_response: finished processing request latency=0 ms status=200
2024-05-10T10:21:23.860224Z DEBUG request{method=POST uri=/api/1/envelope/ version=HTTP/1.0}: tower_http::trace::on_request: started processing request
2024-05-10T10:21:23.860461Z DEBUG request{method=POST uri=/api/1/envelope/ version=HTTP/1.0}: tower_http::trace::on_response: finished processing request latency=0 ms status=200
2024-05-10T10:21:23.860762Z DEBUG relay_server::services::project: sending metrics straight to aggregator
2024-05-10T10:21:32.273937Z DEBUG request{method=GET uri=/api/relay/healthcheck/ready/ version=HTTP/1.1}: tower_http::trace::on_request: started processing request
2024-05-10T10:21:32.273937Z DEBUG request{method=GET uri=/api/relay/healthcheck/live/ version=HTTP/1.1}: tower_http::trace::on_request: started processing request
2024-05-10T10:21:32.274031Z DEBUG request{method=GET uri=/api/relay/healthcheck/live/ version=HTTP/1.1}: tower_http::trace::on_response: finished processing request latency=0 ms status=200
2024-05-10T10:21:32.274213Z DEBUG request{method=GET uri=/api/relay/healthcheck/ready/ version=HTTP/1.1}: tower_http::trace::on_response: finished processing request latency=0 ms status=200
2024-05-10T10:21:42.273342Z DEBUG request{method=GET uri=/api/relay/healthcheck/live/ version=HTTP/1.1}: tower_http::trace::on_request: started processing request
2024-05-10T10:21:42.273342Z DEBUG request{method=GET uri=/api/relay/healthcheck/ready/ version=HTTP/1.1}: tower_http::trace::on_request: started processing request
2024-05-10T10:21:42.273432Z DEBUG request{method=GET uri=/api/relay/healthcheck/live/ version=HTTP/1.1}: tower_http::trace::on_response: finished processing request latency=0 ms status=200
2024-05-10T10:21:42.273640Z DEBUG request{method=GET uri=/api/relay/healthcheck/ready/ version=HTTP/1.1}: tower_http::trace::on_response: finished processing request latency=0 ms status=200
2024-05-10T10:21:42.876533Z DEBUG request{method=POST uri=/api/1/envelope/ version=HTTP/1.0}: tower_http::trace::on_request: started processing request
2024-05-10T10:21:42.876837Z DEBUG request{method=POST uri=/api/1/envelope/ version=HTTP/1.0}: tower_http::trace::on_response: finished processing request latency=0 ms status=200
2024-05-10T10:21:42.877108Z DEBUG relay_server::utils::managed_envelope: dropped envelope: rate limited
2024-05-10T10:21:42.877197Z DEBUG relay_server::services::project: sending metrics straight to aggregator
2024-05-10T10:21:46.196513Z DEBUG relay_server::utils::managed_envelope: dropped envelope: rate limited
2024-05-10T10:21:46.196582Z DEBUG relay_server::services::project: sending metrics straight to aggregator
2024-05-10T10:21:52.256518Z DEBUG request{method=POST uri=/api/1/envelope/ version=HTTP/1.0}: tower_http::trace::on_request: started processing request
2024-05-10T10:21:52.256772Z DEBUG request{method=POST uri=/api/1/envelope/ version=HTTP/1.0}: tower_http::trace::on_response: finished processing request latency=0 ms status=200
2024-05-10T10:21:52.256916Z DEBUG relay_server::services::project: sending metrics straight to aggregator
2024-05-10T10:21:52.273749Z DEBUG request{method=GET uri=/api/relay/healthcheck/ready/ version=HTTP/1.1}: tower_http::trace::on_request: started processing request
2024-05-10T10:21:52.273749Z DEBUG request{method=GET uri=/api/relay/healthcheck/live/ version=HTTP/1.1}: tower_http::trace::on_request: started processing request
2024-05-10T10:21:52.273836Z DEBUG request{method=GET uri=/api/relay/healthcheck/live/ version=HTTP/1.1}: tower_http::trace::on_response: finished processing request latency=0 ms status=200
2024-05-10T10:21:52.274042Z DEBUG request{method=GET uri=/api/relay/healthcheck/ready/ version=HTTP/1.1}: tower_http::trace::on_response: finished processing request latency=0 ms status=200
2024-05-10T10:21:53.729430Z DEBUG request{method=POST uri=/api/1/envelope/ version=HTTP/1.0}: tower_http::trace::on_request: started processing request
2024-05-10T10:21:53.729715Z DEBUG request{method=POST uri=/api/1/envelope/ version=HTTP/1.0}: tower_http::trace::on_response: finished processing request latency=0 ms status=200
2024-05-10T10:21:53.729849Z DEBUG relay_server::utils::managed_envelope: dropped envelope: rate limited
2024-05-10T10:21:53.729900Z DEBUG relay_server::services::project: sending metrics straight to aggregator
2024-05-10T10:21:54.209172Z ERROR relay_server::services::project: there is no project state: dropping 12 buckets tags.project_key="ab8917eca96389c9d57b15933b2868ac"

@jjbayer
Copy link
Member

jjbayer commented May 10, 2024

Thanks for the logs, this makes me confident that we're running into the following TODO:

relay/relay-server/src/services/project.rs

Lines 730 to 735 in e3e3bb1

// We can send metrics straight to the aggregator.
relay_log::debug!("sending metrics straight to aggregator");
// TODO: When the state is present but expired, we should send buckets
// to the metrics buffer instead. In practice, the project state should be
// refreshed at the time when the buckets emerge from the aggregator though.

We will fix this, I'll keep you posted!

@Dav1dde Dav1dde mentioned this issue May 24, 2024
Closed
@jjbayer jjbayer assigned jjbayer and Dav1dde and unassigned jjbayer May 24, 2024
@jjbayer jjbayer mentioned this issue May 27, 2024
Open
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@Dav1dde Dav1dde

Labels
None yet
Projects
GitHub Issues with 👀 3
Status: No status
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

ref(project): Use latest state when flushing buckets getsentry/relay
3 participants
@Dav1dde @jjbayer @snowair