Base: Logging improvements

Use blog_debug() in place of almost all debug logging messages, and
change some log levels to be less verbose.
This commit is contained in:
tt2468 2021-11-20 01:50:49 -08:00
parent 60f12a16f3
commit 32a9e12f62
9 changed files with 28 additions and 52 deletions

View File

@ -39,7 +39,7 @@ class Config {
bool ServerEnabled; bool ServerEnabled;
uint16_t ServerPort; uint16_t ServerPort;
std::atomic<bool> DebugEnabled; std::atomic<bool> DebugEnabled;
std::atomic<bool> AlertsEnabled; bool AlertsEnabled;
bool AuthRequired; bool AuthRequired;
QString ServerPassword; QString ServerPassword;

View File

@ -19,8 +19,7 @@ WebSocketApi::Vendor *get_vendor(calldata_t *cd)
WebSocketApi::WebSocketApi(EventCallback cb) : WebSocketApi::WebSocketApi(EventCallback cb) :
_eventCallback(cb) _eventCallback(cb)
{ {
if (IsDebugEnabled()) blog_debug("[WebSocketApi::WebSocketApi] Setting up...");
blog(LOG_INFO, "[WebSocketApi::WebSocketApi] Setting up...");
_procHandler = proc_handler_create(); _procHandler = proc_handler_create();
@ -34,25 +33,21 @@ WebSocketApi::WebSocketApi(EventCallback cb) :
proc_handler_add(ph, "bool obs_websocket_api_get_ph(out ptr ph)", &get_ph_cb, this); proc_handler_add(ph, "bool obs_websocket_api_get_ph(out ptr ph)", &get_ph_cb, this);
if (IsDebugEnabled()) blog_debug("[WebSocketApi::WebSocketApi] Finished.");
blog(LOG_INFO, "[WebSocketApi::WebSocketApi] Finished.");
} }
WebSocketApi::~WebSocketApi() WebSocketApi::~WebSocketApi()
{ {
if (IsDebugEnabled()) blog_debug("[WebSocketApi::~WebSocketApi] Shutting down...");
blog(LOG_INFO, "[WebSocketApi::~WebSocketApi] Shutting down...");
proc_handler_destroy(_procHandler); proc_handler_destroy(_procHandler);
for (auto vendor : _vendors) { for (auto vendor : _vendors) {
if (IsDebugEnabled()) blog_debug("[WebSocketApi::~WebSocketApi] Deleting vendor: %s", vendor.first.c_str());
blog(LOG_INFO, "[WebSocketApi::~WebSocketApi] Deleting vendor: %s", vendor.first.c_str());
delete vendor.second; delete vendor.second;
} }
if (IsDebugEnabled()) blog_debug("[WebSocketApi::~WebSocketApi] Finished.");
blog(LOG_INFO, "[WebSocketApi::~WebSocketApi] Finished.");
} }
enum WebSocketApi::RequestReturnCode WebSocketApi::PerformVendorRequest(std::string vendorName, std::string requestType, obs_data_t *requestData, obs_data_t *responseData) enum WebSocketApi::RequestReturnCode WebSocketApi::PerformVendorRequest(std::string vendorName, std::string requestType, obs_data_t *requestData, obs_data_t *responseData)
@ -112,8 +107,7 @@ void WebSocketApi::vendor_register_cb(void *priv_data, calldata_t *cd)
c->_vendors[vendorName] = v; c->_vendors[vendorName] = v;
if (IsDebugEnabled()) blog_debug("[WebSocketApi::vendor_register_cb] [vendorName: %s] Registered new vendor.", v->_name.c_str());
blog(LOG_INFO, "[WebSocketApi::vendor_register_cb] [vendorName: %s] Registered new vendor.", v->_name.c_str());
calldata_set_ptr(cd, "vendor", static_cast<void*>(v)); calldata_set_ptr(cd, "vendor", static_cast<void*>(v));
@ -151,8 +145,7 @@ void WebSocketApi::vendor_request_register_cb(void *priv_data, calldata_t *cd)
v->_requests[requestType] = *cb; v->_requests[requestType] = *cb;
if (IsDebugEnabled()) blog_debug("[WebSocketApi::vendor_request_register_cb] [vendorName: %s] Registered new vendor request: %s", v->_name.c_str(), requestType);
blog(LOG_INFO, "[WebSocketApi::vendor_request_register_cb] [vendorName: %s] Registered new vendor request: %s", v->_name.c_str(), requestType);
RETURN_SUCCESS(); RETURN_SUCCESS();
} }
@ -180,8 +173,7 @@ void WebSocketApi::vendor_request_unregister_cb(void *priv_data, calldata_t *cd)
v->_requests.erase(requestType); v->_requests.erase(requestType);
if (IsDebugEnabled()) blog_debug("[WebSocketApi::vendor_request_unregister_cb] [vendorName: %s] Unregistered vendor request: %s", v->_name.c_str(), requestType);
blog(LOG_INFO, "[WebSocketApi::vendor_request_unregister_cb] [vendorName: %s] Unregistered vendor request: %s", v->_name.c_str(), requestType);
RETURN_SUCCESS(); RETURN_SUCCESS();
} }

View File

@ -26,8 +26,7 @@ EventHandler::EventHandler() :
_inputShowStateChangedRef(0), _inputShowStateChangedRef(0),
_sceneItemTransformChangedRef(0) _sceneItemTransformChangedRef(0)
{ {
if (IsDebugEnabled()) blog_debug("[EventHandler::EventHandler] Setting up...");
blog(LOG_INFO, "[EventHandler::EventHandler] Setting up...");
obs_frontend_add_event_callback(OnFrontendEvent, this); obs_frontend_add_event_callback(OnFrontendEvent, this);
@ -41,14 +40,12 @@ EventHandler::EventHandler() :
blog(LOG_ERROR, "[EventHandler::EventHandler] Unable to get libobs signal handler!"); blog(LOG_ERROR, "[EventHandler::EventHandler] Unable to get libobs signal handler!");
} }
if (IsDebugEnabled()) blog_debug("[EventHandler::EventHandler] Finished.");
blog(LOG_INFO, "[EventHandler::EventHandler] Finished.");
} }
EventHandler::~EventHandler() EventHandler::~EventHandler()
{ {
if (IsDebugEnabled()) blog_debug("[EventHandler::~EventHandler] Shutting down...");
blog(LOG_INFO, "[EventHandler::~EventHandler] Shutting down...");
obs_frontend_remove_event_callback(OnFrontendEvent, this); obs_frontend_remove_event_callback(OnFrontendEvent, this);
@ -62,8 +59,7 @@ EventHandler::~EventHandler()
blog(LOG_ERROR, "[EventHandler::~EventHandler] Unable to get libobs signal handler!"); blog(LOG_ERROR, "[EventHandler::~EventHandler] Unable to get libobs signal handler!");
} }
if (IsDebugEnabled()) blog_debug("[EventHandler::~EventHandler] Finished.");
blog(LOG_INFO, "[EventHandler::~EventHandler] Finished.");
} }
void EventHandler::SetBroadcastCallback(EventHandler::BroadcastCallback cb) void EventHandler::SetBroadcastCallback(EventHandler::BroadcastCallback cb)
@ -197,7 +193,7 @@ void EventHandler::OnFrontendEvent(enum obs_frontend_event event, void *private_
if (!eventHandler->_obsLoaded.load()) { if (!eventHandler->_obsLoaded.load()) {
if (event == OBS_FRONTEND_EVENT_FINISHED_LOADING) { if (event == OBS_FRONTEND_EVENT_FINISHED_LOADING) {
blog(LOG_INFO, "[EventHandler::OnFrontendEvent] OBS has finished loading. Connecting final handlers and enabling events..."); blog_debug("[EventHandler::OnFrontendEvent] OBS has finished loading. Connecting final handlers and enabling events...");
// Connect source signals and enable events only after OBS has fully loaded (to reduce extra logging). // Connect source signals and enable events only after OBS has fully loaded (to reduce extra logging).
eventHandler->_obsLoaded.store(true); eventHandler->_obsLoaded.store(true);
@ -216,7 +212,7 @@ void EventHandler::OnFrontendEvent(enum obs_frontend_event event, void *private_
return true; return true;
}, private_data); }, private_data);
blog(LOG_INFO, "[EventHandler::OnFrontendEvent] Finished."); blog_debug("[EventHandler::OnFrontendEvent] Finished.");
if (eventHandler->_obsLoadedCallback) if (eventHandler->_obsLoadedCallback)
eventHandler->_obsLoadedCallback(); eventHandler->_obsLoadedCallback();
@ -230,7 +226,7 @@ void EventHandler::OnFrontendEvent(enum obs_frontend_event event, void *private_
case OBS_FRONTEND_EVENT_EXIT: case OBS_FRONTEND_EVENT_EXIT:
eventHandler->HandleExitStarted(); eventHandler->HandleExitStarted();
blog(LOG_INFO, "[EventHandler::OnFrontendEvent] OBS is unloading. Disabling events..."); blog_debug("[EventHandler::OnFrontendEvent] OBS is unloading. Disabling events...");
// Disconnect source signals and disable events when OBS starts unloading (to reduce extra logging). // Disconnect source signals and disable events when OBS starts unloading (to reduce extra logging).
eventHandler->_obsLoaded.store(false); eventHandler->_obsLoaded.store(false);
@ -249,7 +245,7 @@ void EventHandler::OnFrontendEvent(enum obs_frontend_event event, void *private_
return true; return true;
}, private_data); }, private_data);
blog(LOG_INFO, "[EventHandler::OnFrontendEvent] Finished."); blog_debug("[EventHandler::OnFrontendEvent] Finished.");
break; break;
case OBS_FRONTEND_EVENT_STUDIO_MODE_ENABLED: case OBS_FRONTEND_EVENT_STUDIO_MODE_ENABLED:

View File

@ -91,7 +91,7 @@ void obs_module_unload()
blog(LOG_INFO, "[obs_module_unload] Shutting down..."); blog(LOG_INFO, "[obs_module_unload] Shutting down...");
if (_webSocketServer->IsListening()) { if (_webSocketServer->IsListening()) {
blog(LOG_INFO, "[obs_module_unload] WebSocket server is running. Stopping..."); blog_debug("[obs_module_unload] WebSocket server is running. Stopping...");
_webSocketServer->Stop(); _webSocketServer->Stop();
} }
_webSocketServer.reset(); _webSocketServer.reset();

View File

@ -306,8 +306,6 @@ std::vector<json> Utils::Obs::ListHelper::GetSceneItemList(obs_scene_t *scene, b
item["sceneItemId"] = obs_sceneitem_get_id(sceneItem); item["sceneItemId"] = obs_sceneitem_get_id(sceneItem);
// Should be slightly faster than calling obs_sceneitem_get_order_position() // Should be slightly faster than calling obs_sceneitem_get_order_position()
item["sceneItemIndex"] = enumData->first.size(); item["sceneItemIndex"] = enumData->first.size();
//OBSSource itemSourcee = obs_sceneitem_get_source(sceneItem);
//blog(LOG_INFO, "source name: %s | item refs: %lu", obs_source_get_name(itemSourcee), obs_source_get_sceneitem_count(itemSourcee));
if (!enumData->second) { if (!enumData->second) {
OBSSource itemSource = obs_sceneitem_get_source(sceneItem); OBSSource itemSource = obs_sceneitem_get_source(sceneItem);
item["sourceName"] = obs_source_get_name(itemSource); item["sourceName"] = obs_source_get_name(itemSource);

View File

@ -114,13 +114,12 @@ void WebSocketServer::Start()
_serverPort = conf->ServerPort; _serverPort = conf->ServerPort;
_serverPassword = conf->ServerPassword; _serverPassword = conf->ServerPassword;
_debugEnabled = conf->DebugEnabled;
AuthenticationRequired = conf->AuthRequired; AuthenticationRequired = conf->AuthRequired;
AuthenticationSalt = Utils::Crypto::GenerateSalt(); AuthenticationSalt = Utils::Crypto::GenerateSalt();
AuthenticationSecret = Utils::Crypto::GenerateSecret(conf->ServerPassword.toStdString(), AuthenticationSalt); AuthenticationSecret = Utils::Crypto::GenerateSecret(conf->ServerPassword.toStdString(), AuthenticationSalt);
// Set log levels if debug is enabled // Set log levels if debug is enabled
if (_debugEnabled) { if (IsDebugEnabled()) {
_server.get_alog().set_channels(websocketpp::log::alevel::all); _server.get_alog().set_channels(websocketpp::log::alevel::all);
_server.get_alog().clear_channels(websocketpp::log::alevel::frame_header | websocketpp::log::alevel::frame_payload | websocketpp::log::alevel::control); _server.get_alog().clear_channels(websocketpp::log::alevel::frame_header | websocketpp::log::alevel::frame_payload | websocketpp::log::alevel::control);
_server.get_elog().set_channels(websocketpp::log::elevel::all); _server.get_elog().set_channels(websocketpp::log::elevel::all);
@ -232,8 +231,7 @@ void WebSocketServer::onObsLoaded()
} }
if (conf->ServerEnabled) { if (conf->ServerEnabled) {
if (conf->DebugEnabled) blog(LOG_INFO, "[WebSocketServer::onObsLoaded] WebSocket server is enabled, starting...");
blog(LOG_INFO, "[WebSocketServer::onObsLoaded] Server is enabled in configuration. Starting server...");
Start(); Start();
} }
} }
@ -307,8 +305,7 @@ void WebSocketServer::onOpen(websocketpp::connection_hdl hdl)
// Log connection // Log connection
blog(LOG_INFO, "[WebSocketServer::onOpen] New WebSocket client has connected from %s", session->RemoteAddress().c_str()); blog(LOG_INFO, "[WebSocketServer::onOpen] New WebSocket client has connected from %s", session->RemoteAddress().c_str());
if (_debugEnabled) blog_debug("[WebSocketServer::onOpen] Sending Op 0 (Hello) message:\n%s", helloMessage.dump(2).c_str());
blog(LOG_INFO, "[WebSocketServer::onOpen] Sending Op 0 (Hello) message:\n%s", helloMessage.dump(2).c_str());
// Send object to client // Send object to client
websocketpp::lib::error_code errorCode; websocketpp::lib::error_code errorCode;
@ -426,8 +423,7 @@ void WebSocketServer::onMessage(websocketpp::connection_hdl hdl, websocketpp::se
} }
} }
if (_debugEnabled) blog_debug("[WebSocketServer::onMessage] Incoming message (decoded):\n%s", incomingMessage.dump(2).c_str());
blog(LOG_INFO, "[WebSocketServer::onMessage] Incoming message (decoded):\n%s", incomingMessage.dump(2).c_str());
ProcessResult ret; ProcessResult ret;
@ -480,8 +476,7 @@ skipProcessing:
} }
session->IncrementOutgoingMessages(); session->IncrementOutgoingMessages();
if (_debugEnabled) blog_debug("[WebSocketServer::onMessage] Outgoing message:\n%s", ret.result.dump(2).c_str());
blog(LOG_INFO, "[WebSocketServer::onMessage] Outgoing message:\n%s", ret.result.dump(2).c_str());
if (errorCode) if (errorCode)
blog(LOG_WARNING, "[WebSocketServer::onMessage] Sending message to client failed: %s", errorCode.message().c_str()); blog(LOG_WARNING, "[WebSocketServer::onMessage] Sending message to client failed: %s", errorCode.message().c_str());

View File

@ -132,5 +132,4 @@ class WebSocketServer : QObject
std::map<websocketpp::connection_hdl, SessionPtr, std::owner_less<websocketpp::connection_hdl>> _sessions; std::map<websocketpp::connection_hdl, SessionPtr, std::owner_less<websocketpp::connection_hdl>> _sessions;
uint16_t _serverPort; uint16_t _serverPort;
QString _serverPassword; QString _serverPassword;
bool _debugEnabled;
}; };

View File

@ -354,7 +354,7 @@ void WebSocketServer::BroadcastEvent(uint64_t requiredIntent, std::string eventT
} }
} }
lock.unlock(); lock.unlock();
if (_debugEnabled && (EventSubscription::All & requiredIntent) != 0) // Don't log high volume events if (IsDebugEnabled() && (EventSubscription::All & requiredIntent) != 0) // Don't log high volume events
blog(LOG_INFO, "[WebSocketServer::BroadcastEvent] Outgoing event:\n%s", eventMessage.dump(2).c_str()); blog(LOG_INFO, "[WebSocketServer::BroadcastEvent] Outgoing event:\n%s", eventMessage.dump(2).c_str());
})); }));
} }

View File

@ -81,14 +81,12 @@ bool PreProcessVariables(const json &variables, const json &inputVariables, json
std::string key = it.key(); std::string key = it.key();
if (!variables.contains(key)) { if (!variables.contains(key)) {
if (IsDebugEnabled()) blog_debug("[WebSocketServer::ProcessRequestBatch] inputVariables requested variable `%s`, but it does not exist. Skipping!", key.c_str());
blog(LOG_WARNING, "[WebSocketServer::ProcessRequestBatch] inputVariables requested variable `%s`, but it does not exist. Skipping!", key.c_str());
continue; continue;
} }
if (!it.value().is_string()) { if (!it.value().is_string()) {
if (IsDebugEnabled()) blog_debug("[WebSocketServer::ProcessRequestBatch] Value of item `%s` in inputVariables is not a string. Skipping!", key.c_str());
blog(LOG_WARNING, "[WebSocketServer::ProcessRequestBatch] Value of item `%s` in inputVariables is not a string. Skipping!", key.c_str());
continue; continue;
} }
@ -108,14 +106,12 @@ void PostProcessVariables(json &variables, const json &outputVariables, const js
std::string key = it.key(); std::string key = it.key();
if (!responseData.contains(key)) { if (!responseData.contains(key)) {
if (IsDebugEnabled()) blog_debug("[WebSocketServer::ProcessRequestBatch] outputVariables requested responseData item `%s`, but it does not exist. Skipping!", key.c_str());
blog(LOG_WARNING, "[WebSocketServer::ProcessRequestBatch] outputVariables requested responseData item `%s`, but it does not exist. Skipping!", key.c_str());
continue; continue;
} }
if (!it.value().is_string()) { if (!it.value().is_string()) {
if (IsDebugEnabled()) blog_debug("[WebSocketServer::ProcessRequestBatch] Value of item `%s` in outputVariables is not a string. Skipping!", key.c_str());
blog(LOG_WARNING, "[WebSocketServer::ProcessRequestBatch] Value of item `%s` in outputVariables is not a string. Skipping!", key.c_str());
continue; continue;
} }