Skip to content

Commit

Permalink
Improve the logging implementation (#943)
Browse files Browse the repository at this point in the history 
* better logging

* more logging
  • Loading branch information
@robotastic
robotastic committed Apr 2, 2024
1 parent fbe8719 commit eaffa01
Show file tree
Hide file tree
Showing 13 changed files with 123 additions and 85 deletions.
7 changes: 4 additions & 3 deletions plugins/openmhz_uploader/openmhz_uploader.cc
View file
Original file line number Diff line number Diff line change
Expand Up @@ -291,13 +291,14 @@ class Openmhz_Uploader : public Plugin_Api {
if (res == CURLM_OK && response_code == 200) {
struct stat file_info;
stat(call_info.converted, &file_info);

BOOST_LOG_TRIVIAL(info) << "[" << call_info.short_name << "]\t\033[0;34m" << call_info.call_num << "C\033[0m\tTG: " << call_info.talkgroup_display << "\tFreq: " << format_freq(call_info.freq) << "\tOpenMHz Upload Success - file size: " << file_info.st_size;
std::string loghdr = log_header(call_info.short_name,call_info.call_num,talkgroup_display,call_info.freq);
BOOST_LOG_TRIVIAL(info) << loghdr << "\tOpenMHz Upload Success - file size: " << file_info.st_size;
;
return 0;
}
}
BOOST_LOG_TRIVIAL(error) << "[" << call_info.short_name << "]\t\033[0;34m" << call_info.call_num << "C\033[0m\tTG: " << call_info.talkgroup_display << "\tFreq: " << format_freq(call_info.freq) << "\tOpenMHz Upload Error: " << response_buffer;
std::string loghdr = log_header(call_info.short_name,call_info.call_num,talkgroup_display,call_info.freq);
BOOST_LOG_TRIVIAL(error) << loghdr << "\tOpenMHz Upload Error: " << response_buffer;
return 1;
}

Expand Down
12 changes: 8 additions & 4 deletions plugins/rdioscanner_uploader/rdioscanner_uploader.cc
View file
Original file line number Diff line number Diff line change
Expand Up @@ -115,7 +115,10 @@ class Rdio_Scanner_Uploader : public Plugin_Api {
} else {
patch_list << "]";
}

char formattedTalkgroup[62];
snprintf(formattedTalkgroup, 61, "%c[%dm%10ld%c[0m", 0x1B, 35, call_info.talkgroup, 0x1B);
std::string talkgroup_display = boost::lexical_cast<std::string>(formattedTalkgroup);

std::ostringstream freq_list;
std::string freq_list_string;
freq_list << std::fixed << std::setprecision(2);
Expand Down Expand Up @@ -327,13 +330,14 @@ class Rdio_Scanner_Uploader : public Plugin_Api {
if (res == CURLM_OK && response_code == 200) {
struct stat file_info;
stat(compress_wav ? call_info.converted : call_info.filename, &file_info);

BOOST_LOG_TRIVIAL(info) << "[" << call_info.short_name << "]\t\033[0;34m" << call_info.call_num << "C\033[0m\tTG: " << call_info.talkgroup_display << "\tFreq: " << format_freq(call_info.freq) << "\tRdio Scanner Upload Success - file size: " << file_info.st_size;
std::string loghdr = log_header(call_info.short_name,call_info.call_num,talkgroup_display,call_info.freq);
BOOST_LOG_TRIVIAL(info) << loghdr << "\tRdio Scanner Upload Success - file size: " << file_info.st_size;
;
return 0;
}
}
BOOST_LOG_TRIVIAL(error) << "[" << call_info.short_name << "]\t\033[0;34m" << call_info.call_num << "C\033[0m\tTG: " << call_info.talkgroup_display << "\tFreq: " << format_freq(call_info.freq) << "\tRdio Scanner Upload Error: " << response_buffer;
std::string loghdr = log_header(call_info.short_name,call_info.call_num,talkgroup_display,call_info.freq);
BOOST_LOG_TRIVIAL(error) << loghdr << "\tRdio Scanner Upload Error: " << response_buffer;
return 1;
}

Expand Down
30 changes: 17 additions & 13 deletions trunk-recorder/call_concluder/call_concluder.cc
View file
Original file line number Diff line number Diff line change
Expand Up @@ -116,7 +116,8 @@ int create_call_json(Call_Data_t& call_info) {
json_file << json_data.dump(2);
return 0;
} else {
BOOST_LOG_TRIVIAL(error) << "[" << call_info.short_name << "]\t\033[0;34m" << call_info.call_num << "C\033[0m \t Unable to create JSON file: " << call_info.status_filename;
std::string loghdr = log_header( call_info.short_name, call_info.call_num, call_info.talkgroup_display , call_info.freq);
BOOST_LOG_TRIVIAL(error) << loghdr << "C\033[0m \t Unable to create JSON file: " << call_info.status_filename;
return 1;
}
}
Expand Down Expand Up @@ -239,8 +240,8 @@ Call_Data_t upload_call_worker(Call_Data_t call_info) {
if (call_info.upload_script.length() != 0) {
shell_command << call_info.upload_script << " " << call_info.filename << " " << call_info.status_filename << " " << call_info.converted;
shell_command_string = shell_command.str();

BOOST_LOG_TRIVIAL(info) << "[" << call_info.short_name << "]\t\033[0;34m" << call_info.call_num << "C\033[0m \t Running upload script: " << shell_command_string;
std::string loghdr = log_header( call_info.short_name, call_info.call_num, call_info.talkgroup_display , call_info.freq);
BOOST_LOG_TRIVIAL(info) << loghdr << "C\033[0m \t Running upload script: " << shell_command_string;

result = system(shell_command_string.c_str());
}
Expand Down Expand Up @@ -356,8 +357,8 @@ Call_Data_t Call_Concluder::create_call_data(Call *call, System *sys, Config con

if (t.length < sys->get_min_tx_duration()) {
if (!call_info.transmission_archive) {

BOOST_LOG_TRIVIAL(info) << "[" << call_info.short_name << "]\t\033[0;34m" << call_info.call_num << "C\033[0m\tTG: " << call_info.talkgroup_display << "\tFreq: " << format_freq(call_info.freq) << "\tRemoving transmission less than " << sys->get_min_tx_duration() << " seconds. Actual length: " << t.length << ".";
std::string loghdr = log_header( call_info.short_name, call_info.call_num, call_info.talkgroup_display , call_info.freq);
BOOST_LOG_TRIVIAL(info) << loghdr << "\tRemoving transmission less than " << sys->get_min_tx_duration() << " seconds. Actual length: " << t.length << ".";
call_info.min_transmissions_removed++;

if (checkIfFile(t.filename)) {
Expand All @@ -376,7 +377,8 @@ Call_Data_t Call_Concluder::create_call_data(Call *call, System *sys, Config con
}

std::stringstream transmission_info;
transmission_info << "[" << call_info.short_name << "]\t\033[0;34m" << call_info.call_num << "C\033[0m\tTG: " << call_info.talkgroup_display << "\tFreq: " << format_freq(call_info.freq) << "\t- Transmission src: " << t.source << display_tag << " pos: " << format_time(total_length) << " length: " << format_time(t.length);
std::string loghdr = log_header( call_info.short_name, call_info.call_num, call_info.talkgroup_display , call_info.freq);
transmission_info << loghdr << "\t- Transmission src: " << t.source << display_tag << " pos: " << format_time(total_length) << " length: " << format_time(t.length);

if (t.error_count < 1) {
BOOST_LOG_TRIVIAL(info) << transmission_info.str();
Expand Down Expand Up @@ -411,22 +413,23 @@ Call_Data_t Call_Concluder::create_call_data(Call *call, System *sys, Config con
void Call_Concluder::conclude_call(Call *call, System *sys, Config config) {
Call_Data_t call_info = create_call_data(call, sys, config);

std::string loghdr = log_header( call_info.short_name, call_info.call_num, call_info.talkgroup_display , call_info.freq);
if(call->get_state() == MONITORING && call->get_monitoring_state() == SUPERSEDED){
BOOST_LOG_TRIVIAL(info) << "[" << call_info.short_name << "]\t\033[0;34m" << call_info.call_num << "C\033[0m\tTG: " << call_info.talkgroup_display << "\tFreq: " << format_freq(call_info.freq) << "\tCall has been superseded. Removing files.";
BOOST_LOG_TRIVIAL(info) << loghdr << "\tCall has been superseded. Removing files.";
remove_call_files(call_info);
return;
}
else if (call_info.transmission_list.size()== 0 && call_info.min_transmissions_removed == 0) {
BOOST_LOG_TRIVIAL(error) << "[" << call_info.short_name << "]\t\033[0;34m" << call_info.call_num << "C\033[0m\tTG: " << call_info.talkgroup_display << "\t Freq: " << format_freq(call_info.freq) << "\tNo Transmissions were recorded!";
BOOST_LOG_TRIVIAL(error) << loghdr << "\tNo Transmissions were recorded!";
return;
}
else if (call_info.transmission_list.size() == 0 && call_info.min_transmissions_removed > 0) {
BOOST_LOG_TRIVIAL(info) << "[" << call_info.short_name << "]\t\033[0;34m" << call_info.call_num << "C\033[0m\tTG: " << call_info.talkgroup_display << "\t Freq: " << format_freq(call_info.freq) << "\tNo Transmissions were recorded! " << call_info.min_transmissions_removed << " tranmissions less than " << sys->get_min_tx_duration() << " seconds were removed.";
BOOST_LOG_TRIVIAL(info) << loghdr << "\tNo Transmissions were recorded! " << call_info.min_transmissions_removed << " tranmissions less than " << sys->get_min_tx_duration() << " seconds were removed.";
return;
}

if (call_info.length <= sys->get_min_duration()) {
BOOST_LOG_TRIVIAL(error) << "[" << call_info.short_name << "]\t\033[0;34m" << call_info.call_num << "C\033[0m\tTG: " << call_info.talkgroup_display << "\t Freq: " << format_freq(call_info.freq) << "\t Call length: " << call_info.length << " is less than min duration: " << sys->get_min_duration();
BOOST_LOG_TRIVIAL(error) << loghdr << "\t Call length: " << call_info.length << " is less than min duration: " << sys->get_min_duration();
remove_call_files(call_info);
return;
}
Expand All @@ -440,20 +443,21 @@ void Call_Concluder::manage_call_data_workers() {

if (it->wait_for(std::chrono::seconds(0)) == std::future_status::ready) {
Call_Data_t call_info = it->get();

if (call_info.status == RETRY) {
call_info.retry_attempt++;
time_t start_time = call_info.start_time;
std::string loghdr = log_header( call_info.short_name, call_info.call_num, call_info.talkgroup_display , call_info.freq);

if (call_info.retry_attempt > Call_Concluder::MAX_RETRY) {
remove_call_files(call_info);
BOOST_LOG_TRIVIAL(error) << "[" << call_info.short_name << "]\t\033[0;34m" << call_info.call_num << "C\033[0m Failed to conclude call - TG: " << call_info.talkgroup_display << "\t" << std::put_time(std::localtime(&start_time), "%c %Z");
BOOST_LOG_TRIVIAL(error) << loghdr << " Failed to conclude call - TG: " << call_info.talkgroup_display << "\t" << std::put_time(std::localtime(&start_time), "%c %Z");
} else {
long jitter = rand() % 10;
long backoff = (2 ^ call_info.retry_attempt * 60) + jitter;
call_info.process_call_time = time(0) + backoff;
retry_call_list.push_back(call_info);
BOOST_LOG_TRIVIAL(error) << "[" << call_info.short_name << "]\t\033[0;34m" << call_info.call_num << "C\033[0m \tTG: " << call_info.talkgroup_display << "\t" << std::put_time(std::localtime(&start_time), "%c %Z") << " retry attempt " << call_info.retry_attempt << " in " << backoff << "s\t retry queue: " << retry_call_list.size() << " calls";
BOOST_LOG_TRIVIAL(error) << loghdr << " \tTG: " << call_info.talkgroup_display << "\t" << std::put_time(std::localtime(&start_time), "%c %Z") << " retry attempt " << call_info.retry_attempt << " in " << backoff << "s\t retry queue: " << retry_call_list.size() << " calls";
}
}
it = call_data_workers.erase(it);
Expand Down
17 changes: 10 additions & 7 deletions trunk-recorder/call_impl.cc
View file
Original file line number Diff line number Diff line change
Expand Up @@ -111,7 +111,8 @@ void Call_impl::stop_call() {
// If the call is being recorded, check to see if the recorder is currently in an INACTIVE state. This means that the recorder is not
// doing anything and can be stopped.
if ((state == RECORDING) && this->get_recorder()->is_idle()) {
BOOST_LOG_TRIVIAL(info) << "[" << sys->get_short_name() << "]\t\033[0;34m" << this->get_call_num() << "C\033[0m\tTG: " << this->get_talkgroup_display() << "\tFreq: " << format_freq(get_freq()) << "\tStopping Recorded Call_impl - Last Update: " << this->since_last_update() << "s";
std::string loghdr = log_header( sys->get_short_name(), this->get_call_num(), this->get_talkgroup_display(), this->get_freq());
BOOST_LOG_TRIVIAL(info) << loghdr << "\tStopping Recorded Call_impl - Last Update: " << this->since_last_update() << "s";
}
}
}
Expand Down Expand Up @@ -140,13 +141,15 @@ void Call_impl::conclude_call() {
} else {
this->set_signal(this->get_recorder()->get_pwr());
}

BOOST_LOG_TRIVIAL(info) << "[" << sys->get_short_name() << "]\t\033[0;34m" << this->get_call_num() << "C\033[0m\tTG: " << this->get_talkgroup_display() << "\tFreq: " << format_freq(get_freq()) << "\t\u001b[33mConcluding Recorded Call\u001b[0m - Last Update: " << this->since_last_update() << "s\tRecorder last write:" << recorder->since_last_write() << "\tCall Elapsed: " << this->elapsed() << "\t Signal: " << floor(this->get_signal()) << "dBm\t Noise: " << floor(this->get_noise()) << "dBm";
std::string loghdr = log_header( sys->get_short_name(), this->get_call_num(), this->get_talkgroup_display(), this->get_freq());
BOOST_LOG_TRIVIAL(info) << loghdr << "\t\u001b[33mConcluding Recorded Call\u001b[0m - Last Update: " << this->since_last_update() << "s\tRecorder last write:" << recorder->since_last_write() << "\tCall Elapsed: " << this->elapsed() << "\t Signal: " << floor(this->get_signal()) << "dBm\t Noise: " << floor(this->get_noise()) << "dBm";
} else {
BOOST_LOG_TRIVIAL(info) << "[" << sys->get_short_name() << "]\t\033[0;34m" << this->get_call_num() << "C\033[0m\tTG: " << this->get_talkgroup_display() << "\tFreq: " << format_freq(get_freq()) << "\t\u001b[33mConcluding Recorded Call\u001b[0m - Last Update: " << this->since_last_update() << "s\tRecorder last write:" << recorder->since_last_write() << "\tCall Elapsed: " << this->elapsed();
std::string loghdr = log_header( sys->get_short_name(), this->get_call_num(), this->get_talkgroup_display(), this->get_freq());
BOOST_LOG_TRIVIAL(info) << loghdr << "\t\u001b[33mConcluding Recorded Call\u001b[0m - Last Update: " << this->since_last_update() << "s\tRecorder last write:" << recorder->since_last_write() << "\tCall Elapsed: " << this->elapsed();
}
if (was_update) {
BOOST_LOG_TRIVIAL(info) << "[" << sys->get_short_name() << "]\t\033[0;34m" << this->get_call_num() << "C\033[0m\tTG: " << this->get_talkgroup_display() << "\tFreq: " << format_freq(get_freq()) << "\t\u001b[33mCall was UPDATE not GRANT\u001b[0m";
std::string loghdr = log_header( sys->get_short_name(), this->get_call_num(), this->get_talkgroup_display(), this->get_freq());
BOOST_LOG_TRIVIAL(info) << loghdr << "\t\u001b[33mCall was UPDATE not GRANT\u001b[0m";
}
freq_error = this->get_recorder()->get_freq_error();
this->get_recorder()->stop();
Expand Down Expand Up @@ -181,7 +184,6 @@ Recorder *Call_impl::get_debug_recorder() {

void Call_impl::set_recorder(Recorder *r) {
recorder = r;
// BOOST_LOG_TRIVIAL(info) << "[" << sys->get_short_name() << "]\t\033[0;34m" << this->get_call_num() << "C\033[0m\tTG: " << this->get_talkgroup_display() << "\tFreq: " << format_freq(this->get_freq()) << "\t\u001b[32mStarting Recorder on Src: " << recorder->get_source()->get_device() << "\u001b[0m";
}

Recorder *Call_impl::get_recorder() {
Expand Down Expand Up @@ -377,7 +379,8 @@ bool Call_impl::add_source(long src) {
bool Call_impl::update(TrunkMessage message) {
last_update = time(NULL);
if ((message.freq != this->curr_freq) || (message.talkgroup != this->talkgroup)) {
BOOST_LOG_TRIVIAL(error) << "[" << sys->get_short_name() << "]\t\033[0;34m" << this->get_call_num() << "C\033[0m\tCall_impl Update, message mismatch - Call_impl TG: " << get_talkgroup() << "\t Call_impl Freq: " << get_freq() << "\tMsg Tg: " << message.talkgroup << "\tMsg Freq: " << message.freq;
std::string loghdr = log_header( sys->get_short_name(), this->get_call_num(), this->get_talkgroup_display(), this->get_freq());
BOOST_LOG_TRIVIAL(error) << loghdr << "C\033[0m\tCall_impl Update, message mismatch - \ttMsg Tg: " << message.talkgroup << "\tMsg Freq: " << message.freq;
} else {
return add_source(message.source);
}
Expand Down
7 changes: 7 additions & 0 deletions trunk-recorder/formatter.cc
View file
Original file line number Diff line number Diff line change
Expand Up @@ -90,3 +90,10 @@ std::string format_state(State state, MonitoringState monitoringState) {
}
return boost::lexical_cast<std::string>(state);
}

std::string log_header(std::string short_name,long call_num, std::string talkgroup_display, double freq) {
std::stringstream ss;
ss << "[" << short_name << "]\t\033[0;34m" << call_num << "C\033[0m\tTG: " << talkgroup_display << "\tFreq: " << format_freq(freq) << "\t\u001b[36m";
std::string s = ss.str();
return s;
}
1 change: 1 addition & 0 deletions trunk-recorder/formatter.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -11,6 +11,7 @@ extern boost::format format_time(float f);
extern std::string format_state(State state);
extern std::string format_state(State state, MonitoringState monitoringState);
std::string get_frequency_format();
extern std::string log_header(std::string short_name,long call_num, std::string talkgroup_display, double freq);
extern int frequency_format;
extern bool statusAsString;

Expand Down

0 comments on commit eaffa01

Please sign in to comment.