Azure Functions Console/Stream Logger for Hot Chocolate GraphQL v13

AzFuncGraphQLConsoleLoggingEventListener.cs

using HotChocolate.Execution.Instrumentation;
using HotChocolate.Execution;
using System;
using System.Diagnostics;
using System.Linq;
using Aeg.Common.CSharp.CustomExtensions;
using Microsoft.Extensions.Logging;
using Microsoft.Extensions.DependencyInjection;
using GraphQL.HotChocolate.AzureFunctions.Authorization;
using System.Security.Claims;
using HotChocolate.Execution.Processing;
using HotChocolate.Resolvers;
using HotChocolate;
using HotChocolate.Language;

namespace GraphQL.HotChocolate.AzureFunctions.Logging
{
    ///This Framework was taken directly from the GitHub Gist located Here:
    /// https://gist.github.com/cajuncoding/c28c04741678efd44ff476671cafdb33
    /// 
    /// <summary>
    /// BBernard / CajunCoding
    /// A simplified framework for Console Logging of GraphQL Request details including:
    ///     - Current User Principal and any/all Roles they have defined (aka ClaimType.Role)
    ///     - Full GraphQL Query
    ///     - All variables and their values
    ///
    /// NOTE: For this to work correctly you will have to support resolving the ILogger (non generic) interface
    ///         with a registration that uses a valid Azure Function Class Name as the LogFactory param as follows:
    /// 
    ///         services.AddTransient((svc) =>
    ///         {
    ///             //Enable Log Streaming for our primary endpoint as the Default ILogger (but can be overridden by ScopedLogger user in the AzFuncDependency Resolver!
    ///             var logFactory = svc.GetService<ILoggerFactory>();
    ///             return logFactory?.CreateLogger(LogCategories.CreateFunctionUserCategory(nameof(GraphQLFunctionApiEndpoint)));
    ///         });
    ///</summary>
    public class AzFuncGraphQLConsoleLoggingEventListener : ExecutionDiagnosticEventListener
    {
        private readonly IServiceProvider _serviceProvider;

        public AzFuncGraphQLConsoleLoggingEventListener(IServiceProvider serviceProvider)
        {
            _serviceProvider = serviceProvider;
        }

        /// <summary>
        /// The ExecuteOperation will run when HC is starting to execute the GraphQL operation and its resolvers.
        /// So the GraphQL Query Document will be fully parsed and available at this time for Logging.
        /// </summary>
        public override IDisposable ExecuteOperation(IRequestContext context)
        {
            var timer = Stopwatch.StartNew();
            var logger = _serviceProvider.GetService<ILogger>();
            if (logger == null)
            {
                throw new ArgumentNullException("The ILogger (non-generic) interface could not be resolved from the DI services; " +
                                                "without this non-generic version we cannot be sure that the log messages will be written to the console/stream as expected.");
            }

            //The processing of User Authorization is currently dependent on another small Gist for Az Func Role Based Authorization
            // that can be found here: https://gist.github.com/cajuncoding/4c037cb881a31da4aada061fde7f95f7
            //Otherwise this if/else may be removed and no logging of the User will be done.
            if(context.ContextData.TryGetValue(nameof(ClaimsPrincipal), out var userObj) && userObj is ClaimsPrincipal user)
                logger.LogInformation("[GRAPHQL-AUTHENTICATION] Request from User [{UserName}] with Roles [{RolesCsv}]", user.GetName(), user.GetRoles().ToCsvString(includeSpaceAfterComma: true));
            else
                logger.LogInformation("[GRAPHQL-AUTHENTICATION] Missing User Principal; the current User ClaimsPrincipal could not be retrieved from the Request Context Data.");

            if (logger.IsEnabled(LogLevel.Trace) && context.Document is not null && context.Operation is not null)
            {
                var graphQLOperationName = context.Operation.Definition.SelectionSet.Selections.OfType<NamedSyntaxNode>().FirstOrDefault()?.Name;
                logger.LogTrace("[GRAPHQL-OPERATION] {GraphQLOperation} {{...}}", graphQLOperationName);
            
                var graphQLQuery = context.Document.ToString(true);
                logger.LogTrace($"[GRAPHQL-QUERY]{Environment.NewLine}{{GraphQLQuery}}", graphQLQuery);

                if (context.Variables.HasAny())
                    foreach (var variable in context.Variables!)
                        //NOTE: THis will dynamically log the Variable Value as Telemetry using the Variable.Name as the Telemetry name...
                        logger.LogTrace($"[GRAPHQL-VARIABLE] <{variable.Type.Kind}> GraphQLVariable[{variable.Name}] ==> {{GraphQLVariable[{variable.Name}]}}", variable.Value);
            }

            var baseExecuteOperation = base.ExecuteOperation(context);
            return new RunActionOnDisposalActivityScope(() =>
            {
                timer.Stop();
                logger.LogInformation("[GRAPHQL-TIMER] GraphQL Query Execution Completed in [{GraphQLExecutionTime}]", timer.Elapsed.ToElapsedTimeDescriptiveFormat());

                //If specified then call the Disposal of the base operation... (Though this is currently a No-op).
                baseExecuteOperation.Dispose();
            });
        }

        public class RunActionOnDisposalActivityScope : IDisposable
        {
            private readonly Action _action;
            public RunActionOnDisposalActivityScope(Action action) { _action = action; }
            public void Dispose() => _action?.Invoke();
        }
        
        public override void ResolverError(IRequestContext context, ISelection selection, IError error)
            => LogExceptionInternal(error.Exception, BuildMessage(nameof(ResolverError), error.Message));

        public override void ResolverError(IMiddlewareContext context, IError error)
            => LogExceptionInternal(error.Exception, BuildMessage(nameof(ResolverError), error.Message));

        public override void TaskError(IExecutionTask task, IError error)
            => LogExceptionInternal(error.Exception, BuildMessage(nameof(TaskError), error.Message));

        public override void RequestError(IRequestContext context, Exception exception)
            => LogExceptionInternal(exception, BuildMessage(nameof(RequestError)));

        public override void SubscriptionEventError(SubscriptionEventContext context, Exception exception)
            => LogExceptionInternal(exception, BuildMessage(nameof(SubscriptionEventError)));

        public override void SubscriptionTransportError(ISubscription subscription, Exception exception)
            => LogExceptionInternal(exception, BuildMessage(nameof(RequestError)));

        #region Internal Helpers

        protected virtual void LogExceptionInternal(Exception exception, string message)
        {
            var logger = GetLoggerInternal();
            logger.LogError(exception, message);
            logger.LogError($"STACK TRACE:{Environment.NewLine}{exception?.StackTrace}");
        }

        protected virtual ILogger GetLoggerInternal()
            => _serviceProvider.GetService<ILogger>()
                ?? throw new ArgumentNullException("The ILogger (non-generic) interface could not be resolved from the DI services; " +
                    "without this non-generic version we cannot be sure that the log messages will be written to the console/stream as expected.");

        protected virtual string BuildMessage(string handlerName, string hotChocolateMessage = null)
            => string.IsNullOrWhiteSpace(hotChocolateMessage)
                ? $"An exception occurred and is being logged by {nameof(AzFuncGraphQLConsoleLoggingEventListener)}.{handlerName}()."
                : $"{hotChocolateMessage.TrimEnd('.')}. The exception is being logged by {nameof(AzFuncGraphQLConsoleLoggingEventListener)}.{handlerName}().";

        #endregion        
    }
}

There is a documented issue with logging in Azure Functions so that the logs appear correctly in the log stream as expected and unfortunately workarounds are needed to make this work reliably.

For more info see here:
Azure/azure-functions-host#4689

In it's most simple form, for this to work correctly you will have to support resolving the ILogger (non generic) interface with a registration that uses a valid Azure Function Class Name so that the logs are not filtered out. This can be done using the as the LogFactory with the Azure Function name as the param as follows (replace GraphQLHttpTriggerAzFunction with your own Function name; in my case I always use the class name with nameof() to set the actual Function names also so they match):

services.AddScoped((svc) =>
{
     //Enable Log Streaming for our primary endpoint as the Default ILogger (but can be overridden by ScopedLogger user in the 
     AzFuncDependency Resolver!
     var logFactory = svc.GetService<ILoggerFactory>();
     return logFactory?.CreateLogger(LogCategories.CreateFunctionUserCategory(nameof(GraphQLHttpTriggerAzFunction)));
});

The processing of User Authorization is currently dependent on another small Gist for Az Func GraphQL Role Based Authorization that can be found here: https://gist.github.com/cajuncoding/4c037cb881a31da4aada061fde7f95f7

Otherwise that if/else statement logging User Claim details may be removed and no logging of the User will be done.