diff --git a/CHANGELOG.md b/CHANGELOG.md index 1fb99ed..ff880dc 100644 --- a/CHANGELOG.md +++ b/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. diff --git a/README.md b/README.md index 2d278ca..7f5cb13 100644 --- a/README.md +++ b/README.md @@ -648,6 +648,27 @@ ls /etc/pve/nodes/*/qemu-server/.conf 2>/dev/null # no output → VM no lon To free an orphan, use `pvesm free :`. 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 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 && qm destroy `. + ### 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::`). diff --git a/perl5/PVE/Storage/Custom/TrueNAS.pm b/perl5/PVE/Storage/Custom/TrueNAS.pm index 0273aef..958027c 100644 --- a/perl5/PVE/Storage/Custom/TrueNAS.pm +++ b/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}) diff --git a/t/ws_reconnect.t b/t/ws_reconnect.t new file mode 100644 index 0000000..8d6f85c --- /dev/null +++ b/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();