trunk-recorder
trunk-recorder copied to clipboard
robotastic
P25 Transmissions Bleeding Together
There seems to be an issue with transmissions occasionally bleeding together within a call. From the attached call audio and JSON, you can clearly hear that there should be four distinct transmissions. All four of the transmissions are recorded correctly, but for some reason the last two seem to be combined by trunk-recorder. There are only three transmissions listed in the JSON .
2191 [SRCID 151586]: "2191." DISP [SRCID 151004]: "Go ahead." 2191 [SRCID 151586]: "Begin Oak Street Ramp." DISP [SRCID 151004]: "Copy."
[2022-06-08 17:46:36.764709] (debug) tsbk00 Chan Grant Channel ID: 1237 Freq: 858.737500 MHz ga 3580 TDMA -1 sa 151586 Encrypt 0 Bandwidth: 12.5
[2022-06-08 17:46:36.764979] (trace) tsbk00 Chan Grant Channel ID: 1237 Freq: 858.737500 MHz ga 3580 TDMA -1 sa 151586 Encrypt 0 Bandwidth: 12.5
[2022-06-08 17:46:36.765010] (info) [mplscc] 1521C TG: UMN SEC MON ( 3580) Freq: 858.737500 MHz Starting P25 Recorder Num [23] TDMA: false Slot: 0 QPSK: true
[2022-06-08 17:46:36.765074] (trace) [mplscc] 1521C TG: 3580 Freq: 858.737500 MHz Starting wavfile sink SRC ID: 151586
[2022-06-08 17:46:36.765115] (trace) [mplscc] 1521C TG: UMN SEC MON ( 3580) Freq: 858.737500 MHz New Control Channel Transmission. SA: 151586
[2022-06-08 17:46:36.902485] (debug) tsbk00 Chan Grant Channel ID: 1237 Freq: 858.737500 MHz ga 3580 TDMA -1 sa 151586 Encrypt 0 Bandwidth: 12.5
[2022-06-08 17:46:36.902715] (trace) [mplscc] 1521C TG: UMN SEC MON ( 3580) Freq: 858.737500 MHz Ignoring Control Channel Grant. Likely Duplicate. SA: 151586
[2022-06-08 17:46:37.358633] (trace) [mplscc] 1521C TG: 3580 Freq: 858.737500 MHz Starting new Transmission Src ID: 151586
[2022-06-08 17:46:39.105149] (trace) [mplscc] 1521C TG: 3580 Freq: 858.737500 MHz Spike Count: 0 pos: 12960 offset: 1086898
[2022-06-08 17:46:39.105202] (trace) [mplscc] 1521C TG: 3580 Freq: 858.737500 MHz Error Count: 0 pos: 12960 offset: 1086898
[2022-06-08 17:46:39.105241] (trace) [mplscc] 1521C TG: 3580 Freq: 858.737500 MHz TERM - record_more_transmissions = false, setting Recorder More: true - count: 12960
[2022-06-08 17:46:39.657787] (debug) tsbk00 Chan Grant Channel ID: 1237 Freq: 858.737500 MHz ga 3580 TDMA -1 sa 151004 Encrypt 0 Bandwidth: 12.5
[2022-06-08 17:46:39.657962] (trace) [mplscc] 1521C TG: UMN SEC MON ( 3580) Freq: 858.737500 MHz New Control Channel Transmission. SA: 151004
[2022-06-08 17:46:39.727647] (debug) tsbk00 Chan Grant Channel ID: 1237 Freq: 858.737500 MHz ga 3580 TDMA -1 sa 151004 Encrypt 0 Bandwidth: 12.5
[2022-06-08 17:46:39.728025] (trace) [mplscc] 1521C TG: UMN SEC MON ( 3580) Freq: 858.737500 MHz Ignoring Control Channel Grant. Likely Duplicate. SA: 151004
[2022-06-08 17:46:40.156423] (trace) [mplscc] 1521C TG: 3580 Freq: 858.737500 MHz Starting new Transmission Src ID: -1
[2022-06-08 17:46:41.112359] (trace) [mplscc] 1521C TG: 3580 Freq: 858.737500 MHz Spike Count: 0 pos: 7200 offset: 1094105
[2022-06-08 17:46:41.112514] (trace) [mplscc] 1521C TG: 3580 Freq: 858.737500 MHz Error Count: 0 pos: 7200 offset: 1094105
[2022-06-08 17:46:41.112559] (trace) [mplscc] 1521C TG: 3580 Freq: 858.737500 MHz TERM - record_more_transmissions = false, setting Recorder More: true - count: 7200
[2022-06-08 17:46:41.829025] (debug) tsbk00 Chan Grant Channel ID: 1237 Freq: 858.737500 MHz ga 3580 TDMA -1 sa 151586 Encrypt 0 Bandwidth: 12.5
[2022-06-08 17:46:41.829124] (trace) [mplscc] 1521C TG: UMN SEC MON ( 3580) Freq: 858.737500 MHz New Control Channel Transmission. SA: 151586
[2022-06-08 17:46:41.947872] (debug) tsbk00 Chan Grant Channel ID: 1237 Freq: 858.737500 MHz ga 3580 TDMA -1 sa 151586 Encrypt 0 Bandwidth: 12.5
[2022-06-08 17:46:41.947968] (trace) [mplscc] 1521C TG: UMN SEC MON ( 3580) Freq: 858.737500 MHz Ignoring Control Channel Grant. Likely Duplicate. SA: 151586
[2022-06-08 17:46:42.424176] (trace) [mplscc] 1521C TG: 3580 Freq: 858.737500 MHz Starting new Transmission Src ID: -1
[2022-06-08 17:46:44.177489] (debug) tsbk00 Chan Grant Channel ID: 1237 Freq: 858.737500 MHz ga 3580 TDMA -1 sa 151004 Encrypt 0 Bandwidth: 12.5
[2022-06-08 17:46:44.177626] (trace) [mplscc] 1521C TG: UMN SEC MON ( 3580) Freq: 858.737500 MHz New Control Channel Transmission. SA: 151004
[2022-06-08 17:46:44.238667] (debug) tsbk00 Chan Grant Channel ID: 1237 Freq: 858.737500 MHz ga 3580 TDMA -1 sa 151004 Encrypt 0 Bandwidth: 12.5
[2022-06-08 17:46:44.238888] (trace) [mplscc] 1521C TG: UMN SEC MON ( 3580) Freq: 858.737500 MHz Ignoring Control Channel Grant. Likely Duplicate. SA: 151004
[2022-06-08 17:46:45.829419] (trace) [mplscc] 1521C TG: 3580 Freq: 858.737500 MHz Spike Count: 3 pos: 24480 offset: 1118595
[2022-06-08 17:46:45.829459] (trace) [mplscc] 1521C TG: 3580 Freq: 858.737500 MHz Error Count: 45 pos: 24480 offset: 1118595
[2022-06-08 17:46:45.829489] (trace) [mplscc] 1521C TG: 3580 Freq: 858.737500 MHz TERM - record_more_transmissions = false, setting Recorder More: true - count: 24480
[2022-06-08 17:46:50.008547] (trace) [mplscc] 1521C TG: UMN SEC MON ( 3580) Freq: 858.737500 MHz Removing call that has been inactive for more than 3 Sec Rec last write: 1 State: 4
[2022-06-08 17:46:50.008993] (error) [mplscc] 1521C TG: 3580 Freq: 858.737500 MHz Call Grants: 4 . Recorded Transmissions: 3.
[2022-06-08 17:46:50.009031] (info) [mplscc] 1521C TG: 3580 Freq: 858.737500 MHz - Transmission src: 151586 pos: 0 length: 1.62
[2022-06-08 17:46:50.009066] (info) [mplscc] 1521C TG: 3580 Freq: 858.737500 MHz - Transmission src: 151004 pos: 1.62 length: 0.9
[2022-06-08 17:46:50.009099] (info) [mplscc] 1521C TG: 3580 Freq: 858.737500 MHz - Transmission src: 151004 pos: 2.52 length: 3.06
It seems like this Grant correctly starts a third transmission, but does not decode/respond to a TDU before the next transmission begins.
[2022-06-08 17:46:41.829025] (debug) tsbk00 Chan Grant Channel ID: 1237 Freq: 858.737500 MHz ga 3580 TDMA -1 sa 151586 Encrypt 0 Bandwidth: 12.5
I'm assuming that this Grant then updates the SRCID, but does not end the previous transmission and start a new one.
[2022-06-08 17:46:44.177489] (debug) tsbk00 Chan Grant Channel ID: 1237 Freq: 858.737500 MHz ga 3580 TDMA -1 sa 151004 Encrypt 0 Bandwidth: 12.5
I realize this could theoretically be a signal issue, but it is happening on multiple systems, and evenly distributed across frequencies, so it leads me to believe there may be a certain condition that is causing it. It seems this is happening on about 2% of calls.
3580-1654728397_858737500-call_1521.zip
@robotastic I've tried to track this down, and it seems it's sometimes not recognizing the terminator (TDU), and that is causing transmissions to occasionally blend. Can you double check this block at some point? I keep coming back to it, and it wondering if you are purposely only tagging "terminate" if the amt_produce<= 0. https://github.com/robotastic/trunk-recorder/blob/7c5b88491f6239859977e6e7cf46c1b00e6ebffb/lib/op25_repeater/lib/p25_frame_assembler_impl.cc#L203-L240
I've had no issues with transmission bleeding into other recordings from one talk group into another now that I've moved over to a much more powerful AMD 5800 based system from the Raspberry Pis. I think it's very likely that given that the system is CPU starved it will continue recording on a frequency that is reused from another talk group when the terminate is late to the processed and is racing against other in flight recordings. So I think there is a data race here.
Just to clarify, this issue doesn't present itself as recordings from two different talk groups bleeding together. This is just two transmissions from the same talk group by two different radios, being recorded together is a single "transmission" within a call. You probably wouldn't even notice this happening unless you're logging and comparing the "Call Grants" and actual recorded transmissions, or you're able to watch the SUIDs like a hawk. I could be proven wrong, and it could be a race condition, or resource issue. But given that the audio, the terminations, and the next audio is all on the same voice channel (same recorder) and that it's clearly picking up the audio but missing the 20ish TDUs in between leads me to believe there's a bug to look into.
Thanks for digging into this @tadscottsmith - it is VERY possible there is either a subtle bug in there OR some of the assumptions I made are not universal and are just local to systems I have tested on. The reason I hadn't been including TDU units where there is some audio being produced is because the audio would get dropped because the Termination Flag if true. (I have to double check this). I was always seeing lots of TDUs with amt_produced = 0 . It could be though that there is low signal sometimes and the TDUs are lost... or maybe on some systems there are no blank TDUs... or maybe when a system gets really busy the buffers back up, so the AMT produced could grow even though there is a TDU there.
I can take a look into it. let me know if you find clues!
[@Dewey3] If you want to give it a shot, this branch has been updated to better handle things on my P25 P1 system. However, I don't have a P25 P2 system close, so I can't test against one. https://github.com/tadscottsmith/trunk-recorder/tree/p25-tx-update
[@Dewey3] If you want to give it a shot, this branch has been updated to better handle things on my P25 P1 system. However, I don't have a P25 P2 system close, so I can't test against one. https://github.com/tadscottsmith/trunk-recorder/tree/p25-tx-update
I just tried it, but unfortunately, I didn't see a difference on the P25 P2-TDMA system. Thank you for trying!
Has it ever worked on a 4.x version? I just want to double check, since you'd called out 4.3 on the other thread.
I added a couple a couple of commits. I'm kind of flying blind just digging through code, but I noticed the p25_frame_assembler_impl.cc wasn't ever trying to update the source for P25P2. If you have a minute, give it a shot and see if it makes anything better (or way way worse...).
https://github.com/tadscottsmith/trunk-recorder/tree/p25-tx-update
Has it ever worked on a 4.x version? I just want to double check, since you'd called out 4.3 on the other thread.
I want to say no it has not, BUT, that is from a memory that doesn't work like it used to. With that said, I have to add that I actually came into the v4 game late because I thought there was a problem with the recordings, and it wasn't until just about 3 or 4 months ago that I realized the problem was my fault. I had my v3 gains set at something like 7 for digital and 7 for analog and the raspy sound of the over-modulation in v4 with my v3 gains did not click on what to do until earlier this year.
Thanks again! It's close to nighttime retirement time for me, so I'll give this a shot when I return home from work tomorrow.
I added a couple a couple of commits. I'm kind of flying blind just digging through code, but I noticed the p25_frame_assembler_impl.cc wasn't ever trying to update the source for P25P2. If you have a minute, give it a shot and see if it makes anything better (or way way worse...).
https://github.com/tadscottsmith/trunk-recorder/tree/p25-tx-update
I just gave it a shot and unfortunately, no change. Just for a matter of clarification, the way I'm doing the checking is by watching the UID live in Rdio-Scanner after TrunkRecorder sends the transmissions. The system is a very busy system, and a lot of the transmissions are back-to-back-to-back-to-back. When the rapid transmissions happen, most times the same UID will remain on the Rdio-Scanner screen, but occasionally, the UID will fail to populate at all, For the sake of comparison, when I pop my TrunkRecorder v3 card back into the RPi, everything returns to working as it should with the UID following the actual transmitting UID no matter how fast the transmissions come behind each other. I am able to verify the correctness of the live UIDs buy following the same transmissions on the SDS100, SDS200, and Unitrunker.
Bummer! Well, if anyone has a spare box around near a P25P2 system, let me know. Otherwise, without being able to print out some debugging statements to troubleshoot, I am not sure how much more I can dig into for P25P2. I know on P25P1 it seemed that either intentionally or unintentionally the Control Channel wasn't always processing grant message as fast as the voice channel, and it seems to work a little better to trust the voice channel once the recorder has started.
When I get home today, I'll see if I can build a quick testbed RPi for the 2A8 system that you can ssh into and I'll leave up for the weekend.
I won't be able to do anything this weekend, but I can probably find some time next week! We can touch base after the weekend.
I get spotty reception of the PG County system. I can try running to see if I can spot something. There is also a chance the pipeline for getting those IDs to Rdio could have been messed up too.
If I have enough SDRs I maybe able to run 3.x side by side with 4.x and look for differences.
On Jun 17, 2022, at 11:50 AM, tadscottsmith @.***> wrote:
I won't be able to do anything this weekend, but I can probably find some time next week! We can touch base after the weekend.
— Reply to this email directly, view it on GitHub, or unsubscribe. You are receiving this because you were mentioned.
I get spotty reception of the PG County system. I can try running to see if I can spot something. There is also a chance the pipeline for getting those IDs to Rdio could have been messed up too. If I have enough SDRs I maybe able to run 3.x side by side with 4.x and look for differences. … On Jun 17, 2022, at 11:50 AM, tadscottsmith @.***> wrote: I won't be able to do anything this weekend, but I can probably find some time next week! We can touch base after the weekend. — Reply to this email directly, view it on GitHub, or unsubscribe. You are receiving this because you were mentioned.
Thanks Luke. You gave me another idea for one thing I didn't think about before. With v4, I am sending the recordings to Rdio on another RPi via plugin. Since the plugin did not exist in v3, I run both on the receiving Rpi ingesting the call into the local copy of Rdio via DIrwatch, then sending downstream to the main Rpi. I need to throw Rdio on the local Rpi when running v4, then ingest the calls locally as I do with v3 to see if there is a difference. Thanks again... I'll probably give that a try this evening since I will not be in a rush to build the testbed RPi.
@robotastic I've got a lot of extra logging turned on, but here's an example on P25 P1 where the master branch wouldn't correctly update the SRCID.
The second transmission (below) either doesn't receive or fails to process any TDUs.
[2022-06-17 11:34:24.370340] (error) [ramsey] 363C TG: 11532 Freq: 853.212500 MHz Starting New Transmission Src ID: 320643
This means that the second and third transmissions (320643 and 312993) would be recorded together and would only have one SRCID (320643). What seems to be working pretty well is to end the transmission and let it start a new transmission any time that the voice channel and current call have different sources. I think you had most of the code already stubbed out and commented. I'm wondering if something similar is occurring in P25P2.
[2022-06-17 11:34:19.687548] (error) [ramsey] 363C TG: SPPD CH 5 ( 11532) Freq: 853.212500 MHz Starting P25 Recorder Num [0] TDMA: false Slot: 0 QPSK: true
[2022-06-17 11:34:19.783264] (error) [ramsey] 363C TG: 11532 Freq: 853.212500 MHz TERM - CHANNEL Record More Transmissions: true
[2022-06-17 11:34:19.790885] (error) [ramsey] 363C TG: SPPD CH 5 ( 11532) Freq: 853.212500 MHz Chan Grant SA: 312993
[2022-06-17 11:34:19.849784] (error) [ramsey] 363C TG: SPPD CH 5 ( 11532) Freq: 853.212500 MHz Grant Update SA: -1
[2022-06-17 11:34:19.947267] (error) [ramsey] 363C TG: SPPD CH 5 ( 11532) Freq: 853.212500 MHz Grant Update SA: -1
[2022-06-17 11:34:20.112490] (error) [ramsey] 363C TG: 11532 Freq: 853.212500 MHz Starting New Transmission Voice Src ID: 312993 Call Src ID: 312993
[2022-06-17 11:34:20.112568] (error) [ramsey] 363C TG: 11532 Freq: 853.212500 MHz Starting New Transmission Src ID: 312993
[2022-06-17 11:34:20.224172] (error) [ramsey] 363C TG: SPPD CH 5 ( 11532) Freq: 853.212500 MHz Grant Update SA: -1
[2022-06-17 11:34:20.607187] (error) [ramsey] 363C TG: SPPD CH 5 ( 11532) Freq: 853.212500 MHz Grant Update SA: -1
[2022-06-17 11:34:20.879678] (error) [ramsey] 363C TG: SPPD CH 5 ( 11532) Freq: 853.212500 MHz Grant Update SA: -1
[2022-06-17 11:34:21.211245] (error) [ramsey] 363C TG: SPPD CH 5 ( 11532) Freq: 853.212500 MHz Grant Update SA: -1
[2022-06-17 11:34:21.491654] (error) [ramsey] 363C TG: SPPD CH 5 ( 11532) Freq: 853.212500 MHz Grant Update SA: -1
[2022-06-17 11:34:21.810562] (error) [ramsey] 363C TG: SPPD CH 5 ( 11532) Freq: 853.212500 MHz Grant Update SA: -1
[2022-06-17 11:34:22.082737] (error) [ramsey] 363C TG: SPPD CH 5 ( 11532) Freq: 853.212500 MHz Grant Update SA: -1
[2022-06-17 11:34:22.186830] (error) [ramsey] 363C TG: 11532 Freq: 853.212500 MHz TERM - record_more_transmissions = false, setting Recorder More: true - count: 15840
[2022-06-17 11:34:22.187336] (error) [ramsey] 363C TG: 11532 Freq: 853.212500 MHz Ending Current Transmission Src ID: 312993
[2022-06-17 11:34:22.463333] (error) [ramsey] 363C TG: SPPD CH 5 ( 11532) Freq: 853.212500 MHz Grant Update SA: -1
[2022-06-17 11:34:22.800504] (error) [ramsey] 363C TG: SPPD CH 5 ( 11532) Freq: 853.212500 MHz Grant Update SA: -1
[2022-06-17 11:34:23.389278] (error) [ramsey] 363C TG: 11532 Freq: 853.212500 MHz TERM - CHANNEL Record More Transmissions: true
[2022-06-17 11:34:23.493535] (error) [ramsey] 363C TG: 11532 Freq: 853.212500 MHz TERM - CHANNEL Record More Transmissions: true
[2022-06-17 11:34:23.604291] (error) [ramsey] 363C TG: 11532 Freq: 853.212500 MHz TERM - CHANNEL Record More Transmissions: true
[2022-06-17 11:34:23.773936] (error) [ramsey] 363C TG: SPPD CH 5 ( 11532) Freq: 853.212500 MHz Chan Grant SA: 320643
[2022-06-17 11:34:23.832160] (error) [ramsey] 363C TG: SPPD CH 5 ( 11532) Freq: 853.212500 MHz Chan Grant SA: 320643
[2022-06-17 11:34:23.889922] (error) [ramsey] 363C TG: SPPD CH 5 ( 11532) Freq: 853.212500 MHz Grant Update SA: -1
[2022-06-17 11:34:24.108429] (error) [ramsey] 363C TG: SPPD CH 5 ( 11532) Freq: 853.212500 MHz Grant Update SA: -1
[2022-06-17 11:34:24.370244] (error) [ramsey] 363C TG: 11532 Freq: 853.212500 MHz Starting New Transmission Voice Src ID: -1 Call Src ID: 320643
[2022-06-17 11:34:24.370340] (error) [ramsey] 363C TG: 11532 Freq: 853.212500 MHz Starting New Transmission Src ID: 320643
[2022-06-17 11:34:24.439671] (error) [ramsey] 363C TG: SPPD CH 5 ( 11532) Freq: 853.212500 MHz Grant Update SA: -1
[2022-06-17 11:34:24.809846] (error) [ramsey] 363C TG: SPPD CH 5 ( 11532) Freq: 853.212500 MHz Grant Update SA: -1
[2022-06-17 11:34:25.092216] (error) [ramsey] 363C TG: SPPD CH 5 ( 11532) Freq: 853.212500 MHz Grant Update SA: -1
[2022-06-17 11:34:25.308516] (error) [ramsey] 363C TG: SPPD CH 5 ( 11532) Freq: 853.212500 MHz Chan Grant SA: 312993
[2022-06-17 11:34:25.423763] (error) [ramsey] 363C TG: SPPD CH 5 ( 11532) Freq: 853.212500 MHz Chan Grant SA: 312993
[2022-06-17 11:34:25.480384] (error) [ramsey] 363C TG: SPPD CH 5 ( 11532) Freq: 853.212500 MHz Grant Update SA: -1
[2022-06-17 11:34:25.573762] (error) [ramsey] 363C TG: SPPD CH 5 ( 11532) Freq: 853.212500 MHz Grant Update SA: -1
[2022-06-17 11:34:25.857400] (error) [ramsey] 363C TG: SPPD CH 5 ( 11532) Freq: 853.212500 MHz Grant Update SA: -1
[2022-06-17 11:34:26.240303] (error) [ramsey] 363C TG: SPPD CH 5 ( 11532) Freq: 853.212500 MHz Grant Update SA: -1
[2022-06-17 11:34:26.449163] (error) [ramsey] 363C TG: 11532 Freq: 853.212500 MHz Mismatched Voice Channel Source ID: 312993 Current Source ID: 320643 Since Update: 0
[2022-06-17 11:34:26.449471] (error) [ramsey] 363C TG: 11532 Freq: 853.212500 MHz Ending Current Transmission Src ID: 320643
[2022-06-17 11:34:26.449725] (error) [ramsey] 363C TG: 11532 Freq: 853.212500 MHz Starting New Transmission Voice Src ID: 312993 Call Src ID: 312993
[2022-06-17 11:34:26.449786] (error) [ramsey] 363C TG: 11532 Freq: 853.212500 MHz Starting New Transmission Src ID: 312993
[2022-06-17 11:34:26.622934] (error) [ramsey] 363C TG: SPPD CH 5 ( 11532) Freq: 853.212500 MHz Grant Update SA: -1
[2022-06-17 11:34:26.831335] (error) [ramsey] 363C TG: SPPD CH 5 ( 11532) Freq: 853.212500 MHz Grant Update SA: -1
[2022-06-17 11:34:27.008367] (error) [ramsey] 363C TG: SPPD CH 5 ( 11532) Freq: 853.212500 MHz Grant Update SA: -1
[2022-06-17 11:34:27.265864] (error) [ramsey] 363C TG: SPPD CH 5 ( 11532) Freq: 853.212500 MHz Grant Update SA: -1
[2022-06-17 11:34:27.606536] (error) [ramsey] 363C TG: SPPD CH 5 ( 11532) Freq: 853.212500 MHz Grant Update SA: -1
[2022-06-17 11:34:27.872394] (error) [ramsey] 363C TG: SPPD CH 5 ( 11532) Freq: 853.212500 MHz Grant Update SA: -1
[2022-06-17 11:34:28.197931] (error) [ramsey] 363C TG: SPPD CH 5 ( 11532) Freq: 853.212500 MHz Grant Update SA: -1
[2022-06-17 11:34:28.409382] (error) [ramsey] 363C TG: 11532 Freq: 853.212500 MHz TERM - record_more_transmissions = false, setting Recorder More: true - count: 14976
[2022-06-17 11:34:28.409641] (error) [ramsey] 363C TG: 11532 Freq: 853.212500 MHz Ending Current Transmission Src ID: 312993
I'm also curious about this line not having an equivalent for p2tdma? I tried to build it out blind in my branch above, but it may not have worked.
https://github.com/robotastic/trunk-recorder/blob/fc16d6e85d5a0ea04f11da23bd0d7d07bea5ccd5/lib/op25_repeater/lib/p25_frame_assembler_impl.cc#L204
I just completed the trial of v4 into a local copy of Rdio via Rdio's Dirwatch, and I'm still missing a lot of the UIDs when the transmissions are right behind each other.
What is the JSON configuration needed for that level of logging? @tadscottsmith?
What is the JSON configuration needed for that level of logging? @tadscottsmith?
It's just a custom branch I've been using for debugging with a bunch of extra log statements. Nothing that can be changed in the config file as of yet, but I could certainly put in a PR with some additional call logging.
@tadscottsmith that is a really interesting catch, where the source changes but there is no TDU message. How is your reception? is it possible that those "packets" were just dropped for some reason?
I was thinking of having the transmissions switch if the source does... I just wasn't sure if that would create new problems if I have some weird errors with the src decoding. It might be worth trying to re-enable that.
If I am remembering things right, Phase 2 audio still gets put through the Phase 1 decoder first, and that is where the SRC ID is captured.... I should go check though
I'm not seeing a way to PM on Github so I don't know how to send the credentials. I do have a duplicate Prince George's Co, MD 2A8 system up and running on a spare RPi that is ready for either of you to take a look at via SSH and/or Rdio-Scanner and fiddle with if needed.
@robotastic I added some additional logging, and it appears the TDUs are being received, although this issue seems to happen when there are just a short number of TDUs before the next HDU/LDU. Here's the full log of a transmission from two different sources, 117020 and 116007.
[2022-06-22 17:30:40.373361] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 856.938e+08 Starting New Transmission Voice Src ID: 117020 Call Src ID: 117020
[2022-06-22 17:30:40.464770] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 856.938e+08 TRANSMISSION SINK - DOWORK NOUTPUT_ITEMS: 576 SAMPLE COUNT: 864
[2022-06-22 17:30:40.649723] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 P25P1 - LDU2 Last Source 0
[2022-06-22 17:30:40.651104] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 856.938e+08 TRANSMISSION SINK - DOWORK NOUTPUT_ITEMS: 864 SAMPLE COUNT: 1440
[2022-06-22 17:30:40.744241] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 P25P1 - LDU1 Last Source 0
[2022-06-22 17:30:40.746517] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 856.938e+08 TRANSMISSION SINK - DOWORK NOUTPUT_ITEMS: 864 SAMPLE COUNT: 2304
[2022-06-22 17:30:40.843743] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 856.938e+08 TRANSMISSION SINK - DOWORK NOUTPUT_ITEMS: 864 SAMPLE COUNT: 3168
[2022-06-22 17:30:40.933515] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 P25P1 - LDU2 Last Source 0
[2022-06-22 17:30:40.935140] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 856.938e+08 TRANSMISSION SINK - DOWORK NOUTPUT_ITEMS: 864 SAMPLE COUNT: 4032
[2022-06-22 17:30:41.027413] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 856.938e+08 TRANSMISSION SINK - DOWORK NOUTPUT_ITEMS: 864 SAMPLE COUNT: 4896
[2022-06-22 17:30:41.214697] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 P25P1 - LDU1 Last Source 0
[2022-06-22 17:30:41.214736] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 P25P1 - GRP_V_CH_USR New Source 117020
[2022-06-22 17:30:41.216523] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 856.938e+08 TRANSMISSION SINK - DOWORK NOUTPUT_ITEMS: 864 SAMPLE COUNT: 5760
[2022-06-22 17:30:41.305251] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 P25P1 - LDU2 Last Source 117020
[2022-06-22 17:30:41.308623] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 856.938e+08 TRANSMISSION SINK - DOWORK NOUTPUT_ITEMS: 864 SAMPLE COUNT: 6624
[2022-06-22 17:30:41.400048] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 856.938e+08 TRANSMISSION SINK - DOWORK NOUTPUT_ITEMS: 864 SAMPLE COUNT: 7488
[2022-06-22 17:30:41.498878] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 P25P1 - LDU1 Last Source 117020
[2022-06-22 17:30:41.498921] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 P25P1 - GRP_V_CH_USR New Source 117020
[2022-06-22 17:30:41.501865] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 856.938e+08 TRANSMISSION SINK - DOWORK NOUTPUT_ITEMS: 864 SAMPLE COUNT: 8352
[2022-06-22 17:30:41.588484] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 P25P1 - LDU2 Last Source 117020
[2022-06-22 17:30:41.591811] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 856.938e+08 TRANSMISSION SINK - DOWORK NOUTPUT_ITEMS: 864 SAMPLE COUNT: 9216
[2022-06-22 17:30:41.772996] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 856.938e+08 TRANSMISSION SINK - DOWORK NOUTPUT_ITEMS: 864 SAMPLE COUNT: 10080
[2022-06-22 17:30:41.867600] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 P25P1 - LDU1 Last Source 117020
[2022-06-22 17:30:41.871960] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 856.938e+08 TRANSMISSION SINK - DOWORK NOUTPUT_ITEMS: 864 SAMPLE COUNT: 10944
[2022-06-22 17:30:41.962019] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 856.938e+08 TRANSMISSION SINK - DOWORK NOUTPUT_ITEMS: 864 SAMPLE COUNT: 11808
[2022-06-22 17:30:42.055375] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 P25P1 - LDU2 Last Source 117020
[2022-06-22 17:30:42.056961] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 856.938e+08 TRANSMISSION SINK - DOWORK NOUTPUT_ITEMS: 864 SAMPLE COUNT: 12672
[2022-06-22 17:30:42.154517] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 P25P1 - LDU1 Last Source 117020
[2022-06-22 17:30:42.155714] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 856.938e+08 TRANSMISSION SINK - DOWORK NOUTPUT_ITEMS: 864 SAMPLE COUNT: 13536
[2022-06-22 17:30:42.244629] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 856.938e+08 TRANSMISSION SINK - DOWORK NOUTPUT_ITEMS: 864 SAMPLE COUNT: 14400
[2022-06-22 17:30:42.428257] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 P25P1 - LDU2 Last Source 117020
[2022-06-22 17:30:42.430114] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 856.938e+08 TRANSMISSION SINK - DOWORK NOUTPUT_ITEMS: 864 SAMPLE COUNT: 15264
[2022-06-22 17:30:42.456573] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 856.938e+08 Chan Grant SA: 116007
[2022-06-22 17:30:42.528215] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 856.938e+08 Chan Grant SA: 116007
[2022-06-22 17:30:42.531649] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 856.938e+08 TRANSMISSION SINK - DOWORK NOUTPUT_ITEMS: 864 SAMPLE COUNT: 16128
[2022-06-22 17:30:42.617743] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 P25P1 - LDU1 Last Source 117020
[2022-06-22 17:30:42.619740] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 P25P1 - TDU Last Source 117020
[2022-06-22 17:30:42.619789] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 P25P1 - TDULC Last Source 117020
[2022-06-22 17:30:42.619843] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 FRAME ASSEMBLER - P1FDMA TERMINATE_CALL : TRUE
[2022-06-22 17:30:42.619859] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 FRAME ASSEMBLER - IGNORING ADDING TERMINATE TAG AMT_PRODUCE: 864
[2022-06-22 17:30:42.619964] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 856.938e+08 TRANSMISSION SINK - DOWORK NOUTPUT_ITEMS: 864 SAMPLE COUNT: 16992
[2022-06-22 17:30:42.714042] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 P25P1 - TDULC Last Source 117020
[2022-06-22 17:30:42.714074] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 P25P1 - GRP_V_CH_USR New Source 0
[2022-06-22 17:30:42.714124] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 P25P1 - TDULC Last Source 0
[2022-06-22 17:30:42.714171] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 P25P1 - TDU Last Source 0
[2022-06-22 17:30:42.714215] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 FRAME ASSEMBLER - P1FDMA TERMINATE_CALL : TRUE
[2022-06-22 17:30:42.714232] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 FRAME ASSEMBLER - IGNORING ADDING TERMINATE TAG AMT_PRODUCE: 864
[2022-06-22 17:30:42.714281] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 856.938e+08 TRANSMISSION SINK - DOWORK NOUTPUT_ITEMS: 864 SAMPLE COUNT: 17856
[2022-06-22 17:30:42.811498] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 P25P1 - HDU Last Source 0
[2022-06-22 17:30:42.900121] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 P25P1 - LDU1 Last Source 0
[2022-06-22 17:30:42.901284] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 856.938e+08 TRANSMISSION SINK - DOWORK NOUTPUT_ITEMS: 864 SAMPLE COUNT: 18720
[2022-06-22 17:30:43.084762] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 856.938e+08 TRANSMISSION SINK - DOWORK NOUTPUT_ITEMS: 576 SAMPLE COUNT: 19584
[2022-06-22 17:30:43.178968] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 P25P1 - LDU2 Last Source 0
[2022-06-22 17:30:43.184102] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 856.938e+08 TRANSMISSION SINK - DOWORK NOUTPUT_ITEMS: 864 SAMPLE COUNT: 20160
[2022-06-22 17:30:43.273696] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 856.938e+08 TRANSMISSION SINK - DOWORK NOUTPUT_ITEMS: 576 SAMPLE COUNT: 21024
[2022-06-22 17:30:43.368657] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 P25P1 - LDU1 Last Source 0
[2022-06-22 17:30:43.368685] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 P25P1 - GRP_V_CH_USR New Source 0
[2022-06-22 17:30:43.371292] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 856.938e+08 TRANSMISSION SINK - DOWORK NOUTPUT_ITEMS: 864 SAMPLE COUNT: 21600
[2022-06-22 17:30:43.467200] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 P25P1 - LDU2 Last Source 0
[2022-06-22 17:30:43.471042] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 856.938e+08 TRANSMISSION SINK - DOWORK NOUTPUT_ITEMS: 864 SAMPLE COUNT: 22464
[2022-06-22 17:30:43.645862] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 856.938e+08 TRANSMISSION SINK - DOWORK NOUTPUT_ITEMS: 864 SAMPLE COUNT: 23328
[2022-06-22 17:30:43.739880] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 P25P1 - LDU1 Last Source 0
[2022-06-22 17:30:43.739911] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 P25P1 - GRP_V_CH_USR New Source 116007
[2022-06-22 17:30:43.745277] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 856.938e+08 Mismatched Voice Channel Source ID: 116007 Current Source ID: 117020 Samples: 24192
[2022-06-22 17:30:43.745305] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 856.938e+08 TRANSMISSION SINK - DOWORK NOUTPUT_ITEMS: 864 SAMPLE COUNT: 24192
[2022-06-22 17:30:43.844658] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 856.938e+08 TRANSMISSION SINK - DOWORK NOUTPUT_ITEMS: 864 SAMPLE COUNT: 25056
[2022-06-22 17:30:43.929255] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 P25P1 - LDU2 Last Source 116007
[2022-06-22 17:30:43.933203] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 856.938e+08 TRANSMISSION SINK - DOWORK NOUTPUT_ITEMS: 864 SAMPLE COUNT: 25920
[2022-06-22 17:30:44.023232] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 P25P1 - LDU1 Last Source 116007
[2022-06-22 17:30:44.027927] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 856.938e+08 TRANSMISSION SINK - DOWORK NOUTPUT_ITEMS: 864 SAMPLE COUNT: 26784
[2022-06-22 17:30:44.206758] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 856.938e+08 TRANSMISSION SINK - DOWORK NOUTPUT_ITEMS: 864 SAMPLE COUNT: 27648
[2022-06-22 17:30:44.301314] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 P25P1 - LDU2 Last Source 116007
[2022-06-22 17:30:44.302706] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 856.938e+08 TRANSMISSION SINK - DOWORK NOUTPUT_ITEMS: 864 SAMPLE COUNT: 28512
[2022-06-22 17:30:44.395613] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 P25P1 - LDU1 Last Source 116007
[2022-06-22 17:30:44.396700] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 P25P1 - TDU Last Source 116007
[2022-06-22 17:30:44.396718] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 FRAME ASSEMBLER - P1FDMA TERMINATE_CALL : TRUE
[2022-06-22 17:30:44.396733] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 FRAME ASSEMBLER - IGNORING ADDING TERMINATE TAG AMT_PRODUCE: 864
[2022-06-22 17:30:44.396881] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 856.938e+08 TRANSMISSION SINK - DOWORK NOUTPUT_ITEMS: 864 SAMPLE COUNT: 29376
[2022-06-22 17:30:44.490792] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 P25P1 - TDULC Last Source 116007
[2022-06-22 17:30:44.490871] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 P25P1 - TDULC Last Source 116007
[2022-06-22 17:30:44.490930] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 FRAME ASSEMBLER - P1FDMA TERMINATE_CALL : TRUE
[2022-06-22 17:30:44.490951] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 FRAME ASSEMBLER - IGNORING ADDING TERMINATE TAG AMT_PRODUCE: 864
[2022-06-22 17:30:44.491167] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 856.938e+08 TRANSMISSION SINK - DOWORK NOUTPUT_ITEMS: 864 SAMPLE COUNT: 30240
[2022-06-22 17:30:44.585033] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 P25P1 - TDULC Last Source 116007
[2022-06-22 17:30:44.585114] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 P25P1 - TDULC Last Source 116007
[2022-06-22 17:30:44.585181] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 FRAME ASSEMBLER - P1FDMA TERMINATE_CALL : TRUE
[2022-06-22 17:30:44.585201] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 FRAME ASSEMBLER - IGNORING ADDING TERMINATE TAG AMT_PRODUCE: 576
[2022-06-22 17:30:44.585269] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 856.938e+08 TRANSMISSION SINK - DOWORK NOUTPUT_ITEMS: 576 SAMPLE COUNT: 31104
[2022-06-22 17:30:44.771612] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 P25P1 - TDULC Last Source 116007
[2022-06-22 17:30:44.771650] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 P25P1 - GRP_V_CH_USR New Source 0
[2022-06-22 17:30:44.771712] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 P25P1 - TDULC Last Source 0
[2022-06-22 17:30:44.771784] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 P25P1 - TDULC Last Source 0
[2022-06-22 17:30:44.771846] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 FRAME ASSEMBLER - P1FDMA TERMINATE_CALL : TRUE
[2022-06-22 17:30:44.771866] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 FRAME ASSEMBLER - ADDING TERMINATE TAG AMT_PRODUCE: 0
[2022-06-22 17:30:44.772207] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 856.938e+08 TRANSMISSION SINK - TERMINATE TAG RECEIVED Sample count 31680 Pos: 31680 Offset: 53326
[2022-06-22 17:30:44.772235] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 856.938e+08 TRANSMISSION SINK - DOWORK NOUTPUT_ITEMS: 1 SAMPLE COUNT: 31680
[2022-06-22 17:30:44.772397] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 856.938e+08 TERM - record_more_transmissions = false, setting Recorder More: true - count: 31680
[2022-06-22 17:30:44.772522] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 856.938e+08 Ending Current Transmission Src ID: 116007
You can see here that there are only 5 TDUs in a very brief period of time, and the p25_frame_assembler_impl::general_work() ignores them, because it apparently is never able to get to a state of AMT_PRODUCE == 0 while terminate_call == true.
[2022-06-22 17:30:42.456573] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 856.938e+08 Chan Grant SA: 116007
[2022-06-22 17:30:42.528215] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 856.938e+08 Chan Grant SA: 116007
[2022-06-22 17:30:42.531649] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 856.938e+08 TRANSMISSION SINK - DOWORK NOUTPUT_ITEMS: 864 SAMPLE COUNT: 16128
[2022-06-22 17:30:42.617743] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 P25P1 - LDU1 Last Source 117020
[2022-06-22 17:30:42.619740] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 P25P1 - TDU Last Source 117020
[2022-06-22 17:30:42.619789] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 P25P1 - TDULC Last Source 117020
[2022-06-22 17:30:42.619843] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 FRAME ASSEMBLER - P1FDMA TERMINATE_CALL : TRUE
[2022-06-22 17:30:42.619859] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 FRAME ASSEMBLER - IGNORING ADDING TERMINATE TAG AMT_PRODUCE: 864
[2022-06-22 17:30:42.619964] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 856.938e+08 TRANSMISSION SINK - DOWORK NOUTPUT_ITEMS: 864 SAMPLE COUNT: 16992
[2022-06-22 17:30:42.714042] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 P25P1 - TDULC Last Source 117020
[2022-06-22 17:30:42.714074] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 P25P1 - GRP_V_CH_USR New Source 0
[2022-06-22 17:30:42.714124] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 P25P1 - TDULC Last Source 0
[2022-06-22 17:30:42.714171] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 P25P1 - TDU Last Source 0
[2022-06-22 17:30:42.714215] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 FRAME ASSEMBLER - P1FDMA TERMINATE_CALL : TRUE
[2022-06-22 17:30:42.714232] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 FRAME ASSEMBLER - IGNORING ADDING TERMINATE TAG AMT_PRODUCE: 864
[2022-06-22 17:30:42.714281] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 856.938e+08 TRANSMISSION SINK - DOWORK NOUTPUT_ITEMS: 864 SAMPLE COUNT: 17856
[2022-06-22 17:30:42.811498] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 P25P1 - HDU Last Source 0
[2022-06-22 17:30:42.900121] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 P25P1 - LDU1 Last Source 0
[2022-06-22 17:30:42.901284] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 856.938e+08 TRANSMISSION SINK - DOWORK NOUTPUT_ITEMS: 864 SAMPLE COUNT: 18720
[2022-06-22 17:30:43.084762] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 856.938e+08 TRANSMISSION SINK - DOWORK NOUTPUT_ITEMS: 576 SAMPLE COUNT: 19584
And here you can see at the end of the second "transmission", there were 8 TDUs over a longer period of time and p25_frame_assembler_impl::general_work() appears to be able to process all they way through amt_produced and the terminate tag is correctly applied and sent to the transmission_sink.
[2022-06-22 17:30:44.396700] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 P25P1 - TDU Last Source 116007
[2022-06-22 17:30:44.396718] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 FRAME ASSEMBLER - P1FDMA TERMINATE_CALL : TRUE
[2022-06-22 17:30:44.396733] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 FRAME ASSEMBLER - IGNORING ADDING TERMINATE TAG AMT_PRODUCE: 864
[2022-06-22 17:30:44.396881] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 856.938e+08 TRANSMISSION SINK - DOWORK NOUTPUT_ITEMS: 864 SAMPLE COUNT: 29376
[2022-06-22 17:30:44.490792] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 P25P1 - TDULC Last Source 116007
[2022-06-22 17:30:44.490871] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 P25P1 - TDULC Last Source 116007
[2022-06-22 17:30:44.490930] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 FRAME ASSEMBLER - P1FDMA TERMINATE_CALL : TRUE
[2022-06-22 17:30:44.490951] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 FRAME ASSEMBLER - IGNORING ADDING TERMINATE TAG AMT_PRODUCE: 864
[2022-06-22 17:30:44.491167] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 856.938e+08 TRANSMISSION SINK - DOWORK NOUTPUT_ITEMS: 864 SAMPLE COUNT: 30240
[2022-06-22 17:30:44.585033] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 P25P1 - TDULC Last Source 116007
[2022-06-22 17:30:44.585114] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 P25P1 - TDULC Last Source 116007
[2022-06-22 17:30:44.585181] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 FRAME ASSEMBLER - P1FDMA TERMINATE_CALL : TRUE
[2022-06-22 17:30:44.585201] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 FRAME ASSEMBLER - IGNORING ADDING TERMINATE TAG AMT_PRODUCE: 576
[2022-06-22 17:30:44.585269] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 856.938e+08 TRANSMISSION SINK - DOWORK NOUTPUT_ITEMS: 576 SAMPLE COUNT: 31104
[2022-06-22 17:30:44.771612] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 P25P1 - TDULC Last Source 116007
[2022-06-22 17:30:44.771650] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 P25P1 - GRP_V_CH_USR New Source 0
[2022-06-22 17:30:44.771712] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 P25P1 - TDULC Last Source 0
[2022-06-22 17:30:44.771784] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 P25P1 - TDULC Last Source 0
[2022-06-22 17:30:44.771846] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 FRAME ASSEMBLER - P1FDMA TERMINATE_CALL : TRUE
[2022-06-22 17:30:44.771866] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 FRAME ASSEMBLER - ADDING TERMINATE TAG AMT_PRODUCE: 0
[2022-06-22 17:30:44.772207] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 856.938e+08 TRANSMISSION SINK - TERMINATE TAG RECEIVED Sample count 31680 Pos: 31680 Offset: 53326
[2022-06-22 17:30:44.772235] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 856.938e+08 TRANSMISSION SINK - DOWORK NOUTPUT_ITEMS: 1 SAMPLE COUNT: 31680
[2022-06-22 17:30:44.772397] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 856.938e+08 TERM - record_more_transmissions = false, setting Recorder More: true - count: 31680
[2022-06-22 17:30:44.772522] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 856.938e+08 Ending Current Transmission Src ID: 116007
I'm still learning this flow, so I figured I'd log what I have so far, and maybe something will stand out to you.
Nice detective work - I am going to have to dig into your fork so I can better match up the log messages with what is happening.
One interesting thing I saw:
[2022-06-22 17:30:42.428257] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 P25P1 - LDU2 Last Source 117020
[2022-06-22 17:30:42.430114] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 856.938e+08 TRANSMISSION SINK - DOWORK NOUTPUT_ITEMS: 864 SAMPLE COUNT: 15264
[2022-06-22 17:30:42.456573] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 856.938e+08 Chan Grant SA: 116007
[2022-06-22 17:30:42.528215] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 856.938e+08 Chan Grant SA: 116007
[2022-06-22 17:30:42.531649] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 856.938e+08 TRANSMISSION SINK - DOWORK NOUTPUT_ITEMS: 864 SAMPLE COUNT: 16128
[2022-06-22 17:30:42.617743] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 P25P1 - LDU1 Last Source 117020
[2022-06-22 17:30:42.619740] (error) [mplscc] 34C TG: MPLS PD 3 DI ( 2958) Freq: 8.56938e+08 P25P1 - TDU Last Source 117020
If I am reading this right, it looks like the Control Channel, channel grant message comes in before the TDU... which sort of shows the difference in processing time between the two.
I will dig in more
PS - I did try to put together a flow chart on call handling... not sure it makes things clearer: https://github.com/robotastic/trunk-recorder/blob/master/docs/notes/CALL-HANDLING.md
This branch is very similar to your master, except that it has a ton of extra logging: https://github.com/tadscottsmith/trunk-recorder/tree/p25-logging It segfaults occasionally, which I assume has something to do with my hasty work to pass the call info all over, but it generally runs long enough to see a few mismatches.
To further complicate things, it appears there is a "hang time", or "teardown time" (approximately 2 seconds) in which there is never a grant on the control channel and the source is only updated via the voice channel. I'm trying to find actual documentation on it, but here's an example (no Grant for 154241)...
[2022-06-22 20:26:35.213467] (error) [mplscc] 195C TG: MTC PD DISPW ( 2532) Freq: 856.262500 MHz Chan Grant SA: 169895
[2022-06-22 20:26:35.264950] (error) [mplscc] 195C TG: MTC PD DISPW ( 2532) Freq: 856.262500 MHz Chan Grant SA: 169895
[2022-06-22 20:26:35.816026] (error) [mplscc] 195C TG: MTC PD DISPW ( 2532) Freq: 8.56262e+08 P25P1 - GRP_V_CH_USR New Source 0
[2022-06-22 20:26:36.566575] (error) [mplscc] 195C TG: MTC PD DISPW ( 2532) Freq: 8.56262e+08 P25P1 - GRP_V_CH_USR New Source 169895
[2022-06-22 20:26:36.849852] (error) [mplscc] 195C TG: MTC PD DISPW ( 2532) Freq: 8.56262e+08 P25P1 - GRP_V_CH_USR New Source 169895
[2022-06-22 20:26:37.694223] (error) [mplscc] 195C TG: MTC PD DISPW ( 2532) Freq: 8.56262e+08 P25P1 - GRP_V_CH_USR New Source 0
[2022-06-22 20:26:37.877389] (error) [mplscc] 195C TG: MTC PD DISPW ( 2532) Freq: 8.56262e+08 P25P1 - GRP_V_CH_USR New Source 0
[2022-06-22 20:26:37.958355] (error) [mplscc] 195C TG: MTC PD DISPW ( 2532) Freq: 856.262500 MHz Chan Grant SA: 154241
[2022-06-22 20:26:38.066893] (error) [mplscc] 195C TG: MTC PD DISPW ( 2532) Freq: 8.56262e+08 P25P1 - GRP_V_CH_USR New Source 0
[2022-06-22 20:26:38.067037] (error) [mplscc] 195C TG: MTC PD DISPW ( 2532) Freq: 8.56262e+08 P25P1 - GRP_V_CH_USR New Source 0
[2022-06-22 20:26:38.067131] (error) [mplscc] 195C TG: MTC PD DISPW ( 2532) Freq: 8.56262e+08 P25P1 - GRP_V_CH_USR New Source 0
[2022-06-22 20:26:38.086145] (error) [mplscc] 195C TG: MTC PD DISPW ( 2532) Freq: 856.262500 MHz Chan Grant SA: 154241
[2022-06-22 20:26:39.188686] (error) [mplscc] 195C TG: MTC PD DISPW ( 2532) Freq: 8.56262e+08 P25P1 - GRP_V_CH_USR New Source 154241
[2022-06-22 20:26:39.560565] (error) [mplscc] 195C TG: MTC PD DISPW ( 2532) Freq: 8.56262e+08 P25P1 - GRP_V_CH_USR New Source 154241
[2022-06-22 20:26:39.940334] (error) [mplscc] 195C TG: MTC PD DISPW ( 2532) Freq: 8.56262e+08 P25P1 - GRP_V_CH_USR New Source 0
[2022-06-22 20:26:40.121914] (error) [mplscc] 195C TG: MTC PD DISPW ( 2532) Freq: 8.56262e+08 P25P1 - GRP_V_CH_USR New Source 0
[2022-06-22 20:26:40.316568] (error) [mplscc] 195C TG: MTC PD DISPW ( 2532) Freq: 8.56262e+08 P25P1 - GRP_V_CH_USR New Source 0
[2022-06-22 20:26:40.405384] (error) [mplscc] 195C TG: MTC PD DISPW ( 2532) Freq: 8.56262e+08 P25P1 - GRP_V_CH_USR New Source 0
[2022-06-22 20:26:40.683649] (error) [mplscc] 195C TG: MTC PD DISPW ( 2532) Freq: 8.56262e+08 P25P1 - GRP_V_CH_USR New Source 0
[2022-06-22 20:26:40.707643] (error) [mplscc] 195C TG: MTC PD DISPW ( 2532) Freq: 856.262500 MHz Chan Grant SA: 169895
[2022-06-22 20:26:40.767539] (error) [mplscc] 195C TG: MTC PD DISPW ( 2532) Freq: 856.262500 MHz Chan Grant SA: 169895
[2022-06-22 20:26:40.872408] (error) [mplscc] 195C TG: MTC PD DISPW ( 2532) Freq: 8.56262e+08 P25P1 - GRP_V_CH_USR New Source 0
[2022-06-22 20:26:40.872664] (error) [mplscc] 195C TG: MTC PD DISPW ( 2532) Freq: 8.56262e+08 P25P1 - GRP_V_CH_USR New Source 0
[2022-06-22 20:26:41.061740] (error) [mplscc] 195C TG: MTC PD DISPW ( 2532) Freq: 8.56262e+08 P25P1 - GRP_V_CH_USR New Source 0
[2022-06-22 20:26:42.089530] (error) [mplscc] 195C TG: MTC PD DISPW ( 2532) Freq: 8.56262e+08 P25P1 - GRP_V_CH_USR New Source 169895
[2022-06-22 20:26:42.372853] (error) [mplscc] 195C TG: MTC PD DISPW ( 2532) Freq: 8.56262e+08 P25P1 - GRP_V_CH_USR New Source 169895
[2022-06-22 20:26:44.151175] (error) [mplscc] 195C TG: MTC PD DISPW ( 2532) Freq: 8.56262e+08 P25P1 - GRP_V_CH_USR New Source 169895
[2022-06-22 20:26:45.181031] (error) [mplscc] 195C TG: MTC PD DISPW ( 2532) Freq: 8.56262e+08 P25P1 - GRP_V_CH_USR New Source 0
[2022-06-22 20:26:45.274233] (error) [mplscc] 195C TG: MTC PD DISPW ( 2532) Freq: 8.56262e+08 P25P1 - GRP_V_CH_USR New Source 0
[2022-06-22 20:26:45.462676] (error) [mplscc] 195C TG: MTC PD DISPW ( 2532) Freq: 8.56262e+08 P25P1 - GRP_V_CH_USR New Source 0
[2022-06-22 20:26:45.646334] (error) [mplscc] 195C TG: MTC PD DISPW ( 2532) Freq: 8.56262e+08 P25P1 - GRP_V_CH_USR New Source 0
[2022-06-22 20:26:45.837110] (error) [mplscc] 195C TG: MTC PD DISPW ( 2532) Freq: 8.56262e+08 P25P1 - GRP_V_CH_USR New Source 0
[2022-06-22 20:26:45.930337] (error) [mplscc] 195C TG: MTC PD DISPW ( 2532) Freq: 8.56262e+08 P25P1 - GRP_V_CH_USR New Source 0
[2022-06-22 20:26:46.023214] (error) [mplscc] 195C TG: MTC PD DISPW ( 2532) Freq: 8.56262e+08 P25P1 - GRP_V_CH_USR New Source 0
[2022-06-22 20:26:47.050760] (error) [mplscc] 195C TG: MTC PD DISPW ( 2532) Freq: 8.56262e+08 P25P1 - GRP_V_CH_USR New Source 154241
[2022-06-22 20:26:47.424643] (error) [mplscc] 195C TG: MTC PD DISPW ( 2532) Freq: 8.56262e+08 P25P1 - GRP_V_CH_USR New Source 154241
[2022-06-22 20:26:48.833810] (error) [mplscc] 195C TG: MTC PD DISPW ( 2532) Freq: 8.56262e+08 P25P1 - GRP_V_CH_USR New Source 154241
[2022-06-22 20:26:49.113036] (error) [mplscc] 195C TG: MTC PD DISPW ( 2532) Freq: 8.56262e+08 P25P1 - GRP_V_CH_USR New Source 0
[2022-06-22 20:26:49.297586] (error) [mplscc] 195C TG: MTC PD DISPW ( 2532) Freq: 8.56262e+08 P25P1 - GRP_V_CH_USR New Source 0
[2022-06-22 20:26:49.493903] (error) [mplscc] 195C TG: MTC PD DISPW ( 2532) Freq: 8.56262e+08 P25P1 - GRP_V_CH_USR New Source 0
[2022-06-22 20:26:49.581115] (error) [mplscc] 195C TG: MTC PD DISPW ( 2532) Freq: 8.56262e+08 P25P1 - GRP_V_CH_USR New Source 0
[2022-06-22 20:26:49.772459] (error) [mplscc] 195C TG: MTC PD DISPW ( 2532) Freq: 8.56262e+08 P25P1 - GRP_V_CH_USR New Source 0
[2022-06-22 20:26:50.046860] (error) [mplscc] 195C TG: MTC PD DISPW ( 2532) Freq: 8.56262e+08 P25P1 - GRP_V_CH_USR New Source 0
[2022-06-22 20:26:50.143036] (error) [mplscc] 195C TG: MTC PD DISPW ( 2532) Freq: 8.56262e+08 P25P1 - GRP_V_CH_USR New Source 0
SO! It looks like the voice data that is sent along with the TDU, may actually be silence. This means it should be safe to terminate if we see any TDU come in... I think. I am going to look at the specs some more. There is also a good chance that there are differences in implementations.
That is super weird that there was no Channel Grant for the new Source. I wonder if it came in as a Channel Update message vs a Channel Grant? The update messages do not have a Src ID in them. Still - I thought all new units transmitting got a channel grant.
Luke, you're w - a - a - a - y - y beyond my education and pay scale now; however, is there something you can do to compare the last few versions of v3 to the latest versions? I still run v3 and do not see any problems between the transmissions.