When closing a receiver, another receiver switches frequency to the closed one

[luarvique]

After finally receiving a decent 12V power supply, I have been torturing HL2 a lot and finally got the hpsdrconnector to fail (did take an effort). At some point, it becomes impossible to change profiles on an HL2 device or side-step the current profile. The log shows the following messages:

orange openwebrx[975]: 2024-01-07 00:10:11,664 - owrx.websocket - WARNING - _sendBytes() after socket error, ignoring
orange openwebrx[975]: 2024-01-07 00:10:11,686 - owrx.websocket - WARNING - _sendBytes() after socket error, ignoring

It looks like the control connection broke somehow, and hpsdrconnector knows about it, but is not trying to reestablish the connection.

[jancona]

There's no provision for reopening the control connection. I suspect the the connector crashed. Is there anything out of the ordinary in the logs before the messages you posted? Ideally, I need a log of the failure with debug logging turned on in the profile.

[luarvique]

There was absolutely nothing out of the ordinary, other than these messages. The power is currently out, so whatever coredumps were there, are gone now. Will try to recreate the problem once the power is back.

[luarvique]

Encountered one more issue, that is likely different from the one reported above. Going to report it here though, to avoid creating too many issues:

1) Starting with OpenWebRX+ running two HL2 devices (HL2-1 and HL2-2) in two separate browser tabs: one is 40m another one is 80m.

2) Switching tab №1 from HL2-1-40m to RSP-40m (the same band might be purely coincidental).

3) Tab №1 successfully switches to RSP-40m. Tab №2 somehow changes to 40m band, although it is still showing HL2-2-80m profile.

4) Attempt to side-step tab №2 (i.e. change its center_freq) restores it to 80m band.

So, it looks like when HL2-1 device is closed, some frequency change, destined to HL2-1, somehow hits HL2-2.

Only happened once so far.

[luarvique]

Just confirmed above problem. Starting with HL2-2-40m and HL2-3-80m. Switching first tab from HL2-2-40m to RSP-31m. Second tab (HL2-3) somehow goes to 40m. OpenWebRX+ log:

23:43:17,525 - owrx.source.HL2-2 - INFO - STDOUT: 2024/01/08 23:43:17 client: Received an interrupt, stopping...
23:43:17,528 - owrx.source.HL2-2 - INFO - STDOUT: 2024/01/08 23:43:17 [DEBUG] server(7300): Received server command 'close_receiver:52979'
23:43:17,529 - owrx.source.HL2-2 - DEBUG - shut down with RC=0
23:43:17,529 - owrx.source.HL2-2 - INFO - STDOUT: 2024/01/08 23:43:17 [DEBUG] server(7300): closeReceiver(52979)
23:43:17,530 - owrx.source.HL2-2 - INFO - STDOUT: 2024/01/08 23:43:17 [DEBUG] server(7300): handleControlListener() on port 52979 received stopReceiver
23:43:17,536 - owrx.source.HL2-2 - INFO - STDOUT: 2024/01/08 23:43:17 [DEBUG] server(7300): Closing connection on control port 52979, 127.0.0.1:52979
23:43:17,537 - owrx.source.HL2-2 - INFO - STDOUT: 2024/01/08 23:43:17 [DEBUG] server(7300): Error reading on control socket 52979: read tcp 127.0.0.1:52979->127.0.0.1:52250: use of closed network connection
23:43:17,537 - owrx.source.HL2-2 - INFO - STDOUT: 2024/01/08 23:43:17 [DEBUG] server(7300): Calling controlListener.Close() for port 52979
23:43:17,537 - owrx.source.HL2-2 - INFO - STDOUT: 2024/01/08 23:43:17 [ERROR] server(7300): Error accepting connection on control port 52979: accept tcp 127.0.0.1:52979: use of closed network connection
23:43:17,537 - owrx.source.HL2-2 - INFO - STDOUT: 2024/01/08 23:43:17 [INFO] server(7300): Control goroutine for port 52979 exiting
23:43:17,550 - owrx.source.HL2-2 - INFO - STDOUT: 2024/01/08 23:43:17 [DEBUG] server(7300): Finished controlListener.Close() for port 52979
23:43:17,562 - owrx.source.HL2-2 - INFO - STDOUT: 2024/01/08 23:43:17 [DEBUG] server(7300): handleIQListener() on port 40083 received stopReceiver
23:43:17,564 - owrx.source.HL2-2 - INFO - STDOUT: 2024/01/08 23:43:17 [DEBUG] server(7300): Calling iqListener.Close() for port 40083
23:43:17,568 - owrx.source.HL2-2 - INFO - STDOUT: 2024/01/08 23:43:17 [ERROR] server(7300): Error accepting connection on IQ port 40083: accept tcp 127.0.0.1:40083: use of closed network connection
23:43:17,572 - owrx.source.HL2-2 - INFO - STDOUT: 2024/01/08 23:43:17 [DEBUG] server(7300): IQ goroutine for port 40083 exiting
23:43:17,579 - owrx.source.HL2-2 - INFO - STDOUT: 2024/01/08 23:43:17 [DEBUG] server(7300): Finished iqListener.Close() for port 40083
23:43:17,586 - owrx.source.HL2-2 - INFO - STDOUT: 2024/01/08 23:43:17 [DEBUG] Attempting to delete receiver protocol1.Receiver{radio:(*protocol1.Radio)(0x40000100b0), sampleFunc:(func([]hpsdr.ReceiveSample))(0x1015a0)}
23:43:17,595 - owrx.source.HL2-2 - INFO - STDOUT: 2024/01/08 23:43:17 [DEBUG] Deleting receiver protocol1.Receiver{radio:(*protocol1.Radio)(0x40000100b0), sampleFunc:(func([]hpsdr.ReceiveSample))(0x1015a0)}
23:43:17,606 - owrx.source.HL2-2 - INFO - STDOUT: 2024/01/08 23:43:17 [INFO] server(7300): Closed receiver listening on control port 52979, 1 receivers left
23:43:17,612 - owrx.source.HL2-2 - INFO - STDOUT: 2024/01/08 23:43:17 [DEBUG] server(7300): Error reading server socket: EOF
23:43:17,615 - owrx.source.HL2-2 - INFO - STDOUT: 2024/01/08 23:43:17 [DEBUG] server(7300): Error writing to IQ port 40083: write tcp 127.0.0.1:40083->127.0.0.1:33330: use of closed network connection
23:43:17,618 - owrx.source.HL2-2 - INFO - STDOUT: 2024/01/08 23:43:17 [DEBUG] server(7300): Calling distributor.Close() for IQ port 40083
23:43:17,620 - owrx.source.HL2-2 - INFO - STDOUT: 2024/01/08 23:43:17 [DEBUG] server(7300): Removing listener 0x40001166c0
23:43:17,621 - owrx.source.HL2-2 - INFO - STDOUT: 2024/01/08 23:43:17 [DEBUG] server(7300): Removed listener 0x40001166c0
23:43:17,635 - owrx.dsp - DEBUG - wiring new output of type audio
23:43:17,848 - owrx.dsp - DEBUG - wiring new output of type secondary_fft
23:43:18,053 - owrx.dsp - DEBUG - wiring new output of type smeter
23:43:18,059 - owrx.dsp - DEBUG - wiring new output of type meta
23:43:18,062 - owrx.dsp - DEBUG - wiring new output of type secondary_fft
23:43:18,067 - owrx.dsp - DEBUG - wiring new output of type secondary_demod
23:43:18,070 - owrx.dsp - DEBUG - received STATE_RUNNING, attempting DspSource restart
23:43:26,121 - owrx.fft - DEBUG - Spectrum thread initialized successfully.
23:43:26,539 - owrx.source.rspdx - DEBUG - activating profile "31m Broadcast" for "RSPdx"
23:43:26,549 - owrx.source.rspdx - DEBUG - sending property change over control socket: samp_rate changed to 768000

[luarvique]

Proof pic

[luarvique]

I have renamed the issue to reflect the problem reported last. From what I can see so far, it looks like the hpsdrconnector server closes the wrong receiver and moves the receiver user wanted to close in its place.

In the above example, when closing HL2-1, the server actually closes HL2-2 (last open receiver) and starts sending the HL2-2 client HL2-1 stream instead.

I did look into the hpsdrconnector source code, but Go syntax is too much for me to handle without some ramp-up. Could you look into this? It is 100% repeatable and looks very much like some logic problem in the hpsdrconnector server.

[luarvique]

Since there has been no activity here, I started investigating the issue on my own. The main suspect so far is the way separate receivers are indexed inside the hpsdr project. The protocol1/radio.go::receiverIndex() function essentially returns the ordinal number of a receiver within the array. That index is later used in protocol1/receiver.go::SetFrequency() and protocol1/receiver.go::GetFrequency(), as well as unknown number of other places.

BUT, the ordinal number of a receiver may change if one of the previous receivers is removed with the protocol1/radio.go::deleteReceiver() call. While I do not know for sure if this is indeed the problem, it surely looks like it.

[luarvique]

Fixed this problem last night. Please, review and merge pull request https://github.com/jancona/hpsdr/pull/2

[jancona]

Thanks again for tracking this down! It should be fixed in release 0.8.0. I will push it into the main OWRX build soon.

[luarvique]

Any news on getting issue #14 fixed? I have patched over it on the OpenWebRX+ side, by sending an extra frequency update when the HPSDR source starts, but getting this fixed in the hpsdrconnector would be much more preferable.

[jancona]

I just reproduced this again, even though I can see the rxFrequency array is being properly updated. The procedure was:

1. Start one receiver on Profile 1.
2. In a second browser, start OWRX and switch to Profile 2.
3. Close the OWRX window in the first browser. The waterfall in the second browser switches to the first profile's frequency, even though nothing else in the UI (profile, frequency, mode) changes.

Logging says radio.receivers and radio.rxFrequency have been updated.

[luarvique]

Confirmed, able to recreate it here as well.

[jancona]

I think this is fixed now.