VARA (either) fails to terminate after a RadioMail connection

[krvw]

The latest build of Varanny now launches my VARA modems successfully, but the modem process remains running after the connection is terminated.

Happy to provide whatever logging you'd like.

Configuration:

• Raspberry Pi 5 (8 Gb with NVMe SSD)
• Raspberry Pi OS (current)
• Icom IC-7100
• Both VARA modems are up to date
• WINE + Box86 + Box 64
• RadioMail (current) on iPhone 13

[krvw]

More SW version numbers here:

Box86 with Dynarec v0.2.7 14113faa built on Oct 10 2022 20:20:17
wine-7.1
Dynarec for ARM64, with extension: ASIMD AES CRC32 PMULL ATOMICS SHA1 SHA2 PageSize:4096 Running on Cortex-A76 with 4 Cores
Params database has 59 entries
Box64 with Dynarec v0.2.7 f02d5fc2 built on Feb 24 2024 06:15:58

[georges]

In the logs, you should see something like that, were the modem process is being shutdown

2024/02/24 13:09:16 Client closed the connection
2024/02/24 13:09:16 Received command: stop
2024/02/24 13:09:16 Cleaning up after closing connection
2024/02/24 13:09:16 Shutdown modem process gracefully
2024/02/24 13:09:16 Shutdown modem process gracefully failed, killing
2024/02/24 13:09:16 Restoring original config file C:\VARA FM\VARAFM.ini

Try to see if you can get to do this interactively without RadioMail first. With varanny running, try to telnet to the host where varanny runs, using port 8273.

Then start and stop one of the modem you defined in the varanny.json config.

For example:

$ telnet t4windoz.local 8273
Trying fe80::7e82:6fbe:2499:e439...
Connected to t4windoz.local.
Escape character is '^]'.
start IC705FM
OK
stop
OK
Connection closed by foreign host.

You should see VARA being launched and killed.

[krvw]

I did exactly that - in the telnet dialog, with no RadioMail involvement. Here's what I saw:

2024/02/24 19:01:17 Received command: stop
2024/02/24 19:01:17 Cleaning up after closing connection
2024/02/24 19:01:17 Shutdown modem process gracefully
2024/02/24 19:01:17 Restoring original config file /home/krvw/.wine/drive_c/VARA/VARA.ini
2024/02/24 19:01:17 Shutdown cat control process gracefully

Terminating application, caught signal 15
2024/02/24 19:01:18 Warning: awaiting termination of cat control process failed
2024/02/24 19:01:18 read tcp [::1]:8273->[::1]:57568: use of closed network connection
ALSA lib pcm.c:8570:(snd_pcm_recover) overrun occurred

Note, the VARA HF process is still running. Identical behavior for VARA FM.

Also, you asked how long VARA takes to launch. Roughly timed, it's about 7-8 seconds on my Pi5.

[georges]

Can you please post your varanny.json config?

[krvw]

Sure, here you go:

{
"Delay": 0,
"Port": 8273,
"Modems": [
{
"Name": "IC-7100fm",
"Type": "fm",
"Cmd": "wine",
"Args": "/home/krvw/.wine/drive_c/VARA FM/VARAFM.exe",
"Config": "/home/krvw/.wine/drive_c/VARA FM/VARAFM.ic7100.ini",
"CatCtrl": {
"Port": 4532,
"Dialect": "hamlib",
"Cmd": "rigctld",
"Args": "-m 3070 -r /dev/ttyUSB0 -s 19200"
}
},
{
"Name": "IC-7100hf",
"Type": "hf",
"Cmd": "wine",
"Args": "/home/krvw/.wine/drive_c/VARA/VARA.exe",
"Config": "/home/krvw/.wine/drive_c/VARA/VARA.ic7100.ini",
"CatCtrl": {
"Port": 4532,
"Dialect": "hamlib",
"Cmd": "rigctld",
"Args": "-m 3070 -r /dev/ttyUSB0 -s 19200"
}
}
]
}

[georges]

That's strange. varanny sends a SIGTERM to the process as you can see here:

varanny/varanny.go

Lines 251 to 266 in 9b05bc6

	log.Println("Cleaning up after closing connection")
	if modemCmd != nil && modemCmd.Process != nil {
	log.Println("Shutdown modem process gracefully")
	// Gracefully shutdown process on linux and kill on windows
	err := modemCmd.Process.Signal(syscall.SIGTERM)
	if err != nil {
	log.Println("Shutdown modem process gracefully failed, killing")
	modemCmd.Process.Kill()
	}
	processState, err := modemCmd.Process.Wait()
	if err != nil || processState.Success() {
	log.Println("Warning: awaiting termination of modem process failed")
	}
	modemCmd.Process.Release()
	}

The Wine executable should catch that and terminate accordingly. Perhaps there is some weird interaction with Box86? I don't have a setup on RPi so this is a bit uncharted territory.

[krvw]

I cannot speak to that, unfortunately. However, when I have a VARA.exe running, I can see it as expected in the process table, and a "kill PID" terminates it with immediate effect.

Anyone else running this on a Pi?

Ken

[krvw]

I've been looking at the code and scratching my head on this issue.

Here's a data point that may be helpful. I hope.

When I use Winlink Express and load a VARA modem, and then later switch to a different modem, I often get an exception when the new modem fails to bind to localhost. But, when I wait for several seconds and try again, the new modem launches fine.

Perhaps you should wait a bit before checking the return code from the SIGTERM signal? Perhaps you're releasing the process too soon?

I know that's clunky, but the above behavior is repeatable. If I run VARA HF and then go to VARA FM, it happens every time. But, as I said, if I wait a bit, I can launch the new modem/TNC just fine.

In any case, I'm happy to do any testing here that could be helpful.

[krvw]

Under the assumption that timing is playing a role here, I'm experimenting with overclocking my Pi5 a bit. My results thus far have been a bit different, though the problem of not terminating the finished modem session remains. I'll post more information after I've experimented more. FWIW, launch time seems to have significantly improved with the overclocking. More to come...

[datastory]

I cannot speak to that, unfortunately. However, when I have a VARA.exe running, I can see it as expected in the process table, and a "kill PID" terminates it with immediate effect.

Anyone else running this on a Pi?

Ken

I have the exact same problem.

Other interesting thing: when trying to use Audio Input Monitor on Radiomail, it throws an error "Missing Audio Interface". But when I run the varanny as sudo, it works (and everything else fails).

The varanny throws an error "Device name (no match): All-In-One-Cable Mono (similarity: 0.409090... threshold: 0.7)". From what is this similarity calculated? 🤔