Skip to content

Commit

Permalink
Replaces spdlog with OTEL Logger (#363)
Browse files Browse the repository at this point in the history 
* Added OTEL logger includes

Added OTEL tracer & logger cleanup on shutdown

* Adjusted OTEL debugging settings

Added OTEL logger initialization

* Update Common.h

* Switched to OTEL gRPC

* Added GetLogger method

* Migrating to OTEL logging

* Added logging helpers

* Update GlobalState.cpp

* Finished migration

* Update Common.h

* Removed HTTP exporter

* Update appveyor.yml

* Moved all telemetry stuff out of DllMain

* Update README.md

* Update Common.h

* Update README.md

* Simplifying tracing macros

* Simplified tracing

* More tracing

* Finished conversion to trace macros

* Replaced libfmt with std::format

* Update README.md
  • Loading branch information
@nefarius
nefarius committed May 23, 2024
1 parent a96e30e commit 17a0ccb
Show file tree
Hide file tree
Showing 17 changed files with 300 additions and 257 deletions.
29 changes: 21 additions & 8 deletions XInputBridge/Common.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -22,12 +22,8 @@
#include <string>
#include <memory>
#include <thread>

//
// Logging
//
#include <spdlog/logger.h>
#include <spdlog/spdlog.h>
#include <array>
#include <format>

//
// Abseil
Expand All @@ -40,19 +36,36 @@
//
#if defined(SCPLIB_ENABLE_TELEMETRY)
#define HAVE_ABSEIL // fixes redefinitions of absl types
#include <opentelemetry/exporters/otlp/otlp_http_exporter_factory.h>
#include <opentelemetry/exporters/otlp/otlp_http_exporter_options.h>
// gRPC exporter
#include <opentelemetry/exporters/otlp/otlp_grpc_exporter_factory.h>
#include <opentelemetry/exporters/otlp/otlp_grpc_exporter_options.h>

#include <opentelemetry/sdk/trace/processor.h>
#include <opentelemetry/sdk/trace/simple_processor_factory.h>
#include <opentelemetry/sdk/trace/tracer_provider_factory.h>
#include <opentelemetry/sdk/resource/resource.h>
#include <opentelemetry/sdk/resource/semantic_conventions.h>
#include <opentelemetry/trace/provider.h>
#include <opentelemetry/sdk/trace/tracer_provider.h>

namespace trace = opentelemetry::trace;
namespace nostd = opentelemetry::nostd;
namespace sdktrace = opentelemetry::sdk::trace;
namespace otlp = opentelemetry::exporter::otlp;
namespace sdkresource = opentelemetry::sdk::resource;

// gRPC exporter
#include <opentelemetry/exporters/otlp/otlp_grpc_log_record_exporter_factory.h>
#include <opentelemetry/exporters/otlp/otlp_grpc_log_record_exporter_options.h>

#include <opentelemetry/logs/provider.h>
#include <opentelemetry/sdk/common/global_log_handler.h>
#include <opentelemetry/sdk/logs/logger_provider_factory.h>
#include <opentelemetry/sdk/logs/logger_provider.h>
#include <opentelemetry/sdk/logs/processor.h>
#include <opentelemetry/sdk/logs/simple_log_record_processor_factory.h>

namespace sdklogs = opentelemetry::sdk::logs;
namespace logs = opentelemetry::logs;
#endif

35 changes: 14 additions & 21 deletions XInputBridge/DeviceState.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -5,9 +5,10 @@

bool DeviceState::InitializeAsXusb(const std::wstring& Symlink, const DWORD UserIndex)
{
#if defined(SCPLIB_ENABLE_TELEMETRY)
auto scopedSpan = trace::Scope(GlobalState::GetTracer()->StartSpan(__FUNCTION__));
#endif
auto scopedSpan = TRACE_SCOPED_SPAN("",
{ "device.symlink", ConvertWideToANSI(Symlink) },
{ "device.userIndex", std::to_string(UserIndex) }
);

this->Type = XI_DEVICE_TYPE_NOT_CONNECTED;

Expand All @@ -20,11 +21,9 @@ bool DeviceState::InitializeAsXusb(const std::wstring& Symlink, const DWORD User

bool DeviceState::InitializeAsDs3(const std::wstring& Symlink)
{
const std::shared_ptr<spdlog::logger> logger = spdlog::get(LOGGER_NAME)->clone(__FUNCTION__);

#if defined(SCPLIB_ENABLE_TELEMETRY)
auto scopedSpan = trace::Scope(GlobalState::GetTracer()->StartSpan(__FUNCTION__));
#endif
auto scopedSpan = TRACE_SCOPED_SPAN("",
{ "device.symlink", ConvertWideToANSI(Symlink) }
);

int retries = 5;

Expand All @@ -35,7 +34,7 @@ bool DeviceState::InitializeAsDs3(const std::wstring& Symlink)

if (!instanceId.has_value())
{
logger->error("Failed to get Instance ID for instance {}", this->SymbolicLink);
LOG_ERROR("Failed to get Instance ID for instance {}", this->SymbolicLink);
return false;
}

Expand All @@ -46,7 +45,7 @@ bool DeviceState::InitializeAsDs3(const std::wstring& Symlink)
{
if (--retries == 0)
{
logger->error("Failed to get child devices for instance {}", this->SymbolicLink);
LOG_ERROR("Failed to get child devices for instance {}", this->SymbolicLink);
return false;
}

Expand All @@ -65,7 +64,7 @@ bool DeviceState::InitializeAsDs3(const std::wstring& Symlink)
{
if (--retries == 0)
{
logger->error("Failed to get HID instance path for instance {}", this->SymbolicLink);
LOG_ERROR("Failed to get HID instance path for instance {}", this->SymbolicLink);
return false;
}

Expand All @@ -80,7 +79,7 @@ bool DeviceState::InitializeAsDs3(const std::wstring& Symlink)

if (device == nullptr)
{
logger->error("Failed to open hid device {} with error {}",
LOG_ERROR("Failed to open hid device {} with error {}",
ConvertWideToANSI(hidSymlink),
ConvertWideToANSI(hid_error(nullptr))
);
Expand All @@ -95,9 +94,7 @@ bool DeviceState::InitializeAsDs3(const std::wstring& Symlink)

void DeviceState::Dispose()
{
#if defined(SCPLIB_ENABLE_TELEMETRY)
auto scopedSpan = trace::Scope(GlobalState::GetTracer()->StartSpan(__FUNCTION__));
#endif
auto scopedSpan = TRACE_SCOPED_SPAN("");

switch (this->Type)
{
Expand All @@ -121,9 +118,7 @@ void DeviceState::Dispose()
_Must_inspect_result_
bool DeviceState::Ds3GetPacketNumber(_In_ PDS3_RAW_INPUT_REPORT Report, _Inout_ DWORD* PacketNumber)
{
#if defined(SCPLIB_ENABLE_TELEMETRY)
auto scopedSpan = trace::Scope(GlobalState::GetTracer()->StartSpan(__FUNCTION__));
#endif
auto scopedSpan = TRACE_SCOPED_SPAN("");

if (!Report || !PacketNumber)
return false;
Expand All @@ -148,9 +143,7 @@ bool DeviceState::Ds3GetPacketNumber(_In_ PDS3_RAW_INPUT_REPORT Report, _Inout_
_Must_inspect_result_
bool DeviceState::Ds3GetDeviceHandle(_Inout_opt_ hid_device** Handle) const
{
#if defined(SCPLIB_ENABLE_TELEMETRY)
auto scopedSpan = trace::Scope(GlobalState::GetTracer()->StartSpan(__FUNCTION__));
#endif
auto scopedSpan = TRACE_SCOPED_SPAN("");

if (this->Type != XI_DEVICE_TYPE_DS3)
return false;
Expand Down
80 changes: 51 additions & 29 deletions XInputBridge/GlobalState.Callbacks.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -19,30 +19,27 @@ DWORD CALLBACK GlobalState::DeviceNotificationCallback(
UNREFERENCED_PARAMETER(EventDataSize);

const auto _this = static_cast<GlobalState*>(Context);
const std::shared_ptr<spdlog::logger> logger = spdlog::get(LOGGER_NAME)->clone(__FUNCTION__);

if (_this == nullptr)
{
logger->error("Missing state pointer");
LOG_ERROR("Missing state pointer");
return ERROR_INVALID_PARAMETER;
}

#if defined(SCPLIB_ENABLE_TELEMETRY)
auto scopedSpan = trace::Scope(GetTracer()->StartSpan(__FUNCTION__));
#endif
auto scopedSpan = TRACE_SCOPED_SPAN("");

switch (Action)
{
case CM_NOTIFY_ACTION_DEVICEINTERFACEARRIVAL:
if (IsEqualGUID(GUID_DEVINTERFACE_DSHIDMINI, EventData->u.DeviceInterface.ClassGuid))
{
const auto symlink = std::wstring(EventData->u.DeviceInterface.SymbolicLink);
logger->info("New DS3 device arrived: {}", ConvertWideToANSI(symlink));
LOG_INFO("New DS3 device arrived: {}", ConvertWideToANSI(symlink));

// child device boot is not instant so we need to do
// this in the background to not block this callback
std::thread asyncArrival{
[_this, logger, symlink]
[_this, symlink]
{
AcquireSRWLockExclusive(&_this->StatesLock);
{
Expand All @@ -52,11 +49,11 @@ DWORD CALLBACK GlobalState::DeviceNotificationCallback(
slot->Dispose();
if (!slot->InitializeAsDs3(symlink))
{
logger->error("Failed to initialize {} as a DS3 HID device", ConvertWideToANSI(symlink));
LOG_ERROR("Failed to initialize {} as a DS3 HID device", ConvertWideToANSI(symlink));
}
else
{
logger->info("Assigned {} to index {}", ConvertWideToANSI(symlink), slotIndex);
LOG_INFO("Assigned {} to index {}", ConvertWideToANSI(symlink), slotIndex);
}
}
}
Expand All @@ -71,12 +68,12 @@ DWORD CALLBACK GlobalState::DeviceNotificationCallback(
{
const auto symlink = ConvertWideToANSI(EventData->u.DeviceInterface.SymbolicLink);

logger->info("New XUSB device arrived: {}", symlink);
LOG_INFO("New XUSB device arrived: {}", symlink);

DWORD userIndex = INVALID_X_INPUT_USER_ID;
if (SymlinkToUserIndex(EventData->u.DeviceInterface.SymbolicLink, &userIndex))
{
logger->info("User index: {}", userIndex);
LOG_INFO("User index: {}", userIndex);

AcquireSRWLockExclusive(&_this->StatesLock);
{
Expand All @@ -86,27 +83,27 @@ DWORD CALLBACK GlobalState::DeviceNotificationCallback(
slot->Dispose();
if (!slot->InitializeAsXusb(EventData->u.DeviceInterface.SymbolicLink, userIndex))
{
logger->error("Failed to initialize {} as a XUSB device", symlink);
LOG_ERROR("Failed to initialize {} as a XUSB device", symlink);
}
else
{
logger->info("Assigned {} to index {}", symlink, slotIndex);
LOG_INFO("Assigned {} to index {}", symlink, slotIndex);
}
}
}
ReleaseSRWLockExclusive(&_this->StatesLock);
}
else
{
logger->error("User index lookup failed");
LOG_ERROR("User index lookup failed");
}
}
break;
case CM_NOTIFY_ACTION_DEVICEINTERFACEREMOVAL:
if (IsEqualGUID(GUID_DEVINTERFACE_DSHIDMINI, EventData->u.DeviceInterface.ClassGuid))
{
const std::string symlink = ConvertWideToANSI(EventData->u.DeviceInterface.SymbolicLink);
logger->info("DS3 device got removed: {}", symlink);
LOG_INFO("DS3 device got removed: {}", symlink);

AcquireSRWLockExclusive(&_this->StatesLock);
{
Expand All @@ -116,7 +113,7 @@ DWORD CALLBACK GlobalState::DeviceNotificationCallback(
}
else
{
logger->warn("No state found for {}", symlink);
LOG_WARN("No state found for {}", symlink);
}
}
ReleaseSRWLockExclusive(&_this->StatesLock);
Expand All @@ -125,7 +122,7 @@ DWORD CALLBACK GlobalState::DeviceNotificationCallback(
if (IsEqualGUID(XUSB_INTERFACE_CLASS_GUID, EventData->u.DeviceInterface.ClassGuid))
{
const std::string symlink = ConvertWideToANSI(EventData->u.DeviceInterface.SymbolicLink);
logger->info("XUSB device got removed: {}", symlink);
LOG_INFO("XUSB device got removed: {}", symlink);

AcquireSRWLockExclusive(&_this->StatesLock);
{
Expand All @@ -135,7 +132,7 @@ DWORD CALLBACK GlobalState::DeviceNotificationCallback(
}
else
{
logger->warn("No state found for {}", symlink);
LOG_WARN("No state found for {}", symlink);
}
}
ReleaseSRWLockExclusive(&_this->StatesLock);
Expand All @@ -153,36 +150,61 @@ DWORD CALLBACK GlobalState::DeviceNotificationCallback(
//
DWORD WINAPI GlobalState::InitAsync(_In_ LPVOID lpParameter)
{
const auto _this = static_cast<GlobalState*>(lpParameter);
const std::shared_ptr<spdlog::logger> logger = spdlog::get(LOGGER_NAME)->clone(__FUNCTION__);

#if defined(SCPLIB_ENABLE_TELEMETRY)
auto scopedSpan = trace::Scope(GetTracer()->StartSpan(__FUNCTION__));
//
// Set up tracing
//

const auto resourceAttributes = sdkresource::ResourceAttributes{
{ opentelemetry::sdk::resource::SemanticConventions::kServiceName, TRACER_NAME }
};

const auto resource = sdkresource::Resource::Create(resourceAttributes);
auto traceExporter = otlp::OtlpGrpcExporterFactory::Create();
auto traceProcessor = sdktrace::SimpleSpanProcessorFactory::Create(std::move(traceExporter));
const std::shared_ptr traceProvider = sdktrace::TracerProviderFactory::Create(std::move(traceProcessor), resource);

trace::Provider::SetTracerProvider(traceProvider);

//
// Set up logger
//

auto loggerExporter = otlp::OtlpGrpcLogRecordExporterFactory::Create();
auto loggerProcessor = sdklogs::SimpleLogRecordProcessorFactory::Create(std::move(loggerExporter));
const std::shared_ptr loggerProvider = sdklogs::LoggerProviderFactory::Create(std::move(loggerProcessor), resource);

logs::Provider::SetLoggerProvider(loggerProvider);

LOG_INFO("Library got loaded into PID {}", GetCurrentProcessId());
#endif

logger->info("Async library startup initialized");
const auto _this = static_cast<GlobalState*>(lpParameter);
auto scopedSpan = TRACE_SCOPED_SPAN("");

LOG_INFO("Async library startup initialized");

CHAR systemDir[MAX_PATH] = {};

if (GetSystemDirectoryA(systemDir, MAX_PATH) == 0)
{
logger->error("GetSystemDirectoryA failed: {:#x}", GetLastError());
LOG_ERROR("GetSystemDirectoryA failed: {:#x}", GetLastError());
return GetLastError();
}

CHAR fullXiPath[MAX_PATH] = {};

if (PathCombineA(fullXiPath, systemDir, XI_SYSTEM_LIB_NAME) == nullptr)
{
logger->error("PathCombineA failed: {:#x}", GetLastError());
LOG_ERROR("PathCombineA failed: {:#x}", GetLastError());
return GetLastError();
}

const HMODULE xiLib = LoadLibraryA(fullXiPath);

if (xiLib == nullptr)
{
logger->error("LoadLibraryA failed: {:#x}", GetLastError());
LOG_ERROR("LoadLibraryA failed: {:#x}", GetLastError());
return GetLastError();
}

Expand Down Expand Up @@ -240,7 +262,7 @@ DWORD WINAPI GlobalState::InitAsync(_In_ LPVOID lpParameter)

if (ret != CR_SUCCESS)
{
logger->error("CM_Register_Notification (DS3) failed: {:#x}", ret);
LOG_ERROR("CM_Register_Notification (DS3) failed: {:#x}", ret);
}

CM_NOTIFY_FILTER xusbFilter = {};
Expand All @@ -255,12 +277,12 @@ DWORD WINAPI GlobalState::InitAsync(_In_ LPVOID lpParameter)

if (ret != CR_SUCCESS)
{
logger->error("CM_Register_Notification (XUSB) failed: {:#x}", ret);
LOG_ERROR("CM_Register_Notification (XUSB) failed: {:#x}", ret);
}

if (const auto result = hid_init(); result != 0)
{
logger->error("hid_init failed: {}", ConvertWideToANSI(hid_error(nullptr)));
LOG_ERROR("hid_init failed: {}", ConvertWideToANSI(hid_error(nullptr)));
}

_this->EnumerateDs3Devices();
Expand Down
Loading

0 comments on commit 17a0ccb

Please sign in to comment.