[BUG] Stops with OSoapySDR device 'driver=sdrplay': readStream failed: OVERFLOW, disabling

[thowe-switzerland]

Background

I have been running an absolutely stable LiveATC feed with an RTL dongle for several years. Now I have built a brand new installation with RPi 4 and the SDRPlay RSP1A. However, this feed has never run longer than 70 minutes because RTLSDR airband is always shutting down.

Describe your environment

Hardware:

• Raspberry Pi 4B 4GB RAM (new, tried with original and alternative strong enough power supply)
• SDRPlay RSP1A (new)

Software:

• Raspberry Pi OS Lite with Release date: March 4th 2021 5.10.17-v7l+ #1414 SMP Fri Apr 30 13:20:47 BST 2021 armv7l GNU/Linux
• RTLSDR-Airband-3.2.1
• SoapySDR 0.8.0
• SoapySDRPlay 0.3.0
• SDRplay_RSP_API-ARM32-3.07.2

What happened?

Using device RSP1A via SoapySDR (the only device).

Basically RTLSDR_Airband starts and works fine as systemd service for some time but shuts down after a random period of about 5 to 70 minutes. Cause seems to be "readStream failed: OVERFLOW, disabling"

Full message: OSoapySDR device 'driver=sdrplay,biasT_ctrl=false': readStream failed: OVERFLOW, disabling

Additional info

system journal at sudo systemctl start rtl_airband

May 15 11:22:18 atc-stream-rpi systemd[1]: Started SDR AM/NFM demodulator.
May 15 11:22:18 atc-stream-rpi rtl_airband[30841]: [30841]: sdrplay_api_Open
May 15 11:22:18 atc-stream-rpi rtl_airband[30841]: [INFO] devIdx: 0
May 15 11:22:18 atc-stream-rpi rtl_airband[30841]: [INFO] hwVer: 255
May 15 11:22:18 atc-stream-rpi rtl_airband[30841]: [INFO] rspDuoMode: 0
May 15 11:22:18 atc-stream-rpi rtl_airband[30841]: [INFO] tuner: 1
May 15 11:22:18 atc-stream-rpi rtl_airband[30841]: [INFO] rspDuoSampleFreq: 0.000000
May 15 11:22:18 atc-stream-rpi rtl_airband[30841]: [30845]: sdrplay_api_device: strmHandlerThread: Entry
May 15 11:22:18 atc-stream-rpi rtl_airband[30841]: [30846]: sdrplay_api_device: eventHandlerThread: Entry
May 15 11:22:18 atc-stream-rpi rtl_airband[30841]: [30847]: sdrplay_api_device: heartBeatThread: Entry
May 15 11:22:18 atc-stream-rpi rtl_airband[30841]: [30846]: sdrplay_api_device: eventHandlerThread: Exit
May 15 11:22:19 atc-stream-rpi rtl_airband[30841]: [30845]: sdrplay_api_device: strmHandlerThread: Exit
May 15 11:22:19 atc-stream-rpi rtl_airband[30841]: [30847]: sdrplay_api_device: heartBeatThread: Exit
May 15 11:22:19 atc-stream-rpi rtl_airband[30841]: SoapySDR: device 'driver=sdrplay,biasT_ctrl=false': using native sample format 'CS16' (fullScale=32767.0)
May 15 11:22:19 atc-stream-rpi rtl_airband[30841]: RTLSDR-Airband version 3.1.0 starting
May 15 11:22:19 atc-stream-rpi rtl_airband[30841]: [INFO] devIdx: 0
May 15 11:22:19 atc-stream-rpi rtl_airband[30841]: [INFO] hwVer: 255
May 15 11:22:19 atc-stream-rpi rtl_airband[30841]: [INFO] rspDuoMode: 0
May 15 11:22:19 atc-stream-rpi rtl_airband[30841]: [INFO] tuner: 1
May 15 11:22:19 atc-stream-rpi rtl_airband[30841]: [INFO] rspDuoSampleFreq: 0.000000
May 15 11:22:19 atc-stream-rpi rtl_airband[30841]: [30851]: sdrplay_api_device: strmHandlerThread: Entry
May 15 11:22:19 atc-stream-rpi rtl_airband[30841]: [30852]: sdrplay_api_device: eventHandlerThread: Entry
May 15 11:22:19 atc-stream-rpi rtl_airband[30841]: [30853]: sdrplay_api_device: heartBeatThread: Entry
May 15 11:22:19 atc-stream-rpi rtl_airband[30841]: [INFO] Using format CS16.
May 15 11:22:20 atc-stream-rpi rtl_airband[30841]: SoapySDR: device 'driver=sdrplay,biasT_ctrl=false': sample rate set to 8000000 sps
May 15 11:22:20 atc-stream-rpi rtl_airband[30841]: SoapySDR: device 'driver=sdrplay,biasT_ctrl=false': AGC off (requested: off)
May 15 11:22:20 atc-stream-rpi rtl_airband[30841]: SoapySDR: device 'driver=sdrplay,biasT_ctrl=false': gain 'IFGR' set to 40.0 dB
May 15 11:22:20 atc-stream-rpi rtl_airband[30841]: SoapySDR: device 'driver=sdrplay,biasT_ctrl=false': gain 'RFGR' set to 4.0 dB
May 15 11:22:20 atc-stream-rpi rtl_airband[30841]: SoapySDR: device 'driver=sdrplay,biasT_ctrl=false' initialized
May 15 11:22:20 atc-stream-rpi rtl_airband[30841]: SoapySDR: device 'driver=sdrplay,biasT_ctrl=false' started
May 15 11:22:34 atc-stream-rpi rtl_airband[30841]: Writing to /home/pi/rtlsdr_airband_data/twr_mp3//TWR_20210515_10.mp3
May 15 11:22:34 atc-stream-rpi rtl_airband[30841]: Writing to /home/pi/rtlsdr_airband_data/arr_dep_mp3//ARR_DEP_20210515_10.mp3
May 15 11:22:34 atc-stream-rpi rtl_airband[30841]: Writing to /home/pi/rtlsdr_airband_data/atis_mp3//ATIS_20210515_10.mp3

system journal when rtl_airband is shutting down

May 15 12:31:21 atc-stream-rpi rtl_airband[30841]: OSoapySDR device 'driver=sdrplay,biasT_ctrl=false': readStream failed: OVERFLOW, disabling
May 15 12:31:22 atc-stream-rpi rtl_airband[30841]: [30852]: sdrplay_api_device: eventHandlerThread: Exit
May 15 12:31:22 atc-stream-rpi rtl_airband[30841]: [30853]: sdrplay_api_device: heartBeatThread: Exit
May 15 12:31:22 atc-stream-rpi rtl_airband[30841]: [30851]: sdrplay_api_device: strmHandlerThread: Exit
May 15 12:31:22 atc-stream-rpi rtl_airband[30841]: [30841]: sdrplay_api_Close
May 15 12:31:22 atc-stream-rpi rtl_airband[30841]: Disabling device outputAll receivers failed, exiting
May 15 12:31:22 atc-stream-rpi rtl_airband[30841]: Cleaning up
May 15 12:31:22 atc-stream-rpi rtl_airband[30841]: Input threads closed
May 15 12:31:22 atc-stream-rpi rtl_airband[30841]: Disabling device output
May 15 12:31:22 atc-stream-rpi systemd[1]: rtl_airband.service: Succeeded.

/var/log/messages at sudo systemctl start rtl_airband

May 15 11:22:18 atc-stream-rpi rtl_airband: [30841]: sdrplay_api_Open
May 15 11:22:18 atc-stream-rpi sdrplay_apiService: [30843]: sdrplay_apiService_device: mCmdHandlerThread: Entry
May 15 11:22:18 atc-stream-rpi rtl_airband: [30845]: sdrplay_api_device: strmHandlerThread: Entry
May 15 11:22:18 atc-stream-rpi sdrplay_apiService: [30844]: sdrplay_apiService_rsp: streamThread: Entry
May 15 11:22:18 atc-stream-rpi rtl_airband: [30846]: sdrplay_api_device: eventHandlerThread: Entry
May 15 11:22:18 atc-stream-rpi sdrplay_apiService: [30843]: sdrplay_apiService_rsp_log_enable 3
May 15 11:22:18 atc-stream-rpi rtl_airband: [30847]: sdrplay_api_device: heartBeatThread: Entry
May 15 11:22:18 atc-stream-rpi sdrplay_apiService: [554]: sdrplay_apiService_log_enable: 0
May 15 11:22:18 atc-stream-rpi sdrplay_apiService: [30843]: sdrplay_apiService_rsp_log_enable 0
May 15 11:22:18 atc-stream-rpi rtl_airband: [30846]: sdrplay_api_device: eventHandlerThread: Exit
May 15 11:22:19 atc-stream-rpi rtl_airband: [30845]: sdrplay_api_device: strmHandlerThread: Exit
May 15 11:22:19 atc-stream-rpi rtl_airband: [30847]: sdrplay_api_device: heartBeatThread: Exit
May 15 11:22:19 atc-stream-rpi sdrplay_apiService: [30844]: sdrplay_apiService_rsp: streamThread: Exit
May 15 11:22:19 atc-stream-rpi sdrplay_apiService: [30843]: sdrplay_apiService_device: mCmdHandlerThread: Exit
May 15 11:22:19 atc-stream-rpi sdrplay_apiService: [30849]: sdrplay_apiService_device: mCmdHandlerThread: Entry
May 15 11:22:19 atc-stream-rpi sdrplay_apiService: [30850]: sdrplay_apiService_rsp: streamThread: Entry
May 15 11:22:19 atc-stream-rpi rtl_airband: [30851]: sdrplay_api_device: strmHandlerThread: Entry
May 15 11:22:19 atc-stream-rpi rtl_airband: [30852]: sdrplay_api_device: eventHandlerThread: Entry
May 15 11:22:19 atc-stream-rpi rtl_airband: [30853]: sdrplay_api_device: heartBeatThread: Entry
May 15 11:22:19 atc-stream-rpi sdrplay_apiService: [30849]: sdrplay_apiService_rsp_log_enable 0
May 15 11:22:19 atc-stream-rpi sdrplay_apiService: [554]: sdrplay_apiService_log_enable: 0
May 15 11:22:19 atc-stream-rpi sdrplay_apiService: [30849]: sdrplay_apiService_rsp_log_enable 0
May 15 11:22:19 atc-stream-rpi sdrplay_apiService: [554]: sdrplay_apiService_log_enable: 0
May 15 11:22:19 atc-stream-rpi sdrplay_apiService: [30849]: sdrplay_apiService_rsp_log_enable 0

/var/log/messages when rtl_airband is shutting down

May 15 12:31:22 atc-stream-rpi rtl_airband: [30852]: sdrplay_api_device: eventHandlerThread: Exit
May 15 12:31:22 atc-stream-rpi rtl_airband: [30853]: sdrplay_api_device: heartBeatThread: Exit
May 15 12:31:22 atc-stream-rpi rtl_airband: [30851]: sdrplay_api_device: strmHandlerThread: Exit
May 15 12:31:22 atc-stream-rpi sdrplay_apiService: [30850]: sdrplay_apiService_rsp: streamThread: Exit
May 15 12:31:22 atc-stream-rpi sdrplay_apiService: [30849]: sdrplay_apiService_device: mCmdHandlerThread: Exit
May 15 12:31:22 atc-stream-rpi rtl_airband: [30841]: sdrplay_api_Close

/usr/local/etc/rtl_airband.conf

# global options
fft_size = 2048;
multiple_demod_threads = true;
stats_filepath = "/home/pi/rtlsdr_airband_data/rtlsdr_airband_stats.txt";

devices:
({
  type = "soapysdr";
  device_string = "driver=sdrplay,biasT_ctrl=false"
  gain = "IFGR=40,RFGR=4";
  sample_rate = 8.0;
  centerfreq = 124.225;
  channels:
  (
    {
      freq = 121.525;
      outputs: (
        {
           type = "file";
           directory = "/home/pi/rtlsdr_airband_data/twr_mp3/";
           filename_template = "TWR";
           continuous = true;
        }
      );
    },
        {
           type = "file";
           directory = "/home/pi/rtlsdr_airband_data/twr_mp3/";
           filename_template = "TWR";
           continuous = true;
        }
      );
    },
    {
      freq = 127.025;
      outputs: (
        {
           type = "file";
           directory = "/home/pi/rtlsdr_airband_data/arr_dep_mp3/";
           filename_template = "ARR_DEP";
           continuous = true;
        }
      );
    },
    {
      freq = 124.025;
      outputs: (
        {
           type = "file";
           directory = "/home/pi/rtlsdr_airband_data/atis_mp3/";
           filename_template = "ATIS";
           continuous = true;
           append = false;
        }
      );
    }
  );
 }
);

[szpajder]

Please try the code from the current "unstable" branch. I have recently pushed a change there which makes SoapySDR stream reading errors non-fatal. It won't cure the root cause, but at least the program will continue running and try to read from the device anyway. Just note that the build system in unstable has recently changed, so compilation instructions from the Wiki no longer apply. Please use instructions from README.md in unstable branch.

[thowe-switzerland]

Thanks Tomasz! 👍

Just checked it out and built for RPi4 according to README.md. Build/install went fine and the following version is spinning right now:

RTLSDR-Airband version 4.0.0pre-891dc48

I'll let you know for how long this version is remaining running. :-)

It seems not uncommon for SoapySDR devices to run into this read stream overflow problem. And you write in all cases that rtlsdr_airband can't fix the cause but at most handle it resiliently.

This raises some questions for me:

1. What exactly is this buffer overflow problem?
2. Why does this overflow problem occur?
3. Who and how can solve it causally?
4. Do I have to post it to SoapySDR or its module for SDRPlay?

[thowe-switzerland]

Interim report: The build based on unstable branch seems to run through so far: 2.5h uptime the release never achieved.

I'll stay in touch.

[thowe-switzerland]

Looks really good! Thanks for the changes in the unstable branch.

Uptime is now around 7 hours without a problem. The audio quality of the RSP1A in this configuration with a bandwidth of 8 MHz is surprisingly good. If the operation remains stable, this will be my new setup.

Other question: Should read stream overflows be listed in the statistics file? Surprisingly there is always 0. Or is this counter no longer incremented due to the modification?

# HELP buffer_overflow_count Number of times a device's buffer has overflowed.
# TYPE buffer_overflow_count counter
buffer_overflow_count{device="0"}       0

[szpajder]

There are two buffering layers involved. The first one is between SoapySDR and the application (in this case - rtl_airband's input thread). The second one is in rtl_airband - between the input thread and the demodulation thread. So there is a three-stage pipeline which is synchronized with mutexes, so that the writing thread does not clobber the buffer with the new data before the reading thread makes some free space by reading the data from it. In case there is not enough space in the buffer, the writing thread declares an overflow event which means a batch of samples gets dropped. The buffer_overflow_count counter only counts overflows that happen in the second buffering stage and this is why you don't see it being incremented on SoapySDR overflows.

Overflows are more likely to happen when using high sampling rates. An occasional overflow isn't usually a problem. If they happen very often, it usually means that the CPU is not fast enough to handle that amount of work. The way to go then is either to reduce CPU usage (by reducing sample rate and/or FFT size or switching off other CPU intensive tasks) or use a faster machine.

[thowe-switzerland]

Thank you for the very good and detailed explanation. I can understand it very well.

The RPi 4 has been running in this configuration for more than 30h now without any problems. I have listened to some of the MP3 files produced: everything seems fine in really excellent quality. I am always amazed to see what the team of SDR and rtlsdr_airband can produce. Fantastic!

From my point of view this ticket can be closed.

Thanks for the impressive software and the excellent support. Appreciate it very much.

[szpajder]

Thanks for the feedback and your kind words.

I'll close the issue after releasing a stable version containing the fix.

[thowe-switzerland]

A little addendum from the field with the new more robust behavior and catching of stream overflows.

The RSP1A now no longer crashes on such a buffer overflow. The audio stream continues to run. However, one notices that apparently samples are lost:

• Sporadically (about every 15 minutes), individual syllables are missing from the ATC stream for fractions of a second. This is not a problem for intelligibility and is only rarely noticed.
• At the same time, I also recorded the stream with an Airspy mini for comparison: This has no overflows and records continuously. At the beginning, both streams are congruent. However, due to the missing samples, the Airspy stream is about one second behind the RSPA1A stream after one hour.

Completely different note: Through my intensive tests I can now say that the RSP1A and the Airspy mini have absolutely identical performance for air traffic communication in the VHF range at least in my setup on the same antenna. You can switch back and forth - zero difference.

[szpajder]

Fix released in v4.0.0.

Closing.