diff --git a/.gitignore b/.gitignore index ff292d7..a674b64 100644 --- a/.gitignore +++ b/.gitignore @@ -4,6 +4,21 @@ ## ## Get latest from https://github.com/github/gitignore/blob/main/VisualStudio.gitignore +#Kevins project namager :) - trace [934875333] +.tmp/ +.manifest/ +Monospace/ +VMspace/ +Sharedspace/ +Graphene/ +Graph2Code-Jibo +Shovel-netProj +Shoveled-Jibo-Cloud +Shoveled-Jibo-Cloud-OpenMemory +latest.ShovelDump + + + # User-specific files *.rsuser *.suo diff --git a/JiboExperiments.sln b/JiboExperiments.sln new file mode 100644 index 0000000..f8e7f92 --- /dev/null +++ b/JiboExperiments.sln @@ -0,0 +1,86 @@ +Microsoft Visual Studio Solution File, Format Version 12.00 +# Visual Studio Version 17 +VisualStudioVersion = 17.5.2.0 +MinimumVisualStudioVersion = 10.0.40219.1 +Project("{2150E333-8FDC-42A3-9474-1A3956D46DE8}") = "OpenJibo", "OpenJibo", "{2FDD1CD9-89DA-D176-F85D-DC517FF08BF4}" +EndProject +Project("{2150E333-8FDC-42A3-9474-1A3956D46DE8}") = "src", "src", "{9CD502EA-259A-A102-F54F-DB66ECB43CCA}" +EndProject +Project("{FAE04EC0-301F-11D3-BF4B-00C04F79EFBC}") = "Jibo.Runtime.Abstractions", "OpenJibo\src\Jibo.Runtime.Abstractions\Jibo.Runtime.Abstractions.csproj", "{4EC1F8A2-7A15-79FC-2A37-9620624156F8}" +EndProject +Project("{FAE04EC0-301F-11D3-BF4B-00C04F79EFBC}") = "Playground", "OpenJibo\src\Playground\Playground.csproj", "{61A125DD-6776-6FF9-D0B9-9945ADBCC0E1}" +EndProject +Project("{2150E333-8FDC-42A3-9474-1A3956D46DE8}") = "tests", "tests", "{C6EF17FD-82CB-6C4D-B0EB-AB57E442D309}" +EndProject +Project("{FAE04EC0-301F-11D3-BF4B-00C04F79EFBC}") = "Jibo.Cloud.Tests", "OpenJibo\tests\Jibo.Cloud.Tests\Jibo.Cloud.Tests.csproj", "{C18A6AEA-FD8E-FDAF-1589-0BC2EF6C8F46}" +EndProject +Project("{2150E333-8FDC-42A3-9474-1A3956D46DE8}") = "Jibo.Cloud", "Jibo.Cloud", "{1E709A93-6AAE-CBDE-D98F-8B1F8D079AE6}" +EndProject +Project("{2150E333-8FDC-42A3-9474-1A3956D46DE8}") = "dotnet", "dotnet", "{7A0D8E3B-15D1-0621-86F9-1CAFD1E26384}" +EndProject +Project("{2150E333-8FDC-42A3-9474-1A3956D46DE8}") = "src", "src", "{42A75C5C-1B56-2C7E-5D8B-C570665075F4}" +EndProject +Project("{FAE04EC0-301F-11D3-BF4B-00C04F79EFBC}") = "Jibo.Cloud.Api", "OpenJibo\src\Jibo.Cloud\dotnet\src\Jibo.Cloud.Api\Jibo.Cloud.Api.csproj", "{888E2B18-7919-73EF-DF00-AD1A4EA157FF}" +EndProject +Project("{FAE04EC0-301F-11D3-BF4B-00C04F79EFBC}") = "Jibo.Cloud.Application", "OpenJibo\src\Jibo.Cloud\dotnet\src\Jibo.Cloud.Application\Jibo.Cloud.Application.csproj", "{EEDE5906-13C3-E9FB-0AFB-27376A77F1AD}" +EndProject +Project("{FAE04EC0-301F-11D3-BF4B-00C04F79EFBC}") = "Jibo.Cloud.Domain", "OpenJibo\src\Jibo.Cloud\dotnet\src\Jibo.Cloud.Domain\Jibo.Cloud.Domain.csproj", "{6B4AD66C-CACD-D9D6-4803-33A5DB0C7F4C}" +EndProject +Project("{FAE04EC0-301F-11D3-BF4B-00C04F79EFBC}") = "Jibo.Cloud.Infrastructure", "OpenJibo\src\Jibo.Cloud\dotnet\src\Jibo.Cloud.Infrastructure\Jibo.Cloud.Infrastructure.csproj", "{5BD9420F-7E77-81A2-713B-8FDBF17C2D6E}" +EndProject +Global + GlobalSection(SolutionConfigurationPlatforms) = preSolution + Debug|Any CPU = Debug|Any CPU + Release|Any CPU = Release|Any CPU + EndGlobalSection + GlobalSection(ProjectConfigurationPlatforms) = postSolution + {4EC1F8A2-7A15-79FC-2A37-9620624156F8}.Debug|Any CPU.ActiveCfg = Debug|Any CPU + {4EC1F8A2-7A15-79FC-2A37-9620624156F8}.Debug|Any CPU.Build.0 = Debug|Any CPU + {4EC1F8A2-7A15-79FC-2A37-9620624156F8}.Release|Any CPU.ActiveCfg = Release|Any CPU + {4EC1F8A2-7A15-79FC-2A37-9620624156F8}.Release|Any CPU.Build.0 = Release|Any CPU + {61A125DD-6776-6FF9-D0B9-9945ADBCC0E1}.Debug|Any CPU.ActiveCfg = Debug|Any CPU + {61A125DD-6776-6FF9-D0B9-9945ADBCC0E1}.Debug|Any CPU.Build.0 = Debug|Any CPU + {61A125DD-6776-6FF9-D0B9-9945ADBCC0E1}.Release|Any CPU.ActiveCfg = Release|Any CPU + {61A125DD-6776-6FF9-D0B9-9945ADBCC0E1}.Release|Any CPU.Build.0 = Release|Any CPU + {C18A6AEA-FD8E-FDAF-1589-0BC2EF6C8F46}.Debug|Any CPU.ActiveCfg = Debug|Any CPU + {C18A6AEA-FD8E-FDAF-1589-0BC2EF6C8F46}.Debug|Any CPU.Build.0 = Debug|Any CPU + {C18A6AEA-FD8E-FDAF-1589-0BC2EF6C8F46}.Release|Any CPU.ActiveCfg = Release|Any CPU + {C18A6AEA-FD8E-FDAF-1589-0BC2EF6C8F46}.Release|Any CPU.Build.0 = Release|Any CPU + {888E2B18-7919-73EF-DF00-AD1A4EA157FF}.Debug|Any CPU.ActiveCfg = Debug|Any CPU + {888E2B18-7919-73EF-DF00-AD1A4EA157FF}.Debug|Any CPU.Build.0 = Debug|Any CPU + {888E2B18-7919-73EF-DF00-AD1A4EA157FF}.Release|Any CPU.ActiveCfg = Release|Any CPU + {888E2B18-7919-73EF-DF00-AD1A4EA157FF}.Release|Any CPU.Build.0 = Release|Any CPU + {EEDE5906-13C3-E9FB-0AFB-27376A77F1AD}.Debug|Any CPU.ActiveCfg = Debug|Any CPU + {EEDE5906-13C3-E9FB-0AFB-27376A77F1AD}.Debug|Any CPU.Build.0 = Debug|Any CPU + {EEDE5906-13C3-E9FB-0AFB-27376A77F1AD}.Release|Any CPU.ActiveCfg = Release|Any CPU + {EEDE5906-13C3-E9FB-0AFB-27376A77F1AD}.Release|Any CPU.Build.0 = Release|Any CPU + {6B4AD66C-CACD-D9D6-4803-33A5DB0C7F4C}.Debug|Any CPU.ActiveCfg = Debug|Any CPU + {6B4AD66C-CACD-D9D6-4803-33A5DB0C7F4C}.Debug|Any CPU.Build.0 = Debug|Any CPU + {6B4AD66C-CACD-D9D6-4803-33A5DB0C7F4C}.Release|Any CPU.ActiveCfg = Release|Any CPU + {6B4AD66C-CACD-D9D6-4803-33A5DB0C7F4C}.Release|Any CPU.Build.0 = Release|Any CPU + {5BD9420F-7E77-81A2-713B-8FDBF17C2D6E}.Debug|Any CPU.ActiveCfg = Debug|Any CPU + {5BD9420F-7E77-81A2-713B-8FDBF17C2D6E}.Debug|Any CPU.Build.0 = Debug|Any CPU + {5BD9420F-7E77-81A2-713B-8FDBF17C2D6E}.Release|Any CPU.ActiveCfg = Release|Any CPU + {5BD9420F-7E77-81A2-713B-8FDBF17C2D6E}.Release|Any CPU.Build.0 = Release|Any CPU + EndGlobalSection + GlobalSection(SolutionProperties) = preSolution + HideSolutionNode = FALSE + EndGlobalSection + GlobalSection(NestedProjects) = preSolution + {9CD502EA-259A-A102-F54F-DB66ECB43CCA} = {2FDD1CD9-89DA-D176-F85D-DC517FF08BF4} + {4EC1F8A2-7A15-79FC-2A37-9620624156F8} = {9CD502EA-259A-A102-F54F-DB66ECB43CCA} + {61A125DD-6776-6FF9-D0B9-9945ADBCC0E1} = {9CD502EA-259A-A102-F54F-DB66ECB43CCA} + {C6EF17FD-82CB-6C4D-B0EB-AB57E442D309} = {2FDD1CD9-89DA-D176-F85D-DC517FF08BF4} + {C18A6AEA-FD8E-FDAF-1589-0BC2EF6C8F46} = {C6EF17FD-82CB-6C4D-B0EB-AB57E442D309} + {1E709A93-6AAE-CBDE-D98F-8B1F8D079AE6} = {9CD502EA-259A-A102-F54F-DB66ECB43CCA} + {7A0D8E3B-15D1-0621-86F9-1CAFD1E26384} = {1E709A93-6AAE-CBDE-D98F-8B1F8D079AE6} + {42A75C5C-1B56-2C7E-5D8B-C570665075F4} = {7A0D8E3B-15D1-0621-86F9-1CAFD1E26384} + {888E2B18-7919-73EF-DF00-AD1A4EA157FF} = {42A75C5C-1B56-2C7E-5D8B-C570665075F4} + {EEDE5906-13C3-E9FB-0AFB-27376A77F1AD} = {42A75C5C-1B56-2C7E-5D8B-C570665075F4} + {6B4AD66C-CACD-D9D6-4803-33A5DB0C7F4C} = {42A75C5C-1B56-2C7E-5D8B-C570665075F4} + {5BD9420F-7E77-81A2-713B-8FDBF17C2D6E} = {42A75C5C-1B56-2C7E-5D8B-C570665075F4} + EndGlobalSection + GlobalSection(ExtensibilityGlobals) = postSolution + SolutionGuid = {E18C2B78-D343-47FC-9314-42977AE46261} + EndGlobalSection +EndGlobal diff --git a/OpenJibo/docs/logging.md b/OpenJibo/docs/logging.md new file mode 100644 index 0000000..ffdb5ce --- /dev/null +++ b/OpenJibo/docs/logging.md @@ -0,0 +1,22 @@ +# Logging argument! +- - - + +using the new `DetailedOperationLogger` class you can do tiered logging , from level 1 -10 + +you can `LogStep` at any level, and it will only log if the log level is 4+ +`logstate` at any level, and it will only log if the log level is 5+ (state tracking) +`logDecision` at any level, and it will only log if the log level is 3+ (decision points) +`logTiming` at any level, and it will only log if the log level is 6= (timing performance metrics) +`logPayload` at any level, and it will only log if the log level is 8+ (payload data) +`logExternalCall` at any level, and it will only log if the log level is 5+ (external service calls) +`LogMatch` at any level, and it will only log if the log level is 4+ (pattern matching) + + +i didnt touch the existing logging but its easy to implement the new logging system in the existing code + +you can see implementations at: +- OpenJibo/src/Jibo.Cloud/dotnet/src/Jibo.Cloud.Infrastructure/Telemetry/FileWebSocketTelemetrySink.cs +- OpenJibo/src/Jibo.Cloud/dotnet/src/Jibo.Cloud.Infrastructure/Telemetry/FileWebSocketTelemetrySink.cs + +the parser is also inside : +`OpenJibo/src/Jibo.Cloud/dotnet/src/Jibo.Cloud.Api/Logging/LogLevelConfigurator.cs` \ No newline at end of file diff --git a/OpenJibo/src/Jibo.Cloud/dotnet/src/Jibo.Cloud.Api/Logging/LogLevelConfigurator.cs b/OpenJibo/src/Jibo.Cloud/dotnet/src/Jibo.Cloud.Api/Logging/LogLevelConfigurator.cs new file mode 100644 index 0000000..bc01e9c --- /dev/null +++ b/OpenJibo/src/Jibo.Cloud/dotnet/src/Jibo.Cloud.Api/Logging/LogLevelConfigurator.cs @@ -0,0 +1,72 @@ +using Microsoft.Extensions.Logging; + +namespace Jibo.Cloud.Api.Logging; + +/// +/// Configures logging levels based on command-line arguments. +/// Higher log values = more verbose logging. +/// +public static class LogLevelConfigurator +{ + /// + /// Parses the log level from command-line arguments (format: log=N where N is 0-10). + /// Returns null if no log argument is found. + /// + public static int? ParseLogLevelFromArgs(string[] args) + { + foreach (var arg in args) + { + if (arg.StartsWith("log=", StringComparison.OrdinalIgnoreCase)) + { + var value = arg["log=".Length..]; + if (int.TryParse(value, out var level) && level >= 0) + { + return Math.Min(level, 10); + } + } + } + return null; + } + + /// + /// Configures logging level based on the numeric intensity (0-10). + /// Higher values enable more verbose logging. + /// + public static void ConfigureLogging(WebApplicationBuilder builder, int logLevel) + { + builder.Logging.ClearProviders(); + builder.Logging.AddConsole(); + builder.Logging.AddDebug(); + + var level = MapToLogLevel(logLevel); + + builder.Logging.SetMinimumLevel(level); + + builder.Logging.AddFilter("Microsoft.AspNetCore", logLevel >= 8 ? LogLevel.Debug : LogLevel.Warning); + builder.Logging.AddFilter("Microsoft.Hosting", logLevel >= 7 ? LogLevel.Information : LogLevel.Warning); + builder.Logging.AddFilter("System", logLevel >= 9 ? LogLevel.Debug : LogLevel.Warning); + + builder.Logging.AddFilter("Jibo.Cloud", logLevel >= 5 ? LogLevel.Debug : LogLevel.Information); + builder.Logging.AddFilter("Jibo.Cloud.Application", logLevel >= 3 ? LogLevel.Debug : LogLevel.Information); + builder.Logging.AddFilter("Jibo.Cloud.Infrastructure", logLevel >= 4 ? LogLevel.Debug : LogLevel.Information); + } + + private static LogLevel MapToLogLevel(int value) + { + return value switch + { + 0 => LogLevel.Error, + 1 => LogLevel.Warning, + 2 => LogLevel.Warning, + 3 => LogLevel.Information, + 4 => LogLevel.Information, + 5 => LogLevel.Information, + 6 => LogLevel.Debug, + 7 => LogLevel.Debug, + 8 => LogLevel.Debug, + 9 => LogLevel.Trace, + 10 => LogLevel.Trace, + _ => LogLevel.Information + }; + } +} diff --git a/OpenJibo/src/Jibo.Cloud/dotnet/src/Jibo.Cloud.Api/Program.cs b/OpenJibo/src/Jibo.Cloud/dotnet/src/Jibo.Cloud.Api/Program.cs index 3af7c8a..0de3e64 100644 --- a/OpenJibo/src/Jibo.Cloud/dotnet/src/Jibo.Cloud.Api/Program.cs +++ b/OpenJibo/src/Jibo.Cloud/dotnet/src/Jibo.Cloud.Api/Program.cs @@ -1,5 +1,6 @@ using System.Net.WebSockets; using System.Text; +using Jibo.Cloud.Api.Logging; using Jibo.Cloud.Application.Abstractions; using Jibo.Cloud.Application.Services; using Jibo.Cloud.Domain.Models; @@ -7,7 +8,13 @@ using Jibo.Cloud.Infrastructure.DependencyInjection; var builder = WebApplication.CreateBuilder(args); -builder.Services.AddOpenJiboCloud(builder.Configuration); +var logLevel = LogLevelConfigurator.ParseLogLevelFromArgs(args); +if (logLevel.HasValue) +{ + LogLevelConfigurator.ConfigureLogging(builder, logLevel.Value); +} + +builder.Services.AddOpenJiboCloud(builder.Configuration, logLevel); var app = builder.Build(); diff --git a/OpenJibo/src/Jibo.Cloud/dotnet/src/Jibo.Cloud.Application/Jibo.Cloud.Application.csproj b/OpenJibo/src/Jibo.Cloud/dotnet/src/Jibo.Cloud.Application/Jibo.Cloud.Application.csproj index 1737e88..66a5ec8 100644 --- a/OpenJibo/src/Jibo.Cloud/dotnet/src/Jibo.Cloud.Application/Jibo.Cloud.Application.csproj +++ b/OpenJibo/src/Jibo.Cloud/dotnet/src/Jibo.Cloud.Application/Jibo.Cloud.Application.csproj @@ -1,6 +1,7 @@ + diff --git a/OpenJibo/src/Jibo.Cloud/dotnet/src/Jibo.Cloud.Application/Logging/DetailedOperationLogger.cs b/OpenJibo/src/Jibo.Cloud/dotnet/src/Jibo.Cloud.Application/Logging/DetailedOperationLogger.cs new file mode 100644 index 0000000..6f114f8 --- /dev/null +++ b/OpenJibo/src/Jibo.Cloud/dotnet/src/Jibo.Cloud.Application/Logging/DetailedOperationLogger.cs @@ -0,0 +1,145 @@ +using Microsoft.Extensions.Logging; + +namespace Jibo.Cloud.Application.Logging; + +/// +/// Provides detailed operation logging that activates based on log intensity level. +/// Higher log levels = more detailed logging. +/// +public sealed class DetailedOperationLogger +{ + private readonly ILogger _logger; + private readonly int _configuredLogLevel; + + public DetailedOperationLogger(ILogger logger, int? configuredLogLevel = null) + { + _logger = logger; + _configuredLogLevel = configuredLogLevel ?? 3; + } + + /// + /// Log method entry at Debug level when log level >= 3 + /// + public void LogEntry(string methodName, params (string Key, object? Value)[] parameters) + { + if (_configuredLogLevel < 3) return; + + if (_logger.IsEnabled(LogLevel.Debug)) + { + var paramStr = parameters.Length > 0 + ? string.Join(", ", parameters.Select(p => $"{p.Key}={p.Value}")) + : "none"; + _logger.LogDebug("[ENTRY] {MethodName}({Parameters})", methodName, paramStr); + } + } + + /// + /// Log method exit at Debug level when log level >= 3 + /// + public void LogExit(string methodName, string? result = null) + { + if (_configuredLogLevel < 3) return; + + if (_logger.IsEnabled(LogLevel.Debug)) + { + var resultStr = result ?? "void"; + _logger.LogDebug("[EXIT] {MethodName} -> {Result}", methodName, resultStr); + } + } + + /// + /// Log a detailed operation step at Debug level when log level >= 4 + /// + public void LogStep(string operation, string step, string? details = null) + { + if (_configuredLogLevel < 4) return; + + if (_logger.IsEnabled(LogLevel.Debug)) + { + var detailStr = details != null ? $" | {details}" : ""; + _logger.LogDebug("[STEP] {Operation}.{Step}{Details}", operation, step, detailStr); + } + } + + /// + /// Log state information at Debug level when log level >= 5 + /// + public void LogState(string context, string stateName, object? value) + { + if (_configuredLogLevel < 5) return; + + if (_logger.IsEnabled(LogLevel.Debug)) + { + _logger.LogDebug("[STATE] {Context}.{StateName} = {Value}", context, stateName, value); + } + } + + /// + /// Log decision information at Information level when log level >= 3 + /// + public void LogDecision(string context, string decision, string? reason = null) + { + if (_configuredLogLevel < 3) return; + + if (_logger.IsEnabled(LogLevel.Information)) + { + var reasonStr = reason != null ? $" (reason: {reason})" : ""; + _logger.LogInformation("[DECISION] {Context}: {Decision}{Reason}", context, decision, reasonStr); + } + } + + /// + /// Log performance timing at Debug level when log level >= 6 + /// + public void LogTiming(string operation, long elapsedMs) + { + if (_configuredLogLevel < 6) return; + + if (_logger.IsEnabled(LogLevel.Debug)) + { + _logger.LogDebug("[TIMING] {Operation} completed in {ElapsedMs}ms", operation, elapsedMs); + } + } + + /// + /// Log data payload at Trace level when log level >= 8 + /// + public void LogPayload(string context, string dataType, int dataSize, string? preview = null) + { + if (_configuredLogLevel < 8) return; + + if (_logger.IsEnabled(LogLevel.Trace)) + { + var previewStr = preview != null ? $" preview: {preview}" : ""; + _logger.LogTrace("[PAYLOAD] {Context} {DataType} size={Size}{Preview}", context, dataType, dataSize, previewStr); + } + } + + /// + /// Log external call at Debug level when log level >= 5 + /// + public void LogExternalCall(string service, string operation, string? details = null) + { + if (_configuredLogLevel < 5) return; + + if (_logger.IsEnabled(LogLevel.Debug)) + { + var detailStr = details != null ? $" ({details})" : ""; + _logger.LogDebug("[EXTERNAL] {Service}.{Operation}{Details}", service, operation, detailStr); + } + } + + /// + /// Log match/pattern information at Debug level when log level >= 4 + /// + public void LogMatch(string context, string pattern, string input, bool matched) + { + if (_configuredLogLevel < 4) return; + + if (_logger.IsEnabled(LogLevel.Debug)) + { + _logger.LogDebug("[MATCH] {Context}: Pattern '{Pattern}' against '{Input}' => {Result}", + context, pattern, input, matched ? "MATCHED" : "NO MATCH"); + } + } +} diff --git a/OpenJibo/src/Jibo.Cloud/dotnet/src/Jibo.Cloud.Application/Services/JiboCloudProtocolService.cs b/OpenJibo/src/Jibo.Cloud/dotnet/src/Jibo.Cloud.Application/Services/JiboCloudProtocolService.cs index ad7a74f..ef39445 100644 --- a/OpenJibo/src/Jibo.Cloud/dotnet/src/Jibo.Cloud.Application/Services/JiboCloudProtocolService.cs +++ b/OpenJibo/src/Jibo.Cloud/dotnet/src/Jibo.Cloud.Application/Services/JiboCloudProtocolService.cs @@ -1,11 +1,16 @@ using System.Text.Json; using Jibo.Cloud.Application.Abstractions; +using Jibo.Cloud.Application.Logging; using Jibo.Cloud.Domain.Models; +using Microsoft.Extensions.Logging; namespace Jibo.Cloud.Application.Services; -public sealed class JiboCloudProtocolService(ICloudStateStore stateStore) +public sealed class JiboCloudProtocolService( + ICloudStateStore stateStore, + ILogger logger) { + private readonly DetailedOperationLogger _detailedLogger = new(logger); private static readonly string[] AcceptedHosts = [ "api.jibo.com", @@ -16,16 +21,25 @@ public sealed class JiboCloudProtocolService(ICloudStateStore stateStore) public Task DispatchAsync(ProtocolEnvelope envelope, CancellationToken cancellationToken = default) { + _detailedLogger.LogEntry(nameof(DispatchAsync), + ("method", envelope.Method), + ("path", envelope.Path), + ("host", envelope.HostName), + ("servicePrefix", envelope.ServicePrefix), + ("operation", envelope.Operation)); + if (envelope.Method.Equals("GET", StringComparison.OrdinalIgnoreCase) && envelope.Path == "/" && string.IsNullOrWhiteSpace(envelope.ServicePrefix)) { + _detailedLogger.LogExit(nameof(DispatchAsync), "NoContent"); return Task.FromResult(ProtocolDispatchResult.NoContent()); } if (envelope.Method.Equals("GET", StringComparison.OrdinalIgnoreCase) && envelope.Path.Equals("/health", StringComparison.OrdinalIgnoreCase)) { + _detailedLogger.LogExit(nameof(DispatchAsync), "Health"); return Task.FromResult(ProtocolDispatchResult.Ok(new { ok = true, host = envelope.HostName })); } @@ -45,6 +59,8 @@ public sealed class JiboCloudProtocolService(ICloudStateStore stateStore) if (!AcceptedHosts.Contains(envelope.HostName, StringComparer.OrdinalIgnoreCase)) { + _detailedLogger.LogDecision(nameof(DispatchAsync), "HostNotAccepted", envelope.HostName); + _detailedLogger.LogExit(nameof(DispatchAsync), "NotAccepted"); return Task.FromResult(ProtocolDispatchResult.Ok(new { ok = true, @@ -53,26 +69,32 @@ public sealed class JiboCloudProtocolService(ICloudStateStore stateStore) })); } + _detailedLogger.LogStep(nameof(DispatchAsync), "ServicePrefixResolved", $"prefix={envelope.ServicePrefix}, operation={envelope.Operation}"); + var servicePrefix = envelope.ServicePrefix ?? string.Empty; var operation = envelope.Operation ?? string.Empty; if (servicePrefix.StartsWith("Log_", StringComparison.OrdinalIgnoreCase)) { + _detailedLogger.LogStep(nameof(DispatchAsync), "HandlerSelected", "Log"); return Task.FromResult(HandleLog(operation, envelope)); } if (servicePrefix.StartsWith("Backup_", StringComparison.OrdinalIgnoreCase)) { + _detailedLogger.LogStep(nameof(DispatchAsync), "HandlerSelected", "Backup"); return Task.FromResult(HandleBackup(operation)); } if (servicePrefix.StartsWith("Account_", StringComparison.OrdinalIgnoreCase)) { + _detailedLogger.LogStep(nameof(DispatchAsync), "HandlerSelected", "Account"); return Task.FromResult(HandleAccount(operation, envelope)); } if (servicePrefix.StartsWith("Notification_", StringComparison.OrdinalIgnoreCase)) { + _detailedLogger.LogStep(nameof(DispatchAsync), "HandlerSelected", "Notification"); return Task.FromResult(HandleNotification(operation, envelope)); } @@ -98,6 +120,7 @@ public sealed class JiboCloudProtocolService(ICloudStateStore stateStore) if (servicePrefix.StartsWith("Robot_", StringComparison.OrdinalIgnoreCase)) { + _detailedLogger.LogStep(nameof(DispatchAsync), "HandlerSelected", "Robot"); return Task.FromResult(HandleRobot(operation, envelope)); } @@ -106,6 +129,8 @@ public sealed class JiboCloudProtocolService(ICloudStateStore stateStore) return Task.FromResult(HandleUpdate(operation, envelope)); } + _detailedLogger.LogDecision(nameof(DispatchAsync), "UnknownHandler", $"{servicePrefix}.{operation}"); + _detailedLogger.LogExit(nameof(DispatchAsync), "DefaultResponse"); return Task.FromResult(ProtocolDispatchResult.Ok(new { ok = true, diff --git a/OpenJibo/src/Jibo.Cloud/dotnet/src/Jibo.Cloud.Application/Services/JiboInteractionService.cs b/OpenJibo/src/Jibo.Cloud/dotnet/src/Jibo.Cloud.Application/Services/JiboInteractionService.cs index ce0275d..9c5c473 100644 --- a/OpenJibo/src/Jibo.Cloud/dotnet/src/Jibo.Cloud.Application/Services/JiboInteractionService.cs +++ b/OpenJibo/src/Jibo.Cloud/dotnet/src/Jibo.Cloud.Application/Services/JiboInteractionService.cs @@ -1,19 +1,31 @@ using Jibo.Cloud.Application.Abstractions; +using Jibo.Cloud.Application.Logging; using Jibo.Runtime.Abstractions; using System.Text.Json; using System.Text.RegularExpressions; +using Microsoft.Extensions.Logging; namespace Jibo.Cloud.Application.Services; public sealed class JiboInteractionService( JiboExperienceContentCache contentCache, - IJiboRandomizer randomizer) + IJiboRandomizer randomizer, + ILogger logger) { + private readonly DetailedOperationLogger _detailedLogger = new(logger); public async Task BuildDecisionAsync(TurnContext turn, CancellationToken cancellationToken = default) { + _detailedLogger.LogEntry(nameof(BuildDecisionAsync), + ("transcript", turn.NormalizedTranscript ?? turn.RawTranscript), + ("inputMode", turn.InputMode), + ("sourceKind", turn.SourceKind)); + var catalog = await contentCache.GetCatalogAsync(cancellationToken); var transcript = (turn.NormalizedTranscript ?? turn.RawTranscript ?? string.Empty).Trim(); var lowered = transcript.ToLowerInvariant(); + + _detailedLogger.LogState(nameof(BuildDecisionAsync), "NormalizedTranscript", transcript); + _detailedLogger.LogState(nameof(BuildDecisionAsync), "ClientIntent", turn.Attributes.TryGetValue("clientIntent", out var ci) ? ci : null); var referenceLocalTime = TryResolveReferenceLocalTime(turn); var clientIntent = turn.Attributes.TryGetValue("clientIntent", out var rawClientIntent) ? rawClientIntent?.ToString() @@ -40,7 +52,10 @@ public sealed class JiboInteractionService( isYesNoTurn, isTimerValueTurn, isAlarmValueTurn); - return semanticIntent switch + + _detailedLogger.LogDecision(nameof(BuildDecisionAsync), "SemanticIntentResolved", semanticIntent); + + var decision = semanticIntent switch { "joke" => BuildJokeDecision(catalog), "dance" => BuildRandomDanceDecision(catalog), @@ -85,6 +100,9 @@ public sealed class JiboInteractionService( "news" => BuildNewsDecision(catalog), _ => new JiboInteractionDecision("chat", BuildGenericReply(catalog, transcript, lowered)) }; + + _detailedLogger.LogExit(nameof(BuildDecisionAsync), $"intent={decision.IntentName}, skill={decision.SkillName ?? "null"}"); + return decision; } private JiboInteractionDecision BuildJokeDecision(JiboExperienceCatalog catalog) diff --git a/OpenJibo/src/Jibo.Cloud/dotnet/src/Jibo.Cloud.Application/Services/JiboWebSocketService.cs b/OpenJibo/src/Jibo.Cloud/dotnet/src/Jibo.Cloud.Application/Services/JiboWebSocketService.cs index 92edf13..c18e598 100644 --- a/OpenJibo/src/Jibo.Cloud/dotnet/src/Jibo.Cloud.Application/Services/JiboWebSocketService.cs +++ b/OpenJibo/src/Jibo.Cloud/dotnet/src/Jibo.Cloud.Application/Services/JiboWebSocketService.cs @@ -1,53 +1,83 @@ using System.Text.Json; using Jibo.Cloud.Application.Abstractions; +using Jibo.Cloud.Application.Logging; using Jibo.Cloud.Domain.Models; +using Microsoft.Extensions.Logging; namespace Jibo.Cloud.Application.Services; public sealed class JiboWebSocketService( ICloudStateStore stateStore, IWebSocketTelemetrySink telemetrySink, - WebSocketTurnFinalizationService turnFinalizationService) + WebSocketTurnFinalizationService turnFinalizationService, + ILogger logger) { + private readonly DetailedOperationLogger _detailedLogger = new(logger); public CloudSession GetOrCreateSession(WebSocketMessageEnvelope envelope) { - return stateStore.FindSessionByToken(envelope.Token ?? string.Empty) ?? + _detailedLogger.LogEntry(nameof(GetOrCreateSession), + ("token", envelope.Token), + ("kind", envelope.Kind), + ("host", envelope.HostName)); + + var session = stateStore.FindSessionByToken(envelope.Token ?? string.Empty) ?? stateStore.OpenSession(envelope.Kind, null, envelope.Token, envelope.HostName, envelope.Path); + + _detailedLogger.LogExit(nameof(GetOrCreateSession), $"sessionId={session.SessionId}"); + return session; } public async Task> HandleMessageAsync(WebSocketMessageEnvelope envelope, CancellationToken cancellationToken = default) { + _detailedLogger.LogEntry(nameof(HandleMessageAsync), + ("isBinary", envelope.IsBinary), + ("textLength", envelope.Text?.Length ?? 0), + ("binaryLength", envelope.Binary?.Length ?? 0)); + var session = GetOrCreateSession(envelope); session.LastSeenUtc = DateTimeOffset.UtcNow; + _detailedLogger.LogState(nameof(HandleMessageAsync), "SessionId", session.SessionId); + _detailedLogger.LogState(nameof(HandleMessageAsync), "SessionKind", session.Kind); + if (envelope.IsBinary) { + _detailedLogger.LogStep(nameof(HandleMessageAsync), "ProcessingBinaryAudio", $"bytes={envelope.Binary?.Length ?? 0}"); var replies = await turnFinalizationService.HandleBinaryAudioAsync(session, envelope, cancellationToken); await telemetrySink.RecordTurnEventAsync(envelope, session, "binary_audio_received", new Dictionary { ["bytes"] = envelope.Binary?.Length ?? 0 }, cancellationToken); + _detailedLogger.LogPayload(nameof(HandleMessageAsync), "BinaryAudio", envelope.Binary?.Length ?? 0, null); + _detailedLogger.LogExit(nameof(HandleMessageAsync), $"replies={replies.Count}"); return replies; } var parsedType = ReadMessageType(envelope.Text); + _detailedLogger.LogDecision(nameof(HandleMessageAsync), "MessageTypeResolved", parsedType); + session.LastMessageType = parsedType; WebSocketTurnFinalizationService.ObserveIncomingMessage(session, envelope.Text); + _detailedLogger.LogState(nameof(HandleMessageAsync), "LastMessageType", parsedType); switch (parsedType) { case "CONTEXT": { + _detailedLogger.LogStep(nameof(HandleMessageAsync), "ProcessingContext", $"transId={session.TurnState.TransId}"); var replies = await turnFinalizationService.HandleContextAsync(session, envelope, cancellationToken); await telemetrySink.RecordTurnEventAsync(envelope, session, "context_received", new Dictionary { ["transID"] = session.TurnState.TransId }, cancellationToken); + _detailedLogger.LogExit(nameof(HandleMessageAsync), $"replies={replies.Count}"); return replies; } case "LISTEN": { - var replies = ContainsInlineTurnPayload(envelope.Text) + var hasInlinePayload = ContainsInlineTurnPayload(envelope.Text); + _detailedLogger.LogDecision(nameof(HandleMessageAsync), "ListenHandlerSelected", hasInlinePayload ? "inline_turn" : "listen_setup"); + var replies = hasInlinePayload ? await turnFinalizationService.HandleTurnAsync(session, envelope, parsedType, cancellationToken) : WebSocketTurnFinalizationService.HandleListenSetup(session, envelope); await telemetrySink.RecordTurnEventAsync(envelope, session, "turn_processed", new Dictionary @@ -57,10 +87,12 @@ public sealed class JiboWebSocketService( ["transcript"] = session.LastTranscript, ["intent"] = session.LastIntent }, cancellationToken); + _detailedLogger.LogExit(nameof(HandleMessageAsync), $"replies={replies.Count}"); return replies; } case "CLIENT_NLU" or "CLIENT_ASR": { + _detailedLogger.LogStep(nameof(HandleMessageAsync), "ProcessingTurn", $"type={parsedType}"); var replies = await turnFinalizationService.HandleTurnAsync(session, envelope, parsedType, cancellationToken); await telemetrySink.RecordTurnEventAsync(envelope, session, "turn_processed", new Dictionary { @@ -69,9 +101,12 @@ public sealed class JiboWebSocketService( ["transcript"] = session.LastTranscript, ["intent"] = session.LastIntent }, cancellationToken); + _detailedLogger.LogExit(nameof(HandleMessageAsync), $"replies={replies.Count}"); return replies; } default: + _detailedLogger.LogDecision(nameof(HandleMessageAsync), "UnknownMessageType", $"type={parsedType}"); + _detailedLogger.LogExit(nameof(HandleMessageAsync), "empty"); return []; } } diff --git a/OpenJibo/src/Jibo.Cloud/dotnet/src/Jibo.Cloud.Application/Services/WebSocketTurnFinalizationService.cs b/OpenJibo/src/Jibo.Cloud/dotnet/src/Jibo.Cloud.Application/Services/WebSocketTurnFinalizationService.cs index c56456a..c991d9d 100644 --- a/OpenJibo/src/Jibo.Cloud/dotnet/src/Jibo.Cloud.Application/Services/WebSocketTurnFinalizationService.cs +++ b/OpenJibo/src/Jibo.Cloud/dotnet/src/Jibo.Cloud.Application/Services/WebSocketTurnFinalizationService.cs @@ -1,17 +1,20 @@ using System.Text.Json; using Jibo.Cloud.Application.Abstractions; +using Jibo.Cloud.Application.Logging; using Jibo.Cloud.Domain.Models; using Jibo.Runtime.Abstractions; using System.Text.RegularExpressions; +using Microsoft.Extensions.Logging; namespace Jibo.Cloud.Application.Services; public sealed partial class WebSocketTurnFinalizationService( IConversationBroker conversationBroker, ISttStrategySelector sttStrategySelector, - ITurnTelemetrySink sink -) + ITurnTelemetrySink sink, + ILogger logger) { + private readonly DetailedOperationLogger _detailedLogger = new(logger); private const int AutoFinalizeMinBufferedAudioBytes = 12000; private const int AutoFinalizeMinBufferedAudioChunks = 4; private static readonly TimeSpan AutoFinalizeMinTurnAge = TimeSpan.FromMilliseconds(1400); @@ -36,12 +39,18 @@ public sealed partial class WebSocketTurnFinalizationService( WebSocketMessageEnvelope envelope, CancellationToken cancellationToken = default) { + _detailedLogger.LogEntry(nameof(HandleBinaryAudioAsync), + ("sessionId", session.SessionId), + ("audioBytes", envelope.Binary?.Length ?? 0)); + var turnState = session.TurnState; if (ShouldIgnoreLateAudio(session) || !turnState.AwaitingTurnCompletion && !session.FollowUpOpen && !turnState.SawListen && !string.IsNullOrWhiteSpace(turnState.TransId)) { + _detailedLogger.LogDecision(nameof(HandleBinaryAudioAsync), "IgnoringLateAudio", $"transId={turnState.TransId}"); + _detailedLogger.LogExit(nameof(HandleBinaryAudioAsync), "empty"); return []; } @@ -59,9 +68,14 @@ public sealed partial class WebSocketTurnFinalizationService( if (ShouldAutoFinalize(session)) { - return await FinalizeTurnAsync(session, envelope, "AUTO_FINALIZE", allowFallbackOnMissingTranscript: true, cancellationToken); + _detailedLogger.LogDecision(nameof(HandleBinaryAudioAsync), "AutoFinalizing", $"chunks={turnState.BufferedAudioChunkCount}, bytes={turnState.BufferedAudioBytes}"); + var replies = await FinalizeTurnAsync(session, envelope, "AUTO_FINALIZE", allowFallbackOnMissingTranscript: true, cancellationToken); + _detailedLogger.LogExit(nameof(HandleBinaryAudioAsync), $"replies={replies.Count}"); + return replies; } + _detailedLogger.LogStep(nameof(HandleBinaryAudioAsync), "BufferingAudio", $"chunks={turnState.BufferedAudioChunkCount}, bytes={turnState.BufferedAudioBytes}"); + _detailedLogger.LogExit(nameof(HandleBinaryAudioAsync), "empty-awaiting-more"); return []; } diff --git a/OpenJibo/src/Jibo.Cloud/dotnet/src/Jibo.Cloud.Infrastructure/DependencyInjection/ServiceCollectionExtensions.cs b/OpenJibo/src/Jibo.Cloud/dotnet/src/Jibo.Cloud.Infrastructure/DependencyInjection/ServiceCollectionExtensions.cs index b5e2a9b..3e571c8 100644 --- a/OpenJibo/src/Jibo.Cloud/dotnet/src/Jibo.Cloud.Infrastructure/DependencyInjection/ServiceCollectionExtensions.cs +++ b/OpenJibo/src/Jibo.Cloud/dotnet/src/Jibo.Cloud.Infrastructure/DependencyInjection/ServiceCollectionExtensions.cs @@ -12,7 +12,7 @@ namespace Jibo.Cloud.Infrastructure.DependencyInjection; public static class ServiceCollectionExtensions { - public static IServiceCollection AddOpenJiboCloud(this IServiceCollection services, IConfiguration? configuration = null) + public static IServiceCollection AddOpenJiboCloud(this IServiceCollection services, IConfiguration? configuration = null, int? logLevel = null) { var sttOptions = new BufferedAudioSttOptions(); if (configuration is not null) diff --git a/OpenJibo/src/Jibo.Cloud/dotnet/src/Jibo.Cloud.Infrastructure/Telemetry/FileWebSocketTelemetrySink.cs b/OpenJibo/src/Jibo.Cloud/dotnet/src/Jibo.Cloud.Infrastructure/Telemetry/FileWebSocketTelemetrySink.cs index cee4010..9dbb2b1 100644 --- a/OpenJibo/src/Jibo.Cloud/dotnet/src/Jibo.Cloud.Infrastructure/Telemetry/FileWebSocketTelemetrySink.cs +++ b/OpenJibo/src/Jibo.Cloud/dotnet/src/Jibo.Cloud.Infrastructure/Telemetry/FileWebSocketTelemetrySink.cs @@ -1,6 +1,7 @@ using System.Collections.Concurrent; using System.Text.Json; using Jibo.Cloud.Application.Abstractions; +using Jibo.Cloud.Application.Logging; using Jibo.Cloud.Domain.Models; using Microsoft.Extensions.Logging; using Microsoft.Extensions.Options; @@ -11,6 +12,7 @@ public sealed class FileWebSocketTelemetrySink( ILogger logger, IOptions options) : IWebSocketTelemetrySink { + private readonly DetailedOperationLogger _detailedLogger = new(logger); private static readonly JsonSerializerOptions JsonOptions = new(JsonSerializerDefaults.Web) { WriteIndented = true @@ -21,8 +23,14 @@ public sealed class FileWebSocketTelemetrySink( public async Task RecordConnectionOpenedAsync(WebSocketMessageEnvelope envelope, CloudSession session, CancellationToken cancellationToken = default) { + _detailedLogger.LogEntry(nameof(RecordConnectionOpenedAsync), + ("sessionId", session.SessionId), + ("host", envelope.HostName), + ("kind", envelope.Kind)); + if (!options.Value.Enabled) { + _detailedLogger.LogStep(nameof(RecordConnectionOpenedAsync), "TelemetryDisabled"); return; } @@ -42,10 +50,20 @@ public sealed class FileWebSocketTelemetrySink( public Task RecordInboundAsync(WebSocketMessageEnvelope envelope, CloudSession session, string? messageType, CancellationToken cancellationToken = default) { - return !options.Value.Enabled - ? Task.CompletedTask - : WriteRecordAsync(BuildRecord("message_in", envelope, session, messageType, "in", null, null), - cancellationToken); + _detailedLogger.LogEntry(nameof(RecordInboundAsync), + ("sessionId", session.SessionId), + ("messageType", messageType), + ("textLength", envelope.Text?.Length ?? 0), + ("binaryLength", envelope.Binary?.Length ?? 0)); + + if (!options.Value.Enabled) + { + return Task.CompletedTask; + } + + _detailedLogger.LogPayload(nameof(RecordInboundAsync), "WebSocketMessage", envelope.Text?.Length ?? envelope.Binary?.Length ?? 0, envelope.Text?[..Math.Min(100, envelope.Text?.Length ?? 0)]); + + return WriteRecordAsync(BuildRecord("message_in", envelope, session, messageType, "in", null, null), cancellationToken); } public Task RecordTurnEventAsync(WebSocketMessageEnvelope envelope, CloudSession session, string eventType, IReadOnlyDictionary details, CancellationToken cancellationToken = default) @@ -58,11 +76,17 @@ public sealed class FileWebSocketTelemetrySink( public async Task RecordOutboundAsync(WebSocketMessageEnvelope envelope, CloudSession session, IReadOnlyList replies, CancellationToken cancellationToken = default) { + _detailedLogger.LogEntry(nameof(RecordOutboundAsync), + ("sessionId", session.SessionId), + ("replyCount", replies.Count)); + if (!options.Value.Enabled) { return; } + _detailedLogger.LogState(nameof(RecordOutboundAsync), "ReplyCount", replies.Count); + var replyTypes = replies .Select(reply => ReadReplyType(reply.Text)) .Where(type => !string.IsNullOrWhiteSpace(type))