Add logging via spdlog library

It works for CPP, but from C code we have to keep using printf

Author: seriyps

.github/workflows/build.yml

@@ -54,7 +54,7 @@ jobs:
           tee /etc/apt/sources.list.d/80-rockchip.list <<< "deb [signed-by=/usr/share/keyrings/radxa-archive-keyring.gpg] https://radxa-repo.github.io/bullseye rockchip-bullseye main"
 
           apt-get update
-          apt-get install -y cmake g++ git pkg-config librockchip-mpp-dev libcairo-dev libdrm-dev libgstreamer1.0-dev libgstreamer-plugins-base1.0-dev
+          apt-get install -y cmake g++ git pkg-config librockchip-mpp-dev libcairo-dev libdrm-dev libgstreamer1.0-dev libgstreamer-plugins-base1.0-dev libspdlog-dev
           apt clean
 
           cmake -B build

CMakeLists.txt

@@ -23,12 +23,14 @@ set(SOURCE_FILES
         src/gstrtpreceiver.cpp
         src/gstrtpreceiver.h)
 
-include_directories("/usr/include/libdrm" "/usr/include/cairo")
+include_directories("/usr/include/libdrm" "/usr/include/cairo" "/usr/include/spdlog")
 
 configure_file("${PROJECT_NAME}_config.h.in" "${PROJECT_NAME}_config.h")
 
+find_package(spdlog REQUIRED)
+
 add_executable(${PROJECT_NAME} ${SOURCE_FILES})
-target_link_libraries(${PROJECT_NAME} rockchip_mpp pthread drm m cairo)
+target_link_libraries(${PROJECT_NAME} rockchip_mpp pthread drm m cairo spdlog::spdlog)
 
 # Embed gstreamer
 find_package(PkgConfig REQUIRED)
@@ -41,6 +43,7 @@ pkg_search_module(gstreamer-app REQUIRED IMPORTED_TARGET gstreamer-app-1.0>=1.4)
 target_link_libraries(${PROJECT_NAME} PkgConfig::gstreamer PkgConfig::gstreamer-app)
 
 if(CMAKE_BUILD_TYPE MATCHES "Debug")
+  add_compile_definitions(SPDLOG_ACTIVE_LEVEL=SPDLOG_LEVEL_TRACE)
   set(
     CMAKE_C_FLAGS
     "${CMAKE_C_FLAGS} -Werror -fsanitize=undefined -fsanitize=address"

README.md

@@ -19,10 +19,10 @@ Build on the Rockchip linux system directly.
 
 ## Install dependencies
 
-- drm, cairo, mpp
+- drm, cairo, mpp, logging
 
 ```
-sudo apt install libdrm-dev libcairo-dev librockchip-mpp-dev
+sudo apt install libdrm-dev libcairo-dev librockchip-mpp-dev libspdlog-dev
 ```
 
 - gstreamer

src/dvr.cpp

@@ -1,8 +1,9 @@
 #include <pthread.h>
-#include <stdio.h>
 #include <stdlib.h>
 #include <stdint.h>
 
+#include "spdlog/spdlog.h"
+
 #include "dvr.h"
 #include "minimp4.h"
 
@@ -108,7 +109,7 @@ void Dvr::loop() {
 			switch (rpc.command) {
 			case dvr_rpc::RPC_SET_PARAMS:
 				{
-					printf("got rpc SET_PARAMS\n");
+					SPDLOG_DEBUG("got rpc SET_PARAMS");
 					if (dvr_file == NULL) {
 						break;
 					}
@@ -117,7 +118,7 @@ void Dvr::loop() {
 				}
 			case dvr_rpc::RPC_START:
 				{
-					printf("got rpc START\n");
+					SPDLOG_DEBUG("got rpc START");
 					if (dvr_file != NULL) {
 						break;
 					}
@@ -129,7 +130,7 @@ void Dvr::loop() {
 				}
 			case dvr_rpc::RPC_STOP:
 				{
-					printf("got rpc STOP\n");
+					SPDLOG_DEBUG("got rpc STOP");
 					if (dvr_file == NULL) {
 						break;
 					}
@@ -138,7 +139,7 @@ void Dvr::loop() {
 				}
 			case dvr_rpc::RPC_TOGGLE:
 				{
-					printf("got rpc TOGGLE\n");
+					SPDLOG_DEBUG("got rpc TOGGLE");
 					if (dvr_file == NULL) {
 						start();
 						if (video_frm_width > 0 && video_frm_height > 0) {
@@ -157,7 +158,7 @@ void Dvr::loop() {
 					std::shared_ptr<std::vector<uint8_t>> frame = rpc.frame;
 					auto res = mp4_h26x_write_nal(mp4wr, frame->data(), frame->size(), 90000/video_framerate);
 					if (!(MP4E_STATUS_OK == res || MP4E_STATUS_BAD_ARGUMENTS == res)) {
-						printf("mp4_h26x_write_nal failed with error %d\n", res);
+						spdlog::warn("mp4_h26x_write_nal failed with error {}", res);
 					}
 					break;
 				}
@@ -170,7 +171,7 @@ void Dvr::loop() {
 	if (dvr_file != NULL) {
 		stop();
 	}
-	printf("DVR thread done.\n");
+	spdlog::info("DVR thread done.");
 }
 
 int Dvr::start() {
@@ -179,7 +180,7 @@ int Dvr::start() {
 	time_t t = time(NULL);
 	strftime(fname, sizeof(fname), fname_tpl, localtime(&t));
 	if ((dvr_file = fopen(fname,"w")) == NULL){
-		fprintf(stderr, "ERROR: unable to open %s\n", fname);
+		spdlog::error("unable to open DVR file {}", fname);
 		return -1;
 	}
 	osd_vars.enable_recording = 1;
@@ -189,12 +190,12 @@ int Dvr::start() {
 }
 
 void Dvr::init() {
-	printf("setting up dvr and mux to %dx%d\n", video_frm_width, video_frm_height);
+	spdlog::info("setting up dvr and mux to {}x{}", video_frm_width, video_frm_height);
 	if (MP4E_STATUS_OK != mp4_h26x_write_init(mp4wr, mux,
 											  video_frm_width,
 											  video_frm_height,
 											  codec==VideoCodec::H265)) {
-		fprintf(stderr, "error: mp4_h26x_write_init failed\n");
+		spdlog::error("mp4_h26x_write_init failed");
 		mux = NULL;
 		dvr_file = NULL;
 	}

src/gstrtpreceiver.cpp

@@ -7,6 +7,7 @@
 #include "gst/gstparse.h"
 #include "gst/gstpipeline.h"
 #include "gst/app/gstappsink.h"
+#include "spdlog/spdlog.h"
 #include <cstring>
 #include <stdexcept>
 #include <cassert>
@@ -15,8 +16,6 @@
 #include <memory>
 #include <utility>
 
-#define qDebug() std::cout
-
 namespace pipeline {
     static std::string gst_create_rtp_caps(const VideoCodec& videoCodec){
         std::stringstream ss;
@@ -143,20 +142,20 @@ void GstRtpReceiver::on_new_sample(std::shared_ptr<std::vector<uint8_t> > sample
 
 void GstRtpReceiver::start_receiving(NEW_FRAME_CALLBACK cb)
 {
-    std::cout<<"GstRtpReceiver::start_receiving begin"<<std::endl;
+    spdlog::info("GstRtpReceiver::start_receiving begin");
     assert(m_gst_pipeline==nullptr);
     m_cb=cb;
 
     const auto pipeline=construct_gstreamer_pipeline();
     GError *error = nullptr;
     m_gst_pipeline = gst_parse_launch(pipeline.c_str(), &error);
-    std::cout<< "GSTREAMER PIPE=[" << pipeline.c_str()<<"]"<<std::endl;
+    spdlog::info("GSTREAMER PIPE=[{}]", pipeline);
     if (error) {
-        qDebug() << "gst_parse_launch error: " << error->message;
+        spdlog::warn("gst_parse_launch error: {}", error->message);
         return;
     }
     if(!m_gst_pipeline || !(GST_IS_PIPELINE(m_gst_pipeline))){
-        qDebug()<<"Cannot construct pipeline";
+        spdlog::warn("Cannot construct pipeline");
         m_gst_pipeline = nullptr;
         return;
     }
@@ -168,7 +167,7 @@ void GstRtpReceiver::start_receiving(NEW_FRAME_CALLBACK cb)
     m_pull_samples_run= true;
     m_pull_samples_thread=std::make_unique<std::thread>(&GstRtpReceiver::loop_pull_samples, this);
 
-    qDebug()<<"GstRtpReceiver::start_receiving end";
+    spdlog::info("GstRtpReceiver::start_receiving end");
 }
 
 void GstRtpReceiver::stop_receiving()
@@ -187,4 +186,4 @@ void GstRtpReceiver::stop_receiving()
         gst_object_unref (m_gst_pipeline);
         m_gst_pipeline=nullptr;
     }
-}
+}

src/main.cpp

@@ -32,6 +32,7 @@
 #include <drm_fourcc.h>
 #include <linux/videodev2.h>
 #include <rockchip/rk_mpi.h>
+#include "spdlog/spdlog.h"
 
 extern "C" {
 #include "main.h"
@@ -92,7 +93,8 @@ void init_buffer(MppFrame frame) {
 	MppFrameFormat fmt = mpp_frame_get_fmt(frame);
 	assert((fmt == MPP_FMT_YUV420SP) || (fmt == MPP_FMT_YUV420SP_10BIT));
 
-	printf("Frame info changed %d(%d)x%d(%d)\n", output_list->video_frm_width, hor_stride, output_list->video_frm_height, ver_stride);
+	spdlog::info("Frame info changed {}({})x{}({})",
+				 output_list->video_frm_width, hor_stride, output_list->video_frm_height, ver_stride);
 
 	output_list->video_fb_x = 0;
 	output_list->video_fb_y = 0;
@@ -237,7 +239,7 @@ void *__FRAME_THREAD__(void *param)
 			frame = NULL;
 		} else assert(0);
 	}
-	printf("Frame thread done.\n");
+	spdlog::info("Frame thread done.");
 	return nullptr;
 }
 
@@ -313,7 +315,9 @@ void *__DISPLAY_THREAD__(void *param)
 			osd_vars.latency_min = min_latency;
 			osd_vars.current_framerate = frame_counter*(1000/osd_vars.refresh_frequency_ms);
 
-			// printf("decoding decoding latency=%.2f ms (%.2f, %.2f), framerate=%d fps\n", osd_vars.latency_avg/1000.0, osd_vars.latency_max/1000.0, osd_vars.latency_min/1000.0, osd_vars.current_framerate);
+			SPDLOG_DEBUG("decoding decoding latency={:.2f} ms ({:.2f}, {:.2f}), framerate={} fps",
+						  osd_vars.latency_avg/1000.0, osd_vars.latency_max/1000.0,
+						  osd_vars.latency_min/1000.0, osd_vars.current_framerate);
 
 			fps_start = fps_end;
 			frame_counter = 0;
@@ -327,7 +331,7 @@ void *__DISPLAY_THREAD__(void *param)
 
 	}
 end:	
-	printf("Display thread done.\n");
+	spdlog::info("Display thread done.");
 	return nullptr;
 }
 
@@ -337,7 +341,7 @@ int signal_flag = 0;
 
 void sig_handler(int signum)
 {
-	printf("Received signal %d\n", signum);
+	spdlog::info("Received signal {}", signum);
 	signal_flag++;
 	mavlink_thread_signal++;
 	osd_thread_signal++;
@@ -347,7 +351,7 @@ void sig_handler(int signum)
 }
 
 void sigusr1_handler(int signum) {
-	printf("Received signal %d\n", signum);
+	spdlog::info("Received signal {}", signum);
 	if (dvr) {
 		dvr->toggle_recording();
 	}
@@ -369,7 +373,7 @@ bool feed_packet_to_decoder(MppPacket *packet,void* data_p,int data_len){
         uint64_t elapsed = get_time_ms() - data_feed_begin;
         if (elapsed > 100) {
             decoder_stalled_count++;
-            printf("Cannot feed decoder, stalled %d ?\n",decoder_stalled_count);
+            spdlog::warn("Cannot feed decoder, stalled {} ?", decoder_stalled_count);
             return false;
         }
         usleep(2 * 1000);
@@ -407,7 +411,7 @@ void read_gstreamerpipe_stream(MppPacket *packet, int gst_udp_port, const VideoC
         sleep(10);
     }
     receiver.stop_receiving();
-    printf("Feeding eos\n");
+    spdlog::info("Feeding eos");
     mpp_packet_set_eos(packet);
     //mpp_packet_set_pos(packet, nal_buffer);
     mpp_packet_set_length(packet, 0);
@@ -420,7 +424,7 @@ void read_gstreamerpipe_stream(MppPacket *packet, int gst_udp_port, const VideoC
 void set_control_verbose(MppApi * mpi,  MppCtx ctx,MpiCmd control,RK_U32 enable){
     RK_U32 res = mpi->control(ctx, control, &enable);
     if(res){
-        printf("Could not set control %d %d\n",control,enable);
+        spdlog::warn("Could not set control {} {}", control, enable);
         assert(false);
     }
 }
@@ -432,20 +436,20 @@ void set_mpp_decoding_parameters(MppApi * mpi,  MppCtx ctx) {
     // get default config from decoder context
     int ret = mpi->control(ctx, MPP_DEC_GET_CFG, cfg);
     if (ret) {
-        printf("%p failed to get decoder cfg ret %d\n", ctx, ret);
+        spdlog::warn("{} failed to get decoder cfg ret {}", ctx, ret);
         assert(false);
     }
     // split_parse is to enable mpp internal frame spliter when the input
     // packet is not aplited into frames.
     RK_U32 need_split   = 1;
     ret = mpp_dec_cfg_set_u32(cfg, "base:split_parse", need_split);
     if (ret) {
-        printf("%p failed to set split_parse ret %d\n", ctx, ret);
+        spdlog::warn("{} failed to set split_parse ret {}", ctx, ret);
         assert(false);
     }
     ret = mpi->control(ctx, MPP_DEC_SET_CFG, cfg);
     if (ret) {
-        printf("%p failed to set cfg %p ret %d\n", ctx, cfg, ret);
+        spdlog::warn("{} failed to set cfg {} ret {}", ctx, cfg, ret);
         assert(false);
     }
 	int mpp_split_mode =0;
@@ -478,6 +482,8 @@ void printHelp() {
     "\n"
     "    --codec <codec>        - Video codec, should be the same as on VTX  (Default: h265 <h264|h265>)\n"
     "\n"
+    "    --log-level <level>    - Log verbosity level, debug|info|warn|error (Default: info)\n"
+    "\n"
     "    --osd                  - Enable OSD\n"
     "\n"
     "    --osd-elements <els>   - Customize osd elements   			    (Default: video,wfbng,telem)\n"
@@ -524,9 +530,10 @@ int main(int argc, char **argv)
 	uint16_t mode_width = 0;
 	uint16_t mode_height = 0;
 	uint32_t mode_vrefresh = 0;
+	auto log_level = spdlog::level::info;
 
 	osd_vars.enable_recording = 0;
-	
+
 	// Load console arguments
 	__BeginParseConsoleArguments__(printHelp) 
 
@@ -539,7 +546,7 @@ int main(int argc, char **argv)
 		char * codec_str = const_cast<char*>(__ArgValue);
 		codec = video_codec(codec_str);
 		if (codec == VideoCodec::UNKNOWN ) {
-			printf("unsupported video codec");
+			fprintf(stderr, "unsupported video codec");
 			return -1;
 		}
 		continue;
@@ -572,6 +579,25 @@ int main(int argc, char **argv)
 		continue;
 	}
 
+	__OnArgument("--log-level") {
+		std::string log_l = std::string(__ArgValue);
+		if (log_l == "info") {
+			log_level = spdlog::level::info;
+		} else if (log_l == "debug"){
+			log_level = spdlog::level::debug;
+			spdlog::set_pattern("[%Y-%m-%d %H:%M:%S.%e] [thread %t] [%s:%#] [%^%l%$] %v");
+		} else if (log_l == "warn"){
+			log_level = spdlog::level::warn;
+		} else if (log_l == "error"){
+			log_level = spdlog::level::err;
+		} else {
+			fprintf(stderr, "invalid log level %s\n", log_l.c_str());
+			printHelp();
+			return -1;
+		}
+		continue;
+	}
+
 	__OnArgument("--mavlink-port") {
 		mavlink_port = atoi(__ArgValue);
 		continue;
@@ -647,6 +673,8 @@ int main(int argc, char **argv)
 
 	__EndParseConsoleArguments__
 
+	spdlog::set_level(log_level);
+
 	if (dvr_template != NULL && video_framerate < 0 ) {
 		printf("--dvr-framerate must be provided when dvr is enabled.\n");
 		return 0;
@@ -668,7 +696,7 @@ int main(int argc, char **argv)
 	//////////////////////////////////  DRM SETUP
 	ret = modeset_open(&drm_fd, "/dev/dri/card0");
 	if (ret < 0) {
-		printf("modeset_open() =  %d\n", ret);
+		spdlog::warn("modeset_open() =  {}", ret);
 	}
 	assert(drm_fd >= 0);
 	if (print_modelist) {