PrometheusExporter::Server::Collector#process JSON::ParserError

[konfortes]

Hey, I have a ruby app, sending metrics to the built-in collector through the client. For some reason, I'm getting 500 response to POST /send-metrics with log messages like: #<JSON::ParserError: 767: unexpected token at (full message below) with this trace:

server /usr/local/lib/ruby/2.6.0/json/common.rb:156:in `parse'
server /usr/local/lib/ruby/2.6.0/json/common.rb:156:in `parse'
server /usr/local/bundle/gems/prometheus_exporter-0.5.1/lib/prometheus_exporter/server/collector.rb:29:in `process'
server /usr/local/bundle/gems/prometheus_exporter-0.5.1/lib/prometheus_exporter/server/web_server.rb:82:in `block in handle_metrics'
server /usr/local/lib/ruby/2.6.0/webrick/httprequest.rb:546:in `read_chunked'
server /usr/local/lib/ruby/2.6.0/webrick/httprequest.rb:506:in `read_body'
server /usr/local/lib/ruby/2.6.0/webrick/httprequest.rb:256:in `body'
server /usr/local/bundle/gems/prometheus_exporter-0.5.1/lib/prometheus_exporter/server/web_server.rb:79:in `handle_metrics'
server /usr/local/bundle/gems/prometheus_exporter-0.5.1/lib/prometheus_exporter/server/web_server.rb:69:in `block in initialize'
server /usr/local/lib/ruby/2.6.0/webrick/httpservlet/prochandler.rb:39:in `do_GET'
server /usr/local/lib/ruby/2.6.0/webrick/httpservlet/abstract.rb:105:in `service'
server /usr/local/lib/ruby/2.6.0/webrick/httpserver.rb:140:in `service'
server /usr/local/lib/ruby/2.6.0/webrick/httpserver.rb:96:in `run'
server /usr/local/lib/ruby/2.6.0/webrick/server.rb:307:in `block in start_thread'

My usage is pretty basic, kind of copy-paste from the readme:

collector:

CMD ["bundle", "exec", "prometheus_exporter", "-b", "0.0.0.0", "-t", "3", "--prefix", "my_app_"]

client:

PrometheusExporter::Client.default = PrometheusExporter::Client.new(custom_labels: {app: 'workers', env: 'production'})
Prometheus::Client.register_counter('order_links', 'order links')

Prometheus::Client.increment('order_links', link:: 'billing_phone')

Full Message:

server #<JSON::ParserError: 767: unexpected token at '{"type":"counter","help":"order links","name":"order_links","keys":{"link":"billing_phone"},"value":1,"prometheus_exporter_action":"increment","custom_labels":{"app":"workers","env":"production"}}{"type":"counter","help":"order links","name":"order_links","keys":{"link":"customer_last_name"},"value":1,"prometheus_exporter_action":"increment","custom_labels":{"app":"workers","env":"production"}}{"type":"counter","help":"order links","name":"order_links","keys":{"link":"shipping_first_name"},"value":1,"prometheus_exporter_action":"increment","custom_labels":{"app":"workers","env":"production"}}{"type":"counter","help":"order links","name":"order_links","keys":{"link":"customer_first_name"},"value":1,"prometheus_exporter_action":"increment","custom_labels":{"app":"workers","env":"production"}}{"type":"counter","help":"order links","name":"order_links","keys":{"link":"shipping_address1"},"value":1,"prometheus_exporter_action":"increment","custom_labels":{"app":"workers","env":"production"}}{"type":"counter","help":"order links","name":"order_links","keys":{"link":"shipping_phone"},"value":1,"prometheus_exporter_action":"increment","custom_labels":{"app":"workers","env":"production"}}{"type":"counter","help":"order links","name":"order_links","keys":{"link":"shipping_last_name"},"value":1,"prometheus_exporter_action":"increment","custom_labels":{"app":"workers","env":"production"}}{"type":"counter","help":"order links","name":"order_links","keys":{"link":"billing_first_name"},"value":1,"prometheus_exporter_action":"increment","custom_labels":{"app":"workers","env":"production"}}{"type":"counter","help":"order links","name":"order_links","keys":{"link":"billing_address1"},"value":1,"prometheus_exporter_action":"increment","custom_labels":{"app":"workers","env":"production"}}{"type":"counter","help":"order links","name":"order_links","keys":{"link":"billing_address1"},"value":1,"prometheus_exporter_action":"increment","custom_labels":{"app":"workers","env":"production"}}{"type":"counter","help":"order links","name":"order_links","keys":{"link":"wp_billing_formatted_address"},"value":1,"prometheus_exporter_action":"increment","custom_labels":{"app":"workers","env":"production"}}{"type":"counter","help":"order links","name":"order_links","keys":{"link":"billing_address1"},"value":1,"prometheus_exporter_action":"increment","custom_labels":{"app":"workers","env":"production"}}{"type":"counter","help":"order links","name":"order_links","keys":{"link":"wp_billing_formatted_address"},"value":1,"prometheus_exporter_action":"increment","custom_labels":{"app":"workers","env":"production"}}{"type":"counter","help":"order links","name":"order_links","keys":{"link":"billing_address1"},"value":1,"prometheus_exporter_action":"increment","custom_labels":{"app":"workers","env":"production"}}{"type":"counter","help":"order links","name":"order_links","keys":{"link":"wp_billing_formatted_address"},"value":1,"prometheus_exporter_action":"increment","custom_labels":{"app":"workers","env":"production"}}{"type":"counter","help":"order links","name":"order_links","keys":{"link":"billing_address1"},"value":1,"prometheus_exporter_action":"increment","custom_labels":{"app":"workers","env":"production"}}{"type":"counter","help":"order links","name":"order_links","keys":{"link":"wp_billing_formatted_address"},"value":1,"prometheus_exporter_action":"increment","custom_labels":{"app":"workers","env":"production"}}{"type":"counter","help":"order links","name":"order_links","keys":{"link":"billing_address1"},"value":1,"prometheus_exporter_action":"increment","custom_labels":{"app":"workers","env":"production"}}{"type":"counter","help":"order links","name":"order_links","keys":{"link":"wp_billing_formatted_address"},"value":1,"prometheus_exporter_action":"increment","custom_labels":{"app":"workers","env":"production"}}{"type":"counter","help":"order links","name":"order_links","keys":{"link":"billing_address1"},"value":1,"prometheus_exporter_action":"increment","custom_labels":{"app":"workers","env":"production"}}{"type":"counter","help":"order links","name":"order_links","keys":{"link":"wp_billing_formatted_address"},"value":1,"prometheus_exporter_action":"increment","custom_labels":{"app":"workers","env":"production"}}{"type":"counter","help":"order links","name":"order_links","keys":{"link":"billing_address1"},"value":1,"prometheus_exporter_action":"increment","custom_labels":{"app":"workers","env":"production"}}{"type":"counter","help":"order links","name":"order_links","keys":{"link":"wp_billing_formatted_address"},"value":1,"prometheus_exporter_action":"increment","custom_labels":{"app":"workers","env":"production"}}{"type":"counter","help":"order links","name":"order_links","keys":{"link":"billing_address1"},"value":1,"prometheus_exporter_action":"increment","custom_labels":{"app":"workers","env":"production"}}{"type":"counter","help":"order links","name":"order_links","keys":{"link":"wp_billing_formatted_address"},"value":1,"prometheus_exporter_action":"increment","custom_labels":{"app":"workers","env":"production"}}{"type":"counter","help":"order links","name":"order_links","keys":{"link":"billing_address1"},"value":1,"prometheus_exporter_action":"increment","custom_labels":{"app":"workers","env":"production"}}{"type":"counter","help":"order links","name":"order_links","keys":{"link":"wp_billing_formatted_address"},"value":1,"prometheus_exporter_action":"increment","custom_labels":{"app":"workers","env":"production"}}{"type":"counter","help":"order links","name":"order_links","keys":{"link":"billing_address1"},"value":1,"prometheus_exporter_action":"increment","custom_labels":{"app":"workers","env":"production"}}{"type":"counter","help":"order links","name":"order_links","keys":{"link":"wp_billing_formatted_address"},"value":1,"prometheus_exporter_action":"increment","custom_labels":{"app":"workers","env":"production"}}{"type":"counter","help":"order links","name":"order_links","keys":{"link":"billing_address1"},"value":1,"prometheus_exporter_action":"increment","custom_labels":{"app":"workers","env":"production"}}{"type":"counter","help":"order links","name":"order_links","keys":{"link":"wp_billing_formatted_address"},"value":1,"prometheus_exporter_action":"increment","custom_labels":{"app":"workers","env":"production"}}{"type":"counter","help":"order links","name":"order_links","keys":{"link":"billing_last_name"},"value":1,"prometheus_exporter_action":"increment","custom_labels":{"app":"workers","env":"production"}}{"type":"counter","help":"order links","name":"order_links","keys":{"link":"billing_phone"},"value":1,"prometheus_exporter_action":"increment","custom_labels":{"app":"workers","env":"production"}}{"type":"counter","help":"order links","name":"order_links","keys":{"link":"billing_first_name"},"value":1,"prometheus_exporter_action":"increment","custom_labels":{"app":"workers","env":"production"}}{"type":"counter","help":"order links","name":"order_links","keys":{"link":"billing_last_name"},"value":1,"prometheus_exporter_action":"increment","custom_labels":{"app":"workers","env":"production"}}{"type":"counter","help":"order links","name":"order_links","keys":{"link":"billing_phone"},"value":1,"prometheus_exporter_action":"increment","custom_labels":{"app":"workers","env":"production"}}{"type":"counter","help":"order links","name":"order_links","keys":{"link":"billing_first_name"},"value":1,"prometheus_exporter_action":"increment","custom_labels":{"app":"workers","env":"production"}}{"type":"counter","help":"order links","name":"order_links","keys":{"link":"billing_last_name"},"value":1,"prometheus_exporter_action":"increment","custom_labels":{"app":"workers","env":"production"}}{"type":"counter","help":"order links","name":"order_links","keys":{"link":"billing_phone"},"value":1,"prometheus_exporter_action":"increment","custom_labels":{"app":"workers","env":"production"}}{"type":"counter","help":"order links","name":"order_links","keys":{"link":"billing_first_name"},"value":1,"prometheus_exporter_action":"increment","custom_labels":{"app":"workers","env":"production"}}{"type":"counter","help":"order links","name":"order_links","keys":{"link":"billing_last_name"},"value":1,"prometheus_exporter_action":"increment","custom_labels":{"app":"workers","env":"production"}}{"type":"counter","help":"order links","name":"order_links","keys":{"link":"billing_phone"},"value":1,"prometheus_exporter_action":"increment","custom_labels":{"app":"workers","env":"production"}}{"type":"counter","help":"order links","name":"order_links","keys":{"link":"billing_first_name"},"value":1,"prometheus_exporter_action":"increment","custom_labels":{"app":"workers","env":"production"}}{"type":"counter","help":"order links","name":"order_links","keys":{"link":"billing_last_name"},"value":1,"prometheus_exporter_action":"increment","custom_labels":{"app":"workers","env":"production"}}{"type":"counter","help":"order links","name":"order_links","keys":{"link":"billing_phone"},"value":1,"prometheus_exporter_action":"increment","custom_labels":{"app":"workers","env":"production"}}'>

I guess this is a WEBrick log, right? should it be a valid json? (there are no commas between items)

[konfortes]

@SamSaffron

[SamSaffron]

I saw this, can you try to debug what is wrong with the json? what is the unexpected token?

[konfortes]

Look at the Full Message, it looks like all chunks are sent over the TCP connection instead of each chunk separately. I'm trying to reproduce on my machine but no success so far.

[konfortes]

@SamSaffron I tried to write my own web server (with Go) and kept getting the same JSON parse errors. That reduces the issue to the client. Still trying to reproduce it.

[bogn83]

Also seeing problems with chunking. No JSON::ParserError though. It's just that nothing happens because the chunking receiver block is not yielded. The effect for us is that the new sidekiq metrics don't show up at all.

If I comment out the chunking block from the Webrick request.body block as follows everything works. Without the comments all packets are "lost" because the req.body block is never yielded.

    def handle_metrics(req, res)
      @sessions_total.observe
#     req.body do |block|
        begin
          @metrics_total.observe
#         @collector.process(block)
          @collector.process(req.body)
        rescue => e
          if @verbose
            STDERR.puts
            STDERR.puts e.inspect
            STDERR.puts e.backtrace
            STDERR.puts
          end
          @bad_metrics_total.observe
          res.body = "Bad Metrics #{e}"
          res.status = e.respond_to?(:status_code) ? e.status_code : 500
          return
        end
#     end

This is for a localhost connection test inside a docker container.

Server start

bundle exec prometheus_exporter -v --bind 0.0.0.0 -p 9395

Sending from client

PrometheusExporter::Client.new(host: 'localhost', port: 9395).send_json(JSON.parse(File.read('queue.json')))

When req.body is commented out, I can grep new sidekiq values from the console after using above send_json call from ruby:

curl -s localhost:9395/metrics | grep backlog

[SamSaffron]

Where is the client, is there a proxy between the client and server?

[bogn83]

Sorry wasn't that clearly communicated, they're both in the same docker container with no proxy in between. I thought that this next bit of info is irrelevant but who knows: on the host itself the docker daemon uses socat forwarding for IPv6. Shouldn't matter for traffic that's purely inside the container though, at least that was my assumption.

[SamSaffron]

Can you repro this on local? If so a failing test case would be enormously useful.

[bogn83]

The setup mentioned above can be considered local as the exporter client connects to a locally running prometheus_exporter server, both server and client are in the same container.

Not sure right now, how to simulate a client that is sending packets that are not actually chunked to a chunked connection with a server that is running simultaneously from that same test process. Does anyone have a pointer or hint here?

[bogn83]

Actually with 0.6.0 the new queue metrics are finally included. Maybe it's those socket fixes in that release. We'll test it out now.

[johnson]

I have similar error in a K8S deployment. I added rescue puts "#{obj}" to https://github.com/discourse/prometheus_exporter/blob/v2.0.3/lib/prometheus_exporter.rb#L18, and print out examples like:

{"type":"web","timings":{"sql":{"duration":0.0008798960188869387,"calls":1},"total_duration":0.01029436700628139},"queue_time":null,"status":200,"default_labels":{"action":"index","controller":"site"},}{"type":"web","timings":{"sql":{"duration":0.0008893409976735711,"calls":1},"total_duration":0.010752125002909452},"queue_time":null,"status":200,"default_labels":{"action":"index","controller":"site"},}{"pid":346,"type":"active_record","hostname":"web-app-6fb6dffb99-rw845","metric_labels":{"pool_name":"primary","dbconfig_database":"production","dbconfig_host":"postgresql"},"size":5,"connections":1,"busy":0,"dead":0,"idle":1,"waiting":0,"checkout_timeout":5.0}

It's three json objects combined together without comma amount them. You may check with json lint tool like https://jsonformatter.curiousconcept.com.

I can't reproduce in my local dev environment, but it's present in K8S production environment.

[sosedoff]

I also ran into this issue while running prometheus_exporter behind nginx in docker, and its fairly easy to reproduce locally.

FROM ruby:2.7
# 3.x also could be used

RUN apt-get update && \
    apt-get install -y nginx
ADD nginx.conf /etc/nginx/sites-available/default

WORKDIR /app

ADD Gemfile Gemfile.lock /app
RUN bundle install --jobs=4
ADD . /app

EXPOSE 9394
EXPOSE 80

CMD ["bundle", "exec", "foreman", "start"]

My Gemfile:

source "https://rubygems.org"

gem "prometheus_exporter"
gem "foreman"

Procfile:

prometheus_exporter: bundle exec prometheus_exporter -t 10 -v -b 0.0.0.0
nginx: nginx -g 'daemon off;'

nginx.conf:

upstream ruby {
  server 127.0.0.1:9394;
}

server {
  listen 80 default_server;
  listen [::]:80 default_server;

  access_log /dev/stdout;
  error_log /dev/stdout;

  server_name _;

  location / {
    proxy_pass http://ruby;
    proxy_redirect off;
    proxy_set_header Host             $host;
    proxy_set_header X-Real-IP        $remote_addr;
    proxy_set_header X-Forwarded-For  $proxy_add_x_forwarded_for;
    
    # needs to be set, otherwise nginx errors out with HTTP 499
    proxy_ignore_client_abort on;
  }
}

I have not found a fix yet.

[sosedoff]

I needed to get the prometheus_exporter working with nginx, so i monkey-patched the collector code for the time being:

diff --git a/lib/prometheus_exporter/server/collector.rb b/lib/prometheus_exporter/server/collector.rb
index a26263a..b3afcc3 100644
--- a/lib/prometheus_exporter/server/collector.rb
+++ b/lib/prometheus_exporter/server/collector.rb
@@ -30,7 +30,9 @@ module PrometheusExporter::Server
     end
 
     def process(str)
-      process_hash(@json_serializer.parse(str))
+      read_json_blocks(str) do |line|
+        process_hash(@json_serializer.parse(line))
+      end
     end
 
     def process_hash(obj)
@@ -102,5 +104,29 @@ module PrometheusExporter::Server
     def symbolize_keys(hash)
       hash.inject({}) { |memo, k| memo[k.first.to_sym] = k.last; memo }
     end
+
+    def read_json_blocks(str)
+      start = nil
+      nest  = 0
+      read  = 0
+
+      0.upto(str.length - 1) do |idx|
+        if str[idx] == '{'
+          start ||= idx
+          nest += 1
+        elsif str[idx] == '}' && start && (nest -= 1) == 0
+          yield str[start..idx]
+          read += 1
+          start = nil
+        end
+      end
+
+      if read == 0
+        yield str
+        read += 1
+      end
+
+      read
+    end
   end
 end

I'll keep digging on the chunking issue later this week.