Why do my grafana tempo ingester pods go into Backoff restarting state after max_block_duration?

[vaibhhavv]

I am using grafana-tempo distributed helm chart. It is successfully deployed and its backend is configured on Azure Storage (blob containers) and working fine.

I have a demo application which is sending traces to grafana-tempo. I can confirm I'm receiving traces.

The issue I have observed is that exactly after 30m, my ingester pods are going into Back-off restarting state. And I have to manually restart its statefulset.

While searching the root cause, found that their is one parameter max_block_duration which has a default value of 30m: "max_block_duration: maximum length of time before cutting a block."

So I tried to increase the timing, and given value 60m. Now after 60 minutes my ingester pods are going into Back-off restarting state.

I have also enabled autoscaling. But no new pods are coming up if all ingester pods are in the same error state.

Can someone help me out to understand why its happening like this and the possible solution to eleminate the issue?

What value should be passed to max_block_duration so that this pods will not so in Back-off restarting?

Expectation: I expect my Ingester pods should run fine every time.

[joe-elliott]

Can you share the k8s reason they restarted? OOM? unexpected exit?

If it's an unexpected exit the logs would be helpful. If it's an OOM try increasing the memory limit.

[vaibhhavv]

Hi @joe-elliott Thanks for replying.
It was definitely not the OOM, I check the memory and cpu itself and it was good.

I can attach a screenshot of the my tempo ingester pod logs.

5-17708:00:45.045150796Z caller-module_service.go:82 msg=initialising module=server
5-17708:00:45.045355037 caller-module_service.go:82 msg-initialising module=store
5-17708:00:45.0453746227 caller=module_service.go:82 msg=initialising module=memberlist-kv
5-17708:00:45.0453936677 caller=module_service.go:82 msg=initialising module=overrides
5-17708:00:45.045588337 caller=module service.go: 82 msg-initialising module=usage-report
5-17708:00:45.045651317 caller=module_service.go:82 msg-initialising module-ingester
5-17708:00:45.0456691617 caller-ingester.go:329 msg- "beginning wal replay"
5-17708:00:45.045718491Z caller=wal.go: 122 msg-"beginning replay" file-7d1a535a-d864-4657-931c-9c0583dbfdel+single-tenant+varquet size=4096
5-17708:00:45.0457791647 caller-wal.go:128 msg-"failed to replay block. removing." file-7d1a535a-d864-4657-931c-9c0583dbfdel+single-tenant+vParquet err-"e
5-17708:00:45.045898078Z caller-wal.go:122 msg-"beginning replay" file-919a395b-0b8e-4737-a547-71c4d2b0e82c+singLe-tenant+vParquet size-4096
5-17708:00:47.2432900827 caller-flush.go:244 msg-"completing block" userid-single-tenant blockID-919a395b-068-4737-a547-71c4d260e82c
48.0036673397 caller-memberlist_logger.go:74 level=warn msg- "Got ping for unexpected node 'tempo-ingester-0-d19a567d' from-10.67.135.187:7946"
48.0037253657 caller-memberlist_logger.go:74 level=warn msg-"Got ping for unexpected node 'tempo-ingester-0-d19a567d' from-10.67.130.88:7946"

These was basically the logs.
I was troubleshooting these and wanted to know the root cause.
As I mentioned above I tried to give different values for the attribute "max_block_duration".

ingester:
        max_block_duration: 

1. First I tried with max_block_duration: null .
   Result: My ingester pods were going in Backoff restarting state exactly after 30 mins

2. Then I tried with max_block_duration: 60m .
   Result: My ingester pods were again going in Backoff restarting state exactly after 60 mins

3. Then I tried with max_block_duration: 15m
   Result: Now, from past 24 hours I am keeping an eye on them, none of them are going down and are working properly.

   I still not know the root cause but I'm very much interested to know that. And specially how its working.

@joe-elliott @mdisibio

[joe-elliott]

Can you please attach the logs when it crashed? kubectl -p will give you the previous containers log which may contain a panic or other information.

[vaibhhavv]

Hi @joe-elliott, I cant get them now because yesterday I uninstalled and re-installed the tempo.

But I remember it was this only

5-17708:00:45.045150796Z caller-module_service.go:82 msg=initialising module=server
5-17708:00:45.045355037 caller-module_service.go:82 msg-initialising module=store
5-17708:00:45.0453746227 caller=module_service.go:82 msg=initialising module=memberlist-kv
5-17708:00:45.0453936677 caller=module_service.go:82 msg=initialising module=overrides
5-17708:00:45.045588337 caller=module service.go: 82 msg-initialising module=usage-report
5-17708:00:45.045651317 caller=module_service.go:82 msg-initialising module-ingester
5-17708:00:45.0456691617 caller-ingester.go:329 msg- "beginning wal replay"
5-17708:00:45.045718491Z caller=wal.go: 122 msg-"beginning replay" file-7d1a535a-d864-4657-931c-9c0583dbfdel+single-tenant+varquet size=4096
5-17708:00:45.0457791647 caller-wal.go:128 msg-"failed to replay block. removing." file-7d1a535a-d864-4657-931c-9c0583dbfdel+single-tenant+vParquet err-"e
5-17708:00:45.045898078Z caller-wal.go:122 msg-"beginning replay" file-919a395b-0b8e-4737-a547-71c4d2b0e82c+singLe-tenant+vParquet size-4096
5-17708:00:47.2432900827 caller-flush.go:244 msg-"completing block" userid-single-tenant blockID-919a395b-068-4737-a547-71c4d260e82c
48.0036673397 caller-memberlist_logger.go:74 level=warn msg- "Got ping for unexpected node 'tempo-ingester-0-d19a567d' from-10.67.135.187:7946"
48.0037253657 caller-memberlist_logger.go:74 level=warn msg-"Got ping for unexpected node 'tempo-ingester-0-d19a567d' from-10.67.130.88:7946"

[vaibhhavv]

@joe-elliott Now As mentioned ingester works fine (without single restart), but I have also seen that my compactor fails and keeps on restarting.. then runs for some minutes then again goes on backoff restart and then again goes up and on and off..

Here are my compactor pod logs:

level=info ts=2023-05-22T13:46:55.881937268Z caller=module_service.go:82 msg=initialising module=memberlist-kv
level=info ts=2023-05-22T13:46:55.881994292Z caller=module_service.go:82 msg=initialising module=overrides
level=info ts=2023-05-22T13:46:55.881939405Z caller=module_service.go:82 msg=initialising module=store
level=info ts=2023-05-22T13:46:55.882065194Z caller=module_service.go:82 msg=initialising module=usage-report
level=info ts=2023-05-22T13:46:55.882752606Z caller=memberlist_client.go:543 msg="memberlist fast-join starting" nodes_found=1 to_join=2
level=info ts=2023-05-22T13:46:55.913290606Z caller=module_service.go:82 msg=initialising module=compactor
level=info ts=2023-05-22T13:46:56.013865875Z caller=memberlist_client.go:563 msg="memberlist fast-join finished" joined_nodes=8 elapsed_time=131.114012ms
level=info ts=2023-05-22T13:46:56.0139331Z caller=memberlist_client.go:576 msg="joining memberlist cluster" join_members=tempo-gossip-ring
level=info ts=2023-05-22T13:46:56.013996826Z caller=basic_lifecycler.go:259 msg="instance found in the ring" instance=tempo-compactor-84dd5f64cc-8hfsk ring=compactor state=ACTIVE tokens=512 registered_at="2023-05-22 13:38:25 +0000 UTC"
level=info ts=2023-05-22T13:46:56.014393885Z caller=compactor.go:129 msg="waiting until compactor is ACTIVE in the ring"
level=info ts=2023-05-22T13:46:56.014450041Z caller=compactor.go:135 msg="compactor is ACTIVE in the ring"
level=info ts=2023-05-22T13:46:56.014458957Z caller=compactor.go:144 msg="waiting until compactor ring topology is stable" min_waiting=1m0s max_waiting=5m0s
level=info ts=2023-05-22T13:46:56.119149642Z caller=memberlist_client.go:595 msg="joining memberlist cluster succeeded" reached_nodes=8 elapsed_time=105.21676ms
level=info ts=2023-05-22T13:47:56.014518831Z caller=compactor.go:148 msg="compactor ring topology is stable"
level=info ts=2023-05-22T13:47:56.014617973Z caller=tempodb.go:432 msg="polling enabled" interval=5m0s concurrency=50
level=info ts=2023-05-22T13:47:56.079266581Z caller=poller.go:167 msg="successfully pulled tenant index" tenant=single-tenant createdAt=2023-05-22T13:46:23.113157598Z metas=6 compactedMetas=7
level=info ts=2023-05-22T13:47:56.079319692Z caller=compactor.go:161 msg="enabling compaction"
level=info ts=2023-05-22T13:47:56.079328309Z caller=tempodb.go:406 msg="compaction and retention enabled."
level=info ts=2023-05-22T13:47:56.079345149Z caller=app.go:183 msg="Tempo started"
level=info ts=2023-05-22T13:48:26.079943356Z caller=compactor.go:101 msg="starting compaction cycle" tenantID=single-tenant offset=0
level=info ts=2023-05-22T13:48:26.079996493Z caller=compactor.go:114 msg="Compacting hash" hashString=single-tenant-1-467988
level=info ts=2023-05-22T13:48:26.080037407Z caller=compactor.go:144 msg="beginning compaction" traceID=35683b7db5ede4d5
level=info ts=2023-05-22T13:48:26.080097992Z caller=compactor.go:156 msg="compacting block" block="&{Version:vParquet BlockID:f4e5cee3-de6e-425a-8216-c34ff36e0575 MinID:[47 5 221 81 106 4 58 92 193 187 211 208 144 9 35 106] MaxID:[187 16 150 84 209 119 207 137 192 97 56 47 92 247 78 17] TenantID:single-tenant StartTime:2023-05-22 12:13:50 +0000 UTC EndTime:2023-05-22 12:14:05 +0000 UTC TotalObjects:6 Size:13568 CompactionLevel:1 Encoding:none IndexPageSize:0 TotalRecords:1 DataEncoding: BloomShardCount:1 FooterSize:5659}"
level=info ts=2023-05-22T13:48:26.099641176Z caller=compactor.go:156 msg="compacting block" block="&{Version:vParquet BlockID:4ea5d75a-72cd-4e35-b1af-6a0b4e99a472 MinID:[47 5 221 81 106 4 58 92 193 187 211 208 144 9 35 106] MaxID:[187 16 150 84 209 119 207 137 192 97 56 47 92 247 78 17] TenantID:single-tenant StartTime:2023-05-22 12:13:50 +0000 UTC EndTime:2023-05-22 12:14:05 +0000 UTC TotalObjects:6 Size:13568 CompactionLevel:1 Encoding:none IndexPageSize:0 TotalRecords:1 DataEncoding: BloomShardCount:1 FooterSize:5659}"
level=info ts=2023-05-22T13:48:26.121578791Z caller=compactor.go:156 msg="compacting block" block="&{Version:vParquet BlockID:e04ffecc-f4cd-46e4-85e7-b3562e4fb914 MinID:[2 81 103 6 171 19 29 173 206 117 145 91 17 163 29 94] MaxID:[248 86 96 109 159 223 77 213 199 20 127 149 13 220 252 119] TenantID:single-tenant StartTime:2023-05-22 11:35:03 +0000 UTC EndTime:2023-05-22 12:04:54 +0000 UTC TotalObjects:77 Size:34581 CompactionLevel:1 Encoding:none IndexPageSize:0 TotalRecords:1 DataEncoding: BloomShardCount:1 FooterSize:5923}"

what can be the issue with this?

[joe-elliott]

I'm struggling to understand your issue. Perhaps you could give the output of kubectl get po when a pod is having issues as well as kubectl describe po <crashing pod>?

[vaibhhavv]

Hi @joe-elliott, thanks!
I described the compactor pods and basically they were getting killed due to OOM.
I increased the limits and now they are greeny-green.

[joe-elliott]

Good to hear. If your compactors are having issues OOMing, I would also consider using GO_MEMLIMIT or reducing your max_bytes_per_trace.

Closing this issue. Thanks for the report!

[vaibhhavv]

Many Thanks @joe-elliott for your help!

[nishasati6oct]

Can anyone share their grafana tempo configuration for using Azure blob storage (access key with SOPS secret)?

[vaibhhavv]

Hi @nishasati6oct , here is a sample config on the docs itself.
Have a look here

  storage:
    trace:
      backend: azure
      azure:
        container_name: container-name
        storage_account_name: storage-account-name
        storage_account_key: ${STORAGE_ACCOUNT_ACCESS_KEY}

  extraArgs:
    config.expand-env: true
  extraEnv:
    - name: STORAGE_ACCOUNT_ACCESS_KEY
      valueFrom:
        secretKeyRef:
          name: secret-name
          key: STORAGE_ACCOUNT_ACCESS_KEY

[nishasati6oct]

This is my config
values:
storage:
trace:
backend: azure
azure:
container_name: grafana-tempo
storage_account_name: account-name
storage_account_key: ${STORAGE_ACCOUNT_ACCESS_KEY}

distributor:
  log_received_spans:
    enabled: true
  extraArgs:
    - -config.expand-env=true  (tried this also "config.expand-env: true")
  extraEnv:
  - name: STORAGE_ACCOUNT_ACCESS_KEY
    valueFrom:
      secretKeyRef:
        name: grafana-tempo-secret
        key: storage-account-key  
  service:
    type: LoadBalancer
    annotations:
      service.beta.kubernetes.io/azure-load-balancer-internal: 'true'

SOPS secret with Az keyVault

apiVersion: v1
kind: Secret
metadata:
name: grafana-tempo-secret
namespace: monitoring
stringData:
storage-account-key: xsacsedwfefergergeg

I am using SOPS to encrypt storage-account-key, and helm-release is failing as not able to find storage-account-key (error - field storage-account-key not found in type config.Config).

Can u plz suggest if something is misconfigured here?

[vaibhhavv]

@nishasati6oct can you paste the exact error in a more readable way?

[nishasati6oct]

kubectl logs grafana-tempo-compactor -n monitoring

failed parsing config: failed to parse configFile /conf/tempo.yaml: yaml: unmarshal errors:
line 96: field storage-account-key not found in type config.Config

[vaibhhavv]

instead of creating a secret like you mentioned above,

storage-account-key: xsacsedwfefergergeg

Please create with underscore like below:
storage_account_key: "xsacsedwfefergergeg"

And adjust in extraEnv as well and give it a try.

extraEnv:
  - name: STORAGE_ACCOUNT_ACCESS_KEY
    valueFrom:
      secretKeyRef:
        name: grafana-tempo-secret
        key: storage_account_key 

[nishasati6oct]

This actually worked finally :) Thanku so much for your support.
Here is my final configuration if anyone wants to refer:
I am using SOPS secret for storage-account-key.

apiVersion: helm.toolkit.fluxcd.io/v2beta1
kind: HelmRelease
metadata:
name: grafana-tempo
namespace: monitoring
spec:
chart:
spec:
chart: tempo-distributed
version: "=1.7.5"
sourceRef:
kind: HelmRepository
name: grafana
namespace: flux-system
install:
remediation:
retries: 3
upgrade:
remediation:
retries: 3
interval: 10m0s
values:
storage:
trace:
backend: azure
azure:
container_name: grafana-tempo
storage_account_name: storageaccount
storage_account_key: ${STORAGE_ACCOUNT_ACCESS_KEY}

distributor:
  log_received_spans:
    enabled: true
  extraArgs:
    - -config.expand-env=true 
  extraEnv:
  - name: STORAGE_ACCOUNT_ACCESS_KEY
    valueFrom:
      secretKeyRef:
        name: grafana-tempo-secret
        key: storage_account_key  
  service:
    type: LoadBalancer
    annotations:
      service.beta.kubernetes.io/azure-load-balancer-internal: 'true'

compactor:
  extraArgs:
    - -config.expand-env=true 
  extraEnv:
  - name: STORAGE_ACCOUNT_ACCESS_KEY
    valueFrom:
      secretKeyRef:
        name: grafana-tempo-secret
        key: storage_account_key  

ingester:
  extraArgs:
    - -config.expand-env=true 
  extraEnv:
  - name: STORAGE_ACCOUNT_ACCESS_KEY
    valueFrom:
      secretKeyRef:
        name: grafana-tempo-secret
        key: storage_account_key

querier:
  extraArgs:
    - -config.expand-env=true 
  extraEnv:
  - name: STORAGE_ACCOUNT_ACCESS_KEY
    valueFrom:
      secretKeyRef:
        name: grafana-tempo-secret
        key: storage_account_key
  
queryFrontend:
  extraArgs:
    - -config.expand-env=true 
  extraEnv:
  - name: STORAGE_ACCOUNT_ACCESS_KEY
    valueFrom:
      secretKeyRef:
        name: grafana-tempo-secret
        key: storage_account_key

traces:
  otlp:
    http:
      enabled: true
    grpc:
      enabled: true

One last question - can we define the below section globally instead of defining it for every component?
extraArgs:
- -config.expand-env=true
extraEnv:
- name: STORAGE_ACCOUNT_ACCESS_KEY
valueFrom:
secretKeyRef:
name: grafana-tempo-secret
key: storage_account_key

[vaibhhavv]

@nishasati6oct glad it got worked.

One last question - can we define the below section globally instead of defining it for every component?

I know it is little hectic to provide it multiple times but actually it is a requirement as a developer to define env variables explicitly to a tempo component and not all, that is the reason we have to pass these configuration for every components, helm chart is made in that way only.

I hope you have masked your actual azure storage values in above discussion.

[nishasati6oct]

Thanku for your prompt reply. yes, Those are not real values of storage account and Key. :)