Provide CRC errors in API

[TheDaChicken]

This is my implementation of providing CRC errors in the API.

I moved the logic for partial packets into the elastic buffer. This is to hopefully reduce code complexity. Elastic buffer is basically another packet store.

I also made a packet_ref_t to hopefully reduce argument calls when pushing packets into the elastic buffer.

[argilo]

Some thoughts on logging:

1. Since the CLI apps only play back one program at a time, it would probably make sense to log only for HDC packets pertaining to the selected program. If we do that, then the program number will no longer need to be part of the log messages.
2. The C & Python CLIs should use the same log level. (At the moment, C logs at the warning level, and Python at the error level).
3. CRC errors are normal at low SNR, so they should probably be reported at most at the warning level.
4. CRC errors can be frequent at low SNR, so it might be worth aggregating them and logging a count. The CLI apps report bit rate once every 32 packets, so it might make sense to do the same for CRC errors.
5. It's entirely normal and expected to see a half-packet when synchronization is achieved. I expect the same would be true when synchronization is lost, and half-packets shouldn't occur in other circumstances. Since they are normal and expected, they probably should be logged at the debug level. In fact, I'm not convinced that they should be reported through the API at all, but I'll have to think about it some more.

[TheDaChicken]

Thanks for the feedback. I will update based on this feedback.

2. The C & Python CLIs should use the same log level. (At the moment, C logs at the warning level, and Python at the error level).

Oopsy. I didn't do that on purpose!

4. CRC errors can be frequent at low SNR, so it might be worth aggregating them and logging a count. The CLI apps report bit rate once every 32 packets, so it might make sense to do the same for CRC errors.

That's a good idea. I've already seen the CLI get spammed very quickly.

5. In fact, I'm not convinced that they should be reported through the API at all, but I'll have to think about it some more.

I can always remove it. I only included it to bring back the original behavior since "ignoring partial pdu" used to be logged. I cannot think of any other reason to include it.

[argilo]

I can always remove it. I only included it to bring back the original behavior since "ignoring partial pdu" used to be logged. I cannot think of any other reason to include it.

I suspect the old "ignoring partial pdu" message (removed in #427) was just there to help with debugging during the initial development of nrsc5. I didn't ever need it for anything myself, even while debugging.

After thinking about it some more, I don't think it's worth including the HALF_BACK and HALF_FRONT flags in the API. I can't think of any use that an API client could have for knowing the details of how a particular audio packet was packed into audio transport PDUs.

[TheDaChicken]

After thinking about it some more, I don't think it's worth including the HALF_BACK and HALF_FRONT flags in the API. I can't think of any use that an API client could have for knowing the details of how a particular audio packet was packed into audio transport PDUs.

Do you mean to still include half_packet flag or don't report half-packets in general?

[argilo]

The latter. I don't see a need to report anything other than CRC errors.

[TheDaChicken]

Okay, I removed reporting half packets. This also now doesn't save packets with crc errors since there is no point to keep them in elastic-buffer.

I also squashed commits to make looking at the changes a lot easier.

[argilo]

Thanks. I'll do a bit more testing and a final code review, but it may not be until Monday.

[TheDaChicken]

Okay I updated changes based on your feedback.

Apoglizes if you saw my comments posted twice. The Github mobile app is sending my comments twice for some reason.

[argilo]

One last issue I just noticed: the presence of zero-length HDC packets pushes down the calculated audio bit rate:

20:09:18 Audio bit rate: 0.0 kbps
20:09:18 Audio packet CRC mismatches: 32
--
20:09:18 Audio bit rate: 0.0 kbps
20:09:18 Audio packet CRC mismatches: 32
--
20:09:18 Audio bit rate: 2.4 kbps
20:09:18 Audio packet CRC mismatches: 31
--
20:09:18 Audio bit rate: 1.7 kbps
20:09:18 Audio packet CRC mismatches: 31
--
20:09:19 Audio bit rate: 3.6 kbps
20:09:19 Audio packet CRC mismatches: 30
--
20:09:19 Audio bit rate: 0.0 kbps
20:09:19 Audio packet CRC mismatches: 32

I'll have to think about how best to handle that.

[argilo]

Maybe we should change the bit rate calculation to count & average valid packets only (which would match the previous behaviour), and aggregate CRC mismatches separately.

[argilo]

Or do we take this as a sign that zero-length packets are a potentially disruptive API change and report CRC errors in a new event type instead?

[argilo]

To be honest, I'm not too worried about this particular API change being disruptive. We can always number the next release 4.0.0 so it's clear there's an API change that clients need to be mindful of.

[TheDaChicken]

One last issue I just noticed: the presence of zero-length HDC packets pushes down the calculated audio bit rate:

20:09:18 Audio bit rate: 0.0 kbps
20:09:18 Audio packet CRC mismatches: 32
--
20:09:18 Audio bit rate: 0.0 kbps
20:09:18 Audio packet CRC mismatches: 32
--
20:09:18 Audio bit rate: 2.4 kbps
20:09:18 Audio packet CRC mismatches: 31
--
20:09:18 Audio bit rate: 1.7 kbps
20:09:18 Audio packet CRC mismatches: 31
--
20:09:19 Audio bit rate: 3.6 kbps
20:09:19 Audio packet CRC mismatches: 30
--
20:09:19 Audio bit rate: 0.0 kbps
20:09:19 Audio packet CRC mismatches: 32

I'll have to think about how best to handle that.

Oh crap, you are right. I think if you wanted to report NRSC5_EVENT_HDC and NRSC5_EVENT_AUDIO packet-for-packet so that the audio stream could be exactly recovered from the HDC stream if desire, I think this should be dealt with instead of creating a new event for crcs.

[argilo]

Yeah, keeping information about the HDC stream in one place seems like the way to go. We could make a new HDC2 event and deprecate the old one, but that seems like overkill for an event type that's probably not used for much (yet).

[TheDaChicken]

Should I add a check to only add to audio_bytes if its a valid packet?

[argilo]

Another behaviour change in the API clients is that --dump-hdc will write out an ADTS header & zero-length packet each time an invalid CRC occurs. Maybe that's a sensible thing to do though, if we're aiming for enough information to be saved that the audio stream can be fully recovered.

[argilo]

Should I add a check to only add to audio_bytes if its a valid packet?

Hmm, that change wouldn't do anything since not adding zero is the same as adding zero. 😄 We'd also need to skip incrementing audio_packets, which means we'd need to aggregate CRC errors differently instead of piggybacking on audio_packets.

[TheDaChicken]

Should I add a check to only add to audio_bytes if its a valid packet?

Hmm, that change wouldn't do anything since not adding zero is the same as adding zero. 😄 We'd also need to skip incrementing audio_packets, which means we'd need to aggregate CRC errors differently instead of piggybacking on audio_packets.

Oh, right! 😄. I was asking without looking at the code. I am not sure if adding another field for counting audio packets specifically for crc errors would be a good idea. It may be printed in the console at a different rate if that's the case.

[TheDaChicken]

Actually, no. Ignore what I am saying. This would be fine actually.

[TheDaChicken]

Is something like this fine? To count valid packets and all audio_packets??

        elif evt_type == nrsc5.EventType.HDC:
            if evt.program == self.args.program:
                if self.args.dump_hdc:
                    self.hdc_output.write(self.adts_header(len(evt.data)))
                    self.hdc_output.write(evt.data)

                self.audio_packets += 1
                self.audio_bytes += len(evt.data)
                if evt.flags & nrsc5.PacketFlags.CRC_ERROR:
                    self.audio_errors += 1
                else:
                    self.audio_packets_valid += 1

                if self.audio_packets_valid >= 32:
                    logging.info("Audio bit rate: %.1f kbps", self.audio_bytes * 8 * nrsc5.SAMPLE_RATE_AUDIO
                                 / nrsc5.AUDIO_FRAME_SAMPLES / self.audio_packets_valid / 1000)
                    self.audio_packets_valid = 0
                    self.audio_bytes = 0
                    self.audio_errors = 0
                if self.audio_packets >= 32:
                    if self.audio_errors > 0:
                        logging.warning("Audio packet CRC mismatches: %d", self.audio_errors)
                    self.audio_packets = 0

[argilo]

Yeah, I think that would work. I don't think it's a big deal if CRC errors are reported at a different cadence as the audio bit rate.

[TheDaChicken]

Alright, I have made the changes separating regular packets and full packets (?) if thats how it should be called?

[argilo]

The updated code doesn't seem to work properly:

argilo@argilo-t580:~/git/nrsc5/build$ src/nrsc5 -o /dev/null -r ~/Documents/nrsc5-samp/detr-home-0947.cu8 0 2>&1 | grep -E "bit rate|CRC"
22:33:21 Audio bit rate: 3.5 kbps
22:33:21 Audio bit rate: 0.0 kbps
22:33:21 Audio bit rate: 0.0 kbps
22:33:21 Audio bit rate: 0.0 kbps
22:33:21 Audio bit rate: 0.0 kbps
22:33:22 Audio bit rate: 1.8 kbps
22:33:22 Audio bit rate: 0.0 kbps
22:33:22 Audio bit rate: 0.0 kbps
22:33:22 Audio bit rate: 0.0 kbps
22:33:22 Audio bit rate: 0.0 kbps
22:33:22 Audio bit rate: 0.0 kbps
22:33:22 Audio bit rate: 2.4 kbps
22:33:22 Audio bit rate: 1.7 kbps
22:33:22 Audio bit rate: 3.6 kbps
22:33:22 Audio bit rate: 0.0 kbps

argilo@argilo-t580:~/git/nrsc5/build$ ../support/cli.py -o /dev/null -r ~/Documents/nrsc5-samp/detr-home-0947.cu8 0 2>&1 | grep -E "bit rate|CRC"
22:34:20 Audio packet CRC mismatches: 30
22:34:20 Audio packet CRC mismatches: 62
22:34:20 Audio packet CRC mismatches: 94
22:34:20 Audio packet CRC mismatches: 126
22:34:20 Audio packet CRC mismatches: 158
22:34:20 Audio packet CRC mismatches: 189
22:34:20 Audio packet CRC mismatches: 221
22:34:20 Audio packet CRC mismatches: 253
22:34:21 Audio packet CRC mismatches: 285
22:34:21 Audio packet CRC mismatches: 317
22:34:21 Audio packet CRC mismatches: 349
22:34:21 Audio packet CRC mismatches: 380
22:34:21 Audio packet CRC mismatches: 411
22:34:21 Audio packet CRC mismatches: 441
22:34:21 Audio packet CRC mismatches: 473

[argilo]

Looking better, I'm now seeing the expected output from both clients.

[TheDaChicken]

I am so glad you do testing. Thanks for checking. I do this thing where I only test on either the python cli or the c client. 😄 I rebased and squashed two commits trying to fix it. Should work now.

[argilo]

Yep, all is looking good and I'm seeing the same audio bit rates as before. I'll get this merged once CI is happy.

[TheDaChicken]

Thank you!

[argilo]

Nice, this has eliminated almost 90% of the lines logged by libnrsc5 while playing back my library of recordings!

[TheDaChicken]

WOW! That's a lot of logging!