Skip to content

Commit

Permalink
Clean up how logging works. (#773)
Browse files Browse the repository at this point in the history
* Begin cleanup of logging.

* Fix Windows build failure.

* Bump up minimum macOS version to 10.13 to make compiler happy about fmemopen().

* Switch printf/fprintf to log_* calls.

* Remove spurious newlines from log messages.

* Remove g_verbose from codebase.

* Ensure Hamlib logs via ulog.

* Convert cerr/cout to ulog.

* Fix unit test and Linux compiler errors.

* Strip newlines from end of hamlib log messages.

* It would help if we actually printed the non-newline version of the log message.

* Actually fix Windows compiler errors.

* Replace additional printfs with log_* after merge from main.

* Add locking around logging to make sure we don't lose any.

* Try disabling color to get Windows tests working again.

* Use regular wine instead of wine-staging.

* Revert "Use regular wine instead of wine-staging."

This reverts commit 88bf4ef.

* Add missed changelog entries.

* Poll for xvfb to come up.

* Try framebuffer dir instead.

* Fix typo.

* Try 24 bit color.

* Try xvfb-run instead.

* Fix xvfb-run command.

* Try the screen arguments again.

* Try wine-devel instead as it might be more stable.

* Update cmake-windows.yml

* Lock log mutex before running RADE RX.

This is to avoid test output loss on Windows.

* Log to stderr and not stdout.

* Update RADEReceiveStep.cpp
  • Loading branch information
tmiw authored Nov 24, 2024
1 parent 0d40130 commit 8b87553
Show file tree
Hide file tree
Showing 35 changed files with 1,271 additions and 235 deletions.
11 changes: 4 additions & 7 deletions .github/workflows/cmake-windows.yml
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -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
Expand Down
2 changes: 1 addition & 1 deletion CMakeLists.txt
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand Down
2 changes: 2 additions & 0 deletions USER_MANUAL.md
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand Down
6 changes: 5 additions & 1 deletion src/CMakeLists.txt
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand Down Expand Up @@ -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)
20 changes: 5 additions & 15 deletions src/audio/PulseAudioDevice.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -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(
Expand All @@ -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(
Expand Down Expand Up @@ -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;

Expand Down
1 change: 1 addition & 0 deletions src/defines.h
Original file line number Diff line number Diff line change
Expand Up @@ -22,6 +22,7 @@
#define __FDMDV2_DEFINES__

#include "wx/wx.h"
#include "util/logging/ulog.h"
#include "freedv_api.h"
#include "modem_stats.h"

Expand Down
4 changes: 3 additions & 1 deletion src/freedv_interface.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand Down Expand Up @@ -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);
Expand Down
8 changes: 1 addition & 7 deletions src/gui/controls/plot_scatter.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -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;

Expand All @@ -210,9 +206,7 @@ void PlotScatter::draw(wxGraphicsContext* ctx)
}
prev_x = x; prev_y = y;
}
//printf("\n");
}

}
}
}

Expand Down
44 changes: 19 additions & 25 deletions src/gui/dialogs/dlg_audiooptions.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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;
}
Expand All @@ -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");
Expand All @@ -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,
Expand All @@ -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,
Expand Down Expand Up @@ -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);
Expand All @@ -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) {
Expand All @@ -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);

Expand Down Expand Up @@ -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)
{
Expand Down
2 changes: 1 addition & 1 deletion src/gui/dialogs/dlg_easy_setup.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -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();
}
Expand Down
10 changes: 0 additions & 10 deletions src/gui/dialogs/dlg_filter.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -644,7 +644,6 @@ void FilterDlg::OnSpkOutDefault(wxCommandEvent& event)
//-------------------------------------------------------------------------
void FilterDlg::OnOK(wxCommandEvent& event)
{
//printf("FilterDlg::OnOK\n");
Close();
}

Expand All @@ -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) {
Expand Down Expand Up @@ -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();
Expand Down Expand Up @@ -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();
Expand Down Expand Up @@ -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
Expand All @@ -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]);
}
}
Loading

0 comments on commit 8b87553

Please sign in to comment.