robotastic / trunk-recorder

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

Audio Duplication through Rdio-Scanner OpenMHZ #616

Open Nokoa opened 2 years ago

Nokoa commented 2 years ago

I seem to be having an issue, which from what I noticed on OpenMHZ others are perhaps also experiencing.

The issue I am having is with file uploading to Rdio-Scanner using upload script, or directory watching.

On a regular basis a full transmission is uploaded, and then parts of the same transmissions are also uploaded again. The partial recordings may start in the middle and go through to the end. This can happen multiple times for the same transmission. An attached example was taken from a Feed from OpenMHZ. recordings.zip

UberPlexCa commented 2 years ago

I suspect your seeing the same thing https://github.com/robotastic/trunk-recorder/issues/535

I was able to reduce mine a lot by changing the call timeout to 4 seconds but still get them when the system is busy.

robotastic commented 2 years ago

Can you give the overlap branch a try? It should help cut down on this.

Nokoa commented 2 years ago

Switched over to this branch, will report back, thank you.

Nokoa commented 2 years ago

Still observing duplications, but much less I believe. The picture below shows the waveform of 2 recording files. The top file contains the full series of transmissions all for the same talkgroup ID. The bottom file contains the same recording from the one above but starts 1/4 of the way through in the middle of a sentence. Capture

robotastic commented 2 years ago

@Nokoa If you are able to capture the output from Trunk Recorder the next time you see this, that would be really helpful. It would be good to have all the output covering when the calls start to when they end.

Nokoa commented 2 years ago

Here are parts of the logs for duplicated transmission. One file contains the full transmission while the other contains only a part from middle to end. Just note that the issue I am describing here is different than this one #321

[2022-02-07 10:07:24.091309] (info) [islps-74] 105404C TG:  4051 Freq: 8.677000e+08 TG not in Talkgroup File [2022-02-07 10:07:24.091388] (info) [islps-74] 105404C TG:  4051 Freq: 8.677000e+08 Starting P25 Recorder Num [0] TDMA: true Slot: 1 QPSK: true [2022-02-07 10:07:24.464924] (info) [islps-74] 105404C TG:  4051 Freq: 8.677000e+08 Starting new Transmission Src ID: -1 [2022-02-07 10:07:28.005370] (trace) [islps-74] 105404C TG:  4051 Freq: 8.677000e+08 Stopping Recorded Call, setting call state to INACTIVE - Last Update: 4s [2022-02-07 10:07:28.852888] (info) [islps-74] 105405C TG:  4051 Freq: 8.677000e+08 TG not in Talkgroup File [2022-02-07 10:07:28.852980] (info) [islps-74] 105405C TG:  4051 Freq: 8.677000e+08 Starting P25 Recorder Num [1] TDMA: true Slot: 1 QPSK: true [2022-02-07 10:07:29.872283] (info) - Stopping call because of overlapping Freq [2022-02-07 10:07:29.872366] (trace) [islps-74] 105405C TG:  4051 Freq: 8.677000e+08 Stopping Recorded Call, setting call state to COMPLETED - Last Update: 1s [2022-02-07 10:07:29.872410] (info) [islps-74] 105406C TG:  919 Freq: 8.677000e+08 TG not in Talkgroup File [2022-02-07 10:07:29.872446] (info) [islps-74] 105406C TG:  919 Freq: 8.677000e+08 Starting P25 Recorder Num [4] TDMA: true Slot: 1 QPSK: true [2022-02-07 10:07:30.003811] (trace) [islps-74] 105403C TG:  4051 Freq: 8.677000e+08 Concluding Recorded Call - Last Update: 12s Call Elapsed: 18 [2022-02-07 10:07:30.003908] (info) [islps-74] 105403C TG:  4051 Freq: 8.677000e+08 - Transmission src: 3190008 pos: 0 length: 16.24 [2022-02-07 10:07:30.003992] (trace) [islps-74] 105404C TG:  4051 Freq: 8.677000e+08 Concluding Recorded Call - Last Update: 6s Call Elapsed: 6 [2022-02-07 10:07:30.004043] (info) [islps-74] 105404C TG:  4051 Freq: 8.677000e+08 - Transmission src: -1 pos: 0 length: 4.4 [2022-02-07 10:07:30.004099] (trace) [islps-74] 105405C TG:  4051 Freq: 8.677000e+08 Concluding Recorded Call - Last Update: 2s Call Elapsed: 2 [2022-02-07 10:07:30.004137] (error) [islps-74] 105405C TG:  4051 Freq: 8.677e+08 No Transmission were recorded! [2022-02-07 10:07:30.007025] (info) [islps-74] 105404C Running upload script: ./upload-call.sh 1 /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/4051-1644257244_867700000-call_105404.wav /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/4051-1644257244_867700000-call_105404.json /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/4051-1644257244_867700000-call_105404.m4a [2022-02-07 10:07:30.007592] (info) [islps-74] 105403C Running upload script: ./upload-call.sh 1 /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/4051-1644257232_867700000-call_105403.wav /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/4051-1644257232_867700000-call_105403.json /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/4051-1644257232_867700000-call_105403.m4a

robotastic commented 2 years ago

[2022-02-07 10:07:24.091309] (info) [islps-74]  105404C  TG:   4051  Freq: 8.677000e+08 TG not in Talkgroup File 
[2022-02-07 10:07:24.091388] (info) [islps-74]  105404C  TG:   4051  Freq: 8.677000e+08  Starting P25 Recorder Num [0]  TDMA: true Slot: 1 QPSK: true 
[2022-02-07 10:07:24.464924] (info) [islps-74]  105404C  TG:   4051  Freq: 8.677000e+08 Starting new Transmission Src ID: -1 
[2022-02-07 10:07:28.005370] (trace) [islps-74]  105404C  TG:   4051  Freq: 8.677000e+08 Stopping Recorded Call, setting call state to INACTIVE - Last Update: 4s 
[2022-02-07 10:07:28.852888] (info) [islps-74]  105405C  TG:   4051  Freq: 8.677000e+08 TG not in Talkgroup File 
[2022-02-07 10:07:28.852980] (info) [islps-74]  105405C  TG:   4051  Freq: 8.677000e+08  Starting P25 Recorder Num [1]  TDMA: true Slot: 1 QPSK: true 
[2022-02-07 10:07:29.872283] (info) - Stopping call because of overlapping Freq 
[2022-02-07 10:07:29.872366] (trace) [islps-74]  105405C  TG:   4051  Freq: 8.677000e+08 Stopping Recorded Call, setting call state to COMPLETED - Last Update: 1s 
[2022-02-07 10:07:29.872410] (info) [islps-74]  105406C  TG:   919  Freq: 8.677000e+08 TG not in Talkgroup File 
[2022-02-07 10:07:29.872446] (info) [islps-74]  105406C  TG:   919  Freq: 8.677000e+08  Starting P25 Recorder Num [4]  TDMA: true Slot: 1 QPSK: true 
[2022-02-07 10:07:30.003811] (trace) [islps-74]  105403C  TG:   4051  Freq: 8.677000e+08  Concluding Recorded Call  - Last Update: 12s Call Elapsed: 18 
[2022-02-07 10:07:30.003908] (info) [islps-74]  105403C  TG:   4051  Freq: 8.677000e+08 - Transmission src: 3190008 pos: 0 length: 16.24 
[2022-02-07 10:07:30.003992] (trace) [islps-74]  105404C  TG:   4051  Freq: 8.677000e+08  Concluding Recorded Call  - Last Update: 6s Call Elapsed: 6 
[2022-02-07 10:07:30.004043] (info) [islps-74]  105404C  TG:   4051  Freq: 8.677000e+08 - Transmission src: -1 pos: 0 length: 4.4 
[2022-02-07 10:07:30.004099] (trace) [islps-74]  105405C  TG:   4051  Freq: 8.677000e+08  Concluding Recorded Call  - Last Update: 2s Call Elapsed: 2 
[2022-02-07 10:07:30.004137] (error) [islps-74]  105405C  TG:   4051  Freq: 8.677e+08 No Transmission were recorded! 
[2022-02-07 10:07:30.007025] (info) [islps-74]  105404C  Running upload script: ./upload-call.sh 1 /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/4051-1644257244_867700000-call_105404.wav /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/4051-1644257244_867700000-call_105404.json /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/4051-1644257244_867700000-call_105404.m4a \n
[2022-02-07 10:07:30.007592] (info) [islps-74]  105403C  Running upload script: ./upload-call.sh 1 /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/4051-1644257232_867700000-call_105403.wav /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/4051-1644257232_867700000-call_105403.json /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/4051-1644257232_867700000-call_105403.m4a

Awesome- Thanks, I added in some formatting. I will see if I can spot anything

robotastic commented 2 years ago

@Nokoa It looks like there are actually 3 calls in this section. Do you know which calls it was? It looks like there is 105403C , 105404C , 105405C

The interesting thing is that they are all the same TG on the same Freq.... I will go dig into that scenario

Nokoa commented 2 years ago

I will get you some more logs that may have more information.

TG 4051 in this instance was duplicated partially as described before. It looks like in the logs I had 4051 and 919 both active on the same frequency in different TDMA slots. Could it be that 919 starting in the middle of the transmission of 4051 in the other slot started a new recorder for 919 and then again for 4051. Maybe that's why the duplicated transmission doesn't start at the beginning, but still ends at the end? But then I am not sure why 4051 had 2 recorders started before 919 began.

Nokoa commented 2 years ago

Here is another instance, here TG 4087 is duplicated. One recording is the full recording. The second one starts a little bit after the first one and goes on until its end.

[2022-02-07 22:24:00.688738] (info) [islps-74] 2816C TG:  1097 Freq: 8.682375e+08 Starting new Transmission Src ID: 2900945 [2022-02-07 22:24:12.243453] (info) [islps-74] 2818C TG:  51397 Freq: 8.685250e+08 TG not in Talkgroup File [2022-02-07 22:24:12.243587] (info) [islps-74] 2818C TG:  51397 Freq: 8.685250e+08 Starting P25 Recorder Num [1] TDMA: true Slot: 1 QPSK: true [2022-02-07 22:24:12.855116] (info) [islps-74] 2818C TG:  51397 Freq: 8.685250e+08 Starting new Transmission Src ID: 6922592 [2022-02-07 22:24:15.696425] (info) [islps-74] 2818C TG:  51397 Freq: 8.685250e+08 Starting new Transmission Src ID: 6922592 [2022-02-07 22:24:19.013459] (trace) [islps-74] 2816C TG:  1097 Freq: 8.682375e+08 Stopping Recorded Call, setting call state to INACTIVE - Last Update: 4s [2022-02-07 22:24:19.013573] (trace) [islps-74] 2818C TG:  51397 Freq: 8.685250e+08 Stopping Recorded Call, setting call state to INACTIVE - Last Update: 4s [2022-02-07 22:24:20.799516] (info) [islps-74] 2819C TG:  917 Freq: 8.679625e+08 TG not in Talkgroup File [2022-02-07 22:24:20.799607] (info) [islps-74] 2819C TG:  917 Freq: 8.679625e+08 Starting P25 Recorder Num [3] TDMA: true Slot: 1 QPSK: true [2022-02-07 22:24:21.265375] (info) [islps-74] 2819C TG:  917 Freq: 8.679625e+08 Starting new Transmission Src ID: 2900451 [2022-02-07 22:24:21.344858] (info) [islps-74] 2820C TG:  1097 Freq: 8.682375e+08 TG not in Talkgroup File [2022-02-07 22:24:21.344970] (info) [islps-74] 2820C TG:  1097 Freq: 8.682375e+08 Starting P25 Recorder Num [4] TDMA: true Slot: 0 QPSK: true [2022-02-07 22:24:21.602840] (info) [islps-74] 2820C TG:  1097 Freq: 8.682375e+08 Starting new Transmission Src ID: -1 [2022-02-07 22:24:26.016494] (info) Recorder state: 1 [2022-02-07 22:24:26.016623] (error) [islps-74] 2818C Rec Num: 1 TG:  51397 Freq: 8.685250e+08  Removing call with stuck recorder  [2022-02-07 22:24:26.016702] (trace) [islps-74] 2818C TG:  51397 Freq: 8.685250e+08 Concluding Recorded Call - Last Update: 11s Call Elapsed: 14 [2022-02-07 22:24:26.016860] (error) stop_recording() - stopping wavfile sink but recorder state is: 1 [2022-02-07 22:24:26.016927] (info) [islps-74] 2818C TG:  51397 Freq: 8.685250e+08 - Transmission src: 6922592 pos: 0 length: 0.16 [2022-02-07 22:24:26.017006] (info) [islps-74] 2818C TG:  51397 Freq: 8.685250e+08 - Transmission src: 6922592 pos: 0.16 length: 0.08 [2022-02-07 22:24:26.020456] (info) [islps-74] 2818C Running upload script: ./upload-call.sh 1 /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/51397-1644301452_868525000-call_2818.wav /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/51397-1644301452_868525000-call_2818.json /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/51397-1644301452_868525000-call_2818.m4a [2022-02-07 22:24:27.015512] (trace) [islps-74] 2819C TG:  917 Freq: 8.679625e+08 Stopping Recorded Call, setting call state to COMPLETED - Last Update: 4s [2022-02-07 22:24:27.015610] (trace) [islps-74] 2819C TG:  917 Freq: 8.679625e+08 Concluding Recorded Call - Last Update: 4s Call Elapsed: 7 [2022-02-07 22:24:27.015649] (info) [islps-74] 2819C TG:  917 Freq: 8.679625e+08 - Transmission src: 2900451 pos: 0 length: 0.16 [2022-02-07 22:24:27.015721] (trace) [islps-74] 2820C TG:  1097 Freq: 8.682375e+08 Stopping Recorded Call, setting call state to INACTIVE - Last Update: 4s [2022-02-07 22:24:27.018741] (info) [islps-74] 2819C Running upload script: ./upload-call.sh 1 /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/917-1644301461_867962500-call_2819.wav /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/917-1644301461_867962500-call_2819.json /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/917-1644301461_867962500-call_2819.m4a [2022-02-07 22:24:28.397873] (info) [islps-74] 2821C TG:  1097 Freq: 8.682375e+08 TG not in Talkgroup File [2022-02-07 22:24:28.397957] (info) [islps-74] 2821C TG:  1097 Freq: 8.682375e+08 Starting P25 Recorder Num [1] TDMA: true Slot: 0 QPSK: true [2022-02-07 22:24:28.673655] (info) [islps-74] 2821C TG:  1097 Freq: 8.682375e+08 Starting new Transmission Src ID: 3190012 [2022-02-07 22:24:32.010575] (trace) [islps-74] 2817C TG:  11149 Freq: 8.682375e+08 Stopping Recorded Call, setting call state to COMPLETED - Last Update: 4s [2022-02-07 22:24:32.010670] (trace) [islps-74] 2817C TG:  11149 Freq: 8.682375e+08 Concluding Recorded Call - Last Update: 4s Call Elapsed: 35 [2022-02-07 22:24:32.010741] (info) [islps-74] 2817C TG:  11149 Freq: 8.682375e+08 - Transmission src: 2002157 pos: 0 length: 18.96 [2022-02-07 22:24:32.015008] (info) [islps-74] 2817C Running upload script: ./upload-call.sh 1 /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/11149-1644301437_868237500-call_2817.wav /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/11149-1644301437_868237500-call_2817.json /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/11149-1644301437_868237500-call_2817.m4a [2022-02-07 22:24:37.983677] (info) [islps-74] 2822C TG:  917 Freq: 8.682375e+08 TG not in Talkgroup File [2022-02-07 22:24:37.983897] (info) [islps-74] 2822C TG:  917 Freq: 8.682375e+08 Starting P25 Recorder Num [2] TDMA: true Slot: 1 QPSK: true [2022-02-07 22:24:38.446090] (info) [islps-74] 2822C TG:  917 Freq: 8.682375e+08 Starting new Transmission Src ID: 2900407 [2022-02-07 22:24:39.598752] (info) [islps-74] 2823C TG:  11149 Freq: 8.677000e+08 TG not in Talkgroup File [2022-02-07 22:24:39.598842] (info) [islps-74] 2823C TG:  11149 Freq: 8.677000e+08 Starting P25 Recorder Num [3] TDMA: true Slot: 0 QPSK: true [2022-02-07 22:24:39.659545] (info) [islps-74] 2824C TG:  4087 Freq: 8.677000e+08 TG not in Talkgroup File [2022-02-07 22:24:39.659649] (info) [islps-74] 2824C TG:  4087 Freq: 8.677000e+08 Starting P25 Recorder Num [5] TDMA: true Slot: 1 QPSK: true [2022-02-07 22:24:39.989749] (info) [islps-74] 2823C TG:  11149 Freq: 8.677000e+08 Starting new Transmission Src ID: 3100004 [2022-02-07 22:24:40.063620] (info) [islps-74] 2824C TG:  4087 Freq: 8.677000e+08 Starting new Transmission Src ID: 3120006 [2022-02-07 22:24:43.008846] (trace) [islps-74] 2824C TG:  4087 Freq: 8.677000e+08 Stopping Recorded Call, setting call state to INACTIVE - Last Update: 4s [2022-02-07 22:24:43.997532] (info) [islps-74] 2825C TG:  4087 Freq: 8.677000e+08 TG not in Talkgroup File [2022-02-07 22:24:43.997670] (info) [islps-74] 2825C TG:  4087 Freq: 8.677000e+08 Starting P25 Recorder Num [6] TDMA: true Slot: 1 QPSK: true [2022-02-07 22:24:44.424089] (info) [islps-74] 2825C TG:  4087 Freq: 8.677000e+08 Starting new Transmission Src ID: -1 [2022-02-07 22:24:46.015313] (trace) [islps-74] 2816C TG:  1097 Freq: 8.682375e+08 Concluding Recorded Call - Last Update: 31s Call Elapsed: 54 [2022-02-07 22:24:46.015593] (info) [islps-74] 2816C TG:  1097 Freq: 8.682375e+08 - Transmission src: 2900945 pos: 0 length: 3.72 [2022-02-07 22:24:46.015689] (info) [islps-74] 2816C TG:  1097 Freq: 8.682375e+08 - Transmission src: 2900945 pos: 3.72 length: 29.56 [2022-02-07 22:24:46.015814] (trace) [islps-74] 2820C TG:  1097 Freq: 8.682375e+08 Concluding Recorded Call - Last Update: 23s Call Elapsed: 25 [2022-02-07 22:24:46.015905] (info) [islps-74] 2820C TG:  1097 Freq: 8.682375e+08 - Transmission src: -1 pos: 0 length: 14.12 [2022-02-07 22:24:46.019601] (info) [islps-74] 2820C Running upload script: ./upload-call.sh 1 /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/1097-1644301461_868237500-call_2820.wav /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/1097-1644301461_868237500-call_2820.json /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/1097-1644301461_868237500-call_2820.m4a [2022-02-07 22:24:46.020372] (info) [islps-74] 2816C Running upload script: ./upload-call.sh 1 /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/1097-1644301432_868237500-call_2816.wav /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/1097-1644301432_868237500-call_2816.json /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/1097-1644301432_868237500-call_2816.m4a [2022-02-07 22:24:47.014011] (trace) [islps-74] 2823C TG:  11149 Freq: 8.677000e+08 Stopping Recorded Call, setting call state to COMPLETED - Last Update: 4s [2022-02-07 22:24:47.014134] (trace) [islps-74] 2823C TG:  11149 Freq: 8.677000e+08 Concluding Recorded Call - Last Update: 4s Call Elapsed: 8 [2022-02-07 22:24:47.014194] (info) [islps-74] 2823C TG:  11149 Freq: 8.677000e+08 - Transmission src: 3100004 pos: 0 length: 1.6 [2022-02-07 22:24:47.017222] (info) [islps-74] 2823C Running upload script: ./upload-call.sh 1 /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/11149-1644301479_867700000-call_2823.wav /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/11149-1644301479_867700000-call_2823.json /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/11149-1644301479_867700000-call_2823.m4a [2022-02-07 22:24:48.012421] (trace) [islps-74] 2821C TG:  1097 Freq: 8.682375e+08 Stopping Recorded Call, setting call state to COMPLETED - Last Update: 4s [2022-02-07 22:24:48.012511] (trace) [islps-74] 2821C TG:  1097 Freq: 8.682375e+08 Concluding Recorded Call - Last Update: 4s Call Elapsed: 20 [2022-02-07 22:24:48.012547] (info) [islps-74] 2821C TG:  1097 Freq: 8.682375e+08 - Transmission src: 3190012 pos: 0 length: 9.36 [2022-02-07 22:24:48.014986] (info) [islps-74] 2821C Running upload script: ./upload-call.sh 1 /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/1097-1644301468_868237500-call_2821.wav /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/1097-1644301468_868237500-call_2821.json /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/1097-1644301468_868237500-call_2821.m4a [2022-02-07 22:24:48.163861] (info) [islps-74] 2826C TG:  11149 Freq: 8.677000e+08 TG not in Talkgroup File [2022-02-07 22:24:48.163967] (info) [islps-74] 2826C TG:  11149 Freq: 8.677000e+08 Starting P25 Recorder Num [0] TDMA: true Slot: 0 QPSK: true [2022-02-07 22:24:48.264127] (info) [islps-74] 2826C TG:  11149 Freq: 8.677000e+08 Starting new Transmission Src ID: 2001250 [2022-02-07 22:24:50.009487] (trace) [islps-74] 2822C TG:  917 Freq: 8.682375e+08 Stopping Recorded Call, setting call state to COMPLETED - Last Update: 4s [2022-02-07 22:24:50.009659] (trace) [islps-74] 2822C TG:  917 Freq: 8.682375e+08 Concluding Recorded Call - Last Update: 4s Call Elapsed: 13 [2022-02-07 22:24:50.009986] (info) [islps-74] 2822C TG:  917 Freq: 8.682375e+08 - Transmission src: 2900407 pos: 0 length: 3.44 [2022-02-07 22:24:50.013670] (info) [islps-74] 2822C Running upload script: ./upload-call.sh 1 /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/917-1644301478_868237500-call_2822.wav /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/917-1644301478_868237500-call_2822.json /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/917-1644301478_868237500-call_2822.m4a [2022-02-07 22:24:52.007089] (trace) [islps-74] 2826C TG:  11149 Freq: 8.677000e+08 Stopping Recorded Call, setting call state to INACTIVE - Last Update: 4s [2022-02-07 22:24:53.015761] (trace) [islps-74] 2826C TG:  11149 Freq: 8.677000e+08 Concluding Recorded Call - Last Update: 5s Call Elapsed: 5 [2022-02-07 22:24:53.015885] (info) [islps-74] 2826C TG:  11149 Freq: 8.677000e+08 - Transmission src: 2001250 pos: 0 length: 1.76 [2022-02-07 22:24:53.019172] (info) [islps-74] 2826C Running upload script: ./upload-call.sh 1 /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/11149-1644301488_867700000-call_2826.wav /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/11149-1644301488_867700000-call_2826.json /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/11149-1644301488_867700000-call_2826.m4a [2022-02-07 22:24:55.204302] (info) [islps-74] 2827C TG:  11149 Freq: 8.677000e+08 TG not in Talkgroup File [2022-02-07 22:24:55.204417] (info) [islps-74] 2827C TG:  11149 Freq: 8.677000e+08 Starting P25 Recorder Num [0] TDMA: true Slot: 0 QPSK: true [2022-02-07 22:24:55.598144] (info) [islps-74] 2827C TG:  11149 Freq: 8.677000e+08 Starting new Transmission Src ID: 2001250 [2022-02-07 22:24:59.542998] (info) [islps-74] 2828C TG:  1097 Freq: 8.685250e+08 TG not in Talkgroup File [2022-02-07 22:24:59.543096] (info) [islps-74] 2828C TG:  1097 Freq: 8.685250e+08 Starting P25 Recorder Num [1] TDMA: true Slot: 0 QPSK: true [2022-02-07 22:24:59.967578] (info) [islps-74] 2828C TG:  1097 Freq: 8.685250e+08 Starting new Transmission Src ID: 2900815 [2022-02-07 22:25:12.013245] (info) Currently Active Calls: 4 [2022-02-07 22:25:12.013364] (info) [islps-74] 2824C TG:  4087 Freq: 8.677000e+08 Elapsed: 33 State: inactive [2022-02-07 22:25:12.013429] (info) [ 5 ] State: recording [2022-02-07 22:25:12.013482] (info) [islps-74] 2825C TG:  4087 Freq: 8.677000e+08 Elapsed: 29 State: recording [2022-02-07 22:25:12.013530] (info) [ 6 ] State: recording [2022-02-07 22:25:12.013556] (info) [islps-74] 2827C TG:  11149 Freq: 8.677000e+08 Elapsed: 17 State: recording [2022-02-07 22:25:12.013582] (info) [ 0 ] State: recording [2022-02-07 22:25:12.013599] (info) [islps-74] 2828C TG:  1097 Freq: 8.685250e+08 Elapsed: 13 State: recording [2022-02-07 22:25:12.013634] (info) [ 1 ] State: recording [2022-02-07 22:25:12.013651] (info) Recorders: [2022-02-07 22:25:12.013693] (info) [ airspy=260868c8:267c4f9b ] [2022-02-07 22:25:12.013751] (info) [ D0 ] State: recording [2022-02-07 22:25:12.013775] (info) [ D1 ] State: recording [2022-02-07 22:25:12.013792] (info) [ D2 ] State: available [2022-02-07 22:25:12.013809] (info) [ D3 ] State: available [2022-02-07 22:25:12.013825] (info) [ D4 ] State: available [2022-02-07 22:25:12.013842] (info) [ D5 ] State: recording [2022-02-07 22:25:12.013858] (info) [ D6 ] State: recording [2022-02-07 22:25:12.013874] (info) [ D7 ] State: available [2022-02-07 22:25:12.013890] (info) [ D8 ] State: available [2022-02-07 22:25:12.013935] (info) [ D9 ] State: available [2022-02-07 22:25:12.013962] (info) [ D10 ] State: available [2022-02-07 22:25:12.013980] (info) [ D11 ] State: available [2022-02-07 22:25:20.013000] (trace) [islps-74] 2824C TG:  4087 Freq: 8.677000e+08 Concluding Recorded Call - Last Update: 41s Call Elapsed: 41 [2022-02-07 22:25:20.013117] (info) [islps-74] 2824C TG:  4087 Freq: 8.677000e+08 - Transmission src: 3120006 pos: 0 length: 39.04 [2022-02-07 22:25:20.022159] (info) [islps-74] 2824C Running upload script: ./upload-call.sh 1 /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/4087-1644301480_867700000-call_2824.wav /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/4087-1644301480_867700000-call_2824.json /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/4087-1644301480_867700000-call_2824.m4a [2022-02-07 22:25:22.080784] (info) [islps-74] 2829C TG:  51395 Freq: 8.685250e+08 TG not in Talkgroup File [2022-02-07 22:25:22.080895] (info) [islps-74] 2829C TG:  51395 Freq: 8.685250e+08 Starting P25 Recorder Num [2] TDMA: true Slot: 1 QPSK: true [2022-02-07 22:25:22.488759] (info) [islps-74] 2829C TG:  51395 Freq: 8.685250e+08 Starting new Transmission Src ID: 6942112 [2022-02-07 22:25:23.009265] (trace) [islps-74] 2825C TG:  4087 Freq: 8.677000e+08 Stopping Recorded Call, setting call state to COMPLETED - Last Update: 4s [2022-02-07 22:25:23.009370] (trace) [islps-74] 2825C TG:  4087 Freq: 8.677000e+08 Concluding Recorded Call - Last Update: 4s Call Elapsed: 40 [2022-02-07 22:25:23.009424] (info) [islps-74] 2825C TG:  4087 Freq: 8.677000e+08 - Transmission src: -1 pos: 0 length: 34.72 [2022-02-07 22:25:23.013505] (info) [islps-74] 2825C Running upload script: ./upload-call.sh 1 /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/4087-1644301484_867700000-call_2825.wav /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/4087-1644301484_867700000-call_2825.json /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/4087-1644301484_867700000-call_2825.m4a [2022-02-07 22:25:25.359705] (info) [islps-74] 2827C TG:  11149 Freq: 8.677000e+08 Starting new Transmission Src ID: 2001250 [2022-02-07 22:25:28.013050] (trace) [islps-74] 2827C TG:  11149 Freq: 8.677000e+08 Stopping Recorded Call, setting call state to INACTIVE - Last Update: 4s [2022-02-07 22:25:28.013155] (trace) [islps-74] 2828C TG:  1097 Freq: 8.685250e+08 Stopping Recorded Call, setting call state to INACTIVE - Last Update: 4s [2022-02-07 22:25:28.043508] (info) [islps-74] 2830C TG:  1097 Freq: 8.685250e+08 TG not in Talkgroup File [2022-02-07 22:25:28.043651] (info) [islps-74] 2830C TG:  1097 Freq: 8.685250e+08 Starting P25 Recorder Num [3] TDMA: true Slot: 0 QPSK: true [2022-02-07 22:25:28.350781] (info) [islps-74] 2830C TG:  1097 Freq: 8.685250e+08 Starting new Transmission Src ID: -1 [2022-02-07 22:25:31.010099] (trace) [islps-74] 2829C TG:  51395 Freq: 8.685250e+08 Stopping Recorded Call, setting call state to COMPLETED - Last Update: 4s [2022-02-07 22:25:31.010212] (trace) [islps-74] 2829C TG:  51395 Freq: 8.685250e+08 Concluding Recorded Call - Last Update: 4s Call Elapsed: 9 [2022-02-07 22:25:31.010259] (info) [islps-74] 2829C TG:  51395 Freq: 8.685250e+08 - Transmission src: 6942112 pos: 0 length: 3.04 [2022-02-07 22:25:31.014424] (info) [islps-74] 2829C Running upload script: ./upload-call.sh 1 /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/51395-1644301522_868525000-call_2829.wav /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/51395-1644301522_868525000-call_2829.json /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/51395-1644301522_868525000-call_2829.m4a [2022-02-07 22:25:31.594952] (info) [islps-74] 2831C TG:  917 Freq: 8.685250e+08 TG not in Talkgroup File [2022-02-07 22:25:31.595056] (info) [islps-74] 2831C TG:  917 Freq: 8.685250e+08 Starting P25 Recorder Num [2] TDMA: true Slot: 1 QPSK: true [2022-02-07 22:25:32.056917] (info) [islps-74] 2831C TG:  917 Freq: 8.685250e+08 Starting new Transmission Src ID: 2900432 [2022-02-07 22:25:36.013361] (info) Recorder state: 1 [2022-02-07 22:25:36.013478] (error) [islps-74] 2827C Rec Num: 0 TG:  11149 Freq: 8.677000e+08  Removing call with stuck recorder  [2022-02-07 22:25:36.013533] (trace) [islps-74] 2827C TG:  11149 Freq: 8.677000e+08 Concluding Recorded Call - Last Update: 12s Call Elapsed: 41 [2022-02-07 22:25:36.013619] (error) stop_recording() - stopping wavfile sink but recorder state is: 1 [2022-02-07 22:25:36.013659] (info) [islps-74] 2827C TG:  11149 Freq: 8.677000e+08 - Transmission src: 2001250 pos: 0 length: 23.48 [2022-02-07 22:25:36.013706] (info) [islps-74] 2827C TG:  11149 Freq: 8.677000e+08 - Transmission src: 2001250 pos: 23.48 length: 0.04 [2022-02-07 22:25:36.013791] (trace) [islps-74] 2828C TG:  1097 Freq: 8.685250e+08 Concluding Recorded Call - Last Update: 12s Call Elapsed: 37 [2022-02-07 22:25:36.013842] (info) [islps-74] 2828C TG:  1097 Freq: 8.685250e+08 - Transmission src: 2900815 pos: 0 length: 28.44 [2022-02-07 22:25:36.018867] (info) [islps-74] 2827C Running upload script: ./upload-call.sh 1 /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/11149-1644301495_867700000-call_2827.wav /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/11149-1644301495_867700000-call_2827.json /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/11149-1644301495_867700000-call_2827.m4a [2022-02-07 22:25:36.019152] (info) [islps-74] 2828C Running upload script: ./upload-call.sh 1 /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/1097-1644301499_868525000-call_2828.wav /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/1097-1644301499_868525000-call_2828.json /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/1097-1644301499_868525000-call_2828.m4a [2022-02-07 22:25:36.445795] (info) [islps-74] 2830C TG:  1097 Freq: 8.685250e+08 Starting new Transmission Src ID: -1 [2022-02-07 22:25:40.008021] (trace) [islps-74] 2831C TG:  917 Freq: 8.685250e+08 Stopping Recorded Call, setting call state to COMPLETED - Last Update: 4s [2022-02-07 22:25:40.008142] (trace) [islps-74] 2831C TG:  917 Freq: 8.685250e+08 Concluding Recorded Call - Last Update: 4s Call Elapsed: 9 [2022-02-07 22:25:40.008213] (info) [islps-74] 2831C TG:  917 Freq: 8.685250e+08 - Transmission src: 2900432 pos: 0 length: 1.52 [2022-02-07 22:25:40.011852] (info) [islps-74] 2831C Running upload script: ./upload-call.sh 1 /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/917-1644301532_868525000-call_2831.wav /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/917-1644301532_868525000-call_2831.json /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/917-1644301532_868525000-call_2831.m4a [2022-02-07 22:25:47.384098] (info) [islps-74] 2832C TG:  1097 Freq: 8.679625e+08 TG not in Talkgroup File [2022-02-07 22:25:47.384197] (info) [islps-74] 2832C TG:  1097 Freq: 8.679625e+08 Starting P25 Recorder Num [0] TDMA: true Slot: 0 QPSK: true [2022-02-07 22:25:47.762723] (info) [islps-74] 2832C TG:  1097 Freq: 8.679625e+08 Starting new Transmission Src ID: 2900250 [2022-02-07 22:25:50.008605] (trace) [islps-74] 2830C TG:  1097 Freq: 8.685250e+08 Stopping Recorded Call, setting call state to COMPLETED - Last Update: 4s [2022-02-07 22:25:50.009192] (trace) [islps-74] 2830C TG:  1097 Freq: 8.685250e+08 Concluding Recorded Call - Last Update: 4s Call Elapsed: 22 [2022-02-07 22:25:50.009443] (info) [islps-74] 2830C TG:  1097 Freq: 8.685250e+08 - Transmission src: -1 pos: 0 length: 4.96 [2022-02-07 22:25:50.009696] (info) [islps-74] 2830C TG:  1097 Freq: 8.685250e+08 - Transmission src: -1 pos: 4.96 length: 7.52 [2022-02-07 22:25:50.014439] (info) [islps-74] 2830C Running upload script: ./upload-call.sh 1 /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/1097-1644301528_868525000-call_2830.wav /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/1097-1644301528_868525000-call_2830.json /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/1097-1644301528_868525000-call_2830.m4a [2022-02-07 22:25:54.672310] (info) [islps-74] 2833C TG:  51395 Freq: 8.679625e+08 TG not in Talkgroup File [2022-02-07 22:25:54.672632] (info) [islps-74] 2833C TG:  51395 Freq: 8.679625e+08 Starting P25 Recorder Num [1] TDMA: true Slot: 1 QPSK: true [2022-02-07 22:25:55.103751] (info) [islps-74] 2833C TG:  51395 Freq: 8.679625e+08 Starting new Transmission Src ID: 6942112 [2022-02-07 22:26:01.009157] (trace) [islps-74] 2833C TG:  51395 Freq: 8.679625e+08 Stopping Recorded Call, setting call state to COMPLETED - Last Update: 4s [2022-02-07 22:26:01.009282] (trace) [islps-74] 2833C TG:  51395 Freq: 8.679625e+08 Concluding Recorded Call - Last Update: 4s Call Elapsed: 7 [2022-02-07 22:26:01.009341] (info) [islps-74] 2833C TG:  51395 Freq: 8.679625e+08 - Transmission src: 6942112 pos: 0 length: 3.12 [2022-02-07 22:26:01.012432] (info) [islps-74] 2833C Running upload script: ./upload-call.sh 1 /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/51395-1644301555_867962500-call_2833.wav /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/51395-1644301555_867962500-call_2833.json /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/51395-1644301555_867962500-call_2833.m4a [2022-02-07 22:26:03.667518] (info) [islps-74] 2832C TG:  1097 Freq: 8.679625e+08 Starting new Transmission Src ID: 2900250 [2022-02-07 22:26:07.012781] (trace) [islps-74] 2832C TG:  1097 Freq: 8.679625e+08 Stopping Recorded Call, setting call state to INACTIVE - Last Update: 4s

robotastic commented 2 years ago

That would be great - I will double check the code around TDMA Slots. I think I check for that, but it could be a weird corner case.

One thing that will definitely help is if you set callTimeout to be 2 secs or maybe 1. The callTimeout governs how long a "Call" sticks around after the last trunk update message is heard. If a new transmission starts on the control channel, it should stop the recorder... but if for some reason the recorder catches the start of the new transmission on the voice channel before the control channel message, it will start recording.

Also make sure you have good reception for your control channel. Set controlWarnRate to -1 and it will print out the number of messages decoded. It should be above 30. Both of these settings should be at the top level of the config file.

robotastic commented 2 years ago

Formatted version:


[2022-02-07 22:24:00.688738] (info) [islps-74] 2816C TG:  1097 Freq: 8.682375e+08 Starting new Transmission Src ID: 2900945 
[2022-02-07 22:24:12.243453] (info) [islps-74] 2818C TG:  51397 Freq: 8.685250e+08 TG not in Talkgroup File 
[2022-02-07 22:24:12.243587] (info) [islps-74] 2818C TG:  51397 Freq: 8.685250e+08 Starting P25 Recorder Num [1] TDMA: true Slot: 1 QPSK: true 
[2022-02-07 22:24:12.855116] (info) [islps-74] 2818C TG:  51397 Freq: 8.685250e+08 Starting new Transmission Src ID: 6922592 
[2022-02-07 22:24:15.696425] (info) [islps-74] 2818C TG:  51397 Freq: 8.685250e+08 Starting new Transmission Src ID: 6922592 
[2022-02-07 22:24:19.013459] (trace) [islps-74] 2816C TG:  1097 Freq: 8.682375e+08 Stopping Recorded Call, setting call state to INACTIVE - Last Update: 4s 
[2022-02-07 22:24:19.013573] (trace) [islps-74] 2818C TG:  51397 Freq: 8.685250e+08 Stopping Recorded Call, setting call state to INACTIVE - Last Update: 4s 
[2022-02-07 22:24:20.799516] (info) [islps-74] 2819C TG:  917 Freq: 8.679625e+08 TG not in Talkgroup File 
[2022-02-07 22:24:20.799607] (info) [islps-74] 2819C TG:  917 Freq: 8.679625e+08 Starting P25 Recorder Num [3] TDMA: true Slot: 1 QPSK: true 
[2022-02-07 22:24:21.265375] (info) [islps-74] 2819C TG:  917 Freq: 8.679625e+08 Starting new Transmission Src ID: 2900451 
[2022-02-07 22:24:21.344858] (info) [islps-74] 2820C TG:  1097 Freq: 8.682375e+08 TG not in Talkgroup File 
[2022-02-07 22:24:21.344970] (info) [islps-74] 2820C TG:  1097 Freq: 8.682375e+08 Starting P25 Recorder Num [4] TDMA: true Slot: 0 QPSK: true 
[2022-02-07 22:24:21.602840] (info) [islps-74] 2820C TG:  1097 Freq: 8.682375e+08 Starting new Transmission Src ID: -1 
[2022-02-07 22:24:26.016494] (info) Recorder state: 1 
[2022-02-07 22:24:26.016623] (error) [islps-74] 2818C Rec Num: 1 TG:  51397 Freq: 8.685250e+08 �[36m Removing call with stuck recorder  
[2022-02-07 22:24:26.016702] (trace) [islps-74] 2818C TG:  51397 Freq: 8.685250e+08 Concluding Recorded Call - Last Update: 11s Call Elapsed: 14 
[2022-02-07 22:24:26.016860] (error) stop_recording() - stopping wavfile sink but recorder state is: 1 
[2022-02-07 22:24:26.016927] (info) [islps-74] 2818C TG:  51397 Freq: 8.685250e+08 - Transmission src: 6922592 pos: 0 length: 0.16 
[2022-02-07 22:24:26.017006] (info) [islps-74] 2818C TG:  51397 Freq: 8.685250e+08 - Transmission src: 6922592 pos: 0.16 length: 0.08 
[2022-02-07 22:24:26.020456] (info) [islps-74] 2818C Running upload script: ./upload-call.sh 1 /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/51397-1644301452_868525000-call_2818.wav /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/51397-1644301452_868525000-call_2818.json /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/51397-1644301452_868525000-call_2818.m4a 
[2022-02-07 22:24:27.015512] (trace) [islps-74] 2819C TG:  917 Freq: 8.679625e+08 Stopping Recorded Call, setting call state to COMPLETED - Last Update: 4s 
[2022-02-07 22:24:27.015610] (trace) [islps-74] 2819C TG:  917 Freq: 8.679625e+08 Concluding Recorded Call - Last Update: 4s Call Elapsed: 7 
[2022-02-07 22:24:27.015649] (info) [islps-74] 2819C TG:  917 Freq: 8.679625e+08 - Transmission src: 2900451 pos: 0 length: 0.16 
[2022-02-07 22:24:27.015721] (trace) [islps-74] 2820C TG:  1097 Freq: 8.682375e+08 Stopping Recorded Call, setting call state to INACTIVE - Last Update: 4s 
[2022-02-07 22:24:27.018741] (info) [islps-74] 2819C Running upload script: ./upload-call.sh 1 /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/917-1644301461_867962500-call_2819.wav /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/917-1644301461_867962500-call_2819.json /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/917-1644301461_867962500-call_2819.m4a 
[2022-02-07 22:24:28.397873] (info) [islps-74] 2821C TG:  1097 Freq: 8.682375e+08 TG not in Talkgroup File 
[2022-02-07 22:24:28.397957] (info) [islps-74] 2821C TG:  1097 Freq: 8.682375e+08 Starting P25 Recorder Num [1] TDMA: true Slot: 0 QPSK: true 
[2022-02-07 22:24:28.673655] (info) [islps-74] 2821C TG:  1097 Freq: 8.682375e+08 Starting new Transmission Src ID: 3190012 
[2022-02-07 22:24:32.010575] (trace) [islps-74] 2817C TG:  11149 Freq: 8.682375e+08 Stopping Recorded Call, setting call state to COMPLETED - Last Update: 4s 
[2022-02-07 22:24:32.010670] (trace) [islps-74] 2817C TG:  11149 Freq: 8.682375e+08 Concluding Recorded Call - Last Update: 4s Call Elapsed: 35 
[2022-02-07 22:24:32.010741] (info) [islps-74] 2817C TG:  11149 Freq: 8.682375e+08 - Transmission src: 2002157 pos: 0 length: 18.96 
[2022-02-07 22:24:32.015008] (info) [islps-74] 2817C Running upload script: ./upload-call.sh 1 /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/11149-1644301437_868237500-call_2817.wav /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/11149-1644301437_868237500-call_2817.json /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/11149-1644301437_868237500-call_2817.m4a 
[2022-02-07 22:24:37.983677] (info) [islps-74] 2822C TG:  917 Freq: 8.682375e+08 TG not in Talkgroup File 
[2022-02-07 22:24:37.983897] (info) [islps-74] 2822C TG:  917 Freq: 8.682375e+08 Starting P25 Recorder Num [2] TDMA: true Slot: 1 QPSK: true 
[2022-02-07 22:24:38.446090] (info) [islps-74] 2822C TG:  917 Freq: 8.682375e+08 Starting new Transmission Src ID: 2900407 
[2022-02-07 22:24:39.598752] (info) [islps-74] 2823C TG:  11149 Freq: 8.677000e+08 TG not in Talkgroup File 
[2022-02-07 22:24:39.598842] (info) [islps-74] 2823C TG:  11149 Freq: 8.677000e+08 Starting P25 Recorder Num [3] TDMA: true Slot: 0 QPSK: true 
[2022-02-07 22:24:39.659545] (info) [islps-74] 2824C TG:  4087 Freq: 8.677000e+08 TG not in Talkgroup File 
[2022-02-07 22:24:39.659649] (info) [islps-74] 2824C TG:  4087 Freq: 8.677000e+08 Starting P25 Recorder Num [5] TDMA: true Slot: 1 QPSK: true 
[2022-02-07 22:24:39.989749] (info) [islps-74] 2823C TG:  11149 Freq: 8.677000e+08 Starting new Transmission Src ID: 3100004 
[2022-02-07 22:24:40.063620] (info) [islps-74] 2824C TG:  4087 Freq: 8.677000e+08 Starting new Transmission Src ID: 3120006 
[2022-02-07 22:24:43.008846] (trace) [islps-74] 2824C TG:  4087 Freq: 8.677000e+08 Stopping Recorded Call, setting call state to INACTIVE - Last Update: 4s 
[2022-02-07 22:24:43.997532] (info) [islps-74] 2825C TG:  4087 Freq: 8.677000e+08 TG not in Talkgroup File 
[2022-02-07 22:24:43.997670] (info) [islps-74] 2825C TG:  4087 Freq: 8.677000e+08 Starting P25 Recorder Num [6] TDMA: true Slot: 1 QPSK: true 
[2022-02-07 22:24:44.424089] (info) [islps-74] 2825C TG:  4087 Freq: 8.677000e+08 Starting new Transmission Src ID: -1 
[2022-02-07 22:24:46.015313] (trace) [islps-74] 2816C TG:  1097 Freq: 8.682375e+08 Concluding Recorded Call - Last Update: 31s Call Elapsed: 54 
[2022-02-07 22:24:46.015593] (info) [islps-74] 2816C TG:  1097 Freq: 8.682375e+08 - Transmission src: 2900945 pos: 0 length: 3.72 
[2022-02-07 22:24:46.015689] (info) [islps-74] 2816C TG:  1097 Freq: 8.682375e+08 - Transmission src: 2900945 pos: 3.72 length: 29.56 
[2022-02-07 22:24:46.015814] (trace) [islps-74] 2820C TG:  1097 Freq: 8.682375e+08 Concluding Recorded Call - Last Update: 23s Call Elapsed: 25 
[2022-02-07 22:24:46.015905] (info) [islps-74] 2820C TG:  1097 Freq: 8.682375e+08 - Transmission src: -1 pos: 0 length: 14.12 
[2022-02-07 22:24:46.019601] (info) [islps-74] 2820C Running upload script: ./upload-call.sh 1 /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/1097-1644301461_868237500-call_2820.wav /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/1097-1644301461_868237500-call_2820.json /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/1097-1644301461_868237500-call_2820.m4a 
[2022-02-07 22:24:46.020372] (info) [islps-74] 2816C Running upload script: ./upload-call.sh 1 /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/1097-1644301432_868237500-call_2816.wav /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/1097-1644301432_868237500-call_2816.json /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/1097-1644301432_868237500-call_2816.m4a 
[2022-02-07 22:24:47.014011] (trace) [islps-74] 2823C TG:  11149 Freq: 8.677000e+08 Stopping Recorded Call, setting call state to COMPLETED - Last Update: 4s 
[2022-02-07 22:24:47.014134] (trace) [islps-74] 2823C TG:  11149 Freq: 8.677000e+08 Concluding Recorded Call - Last Update: 4s Call Elapsed: 8 
[2022-02-07 22:24:47.014194] (info) [islps-74] 2823C TG:  11149 Freq: 8.677000e+08 - Transmission src: 3100004 pos: 0 length: 1.6 
[2022-02-07 22:24:47.017222] (info) [islps-74] 2823C Running upload script: ./upload-call.sh 1 /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/11149-1644301479_867700000-call_2823.wav /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/11149-1644301479_867700000-call_2823.json /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/11149-1644301479_867700000-call_2823.m4a 
[2022-02-07 22:24:48.012421] (trace) [islps-74] 2821C TG:  1097 Freq: 8.682375e+08 Stopping Recorded Call, setting call state to COMPLETED - Last Update: 4s 
[2022-02-07 22:24:48.012511] (trace) [islps-74] 2821C TG:  1097 Freq: 8.682375e+08 Concluding Recorded Call - Last Update: 4s Call Elapsed: 20 
[2022-02-07 22:24:48.012547] (info) [islps-74] 2821C TG:  1097 Freq: 8.682375e+08 - Transmission src: 3190012 pos: 0 length: 9.36 
[2022-02-07 22:24:48.014986] (info) [islps-74] 2821C Running upload script: ./upload-call.sh 1 /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/1097-1644301468_868237500-call_2821.wav /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/1097-1644301468_868237500-call_2821.json /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/1097-1644301468_868237500-call_2821.m4a 
[2022-02-07 22:24:48.163861] (info) [islps-74] 2826C TG:  11149 Freq: 8.677000e+08 TG not in Talkgroup File 
[2022-02-07 22:24:48.163967] (info) [islps-74] 2826C TG:  11149 Freq: 8.677000e+08 Starting P25 Recorder Num [0] TDMA: true Slot: 0 QPSK: true 
[2022-02-07 22:24:48.264127] (info) [islps-74] 2826C TG:  11149 Freq: 8.677000e+08 Starting new Transmission Src ID: 2001250 
[2022-02-07 22:24:50.009487] (trace) [islps-74] 2822C TG:  917 Freq: 8.682375e+08 Stopping Recorded Call, setting call state to COMPLETED - Last Update: 4s 
[2022-02-07 22:24:50.009659] (trace) [islps-74] 2822C TG:  917 Freq: 8.682375e+08 Concluding Recorded Call - Last Update: 4s Call Elapsed: 13 
[2022-02-07 22:24:50.009986] (info) [islps-74] 2822C TG:  917 Freq: 8.682375e+08 - Transmission src: 2900407 pos: 0 length: 3.44 
[2022-02-07 22:24:50.013670] (info) [islps-74] 2822C Running upload script: ./upload-call.sh 1 /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/917-1644301478_868237500-call_2822.wav /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/917-1644301478_868237500-call_2822.json /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/917-1644301478_868237500-call_2822.m4a 
[2022-02-07 22:24:52.007089] (trace) [islps-74] 2826C TG:  11149 Freq: 8.677000e+08 Stopping Recorded Call, setting call state to INACTIVE - Last Update: 4s 
[2022-02-07 22:24:53.015761] (trace) [islps-74] 2826C TG:  11149 Freq: 8.677000e+08 Concluding Recorded Call - Last Update: 5s Call Elapsed: 5 
[2022-02-07 22:24:53.015885] (info) [islps-74] 2826C TG:  11149 Freq: 8.677000e+08 - Transmission src: 2001250 pos: 0 length: 1.76 
[2022-02-07 22:24:53.019172] (info) [islps-74] 2826C Running upload script: ./upload-call.sh 1 /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/11149-1644301488_867700000-call_2826.wav /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/11149-1644301488_867700000-call_2826.json /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/11149-1644301488_867700000-call_2826.m4a 
[2022-02-07 22:24:55.204302] (info) [islps-74] 2827C TG:  11149 Freq: 8.677000e+08 TG not in Talkgroup File 
[2022-02-07 22:24:55.204417] (info) [islps-74] 2827C TG:  11149 Freq: 8.677000e+08 Starting P25 Recorder Num [0] TDMA: true Slot: 0 QPSK: true 
[2022-02-07 22:24:55.598144] (info) [islps-74] 2827C TG:  11149 Freq: 8.677000e+08 Starting new Transmission Src ID: 2001250 
[2022-02-07 22:24:59.542998] (info) [islps-74] 2828C TG:  1097 Freq: 8.685250e+08 TG not in Talkgroup File 
[2022-02-07 22:24:59.543096] (info) [islps-74] 2828C TG:  1097 Freq: 8.685250e+08 Starting P25 Recorder Num [1] TDMA: true Slot: 0 QPSK: true 
[2022-02-07 22:24:59.967578] (info) [islps-74] 2828C TG:  1097 Freq: 8.685250e+08 Starting new Transmission Src ID: 2900815 
[2022-02-07 22:25:12.013245] (info) Currently Active Calls: 4 
[2022-02-07 22:25:12.013364] (info) [islps-74] 2824C TG:  4087 Freq: 8.677000e+08 Elapsed: 33 State: inactive 
[2022-02-07 22:25:12.013429] (info) [ 5 ] State: recording 
[2022-02-07 22:25:12.013482] (info) [islps-74] 2825C TG:  4087 Freq: 8.677000e+08 Elapsed: 29 State: recording 
[2022-02-07 22:25:12.013530] (info) [ 6 ] State: recording 
[2022-02-07 22:25:12.013556] (info) [islps-74] 2827C TG:  11149 Freq: 8.677000e+08 Elapsed: 17 State: recording 
[2022-02-07 22:25:12.013582] (info) [ 0 ] State: recording 
[2022-02-07 22:25:12.013599] (info) [islps-74] 2828C TG:  1097 Freq: 8.685250e+08 Elapsed: 13 State: recording 
[2022-02-07 22:25:12.013634] (info) [ 1 ] State: recording 
[2022-02-07 22:25:12.013651] (info) Recorders: 
[2022-02-07 22:25:12.013693] (info) [ airspy=260868c8:267c4f9b ] 
[2022-02-07 22:25:12.013751] (info) [ D0 ] State: recording 
[2022-02-07 22:25:12.013775] (info) [ D1 ] State: recording 
[2022-02-07 22:25:12.013792] (info) [ D2 ] State: available 
[2022-02-07 22:25:12.013809] (info) [ D3 ] State: available 
[2022-02-07 22:25:12.013825] (info) [ D4 ] State: available 
[2022-02-07 22:25:12.013842] (info) [ D5 ] State: recording 
[2022-02-07 22:25:12.013858] (info) [ D6 ] State: recording 
[2022-02-07 22:25:12.013874] (info) [ D7 ] State: available 
[2022-02-07 22:25:12.013890] (info) [ D8 ] State: available 
[2022-02-07 22:25:12.013935] (info) [ D9 ] State: available 
[2022-02-07 22:25:12.013962] (info) [ D10 ] State: available 
[2022-02-07 22:25:12.013980] (info) [ D11 ] State: available 
[2022-02-07 22:25:20.013000] (trace) [islps-74] 2824C TG:  4087 Freq: 8.677000e+08 Concluding Recorded Call - Last Update: 41s Call Elapsed: 41 
[2022-02-07 22:25:20.013117] (info) [islps-74] 2824C TG:  4087 Freq: 8.677000e+08 - Transmission src: 3120006 pos: 0 length: 39.04 
[2022-02-07 22:25:20.022159] (info) [islps-74] 2824C Running upload script: ./upload-call.sh 1 /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/4087-1644301480_867700000-call_2824.wav /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/4087-1644301480_867700000-call_2824.json /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/4087-1644301480_867700000-call_2824.m4a 
[2022-02-07 22:25:22.080784] (info) [islps-74] 2829C TG:  51395 Freq: 8.685250e+08 TG not in Talkgroup File 
[2022-02-07 22:25:22.080895] (info) [islps-74] 2829C TG:  51395 Freq: 8.685250e+08 Starting P25 Recorder Num [2] TDMA: true Slot: 1 QPSK: true 
[2022-02-07 22:25:22.488759] (info) [islps-74] 2829C TG:  51395 Freq: 8.685250e+08 Starting new Transmission Src ID: 6942112 
[2022-02-07 22:25:23.009265] (trace) [islps-74] 2825C TG:  4087 Freq: 8.677000e+08 Stopping Recorded Call, setting call state to COMPLETED - Last Update: 4s 
[2022-02-07 22:25:23.009370] (trace) [islps-74] 2825C TG:  4087 Freq: 8.677000e+08 Concluding Recorded Call - Last Update: 4s Call Elapsed: 40 
[2022-02-07 22:25:23.009424] (info) [islps-74] 2825C TG:  4087 Freq: 8.677000e+08 - Transmission src: -1 pos: 0 length: 34.72 
[2022-02-07 22:25:23.013505] (info) [islps-74] 2825C Running upload script: ./upload-call.sh 1 /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/4087-1644301484_867700000-call_2825.wav /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/4087-1644301484_867700000-call_2825.json /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/4087-1644301484_867700000-call_2825.m4a 
[2022-02-07 22:25:25.359705] (info) [islps-74] 2827C TG:  11149 Freq: 8.677000e+08 Starting new Transmission Src ID: 2001250 
[2022-02-07 22:25:28.013050] (trace) [islps-74] 2827C TG:  11149 Freq: 8.677000e+08 Stopping Recorded Call, setting call state to INACTIVE - Last Update: 4s 
[2022-02-07 22:25:28.013155] (trace) [islps-74] 2828C TG:  1097 Freq: 8.685250e+08 Stopping Recorded Call, setting call state to INACTIVE - Last Update: 4s 
[2022-02-07 22:25:28.043508] (info) [islps-74] 2830C TG:  1097 Freq: 8.685250e+08 TG not in Talkgroup File 
[2022-02-07 22:25:28.043651] (info) [islps-74] 2830C TG:  1097 Freq: 8.685250e+08 Starting P25 Recorder Num [3] TDMA: true Slot: 0 QPSK: true 
[2022-02-07 22:25:28.350781] (info) [islps-74] 2830C TG:  1097 Freq: 8.685250e+08 Starting new Transmission Src ID: -1 
[2022-02-07 22:25:31.010099] (trace) [islps-74] 2829C TG:  51395 Freq: 8.685250e+08 Stopping Recorded Call, setting call state to COMPLETED - Last Update: 4s 
[2022-02-07 22:25:31.010212] (trace) [islps-74] 2829C TG:  51395 Freq: 8.685250e+08 Concluding Recorded Call - Last Update: 4s Call Elapsed: 9 
[2022-02-07 22:25:31.010259] (info) [islps-74] 2829C TG:  51395 Freq: 8.685250e+08 - Transmission src: 6942112 pos: 0 length: 3.04 
[2022-02-07 22:25:31.014424] (info) [islps-74] 2829C Running upload script: ./upload-call.sh 1 /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/51395-1644301522_868525000-call_2829.wav /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/51395-1644301522_868525000-call_2829.json /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/51395-1644301522_868525000-call_2829.m4a 
[2022-02-07 22:25:31.594952] (info) [islps-74] 2831C TG:  917 Freq: 8.685250e+08 TG not in Talkgroup File 
[2022-02-07 22:25:31.595056] (info) [islps-74] 2831C TG:  917 Freq: 8.685250e+08 Starting P25 Recorder Num [2] TDMA: true Slot: 1 QPSK: true 
[2022-02-07 22:25:32.056917] (info) [islps-74] 2831C TG:  917 Freq: 8.685250e+08 Starting new Transmission Src ID: 2900432 
[2022-02-07 22:25:36.013361] (info) Recorder state: 1 
[2022-02-07 22:25:36.013478] (error) [islps-74] 2827C Rec Num: 0 TG:  11149 Freq: 8.677000e+08 �[36m Removing call with stuck recorder  
[2022-02-07 22:25:36.013533] (trace) [islps-74] 2827C TG:  11149 Freq: 8.677000e+08 Concluding Recorded Call - Last Update: 12s Call Elapsed: 41 
[2022-02-07 22:25:36.013619] (error) stop_recording() - stopping wavfile sink but recorder state is: 1 
[2022-02-07 22:25:36.013659] (info) [islps-74] 2827C TG:  11149 Freq: 8.677000e+08 - Transmission src: 2001250 pos: 0 length: 23.48 
[2022-02-07 22:25:36.013706] (info) [islps-74] 2827C TG:  11149 Freq: 8.677000e+08 - Transmission src: 2001250 pos: 23.48 length: 0.04 
[2022-02-07 22:25:36.013791] (trace) [islps-74] 2828C TG:  1097 Freq: 8.685250e+08 Concluding Recorded Call - Last Update: 12s Call Elapsed: 37 
[2022-02-07 22:25:36.013842] (info) [islps-74] 2828C TG:  1097 Freq: 8.685250e+08 - Transmission src: 2900815 pos: 0 length: 28.44 
[2022-02-07 22:25:36.018867] (info) [islps-74] 2827C Running upload script: ./upload-call.sh 1 /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/11149-1644301495_867700000-call_2827.wav /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/11149-1644301495_867700000-call_2827.json /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/11149-1644301495_867700000-call_2827.m4a 
[2022-02-07 22:25:36.019152] (info) [islps-74] 2828C Running upload script: ./upload-call.sh 1 /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/1097-1644301499_868525000-call_2828.wav /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/1097-1644301499_868525000-call_2828.json /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/1097-1644301499_868525000-call_2828.m4a 
[2022-02-07 22:25:36.445795] (info) [islps-74] 2830C TG:  1097 Freq: 8.685250e+08 Starting new Transmission Src ID: -1 
[2022-02-07 22:25:40.008021] (trace) [islps-74] 2831C TG:  917 Freq: 8.685250e+08 Stopping Recorded Call, setting call state to COMPLETED - Last Update: 4s 
[2022-02-07 22:25:40.008142] (trace) [islps-74] 2831C TG:  917 Freq: 8.685250e+08 Concluding Recorded Call - Last Update: 4s Call Elapsed: 9 
[2022-02-07 22:25:40.008213] (info) [islps-74] 2831C TG:  917 Freq: 8.685250e+08 - Transmission src: 2900432 pos: 0 length: 1.52 
[2022-02-07 22:25:40.011852] (info) [islps-74] 2831C Running upload script: ./upload-call.sh 1 /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/917-1644301532_868525000-call_2831.wav /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/917-1644301532_868525000-call_2831.json /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/917-1644301532_868525000-call_2831.m4a 
[2022-02-07 22:25:47.384098] (info) [islps-74] 2832C TG:  1097 Freq: 8.679625e+08 TG not in Talkgroup File 
[2022-02-07 22:25:47.384197] (info) [islps-74] 2832C TG:  1097 Freq: 8.679625e+08 Starting P25 Recorder Num [0] TDMA: true Slot: 0 QPSK: true 
[2022-02-07 22:25:47.762723] (info) [islps-74] 2832C TG:  1097 Freq: 8.679625e+08 Starting new Transmission Src ID: 2900250 
[2022-02-07 22:25:50.008605] (trace) [islps-74] 2830C TG:  1097 Freq: 8.685250e+08 Stopping Recorded Call, setting call state to COMPLETED - Last Update: 4s 
[2022-02-07 22:25:50.009192] (trace) [islps-74] 2830C TG:  1097 Freq: 8.685250e+08 Concluding Recorded Call - Last Update: 4s Call Elapsed: 22 
[2022-02-07 22:25:50.009443] (info) [islps-74] 2830C TG:  1097 Freq: 8.685250e+08 - Transmission src: -1 pos: 0 length: 4.96 
[2022-02-07 22:25:50.009696] (info) [islps-74] 2830C TG:  1097 Freq: 8.685250e+08 - Transmission src: -1 pos: 4.96 length: 7.52 
[2022-02-07 22:25:50.014439] (info) [islps-74] 2830C Running upload script: ./upload-call.sh 1 /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/1097-1644301528_868525000-call_2830.wav /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/1097-1644301528_868525000-call_2830.json /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/1097-1644301528_868525000-call_2830.m4a 
[2022-02-07 22:25:54.672310] (info) [islps-74] 2833C TG:  51395 Freq: 8.679625e+08 TG not in Talkgroup File 
[2022-02-07 22:25:54.672632] (info) [islps-74] 2833C TG:  51395 Freq: 8.679625e+08 Starting P25 Recorder Num [1] TDMA: true Slot: 1 QPSK: true 
[2022-02-07 22:25:55.103751] (info) [islps-74] 2833C TG:  51395 Freq: 8.679625e+08 Starting new Transmission Src ID: 6942112 
[2022-02-07 22:26:01.009157] (trace) [islps-74] 2833C TG:  51395 Freq: 8.679625e+08 Stopping Recorded Call, setting call state to COMPLETED - Last Update: 4s 
[2022-02-07 22:26:01.009282] (trace) [islps-74] 2833C TG:  51395 Freq: 8.679625e+08 Concluding Recorded Call - Last Update: 4s Call Elapsed: 7 
[2022-02-07 22:26:01.009341] (info) [islps-74] 2833C TG:  51395 Freq: 8.679625e+08 - Transmission src: 6942112 pos: 0 length: 3.12 
[2022-02-07 22:26:01.012432] (info) [islps-74] 2833C Running upload script: ./upload-call.sh 1 /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/51395-1644301555_867962500-call_2833.wav /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/51395-1644301555_867962500-call_2833.json /home/shahar/trunk-recorder2022/overlap-test/islps-74/2022/2/7/51395-1644301555_867962500-call_2833.m4a 
[2022-02-07 22:26:03.667518] (info) [islps-74] 2832C TG:  1097 Freq: 8.679625e+08 Starting new Transmission Src ID: 2900250 
[2022-02-07 22:26:07.012781] (trace) [islps-74] 2832C TG:  1097 Freq: 8.679625e+08 Stopping Recorded Call, setting call state to INACTIVE - Last Update: 4s
Nokoa commented 2 years ago

As I reduced Call Time out down to 1 from 3, there are now much more instances of this happening. Some single transmissions now may have 3-4 duplicates.

robotastic commented 2 years ago

@Nokoa Can you give the no-overlap branch a try? It should do a better job of reducing duplication.

tadscottsmith commented 2 years ago

@robotastic I couldn't build without modifying this line https://github.com/tadscottsmith/trunk-recorder/commit/6b8140d9af903a8c7d6abab7fd5e33aefd2482e1

robotastic commented 2 years ago

You are totally right ... not sure what happened there ... just fixed it, thanks @tadscottsmith

Nokoa commented 2 years ago

@Nokoa Can you give the no-overlap branch a try? It should do a better job of reducing duplication.

I am away from the equipment for a couple weeks, will give it a try as soon as I return, thank you!

tadscottsmith commented 2 years ago

02-22-2022_0152_03.zip

I am running this branch and it seems to be working pretty well. I am not on a SmartNet system where it seems like most of the overlap issues have been happening, but I have noticed that occasionally this branch will drop transmissions. There's pretty clearly a missed transmission in the attached example between calls 753 and 755. I'd actually expect them to be one call, but 753 seems to end prematurely.

  1. Call 753: SRC 317654 - "9175 Traffic."
  2. Call 753: SRC 312983 - "9175."
  3. MISSED - But, I assume something like "Out with plate XXX-XXX at Century /County E".
  4. Call 755: SRC 312983 "Copy. Traffic. Century / County Road E , Echo..."
tadscottsmith commented 2 years ago

I originally attached the wrong log file, but that should be corrected in the zip above.

robotastic commented 2 years ago

Nice find! and helpful feedback. Let me go check out the Log file

This is one of the tricky things... perviously Trunk Recorder failed permissively, where it would default to recording... now it only records when it gets explicit GRANT messages, so if the control is full or not working 100% (or I messed up some code) transmissions may not get recorded.

robotastic commented 2 years ago

yea - so it looks like there were definitely some transmissions that were dropped from call 753. It looks like it never received another GRANT message, so it dropped the samples coming in. I wonder if the fact that it was a Patched TG would have anything to do with it? Any chance the GRANT would have come in with a different TG? I didn't see anything obvious... and it would have ended the existing call if it got a GRANT for a TG on the same channel.

Call 753:

[2022-02-22 02:03:47.484344] (trace)   tbsk02   Moto Patch Grant    Channel ID:   269   Freq: 8.526875e+08  sg   11518  TDMA -1 sa 317654
[2022-02-22 02:03:47.484566] (info)   [ramsey]  753C TG:             RAM SO CENT (     11518)   Freq: 8.526875e+08  Starting P25 Recorder Num [9]  TDMA: false Slot: 0 QPSK: true
[2022-02-22 02:03:54.889841] (info)   TEMINATOR!!
[2022-02-22 02:03:54.890054] (info)   [ramsey]  753C TG:      11518 Freq: 8.526875e+08  record_more_transmissions is false, setting recorder state to STOPPED
[2022-02-22 02:03:59.075975] (trace)   MOT_GRG_CN_GRANT_UPDT(0x03):     Channel ID:   269   Freq: 8.526875e+08  sg   11518  TDMA -1
[2022-02-22 02:03:59.076089] (info)   [ramsey]  753  TTG:             RAM SO CENT (     11518)  Freq: 8.526875e+08   Updating Call 
[2022-02-22 02:03:59.126351] (trace)   P25 Frame Assembler - Amt Prod: 864 output_queue: 1440 noutput_items: 864
[2022-02-22 02:03:59.126609] (trace)   setting silence_frame_count 0 to d_silence_frames: 0
[2022-02-22 02:03:59.126701] (error)   [ramsey] 753C TG:      11518 Freq: 8.526875e+08  Dropping samples - Recorder state is: stopped
----
[2022-02-22 02:03:59.728549] (trace)   P25 Frame Assembler - Amt Prod: 864 output_queue: 1440 noutput_items: 864
[2022-02-22 02:03:59.728917] (trace)   setting silence_frame_count 0 to d_silence_frames: 0
[2022-02-22 02:03:59.729183] (error)   [ramsey] 753C TG:      11518 Freq: 8.526875e+08  Dropping samples - Recorder state is: stopped
[2022-02-22 02:03:59.779754] (trace)   nac 40d type 7 size 12 mesg len: 12
[2022-02-22 02:03:59.779845] (trace)   TSBK: opcode: $3
[2022-02-22 02:03:59.779884] (trace)   MOT_GRG_CN_GRANT_UPDT(0x03):     Channel ID:   269   Freq: 8.526875e+08  sg   11518  TDMA -1
[2022-02-22 02:03:59.779905] (info)   [ramsey]  753  TTG:             RAM SO CENT (     11518)  Freq: 8.526875e+08   Updating Call 
[2022-02-22 02:03:59.779932] (trace)   nac 40d type 7 size 12 mesg len: 12
[2022-02-22 02:03:59.779975] (trace)   TSBK: opcode: $5
[2022-02-22 02:03:59.779991] (debug)   tsbk05: Unit To Unit Answer Request
[2022-02-22 02:03:59.780012] (trace)   nac 40d type 7 size 12 mesg len: 12
[2022-02-22 02:03:59.780030] (trace)   TSBK: opcode: $9
[2022-02-22 02:03:59.780044] (debug)   tsbk09: Telephone Interconnect Voice Channel Grant Update
[2022-02-22 02:03:59.830215] (trace)   P25 Frame Assembler - Amt Prod: 864 output_queue: 576 noutput_items: 864
[2022-02-22 02:03:59.830420] (trace)   setting silence_frame_count 0 to d_silence_frames: 0
[2022-02-22 02:03:59.830515] (error)   [ramsey] 753C TG:      11518 Freq: 8.526875e+08  Dropping samples - Recorder state is: stopped

Call 755:

[2022-02-22 02:04:04.919457] (trace)   tbsk02   Moto Patch Grant    Channel ID:   209   Freq: 8.523125e+08  sg   11518  TDMA -1 sa 312983
[2022-02-22 02:04:04.919498] (info)   [ramsey]  755C TG:             RAM SO CENT (     11518)   Freq: 8.523125e+08  Starting P25 Recorder Num [0]  TDMA: false Slot: 0 QPSK: true

Call 754:

[2022-02-22 02:03:49.504261] (debug)   tsbk00   Chan Grant  Channel ID:    89   Freq: 8.515625e+08  ga    3750  TDMA -1 sa 127071   Encrypt 0   Bandwidth: 12.5
[2022-02-22 02:03:49.504318] (info)   TG: 3750 sys num: 0 freq: 8.51562e+08 TDMA Slot0 TDMA: false
[2022-02-22 02:03:49.548597] (trace)   P25 Frame Assembler - Amt Prod: 864 output_queue: 1152 noutput_items: 864
[2022-02-22 02:03:49.548694] (trace)   setting silence_frame_count 0 to d_silence_frames: 0
[2022-02-22 02:03:49.593397] (trace)   nac 40d type 7 size 12 mesg len: 12
[2022-02-22 02:03:49.593511] (trace)   TSBK: opcode: $0
tadscottsmith commented 2 years ago

It seems like maybe this grant didn't trigger anything?

[2022-02-22 02:03:54.643342] (debug)   tbsk02   Moto Patch Grant        Channel ID:   269       Freq: 8.526875e+08      sg   11518      TDMA -1 sa 317654
[2022-02-22 02:03:54.643931] (debug)   tbsk02   Moto Patch Grant        Channel ID:   269       Freq: 8.526875e+08      sg   11518      TDMA -1 sa 317654
tadscottsmith commented 2 years ago

Trying to tie the recorded transmissions to the appropriate grants during the same time. Call 754 is a separate TG, so it can be safely ignored.

[2022-02-22 02:03:47.484138] (debug)   tbsk02   Moto Patch Grant        Channel ID:   269       Freq: 8.526875e+08      sg   11518      TDMA -1 sa 317654
[2022-02-22 02:03:47.484344] (trace)   tbsk02   Moto Patch Grant        Channel ID:   269       Freq: 8.526875e+08      sg   11518      TDMA -1 sa 317654
[2022-02-22 02:03:47.485100] (debug)   tbsk02   Moto Patch Grant        Channel ID:   269       Freq: 8.526875e+08      sg   11518      TDMA -1 sa 317654

Call 753: SRC 317654 - "9175 Traffic."

[2022-02-22 02:03:52.126097] (debug)   tbsk02   Moto Patch Grant        Channel ID:   269       Freq: 8.526875e+08      sg   11518      TDMA -1 sa 312983
[2022-02-22 02:03:52.216005] (debug)   tbsk02   Moto Patch Grant        Channel ID:   269       Freq: 8.526875e+08      sg   11518      TDMA -1 sa 312983

Call 753: SRC 312983 - "9175."

[2022-02-22 02:03:54.643342] (debug)   tbsk02   Moto Patch Grant        Channel ID:   269       Freq: 8.526875e+08      sg   11518      TDMA -1 sa 317654
[2022-02-22 02:03:54.643931] (debug)   tbsk02   Moto Patch Grant        Channel ID:   269       Freq: 8.526875e+08      sg   11518      TDMA -1 sa 317654
[2022-02-22 02:03:55.297275] (error)   [ramsey] 753C    TG:      11518  Freq: 8.526875e+08      Dropping samples - Recorder state is: stopped
[2022-02-22 02:03:55.398370] (error)   [ramsey] 753C    TG:      11518  Freq: 8.526875e+08      Dropping samples - Recorder state is: stopped
[2022-02-22 02:03:55.498436] (error)   [ramsey] 753C    TG:      11518  Freq: 8.526875e+08      Dropping samples - Recorder state is: stopped
[2022-02-22 02:03:55.601717] (error)   [ramsey] 753C    TG:      11518  Freq: 8.526875e+08      Dropping samples - Recorder state is: stopped
[2022-02-22 02:03:55.700503] (error)   [ramsey] 753C    TG:      11518  Freq: 8.526875e+08      Dropping samples - Recorder state is: stopped
[2022-02-22 02:03:55.802532] (error)   [ramsey] 753C    TG:      11518  Freq: 8.526875e+08      Dropping samples - Recorder state is: stopped
[2022-02-22 02:03:55.904770] (error)   [ramsey] 753C    TG:      11518  Freq: 8.526875e+08      Dropping samples - Recorder state is: stopped
[2022-02-22 02:03:56.004729] (error)   [ramsey] 753C    TG:      11518  Freq: 8.526875e+08      Dropping samples - Recorder state is: stopped
[2022-02-22 02:03:56.204487] (error)   [ramsey] 753C    TG:      11518  Freq: 8.526875e+08      Dropping samples - Recorder state is: stopped
[2022-02-22 02:03:56.302301] (error)   [ramsey] 753C    TG:      11518  Freq: 8.526875e+08      Dropping samples - Recorder state is: stopped
[2022-02-22 02:03:56.407044] (error)   [ramsey] 753C    TG:      11518  Freq: 8.526875e+08      Dropping samples - Recorder state is: stopped
[2022-02-22 02:03:56.508968] (error)   [ramsey] 753C    TG:      11518  Freq: 8.526875e+08      Dropping samples - Recorder state is: stopped
[2022-02-22 02:03:56.606780] (error)   [ramsey] 753C    TG:      11518  Freq: 8.526875e+08      Dropping samples - Recorder state is: stopped
[2022-02-22 02:03:56.710866] (error)   [ramsey] 753C    TG:      11518  Freq: 8.526875e+08      Dropping samples - Recorder state is: stopped
[2022-02-22 02:03:56.811271] (error)   [ramsey] 753C    TG:      11518  Freq: 8.526875e+08      Dropping samples - Recorder state is: stopped
[2022-02-22 02:03:56.911161] (error)   [ramsey] 753C    TG:      11518  Freq: 8.526875e+08      Dropping samples - Recorder state is: stopped
[2022-02-22 02:03:57.013947] (error)   [ramsey] 753C    TG:      11518  Freq: 8.526875e+08      Dropping samples - Recorder state is: stopped
[2022-02-22 02:03:57.112307] (error)   [ramsey] 753C    TG:      11518  Freq: 8.526875e+08      Dropping samples - Recorder state is: stopped
[2022-02-22 02:03:57.216644] (error)   [ramsey] 753C    TG:      11518  Freq: 8.526875e+08      Dropping samples - Recorder state is: stopped
[2022-02-22 02:03:57.414704] (error)   [ramsey] 753C    TG:      11518  Freq: 8.526875e+08      Dropping samples - Recorder state is: stopped
[2022-02-22 02:03:57.511690] (error)   [ramsey] 753C    TG:      11518  Freq: 8.526875e+08      Dropping samples - Recorder state is: stopped
[2022-02-22 02:03:57.615372] (error)   [ramsey] 753C    TG:      11518  Freq: 8.526875e+08      Dropping samples - Recorder state is: stopped
[2022-02-22 02:03:57.715026] (error)   [ramsey] 753C    TG:      11518  Freq: 8.526875e+08      Dropping samples - Recorder state is: stopped
[2022-02-22 02:03:57.817976] (error)   [ramsey] 753C    TG:      11518  Freq: 8.526875e+08      Dropping samples - Recorder state is: stopped
[2022-02-22 02:03:57.919795] (error)   [ramsey] 753C    TG:      11518  Freq: 8.526875e+08      Dropping samples - Recorder state is: stopped
[2022-02-22 02:03:58.019535] (error)   [ramsey] 753C    TG:      11518  Freq: 8.526875e+08      Dropping samples - Recorder state is: stopped
[2022-02-22 02:03:58.123062] (error)   [ramsey] 753C    TG:      11518  Freq: 8.526875e+08      Dropping samples - Recorder state is: stopped
[2022-02-22 02:03:58.223774] (error)   [ramsey] 753C    TG:      11518  Freq: 8.526875e+08      Dropping samples - Recorder state is: stopped
[2022-02-22 02:03:58.323154] (error)   [ramsey] 753C    TG:      11518  Freq: 8.526875e+08      Dropping samples - Recorder state is: stopped
[2022-02-22 02:03:58.520551] (error)   [ramsey] 753C    TG:      11518  Freq: 8.526875e+08      Dropping samples - Recorder state is: stopped
[2022-02-22 02:03:58.619738] (error)   [ramsey] 753C    TG:      11518  Freq: 8.526875e+08      Dropping samples - Recorder state is: stopped
[2022-02-22 02:03:58.724183] (error)   [ramsey] 753C    TG:      11518  Freq: 8.526875e+08      Dropping samples - Recorder state is: stopped
[2022-02-22 02:03:58.825927] (error)   [ramsey] 753C    TG:      11518  Freq: 8.526875e+08      Dropping samples - Recorder state is: stopped
[2022-02-22 02:03:58.924350] (error)   [ramsey] 753C    TG:      11518  Freq: 8.526875e+08      Dropping samples - Recorder state is: stopped
[2022-02-22 02:03:59.029718] (error)   [ramsey] 753C    TG:      11518  Freq: 8.526875e+08      Dropping samples - Recorder state is: stopped
[2022-02-22 02:03:59.126701] (error)   [ramsey] 753C    TG:      11518  Freq: 8.526875e+08      Dropping samples - Recorder state is: stopped
[2022-02-22 02:03:59.230343] (error)   [ramsey] 753C    TG:      11518  Freq: 8.526875e+08      Dropping samples - Recorder state is: stopped
[2022-02-22 02:03:59.330474] (error)   [ramsey] 753C    TG:      11518  Freq: 8.526875e+08      Dropping samples - Recorder state is: stopped
[2022-02-22 02:03:59.431953] (error)   [ramsey] 753C    TG:      11518  Freq: 8.526875e+08      Dropping samples - Recorder state is: stopped
[2022-02-22 02:03:59.532640] (error)   [ramsey] 753C    TG:      11518  Freq: 8.526875e+08      Dropping samples - Recorder state is: stopped
[2022-02-22 02:03:59.729183] (error)   [ramsey] 753C    TG:      11518  Freq: 8.526875e+08      Dropping samples - Recorder state is: stopped
[2022-02-22 02:03:59.830515] (error)   [ramsey] 753C    TG:      11518  Freq: 8.526875e+08      Dropping samples - Recorder state is: stopped

MISSED - But, I assume something like "Out with plate XXX-XXX at Century /County E".

[2022-02-22 02:04:04.919317] (debug)   tbsk02   Moto Patch Grant        Channel ID:   209       Freq: 8.523125e+08      sg   11518      TDMA -1 sa 312983
[2022-02-22 02:04:04.919457] (trace)   tbsk02   Moto Patch Grant        Channel ID:   209       Freq: 8.523125e+08      sg   11518      TDMA -1 sa 312983
[2022-02-22 02:04:05.024255] (debug)   tbsk02   Moto Patch Grant        Channel ID:   209       Freq: 8.523125e+08      sg   11518      TDMA -1 sa 312983

Call 755: SRC 312983 "Copy. Traffic. Century / County Road E , Echo..."

robotastic commented 2 years ago

Interesting - Those Patch Grants come after when all of the dropped samples happen. I wonder if the Control Channel processing got delayed behind the Voice Channel. There may also not be any guarantees about when a grant message comes.

tadscottsmith commented 2 years ago

The dropped samples actually come after. I edited my previous comment and added those logs. It could be some sort of race condition, though, as it's happening in a small percentage of the calls.

robotastic commented 2 years ago

Soooo... turns out this has been happening on my local system too. A lot. I just hadn't been checking the logs. I should be able to iterate on this a bit quicker now.

Here the Grant Message comes in, then the Termination, then some voice samples. I think this can happen when there is less "processing delay" on the Trunk Channel vs the Voice Channel. So the GRANT message resets the flag to start a new call, but the Termination flag then clears. I will have to come up with something a little more nuanced.

Feb 22 21:21:03 radio auto-restart-wmata.sh[241845]: [2022-02-22 21:21:03.652016] (error)   [wmata]        2        TTG:      34480        Freq: 496462500 Hz         GRANT Message
Feb 22 21:21:03 radio auto-restart-wmata.sh[241845]: [2022-02-22 21:21:03.769577] (info)   TEMINATOR!!
Feb 22 21:21:03 radio auto-restart-wmata.sh[241845]: [2022-02-22 21:21:03.769705] (info)   [wmata]        2C        TG:      34480        Freq: 496462500 Hz        record_more_transmissions is false, set>
Feb 22 21:21:04 radio auto-restart-wmata.sh[241845]: [2022-02-22 21:21:04.126904] (error)   [wmata]        2C        TG:      34480        Freq: 496462500 Hz        Dropping samples - Recorder state is: >
robotastic commented 2 years ago

OK - @tadscottsmith I think I have cleaned up quite a bit. I put in place a new approach that essentially has 2 timers. The first tracks when the last grant/update message and only allows new transmissions to be started within 1 sec of receiving one. The second is for the overall call and collects multiple transmissions if the same TG / Freq is used within 5 sec. If you have a chance, can you try out the no-overlap branch again?

tadscottsmith commented 2 years ago

I just updated, so I'll give it a shot. Sounds like a good approach!

tadscottsmith commented 2 years ago

This seems to be working really well for me. While I haven't had a ton of time to dedicate to listening, I haven't heard any noticeable missed transmissions. I also don't have any of the tell-tale chain of "Dropping samples - Recorder state is: stopped" lines being recorded in the logs.

Nokoa commented 2 years ago

Been using this new version for a couple days, and it also appears to be working really well so far. Have not noticed any duplications where I previously had them all the time.

tadscottsmith commented 2 years ago

@robotastic So, this version works great, but it definitely doesn't work for Unit-to-Unit calls. Unit-to-Unit calls seem to stay on the same frequency, but use the destination SUID as the TGID, so it essentially "flips" for each transmission. I'm not sure these have ever worked on 4.x, honestly, but I figured I could start digging in. I'm curious if you have any ideas on how you want to handle the TGIDs though? I've thought of a few different methods, but would love your input.

  1. Always use the smaller or larger SUID as the TGID in trunk-recorder.
  2. Combine the two SUID in an specified order as the TGID, i.e. SUID 111111 and SUID 222222 make a TGID of 111111222222.
  3. Some function to uniquely create a TGID from the pair of SUIDs. Something like a cantor pairing function?

I've done some work to break the UUV Grants and Updates out from the group grants and updates, but I'd like to know if you have a preference on the TGID before I get too much further.

robotastic commented 2 years ago

Great point! yea, it would not be happy with unit-to-unit calls. I don't think I have any of these one my the systems I monitor. With the way it currently is, does each Transmission get turned into its own unique call? If so, that may not be the worst outcome. That way you would be preserving the source-id and the target-id for each transmission.

Currently the TG Num is stored as a Long. I like the idea of combing the 2 src IDs but the problem would be if it can fit in a Long. It is 32-bit, so I think it could. It would cause some serious UI problems though. Option 1 is probably the safest.

I am going to be working on merging this branch in - If you are able to add in better UUV grant/updates, that would be awesome!

Nokoa commented 2 years ago

Thank you for fixing this issue! It has been working quite well. I did however notice that quite often certain recordings are cut short, seconds too early. I have several computers recordings some of the same transmissions on different sites. I have noticed that on one site I would have the full recording for the transmission, and on the other I have that same recording but its cut way short. I was wondering if this is perhaps an issue with my decoding quality, which is mostly 40/sec for the CC so I am not sure. Or maybe an issue with how recordings are being stopped now?

rosecitytransit commented 1 year ago

Regarding unit-unit calls, what about simply always using the first-seen order, e.g by checking to see if there's an active call with a talkgroup matching the the incoming source as in https://github.com/robotastic/trunk-recorder/pull/470/commits/0eb05cdeede051881f41adecbf063606734206fe and if so swapping the IDs? The only downside is that the ID of who's talking in a transmission wouldn't be preserved.

I record a system with a lot of unit-unit calls and would offer it up for debugging, but they don't show up correctly on the control channel--there's never any update messages for them. With my modifications to address that, 4.5.0 does seem to be working fine for them.