Relay\Cluster subscribe method throwing Relay\Exception: Resource temporarily unavailable #163

dorrogeray · 2025-02-19T10:11:32Z

dorrogeray
Feb 19, 2025

With PHP 8.2 and Relay 0.10 or 0.10.1, following script attempting to subscribe to a valkey or redis 7.2 cluster results in an error:

<?php

use Relay\Cluster;

$relayCluster = new Cluster(
    "unprefixed-untracked",
    ["tcp://valkey-cluster-untracked:6372"],
    5,
    5,
    false,
    null,
    [],
);

$relayCluster->subscribe(['abc'], function (): void {
    echo 'subscribed';
});

Error:

www-data@2ed6294b3a05:~/html$ php test-subscribe.php 
[19-Feb-2025 10:00:40 EUROPE/LONDON] PHP Fatal error:  Uncaught Relay\Exception: Resource temporarily unavailable (RELAY_ERR_REDIS; commands.c:7766) in /var/www/html/test-subscribe.php:15
Stack trace:
#0 /var/www/html/test-subscribe.php(15): Relay\Cluster->subscribe()
#1 {main}
  thrown in /var/www/html/test-subscribe.php on line 15
[19-Feb-2025 10:00:40 EUROPE/LONDON] PHP Stack trace:
[19-Feb-2025 10:00:40 EUROPE/LONDON] PHP   1. newrelic_exception_handler($exception = class Relay\Exception { protected $message = 'Resource temporarily unavailable (RELAY_ERR_REDIS; commands.c:7766)'; private string ${Exception}string = 'Relay\\Exception: Resource temporarily unavailable (RELAY_ERR_REDIS; commands.c:7766) in /var/www/html/test-subscribe.php:15\nStack trace:\n#0 /var/www/html/test-subscribe.php(15): Relay\\Cluster->subscribe()\n#1 {main}'; protected $code = 14; protected string $file = '/var/www/html/test-subscribe.php'; protected int $line = 15; private array ${Exception}trace = [0 => [...]]; private ?Throwable ${Exception}previous = NULL }) Unknown:0

Here are the relay logs with log level debug:

[1739959750.777437 DBG 355] shmalloc.c:301 Allocated 16777216 byte pool (head: 7a11ba281000, curr: 7a11ba282020, alignment: 16)
[1739959750.777501 DBG 355] cache.c:45 EPOCH[malloc]: 7a11ba288ec0 (5303 bytes)
[1739959750.777528 NOT 355] relay.c:2529 STARTUP - Relay has started...
[1739959750.778899 DBG 355] relay.c:3431 RINIT - Requests (1 total, 1 active, 1 max)
[1739959750.778982 DBG 355] relay.c:3395 HTTP_HOST - Failed to find HTTP_HOST or it's not a string
[1739959750.778986 DBG 355] relay.c:3370 PLINK - Uninstalling handlers for 0 links
[1739959750.781140 DBG 355] cache.c:45 EPOCH[malloc]: 7a11ba28e770 (4407 bytes)
[1739959750.781177 DBG 355] cache.c:2204 RDB - Adding new db 7a11ba28e640
[1739959750.781673 NOT 355] relay.c:3954 CRON TASKS - GC(keys): 1; GC(msg): 0, EVICTED: 0 keys
[1739959750.781690 NOT 355] relay.c:3962 CRON  PROC - hits/miss: 0/0 (0.00%), oom: 0, errors: 0
[1739959750.781700 NOT 355] relay.c:3913 CRON STATS - Memory 59568/16777216 bytes (0.36%)
[1739959750.783966 DBG 355] cache.c:2352 ENDPOINT - releasing rdb (ep: 7a11ba28e4f0, rdb: 7a11ba28e640
[1739959750.784465 DBG 355] cache.c:45 EPOCH[malloc]: 7a11ba28fb60 (4407 bytes)
[1739959750.784496 DBG 355] cache.c:2204 RDB - Adding new db 7a11ba28fa30
[1739959756.052809 DBG 355] cache.c:2352 ENDPOINT - releasing rdb (ep: 7a11ba28f8e0, rdb: 7a11ba28fa30
[1739959756.053211 DBG 355] relay.c:3487 PID - Unregistering reader 7a11ba288dc0
[1739959756.053226 NOT 355] relay.c:3954 CRON TASKS - GC(keys): 1; GC(msg): 0, EVICTED: 0 keys
[1739959756.053230 NOT 355] relay.c:3962 CRON  PROC - hits/miss: 0/0 (0.00%), oom: 0, errors: 0
[1739959756.053234 NOT 355] relay.c:3913 CRON STATS - Memory 64672/16777216 bytes (0.39%)
[1739959756.053252 DBG 355] relay.c:3313 PLINK - installing handlers for 0 links
[1739959756.053261 DBG 355] cache.c:321 ENDPOINT[0] - 'tcp://[email protected]:6373?cache=1&tracking=1' ep: 7a11ba28f8e0, rdb: 7a11ba28fa30 keys: 0
[1739959756.053265 DBG 355] cache.c:321 ENDPOINT[1] - 'tcp://[email protected]:6372?cache=1&tracking=1' ep: 7a11ba28e4f0, rdb: 7a11ba28e640 keys: 0
[1739959756.053269 DBG 355] relay.c:3522 RSHUTDOWN - Finished request
[1739959756.053487 NOT 355] relay.c:2559 MSHUTDOWN - Relay is shutting down, bye bye

This code has worked for me before, but very curiously, even when I tried downgrading gradually all the way down to relay 0.7.0 which introduced the Relay\Cluster class, I still kept getting the same error. Doing GET / SET / DEL all works fine and I can even see the SUBSCRIBE command in the Redis Insight profiler getting called.

I have tried both with cache enabled and with cache disabled, it made no difference.

So I am wondering what other factor could have caused this..

PHP version:

PHP 8.2.27 (cli) (built: Dec 24 2024 06:15:50) (NTS)
Copyright (c) The PHP Group
Zend Engine v4.2.27, Copyright (c) Zend Technologies
    with Zend OPcache v8.2.27, Copyright (c), by Zend Technologies
    with Xdebug v3.4.1, Copyright (c) 2002-2025, by Derick Rethans

Update: I have also tried rolling back to older docker images with PHP 8.2.13 but nothing seems to help - but at the same time I know for a fact that it worked before, and the code around it did not change in the meantime. Maybe some core OS libraries have been updated and now EAGAIN is produced during SUBSCRIBE where it was not the case before? I have tested with Debian Bullseye and Bookworm and issue seems to be happening on both.

Answered by michael-grunder

Feb 19, 2025

Hi 👋,

This is just a read timeout. You can fix the specific use case by doing something like this:

<?php

use Relay\Cluster;
use Relay\Relay;

$cluster = $argc > 1 ? $argv[1] : "tcp://valkey-cluster-untracked:6372";


$relayCluster = new Cluster(
    "unprefixed-untracked",
    [$cluster],
    5,
    5,
    false,
    null,
    [],
);

// No timeout
$relayCluster->setOption(Relay::OPT_READ_TIMEOUT, 0);

$relayCluster->subscribe(['abc'], function (): void {
    echo 'subscribed';
});

View full answer

dorrogeray · 2025-02-19T13:46:15Z

dorrogeray
Feb 19, 2025
Author

I have been able to retrieve strace for the script, here is the relevant part:

379 sendto(7, "*2\r\n$9\r\nSUBSCRIBE\r\n$3\r\nabc\r\n", 28, 0, NULL, 0) = 28
379 recvfrom(7, ">3\r\n$9\r\nsubscribe\r\n$3\r\nabc\r\n:1\r\n", 16384, 0, NULL, NULL) = 32
379 recvfrom(7, 0x7fff233e5cc0, 16384, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
379 close(7) = 0

Full trace: relay-cluster-subscribe-strace.txt

Here is some commentary fro o3-mini:

Here’s what’s happening step-by-step:

Sending the SUBSCRIBE command:

379 sendto(7, "*2\r\n$9\r\nSUBSCRIBE\r\n$3\r\nabc\r\n", 28, 0, NULL, 0) = 28
The SUBSCRIBE command is sent on file descriptor 7.

Receiving the first response:

379 recvfrom(7, ">3\r\n$9\r\nsubscribe\r\n$3\r\nabc\r\n:1\r\n", 16384, 0, NULL, NULL) = 32
This call receives 32 bytes, which appears to be the expected initial response.

Attempting to receive further data:

379 recvfrom(7, 0x7fff233e5cc0, 16384, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
At this point, the socket has no more data available immediately, so recvfrom returns -1 with an EAGAIN error. In non-blocking mode, this error is expected when no data is ready.

Socket closure:

379 close(7) = 0
The file descriptor is then closed.

What This Means
The EAGAIN indicates that your socket did not have data available to read at the moment of that second recvfrom call. This behavior is typical for a non‑blocking socket.

In a blocking socket:
The call would simply wait (block) until data becomes available.

In a non‑blocking socket:
The call immediately returns with EAGAIN if no data is present, which is what you're seeing.

Seems like if Relay is intentionally using non-blocking sockets, there needs to be special handling around the SUBSCRIBE family of commands. But it still does not answer my question why rolling back to previous versions of Relay had no impact. 🤔

0 replies

michael-grunder · 2025-02-19T17:30:17Z

michael-grunder
Feb 19, 2025
Maintainer

Hi 👋,

This is just a read timeout. You can fix the specific use case by doing something like this:

<?php

use Relay\Cluster;
use Relay\Relay;

$cluster = $argc > 1 ? $argv[1] : "tcp://valkey-cluster-untracked:6372";


$relayCluster = new Cluster(
    "unprefixed-untracked",
    [$cluster],
    5,
    5,
    false,
    null,
    [],
);

// No timeout
$relayCluster->setOption(Relay::OPT_READ_TIMEOUT, 0);

$relayCluster->subscribe(['abc'], function (): void {
    echo 'subscribed';
});

0 replies

dorrogeray · 2025-02-19T20:38:59Z

dorrogeray
Feb 19, 2025
Author

@michael-grunder thanks for the answer, that helped! 👍 I have also noticed that trying to use the first argument passed into callback function leads to segfault:

<?php

use Relay\Cluster;
use Relay\Relay;

$relayCluster = new Cluster(
    "unprefixed-untracked",
    ["tcp://valkey-cluster-untracked:6372"],
    3,
    3,
    false,
    null,
);

// This is required otherwise subscribe will cause EAGAIN Resource temporarily unavailable error!
$relayCluster->setOption(Relay::OPT_READ_TIMEOUT, 0);

$relayCluster->subscribe(['123abc'], function (
    /** @param Relay $relay This parameter cannot be typed or used - leads to segfault **/
    $relay,
    string $channel,
    string $message,
): void {
    echo 'Channel: ' . $channel . PHP_EOL;
    echo 'MSG: ' . $message . PHP_EOL;
    // segfault
    echo get_class($relay) . PHP_EOL;

    // no segfault
    $x = func_get_arg(0);
    // segfault
    var_dump($x instanceof Relay);
});

This can be easily worked around by adding use ($relayCluster): void to add your Relay Cluster into the callback, just wanted to let you know about this issue.

1 reply

michael-grunder Feb 19, 2025
Maintainer

I can replicate the segfault. Will open an issue.

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

Relay\Cluster subscribe method throwing Relay\Exception: Resource temporarily unavailable #163

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{editor}}'s edit

{{editor}}'s edit

Uh oh!

Replies: 3 comments 1 reply

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{editor}}'s edit

{{editor}}'s edit

Uh oh!

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{title}}

Uh oh!

Select a reply

Uh oh!

Relay\Cluster subscribe method throwing Relay\Exception: Resource temporarily unavailable #163

Uh oh!

Uh oh!

dorrogeray Feb 19, 2025

Replies: 3 comments · 1 reply

Uh oh!

Uh oh!

dorrogeray Feb 19, 2025 Author

Here is some commentary fro o3-mini:

Sending the SUBSCRIBE command:

Receiving the first response:

Attempting to receive further data:

Socket closure:

Uh oh!

michael-grunder Feb 19, 2025 Maintainer

Uh oh!

dorrogeray Feb 19, 2025 Author

Uh oh!

michael-grunder Feb 19, 2025 Maintainer

dorrogeray
Feb 19, 2025

Replies: 3 comments 1 reply

dorrogeray
Feb 19, 2025
Author

michael-grunder
Feb 19, 2025
Maintainer

dorrogeray
Feb 19, 2025
Author

michael-grunder Feb 19, 2025
Maintainer