Clean up how logging works.

.github/workflows/cmake-windows.yml

@@ -26,8 +26,8 @@ jobs:
         sudo sh -c "curl https://dl.winehq.org/wine-builds/winehq.key | gpg --dearmor > /etc/apt/trusted.gpg.d/winehq.gpg"
         sudo sh -c "apt-add-repository \"https://dl.winehq.org/wine-builds/ubuntu\""
         sudo apt-get update
-        echo "/opt/wine-staging/bin" >> $GITHUB_PATH
-        sudo apt install -y --install-recommends wine-staging
+        #echo "/opt/wine-staging/bin" >> $GITHUB_PATH
+        sudo apt install -y --install-recommends winehq-stable
         #sudo apt install -y --install-recommends wine64 wine32
 
     - name: Install required packages
@@ -47,12 +47,9 @@ jobs:
       run: |
           export WINEPREFIX=`pwd`/wine-env
           wget https://www.python.org/ftp/python/3.12.7/python-3.12.7-amd64.exe
-          Xvfb :99 -screen 0 1024x768x16 &
-          sleep 10
-          export DISPLAY=:99.0
-          wine ./python-3.12.7-amd64.exe /quiet /log c:\\python.log InstallAllUsers=1 Include_doc=0 Include_tcltk=0 || :
+          xvfb-run -a -e /dev/stdout --server-args="-screen 0 1024x768x24" wine ./python-3.12.7-amd64.exe /quiet /log c:\\python.log InstallAllUsers=1 Include_doc=0 Include_tcltk=0 || :
           cat $WINEPREFIX/drive_c/python.log
-          wine c:\\Program\ Files\\Python312\\Scripts\\pip.exe install numpy
+          DISPLAY= wine c:\\Program\ Files\\Python312\\Scripts\\pip.exe install numpy
 
     - name: Download MinGW LLVM
       shell: bash

CMakeLists.txt

@@ -12,7 +12,7 @@ if (CMAKE_VERSION VERSION_GREATER_EQUAL "3.24.0")
 	cmake_policy(SET CMP0135 NEW)
 endif()
 
-set(CMAKE_OSX_DEPLOYMENT_TARGET "10.11" CACHE STRING "Minimum OS X deployment version")
+set(CMAKE_OSX_DEPLOYMENT_TARGET "10.13" CACHE STRING "Minimum OS X deployment version")
 
 set(PROJECT_NAME FreeDV)
 set(PROJECT_VERSION 2.0.0)

USER_MANUAL.md

@@ -895,13 +895,15 @@ LDPC | Low Density Parity Check Codes - a family of powerful FEC codes
     * Fix bug preventing saving of the previously used path when playing back files. (PR #729)
     * Fix bug preventing proper time display in FreeDV Reporter on macOS. (PR #748)
     * Set timeout for Hamlib comms to avoid GUI getting stuck. (PR #746)
+    * Fix various audio dropout issues, especially on Linux. (PR #761)
 2. Enhancements:
     * Show green line indicating RX frequency. (PR #725)
     * Update configuration of the Voice Keyer feature based on user feedback. (PR #730, #746)
     * Add monitor volume adjustment. (PR #733)
     * Avoid modifying the audio device configuration without the user explicitly doing so. (PR #735)
     * If provided by user, add config file to titlebar. (PR #738)
     * Minor adjustments to spectrum/waterfall tooltips. (PR #743)
+    * Implement new logging framework. (PR #773)
 3. Build system:
     * Allow overrriding the version tag when building. (PR #727)
     * Update wxWidgets to 3.2.6. (PR #748)

src/CMakeLists.txt

@@ -14,6 +14,10 @@ set(FREEDV_LINK_LIBS_OSX
     "-framework AVFoundation"
 )
 
+# Configure logging
+add_definitions(-DULOG_HAVE_TIME)
+add_definitions(-DULOG_NO_COLOR)
+
 # Compile FreeDV components
 add_subdirectory(audio)
 add_subdirectory(config)
@@ -186,4 +190,4 @@ if(SIGN_WINDOWS_BINARIES)
         COMMAND ${OSSLSIGNCODE_BIN} ARGS sign -pkcs11engine ${PKCS11_ENGINE} -pkcs11module ${PKCS11_MODULE} -pkcs11cert "${PKCS11_CERTIFICATE}" -key "${PKCS11_KEY}" -h ${SIGN_HASH} -ts ${TIMESTAMP_SERVER} -comm -ac ${INTERMEDIATE_CERT_FILE} -n "FreeDV - ${PROJECT_DESCRIPTION}" -i "https://freedv.org/" -in $<TARGET_FILE:freedv>.tmp -out $<TARGET_FILE:freedv>
         COMMAND rm $<TARGET_FILE:freedv>.tmp
         VERBATIM)
-endif(SIGN_WINDOWS_BINARIES)
+endif(SIGN_WINDOWS_BINARIES)

src/audio/PulseAudioDevice.cpp

@@ -25,6 +25,8 @@
 
 #include "PulseAudioDevice.h"
 
+#include "../util/logging/ulog.h"
+
 // Optimal settings based on ones used for PortAudio.
 #define PULSE_FPB 256
 #define PULSE_TARGET_LATENCY_US 20000
@@ -104,11 +106,7 @@ void PulseAudioDevice::start()
     int result = 0;
     if (direction_ == IAudioEngine::AUDIO_ENGINE_OUT)
     {
-        time_t result = time(NULL);
-        char buf[256];
-        struct tm *p = localtime(&result);
-        strftime(buf, 256, "%c", p);
-        fprintf(stderr, "PulseAudioDevice[%s]: connecting to playback device %s\n", buf, (const char*)devName_.ToUTF8());
+        log_info("Connecting to playback device %s", (const char*)devName_.ToUTF8());
 
         pa_stream_set_write_callback(stream_, &PulseAudioDevice::StreamWriteCallback_, this);
         result = pa_stream_connect_playback(
@@ -117,11 +115,7 @@ void PulseAudioDevice::start()
     }
     else
     {
-        time_t result = time(NULL);
-        char buf[256];
-        struct tm *p = localtime(&result);
-        strftime(buf, 256, "%c", p);
-        fprintf(stderr, "PulseAudioDevice[%s]: connecting to record device %s\n", buf, (const char*)devName_.ToUTF8());
+        log_info("Connecting to record device %s", (const char*)devName_.ToUTF8());
 
         pa_stream_set_read_callback(stream_, &PulseAudioDevice::StreamReadCallback_, this);
         result = pa_stream_connect_record(
@@ -337,11 +331,7 @@ void PulseAudioDevice::StreamMovedCallback_(pa_stream *p, void *userdata)
     auto newDevName = pa_stream_get_device_name(p);
     PulseAudioDevice* thisObj = static_cast<PulseAudioDevice*>(userdata);
 
-    time_t result = time(NULL);
-    char buf[256];
-    struct tm *lt = localtime(&result);
-    strftime(buf, 256, "%c", lt);
-    fprintf(stderr, "PulseAudioDevice[%s]: stream named %s has been moved to %s\n", buf, (const char*)thisObj->devName_.ToUTF8(), newDevName);
+    log_info("Stream named %s has been moved to %s", (const char*)thisObj->devName_.ToUTF8(), newDevName);
 
     thisObj->devName_ = newDevName;
 

src/defines.h

@@ -22,6 +22,7 @@
 #define __FDMDV2_DEFINES__
 
 #include "wx/wx.h"
+#include "util/logging/ulog.h"
 #include "freedv_api.h"
 #include "modem_stats.h"
 

src/freedv_interface.cpp

@@ -30,6 +30,8 @@
 #include "pipeline/RADETransmitStep.h"
 #include "pipeline/AudioPipeline.h"
 
+#include "util/logging/ulog.h"
+
 using namespace std::placeholders;
 
 static const char* GetCurrentModeStrImpl_(int mode)
@@ -91,7 +93,7 @@ static void callback_err_fn(void *fifo, short error_pattern[], int sz_error_patt
 
 void FreeDVInterface::OnReliableTextRx_(reliable_text_t rt, const char* txt_ptr, int length, void* state) 
 {
-    fprintf(stderr, "FreeDVInterface::OnReliableTextRx_: received %s\n", txt_ptr);
+    log_info("FreeDVInterface::OnReliableTextRx_: received %s", txt_ptr);
 
     FreeDVInterface* obj = (FreeDVInterface*)state;
     assert(obj != nullptr);

src/gui/controls/plot_scatter.cpp

@@ -184,22 +184,18 @@ void PlotScatter::draw(wxGraphicsContext* ctx)
         // much as scaling varies
 
         float quant_m_filter_max_y = exp(floor(0.5+log(m_filter_max_y)));
-        //printf("min_y: %4.3f max_y: %4.3f quant_m_filter_max_y: %4.3f\n", min_y, max_y, quant_m_filter_max_y);
 
         x_scale = (float)m_rGrid.GetWidth()/Ncol;
         y_scale = (float)m_rGrid.GetHeight()/quant_m_filter_max_y;
-        //printf("GetWidth(): %d GetHeight(): %d\n", m_rGrid.GetWidth(), m_rGrid.GetHeight());
 
         // plot eye traces row by row
 
         int prev_x, prev_y;
         prev_x = prev_y = 0;
         for(i=0; i<SCATTER_EYE_MEM_ROWS; i++) {
-            //printf("row: ");
             for(j=0; j<Ncol; j++) {
                 x = x_scale * j;
                 y = m_rGrid.GetHeight()*0.75 - y_scale * eye_mem[i][j];
-               //printf("%4d,%4d  ", x, y);
                 x += PLOT_BORDER + XLEFT_OFFSET;
                 y += PLOT_BORDER;
 
@@ -210,9 +206,7 @@ void PlotScatter::draw(wxGraphicsContext* ctx)
                 }
                 prev_x = x; prev_y = y;
             }
-            //printf("\n");
-        }
-
+        }        
     }
 }
 

src/gui/dialogs/dlg_audiooptions.cpp

@@ -93,7 +93,7 @@ AudioOptsDialog::AudioOptsDialog(wxWindow* parent, wxWindowID id, const wxString
         SetTitle(wxString::Format("%s (%s)", title, wxGetApp().customConfigFileName));
     }
 
-    if (g_verbose) fprintf(stderr, "pos %d %d\n", pos.x, pos.y);
+    log_debug("pos %d %d", pos.x, pos.y);
     audioEngineInit();
 
     wxBoxSizer* mainSizer;
@@ -407,7 +407,7 @@ bool AudioOptsDialog::setTextCtrlIfDevNameValid(wxTextCtrl *textCtrl, wxListCtrl
         if (listCtrl->GetItemText(i, 0).IsSameAs(devName))
         {
             textCtrl->SetValue(listCtrl->GetItemText(i, 0));
-            if (g_verbose) fprintf(stderr,"setting focus of %d\n", i);
+            log_debug("setting focus of %d", i);
             listCtrl->SetItemState(i, wxLIST_STATE_FOCUSED, wxLIST_STATE_FOCUSED);
             return true;
         }
@@ -426,8 +426,8 @@ int AudioOptsDialog::ExchangeData(int inout)
         // Map sound card device numbers to tx/rx device numbers depending
         // on number of sound cards in use
 
-        if (g_verbose) fprintf(stderr,"EXCHANGE_DATA_IN:\n");
-        if (g_verbose) fprintf(stderr,"  g_nSoundCards: %d\n", g_nSoundCards);
+        log_debug("EXCHANGE_DATA_IN:");
+        log_debug("  g_nSoundCards: %d", g_nSoundCards);
 
         if (g_nSoundCards == 0) {
             m_textCtrlRxIn ->SetValue("none");
@@ -437,13 +437,13 @@ int AudioOptsDialog::ExchangeData(int inout)
         }
 
         if (g_nSoundCards == 1) {
-            if (g_verbose) fprintf(stderr,"  m_soundCard1InSampleRate: %d\n", wxGetApp().appConfiguration.audioConfiguration.soundCard1In.sampleRate.get());
+            log_debug("  m_soundCard1InSampleRate: %d", wxGetApp().appConfiguration.audioConfiguration.soundCard1In.sampleRate.get());
 
             setTextCtrlIfDevNameValid(m_textCtrlRxIn, 
                                       m_listCtrlRxInDevices, 
                                       wxGetApp().appConfiguration.audioConfiguration.soundCard1In.deviceName);
 
-            if (g_verbose) fprintf(stderr,"  m_soundCard1OutSampleRate: %d\n", wxGetApp().appConfiguration.audioConfiguration.soundCard1Out.sampleRate.get());
+            log_debug("  m_soundCard1OutSampleRate: %d", wxGetApp().appConfiguration.audioConfiguration.soundCard1Out.sampleRate.get());
 
             setTextCtrlIfDevNameValid(m_textCtrlRxOut, 
                                       m_listCtrlRxOutDevices, 
@@ -463,25 +463,25 @@ int AudioOptsDialog::ExchangeData(int inout)
         }
 
         if (g_nSoundCards == 2) {
-            if (g_verbose) fprintf(stderr,"  m_soundCard1InSampleRate: %d\n", wxGetApp().appConfiguration.audioConfiguration.soundCard1In.sampleRate.get());
+            log_debug("  m_soundCard1InSampleRate: %d", wxGetApp().appConfiguration.audioConfiguration.soundCard1In.sampleRate.get());
 
             setTextCtrlIfDevNameValid(m_textCtrlRxIn, 
                                       m_listCtrlRxInDevices, 
                                       wxGetApp().appConfiguration.audioConfiguration.soundCard1In.deviceName);
 
-            if (g_verbose) fprintf(stderr,"  m_soundCard2OutSampleRate: %d\n", wxGetApp().appConfiguration.audioConfiguration.soundCard2Out.sampleRate.get());
+            log_debug("  m_soundCard2OutSampleRate: %d", wxGetApp().appConfiguration.audioConfiguration.soundCard2Out.sampleRate.get());
 
             setTextCtrlIfDevNameValid(m_textCtrlRxOut, 
                                       m_listCtrlRxOutDevices, 
                                       wxGetApp().appConfiguration.audioConfiguration.soundCard2Out.deviceName);
 
-            if (g_verbose) fprintf(stderr,"  m_soundCard2InDeviceName: %d\n", wxGetApp().appConfiguration.audioConfiguration.soundCard2In.sampleRate.get());
+            log_debug("  m_soundCard2InDeviceName: %d", wxGetApp().appConfiguration.audioConfiguration.soundCard2In.sampleRate.get());
 
             setTextCtrlIfDevNameValid(m_textCtrlTxIn, 
                                       m_listCtrlTxInDevices, 
                                       wxGetApp().appConfiguration.audioConfiguration.soundCard2In.deviceName);
 
-            if (g_verbose) fprintf(stderr,"  m_soundCard1OutSampleRate: %d\n", wxGetApp().appConfiguration.audioConfiguration.soundCard1Out.sampleRate.get());
+            log_debug("  m_soundCard1OutSampleRate: %d", wxGetApp().appConfiguration.audioConfiguration.soundCard1Out.sampleRate.get());
 
             setTextCtrlIfDevNameValid(m_textCtrlTxOut, 
                                       m_listCtrlTxOutDevices, 
@@ -557,7 +557,7 @@ int AudioOptsDialog::ExchangeData(int inout)
             sampleRate4 = m_cbSampleRateTxOut->GetValue();
         }
 
-        if (g_verbose) fprintf(stderr,"  valid_one_card_config: %d  valid_two_card_config: %d\n", valid_one_card_config, valid_two_card_config);
+        log_debug("  valid_one_card_config: %d  valid_two_card_config: %d", valid_one_card_config, valid_two_card_config);
 
         if (!valid_one_card_config && !valid_two_card_config) {
             wxMessageBox(wxT("Invalid one or two sound card configuration. For RX only, both devices in 'Receive' tab must be selected. Otherwise, all devices in both 'Receive' and 'Transmit' tabs must be selected."), wxT(""), wxOK);
@@ -575,11 +575,8 @@ int AudioOptsDialog::ExchangeData(int inout)
             wxGetApp().appConfiguration.audioConfiguration.soundCard1In.sampleRate = wxAtoi(sampleRate1);
             wxGetApp().appConfiguration.audioConfiguration.soundCard1Out.sampleRate = wxAtoi(sampleRate2);
 
-            if (g_verbose)
-            {
-                fprintf(stderr,"  m_soundCard1InSampleRate: %d\n", wxGetApp().appConfiguration.audioConfiguration.soundCard1In.sampleRate.get());
-                fprintf(stderr,"  m_soundCard1OutSampleRate: %d\n", wxGetApp().appConfiguration.audioConfiguration.soundCard1Out.sampleRate.get());
-            }
+            log_debug("  m_soundCard1InSampleRate: %d", wxGetApp().appConfiguration.audioConfiguration.soundCard1In.sampleRate.get());
+            log_debug("  m_soundCard1OutSampleRate: %d", wxGetApp().appConfiguration.audioConfiguration.soundCard1Out.sampleRate.get());
         }
 
         if (valid_two_card_config) {
@@ -589,16 +586,13 @@ int AudioOptsDialog::ExchangeData(int inout)
             wxGetApp().appConfiguration.audioConfiguration.soundCard2In.sampleRate = wxAtoi(sampleRate3);
             wxGetApp().appConfiguration.audioConfiguration.soundCard1Out.sampleRate = wxAtoi(sampleRate4);
 
-            if (g_verbose)
-            {
-                fprintf(stderr,"  m_soundCard1InSampleRate: %d\n", wxGetApp().appConfiguration.audioConfiguration.soundCard1In.sampleRate.get());
-                fprintf(stderr,"  m_soundCard2OutSampleRate: %d\n", wxGetApp().appConfiguration.audioConfiguration.soundCard2Out.sampleRate.get());
-                fprintf(stderr,"  m_soundCard2InSampleRate: %d\n", wxGetApp().appConfiguration.audioConfiguration.soundCard2In.sampleRate.get());
-                fprintf(stderr,"  m_soundCard1OutSampleRate: %d\n", wxGetApp().appConfiguration.audioConfiguration.soundCard1Out.sampleRate.get());
-            }
+            log_debug("  m_soundCard1InSampleRate: %d", wxGetApp().appConfiguration.audioConfiguration.soundCard1In.sampleRate.get());
+            log_debug("  m_soundCard2OutSampleRate: %d", wxGetApp().appConfiguration.audioConfiguration.soundCard2Out.sampleRate.get());
+            log_debug("  m_soundCard2InSampleRate: %d", wxGetApp().appConfiguration.audioConfiguration.soundCard2In.sampleRate.get());
+            log_debug("  m_soundCard1OutSampleRate: %d", wxGetApp().appConfiguration.audioConfiguration.soundCard1Out.sampleRate.get());
         }
 
-        if (g_verbose) fprintf(stderr,"  g_nSoundCards: %d\n", g_nSoundCards);
+        log_debug("  g_nSoundCards: %d", g_nSoundCards);
 
         assert (pConfig != NULL);
 
@@ -1171,7 +1165,7 @@ void AudioOptsDialog::OnOkAudioParameters(wxCommandEvent& event)
 
     // We only accept OK if config successful
 
-    if (g_verbose) fprintf(stderr,"status: %d m_isPaInitialized: %d\n", status, m_isPaInitialized);
+    log_debug("status: %d m_isPaInitialized: %d", status, m_isPaInitialized);
     if (status == 0) {
         if(m_isPaInitialized)
         {

src/gui/dialogs/dlg_easy_setup.cpp

@@ -579,7 +579,7 @@ void EasySetupDialog::ExchangePttDeviceData(int inout)
                 m_cbSerialRate->GetValue().ToLong(&tmp); 
                 wxGetApp().appConfiguration.rigControlConfiguration.hamlibSerialRate = tmp;
             }
-            if (g_verbose) fprintf(stderr, "serial rate: %d\n", wxGetApp().appConfiguration.rigControlConfiguration.hamlibSerialRate.get());
+            log_debug("serial rate: %d", wxGetApp().appConfiguration.rigControlConfiguration.hamlibSerialRate.get());
 
             wxGetApp().appConfiguration.rigControlConfiguration.hamlibPTTType = m_cbPttMethod->GetSelection();
         }

src/gui/dialogs/dlg_filter.cpp

@@ -644,7 +644,6 @@ void FilterDlg::OnSpkOutDefault(wxCommandEvent& event)
 //-------------------------------------------------------------------------
 void FilterDlg::OnOK(wxCommandEvent& event)
 {
-    //printf("FilterDlg::OnOK\n");
     Close();
 }
 
@@ -664,9 +663,7 @@ void FilterDlg::OnClose(wxCloseEvent& event)
 //-------------------------------------------------------------------------
 void FilterDlg::OnInitDialog(wxInitDialogEvent& event)
 {
-    //printf("FilterDlg::OnInitDialog\n");
     ExchangeData(EXCHANGE_DATA_IN);
-    //printf("m_beta: %f\n", m_beta);
 }
 
 void FilterDlg::setBeta(void) {
@@ -812,7 +809,6 @@ void FilterDlg::sliderToGain(EQ *eq, bool micIn)
     float range = MAX_GAIN-MIN_GAIN;
 
     eq->gaindB = MIN_GAIN + range*((float)eq->sliderGain->GetValue()/SLIDER_MAX_GAIN);
-    //printf("gaindB: %f\n", eq->gaindB);
     setGain(eq);
     if (micIn) {
         plotMicInFilterSpectrum();
@@ -844,7 +840,6 @@ void FilterDlg::sliderToQ(EQ *eq, bool micIn)
     float sliderNorm = (float)eq->sliderQ->GetValue()/SLIDER_MAX_Q;
     float log10Q =  MIN_LOG10_Q + sliderNorm*(log10_range);
     eq->Q = pow(10.0, log10Q);
-    //printf("log10Q: %f eq->Q: %f\n", log10Q, eq->Q);
     setQ(eq);
     if (micIn) {
         plotMicInFilterSpectrum();
@@ -959,15 +954,11 @@ void FilterDlg::calcFilterSpectrum(float magdB[], int argc, char *argv[]) {
         in[i] = 0;
     in[0] = IMP_AMP;
 
-    //printf("argv[0]: %s argv[1]: %s\n", argv[0], argv[1]);
     sbq = sox_biquad_create(argc, (const char **)argv);
 
     if (sbq != NULL)
     {
         sox_biquad_filter(sbq, out, in, NIMP);
-        //for(i=0; i<NIMP; i++)
-        //    printf("%d\n", out[i]);
-
         sox_biquad_destroy(sbq);
     }
     else
@@ -992,6 +983,5 @@ void FilterDlg::calcFilterSpectrum(float magdB[], int argc, char *argv[]) {
             X[i].imag -= ((float)out[k]/IMP_AMP) * sin(w*k);
         }
         magdB[i] = 10.0*log10(X[i].real* X[i].real + X[i].imag*X[i].imag + 1E-12);
-        //printf("f: %f X[%d] = %f %f magdB = %f\n", f, i, X[i].real, X[i].imag,  magdB[i]);
     }
 }