Hi Peter.
I have been working on support for both the RC-28 and Countour Shuttle USB devices and have been making progress (the Shuttle works quite well) this is definitely something that wfview will (eventually) support.
73 Phil M0VSE
Thanks, Phil.
I understand suspecting the Pi, but actually I have also tested using a Windows PC with similar results. However, let’s continue with the Pi and see if that gets anywhere.
The ping suggestion is interesting. I have run three tests today:
- Ping from the Pi to google.com
- Ping from the MacBook to google.com
- Ping from another computer on the LAN to the Pi
In all three cases, there were no interruptions to the ping during a wfview hang.
Today I was monitoring the log file, and noticed that I was getting latency warnings (whilst set at 300ms). I increased to 500ms, and the warnings went away - but it was still hanging occasionally.
I have captured a debug log file today during a hang. In this instance (and the first time I have seen this behaviour) it never recovered! I let it continue for about a minute during the hang, and then closed the server.
The start of the trouble is shown below, and the full log-file is available here: Dropbox - wfview.log - Simplify your life
2022-01-05 09:27:22.271 DBG rig: ---- Begin hex dump -----:
2022-01-05 09:27:22.272 DBG rig: "INDEX: 00 01 02 03 04 "
2022-01-05 09:27:22.272 DBG rig: "DATA: 1a 06 01 01 fd "
2022-01-05 09:27:22.272 DBG rig: ----- End hex dump -----
2022-01-05 09:27:22.321 INF udp.server: "::ffff:213.205.194.148" : got out of sequence ping reply. Got: 22279 expecting: 22280
2022-01-05 09:27:22.329 INF udp.server: "::ffff:213.205.194.148" : got out of sequence ping reply. Got: 64147 expecting: 64148
2022-01-05 09:27:22.338 INF udp.server: "::ffff:213.205.194.148" : got out of sequence ping reply. Got: 64694 expecting: 64695
2022-01-05 09:27:22.338 DBG rig: ---- Begin hex dump -----:
2022-01-05 09:27:22.338 DBG rig: "INDEX: 00 01 02 03 04 "
2022-01-05 09:27:22.339 DBG rig: "DATA: 1a 06 01 01 fd "
2022-01-05 09:27:22.339 DBG rig: ----- End hex dump -----
2022-01-05 09:27:22.418 DBG rig: Final payload in rig commander to be sent to rig:
2022-01-05 09:27:22.419 DBG rig: ---- Begin hex dump -----:
2022-01-05 09:27:22.419 DBG rig: "INDEX: 00 01 02 03 04 05 "
2022-01-05 09:27:22.419 DBG rig: "DATA: fe fe a4 e1 04 fd "
2022-01-05 09:27:22.419 DBG rig: ----- End hex dump -----
2022-01-05 09:27:22.421 DBG rig: ---- Begin hex dump -----:
2022-01-05 09:27:22.421 DBG rig: "INDEX: 00 01 02 03 "
2022-01-05 09:27:22.422 DBG rig: "DATA: 04 01 01 fd "
2022-01-05 09:27:22.422 DBG rig: ----- End hex dump -----
2022-01-05 09:27:22.470 DBG rig: Final payload in rig commander to be sent to rig:
2022-01-05 09:27:22.470 DBG rig: ---- Begin hex dump -----:
2022-01-05 09:27:22.471 DBG rig: "INDEX: 00 01 02 03 04 05 06 "
2022-01-05 09:27:22.471 DBG rig: "DATA: fe fe a4 e1 1a 06 fd "
2022-01-05 09:27:22.471 DBG rig: ----- End hex dump -----
2022-01-05 09:27:22.474 DBG rig: ---- Begin hex dump -----:
2022-01-05 09:27:22.474 DBG rig: "INDEX: 00 01 02 03 04 "
2022-01-05 09:27:22.475 DBG rig: "DATA: 1a 06 01 01 fd "
2022-01-05 09:27:22.475 DBG rig: ----- End hex dump -----
2022-01-05 09:27:22.610 DBG audio: No more data available but buffer is not full! sentlen: 5120 nBytes: 16384
2022-01-05 09:27:22.650 INF udp.server: "::ffff:213.205.194.148" : got out of sequence ping reply. Got: 22280 expecting: 22281
2022-01-05 09:27:22.651 INF udp.server: "::ffff:213.205.194.148" : got out of sequence ping reply. Got: 22280 expecting: 22281
2022-01-05 09:27:22.652 INF udp.server: "::ffff:213.205.194.148" : got out of sequence ping reply. Got: 64148 expecting: 64149
2022-01-05 09:27:22.653 INF udp.server: "::ffff:213.205.194.148" : got out of sequence ping reply. Got: 64148 expecting: 64149
2022-01-05 09:27:22.654 DBG rig: ---- Begin hex dump -----:
2022-01-05 09:27:22.655 DBG rig: "INDEX: 00 01 02 03 "
2022-01-05 09:27:22.656 DBG rig: "DATA: 1c 00 00 fd "
2022-01-05 09:27:22.656 DBG rig: ----- End hex dump -----
2022-01-05 09:27:22.668 DBG rig: Final payload in rig commander to be sent to rig:
2022-01-05 09:27:22.668 DBG rig: ---- Begin hex dump -----:
2022-01-05 09:27:22.669 DBG rig: "INDEX: 00 01 02 03 04 05 06 "
2022-01-05 09:27:22.669 DBG rig: "DATA: fe fe a4 e1 1c 00 fd "
2022-01-05 09:27:22.670 DBG rig: ----- End hex dump -----
2022-01-05 09:27:22.670 INF udp.server: "::ffff:213.205.194.148" : got out of sequence ping reply. Got: 64695 expecting: 64696
2022-01-05 09:27:22.671 INF udp.server: "::ffff:213.205.194.148" : got out of sequence ping reply. Got: 64695 expecting: 64696
2022-01-05 09:27:22.672 DBG rig: ---- Begin hex dump -----:
2022-01-05 09:27:22.673 DBG rig: "INDEX: 00 01 02 03 "
2022-01-05 09:27:22.673 DBG rig: "DATA: 1c 00 00 fd "
2022-01-05 09:27:22.673 DBG rig: ----- End hex dump -----
2022-01-05 09:27:22.703 INF udp.server: "::ffff:213.205.194.148" : got out of sequence ping reply. Got: 22280 expecting: 22281
2022-01-05 09:27:22.704 INF udp.server: "::ffff:213.205.194.148" : got out of sequence ping reply. Got: 64695 expecting: 64696
2022-01-05 09:27:22.713 INF udp.server: "::ffff:213.205.194.148" : got out of sequence ping reply. Got: 64148 expecting: 64149
2022-01-05 09:27:22.746 DBG rig: ---- Begin hex dump -----:
2022-01-05 09:27:22.747 DBG rig: "INDEX: 00 01 02 03 04 "
2022-01-05 09:27:22.747 DBG rig: "DATA: 14 0a 00 13 fd "
2022-01-05 09:27:22.748 DBG rig: ----- End hex dump -----
2022-01-05 09:27:22.919 DBG rig: Final payload in rig commander to be sent to rig:
2022-01-05 09:27:22.919 DBG rig: ---- Begin hex dump -----:
2022-01-05 09:27:22.919 DBG rig: "INDEX: 00 01 02 03 04 05 06 "
2022-01-05 09:27:22.919 DBG rig: "DATA: fe fe a4 e1 14 0a fd "
2022-01-05 09:27:22.920 DBG rig: ----- End hex dump -----
2022-01-05 09:27:22.921 DBG rig: ---- Begin hex dump -----:
2022-01-05 09:27:22.921 DBG rig: "INDEX: 00 01 02 03 04 "
2022-01-05 09:27:22.922 DBG rig: "DATA: 14 0a 00 13 fd "
2022-01-05 09:27:22.922 DBG rig: ----- End hex dump -----
2022-01-05 09:27:22.944 DBG udp: Missing Seq: size= 4093 firstKey= 1 lastKey= 4095 missing= 2
2022-01-05 09:27:23.030 DBG audio: No more data available but buffer is not full! sentlen: 11264 nBytes: 16384
2022-01-05 09:27:23.183 DBG rig: Final payload in rig commander to be sent to rig:
2022-01-05 09:27:23.183 DBG rig: ---- Begin hex dump -----:
2022-01-05 09:27:23.184 DBG rig: "INDEX: 00 01 02 03 04 05 06 "
2022-01-05 09:27:23.184 DBG rig: "DATA: fe fe a4 e1 14 02 fd "
2022-01-05 09:27:23.184 DBG rig: ----- End hex dump -----
2022-01-05 09:27:23.185 DBG rig: ---- Begin hex dump -----:
2022-01-05 09:27:23.186 DBG rig: "INDEX: 00 01 02 03 04 "
2022-01-05 09:27:23.186 DBG rig: "DATA: 14 02 02 55 fd "
2022-01-05 09:27:23.186 DBG rig: ----- End hex dump -----
2022-01-05 09:27:23.292 DBG audio: outgoing audio buffer full!
2022-01-05 09:27:23.292 DBG audio: outgoing audio buffer full!
2022-01-05 09:27:23.292 DBG audio: outgoing audio buffer full!
2022-01-05 09:27:23.348 DBG audio: outgoing audio buffer full!
2022-01-05 09:27:23.348 DBG audio: outgoing audio buffer full!
2022-01-05 09:27:23.348 DBG audio: outgoing audio buffer full!
2022-01-05 09:27:23.348 DBG audio: outgoing audio buffer full!
2022-01-05 09:27:23.348 DBG audio: outgoing audio buffer full!
2022-01-05 09:27:23.404 DBG audio: outgoing audio buffer full!
2022-01-05 09:27:23.404 DBG audio: outgoing audio buffer full!
2022-01-05 09:27:23.404 DBG audio: outgoing audio buffer full!
2022-01-05 09:27:23.404 DBG audio: outgoing audio buffer full!
2022-01-05 09:27:23.424 DBG rig: Final payload in rig commander to be sent to rig:
2022-01-05 09:27:23.424 DBG rig: ---- Begin hex dump -----:
2022-01-05 09:27:23.424 DBG rig: "INDEX: 00 01 02 03 04 05 "
2022-01-05 09:27:23.424 DBG rig: "DATA: fe fe a4 e1 11 fd "
2022-01-05 09:27:23.424 DBG rig: ----- End hex dump -----
I would like the RC28 to work with wfview .
That’s great news. I look forward to trying it.
The momentary interruptions I can cope with. But when the audio stops for 5-30 seconds, that makes it unworkable.
Yes, I agree that the hotspot (which is indeed an iPhone) is likely to be doing things in the background. I’m only using this the test because I want the test to go out over the internet and I can’t think of any other way of doing it!
The real application that this is aiming towards is a remote hilltop operation, which will use a 3G router that has no background applications. Although I could test with this (and I have), it is a real hassle to do so because I don’t have a spare SIM so I need to “borrow” my iPhone SIM which of course is a nanoSiM hence needs an adaptor which it tends to fall out of, etc, etc…
Yes, I was seeing this, but I have now increased to 500ms and that problem has gone away. The “long hang” problem persists, however.
Hi Russell,
I have been checking this on my Pi4 test system and after a clean install, I find that I need to do at least the following to ensure I don’t experience periodic dropouts from the server:
Edit file /etc/xdg/lxpanel/LXDG-pi/panels/panel and locate the section “dhcpdui” and add the line BgScan=0 to the Config:
Plugin {
type=dhcpcdui
Config {
BgScan=0
}
}
Then edit /etc/wpa_supplicant/wpa_supplicant.conf and add bgscan=“” to your network section
network={
ssid="xxxx"
psk="xxxxx"
key_mgmt=WPA-PSK
bgscan=""
}
The final thing is to disable the background scan in the interface itself:
Create a file called /etc/modprobe.d/brcmfmac.conf containing:
options brcmfmac roamoff=1
Then reboot. I found that all 3 settings were required to completely remove the ‘stuttering’ issue from a Pi server. All changes must be done with sudo as they are system files so usual caveats about editing system files should apply (take a backup first!)
73 Phil M0VSE
Hmmm… thanks, Phil - I have made those changes. Is that intended to stop Wifi polling? I have actually got wifi turned off, so I’m not sure if that will make any difference - but I have done so anyway.
I’m not sure if it has helped. The behaviour seems good sometimes, and not others… perhaps the performance of the 4G connection varies.
Watching the log file (not in debug mode), I get a constant stream of “out of sequence” messages:
022-01-05 10:50:57.336 INF udp.server: "::ffff:81.109.82.62" : got out of sequence ping reply. Got: 3291 expecting: 3292
2022-01-05 10:50:57.337 INF udp.server: "::ffff:81.109.82.62" : got out of sequence ping reply. Got: 14716 expecting: 14717
2022-01-05 10:50:57.749 INF udp.server: "::ffff:81.109.82.62" : got out of sequence ping reply. Got: 14719 expecting: 14720
2022-01-05 10:50:57.749 INF udp.server: "::ffff:81.109.82.62" : got out of sequence ping reply. Got: 2621 expecting: 2622
2022-01-05 10:50:57.751 INF udp.server: "::ffff:81.109.82.62" : got out of sequence ping reply. Got: 3294 expecting: 3295
2022-01-05 10:50:58.046 INF udp.server: "::ffff:81.109.82.62" ( "Audio" ): Received 'retransmit' request for 148
2022-01-05 10:50:58.046 INF udp.server: "::ffff:81.109.82.62" ( "Audio" ): Sending retransmit of 94
2022-01-05 10:50:58.049 INF udp.server: "::ffff:81.109.82.62" : got out of sequence ping reply. Got: 2622 expecting: 2623
2022-01-05 10:50:58.050 INF udp.server: "::ffff:81.109.82.62" : got out of sequence ping reply. Got: 3295 expecting: 3296
2022-01-05 10:50:58.053 INF udp.server: "::ffff:81.109.82.62" : got out of sequence ping reply. Got: 14720 expecting: 14721
2022-01-05 10:50:58.062 INF udp.server: "::ffff:81.109.82.62" : got out of sequence ping reply. Got: 14720 expecting: 14721
2022-01-05 10:50:58.063 INF udp.server: "::ffff:81.109.82.62" : got out of sequence ping reply. Got: 2622 expecting: 2623
2022-01-05 10:50:58.063 INF udp.server: "::ffff:81.109.82.62" : got out of sequence ping reply. Got: 3295 expecting: 3296
2022-01-05 10:50:58.364 INF udp.server: "::ffff:81.109.82.62" : got out of sequence ping reply. Got: 14722 expecting: 14723
2022-01-05 10:50:58.365 INF udp.server: "::ffff:81.109.82.62" : got out of sequence ping reply. Got: 2624 expecting: 2625
2022-01-05 10:50:58.365 INF udp.server: "::ffff:81.109.82.62" : got out of sequence ping reply. Got: 3297 expecting: 3298
2022-01-05 10:50:58.768 INF udp.server: "::ffff:81.109.82.62" : got out of sequence ping reply. Got: 14725 expecting: 14726
2022-01-05 10:50:58.768 INF udp.server: "::ffff:81.109.82.62" : got out of sequence ping reply. Got: 2627 expecting: 2628
2022-01-05 10:50:58.769 INF udp.server: "::ffff:81.109.82.62" : got out of sequence ping reply. Got: 3300 expecting: 3301
2022-01-05 10:50:58.969 INF udp.server: "::ffff:81.109.82.62" : got out of sequence ping reply. Got: 14726 expecting: 14727
2022-01-05 10:50:58.970 INF udp.server: "::ffff:81.109.82.62" : got out of sequence ping reply. Got: 2628 expecting: 2629
2022-01-05 10:50:58.971 INF udp.server: "::ffff:81.109.82.62" : got out of sequence ping reply. Got: 3301 expecting: 3302
2022-01-05 10:50:59.385 INF udp.server: "::ffff:81.109.82.62" : got out of sequence ping reply. Got: 2631 expecting: 2632
2022-01-05 10:50:59.389 INF udp.server: "::ffff:81.109.82.62" : got out of sequence ping reply. Got: 14729 expecting: 14730
2022-01-05 10:50:59.390 INF udp.server: "::ffff:81.109.82.62" : got out of sequence ping reply. Got: 3304 expecting: 3305
2022-01-05 10:50:59.584 INF udp.server: "::ffff:81.109.82.62" : got out of sequence ping reply. Got: 14730 expecting: 14731
2022-01-05 10:50:59.585 INF udp.server: "::ffff:81.109.82.62" : got out of sequence ping reply. Got: 2632 expecting: 2633
2022-01-05 10:50:59.586 INF udp.server: "::ffff:81.109.82.62" : got out of sequence ping reply. Got: 3305 expecting: 3306
2022-01-05 10:50:59.788 INF udp.server: "::ffff:81.109.82.62" : got out of sequence ping reply. Got: 2633 expecting: 2634
2022-01-05 10:50:59.789 INF udp.server: "::ffff:81.109.82.62" : got out of sequence ping reply. Got: 3306 expecting: 3307
2022-01-05 10:50:59.790 INF udp.server: "::ffff:81.109.82.62" : got out of sequence ping reply. Got: 14731 expecting: 14732
2022-01-05 10:51:00.215 INF udp.server: "::ffff:81.109.82.62" : got out of sequence ping reply. Got: 2636 expecting: 2637
2022-01-05 10:51:00.217 INF udp.server: "::ffff:81.109.82.62" : got out of sequence ping reply. Got: 3309 expecting: 3310
2022-01-05 10:51:00.219 INF udp.server: "::ffff:81.109.82.62" : got out of sequence ping reply. Got: 14734 expecting: 14735
2022-01-05 10:51:00.401 INF udp.server: "::ffff:81.109.82.62" : got out of sequence ping reply. Got: 14735 expecting: 14736
2022-01-05 10:51:00.402 INF udp.server: "::ffff:81.109.82.62" : got out of sequence ping reply. Got: 2637 expecting: 2638
2022-01-05 10:51:00.404 INF udp.server: "::ffff:81.109.82.62" : got out of sequence ping reply. Got: 3310 expecting: 3311
2022-01-05 10:51:00.605 INF udp.server: "::ffff:81.109.82.62" : got out of sequence ping reply. Got: 2638 expecting: 2639
2022-01-05 10:51:00.607 INF udp.server: "::ffff:81.109.82.62" : got out of sequence ping reply. Got: 14736 expecting: 14737
2022-01-05 10:51:00.607 INF udp.server: "::ffff:81.109.82.62" : got out of sequence ping reply. Got: 3311 expecting: 3312
2022-01-05 10:51:01.016 INF udp.server: "::ffff:81.109.82.62" : got out of sequence ping reply. Got: 3314 expecting: 3315
Then after a while it seems to go into a different state where it is giving a constant stream of latency warning messages (note that latency is set to 500ms, so why is it giving the warnings?)
2022-01-05 10:48:09.803 INF udp.server: "::ffff:81.109.82.62" : got out of sequence ping reply. Got: 35003 expecting: 35004
2022-01-05 10:48:09.805 INF udp.server: "::ffff:81.109.82.62" : got out of sequence ping reply. Got: 6003 expecting: 6004
2022-01-05 10:48:09.806 INF udp.server: "::ffff:81.109.82.62" : got out of sequence ping reply. Got: 13231 expecting: 13232
2022-01-05 10:48:09.809 INF audio: Input Packet 0 arrived too late (increase output latency!) 314 ms
2022-01-05 10:48:09.829 INF audio: Input Packet 0 arrived too late (increase output latency!) 333 ms
2022-01-05 10:48:09.850 INF audio: Input Packet 0 arrived too late (increase output latency!) 354 ms
2022-01-05 10:48:09.870 INF audio: Input Packet 0 arrived too late (increase output latency!) 318 ms
2022-01-05 10:48:09.890 INF audio: Input Packet 0 arrived too late (increase output latency!) 338 ms
2022-01-05 10:48:09.911 INF audio: Input Packet 0 arrived too late (increase output latency!) 359 ms
2022-01-05 10:48:09.930 INF audio: Input Packet 0 arrived too late (increase output latency!) 378 ms
2022-01-05 10:48:09.950 INF audio: Input Packet 0 arrived too late (increase output latency!) 341 ms
2022-01-05 10:48:09.970 INF audio: Input Packet 0 arrived too late (increase output latency!) 361 ms
2022-01-05 10:48:09.989 INF audio: Input Packet 0 arrived too late (increase output latency!) 326 ms
2022-01-05 10:48:10.007 INF udp.server: "::ffff:81.109.82.62" : got out of sequence ping reply. Got: 6004 expecting: 6005
2022-01-05 10:48:10.008 INF udp.server: "::ffff:81.109.82.62" : got out of sequence ping reply. Got: 13232 expecting: 13233
2022-01-05 10:48:10.009 INF udp.server: "::ffff:81.109.82.62" : got out of sequence ping reply. Got: 35004 expecting: 35005
2022-01-05 10:48:10.009 INF audio: Input Packet 0 arrived too late (increase output latency!) 345 ms
2022-01-05 10:48:10.030 INF audio: Input Packet 0 arrived too late (increase output latency!) 366 ms
2022-01-05 10:48:10.050 INF audio: Input Packet 0 arrived too late (increase output latency!) 331 ms
2022-01-05 10:48:10.070 INF audio: Input Packet 0 arrived too late (increase output latency!) 350 ms
2022-01-05 10:48:10.089 INF audio: Input Packet 0 arrived too late (increase output latency!) 369 ms
2022-01-05 10:48:10.110 INF audio: Input Packet 0 arrived too late (increase output latency!) 334 ms
2022-01-05 10:48:10.130 INF audio: Input Packet 0 arrived too late (increase output latency!) 354 ms
2022-01-05 10:48:10.149 INF audio: Input Packet 0 arrived too late (increase output latency!) 372 ms
Hi Russell.
I have seen similar issues and I suspect that the bluetooth stack on the Pi can also cause network “glitches”
As I don’t use Bluetooth, I have completely removed it with the command:
sudo apt-get purge bluez -y
sudo apt-get autoremove -y
I also disabled the Bluetooth adaptor by adding this to the end of /boot/config.txt
dtoverlay=disable-bt
My client has been running connected to the server for about 30 minutes so far with no obvious issues.
There are also various fixes that are currently being tested in the “settings” branch, including FEC (forward error correction) for the Opus codec, this should allow single lost audio packets to be reconstructed but has received limited testing. I also find that on Linux, using portaudio (rather than the native QT audio) seems to work better.
73 Phil M0VSE
Thanks for that, Phil.
- Bluetooth
I have removed Bluetooth as suggested, and perhaps it helps but not completely. In testing today, I got:
- Ran for 4 minutes
- Stopped for 1 minute
- Resumed for 2 mintues
- Stopped for 1 minute
- Resumed for 15 minutes
- Stopped for 1 minute
- Resumed for 3 minutes
- Stopped and did not resume even though a connection is shown and rx latency/rtt/loss is being recorded. A Disconnect/Connect causes it to resume.
Note that from about minute 3 onwards I was getting the constant stream of latency ~ 300 ms INF messages, even though latency is set to 500ms and the reported latency is <100 ms.
Here is the log leading up to and including the last stoppage.
2022-01-07 10:22:08.284 INF audio: Input Packet 0 arrived too late (increase output latency!) 301 ms
2022-01-07 10:22:08.303 INF audio: Input Packet 0 arrived too late (increase output latency!) 320 ms
2022-01-07 10:22:08.323 INF audio: Input Packet 0 arrived too late (increase output latency!) 340 ms
2022-01-07 10:22:36.267 INF udp.server: "::ffff:109.249.185.105" : got out of sequence ping reply. Got: 5265 expecting: 5266
2022-01-07 10:22:36.273 INF udp.server: "::ffff:109.249.185.105" : got out of sequence ping reply. Got: 53123 expecting: 53124
2022-01-07 10:22:36.281 INF audio: Input Packet 0 arrived too late (increase output latency!) 28243 ms
2022-01-07 10:23:02.119 INF udp.server: "::ffff:109.249.185.105" ( "Audio" ): Deleting stale connection
2022-01-07 10:23:02.119 INF udp.server: Deleting "Audio" connection to: "::ffff:109.249.185.105" : "62126"
2022-01-07 10:23:02.209 INF udp.server: Found "Audio" connection to: "::ffff:109.249.185.105" : "62126"
2022-01-07 10:23:02.214 INF udp.server: Current Number of clients connected: 0
2022-01-07 10:23:02.221 INF audio: Input Audio now in stopped state: 0 packets in buffer
2022-01-07 10:23:02.222 INF audio: Destroying opus encoder
2022-01-07 10:23:02.228 INF audio: Output Audio now in stopped state: 0 packets in buffer
2022-01-07 10:23:02.233 INF audio: Destroying opus decoder
2022-01-07 10:23:02.241 INF udp.server: "::ffff:109.249.185.105" ( "CIV" ): Deleting stale connection
2022-01-07 10:23:02.242 INF udp.server: Deleting "CIV" connection to: "::ffff:109.249.185.105" : "27879"
2022-01-07 10:23:02.337 INF udp.server: Found "CIV" connection to: "::ffff:109.249.185.105" : "27879"
2022-01-07 10:23:02.337 INF udp.server: Current Number of clients connected: 0
2022-01-07 10:23:02.338 INF udp.server: "::ffff:109.249.185.105" ( "Control" ): Deleting stale connection
2022-01-07 10:23:02.338 INF udp.server: Deleting "Control" connection to: "::ffff:109.249.185.105" : "60639"
2022-01-07 10:23:02.339 INF udp.server: Found "Control" connection to: "::ffff:109.249.185.105" : "60639"
2022-01-07 10:23:02.339 INF udp.server: Current Number of clients connected: 0
2022-01-07 10:23:02.384 INF udp.server: "::ffff:109.249.185.105" : New Control connection created
2022-01-07 10:23:12.082 INF udp.server: "::ffff:109.249.185.105" : got out of sequence ping reply. Got: 56055 expecting: 56056
2022-01-07 10:23:12.392 INF udp.server: "::ffff:109.249.185.105" : got out of sequence ping reply. Got: 56057 expecting: 56058
2022-01-07 10:23:40.128 INF udp.server: "::ffff:109.249.185.105" : got out of sequence ping reply. Got: 56333 expecting: 56334
2022-01-07 10:23:42.401 INF udp.server: "::ffff:109.249.185.105" : got out of sequence ping reply. Got: 56355 expecting: 56356
2022-01-07 10:23:46.589 INF udp.server: "::ffff:109.249.185.105" : got out of sequence ping reply. Got: 56396 expecting: 56397
2022-01-07 10:23:51.685 INF udp.server: "::ffff:109.249.185.105" : got out of sequence ping reply. Got: 56446 expecting: 56447
2022-01-07 10:23:53.062 INF udp.server: "::ffff:109.249.185.105" : Received token request
2022-01-07 10:23:53.063 INF udp.server: "::ffff:109.249.185.105" ( "Control" ): Sending Token response for type: 5
2022-01-07 10:23:53.085 INF udp.server: "::ffff:109.249.185.105" : Received token request
2022-01-07 10:23:53.086 INF udp.server: "::ffff:109.249.185.105" ( "Control" ): Sending Token response for type: 5
2022-01-07 10:23:53.087 INF udp.server: "::ffff:109.249.185.105" : Received token request
2022-01-07 10:23:53.088 INF udp.server: "::ffff:109.249.185.105" ( "Control" ): Sending Token response for type: 5
2022-01-07 10:23:56.798 INF udp.server: "::ffff:109.249.185.105" : got out of sequence ping reply. Got: 56496 expecting: 56497
2022-01-07 10:23:59.187 INF udp.server: "::ffff:109.249.185.105" : got out of sequence ping reply. Got: 56519 expecting: 56520
2022-01-07 10:23:59.489 INF udp.server: "::ffff:109.249.185.105" : got out of sequence ping reply. Got: 56521 expecting: 56522
2022-01-07 10:24:00.699 INF udp.server: "::ffff:109.249.185.105" : got out of sequence ping reply. Got: 56532 expecting: 56533
2022-01-07 10:24:01.282 INF udp.server: "::ffff:109.249.185.105" : got out of sequence ping reply. Got: 56537 expecting: 56538
2022-01-07 10:24:03.384 INF udp.server: "::ffff:109.249.185.105" : got out of sequence ping reply. Got: 56557 expecting: 56558
2022-01-07 10:24:12.398 INF udp.server: "::ffff:109.249.185.105" : got out of sequence ping reply. Got: 56646 expecting: 56647
2022-01-07 10:24:15.984 INF udp.server: "::ffff:109.249.185.105" : got out of sequence ping reply. Got: 56681 expecting: 56682
2022-01-07 10:24:18.981 INF udp.server: "::ffff:109.249.185.105" : got out of sequence ping reply. Got: 56710 expecting: 56711
2022-01-07 10:24:23.118 INF udp.server: "::ffff:109.249.185.105" : got out of sequence ping reply. Got: 56750 expecting: 56751
2022-01-07 10:24:24.980 INF udp.server: "::ffff:109.249.185.105" : got out of sequence ping reply. Got: 56768 expecting: 56769
2022-01-07 10:24:34.280 INF udp.server: "::ffff:109.249.185.105" : got out of sequence ping reply. Got: 56860 expecting: 56861
2022-01-07 10:24:34.572 INF udp.server: "::ffff:109.249.185.105" : got out of sequence ping reply. Got: 56861 expecting: 56862
2022-01-07 10:24:34.930 INF udp.server: "::ffff:109.249.185.105" : got out of sequence ping reply. Got: 56863 expecting: 56864
2022-01-07 10:24:35.110 INF udp.server: "::ffff:109.249.185.105" : got out of sequence ping reply. Got: 56865 expecting: 56866
2022-01-07 10:24:35.451 INF udp.server: "::ffff:109.249.185.105" : got out of sequence ping reply. Got: 56866 expecting: 56867
2022-01-07 10:24:35.596 INF udp.server: "::ffff:109.249.185.105" : got out of sequence ping reply. Got: 56867 expecting: 56868
2022-01-07 10:24:35.930 INF udp.server: "::ffff:109.249.185.105" : got out of sequence ping reply. Got: 56869 expecting: 56870
2022-01-07 10:24:36.112 INF udp.server: "::ffff:109.249.185.105" : got out of sequence ping reply. Got: 56871 expecting: 56872
2022-01-07 10:24:53.090 INF udp.server: "::ffff:109.249.185.105" : Received token request
2022-01-07 10:24:53.090 INF udp.server: "::ffff:109.249.185.105" ( "Control" ): Sending Token response for type: 5
2022-01-07 10:24:53.091 INF udp.server: "::ffff:109.249.185.105" : Received token request
2022-01-07 10:24:53.091 INF udp.server: "::ffff:109.249.185.105" ( "Control" ): Sending Token response for type: 5
2022-01-07 10:24:53.092 INF udp.server: "::ffff:109.249.185.105" : Received token request
2022-01-07 10:24:53.092 INF udp.server: "::ffff:109.249.185.105" ( "Control" ): Sending Token response for type: 5
2022-01-07 10:24:59.189 INF udp.server: "::ffff:109.249.185.105" : got out of sequence ping reply. Got: 57101 expecting: 57102
2022-01-07 10:25:46.792 INF udp.server: "::ffff:109.249.185.105" : got out of sequence ping reply. Got: 57576 expecting: 57577
2022-01-07 10:25:53.083 INF udp.server: "::ffff:109.249.185.105" : Received token request
2022-01-07 10:25:53.083 INF udp.server: "::ffff:109.249.185.105" ( "Control" ): Sending Token response for type: 5
2022-01-07 10:25:53.098 INF udp.server: "::ffff:109.249.185.105" : Received token request
2022-01-07 10:25:53.098 INF udp.server: "::ffff:109.249.185.105" ( "Control" ): Sending Token response for type: 5
2022-01-07 10:25:53.100 INF udp.server: "::ffff:109.249.185.105" : Received token request
2022-01-07 10:25:53.100 INF udp.server: "::ffff:109.249.185.105" ( "Control" ): Sending Token response for type: 5
2022-01-07 10:26:05.537 INF udp.server: "::ffff:109.249.185.105" : got out of sequence ping reply. Got: 57762 expecting: 57763
2022-01-07 10:26:05.716 INF udp.server: "::ffff:109.249.185.105" : got out of sequence ping reply. Got: 57763 expecting: 57764
2022-01-07 10:26:05.921 INF udp.server: "::ffff:109.249.185.105" : got out of sequence ping reply. Got: 57764 expecting: 57765
2022-01-07 10:26:06.225 INF udp.server: "::ffff:109.249.185.105" : got out of sequence ping reply. Got: 57765 expecting: 57766
2022-01-07 10:26:06.416 INF udp.server: "::ffff:109.249.185.105" : got out of sequence ping reply. Got: 57767 expecting: 57768
2022-01-07 10:26:06.613 INF udp.server: "::ffff:109.249.185.105" : got out of sequence ping reply. Got: 57768 expecting: 57769
2022-01-07 10:26:06.905 INF udp.server: "::ffff:109.249.185.105" : got out of sequence ping reply. Got: 57769 expecting: 57770
2022-01-07 10:26:07.098 INF udp.server: "::ffff:109.249.185.105" : got out of sequence ping reply. Got: 57771 expecting: 57772
2022-01-07 10:26:07.399 INF udp.server: "::ffff:109.249.185.105" : got out of sequence ping reply. Got: 57772 expecting: 57773
2022-01-07 10:26:08.106 INF udp.server: "::ffff:109.249.185.105" ( "Control" ): Missing SEQ has been received! 46e3
2022-01-07 10:26:08.106 INF udp.server: "::ffff:109.249.185.105" ( "Control" ): Missing SEQ has been received! 46e4
2022-01-07 10:26:20.188 INF udp.server: "::ffff:109.249.185.105" : got out of sequence ping reply. Got: 57896 expecting: 57897
2022-01-07 10:26:30.900 INF udp.server: "::ffff:109.249.185.105" : got out of sequence ping reply. Got: 58002 expecting: 58003
- “settings” branch
Thanks - I will try that next.
- portaudio
Sorry - I don’t really know anything about Linux audio so I have no idea what this means. Any pointers?
Update: I have built the “settings” version for the Pi server - and the Settings page looks very nice, btw.
Rig control is working well in client/server mode but I have no audio on the client (and rx latency is reporting as 0 ms).
Here’s the log file so far:
2022-01-07 11:08:59.714 INF udp.server: Server Binding CIV to: 50002
2022-01-07 11:08:59.714 INF udp.server: Server Binding Audio to: 50003
2022-01-07 11:09:00.083 INF system: Received CommReady!!
2022-01-07 11:09:00.084 INF system: Delay command interval timing: 75 ms
2022-01-07 11:09:00.084 INF default: Setting rig state for wfmain
2022-01-07 11:09:00.086 INF rig: Using incomingCIVAddr: (int): 164 hex: a4
2022-01-07 11:09:00.086 INF serial: Received rigCapabilities for "IC-705"
2022-01-07 11:09:00.086 INF rig: Have rig ID: decimal: 164
2022-01-07 11:09:00.169 INF system: Delay command interval timing: 25 ms
2022-01-07 11:09:01.891 INF rig: Received 0x15 center span data: for frequency 250000
2022-01-07 11:09:12.659 INF udp.server: "::ffff:81.109.82.62" : New Control connection created
2022-01-07 11:09:12.660 INF udp.server: "::ffff:81.109.82.62" ( "Control" ): Received 'are you there'
2022-01-07 11:09:12.665 INF udp.server: "::ffff:81.109.82.62" ( "Control" ): Received 'Are you ready'
2022-01-07 11:09:12.671 INF udp.server: "::ffff:81.109.82.62" : Received 'login'
2022-01-07 11:09:12.672 INF udp.server: "::ffff:81.109.82.62" : User "G4CTP" login OK
2022-01-07 11:09:12.672 INF udp.server: "::ffff:81.109.82.62" ( "Control" ): Sending Login response: 1
2022-01-07 11:09:12.678 INF udp.server: "::ffff:81.109.82.62" : Received create token request
2022-01-07 11:09:12.678 INF udp.server: "::ffff:81.109.82.62" ( "Control" ): Sending Capabilities : 2
2022-01-07 11:09:12.678 INF udp.server: "::ffff:81.109.82.62" ( "Control" ): Client will have TX audio
2022-01-07 11:09:12.679 INF udp.server: "::ffff:81.109.82.62" ( "Control" ): Sending ConnectionInfo : 3
2022-01-07 11:09:12.684 INF udp.server: "::ffff:81.109.82.62" : Received request for radio connection
2022-01-07 11:09:12.685 INF udp.server: "::ffff:81.109.82.62" ( "Control" ): Sending Status
2022-01-07 11:09:12.685 INF udp.server: "::ffff:81.109.82.62" ( "Control" ): Sending ConnectionInfo : 5
2022-01-07 11:09:12.686 INF udp.server: "::ffff:81.109.82.62" : rxCodec: 64 txCodec: 64 rxSampleRate 48000 txSampleRate 48000 txBufferLen 500
2022-01-07 11:09:12.687 INF audio: Output setVolume: 0 ( 0 )
2022-01-07 11:09:12.688 INF audio: Output Internal: sample rate 48000 channel count 2
2022-01-07 11:09:12.688 INF audio: Input Internal: sample rate 48000 channel count 2
2022-01-07 11:09:12.696 INF udp.server: "::ffff:81.109.82.62" ( "CIV" ): New connection created
2022-01-07 11:09:12.697 INF audio: Creating opus decoder: success
2022-01-07 11:09:12.697 INF audio: Output wf_resampler_init() returned: 0 resampleRatio: 1
2022-01-07 11:09:12.698 INF audio: Output thread id 0x95545380
2022-01-07 11:09:12.698 INF audio: Output start() running
2022-01-07 11:09:12.698 INF udp.server: "::ffff:81.109.82.62" ( "CIV" ): Received 'are you there'
2022-01-07 11:09:12.700 INF udp.server: "::ffff:81.109.82.62" ( "Audio" ): New connection created
2022-01-07 11:09:12.701 INF udp.server: "::ffff:81.109.82.62" ( "Audio" ): Received 'are you there'
2022-01-07 11:09:12.701 WRN default: "Stream error: No such entity"
2022-01-07 11:09:12.703 INF audio: Creating opus encoder: success
2022-01-07 11:09:12.703 INF audio: Input wf_resampler_init() returned: 0 resampleRatio: 1
2022-01-07 11:09:12.704 INF audio: Input thread id 0x94d44380
2022-01-07 11:09:12.704 INF audio: Input start() running
2022-01-07 11:09:12.705 INF udp.server: "::ffff:81.109.82.62" ( "CIV" ): Received 'Are you ready'
2022-01-07 11:09:12.706 WRN default: "Stream error: No such entity"
2022-01-07 11:09:12.708 INF udp.server: "::ffff:81.109.82.62" ( "Audio" ): Received 'Are you ready'
2022-01-07 11:09:12.838 INF rig: Have rig ID: decimal: 164
2022-01-07 11:09:14.555 INF rig: Received 0x15 center span data: for frequency 250000
2022-01-07 11:10:01.069 INF udp.server: "::ffff:81.109.82.62" ( "Audio" ): Missing SEQ has been received! 922
2022-01-07 11:10:13.157 INF udp.server: "::ffff:81.109.82.62" : Received token request
2022-01-07 11:10:13.157 INF udp.server: "::ffff:81.109.82.62" ( "Control" ): Sending Token response for type: 5
2022-01-07 11:10:38.575 INF udp.server: "::ffff:81.109.82.62" ( "Audio" ): Missing SEQ has been received! fea
2022-01-07 11:10:44.352 INF rig: BSR in rigCommander: band: "\u0007" regCode: "\u0001" freq Hz: 21074000 , mode: 1 , filter: 1 data: false
2022-01-07 11:10:44.353 INF system: receiveBandStackReg BSR received into main: Freq: 21074000 , mode: 1 , filter: 1 , data mode: false
2022-01-07 11:11:13.156 INF udp.server: "::ffff:81.109.82.62" : Received token request
2022-01-07 11:11:13.156 INF udp.server: "::ffff:81.109.82.62" ( "Control" ): Sending Token response for type: 5
2022-01-07 11:12:11.169 INF udp.server: "::ffff:81.109.82.62" ( "CIV" ): Received 'retransmit' request for 18532
2022-01-07 11:12:11.169 INF udp.server: "::ffff:81.109.82.62" ( "CIV" ): Sending retransmit of 4864
2022-01-07 11:12:13.158 INF udp.server: "::ffff:81.109.82.62" : Received token request
2022-01-07 11:12:13.158 INF udp.server: "::ffff:81.109.82.62" ( "Control" ): Sending Token response for type: 5
2022-01-07 11:13:13.170 INF udp.server: "::ffff:81.109.82.62" : Received token request
2022-01-07 11:13:13.170 INF udp.server: "::ffff:81.109.82.62" ( "Control" ): Sending Token response for type: 5
2022-01-07 11:14:13.163 INF udp.server: "::ffff:81.109.82.62" : Received token request
2022-01-07 11:14:13.163 INF udp.server: "::ffff:81.109.82.62" ( "Control" ): Sending Token response for type: 5
Hi Russell.
Yes that’s why I suggested using Portaudio! The line
2022-01-07 11:09:12.701 WRN default: "Stream error: No such entity"
Is the issue as it appears that the audio input isn’t being detected correctly and I haven’t been able to locate the cause yet.
Portaudio is easy to configure though, firstly you need to install the Portaudio library:
sudo apt-get install portaudio19-dev
Then edit the wfview.pro file located in the wfview source directory and remove the # before the line:
# DEFINES += PORTAUDIO
Then change to the build directory and run qmake/make:
cd ../build
qmake ../wfview/wfview.pro
make -j2
sudo make install
I am currently hunting a deadlock issue at the moment that seems to ‘kill’ the server occasionally, I will also try to locate the source of the QT Audio problem although we are considering moving to Portaudio as the default anyway as performance (latency) appears much better.
73 Phil M0VSE
Success 
Well, mostly…
I think this is much better. I still get some stutters, but it recovers much better. Unfortunately it does still occasionally go into longer outages, but again it seems to recover well. When this happens, and following recovery of the audio stream, the log file once again drops into a state of streaming INF messages, this time like this:
2022-01-07 15:20:03.465 INF audio: Input Packet 0 arrived too late (increase output latency!) 50079 ms
2022-01-07 15:20:03.486 INF audio: Input Packet 0 arrived too late (increase output latency!) 50080 ms
2022-01-07 15:20:03.505 INF audio: Input Packet 0 arrived too late (increase output latency!) 50079 ms
2022-01-07 15:20:03.528 INF audio: Input Packet 0 arrived too late (increase output latency!) 50082 ms
2022-01-07 15:20:03.545 INF audio: Input Packet 0 arrived too late (increase output latency!) 50079 ms
2022-01-07 15:20:03.565 INF audio: Input Packet 0 arrived too late (increase output latency!) 50079 ms
2022-01-07 15:20:03.586 INF audio: Input Packet 0 arrived too late (increase output latency!) 50080 ms
2022-01-07 15:20:03.606 INF audio: Input Packet 0 arrived too late (increase output latency!) 50079 ms
2022-01-07 15:20:03.627 INF audio: Input Packet 0 arrived too late (increase output latency!) 50078 ms
2022-01-07 15:20:03.646 INF audio: Input Packet 0 arrived too late (increase output latency!) 50080 ms
2022-01-07 15:20:03.666 INF audio: Input Packet 0 arrived too late (increase output latency!) 50077 ms
2022-01-07 15:20:03.688 INF audio: Input Packet 0 arrived too late (increase output latency!) 50081 ms
2022-01-07 15:20:03.705 INF audio: Input Packet 0 arrived too late (increase output latency!) 50079 ms
2022-01-07 15:20:03.727 INF audio: Input Packet 0 arrived too late (increase output latency!) 50081 ms
2022-01-07 15:20:03.745 INF audio: Input Packet 0 arrived too late (increase output latency!) 50079 ms
2022-01-07 15:20:03.766 INF audio: Input Packet 0 arrived too late (increase output latency!) 50080 ms
2022-01-07 15:20:03.785 INF audio: Input Packet 0 arrived too late (increase output latency!) 50078 ms
2022-01-07 15:20:03.805 INF audio: Input Packet 0 arrived too late (increase output latency!) 50077 ms
(Whilst the above was captured, the rx latency being reported by the client was <60ms)
Time for another full test with the 3G router and VPN, I think.
I am still trying to get to the bottom of what is causing these excessive delays and in extreme cases crashes in the server. I am sure that I will find the cause (eventually!)
I do wonder if it is related to resources on the Pi which will hopefully be a non-issue once we have a dedicated server only version of wfview (wfserver).
73 Phil M0VSE
I’m not convinced that the Pi is entirely at fault, as I have seen similar using a Windows PC as the server.
Of course, I have only built the “settings” version for the server. Is there any point in running that for the client as well?
I have now completed a full end-to-end test including a 3G Router and a VPN between two Pis, as shown here:
The Pi at the “Portable Station” is using the “settings” version of wfview.
The good news is that it all works.
The bad news is that - as before - it suffers short and long drop-outs. The short stutters are tolerable, but the longer outages (of typically 5 - 30 seconds, approximately every 5 - 30 minutes) continue to be a frustration.
I’m now out of ideas for further experiments, so I’m going to park the project for now, and I’ll keep an eye on the forum for future iterations of wfview to test.
Hi Russell,
When did you pull from Settings? There’s a lot happening there lately!
My dad is doing a similar setup, only using an iPhone as the hot spot. So far he actually has got it working very well. He had some regular issues almost exactly every 60 seconds, but closing down other applications and wifi scanning seemed to make it go away.
Keep us updated. I think your experiment is very cool.
–E
de W6EL
Hi Russell.
If you pull the latest settings branch, I think (hope) that I have fixed the issues that you have been experiencing?
I would be very interested to hear how it works for you.
73 Phil M0VSE
OK - thanks, Elliott & Phil.
I will try with the latest settings branch and will report back. I’ll probably start a new thread, as this thread’s title is no longer appropriate.
Also, I don’t like testing with the 3G router too often, as I only have my iPhone’s SIM to test with, and it is a pain fitting a nano-SIM into a micro- and mini-SIM adaptor. Also the router’s SIM slot is behind a screwed-in faceplate! But I can test via a hotspot in the interim.