Calls are out of Order

[UberPlexCa]

This is the same thing I posted on Gitter, there are multiple people in the thread reporting the same. This has only started say in the last 2-3 days and only seems to impact digital calls. Analog I have not heard the issue on yet.

I'm not sure if this makes sense and if some patch to linux did it or something else. I am getting calls out of order, a lot of them I hear a call, then hear the dispatcher calling for the unit and then the call continues which of course isn't the right order for a call.
I've increased my timeout from 4 to 5 seconds but I was wondering if anyone has any suggestions.

[johnrockie]

Yeah can confirm same issues since going from v3 to 4, specially the crosstalk where you hear both FD and PD on a single audio file. I'll try to get examples, the weird thing I have two systems in two different locations, both P25 II only difference is HackRF vs Airspy, HackRF one is the one with issues but I don't believe that's the issue. I provided something on #535 but will try to get some more.

[sally-yachts]

I experienced the same issue when testing an upgrade to 4.x. Here's some relevant messages from Gitter (thread from 8/13/21):

So actually I may not be fully converted after all. I'm going to setup another testbed, but i've got users reporting that transmissions within a file are ordered incorrectly - has anyone ever heard of something like this? The only thing that's changed is code upgrade and switching from a LimeSDR Mini to an Airspy.

(Note: I have since tested 4.x using the same LimeSDR Mini and still encountered this issue so I don't believe it to be an issue with the SDR itself)

From what I'm looking at it looks like the actual problem is that recorders don't seem to be tracking/releasing properly. Calls from different talkgroups are being merged in the same file.

An example of this can be seen here - https://tp-dev.atlscanner.com/audio/1e935f22-8fd3-41f9-8a6b-77bab69678b9/ . There are calls from multiple talkgroups in this one converstation, including mixing of fire and police calls. What's interesting is that the extra calls don't appear to be written to the metadata - it's like the WAV recorder just keeps getting fed data that should be going to another recorder process.

To make things even more interesting, that extra audio (like fire audio) destined for another recording process still appears to make it to the proper destination as well, resulting in radio transmissions being duplicated across active recorder processes. Real weird.

For reference the deployment having the issue is using latest docker image/build as of 8/13/2021, and the version that is working properly is commit 0b1719d from 8/13/2020.

[sally-yachts]

The inner workings are way over my head, but when looking through commits I found this one referencing the ability to ignore post-voice data; I wonder if that might be related somehow?

366cd3b

[robotastic]

Just to check a couple things - What type of system is it? If it is P25, is it a mix of TDMA and FDMA?
One thing to check, is the control channel decode rate. Maybe something changed in your reception? I am not sure how this would impact things, but worth seeing if there is a correlation. Could you add "controlWarnRate": -1, to the top level of the config.json file? It should be around 40 for a P25 system.

[robotastic]

Good spot @sally-yachts !!! that was actually a bad change. I backed it out a while ago though:

trunk-recorder/trunk-recorder/call.cc

Lines 344 to 352 in e1048cd

	/*long last_rx;
	if (get_recorder() && (last_rx = recorder->get_rx_status().last_update)) {
	BOOST_LOG_TRIVIAL(trace) << "temp.last_update: " << last_rx << " diff: " << time(NULL) - last_rx;
	return time(NULL) - last_rx;
	//last_update = temp.last_update;
	} else {*/
	BOOST_LOG_TRIVIAL(trace) << "last_update: " << last_update << " diff: " << time(NULL) - last_update;
	return time(NULL) - last_update;
	//}

There could be some other bug lurking... or there could be a case were I am not covering an error condition, like some control channel messages being missed.

[taclane]

I'm looking at a similar-ish issue with disjointed recordings in Conventional P25.

Is anyone else watching the trace logs when recordings start acting up? One thing I'm seeing is that calls can end with a ton of data still in the assembler output queue, which then gets pushed off to the next call. Here's an example from this morning:

[2021-12-02 10:23:34.831881] (trace)   P25 Frame Assembler - Amt Prod: 864 output_queue: 66816 noutput_items: 864
[2021-12-02 10:23:34.832675] (trace)   setting silence_frame_count 0 to d_silence_frames: 0
[2021-12-02 10:23:35.001142] (trace)   [test]    1C Call Length: 16.416s     Idle: false     Idle Count: 0
[2021-12-02 10:23:36.000214] (trace)   [test]    1C Call Length: 16.416s     Idle: false     Idle Count: 1
[2021-12-02 10:23:37.007234] (trace)   [test]    1C Call Length: 16.416s     Idle: false     Idle Count: 2
[2021-12-02 10:23:38.009259] (trace)   [test]    1C Call Length: 16.416s     Idle: false     Idle Count: 3
[2021-12-02 10:23:38.009450] (trace)   last_update: 1638458416 diff: 202
[2021-12-02 10:23:38.009396] (trace)   [test]    1C    TG:          2 (                 Police)    Freq: 455.375000 MHz    Concluding Recorded Call - Last Update: 202s    Call Elapsed: 202
[2021-12-02 10:23:38.009667] (error)   stop_recording() - stopping wavfile sink but recorder state is: 1

And the following call starts off with nearly ten seconds of audio already in the assembler queue:

[2021-12-02 10:23:46.134026] (trace)   P25 Frame Assembler - Amt Prod: 864 output_queue: 65952 noutput_items: 864
[2021-12-02 10:23:46.134191] (trace)   setting silence_frame_count 0 to d_silence_frames: 0
[2021-12-02 10:23:46.134740] (info)   [test]    1C    TG:          2    Freq: 455.375000 MHz    Starting new Transmission     Src ID:  1234325
[2021-12-02 10:23:46.309515] (trace)   P25 Frame Assembler - Amt Prod: 864 output_queue: 66528 noutput_items: 864
[2021-12-02 10:23:46.309644] (trace)   setting silence_frame_count 0 to d_silence_frames: 0

Audio from one call can end up spread across two or three others until the frame assembler has a chance to work that output queue back down to zero.

[robotastic]

Good catch @taclane I just added a change which should fix the samples backing up in the queue. OP25 had removed a forecast function - this helps make sure the processing keeps up by letting it know how often it will need to run. I made the change on master let me know if this helps fix things!

[UberPlexCa]

Good catch @taclane I just added a change which should fix the samples backing up in the queue. OP25 had removed a forecast function - this helps make sure the processing keeps up by letting it know how often it will need to run. I made the change on master let me know if this helps fix things!

I am running it on my 3 instances, seems ok so far.

[taclane]

It's looking good so far! I've watched about a dozen calls in the logs and output_queue hovers between 800-2500 before winding down to zero as the call times out.

Prior to the the forecast function being reintroduced, even calls starting with an empty queue could be anywhere between 5000-25000, with no guarantees that it could work through all the data before the call was terminated.

I'll check back in on the logs in the morning, but it does look like things are back to normal for me. Hopefully it was the root cause of audio crosstalk and related observations in this issue.

[taclane]

Checking back in after letting it run overnight. The recent commit seems to have eliminated time shifting and stopping wavfile sink but recorder state is: 1 errors for P25. Call audio now appears to remain in-sync with the metadata, and hasn't leaked into following transmissions.

[UberPlexCa]

I am seeing the same. I am going to close this now I think it can be reopened if it returns.

[robotastic]

Great to hear! I just made another change... instead of using a buffer and outputting at a constant rate, I change it to just output everything it has decoded directly to the wav file as it gets decoded. This should make it even tougher for something to get stuck in the buffer.