Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

P25 Transmissions Bleeding Together #701

Closed
tadscottsmith opened this issue Jun 9, 2022 · 44 comments
Closed

P25 Transmissions Bleeding Together #701

tadscottsmith opened this issue Jun 9, 2022 · 44 comments

Comments

@tadscottsmith
Copy link
Contributor

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

@tadscottsmith
Copy link
Contributor Author

@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

@Dygear
Copy link
Contributor

Dygear commented Jun 10, 2022

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.

@tadscottsmith
Copy link
Contributor Author

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.

@robotastic
Copy link
Collaborator

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!

@tadscottsmith
Copy link
Contributor Author

[@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
Copy link

Dewey3 commented Jun 15, 2022

[@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!

@tadscottsmith
Copy link
Contributor Author

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.

@tadscottsmith
Copy link
Contributor Author

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

@Dewey3
Copy link

Dewey3 commented Jun 15, 2022

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.

@Dewey3
Copy link

Dewey3 commented Jun 15, 2022

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.

@Dewey3
Copy link

Dewey3 commented Jun 16, 2022

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.

@tadscottsmith
Copy link
Contributor Author

tadscottsmith commented Jun 17, 2022

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.

@Dewey3
Copy link

Dewey3 commented Jun 17, 2022

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.

@tadscottsmith
Copy link
Contributor Author

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.

@robotastic
Copy link
Collaborator

robotastic commented Jun 17, 2022 via email

@Dewey3
Copy link

Dewey3 commented Jun 17, 2022

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.

@tadscottsmith
Copy link
Contributor Author

@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

@tadscottsmith
Copy link
Contributor Author

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

@Dewey3
Copy link

Dewey3 commented Jun 17, 2022

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.

@Dygear
Copy link
Contributor

Dygear commented Jun 19, 2022

What is the JSON configuration needed for that level of logging? @tadscottsmith?

@tadscottsmith
Copy link
Contributor Author

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.

@robotastic
Copy link
Collaborator

@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

@Dewey3
Copy link

Dewey3 commented Jun 22, 2022

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.

@tadscottsmith
Copy link
Contributor Author

@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.

@robotastic
Copy link
Collaborator

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

@robotastic
Copy link
Collaborator

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

@tadscottsmith
Copy link
Contributor Author

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

@robotastic
Copy link
Collaborator

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.

Screen Shot 2022-06-22 at 9 55 07 PM

@robotastic
Copy link
Collaborator

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.

@Dewey3
Copy link

Dewey3 commented Jun 23, 2022

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.

@tadscottsmith
Copy link
Contributor Author

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.

@Dewey3 Are you in the Discord? If you message me, I can take a look and see if I see anything obvious.

@tadscottsmith
Copy link
Contributor Author

If I'm reading this correctly, it seems like if the system is setup in message trunking mode and using the direct call continuation method, that there could be multiple sources (tranmissions) on the traffic channel without additional explicit grants on the control channel. As long as the response was within the hang time, it would just continue sending grant updates.

Pages 74-76 explain (diagram is for control channel method and there is no diagram for direct method).
https://www.taitradioacademy.com/wp-content/uploads/2016/02/TRG-00001-01-M_Intro_to_P25.pdf

@robotastic
Copy link
Collaborator

robotastic commented Jul 2, 2022

Interesting!! that is a great find @tadscottsmith. It could be something like that. I wonder why the old system was working though? It was only getting the Src IDs from the control channel, and those only come on the Grant messages, not the Updates.

Are the transmission really short? Like there wouldn't be time for the Src ID to come over the Voice Channel?

@robotastic
Copy link
Collaborator

Still - There should be TDUs on the voice channel... but maybe in this mode there are less of them or they always have silent voice samples attached. I will go remove the check on the TDUs and just have them all be equal.

@Dewey3
Copy link

Dewey3 commented Jul 2, 2022

Interesting!! that is a great find @tadscottsmith. It could be something like that. I wonder why the old system was working though? It was only getting the Src IDs from the control channel, and those only come on the Grant messages, not the Updates.

Are the transmission really short? Like there wouldn't be time for the Src ID to come over the Voice Channel?

Thanks much @robotastic and @tadscottsmith for all that you do! As I mentioned, I don't know about the inner workings of trunking or TrunkRecorder, so I unfortunately can't comment there. However, I can say like TrunkRecorder v3, I don't think Unitrunker misses the data for any changes and transmissions on the same PG Co, MD P25P2-TDMA system, and I'm pretty sure that it gets its information from only the control channel.

@robotastic
Copy link
Collaborator

To be fair - the inner workings of Trunk Recorder are a bit of a mess! Thanks for putting up with it!

That was a great clue - it looks like I had actually changed the code so Src IDs were not being sent in from the Voice Channel. I just fixed that in the latest build.

@robotastic
Copy link
Collaborator

@tadscottsmith I also changed it so that the TDU flag will end a transmission even if there were audio samples that came in with it.

@tadscottsmith
Copy link
Contributor Author

Sounds great. Thanks for the updates! I'm out for a few days but will do some testing later this week or next. Enjoy the holiday! Perhaps @Dewey3 can pull the latest version and see if it's able to keep up on his busy system.

@tadscottsmith
Copy link
Contributor Author

@robotastic I took a look and can’t see any reason that the changes would impact the TGID. What indications were you seeing that the TGID was messed up? I can certainly dig deeper and find out.

@robotastic
Copy link
Collaborator

@tadscottsmith yea... I didn't see anything either, it was super weird! It could have been some weird compilation thing and it was building against an old library version or something.

I did find a fix, I think. The PTT packet gets sent every time someone keys their radio. It can be used to separate the transmissions... and it also has the SRC ID for the next transmission!! I was testing on the same system as @Dewey3 and I think it is working. Give the Master branch a try.

I am curious though on where you got those extra message types from, that you added in on your branch?

@tadscottsmith
Copy link
Contributor Author

They were in older versions of OP25. I went back to your v3.3.7 and it seems like OP25 used to update the SRC on many more message types, although mostly they are just idle messages or group voice channel user update messages. You should probably be safe just using the SRC from the voice frames, but I have noticed in my logging that occasionally it seems there's a few frames of voice with a SRC of 0 before the voice channel starts sending the real source.

@robotastic
Copy link
Collaborator

oh! That is genius! I didn't catch that it had changed on the OP25 side. Let me see if I can re-create what was happening, but use a test branch!:)

@Dewey3
Copy link

Dewey3 commented Jul 9, 2022

Thanks @robotastic - I built this version, but was only able to run it for 5 or 10 minutes today. Looking at a couple of the json files that contain multiple transmissions, that 5 or 10 minutes looks promising, so I can't wait until tomorrow to give it the full test. Just a side note... when I complete a build, I like to create an image file of the fresh build, so I will do a full clean up of the OS with autoremove --purge, autoclean, and clean. When I did that today, some packages got removed but I don't think that they're affecting the build. I'll find that out tomorrow also. Here's a screenshot of the removals:

image

@Dewey3
Copy link

Dewey3 commented Jul 9, 2022

There is still an occasional miss, but they are far and few... this version is working miles better at catching the SRCID, in fact, I sometimes see the new ID popup on Rdio a second or two before the transmission actually starts (could be the timing for the call grant). Concerning the packages that got removed with this version, it looks like that killed the "compressWav" function. While I have compressWav set to true, I have never seen anything other than a wav file. That's certainly NOT a problem since I can always rebuild electing to not remove those packages, or let Rdio do the compression for me, the latter is what I am doing for now.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

4 participants