Merge pull request #304 from TheGrandWazoo/fix/303-ws-idle-reconnect

fix: reconnect WebSockets that TrueNAS closed while idle (#303)

CHANGELOG.md

@@ -8,6 +8,30 @@ See each [GitHub Release](https://github.com/TheGrandWazoo/truenas-proxmox/relea
 
 ---
 
+## [Unreleased] — 4.0.3
+
+### Fixed
+- **WebSocket calls failed after the connection sat idle in a PVE daemon**
+  (#303). TrueNAS closes an idle WebSocket after 30–60 s (measured on SCALE
+  25.04 and 25.10). Long-lived `pvedaemon` workers reused their cached
+  connection after that and died with `closed unexpectedly during call
+  'pool.dataset.query'`. That failed VM creates (once leaving a VM in
+  `lock: create`), returned HTTP 500 on content listings, and made `status()`
+  report SCALE storages as inactive at random. The CLI was unaffected
+  because each `qm`/`pvesm` is a fresh process.
+  - Before every reuse, a cached connection must have nothing pending on
+    the socket, and if it has been idle for more than 10 s it must answer
+    `core.ping` within 5 s. Otherwise the plugin reconnects. A ping takes
+    2–4 ms, compared with 1–4 s for a reconnect and login.
+  - Read-only calls (`*.query`, `*.config`) that still hit a closed socket
+    reconnect and retry once. Writes are never retried.
+
+### Verified
+- Read-only idle probe on pve01: 4.0.2 fails after 60 s and 90 s of idle
+  time on SCALE 25.04 and 25.10. A long-lived process with the fix ran
+  `status` plus `list_images` every 45 s for 5 minutes against both hosts,
+  14/14 OK.
+
 ## [4.0.2] — 2026-10-13
 
 Volume lifecycle fixes. Every change is backward compatible and `storage.cfg` is unchanged.

README.md

@@ -648,6 +648,27 @@ ls /etc/pve/nodes/*/qemu-server/<id>.conf 2>/dev/null  # no output → VM no lon
 
 To free an orphan, use `pvesm free <storage>:<vol>`. On 4.0.1 and earlier, use the `vdisk_free` one-liner from the entry above. Freeing a VM's last disk also removes its now-empty per-VM target.
 
+### "WebSocket connection ... closed unexpectedly", or a SCALE storage flapping to inactive (4.0.0–4.0.2)
+
+**Symptom:** on TrueNAS SCALE 25.04+, requests through the Proxmox API, GUI or Terraform fail at random. Retrying sometimes helps. The error looks like this:
+
+```
+TrueNAS WebSocket connection to <host> closed unexpectedly during call 'pool.dataset.query'
+```
+
+Other symptoms:
+- VM creation fails, sometimes leaving the VM in `lock: create`.
+- Content listings return HTTP 500.
+- The storage shows `active: 0` for some requests and `active: 1` for others.
+- `qm`/`pvesm` on the command line work fine.
+
+**Cause:** TrueNAS closes an idle WebSocket after 30–60 s. Each long-lived `pvedaemon` worker kept its cached connection and reused it after TrueNAS had closed it. **Fixed in v4.0.3** ([#303](https://github.com/TheGrandWazoo/freenas-proxmox/issues/303)). Now a cached connection is checked before every reuse and pinged if it has been idle, and read-only calls reconnect and retry once. TrueNAS CORE and SCALE < 25.04 (REST) were never affected.
+
+**On 4.0.0–4.0.2:**
+- Upgrade.
+- If you can't upgrade yet, `systemctl restart pvedaemon` clears the stale connections, but only until they go idle again.
+- A VM left in `lock: create` with no disks can be removed with `qm unlock <vmid> && qm destroy <vmid>`.
+
 ### Filing a Bug Report
 
 Please use the [GitHub issue tracker](https://github.com/TheGrandWazoo/truenas-proxmox/issues) and include the [bug report template](.github/ISSUE_TEMPLATE/bug_report.md). Include relevant log lines from `syslog` (search for `FreeNAS::`).

perl5/PVE/Storage/Custom/TrueNAS.pm

@@ -303,6 +303,49 @@ sub _api_rest {
 # - decode_json turns JSON true/false into a blessed JSON::PP::Boolean
 #   object, not a plain 1/0 — ref() on it is truthy. Never assume a non-hash
 #   JSON-RPC result is a plain scalar without checking ref() eq 'HASH' first.
+# - TrueNAS closes an idle WebSocket after 30-60s, and a pvedaemon worker keeps
+#   $state across API requests, so a cached connection can be dead by the time
+#   it is reused (#303). _ws_connect checks a cached connection before every
+#   reuse: nothing may be pending on the socket, and one idle for more than
+#   $ws_ping_after seconds must answer core.ping. A ping is 2-4 ms, while a
+#   reconnect and login takes 1-4 s, and the ping also resets TrueNAS's idle
+#   timer. It also catches half-open connections, where nothing ever becomes
+#   readable.
+my $ws_ping_after   = 10;
+my $ws_ping_timeout = 5;
+
+# Closes and forgets the cached connection for $host, if any.
+sub _ws_drop {
+    my ($host) = @_;
+    my $ws = delete $state->{$host}{ws} or return;
+    eval { $ws->{sock}->close(SSL_no_shutdown => 1) };
+    return;
+}
+
+# True if nothing is readable on a cached connection's socket. This is a
+# strict request/response protocol, so anything readable while idle can only
+# be EOF or a close frame.
+sub _ws_quiet {
+    my ($ws) = @_;
+    my $sock = $ws->{sock};
+    return 0 unless $sock && defined fileno($sock);
+    return 0 if $sock->pending;
+
+    my $rin = '';
+    vec($rin, fileno($sock), 1) = 1;
+    my $nfound = select(my $rout = $rin, undef, undef, 0);
+    return $nfound ? 0 : 1;
+}
+
+# True if the cached connection for $scfg's host can be reused (see above).
+sub _ws_reusable {
+    my ($scfg, $ws) = @_;
+    return 0 unless _ws_quiet($ws);
+    return 1 if time() - ($ws->{last_used} // 0) <= $ws_ping_after;
+
+    my $pong = eval { _ws_call($scfg, 'core.ping', [], $ws_ping_timeout) };
+    return ($pong && !$pong->{error}) ? 1 : 0;
+}
 
 # Blocks until $sock is readable (or dies on timeout), then reads whatever's
 # available and feeds it to the Protocol::WebSocket::Client state machine —
@@ -313,18 +356,26 @@ sub _ws_pump {
     my ($scfg, $sock, $client, $deadline, $what) = @_;
     my $host = $scfg->{truenas_host};
 
+    # After a timeout the stream state is unknown (a late reply may still
+    # arrive), so the connection is dropped rather than kept for reuse.
     my $remaining = $deadline - time();
-    die "TrueNAS WebSocket $what to $host timed out after 30s\n" if $remaining <= 0;
+    if ($remaining <= 0) {
+        _ws_drop($host);
+        die "TrueNAS WebSocket $what to $host timed out\n";
+    }
 
     my $rin = '';
     vec($rin, fileno($sock), 1) = 1;
     my $nfound = select(my $rout = $rin, undef, undef, $remaining);
-    die "TrueNAS WebSocket $what to $host timed out after 30s\n" unless $nfound;
+    unless ($nfound) {
+        _ws_drop($host);
+        die "TrueNAS WebSocket $what to $host timed out\n";
+    }
 
     my $buf;
     my $n = $sock->sysread($buf, 65536);
     unless (defined $n && $n > 0) {
-        delete $state->{$host}{ws};
+        _ws_drop($host);
         die "TrueNAS WebSocket connection to $host closed unexpectedly during $what\n";
     }
     $client->read($buf);
@@ -335,7 +386,10 @@ sub _ws_pump {
 sub _ws_connect {
     my ($scfg) = @_;
     my $host = $scfg->{truenas_host};
-    return $state->{$host}{ws} if $state->{$host}{ws};
+    if (my $cached = $state->{$host}{ws}) {
+        return $cached if _ws_reusable($scfg, $cached);
+        _ws_drop($host);
+    }
 
     my $token = $state->{$host}{api_token}
         or die "TrueNAS API token not resolved for '$host'\n";
@@ -356,7 +410,13 @@ sub _ws_connect {
     my $client = Protocol::WebSocket::Client->new(url => "wss://$host/api/current");
     $client->on(write => sub {
         my (undef, $buf) = @_;
-        print { $sock } $buf;
+        # A peer reset must surface as a closed connection (which read-only
+        # calls retry), not as SIGPIPE or a 30 s wait for a reply.
+        local $SIG{PIPE} = 'IGNORE';
+        unless (print { $sock } $buf) {
+            _ws_drop($host);
+            die "TrueNAS WebSocket connection to $host closed unexpectedly during write\n";
+        }
     });
     $client->on(connect => sub {
         $handshake_done = 1;
@@ -376,16 +436,23 @@ sub _ws_connect {
     _ws_pump($scfg, $sock, $client, $deadline, 'handshake') until $handshake_done;
 
     $state->{$host}{ws} = {
-        sock    => $sock,
-        client  => $client,
-        inbound => \@inbound,
-        next_id => 1,
+        sock      => $sock,
+        client    => $client,
+        inbound   => \@inbound,
+        next_id   => 1,
+        last_used => time(),
     };
 
-    my $auth = _ws_call($scfg, 'auth.login_with_api_key', [$token]);
+    # Never leave an unauthenticated connection cached: it would pass the
+    # reuse check and every later call on it would fail.
+    my $auth = eval { _ws_call($scfg, 'auth.login_with_api_key', [$token]) };
+    if (my $err = $@) {
+        _ws_drop($host);
+        die $err;
+    }
     unless (!$auth->{error} && $auth->{result}) {
         my $reason = $auth->{error}{message} // 'authentication rejected';
-        delete $state->{$host}{ws};
+        _ws_drop($host);
         die "TrueNAS WebSocket auth failed for $host: $reason\n";
     }
 
@@ -396,7 +463,7 @@ sub _ws_connect {
 # Returns the decoded {result=>...} or {error=>...} response envelope —
 # callers (normally just _api_ws) are responsible for checking ->{error}.
 sub _ws_call {
-    my ($scfg, $method, $params) = @_;
+    my ($scfg, $method, $params, $timeout) = @_;
     my $host = $scfg->{truenas_host};
     my $ws   = $state->{$host}{ws}
         or die "TrueNAS WebSocket connection not established for '$host'\n";
@@ -405,7 +472,7 @@ sub _ws_call {
     my $req = { jsonrpc => '2.0', id => $id, method => $method, params => $params // [] };
     $ws->{client}->write(encode_json($req));    # frames + masks + fires 'write'
 
-    my $deadline = time() + 30;
+    my $deadline = time() + ($timeout // 30);
     my $result;
     until (defined $result) {
         while (my $msg = shift @{ $ws->{inbound} }) {
@@ -421,6 +488,7 @@ sub _ws_call {
         _ws_pump($scfg, $ws->{sock}, $ws->{client}, $deadline, "call '$method'")
             unless defined $result;
     }
+    $ws->{last_used} = time();
     return $result;
 }
 
@@ -568,7 +636,16 @@ sub _api_ws {
     die "TrueNAS WebSocket transport: no JSON-RPC mapping for $method $path\n"
         unless $rpc_method;
 
-    my $resp = _ws_call($scfg, $rpc_method, $params);
+    # A connection can still die between _ws_connect's check and the call
+    # (#303). Read-only calls are safe to repeat, so reconnect and retry those
+    # once. Writes are never retried: TrueNAS may already have applied them.
+    my $resp = eval { _ws_call($scfg, $rpc_method, $params) };
+    if (my $err = $@) {
+        die $err unless $err =~ /closed unexpectedly/ && $rpc_method =~ /\.(?:query|config)$/;
+        _log('warning', "$scfg->{truenas_host}: WebSocket closed during '$rpc_method' — reconnecting and retrying once");
+        _ws_connect($scfg);
+        $resp = _ws_call($scfg, $rpc_method, $params);
+    }
 
     if ($resp->{error}) {
         my $reason = (ref($resp->{error}{data}) eq 'HASH' && $resp->{error}{data}{reason})

t/ws_reconnect.t

@@ -0,0 +1,145 @@
+#!/usr/bin/perl
+# WebSocket reconnect (#303): TrueNAS closes an idle WebSocket after 30-60s, and
+# a pvedaemon worker keeps the cached connection across requests. A cached
+# connection is reused only if nothing is pending on it and, once idle for more
+# than 10s, it answers core.ping. A read-only call that still hits a closed
+# socket is retried once (writes never).
+
+use strict;
+use warnings;
+
+use FindBin;
+use lib "$FindBin::Bin/lib", "$FindBin::Bin/../perl5";
+
+use Test::More;
+use Socket qw(AF_UNIX SOCK_STREAM PF_UNSPEC);
+use IO::Handle;
+
+use MockTrueNAS;
+use PVE::Storage::Custom::TrueNAS;
+
+my $TN = 'PVE::Storage::Custom::TrueNAS';
+
+# Stand-in for an IO::Socket::SSL handle: a real fd (so select() works) plus
+# the ->pending method IO::Socket::SSL adds for TLS-buffered bytes.
+package FakeSSL {
+    our @ISA = ('IO::Handle');
+    sub pending { return 0 }
+}
+
+sub sockpair {
+    socketpair(my $mine, my $peer, AF_UNIX, SOCK_STREAM, PF_UNSPEC) or die "socketpair: $!";
+    $peer->autoflush(1);
+    return (bless($mine, 'FakeSSL'), $peer);
+}
+
+subtest '_ws_quiet' => sub {
+    my $quiet = $TN->can('_ws_quiet');
+    my ($sock, $peer) = sockpair();
+    ok($quiet->({ sock => $sock }), 'nothing pending -> quiet');
+
+    print {$peer} "x";
+    ok(!$quiet->({ sock => $sock }), 'unsolicited data while idle (close frame) -> not quiet');
+
+    my ($sock2, $peer2) = sockpair();
+    close $peer2;
+    ok(!$quiet->({ sock => $sock2 }), 'peer closed (EOF readable) -> not quiet');
+
+    ok(!$quiet->({}), 'missing socket -> not quiet');
+};
+
+subtest '_ws_reusable pings only idle connections' => sub {
+    my $reusable = $TN->can('_ws_reusable');
+    my ($pings, $pong) = (0, sub { return { result => 'pong' } });
+    no warnings 'redefine';    ## no critic (TestingAndDebugging::ProhibitNoWarnings)
+    local *PVE::Storage::Custom::TrueNAS::_ws_call = sub {
+        my (undef, $method, undef, $timeout) = @_;
+        $pings++ if $method eq 'core.ping';
+        is($timeout, 5, 'ping uses the short timeout') if $method eq 'core.ping';
+        return $pong->();
+    };
+
+    my ($sock, $peer) = sockpair();
+    my $scfg = MockTrueNAS::scfg();
+
+    ok($reusable->($scfg, { sock => $sock, last_used => time() }), 'recently used -> reused');
+    is($pings, 0, '... without a ping');
+
+    ok($reusable->($scfg, { sock => $sock, last_used => time() - 11 }), 'idle >10s, pong -> reused');
+    is($pings, 1, '... after one core.ping');
+
+    $pong = sub { return { error => { message => 'nope' } } };
+    ok(!$reusable->($scfg, { sock => $sock, last_used => time() - 11 }), 'ping error -> not reused');
+
+    $pong = sub { die "TrueNAS WebSocket call 'core.ping' to truenas.test timed out\n" };
+    ok(!$reusable->($scfg, { sock => $sock, last_used => time() - 11 }),
+       'ping timeout (half-open connection) -> not reused');
+
+    print {$peer} "x";
+    $pings = 0;
+    ok(!$reusable->($scfg, { sock => $sock, last_used => time() - 11 }), 'not quiet -> not reused');
+    is($pings, 0, '... and not pinged');
+};
+
+# Stub transport under _api_ws: _ws_connect counts reconnects, _ws_call fails
+# the first $fail_times calls with $err and then succeeds.
+sub stub_transport {
+    my (%o) = @_;
+    my $s = { connects => 0, calls => [] };
+    $s->{connect} = sub { $s->{connects}++; return {}; };
+    $s->{call}    = sub {
+        my (undef, $method) = @_;
+        push @{ $s->{calls} }, $method;
+        die $o{err} if @{ $s->{calls} } <= ($o{fail_times} // 0);
+        return { result => $o{result} // {} };
+    };
+    return $s;
+}
+
+# Calls _api_ws with $s's stubs installed via `local`, so they can't leak
+# into other subtests.
+sub api_ws {
+    my ($s, @args) = @_;
+    no warnings 'redefine';    ## no critic (TestingAndDebugging::ProhibitNoWarnings)
+    local *PVE::Storage::Custom::TrueNAS::_ws_connect = $s->{connect};
+    local *PVE::Storage::Custom::TrueNAS::_ws_call    = $s->{call};
+    return $TN->can('_api_ws')->(MockTrueNAS::scfg(), @args);
+}
+
+my $closed = "TrueNAS WebSocket connection to truenas.test closed unexpectedly during call 'x'\n";
+
+subtest 'read-only call is retried once after the socket closes' => sub {
+    MockTrueNAS->install();
+    my $s = stub_transport(err => $closed, fail_times => 1, result => { basename => 'iqn.test' });
+    my $r = api_ws($s, 'GET', '/iscsi/global');
+    is($r->{basename}, 'iqn.test', 'second attempt result returned');
+    is_deeply($s->{calls}, ['iscsi.global.config', 'iscsi.global.config'], 'called twice');
+    is($s->{connects}, 2, 'reconnected before the retry');
+};
+
+subtest 'query is retried, but only once' => sub {
+    MockTrueNAS->install();
+    my $s = stub_transport(err => $closed, fail_times => 2);
+    eval { api_ws($s, 'GET', '/iscsi/extent') };
+    like($@, qr/closed unexpectedly/, 'second failure propagates');
+    is(scalar @{ $s->{calls} }, 2, 'no third attempt');
+};
+
+subtest 'writes are never retried' => sub {
+    MockTrueNAS->install();
+    my $s = stub_transport(err => $closed, fail_times => 1);
+    eval { api_ws($s, 'DELETE', '/iscsi/target/id/7') };
+    like($@, qr/closed unexpectedly/, 'error propagates');
+    is_deeply($s->{calls}, ['iscsi.target.delete'], 'called exactly once');
+};
+
+subtest 'other errors on reads are not retried' => sub {
+    MockTrueNAS->install();
+    my $s = stub_transport(err => "TrueNAS WebSocket call 'x' to truenas.test timed out after 30s\n",
+                           fail_times => 1);
+    eval { api_ws($s, 'GET', '/iscsi/global') };
+    like($@, qr/timed out/, 'timeout propagates');
+    is(scalar @{ $s->{calls} }, 1, 'called exactly once');
+};
+
+done_testing();