[bug] Internal error executing set_vfo

[AI7BQ]

Description

Beginning with v2.11.1, Rigplane is unable to maintain connection to IC-9700 via LAN. This issue does not exist with v2.11.0 or earlier. Fails with ERROR Internal error executing set_vfo. See debug log below.

Steps to Reproduce

STEP #1. Install Rigplane v2.11.1
STEP #2. Launch Rigplane with systemd unit file
STEP #3. Rigplane exits with ERROR Internal error executing set_vfo
STEP #4. Downgrade to Rigplane v2.11.0 -- WORKS NORMALLY

[Unit]
Description=Rigplane Daemon (User Context)
After=network.target rigplane-audio.service
Requires=rigplane-audio.service

[Service]
Type=simple
User=username
Group=groupname
WorkingDirectory=/srv/rigplane
Environment=XDG_RUNTIME_DIR=/run/user/1000
Environment=PULSE_SERVER=unix:/run/user/1000/pulse/native
Environment=PULSE_SINK=RigAudioRx
Environment=PULSE_SOURCE=RigAudioTx.monitor
ExecStartPre=/bin/sh -c '/usr/bin/pactl list short sinks | /bin/grep -q "RigAudioRx" || /usr/bin/pactl load-module module-null-sink sink_name=RigAudioRx sink_properties=device.description="Rigplane_RX_Bridge" >/dev/null'
ExecStartPre=/bin/sh -c '/usr/bin/pactl list short sinks | /bin/grep -q "RigAudioTx" || /usr/bin/pactl load-module module-null-sink sink_name=RigAudioTx sink_properties=device.description="Rigplane_TX_Bridge" >/dev/null'
ExecStart=/srv/rigplane/.venv/bin/rigplane --backend lan --model IC-9700 web --host 0.0.0.0 --port 9999 --radio-host 192.168.1.19 --radio-user AI7BQ --radio-pass-file /srv/rigplane/passfile.conf --bridge pulse --bridge-tx-device pulse --rigctld --rigctld-port 4532 --wsjtx-compat
Restart=on-failure
RestartSec=30

[Install]
WantedBy=multi-user.target

Radio Model

IC-9700

rigplane Version

v2.11.1

Python Version

3.11.2

OS

Debian GNU/Linux 12 (bookworm)

Debug Log

Jun 22 14:33:40 pat systemd[1]: Starting rigplane.service - Rigplane Daemon (User Context)...
Jun 22 14:33:40 pat systemd[1]: Started rigplane.service - Rigplane Daemon (User Context).
Jun 22 14:33:41 pat rigplane[107665]: Logging to /home/jsimpson/.cache/rigplane/logs/rigplane.log (rotate at 50000000 bytes, keep 5 backups)
Jun 22 14:33:41 pat rigplane[107665]: 14:33:41 INFO UDP open to 192.168.1.19:50001, my_id=0x0001D7B1
Jun 22 14:33:41 pat rigplane[107665]: 14:33:41 INFO I Am Here received, remote_id=0x0A5E5901
Jun 22 14:33:41 pat rigplane[107665]: 14:33:41 INFO I Am Ready received
Jun 22 14:33:41 pat rigplane[107665]: 14:33:41 INFO Discovery complete, remote_id=0x0A5E5901
Jun 22 14:33:41 pat rigplane[107665]: 14:33:41 INFO Authenticated with 192.168.1.19:50001, token=0x1A833862
Jun 22 14:33:42 pat rigplane[107665]: 14:33:42 INFO Status: civ_port=50002, audio_port=50003, error=0x00000000, disconnected=False
Jun 22 14:33:42 pat rigplane[107665]: 14:33:42 INFO UDP open to 192.168.1.19:50002, my_id=0x00018184
Jun 22 14:33:42 pat rigplane[107665]: 14:33:42 INFO I Am Here received, remote_id=0x9B1BD286
Jun 22 14:33:42 pat rigplane[107665]: 14:33:42 INFO I Am Ready received
Jun 22 14:33:42 pat rigplane[107665]: 14:33:42 INFO Discovery complete, remote_id=0x9B1BD286
Jun 22 14:33:42 pat rigplane[107665]: 14:33:42 INFO civ-data-watchdog: started
Jun 22 14:33:43 pat rigplane[107665]: 14:33:43 INFO Connected to 192.168.1.19 (control=50001, civ=50002)
Jun 22 14:33:43 pat rigplane[107665]: 14:33:43 INFO initial state fetch (63 queries, gap=12ms)...
Jun 22 14:33:45 pat rigplane[107665]: 14:33:45 INFO initial state fetch done (63/63 ok)
Jun 22 14:33:45 pat rigplane[107665]: 14:33:45 INFO AudioFftScope: fft_size=2048 fps=20 window=hann avg=2 sr=48000
Jun 22 14:33:45 pat rigplane[107665]: 14:33:45 INFO Audio FFT scope available (has_audio=True, has_hw_scope=True)
Jun 22 14:33:45 pat rigplane[107665]: 14:33:45 INFO rigplane (IC-9700): state idle → connecting (reason=start, attempt=0)
Jun 22 14:33:45 pat rigplane[107665]: 14:33:45 INFO rigplane (IC-9700): using device 'pulse' (id 6)
Jun 22 14:33:45 pat rigplane[107665]: 14:33:45 INFO rigplane (IC-9700): bridge codec=PCM_1CH_16BIT input_channels=1 output_channels=1 sample_rate=48000 duplex_mode=full
Jun 22 14:33:45 pat rigplane[107665]: 14:33:45 INFO audio-bus: +subscriber 'audio-bridge' (1 total)
Jun 22 14:33:45 pat rigplane[107665]: 14:33:45 INFO UDP open to 192.168.1.19:50003, my_id=0x0001AEB7
Jun 22 14:33:45 pat rigplane[107665]: 14:33:45 INFO I Am Here received, remote_id=0x9AAE69D1
Jun 22 14:33:45 pat rigplane[107665]: 14:33:45 INFO I Am Ready received
Jun 22 14:33:45 pat rigplane[107665]: 14:33:45 INFO Discovery complete, remote_id=0x9AAE69D1
Jun 22 14:33:45 pat rigplane[107665]: 14:33:45 INFO Audio transport connected on port 50003
Jun 22 14:33:45 pat rigplane[107665]: 14:33:45 INFO Audio RX started (jitter_depth=5)
Jun 22 14:33:45 pat rigplane[107665]: 14:33:45 INFO audio-bus: RX started
Jun 22 14:33:45 pat rigplane[107665]: 14:33:45 INFO Audio TX started
Jun 22 14:33:45 pat rigplane[107665]: 14:33:45 INFO rigplane (IC-9700): same-device RX+TX (id 6) — opening single full-duplex stream (MOR-531)
Jun 22 14:33:46 pat rigplane[107665]: 14:33:46 INFO rigplane (IC-9700): state connecting → running (reason=started, attempt=0)
Jun 22 14:33:46 pat rigplane[107665]: 14:33:46 INFO rigplane (IC-9700): started (RX+TX, 48000Hz, 1ch, 20ms frames)
Jun 22 14:33:46 pat rigplane[107665]: 14:33:46 INFO rigctld listening on 0.0.0.0:4532
Jun 22 14:33:46 pat rigplane[107665]: 14:33:46 INFO band-plan: no band-plans/ directory found
Jun 22 14:33:46 pat rigplane[107665]: 14:33:46 INFO web server listening on http://0.0.0.0:9999
Jun 22 14:33:46 pat rigplane[107665]: 14:33:46 INFO radio-poller: started
Jun 22 14:33:46 pat rigplane[107665]: 14:33:46 INFO discovery responder listening on 0.0.0.0:8470 (UDP)
Jun 22 14:33:46 pat rigplane[107665]: 14:33:46 INFO radio-poller: NB controls fetched
Jun 22 14:33:46 pat rigplane[107665]: 14:33:46 INFO ws connect: /api/v1/scope 192.168.1.55:33936 (active=1)
Jun 22 14:33:46 pat rigplane[107665]: 14:33:46 INFO scope: enable queued
Jun 22 14:33:46 pat rigplane[107665]: 14:33:46 INFO radio-poller: scope enabled
Jun 22 14:33:47 pat rigplane[107665]: 14:33:47 INFO client #1 connected from 127.0.0.1:45422
Jun 22 14:33:47 pat rigplane[107665]: 14:33:47 INFO AuditRecord(timestamp='2026-06-22T21:33:47.129520+00:00', client_id=1, peername='127.0.0.1:45422', cmd='\\chk_vfo', long_cmd='chk_vfo', args=(), duration_ms=0.389, rprt=0, is_set=False, vfo=None)
Jun 22 14:33:47 pat rigplane[107665]: 14:33:47 INFO AuditRecord(timestamp='2026-06-22T21:33:47.131459+00:00', client_id=1, peername='127.0.0.1:45422', cmd='\\dump_state', long_cmd='dump_state', args=(), duration_ms=0.147, rprt=0, is_set=False, vfo=None)
Jun 22 14:33:47 pat rigplane[107665]: 14:33:47 INFO AuditRecord(timestamp='2026-06-22T21:33:47.132819+00:00', client_id=1, peername='127.0.0.1:45422', cmd='v', long_cmd='get_vfo', args=(), duration_ms=0.414, rprt=0, is_set=False, vfo=None)
Jun 22 14:33:47 pat rigplane[107665]: 14:33:47 INFO AuditRecord(timestamp='2026-06-22T21:33:47.133972+00:00', client_id=1, peername='127.0.0.1:45422', cmd='f', long_cmd='get_freq', args=(), duration_ms=0.504, rprt=0, is_set=False, vfo='VFOA')
Jun 22 14:33:47 pat rigplane[107665]: 14:33:47 ERROR Internal error executing set_vfo
Jun 22 14:33:47 pat rigplane[107665]: Traceback (most recent call last):
Jun 22 14:33:47 pat rigplane[107665]:   File "/srv/rigplane/.venv/lib/python3.11/site-packages/rigplane/rigctld/handler.py", line 973, in execute
Jun 22 14:33:47 pat rigplane[107665]:     response = cast(RigctldResponse, await handler_fn(self, cmd))
Jun 22 14:33:47 pat rigplane[107665]:                                      ^^^^^^^^^^^^^^^^^^^^^^^^^^^
Jun 22 14:33:47 pat rigplane[107665]:   File "/srv/rigplane/.venv/lib/python3.11/site-packages/rigplane/rigctld/handler.py", line 1539, in _cmd_set_vfo
Jun 22 14:33:47 pat rigplane[107665]:     await self._command_service.execute(
Jun 22 14:33:47 pat rigplane[107665]:   File "/srv/rigplane/.venv/lib/python3.11/site-packages/rigplane/core/command_service.py", line 147, in execute
Jun 22 14:33:47 pat rigplane[107665]:     executor_result = await self._executor.execute(intent)
Jun 22 14:33:47 pat rigplane[107665]:                       ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
Jun 22 14:33:47 pat rigplane[107665]:   File "/srv/rigplane/.venv/lib/python3.11/site-packages/rigplane/rigctld/handler.py", line 362, in execute
Jun 22 14:33:47 pat rigplane[107665]:     error = await self.handler._execute_set_vfo(str(params["vfo"]))
Jun 22 14:33:47 pat rigplane[107665]:             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
Jun 22 14:33:47 pat rigplane[107665]:   File "/srv/rigplane/.venv/lib/python3.11/site-packages/rigplane/rigctld/handler.py", line 1567, in _execute_set_vfo
Jun 22 14:33:47 pat rigplane[107665]:     await select_receiver(target)
Jun 22 14:33:47 pat rigplane[107665]:   File "/srv/rigplane/.venv/lib/python3.11/site-packages/rigplane/runtime/_dual_rx_runtime.py", line 447, in select_receiver
Jun 22 14:33:47 pat rigplane[107665]:     await self._set_vfo_wire(target)
Jun 22 14:33:47 pat rigplane[107665]:   File "/srv/rigplane/.venv/lib/python3.11/site-packages/rigplane/runtime/radio.py", line 3134, in _set_vfo_wire
Jun 22 14:33:47 pat rigplane[107665]:     raise CommandError(f"Radio rejected VFO select {vfo}")
Jun 22 14:33:47 pat rigplane[107665]: rigplane.core.exceptions.CommandError: Radio rejected VFO select SUB
Jun 22 14:33:47 pat rigplane[107665]: 14:33:47 INFO AuditRecord(timestamp='2026-06-22T21:33:47.218322+00:00', client_id=1, peername='127.0.0.1:45422', cmd='V', long_cmd='set_vfo', args=('VFOB',), duration_ms=83.849, rprt=<HamlibError.EINTERNAL: -7>, is_set=True, vfo=None)
Jun 22 14:33:47 pat rigplane[107665]: 14:33:47 INFO AuditRecord(timestamp='2026-06-22T21:33:47.220124+00:00', client_id=1, peername='127.0.0.1:45422', cmd='s', long_cmd='get_split_vfo', args=(), duration_ms=0.607, rprt=0, is_set=False, vfo='VFOA')
Jun 22 14:33:47 pat rigplane[107665]: 14:33:47 INFO AuditRecord(timestamp='2026-06-22T21:33:47.335803+00:00', client_id=1, peername='127.0.0.1:45422', cmd='V', long_cmd='set_vfo', args=('VFOA',), duration_ms=114.913, rprt=<HamlibError.OK: 0>, is_set=True, vfo=None)
Jun 22 14:33:47 pat rigplane[107665]: 14:33:47 INFO AuditRecord(timestamp='2026-06-22T21:33:47.337332+00:00', client_id=1, peername='127.0.0.1:45422', cmd='m', long_cmd='get_mode', args=(), duration_ms=0.812, rprt=0, is_set=False, vfo='VFOA')
Jun 22 14:33:47 pat rigplane[107665]: 14:33:47 ERROR Internal error executing set_vfo
Jun 22 14:33:47 pat rigplane[107665]: Traceback (most recent call last):
Jun 22 14:33:47 pat rigplane[107665]:   File "/srv/rigplane/.venv/lib/python3.11/site-packages/rigplane/rigctld/handler.py", line 973, in execute
Jun 22 14:33:47 pat rigplane[107665]:     response = cast(RigctldResponse, await handler_fn(self, cmd))
Jun 22 14:33:47 pat rigplane[107665]:                                      ^^^^^^^^^^^^^^^^^^^^^^^^^^^
Jun 22 14:33:47 pat rigplane[107665]:   File "/srv/rigplane/.venv/lib/python3.11/site-packages/rigplane/rigctld/handler.py", line 1539, in _cmd_set_vfo
Jun 22 14:33:47 pat rigplane[107665]:     await self._command_service.execute(
Jun 22 14:33:47 pat rigplane[107665]:   File "/srv/rigplane/.venv/lib/python3.11/site-packages/rigplane/core/command_service.py", line 147, in execute
Jun 22 14:33:47 pat rigplane[107665]:     executor_result = await self._executor.execute(intent)
Jun 22 14:33:47 pat rigplane[107665]:                       ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
Jun 22 14:33:47 pat rigplane[107665]:   File "/srv/rigplane/.venv/lib/python3.11/site-packages/rigplane/rigctld/handler.py", line 362, in execute
Jun 22 14:33:47 pat rigplane[107665]:     error = await self.handler._execute_set_vfo(str(params["vfo"]))
Jun 22 14:33:47 pat rigplane[107665]:             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
Jun 22 14:33:47 pat rigplane[107665]:   File "/srv/rigplane/.venv/lib/python3.11/site-packages/rigplane/rigctld/handler.py", line 1567, in _execute_set_vfo
Jun 22 14:33:47 pat rigplane[107665]:     await select_receiver(target)
Jun 22 14:33:47 pat rigplane[107665]:   File "/srv/rigplane/.venv/lib/python3.11/site-packages/rigplane/runtime/_dual_rx_runtime.py", line 447, in select_receiver
Jun 22 14:33:47 pat rigplane[107665]:     await self._set_vfo_wire(target)
Jun 22 14:33:47 pat rigplane[107665]:   File "/srv/rigplane/.venv/lib/python3.11/site-packages/rigplane/runtime/radio.py", line 3134, in _set_vfo_wire
Jun 22 14:33:47 pat rigplane[107665]:     raise CommandError(f"Radio rejected VFO select {vfo}")
Jun 22 14:33:47 pat rigplane[107665]: rigplane.core.exceptions.CommandError: Radio rejected VFO select SUB
Jun 22 14:33:47 pat rigplane[107665]: 14:33:47 INFO AuditRecord(timestamp='2026-06-22T21:33:47.421407+00:00', client_id=1, peername='127.0.0.1:45422', cmd='V', long_cmd='set_vfo', args=('VFOB',), duration_ms=80.738, rprt=<HamlibError.EINTERNAL: -7>, is_set=True, vfo=None)
Jun 22 14:33:48 pat rigplane[107665]: 14:33:48 INFO radio-poller: scope controls fetched (receiver=0)

Analysis (filled during fix)

No response

[morozsm]

Thanks for the excellent report — the systemd unit, the exact version delta (v2.11.0 OK / v2.11.1 broken), and the full debug log with the traceback made this immediately actionable. Reports like this let us move fast, so genuinely: thank you.

Confirmed: this is a regression introduced in v2.11.1. WSJT-X's startup set_vfo VFOB — which on a dual-receiver Icom like the IC-9700 maps to selecting the SUB receiver — is being rejected by the radio and surfaces as Internal error executing set_vfo (RIG_EINTERNAL). v2.11.0 is unaffected, exactly as you found.

The VFO-select code itself is unchanged between v2.11.0 and v2.11.1, so this is an interaction / startup-ordering side-effect of another change in the 2.11.1 line — we're pinning down the precise cause right now and will fix it properly (with a regression test that exercises this exact set_vfo VFOB → SUB path on a dual-RX radio), not paper over the symptom.

A fix is in progress and will ship in v2.11.2; I'll update this issue the moment it's released.

Workaround until then: staying on v2.11.0 restores normal CAT control, as you've already confirmed.

Thanks again for catching this and for the thorough writeup. 73!

[morozsm]

Thanks for your patience — here's an honest update on where the investigation stands, plus a few experiments that would help us pin this down.

We dug carefully through the v2.11.0 → v2.11.1 delta. The VFO/receiver-select path, and the entire rigctld + CI-V command path, are byte-for-byte identical between the two releases. The only source changes in that window touch the audio-session reconciler and the web state broadcaster — neither of which alters the CI-V commands sent to the radio. We also replayed your exact rigctld startup sequence (chk_vfo → dump_state → v → f → V VFOB) against a dual-receiver Icom on a LAN connection here, on both v2.11.0 and v2.11.1 — and in our setup V VFOB (SUB select) is accepted on both versions. So we can't reproduce the NAK locally yet, which points at something specific to your radio, its state, or timing that we'll need your help to isolate.

Three things would be a big help:

1. The working v2.11.0 startup log, captured the same way as the failing one (same systemd unit). A side-by-side of the working-vs-failing startup sequence on your exact radio is the most direct way to see what actually differs. If it's easy, add --log-level DEBUG to that v2.11.0 run — it will include the IC-9700 CI-V exchange around the VFO commands. (Heads-up: v2.11.1 deliberately quiets that particular logger to cut disk churn, so DEBUG is most informative on v2.11.0.)

2. A v2.11.1 run with the audio bridge disabled — drop the --bridge pulse --bridge-tx-device pulse flags, keep --rigctld --wsjtx-compat. Does set_vfo VFOB still get rejected? This cleanly isolates whether the audio TX path is involved at all.

3. Radio configuration: between your v2.11.0 and v2.11.1 tests, was the IC-9700 in the same state — same band/mode, and the SUB receiver / dualwatch in the same on/off configuration? On the IC-9700, selecting SUB can be rejected by the radio itself depending on its current dual-watch / band setup, so we'd like to rule that out.

Thanks again — this kind of back-and-forth is exactly what lets us fix the real cause rather than paper over the symptom. 73.

[AI7BQ]

I am closing this issue for the time being, as Rigplane v2.11.1 is mostly stable with the IC-9700 and the intermittent set_vfo failures cannot be reproduced on demand. Because I remotely control the power to my radio, it is rarely in the exact same state upon startup. I need more time to isolate the exact variables and design a repeatable experiment that consistently demonstrates the failure mode, at which point I will provide the logs and reopen this issue or submit a new one.

[AI7BQ]

How do I include the switch --log-level DEBUG when launching rigplane? This is what I currently use:

/srv/rigplane/.venv/bin/rigplane --backend lan --model IC-9700 web --host 0.0.0.0 --port 9999 --radio-host 192.168.1.19 --radio-user AI7BQ --radio-pass-file /srv/rigplane/passfile.conf --rigctld --rigctld-port 4532 --wsjtx-compat