[🐛 BUG]: "Storage is not defined" exception when reading KV cache early into the PHP worker

[ekisu]

No duplicates 🥲.

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

What happened?

When we read from the KV plugin cache very early in the PHP worker process, sometimes we receive a Storage <x> is not defined exception (it may take a few reruns of the rr executable to trigger the bug).

I expected the caches to be available even if early in the process (or, if that's not possible, a way to wait until they're ready)

Version (rr --version)

rr version 2023.1.4 (build time: 2023-05-25T11:10:33+0000, go1.20.4), OS: linux, arch: amd64

How to reproduce the issue?

.rr.yaml

version: "3"
http:
  address: 127.0.0.1:9000
  pool:
    num_workers: 10
kv:
  in_memory:
    driver: memory
    config: {}
rpc:
  listen: tcp://127.0.0.1:6001
server:
  command: "php psr-worker.php"

psr-worker.php

<?php

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

use Nyholm\Psr7\Response;
use Nyholm\Psr7\Factory\Psr17Factory;
use Psr\Http\Message\ServerRequestInterface;
use Spiral\RoadRunner\Worker;
use Spiral\RoadRunner\Http\PSR7Worker;
use Spiral\Goridge\RPC\RPC;
use Spiral\RoadRunner\KeyValue\Factory as KVFactory;

// Read some value from the KV storage early on the worker
$rpc = RPC::create('tcp://127.0.0.1:6001');
$kvFactory = new KVFactory($rpc);

$storage = $kvFactory->select('in_memory');
$storage->get('test_key');

// Just a sample PHP worker hereafter
$worker = Worker::create();
$factory = new Psr17Factory();

$psr7 = new PSR7Worker($worker, $factory, $factory, $factory);

while (true) {
    try {
        $request = $psr7->waitRequest();
        if (!$request instanceof ServerRequestInterface) { // Termination request received
            break;
        }
    } catch (\Throwable $e) {
        $psr7->respond(new Response(400));
        continue;
    }

    try {
        $psr7->respond(new Response(200, [], 'Hello RoadRunner!'));
    } catch (\Throwable $e) {
        $psr7->respond(new Response(500, [], 'Something Went Wrong!'));
        
        $psr7->getWorker()->error((string)$e);
    }
}

Relevant log output

2023-06-02T15:05:21+0000	DEBUG	rpc         	plugin was started	{"address": "tcp://127.0.0.1:6001", "list of the plugins with RPC methods:": ["lock", "app", "informer", "resetter", "kv"]}
handle_serve_command: Function call error:
	got initial serve error from the Vertex *http.Plugin, stopping execution, error: static_pool_allocate_workers: WorkerAllocate:
	goridge_frame_receive: validation failed on the message sent to STDOUT, see: https://roadrunner.dev/docs/known-issues-stdout-crc/2.x/en, invalid message: 
Fatal error: Uncaught Spiral\RoadRunner\KeyValue\Exception\StorageException: Storage "in_memory" has not been defined. Please make sure your RoadRunner "kv" configuration contains a storage key named "in_memory" in /home/ramon/Projetos/test-roadrunner-kv-bug/vendor/spiral/roadrunner-kv/src/Cache.php:138
Stack trace:
#0 /home/ramon/Projetos/test-roadrunner-kv-bug/vendor/spiral/roadrunner-kv/src/Cache.php(207): Spiral\RoadRunner\KeyValue\Cache->call('kv.MGet', Object(RoadRunner\KV\DTO\V1\Request))
#1 /home/ramon/Projetos/test-roadrunner-kv-bug/vendor/spiral/roadrunner-kv/src/Cache.php(187): Spiral\RoadRunner\KeyValue\Cache->getMultiple(Array, NULL)
#2 /home/ramon/Projetos/test-roadrunner-kv-bug/psr-worker.php(18): Spiral\RoadRunner\KeyValue\Cache->get('test_key')
#3 {main}
  thrown in /home/ramon/Projetos/test-roadrunner-kv-bug/vendor/spiral/roadrunner-kv/src/Cache.php on line 138

[rustatian]

Hey @ekisu 👋🏻
Could you please try to use the following config:

version: "3"
http:
  address: 127.0.0.1:9000
  pool:
    num_workers: 10
kv:
  in_memory:
    driver: memory
    config:
        interval: 1
rpc:
  listen: tcp://127.0.0.1:6001
server:
  command: "php psr-worker.php"

[ekisu]

Hi @rustatian, the bug still happens after adding the interval: 1 setting

[rustatian]

Hm, strange, ok, I'll dig into that, thanks for the report 👍🏻

[rustatian]

Okay, I understand the problem. It's a bit tricky, but easily solved. The problem is in the order in which the plugins are served. I wrote a custom weighted graph to topologically sort the plugins with their deps (among each other if there is one). So the RPC plugin has the biggest weight and is always started first to initialize the RPC transport correctly for all dependend plugins. But the order of KV and HTTP plugins is not defined. They are initialized after their dependencies are ready. This is why this error can occur during random runs (topological sorting). Fix is trivial, add weight to the KV plugin (and all plugins without the pool of workers). Will be fixed and double tested. Expected bugfix release is Thursday, as usual (June 8th). Thanks 👍🏻

[rustatian]

fixed by: roadrunner-server/kv@98bf32a

[ekisu]

Thanks a lot!