From a2cc3b10bb6115b17d980fdb83ed5c561835eb3b Mon Sep 17 00:00:00 2001 From: David Marcec Date: Mon, 26 Nov 2018 17:06:13 +1100 Subject: Changed logging to be "Log before execution", Added more error logging, all services should now log on some level --- src/core/hle/service/audio/audout_u.cpp | 5 ++++ src/core/hle/service/audio/audren_u.cpp | 53 +++++++++++++++++++-------------- src/core/hle/service/audio/hwopus.cpp | 32 +++++++++++++++----- 3 files changed, 60 insertions(+), 30 deletions(-) (limited to 'src/core/hle/service/audio') diff --git a/src/core/hle/service/audio/audout_u.cpp b/src/core/hle/service/audio/audout_u.cpp index 23e1f1165..2ee9bc273 100644 --- a/src/core/hle/service/audio/audout_u.cpp +++ b/src/core/hle/service/audio/audout_u.cpp @@ -86,6 +86,7 @@ private: void GetAudioOutState(Kernel::HLERequestContext& ctx) { LOG_DEBUG(Service_Audio, "called"); + IPC::ResponseBuilder rb{ctx, 3}; rb.Push(RESULT_SUCCESS); rb.Push(static_cast(stream->IsPlaying() ? AudioState::Started : AudioState::Stopped)); @@ -148,6 +149,7 @@ private: void GetReleasedAudioOutBufferImpl(Kernel::HLERequestContext& ctx) { LOG_DEBUG(Service_Audio, "called {}", ctx.Description()); + IPC::RequestParser rp{ctx}; const u64 max_count{ctx.GetWriteBufferSize() / sizeof(u64)}; const auto released_buffers{audio_core.GetTagsAndReleaseBuffers(stream, max_count)}; @@ -163,6 +165,7 @@ private: void ContainsAudioOutBuffer(Kernel::HLERequestContext& ctx) { LOG_DEBUG(Service_Audio, "called"); + IPC::RequestParser rp{ctx}; const u64 tag{rp.Pop()}; IPC::ResponseBuilder rb{ctx, 3}; @@ -172,6 +175,7 @@ private: void GetAudioOutBufferCount(Kernel::HLERequestContext& ctx) { LOG_DEBUG(Service_Audio, "called"); + IPC::ResponseBuilder rb{ctx, 3}; rb.Push(RESULT_SUCCESS); rb.Push(static_cast(stream->GetQueueSize())); @@ -189,6 +193,7 @@ private: void AudOutU::ListAudioOutsImpl(Kernel::HLERequestContext& ctx) { LOG_DEBUG(Service_Audio, "called"); + IPC::RequestParser rp{ctx}; ctx.WriteBuffer(DefaultDevice); diff --git a/src/core/hle/service/audio/audren_u.cpp b/src/core/hle/service/audio/audren_u.cpp index d3ea57ea7..1c418a9bb 100644 --- a/src/core/hle/service/audio/audren_u.cpp +++ b/src/core/hle/service/audio/audren_u.cpp @@ -52,74 +52,79 @@ private: } void GetSampleRate(Kernel::HLERequestContext& ctx) { + LOG_DEBUG(Service_Audio, "called"); + IPC::ResponseBuilder rb{ctx, 3}; rb.Push(RESULT_SUCCESS); rb.Push(renderer->GetSampleRate()); - LOG_DEBUG(Service_Audio, "called"); } void GetSampleCount(Kernel::HLERequestContext& ctx) { + LOG_DEBUG(Service_Audio, "called"); + IPC::ResponseBuilder rb{ctx, 3}; rb.Push(RESULT_SUCCESS); rb.Push(renderer->GetSampleCount()); - LOG_DEBUG(Service_Audio, "called"); } void GetState(Kernel::HLERequestContext& ctx) { + LOG_DEBUG(Service_Audio, "called"); + IPC::ResponseBuilder rb{ctx, 3}; rb.Push(RESULT_SUCCESS); rb.Push(static_cast(renderer->GetStreamState())); - LOG_DEBUG(Service_Audio, "called"); } void GetMixBufferCount(Kernel::HLERequestContext& ctx) { + LOG_DEBUG(Service_Audio, "called"); + IPC::ResponseBuilder rb{ctx, 3}; rb.Push(RESULT_SUCCESS); rb.Push(renderer->GetMixBufferCount()); - LOG_DEBUG(Service_Audio, "called"); } void RequestUpdateImpl(Kernel::HLERequestContext& ctx) { + LOG_WARNING(Service_Audio, "(STUBBED) called"); + ctx.WriteBuffer(renderer->UpdateAudioRenderer(ctx.ReadBuffer())); IPC::ResponseBuilder rb{ctx, 2}; rb.Push(RESULT_SUCCESS); - LOG_WARNING(Service_Audio, "(STUBBED) called"); } void Start(Kernel::HLERequestContext& ctx) { + LOG_WARNING(Service_Audio, "(STUBBED) called"); + IPC::ResponseBuilder rb{ctx, 2}; rb.Push(RESULT_SUCCESS); - - LOG_WARNING(Service_Audio, "(STUBBED) called"); } void Stop(Kernel::HLERequestContext& ctx) { + LOG_WARNING(Service_Audio, "(STUBBED) called"); + IPC::ResponseBuilder rb{ctx, 2}; rb.Push(RESULT_SUCCESS); - - LOG_WARNING(Service_Audio, "(STUBBED) called"); } void QuerySystemEvent(Kernel::HLERequestContext& ctx) { + LOG_WARNING(Service_Audio, "(STUBBED) called"); + IPC::ResponseBuilder rb{ctx, 2, 1}; rb.Push(RESULT_SUCCESS); rb.PushCopyObjects(system_event); - - LOG_WARNING(Service_Audio, "(STUBBED) called"); } void SetRenderingTimeLimit(Kernel::HLERequestContext& ctx) { IPC::RequestParser rp{ctx}; rendering_time_limit_percent = rp.Pop(); + LOG_DEBUG(Service_Audio, "called. rendering_time_limit_percent={}", + rendering_time_limit_percent); + ASSERT(rendering_time_limit_percent >= 0 && rendering_time_limit_percent <= 100); IPC::ResponseBuilder rb{ctx, 2}; rb.Push(RESULT_SUCCESS); - - LOG_DEBUG(Service_Audio, "called. rendering_time_limit_percent={}", - rendering_time_limit_percent); } void GetRenderingTimeLimit(Kernel::HLERequestContext& ctx) { @@ -211,6 +216,7 @@ private: void GetActiveChannelCount(Kernel::HLERequestContext& ctx) { LOG_WARNING(Service_Audio, "(STUBBED) called"); + IPC::ResponseBuilder rb{ctx, 3}; rb.Push(RESULT_SUCCESS); rb.Push(1); @@ -235,19 +241,20 @@ AudRenU::AudRenU() : ServiceFramework("audren:u") { AudRenU::~AudRenU() = default; void AudRenU::OpenAudioRenderer(Kernel::HLERequestContext& ctx) { + LOG_DEBUG(Service_Audio, "called"); + IPC::RequestParser rp{ctx}; auto params = rp.PopRaw(); IPC::ResponseBuilder rb{ctx, 2, 0, 1}; rb.Push(RESULT_SUCCESS); rb.PushIpcInterface(std::move(params)); - - LOG_DEBUG(Service_Audio, "called"); } void AudRenU::GetAudioRendererWorkBufferSize(Kernel::HLERequestContext& ctx) { IPC::RequestParser rp{ctx}; auto params = rp.PopRaw(); + LOG_DEBUG(Service_Audio, "called"); u64 buffer_sz = Common::AlignUp(4 * params.mix_buffer_count, 0x40); buffer_sz += params.unknown_c * 1024; @@ -301,26 +308,26 @@ void AudRenU::GetAudioRendererWorkBufferSize(Kernel::HLERequestContext& ctx) { rb.Push(RESULT_SUCCESS); rb.Push(output_sz); - LOG_DEBUG(Service_Audio, "called, buffer_size=0x{:X}", output_sz); + LOG_DEBUG(Service_Audio, "buffer_size=0x{:X}", output_sz); } void AudRenU::GetAudioDevice(Kernel::HLERequestContext& ctx) { + LOG_DEBUG(Service_Audio, "called"); + IPC::ResponseBuilder rb{ctx, 2, 0, 1}; rb.Push(RESULT_SUCCESS); rb.PushIpcInterface(); - - LOG_DEBUG(Service_Audio, "called"); } void AudRenU::GetAudioDeviceServiceWithRevisionInfo(Kernel::HLERequestContext& ctx) { + LOG_WARNING(Service_Audio, "(STUBBED) called"); + IPC::ResponseBuilder rb{ctx, 2, 0, 1}; rb.Push(RESULT_SUCCESS); - rb.PushIpcInterface(); - - LOG_WARNING(Service_Audio, "(STUBBED) called"); // TODO(ogniK): Figure out what is different - // based on the current revision + rb.PushIpcInterface(); // TODO(ogniK): Figure out what is different + // based on the current revision } bool AudRenU::IsFeatureSupported(AudioFeatures feature, u32_le revision) const { diff --git a/src/core/hle/service/audio/hwopus.cpp b/src/core/hle/service/audio/hwopus.cpp index 763e619a4..832159394 100644 --- a/src/core/hle/service/audio/hwopus.cpp +++ b/src/core/hle/service/audio/hwopus.cpp @@ -46,10 +46,13 @@ public: private: void DecodeInterleaved(Kernel::HLERequestContext& ctx) { + LOG_DEBUG(Audio, "called"); + u32 consumed = 0; u32 sample_count = 0; std::vector samples(ctx.GetWriteBufferSize() / sizeof(opus_int16)); if (!Decoder_DecodeInterleaved(consumed, sample_count, ctx.ReadBuffer(), samples)) { + LOG_ERROR(Audio, "Failed to decode opus data"); IPC::ResponseBuilder rb{ctx, 2}; // TODO(ogniK): Use correct error code rb.Push(ResultCode(-1)); @@ -63,12 +66,15 @@ private: } void DecodeInterleavedWithPerformance(Kernel::HLERequestContext& ctx) { + LOG_DEBUG(Audio, "called"); + u32 consumed = 0; u32 sample_count = 0; u64 performance = 0; std::vector samples(ctx.GetWriteBufferSize() / sizeof(opus_int16)); if (!Decoder_DecodeInterleaved(consumed, sample_count, ctx.ReadBuffer(), samples, performance)) { + LOG_ERROR(Audio, "Failed to decode opus data"); IPC::ResponseBuilder rb{ctx, 2}; // TODO(ogniK): Use correct error code rb.Push(ResultCode(-1)); @@ -88,24 +94,31 @@ private: std::optional> performance_time = std::nullopt) { const auto start_time = std::chrono::high_resolution_clock::now(); std::size_t raw_output_sz = output.size() * sizeof(opus_int16); - if (sizeof(OpusHeader) > input.size()) + if (sizeof(OpusHeader) > input.size()) { + LOG_ERROR(Audio, "Input is smaller than the header size"); return false; + } OpusHeader hdr{}; std::memcpy(&hdr, input.data(), sizeof(OpusHeader)); if (sizeof(OpusHeader) + static_cast(hdr.sz) > input.size()) { + LOG_ERROR(Audio, "Input does not fit in the opus header size"); return false; } auto frame = input.data() + sizeof(OpusHeader); auto decoded_sample_count = opus_packet_get_nb_samples( frame, static_cast(input.size() - sizeof(OpusHeader)), static_cast(sample_rate)); - if (decoded_sample_count * channel_count * sizeof(u16) > raw_output_sz) + if (decoded_sample_count * channel_count * sizeof(u16) > raw_output_sz) { + LOG_ERROR(Audio, "Decoded data does not fit into the output data"); return false; + } auto out_sample_count = opus_decode(decoder.get(), frame, hdr.sz, output.data(), (static_cast(raw_output_sz / sizeof(s16) / channel_count)), 0); - if (out_sample_count < 0) + if (out_sample_count < 0) { + LOG_ERROR(Audio, "Incorrect sample count received from opus_decode"); return false; + } const auto end_time = std::chrono::high_resolution_clock::now() - start_time; sample_count = out_sample_count; consumed = static_cast(sizeof(OpusHeader) + hdr.sz); @@ -134,14 +147,17 @@ static std::size_t WorkerBufferSize(u32 channel_count) { void HwOpus::GetWorkBufferSize(Kernel::HLERequestContext& ctx) { IPC::RequestParser rp{ctx}; - auto sample_rate = rp.Pop(); - auto channel_count = rp.Pop(); + const auto sample_rate = rp.Pop(); + const auto channel_count = rp.Pop(); + LOG_DEBUG(Audio, "called with sample_rate={}, channel_count={}", sample_rate, channel_count); + ASSERT_MSG(sample_rate == 48000 || sample_rate == 24000 || sample_rate == 16000 || sample_rate == 12000 || sample_rate == 8000, "Invalid sample rate"); ASSERT_MSG(channel_count == 1 || channel_count == 2, "Invalid channel count"); - u32 worker_buffer_sz = static_cast(WorkerBufferSize(channel_count)); - LOG_DEBUG(Audio, "called worker_buffer_sz={}", worker_buffer_sz); + + const u32 worker_buffer_sz = static_cast(WorkerBufferSize(channel_count)); + LOG_DEBUG(Audio, "worker_buffer_sz={}", worker_buffer_sz); IPC::ResponseBuilder rb{ctx, 3}; rb.Push(RESULT_SUCCESS); @@ -155,6 +171,7 @@ void HwOpus::OpenOpusDecoder(Kernel::HLERequestContext& ctx) { auto buffer_sz = rp.Pop(); LOG_DEBUG(Audio, "called sample_rate={}, channel_count={}, buffer_size={}", sample_rate, channel_count, buffer_sz); + ASSERT_MSG(sample_rate == 48000 || sample_rate == 24000 || sample_rate == 16000 || sample_rate == 12000 || sample_rate == 8000, "Invalid sample rate"); @@ -165,6 +182,7 @@ void HwOpus::OpenOpusDecoder(Kernel::HLERequestContext& ctx) { std::unique_ptr decoder{ static_cast(operator new(worker_sz))}; if (opus_decoder_init(decoder.get(), sample_rate, channel_count)) { + LOG_ERROR(Audio, "Failed to init opus decoder"); IPC::ResponseBuilder rb{ctx, 2}; // TODO(ogniK): Use correct error code rb.Push(ResultCode(-1)); -- cgit v1.2.3