"invalid character '\\x1f' looking for beginning of value" error while using 'tsm' ALB mode

[atkrv]

Hey! 👋

Got alot of errors in logs while using 'tsm' ALB mode 🙁

I assume that I misconfigure something, but I've spend a couple of days on debugging already and found nothing special in my config.

@jranson could you please assist? 🙏

Thanks!

Log:

...
time=2022-03-17T17:27:54.525807351Z app=trickster level=debug event="memorycache cache store" cacheName=default cacheKey=prometheus-1.example.org:9090.opc.fcfefe8641c333d7cf85566801eec0e9 length=0 ttl=30s is_direct=true caller=cache/memory/memory.go:99
time=2022-03-17T17:27:54.525818951Z app=trickster level=debug event="memorycache cache store" cacheKey=prometheus-2.example.org:9090.opc.fcfefe8641c333d7cf85566801eec0e9 length=0 ttl=30s is_direct=true caller=cache/memory/memory.go:99 cacheName=default
time=2022-03-17T17:27:54.526315004Z app=trickster level=error event="vector unmarshaling error" provider=prometheus detail="json: cannot unmarshal number into Go struct field WFMatrixData.data.result of type model.WFResult" caller=backends/prometheus/transformations.go:51
time=2022-03-17T17:27:54.526342486Z app=trickster level=error event="vector unmarshaling error" caller=backends/prometheus/transformations.go:51 provider=prometheus detail="json: cannot unmarshal number into Go struct field WFMatrixData.data.result of type model.WFResult"
time=2022-03-17T17:27:54.527278692Z app=trickster level=error event="vector unmarshaling error" provider=prometheus detail="invalid character '\\x1f' looking for beginning of value" caller=backends/prometheus/model/vector.go:68
time=2022-03-17T17:27:54.527391793Z app=trickster level=error event="vector unmarshaling error" provider=prometheus detail="invalid character '\\x1f' looking for beginning of value" caller=backends/prometheus/model/vector.go:68
time=2022-03-17T17:27:54.531197161Z app=trickster level=debug event="memorycache cache store" cacheName=default cacheKey=prometheus-2.example.org:9090.opc.b95724c13c5dd4d5322c552ffa4be3bb length=0 ttl=30s is_direct=true caller=cache/memory/memory.go:99
time=2022-03-17T17:27:54.531886319Z app=trickster level=debug event="memorycache cache store" ttl=30s is_direct=true caller=cache/memory/memory.go:99 cacheName=default cacheKey=prometheus-1.example.org:9090.opc.b95724c13c5dd4d5322c552ffa4be3bb length=0
time=2022-03-17T17:27:54.532798924Z app=trickster level=error event="labels unmarshaling error" provider=prometheus detail="invalid character '\\x1f' looking for beginning of value" caller=backends/prometheus/model/labels.go:81
time=2022-03-17T17:27:54.532833629Z app=trickster level=error event="labels unmarshaling error" provider=prometheus detail="invalid character '\\x1f' looking for beginning of value" caller=backends/prometheus/model/labels.go:81
time=2022-03-17T17:27:55.208069154Z app=trickster level=error event="vector unmarshaling error" provider=prometheus detail="json: cannot unmarshal number into Go struct field WFMatrixData.data.result of type model.WFResult" caller=backends/prometheus/transformations.go:51
time=2022-03-17T17:27:55.208160555Z app=trickster level=debug event="memory cache retrieve" caller=cache/memory/memory.go:148 cacheKey=prometheus-2.example.org:9090.opc.fcfefe8641c333d7cf85566801eec0e9
time=2022-03-17T17:27:55.2085418Z app=trickster level=debug event="memory cache retrieve" cacheKey=prometheus-1.example.org:9090.opc.fcfefe8641c333d7cf85566801eec0e9 caller=cache/memory/memory.go:148
time=2022-03-17T17:27:55.208790904Z app=trickster level=error event="vector unmarshaling error" detail="invalid character '\\x1f' looking for beginning of value" caller=backends/prometheus/model/vector.go:68 provider=prometheus
time=2022-03-17T17:27:55.208845925Z app=trickster level=error event="vector unmarshaling error" provider=prometheus detail="invalid character '\\x1f' looking for beginning of value" caller=backends/prometheus/model/vector.go:68
time=2022-03-17T17:27:55.209217154Z app=trickster level=error event="vector unmarshaling error" provider=prometheus detail="json: cannot unmarshal number into Go struct field WFMatrixData.data.result of type model.WFResult" caller=backends/prometheus/transformations.go:51
time=2022-03-17T17:27:55.210003957Z app=trickster level=debug event="memory cache retrieve" cacheKey=prometheus-2.example.org:9090.opc.b95724c13c5dd4d5322c552ffa4be3bb caller=cache/memory/memory.go:148
time=2022-03-17T17:27:55.210048805Z app=trickster level=debug event="memory cache retrieve" cacheKey=prometheus-1.example.org:9090.opc.b95724c13c5dd4d5322c552ffa4be3bb caller=cache/memory/memory.go:148
time=2022-03-17T17:27:55.213145618Z app=trickster level=error event="labels unmarshaling error" detail="invalid character '\\x1f' looking for beginning of value" caller=backends/prometheus/model/labels.go:81 provider=prometheus
time=2022-03-17T17:27:55.21315784Z app=trickster level=error event="labels unmarshaling error" provider=prometheus detail="invalid character '\\x1f' looking for beginning of value" caller=backends/prometheus/model/labels.go:81
time=2022-03-17T17:27:57.723877684Z app=trickster level=error event="vector unmarshaling error" provider=prometheus detail="invalid character '\\x1f' looking for beginning of value" caller=backends/prometheus/transformations.go:51
time=2022-03-17T17:27:57.724431688Z app=trickster level=error event="vector unmarshaling error" provider=prometheus detail="invalid character '\\x1f' looking for beginning of value" caller=backends/prometheus/transformations.go:51
time=2022-03-17T17:27:57.724522004Z app=trickster level=error event="vector unmarshaling error" detail="invalid character '\\x1f' looking for beginning of value" caller=backends/prometheus/model/vector.go:68 provider=prometheus
time=2022-03-17T17:27:57.724524341Z app=trickster level=error event="vector unmarshaling error" provider=prometheus detail="invalid character '\\x1f' looking for beginning of value" caller=backends/prometheus/model/vector.go:68
time=2022-03-17T17:27:57.727053397Z app=trickster level=error event="labels unmarshaling error" provider=prometheus detail="invalid character '\\x1f' looking for beginning of value" caller=backends/prometheus/model/labels.go:81
time=2022-03-17T17:27:57.727072358Z app=trickster level=error event="labels unmarshaling error" provider=prometheus detail="invalid character '\\x1f' looking for beginning of value" caller=backends/prometheus/model/labels.go:81

Config:

frontend:
  listen_port: 9090

backends:
  zone-01:
    provider: prometheus
    origin_url: prometheus-1.example.org:9090
    prometheus:
      labels:
        region: zone-01

  zone-02:
    provider: prometheus
    origin_url: prometheus-2.example.org:9090
    prometheus:
      labels:
        region: zone-02

  prom-alb-all:
    provider: alb
    alb:
      mechanism: tsm
      pool:
        - zone-01
        - zone-02
    is_default: true

logging:
  log_level: 'debug'

Full config:

main:
  config_handler_path: /trickster/config
  ping_handler_path: /trickster/ping
  reload_handler_path: /trickster/config/reload
  health_handler_path: /trickster/health
  pprof_server: both
  server_name: p-trickster-02
backends:
  prom-alb-all:
    provider: alb
    timeout_ms: 180000
    keep_alive_timeout_ms: 300000
    max_idle_conns: 20
    cache_name: default
    healthcheck:
      verb: GET
      scheme: http
      path: /
      expected_codes:
      - 200
    timeseries_retention_factor: 1024
    timeseries_eviction_method: oldest
    paths:
      /-0000000011:
        path: /
        match_type: prefix
        handler: alb
        methods:
        - GET
        - HEAD
        no_metrics: false
        reqrewriter: []
    negative_cache_name: default
    timeseries_ttl_ms: 21600000
    fastforward_ttl_ms: 15000
    max_ttl_ms: 86400000
    revalidation_factor: 2
    max_object_size_bytes: 524288
    tracing_name: default
    alb:
      mechanism: tsm
      pool:
      - zone-01
      - zone-02
      output_format: prometheus
    tls: {}
    forwarded_headers: standard
    is_default: true
    reqrewriter: []
  zone-01:
    provider: prometheus
    origin_url: http://prometheus-1.example.org:9090
    timeout_ms: 180000
    keep_alive_timeout_ms: 300000
    max_idle_conns: 20
    cache_name: default
    cache_key_prefix: prometheus-1.example.org:9090
    healthcheck:
      verb: GET
      scheme: http
      host: prometheus-1.example.org:9090
      path: /api/v1/query
      query: query=up
      expected_codes:
      - 200
    timeseries_retention_factor: 1024
    timeseries_eviction_method: oldest
    paths:
      /-0000000101:
        path: /
        match_type: prefix
        handler: proxy
        methods:
        - GET
        - POST
        no_metrics: false
        reqrewriter: []
      /api/v1/-0000000101:
        path: /api/v1/
        match_type: prefix
        handler: proxy
        methods:
        - GET
        - POST
        no_metrics: false
        reqrewriter: []
      /api/v1/admin-1111111111:
        path: /api/v1/admin
        match_type: prefix
        handler: admin
        methods:
        - GET
        - HEAD
        - POST
        - PUT
        - DELETE
        - CONNECT
        - OPTIONS
        - TRACE
        - PATCH
        - PURGE
        no_metrics: false
        reqrewriter: []
      /api/v1/alertmanagers-0000000001:
        path: /api/v1/alertmanagers
        match_type: exact
        handler: proxycache
        methods:
        - GET
        response_headers:
          Cache-Control: s-maxage=30
        no_metrics: false
        reqrewriter: []
      /api/v1/alerts-0000000001:
        path: /api/v1/alerts
        match_type: exact
        handler: alerts
        methods:
        - GET
        response_headers:
          Cache-Control: s-maxage=30
        no_metrics: false
        reqrewriter: []
      /api/v1/label/-0000000001:
        path: /api/v1/label/
        match_type: prefix
        handler: labels
        methods:
        - GET
        response_headers:
          Cache-Control: s-maxage=30
        no_metrics: false
        reqrewriter: []
      /api/v1/labels-0000000101:
        path: /api/v1/labels
        match_type: exact
        handler: labels
        methods:
        - GET
        - POST
        response_headers:
          Cache-Control: s-maxage=30
        no_metrics: false
        reqrewriter: []
      /api/v1/query-0000000101:
        path: /api/v1/query
        match_type: exact
        handler: query
        methods:
        - GET
        - POST
        cache_key_params:
        - query
        - time
        response_headers:
          Cache-Control: s-maxage=30
        no_metrics: false
        reqrewriter: []
      /api/v1/query_range-0000000101:
        path: /api/v1/query_range
        match_type: exact
        handler: query_range
        methods:
        - GET
        - POST
        cache_key_params:
        - query
        - step
        response_headers:
          Cache-Control: s-maxage=21600
        no_metrics: false
        reqrewriter: []
      /api/v1/rules-0000000001:
        path: /api/v1/rules
        match_type: exact
        handler: proxycache
        methods:
        - GET
        response_headers:
          Cache-Control: s-maxage=30
        no_metrics: false
        reqrewriter: []
      /api/v1/series-0000000101:
        path: /api/v1/series
        match_type: exact
        handler: series
        methods:
        - GET
        - POST
        cache_key_params:
        - match[]
        - start
        - end
        response_headers:
          Cache-Control: s-maxage=30
        no_metrics: false
        reqrewriter: []
      /api/v1/status-0000000001:
        path: /api/v1/status
        match_type: prefix
        handler: proxycache
        methods:
        - GET
        response_headers:
          Cache-Control: s-maxage=30
        no_metrics: false
        reqrewriter: []
      /api/v1/targets-0000000001:
        path: /api/v1/targets
        match_type: exact
        handler: proxycache
        methods:
        - GET
        response_headers:
          Cache-Control: s-maxage=30
        no_metrics: false
        reqrewriter: []
      /api/v1/targets/metadata-0000000001:
        path: /api/v1/targets/metadata
        match_type: exact
        handler: proxycache
        methods:
        - GET
        cache_key_params:
        - match_target
        - metric
        - limit
        response_headers:
          Cache-Control: s-maxage=30
        no_metrics: false
        reqrewriter: []
    negative_cache_name: default
    timeseries_ttl_ms: 21600000
    fastforward_ttl_ms: 15000
    max_ttl_ms: 86400000
    revalidation_factor: 2
    max_object_size_bytes: 524288
    tracing_name: default
    prometheus:
      labels:
        region: zone-01
    tls: {}
    forwarded_headers: standard
    reqrewriter: []
  zone-02:
    provider: prometheus
    origin_url: http://prometheus-2.example.org:9090
    timeout_ms: 180000
    keep_alive_timeout_ms: 300000
    max_idle_conns: 20
    cache_name: default
    cache_key_prefix: prometheus-2.example.org:9090
    healthcheck:
      verb: GET
      scheme: http
      host: prometheus-2.example.org:9090
      path: /api/v1/query
      query: query=up
      expected_codes:
      - 200
    timeseries_retention_factor: 1024
    timeseries_eviction_method: oldest
    paths:
      /-0000000101:
        path: /
        match_type: prefix
        handler: proxy
        methods:
        - GET
        - POST
        no_metrics: false
        reqrewriter: []
      /api/v1/-0000000101:
        path: /api/v1/
        match_type: prefix
        handler: proxy
        methods:
        - GET
        - POST
        no_metrics: false
        reqrewriter: []
      /api/v1/admin-1111111111:
        path: /api/v1/admin
        match_type: prefix
        handler: admin
        methods:
        - GET
        - HEAD
        - POST
        - PUT
        - DELETE
        - CONNECT
        - OPTIONS
        - TRACE
        - PATCH
        - PURGE
        no_metrics: false
        reqrewriter: []
      /api/v1/alertmanagers-0000000001:
        path: /api/v1/alertmanagers
        match_type: exact
        handler: proxycache
        methods:
        - GET
        response_headers:
          Cache-Control: s-maxage=30
        no_metrics: false
        reqrewriter: []
      /api/v1/alerts-0000000001:
        path: /api/v1/alerts
        match_type: exact
        handler: alerts
        methods:
        - GET
        response_headers:
          Cache-Control: s-maxage=30
        no_metrics: false
        reqrewriter: []
      /api/v1/label/-0000000001:
        path: /api/v1/label/
        match_type: prefix
        handler: labels
        methods:
        - GET
        response_headers:
          Cache-Control: s-maxage=30
        no_metrics: false
        reqrewriter: []
      /api/v1/labels-0000000101:
        path: /api/v1/labels
        match_type: exact
        handler: labels
        methods:
        - GET
        - POST
        response_headers:
          Cache-Control: s-maxage=30
        no_metrics: false
        reqrewriter: []
      /api/v1/query-0000000101:
        path: /api/v1/query
        match_type: exact
        handler: query
        methods:
        - GET
        - POST
        cache_key_params:
        - query
        - time
        response_headers:
          Cache-Control: s-maxage=30
        no_metrics: false
        reqrewriter: []
      /api/v1/query_range-0000000101:
        path: /api/v1/query_range
        match_type: exact
        handler: query_range
        methods:
        - GET
        - POST
        cache_key_params:
        - query
        - step
        response_headers:
          Cache-Control: s-maxage=21600
        no_metrics: false
        reqrewriter: []
      /api/v1/rules-0000000001:
        path: /api/v1/rules
        match_type: exact
        handler: proxycache
        methods:
        - GET
        response_headers:
          Cache-Control: s-maxage=30
        no_metrics: false
        reqrewriter: []
      /api/v1/series-0000000101:
        path: /api/v1/series
        match_type: exact
        handler: series
        methods:
        - GET
        - POST
        cache_key_params:
        - match[]
        - start
        - end
        response_headers:
          Cache-Control: s-maxage=30
        no_metrics: false
        reqrewriter: []
      /api/v1/status-0000000001:
        path: /api/v1/status
        match_type: prefix
        handler: proxycache
        methods:
        - GET
        response_headers:
          Cache-Control: s-maxage=30
        no_metrics: false
        reqrewriter: []
      /api/v1/targets-0000000001:
        path: /api/v1/targets
        match_type: exact
        handler: proxycache
        methods:
        - GET
        response_headers:
          Cache-Control: s-maxage=30
        no_metrics: false
        reqrewriter: []
      /api/v1/targets/metadata-0000000001:
        path: /api/v1/targets/metadata
        match_type: exact
        handler: proxycache
        methods:
        - GET
        cache_key_params:
        - match_target
        - metric
        - limit
        response_headers:
          Cache-Control: s-maxage=30
        no_metrics: false
        reqrewriter: []
    negative_cache_name: default
    timeseries_ttl_ms: 21600000
    fastforward_ttl_ms: 15000
    max_ttl_ms: 86400000
    revalidation_factor: 2
    max_object_size_bytes: 524288
    tracing_name: default
    prometheus:
      labels:
        region: zone-02
    tls: {}
    forwarded_headers: standard
    reqrewriter: []
caches:
  default:
    provider: memory
    index:
      reap_interval_ms: 3000
      flush_interval_ms: 5000
      max_size_bytes: 536870912
      max_size_backoff_bytes: 16777216
      max_size_backoff_objects: 100
    redis:
      client_type: standard
      protocol: tcp
      endpoint: redis:6379
      endpoints:
      - redis:6379
    filesystem:
      cache_path: /tmp/trickster
    bbolt:
      filename: trickster.db
      bucket: trickster
    badger:
      directory: /tmp/trickster
      value_directory: /tmp/trickster
frontend:
  listen_port: 9090
  tls_listen_port: 8483
logging:
  log_level: debug
metrics:
  listen_port: 8481
tracing:
  default:
    provider: none
    service_name: trickster
    sample_rate: 1
    stdout: {}
    jaeger: {}
negative_caches:
  default: {}
reloading:
  listen_address: 127.0.0.1
  listen_port: 8484
  handler_path: /trickster/config/reload
  drain_timeout_ms: 30000
  rate_limit_ms: 3000

[atkrv]

Oh, almost forgot!

I'm using prom/prometheus:v2.33.3 + trickstercache/trickster:2.0.0-beta2 🐳 images.

[jmichalek132]

We also ran into this with similar configuration and same versions of tricksters & prometheus.

[atkrv]

Seems there's some issue while merging of two JSON payloads - https://stackoverflow.com/questions/64460591/unmarshalling-json-returns-an-error-invalid-character-x1f-looking-for-beginn

@jranson could you please take a look? 🙏

[fcoelho]

I have the same issue. at least in my case is happening because trickster is encoding the response from the backends with gzip even if it was received with no encoding. and then when it comes time to parse and merge the results, it's trying to json parse gzip-encoded data directly (hence the \x1f which is the first byte of a gzip header)

the response from the backend gets encoded here, but the client in this case ends up being trickster itself.

I've "fixed" the problem for me by decoding it as needed in the Body function:

diff --git a/pkg/proxy/response/merge/merge.go b/pkg/proxy/response/merge/merge.go
index 4a6ed876..ee2db1f1 100644
--- a/pkg/proxy/response/merge/merge.go
+++ b/pkg/proxy/response/merge/merge.go
@@ -17,8 +17,13 @@
 package merge
 
 import (
+       "bytes"
+       "io"
        "net/http"
 
+       "github.com/trickstercache/trickster/v2/pkg/encoding/profile"
+       "github.com/trickstercache/trickster/v2/pkg/encoding/providers"
+       "github.com/trickstercache/trickster/v2/pkg/proxy/headers"
        "github.com/trickstercache/trickster/v2/pkg/proxy/request"
        "github.com/trickstercache/trickster/v2/pkg/util/copiers"
 )
@@ -57,6 +62,22 @@ func (rg *ResponseGate) WriteHeader(i int) {
 
 // Body returns the stored body for merging
 func (rg *ResponseGate) Body() []byte {
+       ep := profile.Profile{
+               ContentEncoding: rg.header.Get(headers.NameContentEncoding),
+               ContentType:     rg.header.Get(headers.NameContentType),
+       }
+
+       ep.ContentEncodingNum = providers.ProviderID(ep.ContentEncoding)
+
+       di := ep.GetDecoderInitializer()
+       if di != nil {
+               decoder := di(bytes.NewReader(rg.body))
+
+               data, _ := io.ReadAll(decoder)
+
+               return data
+       }
+
        return rg.body
 }

I do not think this is the right solution to the problem though as the error's being ignored and the response to the final client does not have any Content-Encoding set. it does work to validate that the issue is about trying to parse the data without decoding it first (or saving it decoded when it should have been plain text)

@jnichols-git do you know what would be the proper way to handle this?