robotastic / trunk-recorder

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

Feature request: option to disable conversation recording #326

Open blantonl opened 4 years ago

blantonl commented 4 years ago

An option to turn the conversation recording feature on and off would be beneficial. The consolidation of conversations audio and metadata is difficult to work with in some architectures.

Individual clips for each call and associated metadata would be a great feature.

robotastic commented 4 years ago

This would be a pretty easy change - I think I can make it over the weekend.

blantonl commented 4 years ago

Checking in on this... any updates?

robotastic commented 4 years ago

Sorry - my coding has taken a dive. I am spending most of my free time herding kids. This is pretty straight forward. I will try to wrap it up this weekend.

blantonl commented 4 years ago

Wanted to ping you and check in on this again for status?

robotastic commented 4 years ago

I am hoping to get PRs #329 and #330 in this weekend. If that goes smoothly, I will roll this in too.

robotastic commented 4 years ago

Hmmm... this may not be as simple as I thought. Generally multiple Grant messages are sent out when a new call is started, so I will have to add in some logic. I might be able to simple do if you get a new grant message and the time of the recording is greater than 1 sec then start a new recording. I could also see if there is a way to look at the source ID of the transmitter... that could get weird in non-P25 systems. There is also the problem that you will probably end up with some of the next transmission in the previous recording because you have to let the audio stream through to make sure nothing is left in the buffers. I will have to poke at this a little.

EricTendian commented 4 years ago

What I've found after testing out MDC1200 source logging for a bit is that splitting into individual calls would rely on knowing whether the MDC1200 chirp is a leading or trailing one, to avoid transmissions being attributed to the wrong source.

I wonder if another way to solve this, at least for cases where it's troublesome within the process of making the recording, is to read the call metadata file and use sox/ffmpeg after the fact to cut up the audio file based on source timestamps in the metadata. For example, if I know my system uses a trailing MDC1200 code, I could theoretically cut out an individual transmission from when a previous user's chirp was heard until this user's chirp was heard. Then, each of those clips could be uploaded one-by-one. For integrating with the existing call uploading process, this would likely be occurring as an alternative to the current m4a encoding command, generating an array of call info structs and associated m4a files.

JoeGilkey commented 4 years ago

@EricTendian on the MDC PTT opcode there is a flag in the args that differentiates if it is a pre-PTT or post-PTT. In the decoder I can add these as different signal types. Those signals can then be used to create a new file or end the existing file.

EricTendian commented 4 years ago

@JoeGilkey interesting, I didn't realize that. That would be helpful, since currently OpenMHz is treating post-PTTs as if they were pre-PTT, not able to handle the source timestamps at the end of transmissions.

blantonl commented 4 years ago

I wanted to revive this again as this issue is becoming more and more critical to address duplicate call handing from multiple sites and different capture nodes for wide area systems.

Trunk-Recorder seems to take a pretty arbitrary approach to recording conversations vs individual calls, and even though the metadata is captured by conversation it is becoming more and more difficult to manage "conversations" vs "calls" - conversations are pretty arbitrary and difficult to manage in structured environments.

blantonl commented 4 years ago

It might also be helpful to rope in some of the other tickets with regards to encrypted calls and how TR handles those - in mixed environments TR doesn't ignore encrypted calls if the start of the conversation is in the clear.

I think it is going to be worth the time and effort to eliminate conversation handling unless it is explicitly enabled.

natecarlson commented 3 years ago

I agree that this would be a useful feature for many cases -- I'd love to see the conversation metadata stored but with individual calls tracked within. Could do server-side splitting of the current conversations. but it seems a bit silly to have the recorder combine and then the server split it back out. :) I'm currently looking into integrating with speech to text transcription, and it looks like having individual speakers in separate files would make it easier.

Looking at the source code, it looks like the simplest way to implement this would be to decouple the concept of a 'call' (which is the current conversation-style) from the recordings.. unless someone has a different suggestion?

Hmm, I should test and see what happens if we just set callTimeout to next to nothing. Now that I'm actually sending my scanner to Broadcastify Calls and OpenMHz instead of just my private server, it's a bit harder to play with the code though! :) I'll have to pick up a few more RTL-SDR's and antennas..

natecarlson commented 3 years ago

OK - setting callTimeout to -1 or 0 causes each call to get chopped into tiny increments, not good. :)

Setting it to 1 does end up in conversations with delays over a second being broken up.. but a lot of responses are faster than one second. Because we use C's time_t, which is only precise to a second, can't do something silly like set this to one microsecond.

Might look and see how hard it'd be to overhaul things to use millisecond or microsecond resolution..

kcwebby commented 3 years ago

The problem with this concept is that there is not a message from the system that definitively separates between one transmission and another. Sometimes they occur on the same frequency, without an additional grant, and sometimes they are recycled to a separate frequency with a new grant. Add in patches and all of the other methods required to try and track this, and it gets very complex/convoluted very quickly.

To do this reliably, you would need the trunked radio system to delineate between transmissions in any particular "call" But right now, the P25 protocol doesn't do any signalling when one person ends and the messages for a subscriber unit starting to transmit can be one of many things. Trunk recorder follows the call "build up" and then follows it until it times out, while it records the unit ID's that it see's talking, it doesn't track the transmissions like that.

This would be an extremely significant rewrite of alot of the code to even start to get this to function.

On Fri, Oct 30, 2020 at 12:58 PM Nate Carlson notifications@github.com wrote:

OK - setting callTimeout to -1 or 0 causes each call to get chopped into tiny increments, not good. :)

Setting it to 1 does end up in conversations with delays over a second being broken up.. but a lot of responses are faster than one second. Because we use C's time_t, which is only precise to a second, can't do something silly like set this to one microsecond.

Might look and see how hard it'd be to overhaul things to use millisecond or microsecond resolution..

— You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub https://github.com/robotastic/trunk-recorder/issues/326#issuecomment-719707595, or unsubscribe https://github.com/notifications/unsubscribe-auth/ACSNSASMTI5BVWV7CFANJXTSNL5DLANCNFSM4LUHVOOA .

natecarlson commented 3 years ago

Oh, yikes! Yeah, I haven't looked at the code or p25 protocol in significant detail yet; I assumed that since it logs the unit IDs for each segment that those were readily available during the call flow already, but sounds like that isn't the case.

I'll have to dig in some more just to understand what I can!

robotastic commented 3 years ago

@natecarlson interesting thought on changing the timeout. On the P25/Smartnet control channels, you get 30-40 messages per second. The Channel Grant messages for the different calls are what reset that timeout. You maybe able to go down to 0.5 seconds for a timeout, but not much lower because you don't get that many Grant messages per second.

The real problem is that an End Call message doesn't does not go out over the Trunking Control Channel ( I can go double check the specs).

However there is a second source of control messages and that is on the Voice Channel. There is an End Call message that gets broadcast there... I think. It is not super simple to make use of it though. There is a long pipeline for decoding audio, with buffers in between. The initial P25 decoding happens near the start, so when a End Call message comes in, there could still be audio from that transmission that is still being decoded. I think for it to work, all of the Trunking messages recieved on the Voice Channel would need to be attached to the voice data, as meta data and processed as part of the flow. This we be a bit of intensive surgery, but it may not be impossible. This is already done for the Source IDs, which are decoded off the voice channel.

Anyhow... I think this maybe possible, but not easy. I am game to give it a shot though. We should be able to use the same Calls structure to mange the metadata around a transmission.

robotastic commented 3 years ago

It does look like OP25 is already decoding the Terminator codes on the Voice channels: https://github.com/robotastic/trunk-recorder/blob/5305e8f5320315094bcb646e571f79e5e4f9acb2/lib/op25_repeater/lib/p25p2_tdma.cc#L152 https://github.com/robotastic/trunk-recorder/blob/bfb41e52a751a19bb70efb423fe47f3aea5a24b2/lib/op25_repeater/lib/p25p1_fdma.cc#L383

The trick will be having these messages passed through to the right spots and making sure all the audio gets processed. The messages also get repeated a lot, so we also have to make sure they are only handled once.

natecarlson commented 3 years ago

Awesome, thanks for the details! I'll try to dig into this a bit when I've got some time. I think my first steps will be to get a test scanner set up that can receive the full 6mhz off my repeater (gotta get more RTLs!), find a single TG that gets consistent calls and set up the scanner to only that TG, and then add a bunch of debug logging to help understand what is already available to us.

If it is going to take extensive changes, I'm probably not the best person to make them (i do a lot of architecture work, but came up from the system administration side instead of the programming side.. I can certainly understand what the code is doing, but especially in C my code isn't elegant!) - but we'll see where it goes. Really, that's my long winded way of making sure not to make anyone with coding skills and interest in working on this think that the task has been claimed already. :)

robotastic commented 3 years ago

Cool - I added a bunch of messages on the Analog Squelch branch.

It looks like Channel Grant messages on the Trunk Control Channel are completely seperate from the control messages on the voice channel. So you can have an End message come over on the voice channel and then get Trunk Control grant messages after that. Basically it looks like the Trunk system will dedicate a Channel to a talkgroup. Multiple Transmissions may start and stop on that freq. We could have it that a unique WAV file is created for each transmission and a Call represents a group of unique Transmissions.

Basically, the Trunking Control message govern the creation of a Call which tracks the Grant of a frequency to a talkgroup. A Recorder would be Started to monitor a Freq for that Talkgroup. The Recorder would automatically create a new WAV file for each transmission, and associate each Transmission with that Call. When that Channel Grant times out, that Call would be over and that group of transmission WAV files would be uploaded.

So - the Recorder would become smarter and automatically create new WAV files for each transmission. Instead of an array of Src IDs, there would be an array of recordings with the associated src id.

natecarlson commented 3 years ago

I see that commit - awesome!

And that sounds like exactly what I'd be looking for. Not sure if that would match up with the use case @blantonl has in mind or not, as this method wouldn't necessarily result in individual transmissions being uploaded to the server any faster than they are today.

Should have another pair of RTL's on my doorstep sometime tomorrow, assuming Amazon does their job! That'll give me a total of three to play with on a development box.

robotastic commented 3 years ago

I have some very preliminary code working. Right now it just creates separate wav file for each transmission. Upload is probably broken and so is the JSON file stuff.

Still if someone is able to give the analog_squelch branch a try and see if it chops up P25 system calls correctly that would be cool.

I don't think it works with SmartNet because it doesn't look like they send out the call termination message on the voice channel.

natecarlson commented 3 years ago

That is awesome!!

My additional rtl-sdr's showed up today; once I get a test system built and validated I will give this a try.

(As I've noted elsewhere I'm all P25 at my area for LE. There may be other SmartNet and analog systems in the area, but if there are I haven't tried to find 'em.)

natecarlson commented 3 years ago

Got the RTL's set up and tuned (yay), and have them recording the same data as my production system now. Will check in later to see how things look.

natecarlson commented 3 years ago

Found an issue.. here's the srclist for a call on my prod system.. "srcList": [ {"src": 135702, "time": 1604323391, "pos": 0.000000, "emergency": 0, "signal_system": "p25", "tag": ""}, {"src": 131428, "time": 1604323395, "pos": 3.960000, "emergency": 0, "signal_system": "p25", "tag": ""}, {"src": 131410, "time": 1604323397, "pos": 4.320000, "emergency": 0, "signal_system": "p25", "tag": ""}, {"src": 135702, "time": 1604323402, "pos": 8.820000, "emergency": 0, "signal_system": "p25", "tag": ""} ],

..same from the test system: "srcList": [ {"src": 135702, "time": 1604323391, "pos": 0.000000, "emergency": 0, "signal_system": "p25", "tag": ""}, {"src": 131428, "time": 1604323395, "pos": 3.780000, "emergency": 0, "signal_system": "p25", "tag": ""}, {"src": 131410, "time": 1604323396, "pos": 0.360000, "emergency": 0, "signal_system": "p25", "tag": ""}, {"src": 135702, "time": 1604323402, "pos": 4.500000, "emergency": 0, "signal_system": "p25", "tag": ""} ],

First note is that the position is being reset on the test system -- no big deal (you mentioned upload/json are probably busted), but just wanted to note it.

Then, looking at the audio output files from the test system:

-rw-r--r-- 1 nc nc 72044 Nov  2 07:23 4302-1604323391-131410_855987500.wav
-rw-r--r-- 1 nc nc  5804 Nov  2 07:23 4302-1604323391-131428_855987500.wav
-rw-r--r-- 1 nc nc 63404 Nov  2 07:23 4302-1604323391-135702_855987500.wav

...we've only got three files - looks like if a unit transmits twice it only writes out one file right now?

If I listen to the original file (4302-1604323391_855987500.m4a), I hear:

Never hear the message from 131428, looks like it's a short transmission that doesn't have actual content.

Listening to the files from the split recording..

So - need to index the files, or include another 'current' timestamp for each of the unit recordings (might make the most sense to keep them in order?)

natecarlson commented 3 years ago

Added a quick patch:

diff --git a/trunk-recorder/call.cc b/trunk-recorder/call.cc
index 877abd3..e0de625 100644
--- a/trunk-recorder/call.cc
+++ b/trunk-recorder/call.cc
@@ -11,6 +11,7 @@

 void Call::create_filename() {
   tm *ltm = localtime(&start_time);
+  current_time = time(NULL);
   long current_source_id = get_current_source();
   std::stringstream path_stream;

@@ -19,7 +20,7 @@ void Call::create_filename() {
   boost::filesystem::create_directories(path_stream.str());

   int nchars;
-  nchars = snprintf(filename, 255, "%s/%ld-%ld-%ld_%.0f.wav", path_stream.str().c_str(), talkgroup, start_time, current_source_id, curr_freq);
+  nchars = snprintf(filename, 255, "%s/%ld-%ld-%ld-%ld_%.0f.wav", path_stream.str().c_str(), talkgroup, start_time, current_time, current_source_id, curr_freq);

   if (nchars >= 255) {
     BOOST_LOG_TRIVIAL(error) << "Call: Path longer than 255 charecters";
@@ -30,7 +31,7 @@ void Call::create_filename() {
     BOOST_LOG_TRIVIAL(error) << "Call: Path longer than 255 charecters";
   }

-  nchars = snprintf(converted_filename, 255, "%s/%ld-%ld_%.0f.m4a", path_stream.str().c_str(), talkgroup, start_time, curr_freq);
+  nchars = snprintf(converted_filename, 255, "%s/%ld-%ld-%ld-%ld_%.0f.m4a", path_stream.str().c_str(), talkgroup, start_time, current_time, current_source_id, curr_freq);
   if (nchars >= 255) {
     BOOST_LOG_TRIVIAL(error) << "Call: Path longer than 255 charecters";
   }
diff --git a/trunk-recorder/call.h b/trunk-recorder/call.h
index ed79e07..1b946da 100644
--- a/trunk-recorder/call.h
+++ b/trunk-recorder/call.h
@@ -132,6 +132,7 @@ protected:
   int idle_count;
   time_t stop_time;
   time_t start_time;
+  time_t current_time;
   bool debug_recording;
   bool sigmf_recording;
   bool encrypted;

EDIT: Ignore the blank file thing I'm discussing below, it seems to be an artifact of how I'm playing the files over the network to my laptop. The files play fine from the zip I uploaded! Looking at it.

..and it looks better. srcList: "srcList": [ {"src": 561078, "time": 1604324858, "pos": 0.000000, "emergency": 0, "signal_system": "p25", "tag": ""}, {"src": 561100, "time": 1604324860, "pos": 1.800000, "emergency": 0, "signal_system": "p25", "tag": ""}, {"src": 561078, "time": 1604324865, "pos": 1.980000, "emergency": 0, "signal_system": "p25", "tag": ""}, {"src": 561100, "time": 1604324869, "pos": 2.700000, "emergency": 0, "signal_system": "p25", "tag": ""} ],

-rw-r--r-- 1 nc nc 29K Nov  2 07:47 33404-1604324858-1604324858-561078_851375000.wav
-rw-r--r-- 1 nc nc 31K Nov  2 07:47 33404-1604324858-1604324861-561100_851375000.wav
-rw-r--r-- 1 nc nc 43K Nov  2 07:47 33404-1604324858-1604324865-561078_851375000.wav
-rw-r--r-- 1 nc nc 15K Nov  2 07:47 33404-1604324858-1604324869-561100_851375000.wav
-rw-r--r-- 1 nc nc 701 Nov  2 07:47 33404-1604324858_851375000.json

Here's the srcList from my prod system: "srcList": [ {"src": 561078, "time": 1604324858, "pos": 0.000000, "emergency": 0, "signal_system": "p25", "tag": ""}, {"src": 561100, "time": 1604324860, "pos": 1.800000, "emergency": 0, "signal_system": "p25", "tag": ""}, {"src": 561078, "time": 1604324865, "pos": 3.780000, "emergency": 0, "signal_system": "p25", "tag": ""}, {"src": 561100, "time": 1604324869, "pos": 6.480000, "emergency": 0, "signal_system": "p25", "tag": ""} ],

The first three calls have similar audio to the segments of the standard file - however, the last call appears to just be someone keying the transmit key and letting go without saying anything.. on the production file you can hear that, 33404-1604324858-1604324869-561100_851375000.wav doesn't appear to have anything audible in it.

Another call (json from prod system): "srcList": [ {"src": 100526, "time": 1604325143, "pos": 0.000000, "emergency": 0, "signal_system": "p25", "tag": ""}, {"src": 104016, "time": 1604325146, "pos": 1.440000, "emergency": 0, "signal_system": "p25", "tag": ""}, {"src": 100526, "time": 1604325148, "pos": 2.700000, "emergency": 0, "signal_system": "p25", "tag": ""}, {"src": 104016, "time": 1604325153, "pos": 5.760000, "emergency": 0, "signal_system": "p25", "tag": ""} ],

Files from split:

nc@teststorage02:~/trunk-recorder/recordings/scarmer2/2020/11/2$ ls -l 54-1604325143*
-rw-r--r-- 1 nc nc 23084 Nov  2 07:52 54-1604325143-1604325143-100526_851375000.wav
-rw-r--r-- 1 nc nc 20204 Nov  2 07:52 54-1604325143-1604325146-104016_851375000.wav
-rw-r--r-- 1 nc nc 49004 Nov  2 07:52 54-1604325143-1604325148-100526_851375000.wav
-rw-r--r-- 1 nc nc 28844 Nov  2 07:52 54-1604325143-1604325153-104016_851375000.wav
-rw-r--r-- 1 nc nc   698 Nov  2 07:52 54-1604325143_851375000.json

On this one, the second recording doesn't have any audible audio.. weird! Probably a race issue in the recording somewhere or something?

Log file attached (logentries.log) - note that there are other recordings happening at the same time too.. pertinent section, I think? (Again, full log attached - this is just small chunks.)

[2020-11-02 07:52:26.698145]:  [0]-[  : Pos - 11520 offset: 0 :
[2020-11-02 07:52:26.698239]:  [1]-[  : Pos - 11520 offset: 0 :
[2020-11-02 07:52:26.698289]:  [2]-[  : Pos - 11520 offset: 0 :
[2020-11-02 07:52:26.698329]:  [3]-[  : Pos - 11520 offset: 0 :
[2020-11-02 07:52:26.698366]:  [4]-[  : Pos - 11520 offset: 0 :
[2020-11-02 07:52:26.698403]:  [5]-[  : Pos - 11520 offset: 0 :
[2020-11-02 07:52:26.698440]:  [6]-[  : Pos - 11520 offset: 0 :
[2020-11-02 07:52:26.698478]:  [7]-[  : Pos - 11520 offset: 0 :
[2020-11-02 07:52:26.698871]:  Skipping to next file, Call Src:  104016
[2020-11-02 07:52:26.699184]: wav wrote: 1440 to: /home/nc/trunk-recorder/recordings/scarmer2/2020/11/2/54-1604325143-1604325146-104016_851375000.wav from source: 0
[2020-11-02 07:52:26.764782]: [scarmer2]        TG:         54 (^[[35m           MSP 2500 DSP^[[0m)     Freq: 851.375000 MHz    Update! 851.375000 MHz  Elapsed: 3s     Since update: 0s
[2020-11-02 07:52:26.889918]: wav wrote: 1440 to: /home/nc/trunk-recorder/recordings/scarmer2/2020/11/2/54-1604325143-1604325146-104016_851375000.wav from source: 0
[2020-11-02 07:52:27.077804]: wav wrote: 1440 to: /home/nc/trunk-recorder/recordings/scarmer2/2020/11/2/54-1604325143-1604325146-104016_851375000.wav from source: 0
[2020-11-02 07:52:27.139477]: [scarmer2]        TG:         54 (^[[35m           MSP 2500 DSP^[[0m)     Freq: 851.375000 MHz    Update! 851.375000 MHz  Elapsed: 4s     Since update: 1s
[2020-11-02 07:52:27.264449]: wav wrote: 864 to: /home/nc/trunk-recorder/recordings/scarmer2/2020/11/2/54-1604325143-1604325146-104016_851375000.wav from source: 0
[2020-11-02 07:52:27.268472]: wav wrote: 864 to: /home/nc/trunk-recorder/recordings/scarmer2/2020/11/2/54-1604325143-1604325146-104016_851375000.wav from source: 0
[2020-11-02 07:52:27.392266]: [scarmer2]        TG:         54 (^[[35m           MSP 2500 DSP^[[0m)     Freq: 851.375000 MHz    Update! 851.375000 MHz  Elapsed: 4s     Since update: 0s
[2020-11-02 07:52:27.455112]: wav wrote: 1728 to: /home/nc/trunk-recorder/recordings/scarmer2/2020/11/2/54-1604325143-1604325146-104016_851375000.wav from source: 0
[2020-11-02 07:52:27.700430]: wav wrote: 1728 to: /home/nc/trunk-recorder/recordings/scarmer2/2020/11/2/54-1604325143-1604325146-104016_851375000.wav from source: 0
[2020-11-02 07:52:27.766698]: [scarmer2]        TG:         54 (^[[35m           MSP 2500 DSP^[[0m)     Freq: 851.375000 MHz    Update! 851.375000 MHz  Elapsed: 4s     Since update: 0s
[2020-11-02 07:52:27.811411]: Call Terminated, NO amount produced: 0 SRC: 0 n written 754560
[2020-11-02 07:52:27.811782]: Call Terminated, NO amount produced: 0 SRC: 0 n written 754560
[2020-11-02 07:52:27.886262]: wav wrote: 576 to: /home/nc/trunk-recorder/recordings/scarmer2/2020/11/2/54-1604325143-1604325146-104016_851375000.wav from source: 0
[2020-11-02 07:52:27.948993]: [scarmer2]        TG:         54 (^[[35m           MSP 2500 DSP^[[0m)     Freq: 851.375000 MHz    Update! 851.375000 MHz  Elapsed: 4s     Since update: 0s
[2020-11-02 07:52:28.141113]: [scarmer2]        TG:         54 (^[[35m           MSP 2500 DSP^[[0m)     Freq: 851.375000 MHz    Update! 851.375000 MHz  Elapsed: 5s     Since update: 1s
[2020-11-02 07:52:28.141330]: [scarmer2]        TG:         54 (^[[35m           MSP 2500 DSP^[[0m)     Freq: 851.375000 MHz    Update! 851.375000 MHz  Elapsed: 5s     Since update: 0s
[2020-11-02 07:52:28.323286]: [scarmer2]        TG:         54 (^[[35m           MSP 2500 DSP^[[0m)     Freq: 851.375000 MHz    Update! 851.375000 MHz  Elapsed: 5s     Since update: 0s
[2020-11-02 07:52:28.323526]: [scarmer2]        TG:         54 (^[[35m           MSP 2500 DSP^[[0m)     Freq: 851.375000 MHz    Update! 851.375000 MHz  Elapsed: 5s     Since update: 0s
[2020-11-02 07:52:28.515490]: [scarmer2]        TG:         54 (^[[35m           MSP 2500 DSP^[[0m)     Freq: 851.375000 MHz    Update! 851.375000 MHz  Elapsed: 5s     Since update: 0s
[2020-11-02 07:52:28.826423]:  [0]-[  : Pos - 10080 offset: 0 :
[2020-11-02 07:52:28.826520]:  [1]-[  : Pos - 10080 offset: 0 :
[2020-11-02 07:52:28.826569]:  [2]-[  : Pos - 10080 offset: 0 :
[2020-11-02 07:52:28.826980]:  Skipping to next file, Call Src:  100526

Attached the files for this call from my standard/prod and the new system: files-to-compare.zip

robotastic commented 3 years ago

Interesting! yes - since the file writing is now driven by the WAV Sink, samples have to come through for a new file to be created. It is also possible that the file was less than 1 Sec and automatically deleted. I have been doing some work on adding a flag to the config file. I can upload the change in a little. I was also looking at a different approach, where a new Call is created everytime the Call Source changes. I think the timing may line up so that everything is always written to the WAV file before a new speaker starts. I am not sure though...

natecarlson commented 3 years ago

I'll have to review the audio now that it's been running for awhile, but seems like the splitting with this solution is accurate. Downside is that it does require changes to the uploader and (depending on how it's done) the server side. New call would have the benefit of being 100% compatible with existing software.. but wouldn't be able to pass along conversation info.

I'll review more audio tomorrow; if you push more code you want tested just holler!

natecarlson commented 3 years ago

With the current analog_squelch branch, which is splitting via the wav sink, plus my patch to add the current timestamp to the filename of the wav file. Note that I understand that there haven't been any changes made to get the json file working as expected - just adding my notes on the current behavior here. :)

Here's json for one long conversation with the filenames manually added to each srclist..

{
  "freq": 852938000,
  "start_time": 1604380867,
  "stop_time": 1604380909,
  "emergency": 0,
  "talkgroup": 4826,
  "srcList": [
    {
      "src": 140988,
      "time": 1604380867,
      "filename": "4826-1604380867-1604380867-140988_851375000.wav",
      "pos": 0,
      "emergency": 0,
      "signal_system": "p25",
      "tag": ""
    },
    {
      "src": 139421,
      "time": 1604380873,
      "filename": "4826-1604380867-1604380873-139421_851375000.wav",
      "pos": 4.14,
      "emergency": 0,
      "signal_system": "p25",
      "tag": ""
    },
    {
      "src": 140988,
      "time": 1604380876,
      "filename": "4826-1604380867-1604380876-140988_851375000.wav",
      "pos": 1.98,
      "emergency": 0,
      "signal_system": "p25",
      "tag": ""
    },
    {
      "src": 139421,
      "time": 1604380883,
      "filename": "4826-1604380867-1604380884-139421_851375000.wav",
      "pos": 5.76,
      "emergency": 0,
      "signal_system": "p25",
      "tag": ""
    },
    {
      "src": 140988,
      "time": 1604380885,
      "filename": "4826-1604380867-1604380886-140988_851375000.wav",
      "pos": 1.44,
      "emergency": 0,
      "signal_system": "p25",
      "tag": ""
    },
    {
      "src": 139422,
      "time": 1604380889,
      "filename": "4826-1604380867-1604380889-139422_852937500.wav",
      "pos": 1.44,
      "emergency": 0,
      "signal_system": "p25",
      "tag": ""
    },
    {
      "src": 140988,
      "time": 1604380892,
      "filename": "4826-1604380867-1604380892-140988_852937500.wav",
      "pos": 2.34,
      "emergency": 0,
      "signal_system": "p25",
      "tag": ""
    },
    {
      "src": 139422,
      "time": 1604380895,
      "filename": "4826-1604380867-1604380896-139422_852937500.wav",
      "pos": 1.44,
      "emergency": 0,
      "signal_system": "p25",
      "tag": ""
    },
    {
      "src": 140988,
      "time": 1604380902,
      "filename": "4826-1604380867-1604380903-140988_852937500.wav",
      "pos": 6.48,
      "emergency": 0,
      "signal_system": "p25",
      "tag": ""
    }
  ],
  "freqList": [
    {
      "freq": 851375000,
      "time": 1604380867,
      "pos": 0,
      "len": 0,
      "error_count": 0,
      "spike_count": 0
    },
    {
      "freq": 852937500,
      "time": 1604380889,
      "pos": 1.44,
      "len": 99200,
      "error_count": 135,
      "spike_count": 9
    }
  ]
}
natecarlson commented 3 years ago

Pushed some changes I've made here: https://github.com/natecarlson/trunk-recorder/tree/split_recordings_nate

I'm pulling the call time from the source now, which makes it consistent.. and adding the frequency to the source info that gets written in the json - this would theoretically give an upload script enough info to construct the filename for that individual transmission.

robotastic commented 3 years ago

Awesome testing @natecarlson !! I haven't rolled in your changes yet. Can you give the current branch a test first? I added a flag for the config.json file called, transmissionMode that can be set true or false and it is defined for each system. If transmissionMode is true, it will listen to the voice channel for the end of transmission, if transmissionMode is false, it will listen for a change in Source on the trunk channel and start a new recording.

If you can give both modes a try, that would be awesome. I think the Call approach would be easier since the changes would be smaller.

natecarlson commented 3 years ago

Just pulled these changes in to test.. currently running with transmissionMode set to true, some first thoughts:

{
  "freq": 852938000,
  "start_time": 1604504965,
  "stop_time": 1604505000,
  "emergency": 0,
  "talkgroup": 4826,
  "srcList": [
    {
      "src": 140982,
      "time": 1604504965,
      "pos": 0,
      "emergency": 0,
      "signal_system": "p25",
      "tag": ""
    },
    {
      "src": 136440,
      "time": 1604504968,
      "pos": 2.34,
      "emergency": 0,
      "signal_system": "p25",
      "tag": ""
    },
    {
      "src": 140982,
      "time": 1604504973,
      "pos": 3.6,
      "emergency": 0,
      "signal_system": "p25",
      "tag": ""
    },
    {
      "src": 136440,
      "time": 1604504977,
      "pos": 2.7,
      "emergency": 0,
      "signal_system": "p25",
      "tag": ""
    },
    {
      "src": 139422,
      "time": 1604504986,
      "pos": 6.12,
      "emergency": 0,
      "signal_system": "p25",
      "tag": ""
    },
    {
      "src": 140982,
      "time": 1604504986,
      "pos": 6.12,
      "emergency": 0,
      "signal_system": "p25",
      "tag": ""
    }
  ],
  "freqList": [
    {
      "freq": 852937500,
      "time": 1604504965,
      "pos": 0,
      "len": 171904,
      "error_count": 90,
      "spike_count": 6
    }
  ],
  "transmissionList": [
    {
      "src": 140982,
      "startTime": 1604504936,
      "stopTime": 1604504937,
      "filename": "/home/nc/trunk-recorder/recordings/scarmer2/2020/11/4/2700-1604504936-112901_851125000.wav"
    },
    {
      "src": 140982,
      "startTime": 1604504965,
      "stopTime": 1604504968,
      "filename": "/home/nc/trunk-recorder/recordings/scarmer2/2020/11/4/4826-1604504965-140982_852937500.wav"
    },
    {
      "src": 136440,
      "startTime": 1604504969,
      "stopTime": 1604504972,
      "filename": "/home/nc/trunk-recorder/recordings/scarmer2/2020/11/4/4826-1604504965-136440_852937500.wav"
    },
    {
      "src": 140982,
      "startTime": 1604504974,
      "stopTime": 1604504976,
      "filename": "/home/nc/trunk-recorder/recordings/scarmer2/2020/11/4/4826-1604504965-140982_852937500.wav"
    },
    {
      "src": 136440,
      "startTime": 1604504978,
      "stopTime": 1604504984,
      "filename": "/home/nc/trunk-recorder/recordings/scarmer2/2020/11/4/4826-1604504965-136440_852937500.wav"
    },
    {
      "src": 140982,
      "startTime": 1604504986,
      "stopTime": 1604504988,
      "filename": "/home/nc/trunk-recorder/recordings/scarmer2/2020/11/4/4826-1604504965-140982_852937500.wav"
    },
    {
      "src": 140982,
      "startTime": 1604504990,
      "stopTime": 1604504992,
      "filename": "/home/nc/trunk-recorder/recordings/scarmer2/2020/11/4/4826-1604504965-140982_852937500.wav"
    }
  ]
}
natecarlson commented 3 years ago

It looks like the last transmission of a call is leaking into the next call.. IE:

No transmission in this call:

nc@teststorage02:~/trunk-recorder/trunk-recorder$ cat ../recordings/scarmer2/2020/11/4/4826-1604507737_854587500.json
{
"freq": 8.54588e+08,
"start_time": 1604507737,
"stop_time": 1604507746,
"emergency": 0,
"talkgroup": 4826,
"srcList": [ {"src": 140982, "time": 1604507737, "pos": 0.000000, "emergency": 0, "signal_system": "p25", "tag": ""} ],
"freqList": [ { "freq": 854587500.000000, "time": 1604507737, "pos": 0.000000, "len": 25232.000000, "error_count": 166.000000, "spike_count": 22.000000}],
"transmissionList": [  ]
}

But a matching transmission is in this call - and the last transmission of this call isn't present here either..

nc@teststorage02:~/trunk-recorder/trunk-recorder$ cat ../recordings/scarmer2/2020/11/4/4828-1604507736_853225000.json
{
"freq": 8.53225e+08,
"start_time": 1604507736,
"stop_time": 1604507756,
"emergency": 0,
"talkgroup": 4828,
"srcList": [ {"src": 139892, "time": 1604507736, "pos": 0.000000, "emergency": 0, "signal_system": "p25", "tag": ""}, {"src": 140985, "time": 1604507743, "pos": 5.220000, "emergency": 0, "signal_system": "p25", "tag": ""}, {"src": 139892, "time": 1604507747, "pos": 2.880000, "emergency": 0, "signal_system": "p25", "tag": ""}, {"src": 140985, "time": 1604507750, "pos": 2.160000, "emergency": 0, "signal_system": "p25", "tag": ""} ],
"freqList": [ { "freq": 853225000.000000, "time": 1604507736, "pos": 0.000000, "len": 90640.000000, "error_count": 90.000000, "spike_count": 6.000000}],
"transmissionList": [ {"src": 139892, "startTime": 1604507640, "stopTime": 1604507642, "filename": "/home/nc/trunk-recorder/recordings/scarmer2/2020/11/4/4826-1604507640-1604507640-140982_853375000.wav"}, {"src": 139892, "startTime": 1604507737, "stopTime": 1604507742, "filename": "/home/nc/trunk-recorder/recordings/scarmer2/2020/11/4/4828-1604507736-1604507736-139892_853225000.wav"}, {"src": 140985, "startTime": 1604507744, "stopTime": 1604507746, "filename": "/home/nc/trunk-recorder/recordings/scarmer2/2020/11/4/4828-1604507736-1604507743-140985_853225000.wav"}, {"src": 139892, "startTime": 1604507747, "stopTime": 1604507749, "filename": "/home/nc/trunk-recorder/recordings/scarmer2/2020/11/4/4828-1604507736-1604507747-139892_853225000.wav"} ]
}
natecarlson commented 3 years ago

@robotastic, forgot to respond to:

I haven't rolled in your changes yet.

That's fine - not expecting you to, not to that stage yet! :) I just wanted to make the changes publicly accessible in case you want to see 'em/etc. :)

Your current updates plus my patches are now at this branch: https://github.com/natecarlson/trunk-recorder/tree/split_recordings_nate_v2

If you can give both modes a try, that would be awesome.

Results with transmissionMode set to true are above. TL;DR seems to work - except that the last transmission leaks into the next call (unsure of if it's the next call overall, next call on that recorder, or what.)

Testing with transmissionMode set to false, it's looking pretty good. Seeing a new json and wav file per call. Means we lose the metadata defining the call, but that's ok I think.. can always implement grouping on the server side if desired.

I'm leaving it configured this way for now and pushing to this openmhz endpoint: https://openmhz.com/system/scarmertst

..which should have the same content as: https://openmhz.com/system/scarmer2

..but with the new call splitting.

I think the Call approach would be easier since the changes would be smaller.

I assume transmissionMode = false is what you mean by the Call approach?

I agree. It might still be beneficial to capture the metadata of the old style 'call' separately and send that to the server - but that requires a lot of other changes too, and seems unnecessary to me. (It shouldn't be hard to implement server-side logic that groups 'calls' as well as the current recorder-side code anyways, in my opinion.) Heck, might even be simple enough to add a 'overallCallStartTime' that persists across the sub-calls?

Another benefit of this method is that it reduces the delay that some people complain about - instead of waiting for a group of transmissions to finish you get the data uploaded as each individual transmission completes.

natecarlson commented 3 years ago

Hmm, hit a segfault:

[2020-11-04 11:56:13.038744] (info)   Source Switch [scarmertst]        TG:      10808 (           BLMT PD DISP)        Freq: 853.225000 MHz    Elapsed: 3s      Since update: 0s329132 329831
[2020-11-04 11:56:13.038938] (info)   [scarmertst]      TG:      10808 (           BLMT PD DISP)        Freq: 853.225000 MHz    Ending Recorded Call - Last Update: 0s   Call Elapsed: 3
[2020-11-04 11:56:13.039272] (info)     - Stopping P25 Recorder Num [8] TG:      10808 (           BLMT PD DISP)        Freq: 853.225000 MHz    TDMA: false      Slot: 0
[2020-11-04 11:56:13.231607] (debug)   Call not found yet; starting call for freq: 853.225000 MHz talkgroup: 10808 source id 329132

[2020-11-04 11:56:13.231841] (info)     - Starting P25 Recorder Num [8] TG:      10808 (           BLMT PD DISP)        Freq: 853.225000 MHz    TDMA: false      Slot: 0 Mod: true
[2020-11-04 11:56:13.231982] (info)   [scarmertst]      TG:      10808 (           BLMT PD DISP)        Freq: 853.225000 MHz    Starting Recorder on Src: rtl=12340006 For Source ID: 329132
[2020-11-04 11:56:13.232219] (info)   Source Switch [scarmertst]        TG:         54 (           MSP 2500 DSP)        Freq: 855.987500 MHz    Elapsed: 3s      Since update: 0s104016 103944
[2020-11-04 11:56:13.232331] (info)   [scarmertst]      TG:         54 (           MSP 2500 DSP)        Freq: 855.987500 MHz    Ending Recorded Call - Last Update: 0s   Call Elapsed: 3
[2020-11-04 11:56:13.232706] (info)     - Stopping P25 Recorder Num [16]        TG:         54 (           MSP 2500 DSP)        Freq: 855.987500 MHz    TDMA: false      Slot: 0
Segmentation fault

Will restart and see if it occurs again..

Edit: Yup, a few minutes later:

[2020-11-04 12:03:24.231868] (info)     - Starting P25 Recorder Num [0] TG:       2264 (              EMSAL ALS)        Freq: 852.800000 MHz    TDMA: false      Slot: 0 Mod: true
[2020-11-04 12:03:24.231955] (info)   [scarmertst]      TG:       2264 (              EMSAL ALS)        Freq: 852.800000 MHz    Starting Recorder on Src: rtl=12340004 For Source ID: 106075
[2020-11-04 12:03:24.978190] (info)   [scarmertst]      TG:      2264 (              EMSAL ALS) Freq: 852.800000 MHz    Skipping to next file, Call Src:  106075 New filename: /home/nc/trunk-recorder/recordings/scarmertst/2020/11/4/2264-1604513004-1604513004-106075_852800000.wav

[2020-11-04 12:03:27.162053] (info)   Source Switch [scarmertst]        TG:       2264 (              EMSAL ALS)        Freq: 852.800000 MHz    Elapsed: 3s      Since update: 0s106312 106075
[2020-11-04 12:03:27.162208] (info)   [scarmertst]      TG:       2264 (              EMSAL ALS)        Freq: 852.800000 MHz    Ending Recorded Call - Last Update: 0s   Call Elapsed: 3
[2020-11-04 12:03:27.162578] (info)     - Stopping P25 Recorder Num [0] TG:       2264 (              EMSAL ALS)        Freq: 852.800000 MHz    TDMA: false      Slot: 0
Segmentation fault
natecarlson commented 3 years ago

Since I'm not sure where the segfault lies - I created a new branch off current master, and pulled in only the changes necessary to support splitting each transmission into a new call (I think, at least).. here's the branch: https://github.com/natecarlson/trunk-recorder/tree/split_recordings_by_call_minimal_on_master ..and the commit: https://github.com/natecarlson/trunk-recorder/commit/16719ea4c3ef3c387b8bbfebe4567fd2291b9512

It's working so far; we'll see if it continues to segfault or not.

Edit: Been running for over 4 hours without a segfault now on the codebase referenced above.

robotastic commented 3 years ago

@natecarlson thanks so much for doing all this testing! Cool - it seems like the Call based method (looking for changes in the Src ID on the Trunk Control Channel) seems like the best way to go. It should be compatible with everything on the server side without a change, so that is a plus. Down the road I can add some stuff so that it is stored better on the server side, which would allow for filtering by Src ID, now that there is a single source per Call.

I agree that the having a Call multiple transmisssions together probably is not that useful. It is sort of an artificial artifact. It just means that a lot of calls were back to back. I think you could reconstruct this on the server side.

I will go start a clean branch and base it on the change you made... I will also run for a while to make sure it isn't SegFaulting.

robotastic commented 3 years ago

Ok rolled these changes up into a branch called "transmission_mode". To turn on call separation you now need to set the transmissionMode flag to true in the config file. This will enable the Call based separation.

natecarlson commented 3 years ago

Sounds good - looks like you brought over some of the changes from the wavsink/etc too - they must've still been beneficial?

I just switched my test box over to this code; will see how it goes!

natecarlson commented 3 years ago

I'm hitting segfaults again on this build. Attaching valgrind output: recorder.log

Trying to get a segfault again now that I've set up the system to write out a core file..

natecarlson commented 3 years ago

Backtrace:

Core was generated by `./recorder'.
Program terminated with signal SIGSEGV, Segmentation fault.
#0  0x000056346d67d910 in Call::get_transmission_mode() ()
[Current thread is 1 (Thread 0x7f0bf0e49700 (LWP 16640))]
(gdb) bt
#0  0x000056346d67d910 in Call::get_transmission_mode() ()
#1  0x000056346d6b045c in gr::blocks::nonstop_wavfile_sink_impl::dowork(int, std::vector<void const*, std::allocator<void const*> >&, std::vector<void*, std::allocator<void*> >&) [clone .constprop.321] ()
#2  0x000056346d6b0a2d in gr::blocks::nonstop_wavfile_sink_impl::work(int, std::vector<void const*, std::allocator<void const*> >&, std::vector<void*, std::allocator<void*> >&) ()
#3  0x00007f117abfc6f7 in gr::sync_block::general_work(int, std::vector<int, std::allocator<int> >&, std::vector<void const*, std::allocator<void const*> >&, std::vector<void*, std::allocator<void*> >&) ()
   from /lib/x86_64-linux-gnu/libgnuradio-runtime.so.3.7.13
#4  0x00007f117abc20a0 in gr::block_executor::run_one_iteration() ()
   from /lib/x86_64-linux-gnu/libgnuradio-runtime.so.3.7.13
#5  0x00007f117ac05b29 in gr::tpb_thread_body::tpb_thread_body(boost::shared_ptr<gr::block>, boost::shared_ptr<boost::barrier>, int) () from /lib/x86_64-linux-gnu/libgnuradio-runtime.so.3.7.13
#6  0x00007f117abf7ec4 in ?? () from /lib/x86_64-linux-gnu/libgnuradio-runtime.so.3.7.13
#7  0x00007f117abad342 in ?? () from /lib/x86_64-linux-gnu/libgnuradio-runtime.so.3.7.13
#8  0x00007f117b00d615 in ?? () from /lib/x86_64-linux-gnu/libboost_thread.so.1.67.0
#9  0x00007f117afdfea7 in start_thread (arg=<optimized out>) at pthread_create.c:477
#10 0x00007f117905ad4f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
robotastic commented 3 years ago

Interesting - do you have conventional systems also setup? Let me go see if I can spot anything obvious. I had it running all last night without any crashes.

natecarlson commented 3 years ago

No convention systems.. here's my basic config:

{
    "ver": 2,
    "sources": [
        {
        "center": 852000000,
        "rate": 2096000,
        "ppm": -1,
        "error":  100,
        "gain": 49.6,
        "digitalRecorders": 8,
        "analogRecorders": 0,
        "modulation": "qpsk",
        "driver": "osmosdr",
        "digitalLevels": 8,
        "device": "rtl=12340004"
        },
        {
        "center": 854000000,
        "rate": 2096000,
        "ppm": 0,
        "error": 500,
        "gain": 49.6,
        "digitalRecorders": 8,
        "analogRecorders": 0,
        "modulation": "qpsk",
        "driver": "osmosdr",
        "digitalLevels": 8,
        "device": "rtl=12340006"
        },
        {
        "center": 856000000,
        "rate": 2096000,
        "ppm": -1,
        "error": 0,
        "gain": 49.6,
        "digitalRecorders": 8,
        "analogRecorders": 0,
        "modulation": "qpsk",
        "driver": "osmosdr",
        "digitalLevels": 8,
        "device": "rtl=12340005"
        }
    ],
    "systems": [
        {
            "shortName": "scarmertst",
            "apiKey": "[redacted]",
            "control_channels": [852437500,851887500,852075000,853787537],
            "type": "p25",
            "talkgroupsFile": "/home/nc/trunk-recorder/trunk-build/mn-armer.csv",
            "talkgroupDisplayFormat": "id_tag",
            "recordUnknown": true,
            "hideUnknownTalkgroups": false,
            "transmissionMode": true,
            "unitTagsFile": "/home/nc/trunk-recorder/trunk-build/unittags.csv",
            "uploadScript": "upload.sh 1"
        }
    ],
    "captureDir": "/home/nc/trunk-recorder/recordings",
    "uploadServer": "https://api.openmhz.com",
    "frequencyFormat": "mhz",
    "logFile": true,
    "logLevel": "debug",
    "statusAsString": true,
    "controlWarnRate": 30,
    "debugRecorder": 0,
    "callTimeout": 3
}

(and yeah, I know error and ppm don't mix, need to fix that, grin.)

robotastic commented 3 years ago

OK - just pushed a new version. I think it could have crashed because the wav_recording function maybe getting some samples in before everything is setup. I added some checks to make sure everything has been assigned.

If you see any messages with weird in them, let me know...

natecarlson commented 3 years ago

I accidently nerfed my OS on the test box, sigh! Doing a quick re-install and then will have the data again; will validate that it still segfaults before testing the new code.

I was running my branch (with only the changes required for the call splitting) for a good 12-18 hours without segfaults, and seem to get them within a few minutes to 30 minutes of starting your branch (without the last set of changes).. wonder if it's related to how many current recorders are running or something?

natecarlson commented 3 years ago

OK - got the OS running again, and rebuilt recorder with the code I was running previously with the current system libraries (went up to Ubuntu 20.04 while I was at it), and it segfault'ed after about 20 minutes.

Pulled in the new code, built, set up to write out core dumps properly, and start it up.. will check back on it later.

natecarlson commented 3 years ago

With the changes, I am getting lots of these:

[2020-11-06 14:30:41.988602]: Wav - Dropping items, no fp: 1728 Filename: Current sample count: 0

..and it looks like it is failing to actually record anything; it appears that it's ending up with an empty/no wav file?

[2020-11-06 14:31:54.014805] (error)   Wav - Dropping items, no fp: 864 Filename:  Current sample count: 0
[2020-11-06 14:31:54.139521] (error)   Wav - Dropping items, no fp: 1728 Filename:  Current sample count: 0
[2020-11-06 14:31:54.205798] (error)   Wav - Dropping items, no fp: 1728 Filename:  Current sample count: 0
[2020-11-06 14:31:54.328739] (error)   Wav - Dropping items, no fp: 1440 Filename:  Current sample count: 0
[2020-11-06 14:31:54.394849] (error)   Wav - Dropping items, no fp: 1728 Filename:  Current sample count: 0
[2020-11-06 14:31:54.517154] (error)   Wav - Dropping items, no fp: 1440 Filename:  Current sample count: 0
[2020-11-06 14:31:54.642499] (error)   Wav - Dropping items, no fp: 1440 Filename:  Current sample count: 0
[2020-11-06 14:31:54.831899] (error)   Wav - Dropping items, no fp: 864 Filename:  Current sample count: 0
[2020-11-06 14:31:54.832111] (error)   Wav - Dropping items, no fp: 576 Filename:  Current sample count: 0
[2020-11-06 14:31:55.019014] (error)   Wav - Dropping items, no fp: 1440 Filename:  Current sample count: 0
[2020-11-06 14:31:55.207563] (error)   Wav - Dropping items, no fp: 1440 Filename:  Current sample count: 0
[2020-11-06 14:31:55.393493] (error)   Wav - Dropping items, no fp: 1440 Filename:  Current sample count: 0
[2020-11-06 14:31:55.579112] (error)   Wav - Dropping items, no fp: 1440 Filename:  Current sample count: 0
[2020-11-06 14:31:55.581203] (error)   Wav - Dropping items, no fp: 864 Filename:  Current sample count: 0
[2020-11-06 14:31:55.765146] (error)   Wav - Dropping items, no fp: 576 Filename:  Current sample count: 0
[2020-11-06 14:31:58.034235] (info)      - Retune failed, starting a new recording using a new source
[2020-11-06 14:31:58.034979] (info)     - Starting P25 Recorder Num [10]        TG:      22621 (           RI FIRE MAIN)
        Freq: 853.225000 MHz    TDMA: false     Slot: 0 Mod: true
[2020-11-06 14:31:58.035100] (info)   [scarmertst]      TG:      22621 (           RI FIRE MAIN)        Freq: 853.225000
 MHz    Starting Recorder on Src: rtl=12340006
[2020-11-06 14:31:58.643052] (error)   Wav - Dropping items, no fp: 864 Filename:  Current sample count: 0
[2020-11-06 14:31:58.645529] (error)   Wav - Dropping items, no fp: 864 Filename:  Current sample count: 0
[2020-11-06 14:31:58.828504] (error)   Wav - Dropping items, no fp: 864 Filename:  Current sample count: 0
[2020-11-06 14:31:58.831309] (error)   Wav - Dropping items, no fp: 864 Filename:  Current sample count: 0
[2020-11-06 14:31:59.004779] (info)   [scarmertst]      TG:       4826 (           SCOT SO SOUT)        Freq: 854.587500
 MHz    Ending Recorded Call - Last Update: 4s  Call Elapsed: 7
[2020-11-06 14:31:59.005355] (info)     - Stopping P25 Recorder Num [9] TG:       4826 (           SCOT SO SOUT)       F
req: 854.587500 MHz     TDMA: false     Slot: 0
[2020-11-06 14:31:59.005455] (error)   wav error closing file
[2020-11-06 14:31:59.005506] (info)   [scarmertst]      Deleting this call as it has a duration less than minimum durati
on of 0 TG:       4826 (           SCOT SO SOUT)        Freq: 854.587500 MHz    Call Duration: 0s
[2020-11-06 14:31:59.005622] (error)   Could not delete file /home/nc/trunk-recorder/recordings/scarmertst/2020/11/6/482
6-1604694712_854587500.wav
[2020-11-06 14:31:59.016443] (error)   Wav - Dropping items, no fp: 864 Filename:  Current sample count: 0
[2020-11-06 14:31:59.019760] (error)   Wav - Dropping items, no fp: 864 Filename:  Current sample count: 0
[2020-11-06 14:31:59.266276] (error)   Wav - Dropping items, no fp: 576 Filename:  Current sample count: 0
[2020-11-06 14:31:59.270638] (error)   Wav - Dropping items, no fp: 864 Filename:  Current sample count: 0
[2020-11-06 14:31:59.457645] (error)   Wav - Dropping items, no fp: 1728 Filename:  Current sample count: 0
[2020-11-06 14:31:59.644967] (error)   Wav - Dropping items, no fp: 1728 Filename:  Current sample count: 0
[2020-11-06 14:31:59.832162] (error)   Wav - Dropping items, no fp: 1440 Filename:  Current sample count: 0
[2020-11-06 14:32:00.005500] (info)   [scarmertst]      TG:      22621 (           RI FIRE MAIN)        Freq: 853.375000 MHz    Ending Recorded Call - Last Update: 4s  Call Elapsed: 11
[2020-11-06 14:32:00.006036] (info)     - Stopping P25 Recorder Num [8] TG:      22621 (           RI FIRE MAIN)       Freq: 853.375000 MHz     TDMA: false     Slot: 0
[2020-11-06 14:32:00.006134] (error)   wav error closing file
[2020-11-06 14:32:00.006185] (info)   [scarmertst]      Deleting this call as it has a duration less than minimum duration of 0 TG:      22621 (           RI FIRE MAIN)        Freq: 853.375000 MHz    Call Duration: 0s
[2020-11-06 14:32:00.006292] (error)   Could not delete file /home/nc/trunk-recorder/recordings/scarmertst/2020/11/6/22621-1604694709_853375000.wav
[2020-11-06 14:32:00.021572] (error)   Wav - Dropping items, no fp: 1440 Filename:  Current sample count: 0
[2020-11-06 14:32:00.207598] (error)   Wav - Dropping items, no fp: 1440 Filename:  Current sample count: 0
[2020-11-06 14:32:00.396430] (error)   Wav - Dropping items, no fp: 1440 Filename:  Current sample count: 0
[2020-11-06 14:32:00.584345] (error)   Wav - Dropping items, no fp: 1440 Filename:  Current sample count: 0
[2020-11-06 14:32:00.832188] (error)   Wav - Dropping items, no fp: 1440 Filename:  Current sample count: 0
[2020-11-06 14:32:00.976925] (info)     - Starting P25 Recorder Num [8] TG:      33203 (           HUTCH PD DSP)       Freq: 853.462500 MHz     TDMA: false     Slot: 0 Mod: true
[2020-11-06 14:32:00.977081] (info)   [scarmertst]      TG:      33203 (           HUTCH PD DSP)        Freq: 853.462500 MHz    Starting Recorder on Src: rtl=12340006
[2020-11-06 14:32:01.395162] (error)   Wav - Dropping items, no fp: 864 Filename:  Current sample count: 0
[2020-11-06 14:32:01.582398] (error)   Wav - Dropping items, no fp: 864 Filename:  Current sample count: 0
[2020-11-06 14:32:01.582596] (error)   Wav - Dropping items, no fp: 864 Filename:  Current sample count: 0
[2020-11-06 14:32:01.834212] (error)   Wav - Dropping items, no fp: 1728 Filename:  Current sample count: 0
[2020-11-06 14:32:02.019436] (error)   Wav - Dropping items, no fp: 1440 Filename:  Current sample count: 0
[2020-11-06 14:32:02.208925] (error)   Wav - Dropping items, no fp: 864 Filename:  Current sample count: 0
[2020-11-06 14:32:02.209104] (error)   Wav - Dropping items, no fp: 576 Filename:  Current sample count: 0
[2020-11-06 14:32:02.396848] (error)   Wav - Dropping items, no fp: 1440 Filename:  Current sample count: 0
[2020-11-06 14:32:02.583934] (error)   Wav - Dropping items, no fp: 864 Filename:  Current sample count: 0
[2020-11-06 14:32:02.584089] (error)   Wav - Dropping items, no fp: 576 Filename:  Current sample count: 0
[2020-11-06 14:32:02.771028] (error)   Wav - Dropping items, no fp: 864 Filename:  Current sample count: 0
[2020-11-06 14:32:02.772749] (error)   Wav - Dropping items, no fp: 864 Filename:  Current sample count: 0
[2020-11-06 14:32:02.956831] (error)   Wav - Dropping items, no fp: 864 Filename:  Current sample count: 0
[2020-11-06 14:32:02.958557] (error)   Wav - Dropping items, no fp: 864 Filename:  Current sample count: 0
[2020-11-06 14:32:03.145656] (error)   Wav - Dropping items, no fp: 864 Filename:  Current sample count: 0
[2020-11-06 14:32:03.147245] (error)   Wav - Dropping items, no fp: 864 Filename:  Current sample count: 0
[2020-11-06 14:32:03.393282] (error)   Wav - Dropping items, no fp: 576 Filename:  Current sample count: 0
[2020-11-06 14:32:06.007176] (info)   [scarmertst]      TG:      22621 (           RI FIRE MAIN)        Freq: 853.225000 MHz    Ending Recorded Call - Last Update: 4s  Call Elapsed: 8
[2020-11-06 14:32:06.007784] (info)     - Stopping P25 Recorder Num [10]        TG:      22621 (           RI FIRE MAIN)
        Freq: 853.225000 MHz    TDMA: false     Slot: 0
[2020-11-06 14:32:06.007883] (error)   wav error closing file
[2020-11-06 14:32:06.007934] (info)   [scarmertst]      Deleting this call as it has a duration less than minimum duration of 0 TG:      22621 (           RI FIRE MAIN)        Freq: 853.225000 MHz    Call Duration: 0s
[2020-11-06 14:32:06.008039] (error)   Could not delete file /home/nc/trunk-recorder/recordings/scarmertst/2020/11/6/22621-1604694718_853225000.wav

With the transmission_mode branch before these changes to attempt to stop segfaults it was successfully recording.

robotastic commented 3 years ago

Doh - ok i will remove all that stuff from the wav sink in a little and that should stop that and fix the segfaults

📱

On Nov 6, 2020, at 3:33 PM, Nate Carlson notifications@github.com wrote:

 With the changes, I am getting lots of these:

[2020-11-06 14:30:41.988602]: Wav - Dropping items, no fp: 1728 Filename: Current sample count: 0

..and it looks like it is failing to actually record anything; it appears that it's ending up with an empty/no wav file?

[2020-11-06 14:31:54.014805] (error) Wav - Dropping items, no fp: 864 Filename: Current sample count: 0 [2020-11-06 14:31:54.139521] (error) Wav - Dropping items, no fp: 1728 Filename: Current sample count: 0 [2020-11-06 14:31:54.205798] (error) Wav - Dropping items, no fp: 1728 Filename: Current sample count: 0 [2020-11-06 14:31:54.328739] (error) Wav - Dropping items, no fp: 1440 Filename: Current sample count: 0 [2020-11-06 14:31:54.394849] (error) Wav - Dropping items, no fp: 1728 Filename: Current sample count: 0 [2020-11-06 14:31:54.517154] (error) Wav - Dropping items, no fp: 1440 Filename: Current sample count: 0 [2020-11-06 14:31:54.642499] (error) Wav - Dropping items, no fp: 1440 Filename: Current sample count: 0 [2020-11-06 14:31:54.831899] (error) Wav - Dropping items, no fp: 864 Filename: Current sample count: 0 [2020-11-06 14:31:54.832111] (error) Wav - Dropping items, no fp: 576 Filename: Current sample count: 0 [2020-11-06 14:31:55.019014] (error) Wav - Dropping items, no fp: 1440 Filename: Current sample count: 0 [2020-11-06 14:31:55.207563] (error) Wav - Dropping items, no fp: 1440 Filename: Current sample count: 0 [2020-11-06 14:31:55.393493] (error) Wav - Dropping items, no fp: 1440 Filename: Current sample count: 0 [2020-11-06 14:31:55.579112] (error) Wav - Dropping items, no fp: 1440 Filename: Current sample count: 0 [2020-11-06 14:31:55.581203] (error) Wav - Dropping items, no fp: 864 Filename: Current sample count: 0 [2020-11-06 14:31:55.765146] (error) Wav - Dropping items, no fp: 576 Filename: Current sample count: 0 [2020-11-06 14:31:58.034235] (info) - Retune failed, starting a new recording using a new source [2020-11-06 14:31:58.034979] (info) - Starting P25 Recorder Num [10] TG: 22621 ( RI FIRE MAIN) Freq: 853.225000 MHz TDMA: false Slot: 0 Mod: true [2020-11-06 14:31:58.035100] (info) [scarmertst] TG: 22621 ( RI FIRE MAIN) Freq: 853.225000 MHz Starting Recorder on Src: rtl=12340006 [2020-11-06 14:31:58.643052] (error) Wav - Dropping items, no fp: 864 Filename: Current sample count: 0 [2020-11-06 14:31:58.645529] (error) Wav - Dropping items, no fp: 864 Filename: Current sample count: 0 [2020-11-06 14:31:58.828504] (error) Wav - Dropping items, no fp: 864 Filename: Current sample count: 0 [2020-11-06 14:31:58.831309] (error) Wav - Dropping items, no fp: 864 Filename: Current sample count: 0 [2020-11-06 14:31:59.004779] (info) [scarmertst] TG: 4826 ( SCOT SO SOUT) Freq: 854.587500 MHz Ending Recorded Call - Last Update: 4s Call Elapsed: 7 [2020-11-06 14:31:59.005355] (info) - Stopping P25 Recorder Num [9] TG: 4826 ( SCOT SO SOUT) F req: 854.587500 MHz TDMA: false Slot: 0 [2020-11-06 14:31:59.005455] (error) wav error closing file [2020-11-06 14:31:59.005506] (info) [scarmertst] Deleting this call as it has a duration less than minimum durati on of 0 TG: 4826 ( SCOT SO SOUT) Freq: 854.587500 MHz Call Duration: 0s [2020-11-06 14:31:59.005622] (error) Could not delete file /home/nc/trunk-recorder/recordings/scarmertst/2020/11/6/482 6-1604694712_854587500.wav [2020-11-06 14:31:59.016443] (error) Wav - Dropping items, no fp: 864 Filename: Current sample count: 0 [2020-11-06 14:31:59.019760] (error) Wav - Dropping items, no fp: 864 Filename: Current sample count: 0 [2020-11-06 14:31:59.266276] (error) Wav - Dropping items, no fp: 576 Filename: Current sample count: 0 [2020-11-06 14:31:59.270638] (error) Wav - Dropping items, no fp: 864 Filename: Current sample count: 0 [2020-11-06 14:31:59.457645] (error) Wav - Dropping items, no fp: 1728 Filename: Current sample count: 0 [2020-11-06 14:31:59.644967] (error) Wav - Dropping items, no fp: 1728 Filename: Current sample count: 0 [2020-11-06 14:31:59.832162] (error) Wav - Dropping items, no fp: 1440 Filename: Current sample count: 0 [2020-11-06 14:32:00.005500] (info) [scarmertst] TG: 22621 ( RI FIRE MAIN) Freq: 853.375000 MHz Ending Recorded Call - Last Update: 4s Call Elapsed: 11 [2020-11-06 14:32:00.006036] (info) - Stopping P25 Recorder Num [8] TG: 22621 ( RI FIRE MAIN) Freq: 853.375000 MHz TDMA: false Slot: 0 [2020-11-06 14:32:00.006134] (error) wav error closing file [2020-11-06 14:32:00.006185] (info) [scarmertst] Deleting this call as it has a duration less than minimum duration of 0 TG: 22621 ( RI FIRE MAIN) Freq: 853.375000 MHz Call Duration: 0s [2020-11-06 14:32:00.006292] (error) Could not delete file /home/nc/trunk-recorder/recordings/scarmertst/2020/11/6/22621-1604694709_853375000.wav [2020-11-06 14:32:00.021572] (error) Wav - Dropping items, no fp: 1440 Filename: Current sample count: 0 [2020-11-06 14:32:00.207598] (error) Wav - Dropping items, no fp: 1440 Filename: Current sample count: 0 [2020-11-06 14:32:00.396430] (error) Wav - Dropping items, no fp: 1440 Filename: Current sample count: 0 [2020-11-06 14:32:00.584345] (error) Wav - Dropping items, no fp: 1440 Filename: Current sample count: 0 [2020-11-06 14:32:00.832188] (error) Wav - Dropping items, no fp: 1440 Filename: Current sample count: 0 [2020-11-06 14:32:00.976925] (info) - Starting P25 Recorder Num [8] TG: 33203 ( HUTCH PD DSP) Freq: 853.462500 MHz TDMA: false Slot: 0 Mod: true [2020-11-06 14:32:00.977081] (info) [scarmertst] TG: 33203 ( HUTCH PD DSP) Freq: 853.462500 MHz Starting Recorder on Src: rtl=12340006 [2020-11-06 14:32:01.395162] (error) Wav - Dropping items, no fp: 864 Filename: Current sample count: 0 [2020-11-06 14:32:01.582398] (error) Wav - Dropping items, no fp: 864 Filename: Current sample count: 0 [2020-11-06 14:32:01.582596] (error) Wav - Dropping items, no fp: 864 Filename: Current sample count: 0 [2020-11-06 14:32:01.834212] (error) Wav - Dropping items, no fp: 1728 Filename: Current sample count: 0 [2020-11-06 14:32:02.019436] (error) Wav - Dropping items, no fp: 1440 Filename: Current sample count: 0 [2020-11-06 14:32:02.208925] (error) Wav - Dropping items, no fp: 864 Filename: Current sample count: 0 [2020-11-06 14:32:02.209104] (error) Wav - Dropping items, no fp: 576 Filename: Current sample count: 0 [2020-11-06 14:32:02.396848] (error) Wav - Dropping items, no fp: 1440 Filename: Current sample count: 0 [2020-11-06 14:32:02.583934] (error) Wav - Dropping items, no fp: 864 Filename: Current sample count: 0 [2020-11-06 14:32:02.584089] (error) Wav - Dropping items, no fp: 576 Filename: Current sample count: 0 [2020-11-06 14:32:02.771028] (error) Wav - Dropping items, no fp: 864 Filename: Current sample count: 0 [2020-11-06 14:32:02.772749] (error) Wav - Dropping items, no fp: 864 Filename: Current sample count: 0 [2020-11-06 14:32:02.956831] (error) Wav - Dropping items, no fp: 864 Filename: Current sample count: 0 [2020-11-06 14:32:02.958557] (error) Wav - Dropping items, no fp: 864 Filename: Current sample count: 0 [2020-11-06 14:32:03.145656] (error) Wav - Dropping items, no fp: 864 Filename: Current sample count: 0 [2020-11-06 14:32:03.147245] (error) Wav - Dropping items, no fp: 864 Filename: Current sample count: 0 [2020-11-06 14:32:03.393282] (error) Wav - Dropping items, no fp: 576 Filename: Current sample count: 0 [2020-11-06 14:32:06.007176] (info) [scarmertst] TG: 22621 ( RI FIRE MAIN) Freq: 853.225000 MHz Ending Recorded Call - Last Update: 4s Call Elapsed: 8 [2020-11-06 14:32:06.007784] (info) - Stopping P25 Recorder Num [10] TG: 22621 ( RI FIRE MAIN) Freq: 853.225000 MHz TDMA: false Slot: 0 [2020-11-06 14:32:06.007883] (error) wav error closing file [2020-11-06 14:32:06.007934] (info) [scarmertst] Deleting this call as it has a duration less than minimum duration of 0 TG: 22621 ( RI FIRE MAIN) Freq: 853.225000 MHz Call Duration: 0s [2020-11-06 14:32:06.008039] (error) Could not delete file /home/nc/trunk-recorder/recordings/scarmertst/2020/11/6/22621-1604694718_853225000.wav With the transmission_mode branch before these changes to attempt to stop segfaults it was successfully recording.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub, or unsubscribe.

robotastic commented 3 years ago

OK - Well I at least fixed it so it is recording WAV files, give the latest push of the branch a try.

I have been running it with transmissionMode set to true on this system: https://openmhz.com/system/dcfd

I haven't been able to get it to segfault yet, but I will leave it running for a while.

robotastic commented 3 years ago

I got a segfault too...

Program terminated with signal SIGSEGV, Segmentation fault.
#0  0x000055ec9ba7c93d in Call::get_system_type[abi:cxx11]() ()
[Current thread is 1 (Thread 0x7f736779e700 (LWP 2851784))]
(gdb) bt
#0  0x000055ec9ba7c93d in Call::get_system_type[abi:cxx11]() ()
#1  0x000055ec9bab2f84 in gr::blocks::nonstop_wavfile_sink_impl::dowork(int, std::vector<void const*, std::allocator<void const*> >&, std::vector<void*, std::allocator<void*> >&) ()
#2  0x000055ec9bab1d72 in gr::blocks::nonstop_wavfile_sink_impl::work(int, std::vector<void const*, std::allocator<void const*> >&, std::vector<void*, std::allocator<void*> >&) ()
#3  0x00007f74c3a4684b in gr::sync_block::general_work(int, std::vector<int, std::allocator<int> >&, std::vector<void const*, std::allocator<void const*> >&, std::vector<void*, std::allocator<void*> >&) () from /usr/lib/x86_64-linux-gnu/libgnuradio-runtime.so.3.8.1
#4  0x00007f74c39fec03 in gr::block_executor::run_one_iteration() () from /usr/lib/x86_64-linux-gnu/libgnuradio-runtime.so.3.8.1
#5  0x00007f74c3a5259a in gr::tpb_thread_body::tpb_thread_body(boost::shared_ptr<gr::block>, boost::shared_ptr<boost::barrier>, int) ()
   from /usr/lib/x86_64-linux-gnu/libgnuradio-runtime.so.3.8.1

Gonna have to dig into this more. There must be some condition where either the call associated with a recording is sometimes Null or the system associated with a Call is Null.

The segfault may have happened right around the ending of a call:

[2020-11-07 16:07:54.278828] (info)     - Starting P25 Recorder Num [3] TG:      11618  Freq: 8.589875e+08      TDMA: false     Slot: 0 Mod: true
[2020-11-07 16:07:54.278989] (info)   [dcfd]    TG:      11618  Freq: 8.589875e+08      Starting Recorder on Src: 
[2020-11-07 16:07:55.488757] (info)   Source Switch [dcfd]      TG:      11618  Freq: 8.589875e+08      Elapsed: 1s     Since update: 0s1116766 0
[2020-11-07 16:07:55.488836] (info)   [dcfd]    TG:      11618  Freq: 8.589875e+08      Ending Recorded Call - Last Update: 0s  Call Elapsed: 1
[2020-11-07 16:07:55.489035] (info)     - Stopping P25 Recorder Num [3] TG:      11618  Freq: 8.589875e+08      TDMA: false     Slot: 0
Segmentation fault (core dumped)
natecarlson commented 3 years ago

Sorry, it's been a crazy weekend. I see you've added more debug code, want me to give it a shot?

Also, is the wav sink code even needed for this? I didn't copy those to my branch which seems to be working - I haven't added the transmissionmode flag to mine, but seems that should be doable entirely within main/call?

Here's the diff I'm using: https://github.com/natecarlson/trunk-recorder/commit/16719ea4c3ef3c387b8bbfebe4567fd2291b9512