[🐛 BUG]: Error while declaring metrics by on_init command: duplicate metrics collector registration attempted

[Kaspiman]

No duplicates 🥲.

• I have searched for a similar issue in our bug tracker and didn't find any solutions.

What happened?

A bug happened!

Version (rr --version)

version: 2023.2.0, buildtime: 2023-07-06T19:02:05+0000

How to reproduce the issue?

Try to init some metrics by on_init command and got error "duplicate metrics collector registration attempted".

Demo: see metric.php, rr.yaml and README.md

Relevant log output

2023-07-19T10:47:02+0000        DEBUG   rpc             plugin was started      {"address": "tcp://0.0.0.0:6001", "list of the plugins with RPC methods:": ["app", "metrics", "informer", "resetter", "lock"]}
2023-07-19T10:47:02+0000        DEBUG   metrics         declaring new metric    {"name": "test", "type": "counter", "namespace": ""}
2023-07-19T10:47:02+0000        DEBUG   metrics         metric successfully added       {"name": "test", "type": "counter", "namespace": ""}
2023-07-19T10:47:02+0000        DEBUG   metrics         adding metric   {"name": "test", "value": 1, "labels": []}
2023-07-19T10:47:02+0000        DEBUG   metrics         metric successfully added       {"name": "test", "labels": [], "value": 1}
2023-07-19T10:47:02+0000        INFO    server          ON INIT
handle_serve_command: Function call error:
        got initial serve error from the Vertex *metrics.Plugin, stopping execution, error: duplicate metrics collector registration attempted

[rustatian]

Hey @Kaspiman 👋🏻
I don't think this is the on_init case. Since you are trying to declare the metric twice, which is not allowed by Prometheus, this is the worker problem.

[rustatian]

You can use lock plugin: https://github.com/roadrunner-php/lock to prevent registration of the same metrics. Registration should be done by one process (worker). Lock the resource with a wait time like 1 millisecond. Only 1 worker would be able to get a lock. Then register all needed metrics and release the lock.

[Kaspiman]

@rustatian on_init does not called for every worker. As you see ON INIT printed once, not 8 times

[Kaspiman]

Two calls of rpc declare looks like that:

2023-07-19T11:21:13+0000        DEBUG   rpc             plugin was started      {"address": "tcp://0.0.0.0:6001", "list of the plugins with RPC methods:": ["metrics", "app", "lock", "resetter", "informer"]}
2023-07-19T11:21:13+0000        DEBUG   metrics         declaring new metric    {"name": "test", "type": "counter", "namespace": ""}
2023-07-19T11:21:13+0000        DEBUG   metrics         metric successfully added       {"name": "test", "type": "counter", "namespace": ""}
2023-07-19T11:21:13+0000        DEBUG   metrics         declaring new metric    {"name": "test", "type": "counter", "namespace": ""}
2023-07-19T11:21:13+0000        ERROR   metrics         metric with provided name already exist {"name": "test", "type": "counter", "namespace": ""}
2023-07-19T11:21:13+0000        INFO    server      
Fatal error: Uncaught Spiral\Goridge\RPC\Exception\ServiceException: Error 'metrics_plugin_declare: tried to register existing collector with the name `test`' on tcp://0.0.0.0:6001 in /var/www/html/vendor/spiral/goridge/src/RPC/RPC.php:101
Stack trace:
#0 /var/www/html/vendor/spiral/goridge/src/RPC/RPC.php(75): Spiral\Goridge\RPC\RPC->decodeResponse(Object(Spiral\Goridge\Frame), NULL)
#1 /var/www/html/metric.php(28): Spiral\Goridge\RPC\RPC->call('Declare', Array)
#2 {main}
  thrown in /var/www/html/vendor/spiral/goridge/src/RPC/RPC.php on line 101
2023-07-19T11:21:13+0000        ERROR   server          process wait    {"error": "exit status 255"}
[INFO] RoadRunner server started; version: 2023.2.0, buildtime: 2023-07-06T19:02:05+0000

[Kaspiman]

I tried on_init but it does not working

[rustatian]

It's hard to tell what's happening in your env. The on_init command is called once after the server plugin initialization. But the fact is that somewhere (maybe in the regular worker) or in the configuration, you have already declared this metric and trying to re-declare it then.

[Kaspiman]

It's easy to see what's happening in my env because i attached DEMO with simple reproduce steps

[rustatian]

As I mentioned, the problem is somewhere in your env.
Tested on the following inputs:

• config:

version: '3'

metrics:
  address: '0.0.0.0:9254'

logs:
  level: debug
  mode: development

rpc:
  listen: 'tcp://0.0.0.0:6001'

server:
  command: "php foo"
  on_init:
    command: "php ../../php_test_files/on-init-metrics.php"

• worker:

require __DIR__ . '/vendor/autoload.php';

use Spiral\Goridge\Relay;
use Spiral\Goridge\RPC\RPC;

$rpc = new RPC(
    Relay::create('tcp://0.0.0.0:6001')
);
echo "foo";
$rpc = $rpc->withServicePrefix('metrics');

$rpc->call('Declare', [
    'name'      => 'test',
    'collector' => [
        'namespace' => '',
        'subsystem' => '',
        'type'      => 'counter',
        'help'      => '',
        'labels'    => [],
        'buckets'   => [],
    ],
]);

echo "foo2";
$rpc->call('Add', [
    'name'   => 'test',
    'value'  => 1.0,
    'labels' => [],
]);

echo "ON INIT";

• logs:

2023-07-19T15:56:42+0000	DEBUG	rpc         	plugin was started	{"address": "tcp://0.0.0.0:6001", "list of the plugins with RPC methods:": ["metrics"]}
{"time":"2023-07-19T17:56:42.265395585+02:00","level":"DEBUG","msg":"calling serve method","plugin":"*logger.Plugin"}
{"time":"2023-07-19T17:56:42.265400356+02:00","level":"DEBUG","msg":"calling serve method","plugin":"*metrics.Plugin"}
{"time":"2023-07-19T17:56:42.265407797+02:00","level":"DEBUG","msg":"calling serve method","plugin":"*server.Plugin"}
2023-07-19T15:56:42+0000	INFO	server      	foo
2023-07-19T15:56:42+0000	DEBUG	metrics     	declaring new metric	{"name": "test", "type": "counter", "namespace": ""}
2023-07-19T15:56:42+0000	DEBUG	metrics     	metric successfully added	{"name": "test", "type": "counter", "namespace": ""}
2023-07-19T15:56:42+0000	INFO	server      	foo2
2023-07-19T15:56:42+0000	DEBUG	metrics     	adding metric	{"name": "test", "value": 1, "labels": []}
2023-07-19T15:56:42+0000	DEBUG	metrics     	metric successfully added	{"name": "test", "labels": [], "value": 1}
2023-07-19T15:56:42+0000	INFO	server      	ON INIT
{"time":"2023-07-19T17:56:42.275236164+02:00","level":"DEBUG","msg":"serving"}
{"time":"2023-07-19T17:56:47.27813494+02:00","level":"DEBUG","msg":"calling stop"}
{"time":"2023-07-19T17:56:47.27827736+02:00","level":"DEBUG","msg":"calling stop function","plugin":"*server.Plugin"}
{"time":"2023-07-19T17:56:48.279396177+02:00","level":"DEBUG","msg":"calling stop function","plugin":"*rpc.Plugin"}
{"time":"2023-07-19T17:56:48.279640634+02:00","level":"DEBUG","msg":"calling stop function","plugin":"*metrics.Plugin"}
{"time":"2023-07-19T17:56:48.279796815+02:00","level":"DEBUG","msg":"calling stop function","plugin":"*logger.Plugin"}

[rustatian]

I would be happy to help you, but I do not have a reproduction of the problem.

[rustatian]

Reopening, looks like I found a problem.