search

robotastic / trunk-recorder

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

Removing call with stuck recorder #544

Open switchport0 opened 2 years ago

switchport0 commented 2 years ago

After moving from v3.37 to v4.0.3, I'm seeing errors like this in the log:

[2021-11-04 01:55:33.130626] (info)   [svrcs2]  92C TG:       2801  Freq: 770.556250 MHz    Starting P25 Recorder Num [0]   TDMA: true  Slot: 0 QPSK: true
[2021-11-04 01:55:33.130733] (error)   [svrcs2] 92C TG:       2801  Freq: 770.556250 MHz    Starting wavfile sink
[2021-11-04 01:55:33.485305] (info)   [svrcs2]  92C TG:       2801  Freq: 770.556250 MHz    Starting new Transmission   Src ID:  13330015
[2021-11-04 01:55:37.378161] (info)   [svrcs2]  92C TG:       2801  Freq: 770.556250 MHz    Starting new Transmission   Src ID:  13330015
[2021-11-04 01:55:40.010322] (trace)   [svrcs2] 92C TG:       2801  Freq: 770.556250 MHz    Stopping Recorded Call, setting call state to INACTIVE - Last Update: 4s
[2021-11-04 01:55:48.008579] (error)   [svrcs2] 92C  Rec Num: 0 TG:       2801  Freq: 770.556250 MHz Removing call with stuck recorder
[2021-11-04 01:55:48.008639] (trace)   [svrcs2] 92C TG:       2801  Freq: 770.556250 MHz    Concluding Recorded Call - Last Update: 12s Call Elapsed: 15
[2021-11-04 01:55:48.008790] (info)   [svrcs2]  92C TG:       2801  Freq: 770.556250 MHz    - Transmission src: 13330015 pos: 0 length: 2.68
[2021-11-04 01:55:48.008842] (info)   [svrcs2]  92C TG:       2801  Freq: 770.556250 MHz    - Transmission src: 13330015 pos: 2.68 length: 0.08
[2021-11-04 01:55:48.516577] (info)   [svrcs2]  92C TG:       2801  Freq: 7.70556e+08   OpenMHz Upload Success - file size: 19471

Most calls seem unaffected, but this happens once every few minutes. Config was not changed between v3.3.7 and v4.0.3 runs:

{
    "ver": 2,
    "sources": [{
        "center": 770280250,
        "rate": 2560000,
        "error": -200,
        "gain": 40,
        "digitalRecorders": 9,
        "driver": "osmosdr",
        "device": "rtl=xyz"
    }, {
        "center": 772993750,
        "rate": 2560000,
        "error": -300,
        "gain": 42,
        "digitalRecorders": 0,
        "driver": "osmosdr",
        "device": "rtl=abc"
    }],
    "systems": [{
        "control_channels": [774206250,772081250,771781250],
        "type": "p25",
        "shortName": "svrcs2",
        "talkgroupsFile": "/app/svrcs_talkgroups.csv",
        "apiKey": "<redacted>",
        "recordUnknown": true,
        "unitScript": "unitScript.sh"
    }],
    "uploadServer": "https://api.openmhz.com",
    "captureDir": "/media",
    "frequencyFormat": "mhz",
    "logFile": true
}

Any suggestions on how to debug this further?

robotastic commented 2 years ago

So what is happening here is that the Trunk Control Channel stopped saying that the freq was being used by a talkgroup... but the recorder had recorder something and hadn't received a Termination Packet on the voice channel yet. It is a little weird that the second transmission was only 0.08 seconds long. It probably should have started that second transmission recording. Can you keep an eye on it to see if when it happens, there is just a short transmission at the end? IT could be that I am not processing some P25 messages correctly.

ww7ch commented 2 years ago

I'm seeing the same thing, pops up semi-frequently. Log is below. Appears that not all calls are getting sent to broadcastify because of it. Let me know if there is any more detail I can share.

[2021-12-12 11:15:19.692489] (info)   [psrs-t]  17132C  TG:      40202  Freq: 853.325000 MHz    Starting P25 Recorder Num [20]  TDMA: true      Slot: 1 QPSK: true
[2021-12-12 11:15:20.101837] (info)   [psrs-t]  17132C  TG:      40202  Freq: 853.325000 MHz    Starting new Transmission       Src ID:  45462
[2021-12-12 11:15:23.947843] (info)   [psrs-t]  17132C  TG:      40202  Freq: 853.325000 MHz    Starting new Transmission       Src ID:  45462
[2021-12-12 11:15:26.010138] (trace)   [psrs-t] 17132C  TG:      40202  Freq: 853.325000 MHz    Stopping Recorded Call, setting call state to INACTIVE - Last Update: 4s
[2021-12-12 11:15:34.009239] (error)   [psrs-t] 17132C  Rec Num: 20     TG:      40202  Freq: 853.325000 MHz     Removing call with stuck recorder 
[2021-12-12 11:15:34.009266] (trace)   [psrs-t] 17132C  TG:      40202  Freq: 853.325000 MHz    Concluding Recorded Call - Last Update: 12s     Call Elapsed: 15
[2021-12-12 11:15:34.009340] (info)   [psrs-t]  17132C  TG:      40202  Freq: 853.325000 MHz    - Transmission src: 45462 pos: 0 length: 1.44
[2021-12-12 11:15:34.009367] (info)   [psrs-t]  17132C  TG:      40202  Freq: 853.325000 MHz    - Transmission src: 45462 pos: 1.44 length: 0.08

[2021-12-12 11:15:19.692489] (info)   [psrs-t]  17132C  TG:      40202  Freq: 853.325000 MHz    Starting P25 Recorder Num [20]  TDMA: true      Slot: 1 QPSK: true
[2021-12-12 11:15:20.101837] (info)   [psrs-t]  17132C  TG:      40202  Freq: 853.325000 MHz    Starting new Transmission       Src ID:  45462
[2021-12-12 11:15:23.947843] (info)   [psrs-t]  17132C  TG:      40202  Freq: 853.325000 MHz    Starting new Transmission       Src ID:  45462
[2021-12-12 11:15:26.010138] (trace)   [psrs-t] 17132C  TG:      40202  Freq: 853.325000 MHz    Stopping Recorded Call, setting call state to INACTIVE - Last Update: 4s
[2021-12-12 11:15:34.009239] (error)   [psrs-t] 17132C  Rec Num: 20     TG:      40202  Freq: 853.325000 MHz     Removing call with stuck recorder 
[2021-12-12 11:15:34.009266] (trace)   [psrs-t] 17132C  TG:      40202  Freq: 853.325000 MHz    Concluding Recorded Call - Last Update: 12s     Call Elapsed: 15
[2021-12-12 11:15:34.009340] (info)   [psrs-t]  17132C  TG:      40202  Freq: 853.325000 MHz    - Transmission src: 45462 pos: 0 length: 1.44
[2021-12-12 11:15:34.009367] (info)   [psrs-t]  17132C  TG:      40202  Freq: 853.325000 MHz    - Transmission src: 45462 pos: 1.44 length: 0.08

[2021-12-12 11:18:25.274770] (info)   [psrs-t]  17195C  TG:      40202  Freq: 855.687500 MHz    Starting P25 Recorder Num [22]  TDMA: true      Slot: 1 QPSK: true
[2021-12-12 11:18:25.610270] (info)   [psrs-t]  17195C  TG:      40202  Freq: 855.687500 MHz    Starting new Transmission       Src ID:  45462
[2021-12-12 11:18:30.995639] (info)   [psrs-t]  17195C  TG:      40202  Freq: 855.687500 MHz    Starting new Transmission       Src ID:  45462
[2021-12-12 11:18:32.008867] (trace)   [psrs-t] 17195C  TG:      40202  Freq: 855.687500 MHz    Stopping Recorded Call, setting call state to INACTIVE - Last Update: 4s
[2021-12-12 11:18:41.008045] (error)   [psrs-t] 17195C  Rec Num: 22     TG:      40202  Freq: 855.687500 MHz     Removing call with stuck recorder 
[2021-12-12 11:18:41.008210] (trace)   [psrs-t] 17195C  TG:      40202  Freq: 855.687500 MHz    Concluding Recorded Call - Last Update: 13s     Call Elapsed: 16
[2021-12-12 11:18:41.008427] (info)   [psrs-t]  17195C  TG:      40202  Freq: 855.687500 MHz    - Transmission src: 45462 pos: 0 length: 1.68
[2021-12-12 11:18:41.008493] (info)   [psrs-t]  17195C  TG:      40202  Freq: 855.687500 MHz    - Transmission src: 45462 pos: 1.68 length: 0.04

[2021-12-12 11:19:27.438545] (info)   [psrs-p]  17213C  TG:      40230  Freq: 771.306250 MHz    Starting P25 Recorder Num [4]   TDMA: true      Slot: 1 QPSK: true
[2021-12-12 11:19:28.990492] (info)   [psrs-p]  17213C  TG:      40230  Freq: 771.306250 MHz    Starting new Transmission       Src ID:  -1
[2021-12-12 11:19:32.009605] (trace)   [psrs-p] 17213C  TG:      40230  Freq: 771.306250 MHz    Stopping Recorded Call, setting call state to INACTIVE - Last Update: 4s
[2021-12-12 11:19:40.015866] (error)   [psrs-p] 17213C  Rec Num: 4      TG:      40230  Freq: 771.306250 MHz     Removing call with stuck recorder 
[2021-12-12 11:19:40.015917] (trace)   [psrs-p] 17213C  TG:      40230  Freq: 771.306250 MHz    Concluding Recorded Call - Last Update: 12s     Call Elapsed: 13
[2021-12-12 11:19:40.016014] (info)   [psrs-p]  17213C  TG:      40230  Freq: 771.306250 MHz    - Transmission src: -1 pos: 0 length: 0.12
[2021-12-12 11:19:40.016049] (error)   [psrs-p] 17213C  TG:      40230   Freq: 7.71306e+08       Call length: 0.12 is less than min duration: 1

[2021-12-12 11:19:53.331620] (info)   [ss911-s] 17226C  TG:      40305  Freq: 771.131250 MHz    Starting P25 Recorder Num [0]   TDMA: true      Slot: 0 QPSK: true
[2021-12-12 11:19:53.683633] (info)   [ss911-s] 17226C  TG:      40305  Freq: 771.131250 MHz    Starting new Transmission       Src ID:  0
[2021-12-12 11:20:09.014157] (info)   [ss911-s] 17226C TG:      40305 Freq: 771.131250 MHz Elapsed: 16 State: recording
[2021-12-12 11:20:21.901969] (info)   [ss911-s] 17226C  TG:      40305  Freq: 771.131250 MHz    Starting new Transmission       Src ID:  0
[2021-12-12 11:20:25.015480] (trace)   [ss911-s]        17226C  TG:      40305  Freq: 771.131250 MHz    Stopping Recorded Call, setting call state to INACTIVE - Last Update: 4s
[2021-12-12 11:20:32.006801] (error)   [ss911-s]        17226C  Rec Num: 0      TG:      40305  Freq: 771.131250 MHz     Removing call with stuck recorder 
[2021-12-12 11:20:32.006849] (trace)   [ss911-s]        17226C  TG:      40305  Freq: 771.131250 MHz    Concluding Recorded Call - Last Update: 11s     Call Elapsed: 39
[2021-12-12 11:20:32.006969] (info)   [ss911-s] 17226C  TG:      40305  Freq: 771.131250 MHz    - Transmission src: 0 pos: 0 length: 26.72
[2021-12-12 11:20:32.007003] (info)   [ss911-s] 17226C  TG:      40305  Freq: 771.131250 MHz    - Transmission src: 0 pos: 26.72 length: 0.04