robotastic / trunk-recorder

Records calls from a Trunked Radio System (P25 & SmartNet)
GNU General Public License v3.0
850 stars 191 forks source link

t-r retuning to control channels on different system #826

Open rosecitytransit opened 1 year ago

rosecitytransit commented 1 year ago

I'm using a modified version of the new_call_mgmt branch, including the cc-retune fix, and things are working pretty good. But I've noticed twice now that recordings start getting saved into the wrong system.

I looked at the logs when it started this time and it seems that after trying the last defined control channel, trunk-recorder isn't going back to the first one but instead trying ones in a different system.

Log excerpts:

...
[2023-06-03 02:54:19.765073] (info)   Control channel retune limit: 0
...
System Number: 1
-------------------------------------
[2023-06-03 02:54:19.765166] (info)   Short Name: ms
[2023-06-03 02:54:19.765175] (info)   System Type: p25
[2023-06-03 02:54:19.765184] (info)   Control Channels: 
[2023-06-03 02:54:19.765195] (info)     769.856250 MHz
[2023-06-03 02:54:19.765225] (info)     770.343750 MHz
[2023-06-03 02:54:19.765242] (info)     770.093750 MHz
[2023-06-03 02:54:19.765257] (info)     771.268750 MHz
[2023-06-03 02:54:19.765272] (info)     771.693750 MHz
[2023-06-03 02:54:19.765287] (info)     771.768750 MHz
[2023-06-03 02:54:19.765302] (info)     772.068750 MHz
[2023-06-03 02:54:19.765316] (info)     772.968750 MHz
...
System Number: 2
-------------------------------------
[2023-06-03 02:54:19.765929] (info)   Short Name: cc
[2023-06-03 02:54:19.765938] (info)   System Type: p25
[2023-06-03 02:54:19.765946] (info)   Control Channels: 
[2023-06-03 02:54:19.765957] (info)     772.056250 MHz
[2023-06-03 02:54:19.765974] (info)     770.081250 MHz
[2023-06-03 02:54:19.765989] (info)     770.331250 MHz
[2023-06-03 02:54:19.766003] (info)     771.206250 MHz
[2023-06-03 02:54:19.766018] (info)     771.256250 MHz
[2023-06-03 02:54:19.766033] (info)     771.481250 MHz
[2023-06-03 02:54:19.766047] (info)     771.681250 MHz
[2023-06-03 02:54:19.766062] (info)     771.756250 MHz
[2023-06-03 02:54:19.766076] (info)     772.056250 MHz
[2023-06-03 02:54:19.766090] (info)     772.356250 MHz
[2023-06-03 02:54:19.766105] (info)     773.231250 MHz
...
System Number: 3
-------------------------------------
[2023-06-03 02:54:19.766710] (info)   Short Name: osrppdxc
[2023-06-03 02:54:19.766719] (info)   System Type: p25
[2023-06-03 02:54:19.766727] (info)   Control Channels: 
[2023-06-03 02:54:19.766738] (info)     773.031250 MHz
[2023-06-03 02:54:19.766755] (info)     769.456250 MHz
[2023-06-03 02:54:19.766770] (info)     770.943750 MHz
[2023-06-03 02:54:19.766784] (info)     770.443750 MHz
[2023-06-03 02:54:19.766799] (info)     773.831250 MHz
[2023-06-03 02:54:19.766813] (info)     774.568750 MHz
[2023-06-03 02:54:19.766828] (info)     773.306250 MHz
[2023-06-03 02:54:19.766843] (info)     773.568750 MHz
[2023-06-03 02:54:19.766857] (info)     774.281250 MHz
[2023-06-03 02:54:19.766883] (info)     774.831250 MHz
...
System Number: 4
-------------------------------------
[2023-06-03 02:54:19.768313] (info)   Short Name: pdx2
[2023-06-03 02:54:19.768321] (info)   System Type: p25
[2023-06-03 02:54:19.768330] (info)   Control Channels: 
[2023-06-03 02:54:19.768340] (info)     772.606250 MHz
[2023-06-03 02:54:19.768357] (info)     771.131250 MHz
[2023-06-03 02:54:19.768371] (info)     773.131250 MHz
[2023-06-03 02:54:19.768386] (info)      85.266250 MHz
[2023-06-03 02:54:19.768401] (info)     854.462500 MHz
[2023-06-03 02:54:19.768416] (info)     770.606250 MHz
[2023-06-03 02:54:19.768431] (info)     852.100000 MHz
[2023-06-03 02:54:19.768445] (info)     852.387500 MHz
[2023-06-03 02:54:19.768460] (info)     853.637500 MHz
[2023-06-03 02:54:19.768474] (info)     856.737500 MHz
[2023-06-03 02:54:19.768489] (info)     856.887500 MHz
[2023-06-03 02:54:19.768504] (info)     857.062500 MHz
[2023-06-03 02:54:19.768518] (info)     857.462500 MHz
[2023-06-03 02:54:19.768533] (info)     857.687500 MHz
...
[2023-06-07 19:01:15.022090] (error)   [ms] Retuning to Control Channel: 770.343750 MHz
[2023-06-07 19:01:15.022178] (info)      - System Source 0 - Min Freq: 769.435250 MHz Max Freq: 771.227250 MHz
[2023-06-07 19:01:15.022235] (error)   [ms]  Control Channel Message Decode Rate: 1/sec, count:  4
[2023-06-07 19:01:18.021302] (error)   [ms] Retuning to Control Channel: 770.093750 MHz
[2023-06-07 19:01:18.021364] (info)      - System Source 0 - Min Freq: 769.435250 MHz Max Freq: 771.227250 MHz
[2023-06-07 19:01:18.021419] (error)   [ms]  Control Channel Message Decode Rate: 1/sec, count:  3
[2023-06-07 19:01:21.015765] (error)   [ms] Retuning to Control Channel: 771.268750 MHz
[2023-06-07 19:01:21.015833] (info)      - System Source 1 - Min Freq: 771.247750 MHz Max Freq: 773.039750 MHz
[2023-06-07 19:01:21.035383] (debug)   P25 trunking Decim: 20 Decim2:  4
[2023-06-07 19:01:21.035423] (info)      P25 Trunking two-stage decimator - Initial decimated rate: 96000 Second decimated rate: 24000 FA: 6250 FB: 12000 System Rate: 1920000
[2023-06-07 19:01:21.045103] (info)      P25 Trunking ARB - Initial Rate: 1920000 Resampled Rate: 24000 Initial Decimation: 20 System Rate: 24000 ARB Rate: 1
[2023-06-07 19:01:22.568236] (error)   [ms]  Control Channel Message Decode Rate: 1/sec, count:  3
[2023-06-07 19:01:24.015650] (error)   [ms] Retuning to Control Channel: 771.693750 MHz
[2023-06-07 19:01:24.015774] (info)      - System Source 1 - Min Freq: 771.247750 MHz Max Freq: 773.039750 MHz
[2023-06-07 19:01:24.015909] (error)   [ms]  Control Channel Message Decode Rate: 0/sec, count:  2
[2023-06-07 19:01:27.022323] (error)   [ms] Retuning to Control Channel: 771.768750 MHz
[2023-06-07 19:01:27.022378] (info)      - System Source 1 - Min Freq: 771.247750 MHz Max Freq: 773.039750 MHz
[2023-06-07 19:01:27.022434] (error)   [ms]  Control Channel Message Decode Rate: 1/sec, count:  3
[2023-06-07 19:01:30.021362] (error)   [ms] Retuning to Control Channel: 772.068750 MHz
[2023-06-07 19:01:30.021438] (info)      - System Source 1 - Min Freq: 771.247750 MHz Max Freq: 773.039750 MHz
[2023-06-07 19:01:30.021489] (error)   [ms]  Control Channel Message Decode Rate: 1/sec, count:  3
[2023-06-07 19:01:33.015352] (error)   [ms] Retuning to Control Channel: 772.968750 MHz
[2023-06-07 19:01:33.015414] (info)      - System Source 1 - Min Freq: 771.247750 MHz Max Freq: 773.039750 MHz
[2023-06-07 19:01:33.015472] (error)   [ms]  Control Channel Message Decode Rate: 1/sec, count:  3
[2023-06-07 19:01:36.015707] (error)   [ms] Retuning to Control Channel: 774.281250 MHz
[2023-06-07 19:01:36.015759] (info)      - System Source 2 - Min Freq: 773.122750 MHz Max Freq: 774.914750 MHz
[2023-06-07 19:01:36.032560] (debug)   P25 trunking Decim: 20 Decim2:  4
[2023-06-07 19:01:36.032607] (info)      P25 Trunking two-stage decimator - Initial decimated rate: 96000 Second decimated rate: 24000 FA: 6250 FB: 12000 System Rate: 1920000
[2023-06-07 19:01:36.042116] (info)      P25 Trunking ARB - Initial Rate: 1920000 Resampled Rate: 24000 Initial Decimation: 20 System Rate: 24000 ARB Rate: 1
[2023-06-07 19:01:37.656044] (error)   [ms]  Control Channel Message Decode Rate: 1/sec, count:  3
[2023-06-07 19:01:39.013996] (error)   [ms] Retuning to Control Channel: 774.568750 MHz
[2023-06-07 19:01:39.014074] (info)      - System Source 2 - Min Freq: 773.122750 MHz Max Freq: 774.914750 MHz
[2023-06-07 19:01:39.014132] (error)   [ms]  Control Channel Message Decode Rate: 0/sec, count:  2
[2023-06-07 19:01:39.074886] (error)   [ms] 381391C  TG:      34046 Freq:   0.000000 MHz    Not Recording: no source covering Freq
[2023-06-07 19:01:39.074953] (info)   [ms]  381391C  TG:      34046 Freq:   0.000000 MHz    This was an UPDATE 
[2023-06-07 19:01:39.076670] (info)   [ms]  381392C  TG:      34250 Freq: 773.031250 MHz    TG not in Talkgroup File 
[2023-06-07 19:01:39.076734] (info)   [ms]  381392C  TG:      34250 Freq: 773.031250 MHz    Starting P25 Recorder Num [11] TDMA: false Slot: 0 QPSK: true
[2023-06-07 19:01:39.076815] (info)   [ms]  381392C  TG:      34250 Freq: 773.031250 MHz    This was an UPDATE 

The first 7 retunes are as expected, but then trunk-recorder tries 2 channels on a completely different system (osrppdxc) and not even ones in a discernible order. The first one tried is parallel with where a next one on the ms system would be, but the next one seems random. And trunk-recorder does indeed lock onto the osrpppdxc control channel and start recording calls from it into the ms system.

Note that I now have a Pi 3B+ that I was given up and running, and intend use that as a test bed if someone has some ideas to try

robotastic commented 1 year ago

That is weird - I just made a change to the master branch to print out all of the Control Channels that were added for a system after it reads in the config file. Could you try running the this branch and seeing if the problem is still there and what it prints out after processing the config file?

rosecitytransit commented 1 year ago

For now, I added some logging to System_impl::get_next_control_channel() since I'm thinking weirdness should show in there:

double System_impl::get_next_control_channel() {
  BOOST_LOG_TRIVIAL(info) << "[" << this->get_short_name() << "/" << short_name << "] old currrent_control_channel=" << current_control_channel << ", control_channels.size()=" << control_channels.size() << ", control_channels[]=" << this->control_channels[current_control_channel];
  current_control_channel++;
  if (current_control_channel >= control_channels.size()) {
    current_control_channel = 0;
  }
  BOOST_LOG_TRIVIAL(info) << "[" << this->get_short_name() << "/" << short_name << "] currrent_control_channel=" << current_control_channel << ", control_channels[]=" << this->control_channels[current_control_channel];
  return this->control_channels[current_control_channel];
}

When I have time (I'm leaving for the weekend) and get every thing set up on the pi, or when I next need to restart the program, I can definitely try out your change. As well as see if I can induce the problem and further troubleshoot.

taclane commented 1 year ago

In the event there's an issue mixing up the channels sometime after initial t-r setup, a patch-free option is also to check out the status server plugin.

The html tables are a little flaky, but it it should still output each system's control channel list, up-to-date as of that moment the page is refreshed.

rosecitytransit commented 1 year ago

Well it did it again, and the added logging shows control_channels.size() magically growing from 8 to 10 and then 12, and hours and many retunes after start.

For now, I've just removed all but the current one in the config. They don't change that often anyways.

On Sat, Jun 10, 2023, 9:13 AM Nick @.***> wrote:

In the event there's an issue mixing up the channels sometime after initial t-r setup, a patch-free option is also to check out the status server plugin.

The html tables are a little flaky, but it it should still output each system's control channel list, up-to-date as of that moment the page is refreshed.

— Reply to this email directly, view it on GitHub https://github.com/robotastic/trunk-recorder/issues/826#issuecomment-1585718319, or unsubscribe https://github.com/notifications/unsubscribe-auth/AFAB7DMVWXK4E2S5D5HZ5ILXKSMKVANCNFSM6AAAAAAZBNW7EY . You are receiving this because you authored the thread.Message ID: @.***>

robotastic commented 1 year ago

I just tried to reproduce this but didn't have any luck. I have one system locked onto a control channel and the other is retuning. Could you share you config file?

{
    "ver": 2,
    "sources": [
        {
            "center": 855700000,
            "rate": 2048000,
            "error": 0,
            "gain": 24,
            "digitalRecorders": 1,
            "driver": "osmosdr",
            "device": "rtl=200,buflen=65536"
        }
    ],
    "systems": [

        {
            "control_channels": [
                855462500,
                855237500
            ],
            "type": "p25",
            "modulation": "qpsk",
            "shortName": "test2"
        },
        {
            "control_channels": [
                855560001,
                855570001
            ],
            "type": "p25",
            "modulation": "qpsk",
            "shortName": "test1"
        }
    ],
    "controlWarnRate": -1
}
rosecitytransit commented 1 year ago

I put a copy here: http://www.rosecitytransit.org/files/config.json

Note that I don't think I've had the issue since I went and removed all the other frequencies for the system it was happening on. I may try to do some troubleshooting myself, or close this issue for now and reopen it if I see it happen again.

tadscottsmith commented 3 months ago

You have a control channel for Pete's Mountain (770.093750) listed in your config for Mount Scott. If trunk-recorder tunes to that control channel it's going to automatically add the alternate CCs that are being broadcast for Pete's Mountain.

rosecitytransit commented 3 months ago

Don't think I'd get Pete's Mountain from where I'm located, and don't think that there should be any shared frequencies with the Oregon State Radio Project system, but that's a good catch. I know the DB doesn't have all the frequencies listed for Mt Scott.

As I said in the other issue, I could test a more current version and see if the issue still exists.